src/log/ModDaemon.cc

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