ucw/log.c

   1 /*
   2  *      UCW Library -- Logging
   3  *
   4  *      (c) 1997--2009 Martin Mares <mj@ucw.cz>
   5  *      (c) 2008 Tomas Gavenciak <gavento@ucw.cz>
   6  *      (c) 2014 Tomas Valla <tom@ucw.cz>
   7  *      (c) 2020 Pavel Charvat <pchar@ucw.cz>
   8  *
   9  *      This software may be freely distributed and used according to the terms
  10  *      of the GNU Lesser General Public License.
  11  */
  12
  13 #include <ucw/lib.h>
  14 #include <ucw/log.h>
  15 #include <ucw/log-internal.h>
  16 #include <ucw/simple-lists.h>
  17
  18 #include <stdio.h>
  19 #include <stdlib.h>
  20 #include <string.h>
  21 #include <unistd.h>
  22 #include <sys/time.h>
  23 #include <time.h>
  24 #include <alloca.h>
  25 #include <errno.h>
  26
  27 char *log_title;
  28 int log_pid;
  29 void (*log_die_hook)(void);
  30
  31 static void NONRET do_die(void);
  32
  33 /*** The default log stream, which logs to stderr ***/
  34
  35 static int default_log_handler(struct log_stream *ls UNUSED, struct log_msg *m)
  36 {
  37   // This is a completely bare version of the log-file module. Errors are ignored.
  38   if (write(2, m->m, m->m_len) < 0)
  39     {
  40     }
  41   return 0;
  42 }
  43
  44 struct log_stream log_stream_default = {
  45   .name = "stderr",
  46   .use_count = 1000000,
  47   .handler = default_log_handler,
  48   .levels = ~0U,
  49   .types = ~0U,
  50   .msgfmt = LSFMT_DEFAULT,
  51   // an empty clist
  52   .substreams.head = {
  53     .next = (cnode *) &log_stream_default.substreams.head,
  54     .prev = (cnode *) &log_stream_default.substreams.head,
  55   },
  56 };
  57
  58 /*** Registry of streams and their identifiers ***/
  59
  60 struct lsbuf_t log_streams;             /* A growing array of pointers to log_streams */
  61 int log_streams_after = 0;              /* The first never-used index in log_streams.ptr */
  62
  63 /*
  64  *  Find a stream by its identifier given as LS_SET_STRNUM(flags).
  65  *  Returns NULL if the stream doesn't exist or it's invalid.
  66  *
  67  *  If the log-stream machinery has not been initialized (which is normal for programs
  68  *  with no fancy logging), the log_streams gbuf is empty and this function only
  69  *  translates stream #0 to the static log_stream_default.
  70  */
  71
  72 struct log_stream *
  73 log_stream_by_flags(uint flags)
  74 {
  75   int n = LS_GET_STRNUM(flags);
  76   if (n < 0 || n >= log_streams_after || log_streams.ptr[n]->regnum == -1)
  77     return (n ? NULL : &log_stream_default);
  78   return log_streams.ptr[n];
  79 }
  80
  81 /*** Known message types ***/
  82
  83 char **log_type_names;
  84
  85 char *
  86 log_type_name(uint flags)
  87 {
  88   uint type = LS_GET_TYPE(flags);
  89
  90   if (!log_type_names || !log_type_names[type])
  91     return "default";
  92   else
  93     return log_type_names[type];
  94 }
  95
  96 /*** Logging ***/
  97
  98 void
  99 vmsg(uint cat, const char *fmt, va_list args)
 100 {
 101   int saved_errno = errno;
 102   struct timeval tv;
 103   struct tm tm;
 104   va_list args2;
 105   char stime[24];
 106   char sutime[12];
 107   char msgbuf[256];
 108   char *p;
 109   int len;
 110   uint sighandler = cat & L_SIGHANDLER;
 111   struct log_stream *ls;
 112   struct log_msg m = { .flags = cat };
 113
 114   /* Find the destination stream */
 115   if (sighandler)
 116     ls = &log_stream_default;
 117   else if (!(ls = log_stream_by_flags(cat)))
 118     {
 119       msg((LS_CTRL_MASK&cat)|L_WARN, "No log_stream with number %d! Logging to the default log.", LS_GET_STRNUM(cat));
 120       ls = &log_stream_default;
 121     }
 122
 123   /* Get the current time */
 124   if (!sighandler)
 125     {
 126       /* CAVEAT: These calls are not safe in signal handlers. */
 127       gettimeofday(&tv, NULL);
 128       m.tv = &tv;
 129       if (localtime_r(&tv.tv_sec, &tm))
 130         m.tm = &tm;
 131     }
 132
 133   /* Generate time strings */
 134   if (m.tm)
 135     {
 136       strftime(stime, sizeof(stime), "%Y-%m-%d %H:%M:%S", &tm);
 137       snprintf(sutime, sizeof(sutime), ".%06d", (int)tv.tv_usec);
 138       m.stime = stime;
 139       m.sutime = sutime;
 140     }
 141   else
 142     {
 143       m.stime = "\?\?\?\?-\?\?-\?\? \?\?:\?\?:\?\?";
 144       m.sutime = ".\?\?\?\?\?\?";
 145     }
 146
 147   /* Generate the message string */
 148   va_copy(args2, args);
 149   errno = saved_errno;
 150   len = vsnprintf(msgbuf, sizeof(msgbuf), fmt, args2);
 151   va_end(args2);
 152   if (len < (int) sizeof(msgbuf) || sighandler)
 153     m.raw_msg = msgbuf;
 154   else
 155     {
 156       m.raw_msg = xmalloc(len+1);
 157       errno = saved_errno;
 158       vsnprintf(m.raw_msg, len+1, fmt, args);
 159     }
 160
 161   /* Remove non-printable characters and newlines */
 162   p = m.raw_msg;
 163   while (*p)
 164     {
 165       if (*p >= 0 && *p < 0x20 && *p != '\t')
 166         *p = 0x7f;
 167       p++;
 168     }
 169
 170   /* Pass the message to the log_stream */
 171   log_pass_msg(ls, &m);
 172   if (m.error)
 173     {
 174       /* Error (such as infinite loop) occurred */
 175       log_pass_msg(&log_stream_default, &m);
 176     }
 177
 178   if (m.raw_msg != msgbuf)
 179     xfree(m.raw_msg);
 180
 181   errno = saved_errno;
 182 }
 183
 184 static void
 185 log_report_err(struct log_stream *ls, struct log_msg *m, int err)
 186 {
 187   if (m->flags & L_LOGGER_ERR)
 188     return;
 189   if (ls->stream_flags & LSFLAG_ERR_REPORTED)
 190     return;
 191   ls->stream_flags |= LSFLAG_ERR_REPORTED;
 192
 193   struct log_msg errm = *m;
 194   char errbuf[128];
 195   char *name = (ls->name ? : "<unnamed>");
 196
 197   errm.flags = ((ls->stream_flags & LSFLAG_ERR_IS_FATAL) ? L_FATAL : L_ERROR);
 198   errm.flags |= L_LOGGER_ERR | (m->flags & LS_CTRL_MASK);
 199   errm.raw_msg = errbuf;
 200   if (err == EDEADLK)
 201     snprintf(errbuf, sizeof(errbuf), "Error logging to %s: Maximum nesting level of log streams exceeded", name);
 202   else
 203     {
 204       errno = err;
 205       snprintf(errbuf, sizeof(errbuf), "Error logging to %s: %m", name);
 206     }
 207   log_pass_msg(&log_stream_default, &errm);
 208
 209   if (ls->stream_flags & LSFLAG_ERR_IS_FATAL)
 210     do_die();
 211 }
 212
 213 /* Maximal depth of log_pass_msg recursion */
 214 #define LS_MAX_DEPTH 64
 215
 216 void
 217 log_pass_filtered(struct log_stream *ls, struct log_msg *m)
 218 {
 219   /* Pass the message to substreams */
 220   CLIST_FOR_EACH(simp_node *, s, ls->substreams)
 221     {
 222       log_pass_msg(s->p, m);
 223       if (m->error)
 224         return;
 225     }
 226
 227   /* Will pass to the handler of this stream... is there any? */
 228   if (!ls->handler)
 229     return;
 230
 231   /* Will print a message type? */
 232   char *type = NULL;
 233   if ((ls->msgfmt & LSFMT_TYPE) && LS_GET_TYPE(m->flags))
 234     type = log_type_name(m->flags);
 235
 236   /* Upper bound on message length */
 237   int len = strlen(m->raw_msg) + strlen(m->stime) + strlen(m->sutime) + 32;
 238   if (log_title)
 239     len += strlen(log_title);
 240   if (ls->name)
 241     len += strlen(ls->name);
 242   if (type)
 243     len += strlen(type) + 3;
 244
 245   /* Get a buffer and format the message */
 246   char *free_buf = NULL;
 247   if (len <= 256 || (m->flags & L_SIGHANDLER))
 248     m->m = alloca(len);
 249   else
 250     m->m = free_buf = xmalloc(len);
 251   char *p = m->m;
 252
 253   /* Level (2 chars) */
 254   if (ls->msgfmt & LSFMT_LEVEL)
 255     {
 256       *p++ = LS_LEVEL_LETTER(LS_GET_LEVEL(m->flags));
 257       *p++ = ' ';
 258     }
 259
 260   /* Time (|stime| + |sutime| + 1 chars) */
 261   if (ls->msgfmt & LSFMT_TIME)
 262     {
 263       const char *q = m->stime;
 264       while (*q)
 265         *p++ = *q++;
 266       if (ls->msgfmt & LSFMT_USEC)
 267         {
 268           q = m->sutime;
 269           while (*q)
 270             *p++ = *q++;
 271         }
 272       *p++ = ' ';
 273     }
 274
 275   /* Process name, PID ( |log_title| + 6 + (|PID|<=10) chars ) */
 276   if ((ls->msgfmt & LSFMT_TITLE) && log_title)
 277     {
 278       if ((ls->msgfmt & LSFMT_PID) && log_pid)
 279         p += sprintf(p, "[%s (%d)] ", log_title, log_pid);
 280       else
 281         p += sprintf(p, "[%s] ", log_title);
 282     }
 283   else
 284     {
 285       if ((ls->msgfmt & LSFMT_PID) && log_pid)
 286         p += sprintf(p, "[%d] ", log_pid);
 287     }
 288
 289   /* log_stream name ( |ls->name| + 4 chars ) */
 290   if (ls->msgfmt & LSFMT_LOGNAME)
 291     {
 292       if (ls->name)
 293         p += sprintf(p, "<%s> ", ls->name);
 294       else
 295         p += sprintf(p, "<?> ");
 296     }
 297
 298   /* Message type ( |type| + 3 chars ) */
 299   if (type)
 300     p += sprintf(p, "{%s} ", type);
 301
 302   /* The message itself ( |m| + 1 chars ) */
 303     {
 304       const char *q = m->raw_msg;
 305       while (*q)
 306         *p++ = *q++;
 307       *p++ = '\n';
 308       *p = '\0';
 309       m->m_len = p - m->m;
 310       int err = ls->handler(ls, m);
 311       if (err)
 312         log_report_err(ls, m, err);
 313     }
 314
 315   if (free_buf)
 316     xfree(free_buf);
 317 }
 318
 319 void
 320 log_pass_msg(struct log_stream *ls, struct log_msg *m)
 321 {
 322   ASSERT(ls);
 323
 324   /* Check recursion depth */
 325   if (m->depth > LS_MAX_DEPTH)
 326     {
 327       log_report_err(ls, m, EDEADLK);
 328       m->error = 1;
 329       return;
 330     }
 331
 332   /* Filter by level and type */
 333   if (!((1 << LS_GET_LEVEL(m->flags)) & ls->levels) ||
 334       !((1 << LS_GET_TYPE(m->flags)) & ls->types))
 335     return;
 336
 337   m->depth++;
 338
 339   if (ls->filter && ls->filter(ls, m))
 340     {
 341       // The filter might have called log_pass_filtered()
 342     }
 343   else
 344     log_pass_filtered(ls, m);
 345
 346   m->depth--;
 347 }
 348
 349 /*** Utility functions ***/
 350
 351 void
 352 msg(uint cat, const char *fmt, ...)
 353 {
 354   va_list args;
 355
 356   va_start(args, fmt);
 357   vmsg(cat, fmt, args);
 358   va_end(args);
 359 }
 360
 361 static void NONRET
 362 do_die(void)
 363 {
 364 #ifdef DEBUG_DIE_BY_ABORT
 365   abort();
 366 #else
 367   const char *env = getenv(CONFIG_UCW_ENV_VAR_DIE_BY_ABORT);
 368   if (env && *env)
 369     abort();
 370   exit(1);
 371 #endif
 372 }
 373
 374 void
 375 vdie(const char *fmt, va_list args)
 376 {
 377   vmsg(L_FATAL, fmt, args);
 378   if (log_die_hook)
 379     log_die_hook();
 380   do_die();
 381 }
 382
 383 void
 384 die(const char *fmt, ...)
 385 {
 386   va_list args;
 387   va_start(args, fmt);
 388   vdie(fmt, args);
 389 }
 390
 391 void
 392 assert_failed(const char *assertion, const char *file, int line)
 393 {
 394   msg(L_FATAL, "Assertion `%s' failed at %s:%d", assertion, file, line);
 395   abort();
 396 }
 397
 398 void
 399 assert_failed_msg(const char *assertion, const char *file, int line, const char *fmt, ...)
 400 {
 401   va_list args;
 402   va_start(args, fmt);
 403   vmsg(L_DEBUG, fmt, args);
 404   msg(L_FATAL, "Assertion `%s' failed at %s:%d", assertion, file, line);
 405   abort();
 406 }
 407
 408 void
 409 assert_failed_noinfo(void)
 410 {
 411   die("Internal error: Assertion failed.");
 412 }
 413
 414 static const char *
 415 log_basename(const char *n)
 416 {
 417   const char *p = n;
 418
 419   while (*n)
 420     if (*n++ == '/')
 421       p = n;
 422   return p;
 423 }
 424
 425 void
 426 log_init(const char *argv0)
 427 {
 428   if (argv0)
 429     {
 430       static char log_progname[32];
 431       strncpy(log_progname, log_basename(argv0), sizeof(log_progname)-1);
 432       log_progname[sizeof(log_progname)-1] = 0;
 433       log_title = log_progname;
 434     }
 435 }
 436
 437 void
 438 log_fork(void)
 439 {
 440   log_pid = getpid();
 441 }
 442
 443 #ifdef TEST
 444
 445 #include <syslog.h>
 446
 447 int main(void)
 448 {
 449   int type = log_find_type("foo");
 450   ASSERT(type < 0);
 451   type = log_register_type("foo");
 452
 453   struct log_stream *ls = log_new_syslog("local3", 0);
 454 #if 0
 455   log_add_substream(ls, ls);
 456   ls->stream_flags |= LSFLAG_ERR_IS_FATAL;
 457 #endif
 458   msg(L_INFO | ls->regnum, "Brum <%300s>", ":-)");
 459   log_set_format(log_default_stream(), ~0U, LSFMT_USEC | LSFMT_TYPE);
 460   msg(L_INFO | type, "Brum <%300s>", ":-)");
 461   log_close_all();
 462   return 0;
 463 }
 464
 465 #endif