Hello Squid Dev List,
I've been modifying squid-2.5.STABLE10 to allow log data to be passed to a
external helper program in much the same way as an external acl or
redirector. This gives me a lot more freedom in how I log proxy access.
Basically, using the redirector and helper code as a guide, I've written
functions that create a logHelper object (well, struct) and using ipcCreate()
it forks a child and passes data using the normal comm_write functions in the
same way as the normal helpers.
Then, instead of calling logfilePrintf, you call a logHelper function that
passes the data to the loghelper process.
This works, for the most part. I am running into a issue, and I am not able to
guess the best way to fix it. Also, I am hoping someone with more knowledge
of the squid code can cast a critical eye on the attached patch, and make
some suggestions.
The issue I am having, is that comm_write occasionally throws the following
debug message into the cache.log:
fd_table[31].rwstate != NULL
At the same time, a line fails to be passed to my loghelper program. After
some simple load testing it became apparent that this only happened when
squid is under a reasonably high load. Would I be right in thinking that the
error occurs when one line is still being written and another line appears?
I've tried to remove calls to commSetNonBlocking() when the wfd and rfd for
the loghelper is setup, in the hopes that non-blocking IO would mean that
squid waits until one line is handled before sending another (I assume this
is what happens when with the normal access log).
The redirector and acl helpers get around this by using multiple helpers and a
request queue (this is a bit of a guess), but I wish to have only one
loghelper if I can help it. Is there a way I can set up my loghelper to
prevent this from occurring?
Thanks for any help you can give,
Matthew Smith
diff -urN squid-2.5.STABLE10/src/access_log.c squid-2.5.STABLE10-loghelper/src/access_log.c
--- squid-2.5.STABLE10/src/access_log.c 2005-03-30 09:13:11.000000000 +1000
+++ squid-2.5.STABLE10-loghelper/src/access_log.c 2005-08-26 13:40:51.000000000 +1000
@@ -245,21 +245,39 @@
client = inet_ntoa(al->cache.caddr);
user = accessLogFormatName(al->cache.authuser ?
al->cache.authuser : al->cache.rfc931);
- logfilePrintf(logfile, "%9ld.%03d %6d %s %s/%03d %" PRINTF_OFF_T " %s %s %s %s%s/%s %s",
- (long int) current_time.tv_sec,
- (int) current_time.tv_usec / 1000,
- al->cache.msec,
- client,
- log_tags[al->cache.code],
- al->http.code,
- al->cache.size,
- al->private.method_str,
- al->url,
- user && *user ? user : dash_str,
- al->hier.ping.timedout ? "TIMEOUT_" : "",
- hier_strings[al->hier.code],
- al->hier.host,
- al->http.content_type);
+ if (!Config.Program.loghelper) {
+ logfilePrintf(logfile, "%9ld.%03d %6d %s %s/%03d %" PRINTF_OFF_T " %s %s %s %s%s/%s %s",
+ (long int) current_time.tv_sec,
+ (int) current_time.tv_usec / 1000,
+ al->cache.msec,
+ client,
+ log_tags[al->cache.code],
+ al->http.code,
+ al->cache.size,
+ al->private.method_str,
+ al->url,
+ user && *user ? user : dash_str,
+ al->hier.ping.timedout ? "TIMEOUT_" : "",
+ hier_strings[al->hier.code],
+ al->hier.host,
+ al->http.content_type);
+ } else {
+ logHelperStart("%9ld.%03d %6d %s %s/%03d %" PRINTF_OFF_T " %s %s %s %s%s/%s %s\n",
+ (long int) current_time.tv_sec,
+ (int) current_time.tv_usec / 1000,
+ al->cache.msec,
+ client,
+ log_tags[al->cache.code],
+ al->http.code,
+ al->cache.size,
+ al->private.method_str,
+ al->url,
+ user && *user ? user : dash_str,
+ al->hier.ping.timedout ? "TIMEOUT_" : "",
+ hier_strings[al->hier.code],
+ al->hier.host,
+ al->http.content_type);
+ }
safe_free(user);
}
@@ -274,18 +292,33 @@
client = inet_ntoa(al->cache.caddr);
user1 = accessLogFormatName(al->cache.authuser);
user2 = accessLogFormatName(al->cache.rfc931);
- logfilePrintf(logfile, "%s %s %s [%s] \"%s %s HTTP/%d.%d\" %d %" PRINTF_OFF_T " %s:%s",
- client,
- user2 ? user2 : dash_str,
- user1 ? user1 : dash_str,
- mkhttpdlogtime(&squid_curtime),
- al->private.method_str,
- al->url,
- al->http.version.major, al->http.version.minor,
- al->http.code,
- al->cache.size,
- log_tags[al->cache.code],
- hier_strings[al->hier.code]);
+ if (!Config.Program.loghelper) {
+ logfilePrintf(logfile, "%s %s %s [%s] \"%s %s HTTP/%d.%d\" %d %" PRINTF_OFF_T " %s:%s",
+ client,
+ user2 ? user2 : dash_str,
+ user1 ? user1 : dash_str,
+ mkhttpdlogtime(&squid_curtime),
+ al->private.method_str,
+ al->url,
+ al->http.version.major, al->http.version.minor,
+ al->http.code,
+ al->cache.size,
+ log_tags[al->cache.code],
+ hier_strings[al->hier.code]);
+ } else {
+ logHelperStart("%s %s %s [%s] \"%s %s HTTP/%d.%d\" %d %" PRINTF_OFF_T " %s:%s\n",
+ client,
+ user2 ? user2 : dash_str,
+ user1 ? user1 : dash_str,
+ mkhttpdlogtime(&squid_curtime),
+ al->private.method_str,
+ al->url,
+ al->http.version.major, al->http.version.minor,
+ al->http.code,
+ al->cache.size,
+ log_tags[al->cache.code],
+ hier_strings[al->hier.code]);
+ }
safe_free(user1);
safe_free(user2);
}
@@ -313,11 +346,15 @@
if (Config.onoff.log_mime_hdrs) {
char *ereq = log_quote(al->headers.request);
char *erep = log_quote(al->headers.reply);
- logfilePrintf(logfile, " [%s] [%s]\n", ereq, erep);
+ if (!Config.Program.loghelper) {
+ logfilePrintf(logfile, " [%s] [%s]\n", ereq, erep);
+ }
safe_free(ereq);
safe_free(erep);
} else {
- logfilePrintf(logfile, "\n");
+ if (!Config.Program.loghelper) {
+ logfilePrintf(logfile, "\n");
+ }
}
logfileFlush(logfile);
#if MULTICAST_MISS_STREAM
diff -urN squid-2.5.STABLE10/src/cache_cf.c squid-2.5.STABLE10-loghelper/src/cache_cf.c
--- squid-2.5.STABLE10/src/cache_cf.c 2005-05-07 08:33:53.000000000 +1000
+++ squid-2.5.STABLE10-loghelper/src/cache_cf.c 2005-08-26 09:22:46.000000000 +1000
@@ -393,6 +393,9 @@
#if USE_UNLINKD
requirePathnameExists("unlinkd_program", Config.Program.unlinkd);
#endif
+ if (Config.Program.loghelper) {
+ requirePathnameExists("loghelper_program", Config.Program.loghelper->key);
+ }
if (Config.Program.redirect)
requirePathnameExists("redirect_program", Config.Program.redirect->key);
requirePathnameExists("Icon Directory", Config.icons.directory);
diff -urN squid-2.5.STABLE10/src/cbdata.c squid-2.5.STABLE10-loghelper/src/cbdata.c
--- squid-2.5.STABLE10/src/cbdata.c 2003-07-16 17:18:43.000000000 +1000
+++ squid-2.5.STABLE10-loghelper/src/cbdata.c 2005-08-24 16:00:54.000000000 +1000
@@ -139,6 +139,7 @@
CREATE_CBDATA(ErrorState);
CREATE_CBDATA(FwdState);
CREATE_CBDATA(generic_cbdata);
+ CREATE_CBDATA(LogHelper);
CREATE_CBDATA(helper);
CREATE_CBDATA(helper_server);
CREATE_CBDATA(statefulhelper);
diff -urN squid-2.5.STABLE10/src/cf.data.pre squid-2.5.STABLE10-loghelper/src/cf.data.pre
--- squid-2.5.STABLE10/src/cf.data.pre 2005-05-11 09:08:40.000000000 +1000
+++ squid-2.5.STABLE10-loghelper/src/cf.data.pre 2005-08-26 09:16:50.000000000 +1000
@@ -1220,6 +1220,14 @@
Specify the location of the executable for the pinger process.
DOC_END
+NAME: loghelper_program
+TYPE: wordlist
+LOC: Config.Program.loghelper
+DEFAULT: none
+DOC_START
+ Specify the location of the executable for the log helper.
+ If unused logging is to the standard log setup.
+DOC_END
NAME: redirect_program
TYPE: wordlist
diff -urN squid-2.5.STABLE10/src/enums.h squid-2.5.STABLE10-loghelper/src/enums.h
--- squid-2.5.STABLE10/src/enums.h 2005-03-26 13:50:52.000000000 +1100
+++ squid-2.5.STABLE10-loghelper/src/enums.h 2005-08-24 15:36:04.000000000 +1000
@@ -696,6 +696,7 @@
CBDATA_ErrorState,
CBDATA_FwdState,
CBDATA_generic_cbdata,
+ CBDATA_LogHelper,
CBDATA_helper,
CBDATA_helper_server,
CBDATA_statefulhelper,
diff -urN squid-2.5.STABLE10/src/logHelper.c squid-2.5.STABLE10-loghelper/src/logHelper.c
--- squid-2.5.STABLE10/src/logHelper.c 1970-01-01 11:00:00.000000000 +1100
+++ squid-2.5.STABLE10-loghelper/src/logHelper.c 2005-08-26 15:24:19.000000000 +1000
@@ -0,0 +1,239 @@
+
+/*
+ * $Id: ???
+ *
+ * DEBUG: section ?? LogHelper?
+ * AUTHOR: Matthew Smith
+ *
+ * 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"
+
+static LogHelper *log_helper = NULL;
+static PF LogHelperFree;
+static PF logHelperHandleRead;
+
+#define HELPER_MAX_ARGS 64
+
+/* ====================================================================== */
+/* LOCAL FUNCTIONS */
+/* ====================================================================== */
+
+static void
+LogHelperFree(int fd, void *data)
+{
+ LogHelper *hlp = data;
+ assert(hlp->rfd == fd);
+ if (hlp->buf) {
+ memFree(hlp->buf, MEM_8K_BUF);
+ hlp->buf = NULL;
+ }
+ if (hlp->wfd != hlp->rfd && hlp->wfd != -1) {
+ comm_close(hlp->wfd);
+ }
+ // what happens if the LogHelper is dieing?
+}
+
+static void
+logHelperHandleRead(int fd, void *data)
+{
+ int len;
+ char *t = NULL;
+ LogHelper *hlp = data;
+ assert(fd == hlp->rfd);
+ //assert(cbdataValid(data));
+ len = FD_READ_METHOD(fd, hlp->buf + hlp->offset, hlp->buf_sz - hlp->offset);
+ fd_bytes(fd, len, FD_READ);
+ /*debug(84, 5) ("logHelperHandleRead: %d bytes from %s #%d.\n",
+ len, hlp->id_name, srv->index + 1);*/
+ if (len <= 0) {
+ if (len < 0)
+ //debug(84, 1) ("logHelperHandleRead: FD %d read: %s\n", fd, xstrerror());
+ comm_close(fd);
+ return;
+ }
+ commSetSelect(hlp->rfd, COMM_SELECT_READ, logHelperHandleRead, hlp, 0);
+ hlp->offset += len;
+ hlp->buf[hlp->offset] = '\0';
+ if ((t = strchr(hlp->buf, '\n'))) {
+ /* end of reply found */
+ //debug(84, 3) ("logHelperHandleRead: end of reply found\n");
+ *t = '\0';
+ hlp->offset = 0;
+ // should we close the wfd?
+ /*if () {
+ int wfd = hlp->wfd;
+ hlp->wfd = -1;
+ comm_close(wfd);
+ }*/
+ }
+}
+
+void
+LogHelperOpen(LogHelper *hlp)
+{
+ char *s;
+ char *progname;
+ char *shortname;
+ char *procname;
+ const char *args[HELPER_MAX_ARGS];
+ char fd_note_buf[FD_DESC_SZ];
+ int nargs = 0;
+ int k = 0;
+ int x;
+ int rfd;
+ int wfd;
+ wordlist *w;
+ if (hlp->cmdline == NULL) {
+ return;
+ }
+ progname = hlp->cmdline->key;
+ if ((s = strrchr(progname, '/'))) {
+ shortname = xstrdup(s + 1);
+ } else {
+ shortname = xstrdup(progname);
+ }
+ procname = xmalloc(strlen(shortname) + 3);
+ snprintf(procname, strlen(shortname) + 3, "(%s)", shortname);
+ args[nargs++] = procname;
+ for (w = hlp->cmdline->next; w && nargs < HELPER_MAX_ARGS; w = w->next) {
+ args[nargs++] = w->key;
+ }
+ args[nargs++] = NULL;
+ assert(nargs <= HELPER_MAX_ARGS);
+ getCurrentTime();
+ rfd = wfd = -1;
+ x = ipcCreate(hlp->ipc_type,
+ progname,
+ args,
+ shortname,
+ &rfd,
+ &wfd);
+ if (x < 0) {
+ debug(84, 1) ("WARNING: Cannot run '%s' process.\n", progname);
+ }
+ hlp->pid = x;
+ hlp->rfd = rfd;
+ hlp->wfd = wfd;
+ hlp->buf = memAllocate(MEM_8K_BUF);
+ hlp->buf_sz = 8192;
+ hlp->offset = 0;
+ if (rfd == wfd) {
+ snprintf(fd_note_buf, FD_DESC_SZ, "%s #%d", shortname, k + 1);
+ fd_note(rfd, fd_note_buf);
+ } else {
+ snprintf(fd_note_buf, FD_DESC_SZ, "reading %s #%d", shortname, k + 1);
+ fd_note(rfd, fd_note_buf);
+ snprintf(fd_note_buf, FD_DESC_SZ, "writing %s #%d", shortname, k + 1);
+ fd_note(wfd, fd_note_buf);
+ }
+
+ //commSetNonBlocking(rfd);
+ //if (wfd != rfd) {
+ // commSetNonBlocking(wfd);
+ //}
+
+ comm_add_close_handler(rfd, LogHelperFree, hlp);
+ commSetSelect(hlp->rfd, COMM_SELECT_READ, logHelperHandleRead, hlp, 0);
+ safe_free(shortname);
+ safe_free(procname);
+}
+
+/**** PUBLIC FUNCTIONS ****/
+
+// some sort of logThisLine func is needed
+void
+#if STDC_HEADERS
+logHelperStart(const char *fmt,...)
+#else
+logHelperStart(va_alist)
+ va_dcl
+#endif
+{
+ va_list args;
+ char buf[8192];
+ char * msg;
+ int s;
+#if STDC_HEADERS
+ va_start(args, fmt);
+#else
+ const char *fmt;
+ va_start(args);
+ fmt = va_arg(args, char *);
+#endif
+ s = vsnprintf(buf, 8192, fmt, args);
+ if (s > 8192) {
+ s = 8192;
+ if (fmt[strlen(fmt) - 1] == '\n') {
+ buf[8191] = '\n';
+ }
+ }
+
+ msg = xstrdup(buf);
+ comm_write(log_helper->wfd,
+ msg,
+ strlen(msg),
+ NULL, /* Handler */
+ NULL, /* Handler-data */
+ NULL); /* free */
+ va_end(args);
+}
+
+void
+logHelperInit(void)
+{
+ if (!Config.Program.loghelper) {
+ return;
+ }
+ if (log_helper == NULL) {
+ log_helper = cbdataAlloc(LogHelper);
+ }
+ log_helper->cmdline = Config.Program.loghelper;
+ log_helper->ipc_type = IPC_TCP_SOCKET;
+ LogHelperOpen(log_helper);
+ debug(84, 1) ("logHelper Initialised\n");
+}
+
+void
+logHelperShutdown(void)
+{
+ int wfd;
+
+ if (!log_helper) {
+ return;
+ }
+
+ wfd = log_helper->wfd;
+ log_helper->wfd = -1;
+ comm_close(wfd);
+
+ cbdataFree(log_helper);
+ log_helper = NULL;
+ debug(84, 1) ("LogHelper has Shutdown\n");
+}
diff -urN squid-2.5.STABLE10/src/main.c squid-2.5.STABLE10-loghelper/src/main.c
--- squid-2.5.STABLE10/src/main.c 2005-04-21 07:52:26.000000000 +1000
+++ squid-2.5.STABLE10-loghelper/src/main.c 2005-08-24 15:36:04.000000000 +1000
@@ -354,6 +354,7 @@
redirectShutdown();
authenticateShutdown();
externalAclShutdown();
+ logHelperShutdown();
storeDirCloseSwapLogs();
storeLogClose();
accessLogClose();
@@ -381,6 +382,7 @@
redirectInit();
authenticateInit(&Config.authConfig);
externalAclInit();
+ logHelperInit();
#if USE_WCCP
wccpInit();
#endif
@@ -409,6 +411,7 @@
redirectShutdown();
authenticateShutdown();
externalAclShutdown();
+ logHelperShutdown();
_db_rotate_log(); /* cache.log */
storeDirWriteCleanLogs(1);
storeLogRotate(); /* store.log */
@@ -425,6 +428,7 @@
redirectInit();
authenticateInit(&Config.authConfig);
externalAclInit();
+ logHelperInit();
}
static void
@@ -510,6 +514,7 @@
redirectInit();
authenticateInit(&Config.authConfig);
externalAclInit();
+ logHelperInit();
useragentOpenLog();
refererOpenLog();
httpHeaderInitModule(); /* must go before any header processing (e.g. the one in errorInitialize) */
@@ -962,6 +967,7 @@
#endif
redirectShutdown();
externalAclShutdown();
+ logHelperShutdown();
icpConnectionClose();
#if USE_HTCP
htcpSocketClose();
diff -urN squid-2.5.STABLE10/src/Makefile.am squid-2.5.STABLE10-loghelper/src/Makefile.am
--- squid-2.5.STABLE10/src/Makefile.am 2005-04-23 11:32:27.000000000 +1000
+++ squid-2.5.STABLE10-loghelper/src/Makefile.am 2005-08-24 15:36:04.000000000 +1000
@@ -174,6 +174,7 @@
peer_select.c \
protos.h \
redirect.c \
+ logHelper.c \
referer.c \
refresh.c \
send-announce.c \
diff -urN squid-2.5.STABLE10/src/Makefile.in squid-2.5.STABLE10-loghelper/src/Makefile.in
--- squid-2.5.STABLE10/src/Makefile.in 2005-04-24 10:12:08.000000000 +1000
+++ squid-2.5.STABLE10-loghelper/src/Makefile.in 2005-08-24 15:36:04.000000000 +1000
@@ -270,6 +270,7 @@
peer_select.c \
protos.h \
redirect.c \
+ logHelper.c \
referer.c \
refresh.c \
send-announce.c \
@@ -500,7 +501,7 @@
MemPool.$(OBJEXT) MemBuf.$(OBJEXT) mime.$(OBJEXT) \
multicast.$(OBJEXT) neighbors.$(OBJEXT) net_db.$(OBJEXT) \
Packer.$(OBJEXT) pconn.$(OBJEXT) peer_digest.$(OBJEXT) \
- peer_select.$(OBJEXT) redirect.$(OBJEXT) referer.$(OBJEXT) \
+ peer_select.$(OBJEXT) redirect.$(OBJEXT) logHelper.$(OBJEXT) referer.$(OBJEXT) \
refresh.$(OBJEXT) send-announce.$(OBJEXT) $(am__objects_7) \
ssl.$(OBJEXT) $(am__objects_8) stat.$(OBJEXT) \
StatHist.$(OBJEXT) String.$(OBJEXT) stmem.$(OBJEXT) \
diff -urN squid-2.5.STABLE10/src/protos.h squid-2.5.STABLE10-loghelper/src/protos.h
--- squid-2.5.STABLE10/src/protos.h 2005-04-20 08:19:27.000000000 +1000
+++ squid-2.5.STABLE10-loghelper/src/protos.h 2005-08-25 10:51:03.000000000 +1000
@@ -725,6 +725,16 @@
extern void redirectInit(void);
extern void redirectShutdown(void);
+#if STDC_HEADERS
+extern void
+logHelperStart(const char *fmt,...) PRINTF_FORMAT_ARG1;
+#else
+extern void logHelperStart(va_alist);
+#endif
+
+extern void logHelperInit(void);
+extern void logHelperShutdown(void);
+
/* auth_modules.c */
extern void authSchemeSetup(void);
diff -urN squid-2.5.STABLE10/src/structs.h squid-2.5.STABLE10-loghelper/src/structs.h
--- squid-2.5.STABLE10/src/structs.h 2005-05-05 04:03:47.000000000 +1000
+++ squid-2.5.STABLE10-loghelper/src/structs.h 2005-08-26 09:19:46.000000000 +1000
@@ -487,6 +487,7 @@
char *dnsserver;
#endif
wordlist *redirect;
+ wordlist *loghelper;
#if USE_ICMP
char *pinger;
#endif
@@ -2025,6 +2026,16 @@
#endif
+struct _LogHelper {
+ wordlist *cmdline;
+ int ipc_type;
+ int pid;
+ int rfd;
+ int wfd;
+ char *buf;
+ size_t buf_sz;
+ int offset;
+};
struct _helper_request {
char *buf;
diff -urN squid-2.5.STABLE10/src/typedefs.h squid-2.5.STABLE10-loghelper/src/typedefs.h
--- squid-2.5.STABLE10/src/typedefs.h 2005-03-27 10:20:13.000000000 +1000
+++ squid-2.5.STABLE10-loghelper/src/typedefs.h 2005-08-24 15:36:04.000000000 +1000
@@ -194,6 +194,7 @@
typedef struct _Version Version;
typedef struct _FwdState FwdState;
typedef struct _FwdServer FwdServer;
+typedef struct _LogHelper LogHelper;
typedef struct _helper helper;
typedef struct _helper_stateful statefulhelper;
typedef struct _helper_server helper_server;
