Better fix for 2190: defer libevent->controller messages instead of dropping

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

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

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 */

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.