src/log/ModDaemon.cc

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