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