src/common/log.c

   1 /* Copyright (c) 2001 Matej Pfajfar.
   2  * Copyright (c) 2001-2004, Roger Dingledine.
   3  * Copyright (c) 2004-2007, Roger Dingledine, Nick Mathewson. */
   4 /* See LICENSE for licensing information */
   5 /* $Id$ */
   6 const char log_c_id[] = "$Id$";
   7
   8 /**
   9  * \file log.c
  10  * \brief Functions to send messages to log files or the console.
  11  **/
  12
  13 #include "orconfig.h"
  14 #include <stdarg.h>
  15 #include <assert.h>
  16 #include <stdio.h>
  17 #include <stdlib.h>
  18 #include <string.h>
  19 #ifdef HAVE_SYS_TIME_H
  20 #include <sys/time.h>
  21 #endif
  22 #ifdef HAVE_TIME_H
  23 #include <time.h>
  24 #endif
  25 #include "./util.h"
  26 #include "./log.h"
  27
  28 #ifdef HAVE_EVENT_H
  29 #include <event.h>
  30 #else
  31 #error "Tor requires libevent to build."
  32 #endif
  33
  34 #define TRUNCATED_STR "[...truncated]"
  35 #define TRUNCATED_STR_LEN 14
  36
  37 /** Information for a single logfile; only used in log.c */
  38 typedef struct logfile_t {
  39   struct logfile_t *next; /**< Next logfile_t in the linked list. */
  40   char *filename; /**< Filename to open. */
  41   FILE *file; /**< Stream to receive log messages. */
  42   int needs_close; /**< Boolean: true if the stream gets closed on shutdown. */
  43   int min_loglevel; /**< Lowest severity level to send to this stream. */
  44   int max_loglevel; /**< Highest severity level to send to this stream. */
  45   int is_temporary; /**< Boolean: close after initializing logging subsystem.*/
  46   int is_syslog; /**< Boolean: send messages to syslog. */
  47   log_callback callback; /**< If not NULL, send messages to this function. */
  48 } logfile_t;
  49
  50 /** Helper: map a log severity to descriptive string. */
  51 static INLINE const char *
  52 sev_to_string(int severity)
  53 {
  54   switch (severity) {
  55     case LOG_DEBUG:   return "debug";
  56     case LOG_INFO:    return "info";
  57     case LOG_NOTICE:  return "notice";
  58     case LOG_WARN:    return "warn";
  59     case LOG_ERR:     return "err";
  60     default:          assert(0); return "UNKNOWN";
  61   }
  62 }
  63
  64 /** Helper: decide whether to include the function name in the log message. */
  65 static INLINE int
  66 should_log_function_name(uint32_t domain, int severity)
  67 {
  68   switch (severity) {
  69     case LOG_DEBUG:
  70     case LOG_INFO:
  71       /* All debugging messages occur in interesting places. */
  72       return 1;
  73     case LOG_NOTICE:
  74     case LOG_WARN:
  75     case LOG_ERR:
  76       /* We care about places where bugs occur. */
  77       return (domain == LD_BUG);
  78     default:
  79       assert(0); return 0;
  80   }
  81 }
  82
  83 /** Linked list of logfile_t. */
  84 static logfile_t *logfiles = NULL;
  85 #ifdef HAVE_SYSLOG_H
  86 static int syslog_count = 0;
  87 #endif
  88
  89 /* What's the lowest log level anybody cares about? */
  90 int _log_global_min_severity = LOG_NOTICE;
  91
  92 static void delete_log(logfile_t *victim);
  93 static void close_log(logfile_t *victim);
  94
  95 /** Helper: Write the standard prefix for log lines to a
  96  * <b>buf_len</b> character buffer in <b>buf</b>.
  97  */
  98 static INLINE size_t
  99 _log_prefix(char *buf, size_t buf_len, int severity)
 100 {
 101   time_t t;
 102   struct timeval now;
 103   struct tm tm;
 104   size_t n;
 105   int r;
 106
 107   tor_gettimeofday(&now);
 108   t = (time_t)now.tv_sec;
 109
 110   n = strftime(buf, buf_len, "%b %d %H:%M:%S", tor_localtime_r(&t, &tm));
 111   r = tor_snprintf(buf+n, buf_len-n,
 112                 ".%.3ld [%s] ",
 113                 (long)now.tv_usec / 1000, sev_to_string(severity));
 114   if (r<0)
 115     return buf_len-1;
 116   else
 117     return n+r;
 118 }
 119
 120 /** If lf refers to an actual file that we have just opened, and the file
 121  * contains no data, log an "opening new logfile" message at the top.
 122  *
 123  * Return -1 if the log is broken and needs to be deleted, else return 0.
 124  */
 125 static int
 126 log_tor_version(logfile_t *lf, int reset)
 127 {
 128   char buf[256];
 129   size_t n;
 130   int is_new;
 131
 132   if (!lf->needs_close)
 133     /* If it doesn't get closed, it isn't really a file. */
 134     return 0;
 135   if (lf->is_temporary)
 136     /* If it's temporary, it isn't really a file. */
 137     return 0;
 138 #ifdef HAVE_FTELLO
 139   is_new = (ftello(lf->file) == 0);
 140 #else
 141   is_new = (ftell(lf->file) == 0);
 142 #endif
 143   if (reset && !is_new)
 144     /* We are resetting, but we aren't at the start of the file; no
 145      * need to log again. */
 146     return 0;
 147   n = _log_prefix(buf, sizeof(buf), LOG_NOTICE);
 148   tor_snprintf(buf+n, sizeof(buf)-n,
 149                "Tor %s opening %slog file.\n", VERSION, is_new?"new ":"");
 150   if (fputs(buf, lf->file) == EOF ||
 151       fflush(lf->file) == EOF) /* error */
 152     return -1; /* failed */
 153   return 0;
 154 }
 155
 156 /** Helper: Format a log message into a fixed-sized buffer. (This is
 157  * factored out of <b>logv</b> so that we never format a message more
 158  * than once.)  Return a pointer to the first character of the message
 159  * portion of the formatted string.
 160  */
 161 static INLINE char *
 162 format_msg(char *buf, size_t buf_len,
 163            uint32_t domain, int severity, const char *funcname,
 164            const char *format, va_list ap)
 165 {
 166   size_t n;
 167   int r;
 168   char *end_of_prefix;
 169
 170   tor_assert(buf_len >= 2); /* prevent integer underflow */
 171   buf_len -= 2; /* subtract 2 characters so we have room for \n\0 */
 172
 173   n = _log_prefix(buf, buf_len, severity);
 174   end_of_prefix = buf+n;
 175
 176   if (funcname && should_log_function_name(domain, severity)) {
 177     r = tor_snprintf(buf+n, buf_len-n, "%s(): ", funcname);
 178     if (r<0)
 179       n = strlen(buf);
 180     else
 181       n += r;
 182   }
 183
 184   r = tor_vsnprintf(buf+n,buf_len-n,format,ap);
 185   if (r < 0) {
 186     /* The message was too long; overwrite the end of the buffer with
 187      * "[...truncated]" */
 188     if (buf_len >= TRUNCATED_STR_LEN) {
 189       int offset = buf_len-TRUNCATED_STR_LEN;
 190       /* We have an extra 2 characters after buf_len to hold the \n\0,
 191        * so it's safe to add 1 to the size here. */
 192       strlcpy(buf+offset, TRUNCATED_STR, buf_len-offset+1);
 193     }
 194     /* Set 'n' to the end of the buffer, where we'll be writing \n\0.
 195      * Since we already subtracted 2 from buf_len, this is safe.*/
 196     n = buf_len;
 197   } else {
 198     n += r;
 199   }
 200   buf[n]='\n';
 201   buf[n+1]='\0';
 202   return end_of_prefix;
 203 }
 204
 205 /** Helper: sends a message to the appropriate logfiles, at loglevel
 206  * <b>severity</b>.  If provided, <b>funcname</b> is prepended to the
 207  * message.  The actual message is derived as from tor_snprintf(format,ap).
 208  */
 209 static void
 210 logv(int severity, uint32_t domain, const char *funcname, const char *format,
 211      va_list ap)
 212 {
 213   char buf[10024];
 214   int formatted = 0;
 215   logfile_t *lf;
 216   char *end_of_prefix=NULL;
 217
 218   assert(format);
 219   lf = logfiles;
 220   while (lf) {
 221     if (severity > lf->min_loglevel || severity < lf->max_loglevel) {
 222       lf = lf->next;
 223       continue;
 224     }
 225     if (! (lf->file || lf->is_syslog || lf->callback)) {
 226       lf = lf->next;
 227       continue;
 228     }
 229
 230     if (!formatted) {
 231       end_of_prefix =
 232         format_msg(buf, sizeof(buf), domain, severity, funcname, format, ap);
 233       formatted = 1;
 234     }
 235     if (lf->is_syslog) {
 236 #ifdef HAVE_SYSLOG_H
 237       /* XXXX Some syslog implementations have scary limits on the length of
 238        * what you can pass them.  Can/should we detect this? */
 239       syslog(severity, "%s", end_of_prefix);
 240 #endif
 241       lf = lf->next;
 242       continue;
 243     } else if (lf->callback) {
 244       lf->callback(severity, domain, end_of_prefix);
 245       lf = lf->next;
 246       continue;
 247     }
 248     if (fputs(buf, lf->file) == EOF ||
 249         fflush(lf->file) == EOF) { /* error */
 250       /* don't log the error! Blow away this log entry and continue. */
 251       logfile_t *victim = lf;
 252       lf = victim->next;
 253       delete_log(victim);
 254     } else {
 255       lf = lf->next;
 256     }
 257   }
 258 }
 259
 260 /** Output a message to the log. */
 261 void
 262 _log(int severity, uint32_t domain, const char *format, ...)
 263 {
 264   va_list ap;
 265   va_start(ap,format);
 266   logv(severity, domain, NULL, format, ap);
 267   va_end(ap);
 268 }
 269
 270 /** Output a message to the log, prefixed with a function name <b>fn</b>. */
 271 #ifdef __GNUC__
 272 void
 273 _log_fn(int severity, uint32_t domain, const char *fn, const char *format, ...)
 274 {
 275   va_list ap;
 276   va_start(ap,format);
 277   logv(severity, domain, fn, format, ap);
 278   va_end(ap);
 279 }
 280 #else
 281 const char *_log_fn_function_name=NULL;
 282 void
 283 _log_fn(int severity, uint32_t domain, const char *format, ...)
 284 {
 285   va_list ap;
 286   va_start(ap,format);
 287   logv(severity, domain, _log_fn_function_name, format, ap);
 288   va_end(ap);
 289   _log_fn_function_name = NULL;
 290 }
 291 void
 292 _log_debug(uint32_t domain, const char *format, ...)
 293 {
 294   va_list ap;
 295   va_start(ap,format);
 296   logv(LOG_DEBUG, domain, _log_fn_function_name, format, ap);
 297   va_end(ap);
 298   _log_fn_function_name = NULL;
 299 }
 300 void
 301 _log_info(uint32_t domain, const char *format, ...)
 302 {
 303   va_list ap;
 304   va_start(ap,format);
 305   logv(LOG_INFO, domain, _log_fn_function_name, format, ap);
 306   va_end(ap);
 307   _log_fn_function_name = NULL;
 308 }
 309 void
 310 _log_notice(uint32_t domain, const char *format, ...)
 311 {
 312   va_list ap;
 313   va_start(ap,format);
 314   logv(LOG_NOTICE, domain, _log_fn_function_name, format, ap);
 315   va_end(ap);
 316   _log_fn_function_name = NULL;
 317 }
 318 void
 319 _log_warn(uint32_t domain, const char *format, ...)
 320 {
 321   va_list ap;
 322   va_start(ap,format);
 323   logv(LOG_WARN, domain, _log_fn_function_name, format, ap);
 324   va_end(ap);
 325   _log_fn_function_name = NULL;
 326 }
 327 void
 328 _log_err(uint32_t domain, const char *format, ...)
 329 {
 330   va_list ap;
 331   va_start(ap,format);
 332   logv(LOG_ERR, domain, _log_fn_function_name, format, ap);
 333   va_end(ap);
 334   _log_fn_function_name = NULL;
 335 }
 336 #endif
 337
 338 /** Close all open log files. */
 339 void
 340 close_logs(void)
 341 {
 342   logfile_t *victim, *next;
 343   next = logfiles;
 344   logfiles = NULL;
 345   while (next) {
 346     victim = next;
 347     next = next->next;
 348     close_log(victim);
 349     tor_free(victim->filename);
 350     tor_free(victim);
 351   }
 352 }
 353
 354 /** Remove and free the log entry <b>victim</b> from the linked-list
 355  * logfiles (it is probably present, but it might not be due to thread
 356  * racing issues). After this function is called, the caller shouldn't
 357  * refer to <b>victim</b> anymore.
 358  *
 359  * Long-term, we need to do something about races in the log subsystem
 360  * in general. See bug 222 for more details.
 361  */
 362 static void
 363 delete_log(logfile_t *victim)
 364 {
 365   logfile_t *tmpl;
 366   if (victim == logfiles)
 367     logfiles = victim->next;
 368   else {
 369     for (tmpl = logfiles; tmpl && tmpl->next != victim; tmpl=tmpl->next) ;
 370 //    tor_assert(tmpl);
 371 //    tor_assert(tmpl->next == victim);
 372     if (!tmpl)
 373       return;
 374     tmpl->next = victim->next;
 375   }
 376   tor_free(victim->filename);
 377   tor_free(victim);
 378 }
 379
 380 /** Helper: release system resources (but not memory) held by a single
 381  * logfile_t. */
 382 static void
 383 close_log(logfile_t *victim)
 384 {
 385   if (victim->needs_close && victim->file) {
 386     fclose(victim->file);
 387   } else if (victim->is_syslog) {
 388 #ifdef HAVE_SYSLOG_H
 389     if (--syslog_count == 0) {
 390       /* There are no other syslogs; close the logging facility. */
 391       closelog();
 392     }
 393 #endif
 394   }
 395 }
 396
 397 /** Add a log handler to send all messages of severity <b>loglevel</b>
 398  * or higher to <b>stream</b>. */
 399 void
 400 add_stream_log(int loglevelMin, int loglevelMax,
 401                const char *name, FILE *stream)
 402 {
 403   logfile_t *lf;
 404   lf = tor_malloc_zero(sizeof(logfile_t));
 405   lf->filename = tor_strdup(name);
 406   lf->min_loglevel = loglevelMin;
 407   lf->max_loglevel = loglevelMax;
 408   lf->file = stream;
 409   lf->next = logfiles;
 410   logfiles = lf;
 411
 412   _log_global_min_severity = get_min_log_level();
 413 }
 414
 415 /** Add a log handler to receive messages during startup (before the real
 416  * logs are initialized).
 417  */
 418 void
 419 add_temp_log(void)
 420 {
 421   add_stream_log(LOG_NOTICE, LOG_ERR, "<temp>", stdout);
 422   logfiles->is_temporary = 1;
 423
 424   _log_global_min_severity = get_min_log_level();
 425 }
 426
 427 /**
 428  * Add a log handler to send messages of severity between
 429  * <b>logLevelmin</b> and <b>logLevelMax</b> to the function
 430  * <b>cb</b>.
 431  */
 432 int
 433 add_callback_log(int loglevelMin, int loglevelMax, log_callback cb)
 434 {
 435   logfile_t *lf;
 436   lf = tor_malloc_zero(sizeof(logfile_t));
 437   lf->min_loglevel = loglevelMin;
 438   lf->max_loglevel = loglevelMax;
 439   lf->filename = tor_strdup("<callback>");
 440   lf->callback = cb;
 441   lf->next = logfiles;
 442   logfiles = lf;
 443
 444   _log_global_min_severity = get_min_log_level();
 445   return 0;
 446 }
 447
 448 /** Adjust the configured severity of any logs whose callback function is
 449  * <b>cb</b>. */
 450 void
 451 change_callback_log_severity(int loglevelMin, int loglevelMax,
 452                              log_callback cb)
 453 {
 454   logfile_t *lf;
 455   for (lf = logfiles; lf; lf = lf->next) {
 456     if (lf->callback == cb) {
 457       lf->min_loglevel = loglevelMin;
 458       lf->max_loglevel = loglevelMax;
 459     }
 460   }
 461
 462   _log_global_min_severity = get_min_log_level();
 463 }
 464
 465 /** Close any log handlers added by add_temp_log or marked by mark_logs_temp */
 466 void
 467 close_temp_logs(void)
 468 {
 469   logfile_t *lf, **p;
 470   for (p = &logfiles; *p; ) {
 471     if ((*p)->is_temporary) {
 472       lf = *p;
 473       /* we use *p here to handle the edge case of the head of the list */
 474       *p = (*p)->next;
 475       close_log(lf);
 476       tor_free(lf->filename);
 477       tor_free(lf);
 478     } else {
 479       p = &((*p)->next);
 480     }
 481   }
 482
 483   _log_global_min_severity = get_min_log_level();
 484 }
 485
 486 /** Make all currently temporary logs (set to be closed by close_temp_logs)
 487  * live again, and close all non-temporary logs. */
 488 void
 489 rollback_log_changes(void)
 490 {
 491   logfile_t *lf;
 492   for (lf = logfiles; lf; lf = lf->next)
 493     lf->is_temporary = ! lf->is_temporary;
 494   close_temp_logs();
 495 }
 496
 497 /** Configure all log handles to be closed by close_temp_logs */
 498 void
 499 mark_logs_temp(void)
 500 {
 501   logfile_t *lf;
 502   for (lf = logfiles; lf; lf = lf->next)
 503     lf->is_temporary = 1;
 504 }
 505
 506 /**
 507  * Add a log handler to send messages to <b>filename</b>. If opening
 508  * the logfile fails, -1 is returned and errno is set appropriately
 509  * (by fopen).
 510  */
 511 int
 512 add_file_log(int loglevelMin, int loglevelMax, const char *filename)
 513 {
 514   FILE *f;
 515   f = fopen(filename, "a");
 516   if (!f) return -1;
 517   add_stream_log(loglevelMin, loglevelMax, filename, f);
 518   logfiles->needs_close = 1;
 519   if (log_tor_version(logfiles, 0) < 0) {
 520     delete_log(logfiles);
 521   }
 522   _log_global_min_severity = get_min_log_level();
 523   return 0;
 524 }
 525
 526 #ifdef HAVE_SYSLOG_H
 527 /**
 528  * Add a log handler to send messages to they system log facility.
 529  */
 530 int
 531 add_syslog_log(int loglevelMin, int loglevelMax)
 532 {
 533   logfile_t *lf;
 534   if (syslog_count++ == 0)
 535     /* This is the first syslog. */
 536     openlog("Tor", LOG_PID | LOG_NDELAY, LOGFACILITY);
 537
 538   lf = tor_malloc_zero(sizeof(logfile_t));
 539   lf->min_loglevel = loglevelMin;
 540   lf->filename = tor_strdup("<syslog>");
 541   lf->max_loglevel = loglevelMax;
 542   lf->is_syslog = 1;
 543   lf->next = logfiles;
 544   logfiles = lf;
 545
 546   _log_global_min_severity = get_min_log_level();
 547   return 0;
 548 }
 549 #endif
 550
 551 /** If <b>level</b> is a valid log severity, return the corresponding
 552  * numeric value.  Otherwise, return -1. */
 553 int
 554 parse_log_level(const char *level)
 555 {
 556   if (!strcasecmp(level, "err"))
 557     return LOG_ERR;
 558   if (!strcasecmp(level, "warn"))
 559     return LOG_WARN;
 560   if (!strcasecmp(level, "notice"))
 561     return LOG_NOTICE;
 562   if (!strcasecmp(level, "info"))
 563     return LOG_INFO;
 564   if (!strcasecmp(level, "debug"))
 565     return LOG_DEBUG;
 566   return -1;
 567 }
 568
 569 /** Return the string equivalent of a given log level. */
 570 const char *
 571 log_level_to_string(int level)
 572 {
 573   return sev_to_string(level);
 574 }
 575
 576 /** Return the least severe log level that any current log is interested in. */
 577 int
 578 get_min_log_level(void)
 579 {
 580   logfile_t *lf;
 581   int min = LOG_ERR;
 582   for (lf = logfiles; lf; lf = lf->next) {
 583     if (lf->min_loglevel > min)
 584       min = lf->min_loglevel;
 585   }
 586   return min;
 587 }
 588
 589 /** Switch all logs to output at most verbose level. */
 590 void
 591 switch_logs_debug(void)
 592 {
 593   logfile_t *lf;
 594   for (lf = logfiles; lf; lf=lf->next) {
 595     lf->min_loglevel = LOG_DEBUG;
 596   }
 597 }
 598
 599 #ifdef HAVE_EVENT_SET_LOG_CALLBACK
 600 /** A string which, if it appears in a libevent log, should be ignored. */
 601 static const char *suppress_msg = NULL;
 602 /** Callback function passed to event_set_log() so we can intercept
 603  * log messages from libevent. */
 604 static void
 605 libevent_logging_callback(int severity, const char *msg)
 606 {
 607   char buf[1024];
 608   size_t n;
 609   if (suppress_msg && strstr(msg, suppress_msg))
 610     return;
 611   n = strlcpy(buf, msg, sizeof(buf));
 612   if (n && n < sizeof(buf) && buf[n-1] == '\n') {
 613     buf[n-1] = '\0';
 614   }
 615   switch (severity) {
 616     case _EVENT_LOG_DEBUG:
 617       log(LOG_DEBUG, LD_NET, "Message from libevent: %s", buf);
 618       break;
 619     case _EVENT_LOG_MSG:
 620       log(LOG_INFO, LD_NET, "Message from libevent: %s", buf);
 621       break;
 622     case _EVENT_LOG_WARN:
 623       log(LOG_WARN, LD_GENERAL, "Warning from libevent: %s", buf);
 624       break;
 625     case _EVENT_LOG_ERR:
 626       log(LOG_ERR, LD_GENERAL, "Error from libevent: %s", buf);
 627       break;
 628     default:
 629       log(LOG_WARN, LD_GENERAL, "Message [%d] from libevent: %s",
 630           severity, buf);
 631       break;
 632   }
 633 }
 634 /** Set hook to intercept log messages from libevent. */
 635 void
 636 configure_libevent_logging(void)
 637 {
 638   event_set_log_callback(libevent_logging_callback);
 639 }
 640 /** Ignore any libevent log message that contains <b>msg</b>. */
 641 void
 642 suppress_libevent_log_msg(const char *msg)
 643 {
 644   suppress_msg = msg;
 645 }
 646 #else
 647 void
 648 configure_libevent_logging(void)
 649 {
 650 }
 651 void
 652 suppress_libevent_log_msg(const char *msg)
 653 {
 654 }
 655 #endif
 656
 657 #if 0
 658 static void
 659 dump_log_info(logfile_t *lf)
 660 {
 661   const char *tp;
 662
 663   if (lf->filename) {
 664     printf("=== log into \"%s\" (%s-%s) (%stemporary)\n", lf->filename,
 665            sev_to_string(lf->min_loglevel),
 666            sev_to_string(lf->max_loglevel),
 667            lf->is_temporary?"":"not ");
 668   } else if (lf->is_syslog) {
 669     printf("=== syslog (%s-%s) (%stemporary)\n",
 670            sev_to_string(lf->min_loglevel),
 671            sev_to_string(lf->max_loglevel),
 672            lf->is_temporary?"":"not ");
 673   } else {
 674     printf("=== log (%s-%s) (%stemporary)\n",
 675            sev_to_string(lf->min_loglevel),
 676            sev_to_string(lf->max_loglevel),
 677            lf->is_temporary?"":"not ");
 678   }
 679 }
 680
 681 void
 682 describe_logs(void)
 683 {
 684   logfile_t *lf;
 685   printf("==== BEGIN LOGS ====\n");
 686   for (lf = logfiles; lf; lf = lf->next)
 687     dump_log_info(lf);
 688   printf("==== END LOGS ====\n");
 689 }
 690 #endif
 691