Author: Nathan Hoad Author: Alex Rousskov Bug 3389: Auto-reconnect for tcp access_log. Major changes: 1. Squid reconnects to TCP logger as needed. Squid keeps trying to connect forever, using a hard-coded 0.5 second delay between attempts. 2. Squid buffers log records while there is no connectivity. The buffering limit is configurable. 3. On buffer overflows, Squid worker either dies or starts dropping log records. The choice is configurable. 4. The tcp logging module honors buffered_logs setting. Old code was flushing each record. 5. Squid reports changes in logging state to cache.log. Routine connection retries are not reported at level 1, to reduce noise level. 6. A new access_log configuration format/style has been added. It allows us to easily add named options such as buffer-size or on-error. The same format can be used to add module-specific options in the future, but doing so would require changes to the high-level logging code. All old configuration formats/styles are still supported. 7. squid.conf buffered_log option documentation now reflects reality. It used to talk about cache.log but I do not think Squid uses that option for cache.log maintenance. Known minor side-effects of these changes: i) All access_log logs can now be configured to bypass errors because the old "fatal" flag is now configurable via log-specific on-error option in squid.conf. The default is still "die". I have not checked whether modules other than TCP logger honor that flag. ii) All access_log logs now use 8*MAX_URL (64KB) instead of a 4*MAX_URL (32KB) or smaller buffer size by default. The ICAP logger was using 2*MAX_URL buffer size. The TCP logger was using 64KB buffer size before so no change for TCP. I decided that it is better to raise the default buffering level for some logs rather than decrease it for other logs, but it is not clear what the best default is. The buffer size is now configurable via buffer-size so admins can control it on individual log basis. TODO: We have attempted to solve more TCP logging problems, but it turns out that correct solutions would require fixing higher-level logging code, not specific to TCP logger or Bug 3389 scope. Those unsolved problems include: A. During reconfiguration, all logs are closed and reopened, even if there have been no changes to their configuration that necessitate such a drastic action (or no changes at all!). For TCP logger, this means that the old connection is used to flush remaining buffered records (if any), and the new connection is used to log new records, possibly at the same time. Nathan wrote clever code that keeps logging going using the same job/connection. However, we had to yank that code out because it clashed with higher-level logging state in subtle ways. B. During shutdown, all connections are put in the closing state before logs are told to flush remaining records. For TCP logger, this means that the remaining buffered records (if any) are lost. The correct fix would probably require rearranging shutdown sequence AND letting EventLoop run during shutdown (probably among other things). C. When logger connectivity is lost, Squid does not notice the problem until the second TCP socket write (or later). This results in lost records. This is due to TCP-level buffering. I suspect the only cure for this is adding logger-to-Squid "I got your records" feedback, which requires changes in the logging protocol (currently there is no logger-to-Squid communication at all). === modified file 'CONTRIBUTORS' --- CONTRIBUTORS 2013-03-11 00:30:26 +0000 +++ CONTRIBUTORS 2013-04-18 21:43:22 +0000 @@ -39,6 +39,7 @@ Cord Beermann Daniel O'Callaghan David Luyer + Dhaval Varia Diego Woitasen Dmitry Kurochkin Don Hopkins === modified file 'src/Makefile.am' --- src/Makefile.am 2013-03-18 04:55:51 +0000 +++ src/Makefile.am 2013-04-12 15:45:24 +0000 @@ -1487,6 +1487,7 @@ multicast.h \ multicast.cc \ mem_node.cc \ + MemBlob.cc \ MemBuf.cc \ MemObject.cc \ mime.h \ @@ -1901,6 +1902,7 @@ Mem.h \ mem.cc \ mem_node.cc \ + MemBlob.cc \ MemBuf.cc \ MemObject.cc \ mime.h \ @@ -2144,6 +2146,7 @@ internal.cc \ SquidList.h \ SquidList.cc \ + MemBlob.cc \ MemBuf.cc \ MemObject.cc \ Mem.h \ @@ -2387,6 +2390,7 @@ ipcache.cc \ SquidList.h \ SquidList.cc \ + MemBlob.cc \ MemBuf.cc \ MemObject.cc \ Mem.h \ @@ -2677,6 +2681,7 @@ multicast.h \ multicast.cc \ mem_node.cc \ + MemBlob.cc \ MemBuf.cc \ MemObject.cc \ mime.h \ @@ -3647,6 +3652,7 @@ Mem.h \ mem.cc \ mem_node.cc \ + MemBlob.cc \ MemBuf.cc \ MemObject.cc \ mime.h \ === modified file 'src/acl/Gadgets.cc' --- src/acl/Gadgets.cc 2012-09-05 14:49:29 +0000 +++ src/acl/Gadgets.cc 2013-04-16 04:46:27 +0000 @@ -209,7 +209,7 @@ /* next expect a list of ACL names, possibly preceeded * by '!' for negation */ - while ((t = strtok(NULL, w_space))) { + while ((t = parser.strtokFile())) { ACLList *L = new ACLList; if (*t == '!') { === modified file 'src/adaptation/icap/icap_log.cc' --- src/adaptation/icap/icap_log.cc 2012-09-06 13:29:14 +0000 +++ src/adaptation/icap/icap_log.cc 2013-04-05 23:50:25 +0000 @@ -17,7 +17,7 @@ if (log->type == Log::Format::CLF_NONE) continue; - log->logfile = logfileOpen(log->filename, MAX_URL << 1, 1); + log->logfile = logfileOpen(log->filename, log->bufferSize, log->fatal); IcapLogfileStatus = LOG_ENABLE; } === modified file 'src/cache_cf.cc' --- src/cache_cf.cc 2013-03-26 22:08:43 +0000 +++ src/cache_cf.cc 2013-04-16 04:46:27 +0000 @@ -1224,7 +1224,6 @@ } #endif -#if USE_SSL /** * Parse bytes from a string. * Similar to the parseBytesLine function but parses the string value instead of @@ -1260,7 +1259,6 @@ if (static_cast(*bptr) * 2 != (m * d / u) * 2) self_destruct(); } -#endif static size_t parseBytesUnits(const char *unit) @@ -4024,19 +4022,40 @@ #include "AccessLogEntry.h" +/* + We support several access_log configuration styles + + # New style with extensible named options + # The logger option is required and required to be first. + # Other options may include logformat=name, on-error=..., etc. + # ACL names may not contain '='. + access_log logger=module:place [option ...] [acl ...] + + # Old styles #1 and #2, without named options + access_log module:place [[logformat_name] acl ...] + access_log none [acl ...] + + # ancient style + access_log /var/log/access.log +*/ static void parse_access_log(CustomLog ** logs) { - const char *filename, *logdef_name; - CustomLog *cl = (CustomLog *)xcalloc(1, sizeof(*cl)); - if ((filename = strtok(NULL, w_space)) == NULL) { + // default buffer size and fatal settings + cl->bufferSize = 8*MAX_URL; + cl->fatal = true; + + /* determine configuration style */ + + const char *token = strtok(NULL, w_space); + if (!token) { self_destruct(); return; } - if (strcmp(filename, "none") == 0) { + if (strcmp(token, "none") == 0) { cl->type = Log::Format::CLF_NONE; aclParseAclList(LegacyParser, &cl->aclList); while (*logs) @@ -4045,12 +4064,49 @@ return; } - if ((logdef_name = strtok(NULL, w_space)) == NULL) + const char *logdef_name = NULL; + // new style must start with a logger=... option + if (strncasecmp(token, "logger=", 7) == 0) { + cl->filename = xstrdup(token+7); + + while ((token = ConfigParser::strtokFile()) != NULL) { + if (strncasecmp(token, "on-error=", 9) == 0) { + if (strncasecmp(token+9, "die", 3) == 0) { + cl->fatal = true; + } else if (strncasecmp(token+9, "drop", 4) == 0) { + cl->fatal = false; + } else { + debugs(3, DBG_CRITICAL, "Unknown value for on-error '" << + token << "' expected 'drop' or 'die'"); + self_destruct(); + } + } else if (strncasecmp(token, "buffer-size=", 12) == 0) { + parseBytesOptionValue(&cl->bufferSize, B_BYTES_STR, token+12); + } else if (strncasecmp(token, "logger=", 7) == 0) { + debugs(3, DBG_CRITICAL, "duplicate access_log logger=... " << + "option near " << token); + self_destruct(); + } else if (strncasecmp(token, "logformat=", 10) == 0) { + logdef_name = token+10; + } else if (strchr(token, '=') != NULL) { + debugs(3, DBG_CRITICAL, "Unknown access_log option " << token); + self_destruct(); + } else { + // put back the token; it must be an ACL + ConfigParser::strtokFileUndo(); + break; // done with name=value options, now to ACLs + } + } + } else { + // old or ancient style + cl->filename = xstrdup(token); + logdef_name = strtok(NULL, w_space); // may be nil + } + + if (logdef_name == NULL) logdef_name = "squid"; - debugs(3, 9, "Log definition name '" << logdef_name << "' file '" << filename << "'"); - - cl->filename = xstrdup(filename); + debugs(3, 9, "Log definition name '" << logdef_name << "' file '" << cl->filename << "'"); /* look for the definition pointer corresponding to this name */ Format::Format *lf = Log::TheConfig.logformats; === modified file 'src/cf.data.pre' --- src/cf.data.pre 2013-03-18 10:10:13 +0000 +++ src/cf.data.pre 2013-04-12 16:29:21 +0000 @@ -3692,16 +3692,43 @@ LOC: Config.Log.accesslogs DEFAULT_IF_NONE: daemon:@DEFAULT_ACCESS_LOG@ squid DOC_START - These files log client request activities. Has a line every HTTP or - ICP request. The format is: + Configures whether and how Squid logs HTTP and ICP transactions. + If access logging is enabled, a single line is logged for every + matching HTTP or ICP request. The recommended directive formats are: + + access_log logger=: [option ...] [acl acl ...] + access_log none [acl acl ...]] + + The following directive format is accepted but may be deprecated: access_log : [ [acl acl ...]] - access_log none [acl acl ...]] Will log to the specified module:place using the specified format (which must be defined in a logformat directive) those entries which match ALL the acl's specified (which must be defined in acl clauses). If no acl is specified, all requests will be logged to this destination. + ===== Available options for the recommended directive format ===== + + logformat=name Names log line format (either built-in or + defined by a logformat directive). Defaults + to 'squid'. + + buffer-size=64KB Defines approximate buffering limit for log + records (see buffered_logs). Squid should not + keep more than the specified size and, hence, + should flush records before the buffer becomes + full to avoid overflows under normal + conditions (the exact flushing algorithm is + module-dependent though). The on-error option + controls overflow handling. + + on-error=die|drop Defines action on unrecoverable errors. The + 'drop' action ignores (i.e., does not log) + affected log records. The default 'die' action + kills the affected worker. The drop action + support has not been tested for modules other + than tcp. + ===== Modules Currently available ===== none Do not log any requests matching these ACL. @@ -3732,6 +3759,7 @@ Place Format: //host:port tcp To send each log line as text data to a TCP receiver. + Lines may be accumulated before sending (see buffered_logs). Place: The destination host name or IP and port. Place Format: //host:port @@ -4041,11 +4069,18 @@ DEFAULT: off LOC: Config.onoff.buffered_logs DOC_START - cache.log log file is written with stdio functions, and as such - it can be buffered or unbuffered. By default it will be unbuffered. - Buffering it can speed up the writing slightly (though you are - unlikely to need to worry unless you run with tons of debugging - enabled in which case performance will suffer badly anyway..). + Whether to write/send access_log records ASAP or accumulate them and + then write/send them in larger chunks. Buffering may improve + performance because it decreases the number of I/Os. However, + buffering increases the delay before log records become available to + the final recipient (e.g., a disk file or logging daemon) and, + hence, increases the risk of log records loss. + + Note that even when buffered_logs are off, Squid may have to buffer + records if it cannot write/send them immediately due to pending I/Os + (e.g., the I/O writing the previous log record) or connectivity loss. + + Currently honored by 'daemon' and 'tcp' access_log modules only. DOC_END NAME: netdb_filename === modified file 'src/log/CustomLog.h' --- src/log/CustomLog.h 2012-10-04 00:23:44 +0000 +++ src/log/CustomLog.h 2013-04-12 00:15:02 +0000 @@ -48,6 +48,10 @@ Logfile *logfile; CustomLog *next; Log::Format::log_type type; + /// how much to buffer before dropping or dying (access_log buffer-size) + size_t bufferSize; + /// whether unrecoverable errors (e.g., dropping a log record) kill worker + bool fatal; }; #endif /* SQUID_CUSTOMLOG_H_ */ === modified file 'src/log/File.cc' --- src/log/File.cc 2012-09-01 14:38:36 +0000 +++ src/log/File.cc 2013-04-18 21:43:22 +0000 @@ -37,7 +37,7 @@ #include "log/ModStdio.h" #include "log/ModSyslog.h" #include "log/ModUdp.h" -#include "log/ModTcp.h" +#include "log/TcpLogger.h" CBDATA_TYPE(Logfile); @@ -62,7 +62,7 @@ ret = logfile_mod_daemon_open(lf, patharg, bufsz, fatal_flag); } else if (strncmp(path, "tcp:", 4) == 0) { patharg = path + 4; - ret = logfile_mod_tcp_open(lf, patharg, bufsz, fatal_flag); + ret = Log::TcpLogger::Open(lf, patharg, bufsz, fatal_flag); } else if (strncmp(path, "udp:", 4) == 0) { patharg = path + 4; ret = logfile_mod_udp_open(lf, patharg, bufsz, fatal_flag); @@ -72,7 +72,7 @@ ret = logfile_mod_syslog_open(lf, patharg, bufsz, fatal_flag); #endif } else { - debugs(50, DBG_IMPORTANT, "WARNING: log parameters now start with a module name. Use 'stdio:" << patharg << "'"); + debugs(50, DBG_IMPORTANT, "WARNING: log name now starts with a module name. Use 'stdio:" << patharg << "'"); snprintf(lf->path, MAXPATHLEN, "stdio:%s", patharg); ret = logfile_mod_stdio_open(lf, patharg, bufsz, fatal_flag); } === modified file 'src/log/Makefile.am' --- src/log/Makefile.am 2012-09-06 12:47:15 +0000 +++ src/log/Makefile.am 2013-04-18 21:43:22 +0000 @@ -24,10 +24,10 @@ ModStdio.h \ ModSyslog.cc \ ModSyslog.h \ - ModTcp.cc \ - ModTcp.h \ ModUdp.cc \ ModUdp.h \ CustomLog.h \ - CustomLog.cc + CustomLog.cc \ + TcpLogger.cc \ + TcpLogger.h === removed file 'src/log/ModTcp.cc' --- src/log/ModTcp.cc 2012-09-23 09:04:21 +0000 +++ src/log/ModTcp.cc 1970-01-01 00:00:00 +0000 @@ -1,237 +0,0 @@ -/* - * DEBUG: section 50 Log file handling - * AUTHOR: Dhaval Varia - * Developed based on ModUdp.* by Adrian Chadd - * - * SQUID Web Proxy Cache http://www.squid-cache.org/ - * ---------------------------------------------------------- - * - * Squid is the result of efforts by numerous individuals from - * the Internet community; see the CONTRIBUTORS file for full - * details. Many organizations have provided support for Squid's - * development; see the SPONSORS file for full details. Squid is - * Copyrighted (C) 2001 by the Regents of the University of - * California; see the COPYRIGHT file for full details. Squid - * incorporates software developed and/or copyrighted by other - * sources; see the CREDITS file for full details. - * - * This program is free software; you can redistribute it and/or modify - * it under the terms of the GNU General Public License as published by - * the Free Software Foundation; either version 2 of the License, or - * (at your option) any later version. - * - * This program is distributed in the hope that it will be useful, - * but WITHOUT ANY WARRANTY; without even the implied warranty of - * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the - * GNU General Public License for more details. - * - * You should have received a copy of the GNU General Public License - * along with this program; if not, write to the Free Software - * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111, USA. - * - */ - -#include "squid.h" -#include "comm.h" -#include "comm/Connection.h" -#include "disk.h" -#include "fd.h" -#include "log/File.h" -#include "log/ModTcp.h" -#include "Parsing.h" -#include "SquidConfig.h" - -#if HAVE_ERRNO_H -#include -#endif -/* - * This logfile TCP module is mostly inspired by a patch by Tim Starling - * from Wikimedia. - * - * It doesn't do any TCP buffering - it'd be quite a bit of work for - * something which the kernel could be doing for you! - */ - -typedef struct { - int fd; - char *buf; - size_t bufsz; - int offset; -} l_tcp_t; - -static void -logfile_mod_tcp_write(Logfile * lf, const char *buf, size_t len) -{ - l_tcp_t *ll = (l_tcp_t *) lf->data; - ssize_t s; - s = write(ll->fd, (char const *) buf, len); - - fd_bytes(ll->fd, s, FD_WRITE); -#if 0 - if (s < 0) { - debugs(1, DBG_IMPORTANT, "logfile (tcp): got errno (" << errno << "):" << xstrerror()); - } - if (s != len) { - debugs(1, DBG_IMPORTANT, "logfile (tcp): len=" << len << ", wrote=" << s); - } -#endif - - /* We don't worry about network errors for now */ -} - -static void -logfile_mod_tcp_flush(Logfile * lf) -{ - l_tcp_t *ll = (l_tcp_t *) lf->data; - if (0 == ll->offset) - return; - logfile_mod_tcp_write(lf, ll->buf, (size_t) ll->offset); - ll->offset = 0; -} - -static void -logfile_mod_tcp_writeline(Logfile * lf, const char *buf, size_t len) -{ - l_tcp_t *ll = (l_tcp_t *) lf->data; - - if (0 == ll->bufsz) { - /* buffering disabled */ - logfile_mod_tcp_write(lf, buf, len); - return; - } - if (ll->offset > 0 && (ll->offset + len + 4) > ll->bufsz) - logfile_mod_tcp_flush(lf); - - if (len > ll->bufsz) { - /* too big to fit in buffer */ - logfile_mod_tcp_write(lf, buf, len); - return; - } - /* buffer it */ - memcpy(ll->buf + ll->offset, buf, len); - - ll->offset += len; - - assert(ll->offset >= 0); - - assert((size_t) ll->offset <= ll->bufsz); -} - -static void -logfile_mod_tcp_linestart(Logfile * lf) -{ -} - -static void -logfile_mod_tcp_lineend(Logfile * lf) -{ - logfile_mod_tcp_flush(lf); -} - -static void -logfile_mod_tcp_rotate(Logfile * lf) -{ - return; -} - -static void -logfile_mod_tcp_close(Logfile * lf) -{ - l_tcp_t *ll = (l_tcp_t *) lf->data; - lf->f_flush(lf); - - if (ll->fd >= 0) - file_close(ll->fd); - - if (ll->buf) - xfree(ll->buf); - - xfree(lf->data); - lf->data = NULL; -} - -/* - * This code expects the path to be //host:port - */ -int -logfile_mod_tcp_open(Logfile * lf, const char *path, size_t bufsz, int fatal_flag) -{ - debugs(5, 3, "Tcp Open called"); - Ip::Address addr; - - char *strAddr; - - lf->f_close = logfile_mod_tcp_close; - lf->f_linewrite = logfile_mod_tcp_writeline; - lf->f_linestart = logfile_mod_tcp_linestart; - lf->f_lineend = logfile_mod_tcp_lineend; - lf->f_flush = logfile_mod_tcp_flush; - lf->f_rotate = logfile_mod_tcp_rotate; - - l_tcp_t *ll = static_cast(xcalloc(1, sizeof(*ll))); - lf->data = ll; - - if (strncmp(path, "//", 2) == 0) { - path += 2; - } - strAddr = xstrdup(path); - - if (!GetHostWithPort(strAddr, &addr)) { - if (lf->flags.fatal) { - fatalf("Invalid TCP logging address '%s'\n", lf->path); - } else { - debugs(50, DBG_IMPORTANT, "Invalid TCP logging address '" << lf->path << "'"); - safe_free(strAddr); - return FALSE; - } - } - - safe_free(strAddr); - - Ip::Address any_addr; - any_addr.SetAnyAddr(); - - // require the sending TCP port to be of the right family for the destination address. - if (addr.IsIPv4()) - any_addr.SetIPv4(); - - ll->fd = comm_open(SOCK_STREAM, IPPROTO_TCP, any_addr, COMM_NONBLOCKING, "TCP log socket"); - if (ll->fd < 0) { - if (lf->flags.fatal) { - fatalf("Unable to open TCP socket for logging\n"); - } else { - debugs(50, DBG_IMPORTANT, "Unable to open TCP socket for logging"); - return FALSE; - } - } else if (!comm_connect_addr(ll->fd, &addr)) { - if (lf->flags.fatal) { - fatalf("Unable to connect to %s for TCP log: %s\n", lf->path, xstrerror()); - } else { - debugs(50, DBG_IMPORTANT, "Unable to connect to " << lf->path << " for TCP log: " << xstrerror()); - return FALSE; - } - } - if (ll->fd == -1) { - if (ENOENT == errno && fatal_flag) { - fatalf("Cannot open '%s' because\n" - "\tthe parent directory does not exist.\n" - "\tPlease create the directory.\n", path); - } else if (EACCES == errno && fatal_flag) { - fatalf("Cannot open '%s' for writing.\n" - "\tThe parent directory must be writeable by the\n" - "\tuser '%s', which is the cache_effective_user\n" - "\tset in squid.conf.", path, Config.effectiveUser); - } else { - debugs(50, DBG_IMPORTANT, "logfileOpen (TCP): " << lf->path << ": " << xstrerror()); - return 0; - } - } - - bufsz = 65536; - if (bufsz > 0) { - ll->buf = static_cast(xmalloc(bufsz)); - ll->bufsz = bufsz; - } - - return 1; -} === removed file 'src/log/ModTcp.h' --- src/log/ModTcp.h 2012-10-04 09:14:06 +0000 +++ src/log/ModTcp.h 1970-01-01 00:00:00 +0000 @@ -1,40 +0,0 @@ -/* - * DEBUG: section 50 Log file handling - * AUTHOR: Dhaval Varia - * Developed based on ModUdp.* by Adrian Chadd - * - * SQUID Web Proxy Cache http://www.squid-cache.org/ - * ---------------------------------------------------------- - * - * Squid is the result of efforts by numerous individuals from - * the Internet community; see the CONTRIBUTORS file for full - * details. Many organizations have provided support for Squid's - * development; see the SPONSORS file for full details. Squid is - * Copyrighted (C) 2001 by the Regents of the University of - * California; see the COPYRIGHT file for full details. Squid - * incorporates software developed and/or copyrighted by other - * sources; see the CREDITS file for full details. - * - * This program is free software; you can redistribute it and/or modify - * it under the terms of the GNU General Public License as published by - * the Free Software Foundation; either version 2 of the License, or - * (at your option) any later version. - * - * This program is distributed in the hope that it will be useful, - * but WITHOUT ANY WARRANTY; without even the implied warranty of - * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the - * GNU General Public License for more details. - * - * You should have received a copy of the GNU General Public License - * along with this program; if not, write to the Free Software - * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111, USA. - * - */ -#ifndef _SQUID_SRC_LOG_MODTCP_H -#define _SQUID_SRC_LOG_MODTCP_H - -class Logfile; - -int logfile_mod_tcp_open(Logfile * lf, const char *path, size_t bufsz, int fatal_flag); - -#endif /* _SQUID_SRC_LOG_MODTCP_H */ === added file 'src/log/TcpLogger.cc' --- src/log/TcpLogger.cc 1970-01-01 00:00:00 +0000 +++ src/log/TcpLogger.cc 2013-04-18 21:43:22 +0000 @@ -0,0 +1,471 @@ +#include "squid.h" +#include "comm.h" +#include "comm/ConnOpener.h" +#include "comm/Connection.h" +#include "comm/Loops.h" +#include "comm/Write.h" +#include "fde.h" +#include "globals.h" // for shutting_down +#include "log/CustomLog.h" +#include "log/File.h" +#include "log/TcpLogger.h" +#include "MemBlob.h" +#include "Parsing.h" +#include "SquidConfig.h" +#include "SquidTime.h" + +// a single I/O buffer should be large enough to store any access.log record +const size_t Log::TcpLogger::IoBufSize = 2*MAX_URL; +// We need at least two buffers because when we write the first buffer, +// we have to use the second buffer to accumulate new entries. +const size_t Log::TcpLogger::BufferCapacityMin = 2*Log::TcpLogger::IoBufSize; + +#define MY_DEBUG_SECTION 50 /* Log file handling */ + + +CBDATA_NAMESPACED_CLASS_INIT(Log, TcpLogger); + +Log::TcpLogger::TcpLogger(size_t bufCap, bool dieOnErr, Ip::Address them): + AsyncJob("TcpLogger"), + dieOnError(dieOnErr), + bufferCapacity(bufCap), + bufferedSize(0), + flushDebt(0), + quitOnEmpty(false), + reconnectScheduled(false), + writeScheduled(false), + conn(NULL), + remote(them), + connectFailures(0), + drops(0) +{ + if (bufferCapacity < BufferCapacityMin) { + debugs(MY_DEBUG_SECTION, DBG_IMPORTANT, + "WARNING: tcp:" << remote << " logger configured buffer " << + "size " << bufferCapacity << " is smaller than the " << + BufferCapacityMin << "-byte" << " minimum. " << + "Using the minimum instead."); + bufferCapacity = BufferCapacityMin; + } +} + +Log::TcpLogger::~TcpLogger() +{ + // make sure Comm::Write does not have our buffer pointer + assert(!writeScheduled); +} + +void +Log::TcpLogger::start() +{ + connect(); +} + +bool +Log::TcpLogger::doneAll() const +{ + debugs(MY_DEBUG_SECTION, 5, "quitOnEmpty: " << quitOnEmpty << + " buffered: " << bufferedSize << + " conn: " << conn << ' ' << connectFailures); + + // we do not quit unless we are told that we may + if (!quitOnEmpty) + return false; + + /* We were asked to quit after we are done writing buffers. Are we done? */ + + // If we have records but are failing to connect, quit. Otherwise, we may + // be trying to connect forever due to a [since fixed] misconfiguration! + const bool failingToConnect = !conn && connectFailures; + if (bufferedSize && !failingToConnect) + return false; + + return AsyncJob::doneAll(); +} + +void +Log::TcpLogger::swanSong() +{ + disconnect(); // optional: refcounting should close/delete conn eventually + AsyncJob::swanSong(); +} + +void +Log::TcpLogger::endGracefully() +{ + // job call protection must end our job if we are done logging current bufs + assert(inCall != NULL); + quitOnEmpty = true; + flush(); +} + +void +Log::TcpLogger::flush() +{ + flushDebt = bufferedSize; + writeIfNeeded(); +} + +void +Log::TcpLogger::logRecord(const char *buf, const size_t len) +{ + appendRecord(buf, len); + writeIfNeeded(); +} + +/// starts writing if and only if it is time to write accumulated records +void +Log::TcpLogger::writeIfNeeded() +{ + // write if an earlier flush command forces us to write or + // if we have filled at least one I/O buffer + if (flushDebt > 0 || buffers.size() > 1) + writeIfPossible(); +} + +/// starts writing if possible +void Log::TcpLogger::writeIfPossible() +{ + debugs(MY_DEBUG_SECTION, 7, "guards: " << (!writeScheduled) << + (bufferedSize > 0) << (conn != NULL) << + (conn != NULL && !fd_table[conn->fd].closing()) << " buffered: " << + bufferedSize << '/' << buffers.size()); + + // XXX: Squid shutdown sequence starts closing our connection before + // calling LogfileClose, leading to loss of log records during shutdown. + if (!writeScheduled && bufferedSize > 0 && conn != NULL && + !fd_table[conn->fd].closing()) { + debugs(MY_DEBUG_SECTION, 5, "writing first buffer"); + + typedef CommCbMemFunT WriteDialer; + AsyncCall::Pointer callback = JobCallback(MY_DEBUG_SECTION, 5, WriteDialer, this, Log::TcpLogger::writeDone); + const MemBlob::Pointer &buffer = buffers.front(); + Comm::Write(conn, buffer->mem, buffer->size, callback, NULL); + writeScheduled = true; + } +} + +/// whether len more bytes can be buffered +bool +Log::TcpLogger::canFit(const size_t len) const +{ + // TODO: limit reporting frequency in addition to reporting only changes + + if (bufferedSize+len <= bufferCapacity) { + if (drops) { + // We can get here if a shorter record accidentally fits after we + // started dropping records. When that happens, the following + // DBG_IMPORTANT message will mislead admin into thinking that + // the problem was resolved (for a brief period of time, until + // another record comes in and overflows the buffer). It is + // difficult to prevent this without also creating the opposite + // problem: A huge record that does not fit and is dropped blocks + // subsequent regular records from being buffered until we write. + debugs(MY_DEBUG_SECTION, DBG_IMPORTANT, "tcp:" << remote << + " logger stops dropping records after " << drops << " drops" << + "; current buffer use: " << (bufferedSize+len) << + " out of " << bufferCapacity << " bytes"); + } + return true; + } + + if (!drops || dieOnError) { + debugs(MY_DEBUG_SECTION, + dieOnError ? DBG_CRITICAL : DBG_IMPORTANT, + "tcp:" << remote << " logger " << bufferCapacity << "-byte " << + "buffer overflowed; cannot fit " << + (bufferedSize+len-bufferCapacity) << " bytes"); + } + + if (dieOnError) + fatal("tcp logger buffer overflowed"); + + if (!drops) { + debugs(MY_DEBUG_SECTION, DBG_IMPORTANT, "tcp:" << remote << + " logger starts dropping records."); + } + + return false; +} + +/// buffer a record that might exceed IoBufSize +void +Log::TcpLogger::appendRecord(const char *record, const size_t len) +{ + // they should not happen, but to be safe, let's protect drop start/stop + // monitoring algorithm from empty records (which can never be dropped) + if (!len) + return; + + if (!canFit(len)) { + ++drops; + return; + } + + drops = 0; + // append without spliting buf, unless it exceeds IoBufSize + for (size_t off = 0; off < len; off += IoBufSize) + appendChunk(record + off, min(len - off, IoBufSize)); +} + +/// buffer a record chunk without splitting it across buffers +void +Log::TcpLogger::appendChunk(const char *chunk, const size_t len) +{ + Must(len <= IoBufSize); + // add a buffer if there is not one that can accomodate len bytes + bool addBuffer = buffers.empty() || + (buffers.back()->size+len > IoBufSize); + // also add a buffer if there is only one and that one is being written + addBuffer = addBuffer || (writeScheduled && buffers.size() == 1); + + if (addBuffer) { + buffers.push_back(new MemBlob(IoBufSize)); + debugs(MY_DEBUG_SECTION, 7, "added buffer #" << buffers.size()); + } + + Must(!buffers.empty()); + buffers.back()->append(chunk, len); + bufferedSize += len; +} + +/// starts [re]connecting to the remote logger +void +Log::TcpLogger::connect() +{ + if (shutting_down) + return; + + debugs(MY_DEBUG_SECTION, 3, "connecting"); + Must(!conn); + + Comm::ConnectionPointer futureConn = new Comm::Connection; + futureConn->remote = remote; + futureConn->local.SetAnyAddr(); + if (futureConn->remote.IsIPv4()) + futureConn->local.SetIPv4(); + + typedef CommCbMemFunT Dialer; + AsyncCall::Pointer call = JobCallback(MY_DEBUG_SECTION, 5, Dialer, this, Log::TcpLogger::connectDone); + AsyncJob::Start(new Comm::ConnOpener(futureConn, call, 2)); +} + +/// Comm::ConnOpener callback +void +Log::TcpLogger::connectDone(const CommConnectCbParams ¶ms) +{ + if (params.flag != COMM_OK) { + const double delay = 0.5; // seconds + if (connectFailures++ % 100 == 0) { + debugs(MY_DEBUG_SECTION, DBG_IMPORTANT, "tcp:" << remote << + " logger connection attempt #" << connectFailures << + " failed. Will keep trying every " << delay << " seconds."); + } + + if (!reconnectScheduled) { + reconnectScheduled = true; + eventAdd("Log::TcpLogger::DelayedReconnect", + Log::TcpLogger::DelayedReconnect, + new Pointer(this), 0.5, 0, false); + } + } else { + if (connectFailures > 0) { + debugs(MY_DEBUG_SECTION, DBG_IMPORTANT, "tcp:" << remote << + " logger connectivity restored after " << + (connectFailures+1) << " attempts."); + connectFailures = 0; + } + + Must(!conn); + conn = params.conn; + + Must(!closer); + typedef CommCbMemFunT Closer; + closer = JobCallback(MY_DEBUG_SECTION, 4, Closer, this, Log::TcpLogger::handleClosure); + comm_add_close_handler(conn->fd, closer); + + writeIfNeeded(); + } +} + +// XXX: Needed until eventAdd() starts accepting Async calls directly. +/// Log::TcpLogger::delayedReconnect() wrapper. +void +Log::TcpLogger::DelayedReconnect(void *data) +{ + Pointer *ptr = static_cast(data); + assert(ptr); + if (TcpLogger *logger = ptr->valid()) { + // Get back inside AsyncJob protections by scheduling another call. + typedef NullaryMemFunT Dialer; + AsyncCall::Pointer call = JobCallback(MY_DEBUG_SECTION, 5, Dialer, + logger, + Log::TcpLogger::delayedReconnect); + ScheduleCallHere(call); + } + delete ptr; +} + +/// "sleep a little before trying to connect again" event callback +void +Log::TcpLogger::delayedReconnect() { + Must(reconnectScheduled); + Must(!conn); + reconnectScheduled = false; + connect(); +} + +/// Comm::Write callback +void +Log::TcpLogger::writeDone(const CommIoCbParams &io) +{ + writeScheduled = false; + if (io.flag == COMM_ERR_CLOSING) { + debugs(MY_DEBUG_SECTION, 7, "closing"); + // do nothing here -- our comm_close_handler will be called to clean up + } else + if (io.flag != COMM_OK) { + debugs(MY_DEBUG_SECTION, 2, "write failure: " << xstrerr(io.xerrno)); + // keep the first buffer (the one we failed to write) + disconnect(); + connect(); + } else { + debugs(MY_DEBUG_SECTION, 5, "write successful"); + + Must(!buffers.empty()); // we had a buffer to write + const MemBlob::Pointer &written = buffers.front(); + const size_t writtenSize = static_cast(written->size); + // and we wrote the whole buffer + Must(io.size >= 0 && writtenSize >= 0 && io.size == writtenSize); + Must(bufferedSize >= writtenSize); + bufferedSize -= writtenSize; + + buffers.pop_front(); + + if (flushDebt > io.size) + flushDebt -= io.size; + else + flushDebt = 0; // wrote everything we owed (or more) + + writeIfNeeded(); + } +} + +/// This is our comm_close_handler. It is called when some external force +/// (e.g., reconfigure or shutdown) is closing the connection (rather than us). +void +Log::TcpLogger::handleClosure(const CommCloseCbParams &io) +{ + assert(inCall != NULL); + closer = NULL; + conn = NULL; + // in all current use cases, we should not try to reconnect + mustStop("Log::TcpLogger::handleClosure"); +} + +/// close our connection now, without flushing +void +Log::TcpLogger::disconnect() +{ + if (conn != NULL) { + if (closer != NULL) { + comm_remove_close_handler(conn->fd, closer); + closer = NULL; + } + conn->close(); + conn = NULL; + } +} + +/// Converts Logfile into a pointer to a valid TcpLogger job or, +/// if the logger job has quit, into a nill pointer +Log::TcpLogger * +Log::TcpLogger::StillLogging(Logfile *lf) +{ + if (Pointer *pptr = static_cast(lf->data)) + return pptr->get(); // may be nil + return NULL; +} + +void +Log::TcpLogger::Flush(Logfile * lf) +{ + if (TcpLogger *logger = StillLogging(lf)) + logger->flush(); +} + +void +Log::TcpLogger::WriteLine(Logfile * lf, const char *buf, size_t len) +{ + if (TcpLogger *logger = StillLogging(lf)) + logger->logRecord(buf, len); +} + +void +Log::TcpLogger::StartLine(Logfile * lf) +{ +} + +void +Log::TcpLogger::EndLine(Logfile * lf) +{ + if (!Config.onoff.buffered_logs) + Flush(lf); +} + +void +Log::TcpLogger::Rotate(Logfile * lf) +{ +} + +void +Log::TcpLogger::Close(Logfile * lf) +{ + if (TcpLogger *logger = StillLogging(lf)) { + debugs(50, 3, "Closing " << logger); + typedef NullaryMemFunT Dialer; + Dialer dialer(logger, &Log::TcpLogger::endGracefully); + AsyncCall::Pointer call = asyncCall(50, 3, "Log::TcpLogger::endGracefully", dialer); + ScheduleCallHere(call); + } + delete static_cast(lf->data); + lf->data = NULL; +} + +/* + * This code expects the path to be //host:port + */ +int +Log::TcpLogger::Open(Logfile * lf, const char *path, size_t bufsz, int fatalFlag) +{ + assert(!StillLogging(lf)); + debugs(5, 3, "Tcp Open called"); + + Ip::Address addr; + + if (strncmp(path, "//", 2) == 0) + path += 2; + char *strAddr = xstrdup(path); + if (!GetHostWithPort(strAddr, &addr)) { + if (lf->flags.fatal) { + fatalf("Invalid TCP logging address '%s'\n", lf->path); + } else { + debugs(50, DBG_IMPORTANT, "Invalid TCP logging address '" << lf->path << "'"); + safe_free(strAddr); + return FALSE; + } + } + safe_free(strAddr); + + TcpLogger *logger = new TcpLogger(bufsz, fatalFlag, addr); + lf->data = new Pointer(logger); + lf->f_close = &Close; + lf->f_linewrite = &WriteLine; + lf->f_linestart = &StartLine; + lf->f_lineend = &EndLine; + lf->f_flush = &Flush; + lf->f_rotate = &Rotate; + AsyncJob::Start(logger); + + return 1; +} === added file 'src/log/TcpLogger.h' --- src/log/TcpLogger.h 1970-01-01 00:00:00 +0000 +++ src/log/TcpLogger.h 2013-04-18 21:43:22 +0000 @@ -0,0 +1,106 @@ +#ifndef _SQUID_SRC_LOG_TCPLOGGER_H +#define _SQUID_SRC_LOG_TCPLOGGER_H + +#include "squid.h" +#include "base/AsyncJob.h" +#include "ip/Address.h" + +#ifdef HAVE_LIST +#include +#endif + +class MemBlob; +typedef RefCount MemBlobPointer; + +namespace Log { + +/** + * Sends log records to a remote TCP logger at the configured IP:port address. + * Handles loss of connectivity, record buffering, and buffer overflows. + */ +class TcpLogger : public AsyncJob +{ +public: + typedef CbcPointer Pointer; + + // Logfile API. XXX: The only method general logging code needs to know. + static int Open(Logfile *lf, const char *path, size_t bufSz, int fatalFlag); + +protected: + TcpLogger(size_t, bool, Ip::Address); + virtual ~TcpLogger(); + + /// Called when Squid is reconfiguring (or exiting) to give us a chance to + /// flush remaining buffers and end this job w/o loss of data. No new log + /// records are expected. Must be used as (or inside) an async job call and + /// will result in [eventual] job termination. + void endGracefully(); + + /// buffers record and possibly writes it to the remote logger + void logRecord(const char *buf, size_t len); + /// write all currently buffered records ASAP + void flush(); + + /* AsyncJob API */ + virtual void start(); + virtual bool doneAll() const; + virtual void swanSong(); + +private: + /* Logfile API. Map c-style Logfile calls to TcpLogger method calls. */ + static void Flush(Logfile *lf); + static void WriteLine(Logfile *lf, const char *buf, size_t len); + static void StartLine(Logfile *lf); + static void EndLine(Logfile *lf); + static void Rotate(Logfile *lf); + static void Close(Logfile *lf); + + static TcpLogger *StillLogging(Logfile *lf); + + static void DelayedReconnect(void *data); + void delayedReconnect(); + + bool canFit(const size_t len) const; + void appendRecord(const char *buf, size_t len); + void appendChunk(const char *chunk, const size_t len); + void writeIfNeeded(); + void writeIfPossible(); + void connect(); + void disconnect(); + + /* comm callbacks */ + void connectDone(const CommConnectCbParams &conn); + void writeDone(const CommIoCbParams &io); + void handleClosure(const CommCloseCbParams &io); + + static const size_t IoBufSize; ///< fixed I/O buffer size + static const size_t BufferCapacityMin; ///< minimum bufferCapacity value + + /// Whether this job must kill Squid on the first unrecoverable error. + /// Note that we may be able to recover from a failure to connect, but we + /// cannot recover from forgetting (dropping) a record while connecting. + bool dieOnError; + + std::list buffers; ///< I/O buffers + size_t bufferCapacity; ///< bufferedSize limit + size_t bufferedSize; ///< number of log record bytes stored in RAM now + size_t flushDebt; ///< how many record bytes we still need to write ASAP + + bool quitOnEmpty; ///< whether this job should quit when buffers are empty + bool reconnectScheduled; ///< we are sleeping before the next connection attempt + bool writeScheduled; ///< we are waiting for the latest write() results + + Comm::ConnectionPointer conn; ///< opened connection to the remote logger + Ip::Address remote; ///< where the remote logger expects our records + AsyncCall::Pointer closer; ///< handles unpexted/external conn closures + + uint64_t connectFailures; ///< number of sequential connection failures + uint64_t drops; ///< number of records dropped during the current outage + + CBDATA_CLASS2(TcpLogger); +}; + +} // namespace Log + + +#endif /* _SQUID_SRC_LOG_TCPLOGGER_H */ === modified file 'src/log/access_log.cc' --- src/log/access_log.cc 2013-03-18 04:55:51 +0000 +++ src/log/access_log.cc 2013-04-05 23:50:25 +0000 @@ -320,7 +320,7 @@ if (log->type == Log::Format::CLF_NONE) continue; - log->logfile = logfileOpen(log->filename, MAX_URL << 2, 1); + log->logfile = logfileOpen(log->filename, log->bufferSize, log->fatal); LogfileStatus = LOG_ENABLE;