log.c 43.8 KB
Newer Older
1
/* Copyright (c) 2001, Matej Pfajfar.
Roger Dingledine's avatar
Roger Dingledine committed
2
 * Copyright (c) 2001-2004, Roger Dingledine.
3
 * Copyright (c) 2004-2006, Roger Dingledine, Nick Mathewson.
4
 * Copyright (c) 2007-2020, The Tor Project, Inc. */
5
/* See LICENSE for licensing information */
Roger Dingledine's avatar
Roger Dingledine committed
6

Nick Mathewson's avatar
Nick Mathewson committed
7
/**
8
 * \file log.c
Nick Mathewson's avatar
Nick Mathewson committed
9
 * \brief Functions to send messages to log files or the console.
10
 **/
Nick Mathewson's avatar
Nick Mathewson committed
11

12
#include "orconfig.h"
13
#include <stdarg.h>
14
#include <stdio.h>
15
#include <stdlib.h>
16
#include <string.h>
17
18
19
20
21
22
#ifdef HAVE_SYS_TIME_H
#include <sys/time.h>
#endif
#ifdef HAVE_TIME_H
#include <time.h>
#endif
23
24
25
26
27
28
29
30
31
#ifdef HAVE_UNISTD_H
#include <unistd.h>
#endif
#ifdef HAVE_SYS_TYPES_H
#include <sys/types.h>
#endif
#ifdef HAVE_FCNTL_H
#include <fcntl.h>
#endif
32

33
#define LOG_PRIVATE
34
#include "lib/log/log.h"
35
#include "lib/log/log_sys.h"
36
#include "lib/version/git_revision.h"
37
38
#include "lib/log/ratelim.h"
#include "lib/lock/compat_mutex.h"
39
40
41
#include "lib/smartlist_core/smartlist_core.h"
#include "lib/smartlist_core/smartlist_foreach.h"
#include "lib/smartlist_core/smartlist_split.h"
42
#include "lib/err/torerr.h"
43
#include "lib/intmath/bits.h"
44
45
#include "lib/string/compat_string.h"
#include "lib/string/printf.h"
Nick Mathewson's avatar
Nick Mathewson committed
46
#include "lib/malloc/malloc.h"
47
#include "lib/string/util_string.h"
48
49
#include "lib/wallclock/tor_gettimeofday.h"
#include "lib/wallclock/approx_time.h"
Nick Mathewson's avatar
Nick Mathewson committed
50
#include "lib/wallclock/time_to_tm.h"
51
#include "lib/fdio/fdio.h"
Nick Mathewson's avatar
Nick Mathewson committed
52
#include "lib/cc/ctassert.h"
53

54
55
56
#ifdef HAVE_ANDROID_LOG_H
#include <android/log.h>
#endif // HAVE_ANDROID_LOG_H.
57

58
59
60
/** @{ */
/** The string we stick at the end of a log message when it is too long,
 * and its length. */
61
62
#define TRUNCATED_STR "[...truncated]"
#define TRUNCATED_STR_LEN 14
63
/** @} */
64

65
66
/** Defining compile-time constants for Tor log levels (used by the Rust
 * log wrapper at src/rust/tor_log) */
67
68
69
70
const int LOG_WARN_ = LOG_WARN;
const int LOG_NOTICE_ = LOG_NOTICE;
const log_domain_mask_t LD_GENERAL_ = LD_GENERAL;
const log_domain_mask_t LD_NET_ = LD_NET;
71

Nick Mathewson's avatar
Nick Mathewson committed
72
/** Information for a single logfile; only used in log.c */
73
typedef struct logfile_t {
74
  struct logfile_t *next; /**< Next logfile_t in the linked list. */
75
  char *filename; /**< Filename to open. */
76
  int fd; /**< fd to receive log messages, or -1 for none. */
77
  int seems_dead; /**< Boolean: true if the stream seems to be kaput. */
Nick Mathewson's avatar
Nick Mathewson committed
78
  int needs_close; /**< Boolean: true if the stream gets closed on shutdown. */
79
  int is_temporary; /**< Boolean: close after initializing logging subsystem.*/
80
  int is_syslog; /**< Boolean: send messages to syslog. */
81
82
  int is_android; /**< Boolean: send messages to Android's log subsystem. */
  char *android_tag; /**< Identity Tag used in Android's log subsystem. */
Nick Mathewson's avatar
Nick Mathewson committed
83
  log_callback callback; /**< If not NULL, send messages to this function. */
Nick Mathewson's avatar
Nick Mathewson committed
84
85
  log_severity_list_t *severities; /**< Which severity of messages should we
                                    * log for each log domain? */
86
87
} logfile_t;

88
89
static void log_free_(logfile_t *victim);
#define log_free(lg)    \
90
  FREE_AND_NULL(logfile_t, log_free_, (lg))
91

92
/** Helper: map a log severity to descriptive string. */
93
static inline const char *
94
95
sev_to_string(int severity)
{
96
  switch (severity) {
97
98
    case LOG_DEBUG:   return "debug";
    case LOG_INFO:    return "info";
Roger Dingledine's avatar
Roger Dingledine committed
99
    case LOG_NOTICE:  return "notice";
Roger Dingledine's avatar
Roger Dingledine committed
100
    case LOG_WARN:    return "warn";
101
    case LOG_ERR:     return "err";
102
    default:     /* Call raw_assert, not tor_assert, since tor_assert
103
104
                  * calls log on failure. */
                 raw_assert_unreached(); return "UNKNOWN"; // LCOV_EXCL_LINE
105
106
107
  }
}

108
/** Helper: decide whether to include the function name in the log message. */
109
static inline int
110
should_log_function_name(log_domain_mask_t domain, int severity)
111
112
113
114
115
{
  switch (severity) {
    case LOG_DEBUG:
    case LOG_INFO:
      /* All debugging messages occur in interesting places. */
116
      return (domain & LD_NOFUNCNAME) == 0;
117
    case LOG_NOTICE:
118
    case LOG_WARN:
119
120
    case LOG_ERR:
      /* We care about places where bugs occur. */
121
      return (domain & (LD_BUG|LD_NOFUNCNAME)) == LD_BUG;
122
    default:
123
124
      /* Call raw_assert, not tor_assert, since tor_assert calls
       * log on failure. */
125
      raw_assert(0); return 0; // LCOV_EXCL_LINE
126
127
128
  }
}

129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
#ifdef HAVE_ANDROID_LOG_H
/** Helper function to convert Tor's log severity into the matching
 * Android log priority.
 */
static int
severity_to_android_log_priority(int severity)
{
  switch (severity) {
    case LOG_DEBUG:
      return ANDROID_LOG_VERBOSE;
    case LOG_INFO:
      return ANDROID_LOG_DEBUG;
    case LOG_NOTICE:
      return ANDROID_LOG_INFO;
    case LOG_WARN:
      return ANDROID_LOG_WARN;
    case LOG_ERR:
      return ANDROID_LOG_ERROR;
    default:
      // LCOV_EXCL_START
      raw_assert(0);
      return 0;
      // LCOV_EXCL_STOP
  }
}
Nick Mathewson's avatar
Nick Mathewson committed
154
#endif /* defined(HAVE_ANDROID_LOG_H) */
155

156
/** A mutex to guard changes to logfiles and logging. */
157
static tor_mutex_t log_mutex;
Nick Mathewson's avatar
Nick Mathewson committed
158
/** True iff we have initialized log_mutex */
159
static int log_mutex_initialized = 0;
160

161
/** Linked list of logfile_t. */
162
static logfile_t *logfiles = NULL;
163
164
165
/** Boolean: do we report logging domains? */
static int log_domains_are_logged = 0;

166
#ifdef HAVE_SYSLOG_H
167
168
/** The number of open syslog log handlers that we have.  When this reaches 0,
 * we can close our connection to the syslog facility. */
169
170
static int syslog_count = 0;
#endif
171

172
173
/** Represents a log message that we are going to send to callback-driven
 * loggers once we can do so in a non-reentrant way. */
174
typedef struct pending_log_message_t {
175
176
  int severity; /**< The severity of the message */
  log_domain_mask_t domain; /**< The domain of the message */
177
  char *fullmsg; /**< The message, with all decorations */
178
  char *msg; /**< The content of the message */
179
} pending_log_message_t;
180
181
182
183

/** Log messages waiting to be replayed onto callback-based logs */
static smartlist_t *pending_cb_messages = NULL;

184
185
186
/** Callback to invoke when pending_cb_messages becomes nonempty. */
static pending_callback_callback pending_cb_cb = NULL;

187
188
189
190
/** Log messages waiting to be replayed once the logging system is initialized.
 */
static smartlist_t *pending_startup_messages = NULL;

191
192
193
194
195
196
197
198
199
/** Number of bytes of messages queued in pending_startup_messages.  (This is
 * the length of the messages, not the number of bytes used to store
 * them.) */
static size_t pending_startup_messages_len;

/** True iff we should store messages while waiting for the logs to get
 * configured. */
static int queue_startup_messages = 1;

200
201
202
/** True iff __PRETTY_FUNCTION__ includes parenthesized arguments. */
static int pretty_fn_has_parens = 0;

203
204
205
206
/** Don't store more than this many bytes of messages while waiting for the
 * logs to get configured. */
#define MAX_STARTUP_MSG_LEN (1<<16)

207
/** Lock the log_mutex to prevent others from changing the logfile_t list */
208
#define LOCK_LOGS() STMT_BEGIN                                          \
209
  raw_assert(log_mutex_initialized);                                    \
210
  tor_mutex_acquire(&log_mutex);                                        \
211
  STMT_END
212
/** Unlock the log_mutex */
213
#define UNLOCK_LOGS() STMT_BEGIN                                        \
214
  raw_assert(log_mutex_initialized);                                    \
215
216
  tor_mutex_release(&log_mutex);                                        \
  STMT_END
217

218
219
/** What's the lowest log level anybody cares about?  Checking this lets us
 * bail out early from log_debug if we aren't debugging.  */
220
int log_global_min_severity_ = LOG_NOTICE;
221

Roger Dingledine's avatar
Roger Dingledine committed
222
static void delete_log(logfile_t *victim);
223
static void close_log(logfile_t *victim);
224
static void close_log_sigsafe(logfile_t *victim);
Roger Dingledine's avatar
Roger Dingledine committed
225

226
227
static char *domain_to_string(log_domain_mask_t domain,
                             char *buf, size_t buflen);
228
static inline char *format_msg(char *buf, size_t buf_len,
229
           log_domain_mask_t domain, int severity, const char *funcname,
230
           const char *suffix,
231
           const char *format, va_list ap, size_t *msg_len_out)
232
  CHECK_PRINTF(7,0);
233

234
235
/** Name of the application: used to generate the message we write at the
 * start of each new log. */
236
237
static char *appname = NULL;

238
239
240
241
242
/** Set the "application name" for the logs to <b>name</b>: we'll use this
 * name in the message we write when starting up, and at the start of each new
 * log.
 *
 * Tor uses this string to write the version number to the log file. */
243
244
245
246
247
248
249
void
log_set_application_name(const char *name)
{
  tor_free(appname);
  appname = name ? tor_strdup(name) : NULL;
}

250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
/** Return true if some of the running logs might be interested in a log
 * message of the given severity in the given domains. If this function
 * returns true, the log message might be ignored anyway, but if it returns
 * false, it is definitely_ safe not to log the message. */
int
log_message_is_interesting(int severity, log_domain_mask_t domain)
{
  (void) domain;
  return (severity <= log_global_min_severity_);
}

/**
 * As tor_log, but takes an optional function name, and does not treat its
 * <b>string</b> as a printf format.
 *
 * For use by Rust integration.
 */
void
tor_log_string(int severity, log_domain_mask_t domain,
               const char *function, const char *string)
{
  log_fn_(severity, domain, function, "%s", string);
}

274
275
276
277
278
/** Log time granularity in milliseconds. */
static int log_time_granularity = 1;

/** Define log time granularity for all logs to be <b>granularity_msec</b>
 * milliseconds. */
279
280
MOCK_IMPL(void,
set_log_time_granularity,(int granularity_msec))
281
282
{
  log_time_granularity = granularity_msec;
283
  tor_log_sigsafe_err_set_granularity(granularity_msec);
284
285
}

286
287
288
/** Helper: Write the standard prefix for log lines to a
 * <b>buf_len</b> character buffer in <b>buf</b>.
 */
289
static inline size_t
290
log_prefix_(char *buf, size_t buf_len, int severity)
Roger Dingledine's avatar
Roger Dingledine committed
291
{
292
  time_t t;
293
  struct timeval now;
294
  struct tm tm;
295
  size_t n;
296
  int r, ms;
297

298
  tor_gettimeofday(&now);
299
  t = (time_t)now.tv_sec;
300
301
302
303
304
305
306
  ms = (int)now.tv_usec / 1000;
  if (log_time_granularity >= 1000) {
    t -= t % (log_time_granularity / 1000);
    ms = 0;
  } else {
    ms -= ((int)now.tv_usec / 1000) % log_time_granularity;
  }
307

308
309
  n = strftime(buf, buf_len, "%b %d %H:%M:%S",
               tor_localtime_r_msg(&t, &tm, NULL));
310
311
312
  r = tor_snprintf(buf+n, buf_len-n, ".%.3i [%s] ", ms,
                   sev_to_string(severity));

313
314
315
316
  if (r<0)
    return buf_len-1;
  else
    return n+r;
317
318
319
}

/** If lf refers to an actual file that we have just opened, and the file
320
321
322
323
 * contains no data, log an "opening new logfile" message at the top.
 *
 * Return -1 if the log is broken and needs to be deleted, else return 0.
 */
324
325
static int
log_tor_version(logfile_t *lf, int reset)
326
327
328
{
  char buf[256];
  size_t n;
329
  int is_new;
330
331
332

  if (!lf->needs_close)
    /* If it doesn't get closed, it isn't really a file. */
333
    return 0;
334
335
  if (lf->is_temporary)
    /* If it's temporary, it isn't really a file. */
336
    return 0;
337
338
339

  is_new = lf->fd >= 0 && tor_fd_getpos(lf->fd) == 0;

340
341
342
  if (reset && !is_new)
    /* We are resetting, but we aren't at the start of the file; no
     * need to log again. */
343
    return 0;
344
  n = log_prefix_(buf, sizeof(buf), LOG_NOTICE);
345
346
347
348
349
350
351
  if (appname) {
    tor_snprintf(buf+n, sizeof(buf)-n,
                 "%s opening %slog file.\n", appname, is_new?"new ":"");
  } else {
    tor_snprintf(buf+n, sizeof(buf)-n,
                 "Tor %s opening %slog file.\n", VERSION, is_new?"new ":"");
  }
352
  if (write_all_to_fd_minimal(lf->fd, buf, strlen(buf)) < 0) /* error */
353
354
    return -1; /* failed */
  return 0;
355
356
357
358
}

/** Helper: Format a log message into a fixed-sized buffer. (This is
 * factored out of <b>logv</b> so that we never format a message more
359
360
 * than once.)  Return a pointer to the first character of the message
 * portion of the formatted string.
361
 */
362
static inline char *
363
format_msg(char *buf, size_t buf_len,
364
           log_domain_mask_t domain, int severity, const char *funcname,
365
           const char *suffix,
366
           const char *format, va_list ap, size_t *msg_len_out)
367
368
{
  size_t n;
369
  int r;
370
  char *end_of_prefix;
371
  char *buf_end;
372

373
  raw_assert(buf_len >= 16); /* prevent integer underflow and stupidity */
374
  buf_len -= 2; /* subtract 2 characters so we have room for \n\0 */
375
  buf_end = buf+buf_len; /* point *after* the last char we can write to */
376

377
  n = log_prefix_(buf, buf_len, severity);
378
  end_of_prefix = buf+n;
379

380
381
  if (log_domains_are_logged) {
    char *cp = buf+n;
382
    if (cp == buf_end) goto format_msg_no_room_for_domains;
383
    *cp++ = '{';
384
    if (cp == buf_end) goto format_msg_no_room_for_domains;
385
    cp = domain_to_string(domain, cp, (buf+buf_len-cp));
386
    if (cp == buf_end) goto format_msg_no_room_for_domains;
387
    *cp++ = '}';
388
    if (cp == buf_end) goto format_msg_no_room_for_domains;
389
    *cp++ = ' ';
390
    if (cp == buf_end) goto format_msg_no_room_for_domains;
391
392
    end_of_prefix = cp;
    n = cp-buf;
393
394
395
  format_msg_no_room_for_domains:
    /* This will leave end_of_prefix and n unchanged, and thus cause
     * whatever log domain string we had written to be clobbered. */
396
    ;
397
398
  }

399
  if (funcname && should_log_function_name(domain, severity)) {
400
401
402
    r = tor_snprintf(buf+n, buf_len-n,
                     pretty_fn_has_parens ? "%s: " : "%s(): ",
                     funcname);
403
404
405
406
    if (r<0)
      n = strlen(buf);
    else
      n += r;
407
  }
408

409
410
411
412
413
  if (domain == LD_BUG && buf_len-n > 6) {
    memcpy(buf+n, "Bug: ", 6);
    n += 5;
  }

414
  r = tor_vsnprintf(buf+n,buf_len-n,format,ap);
415
  if (r < 0) {
416
417
418
    /* The message was too long; overwrite the end of the buffer with
     * "[...truncated]" */
    if (buf_len >= TRUNCATED_STR_LEN) {
419
      size_t offset = buf_len-TRUNCATED_STR_LEN;
420
421
422
      /* We have an extra 2 characters after buf_len to hold the \n\0,
       * so it's safe to add 1 to the size here. */
      strlcpy(buf+offset, TRUNCATED_STR, buf_len-offset+1);
423
424
425
426
    }
    /* Set 'n' to the end of the buffer, where we'll be writing \n\0.
     * Since we already subtracted 2 from buf_len, this is safe.*/
    n = buf_len;
427
428
  } else {
    n += r;
429
430
431
432
433
434
435
    if (suffix) {
      size_t suffix_len = strlen(suffix);
      if (buf_len-n >= suffix_len) {
        memcpy(buf+n, suffix, suffix_len);
        n += suffix_len;
      }
    }
436
  }
437
438

  if (domain == LD_BUG &&
439
440
441
      buf_len - n > strlen(tor_bug_suffix)+1) {
    memcpy(buf+n, tor_bug_suffix, strlen(tor_bug_suffix));
    n += strlen(tor_bug_suffix);
442
443
  }

444
445
  buf[n]='\n';
  buf[n+1]='\0';
446
  *msg_len_out = n+1;
447
  return end_of_prefix;
448
449
}

450
451
/* Create a new pending_log_message_t with appropriate values */
static pending_log_message_t *
452
453
pending_log_message_new(int severity, log_domain_mask_t domain,
                        const char *fullmsg, const char *shortmsg)
454
455
456
457
{
  pending_log_message_t *m = tor_malloc(sizeof(pending_log_message_t));
  m->severity = severity;
  m->domain = domain;
458
459
  m->fullmsg = fullmsg ? tor_strdup(fullmsg) : NULL;
  m->msg = tor_strdup(shortmsg);
460
461
462
  return m;
}

463
464
465
#define pending_log_message_free(msg) \
  FREE_AND_NULL(pending_log_message_t, pending_log_message_free_, (msg))

466
467
/** Release all storage held by <b>msg</b>. */
static void
468
pending_log_message_free_(pending_log_message_t *msg)
469
470
471
472
{
  if (!msg)
    return;
  tor_free(msg->msg);
473
  tor_free(msg->fullmsg);
474
475
476
  tor_free(msg);
}

477
478
479
480
/** Helper function: returns true iff the log file, given in <b>lf</b>, is
 * handled externally via the system log API, the Android logging API, or is an
 * external callback function. */
static inline int
481
logfile_is_external(const logfile_t *lf)
482
483
484
485
486
{
  raw_assert(lf);
  return lf->is_syslog || lf->is_android || lf->callback;
}

487
488
/** Return true iff <b>lf</b> would like to receive a message with the
 * specified <b>severity</b> in the specified <b>domain</b>.
489
 */
490
static inline int
491
492
493
494
495
496
logfile_wants_message(const logfile_t *lf, int severity,
                      log_domain_mask_t domain)
{
  if (! (lf->severities->masks[SEVERITY_MASK_IDX(severity)] & domain)) {
    return 0;
  }
497
  if (! (lf->fd >= 0 || logfile_is_external(lf))) {
498
499
500
501
502
503
504
505
506
    return 0;
  }
  if (lf->seems_dead) {
    return 0;
  }

  return 1;
}

507
508
509
510
511
512
/** Send a message to <b>lf</b>.  The full message, with time prefix and
 * severity, is in <b>buf</b>.  The message itself is in
 * <b>msg_after_prefix</b>.  If <b>callbacks_deferred</b> points to true, then
 * we already deferred this message for pending callbacks and don't need to do
 * it again.  Otherwise, if we need to do it, do it, and set
 * <b>callbacks_deferred</b> to 1. */
513
static inline void
514
515
516
517
518
519
520
521
522
523
524
525
logfile_deliver(logfile_t *lf, const char *buf, size_t msg_len,
                const char *msg_after_prefix, log_domain_mask_t domain,
                int severity, int *callbacks_deferred)
{

  if (lf->is_syslog) {
#ifdef HAVE_SYSLOG_H
#ifdef MAXLINE
    /* Some syslog implementations have limits on the length of what you can
     * pass them, and some very old ones do not detect overflow so well.
     * Regrettably, they call their maximum line length MAXLINE. */
#if MAXLINE < 64
526
#warning "MAXLINE is a very low number; it might not be from syslog.h."
527
528
529
530
531
532
533
534
#endif
    char *m = msg_after_prefix;
    if (msg_len >= MAXLINE)
      m = tor_strndup(msg_after_prefix, MAXLINE-1);
    syslog(severity, "%s", m);
    if (m != msg_after_prefix) {
      tor_free(m);
    }
535
#else /* !defined(MAXLINE) */
536
537
    /* We have syslog but not MAXLINE.  That's promising! */
    syslog(severity, "%s", msg_after_prefix);
538
539
#endif /* defined(MAXLINE) */
#endif /* defined(HAVE_SYSLOG_H) */
540
541
542
543
544
  } else if (lf->is_android) {
#ifdef HAVE_ANDROID_LOG_H
    int priority = severity_to_android_log_priority(severity);
    __android_log_write(priority, lf->android_tag, msg_after_prefix);
#endif // HAVE_ANDROID_LOG_H.
545
546
547
548
  } else if (lf->callback) {
    if (domain & LD_NOCB) {
      if (!*callbacks_deferred && pending_cb_messages) {
        smartlist_add(pending_cb_messages,
549
            pending_log_message_new(severity,domain,NULL,msg_after_prefix));
550
        *callbacks_deferred = 1;
551
552
553
        if (smartlist_len(pending_cb_messages) == 1 && pending_cb_cb) {
          pending_cb_cb();
        }
554
555
556
557
558
      }
    } else {
      lf->callback(severity, domain, msg_after_prefix);
    }
  } else {
559
    if (write_all_to_fd_minimal(lf->fd, buf, msg_len) < 0) { /* error */
560
561
562
563
564
565
566
      /* don't log the error! mark this log entry to be blown away, and
       * continue. */
      lf->seems_dead = 1;
    }
  }
}

Nick Mathewson's avatar
Nick Mathewson committed
567
568
/** Helper: sends a message to the appropriate logfiles, at loglevel
 * <b>severity</b>.  If provided, <b>funcname</b> is prepended to the
569
 * message.  The actual message is derived as from tor_snprintf(format,ap).
Nick Mathewson's avatar
Nick Mathewson committed
570
 */
571
572
573
MOCK_IMPL(STATIC void,
logv,(int severity, log_domain_mask_t domain, const char *funcname,
     const char *suffix, const char *format, va_list ap))
574
{
teor's avatar
teor committed
575
  char buf[10240];
576
  size_t msg_len = 0;
577
578
  int formatted = 0;
  logfile_t *lf;
579
  char *end_of_prefix=NULL;
580
  int callbacks_deferred = 0;
581

582
  /* Call raw_assert, not tor_assert, since tor_assert calls log on failure. */
583
  raw_assert(format);
584
585
  /* check that severity is sane.  Overrunning the masks array leads to
   * interesting and hard to diagnose effects */
586
  raw_assert(severity >= LOG_ERR && severity <= LOG_DEBUG);
587

588
  LOCK_LOGS();
589

590
591
  if ((! (domain & LD_NOCB)) && pending_cb_messages
      && smartlist_len(pending_cb_messages))
592
593
    flush_pending_log_callbacks();

594
595
596
597
598
599
600
601
602
603
604
605
  if (queue_startup_messages &&
      pending_startup_messages_len < MAX_STARTUP_MSG_LEN) {
    end_of_prefix =
      format_msg(buf, sizeof(buf), domain, severity, funcname, suffix,
      format, ap, &msg_len);
    formatted = 1;

    smartlist_add(pending_startup_messages,
      pending_log_message_new(severity,domain,buf,end_of_prefix));
    pending_startup_messages_len += msg_len;
  }

606
607
  for (lf = logfiles; lf; lf = lf->next) {
    if (! logfile_wants_message(lf, severity, domain))
608
      continue;
609

610
    if (!formatted) {
611
      end_of_prefix =
612
613
        format_msg(buf, sizeof(buf), domain, severity, funcname, suffix,
                   format, ap, &msg_len);
614
615
      formatted = 1;
    }
616

617
618
    logfile_deliver(lf, buf, msg_len, end_of_prefix, domain, severity,
      &callbacks_deferred);
619
  }
620
  UNLOCK_LOGS();
621
}
622

623
624
/** Output a message to the log.  It gets logged to all logfiles that
 * care about messages with <b>severity</b> in <b>domain</b>. The content
Robert Ransom's avatar
Robert Ransom committed
625
 * is formatted printf-style based on <b>format</b> and extra arguments.
626
 * */
627
void
628
tor_log(int severity, log_domain_mask_t domain, const char *format, ...)
629
630
{
  va_list ap;
631
632
633
634

  /* check that domain is composed of known domains and flags */
  raw_assert((domain & (LD_ALL_DOMAINS|LD_ALL_FLAGS)) == domain);

635
  if (severity > log_global_min_severity_)
636
    return;
637
  va_start(ap,format);
638
639
640
641
642
#ifdef TOR_UNIT_TESTS
  if (domain & LD_NO_MOCK)
    logv__real(severity, domain, NULL, NULL, format, ap);
  else
#endif
643
  logv(severity, domain, NULL, NULL, format, ap);
644
  va_end(ap);
Roger Dingledine's avatar
Roger Dingledine committed
645
}
646

647
648
649
650
651
652
653
654
655
656
657
658
659
660
661
662
663
664
665
/** Helper function; return true iff the <b>n</b>-element array <b>array</b>
 * contains <b>item</b>. */
static int
int_array_contains(const int *array, int n, int item)
{
  int j;
  for (j = 0; j < n; ++j) {
    if (array[j] == item)
      return 1;
  }
  return 0;
}

/** Function to call whenever the list of logs changes to get ready to log
 * from signal handlers. */
void
tor_log_update_sigsafe_err_fds(void)
{
  const logfile_t *lf;
666
  int found_real_stderr = 0;
667

teor's avatar
teor committed
668
669
670
  /* The fds are the file descriptors of tor's stdout, stderr, and file
   * logs. The log and err modules flush these fds during their shutdowns. */
  int fds[TOR_SIGSAFE_LOG_MAX_FDS];
671
672
  int n_fds;

673
  LOCK_LOGS();
674
  /* Reserve the first one for stderr. This is safe because when we daemonize,
teor's avatar
teor committed
675
676
   * we dup2 /dev/null to stderr. */
  fds[0] = STDERR_FILENO;
677
  n_fds = 1;
678
679

  for (lf = logfiles; lf; lf = lf->next) {
680
681
682
     /* Don't try callback to the control port, syslogs, android logs, or any
      * other non-file descriptor log: We can't call arbitrary functions from a
      * signal handler.
683
      */
684
685
    if (lf->is_temporary || logfile_is_external(lf)
        || lf->seems_dead || lf->fd < 0)
686
687
688
      continue;
    if (lf->severities->masks[SEVERITY_MASK_IDX(LOG_ERR)] &
        (LD_BUG|LD_GENERAL)) {
689
690
      if (lf->fd == STDERR_FILENO)
        found_real_stderr = 1;
teor's avatar
teor committed
691
692
      /* Avoid duplicates by checking the log module fd against fds */
      if (int_array_contains(fds, n_fds, lf->fd))
693
        continue;
teor's avatar
teor committed
694
695
      /* Update fds using the log module's fd */
      fds[n_fds] = lf->fd;
696
      n_fds++;
697
      if (n_fds == TOR_SIGSAFE_LOG_MAX_FDS)
698
699
700
        break;
    }
  }
701
702

  if (!found_real_stderr &&
teor's avatar
teor committed
703
      int_array_contains(fds, n_fds, STDOUT_FILENO)) {
704
705
706
707
    /* Don't use a virtual stderr when we're also logging to stdout.
     * If we reached max_fds logs, we'll now have (max_fds - 1) logs.
     * That's ok, max_fds is large enough that most tor instances don't exceed
     * it. */
708
    raw_assert(n_fds >= 2); /* Don't tor_assert inside log fns */
709
    --n_fds;
teor's avatar
teor committed
710
    fds[0] = fds[n_fds];
711
712
  }

713
  UNLOCK_LOGS();
714

teor's avatar
teor committed
715
  tor_log_set_sigsafe_err_fds(fds, n_fds);
716
717
}

718
719
720
721
722
723
/** Add to <b>out</b> a copy of every currently configured log file name. Used
 * to enable access to these filenames with the sandbox code. */
void
tor_log_get_logfile_names(smartlist_t *out)
{
  logfile_t *lf;
724
  raw_assert(out);
725
726
727
728

  LOCK_LOGS();

  for (lf = logfiles; lf; lf = lf->next) {
729
    if (lf->is_temporary || logfile_is_external(lf))
730
731
732
      continue;
    if (lf->filename == NULL)
      continue;
733
    smartlist_add_strdup(out, lf->filename);
734
735
736
737
738
  }

  UNLOCK_LOGS();
}

739
/** Implementation of the log_fn backend, used when we have
Nick Mathewson's avatar
Nick Mathewson committed
740
 * variadic macros. All arguments are as for log_fn, except for
741
 * <b>fn</b>, which is the name of the calling function. */
742
void
743
log_fn_(int severity, log_domain_mask_t domain, const char *fn,
744
        const char *format, ...)
745
746
{
  va_list ap;
747
  if (severity > log_global_min_severity_)
748
    return;
749
  va_start(ap,format);
750
751
752
753
754
755
756
757
758
759
760
761
762
763
764
765
  logv(severity, domain, fn, NULL, format, ap);
  va_end(ap);
}
void
log_fn_ratelim_(ratelim_t *ratelim, int severity, log_domain_mask_t domain,
                const char *fn, const char *format, ...)
{
  va_list ap;
  char *m;
  if (severity > log_global_min_severity_)
    return;
  m = rate_limit_log(ratelim, approx_time());
  if (m == NULL)
      return;
  va_start(ap, format);
  logv(severity, domain, fn, m, format, ap);
766
  va_end(ap);
767
  tor_free(m);
768
769
}

Nick Mathewson's avatar
Nick Mathewson committed
770
/** Free all storage held by <b>victim</b>. */
771
static void
772
log_free_(logfile_t *victim)
773
{
774
775
  if (!victim)
    return;
776
777
  tor_free(victim->severities);
  tor_free(victim->filename);
778
  tor_free(victim->android_tag);
779
780
781
  tor_free(victim);
}

782
/** Close all open log files, and free other static memory. */
783
void
784
logs_free_all(void)
785
{
786
  logfile_t *victim, *next;
787
  smartlist_t *messages, *messages2;
788
  LOCK_LOGS();
789
790
  next = logfiles;
  logfiles = NULL;
791
792
  messages = pending_cb_messages;
  pending_cb_messages = NULL;
793
  pending_cb_cb = NULL;
794
795
  messages2 = pending_startup_messages;
  pending_startup_messages = NULL;
796
  UNLOCK_LOGS();
797
798
799
  while (next) {
    victim = next;
    next = next->next;
800
    close_log(victim);
801
    log_free(victim);
802
  }
803
  tor_free(appname);
804

805
806
  SMARTLIST_FOREACH(messages, pending_log_message_t *, msg, {
      pending_log_message_free(msg);
807
808
809
    });
  smartlist_free(messages);

810
811
812
813
814
815
816
  if (messages2) {
    SMARTLIST_FOREACH(messages2, pending_log_message_t *, msg, {
        pending_log_message_free(msg);
      });
    smartlist_free(messages2);
  }

817
  /* We _could_ destroy the log mutex here, but that would screw up any logs
818
819
820
821
   * that happened between here and the end of execution.
   * If tor is re-initialized, log_mutex_initialized will still be 1. So we
   * won't trigger any undefined behaviour by trying to re-initialize the
   * log mutex. */
822
}
823

824
/** Flush the signal-safe log files.
825
 *
826
827
 * This function is safe to call from a signal handler. It is currenly called
 * by the BUG() macros, when terminating the process on an abnormal condition.
828
829
 */
void
830
logs_flush_sigsafe(void)
831
{
832
833
  /* If we don't have fsync() in unistd.h, we can't flush the logs. */
#ifdef HAVE_FSYNC
834
835
836
837
838
839
840
841
842
  logfile_t *victim, *next;
  /* We can't LOCK_LOGS() in a signal handler, because it may call
   * signal-unsafe functions. And we can't deallocate memory, either. */
  next = logfiles;
  logfiles = NULL;
  while (next) {
    victim = next;
    next = next->next;
    if (victim->needs_close) {
843
844
      /* We can't do anything useful if the flush fails. */
      (void)fsync(victim->fd);
845
846
    }
  }
teor's avatar
teor committed
847
#endif /* defined(HAVE_FSYNC) */
848
849
}

Roger Dingledine's avatar
Roger Dingledine committed
850
/** Remove and free the log entry <b>victim</b> from the linked-list
851
852
853
 * logfiles (it is probably present, but it might not be due to thread
 * racing issues). After this function is called, the caller shouldn't
 * refer to <b>victim</b> anymore.
Roger Dingledine's avatar
Roger Dingledine committed
854
 */
855
856
857
static void
delete_log(logfile_t *victim)
{
Roger Dingledine's avatar
Roger Dingledine committed
858
  logfile_t *tmpl;
859
  if (victim == logfiles)
Roger Dingledine's avatar
Roger Dingledine committed
860
861
    logfiles = victim->next;
  else {
862
    for (tmpl = logfiles; tmpl && tmpl->next != victim; tmpl=tmpl->next) ;
863
864
//    raw_assert(tmpl);
//    raw_assert(tmpl->next == victim);
865
866
    if (!tmpl)
      return;
Roger Dingledine's avatar
Roger Dingledine committed
867
868
    tmpl->next = victim->next;
  }
869
  log_free(victim);
Roger Dingledine's avatar
Roger Dingledine committed
870
871
}

872
/** Helper: release system resources (but not memory) held by a single
873
874
 * signal-safe logfile_t. If the log's resources can not be released in
 * a signal handler, does nothing. */
875
static void
876
close_log_sigsafe(logfile_t *victim)
877
{
878
  if (victim->needs_close && victim->fd >= 0) {
879
880
    /* We can't do anything useful here if close() fails: we're shutting
     * down logging, and the err module only does fatal errors. */
881
882
    close(victim->fd);
    victim->fd = -1;
883
884
885
886
887
888
889
890
891
892
  }
}

/** Helper: release system resources (but not memory) held by a single
 * logfile_t. */
static void
close_log(logfile_t *victim)
{
  if (victim->needs_close) {
    close_log_sigsafe(victim);
893
894
  } else if (victim->is_syslog) {
#ifdef HAVE_SYSLOG_H
895
    if (--syslog_count == 0) {
896
897
      /* There are no other syslogs; close the logging facility. */
      closelog();
898
    }
899
#endif /* defined(HAVE_SYSLOG_H) */
900
901
902
  }
}

903
904
905
906
907
908
/** Adjust a log severity configuration in <b>severity_out</b> to contain
 * every domain between <b>loglevelMin</b> and <b>loglevelMax</b>, inclusive.
 */
void
set_log_severity_config(int loglevelMin, int loglevelMax,
                        log_severity_list_t *severity_out)
909
910
{
  int i;
911
912
913
  raw_assert(loglevelMin >= loglevelMax);
  raw_assert(loglevelMin >= LOG_ERR && loglevelMin <= LOG_DEBUG);
  raw_assert(loglevelMax >= LOG_ERR && loglevelMax <= LOG_DEBUG);
914
  memset(severity_out, 0, sizeof(log_severity_list_t));
915
  for (i = loglevelMin; i >= loglevelMax; --i) {
916
    severity_out->masks[SEVERITY_MASK_IDX(i)] = LD_ALL_DOMAINS;
917
918
919
920
  }
}

/** Add a log handler named <b>name</b> to send all messages in <b>severity</b>
921
 * to <b>fd</b>. Copies <b>severity</b>. Helper: does no locking. */
922
923
924
MOCK_IMPL(STATIC void,
add_stream_log_impl,(const log_severity_list_t *severity,
                     const char *name, int fd))
925
926
{
  logfile_t *lf;
927
  lf = tor_malloc_zero(sizeof(logfile_t));
928
  lf->fd = fd;
929
  lf->filename = tor_strdup(name);
930
  lf->severities = tor_memdup(severity, sizeof(log_severity_list_t));
931
  lf->next = logfiles;
932

933
  logfiles = lf;
934
  log_global_min_severity_ = get_min_log_level();
935
936
}

937
/** Add a log handler named <b>name</b> to send all messages in <b>severity</b>
938
 * to <b>fd</b>. Steals a reference to <b>severity</b>; the caller must
939
 * not use it after calling this function. */
Nick Mathewson's avatar