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