log.c 41.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.
Nick Mathewson's avatar
Nick Mathewson committed
4
 * Copyright (c) 2007-2018, 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/git_revision.h"
36
37
#include "lib/log/ratelim.h"
#include "lib/lock/compat_mutex.h"
38
39
40
#include "lib/smartlist_core/smartlist_core.h"
#include "lib/smartlist_core/smartlist_foreach.h"
#include "lib/smartlist_core/smartlist_split.h"
41
#include "lib/err/torerr.h"
42
#include "lib/intmath/bits.h"
43
44
#include "lib/string/compat_string.h"
#include "lib/string/printf.h"
Nick Mathewson's avatar
Nick Mathewson committed
45
#include "lib/malloc/malloc.h"
46
#include "lib/string/util_string.h"
47
48
#include "lib/wallclock/tor_gettimeofday.h"
#include "lib/wallclock/approx_time.h"
Nick Mathewson's avatar
Nick Mathewson committed
49
#include "lib/wallclock/time_to_tm.h"
50
#include "lib/fdio/fdio.h"
51

52
53
54
#ifdef HAVE_ANDROID_LOG_H
#include <android/log.h>
#endif // HAVE_ANDROID_LOG_H.
55

56
57
58
59
/** Given a severity, yields an index into log_severity_list_t.masks to use
 * for that severity. */
#define SEVERITY_MASK_IDX(sev) ((sev) - LOG_ERR)

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

67
68
/** Defining compile-time constants for Tor log levels (used by the Rust
 * log wrapper at src/rust/tor_log) */
69
70
71
72
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;
73

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

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

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

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

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

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

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

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

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

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

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

192
193
194
195
196
197
198
199
200
/** 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;

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

204
205
206
207
/** 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)

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

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

Roger Dingledine's avatar
Roger Dingledine committed
223
static void delete_log(logfile_t *victim);
224
static void close_log(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
279
280
281
282
/** 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. */
void
set_log_time_granularity(int granularity_msec)
{
  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
526
527
528
529
530
531
532
533
534
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
#warn "MAXLINE is a very low number; it might not be from syslog.h after all"
#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 assert, not raw_assert, since raw_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
  /* check that we've initialised the log mutex before we try to lock it */
588
  raw_assert(log_mutex_initialized);
589
  LOCK_LOGS();
590

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

595
596
597
598
599
600
601
602
603
604
605
606
  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;
  }

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

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

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

624
625
/** 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
626
 * is formatted printf-style based on <b>format</b> and extra arguments.
627
 * */
628
void
629
tor_log(int severity, log_domain_mask_t domain, const char *format, ...)
630
631
{
  va_list ap;
632
  if (severity > log_global_min_severity_)
633
    return;
634
  va_start(ap,format);
635
636
637
638
639
#ifdef TOR_UNIT_TESTS
  if (domain & LD_NO_MOCK)
    logv__real(severity, domain, NULL, NULL, format, ap);
  else
#endif
640
  logv(severity, domain, NULL, NULL, format, ap);
641
  va_end(ap);
Roger Dingledine's avatar
Roger Dingledine committed
642
}
643

644
645
646
647
648
649
650
651
652
653
654
655
656
657
658
659
660
661
662
/** 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;
663
  int found_real_stderr = 0;
664

665
666
667
  int fds[TOR_SIGSAFE_LOG_MAX_FDS];
  int n_fds;

668
  LOCK_LOGS();
669
670
  /* Reserve the first one for stderr. This is safe because when we daemonize,
   * we dup2 /dev/null to stderr, */
671
672
  fds[0] = STDERR_FILENO;
  n_fds = 1;
673
674
675
676
677

  for (lf = logfiles; lf; lf = lf->next) {
     /* Don't try callback to the control port, or syslogs: We can't
      * do them from a signal handler. Don't try stdout: we always do stderr.
      */
678
679
    if (lf->is_temporary || logfile_is_external(lf)
        || lf->seems_dead || lf->fd < 0)
680
681
682
      continue;
    if (lf->severities->masks[SEVERITY_MASK_IDX(LOG_ERR)] &
        (LD_BUG|LD_GENERAL)) {
683
684
      if (lf->fd == STDERR_FILENO)
        found_real_stderr = 1;
685
      /* Avoid duplicates */
686
      if (int_array_contains(fds, n_fds, lf->fd))
687
        continue;
688
689
      fds[n_fds++] = lf->fd;
      if (n_fds == TOR_SIGSAFE_LOG_MAX_FDS)
690
691
692
        break;
    }
  }
693
694

  if (!found_real_stderr &&
695
      int_array_contains(fds, n_fds, STDOUT_FILENO)) {
696
    /* Don't use a virtual stderr when we're also logging to stdout. */
697
    raw_assert(n_fds >= 2); /* Don't raw_assert inside log fns */
698
    fds[0] = fds[--n_fds];
699
700
  }

701
  UNLOCK_LOGS();
702
703

  tor_log_set_sigsafe_err_fds(fds, n_fds);
704
705
}

706
707
708
709
710
711
/** 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;
712
  raw_assert(out);
713
714
715
716

  LOCK_LOGS();

  for (lf = logfiles; lf; lf = lf->next) {
717
    if (lf->is_temporary || logfile_is_external(lf))
718
719
720
      continue;
    if (lf->filename == NULL)
      continue;
721
    smartlist_add_strdup(out, lf->filename);
722
723
724
725
726
  }

  UNLOCK_LOGS();
}

727
/** Implementation of the log_fn backend, used when we have
Nick Mathewson's avatar
Nick Mathewson committed
728
729
 * variadic macros. All arguments are as for log_fn, except for
 * <b>fn</b>, which is the name of the calling functions. */
730
void
731
log_fn_(int severity, log_domain_mask_t domain, const char *fn,
732
        const char *format, ...)
733
734
{
  va_list ap;
735
  if (severity > log_global_min_severity_)
736
    return;
737
  va_start(ap,format);
738
739
740
741
742
743
744
745
746
747
748
749
750
751
752
753
  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);
754
  va_end(ap);
755
  tor_free(m);
756
757
}

Nick Mathewson's avatar
Nick Mathewson committed
758
/** Free all storage held by <b>victim</b>. */
759
static void
760
log_free_(logfile_t *victim)
761
{
762
763
  if (!victim)
    return;
764
765
  tor_free(victim->severities);
  tor_free(victim->filename);
766
  tor_free(victim->android_tag);
767
768
769
  tor_free(victim);
}

770
/** Close all open log files, and free other static memory. */
771
void
772
logs_free_all(void)
773
{
774
  logfile_t *victim, *next;
775
  smartlist_t *messages, *messages2;
776
  LOCK_LOGS();
777
778
  next = logfiles;
  logfiles = NULL;
779
780
  messages = pending_cb_messages;
  pending_cb_messages = NULL;
781
  pending_cb_cb = NULL;
782
783
  messages2 = pending_startup_messages;
  pending_startup_messages = NULL;
784
  UNLOCK_LOGS();
785
786
787
  while (next) {
    victim = next;
    next = next->next;
788
    close_log(victim);
789
    log_free(victim);
790
  }
791
  tor_free(appname);
792

793
794
  SMARTLIST_FOREACH(messages, pending_log_message_t *, msg, {
      pending_log_message_free(msg);
795
796
797
    });
  smartlist_free(messages);

798
799
800
801
802
803
804
  if (messages2) {
    SMARTLIST_FOREACH(messages2, pending_log_message_t *, msg, {
        pending_log_message_free(msg);
      });
    smartlist_free(messages2);
  }

805
806
  /* We _could_ destroy the log mutex here, but that would screw up any logs
   * that happened between here and the end of execution. */
807
}
808

Roger Dingledine's avatar
Roger Dingledine committed
809
/** Remove and free the log entry <b>victim</b> from the linked-list
810
811
812
813
814
815
 * 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.
 *
 * Long-term, we need to do something about races in the log subsystem
 * in general. See bug 222 for more details.
Roger Dingledine's avatar
Roger Dingledine committed
816
 */
817
818
819
static void
delete_log(logfile_t *victim)
{
Roger Dingledine's avatar
Roger Dingledine committed
820
  logfile_t *tmpl;
821
  if (victim == logfiles)
Roger Dingledine's avatar
Roger Dingledine committed
822
823
    logfiles = victim->next;
  else {
824
    for (tmpl = logfiles; tmpl && tmpl->next != victim; tmpl=tmpl->next) ;
825
826
//    raw_assert(tmpl);
//    raw_assert(tmpl->next == victim);
827
828
    if (!tmpl)
      return;
Roger Dingledine's avatar
Roger Dingledine committed
829
830
    tmpl->next = victim->next;
  }
831
  log_free(victim);
Roger Dingledine's avatar
Roger Dingledine committed
832
833
}

834
835
/** Helper: release system resources (but not memory) held by a single
 * logfile_t. */
836
837
static void
close_log(logfile_t *victim)
838
{
839
840
841
  if (victim->needs_close && victim->fd >= 0) {
    close(victim->fd);
    victim->fd = -1;
842
843
  } else if (victim->is_syslog) {
#ifdef HAVE_SYSLOG_H
844
    if (--syslog_count == 0) {
845
846
      /* There are no other syslogs; close the logging facility. */
      closelog();
847
    }
848
#endif /* defined(HAVE_SYSLOG_H) */
849
850
851
  }
}

852
853
854
855
856
857
/** 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)
858
859
{
  int i;
860
861
862
  raw_assert(loglevelMin >= loglevelMax);
  raw_assert(loglevelMin >= LOG_ERR && loglevelMin <= LOG_DEBUG);
  raw_assert(loglevelMax >= LOG_ERR && loglevelMax <= LOG_DEBUG);
863
  memset(severity_out, 0, sizeof(log_severity_list_t));
864
  for (i = loglevelMin; i >= loglevelMax; --i) {
865
    severity_out->masks[SEVERITY_MASK_IDX(i)] = ~0u;
866
867
868
869
  }
}

/** Add a log handler named <b>name</b> to send all messages in <b>severity</b>
870
 * to <b>fd</b>. Copies <b>severity</b>. Helper: does no locking. */
871
static void
872
add_stream_log_impl(const log_severity_list_t *severity,
873
                    const char *name, int fd)
874
875
{
  logfile_t *lf;
876
  lf = tor_malloc_zero(sizeof(logfile_t));
877
  lf->fd = fd;
878
  lf->filename = tor_strdup(name);
879
  lf->severities = tor_memdup(severity, sizeof(log_severity_list_t));
880
  lf->next = logfiles;
881

882
  logfiles = lf;
883
  log_global_min_severity_ = get_min_log_level();
884
885
}

886
/** Add a log handler named <b>name</b> to send all messages in <b>severity</b>
887
 * to <b>fd</b>. Steals a reference to <b>severity</b>; the caller must
888
 * not use it after calling this function. */
889
void
890
add_stream_log(const log_severity_list_t *severity, const char *name, int fd)
891
892
{
  LOCK_LOGS();
893
  add_stream_log_impl(severity, name, fd);
894
895
896
897
898
  UNLOCK_LOGS();
}

/** Initialize the global logging facility */
void
899
init_logging(int disable_startup_queue)
900
{
901
902
903
904
  if (!log_mutex_initialized) {
    tor_mutex_init(&log_mutex);
    log_mutex_initialized = 1;
  }
905
906
907
908
909
#ifdef __GNUC__
  if (strchr(__PRETTY_FUNCTION__, '(')) {
    pretty_fn_has_parens = 1;
  }
#endif
910
  if (pending_cb_messages == NULL)
911
    pending_cb_messages = smartlist_new();
912
913
914
  if (disable_startup_queue)
    queue_startup_messages = 0;
  if (pending_startup_messages == NULL && queue_startup_messages) {
915
    pending_startup_messages = smartlist_new();
916
  }
917
918
}

919
920
921
922
923
924
925
926
927
928
/** Set whether we report logging domains as a part of our log messages.
 */
void
logs_set_domain_logging(int enabled)
{
  LOCK_LOGS();
  log_domains_are_logged = enabled;
  UNLOCK_LOGS();
}

929
930
931
/** Add a log handler to receive messages during startup (before the real
 * logs are initialized).
 */
932
void
Peter Palfrader's avatar
Peter Palfrader committed
933
add_temp_log(int min_severity)
934
{
935
  log_severity_list_t *s = tor_malloc_zero(sizeof(log_severity_list_t));
Peter Palfrader's avatar
Peter Palfrader committed
936
  set_log_severity_config(min_severity, LOG_ERR, s);
937
  LOCK_LOGS();
938
  add_stream_log_impl(s, "<temp>", fileno(stdout));
939
  tor_free(s);
940
  logfiles->is_temporary = 1;
941
  UNLOCK_LOGS();