/* Copyright 2001,2002,2003 Roger Dingledine, Matej Pfajfar. * Copyright 2004-2005 Roger Dingledine, Nick Mathewson */ /* See LICENSE for licensing information */ /* $Id$ */ const char log_c_id[] = "$Id$"; /** * \file log.c * * \brief Functions to send messages to log files or the console. */ #include "orconfig.h" #include #include #include #include #include "./util.h" #include "./log.h" #ifdef HAVE_EVENT_H #include #else #error "Tor requires libevent to build." #endif #define TRUNCATED_STR "[...truncated]" #define TRUNCATED_STR_LEN 14 /** Information for a single logfile; only used in log.c */ typedef struct logfile_t { struct logfile_t *next; /**< Next logfile_t in the linked list. */ char *filename; /**< Filename to open. */ FILE *file; /**< Stream to receive log messages. */ int needs_close; /**< Boolean: true if the stream gets closed on shutdown. */ int loglevel; /**< Lowest severity level to send to this stream. */ int max_loglevel; /**< Highest severity level to send to this stream. */ int is_temporary; /**< Boolean: close after initializing logging subsystem.*/ int is_syslog; /**< Boolean: send messages to syslog. */ log_callback callback; /**< If not NULL, send messages to this function. */ } logfile_t; /** Helper: map a log severity to descriptive string. */ static INLINE const char *sev_to_string(int severity) { switch (severity) { case LOG_DEBUG: return "debug"; case LOG_INFO: return "info"; case LOG_NOTICE: return "notice"; case LOG_WARN: return "warn"; case LOG_ERR: return "err"; default: assert(0); return "UNKNOWN"; } } /** Linked list of logfile_t. */ static logfile_t *logfiles = NULL; #ifdef HAVE_SYSLOG_H static int syslog_count = 0; #endif static void delete_log(logfile_t *victim); static void close_log(logfile_t *victim); static int reset_log(logfile_t *lf); /** Helper: Write the standard prefix for log lines to a * buf_len character buffer in buf. */ static INLINE size_t _log_prefix(char *buf, size_t buf_len, int severity) { time_t t; struct timeval now; struct tm tm; size_t n; int r; tor_gettimeofday(&now); t = (time_t)now.tv_sec; n = strftime(buf, buf_len, "%b %d %H:%M:%S", tor_localtime_r(&t, &tm)); r = tor_snprintf(buf+n, buf_len-n, ".%.3ld [%s] ", (long)now.tv_usec / 1000, sev_to_string(severity)); if (r<0) return buf_len-1; else return n+r; } /** If lf refers to an actual file that we have just opened, and the file * contains no data, log an "opening new logfile" message at the top. * * Return -1 if the log is broken and needs to be deleted, else return 0. */ static int log_tor_version(logfile_t *lf, int reset) { char buf[256]; size_t n; int is_new; if (!lf->needs_close) /* If it doesn't get closed, it isn't really a file. */ return 0; if (lf->is_temporary) /* If it's temporary, it isn't really a file. */ return 0; #ifdef HAVE_FTELLO is_new = (ftello(lf->file) == 0); #else is_new = (ftell(lf->file) == 0); #endif if (reset && !is_new) /* 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); tor_snprintf(buf+n, sizeof(buf)-n, "Tor %s opening %slog file.\n", VERSION, is_new?"new ":""); if (fputs(buf, lf->file) == EOF || fflush(lf->file) == EOF) /* error */ return -1; /* failed */ return 0; } /** Helper: Format a log message into a fixed-sized buffer. (This is * factored out of logv 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 *format_msg(char *buf, size_t buf_len, int severity, const char *funcname, const char *format, va_list ap) { size_t n; int r; char *end_of_prefix; tor_assert(buf_len >= 2); /* prevent integer underflow */ buf_len -= 2; /* subtract 2 characters so we have room for \n\0 */ n = _log_prefix(buf, buf_len, severity); end_of_prefix = buf+n; if (funcname) { r = tor_snprintf(buf+n, buf_len-n, "%s(): ", funcname); if (r<0) n = strlen(buf); else n += r; } r = tor_vsnprintf(buf+n,buf_len-n,format,ap); if (r < 0) { /* The message was too long; overwrite the end of the buffer with * "[...truncated]" */ if (buf_len >= TRUNCATED_STR_LEN) { int offset = buf_len-TRUNCATED_STR_LEN; /* We have an extra 2 characters after buf_len to hold the \n\0, * so it's safe to add 1 to the size here. */ strlcpy(buf+offset, TRUNCATED_STR, buf_len-offset+1); } /* Set 'n' to the end of the buffer, where we'll be writing \n\0. * Since we already subtracted 2 from buf_len, this is safe.*/ n = buf_len; } else { n += r; } buf[n]='\n'; buf[n+1]='\0'; return end_of_prefix; } /** 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). */ static void logv(int severity, const char *funcname, const char *format, va_list ap) { char buf[10024]; int formatted = 0; logfile_t *lf; char *end_of_prefix=NULL; assert(format); lf = logfiles; while (lf) { if (severity > lf->loglevel || severity < lf->max_loglevel) { lf = lf->next; continue; } if (! (lf->file || lf->is_syslog || lf->callback)) { lf = lf->next; continue; } if (!formatted) { end_of_prefix = format_msg(buf, sizeof(buf), severity, funcname, format, ap); formatted = 1; } if (lf->is_syslog) { #ifdef HAVE_SYSLOG_H syslog(severity, "%s", end_of_prefix); #endif lf = lf->next; continue; } else if (lf->callback) { lf->callback(severity, end_of_prefix); lf = lf->next; continue; } if (fputs(buf, lf->file) == EOF || fflush(lf->file) == EOF) { /* error */ /* don't log the error! Blow away this log entry and continue. */ logfile_t *victim = lf; lf = victim->next; delete_log(victim); } else { lf = lf->next; } } } /** Output a message to the log. */ void _log(int severity, const char *format, ...) { va_list ap; va_start(ap,format); logv(severity, NULL, format, ap); va_end(ap); } /** Output a message to the log, prefixed with a function name fn. */ #ifdef __GNUC__ void _log_fn(int severity, const char *fn, const char *format, ...) { va_list ap; va_start(ap,format); logv(severity, fn, format, ap); va_end(ap); } #else const char *_log_fn_function_name=NULL; void _log_fn(int severity, const char *format, ...) { va_list ap; va_start(ap,format); logv(severity, _log_fn_function_name, format, ap); va_end(ap); _log_fn_function_name = NULL; } #endif /** Close all open log files. */ void close_logs() { logfile_t *victim; while (logfiles) { victim = logfiles; logfiles = logfiles->next; close_log(victim); tor_free(victim->filename); tor_free(victim); } } /** Close and re-open all log files; used to rotate logs on SIGHUP. */ void reset_logs() { logfile_t *lf = logfiles; while (lf) { if (reset_log(lf)) { /* error. don't log it. delete the log entry and continue. */ logfile_t *victim = lf; lf = victim->next; delete_log(victim); continue; } lf = lf->next; } } /** Remove and free the log entry victim from the linked-list * logfiles (it must be present in the list when this function is * called). After this function is called, the caller shouldn't refer * to victim anymore. */ static void delete_log(logfile_t *victim) { logfile_t *tmpl; if (victim == logfiles) logfiles = victim->next; else { for (tmpl = logfiles; tmpl && tmpl->next != victim; tmpl=tmpl->next) ; tor_assert(tmpl); tor_assert(tmpl->next == victim); tmpl->next = victim->next; } tor_free(victim->filename); tor_free(victim); } /** Helper: release system resources (but not memory) held by a single * logfile_t. */ static void close_log(logfile_t *victim) { if (victim->needs_close && victim->file) { fclose(victim->file); } else if (victim->is_syslog) { #ifdef HAVE_SYSLOG_H if (--syslog_count == 0) /* There are no other syslogs; close the logging facility. */ closelog(); #endif } } /** Helper: reset a single logfile_t. For a file log, this involves * closing and reopening the log, and maybe writing the version. For * other log types, do nothing. */ static int reset_log(logfile_t *lf) { if (lf->needs_close) { if (fclose(lf->file)==EOF || !(lf->file = fopen(lf->filename, "a"))) { return -1; } else { if (log_tor_version(lf, 1) < 0) return -1; } } return 0; } /** Add a log handler to send all messages of severity loglevel * or higher to stream. */ void add_stream_log(int loglevelMin, int loglevelMax, const char *name, FILE *stream) { logfile_t *lf; lf = tor_malloc_zero(sizeof(logfile_t)); lf->filename = tor_strdup(name); lf->loglevel = loglevelMin; lf->max_loglevel = loglevelMax; lf->file = stream; lf->next = logfiles; logfiles = lf; } /** Add a log handler to receive messages during startup (before the real * logs are initialized). */ void add_temp_log(void) { add_stream_log(LOG_NOTICE, LOG_ERR, "", stdout); logfiles->is_temporary = 1; } /** * Add a log handler to send messages of severity between * logLevelmin and logLevelMax to the function * cb. */ int add_callback_log(int loglevelMin, int loglevelMax, log_callback cb) { logfile_t *lf; lf = tor_malloc_zero(sizeof(logfile_t)); lf->loglevel = loglevelMin; lf->max_loglevel = loglevelMax; lf->filename = tor_strdup(""); lf->callback = cb; lf->next = logfiles; logfiles = lf; return 0; } void change_callback_log_severity(int loglevelMin, int loglevelMax, log_callback cb) { logfile_t *lf; for (lf = logfiles; lf; lf = lf->next) { if (lf->callback == cb) { lf->loglevel = loglevelMin; lf->max_loglevel = loglevelMax; } } } /** Close any log handlers added by add_temp_log or marked by mark_logs_temp */ void close_temp_logs(void) { logfile_t *lf, **p; for (p = &logfiles; *p; ) { if ((*p)->is_temporary) { lf = *p; /* we use *p here to handle the edge case of the head of the list */ *p = (*p)->next; close_log(lf); tor_free(lf->filename); tor_free(lf); } else { p = &((*p)->next); } } } /** Configure all log handles to be closed by close_temp_logs */ void mark_logs_temp(void) { logfile_t *lf; for (lf = logfiles; lf; lf = lf->next) lf->is_temporary = 1; } /** * Add a log handler to send messages to filename. If opening * the logfile fails, -1 is returned and errno is set appropriately * (by fopen). */ int add_file_log(int loglevelMin, int loglevelMax, const char *filename) { FILE *f; f = fopen(filename, "a"); if (!f) return -1; add_stream_log(loglevelMin, loglevelMax, filename, f); logfiles->needs_close = 1; if (log_tor_version(logfiles, 0) < 0) { delete_log(logfiles); } return 0; } #ifdef HAVE_SYSLOG_H /** * Add a log handler to send messages to they system log facility. */ int add_syslog_log(int loglevelMin, int loglevelMax) { logfile_t *lf; if (syslog_count++ == 0) /* This is the first syslog. */ openlog("Tor", LOG_NDELAY, LOG_DAEMON); lf = tor_malloc_zero(sizeof(logfile_t)); lf->loglevel = loglevelMin; lf->filename = tor_strdup(""); lf->max_loglevel = loglevelMax; lf->is_syslog = 1; lf->next = logfiles; logfiles = lf; return 0; } #endif /** If level is a valid log severity, return the corresponding * numeric value. Otherwise, return -1. */ int parse_log_level(const char *level) { if (!strcasecmp(level, "err")) return LOG_ERR; if (!strcasecmp(level, "warn")) return LOG_WARN; if (!strcasecmp(level, "notice")) return LOG_NOTICE; if (!strcasecmp(level, "info")) return LOG_INFO; if (!strcasecmp(level, "debug")) return LOG_DEBUG; return -1; } /** Return the string equivalent of a given log level. */ const char *log_level_to_string(int level) { return sev_to_string(level); } /** Return the least severe log level that any current log is interested in. */ int get_min_log_level(void) { logfile_t *lf; int min = LOG_ERR; for (lf = logfiles; lf; lf = lf->next) { if (lf->loglevel > min) min = lf->loglevel; } return min; } /** Switch all logs to output at most verbose level. */ void switch_logs_debug(void) { logfile_t *lf; for (lf = logfiles; lf; lf=lf->next) { lf->loglevel = LOG_DEBUG; } } #ifdef HAVE_EVENT_SET_LOG_CALLBACK static const char *suppress_msg = NULL; static void libevent_logging_callback(int severity, const char *msg) { if (suppress_msg && strstr(msg, suppress_msg)) return; switch (severity) { case _EVENT_LOG_DEBUG: log(LOG_DEBUG, "Message from libevent: %s", msg); break; case _EVENT_LOG_MSG: log(LOG_INFO, "Message from libevent: %s", msg); break; case _EVENT_LOG_WARN: log(LOG_WARN, "Warning from libevent: %s", msg); break; case _EVENT_LOG_ERR: log(LOG_ERR, "Error from libevent: %s", msg); break; default: log(LOG_WARN, "Message [%d] from libevent: %s", severity, msg); break; } } void configure_libevent_logging(void) { event_set_log_callback(libevent_logging_callback); } void suppress_libevent_log_msg(const char *msg) { suppress_msg = msg; } #else void configure_libevent_logging(void) {} void suppress_libevent_log_msg(const char *msg) {} #endif