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