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 20:04:29 +0000 @@ -22,40 +22,41 @@ Arthur Tumanyan Assar Westerlund Automatic source maintenance Axel Westerhold Benno Rice Bertrand Jacquin Bojan Smojver Brad Smith Brian Brian Degenhardt Brian Denehy Bruce Murphy Carson Gaspar (carson@lehman.com, carson@cs.columbia.edu) Chris Hills Christos Tsantilas Cloyce Constantin Rack Cord Beermann Daniel O'Callaghan David Luyer + Dhaval Varia Diego Woitasen Dmitry Kurochkin Don Hopkins Doug Dixon Doug Urner Dragutin Cirkovic Duane Wessels Dustin J. Mitchell Ed Knowles Edward Moy Emilio Casbas Endre Balint Nagy Eric Stern Eugene Gladchenko Evan Jones Felix Meschberger Finn Thain Flavio Pescuma Francesco Chemolli Francesco Salvestrini === modified file 'src/log/File.cc' --- src/log/File.cc 2013-04-05 23:50:25 +0000 +++ src/log/File.cc 2013-04-18 21:03:41 +0000 @@ -20,66 +20,66 @@ * (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 "fde.h" #include "log/File.h" #include "log/ModDaemon.h" #include "log/ModStdio.h" #include "log/ModSyslog.h" #include "log/ModUdp.h" -#include "log/ModTcp.h" +#include "log/TcpLogger.h" CBDATA_TYPE(Logfile); Logfile * logfileOpen(const char *path, size_t bufsz, int fatal_flag) { int ret; const char *patharg; debugs(50, DBG_IMPORTANT, "Logfile: opening log " << path); CBDATA_INIT_TYPE(Logfile); Logfile *lf = cbdataAlloc(Logfile); xstrncpy(lf->path, path, MAXPATHLEN); 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); + 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); #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 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); === modified file 'src/log/Makefile.am' --- src/log/Makefile.am 2013-04-05 23:50:25 +0000 +++ src/log/Makefile.am 2013-04-18 20:20:22 +0000 @@ -7,29 +7,27 @@ access_log.h \ access_log.cc \ Config.cc \ Config.h \ File.cc \ 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 \ TcpLogger.cc \ TcpLogger.h === removed file 'src/log/ModTcp.cc' --- src/log/ModTcp.cc 2013-04-12 05:11:51 +0000 +++ src/log/ModTcp.cc 1970-01-01 00:00:00 +0000 @@ -1,130 +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 "defines.h" -#include "log/ModTcp.h" -#include "log/TcpLogger.h" -#include "Parsing.h" -#include "SquidConfig.h" - -static void -logfile_mod_tcp_flush(Logfile * lf) -{ - 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) -{ - 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) -{ - 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) -{ - TcpLogger *logger = static_cast(lf->data); - debugs(50, 3, "Closing " << logger); - - assert(logger != NULL); - - 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; - - 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); - - TcpLogger *logger = new TcpLogger(bufsz, fatal_flag, addr); - AsyncJob::Start(logger); - lf->data = logger; - - return 1; -} === removed file 'src/log/ModTcp.h' --- src/log/ModTcp.h 2013-04-12 00:15:02 +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 */ === modified file 'src/log/TcpLogger.cc' --- src/log/TcpLogger.cc 2013-04-12 14:50:44 +0000 +++ src/log/TcpLogger.cc 2013-04-18 21:40:09 +0000 @@ -1,168 +1,170 @@ #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 TcpLogger::IoBufSize = 2*MAX_URL; +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 TcpLogger::BufferCapacityMin = 2*TcpLogger::IoBufSize; +const size_t Log::TcpLogger::BufferCapacityMin = 2*Log::TcpLogger::IoBufSize; #define MY_DEBUG_SECTION 50 /* Log file handling */ -CBDATA_CLASS_INIT(TcpLogger); +CBDATA_NAMESPACED_CLASS_INIT(Log, TcpLogger); -TcpLogger::TcpLogger(size_t bufCap, bool dieOnErr, Ip::Address them): +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; } } -TcpLogger::~TcpLogger() +Log::TcpLogger::~TcpLogger() { // make sure Comm::Write does not have our buffer pointer assert(!writeScheduled); } void -TcpLogger::start() +Log::TcpLogger::start() { connect(); } bool -TcpLogger::doneAll() const +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 -TcpLogger::swanSong() +Log::TcpLogger::swanSong() { disconnect(); // optional: refcounting should close/delete conn eventually AsyncJob::swanSong(); } void -TcpLogger::endGracefully() +Log::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() +Log::TcpLogger::flush() { flushDebt = bufferedSize; writeIfNeeded(); } void -TcpLogger::logRecord(const char *buf, const size_t len) +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 -TcpLogger::writeIfNeeded() +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 TcpLogger::writeIfPossible() +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, TcpLogger::writeDone); + 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 -TcpLogger::canFit(const size_t len) const +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; } @@ -171,206 +173,299 @@ 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) +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 -TcpLogger::appendChunk(const char *chunk, const size_t len) +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 -TcpLogger::connect() +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, TcpLogger::connectDone); + 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 -TcpLogger::connectDone(const CommConnectCbParams ¶ms) +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("TcpLogger::DelayedReconnect", - TcpLogger::DelayedReconnect, + 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, TcpLogger::handleClosure); + 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. -/// TcpLogger::delayedReconnect() wrapper. +/// Log::TcpLogger::delayedReconnect() wrapper. void -TcpLogger::DelayedReconnect(void *data) +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, - TcpLogger::delayedReconnect); + Log::TcpLogger::delayedReconnect); ScheduleCallHere(call); } delete ptr; } /// "sleep a little before trying to connect again" event callback void -TcpLogger::delayedReconnect() { +Log::TcpLogger::delayedReconnect() { Must(reconnectScheduled); Must(!conn); reconnectScheduled = false; connect(); } /// Comm::Write callback void -TcpLogger::writeDone(const CommIoCbParams &io) +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 -TcpLogger::handleClosure(const CommCloseCbParams &io) +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("TcpLogger::handleClosure"); + mustStop("Log::TcpLogger::handleClosure"); } /// close our connection now, without flushing void -TcpLogger::disconnect() +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; +} === modified file 'src/log/TcpLogger.h' --- src/log/TcpLogger.h 2013-04-12 14:50:44 +0000 +++ src/log/TcpLogger.h 2013-04-18 21:02:10 +0000 @@ -1,66 +1,79 @@ #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" +#ifdef HAVE_LIST #include -#include +#endif class MemBlob; typedef RefCount MemBlobPointer; +namespace Log { + /** - * Async tcp logger processor. Buffers writes, has - * configurable error handling and buffer size. + * 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(); -protected: /* 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. @@ -70,21 +83,24 @@ 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 */