diff --git a/changes/bug2190 b/changes/bug2190 new file mode 100644 index 0000000000..0591acb6ff --- /dev/null +++ b/changes/bug2190 @@ -0,0 +1,11 @@ + o Minor bugfixes + - Prevent calls from Libevent from inside Libevent log handlers. + This had potential to cause a nasty set of crashes, especially if + 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/compat_libevent.c b/src/common/compat_libevent.c index 7bbad54415..4e50cfaded 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 6f86406c2c..427ff62a86 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 @@ -280,6 +291,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); @@ -287,6 +299,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)) { @@ -331,7 +347,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_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; } @@ -570,6 +598,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 @@ -628,6 +658,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 d119993e87..7b48d0b32a 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 + * immediately. 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 @@ -137,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); void set_log_time_granularity(int granularity_msec); diff --git a/src/or/main.c b/src/or/main.c index 08a93133ef..7c6ef19be2 100644 --- a/src/or/main.c +++ b/src/or/main.c @@ -1065,6 +1065,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.