From 15a318b49acfb2b7618b25cf8cddf813c745f3ab Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Wed, 10 Sep 2014 22:35:16 -0400 Subject: [PATCH 1/4] Refactor pending_cb_message_t into a type with proper functions Also, rename it. --- src/common/log.c | 49 ++++++++++++++++++++++++++++++++++-------------- 1 file changed, 35 insertions(+), 14 deletions(-) diff --git a/src/common/log.c b/src/common/log.c index 2e51e5c578..193389c504 100644 --- a/src/common/log.c +++ b/src/common/log.c @@ -117,15 +117,19 @@ static int syslog_count = 0; /** 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 { +typedef struct pending_log_message_t { int severity; /**< The severity of the message */ log_domain_mask_t domain; /**< The domain of the message */ char *msg; /**< The content of the message */ -} pending_cb_message_t; +} pending_log_message_t; /** Log messages waiting to be replayed onto callback-based logs */ static smartlist_t *pending_cb_messages = NULL; +/** Log messages waiting to be replayed once the logging system is initialized. + */ +static smartlist_t *pending_startup_messages = NULL; + /** Lock the log_mutex to prevent others from changing the logfile_t list */ #define LOCK_LOGS() STMT_BEGIN \ tor_mutex_acquire(&log_mutex); \ @@ -329,6 +333,27 @@ format_msg(char *buf, size_t buf_len, return end_of_prefix; } +/* 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_t *m = tor_malloc(sizeof(pending_log_message_t)); + m->severity = severity; + m->domain = domain; + m->msg = tor_strdup(msg); + return m; +} + +/** Release all storage held by msg. */ +static void +pending_log_message_free(pending_log_message_t *msg) +{ + if (!msg) + return; + tor_free(msg->msg); + tor_free(msg); +} + /** Helper: sends a message to the appropriate logfiles, at loglevel * severity. If provided, funcname is prepended to the * message. The actual message is derived as from tor_snprintf(format,ap). @@ -401,12 +426,8 @@ logv,(int severity, log_domain_mask_t domain, const char *funcname, } else if (lf->callback) { if (domain & LD_NOCB) { if (!callbacks_deferred && pending_cb_messages) { - 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); - + smartlist_add(pending_cb_messages, + pending_log_message_new(severity,domain,end_of_prefix)); callbacks_deferred = 1; } } else { @@ -739,9 +760,8 @@ logs_free_all(void) } tor_free(appname); - SMARTLIST_FOREACH(messages, pending_cb_message_t *, msg, { - tor_free(msg->msg); - tor_free(msg); + SMARTLIST_FOREACH(messages, pending_log_message_t *, msg, { + pending_log_message_free(msg); }); smartlist_free(messages); @@ -847,6 +867,8 @@ init_logging(void) } if (pending_cb_messages == NULL) pending_cb_messages = smartlist_new(); + if (pending_startup_messages == NULL) + pending_startup_messages = smartlist_new(); } /** Set whether we report logging domains as a part of our log messages. @@ -932,7 +954,7 @@ flush_pending_log_callbacks(void) messages = pending_cb_messages; pending_cb_messages = smartlist_new(); do { - SMARTLIST_FOREACH_BEGIN(messages, pending_cb_message_t *, msg) { + SMARTLIST_FOREACH_BEGIN(messages, pending_log_message_t *, msg) { const int severity = msg->severity; const int domain = msg->domain; for (lf = logfiles; lf; lf = lf->next) { @@ -942,8 +964,7 @@ flush_pending_log_callbacks(void) } lf->callback(severity, domain, msg->msg); } - tor_free(msg->msg); - tor_free(msg); + pending_log_message_free(msg); } SMARTLIST_FOREACH_END(msg); smartlist_clear(messages); From de114587f047b337cf49e6a308be22f373b4bfc8 Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Wed, 10 Sep 2014 22:39:55 -0400 Subject: [PATCH 2/4] Turn log loop into a for loop, and "Does this lf want this" into a fn --- src/common/log.c | 38 ++++++++++++++++++++++---------------- 1 file changed, 22 insertions(+), 16 deletions(-) diff --git a/src/common/log.c b/src/common/log.c index 193389c504..544aae964b 100644 --- a/src/common/log.c +++ b/src/common/log.c @@ -354,6 +354,26 @@ pending_log_message_free(pending_log_message_t *msg) tor_free(msg); } +/** Return true iff lf would like to receive a message with the specified + * severity in the specified domain. + */ +static INLINE int +logfile_wants_message(const logfile_t *lf, int severity, + log_domain_mask_t domain) +{ + if (! (lf->severities->masks[SEVERITY_MASK_IDX(severity)] & domain)) { + return 0; + } + if (! (lf->fd >= 0 || lf->is_syslog || lf->callback)) { + return 0; + } + if (lf->seems_dead) { + return 0; + } + + return 1; +} + /** Helper: sends a message to the appropriate logfiles, at loglevel * severity. If provided, funcname is prepended to the * message. The actual message is derived as from tor_snprintf(format,ap). @@ -379,20 +399,9 @@ logv,(int severity, log_domain_mask_t domain, const char *funcname, 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)) { - lf = lf->next; + for (lf = logfiles; lf; lf = lf->next) { + if (! logfile_wants_message(lf, severity, domain)) continue; - } - if (! (lf->fd >= 0 || lf->is_syslog || lf->callback)) { - lf = lf->next; - continue; - } - if (lf->seems_dead) { - lf = lf->next; - continue; - } if (!formatted) { end_of_prefix = @@ -421,7 +430,6 @@ logv,(int severity, log_domain_mask_t domain, const char *funcname, } #endif #endif - lf = lf->next; continue; } else if (lf->callback) { if (domain & LD_NOCB) { @@ -433,7 +441,6 @@ logv,(int severity, log_domain_mask_t domain, const char *funcname, } else { lf->callback(severity, domain, end_of_prefix); } - lf = lf->next; continue; } if (write_all(lf->fd, buf, msg_len, 0) < 0) { /* error */ @@ -441,7 +448,6 @@ logv,(int severity, log_domain_mask_t domain, const char *funcname, * continue. */ lf->seems_dead = 1; } - lf = lf->next; } UNLOCK_LOGS(); } From 6e2ef4bc5ef882b3434d2fe15c1007b4ac711374 Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Wed, 10 Sep 2014 22:58:36 -0400 Subject: [PATCH 3/4] Refactor the 'deliver a log message' logic to its own function. --- src/common/log.c | 92 ++++++++++++++++++++++++++++-------------------- 1 file changed, 54 insertions(+), 38 deletions(-) diff --git a/src/common/log.c b/src/common/log.c index 544aae964b..fb1d85bd6c 100644 --- a/src/common/log.c +++ b/src/common/log.c @@ -374,6 +374,58 @@ logfile_wants_message(const logfile_t *lf, int severity, return 1; } +/** Send a message to lf. The full message, with time prefix and + * severity, is in buf. The message itself is in + * msg_after_prefix. If callbacks_deferred points to true, then + * we already deferred this message for pending callbacks and don't need to do + * it again. Otherwise, if we need to do it, do it, and set + * callbacks_deferred to 1. */ +static INLINE void +logfile_deliver(logfile_t *lf, const char *buf, size_t msg_len, + const char *msg_after_prefix, log_domain_mask_t domain, + int severity, int *callbacks_deferred) +{ + + if (lf->is_syslog) { +#ifdef HAVE_SYSLOG_H +#ifdef MAXLINE + /* Some syslog implementations have limits on the length of what you can + * pass them, and some very old ones do not detect overflow so well. + * Regrettably, they call their maximum line length MAXLINE. */ +#if MAXLINE < 64 +#warn "MAXLINE is a very low number; it might not be from syslog.h after all" +#endif + char *m = msg_after_prefix; + if (msg_len >= MAXLINE) + m = tor_strndup(msg_after_prefix, MAXLINE-1); + syslog(severity, "%s", m); + if (m != msg_after_prefix) { + tor_free(m); + } +#else + /* We have syslog but not MAXLINE. That's promising! */ + syslog(severity, "%s", msg_after_prefix); +#endif +#endif + } else if (lf->callback) { + if (domain & LD_NOCB) { + if (!*callbacks_deferred && pending_cb_messages) { + smartlist_add(pending_cb_messages, + pending_log_message_new(severity,domain,msg_after_prefix)); + *callbacks_deferred = 1; + } + } else { + lf->callback(severity, domain, msg_after_prefix); + } + } else { + if (write_all(lf->fd, buf, msg_len, 0) < 0) { /* error */ + /* don't log the error! mark this log entry to be blown away, and + * continue. */ + lf->seems_dead = 1; + } + } +} + /** Helper: sends a message to the appropriate logfiles, at loglevel * severity. If provided, funcname is prepended to the * message. The actual message is derived as from tor_snprintf(format,ap). @@ -410,44 +462,8 @@ logv,(int severity, log_domain_mask_t domain, const char *funcname, formatted = 1; } - if (lf->is_syslog) { -#ifdef HAVE_SYSLOG_H - char *m = end_of_prefix; -#ifdef MAXLINE - /* Some syslog implementations have limits on the length of what you can - * pass them, and some very old ones do not detect overflow so well. - * Regrettably, they call their maximum line length MAXLINE. */ -#if MAXLINE < 64 -#warn "MAXLINE is a very low number; it might not be from syslog.h after all" -#endif - if (msg_len >= MAXLINE) - m = tor_strndup(end_of_prefix, MAXLINE-1); -#endif - syslog(severity, "%s", m); -#ifdef MAXLINE - if (m != end_of_prefix) { - tor_free(m); - } -#endif -#endif - continue; - } else if (lf->callback) { - if (domain & LD_NOCB) { - if (!callbacks_deferred && pending_cb_messages) { - smartlist_add(pending_cb_messages, - pending_log_message_new(severity,domain,end_of_prefix)); - callbacks_deferred = 1; - } - } else { - lf->callback(severity, domain, end_of_prefix); - } - continue; - } - if (write_all(lf->fd, buf, msg_len, 0) < 0) { /* error */ - /* don't log the error! mark this log entry to be blown away, and - * continue. */ - lf->seems_dead = 1; - } + logfile_deliver(lf, buf, msg_len, end_of_prefix, domain, severity, + &callbacks_deferred); } UNLOCK_LOGS(); } From 93dfb1203715bd275d0eed6c8cccf6b6db76fd95 Mon Sep 17 00:00:00 2001 From: Nick Mathewson Date: Wed, 10 Sep 2014 23:30:37 -0400 Subject: [PATCH 4/4] 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(-) create mode 100644 changes/ticket6938 diff --git a/changes/ticket6938 b/changes/ticket6938 new file mode 100644 index 0000000000..4e3979a7e9 --- /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 fb1d85bd6c..4b3817780b 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 34e39b4b94..8105af4351 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 ba9c944f56..85e36c7534 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 094120fecf..ffbed6edbe 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 f6c33626f2..70bac63727 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 e836160bf4..a14064f237 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 720ccd4627..d7a3cab7c3 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 9f57000bea..76cc9e970e 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 d50f12ed2a..295da33051 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 fae26ef956..0fe6821ff8 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 306f6c66ab..1b1e6745cb 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;