From fb0c2f1700b650d40c64d77f2bd17e29809216e5 Mon Sep 17 00:00:00 2001 From: Nathan Hoad Date: Sat, 11 May 2013 14:59:44 -0600 Subject: [PATCH] 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. Except for every 100th consecutive connection failures, 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. iii) Some access_log configuration styles overlap. To resolve ambiguities, Squid may need to assume that the first logging ACL name (if any) does not contain '=' and is not equal to an existing logformat name. It is possible to use 'all' as the first ACL name if these heuristics cause problems. 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 may require rearranging shutdown sequence AND letting EventLoop run during shutdown (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). --- CONTRIBUTORS | 1 + src/Makefile.am | 6 + src/acl/Gadgets.cc | 2 +- src/adaptation/icap/icap_log.cc | 2 +- src/cache_cf.cc | 115 ++++++-- src/cf.data.pre | 40 ++- src/log/CustomLog.h | 4 + src/log/File.cc | 6 +- src/log/Makefile.am | 6 +- src/log/ModTcp.cc | 237 ---------------- src/log/ModTcp.h | 40 --- src/log/TcpLogger.cc | 471 ++++++++++++++++++++++++++++++++ src/log/TcpLogger.h | 105 +++++++ src/log/access_log.cc | 2 +- 14 files changed, 730 insertions(+), 307 deletions(-) delete mode 100644 src/log/ModTcp.cc delete mode 100644 src/log/ModTcp.h create mode 100644 src/log/TcpLogger.cc create mode 100644 src/log/TcpLogger.h diff --git a/CONTRIBUTORS b/CONTRIBUTORS index ed6edcce05..de4f76e656 100644 --- a/CONTRIBUTORS +++ b/CONTRIBUTORS @@ -39,6 +39,7 @@ and ideas to make this software available. Cord Beermann Daniel O'Callaghan David Luyer + Dhaval Varia Diego Woitasen Dmitry Kurochkin Don Hopkins diff --git a/src/Makefile.am b/src/Makefile.am index 95bf17430b..3385a03bc7 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -1488,6 +1488,7 @@ tests_testCacheManager_SOURCES = \ multicast.h \ multicast.cc \ mem_node.cc \ + MemBlob.cc \ MemBuf.cc \ MemObject.cc \ mime.h \ @@ -1902,6 +1903,7 @@ tests_testEvent_SOURCES = \ Mem.h \ mem.cc \ mem_node.cc \ + MemBlob.cc \ MemBuf.cc \ MemObject.cc \ mime.h \ @@ -2145,6 +2147,7 @@ tests_testEventLoop_SOURCES = \ internal.cc \ SquidList.h \ SquidList.cc \ + MemBlob.cc \ MemBuf.cc \ MemObject.cc \ Mem.h \ @@ -2388,6 +2391,7 @@ tests_test_http_range_SOURCES = \ ipcache.cc \ SquidList.h \ SquidList.cc \ + MemBlob.cc \ MemBuf.cc \ MemObject.cc \ Mem.h \ @@ -2679,6 +2683,7 @@ tests_testHttpRequest_SOURCES = \ multicast.h \ multicast.cc \ mem_node.cc \ + MemBlob.cc \ MemBuf.cc \ MemObject.cc \ mime.h \ @@ -3647,6 +3652,7 @@ tests_testURL_SOURCES = \ Mem.h \ mem.cc \ mem_node.cc \ + MemBlob.cc \ MemBuf.cc \ MemObject.cc \ mime.h \ diff --git a/src/acl/Gadgets.cc b/src/acl/Gadgets.cc index f6fd6ba3cb..b3eddab486 100644 --- a/src/acl/Gadgets.cc +++ b/src/acl/Gadgets.cc @@ -209,7 +209,7 @@ aclParseAclList(ConfigParser &parser, ACLList ** head) /* 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 == '!') { diff --git a/src/adaptation/icap/icap_log.cc b/src/adaptation/icap/icap_log.cc index 80470480d3..ea74ea11a2 100644 --- a/src/adaptation/icap/icap_log.cc +++ b/src/adaptation/icap/icap_log.cc @@ -17,7 +17,7 @@ icapLogOpen() 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; } diff --git a/src/cache_cf.cc b/src/cache_cf.cc index 0f7195eee6..95f44b88b8 100644 --- a/src/cache_cf.cc +++ b/src/cache_cf.cc @@ -180,6 +180,7 @@ static void parse_access_log(CustomLog ** customlog_definitions); static int check_null_access_log(CustomLog *customlog_definitions); static void dump_access_log(StoreEntry * entry, const char *name, CustomLog * definitions); static void free_access_log(CustomLog ** definitions); +static bool setLogformat(CustomLog *cl, const char *name, const bool dieWhenMissing); static void update_maxobjsize(void); static void configDoConfigure(void); @@ -1220,7 +1221,6 @@ parseBytesLineSigned(ssize_t * bptr, const char *units) } #endif -#if USE_SSL /** * Parse bytes from a string. * Similar to the parseBytesLine function but parses the string value instead of @@ -1256,7 +1256,6 @@ static void parseBytesOptionValue(size_t * bptr, const char *units, char const * if (static_cast(*bptr) * 2 != (m * d / u) * 2) self_destruct(); } -#endif static size_t parseBytesUnits(const char *unit) @@ -4034,14 +4033,39 @@ strtokFile(void) #include "AccessLogEntry.h" +/** + * We support several access_log configuration styles: + * + * #1: Deprecated ancient style without an explicit logging module: + * access_log /var/log/access.log + * + * #2: The "none" logging module (i.e., no logging [of matching transactions]): + * access_log none [acl ...] + * + * #3: Configurable logging module without named options: + * Logformat or the first ACL name, whichever comes first, may not contain '='. + * If no explicit logformat name is given, the first ACL name, if any, + * should not be an existing logformat name or it will be treated as such. + * access_log module:place [logformat_name] [acl ...] + * + * #4: Configurable logging module with name=value options such as logformat=x: + * The first ACL name may not contain '='. + * access_log module:place [option ...] [acl ...] + * + */ 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 *filename = strtok(NULL, w_space); + if (!filename) { self_destruct(); return; } @@ -4055,12 +4079,72 @@ parse_access_log(CustomLog ** logs) return; } - if ((logdef_name = strtok(NULL, w_space)) == NULL) - logdef_name = "squid"; + cl->filename = xstrdup(filename); + cl->type = Log::Format::CLF_UNKNOWN; + + const char *token = ConfigParser::strtokFile(); + if (!token) { // style #1 + // no options to deal with + } else if (!strchr(token, '=')) { // style #3 + // if logformat name is not recognized, + // put back the token; it must be an ACL name + if (!setLogformat(cl, token, false)) + ConfigParser::strtokFileUndo(); + } else { // style #4 + do { + 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, "logformat=", 10) == 0) { + setLogformat(cl, token+10, true); + } else if (!strchr(token, '=')) { + // put back the token; it must be an ACL name + ConfigParser::strtokFileUndo(); + break; // done with name=value options, now to ACLs + } else { + debugs(3, DBG_CRITICAL, "Unknown access_log option " << token); + self_destruct(); + } + } while ((token = ConfigParser::strtokFile()) != NULL); + } - debugs(3, 9, "Log definition name '" << logdef_name << "' file '" << filename << "'"); + // set format if it has not been specified explicitly + if (cl->type == Log::Format::CLF_UNKNOWN) + setLogformat(cl, "squid", true); - cl->filename = xstrdup(filename); + aclParseAclList(LegacyParser, &cl->aclList); + + while (*logs) + logs = &(*logs)->next; + + *logs = cl; +} + +/// sets CustomLog::type and, if needed, CustomLog::lf +/// returns false iff there is no named log format +static bool +setLogformat(CustomLog *cl, const char *logdef_name, const bool dieWhenMissing) +{ + assert(cl); + assert(logdef_name); + + debugs(3, 9, "possible " << cl->filename << " logformat: " << logdef_name); + + if (cl->type != Log::Format::CLF_UNKNOWN) { + debugs(3, DBG_CRITICAL, "Second logformat name in one access_log: " << + logdef_name << " " << cl->type << " ? " << Log::Format::CLF_NONE); + self_destruct(); + return false; + } /* look for the definition pointer corresponding to this name */ Format::Format *lf = Log::TheConfig.logformats; @@ -4094,18 +4178,15 @@ parse_access_log(CustomLog ** logs) cl->type = Log::Format::CLF_USERAGENT; } else if (strcmp(logdef_name, "referrer") == 0) { cl->type = Log::Format::CLF_REFERER; - } else { + } else if (dieWhenMissing) { debugs(3, DBG_CRITICAL, "Log format '" << logdef_name << "' is not defined"); self_destruct(); - return; + return false; + } else { + return false; } - aclParseAclList(LegacyParser, &cl->aclList); - - while (*logs) - logs = &(*logs)->next; - - *logs = cl; + return true; } static int diff --git a/src/cf.data.pre b/src/cf.data.pre index e6f3ddb9aa..a00700ca2e 100644 --- a/src/cf.data.pre +++ b/src/cf.data.pre @@ -3797,16 +3797,47 @@ 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: + 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 : [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 ...]] + + In most cases, the first ACL name must not contain the '=' character + and should not be equal to an existing logformat name. You can always + start with an 'all' ACL to work around those restrictions. 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. @@ -3837,6 +3868,7 @@ DOC_START 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 @@ -4165,7 +4197,7 @@ DOC_START 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' access_log module only. + Currently honored by 'daemon' and 'tcp' access_log modules only. DOC_END NAME: netdb_filename diff --git a/src/log/CustomLog.h b/src/log/CustomLog.h index 77d3af4d61..391c2bcdf7 100644 --- a/src/log/CustomLog.h +++ b/src/log/CustomLog.h @@ -48,6 +48,10 @@ public: 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_ */ diff --git a/src/log/File.cc b/src/log/File.cc index afff1aae53..8d84484b30 100644 --- a/src/log/File.cc +++ b/src/log/File.cc @@ -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 @@ logfileOpen(const char *path, size_t bufsz, int fatal_flag) 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 @@ logfileOpen(const char *path, size_t bufsz, int fatal_flag) 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); } diff --git a/src/log/Makefile.am b/src/log/Makefile.am index 93c49d009c..1ecf9ccb73 100644 --- a/src/log/Makefile.am +++ b/src/log/Makefile.am @@ -24,10 +24,10 @@ liblog_la_SOURCES = \ ModStdio.h \ ModSyslog.cc \ ModSyslog.h \ - ModTcp.cc \ - ModTcp.h \ ModUdp.cc \ ModUdp.h \ CustomLog.h \ - CustomLog.cc + CustomLog.cc \ + TcpLogger.cc \ + TcpLogger.h diff --git a/src/log/ModTcp.cc b/src/log/ModTcp.cc deleted file mode 100644 index 5d44b12868..0000000000 --- a/src/log/ModTcp.cc +++ /dev/null @@ -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; -} diff --git a/src/log/ModTcp.h b/src/log/ModTcp.h deleted file mode 100644 index be577ded52..0000000000 --- a/src/log/ModTcp.h +++ /dev/null @@ -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 */ diff --git a/src/log/TcpLogger.cc b/src/log/TcpLogger.cc new file mode 100644 index 0000000000..1e8f4eca06 --- /dev/null +++ b/src/log/TcpLogger.cc @@ -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; +} diff --git a/src/log/TcpLogger.h b/src/log/TcpLogger.h new file mode 100644 index 0000000000..e12a38f24c --- /dev/null +++ b/src/log/TcpLogger.h @@ -0,0 +1,105 @@ +#ifndef _SQUID_SRC_LOG_TCPLOGGER_H +#define _SQUID_SRC_LOG_TCPLOGGER_H + +#include "base/AsyncJob.h" +#include "ip/Address.h" + +#if 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 */ + 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 unexpected/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 */ diff --git a/src/log/access_log.cc b/src/log/access_log.cc index 7ab4cb9c05..cb5af0eed9 100644 --- a/src/log/access_log.cc +++ b/src/log/access_log.cc @@ -320,7 +320,7 @@ accessLogInit(void) 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; -- 2.47.2