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.

diff --git a/changes/ticket6938 b/changes/ticket6938
new file mode 100644 (file)
index 0000000..4e3979a
--- /dev/null
+++ b/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.

diff --git a/src/common/log.c b/src/common/log.c
index fb1d85bd6c2f9d5f2862e46a259c7e62ad0b90a4..4b3817780bd4deabd210ed148e75fcedaa1174d4 100644 (file)
--- a/src/common/log.c
+++ b/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

diff --git a/src/common/torlog.h b/src/common/torlog.h
index 34e39b4b94650759b9fc609bb97512be7f536dec..8105af4351b7e80257e3d688b92d614a39af91e6 100644 (file)
--- a/src/common/torlog.h
+++ b/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);

diff --git a/src/or/config.c b/src/or/config.c
index ba9c944f564266edbee5a7ba792f184ae4b678bd..85e36c7534598a0a12b6b611d4555cca88fb35ba 100644 (file)
--- a/src/or/config.c
+++ b/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;

diff --git a/src/or/main.c b/src/or/main.c
index 094120fecfc80013f6a79728c7d67429f4682748..ffbed6edbe9374026668d011be900c2798f9ee47 100644 (file)
--- a/src/or/main.c
+++ b/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,

diff --git a/src/test/bench.c b/src/test/bench.c
index f6c33626f24d9cde643aa6b397031ddbb0214ed2..70bac6372730bca7c75f92ed642740e2b1b6e59b 100644 (file)
--- a/src/test/bench.c
+++ b/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);

diff --git a/src/test/test.c b/src/test/test.c
index e836160bf4ec033c6e69a5493dce3b48abcf80c5..a14064f237a023bd13a80c3ebccb05ceffe185be 100644 (file)
--- a/src/test/test.c
+++ b/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) {

diff --git a/src/test/test_bt_cl.c b/src/test/test_bt_cl.c
index 720ccd46274bf4a8d79bdad73e0353d9bd7e9b3d..d7a3cab7c30138dce3646f789fb1b8324225d810 100644 (file)
--- a/src/test/test_bt_cl.c
+++ b/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();

diff --git a/src/test/test_logging.c b/src/test/test_logging.c
index 9f57000beaaa92cb6e10d5609d91db729c2ed4e0..76cc9e970e1df1c9aeece7a2c18f927febb161ec 100644 (file)
--- a/src/test/test_logging.c
+++ b/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();

diff --git a/src/tools/tor-checkkey.c b/src/tools/tor-checkkey.c
index d50f12ed2a3f003dd6595b060f98a251d1df03b9..295da33051a7cc07023bb7767f906ff380f03634 100644 (file)
--- a/src/tools/tor-checkkey.c
+++ b/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 "

diff --git a/src/tools/tor-gencert.c b/src/tools/tor-gencert.c
index fae26ef9568defd4911b98775570cd5df6be1054..0fe6821ff8653930e9fb51cf782db0a56e637873 100644 (file)
--- a/src/tools/tor-gencert.c
+++ b/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)) {

diff --git a/src/tools/tor-resolve.c b/src/tools/tor-resolve.c
index 306f6c66ab47397a708fa6cad0bf5e4b50f76423..1b1e6745cb057fe6dcb3f7b28fbca331b947a5e2 100644 (file)
--- a/src/tools/tor-resolve.c
+++ b/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;