Logging: Report logging errors.

Introduce an analogue of the infamous "Error while printing error message" :-)

When logging to a stream fails, the error is reported to the default stream,
but there are two precautions against infinite loops and floods of error
messages. First, we never report an error when logging of an error fails.
Second, we report only the first failure of a stream.

It is also possible to request program termination when logging fails.

diff --git a/ucw/lib.h b/ucw/lib.h
index 5167e24e05357ebab137ab15c2bfee94a796ee0f..b15b6d0cfe395391ee7254fe0684971c0bf790c7 100644 (file)
--- a/ucw/lib.h
+++ b/ucw/lib.h
@@ -100,11 +100,13 @@ enum log_levels {                 /** The available log levels to pass to msg() and friends. *
   L_WARN_R,                            // 'w'   (e.g., a packet received via network)
   L_ERROR_R,                           // 'e'
   L_FATAL,                             // '!' - Fatal error
+  L_MAX
 };
 
 #define LOG_LEVEL_NAMES P(DEBUG) P(INFO) P(WARN) P(ERROR) P(INFO_R) P(WARN_R) P(ERROR_R) P(FATAL)
 
-#define L_SIGHANDLER 0x80000000                /** Avoid operations that are unsafe in signal handlers **/
+#define L_SIGHANDLER   0x80000000      /** Avoid operations that are unsafe in signal handlers **/
+#define L_LOGGER_ERR   0x40000000      /** Used internally to avoid infinite reporting of logging errors **/
 
 /**
  * This is the basic printf-like function for logging a message.

diff --git a/ucw/log.c b/ucw/log.c
index 5c4a006982f863b760e9309d34deb51eaaa05e09..411a1068fbef1d62605da56a459b5a9b6a8ba506 100644 (file)
--- a/ucw/log.c
+++ b/ucw/log.c
@@ -26,6 +26,8 @@ char *log_title;
 int log_pid;
 void (*log_die_hook)(void);
 
+static void NONRET do_die(void);
+
 /*** The default log stream, which logs to stderr ***/
 
 static int default_log_handler(struct log_stream *ls UNUSED, struct log_msg *m)
@@ -147,6 +149,35 @@ vmsg(uns cat, const char *fmt, va_list args)
     xfree(m.raw_msg);
 }
 
+static void
+log_report_err(struct log_stream *ls, struct log_msg *m, int err)
+{
+  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
+    {
+      errno = err;
+      snprintf(errbuf, sizeof(errbuf), "Error logging to %s: %m", name);
+    }
+  log_pass_msg(0, &log_stream_default, &errm);
+
+  if (ls->stream_flags & LSFLAG_ERR_IS_FATAL)
+    do_die();
+}
+
 /* Maximal depth of log_pass_msg recursion */
 #define LS_MAX_DEPTH 64
 
@@ -158,10 +189,8 @@ log_pass_msg(int depth, struct log_stream *ls, struct log_msg *m)
   /* Check recursion depth */
   if (depth > LS_MAX_DEPTH)
     {
-      struct log_msg errm = *m;
-      errm.flags = L_ERROR | (m->flags & LS_CTRL_MASK);
-      errm.raw_msg = "Loop in the log_stream system detected.";
-      log_pass_msg(0, &log_stream_default, &errm);
+      log_report_err(ls, m, EDEADLK);
+      return 1;
     }
 
   /* Filter by level and hook function */
@@ -247,7 +276,9 @@ log_pass_msg(int depth, struct log_stream *ls, struct log_msg *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)
@@ -267,6 +298,16 @@ msg(unsigned int cat, const char *fmt, ...)
   va_end(args);
 }
 
+static void NONRET
+do_die(void)
+{
+#ifdef DEBUG_DIE_BY_ABORT
+  abort();
+#else
+  exit(1);
+#endif
+}
+
 void
 die(const char *fmt, ...)
 {
@@ -277,11 +318,7 @@ die(const char *fmt, ...)
   va_end(args);
   if (log_die_hook)
     log_die_hook();
-#ifdef DEBUG_DIE_BY_ABORT
-  abort();
-#else
-  exit(1);
-#endif
+  do_die();
 }
 
 void
@@ -333,6 +370,10 @@ log_fork(void)
 int main(void)
 {
   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>", ":-)");
   log_set_format(log_default_stream(), ~0U, LSFMT_USEC);
   msg(L_INFO, "Brum <%300s>", ":-)");

diff --git a/ucw/log.h b/ucw/log.h
index 0b1edd9a6a6482ed0a35e99809c909cd59e5db2f..0e4ea30d77e0102b652ba5ee282cdf84f06b00c3 100644 (file)
--- a/ucw/log.h
+++ b/ucw/log.h
@@ -37,6 +37,7 @@ struct log_stream {
   uns levels;                          // Bitmask of accepted severity levels (default: all)
   uns msgfmt;                          // Formatting flags (LSFMT_xxx)
   uns use_count;                       // Number of references to the stream
+  uns stream_flags;                    // Various other flags (LSFLAG_xxx)
   int (*filter)(struct log_stream* ls, struct log_msg *m);     // Filter function, return non-zero to discard the message
   clist substreams;                    // Pass the message to these streams (simple_list of pointers)
   int (*handler)(struct log_stream *ls, struct log_msg *m);    // Called to commit the message, return 0 for success, errno on error
@@ -58,6 +59,14 @@ enum ls_fmt {
 
 #define LSFMT_DEFAULT (LSFMT_LEVEL | LSFMT_TIME | LSFMT_TITLE | LSFMT_PID)     /** Default format **/
 
+/**
+ * General stream flags.
+ **/
+enum ls_flag {
+  LSFLAG_ERR_IS_FATAL =        1,              // When a logging error occurs, die() immediately
+  LSFLAG_ERR_REPORTED =        2,              // A logging error has been already reported on this stream
+};
+
 // Return the letter associated with a given severity level
 #define LS_LEVEL_LETTER(level) ("DIiWwEe!###"[( level )])