commit 93dfb1203715bd275d0eed6c8cccf6b6db76fd95 Author: Nick Mathewson <nickm@torproject.org> Date: Wed Sep 10 23:30:37 2014 -0400 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 | 4 +++ src/common/log.c | 86 ++++++++++++++++++++++++++++++++++++++++++---- src/common/torlog.h | 3 +- src/or/config.c | 6 +++- src/or/main.c | 2 +- src/test/bench.c | 2 +- src/test/test.c | 2 +- src/test/test_bt_cl.c | 2 +- src/test/test_logging.c | 4 +-- src/tools/tor-checkkey.c | 2 +- src/tools/tor-gencert.c | 2 +- src/tools/tor-resolve.c | 2 +- 12 files changed, 100 insertions(+), 17 deletions(-) diff --git a/changes/ticket6938 b/changes/ticket6938 new file mode 100644 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 fb1d85b..4b38177 100644 --- 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 34e39b4..8105af4 100644 --- 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 ba9c944..85e36c7 100644 --- 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 094120f..ffbed6e 100644 --- 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 f6c3362..70bac63 100644 --- 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 e836160..a14064f 100644 --- 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 720ccd4..d7a3cab 100644 --- 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 9f57000..76cc9e9 100644 --- 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 d50f12e..295da33 100644 --- 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 fae26ef..0fe6821 100644 --- 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 306f6c6..1b1e674 100644 --- 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;