GCC Code Coverage Report
Directory: cvmfs/ Exec Total Coverage
File: cvmfs/logging.cc Lines: 177 245 72.2 %
Date: 2019-02-03 02:48:13 Branches: 96 177 54.2 %

Line Branch Exec Source
1
/**
2
 * This file is part of the CernVM File System.
3
 *
4
 * LogCvmfs() handles all message output.  It works like printf.
5
 * It can log to a debug log file, stdout, stderr, and syslog.
6
 * The tracer is a separate module, messages do not overlap with logging.
7
 *
8
 * The syslog setter routines are not thread-safe.  They are meant to be
9
 * invoked at the very first, single-threaded stage.
10
 *
11
 * If DEBUGMSG is undefined, pure debug messages are compiled into no-ops.
12
 */
13
14
#include "logging_internal.h"  // NOLINT(build/include)
15
16
#include <errno.h>
17
#include <fcntl.h>
18
#include <pthread.h>
19
#include <syslog.h>
20
#include <time.h>
21
#include <unistd.h>
22
23
#include <cassert>
24
#include <cstdio>
25
#include <cstdlib>
26
#include <cstring>
27
#include <ctime>
28
29
#include "platform.h"
30
#include "smalloc.h"
31
#include "util/posix.h"
32
33
using namespace std;  // NOLINT
34
35
#ifdef CVMFS_NAMESPACE_GUARD
36
namespace CVMFS_NAMESPACE_GUARD {
37
#endif
38
39
static void LogCustom(unsigned id, const std::string &message);
40
41
namespace {
42
43
const unsigned kMicroSyslogMax = 500 * 1024;  // rotate after 500kB
44
45
pthread_mutex_t lock_stdout = PTHREAD_MUTEX_INITIALIZER;
46
pthread_mutex_t lock_stderr = PTHREAD_MUTEX_INITIALIZER;
47
#ifdef DEBUGMSG
48
pthread_mutex_t lock_debug = PTHREAD_MUTEX_INITIALIZER;
49
FILE *file_debug = NULL;
50
string *path_debug = NULL;
51
#endif
52
const char *module_names[] = {
53
    "unknown",   "cache",       "catalog",      "sql",
54
    "cvmfs",     "hash",        "download",     "compress",
55
    "quota",     "talk",        "monitor",      "lru",
56
    "fuse stub", "signature",   "fs traversal", "catalog traversal",
57
    "nfs maps",  "publish",     "spooler",      "concurrency",
58
    "utility",   "glue buffer", "history",      "unionfs",
59
    "pathspec",  "receiver",    "upload s3",    "upload http",
60
    "s3fanout",  "gc",          "dns",          "authz",
61
    "reflog",    "kvstore"};
62
int syslog_facility = LOG_USER;
63
int syslog_level = LOG_NOTICE;
64
char *syslog_prefix = NULL;
65
66
string *usyslog_dest = NULL;
67
int usyslog_fd = -1;
68
int usyslog_fd1 = -1;
69
unsigned usyslog_size = 0;
70
pthread_mutex_t lock_usyslock = PTHREAD_MUTEX_INITIALIZER;
71
72
const unsigned kMaxCustomlog = 3;
73
string *customlog_dests[] = {NULL, NULL, NULL};
74
int customlog_fds[] = {-1, -1, -1};
75
pthread_mutex_t customlog_locks[] = {
76
  PTHREAD_MUTEX_INITIALIZER,
77
  PTHREAD_MUTEX_INITIALIZER,
78
  PTHREAD_MUTEX_INITIALIZER};
79
80
LogLevels min_log_level = kLogNormal;
81
static void (*alt_log_func)(const LogSource source, const int mask,
82
                            const char *msg) = NULL;
83
84
}  // namespace
85
86
/**
87
 * Sets the level that is used for all messages to the syslog facility.
88
 */
89
12
void SetLogSyslogLevel(const int level) {
90

12
  switch (level) {
91
    case 1:
92
      syslog_level = LOG_DEBUG;
93
      break;
94
    case 2:
95
      syslog_level = LOG_INFO;
96
      break;
97
    case 3:
98
12
      syslog_level = LOG_NOTICE;
99
12
      break;
100
    default:
101
      syslog_level = LOG_NOTICE;
102
      break;
103
  }
104
12
}
105
106
33
int GetLogSyslogLevel() {
107
33
  switch (syslog_level) {
108
    case LOG_DEBUG:
109
      return 1;
110
    case LOG_INFO:
111
      return 2;
112
    default:
113
33
      return 3;
114
  }
115
}
116
117
/**
118
 * Sets the syslog facility to one of local0 .. local7.
119
 * Falls back to LOG_USER if local_facility is not in [0..7]
120
 */
121
void SetLogSyslogFacility(const int local_facility) {
122
  switch (local_facility) {
123
    case 0:
124
      syslog_facility = LOG_LOCAL0;
125
      break;
126
    case 1:
127
      syslog_facility = LOG_LOCAL1;
128
      break;
129
    case 2:
130
      syslog_facility = LOG_LOCAL2;
131
      break;
132
    case 3:
133
      syslog_facility = LOG_LOCAL3;
134
      break;
135
    case 4:
136
      syslog_facility = LOG_LOCAL4;
137
      break;
138
    case 5:
139
      syslog_facility = LOG_LOCAL5;
140
      break;
141
    case 6:
142
      syslog_facility = LOG_LOCAL6;
143
      break;
144
    case 7:
145
      syslog_facility = LOG_LOCAL7;
146
      break;
147
    default:
148
      syslog_facility = LOG_USER;
149
  }
150
}
151
152
33
int GetLogSyslogFacility() {
153


33
  switch (syslog_facility) {
154
    case LOG_LOCAL0:
155
      return 0;
156
    case LOG_LOCAL1:
157
      return 1;
158
    case LOG_LOCAL2:
159
      return 2;
160
    case LOG_LOCAL3:
161
      return 3;
162
    case LOG_LOCAL4:
163
      return 4;
164
    case LOG_LOCAL5:
165
      return 5;
166
    case LOG_LOCAL6:
167
      return 6;
168
    case LOG_LOCAL7:
169
      return 7;
170
    default:
171
33
      return -1;
172
  }
173
}
174
175
/**
176
 * The syslog prefix is used to distinguish multiple repositories in
177
 * /var/log/messages
178
 */
179
273
void SetLogSyslogPrefix(const std::string &prefix) {
180
273
  if (syslog_prefix) free(syslog_prefix);
181
182
273
  if (prefix == "") {
183
134
    syslog_prefix = NULL;
184
  } else {
185
139
    unsigned len = prefix.length() + 1;
186
139
    syslog_prefix = static_cast<char *>(smalloc(len));
187
139
    syslog_prefix[len - 1] = '\0';
188
139
    memcpy(syslog_prefix, &prefix[0], prefix.length());
189
  }
190
273
}
191
192
void SetLogSyslogShowPID(bool flag) {
193
  openlog(NULL, flag ? LOG_PID : 0, GetLogSyslogFacility());
194
}
195
196
/**
197
 * Set the minimum verbosity level.  By default kLogNormal.
198
 */
199
2
void SetLogVerbosity(const LogLevels min_level) { min_log_level = min_level; }
200
201
202
/**
203
 * "Micro-Syslog" write kLogSyslog messages into filename.  It rotates this
204
 * file.  Requires for ��CernVM
205
 */
206
141
void SetLogMicroSyslog(const std::string &filename) {
207
141
  pthread_mutex_lock(&lock_usyslock);
208
141
  if (usyslog_fd >= 0) {
209
2
    close(usyslog_fd);
210
2
    close(usyslog_fd1);
211
2
    usyslog_fd = -1;
212
2
    usyslog_fd1 = -1;
213
  }
214
215
141
  if (filename == "") {
216
139
    delete usyslog_dest;
217
139
    usyslog_dest = NULL;
218
139
    pthread_mutex_unlock(&lock_usyslock);
219
139
    return;
220
  }
221
222
2
  usyslog_fd = open(filename.c_str(), O_RDWR | O_APPEND | O_CREAT, 0600);
223
2
  if (usyslog_fd < 0) {
224
    fprintf(stderr, "could not open usyslog file %s (%d), aborting\n",
225
            filename.c_str(), errno);
226
    abort();
227
  }
228
2
  usyslog_fd1 = open((filename + ".1").c_str(), O_WRONLY | O_CREAT, 0600);
229
2
  if (usyslog_fd1 < 0) {
230
    fprintf(stderr, "could not open usyslog.1 file %s.1 (%d), aborting\n",
231
            filename.c_str(), errno);
232
    abort();
233
  }
234
  platform_stat64 info;
235
2
  int retval = platform_fstat(usyslog_fd, &info);
236
2
  assert(retval == 0);
237
2
  usyslog_size = info.st_size;
238
2
  usyslog_dest = new string(filename);
239
2
  pthread_mutex_unlock(&lock_usyslock);
240
}
241
242
3
std::string GetLogMicroSyslog() {
243
3
  pthread_mutex_lock(&lock_usyslock);
244
3
  string result;
245
3
  if (usyslog_dest) result = *usyslog_dest;
246
3
  pthread_mutex_unlock(&lock_usyslock);
247
  return result;
248
}
249
250
1000004
static void LogMicroSyslog(const std::string &message) {
251
1000004
  if (message.size() == 0) return;
252
253
1000004
  pthread_mutex_lock(&lock_usyslock);
254
1000004
  if (usyslog_fd < 0) {
255
    pthread_mutex_unlock(&lock_usyslock);
256
    return;
257
  }
258
259
1000004
  int written = write(usyslog_fd, message.data(), message.size());
260

1000004
  if ((written < 0) || (static_cast<unsigned>(written) != message.size())) {
261
    close(usyslog_fd);
262
    usyslog_fd = -1;
263
    abort();
264
  }
265
1000004
  int retval = fsync(usyslog_fd);
266
1000004
  assert(retval == 0);
267
1000004
  usyslog_size += written;
268
269
1000004
  if (usyslog_size >= kMicroSyslogMax) {
270
    // Wipe out usyslog.1 file
271
76
    retval = ftruncate(usyslog_fd1, 0);
272
76
    assert(retval == 0);
273
274
    // Copy from usyslog to usyslog.1
275
76
    retval = lseek(usyslog_fd, 0, SEEK_SET);
276
76
    assert(retval == 0);
277
    unsigned char buf[4096];
278
    int num_bytes;
279
9576
    do {
280
9576
      num_bytes = read(usyslog_fd, buf, 4096);
281
9576
      assert(num_bytes >= 0);
282
9576
      if (num_bytes == 0) break;
283
9576
      int written = write(usyslog_fd1, buf, num_bytes);
284
9576
      assert(written == num_bytes);
285
    } while (num_bytes == 4096);
286
76
    retval = lseek(usyslog_fd1, 0, SEEK_SET);
287
76
    assert(retval == 0);
288
289
    // Reset usyslog
290
76
    retval = lseek(usyslog_fd, 0, SEEK_SET);
291
76
    assert(retval == 0);
292
76
    retval = ftruncate(usyslog_fd, 0);
293
76
    assert(retval == 0);
294
76
    usyslog_size = 0;
295
  }
296
1000004
  pthread_mutex_unlock(&lock_usyslock);
297
}
298
299
/**
300
 * Changes the debug log file from stderr. No effect if DEBUGMSG is undefined.
301
 */
302
#ifdef DEBUGMSG
303
134
void SetLogDebugFile(const string &filename) {
304
134
  if (filename == "") {
305

134
    if ((file_debug != NULL) && (file_debug != stderr)) {
306
      fclose(file_debug);
307
      file_debug = NULL;
308
    }
309
134
    delete path_debug;
310
134
    path_debug = NULL;
311
134
    return;
312
  }
313
314
  if ((file_debug != NULL) && (file_debug != stderr)) {
315
    if ((fclose(file_debug) < 0)) {
316
      fprintf(stderr, "could not close current log file (%d), aborting\n",
317
              errno);
318
319
      abort();
320
    }
321
  }
322
  int fd = open(filename.c_str(), O_WRONLY | O_APPEND | O_CREAT, 0600);
323
  if ((fd < 0) || ((file_debug = fdopen(fd, "a")) == NULL)) {
324
    fprintf(stderr, "could not open debug log file %s (%d), aborting\n",
325
            filename.c_str(), errno);
326
    syslog(syslog_facility | LOG_ERR,
327
           "could not open debug log file %s (%d), "
328
           "aborting\n",
329
           filename.c_str(), errno);
330
    abort();
331
  }
332
  delete path_debug;
333
  path_debug = new string(filename);
334
}
335
336
33
string GetLogDebugFile() {
337
33
  if (path_debug) return *path_debug;
338
33
  return "";
339
}
340
#endif
341
342
53
void SetAltLogFunc(void (*fn)(const LogSource source, const int mask,
343
                              const char *msg)) {
344
53
  alt_log_func = fn;
345
53
}
346
347
348
/**
349
 * Logs a message to one or multiple facilities specified by mask.
350
 * Mask can be extended by a log level in the future, using the higher bits.
351
 *
352
 * @param[in] source Component that triggers the logging
353
 * @param[in] mask Bit mask of log facilities
354
 * @param[in] format Format string followed by arguments like printf
355
 */
356
1521867
void LogCvmfs(const LogSource source, const int mask, const char *format, ...) {
357
1521867
  char *msg = NULL;
358
  va_list variadic_list;
359
360
// Log level check, no flag set in mask means kLogNormal
361
#ifndef DEBUGMSG
362
  int log_level = mask & ((2 * kLogNone - 1) ^ (kLogLevel0 - 1));
363
  if (!log_level) log_level = kLogNormal;
364
  if (log_level < min_log_level) return;
365
#endif
366
367
  // Format the message string
368
1521867
  va_start(variadic_list, format);
369
1521867
  int retval = vasprintf(&msg, format, variadic_list);
370
1521867
  assert(retval != -1);  // else: out of memory
371
1521867
  va_end(variadic_list);
372
373
1521867
  if (alt_log_func) {
374
7426
    (*alt_log_func)(source, mask, msg);
375
7426
    return;
376
  }
377
378
#ifdef DEBUGMSG
379
1514441
  if (mask & kLogDebug) {
380
306176
    pthread_mutex_lock(&lock_debug);
381
382
    // Set the file pointer for debuging to stderr, if necessary
383
306176
    if (file_debug == NULL) file_debug = stderr;
384
385
    // Get timestamp
386
    time_t rawtime;
387
306176
    time(&rawtime);
388
    struct tm now;
389
306176
    localtime_r(&rawtime, &now);
390
391
306176
    if (file_debug == stderr) pthread_mutex_lock(&lock_stderr);
392
    fprintf(file_debug, "(%s) %s    [%02d-%02d-%04d %02d:%02d:%02d %s]\n",
393
            module_names[source], msg, (now.tm_mon) + 1, now.tm_mday,
394
            (now.tm_year) + 1900, now.tm_hour, now.tm_min, now.tm_sec,
395
306176
            now.tm_zone);
396
306176
    fflush(file_debug);
397
306176
    if (file_debug == stderr) pthread_mutex_unlock(&lock_stderr);
398
399
306176
    pthread_mutex_unlock(&lock_debug);
400
  }
401
#endif
402
403
1514440
  if (mask & kLogStdout) {
404
208242
    pthread_mutex_lock(&lock_stdout);
405
208242
    if (mask & kLogShowSource) printf("(%s) ", module_names[source]);
406
208242
    printf("%s", msg);
407
208242
    if (!(mask & kLogNoLinebreak)) printf("\n");
408
208242
    fflush(stdout);
409
208242
    pthread_mutex_unlock(&lock_stdout);
410
  }
411
412
1514440
  if (mask & kLogStderr) {
413
2
    pthread_mutex_lock(&lock_stderr);
414
2
    if (mask & kLogShowSource) fprintf(stderr, "(%s) ", module_names[source]);
415
2
    fprintf(stderr, "%s", msg);
416
2
    if (!(mask & kLogNoLinebreak)) fprintf(stderr, "\n");
417
2
    fflush(stderr);
418
2
    pthread_mutex_unlock(&lock_stderr);
419
  }
420
421
1514440
  if (mask & (kLogSyslog | kLogSyslogWarn | kLogSyslogErr)) {
422
1000838
    if (usyslog_dest) {
423
1000004
      string fmt_msg(msg);
424
1000004
      if (syslog_prefix) fmt_msg = "(" + string(syslog_prefix) + ") " + fmt_msg;
425
      time_t rawtime;
426
1000004
      time(&rawtime);
427
      char fmt_time[26];
428
1000004
      ctime_r(&rawtime, fmt_time);
429
1000004
      fmt_msg = string(fmt_time, 24) + " " + fmt_msg;
430
1000004
      fmt_msg.push_back('\n');
431
1000004
      LogMicroSyslog(fmt_msg);
432
    } else {
433
834
      int level = syslog_level;
434
834
      if (mask & kLogSyslogWarn) level = LOG_WARNING;
435
834
      if (mask & kLogSyslogErr) level = LOG_ERR;
436
834
      if (syslog_prefix) {
437
146
        syslog(syslog_facility | level, "(%s) %s", syslog_prefix, msg);
438
      } else {
439
688
        syslog(syslog_facility | level, "%s", msg);
440
      }
441
    }
442
  }
443
444
1514440
  if (mask & (kLogCustom0 | kLogCustom1 | kLogCustom2)) {
445
4
    string fmt_msg(msg);
446
4
    if (syslog_prefix) fmt_msg = "(" + string(syslog_prefix) + ") " + fmt_msg;
447
4
    if (!(mask & kLogNoLinebreak)) fmt_msg += "\n";
448
4
    if (mask & kLogCustom0) LogCustom(0, fmt_msg);
449
4
    if (mask & kLogCustom1) LogCustom(1, fmt_msg);
450
4
    if (mask & kLogCustom2) LogCustom(2, fmt_msg);
451
  }
452
453
1514440
  free(msg);
454
}
455
456
5
void PrintError(const string &message) {
457
5
  LogCvmfs(kLogCvmfs, kLogStderr, "[ERROR] %s", message.c_str());
458
5
}
459
460
void PrintWarning(const string &message) {
461
  LogCvmfs(kLogCvmfs, kLogStderr, "[WARNING] %s", message.c_str());
462
}
463
464
465
/**
466
 * Opens a custom log file
467
 */
468
15
void SetLogCustomFile(unsigned id, const std::string &filename) {
469
15
  assert(id < kMaxCustomlog);
470
15
  pthread_mutex_lock(&customlog_locks[id]);
471
472
15
  if (customlog_fds[id] >= 0) {
473
3
    close(customlog_fds[id]);
474
3
    customlog_fds[id] = -1;
475
  }
476
477
15
  if (filename.empty()) {
478
12
    delete customlog_dests[id];
479
12
    customlog_dests[id] = NULL;
480
12
    pthread_mutex_unlock(&customlog_locks[id]);
481
12
    return;
482
  }
483
484
3
  customlog_fds[id] = open(filename.c_str(), O_RDWR | O_APPEND | O_CREAT, 0600);
485
3
  if (customlog_fds[id] < 0) {
486
    LogCvmfs(kLogCvmfs, kLogDebug | kLogSyslogErr,
487
             "could not open log file %s (%d), aborting",
488
             filename.c_str(), errno);
489
    abort();
490
  }
491
3
  delete customlog_dests[id];
492
3
  customlog_dests[id] = new string(filename);
493
494
3
  pthread_mutex_unlock(&customlog_locks[id]);
495
}
496
497
498
4
static void LogCustom(unsigned id, const std::string &message) {
499
4
  assert(id < kMaxCustomlog);
500
4
  if (message.size() == 0) return;
501
502
4
  pthread_mutex_lock(&customlog_locks[id]);
503
4
  assert(customlog_fds[id] >= 0);
504
505
4
  bool retval_b = SafeWrite(customlog_fds[id], message.data(), message.size());
506
4
  if (!retval_b) {
507
    LogCvmfs(kLogCvmfs, kLogDebug | kLogSyslogErr,
508
             "could not write into log file %s (%d), aborting - lost: %s",
509
             customlog_dests[id]->c_str(), errno, message.c_str());
510
    abort();
511
  }
512
4
  int retval_i = fsync(customlog_fds[id]);
513
4
  assert(retval_i == 0);
514
515
4
  pthread_mutex_unlock(&customlog_locks[id]);
516
}
517
518
519
4
void LogShutdown() {
520
4
  SetLogMicroSyslog("");
521
16
  for (unsigned i = 0; i < kMaxCustomlog; ++i)
522
12
    SetLogCustomFile(i, "");
523
4
}
524
525
526
#ifdef CVMFS_NAMESPACE_GUARD
527
}  // namespace CVMFS_NAMESPACE_GUARD
528
#endif