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