--------------------- PatchSet 8463 Date: 2006/08/07 09:30:54 Author: adri Branch: s26_logfile_daemon Tag: (none) Log: This is the initial cut of my work to move logfile writing (specifically access and store logs) into an external process freeing up squid to be more non-blocking. Whats implemented: * A simple hacked up protocol to talk between the client and server - each line is prefixed with a byte describing what it is (log line, rotate, buffering on/on, set rotate count, etc.) * A simple logfile daemon to do the writing, buffered or not buffered * Some very naive flush and rotate logic Whats needed: * More testing! Lots and lots more testing! * A "logfile_daemon" squid config entry to define where the logfile daemon lives. At the moment its hard-coded to my iBook development environment. * Build logfile-daemon as part of the squid build rather than being done separately * Specify an upper limit on the size of the logging buffer - if the buffer exceeds this limit then log something in cache.log identifying that log entries were "skipped" (but allow other commands like rotate and such to make it into the queue.) Members: src/access_log.c:1.28->1.28.2.1 src/logfile-daemon.c:1.1->1.1.2.1 src/logfile.c:1.12->1.12.2.1 src/protos.h:1.118->1.118.2.1 src/structs.h:1.126->1.126.2.1 src/typedefs.h:1.39->1.39.2.1 Index: squid/src/access_log.c =================================================================== RCS file: /cvsroot/squid-sf//squid/src/access_log.c,v retrieving revision 1.28 retrieving revision 1.28.2.1 diff -u -r1.28 -r1.28.2.1 --- squid/src/access_log.c 3 Aug 2006 01:52:15 -0000 1.28 +++ squid/src/access_log.c 7 Aug 2006 09:30:54 -0000 1.28.2.1 @@ -1,6 +1,6 @@ /* - * $Id: access_log.c,v 1.28 2006/08/03 01:52:15 squidadm Exp $ + * $Id: access_log.c,v 1.28.2.1 2006/08/07 09:30:54 adri Exp $ * * DEBUG: section 46 Access Log * AUTHOR: Duane Wessels @@ -1138,7 +1138,7 @@ fatalf("Unknown log format %d\n", log->type); break; } - logfileFlush(log->logfile); + //logfileFlush(log->logfile); if (!checklist) break; } @@ -1438,7 +1438,7 @@ logfileWrite(headerslog, &S, sizeof(S)); logfileWrite(headerslog, hmask, sizeof(HttpHeaderMask)); logfileWrite(headerslog, &ccmask, sizeof(int)); - logfileFlush(headerslog); + //logfileFlush(headerslog); } #endif --- /dev/null Wed Feb 14 01:16:53 2007 +++ squid/src/logfile-daemon.c Wed Feb 14 01:16:53 2007 @@ -0,0 +1,127 @@ +#include +#include +#include +#include +#include +#include + +#define LOGFILE_BUF_LEN 65536 + +int do_flush = 0; + +void +signal_alarm(int unused) +{ + do_flush = 1; +} + +void +rotate(const char *path, int rotate_count) +{ +#ifdef S_ISREG + struct stat sb; +#endif + int i; + char from[MAXPATHLEN]; + char to[MAXPATHLEN]; + assert(path); +#ifdef S_ISREG + if (stat(path, &sb) == 0) + if (S_ISREG(sb.st_mode) == 0) + return; +#endif + /* Rotate numbers 0 through N up one */ + for (i = rotate_count; i > 1;) { + i--; + snprintf(from, MAXPATHLEN, "%s.%d", path, i - 1); + snprintf(to, MAXPATHLEN, "%s.%d", path, i); + rename(from, to); + } + if (rotate_count > 0) { + snprintf(to, MAXPATHLEN, "%s.%d", path, 0); + rename(path, to); + } +} + +/* + * The commands: + * + * L\n - logfile data + * R\n - rotate file + * T\n - truncate file + * O\n - repoen file + * r\n - set rotate count to + * b\n - 1 = buffer output, 0 = don't buffer output + */ +int +main(int argc, char *argv[]) +{ + int t; + FILE *fp; + char buf[LOGFILE_BUF_LEN]; + int rotate_count = 10; + int do_buffer = 0; + + /* Try flushing to disk every second */ + signal(SIGALRM, signal_alarm); + ualarm(1000000, 1000000); + + if (argc < 2) { + printf("Error: usage: %s \n", argv[0]); + exit(1); + } + + fp = fopen(argv[1], "a"); + if (fp == NULL) { + perror("fopen"); + exit(1); + } + + setbuf(stdin, NULL); + setbuf(stdout, NULL); + close(2); + t = open("/dev/null", O_RDWR); + assert(t > -1); + dup2(t, 2); + + while(fgets(buf, LOGFILE_BUF_LEN, stdin)) { + /* First byte indicates what we're logging! */ + switch(buf[0]) { + case 'L': + if (buf[1] != '\0') { + fprintf(fp, "%s", buf + 1); + } + break; + case 'R': + fclose(fp); + rotate(argv[1], rotate_count); + fp = fopen(argv[1], "a"); + if (fp == NULL) { + perror("fopen"); + exit(1); + } + break; + case 'T': + break; + case 'O': + break; + case 'r': + //fprintf(fp, "SET ROTATE: %s\n", buf + 1); + break; + case 'b': + //fprintf(fp, "SET BUFFERED: %s\n", buf + 1); + do_buffer = (buf[1] == '1'); + break; + default: + break; + } + + if (do_flush) { + do_flush = 0; + if (do_buffer == 0) + fflush(fp); + } + } + fclose(fp); fp = NULL; + exit(0); +} Index: squid/src/logfile.c =================================================================== RCS file: /cvsroot/squid-sf//squid/src/logfile.c,v retrieving revision 1.12 retrieving revision 1.12.2.1 diff -u -r1.12 -r1.12.2.1 --- squid/src/logfile.c 18 Jul 2006 22:51:30 -0000 1.12 +++ squid/src/logfile.c 7 Aug 2006 09:30:54 -0000 1.12.2.1 @@ -34,8 +34,6 @@ #include "squid.h" -static void logfileWriteWrapper(Logfile * lf, const void *buf, size_t len); - #if HAVE_SYSLOG /* Define LOG_AUTHPRIV as LOG_AUTH on systems still using the old deprecated LOG_AUTH */ @@ -115,15 +113,152 @@ #define PRIORITY_MASK (LOG_ERR | LOG_WARNING | LOG_NOTICE | LOG_INFO | LOG_DEBUG) #endif /* HAVE_SYSLOG */ +/* Internal code */ +static void +logfileNewBuffer(Logfile *lf) +{ + logfile_buffer_t *b; + + debug(50, 5) ("logfileNewBuffer: %s: new buffer\n", lf->path); + + b = xcalloc(1, sizeof(logfile_buffer_t)); + assert(b != NULL); + b->buf = xcalloc(1, 32768); /* XXX eww to hard-coded stuff! */ + assert(b->buf != NULL); + b->size = 32768; + b->written_len = 0; + b->len = 0; + b->full = 0; + dlinkAddTail(b, &b->node, &lf->bufs); + lf->nbufs++; +} + +static void +logfileFreeBuffer(Logfile *lf, logfile_buffer_t *b) +{ + assert(b != NULL); + dlinkDelete(&b->node, &lf->bufs); + lf->nbufs --; + xfree(b->buf); + xfree(b); +} + +static void +logfileHandleWrite(int fd, void *data) +{ + Logfile *lf = (Logfile *) data; + int ret; + logfile_buffer_t *b; + + /* + * We'll try writing the first entry until its done - if we + * get a partial write then we'll re-schedule until its completed. + * Its naive but it'll do for now. + */ + b = lf->bufs.head->data; + assert (b != NULL); + lf->flush_pending = 0; + + ret = FD_WRITE_METHOD(lf->wfd, b->buf + b->written_len, b->len - b->written_len); + debug(50, 3) ("logfileHandleWrite: %s: write returned %d\n", lf->path, ret); + if (ret < 0) { + if (ignoreErrno(errno)) { + /* something temporary */ + goto reschedule; + } + debug(50, 1) ("logfileHandleWrite: %s: error writing (%s)\n", lf->path, xstrerror()); + /* XXX should handle this better */ + fatal("I don't handle this error well!"); + } + if (ret == 0) { + /* error? */ + debug(50, 1) ("logfileHandleWrite: %s: wrote 0 bytes?\n", lf->path); + /* XXX should handle this better */ + fatal("I don't handle this error well!"); + } + + /* ret > 0, so something was written */ + b->written_len += ret; + assert(b->written_len <= b->len); + if (b->written_len == b->len) { + /* written the whole buffer! */ + logfileFreeBuffer(lf, b); + b = NULL; + } + /* Is there more to write? */ + if (lf->bufs.head == NULL) { + goto finish; + } + /* there is, so schedule more */ + +reschedule: + commSetSelect(lf->wfd, COMM_SELECT_WRITE, logfileHandleWrite, lf, 0); + lf->flush_pending = 1; +finish: + return; +} + +static void +logfileQueueWrite(Logfile *lf) +{ + if (lf->flush_pending) { + return; + } + /* Ok, schedule a write-event */ + commSetSelect(lf->wfd, COMM_SELECT_WRITE, logfileHandleWrite, lf, 0); + lf->flush_pending = 1; +} + + +static void +logfileAppend(Logfile *lf, char *buf, int len) +{ + logfile_buffer_t *b; + int s; + + /* Is there a buffer? If not, create one */ + if (lf->bufs.head == NULL) { + logfileNewBuffer(lf); + } + debug(50, 3) ("logfileAppend: %s: appending %d bytes\n", lf->path, len); + /* Copy what can be copied */ + while (len > 0) { + b = lf->bufs.tail->data; + debug(50, 3) ("logfileAppend: current buffer has %d of %d bytes before append\n", b->len, b->size); + s = XMIN(len, (b->size - b->len)); + xmemcpy(b->buf + b->len, buf, s); + len = len - s; + buf = buf + s; + b->len = b->len + s; + assert(b->len <= 32768); + assert(len >= 0); + if (len > 0) { + logfileNewBuffer(lf); + } + } + if (lf->bufs.head != NULL) { + logfileQueueWrite(lf); + } +} + + +/* External code */ + Logfile * logfileOpen(const char *path, size_t bufsz, int fatal_flag) { Logfile *lf = xcalloc(1, sizeof(*lf)); + int ret; + const char * args[5]; + char *tmpbuf; + debug(50, 1) ("Logfile: opening log %s\n", path); xstrncpy(lf->path, path, MAXPATHLEN); + lf->eol = 1; #if HAVE_SYSLOG if (strcmp(path, "syslog") == 0 || strncmp(path, "syslog:", 7) == 0) { lf->flags.syslog = 1; - lf->fd = -1; + lf->rfd = -1; + lf->wfd = -1; if (path[6] != '\0') { const char *priority = path + 7; char *facility = (char *) strchr(priority, '|'); @@ -138,29 +273,20 @@ } else #endif { - int fd = file_open(path, O_WRONLY | O_CREAT | O_TEXT); - if (DISK_ERROR == fd) { - 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 { - debug(50, 1) ("logfileOpen: %s: %s\n", path, xstrerror()); - safe_free(lf); - return NULL; - } - } - lf->fd = fd; - if (bufsz > 0) { - lf->buf = xmalloc(bufsz); - lf->bufsz = bufsz; - } + args[0] = "(logfile-daemon)"; + args[1] = path; + args[2] = NULL; + ret = ipcCreate(IPC_STREAM, "/Users/adrian/work/squid/squid-2.6/src/logfile-daemon", args, "logfile-daemon", &lf->rfd, &lf->wfd); + if (ret < 0) + fatal("Couldn't start logfile helper"); } + lf->nbufs = 0; + + /* Queue the initial control data */ + asprintf(&tmpbuf, "r%d\nb%d\n", Config.Log.rotateNumber, Config.onoff.buffered_logs); + logfileAppend(lf, tmpbuf, strlen(tmpbuf)); + xfree(tmpbuf); + if (fatal_flag) lf->flags.fatal = 1; return lf; @@ -169,79 +295,57 @@ void logfileClose(Logfile * lf) { + debug(50, 1) ("Logfile: closing log %s\n", lf->path); logfileFlush(lf); - if (lf->fd >= 0) - file_close(lf->fd); - if (lf->buf) - xfree(lf->buf); + fd_close(lf->rfd); + fd_close(lf->wfd); xfree(lf); } void logfileRotate(Logfile * lf) { -#ifdef S_ISREG - struct stat sb; -#endif - int i; - char from[MAXPATHLEN]; - char to[MAXPATHLEN]; - assert(lf->path); - if (lf->flags.syslog) - return; -#ifdef S_ISREG - if (stat(lf->path, &sb) == 0) - if (S_ISREG(sb.st_mode) == 0) - return; -#endif - debug(0, 1) ("logfileRotate: %s\n", lf->path); - /* Rotate numbers 0 through N up one */ - for (i = Config.Log.rotateNumber; i > 1;) { - i--; - snprintf(from, MAXPATHLEN, "%s.%d", lf->path, i - 1); - snprintf(to, MAXPATHLEN, "%s.%d", lf->path, i); - xrename(from, to); - } - /* Rotate the current log to .0 */ - logfileFlush(lf); - file_close(lf->fd); /* always close */ - if (Config.Log.rotateNumber > 0) { - snprintf(to, MAXPATHLEN, "%s.%d", lf->path, 0); - xrename(lf->path, to); - } - /* Reopen the log. It may have been renamed "manually" */ - lf->fd = file_open(lf->path, O_WRONLY | O_CREAT | O_TEXT); - if (DISK_ERROR == lf->fd && lf->flags.fatal) { - debug(50, 1) ("logfileRotate: %s: %s\n", lf->path, xstrerror()); - fatalf("Cannot open %s: %s", lf->path, xstrerror()); - } + char tb[3]; + debug(50, 1) ("logfileRotate: %s\n", lf->path); + tb[0] = 'R'; + tb[1] = '\n'; + tb[2] = '\0'; + logfileAppend(lf, tb, 2); } + +/* + * This routine assumes that up to one line is written. Don't try to + * call this routine with more than one line or 'eol' won't be set + * right; thusly breaking the data format which is being written out + * to the logfile daemon. + */ void -logfileWrite(Logfile * lf, void *buf, size_t len) +logfileWrite(Logfile * lf, char *buf, size_t len) { + char tb[2]; + #if HAVE_SYSLOG if (lf->flags.syslog) { syslog(lf->syslog_priority, "%s", (char *) buf); return; } #endif - if (0 == lf->bufsz) { - /* buffering disabled */ - logfileWriteWrapper(lf, buf, len); - return; + /* Append this data to the end buffer; create a new one if needed */ + + /* Are we eol? If so, prefix with our logfile command byte */ + if (lf->eol == 1) { + lf->eol = 0; + tb[0] = 'L'; + tb[1] = '\0'; + logfileAppend(lf, tb, 1); } - if (lf->offset > 0 && lf->offset + len > lf->bufsz) - logfileFlush(lf); - if (len > lf->bufsz) { - /* too big to fit in buffer */ - logfileWriteWrapper(lf, buf, len); - return; + logfileAppend(lf, buf, len); + + /* If the last byte in buf is \n then set eol */ + if (len > 0 && buf[len - 1] == '\n') { + lf->eol = 1; } - /* buffer it */ - xmemcpy(lf->buf + lf->offset, buf, len); - lf->offset += len; - assert(lf->offset <= lf->bufsz); } void @@ -280,25 +384,15 @@ void logfileFlush(Logfile * lf) { - if (0 == lf->offset) - return; - logfileWriteWrapper(lf, lf->buf, (size_t) lf->offset); - lf->offset = 0; -} - -/* - * Aborts with fatal message if write() returns something other - * than its length argument. - */ -static void -logfileWriteWrapper(Logfile * lf, const void *buf, size_t len) -{ - int s; - s = FD_WRITE_METHOD(lf->fd, buf, len); - fd_bytes(lf->fd, s, FD_WRITE); - if (s == len) - return; - if (!lf->flags.fatal) - return; - fatalf("logfileWrite: %s: %s\n", lf->path, xstrerror()); + if (commUnsetNonBlocking(lf->wfd)) { + debug(50, 1) ("Logfile: Couldn't set the pipe blocking for flush! You're now missing some log entries.\n"); + return; + } + while (lf->bufs.head != NULL) { + logfileHandleWrite(lf->wfd, lf); + } + if (commSetNonBlocking(lf->wfd)) { + fatalf("Logfile: %s: Couldn't set the pipe non-blocking for flush!\n", lf->path); + return; + } } Index: squid/src/protos.h =================================================================== RCS file: /cvsroot/squid-sf//squid/src/protos.h,v retrieving revision 1.118 retrieving revision 1.118.2.1 diff -u -r1.118 -r1.118.2.1 --- squid/src/protos.h 30 Jul 2006 23:52:54 -0000 1.118 +++ squid/src/protos.h 7 Aug 2006 09:30:54 -0000 1.118.2.1 @@ -1,6 +1,6 @@ /* - * $Id: protos.h,v 1.118 2006/07/30 23:52:54 squidadm Exp $ + * $Id: protos.h,v 1.118.2.1 2006/08/07 09:30:54 adri Exp $ * * * SQUID Web Proxy Cache http://www.squid-cache.org/ @@ -1318,7 +1318,7 @@ extern Logfile *logfileOpen(const char *path, size_t bufsz, int); extern void logfileClose(Logfile * lf); extern void logfileRotate(Logfile * lf); -extern void logfileWrite(Logfile * lf, void *buf, size_t len); +extern void logfileWrite(Logfile * lf, char *buf, size_t len); extern void logfileFlush(Logfile * lf); #if STDC_HEADERS extern void Index: squid/src/structs.h =================================================================== RCS file: /cvsroot/squid-sf//squid/src/structs.h,v retrieving revision 1.126 retrieving revision 1.126.2.1 diff -u -r1.126 -r1.126.2.1 --- squid/src/structs.h 30 Jul 2006 23:52:55 -0000 1.126 +++ squid/src/structs.h 7 Aug 2006 09:30:54 -0000 1.126.2.1 @@ -1,6 +1,6 @@ /* - * $Id: structs.h,v 1.126 2006/07/30 23:52:55 squidadm Exp $ + * $Id: structs.h,v 1.126.2.1 2006/08/07 09:30:54 adri Exp $ * * * SQUID Web Proxy Cache http://www.squid-cache.org/ @@ -2416,17 +2416,27 @@ } shm; }; +struct _logfile_buffer { + char *buf; + int size; + int len; + int written_len; + int full; + dlink_node node; +}; + struct _Logfile { - int fd; + int rfd, wfd; + char eol; char path[MAXPATHLEN]; - char *buf; - size_t bufsz; - ssize_t offset; + dlink_list bufs; + int nbufs; struct { unsigned int fatal; unsigned int syslog; } flags; int syslog_priority; + int flush_pending; }; struct _logformat { Index: squid/src/typedefs.h =================================================================== RCS file: /cvsroot/squid-sf//squid/src/typedefs.h,v retrieving revision 1.39 retrieving revision 1.39.2.1 diff -u -r1.39 -r1.39.2.1 --- squid/src/typedefs.h 30 Jul 2006 23:52:55 -0000 1.39 +++ squid/src/typedefs.h 7 Aug 2006 09:30:54 -0000 1.39.2.1 @@ -1,6 +1,6 @@ /* - * $Id: typedefs.h,v 1.39 2006/07/30 23:52:55 squidadm Exp $ + * $Id: typedefs.h,v 1.39.2.1 2006/08/07 09:30:54 adri Exp $ * * * SQUID Web Proxy Cache http://www.squid-cache.org/ @@ -213,6 +213,7 @@ typedef struct _storefs_entry storefs_entry_t; typedef struct _storerepl_entry storerepl_entry_t; typedef struct _diskd_queue diskd_queue; +typedef struct _logfile_buffer logfile_buffer_t; typedef struct _Logfile Logfile; typedef struct _logformat_token logformat_token; typedef struct _logformat logformat;