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