X-Git-Url: http://mj.ucw.cz/gitweb/?a=blobdiff_plain;f=ucw%2Flog.c;h=cf5d115ad78ee9aae4dd25e9f370fb3e0f5335e6;hb=f17e4350dcf0c033891e52b30b0c32a4a4fed5e0;hp=075caffbaba7175c340d5ac23c12d2a9cce7d8ad;hpb=50f3497ac9b5b0178de03522b2cfcb5893e7ac2f;p=libucw.git diff --git a/ucw/log.c b/ucw/log.c index 075caffb..cf5d115a 100644 --- a/ucw/log.c +++ b/ucw/log.c @@ -8,9 +8,10 @@ * of the GNU Lesser General Public License. */ -#include "ucw/lib.h" -#include "ucw/log.h" -#include "ucw/simple-lists.h" +#include +#include +#include +#include #include #include @@ -25,24 +26,29 @@ 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, const char *m, uns cat UNUSED) +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. - write(ls->idata, m, strlen(m)); + write(2, m->m, m->m_len); return 0; } -const struct log_stream log_stream_default = { +struct log_stream log_stream_default = { .name = "stderr", - .idata = 2, + .use_count = 1000000, .handler = default_log_handler, - .levels = LS_ALL_LEVELS, + .levels = ~0U, + .types = ~0U, .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 ***/ @@ -64,149 +70,204 @@ log_stream_by_flags(uns flags) { 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]; } +/*** Known message types ***/ + +char **log_type_names; + +char * +log_type_name(uns flags) +{ + uns type = LS_GET_TYPE(flags); + + if (!log_type_names || !log_type_names[type]) + return "default"; + else + return log_type_names[type]; +} + /*** Logging ***/ void vmsg(uns cat, const char *fmt, va_list args) { struct timeval tv; - int have_tm = 0; struct tm tm; va_list args2; char stime[24]; char sutime[12]; char msgbuf[256]; - char *m, *p; + char *p; int len; - struct log_stream *ls = log_stream_by_flags(cat); - - /* Check the stream existence */ - if (!ls) + uns sighandler = cat & L_SIGHANDLER; + struct log_stream *ls; + struct log_msg m = { .flags = cat }; + + /* 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 */ - if (!(cat & LSFLAG_SIGHANDLER)) + if (!sighandler) { /* CAVEAT: These calls are not safe in signal handlers. */ gettimeofday(&tv, NULL); + m.tv = &tv; if (localtime_r(&tv.tv_sec, &tm)) - have_tm = 1; + m.tm = &tm; } /* Generate time strings */ - if (have_tm) + if (m.tm) { strftime(stime, sizeof(stime), "%Y-%m-%d %H:%M:%S", &tm); snprintf(sutime, sizeof(sutime), ".%06d", (int)tv.tv_usec); + m.stime = stime; + m.sutime = sutime; } else { - snprintf(stime, sizeof(stime), "\?\?\?\?-\?\?-\?\? \?\?:\?\?:\?\?"); - snprintf(sutime, sizeof(sutime), ".\?\?\?\?\?\?"); + m.stime = "\?\?\?\?-\?\?-\?\? \?\?:\?\?:\?\?"; + m.sutime = ".\?\?\?\?\?\?"; } /* Generate the message string */ va_copy(args2, args); len = vsnprintf(msgbuf, sizeof(msgbuf), fmt, args2); va_end(args2); - if (len < (int) sizeof(msgbuf)) - m = msgbuf; + if (len < (int) sizeof(msgbuf) || sighandler) + m.raw_msg = msgbuf; else { - m = xmalloc(len+1); - vsnprintf(m, len+1, fmt, args); + m.raw_msg = xmalloc(len+1); + vsnprintf(m.raw_msg, len+1, fmt, args); } /* Remove non-printable characters and newlines */ - p = m; + 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 */ - if (log_pass_msg(0, ls, stime, sutime, m, cat)) + if (log_pass_msg(0, ls, &m)) { /* Error (such as infinite loop) occurred */ - log_pass_msg(0, (struct log_stream *) &log_stream_default, stime, sutime, m, cat); + log_pass_msg(0, &log_stream_default, &m); + } + + if (m.raw_msg != msgbuf) + 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 (m != msgbuf) - xfree(m); + if (ls->stream_flags & LSFLAG_ERR_IS_FATAL) + do_die(); } /* Maximal depth of log_pass_msg recursion */ #define LS_MAX_DEPTH 64 int -log_pass_msg(int depth, struct log_stream *ls, const char *stime, const char *sutime, const char *m, uns cat) +log_pass_msg(int depth, struct log_stream *ls, struct log_msg *m) { ASSERT(ls); /* Check recursion depth */ if (depth > LS_MAX_DEPTH) { - log_pass_msg(0, (struct log_stream *) &log_stream_default, stime, sutime, - "Loop in the log_stream system detected.", L_ERROR | (cat & LS_INTERNAL_MASK)); + log_report_err(ls, m, EDEADLK); return 1; } - /* Filter by level and hook function */ - if (!((1 << LS_GET_LEVEL(cat)) & ls->levels)) - return 0; - if (ls->filter && ls->filter(ls, m, cat)) + /* Filter by level, type and hook function */ + if (!((1 << LS_GET_LEVEL(m->flags)) & ls->levels) || + !((1 << LS_GET_TYPE(m->flags)) & ls->types) || + ls->filter && ls->filter(ls, m)) return 0; /* Pass the message to substreams */ CLIST_FOR_EACH(simp_node *, s, ls->substreams) - if (log_pass_msg(depth+1, s->p, stime, sutime, m, cat)) + if (log_pass_msg(depth+1, s->p, m)) return 1; /* Will pass to the handler of this stream... is there any? */ if (!ls->handler) return 0; + /* 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) + strlen(stime) + strlen(sutime) + 32; + int len = strlen(m->raw_msg) + strlen(m->stime) + strlen(m->sutime) + 32; if (log_title) 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; - char *buf; - if (len <= 256) - buf = alloca(len); + if (len <= 256 || (m->flags & L_SIGHANDLER)) + m->m = alloca(len); else - buf = free_buf = xmalloc(len); - char *p = buf; + m->m = free_buf = xmalloc(len); + char *p = m->m; /* Level (2 chars) */ if (ls->msgfmt & LSFMT_LEVEL) { - *p++ = LS_LEVEL_LETTER(LS_GET_LEVEL(cat)); + *p++ = LS_LEVEL_LETTER(LS_GET_LEVEL(m->flags)); *p++ = ' '; } /* Time (|stime| + |sutime| + 1 chars) */ if (ls->msgfmt & LSFMT_TIME) { - const char *q = (char *)stime; + const char *q = m->stime; while (*q) *p++ = *q++; if (ls->msgfmt & LSFMT_USEC) { - q = sutime; + q = m->sutime; while (*q) *p++ = *q++; } @@ -216,14 +277,14 @@ log_pass_msg(int depth, struct log_stream *ls, const char *stime, const char *su /* 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 { - if (ls->msgfmt & LSFMT_PID) + if ((ls->msgfmt & LSFMT_PID) && log_pid) p += sprintf(p, "[%d] ", log_pid); } @@ -236,14 +297,21 @@ log_pass_msg(int depth, struct log_stream *ls, const char *stime, const char *su 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; + const char *q = m->raw_msg; while (*q) *p++ = *q++; *p++ = '\n'; - *p++ = '\0'; - ls->handler(ls, buf, cat); + *p = '\0'; + m->m_len = p - m->m; + int err = ls->handler(ls, m); + if (err) + log_report_err(ls, m, err); } if (free_buf) @@ -263,16 +331,9 @@ msg(unsigned int cat, const char *fmt, ...) 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 @@ -280,6 +341,23 @@ die(const char *fmt, ...) #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) { @@ -316,11 +394,31 @@ log_init(const char *argv0) } } +void +log_fork(void) +{ + log_pid = getpid(); +} + #ifdef TEST +#include + int main(void) { - msg(L_INFO, "Brum <%300s>", ":-)"); + 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>", ":-)"); + log_set_format(log_default_stream(), ~0U, LSFMT_USEC | LSFMT_TYPE); + msg(L_INFO | type, "Brum <%300s>", ":-)"); + log_close_all(); return 0; }