diff options
Diffstat (limited to 'src/common/log.c')
| -rw-r--r-- | src/common/log.c | 274 |
1 files changed, 185 insertions, 89 deletions
diff --git a/src/common/log.c b/src/common/log.c index fe93bd7f57..ac98f13539 100644 --- a/src/common/log.c +++ b/src/common/log.c @@ -33,13 +33,15 @@ #include "compat.h" #include "util.h" #define LOG_PRIVATE -#include "log.h" +#include "torlog.h" #include "container.h" -#include <event.h> - +/** @{ */ +/** The string we stick at the end of a log message when it is too long, + * and its length. */ #define TRUNCATED_STR "[...truncated]" #define TRUNCATED_STR_LEN 14 +/** @} */ /** Information for a single logfile; only used in log.c */ typedef struct logfile_t { @@ -83,7 +85,7 @@ should_log_function_name(log_domain_mask_t domain, int severity) /* All debugging messages occur in interesting places. */ return 1; case LOG_NOTICE: - case LOG_WARN: + case LOG_WARN: case LOG_ERR: /* We care about places where bugs occur. */ return (domain == LD_BUG); @@ -99,15 +101,31 @@ static int log_mutex_initialized = 0; /** Linked list of logfile_t. */ static logfile_t *logfiles = NULL; +/** Boolean: do we report logging domains? */ +static int log_domains_are_logged = 0; + #ifdef HAVE_SYSLOG_H /** The number of open syslog log handlers that we have. When this reaches 0, * we can close our connection to the syslog facility. */ static int syslog_count = 0; #endif +/** Represents a log message that we are going to send to callback-driven + * loggers once we can do so in a non-reentrant way. */ +typedef struct pending_cb_message_t { + int severity; /**< The severity of the message */ + log_domain_mask_t domain; /**< The domain of the message */ + char *msg; /**< The content of the message */ +} pending_cb_message_t; + +/** Log messages waiting to be replayed onto callback-based logs */ +static smartlist_t *pending_cb_messages = NULL; + +/** Lock the log_mutex to prevent others from changing the logfile_t list */ #define LOCK_LOGS() STMT_BEGIN \ tor_mutex_acquire(&log_mutex); \ STMT_END +/** Unlock the log_mutex */ #define UNLOCK_LOGS() STMT_BEGIN tor_mutex_release(&log_mutex); STMT_END /** What's the lowest log level anybody cares about? Checking this lets us @@ -117,6 +135,9 @@ int _log_global_min_severity = LOG_NOTICE; static void delete_log(logfile_t *victim); static void close_log(logfile_t *victim); +static char *domain_to_string(log_domain_mask_t domain, + char *buf, size_t buflen); + /** Name of the application: used to generate the message we write at the * start of each new log. */ static char *appname = NULL; @@ -208,13 +229,34 @@ format_msg(char *buf, size_t buf_len, size_t n; int r; char *end_of_prefix; + char *buf_end; - assert(buf_len >= 2); /* prevent integer underflow */ + assert(buf_len >= 16); /* prevent integer underflow and general stupidity */ buf_len -= 2; /* subtract 2 characters so we have room for \n\0 */ + buf_end = buf+buf_len; /* point *after* the last char we can write to */ n = _log_prefix(buf, buf_len, severity); end_of_prefix = buf+n; + if (log_domains_are_logged) { + char *cp = buf+n; + if (cp == buf_end) goto format_msg_no_room_for_domains; + *cp++ = '{'; + if (cp == buf_end) goto format_msg_no_room_for_domains; + cp = domain_to_string(domain, cp, (buf+buf_len-cp)); + if (cp == buf_end) goto format_msg_no_room_for_domains; + *cp++ = '}'; + if (cp == buf_end) goto format_msg_no_room_for_domains; + *cp++ = ' '; + if (cp == buf_end) goto format_msg_no_room_for_domains; + end_of_prefix = cp; + n = cp-buf; + format_msg_no_room_for_domains: + /* This will leave end_of_prefix and n unchanged, and thus cause + * whatever log domain string we had written to be clobbered. */ + ; + } + if (funcname && should_log_function_name(domain, severity)) { r = tor_snprintf(buf+n, buf_len-n, "%s(): ", funcname); if (r<0) @@ -263,6 +305,7 @@ logv(int severity, log_domain_mask_t domain, const char *funcname, int formatted = 0; logfile_t *lf; char *end_of_prefix=NULL; + int callbacks_deferred = 0; /* Call assert, not tor_assert, since tor_assert calls log on failure. */ assert(format); @@ -270,6 +313,10 @@ logv(int severity, log_domain_mask_t domain, const char *funcname, * interesting and hard to diagnose effects */ assert(severity >= LOG_ERR && severity <= LOG_DEBUG); LOCK_LOGS(); + + if ((! (domain & LD_NOCB)) && smartlist_len(pending_cb_messages)) + flush_pending_log_callbacks(); + lf = logfiles; while (lf) { if (! (lf->severities->masks[SEVERITY_MASK_IDX(severity)] & domain)) { @@ -280,10 +327,6 @@ logv(int severity, log_domain_mask_t domain, const char *funcname, lf = lf->next; continue; } - if (lf->callback && (domain & LD_NOCB)) { - lf = lf->next; - continue; - } if (lf->seems_dead) { lf = lf->next; continue; @@ -295,6 +338,7 @@ logv(int severity, log_domain_mask_t domain, const char *funcname, &msg_len); formatted = 1; } + if (lf->is_syslog) { #ifdef HAVE_SYSLOG_H char *m = end_of_prefix; @@ -318,7 +362,19 @@ logv(int severity, log_domain_mask_t domain, const char *funcname, lf = lf->next; continue; } else if (lf->callback) { - lf->callback(severity, domain, end_of_prefix); + if (domain & LD_NOCB) { + if (!callbacks_deferred && pending_cb_messages) { + pending_cb_message_t *msg = tor_malloc(sizeof(pending_cb_message_t)); + msg->severity = severity; + msg->domain = domain; + msg->msg = tor_strdup(end_of_prefix); + smartlist_add(pending_cb_messages, msg); + + callbacks_deferred = 1; + } + } else { + lf->callback(severity, domain, end_of_prefix); + } lf = lf->next; continue; } @@ -332,9 +388,12 @@ logv(int severity, log_domain_mask_t domain, const char *funcname, UNLOCK_LOGS(); } -/** Output a message to the log. */ +/** Output a message to the log. It gets logged to all logfiles that + * care about messages with <b>severity</b> in <b>domain</b>. The content + * is formatted printf-style based on <b>format</b> and extra arguments. + * */ void -_log(int severity, log_domain_mask_t domain, const char *format, ...) +tor_log(int severity, log_domain_mask_t domain, const char *format, ...) { va_list ap; if (severity > _log_global_min_severity) @@ -346,6 +405,9 @@ _log(int severity, log_domain_mask_t domain, const char *format, ...) /** Output a message to the log, prefixed with a function name <b>fn</b>. */ #ifdef __GNUC__ +/** GCC-based implementation of the log_fn backend, used when we have + * variadic macros. All arguments are as for log_fn, except for + * <b>fn</b>, which is the name of the calling functions. */ void _log_fn(int severity, log_domain_mask_t domain, const char *fn, const char *format, ...) @@ -358,6 +420,11 @@ _log_fn(int severity, log_domain_mask_t domain, const char *fn, va_end(ap); } #else +/** @{ */ +/** Variant implementation of log_fn, log_debug, log_info,... for C compilers + * without variadic macros. In this case, the calling function sets + * _log_fn_function_name to the name of the function, then invokes the + * appropriate _log_fn, _log_debug, etc. */ const char *_log_fn_function_name=NULL; void _log_fn(int severity, log_domain_mask_t domain, const char *format, ...) @@ -426,12 +493,15 @@ _log_err(log_domain_mask_t domain, const char *format, ...) va_end(ap); _log_fn_function_name = NULL; } +/** @} */ #endif /** Free all storage held by <b>victim</b>. */ static void log_free(logfile_t *victim) { + if (!victim) + return; tor_free(victim->severities); tor_free(victim->filename); tor_free(victim); @@ -442,9 +512,12 @@ void logs_free_all(void) { logfile_t *victim, *next; + smartlist_t *messages; LOCK_LOGS(); next = logfiles; logfiles = NULL; + messages = pending_cb_messages; + pending_cb_messages = NULL; UNLOCK_LOGS(); while (next) { victim = next; @@ -454,6 +527,12 @@ logs_free_all(void) } tor_free(appname); + SMARTLIST_FOREACH(messages, pending_cb_message_t *, msg, { + tor_free(msg->msg); + tor_free(msg); + }); + smartlist_free(messages); + /* We _could_ destroy the log mutex here, but that would screw up any logs * that happened between here and the end of execution. */ } @@ -539,8 +618,7 @@ add_stream_log_impl(const log_severity_list_t *severity, * to <b>fd</b>. Steals a reference to <b>severity</b>; the caller must * not use it after calling this function. */ void -add_stream_log(const log_severity_list_t *severity, - const char *name, int fd) +add_stream_log(const log_severity_list_t *severity, const char *name, int fd) { LOCK_LOGS(); add_stream_log_impl(severity, name, fd); @@ -555,6 +633,18 @@ init_logging(void) tor_mutex_init(&log_mutex); log_mutex_initialized = 1; } + if (pending_cb_messages == NULL) + pending_cb_messages = smartlist_create(); +} + +/** Set whether we report logging domains as a part of our log messages. + */ +void +logs_set_domain_logging(int enabled) +{ + LOCK_LOGS(); + log_domains_are_logged = enabled; + UNLOCK_LOGS(); } /** Add a log handler to receive messages during startup (before the real @@ -613,6 +703,48 @@ change_callback_log_severity(int loglevelMin, int loglevelMax, UNLOCK_LOGS(); } +/** If there are any log messages that were genered with LD_NOCB waiting to + * be sent to callback-based loggers, send them now. */ +void +flush_pending_log_callbacks(void) +{ + logfile_t *lf; + smartlist_t *messages, *messages_tmp; + + LOCK_LOGS(); + if (0 == smartlist_len(pending_cb_messages)) { + UNLOCK_LOGS(); + return; + } + + messages = pending_cb_messages; + pending_cb_messages = smartlist_create(); + do { + SMARTLIST_FOREACH_BEGIN(messages, pending_cb_message_t *, msg) { + const int severity = msg->severity; + const int domain = msg->domain; + for (lf = logfiles; lf; lf = lf->next) { + if (! lf->callback || lf->seems_dead || + ! (lf->severities->masks[SEVERITY_MASK_IDX(severity)] & domain)) { + continue; + } + lf->callback(severity, domain, msg->msg); + } + tor_free(msg->msg); + tor_free(msg); + } SMARTLIST_FOREACH_END(msg); + smartlist_clear(messages); + + messages_tmp = pending_cb_messages; + pending_cb_messages = messages; + messages = messages_tmp; + } while (smartlist_len(messages)); + + smartlist_free(messages); + + UNLOCK_LOGS(); +} + /** Close any log handlers added by add_temp_log() or marked by * mark_logs_temp(). */ void @@ -682,13 +814,11 @@ add_file_log(const log_severity_list_t *severity, const char *filename) logfiles->needs_close = 1; lf = logfiles; _log_global_min_severity = get_min_log_level(); - UNLOCK_LOGS(); if (log_tor_version(lf, 0) < 0) { - LOCK_LOGS(); delete_log(lf); - UNLOCK_LOGS(); } + UNLOCK_LOGS(); return 0; } @@ -709,7 +839,6 @@ add_syslog_log(const log_severity_list_t *severity) lf->fd = -1; lf->severities = tor_memdup(severity, sizeof(log_severity_list_t)); lf->filename = tor_strdup("<syslog>"); - lf->is_syslog = 1; LOCK_LOGS(); @@ -751,7 +880,7 @@ log_level_to_string(int level) static const char *domain_list[] = { "GENERAL", "CRYPTO", "NET", "CONFIG", "FS", "PROTOCOL", "MM", "HTTP", "APP", "CONTROL", "CIRC", "REND", "BUG", "DIR", "DIRSERV", - "OR", "EDGE", "ACCT", "HIST", NULL + "OR", "EDGE", "ACCT", "HIST", "HANDSHAKE", NULL }; /** Return a bitmask for the log domain for which <b>domain</b> is the name, @@ -766,18 +895,41 @@ parse_log_domain(const char *domain) } return 0; } -#if 0 -/** Translate a bitmask of log domains to a string, or NULL if the bitmask - * is undecodable. */ -static const char * -domain_to_string(log_domain_mask_t domain) + +/** Translate a bitmask of log domains to a string. */ +static char * +domain_to_string(log_domain_mask_t domain, char *buf, size_t buflen) { - int bit = tor_log2(domain); - if ((bit == 0 && domain == 0) || bit >= N_LOGGING_DOMAINS) - return NULL; - return domain_list[bit]; + char *cp = buf; + char *eos = buf+buflen; + + buf[0] = '\0'; + if (! domain) + return buf; + while (1) { + const char *d; + int bit = tor_log2(domain); + size_t n; + if (bit >= N_LOGGING_DOMAINS) { + tor_snprintf(buf, buflen, "<BUG:Unknown domain %lx>", (long)domain); + return buf+strlen(buf); + } + d = domain_list[bit]; + n = strlcpy(cp, d, eos-cp); + if (n >= buflen) { + tor_snprintf(buf, buflen, "<BUG:Truncating domain %lx>", (long)domain); + return buf+strlen(buf); + } + cp += n; + domain &= ~(1<<bit); + + if (domain == 0 || (eos-cp) < 2) + return cp; + + memcpy(cp, ",", 2); /*Nul-terminated ,"*/ + cp++; + } } -#endif /** Parse a log severity pattern in *<b>cfg_ptr</b>. Advance cfg_ptr after * the end of the severityPattern. Set the value of <b>severity_out</b> to @@ -853,7 +1005,10 @@ parse_log_severity_config(const char **cfg_ptr, smartlist_free(domains_list); if (err) return -1; - domains &= ~neg_domains; + if (domains == 0 && neg_domains) + domains = ~neg_domains; + else + domains &= ~neg_domains; cfg = eat_whitespace(closebracket+1); } else { ++got_an_unqualified_range; @@ -929,65 +1084,6 @@ switch_logs_debug(void) UNLOCK_LOGS(); } -#ifdef HAVE_EVENT_SET_LOG_CALLBACK -/** A string which, if it appears in a libevent log, should be ignored. */ -static const char *suppress_msg = NULL; -/** Callback function passed to event_set_log() so we can intercept - * log messages from libevent. */ -static void -libevent_logging_callback(int severity, const char *msg) -{ - char buf[1024]; - size_t n; - if (suppress_msg && strstr(msg, suppress_msg)) - return; - n = strlcpy(buf, msg, sizeof(buf)); - if (n && n < sizeof(buf) && buf[n-1] == '\n') { - buf[n-1] = '\0'; - } - switch (severity) { - case _EVENT_LOG_DEBUG: - log(LOG_DEBUG, LD_NOCB|LD_NET, "Message from libevent: %s", buf); - break; - case _EVENT_LOG_MSG: - log(LOG_INFO, LD_NOCB|LD_NET, "Message from libevent: %s", buf); - break; - case _EVENT_LOG_WARN: - log(LOG_WARN, LD_NOCB|LD_GENERAL, "Warning from libevent: %s", buf); - break; - case _EVENT_LOG_ERR: - log(LOG_ERR, LD_NOCB|LD_GENERAL, "Error from libevent: %s", buf); - break; - default: - log(LOG_WARN, LD_NOCB|LD_GENERAL, "Message [%d] from libevent: %s", - severity, buf); - break; - } -} -/** Set hook to intercept log messages from libevent. */ -void -configure_libevent_logging(void) -{ - event_set_log_callback(libevent_logging_callback); -} -/** Ignore any libevent log message that contains <b>msg</b>. */ -void -suppress_libevent_log_msg(const char *msg) -{ - suppress_msg = msg; -} -#else -void -configure_libevent_logging(void) -{ -} -void -suppress_libevent_log_msg(const char *msg) -{ - (void)msg; -} -#endif - #if 0 static void dump_log_info(logfile_t *lf) |