From 3ad33092fedd857c36895fa4237c59e66e1fe0eb Mon Sep 17 00:00:00 2001 From: Martin Mares Date: Thu, 19 Feb 2009 18:48:23 +0100 Subject: [PATCH] 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. --- ucw/lib.h | 4 +++- ucw/log.c | 61 ++++++++++++++++++++++++++++++++++++++++++++++--------- ucw/log.h | 9 ++++++++ 3 files changed, 63 insertions(+), 11 deletions(-) diff --git a/ucw/lib.h b/ucw/lib.h index 5167e24e..b15b6d0c 100644 --- 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 5c4a0069..411a1068 100644 --- 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 ? : ""); + + 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 0b1edd9a..0e4ea30d 100644 --- 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 )]) -- 2.39.2