src/common/log.c

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