src/common/log.c

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