src/log/ModDaemon.cc

   1 /*
   2  * DEBUG: section 50    Log file handling
   3  * AUTHOR: Adrian Chadd <adrian@squid-cache.org>
   4  *
   5  * SQUID Web Proxy Cache          http://www.squid-cache.org/
   6  * ----------------------------------------------------------
   7  *
   8  *  Squid is the result of efforts by numerous individuals from
   9  *  the Internet community; see the CONTRIBUTORS file for full
  10  *  details.   Many organizations have provided support for Squid's
  11  *  development; see the SPONSORS file for full details.  Squid is
  12  *  Copyrighted (C) 2001 by the Regents of the University of
  13  *  California; see the COPYRIGHT file for full details.  Squid
  14  *  incorporates software developed and/or copyrighted by other
  15  *  sources; see the CREDITS file for full details.
  16  *
  17  *  This program is free software; you can redistribute it and/or modify
  18  *  it under the terms of the GNU General Public License as published by
  19  *  the Free Software Foundation; either version 2 of the License, or
  20  *  (at your option) any later version.
  21  *
  22  *  This program is distributed in the hope that it will be useful,
  23  *  but WITHOUT ANY WARRANTY; without even the implied warranty of
  24  *  MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
  25  *  GNU General Public License for more details.
  26  *
  27  *  You should have received a copy of the GNU General Public License
  28  *  along with this program; if not, write to the Free Software
  29  *  Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111, USA.
  30  *
  31  */
  32
  33 #include "squid.h"
  34 #include "cbdata.h"
  35 #include "comm/Loops.h"
  36 #include "fde.h"
  37 #include "globals.h"
  38 #include "log/Config.h"
  39 #include "log/File.h"
  40 #include "log/ModDaemon.h"
  41 #include "SquidIpc.h"
  42 #include "SquidConfig.h"
  43 #include "SquidTime.h"
  44
  45 #if HAVE_ERRNO_H
  46 #include <errno.h>
  47 #endif
  48
  49 /* How many buffers to keep before we say we've buffered too much */
  50 #define LOGFILE_MAXBUFS         128
  51
  52 /* Size of the logfile buffer */
  53 /*
  54  * For optimal performance this should match LOGFILE_BUFSIZ in logfile-daemon.c
  55  */
  56 #define LOGFILE_BUFSZ           32768
  57
  58 /* How many seconds between warnings */
  59 #define LOGFILE_WARN_TIME       30
  60
  61 static LOGWRITE logfile_mod_daemon_writeline;
  62 static LOGLINESTART logfile_mod_daemon_linestart;
  63 static LOGLINEEND logfile_mod_daemon_lineend;
  64 static LOGROTATE logfile_mod_daemon_rotate;
  65 static LOGFLUSH logfile_mod_daemon_flush;
  66 static LOGCLOSE logfile_mod_daemon_close;
  67
  68 static void logfile_mod_daemon_append(Logfile * lf, const char *buf, int len);
  69
  70 struct _l_daemon {
  71     int rfd, wfd;
  72     char eol;
  73     pid_t pid;
  74     int flush_pending;
  75     dlink_list bufs;
  76     int nbufs;
  77     int last_warned;
  78 };
  79
  80 typedef struct _l_daemon l_daemon_t;
  81
  82 /* Internal code */
  83 static void
  84 logfileNewBuffer(Logfile * lf)
  85 {
  86     l_daemon_t *ll = (l_daemon_t *) lf->data;
  87     logfile_buffer_t *b;
  88
  89     debugs(50, 5, "logfileNewBuffer: " << lf->path << ": new buffer");
  90
  91     b = static_cast<logfile_buffer_t*>(xcalloc(1, sizeof(logfile_buffer_t)));
  92     assert(b != NULL);
  93     b->buf = static_cast<char*>(xcalloc(1, LOGFILE_BUFSZ));
  94     assert(b->buf != NULL);
  95     b->size = LOGFILE_BUFSZ;
  96     b->written_len = 0;
  97     b->len = 0;
  98     dlinkAddTail(b, &b->node, &ll->bufs);
  99     ++ ll->nbufs;
 100 }
 101
 102 static void
 103 logfileFreeBuffer(Logfile * lf, logfile_buffer_t * b)
 104 {
 105     l_daemon_t *ll = (l_daemon_t *) lf->data;
 106     assert(b != NULL);
 107     dlinkDelete(&b->node, &ll->bufs);
 108     -- ll->nbufs;
 109     xfree(b->buf);
 110     xfree(b);
 111 }
 112
 113 static void
 114 logfileHandleWrite(int fd, void *data)
 115 {
 116     Logfile *lf = static_cast<Logfile *>(data);
 117     l_daemon_t *ll = static_cast<l_daemon_t *>(lf->data);
 118
 119     /*
 120      * We'll try writing the first entry until its done - if we
 121      * get a partial write then we'll re-schedule until its completed.
 122      * Its naive but it'll do for now.
 123      */
 124     if (!ll->bufs.head) // abort if there is nothing pending right now.
 125         return;
 126
 127     logfile_buffer_t *b = static_cast<logfile_buffer_t*>(ll->bufs.head->data);
 128     assert(b != NULL);
 129     ll->flush_pending = 0;
 130
 131     int ret = FD_WRITE_METHOD(ll->wfd, b->buf + b->written_len, b->len - b->written_len);
 132     debugs(50, 3, lf->path << ": write returned " << ret);
 133     if (ret < 0) {
 134         if (ignoreErrno(errno)) {
 135             /* something temporary */
 136             Comm::SetSelect(ll->wfd, COMM_SELECT_WRITE, logfileHandleWrite, lf, 0);
 137             ll->flush_pending = 1;
 138             return;
 139         }
 140         debugs(50, DBG_IMPORTANT,"logfileHandleWrite: " << lf->path << ": error writing (" << xstrerror() << ")");
 141         /* XXX should handle this better */
 142         fatal("I don't handle this error well!");
 143     }
 144     if (ret == 0) {
 145         /* error? */
 146         debugs(50, DBG_IMPORTANT, "logfileHandleWrite: " << lf->path << ": wrote 0 bytes?");
 147         /* XXX should handle this better */
 148         fatal("I don't handle this error well!");
 149     }
 150     /* ret > 0, so something was written */
 151     b->written_len += ret;
 152     assert(b->written_len <= b->len);
 153     if (b->written_len == b->len) {
 154         /* written the whole buffer! */
 155         logfileFreeBuffer(lf, b);
 156         b = NULL;
 157     }
 158     /* Is there more to write? */
 159     if (!ll->bufs.head)
 160         return;
 161     /* there is, so schedule more */
 162
 163     Comm::SetSelect(ll->wfd, COMM_SELECT_WRITE, logfileHandleWrite, lf, 0);
 164     ll->flush_pending = 1;
 165     return;
 166 }
 167
 168 static void
 169 logfileQueueWrite(Logfile * lf)
 170 {
 171     l_daemon_t *ll = (l_daemon_t *) lf->data;
 172     if (ll->flush_pending || ll->bufs.head == NULL) {
 173         return;
 174     }
 175     ll->flush_pending = 1;
 176     if (ll->bufs.head) {
 177         logfile_buffer_t *b = static_cast<logfile_buffer_t*>(ll->bufs.head->data);
 178         if (b->len + 2 <= b->size)
 179             logfile_mod_daemon_append(lf, "F\n", 2);
 180     }
 181     /* Ok, schedule a write-event */
 182     Comm::SetSelect(ll->wfd, COMM_SELECT_WRITE, logfileHandleWrite, lf, 0);
 183 }
 184
 185 static void
 186 logfile_mod_daemon_append(Logfile * lf, const char *buf, int len)
 187 {
 188     l_daemon_t *ll = (l_daemon_t *) lf->data;
 189     logfile_buffer_t *b;
 190     int s;
 191
 192     /* Is there a buffer? If not, create one */
 193     if (ll->bufs.head == NULL) {
 194         logfileNewBuffer(lf);
 195     }
 196     debugs(50, 3, "logfile_mod_daemon_append: " << lf->path << ": appending " << len << " bytes");
 197     /* Copy what can be copied */
 198     while (len > 0) {
 199         b = static_cast<logfile_buffer_t*>(ll->bufs.tail->data);
 200         debugs(50, 3, "logfile_mod_daemon_append: current buffer has " << b->len << " of " << b->size << " bytes before append");
 201         s = min(len, (b->size - b->len));
 202         memcpy(b->buf + b->len, buf, s);
 203         len = len - s;
 204         buf = buf + s;
 205         b->len = b->len + s;
 206         assert(b->len <= LOGFILE_BUFSZ);
 207         assert(len >= 0);
 208         if (len > 0) {
 209             logfileNewBuffer(lf);
 210         }
 211     }
 212 }
 213
 214 /*
 215  * only schedule a flush (write) if one isn't scheduled.
 216  */
 217 static void
 218 logfileFlushEvent(void *data)
 219 {
 220     Logfile *lf = static_cast<Logfile *>(data);
 221
 222     /*
 223      * This might work better if we keep track of when we wrote last and only
 224      * schedule a write if we haven't done so in the last second or two.
 225      */
 226     logfileQueueWrite(lf);
 227     eventAdd("logfileFlush", logfileFlushEvent, lf, 1.0, 1);
 228 }
 229
 230 /* External code */
 231
 232 int
 233 logfile_mod_daemon_open(Logfile * lf, const char *path, size_t bufsz, int fatal_flag)
 234 {
 235     const char *args[5];
 236     char *tmpbuf;
 237     l_daemon_t *ll;
 238
 239     lf->f_close = logfile_mod_daemon_close;
 240     lf->f_linewrite = logfile_mod_daemon_writeline;
 241     lf->f_linestart = logfile_mod_daemon_linestart;
 242     lf->f_lineend = logfile_mod_daemon_lineend;
 243     lf->f_flush = logfile_mod_daemon_flush;
 244     lf->f_rotate = logfile_mod_daemon_rotate;
 245
 246     cbdataInternalLock(lf); // WTF?
 247     debugs(50, DBG_IMPORTANT, "Logfile Daemon: opening log " << path);
 248     ll = static_cast<l_daemon_t*>(xcalloc(1, sizeof(*ll)));
 249     lf->data = ll;
 250     ll->eol = 1;
 251     {
 252         Ip::Address localhost;
 253         args[0] = "(logfile-daemon)";
 254         args[1] = path;
 255         args[2] = NULL;
 256         localhost.SetLocalhost();
 257         ll->pid = ipcCreate(IPC_STREAM, Log::TheConfig.logfile_daemon, args, "logfile-daemon", localhost, &ll->rfd, &ll->wfd, NULL);
 258         if (ll->pid < 0)
 259             fatal("Couldn't start logfile helper");
 260     }
 261     ll->nbufs = 0;
 262
 263     /* Queue the initial control data */
 264     tmpbuf = static_cast<char*>(xmalloc(BUFSIZ));
 265     snprintf(tmpbuf, BUFSIZ, "r%d\nb%d\n", Config.Log.rotateNumber, Config.onoff.buffered_logs);
 266     logfile_mod_daemon_append(lf, tmpbuf, strlen(tmpbuf));
 267     xfree(tmpbuf);
 268
 269     /* Start the flush event */
 270     eventAdd("logfileFlush", logfileFlushEvent, lf, 1.0, 1);
 271
 272     return 1;
 273 }
 274
 275 static void
 276 logfile_mod_daemon_close(Logfile * lf)
 277 {
 278     l_daemon_t *ll = static_cast<l_daemon_t *>(lf->data);
 279     debugs(50, DBG_IMPORTANT, "Logfile Daemon: closing log " << lf->path);
 280     logfileFlush(lf);
 281     if (ll->rfd == ll->wfd)
 282         comm_close(ll->rfd);
 283     else {
 284         comm_close(ll->rfd);
 285         comm_close(ll->wfd);
 286     }
 287     kill(ll->pid, SIGTERM);
 288     eventDelete(logfileFlushEvent, lf);
 289     xfree(ll);
 290     lf->data = NULL;
 291     cbdataInternalUnlock(lf); // WTF??
 292 }
 293
 294 static void
 295 logfile_mod_daemon_rotate(Logfile * lf)
 296 {
 297     char tb[3];
 298     debugs(50, DBG_IMPORTANT, "logfileRotate: " << lf->path);
 299     tb[0] = 'R';
 300     tb[1] = '\n';
 301     tb[2] = '\0';
 302     logfile_mod_daemon_append(lf, tb, 2);
 303 }
 304
 305 /*
 306  * This routine assumes that up to one line is written. Don't try to
 307  * call this routine with more than one line or subsequent lines
 308  * won't be prefixed with the command type and confuse the logging
 309  * daemon somewhat.
 310  */
 311 static void
 312 logfile_mod_daemon_writeline(Logfile * lf, const char *buf, size_t len)
 313 {
 314     l_daemon_t *ll = static_cast<l_daemon_t *>(lf->data);
 315     /* Make sure the logfile buffer isn't too large */
 316     if (ll->nbufs > LOGFILE_MAXBUFS) {
 317         if (ll->last_warned < squid_curtime - LOGFILE_WARN_TIME) {
 318             ll->last_warned = squid_curtime;
 319             debugs(50, DBG_IMPORTANT, "Logfile: " << lf->path << ": queue is too large; some log messages have been lost.");
 320         }
 321         return;
 322     }
 323     /* Append this data to the end buffer; create a new one if needed */
 324     /* Are we eol? If so, prefix with our logfile command byte */
 325     logfile_mod_daemon_append(lf, buf, len);
 326 }
 327
 328 static void
 329 logfile_mod_daemon_linestart(Logfile * lf)
 330 {
 331     l_daemon_t *ll = static_cast<l_daemon_t *>(lf->data);
 332     char tb[2];
 333     assert(ll->eol == 1);
 334     ll->eol = 0;
 335     tb[0] = 'L';
 336     tb[1] = '\0';
 337     logfile_mod_daemon_append(lf, tb, 1);
 338 }
 339
 340 static void
 341 logfile_mod_daemon_lineend(Logfile * lf)
 342 {
 343     l_daemon_t *ll = static_cast<l_daemon_t *>(lf->data);
 344     logfile_buffer_t *b;
 345     assert(ll->eol == 0);
 346     ll->eol = 1;
 347     /* Kick a write off if the head buffer is -full- */
 348     if (ll->bufs.head != NULL) {
 349         b = static_cast<logfile_buffer_t*>(ll->bufs.head->data);
 350         if (b->node.next != NULL || !Config.onoff.buffered_logs)
 351             logfileQueueWrite(lf);
 352     }
 353 }
 354
 355 static void
 356 logfile_mod_daemon_flush(Logfile * lf)
 357 {
 358     l_daemon_t *ll = static_cast<l_daemon_t *>(lf->data);
 359     if (commUnsetNonBlocking(ll->wfd)) {
 360         debugs(50, DBG_IMPORTANT, "Logfile Daemon: Couldn't set the pipe blocking for flush! You're now missing some log entries.");
 361         return;
 362     }
 363     while (ll->bufs.head != NULL) {
 364         logfileHandleWrite(ll->wfd, lf);
 365     }
 366     if (commSetNonBlocking(ll->wfd)) {
 367         fatalf("Logfile Daemon: %s: Couldn't set the pipe non-blocking for flush!\n", lf->path);
 368         return;
 369     }
 370 }