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