log.c

关于tor匿名通信的源代码

/* Copyright (c) 2001, Matej Pfajfar.
 * Copyright (c) 2001-2004, Roger Dingledine.
 * Copyright (c) 2004-2006, Roger Dingledine, Nick Mathewson.
 * Copyright (c) 2007-2008, 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"
#define LOG_PRIVATE
#include "log.h"
#include "container.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 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. */
  log_severity_list_t *severities; /**< DOCDOC */
} logfile_t;

static void log_free(logfile_t *victim);

/** 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:          /* Call assert, not tor_assert, since tor_assert
                       * calls log on failure. */
                      assert(0); return "UNKNOWN";
  }
}

/** Helper: decide whether to include the function name in the log message. */
static INLINE int
should_log_function_name(log_domain_mask_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:
      /* Call assert, not tor_assert, since tor_assert calls log on failure. */
      assert(0); return 0;
  }
}

#define USE_LOG_MUTEX

#ifdef USE_LOG_MUTEX
/** A mutex to guard changes to logfiles and logging. */
static tor_mutex_t *log_mutex = NULL;
#endif
/** Linked list of logfile_t. */
static logfile_t *logfiles = NULL;
#ifdef HAVE_SYSLOG_H
static int syslog_count = 0;
#endif

#ifdef USE_LOG_MUTEX
#define LOCK_LOGS() STMT_BEGIN                                          \
  tor_mutex_acquire(log_mutex);                                         \
  STMT_END
#define UNLOCK_LOGS() STMT_BEGIN tor_mutex_release(log_mutex); STMT_END
#else
#define LOCK_LOGS() STMT_NIL
#define UNLOCK_LOGS() STMT_NIL
#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,
           log_domain_mask_t domain, int severity, const char *funcname,
           const char *format, va_list ap)
{
  size_t n;
  int r;
  char *end_of_prefix;

  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) {
      size_t 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, log_domain_mask_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;

  /* Call assert, not tor_assert, since tor_assert calls log on failure. */
  assert(format);
  /* check that severity is sane.  Overrunning the masks array leads to
   * interesting and hard to diagnose effects */
  assert(severity >= LOG_ERR && severity <= LOG_DEBUG);
  LOCK_LOGS();
  lf = logfiles;
  while (lf) {
    if (! (lf->severities->masks[SEVERITY_MASK_IDX(severity)] & domain)) {
      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;
  }
  UNLOCK_LOGS();
}

/** Output a message to the log. */
void
_log(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, 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, log_domain_mask_t domain, const char *fn,
        const char *format, ...)
{
  va_list ap;
  if (severity > _log_global_min_severity)
    return;
  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, 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, format, ap);
  va_end(ap);
  _log_fn_function_name = NULL;
}
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, 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, 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, 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, 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, format, ap);
  va_end(ap);
  _log_fn_function_name = NULL;
}
#endif

/** DOCDOC */
static void
log_free(logfile_t *victim)
{
  tor_free(victim->severities);
  tor_free(victim->filename);
  tor_free(victim);
}

/** Close all open log files, and free other static memory. */
void
logs_free_all(void)
{
  logfile_t *victim, *next;
  LOCK_LOGS();
  next = logfiles;
  logfiles = NULL;
  UNLOCK_LOGS();
  while (next) {
    victim = next;
    next = next->next;
    close_log(victim);
    log_free(victim);
  }
  tor_free(appname);
  tor_mutex_free(log_mutex);
  log_mutex = NULL;
}

/** 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;
  }
  log_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
  }
}

/** Adjust a log severity configuration in <b>severity_out</b> to contain
 * every domain between <b>loglevelMin</b> and <b>loglevelMax</b>, inclusive.
 */
void
set_log_severity_config(int loglevelMin, int loglevelMax,
                        log_severity_list_t *severity_out)
{
  int i;
  tor_assert(loglevelMin >= loglevelMax);
  tor_assert(loglevelMin >= LOG_ERR && loglevelMin <= LOG_DEBUG);
  tor_assert(loglevelMax >= LOG_ERR && loglevelMax <= LOG_DEBUG);
  memset(severity_out, 0, sizeof(log_severity_list_t));
  for (i = loglevelMin; i >= loglevelMax; --i) {
    severity_out->masks[SEVERITY_MASK_IDX(i)] = ~0u;
  }
}