Merge remote branch 'origin/maint-0.2.2'

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.
+

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;
   }

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) {
+      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

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);
 

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.