Remember log messages that happen before logs are configured

(And replay them once we know our first real logs.)

This is an implementation for issue 6938.  It solves the problem of
early log mesages not getting sent to log files, but not the issue of
early log messages not getting sent to controllers.

changes/ticket6938

@@ -0,0 +1,4 @@
+  o Minor features:
+
+    - When opening a log file at startup, send it every log message that we
+      generated between startup and opening it.  Closes ticket 6938.

src/common/log.c

@@ -120,6 +120,7 @@ static int syslog_count = 0;
 typedef struct pending_log_message_t {
   int severity; /**< The severity of the message */
   log_domain_mask_t domain; /**< The domain of the message */
+  char *fullmsg; /**< The message, with all decorations */
   char *msg; /**< The content of the message */
 } pending_log_message_t;
 
@@ -130,6 +131,19 @@ static smartlist_t *pending_cb_messages = NULL;
  */
 static smartlist_t *pending_startup_messages = NULL;
 
+/** Number of bytes of messages queued in pending_startup_messages.  (This is
+ * the length of the messages, not the number of bytes used to store
+ * them.) */
+static size_t pending_startup_messages_len;
+
+/** True iff we should store messages while waiting for the logs to get
+ * configured. */
+static int queue_startup_messages = 1;
+
+/** Don't store more than this many bytes of messages while waiting for the
+ * logs to get configured. */
+#define MAX_STARTUP_MSG_LEN (1<<16)
+
 /** Lock the log_mutex to prevent others from changing the logfile_t list */
 #define LOCK_LOGS() STMT_BEGIN                                          \
   tor_mutex_acquire(&log_mutex);                                        \
@@ -335,12 +349,14 @@ format_msg(char *buf, size_t buf_len,
 
 /* Create a new pending_log_message_t with appropriate values */
 static pending_log_message_t *
-pending_log_message_new(int severity, log_domain_mask_t domain, const char *msg)
+pending_log_message_new(int severity, log_domain_mask_t domain,
+                        const char *fullmsg, const char *shortmsg)
 {
   pending_log_message_t *m = tor_malloc(sizeof(pending_log_message_t));
   m->severity = severity;
   m->domain = domain;
-  m->msg = tor_strdup(msg);
+  m->fullmsg = fullmsg ? tor_strdup(fullmsg) : NULL;
+  m->msg = tor_strdup(shortmsg);
   return m;
 }
 
@@ -351,6 +367,7 @@ pending_log_message_free(pending_log_message_t *msg)
   if (!msg)
     return;
   tor_free(msg->msg);
+  tor_free(msg->fullmsg);
   tor_free(msg);
 }
 
@@ -411,7 +428,7 @@ logfile_deliver(logfile_t *lf, const char *buf, size_t msg_len,
     if (domain & LD_NOCB) {
       if (!*callbacks_deferred && pending_cb_messages) {
         smartlist_add(pending_cb_messages,
-                  pending_log_message_new(severity,domain,msg_after_prefix));
+            pending_log_message_new(severity,domain,NULL,msg_after_prefix));
         *callbacks_deferred = 1;
       }
     } else {
@@ -451,6 +468,18 @@ logv,(int severity, log_domain_mask_t domain, const char *funcname,
   if ((! (domain & LD_NOCB)) && smartlist_len(pending_cb_messages))
     flush_pending_log_callbacks();
 
+  if (queue_startup_messages &&
+      pending_startup_messages_len < MAX_STARTUP_MSG_LEN) {
+    end_of_prefix =
+      format_msg(buf, sizeof(buf), domain, severity, funcname, suffix,
+      format, ap, &msg_len);
+    formatted = 1;
+
+    smartlist_add(pending_startup_messages,
+      pending_log_message_new(severity,domain,buf,end_of_prefix));
+    pending_startup_messages_len += msg_len;
+  }
+
   for (lf = logfiles; lf; lf = lf->next) {
     if (! logfile_wants_message(lf, severity, domain))
       continue;
@@ -767,12 +796,14 @@ void
 logs_free_all(void)
 {
   logfile_t *victim, *next;
-  smartlist_t *messages;
+  smartlist_t *messages, *messages2;
   LOCK_LOGS();
   next = logfiles;
   logfiles = NULL;
   messages = pending_cb_messages;
   pending_cb_messages = NULL;
+  messages2 = pending_startup_messages;
+  pending_startup_messages = NULL;
   UNLOCK_LOGS();
   while (next) {
     victim = next;
@@ -787,6 +818,13 @@ logs_free_all(void)
     });
   smartlist_free(messages);
 
+  if (messages2) {
+    SMARTLIST_FOREACH(messages2, pending_log_message_t *, msg, {
+        pending_log_message_free(msg);
+      });
+    smartlist_free(messages2);
+  }
+
   /* We _could_ destroy the log mutex here, but that would screw up any logs
    * that happened between here and the end of execution. */
 }
@@ -881,7 +919,7 @@ add_stream_log(const log_severity_list_t *severity, const char *name, int fd)
 
 /** Initialize the global logging facility */
 void
-init_logging(void)
+init_logging(int disable_startup_queue)
 {
   if (!log_mutex_initialized) {
     tor_mutex_init(&log_mutex);
@@ -889,8 +927,11 @@ init_logging(void)
   }
   if (pending_cb_messages == NULL)
     pending_cb_messages = smartlist_new();
-  if (pending_startup_messages == NULL)
+  if (disable_startup_queue)
+    queue_startup_messages = 0;
+  if (pending_startup_messages == NULL && queue_startup_messages) {
     pending_startup_messages = smartlist_new();
+  }
 }
 
 /** Set whether we report logging domains as a part of our log messages.
@@ -1000,6 +1041,39 @@ flush_pending_log_callbacks(void)
   UNLOCK_LOGS();
 }
 
+/** Flush all the messages we stored from startup while waiting for log
+ * initialization.
+ */
+void
+flush_log_messages_from_startup(void)
+{
+  logfile_t *lf;
+
+  LOCK_LOGS();
+  queue_startup_messages = 0;
+  pending_startup_messages_len = 0;
+  if (! pending_startup_messages)
+    goto out;
+
+  SMARTLIST_FOREACH_BEGIN(pending_startup_messages, pending_log_message_t *,
+                          msg) {
+    int callbacks_deferred = 0;
+    for (lf = logfiles; lf; lf = lf->next) {
+      if (! logfile_wants_message(lf, msg->severity, msg->domain))
+        continue;
+
+      logfile_deliver(lf, msg->fullmsg, strlen(msg->fullmsg), msg->msg,
+                      msg->domain, msg->severity, &callbacks_deferred);
+    }
+    pending_log_message_free(msg);
+  } SMARTLIST_FOREACH_END(msg);
+  smartlist_free(pending_startup_messages);
+  pending_startup_messages = NULL;
+
+ out:
+  UNLOCK_LOGS();
+}
+
 /** Close any log handlers added by add_temp_log() or marked by
  * mark_logs_temp(). */
 void

src/common/torlog.h

@@ -121,7 +121,7 @@ typedef struct log_severity_list_t {
 /** Callback type used for add_callback_log. */
 typedef void (*log_callback)(int severity, uint32_t domain, const char *msg);
 
-void init_logging(void);
+void init_logging(int disable_startup_queue);
 int parse_log_level(const char *level);
 const char *log_level_to_string(int level);
 int parse_log_severity_config(const char **cfg,
@@ -147,6 +147,7 @@ void mark_logs_temp(void);
 void change_callback_log_severity(int loglevelMin, int loglevelMax,
                                   log_callback cb);
 void flush_pending_log_callbacks(void);
+void flush_log_messages_from_startup(void);
 void log_set_application_name(const char *name);
 void set_log_time_granularity(int granularity_msec);
 void truncate_logs(void);

src/or/config.c

@@ -1023,7 +1023,7 @@ options_act_reversible(const or_options_t *old_options, char **msg)
   int running_tor = options->command == CMD_RUN_TOR;
   int set_conn_limit = 0;
   int r = -1;
-  int logs_marked = 0;
+  int logs_marked = 0, logs_initialized = 0;
   int old_min_log_level = get_min_log_level();
 
   /* Daemonize _first_, since we only want to open most of this stuff in
@@ -1153,6 +1153,7 @@ options_act_reversible(const or_options_t *old_options, char **msg)
     *msg = tor_strdup("Failed to init Log options. See logs for details.");
     goto rollback;
   }
+  logs_initialized = 1;
 
  commit:
   r = 0;
@@ -1165,6 +1166,9 @@ options_act_reversible(const or_options_t *old_options, char **msg)
     tor_free(severity);
     tor_log_update_sigsafe_err_fds();
   }
+  if (logs_initialized) {
+    flush_log_messages_from_startup();
+  }
 
   {
     const char *badness = NULL;

src/or/main.c

@@ -2954,7 +2954,7 @@ tor_main(int argc, char *argv[])
 
   update_approx_time(time(NULL));
   tor_threads_init();
-  init_logging();
+  init_logging(0);
 #ifdef USE_DMALLOC
   {
     /* Instruct OpenSSL to use our internal wrappers for malloc,

src/test/bench.c

@@ -569,7 +569,7 @@ main(int argc, const char **argv)
   crypto_seed_rng(1);
   crypto_init_siphash_key();
   options = options_new();
-  init_logging();
+  init_logging(1);
   options->command = CMD_RUN_UNITTESTS;
   options->DataDirectory = tor_strdup("");
   options_init(options);

src/test/test.c

@@ -1381,7 +1381,7 @@ main(int c, const char **v)
   update_approx_time(time(NULL));
   options = options_new();
   tor_threads_init();
-  init_logging();
+  init_logging(1);
   configure_backtrace_handler(get_version());
 
   for (i_out = i = 1; i < c; ++i) {

src/test/test_bt_cl.c

@@ -96,7 +96,7 @@ main(int argc, char **argv)
     return 1;
   }
 
-  init_logging();
+  init_logging(1);
   set_log_severity_config(LOG_WARN, LOG_ERR, &severity);
   add_stream_log(&severity, "stdout", STDOUT_FILENO);
   tor_log_update_sigsafe_err_fds();

src/test/test_logging.c

@@ -19,7 +19,7 @@ test_get_sigsafe_err_fds(void *arg)
   int n;
   log_severity_list_t include_bug, no_bug, no_bug2;
   (void) arg;
-  init_logging();
+  init_logging(1);
 
   n = tor_log_get_sigsafe_err_fds(&fds);
   tt_int_op(n, ==, 1);
@@ -87,7 +87,7 @@ test_sigsafe_err(void *arg)
 
   set_log_severity_config(LOG_WARN, LOG_ERR, &include_bug);
 
-  init_logging();
+  init_logging(1);
   mark_logs_temp();
   add_file_log(&include_bug, fn, 0);
   tor_log_update_sigsafe_err_fds();

src/tools/tor-checkkey.c

@@ -21,7 +21,7 @@ main(int c, char **v)
   int wantdigest=0;
   int fname_idx;
   char *fname=NULL;
-  init_logging();
+  init_logging(1);
 
   if (c < 2) {
     fprintf(stderr, "Hi. I'm tor-checkkey.  Tell me a filename that "

src/tools/tor-gencert.c

@@ -525,7 +525,7 @@ int
 main(int argc, char **argv)
 {
   int r = 1;
-  init_logging();
+  init_logging(1);
 
   /* Don't bother using acceleration. */
   if (crypto_global_init(0, NULL, NULL)) {

src/tools/tor-resolve.c

@@ -343,7 +343,7 @@ main(int argc, char **argv)
   char *result_hostname = NULL;
   log_severity_list_t *s = tor_malloc_zero(sizeof(log_severity_list_t));
 
-  init_logging();
+  init_logging(1);
 
   arg = &argv[1];
   n_args = argc-1;