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