diff options
Diffstat (limited to 'src/common/log.c')
| -rw-r--r-- | src/common/log.c | 336 |
1 files changed, 244 insertions, 92 deletions
diff --git a/src/common/log.c b/src/common/log.c index 5e2e6b5b5..517fa4faa 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-2012, The Tor Project, Inc. */ + * Copyright (c) 2007-2013, The Tor Project, Inc. */ /* See LICENSE for licensing information */ /** @@ -36,6 +36,10 @@ #include "torlog.h" #include "container.h" +/** Given a severity, yields an index into log_severity_list_t.masks to use + * for that severity. */ +#define SEVERITY_MASK_IDX(sev) ((sev) - LOG_ERR) + /** @{ */ /** The string we stick at the end of a log message when it is too long, * and its length. */ @@ -83,12 +87,12 @@ should_log_function_name(log_domain_mask_t domain, int severity) case LOG_DEBUG: case LOG_INFO: /* All debugging messages occur in interesting places. */ - return 1; + return (domain & LD_NOFUNCNAME) == 0; case LOG_NOTICE: case LOG_WARN: case LOG_ERR: /* We care about places where bugs occur. */ - return (domain == LD_BUG); + return (domain & (LD_BUG|LD_NOFUNCNAME)) == LD_BUG; default: /* Call assert, not tor_assert, since tor_assert calls log on failure. */ assert(0); return 0; @@ -131,7 +135,7 @@ static smartlist_t *pending_cb_messages = NULL; /** What's the lowest log level anybody cares about? Checking this lets us * bail out early from log_debug if we aren't debugging. */ -int _log_global_min_severity = LOG_NOTICE; +int log_global_min_severity_ = LOG_NOTICE; static void delete_log(logfile_t *victim); static void close_log(logfile_t *victim); @@ -140,11 +144,9 @@ 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, log_domain_mask_t domain, int severity, const char *funcname, + const char *suffix, const char *format, va_list ap, size_t *msg_len_out) - CHECK_PRINTF(6,0); -static void logv(int severity, log_domain_mask_t domain, const char *funcname, - const char *format, va_list ap) - CHECK_PRINTF(4,0); + CHECK_PRINTF(7,0); /** Name of the application: used to generate the message we write at the * start of each new log. */ @@ -177,7 +179,7 @@ set_log_time_granularity(int granularity_msec) * <b>buf_len</b> character buffer in <b>buf</b>. */ static INLINE size_t -_log_prefix(char *buf, size_t buf_len, int severity) +log_prefix_(char *buf, size_t buf_len, int severity) { time_t t; struct timeval now; @@ -230,7 +232,7 @@ log_tor_version(logfile_t *lf, int reset) /* We are resetting, but we aren't at the start of the file; no * need to log again. */ return 0; - n = _log_prefix(buf, sizeof(buf), LOG_NOTICE); + n = log_prefix_(buf, sizeof(buf), LOG_NOTICE); if (appname) { tor_snprintf(buf+n, sizeof(buf)-n, "%s opening %slog file.\n", appname, is_new?"new ":""); @@ -251,6 +253,7 @@ log_tor_version(logfile_t *lf, int reset) 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) { size_t n; @@ -262,7 +265,7 @@ format_msg(char *buf, size_t buf_len, buf_len -= 2; /* subtract 2 characters so we have room for \n\0 */ buf_end = buf+buf_len; /* point *after* the last char we can write to */ - n = _log_prefix(buf, buf_len, severity); + n = log_prefix_(buf, buf_len, severity); end_of_prefix = buf+n; if (log_domains_are_logged) { @@ -312,6 +315,13 @@ format_msg(char *buf, size_t buf_len, n = buf_len; } else { n += r; + if (suffix) { + size_t suffix_len = strlen(suffix); + if (buf_len-n >= suffix_len) { + memcpy(buf+n, suffix, suffix_len); + n += suffix_len; + } + } } buf[n]='\n'; buf[n+1]='\0'; @@ -323,9 +333,9 @@ format_msg(char *buf, size_t buf_len, * <b>severity</b>. If provided, <b>funcname</b> is prepended to the * message. The actual message is derived as from tor_snprintf(format,ap). */ -static void -logv(int severity, log_domain_mask_t domain, const char *funcname, - const char *format, va_list ap) +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]; size_t msg_len = 0; @@ -361,8 +371,8 @@ logv(int severity, log_domain_mask_t domain, const char *funcname, if (!formatted) { end_of_prefix = - format_msg(buf, sizeof(buf), domain, severity, funcname, format, ap, - &msg_len); + format_msg(buf, sizeof(buf), domain, severity, funcname, suffix, + format, ap, &msg_len); formatted = 1; } @@ -423,102 +433,277 @@ void tor_log(int severity, log_domain_mask_t domain, const char *format, ...) { va_list ap; - if (severity > _log_global_min_severity) + if (severity > log_global_min_severity_) return; va_start(ap,format); - logv(severity, domain, NULL, format, ap); + logv(severity, domain, NULL, NULL, format, ap); va_end(ap); } +/** Maximum number of fds that will get notifications if we crash */ +#define MAX_SIGSAFE_FDS 8 +/** Array of fds to log crash-style warnings to. */ +static int sigsafe_log_fds[MAX_SIGSAFE_FDS] = { STDERR_FILENO }; +/** The number of elements used in sigsafe_log_fds */ +static int n_sigsafe_log_fds = 1; + +/** Write <b>s</b> to each element of sigsafe_log_fds. Return 0 on success, -1 + * on failure. */ +static int +tor_log_err_sigsafe_write(const char *s) +{ + int i; + ssize_t r; + size_t len = strlen(s); + int err = 0; + for (i=0; i < n_sigsafe_log_fds; ++i) { + r = write(sigsafe_log_fds[i], s, len); + err += (r != (ssize_t)len); + } + return err ? -1 : 0; +} + +/** Given a list of string arguments ending with a NULL, writes them + * to our logs and to stderr (if possible). This function is safe to call + * from within a signal handler. */ +void +tor_log_err_sigsafe(const char *m, ...) +{ + va_list ap; + const char *x; + char timebuf[33]; + time_t now = time(NULL); + + if (!m) + return; + if (log_time_granularity >= 2000) { + int g = log_time_granularity / 1000; + now -= now % g; + } + timebuf[0] = now < 0 ? '-' : ' '; + if (now < 0) now = -now; + timebuf[1] = '\0'; + format_dec_number_sigsafe(now, timebuf+1, sizeof(timebuf)-1); + tor_log_err_sigsafe_write("\n==========================================" + "================== T="); + tor_log_err_sigsafe_write(timebuf); + tor_log_err_sigsafe_write("\n"); + tor_log_err_sigsafe_write(m); + va_start(ap, m); + while ((x = va_arg(ap, const char*))) { + tor_log_err_sigsafe_write(x); + } + va_end(ap); +} + +/** Set *<b>out</b> to a pointer to an array of the fds to log errors to from + * inside a signal handler. Return the number of elements in the array. */ +int +tor_log_get_sigsafe_err_fds(const int **out) +{ + *out = sigsafe_log_fds; + return n_sigsafe_log_fds; +} + +/** Helper function; return true iff the <b>n</b>-element array <b>array</b> + * contains <b>item</b>. */ +static int +int_array_contains(const int *array, int n, int item) +{ + int j; + for (j = 0; j < n; ++j) { + if (array[j] == item) + return 1; + } + return 0; +} + +/** Function to call whenever the list of logs changes to get ready to log + * from signal handlers. */ +void +tor_log_update_sigsafe_err_fds(void) +{ + const logfile_t *lf; + int found_real_stderr = 0; + + LOCK_LOGS(); + /* Reserve the first one for stderr. This is safe because when we daemonize, + * we dup2 /dev/null to stderr, */ + sigsafe_log_fds[0] = STDERR_FILENO; + n_sigsafe_log_fds = 1; + + for (lf = logfiles; lf; lf = lf->next) { + /* Don't try callback to the control port, or syslogs: We can't + * do them from a signal handler. Don't try stdout: we always do stderr. + */ + if (lf->is_temporary || lf->is_syslog || + lf->callback || lf->seems_dead || lf->fd < 0) + continue; + if (lf->severities->masks[SEVERITY_MASK_IDX(LOG_ERR)] & + (LD_BUG|LD_GENERAL)) { + if (lf->fd == STDERR_FILENO) + found_real_stderr = 1; + /* Avoid duplicates */ + if (int_array_contains(sigsafe_log_fds, n_sigsafe_log_fds, lf->fd)) + continue; + sigsafe_log_fds[n_sigsafe_log_fds++] = lf->fd; + if (n_sigsafe_log_fds == MAX_SIGSAFE_FDS) + break; + } + } + + if (!found_real_stderr && + int_array_contains(sigsafe_log_fds, n_sigsafe_log_fds, STDOUT_FILENO)) { + /* Don't use a virtual stderr when we're also logging to stdout. */ + assert(n_sigsafe_log_fds >= 2); /* Don't use assert inside log functions*/ + sigsafe_log_fds[0] = sigsafe_log_fds[--n_sigsafe_log_fds]; + } + + UNLOCK_LOGS(); +} + +/** Add to <b>out</b> a copy of every currently configured log file name. Used + * to enable access to these filenames with the sandbox code. */ +void +tor_log_get_logfile_names(smartlist_t *out) +{ + logfile_t *lf; + tor_assert(out); + + LOCK_LOGS(); + + for (lf = logfiles; lf; lf = lf->next) { + if (lf->is_temporary || lf->is_syslog || lf->callback) + continue; + if (lf->filename == NULL) + continue; + smartlist_add(out, tor_strdup(lf->filename)); + } + + 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 * variadic macros. All arguments are as for log_fn, except for * <b>fn</b>, which is the name of the calling functions. */ void -_log_fn(int severity, log_domain_mask_t domain, const char *fn, +log_fn_(int severity, log_domain_mask_t domain, const char *fn, const char *format, ...) { va_list ap; - if (severity > _log_global_min_severity) + if (severity > log_global_min_severity_) return; va_start(ap,format); - logv(severity, domain, fn, format, ap); + logv(severity, domain, fn, NULL, format, ap); va_end(ap); } +void +log_fn_ratelim_(ratelim_t *ratelim, int severity, log_domain_mask_t domain, + const char *fn, 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, fn, m, format, ap); + 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; + * 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, ...) +log_fn_(int severity, log_domain_mask_t domain, const char *format, ...) { va_list ap; - if (severity > _log_global_min_severity) + if (severity > log_global_min_severity_) return; va_start(ap,format); - logv(severity, domain, _log_fn_function_name, format, ap); + logv(severity, domain, log_fn_function_name_, NULL, format, ap); va_end(ap); - _log_fn_function_name = NULL; + log_fn_function_name_ = NULL; } void -_log_debug(log_domain_mask_t domain, const char *format, ...) +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)) + if (PREDICT_LIKELY(LOG_DEBUG > log_global_min_severity_)) return; va_start(ap,format); - logv(LOG_DEBUG, domain, _log_fn_function_name, format, ap); + logv(LOG_DEBUG, domain, log_fn_function_name_, NULL, format, ap); va_end(ap); - _log_fn_function_name = NULL; + log_fn_function_name_ = NULL; } void -_log_info(log_domain_mask_t domain, const char *format, ...) +log_info_(log_domain_mask_t domain, const char *format, ...) { va_list ap; - if (LOG_INFO > _log_global_min_severity) + if (LOG_INFO > log_global_min_severity_) return; va_start(ap,format); - logv(LOG_INFO, domain, _log_fn_function_name, format, ap); + logv(LOG_INFO, domain, log_fn_function_name_, NULL, format, ap); va_end(ap); - _log_fn_function_name = NULL; + log_fn_function_name_ = NULL; } void -_log_notice(log_domain_mask_t domain, const char *format, ...) +log_notice_(log_domain_mask_t domain, const char *format, ...) { va_list ap; - if (LOG_NOTICE > _log_global_min_severity) + if (LOG_NOTICE > log_global_min_severity_) return; va_start(ap,format); - logv(LOG_NOTICE, domain, _log_fn_function_name, format, ap); + logv(LOG_NOTICE, domain, log_fn_function_name_, NULL, format, ap); va_end(ap); - _log_fn_function_name = NULL; + log_fn_function_name_ = NULL; } void -_log_warn(log_domain_mask_t domain, const char *format, ...) +log_warn_(log_domain_mask_t domain, const char *format, ...) { va_list ap; - if (LOG_WARN > _log_global_min_severity) + if (LOG_WARN > log_global_min_severity_) return; va_start(ap,format); - logv(LOG_WARN, domain, _log_fn_function_name, format, ap); + logv(LOG_WARN, domain, log_fn_function_name_, NULL, format, ap); va_end(ap); - _log_fn_function_name = NULL; + log_fn_function_name_ = NULL; } void -_log_err(log_domain_mask_t domain, const char *format, ...) +log_err_(log_domain_mask_t domain, const char *format, ...) { va_list ap; - if (LOG_ERR > _log_global_min_severity) + if (LOG_ERR > log_global_min_severity_) return; va_start(ap,format); - logv(LOG_ERR, domain, _log_fn_function_name, format, ap); + logv(LOG_ERR, domain, log_fn_function_name_, NULL, format, ap); va_end(ap); - _log_fn_function_name = NULL; + log_fn_function_name_ = NULL; } /** @} */ #endif @@ -638,7 +823,7 @@ add_stream_log_impl(const log_severity_list_t *severity, lf->next = logfiles; logfiles = lf; - _log_global_min_severity = get_min_log_level(); + log_global_min_severity_ = get_min_log_level(); } /** Add a log handler named <b>name</b> to send all messages in <b>severity</b> @@ -706,7 +891,7 @@ add_callback_log(const log_severity_list_t *severity, log_callback cb) LOCK_LOGS(); logfiles = lf; - _log_global_min_severity = get_min_log_level(); + log_global_min_severity_ = get_min_log_level(); UNLOCK_LOGS(); return 0; } @@ -726,7 +911,7 @@ change_callback_log_severity(int loglevelMin, int loglevelMax, memcpy(lf->severities, &severities, sizeof(severities)); } } - _log_global_min_severity = get_min_log_level(); + log_global_min_severity_ = get_min_log_level(); UNLOCK_LOGS(); } @@ -792,7 +977,7 @@ close_temp_logs(void) } } - _log_global_min_severity = get_min_log_level(); + log_global_min_severity_ = get_min_log_level(); UNLOCK_LOGS(); } @@ -833,14 +1018,16 @@ add_file_log(const log_severity_list_t *severity, const char *filename) fd = tor_open_cloexec(filename, O_WRONLY|O_CREAT|O_APPEND, 0644); if (fd<0) return -1; - if (tor_fd_seekend(fd)<0) + if (tor_fd_seekend(fd)<0) { + close(fd); return -1; + } LOCK_LOGS(); add_stream_log_impl(severity, filename, fd); logfiles->needs_close = 1; lf = logfiles; - _log_global_min_severity = get_min_log_level(); + log_global_min_severity_ = get_min_log_level(); if (log_tor_version(lf, 0) < 0) { delete_log(lf); @@ -871,7 +1058,7 @@ add_syslog_log(const log_severity_list_t *severity) LOCK_LOGS(); lf->next = logfiles; logfiles = lf; - _log_global_min_severity = get_min_log_level(); + log_global_min_severity_ = get_min_log_level(); UNLOCK_LOGS(); return 0; } @@ -907,7 +1094,7 @@ 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", NULL + "OR", "EDGE", "ACCT", "HIST", "HANDSHAKE", "HEARTBEAT", "CHANNEL", NULL }; /** Return a bitmask for the log domain for which <b>domain</b> is the name, @@ -1106,42 +1293,7 @@ switch_logs_debug(void) for (i = LOG_DEBUG; i >= LOG_ERR; --i) lf->severities->masks[SEVERITY_MASK_IDX(i)] = ~0u; } - _log_global_min_severity = get_min_log_level(); + log_global_min_severity_ = get_min_log_level(); UNLOCK_LOGS(); } -#if 0 -static void -dump_log_info(logfile_t *lf) -{ - const char *tp; - - if (lf->filename) { - printf("=== log into \"%s\" (%s-%s) (%stemporary)\n", lf->filename, - sev_to_string(lf->min_loglevel), - sev_to_string(lf->max_loglevel), - lf->is_temporary?"":"not "); - } else if (lf->is_syslog) { - printf("=== syslog (%s-%s) (%stemporary)\n", - sev_to_string(lf->min_loglevel), - sev_to_string(lf->max_loglevel), - lf->is_temporary?"":"not "); - } else { - printf("=== log (%s-%s) (%stemporary)\n", - sev_to_string(lf->min_loglevel), - sev_to_string(lf->max_loglevel), - lf->is_temporary?"":"not "); - } -} - -void -describe_logs(void) -{ - logfile_t *lf; - printf("==== BEGIN LOGS ====\n"); - for (lf = logfiles; lf; lf = lf->next) - dump_log_info(lf); - printf("==== END LOGS ====\n"); -} -#endif - |