src/common/log.c

   1 /* Copyright 2001,2002,2003 Roger Dingledine, Matej Pfajfar. */
   2 /* See LICENSE for licensing information */
   3 /* $Id$ */
   4 const char log_c_id[] = "$Id$";
   5
   6 /**
   7  * \file log.c
   8  *
   9  * \brief Functions to send messages to log files or the console.
  10  */
  11
  12 #include "orconfig.h"
  13 #include <stdarg.h>
  14 #include <assert.h>
  15 #include <stdlib.h>
  16 #include <string.h>
  17 #include "./util.h"
  18 #include "./log.h"
  19
  20 #ifdef HAVE_EVENT_H
  21 #include <event.h>
  22 #else
  23 #error "Tor requires libevent to build."
  24 #endif
  25
  26 #define TRUNCATED_STR "[...truncated]"
  27 #define TRUNCATED_STR_LEN 14
  28
  29 /** Information for a single logfile; only used in log.c */
  30 typedef struct logfile_t {
  31   struct logfile_t *next; /**< Next logfile_t in the linked list. */
  32   char *filename; /**< Filename to open. */
  33   FILE *file; /**< Stream to receive log messages. */
  34   int needs_close; /**< Boolean: true if the stream gets closed on shutdown. */
  35   int loglevel; /**< Lowest severity level to send to this stream. */
  36   int max_loglevel; /**< Highest severity level to send to this stream. */
  37   int is_temporary; /**< Boolean: close after initializing logging subsystem.*/
  38   int is_syslog; /**< Boolean: send messages to syslog. */
  39   log_callback callback; /**< If not NULL, send messages to this function. */
  40 } logfile_t;
  41
  42 /** Helper: map a log severity to descriptive string. */
  43 static INLINE const char *sev_to_string(int severity) {
  44   switch (severity) {
  45     case LOG_DEBUG:   return "debug";
  46     case LOG_INFO:    return "info";
  47     case LOG_NOTICE:  return "notice";
  48     case LOG_WARN:    return "warn";
  49     case LOG_ERR:     return "err";
  50     default:          assert(0); return "UNKNOWN";
  51   }
  52 }
  53
  54 /** Linked list of logfile_t. */
  55 static logfile_t *logfiles = NULL;
  56 #ifdef HAVE_SYSLOG_H
  57 static int syslog_count = 0;
  58 #endif
  59
  60 static void delete_log(logfile_t *victim);
  61 static void close_log(logfile_t *victim);
  62 static int reset_log(logfile_t *lf);
  63
  64 /** Helper: Write the standard prefix for log lines to a
  65  * <b>buf_len</b> character buffer in <b>buf</b>.
  66  */
  67 static INLINE size_t
  68 _log_prefix(char *buf, size_t buf_len, int severity)
  69 {
  70   time_t t;
  71   struct timeval now;
  72   struct tm tm;
  73   size_t n;
  74   int r;
  75
  76   tor_gettimeofday(&now);
  77   t = (time_t)now.tv_sec;
  78
  79   n = strftime(buf, buf_len, "%b %d %H:%M:%S", tor_localtime_r(&t, &tm));
  80   r = tor_snprintf(buf+n, buf_len-n,
  81                 ".%.3ld [%s] ",
  82                 (long)now.tv_usec / 1000, sev_to_string(severity));
  83   if (r<0)
  84     return buf_len-1;
  85   else
  86     return n+r;
  87 }
  88
  89 /** If lf refers to an actual file that we have just opened, and the file
  90  * contains no data, log an "opening new logfile" message at the top.
  91  *
  92  * Return -1 if the log is broken and needs to be deleted, else return 0.
  93  */
  94 static int log_tor_version(logfile_t *lf, int reset)
  95 {
  96   char buf[256];
  97   size_t n;
  98   int is_new;
  99
 100   if (!lf->needs_close)
 101     /* If it doesn't get closed, it isn't really a file. */
 102     return 0;
 103   if (lf->is_temporary)
 104     /* If it's temporary, it isn't really a file. */
 105     return 0;
 106 #ifdef HAVE_FTELLO
 107   is_new = (ftello(lf->file) == 0);
 108 #else
 109   is_new = (ftell(lf->file) == 0);
 110 #endif
 111   if (reset && !is_new)
 112     /* We are resetting, but we aren't at the start of the file; no
 113      * need to log again. */
 114     return 0;
 115   n = _log_prefix(buf, sizeof(buf), LOG_NOTICE);
 116   tor_snprintf(buf+n, sizeof(buf)-n,
 117                "Tor %s opening %slog file.\n", VERSION, is_new?"new ":"");
 118   if (fputs(buf, lf->file) == EOF ||
 119       fflush(lf->file) == EOF) /* error */
 120     return -1; /* failed */
 121   return 0;
 122 }
 123
 124 /** Helper: Format a log message into a fixed-sized buffer. (This is
 125  * factored out of <b>logv</b> so that we never format a message more
 126  * than once.)  Return a pointer to the first character of the message
 127  * portion of the formatted string.
 128  */
 129 static INLINE char *format_msg(char *buf, size_t buf_len,
 130                               int severity, const char *funcname,
 131                               const char *format, va_list ap)
 132 {
 133   size_t n;
 134   int r;
 135   char *end_of_prefix;
 136
 137   tor_assert(buf_len >= 2); /* prevent integer underflow */
 138   buf_len -= 2; /* subtract 2 characters so we have room for \n\0 */
 139
 140   n = _log_prefix(buf, buf_len, severity);
 141   end_of_prefix = buf+n;
 142
 143   if (funcname) {
 144     r = tor_snprintf(buf+n, buf_len-n, "%s(): ", funcname);
 145     if (r<0)
 146       n = strlen(buf);
 147     else
 148       n += r;
 149   }
 150
 151   r = tor_vsnprintf(buf+n,buf_len-n,format,ap);
 152   if (r < 0) {
 153     /* The message was too long; overwrite the end of the buffer with
 154      * "[...truncated]" */
 155     if (buf_len >= TRUNCATED_STR_LEN) {
 156       int offset = buf_len-TRUNCATED_STR_LEN;
 157       /* We have an extra 2 characters after buf_len to hold the \n\0,
 158        * so it's safe to add 1 to the size here. */
 159       strlcpy(buf+offset, TRUNCATED_STR, buf_len-offset+1);
 160     }
 161     /* Set 'n' to the end of the buffer, where we'll be writing \n\0.
 162      * Since we already subtracted 2 from buf_len, this is safe.*/
 163     n = buf_len;
 164   } else {
 165     n += r;
 166   }
 167   buf[n]='\n';
 168   buf[n+1]='\0';
 169   return end_of_prefix;
 170 }
 171
 172 /** Helper: sends a message to the appropriate logfiles, at loglevel
 173  * <b>severity</b>.  If provided, <b>funcname</b> is prepended to the
 174  * message.  The actual message is derived as from tor_snprintf(format,ap).
 175  */
 176 static void
 177 logv(int severity, const char *funcname, const char *format, va_list ap)
 178 {
 179   char buf[10024];
 180   int formatted = 0;
 181   logfile_t *lf;
 182   char *end_of_prefix=NULL;
 183
 184   assert(format);
 185   lf = logfiles;
 186   while (lf) {
 187     if (severity > lf->loglevel || severity < lf->max_loglevel) {
 188       lf = lf->next;
 189       continue;
 190     }
 191     if (! (lf->file || lf->is_syslog || lf->callback)) {
 192       lf = lf->next;
 193       continue;
 194     }
 195
 196     if (!formatted) {
 197       end_of_prefix =
 198         format_msg(buf, sizeof(buf), severity, funcname, format, ap);
 199       formatted = 1;
 200     }
 201     if (lf->is_syslog) {
 202 #ifdef HAVE_SYSLOG_H
 203       syslog(severity, "%s", end_of_prefix);
 204 #endif
 205       lf = lf->next;
 206       continue;
 207     } else if (lf->callback) {
 208       lf->callback(severity, end_of_prefix);
 209       lf = lf->next;
 210       continue;
 211     }
 212     if (fputs(buf, lf->file) == EOF ||
 213         fflush(lf->file) == EOF) { /* error */
 214       /* don't log the error! Blow away this log entry and continue. */
 215       logfile_t *victim = lf;
 216       lf = victim->next;
 217       delete_log(victim);
 218     } else {
 219       lf = lf->next;
 220     }
 221   }
 222 }
 223
 224 /** Output a message to the log. */
 225 void _log(int severity, const char *format, ...)
 226 {
 227   va_list ap;
 228   va_start(ap,format);
 229   logv(severity, NULL, format, ap);
 230   va_end(ap);
 231 }
 232
 233 /** Output a message to the log, prefixed with a function name <b>fn</b>. */
 234 #ifdef __GNUC__
 235 void _log_fn(int severity, const char *fn, const char *format, ...)
 236 {
 237   va_list ap;
 238   va_start(ap,format);
 239   logv(severity, fn, format, ap);
 240   va_end(ap);
 241 }
 242 #else
 243 const char *_log_fn_function_name=NULL;
 244 void _log_fn(int severity, const char *format, ...)
 245 {
 246   va_list ap;
 247   va_start(ap,format);
 248   logv(severity, _log_fn_function_name, format, ap);
 249   va_end(ap);
 250   _log_fn_function_name = NULL;
 251 }
 252 #endif
 253
 254 /** Close all open log files. */
 255 void close_logs()
 256 {
 257   logfile_t *victim;
 258   while (logfiles) {
 259     victim = logfiles;
 260     logfiles = logfiles->next;
 261     close_log(victim);
 262     tor_free(victim->filename);
 263     tor_free(victim);
 264   }
 265 }
 266
 267 /** Close and re-open all log files; used to rotate logs on SIGHUP. */
 268 void reset_logs()
 269 {
 270   logfile_t *lf = logfiles;
 271   while (lf) {
 272     if (reset_log(lf)) {
 273       /* error. don't log it. delete the log entry and continue. */
 274       logfile_t *victim = lf;
 275       lf = victim->next;
 276       delete_log(victim);
 277       continue;
 278     }
 279     lf = lf->next;
 280   }
 281 }
 282
 283 /** Remove and free the log entry <b>victim</b> from the linked-list
 284  * logfiles (it must be present in the list when this function is
 285  * called). After this function is called, the caller shouldn't refer
 286  * to <b>victim</b> anymore.
 287  */
 288 static void delete_log(logfile_t *victim) {
 289   logfile_t *tmpl;
 290   if (victim == logfiles)
 291     logfiles = victim->next;
 292   else {
 293     for (tmpl = logfiles; tmpl && tmpl->next != victim; tmpl=tmpl->next) ;
 294     tor_assert(tmpl);
 295     tor_assert(tmpl->next == victim);
 296     tmpl->next = victim->next;
 297   }
 298   tor_free(victim->filename);
 299   tor_free(victim);
 300 }
 301
 302 /** Helper: release system resources (but not memory) held by a single
 303  * logfile_t. */
 304 static void close_log(logfile_t *victim)
 305 {
 306   if (victim->needs_close && victim->file) {
 307     fclose(victim->file);
 308   } else if (victim->is_syslog) {
 309 #ifdef HAVE_SYSLOG_H
 310     if (--syslog_count == 0)
 311       /* There are no other syslogs; close the logging facility. */
 312       closelog();
 313 #endif
 314   }
 315 }
 316
 317 /** Helper: reset a single logfile_t.  For a file log, this involves
 318  * closing and reopening the log, and maybe writing the version.  For
 319  * other log types, do nothing. */
 320 static int reset_log(logfile_t *lf)
 321 {
 322   if (lf->needs_close) {
 323     if (fclose(lf->file)==EOF ||
 324        !(lf->file = fopen(lf->filename, "a"))) {
 325       return -1;
 326     } else {
 327       if (log_tor_version(lf, 1) < 0)
 328         return -1;
 329     }
 330   }
 331   return 0;
 332 }
 333
 334 /** Add a log handler to send all messages of severity <b>loglevel</b>
 335  * or higher to <b>stream</b>. */
 336 void add_stream_log(int loglevelMin, int loglevelMax, const char *name, FILE *stream)
 337 {
 338   logfile_t *lf;
 339   lf = tor_malloc_zero(sizeof(logfile_t));
 340   lf->filename = tor_strdup(name);
 341   lf->loglevel = loglevelMin;
 342   lf->max_loglevel = loglevelMax;
 343   lf->file = stream;
 344   lf->next = logfiles;
 345   logfiles = lf;
 346 }
 347
 348 /** Add a log handler to receive messages during startup (before the real
 349  * logs are initialized).
 350  */
 351 void add_temp_log(void)
 352 {
 353   add_stream_log(LOG_NOTICE, LOG_ERR, "<temp>", stdout);
 354   logfiles->is_temporary = 1;
 355 }
 356
 357 /**
 358  * Add a log handler to send messages of severity between
 359  * <b>logLevelmin</b> and <b>logLevelMax</b> to the function
 360  * <b>cb</b>.
 361  */
 362 int add_callback_log(int loglevelMin, int loglevelMax, log_callback cb)
 363 {
 364   logfile_t *lf;
 365   lf = tor_malloc_zero(sizeof(logfile_t));
 366   lf->loglevel = loglevelMin;
 367   lf->max_loglevel = loglevelMax;
 368   lf->filename = tor_strdup("<callback>");
 369   lf->callback = cb;
 370   lf->next = logfiles;
 371   logfiles = lf;
 372   return 0;
 373 }
 374
 375 /** Close any log handlers added by add_temp_log or marked by mark_logs_temp */
 376 void close_temp_logs(void)
 377 {
 378   logfile_t *lf, **p;
 379   for (p = &logfiles; *p; ) {
 380     if ((*p)->is_temporary) {
 381       lf = *p;
 382       /* we use *p here to handle the edge case of the head of the list */
 383       *p = (*p)->next;
 384       close_log(lf);
 385       tor_free(lf->filename);
 386       tor_free(lf);
 387     } else {
 388       p = &((*p)->next);
 389     }
 390   }
 391 }
 392
 393 /** Configure all log handles to be closed by close_temp_logs */
 394 void mark_logs_temp(void)
 395 {
 396   logfile_t *lf;
 397   for (lf = logfiles; lf; lf = lf->next)
 398     lf->is_temporary = 1;
 399 }
 400
 401 /**
 402  * Add a log handler to send messages to <b>filename</b>. If opening
 403  * the logfile fails, -1 is returned and errno is set appropriately
 404  * (by fopen).
 405  */
 406 int add_file_log(int loglevelMin, int loglevelMax, const char *filename)
 407 {
 408   FILE *f;
 409   f = fopen(filename, "a");
 410   if (!f) return -1;
 411   add_stream_log(loglevelMin, loglevelMax, filename, f);
 412   logfiles->needs_close = 1;
 413   if (log_tor_version(logfiles, 0) < 0) {
 414     delete_log(logfiles);
 415   }
 416   return 0;
 417 }
 418
 419 #ifdef HAVE_SYSLOG_H
 420 /**
 421  * Add a log handler to send messages to they system log facility.
 422  */
 423 int add_syslog_log(int loglevelMin, int loglevelMax)
 424 {
 425   logfile_t *lf;
 426   if (syslog_count++ == 0)
 427     /* This is the first syslog. */
 428     openlog("Tor", LOG_NDELAY, LOG_DAEMON);
 429
 430   lf = tor_malloc_zero(sizeof(logfile_t));
 431   lf->loglevel = loglevelMin;
 432   lf->filename = tor_strdup("<syslog>");
 433   lf->max_loglevel = loglevelMax;
 434   lf->is_syslog = 1;
 435   lf->next = logfiles;
 436   logfiles = lf;
 437   return 0;
 438 }
 439 #endif
 440
 441 /** If <b>level</b> is a valid log severity, return the corresponding
 442  * numeric value.  Otherwise, return -1. */
 443 int parse_log_level(const char *level) {
 444   if (!strcasecmp(level, "err"))
 445     return LOG_ERR;
 446   if (!strcasecmp(level, "warn"))
 447     return LOG_WARN;
 448   if (!strcasecmp(level, "notice"))
 449     return LOG_NOTICE;
 450   if (!strcasecmp(level, "info"))
 451     return LOG_INFO;
 452   if (!strcasecmp(level, "debug"))
 453     return LOG_DEBUG;
 454   return -1;
 455 }
 456
 457 /** Return the string equivalent of a given log level. */
 458 const char *log_level_to_string(int level)
 459 {
 460   return sev_to_string(level);
 461 }
 462
 463 /** Return the least severe log level that any current log is interested in. */
 464 int get_min_log_level(void)
 465 {
 466   logfile_t *lf;
 467   int min = LOG_ERR;
 468   for (lf = logfiles; lf; lf = lf->next) {
 469     if (lf->loglevel > min)
 470       min = lf->loglevel;
 471   }
 472   return min;
 473 }
 474
 475 /** Switch all logs to output at most verbose level. */
 476 void switch_logs_debug(void)
 477 {
 478   logfile_t *lf;
 479   for (lf = logfiles; lf; lf=lf->next) {
 480     lf->loglevel = LOG_DEBUG;
 481   }
 482 }
 483
 484 #ifdef HAVE_EVENT_SET_LOG_CALLBACK
 485 static const char *suppress_msg = NULL;
 486 void libevent_logging_callback(int severity, const char *msg)
 487 {
 488   if (suppress_msg && strstr(msg, suppress_msg))
 489     return;
 490   switch (severity) {
 491     case _EVENT_LOG_DEBUG:
 492       log(LOG_DEBUG, "Message from libevent: %s", msg);
 493       break;
 494     case _EVENT_LOG_MSG:
 495       log(LOG_INFO, "Message from libevent: %s", msg);
 496       break;
 497     case _EVENT_LOG_WARN:
 498       log(LOG_WARN, "Warning from libevent: %s", msg);
 499       break;
 500     case _EVENT_LOG_ERR:
 501       log(LOG_ERR, "Error from libevent: %s", msg);
 502       break;
 503     default:
 504       log(LOG_WARN, "Message [%d] from libevent: %s", severity, msg);
 505       break;
 506   }
 507 }
 508 void configure_libevent_logging(void)
 509 {
 510   event_set_log_callback(libevent_logging_callback);
 511 }
 512 void suppress_libevent_log_msg(const char *msg)
 513 {
 514   suppress_msg = msg;
 515 }
 516 #else
 517 void configure_libevent_logging(void) {}
 518 #endif