diff options
Diffstat (limited to 'src/common/log.c')
-rw-r--r-- | src/common/log.c | 451 |
1 files changed, 270 insertions, 181 deletions
diff --git a/src/common/log.c b/src/common/log.c index 517fa4faaa..6c387c6244 100644 --- a/src/common/log.c +++ b/src/common/log.c @@ -1,7 +1,7 @@ /* Copyright (c) 2001, Matej Pfajfar. * Copyright (c) 2001-2004, Roger Dingledine. * Copyright (c) 2004-2006, Roger Dingledine, Nick Mathewson. - * Copyright (c) 2007-2013, The Tor Project, Inc. */ + * Copyright (c) 2007-2016, The Tor Project, Inc. */ /* See LICENSE for licensing information */ /** @@ -64,7 +64,7 @@ typedef struct logfile_t { static void log_free(logfile_t *victim); /** Helper: map a log severity to descriptive string. */ -static INLINE const char * +static inline const char * sev_to_string(int severity) { switch (severity) { @@ -80,7 +80,7 @@ sev_to_string(int severity) } /** Helper: decide whether to include the function name in the log message. */ -static INLINE int +static inline int should_log_function_name(log_domain_mask_t domain, int severity) { switch (severity) { @@ -117,21 +117,46 @@ 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 *fullmsg; /**< The message, with all decorations */ 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; + +/** 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; + +/** True iff __PRETTY_FUNCTION__ includes parenthesized arguments. */ +static int pretty_fn_has_parens = 0; + +/** 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_assert(log_mutex_initialized); \ tor_mutex_acquire(&log_mutex); \ STMT_END /** Unlock the log_mutex */ -#define UNLOCK_LOGS() STMT_BEGIN tor_mutex_release(&log_mutex); STMT_END +#define UNLOCK_LOGS() STMT_BEGIN \ + tor_assert(log_mutex_initialized); \ + tor_mutex_release(&log_mutex); \ + STMT_END /** What's the lowest log level anybody cares about? Checking this lets us * bail out early from log_debug if we aren't debugging. */ @@ -142,7 +167,7 @@ static void close_log(logfile_t *victim); static char *domain_to_string(log_domain_mask_t domain, char *buf, size_t buflen); -static INLINE char *format_msg(char *buf, size_t buf_len, +static inline char *format_msg(char *buf, size_t buf_len, log_domain_mask_t domain, int severity, const char *funcname, const char *suffix, const char *format, va_list ap, size_t *msg_len_out) @@ -178,7 +203,7 @@ set_log_time_granularity(int granularity_msec) /** Helper: Write the standard prefix for log lines to a * <b>buf_len</b> character buffer in <b>buf</b>. */ -static INLINE size_t +static inline size_t log_prefix_(char *buf, size_t buf_len, int severity) { time_t t; @@ -245,12 +270,19 @@ log_tor_version(logfile_t *lf, int reset) return 0; } +const char bug_suffix[] = " (on Tor " VERSION +#ifndef _MSC_VER + " " +#include "micro-revision.i" +#endif + ")"; + /** Helper: Format a log message into a fixed-sized buffer. (This is * factored out of <b>logv</b> so that we never format a message more * than once.) Return a pointer to the first character of the message * portion of the formatted string. */ -static INLINE char * +static inline char * format_msg(char *buf, size_t buf_len, log_domain_mask_t domain, int severity, const char *funcname, const char *suffix, @@ -288,7 +320,9 @@ format_msg(char *buf, size_t buf_len, } if (funcname && should_log_function_name(domain, severity)) { - r = tor_snprintf(buf+n, buf_len-n, "%s(): ", funcname); + r = tor_snprintf(buf+n, buf_len-n, + pretty_fn_has_parens ? "%s: " : "%s(): ", + funcname); if (r<0) n = strlen(buf); else @@ -323,12 +357,115 @@ format_msg(char *buf, size_t buf_len, } } } + + if (domain == LD_BUG && + buf_len - n > strlen(bug_suffix)+1) { + memcpy(buf+n, bug_suffix, strlen(bug_suffix)); + n += strlen(bug_suffix); + } + buf[n]='\n'; buf[n+1]='\0'; *msg_len_out = n+1; 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 *fullmsg, const char *shortmsg) +{ + pending_log_message_t *m = tor_malloc(sizeof(pending_log_message_t)); + m->severity = severity; + m->domain = domain; + m->fullmsg = fullmsg ? tor_strdup(fullmsg) : NULL; + m->msg = tor_strdup(shortmsg); + return m; +} + +/** Release all storage held by <b>msg</b>. */ +static void +pending_log_message_free(pending_log_message_t *msg) +{ + if (!msg) + return; + tor_free(msg->msg); + tor_free(msg->fullmsg); + tor_free(msg); +} + +/** Return true iff <b>lf</b> would like to receive a message with the + * specified <b>severity</b> in the specified <b>domain</b>. + */ +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; +} + +/** Send a message to <b>lf</b>. The full message, with time prefix and + * severity, is in <b>buf</b>. The message itself is in + * <b>msg_after_prefix</b>. If <b>callbacks_deferred</b> 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 + * <b>callbacks_deferred</b> 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,NULL,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 * <b>severity</b>. If provided, <b>funcname</b> is prepended to the * message. The actual message is derived as from tor_snprintf(format,ap). @@ -337,7 +474,7 @@ MOCK_IMPL(STATIC void, logv,(int severity, log_domain_mask_t domain, const char *funcname, const char *suffix, const char *format, va_list ap)) { - char buf[10024]; + char buf[10240]; size_t msg_len = 0; int formatted = 0; logfile_t *lf; @@ -349,25 +486,29 @@ logv,(int severity, log_domain_mask_t domain, const char *funcname, /* check that severity is sane. Overrunning the masks array leads to * interesting and hard to diagnose effects */ assert(severity >= LOG_ERR && severity <= LOG_DEBUG); + /* check that we've initialised the log mutex before we try to lock it */ + assert(log_mutex_initialized); LOCK_LOGS(); - if ((! (domain & LD_NOCB)) && smartlist_len(pending_cb_messages)) + if ((! (domain & LD_NOCB)) && pending_cb_messages + && 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; - continue; - } - if (! (lf->fd >= 0 || lf->is_syslog || lf->callback)) { - lf = lf->next; - continue; - } - if (lf->seems_dead) { - lf = lf->next; + 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; - } if (!formatted) { end_of_prefix = @@ -376,51 +517,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 - lf = lf->next; - continue; - } 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); - - callbacks_deferred = 1; - } - } else { - lf->callback(severity, domain, end_of_prefix); - } - lf = lf->next; - 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; - } - lf = lf->next; + logfile_deliver(lf, buf, msg_len, end_of_prefix, domain, severity, + &callbacks_deferred); } UNLOCK_LOGS(); } @@ -583,9 +681,7 @@ tor_log_get_logfile_names(smartlist_t *out) UNLOCK_LOGS(); } -/** Output a message to the log, prefixed with a function name <b>fn</b>. */ -#ifdef __GNUC__ -/** GCC-based implementation of the log_fn backend, used when we have +/** Implementation of the log_fn backend, used when we have * variadic macros. All arguments are as for log_fn, except for * <b>fn</b>, which is the name of the calling functions. */ void @@ -615,98 +711,6 @@ log_fn_ratelim_(ratelim_t *ratelim, int severity, log_domain_mask_t domain, va_end(ap); tor_free(m); } -#else -/** @{ */ -/** Variant implementation of log_fn, log_debug, log_info,... for C compilers - * without variadic macros. In this case, the calling function sets - * log_fn_function_name_ to the name of the function, then invokes the - * appropriate log_fn_, log_debug_, etc. */ -const char *log_fn_function_name_=NULL; -void -log_fn_(int severity, log_domain_mask_t domain, const char *format, ...) -{ - va_list ap; - if (severity > log_global_min_severity_) - return; - va_start(ap,format); - logv(severity, domain, log_fn_function_name_, NULL, format, ap); - va_end(ap); - log_fn_function_name_ = NULL; -} -void -log_fn_ratelim_(ratelim_t *ratelim, int severity, log_domain_mask_t domain, - const char *format, ...) -{ - va_list ap; - char *m; - if (severity > log_global_min_severity_) - return; - m = rate_limit_log(ratelim, approx_time()); - if (m == NULL) - return; - va_start(ap, format); - logv(severity, domain, log_fn_function_name_, m, format, ap); - va_end(ap); - tor_free(m); -} -void -log_debug_(log_domain_mask_t domain, const char *format, ...) -{ - va_list ap; - /* For GCC we do this check in the macro. */ - if (PREDICT_LIKELY(LOG_DEBUG > log_global_min_severity_)) - return; - va_start(ap,format); - logv(LOG_DEBUG, domain, log_fn_function_name_, NULL, format, ap); - va_end(ap); - log_fn_function_name_ = NULL; -} -void -log_info_(log_domain_mask_t domain, const char *format, ...) -{ - va_list ap; - if (LOG_INFO > log_global_min_severity_) - return; - va_start(ap,format); - logv(LOG_INFO, domain, log_fn_function_name_, NULL, format, ap); - va_end(ap); - log_fn_function_name_ = NULL; -} -void -log_notice_(log_domain_mask_t domain, const char *format, ...) -{ - va_list ap; - if (LOG_NOTICE > log_global_min_severity_) - return; - va_start(ap,format); - logv(LOG_NOTICE, domain, log_fn_function_name_, NULL, format, ap); - va_end(ap); - log_fn_function_name_ = NULL; -} -void -log_warn_(log_domain_mask_t domain, const char *format, ...) -{ - va_list ap; - if (LOG_WARN > log_global_min_severity_) - return; - va_start(ap,format); - logv(LOG_WARN, domain, log_fn_function_name_, NULL, format, ap); - va_end(ap); - log_fn_function_name_ = NULL; -} -void -log_err_(log_domain_mask_t domain, const char *format, ...) -{ - va_list ap; - if (LOG_ERR > log_global_min_severity_) - return; - va_start(ap,format); - logv(LOG_ERR, domain, log_fn_function_name_, NULL, format, ap); - va_end(ap); - log_fn_function_name_ = NULL; -} -/** @} */ -#endif /** Free all storage held by <b>victim</b>. */ static void @@ -724,12 +728,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; @@ -739,12 +745,18 @@ 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); + 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. */ } @@ -839,14 +851,24 @@ 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); log_mutex_initialized = 1; } +#ifdef __GNUC__ + if (strchr(__PRETTY_FUNCTION__, '(')) { + pretty_fn_has_parens = 1; + } +#endif if (pending_cb_messages == NULL) pending_cb_messages = smartlist_new(); + 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. @@ -924,7 +946,7 @@ flush_pending_log_callbacks(void) smartlist_t *messages, *messages_tmp; LOCK_LOGS(); - if (0 == smartlist_len(pending_cb_messages)) { + if (!pending_cb_messages || 0 == smartlist_len(pending_cb_messages)) { UNLOCK_LOGS(); return; } @@ -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); @@ -957,6 +978,45 @@ 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; + + /* We configure a temporary startup log that goes to stdout, so we + * shouldn't replay to stdout/stderr*/ + if (lf->fd == STDOUT_FILENO || lf->fd == STDERR_FILENO) { + 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 @@ -1010,12 +1070,16 @@ mark_logs_temp(void) * logfile fails, -1 is returned and errno is set appropriately (by open(2)). */ int -add_file_log(const log_severity_list_t *severity, const char *filename) +add_file_log(const log_severity_list_t *severity, const char *filename, + const int truncate) { int fd; logfile_t *lf; - fd = tor_open_cloexec(filename, O_WRONLY|O_CREAT|O_APPEND, 0644); + int open_flags = O_WRONLY|O_CREAT; + open_flags |= truncate ? O_TRUNC : O_APPEND; + + fd = tor_open_cloexec(filename, open_flags, 0644); if (fd<0) return -1; if (tor_fd_seekend(fd)<0) { @@ -1040,14 +1104,25 @@ add_file_log(const log_severity_list_t *severity, const char *filename) #ifdef HAVE_SYSLOG_H /** * Add a log handler to send messages to they system log facility. + * + * If this is the first log handler, opens syslog with ident Tor or + * Tor-<syslog_identity_tag> if that is not NULL. */ int -add_syslog_log(const log_severity_list_t *severity) +add_syslog_log(const log_severity_list_t *severity, + const char* syslog_identity_tag) { logfile_t *lf; - if (syslog_count++ == 0) + if (syslog_count++ == 0) { /* This is the first syslog. */ - openlog("Tor", LOG_PID | LOG_NDELAY, LOGFACILITY); + static char buf[256]; + if (syslog_identity_tag) { + tor_snprintf(buf, sizeof(buf), "Tor-%s", syslog_identity_tag); + } else { + tor_snprintf(buf, sizeof(buf), "Tor"); + } + openlog(buf, LOG_PID | LOG_NDELAY, LOGFACILITY); + } lf = tor_malloc_zero(sizeof(logfile_t)); lf->fd = -1; @@ -1094,7 +1169,8 @@ log_level_to_string(int level) static const char *domain_list[] = { "GENERAL", "CRYPTO", "NET", "CONFIG", "FS", "PROTOCOL", "MM", "HTTP", "APP", "CONTROL", "CIRC", "REND", "BUG", "DIR", "DIRSERV", - "OR", "EDGE", "ACCT", "HIST", "HANDSHAKE", "HEARTBEAT", "CHANNEL", NULL + "OR", "EDGE", "ACCT", "HIST", "HANDSHAKE", "HEARTBEAT", "CHANNEL", + "SCHED", NULL }; /** Return a bitmask for the log domain for which <b>domain</b> is the name, @@ -1124,7 +1200,8 @@ domain_to_string(log_domain_mask_t domain, char *buf, size_t buflen) const char *d; int bit = tor_log2(domain); size_t n; - if (bit >= N_LOGGING_DOMAINS) { + if ((unsigned)bit >= ARRAY_LENGTH(domain_list)-1 || + bit >= N_LOGGING_DOMAINS) { tor_snprintf(buf, buflen, "<BUG:Unknown domain %lx>", (long)domain); return buf+strlen(buf); } @@ -1297,3 +1374,15 @@ switch_logs_debug(void) UNLOCK_LOGS(); } +/** Truncate all the log files. */ +void +truncate_logs(void) +{ + logfile_t *lf; + for (lf = logfiles; lf; lf = lf->next) { + if (lf->fd >= 0) { + tor_ftruncate(lf->fd); + } + } +} + |