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.next = (cnode *) &log_stream_default.substreams.head,
  49   .substreams.head.prev = (cnode *) &log_stream_default.substreams.head,
  50 };
  51
  52 /*** Registry of streams and their identifiers ***/
  53
  54 struct lsbuf_t log_streams;             /* A growing array of pointers to log_streams */
  55 int log_streams_after = 0;              /* The first never-used index in log_streams.ptr */
  56
  57 /*
  58  *  Find a stream by its identifier given as LS_SET_STRNUM(flags).
  59  *  Returns NULL if the stream doesn't exist or it's invalid.
  60  *
  61  *  If the log-stream machinery has not been initialized (which is normal for programs
  62  *  with no fancy logging), the log_streams gbuf is empty and this function only
  63  *  translates stream #0 to the static log_stream_default.
  64  */
  65
  66 struct log_stream *
  67 log_stream_by_flags(uns flags)
  68 {
  69   int n = LS_GET_STRNUM(flags);
  70   if (n < 0 || n >= log_streams_after || log_streams.ptr[n]->regnum == -1)
  71     return (n ? NULL : &log_stream_default);
  72   return log_streams.ptr[n];
  73 }
  74
  75 /*** Known message types ***/
  76
  77 char **log_type_names;
  78
  79 char *
  80 log_type_name(uns flags)
  81 {
  82   uns type = LS_GET_TYPE(flags);
  83
  84   if (!log_type_names || !log_type_names[type])
  85     return "default";
  86   else
  87     return log_type_names[type];
  88 }
  89
  90 /*** Logging ***/
  91
  92 void
  93 vmsg(uns cat, const char *fmt, va_list args)
  94 {
  95   struct timeval tv;
  96   struct tm tm;
  97   va_list args2;
  98   char stime[24];
  99   char sutime[12];
 100   char msgbuf[256];
 101   char *p;
 102   int len;
 103   uns sighandler = cat & L_SIGHANDLER;
 104   struct log_stream *ls;
 105   struct log_msg m = { .flags = cat };
 106
 107   /* Find the destination stream */
 108   if (sighandler)
 109     ls = &log_stream_default;
 110   else if (!(ls = log_stream_by_flags(cat)))
 111     {
 112       msg((LS_CTRL_MASK&cat)|L_WARN, "No log_stream with number %d! Logging to the default log.", LS_GET_STRNUM(cat));
 113       ls = &log_stream_default;
 114     }
 115
 116   /* Get the current time */
 117   if (!sighandler)
 118     {
 119       /* CAVEAT: These calls are not safe in signal handlers. */
 120       gettimeofday(&tv, NULL);
 121       m.tv = &tv;
 122       if (localtime_r(&tv.tv_sec, &tm))
 123         m.tm = &tm;
 124     }
 125
 126   /* Generate time strings */
 127   if (m.tm)
 128     {
 129       strftime(stime, sizeof(stime), "%Y-%m-%d %H:%M:%S", &tm);
 130       snprintf(sutime, sizeof(sutime), ".%06d", (int)tv.tv_usec);
 131       m.stime = stime;
 132       m.sutime = sutime;
 133     }
 134   else
 135     {
 136       m.stime = "\?\?\?\?-\?\?-\?\? \?\?:\?\?:\?\?";
 137       m.sutime = ".\?\?\?\?\?\?";
 138     }
 139
 140   /* Generate the message string */
 141   va_copy(args2, args);
 142   len = vsnprintf(msgbuf, sizeof(msgbuf), fmt, args2);
 143   va_end(args2);
 144   if (len < (int) sizeof(msgbuf) || sighandler)
 145     m.raw_msg = msgbuf;
 146   else
 147     {
 148       m.raw_msg = xmalloc(len+1);
 149       vsnprintf(m.raw_msg, len+1, fmt, args);
 150     }
 151
 152   /* Remove non-printable characters and newlines */
 153   p = m.raw_msg;
 154   while (*p)
 155     {
 156       if (*p >= 0 && *p < 0x20 && *p != '\t')
 157         *p = 0x7f;
 158       p++;
 159     }
 160
 161   /* Pass the message to the log_stream */
 162   if (log_pass_msg(0, ls, &m))
 163     {
 164       /* Error (such as infinite loop) occurred */
 165       log_pass_msg(0, &log_stream_default, &m);
 166     }
 167
 168   if (m.raw_msg != msgbuf)
 169     xfree(m.raw_msg);
 170 }
 171
 172 static void
 173 log_report_err(struct log_stream *ls, struct log_msg *m, int err)
 174 {
 175   if (m->flags & L_LOGGER_ERR)
 176     return;
 177   if (ls->stream_flags & LSFLAG_ERR_REPORTED)
 178     return;
 179   ls->stream_flags |= LSFLAG_ERR_REPORTED;
 180
 181   struct log_msg errm = *m;
 182   char errbuf[128];
 183   char *name = (ls->name ? : "<unnamed>");
 184
 185   errm.flags = ((ls->stream_flags & LSFLAG_ERR_IS_FATAL) ? L_FATAL : L_ERROR);
 186   errm.flags |= L_LOGGER_ERR | (m->flags & LS_CTRL_MASK);
 187   errm.raw_msg = errbuf;
 188   if (err == EDEADLK)
 189     snprintf(errbuf, sizeof(errbuf), "Error logging to %s: Maximum nesting level of log streams exceeded", name);
 190   else
 191     {
 192       errno = err;
 193       snprintf(errbuf, sizeof(errbuf), "Error logging to %s: %m", name);
 194     }
 195   log_pass_msg(0, &log_stream_default, &errm);
 196
 197   if (ls->stream_flags & LSFLAG_ERR_IS_FATAL)
 198     do_die();
 199 }
 200
 201 /* Maximal depth of log_pass_msg recursion */
 202 #define LS_MAX_DEPTH 64
 203
 204 int
 205 log_pass_msg(int depth, struct log_stream *ls, struct log_msg *m)
 206 {
 207   ASSERT(ls);
 208
 209   /* Check recursion depth */
 210   if (depth > LS_MAX_DEPTH)
 211     {
 212       log_report_err(ls, m, EDEADLK);
 213       return 1;
 214     }
 215
 216   /* Filter by level, type and hook function */
 217   if (!((1 << LS_GET_LEVEL(m->flags)) & ls->levels) ||
 218       !((1 << LS_GET_TYPE(m->flags)) & ls->types) ||
 219       ls->filter && ls->filter(ls, m))
 220     return 0;
 221
 222   /* Pass the message to substreams */
 223   CLIST_FOR_EACH(simp_node *, s, ls->substreams)
 224     if (log_pass_msg(depth+1, s->p, m))
 225       return 1;
 226
 227   /* Will pass to the handler of this stream... is there any? */
 228   if (!ls->handler)
 229     return 0;
 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   return 0;
 318 }
 319
 320 /*** Utility functions ***/
 321
 322 void
 323 msg(unsigned int cat, const char *fmt, ...)
 324 {
 325   va_list args;
 326
 327   va_start(args, fmt);
 328   vmsg(cat, fmt, args);
 329   va_end(args);
 330 }
 331
 332 static void NONRET
 333 do_die(void)
 334 {
 335 #ifdef DEBUG_DIE_BY_ABORT
 336   abort();
 337 #else
 338   exit(1);
 339 #endif
 340 }
 341
 342 void
 343 die(const char *fmt, ...)
 344 {
 345   va_list args;
 346
 347   va_start(args, fmt);
 348   vmsg(L_FATAL, fmt, args);
 349   va_end(args);
 350   if (log_die_hook)
 351     log_die_hook();
 352   do_die();
 353 }
 354
 355 void
 356 assert_failed(const char *assertion, const char *file, int line)
 357 {
 358   msg(L_FATAL, "Assertion `%s' failed at %s:%d", assertion, file, line);
 359   abort();
 360 }
 361
 362 void
 363 assert_failed_noinfo(void)
 364 {
 365   die("Internal error: Assertion failed.");
 366 }
 367
 368 static const char *
 369 log_basename(const char *n)
 370 {
 371   const char *p = n;
 372
 373   while (*n)
 374     if (*n++ == '/')
 375       p = n;
 376   return p;
 377 }
 378
 379 void
 380 log_init(const char *argv0)
 381 {
 382   if (argv0)
 383     {
 384       static char log_progname[32];
 385       strncpy(log_progname, log_basename(argv0), sizeof(log_progname)-1);
 386       log_progname[sizeof(log_progname)-1] = 0;
 387       log_title = log_progname;
 388     }
 389 }
 390
 391 void
 392 log_fork(void)
 393 {
 394   log_pid = getpid();
 395 }
 396
 397 #ifdef TEST
 398
 399 #include <syslog.h>
 400
 401 int main(void)
 402 {
 403   int type = log_find_type("foo");
 404   ASSERT(type < 0);
 405   type = log_register_type("foo");
 406
 407   struct log_stream *ls = log_new_syslog("local3", 0);
 408 #if 0
 409   log_add_substream(ls, ls);
 410   ls->stream_flags |= LSFLAG_ERR_IS_FATAL;
 411 #endif
 412   msg(L_INFO | ls->regnum, "Brum <%300s>", ":-)");
 413   log_set_format(log_default_stream(), ~0U, LSFMT_USEC | LSFMT_TYPE);
 414   msg(L_INFO | type, "Brum <%300s>", ":-)");
 415   log_close_all();
 416   return 0;
 417 }
 418
 419 #endif