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