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 'src/Makefile.am' --- src/Makefile.am 2013-03-18 04:55:51 +0000 +++ src/Makefile.am 2013-04-12 15:05:33 +0000 @@ -1470,40 +1470,41 @@ HttpHdrCc.cci \ HttpHdrContRange.cc \ HttpHdrRange.cc \ HttpHdrSc.cc \ HttpHdrScTarget.cc \ HttpMsg.cc \ HttpReply.cc \ icp_v2.cc \ icp_v3.cc \ $(IPC_SOURCE) \ ipcache.cc \ int.h \ int.cc \ internal.h \ internal.cc \ SquidList.h \ SquidList.cc \ multicast.h \ multicast.cc \ mem_node.cc \ + MemBlob.cc \ MemBuf.cc \ MemObject.cc \ mime.h \ mime.cc \ mime_header.h \ mime_header.cc \ neighbors.h \ neighbors.cc \ Notes.cc \ Notes.h \ Packer.cc \ Parsing.cc \ pconn.cc \ peer_digest.cc \ peer_proxy_negotiate_auth.h \ peer_proxy_negotiate_auth.cc \ peer_select.cc \ peer_sourcehash.h \ peer_sourcehash.cc \ peer_userhash.h \ @@ -1884,40 +1885,41 @@ HttpParser.cc \ HttpParser.h \ HttpReply.cc \ RequestFlags.h \ RequestFlags.cc \ HttpRequest.cc \ HttpRequestMethod.cc \ icp_v2.cc \ icp_v3.cc \ $(IPC_SOURCE) \ ipcache.cc \ int.h \ int.cc \ internal.h \ internal.cc \ SquidList.h \ SquidList.cc \ Mem.h \ mem.cc \ mem_node.cc \ + MemBlob.cc \ MemBuf.cc \ MemObject.cc \ mime.h \ mime.cc \ mime_header.h \ mime_header.cc \ multicast.h \ multicast.cc \ neighbors.h \ neighbors.cc \ Notes.cc \ Notes.h \ Packer.cc \ Parsing.cc \ pconn.cc \ peer_digest.cc \ peer_proxy_negotiate_auth.h \ peer_proxy_negotiate_auth.cc \ peer_select.cc \ peer_sourcehash.h \ @@ -2127,40 +2129,41 @@ HttpHdrSc.cc \ HttpHdrScTarget.cc \ HttpMsg.cc \ HttpParser.cc \ HttpParser.h \ HttpReply.cc \ RequestFlags.h \ RequestFlags.cc \ HttpRequest.cc \ HttpRequestMethod.cc \ icp_v2.cc \ icp_v3.cc \ $(IPC_SOURCE) \ ipcache.cc \ int.h \ int.cc \ internal.h \ internal.cc \ SquidList.h \ SquidList.cc \ + MemBlob.cc \ MemBuf.cc \ MemObject.cc \ Mem.h \ mem.cc \ mem_node.cc \ mime.h \ mime.cc \ mime_header.h \ mime_header.cc \ multicast.h \ multicast.cc \ neighbors.h \ neighbors.cc \ Notes.cc \ Notes.h \ Packer.cc \ Parsing.cc \ pconn.cc \ peer_digest.cc \ peer_proxy_negotiate_auth.h \ @@ -2370,40 +2373,41 @@ HttpHeaderTools.h \ HttpHeaderTools.cc \ HttpMsg.cc \ HttpParser.cc \ HttpParser.h \ HttpReply.cc \ RequestFlags.h \ RequestFlags.cc \ HttpRequest.cc \ HttpRequestMethod.cc \ icp_v2.cc \ icp_v3.cc \ int.h \ int.cc \ internal.h \ internal.cc \ $(IPC_SOURCE) \ ipcache.cc \ SquidList.h \ SquidList.cc \ + MemBlob.cc \ MemBuf.cc \ MemObject.cc \ Mem.h \ mem.cc \ mem_node.cc \ mime.h \ mime.cc \ mime_header.h \ mime_header.cc \ multicast.h \ multicast.cc \ neighbors.h \ neighbors.cc \ Notes.cc \ Notes.h \ Packer.cc \ Parsing.cc \ peer_digest.cc \ peer_proxy_negotiate_auth.h \ peer_proxy_negotiate_auth.cc \ @@ -2660,40 +2664,41 @@ HttpHdrCc.cci \ HttpHdrContRange.cc \ HttpHdrRange.cc \ HttpHdrSc.cc \ HttpHdrScTarget.cc \ HttpMsg.cc \ HttpReply.cc \ icp_v2.cc \ icp_v3.cc \ $(IPC_SOURCE) \ ipcache.cc \ int.h \ int.cc \ internal.h \ internal.cc \ SquidList.h \ SquidList.cc \ multicast.h \ multicast.cc \ mem_node.cc \ + MemBlob.cc \ MemBuf.cc \ MemObject.cc \ mime.h \ mime.cc \ mime_header.h \ mime_header.cc \ neighbors.h \ neighbors.cc \ Notes.cc \ Notes.h \ Packer.cc \ Parsing.cc \ pconn.cc \ peer_digest.cc \ peer_proxy_negotiate_auth.h \ peer_proxy_negotiate_auth.cc \ peer_select.cc \ peer_sourcehash.h \ peer_sourcehash.cc \ peer_userhash.h \ @@ -3630,40 +3635,41 @@ HttpReply.cc \ RequestFlags.h \ RequestFlags.cc \ HttpRequest.cc \ HttpRequestMethod.cc \ icp_v2.cc \ icp_v3.cc \ $(IPC_SOURCE) \ ipcache.cc \ int.h \ int.cc \ internal.h \ internal.cc \ SquidList.h \ SquidList.cc \ multicast.h \ multicast.cc \ Mem.h \ mem.cc \ mem_node.cc \ + MemBlob.cc \ MemBuf.cc \ MemObject.cc \ mime.h \ mime.cc \ mime_header.h \ mime_header.cc \ neighbors.h \ neighbors.cc \ Notes.cc \ Notes.h \ Packer.cc \ Parsing.cc \ pconn.cc \ peer_digest.cc \ peer_proxy_negotiate_auth.h \ peer_proxy_negotiate_auth.cc \ peer_select.cc \ peer_sourcehash.h \ peer_sourcehash.cc \ peer_userhash.h \ === 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:18:33 +0000 @@ -1,40 +1,40 @@ #include "squid.h" #include "icap_log.h" #include "AccessLogEntry.h" #include "log/CustomLog.h" #include "log/File.h" #include "log/Formats.h" #include "SquidConfig.h" int IcapLogfileStatus = LOG_DISABLE; void icapLogOpen() { CustomLog *log; for (log = Config.Log.icaplogs; log; log = log->next) { 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; } } void icapLogClose() { CustomLog *log; for (log = Config.Log.icaplogs; log; log = log->next) { if (log->logfile) { logfileClose(log->logfile); log->logfile = NULL; } } } void icapLogRotate() === modified file 'src/cache_cf.cc' --- src/cache_cf.cc 2013-03-26 22:08:43 +0000 +++ src/cache_cf.cc 2013-04-12 16:24:35 +0000 @@ -1207,77 +1207,75 @@ (void) 0; else if ((token = strtok(NULL, w_space)) == NULL) debugs(3, DBG_CRITICAL, "WARNING: No units on '" << config_input_line << "', assuming " << d << " " << units ); else if ((m = parseBytesUnits(token)) == 0) { self_destruct(); return; } *bptr = static_cast(m * d / u); if (static_cast(*bptr) * 2 != (m * d / u) * 2) { debugs(3, DBG_CRITICAL, "ERROR: Invalid value '" << d << " " << token << ": integer overflow (ssize_t)."); self_destruct(); } } #endif -#if USE_SSL /** * Parse bytes from a string. * Similar to the parseBytesLine function but parses the string value instead of * the current token value. */ static void parseBytesOptionValue(size_t * bptr, const char *units, char const * value) { int u; if ((u = parseBytesUnits(units)) == 0) { self_destruct(); return; } // Find number from string beginning. char const * number_begin = value; char const * number_end = value; while ((*number_end >= '0' && *number_end <= '9')) { ++number_end; } String number; number.limitInit(number_begin, number_end - number_begin); int d = xatoi(number.termedBuf()); int m; if ((m = parseBytesUnits(number_end)) == 0) { self_destruct(); return; } *bptr = static_cast(m * d / u); if (static_cast(*bptr) * 2 != (m * d / u) * 2) self_destruct(); } -#endif static size_t parseBytesUnits(const char *unit) { if (!strncasecmp(unit, B_BYTES_STR, strlen(B_BYTES_STR))) return 1; if (!strncasecmp(unit, B_KBYTES_STR, strlen(B_KBYTES_STR))) return 1 << 10; if (!strncasecmp(unit, B_MBYTES_STR, strlen(B_MBYTES_STR))) return 1 << 20; if (!strncasecmp(unit, B_GBYTES_STR, strlen(B_GBYTES_STR))) return 1 << 30; debugs(3, DBG_CRITICAL, "WARNING: Unknown bytes unit '" << unit << "'"); return 0; } @@ -4007,67 +4005,122 @@ if (stat(path, &sb) < 0) { debugs(0, DBG_CRITICAL, (opt_parse_cfg_only?"FATAL ":"") << "ERROR: " << name << " " << path << ": " << xstrerror()); // keep going to find more issues if we are only checking the config file with "-k parse" if (opt_parse_cfg_only) return; // this is fatal if it is found during startup or reconfigure if (opt_send_signal == -1 || opt_send_signal == SIGHUP) fatalf("%s %s: %s", name, path, xstrerror()); } } char * strtokFile(void) { return ConfigParser::strtokFile(); } #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) logs = &(*logs)->next; *logs = cl; return; } - if ((logdef_name = strtok(NULL, w_space)) == NULL) - logdef_name = "squid"; + 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 = strtok(NULL, w_space)) != 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 { + debugs(3, DBG_CRITICAL, "Unknown access_log option " << token); + self_destruct(); + return; + } + } + } else { + // old or ancient style + cl->filename = xstrdup(token); + logdef_name = strtok(NULL, w_space); // may be nil + } - debugs(3, 9, "Log definition name '" << logdef_name << "' file '" << filename << "'"); + if (logdef_name == NULL) + logdef_name = "squid"; - 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; while (lf != NULL) { debugs(3, 9, "Comparing against '" << lf->name << "'"); if (strcmp(lf->name, logdef_name) == 0) break; lf = lf->next; } if (lf != NULL) { cl->type = Log::Format::CLF_CUSTOM; cl->logFormat = lf; } else if (strcmp(logdef_name, "auto") == 0) { debugs(0, DBG_CRITICAL, "WARNING: Log format 'auto' no longer exists. Using 'squid' instead."); cl->type = Log::Format::CLF_SQUID; } else if (strcmp(logdef_name, "squid") == 0) { === 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:28:11 +0000 @@ -3675,80 +3675,108 @@ logformat squid %ts.%03tu %6tr %>a %Ss/%03>Hs %a %[ui %[un [%tl] "%rm %ru HTTP/%rv" %>Hs %a %[ui %[un [%tl] "%rm %ru HTTP/%rv" %>Hs %h" "%{User-Agent}>h" %Ss:%Sh logformat referrer %ts.%03tu %>a %{Referer}>h %ru logformat useragent %>a [%tl] "%{User-Agent}>h" NOTE: When the log_mime_hdrs directive is set to ON. The squid, common and combined formats have a safely encoded copy of the mime headers appended to each line within a pair of brackets. NOTE: The common and combined formats are not quite true to the Apache definition. The logs from Squid contain an extra status and hierarchy code appended. DOC_END NAME: access_log cache_access_log TYPE: access_log 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: - access_log : [ [acl acl ...]] + 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 ...]] 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. Do not specify Place or logformat name. stdio Write each log line to disk immediately at the completion of each request. Place: the filename and path to be written. daemon Very similar to stdio. But instead of writing to disk the log line is passed to a daemon helper for asychronous handling instead. Place: varies depending on the daemon. log_file_daemon Place: the file name and path to be written. syslog To log each request via syslog facility. Place: The syslog facility and priority level for these entries. Place Format: facility.priority where facility could be any of: authpriv, daemon, local0 ... local7 or user. And priority could be any of: err, warning, notice, info, debug. udp To send each log line as text data to a UDP receiver. Place: The destination host name or IP and port. 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 Default: access_log daemon:@DEFAULT_ACCESS_LOG@ squid DOC_END NAME: icap_log TYPE: access_log IFDEF: ICAP_CLIENT LOC: Config.Log.icaplogs DEFAULT: none DOC_START ICAP log files record ICAP transaction summaries, one line per transaction. The icap_log option format is: icap_log [ [acl acl ...]] icap_log none [acl acl ...]] @@ -4024,45 +4052,52 @@ TYPE: obsolete DOC_START Use a regular access.log with ACL limiting it to MISS events. DOC_END NAME: strip_query_terms TYPE: onoff LOC: Config.onoff.strip_query_terms DEFAULT: on DOC_START By default, Squid strips query terms from requested URLs before logging. This protects your user's privacy. DOC_END NAME: buffered_logs COMMENT: on|off TYPE: onoff 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 TYPE: string DEFAULT: stdio:@DEFAULT_NETDB_FILE@ LOC: Config.netdbFilename IFDEF: USE_ICMP DOC_START A filename where Squid stores it's netdb state between restarts. To disable, enter "none". DOC_END COMMENT_START OPTIONS FOR TROUBLESHOOTING ----------------------------------------------------------------------------- COMMENT_END NAME: cache_log TYPE: string DEFAULT_IF_NONE: @DEFAULT_CACHE_LOG@ === 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:03:43 +0000 @@ -31,23 +31,27 @@ //#include "format/Format.h" #include "log/Formats.h" class ACLList; class Logfile; namespace Format { class Format; } /// representaiton of a custom log directive. Currently a POD. class CustomLog { public: char *filename; ACLList *aclList; Format::Format *logFormat; 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-05 23:18:33 +0000 @@ -55,41 +55,41 @@ patharg = path; /* need to call the per-logfile-type code */ if (strncmp(path, "stdio:", 6) == 0) { patharg = path + 6; ret = logfile_mod_stdio_open(lf, patharg, bufsz, fatal_flag); } else if (strncmp(path, "daemon:", 7) == 0) { patharg = path + 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); } else if (strncmp(path, "udp:", 4) == 0) { patharg = path + 4; ret = logfile_mod_udp_open(lf, patharg, bufsz, fatal_flag); #if HAVE_SYSLOG } else if (strncmp(path, "syslog:", 7) == 0) { patharg = path + 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); } if (!ret) { if (fatal_flag) fatalf("logfileOpen: %s: couldn't open!\n", path); else debugs(50, DBG_IMPORTANT, "logfileOpen: " << path << ": couldn't open!"); lf->f_close(lf); cbdataFree(lf); return NULL; } assert(lf->data != NULL); if (fatal_flag) lf->flags.fatal = 1; lf->sequence_number = 0; return lf; === modified file 'src/log/Makefile.am' --- src/log/Makefile.am 2012-09-06 12:47:15 +0000 +++ src/log/Makefile.am 2013-04-05 23:18:33 +0000 @@ -12,22 +12,24 @@ File.h \ FormatHttpdCombined.cc \ FormatHttpdCommon.cc \ Formats.h \ FormatSquidCustom.cc \ FormatSquidIcap.cc \ FormatSquidNative.cc \ FormatSquidReferer.cc \ FormatSquidUseragent.cc \ ModDaemon.cc \ ModDaemon.h \ ModStdio.cc \ ModStdio.h \ ModSyslog.cc \ ModSyslog.h \ ModTcp.cc \ ModTcp.h \ ModUdp.cc \ ModUdp.h \ CustomLog.h \ - CustomLog.cc + CustomLog.cc \ + TcpLogger.cc \ + TcpLogger.h === modified file 'src/log/ModTcp.cc' --- src/log/ModTcp.cc 2012-09-23 09:04:21 +0000 +++ src/log/ModTcp.cc 2013-04-12 05:03:14 +0000 @@ -15,223 +15,116 @@ * 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 "defines.h" #include "log/ModTcp.h" +#include "log/TcpLogger.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; + TcpLogger *logger = static_cast(lf->data); + assert(logger != NULL); + logger->flush(); } 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); + TcpLogger *logger = static_cast(lf->data); + assert(logger != NULL); + logger->logRecord(buf, len); } static void logfile_mod_tcp_linestart(Logfile * lf) { } static void logfile_mod_tcp_lineend(Logfile * lf) { - logfile_mod_tcp_flush(lf); + if (!Config.onoff.buffered_logs) + 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); + TcpLogger *logger = static_cast(lf->data); + debugs(50, 3, "Closing " << logger); - if (ll->fd >= 0) - file_close(ll->fd); + assert(logger != NULL); - if (ll->buf) - xfree(ll->buf); - - xfree(lf->data); + typedef NullaryMemFunT Dialer; + Dialer dialer(logger, &TcpLogger::endGracefully); + AsyncCall::Pointer call = asyncCall(50, 3, "TcpLogger::endGracefully", dialer); + ScheduleCallHere(call); 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; - } + TcpLogger *logger = new TcpLogger(bufsz, fatal_flag, addr); + AsyncJob::Start(logger); + lf->data = logger; return 1; } === added file 'src/log/TcpLogger.cc' --- src/log/TcpLogger.cc 1970-01-01 00:00:00 +0000 +++ src/log/TcpLogger.cc 2013-04-12 14:49:32 +0000 @@ -0,0 +1,376 @@ +#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/TcpLogger.h" +#include "MemBlob.h" +#include "Parsing.h" +#include "SquidTime.h" + +// a single I/O buffer should be large enough to store any access.log record +const size_t 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 TcpLogger::BufferCapacityMin = 2*TcpLogger::IoBufSize; + +#define MY_DEBUG_SECTION 50 /* Log file handling */ + + +CBDATA_CLASS_INIT(TcpLogger); + +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; + } +} + +TcpLogger::~TcpLogger() +{ + // make sure Comm::Write does not have our buffer pointer + assert(!writeScheduled); +} + +void +TcpLogger::start() +{ + connect(); +} + +bool +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 +TcpLogger::swanSong() +{ + disconnect(); // optional: refcounting should close/delete conn eventually + AsyncJob::swanSong(); +} + +void +TcpLogger::endGracefully() +{ + // job call protection must end our job if we are done logging current bufs + assert(inCall != NULL); + quitOnEmpty = true; + flush(); +} + +void +TcpLogger::flush() +{ + flushDebt = bufferedSize; + writeIfNeeded(); +} + +void +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 +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 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, 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 +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 +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 +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 +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, TcpLogger::connectDone); + AsyncJob::Start(new Comm::ConnOpener(futureConn, call, 2)); +} + +/// Comm::ConnOpener callback +void +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("TcpLogger::DelayedReconnect", + 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, TcpLogger::handleClosure); + comm_add_close_handler(conn->fd, closer); + + writeIfNeeded(); + } +} + +// XXX: Needed until eventAdd() starts accepting Async calls directly. +/// TcpLogger::delayedReconnect() wrapper. +void +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, + TcpLogger::delayedReconnect); + ScheduleCallHere(call); + } + delete ptr; +} + +/// "sleep a little before trying to connect again" event callback +void +TcpLogger::delayedReconnect() { + Must(reconnectScheduled); + Must(!conn); + reconnectScheduled = false; + connect(); +} + +/// Comm::Write callback +void +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 +TcpLogger::handleClosure(const CommCloseCbParams &io) +{ + assert(inCall != NULL); + closer = NULL; + conn = NULL; + // in all current use cases, we should not try to reconnect + mustStop("TcpLogger::handleClosure"); +} + +/// close our connection now, without flushing +void +TcpLogger::disconnect() +{ + if (conn != NULL) { + if (closer != NULL) { + comm_remove_close_handler(conn->fd, closer); + closer = NULL; + } + conn->close(); + conn = NULL; + } +} === added file 'src/log/TcpLogger.h' --- src/log/TcpLogger.h 1970-01-01 00:00:00 +0000 +++ src/log/TcpLogger.h 2013-04-12 14:42:39 +0000 @@ -0,0 +1,90 @@ +#ifndef _SQUID_SRC_LOG_TCPLOGGER_H +#define _SQUID_SRC_LOG_TCPLOGGER_H + +#include "squid.h" + +#include "CommCalls.h" +#include "base/AsyncJob.h" +#include "ip/Address.h" +#include "log/File.h" + +#include +#include + +class MemBlob; +typedef RefCount MemBlobPointer; + +/** + * Async tcp logger processor. Buffers writes, has + * configurable error handling and buffer size. + */ +class TcpLogger : public AsyncJob +{ +public: + typedef CbcPointer Pointer; + + 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(); + +protected: + /* AsyncJob API */ + virtual void start(); + virtual bool doneAll() const; + virtual void swanSong(); + +private: + 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); +}; + +#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:18:33 +0000 @@ -303,41 +303,41 @@ } void accessLogInit(void) { CustomLog *log; accessLogRegisterWithCacheManager(); #if USE_ADAPTATION Log::TheConfig.hasAdaptToken = false; #endif #if ICAP_CLIENT Log::TheConfig.hasIcapToken = false; #endif for (log = Config.Log.accesslogs; log; log = log->next) { 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; #if USE_ADAPTATION for (Format::Token * curr_token = (log->logFormat?log->logFormat->format:NULL); curr_token; curr_token = curr_token->next) { if (curr_token->type == Format::LFT_ADAPTATION_SUM_XACT_TIMES || curr_token->type == Format::LFT_ADAPTATION_ALL_XACT_TIMES || curr_token->type == Format::LFT_ADAPTATION_LAST_HEADER || curr_token->type == Format::LFT_ADAPTATION_LAST_HEADER_ELEM || curr_token->type == Format::LFT_ADAPTATION_LAST_ALL_HEADERS|| (curr_token->type == Format::LFT_NOTE && !Adaptation::Config::metaHeaders.empty())) { Log::TheConfig.hasAdaptToken = true; } #if ICAP_CLIENT if (curr_token->type == Format::LFT_ICAP_TOTAL_TIME) { Log::TheConfig.hasIcapToken = true; } #endif } #endif