123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281282283284285286287288289290291292293294295296297298299300301302303304305306307308309310311312313314315316317318319320321322323324325326327328329330331332333334335336337338339340341342343344345346347348349350351352353354355356357358359360361362363364365366367368369370371372373374375376377378379380381382383384385386387388389390391392393394395396397398399400401402403404405406407408409410411412413414415416417418419420421422423424425426427428429430431432433434435436437438439440441442443444445446447448449450451452453454455456457458459460461462463464465466467468469470471472473474475476477478479480481482483484485486487488489490491492493494495496497498499500501502503504505506507508509510511512513514515516517518519520521522523524525526527528529530531532533534535536537538539540541542543544545546547548549550551552553554555556557558559560561562563564565566567568569570571572573574575576577578579580581582583584585586587588589590591592593594595596597598599600601602603604605606607608609610611612613614615616617618619620621622623624625626627628629630631632633634635636637638639640641642643644645646647648649650651652653654655656657658659660661662663664665666667668669670671672673674675676677678679680681682683684685686687688689690691692693694695696697698699700701702703704705706707708709710711712713714715716717718719720 |
- /* Copyright (c) 2001, Matej Pfajfar.
- * Copyright (c) 2001-2004, Roger Dingledine.
- * Copyright (c) 2004-2006, Roger Dingledine, Nick Mathewson.
- * Copyright (c) 2007, The Tor Project, Inc. */
- /* 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 <stdarg.h>
- #include <assert.h>
- #include <stdio.h>
- #include <stdlib.h>
- #include <string.h>
- #ifdef HAVE_SYS_TIME_H
- #include <sys/time.h>
- #endif
- #ifdef HAVE_TIME_H
- #include <time.h>
- #endif
- #include "./util.h"
- #include "./log.h"
- #include <event.h>
- #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 seems_dead; /**< Boolean: true if the stream seems to be kaput. */
- int needs_close; /**< Boolean: true if the stream gets closed on shutdown. */
- int min_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";
- }
- }
- /** Helper: decide whether to include the function name in the log message. */
- static INLINE int
- should_log_function_name(uint32_t domain, int severity)
- {
- switch (severity) {
- case LOG_DEBUG:
- case LOG_INFO:
- /* All debugging messages occur in interesting places. */
- return 1;
- case LOG_NOTICE:
- case LOG_WARN:
- case LOG_ERR:
- /* We care about places where bugs occur. */
- return (domain == LD_BUG);
- default:
- assert(0); return 0;
- }
- }
- /* XXXX We should really have this protected by a mutex or something;
- * XXXX see bug 222. */
- /** Linked list of logfile_t. */
- static logfile_t *logfiles = NULL;
- #ifdef HAVE_SYSLOG_H
- static int syslog_count = 0;
- #endif
- /* What's the lowest log level anybody cares about? */
- int _log_global_min_severity = LOG_NOTICE;
- static void delete_log(logfile_t *victim);
- static void close_log(logfile_t *victim);
- /** Name of the application: used to generate the message we write at the
- * start of each new log. */
- static char *appname = NULL;
- /** Set the "application name" for the logs to <b>name</b>: we'll use this
- * name in the message we write when starting up, and at the start of each new
- * log.
- *
- * Tor uses this string to write the version number to the log file. */
- void
- log_set_application_name(const char *name)
- {
- tor_free(appname);
- appname = name ? tor_strdup(name) : NULL;
- }
- /** Helper: Write the standard prefix for log lines to a
- * <b>buf_len</b> character buffer in <b>buf</b>.
- */
- 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);
- if (appname) {
- tor_snprintf(buf+n, sizeof(buf)-n,
- "%s opening %slog file.\n", appname, is_new?"new ":"");
- } else {
- 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 <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 *
- format_msg(char *buf, size_t buf_len,
- uint32_t domain, 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 && should_log_function_name(domain, severity)) {
- r = tor_snprintf(buf+n, buf_len-n, "%s(): ", funcname);
- if (r<0)
- n = strlen(buf);
- else
- n += r;
- }
- if (domain == LD_BUG && buf_len-n > 6) {
- memcpy(buf+n, "Bug: ", 6);
- n += 5;
- }
- 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
- * <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, uint32_t domain, 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->min_loglevel || severity < lf->max_loglevel) {
- lf = lf->next;
- continue;
- }
- if (! (lf->file || lf->is_syslog || lf->callback)) {
- lf = lf->next;
- continue;
- }
- if (lf->seems_dead) {
- lf = lf->next;
- continue;
- }
- if (!formatted) {
- end_of_prefix =
- format_msg(buf, sizeof(buf), domain, severity, funcname, format, ap);
- formatted = 1;
- }
- if (lf->is_syslog) {
- #ifdef HAVE_SYSLOG_H
- /* XXXX Some syslog implementations have scary limits on the length of
- * what you can pass them. Can/should we detect this? */
- syslog(severity, "%s", end_of_prefix);
- #endif
- lf = lf->next;
- continue;
- } else if (lf->callback) {
- lf->callback(severity, domain, end_of_prefix);
- lf = lf->next;
- continue;
- }
- if (fputs(buf, lf->file) == EOF ||
- fflush(lf->file) == EOF) { /* error */
- /* don't log the error! mark this log entry to be blown away, and
- * continue. */
- lf->seems_dead = 1;
- }
- lf = lf->next;
- }
- }
- /** Output a message to the log. */
- void
- _log(int severity, uint32_t domain, const char *format, ...)
- {
- va_list ap;
- va_start(ap,format);
- logv(severity, domain, NULL, format, ap);
- va_end(ap);
- }
- /** Output a message to the log, prefixed with a function name <b>fn</b>. */
- #ifdef __GNUC__
- void
- _log_fn(int severity, uint32_t domain, const char *fn, const char *format, ...)
- {
- va_list ap;
- va_start(ap,format);
- logv(severity, domain, fn, format, ap);
- va_end(ap);
- }
- #else
- const char *_log_fn_function_name=NULL;
- void
- _log_fn(int severity, uint32_t domain, const char *format, ...)
- {
- va_list ap;
- va_start(ap,format);
- logv(severity, domain, _log_fn_function_name, format, ap);
- va_end(ap);
- _log_fn_function_name = NULL;
- }
- void
- _log_debug(uint32_t domain, const char *format, ...)
- {
- va_list ap;
- va_start(ap,format);
- logv(LOG_DEBUG, domain, _log_fn_function_name, format, ap);
- va_end(ap);
- _log_fn_function_name = NULL;
- }
- void
- _log_info(uint32_t domain, const char *format, ...)
- {
- va_list ap;
- va_start(ap,format);
- logv(LOG_INFO, domain, _log_fn_function_name, format, ap);
- va_end(ap);
- _log_fn_function_name = NULL;
- }
- void
- _log_notice(uint32_t domain, const char *format, ...)
- {
- va_list ap;
- va_start(ap,format);
- logv(LOG_NOTICE, domain, _log_fn_function_name, format, ap);
- va_end(ap);
- _log_fn_function_name = NULL;
- }
- void
- _log_warn(uint32_t domain, const char *format, ...)
- {
- va_list ap;
- va_start(ap,format);
- logv(LOG_WARN, domain, _log_fn_function_name, format, ap);
- va_end(ap);
- _log_fn_function_name = NULL;
- }
- void
- _log_err(uint32_t domain, const char *format, ...)
- {
- va_list ap;
- va_start(ap,format);
- logv(LOG_ERR, domain, _log_fn_function_name, format, ap);
- va_end(ap);
- _log_fn_function_name = NULL;
- }
- #endif
- /** Close all open log files, and free other static memory. */
- void
- logs_free_all(void)
- {
- logfile_t *victim, *next;
- next = logfiles;
- logfiles = NULL;
- while (next) {
- victim = next;
- next = next->next;
- close_log(victim);
- tor_free(victim->filename);
- tor_free(victim);
- }
- tor_free(appname);
- }
- /** Remove and free the log entry <b>victim</b> from the linked-list
- * logfiles (it is probably present, but it might not be due to thread
- * racing issues). After this function is called, the caller shouldn't
- * refer to <b>victim</b> anymore.
- *
- * Long-term, we need to do something about races in the log subsystem
- * in general. See bug 222 for more details.
- */
- 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);
- if (!tmpl)
- return;
- 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
- }
- }
- /** Add a log handler to send all messages of severity <b>loglevel</b>
- * or higher to <b>stream</b>. */
- 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->min_loglevel = loglevelMin;
- lf->max_loglevel = loglevelMax;
- lf->file = stream;
- lf->next = logfiles;
- logfiles = lf;
- _log_global_min_severity = get_min_log_level();
- }
- /** 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, "<temp>", stdout);
- logfiles->is_temporary = 1;
- _log_global_min_severity = get_min_log_level();
- }
- /**
- * Add a log handler to send messages of severity between
- * <b>logLevelmin</b> and <b>logLevelMax</b> to the function
- * <b>cb</b>.
- */
- int
- add_callback_log(int loglevelMin, int loglevelMax, log_callback cb)
- {
- logfile_t *lf;
- lf = tor_malloc_zero(sizeof(logfile_t));
- lf->min_loglevel = loglevelMin;
- lf->max_loglevel = loglevelMax;
- lf->filename = tor_strdup("<callback>");
- lf->callback = cb;
- lf->next = logfiles;
- logfiles = lf;
- _log_global_min_severity = get_min_log_level();
- return 0;
- }
- /** Adjust the configured severity of any logs whose callback function is
- * <b>cb</b>. */
- 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->min_loglevel = loglevelMin;
- lf->max_loglevel = loglevelMax;
- }
- }
- _log_global_min_severity = get_min_log_level();
- }
- /** 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);
- }
- }
- _log_global_min_severity = get_min_log_level();
- }
- /** Make all currently temporary logs (set to be closed by close_temp_logs)
- * live again, and close all non-temporary logs. */
- void
- rollback_log_changes(void)
- {
- logfile_t *lf;
- for (lf = logfiles; lf; lf = lf->next)
- lf->is_temporary = ! lf->is_temporary;
- close_temp_logs();
- }
- /** 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 <b>filename</b>. 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);
- }
- _log_global_min_severity = get_min_log_level();
- 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_PID | LOG_NDELAY, LOGFACILITY);
- lf = tor_malloc_zero(sizeof(logfile_t));
- lf->min_loglevel = loglevelMin;
- lf->filename = tor_strdup("<syslog>");
- lf->max_loglevel = loglevelMax;
- lf->is_syslog = 1;
- lf->next = logfiles;
- logfiles = lf;
- _log_global_min_severity = get_min_log_level();
- return 0;
- }
- #endif
- /** If <b>level</b> 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->min_loglevel > min)
- min = lf->min_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->min_loglevel = LOG_DEBUG;
- }
- }
- #ifdef HAVE_EVENT_SET_LOG_CALLBACK
- /** A string which, if it appears in a libevent log, should be ignored. */
- static const char *suppress_msg = NULL;
- /** Callback function passed to event_set_log() so we can intercept
- * log messages from libevent. */
- static void
- libevent_logging_callback(int severity, const char *msg)
- {
- char buf[1024];
- size_t n;
- if (suppress_msg && strstr(msg, suppress_msg))
- return;
- n = strlcpy(buf, msg, sizeof(buf));
- if (n && n < sizeof(buf) && buf[n-1] == '\n') {
- buf[n-1] = '\0';
- }
- switch (severity) {
- case _EVENT_LOG_DEBUG:
- log(LOG_DEBUG, LD_NET, "Message from libevent: %s", buf);
- break;
- case _EVENT_LOG_MSG:
- log(LOG_INFO, LD_NET, "Message from libevent: %s", buf);
- break;
- case _EVENT_LOG_WARN:
- log(LOG_WARN, LD_GENERAL, "Warning from libevent: %s", buf);
- break;
- case _EVENT_LOG_ERR:
- log(LOG_ERR, LD_GENERAL, "Error from libevent: %s", buf);
- break;
- default:
- log(LOG_WARN, LD_GENERAL, "Message [%d] from libevent: %s",
- severity, buf);
- break;
- }
- }
- /** Set hook to intercept log messages from libevent. */
- void
- configure_libevent_logging(void)
- {
- event_set_log_callback(libevent_logging_callback);
- }
- /** Ignore any libevent log message that contains <b>msg</b>. */
- 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)
- {
- (void)msg;
- }
- #endif
- #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
|