XML: Brief documentation of LibUCW-XML

[libucw.git] / ucw / log.c

diff --git a/ucw/log.c b/ucw/log.c
index f3c6aa146f5cc61a29cfdb403226669af356ad77..4a951e3277dc4bad99eae8a99feeaebece38a4c6 100644 (file)
--- a/ucw/log.c
+++ b/ucw/log.c
@@ -3,14 +3,16 @@
  *
  *     (c) 1997--2009 Martin Mares <mj@ucw.cz>
  *     (c) 2008 Tomas Gavenciak <gavento@ucw.cz>
  *
  *     (c) 1997--2009 Martin Mares <mj@ucw.cz>
  *     (c) 2008 Tomas Gavenciak <gavento@ucw.cz>

+ *     (c) 2014 Tomas Valla <tom@ucw.cz>

  *
  *     This software may be freely distributed and used according to the terms
  *     of the GNU Lesser General Public License.
  */
 
  *
  *     This software may be freely distributed and used according to the terms
  *     of the GNU Lesser General Public License.
  */
 

-#include "ucw/lib.h"
-#include "ucw/log.h"
-#include "ucw/simple-lists.h"
+#include <ucw/lib.h>
+#include <ucw/log.h>
+#include <ucw/log-internal.h>
+#include <ucw/simple-lists.h>

 
 #include <stdio.h>
 #include <stdlib.h>
 
 #include <stdio.h>
 #include <stdlib.h>


@@ -25,24 +27,31 @@ char *log_title;
 int log_pid;
 void (*log_die_hook)(void);
 
 int log_pid;
 void (*log_die_hook)(void);
 

+static void NONRET do_die(void);
+

 /*** The default log stream, which logs to stderr ***/
 
 /*** The default log stream, which logs to stderr ***/
 

-static int default_log_handler(struct log_stream *ls, struct log_msg *m)
+static int default_log_handler(struct log_stream *ls UNUSED, struct log_msg *m)

 {
   // This is a completely bare version of the log-file module. Errors are ignored.
 {
   // This is a completely bare version of the log-file module. Errors are ignored.

-  write(ls->idata, m->m, m->m_len);
+  if (write(2, m->m, m->m_len) < 0)
+    {
+    }

   return 0;
 }
 
   return 0;
 }
 

-const struct log_stream log_stream_default = {
+struct log_stream log_stream_default = {

   .name = "stderr",
   .name = "stderr",

-  .idata = 2,
+  .use_count = 1000000,

   .handler = default_log_handler,
   .handler = default_log_handler,

-  .levels = LS_ALL_LEVELS,
+  .levels = ~0U,
+  .types = ~0U,

   .msgfmt = LSFMT_DEFAULT,
   // an empty clist
   .msgfmt = LSFMT_DEFAULT,
   // an empty clist

-  .substreams.head.next = (cnode *) &log_stream_default.substreams.head,
-  .substreams.head.prev = (cnode *) &log_stream_default.substreams.head,
+  .substreams.head = {
+    .next = (cnode *) &log_stream_default.substreams.head,
+    .prev = (cnode *) &log_stream_default.substreams.head,
+  },

 };
 
 /*** Registry of streams and their identifiers ***/
 };
 
 /*** Registry of streams and their identifiers ***/


@@ -60,18 +69,33 @@ int log_streams_after = 0;          /* The first never-used index in log_streams.ptr */
  */
 
 struct log_stream *
  */
 
 struct log_stream *

-log_stream_by_flags(uns flags)
+log_stream_by_flags(uint flags)

 {
   int n = LS_GET_STRNUM(flags);
   if (n < 0 || n >= log_streams_after || log_streams.ptr[n]->regnum == -1)
 {
   int n = LS_GET_STRNUM(flags);
   if (n < 0 || n >= log_streams_after || log_streams.ptr[n]->regnum == -1)

-    return (n ? NULL : (struct log_stream *) &log_stream_default);
+    return (n ? NULL : &log_stream_default);

   return log_streams.ptr[n];
 }
 
   return log_streams.ptr[n];
 }
 

+/*** Known message types ***/
+
+char **log_type_names;
+
+char *
+log_type_name(uint flags)
+{
+  uint type = LS_GET_TYPE(flags);
+
+  if (!log_type_names || !log_type_names[type])
+    return "default";
+  else
+    return log_type_names[type];
+}
+

 /*** Logging ***/
 
 void
 /*** Logging ***/
 
 void

-vmsg(uns cat, const char *fmt, va_list args)
+vmsg(uint cat, const char *fmt, va_list args)

 {
   struct timeval tv;
   struct tm tm;
 {
   struct timeval tv;
   struct tm tm;


@@ -81,21 +105,25 @@ vmsg(uns cat, const char *fmt, va_list args)
   char msgbuf[256];
   char *p;
   int len;
   char msgbuf[256];
   char *p;
   int len;

-  struct log_stream *ls = log_stream_by_flags(cat);
+  uint sighandler = cat & L_SIGHANDLER;
+  struct log_stream *ls;

   struct log_msg m = { .flags = cat };
 
   struct log_msg m = { .flags = cat };
 

-  /* Check the stream existence */
-  if (!ls)
+  /* Find the destination stream */
+  if (sighandler)
+    ls = &log_stream_default;
+  else if (!(ls = log_stream_by_flags(cat)))

     {
     {

-      msg((LS_INTERNAL_MASK&cat)|L_WARN, "No log_stream with number %d! Logging to the default log.", LS_GET_STRNUM(cat));
-      ls = (struct log_stream *) &log_stream_default;
+      msg((LS_CTRL_MASK&cat)|L_WARN, "No log_stream with number %d! Logging to the default log.", LS_GET_STRNUM(cat));
+      ls = &log_stream_default;

     }
 
   /* Get the current time */
     }
 
   /* Get the current time */

-  if (!(cat & LSFLAG_SIGHANDLER))
+  if (!sighandler)

     {
       /* CAVEAT: These calls are not safe in signal handlers. */
       gettimeofday(&tv, NULL);
     {
       /* CAVEAT: These calls are not safe in signal handlers. */
       gettimeofday(&tv, NULL);

+      m.tv = &tv;

       if (localtime_r(&tv.tv_sec, &tm))
        m.tm = &tm;
     }
       if (localtime_r(&tv.tv_sec, &tm))
        m.tm = &tm;
     }


@@ -118,7 +146,7 @@ vmsg(uns cat, const char *fmt, va_list args)
   va_copy(args2, args);
   len = vsnprintf(msgbuf, sizeof(msgbuf), fmt, args2);
   va_end(args2);
   va_copy(args2, args);
   len = vsnprintf(msgbuf, sizeof(msgbuf), fmt, args2);
   va_end(args2);

-  if (len < (int) sizeof(msgbuf))
+  if (len < (int) sizeof(msgbuf) || sighandler)

     m.raw_msg = msgbuf;
   else
     {
     m.raw_msg = msgbuf;
   else
     {


@@ -130,53 +158,74 @@ vmsg(uns cat, const char *fmt, va_list args)
   p = m.raw_msg;
   while (*p)
     {
   p = m.raw_msg;
   while (*p)
     {

-      if (*p < 0x20 && *p != '\t')
+      if (*p >= 0 && *p < 0x20 && *p != '\t')

        *p = 0x7f;
       p++;
     }
 
   /* Pass the message to the log_stream */
        *p = 0x7f;
       p++;
     }
 
   /* Pass the message to the log_stream */

-  if (log_pass_msg(0, ls, &m))
+  log_pass_msg(ls, &m);
+  if (m.error)

     {
       /* Error (such as infinite loop) occurred */
     {
       /* Error (such as infinite loop) occurred */

-      log_pass_msg(0, (struct log_stream *) &log_stream_default, &m);
+      log_pass_msg(&log_stream_default, &m);

     }
 
   if (m.raw_msg != msgbuf)
     xfree(m.raw_msg);
 }
 
     }
 
   if (m.raw_msg != msgbuf)
     xfree(m.raw_msg);
 }
 

-/* Maximal depth of log_pass_msg recursion */
-#define LS_MAX_DEPTH 64
-
-int
-log_pass_msg(int depth, struct log_stream *ls, struct log_msg *m)
+static void
+log_report_err(struct log_stream *ls, struct log_msg *m, int err)

 {
 {

-  ASSERT(ls);
-
-  /* Check recursion depth */
-  if (depth > LS_MAX_DEPTH)
+  if (m->flags & L_LOGGER_ERR)
+    return;
+  if (ls->stream_flags & LSFLAG_ERR_REPORTED)
+    return;
+  ls->stream_flags |= LSFLAG_ERR_REPORTED;
+
+  struct log_msg errm = *m;
+  char errbuf[128];
+  char *name = (ls->name ? : "<unnamed>");
+
+  errm.flags = ((ls->stream_flags & LSFLAG_ERR_IS_FATAL) ? L_FATAL : L_ERROR);
+  errm.flags |= L_LOGGER_ERR | (m->flags & LS_CTRL_MASK);
+  errm.raw_msg = errbuf;
+  if (err == EDEADLK)
+    snprintf(errbuf, sizeof(errbuf), "Error logging to %s: Maximum nesting level of log streams exceeded", name);
+  else

     {
     {

-      struct log_msg errm = *m;
-      errm.flags = L_ERROR | (m->flags & LS_INTERNAL_MASK);
-      errm.raw_msg = "Loop in the log_stream system detected.";
-      log_pass_msg(0, (struct log_stream *) &log_stream_default, &errm);
+      errno = err;
+      snprintf(errbuf, sizeof(errbuf), "Error logging to %s: %m", name);

     }
     }

+  log_pass_msg(&log_stream_default, &errm);

 
 

-  /* Filter by level and hook function */
-  if (!((1 << LS_GET_LEVEL(m->flags)) & ls->levels))
-    return 0;
-  if (ls->filter && ls->filter(ls, m))
-    return 0;
+  if (ls->stream_flags & LSFLAG_ERR_IS_FATAL)
+    do_die();
+}

 
 

+/* Maximal depth of log_pass_msg recursion */
+#define LS_MAX_DEPTH 64
+
+void
+log_pass_filtered(struct log_stream *ls, struct log_msg *m)
+{

   /* Pass the message to substreams */
   CLIST_FOR_EACH(simp_node *, s, ls->substreams)
   /* Pass the message to substreams */
   CLIST_FOR_EACH(simp_node *, s, ls->substreams)

-    if (log_pass_msg(depth+1, s->p, m))
-      return 1;
+    {
+      log_pass_msg(s->p, m);
+      if (m->error)
+       return;
+    }

 
   /* Will pass to the handler of this stream... is there any? */
   if (!ls->handler)
 
   /* Will pass to the handler of this stream... is there any? */
   if (!ls->handler)

-    return 0;
+    return;
+
+  /* Will print a message type? */
+  char *type = NULL;
+  if ((ls->msgfmt & LSFMT_TYPE) && LS_GET_TYPE(m->flags))
+    type = log_type_name(m->flags);

 
   /* Upper bound on message length */
   int len = strlen(m->raw_msg) + strlen(m->stime) + strlen(m->sutime) + 32;
 
   /* Upper bound on message length */
   int len = strlen(m->raw_msg) + strlen(m->stime) + strlen(m->sutime) + 32;


@@ -184,10 +233,12 @@ log_pass_msg(int depth, struct log_stream *ls, struct log_msg *m)
     len += strlen(log_title);
   if (ls->name)
     len += strlen(ls->name);
     len += strlen(log_title);
   if (ls->name)
     len += strlen(ls->name);

+  if (type)
+    len += strlen(type) + 3;

 
   /* Get a buffer and format the message */
   char *free_buf = NULL;
 
   /* Get a buffer and format the message */
   char *free_buf = NULL;

-  if (len <= 256)
+  if (len <= 256 || (m->flags & L_SIGHANDLER))

     m->m = alloca(len);
   else
     m->m = free_buf = xmalloc(len);
     m->m = alloca(len);
   else
     m->m = free_buf = xmalloc(len);


@@ -218,14 +269,14 @@ log_pass_msg(int depth, struct log_stream *ls, struct log_msg *m)
   /* Process name, PID ( |log_title| + 6 + (|PID|<=10) chars ) */
   if ((ls->msgfmt & LSFMT_TITLE) && log_title)
     {
   /* Process name, PID ( |log_title| + 6 + (|PID|<=10) chars ) */
   if ((ls->msgfmt & LSFMT_TITLE) && log_title)
     {

-      if (ls->msgfmt & LSFMT_PID)
+      if ((ls->msgfmt & LSFMT_PID) && log_pid)

        p += sprintf(p, "[%s (%d)] ", log_title, log_pid);
       else
        p += sprintf(p, "[%s] ", log_title);
     }
   else
     {
        p += sprintf(p, "[%s (%d)] ", log_title, log_pid);
       else
        p += sprintf(p, "[%s] ", log_title);
     }
   else
     {

-      if (ls->msgfmt & LSFMT_PID)
+      if ((ls->msgfmt & LSFMT_PID) && log_pid)

        p += sprintf(p, "[%d] ", log_pid);
     }
 
        p += sprintf(p, "[%d] ", log_pid);
     }
 


@@ -238,6 +289,10 @@ log_pass_msg(int depth, struct log_stream *ls, struct log_msg *m)
        p += sprintf(p, "<?> ");
     }
 
        p += sprintf(p, "<?> ");
     }
 

+  /* Message type ( |type| + 3 chars ) */
+  if (type)
+    p += sprintf(p, "{%s} ", type);
+

   /* The message itself ( |m| + 1 chars ) */
     {
       const char *q = m->raw_msg;
   /* The message itself ( |m| + 1 chars ) */
     {
       const char *q = m->raw_msg;


@@ -246,18 +301,49 @@ log_pass_msg(int depth, struct log_stream *ls, struct log_msg *m)
       *p++ = '\n';
       *p = '\0';
       m->m_len = p - m->m;
       *p++ = '\n';
       *p = '\0';
       m->m_len = p - m->m;

-      ls->handler(ls, m);
+      int err = ls->handler(ls, m);
+      if (err)
+       log_report_err(ls, m, err);

     }
 
   if (free_buf)
     xfree(free_buf);
     }
 
   if (free_buf)
     xfree(free_buf);

-  return 0;
+}
+
+void
+log_pass_msg(struct log_stream *ls, struct log_msg *m)
+{
+  ASSERT(ls);
+
+  /* Check recursion depth */
+  if (m->depth > LS_MAX_DEPTH)
+    {
+      log_report_err(ls, m, EDEADLK);
+      m->error = 1;
+      return;
+    }
+
+  /* Filter by level and type */
+  if (!((1 << LS_GET_LEVEL(m->flags)) & ls->levels) ||
+      !((1 << LS_GET_TYPE(m->flags)) & ls->types))
+    return;
+
+  m->depth++;
+
+  if (ls->filter && ls->filter(ls, m))
+    {
+      // The filter might have called log_pass_filtered()
+    }
+  else
+    log_pass_filtered(ls, m);
+
+  m->depth--;

 }
 
 /*** Utility functions ***/
 
 void
 }
 
 /*** Utility functions ***/
 
 void

-msg(unsigned int cat, const char *fmt, ...)
+msg(uint cat, const char *fmt, ...)

 {
   va_list args;
 
 {
   va_list args;
 


@@ -266,23 +352,36 @@ msg(unsigned int cat, const char *fmt, ...)
   va_end(args);
 }
 
   va_end(args);
 }
 

-void
-die(const char *fmt, ...)
+static void NONRET
+do_die(void)

 {
 {

-  va_list args;
-
-  va_start(args, fmt);
-  vmsg(L_FATAL, fmt, args);
-  va_end(args);
-  if (log_die_hook)
-    log_die_hook();

 #ifdef DEBUG_DIE_BY_ABORT
   abort();
 #else
 #ifdef DEBUG_DIE_BY_ABORT
   abort();
 #else

+  const char *env = getenv(CONFIG_UCW_ENV_VAR_DIE_BY_ABORT);
+  if (env && *env)
+    abort();

   exit(1);
 #endif
 }
 
   exit(1);
 #endif
 }
 

+void
+vdie(const char *fmt, va_list args)
+{
+  vmsg(L_FATAL, fmt, args);
+  if (log_die_hook)
+    log_die_hook();
+  do_die();
+}
+
+void
+die(const char *fmt, ...)
+{
+  va_list args;
+  va_start(args, fmt);
+  vdie(fmt, args);
+}
+

 void
 assert_failed(const char *assertion, const char *file, int line)
 {
 void
 assert_failed(const char *assertion, const char *file, int line)
 {


@@ -290,6 +389,16 @@ assert_failed(const char *assertion, const char *file, int line)
   abort();
 }
 
   abort();
 }
 

+void
+assert_failed_msg(const char *assertion, const char *file, int line, const char *fmt, ...)
+{
+  va_list args;
+  va_start(args, fmt);
+  vmsg(L_DEBUG, fmt, args);
+  msg(L_FATAL, "Assertion `%s' failed at %s:%d", assertion, file, line);
+  abort();
+}
+

 void
 assert_failed_noinfo(void)
 {
 void
 assert_failed_noinfo(void)
 {


@@ -331,8 +440,19 @@ log_fork(void)
 
 int main(void)
 {
 
 int main(void)
 {

-  struct log_stream *ls = log_new_syslog(LOG_USER, "syslog");
+  int type = log_find_type("foo");
+  ASSERT(type < 0);
+  type = log_register_type("foo");
+
+  struct log_stream *ls = log_new_syslog("local3", 0);
+#if 0
+  log_add_substream(ls, ls);
+  ls->stream_flags |= LSFLAG_ERR_IS_FATAL;
+#endif

   msg(L_INFO | ls->regnum, "Brum <%300s>", ":-)");
   msg(L_INFO | ls->regnum, "Brum <%300s>", ":-)");

+  log_set_format(log_default_stream(), ~0U, LSFMT_USEC | LSFMT_TYPE);
+  msg(L_INFO | type, "Brum <%300s>", ":-)");
+  log_close_all();

   return 0;
 }
 
   return 0;
 }