From 6199ac5fbec7f8a862440a8b65f7f299de4c2dbf Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Fri, 19 Nov 2010 22:22:43 -0500 Subject: Do not send Libevent log messages to a controller. Doing so could make Libevent call Libevent from inside a Libevent logging call, which is a recipe for reentrant confusion and hard-to-debug crashes. This would especially hurt if Libevent debug-level logging is enabled AND the user has a controller watching for low-severity log messages. Fix bug 2190; fix on 0.1.0.2-rc. --- src/common/compat_libevent.c | 10 +++++----- src/common/log.c | 4 ++++ src/common/torlog.h | 4 ++++ 3 files changed, 13 insertions(+), 5 deletions(-) (limited to 'src/common') diff --git a/src/common/compat_libevent.c b/src/common/compat_libevent.c index 250fa2bdb7..96843c73e4 100644 --- a/src/common/compat_libevent.c +++ b/src/common/compat_libevent.c @@ -65,19 +65,19 @@ libevent_logging_callback(int severity, const char *msg) } switch (severity) { case _EVENT_LOG_DEBUG: - log(LOG_DEBUG, LD_NET, "Message from libevent: %s", buf); + log(LOG_DEBUG, LD_NOCB|LD_NET, "Message from libevent: %s", buf); break; case _EVENT_LOG_MSG: - log(LOG_INFO, LD_NET, "Message from libevent: %s", buf); + log(LOG_INFO, LD_NOCB|LD_NET, "Message from libevent: %s", buf); break; case _EVENT_LOG_WARN: - log(LOG_WARN, LD_GENERAL, "Warning from libevent: %s", buf); + log(LOG_WARN, LD_NOCB|LD_GENERAL, "Warning from libevent: %s", buf); break; case _EVENT_LOG_ERR: - log(LOG_ERR, LD_GENERAL, "Error from libevent: %s", buf); + log(LOG_ERR, LD_NOCB|LD_GENERAL, "Error from libevent: %s", buf); break; default: - log(LOG_WARN, LD_GENERAL, "Message [%d] from libevent: %s", + log(LOG_WARN, LD_NOCB|LD_GENERAL, "Message [%d] from libevent: %s", severity, buf); break; } diff --git a/src/common/log.c b/src/common/log.c index b639e7a781..0ccda53887 100644 --- a/src/common/log.c +++ b/src/common/log.c @@ -278,6 +278,10 @@ 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; diff --git a/src/common/torlog.h b/src/common/torlog.h index 21219569e3..8b6cd1bf02 100644 --- a/src/common/torlog.h +++ b/src/common/torlog.h @@ -95,6 +95,10 @@ /** Number of logging domains in the code. */ #define N_LOGGING_DOMAINS 20 +/** This log message is not safe to send to a callback-based logger. + * Used as a flag, not a log domain. */ +#define LD_NOCB (1u<<31) + typedef uint32_t log_domain_mask_t; /** Configures which severities are logged for each logging domain for a given -- cgit v1.2.3-54-g00ecf From d166d18643197c57ba98d3a476df26c605554b26 Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Fri, 19 Nov 2010 22:52:32 -0500 Subject: Better fix for 2190: defer libevent->controller messages instead of dropping --- changes/bug2190 | 5 ++++ src/common/log.c | 73 +++++++++++++++++++++++++++++++++++++++++++++++++---- src/common/torlog.h | 5 ++-- src/or/main.c | 3 +++ 4 files changed, 79 insertions(+), 7 deletions(-) (limited to 'src/common') diff --git a/changes/bug2190 b/changes/bug2190 index 92ecba7eb0..0591acb6ff 100644 --- a/changes/bug2190 +++ b/changes/bug2190 @@ -4,3 +4,8 @@ running Libevent with debug logging enabled, and running Tor with a controller watching for low-severity log messages. Bugfix on 0.1.0.2-rc. Fixes bug 2190. + - Make Libevent log messages get delievered to controllers later, + and not from inside the Libevent log handler. This prevents + unsafe reentrant Libevent calls while still letting the log + messages get through. + diff --git a/src/common/log.c b/src/common/log.c index 0ccda53887..f26c5ef34a 100644 --- a/src/common/log.c +++ b/src/common/log.c @@ -103,6 +103,17 @@ static logfile_t *logfiles = NULL; 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; + log_domain_mask_t domain; + char *msg; +} pending_cb_message_t; + +/** Log messages waiting to be replayed onto callback-based logs */ +static smartlist_t *pending_cb_messages = NULL; + #define LOCK_LOGS() STMT_BEGIN \ tor_mutex_acquire(&log_mutex); \ STMT_END @@ -268,6 +279,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 (smartlist_len(pending_cb_messages)) + flush_pending_log_callbacks(); + lf = logfiles; while (lf) { if (! (lf->severities->masks[SEVERITY_MASK_IDX(severity)] & domain)) { @@ -278,10 +293,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; @@ -316,7 +327,15 @@ 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) { + 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); + } else { + lf->callback(severity, domain, end_of_prefix); + } lf = lf->next; continue; } @@ -555,6 +574,8 @@ init_logging(void) tor_mutex_init(&log_mutex); log_mutex_initialized = 1; } + if (pending_cb_messages == NULL) + pending_cb_messages = smartlist_create(); } /** Add a log handler to receive messages during startup (before the real @@ -613,6 +634,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 diff --git a/src/common/torlog.h b/src/common/torlog.h index 8b6cd1bf02..73c690631f 100644 --- a/src/common/torlog.h +++ b/src/common/torlog.h @@ -95,8 +95,8 @@ /** Number of logging domains in the code. */ #define N_LOGGING_DOMAINS 20 -/** This log message is not safe to send to a callback-based logger. - * Used as a flag, not a log domain. */ +/** This log message is not safe to send to a callback-based logger + * immediately. Used as a flag, not a log domain. */ #define LD_NOCB (1u<<31) typedef uint32_t log_domain_mask_t; @@ -141,6 +141,7 @@ void rollback_log_changes(void); void mark_logs_temp(void); void change_callback_log_severity(int loglevelMin, int loglevelMax, log_callback cb); +void flush_pending_log_callbacks(void); void log_set_application_name(const char *name); /* Outputs a message to stdout */ diff --git a/src/or/main.c b/src/or/main.c index 9bdbbc17a6..e13215bd2e 100644 --- a/src/or/main.c +++ b/src/or/main.c @@ -893,6 +893,9 @@ run_scheduled_events(time_t now) signewnym_impl(now); } + /* 0c. If we've deferred log messages for the controller, handle them now */ + flush_pending_log_callbacks(); + /** 1a. Every MIN_ONION_KEY_LIFETIME seconds, rotate the onion keys, * shut down and restart all cpuworkers, and update the directory if * necessary. -- cgit v1.2.3-54-g00ecf From 4a9d60734ce47cb3b5cb254e522116cd26b4823f Mon Sep 17 00:00:00 2001 From: Robert Ransom Date: Sat, 11 Dec 2010 04:41:35 -0800 Subject: Don't call flush_pending_log_callbacks while logging LD_NOCB messages. Found by boboper. --- src/common/log.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) (limited to 'src/common') diff --git a/src/common/log.c b/src/common/log.c index f26c5ef34a..f63c3fb9b4 100644 --- a/src/common/log.c +++ b/src/common/log.c @@ -280,7 +280,7 @@ logv(int severity, log_domain_mask_t domain, const char *funcname, assert(severity >= LOG_ERR && severity <= LOG_DEBUG); LOCK_LOGS(); - if (smartlist_len(pending_cb_messages)) + if ((! (domain & LD_NOCB)) && smartlist_len(pending_cb_messages)) flush_pending_log_callbacks(); lf = logfiles; -- cgit v1.2.3-54-g00ecf From cc051f9aca96b55533953cfcc10c86f9fe1e7b9a Mon Sep 17 00:00:00 2001 From: Robert Ransom Date: Sat, 11 Dec 2010 05:26:36 -0800 Subject: Only add each log message to pending_cb_messages once. --- src/common/log.c | 15 ++++++++++----- 1 file changed, 10 insertions(+), 5 deletions(-) (limited to 'src/common') diff --git a/src/common/log.c b/src/common/log.c index f63c3fb9b4..1324ff08c9 100644 --- a/src/common/log.c +++ b/src/common/log.c @@ -272,6 +272,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); @@ -328,11 +329,15 @@ logv(int severity, log_domain_mask_t domain, const char *funcname, continue; } else if (lf->callback) { if (domain & LD_NOCB) { - 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); + if (!callbacks_deferred) { + 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); } -- cgit v1.2.3-54-g00ecf