src/pulsecore/log.c

   1 /***
   2   This file is part of PulseAudio.
   3
   4   Copyright 2004-2006 Lennart Poettering
   5   Copyright 2006 Pierre Ossman <ossman@cendio.se> for Cendio AB
   6
   7   PulseAudio is free software; you can redistribute it and/or modify
   8   it under the terms of the GNU Lesser General Public License as
   9   published by the Free Software Foundation; either version 2.1 of the
  10   License, or (at your option) any later version.
  11
  12   PulseAudio is distributed in the hope that it will be useful, but
  13   WITHOUT ANY WARRANTY; without even the implied warranty of
  14   MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU
  15   General Public License for more details.
  16
  17   You should have received a copy of the GNU Lesser General Public
  18   License along with PulseAudio; if not, write to the Free Software
  19   Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307
  20   USA.
  21 ***/
  22
  23 #ifdef HAVE_CONFIG_H
  24 #include <config.h>
  25 #endif
  26
  27 #include <stdarg.h>
  28 #include <stdio.h>
  29 #include <unistd.h>
  30 #include <string.h>
  31 #include <errno.h>
  32 #include <fcntl.h>
  33
  34 #ifdef HAVE_EXECINFO_H
  35 #include <execinfo.h>
  36 #endif
  37
  38 #ifdef HAVE_SYSLOG_H
  39 #include <syslog.h>
  40 #endif
  41
  42 #include <pulse/gccmacro.h>
  43 #include <pulse/rtclock.h>
  44 #include <pulse/utf8.h>
  45 #include <pulse/xmalloc.h>
  46 #include <pulse/util.h>
  47 #include <pulse/timeval.h>
  48
  49 #include <pulsecore/macro.h>
  50 #include <pulsecore/core-util.h>
  51 #include <pulsecore/core-error.h>
  52 #include <pulsecore/once.h>
  53 #include <pulsecore/ratelimit.h>
  54 #include <pulsecore/thread.h>
  55 #include <pulsecore/i18n.h>
  56
  57 #include "log.h"
  58
  59 #define ENV_LOG_SYSLOG "PULSE_LOG_SYSLOG"
  60 #define ENV_LOG_LEVEL "PULSE_LOG"
  61 #define ENV_LOG_COLORS "PULSE_LOG_COLORS"
  62 #define ENV_LOG_PRINT_TIME "PULSE_LOG_TIME"
  63 #define ENV_LOG_PRINT_FILE "PULSE_LOG_FILE"
  64 #define ENV_LOG_PRINT_META "PULSE_LOG_META"
  65 #define ENV_LOG_PRINT_LEVEL "PULSE_LOG_LEVEL"
  66 #define ENV_LOG_BACKTRACE "PULSE_LOG_BACKTRACE"
  67 #define ENV_LOG_BACKTRACE_SKIP "PULSE_LOG_BACKTRACE_SKIP"
  68 #define ENV_LOG_NO_RATELIMIT "PULSE_LOG_NO_RATE_LIMIT"
  69 #define LOG_MAX_SUFFIX_NUMBER 99
  70
  71 static char *ident = NULL; /* in local charset format */
  72 static pa_log_target target = { PA_LOG_STDERR, NULL };
  73 static pa_log_target_type_t target_override;
  74 static bool target_override_set = false;
  75 static pa_log_level_t maximum_level = PA_LOG_ERROR, maximum_level_override = PA_LOG_ERROR;
  76 static unsigned show_backtrace = 0, show_backtrace_override = 0, skip_backtrace = 0;
  77 static pa_log_flags_t flags = 0, flags_override = 0;
  78 static bool no_rate_limit = false;
  79 static int log_fd = -1;
  80
  81 #ifdef HAVE_SYSLOG_H
  82 static const int level_to_syslog[] = {
  83     [PA_LOG_ERROR] = LOG_ERR,
  84     [PA_LOG_WARN] = LOG_WARNING,
  85     [PA_LOG_NOTICE] = LOG_NOTICE,
  86     [PA_LOG_INFO] = LOG_INFO,
  87     [PA_LOG_DEBUG] = LOG_DEBUG
  88 };
  89 #endif
  90
  91 static const char level_to_char[] = {
  92     [PA_LOG_ERROR] = 'E',
  93     [PA_LOG_WARN] = 'W',
  94     [PA_LOG_NOTICE] = 'N',
  95     [PA_LOG_INFO] = 'I',
  96     [PA_LOG_DEBUG] = 'D'
  97 };
  98
  99 void pa_log_set_ident(const char *p) {
 100     pa_xfree(ident);
 101
 102     if (!(ident = pa_utf8_to_locale(p)))
 103         ident = pa_ascii_filter(p);
 104 }
 105
 106 /* To make valgrind shut up. */
 107 static void ident_destructor(void) PA_GCC_DESTRUCTOR;
 108 static void ident_destructor(void) {
 109     if (!pa_in_valgrind())
 110         return;
 111
 112     pa_xfree(ident);
 113 }
 114
 115 void pa_log_set_level(pa_log_level_t l) {
 116     pa_assert(l < PA_LOG_LEVEL_MAX);
 117
 118     maximum_level = l;
 119 }
 120
 121 int pa_log_set_target(pa_log_target *t) {
 122     int fd = -1;
 123     int old_fd;
 124
 125     pa_assert(t);
 126
 127     switch (t->type) {
 128         case PA_LOG_STDERR:
 129         case PA_LOG_SYSLOG:
 130         case PA_LOG_NULL:
 131             break;
 132         case PA_LOG_FILE:
 133             if ((fd = pa_open_cloexec(t->file, O_WRONLY | O_TRUNC | O_CREAT, S_IRUSR | S_IWUSR)) < 0) {
 134                 pa_log(_("Failed to open target file '%s'."), t->file);
 135                 return -1;
 136             }
 137             break;
 138         case PA_LOG_NEWFILE: {
 139             char *file_path;
 140             char *p;
 141             unsigned version;
 142
 143             file_path = pa_sprintf_malloc("%s.xx", t->file);
 144             p = file_path + strlen(t->file);
 145
 146             for (version = 0; version <= LOG_MAX_SUFFIX_NUMBER; version++) {
 147                 memset(p, 0, 3); /* Overwrite the ".xx" part in file_path with zero bytes. */
 148
 149                 if (version > 0)
 150                     pa_snprintf(p, 4, ".%u", version); /* Why 4? ".xx" + termitating zero byte. */
 151
 152                 if ((fd = pa_open_cloexec(file_path, O_WRONLY | O_TRUNC | O_CREAT | O_EXCL, S_IRUSR | S_IWUSR)) >= 0)
 153                     break;
 154             }
 155
 156             if (version > LOG_MAX_SUFFIX_NUMBER) {
 157                 pa_log(_("Tried to open target file '%s', '%s.1', '%s.2' ... '%s.%d', but all failed."),
 158                         t->file, t->file, t->file, t->file, LOG_MAX_SUFFIX_NUMBER);
 159                 pa_xfree(file_path);
 160                 return -1;
 161             } else
 162                 pa_log_debug("Opened target file %s\n", file_path);
 163
 164             pa_xfree(file_path);
 165             break;
 166         }
 167     }
 168
 169     target.type = t->type;
 170     pa_xfree(target.file);
 171     target.file = pa_xstrdup(t->file);
 172
 173     old_fd = log_fd;
 174     log_fd = fd;
 175
 176     if (old_fd >= 0)
 177         pa_close(old_fd);
 178
 179     return 0;
 180 }
 181
 182 void pa_log_set_flags(pa_log_flags_t _flags, pa_log_merge_t merge) {
 183     pa_assert(!(_flags & ~(PA_LOG_COLORS|PA_LOG_PRINT_TIME|PA_LOG_PRINT_FILE|PA_LOG_PRINT_META|PA_LOG_PRINT_LEVEL)));
 184
 185     if (merge == PA_LOG_SET)
 186         flags |= _flags;
 187     else if (merge == PA_LOG_UNSET)
 188         flags &= ~_flags;
 189     else
 190         flags = _flags;
 191 }
 192
 193 void pa_log_set_show_backtrace(unsigned nlevels) {
 194     show_backtrace = nlevels;
 195 }
 196
 197 void pa_log_set_skip_backtrace(unsigned nlevels) {
 198     skip_backtrace = nlevels;
 199 }
 200
 201 #ifdef HAVE_EXECINFO_H
 202
 203 static char* get_backtrace(unsigned show_nframes) {
 204     void* trace[32];
 205     int n_frames;
 206     char **symbols, *e, *r;
 207     unsigned j, n, s;
 208     size_t a;
 209
 210     pa_assert(show_nframes > 0);
 211
 212     n_frames = backtrace(trace, PA_ELEMENTSOF(trace));
 213
 214     if (n_frames <= 0)
 215         return NULL;
 216
 217     symbols = backtrace_symbols(trace, n_frames);
 218
 219     if (!symbols)
 220         return NULL;
 221
 222     s = skip_backtrace;
 223     n = PA_MIN((unsigned) n_frames, s + show_nframes);
 224
 225     a = 4;
 226
 227     for (j = s; j < n; j++) {
 228         if (j > s)
 229             a += 2;
 230         a += strlen(pa_path_get_filename(symbols[j]));
 231     }
 232
 233     r = pa_xnew(char, a);
 234
 235     strcpy(r, " (");
 236     e = r + 2;
 237
 238     for (j = s; j < n; j++) {
 239         const char *sym;
 240
 241         if (j > s) {
 242             strcpy(e, "<<");
 243             e += 2;
 244         }
 245
 246         sym = pa_path_get_filename(symbols[j]);
 247
 248         strcpy(e, sym);
 249         e += strlen(sym);
 250     }
 251
 252     strcpy(e, ")");
 253
 254     free(symbols);
 255
 256     return r;
 257 }
 258
 259 #endif
 260
 261 static void init_defaults(void) {
 262     PA_ONCE_BEGIN {
 263
 264         const char *e;
 265
 266         if (!ident) {
 267             char binary[256];
 268             if (pa_get_binary_name(binary, sizeof(binary)))
 269                 pa_log_set_ident(binary);
 270         }
 271
 272         if (getenv(ENV_LOG_SYSLOG)) {
 273             target_override = PA_LOG_SYSLOG;
 274             target_override_set = true;
 275         }
 276
 277         if ((e = getenv(ENV_LOG_LEVEL))) {
 278             maximum_level_override = (pa_log_level_t) atoi(e);
 279
 280             if (maximum_level_override >= PA_LOG_LEVEL_MAX)
 281                 maximum_level_override = PA_LOG_LEVEL_MAX-1;
 282         }
 283
 284         if (getenv(ENV_LOG_COLORS))
 285             flags_override |= PA_LOG_COLORS;
 286
 287         if (getenv(ENV_LOG_PRINT_TIME))
 288             flags_override |= PA_LOG_PRINT_TIME;
 289
 290         if (getenv(ENV_LOG_PRINT_FILE))
 291             flags_override |= PA_LOG_PRINT_FILE;
 292
 293         if (getenv(ENV_LOG_PRINT_META))
 294             flags_override |= PA_LOG_PRINT_META;
 295
 296         if (getenv(ENV_LOG_PRINT_LEVEL))
 297             flags_override |= PA_LOG_PRINT_LEVEL;
 298
 299         if ((e = getenv(ENV_LOG_BACKTRACE))) {
 300             show_backtrace_override = (unsigned) atoi(e);
 301
 302             if (show_backtrace_override <= 0)
 303                 show_backtrace_override = 0;
 304         }
 305
 306         if ((e = getenv(ENV_LOG_BACKTRACE_SKIP))) {
 307             skip_backtrace = (unsigned) atoi(e);
 308
 309             if (skip_backtrace <= 0)
 310                 skip_backtrace = 0;
 311         }
 312
 313         if (getenv(ENV_LOG_NO_RATELIMIT))
 314             no_rate_limit = true;
 315
 316     } PA_ONCE_END;
 317 }
 318
 319 void pa_log_levelv_meta(
 320         pa_log_level_t level,
 321         const char*file,
 322         int line,
 323         const char *func,
 324         const char *format,
 325         va_list ap) {
 326
 327     char *t, *n;
 328     int saved_errno = errno;
 329     char *bt = NULL;
 330     pa_log_target_type_t _target;
 331     pa_log_level_t _maximum_level;
 332     unsigned _show_backtrace;
 333     pa_log_flags_t _flags;
 334
 335     /* We don't use dynamic memory allocation here to minimize the hit
 336      * in RT threads */
 337     char text[16*1024], location[128], timestamp[32];
 338
 339     pa_assert(level < PA_LOG_LEVEL_MAX);
 340     pa_assert(format);
 341
 342     init_defaults();
 343
 344     _target = target_override_set ? target_override : target.type;
 345     _maximum_level = PA_MAX(maximum_level, maximum_level_override);
 346     _show_backtrace = PA_MAX(show_backtrace, show_backtrace_override);
 347     _flags = flags | flags_override;
 348
 349     if (PA_LIKELY(level > _maximum_level)) {
 350         errno = saved_errno;
 351         return;
 352     }
 353
 354     pa_vsnprintf(text, sizeof(text), format, ap);
 355
 356     if ((_flags & PA_LOG_PRINT_META) && file && line > 0 && func)
 357         pa_snprintf(location, sizeof(location), "[%s][%s:%i %s()] ",
 358                     pa_strnull(pa_thread_get_name(pa_thread_self())), file, line, func);
 359     else if ((_flags & (PA_LOG_PRINT_META|PA_LOG_PRINT_FILE)) && file)
 360         pa_snprintf(location, sizeof(location), "[%s] %s: ",
 361                     pa_strnull(pa_thread_get_name(pa_thread_self())), pa_path_get_filename(file));
 362     else
 363         location[0] = 0;
 364
 365     if (_flags & PA_LOG_PRINT_TIME) {
 366         static pa_usec_t start, last;
 367         pa_usec_t u, a, r;
 368
 369         u = pa_rtclock_now();
 370
 371         PA_ONCE_BEGIN {
 372             start = u;
 373             last = u;
 374         } PA_ONCE_END;
 375
 376         r = u - last;
 377         a = u - start;
 378
 379         /* This is not thread safe, but this is a debugging tool only
 380          * anyway. */
 381         last = u;
 382
 383         pa_snprintf(timestamp, sizeof(timestamp), "(%4llu.%03llu|%4llu.%03llu) ",
 384                     (unsigned long long) (a / PA_USEC_PER_SEC),
 385                     (unsigned long long) (((a / PA_USEC_PER_MSEC)) % 1000),
 386                     (unsigned long long) (r / PA_USEC_PER_SEC),
 387                     (unsigned long long) (((r / PA_USEC_PER_MSEC)) % 1000));
 388
 389     } else
 390         timestamp[0] = 0;
 391
 392 #ifdef HAVE_EXECINFO_H
 393     if (_show_backtrace > 0)
 394         bt = get_backtrace(_show_backtrace);
 395 #endif
 396
 397     if (!pa_utf8_valid(text))
 398         pa_logl(level, "Invalid UTF-8 string following below:");
 399
 400     for (t = text; t; t = n) {
 401         if ((n = strchr(t, '\n'))) {
 402             *n = 0;
 403             n++;
 404         }
 405
 406         /* We ignore strings only made out of whitespace */
 407         if (t[strspn(t, "\t ")] == 0)
 408             continue;
 409
 410         switch (_target) {
 411
 412             case PA_LOG_STDERR: {
 413                 const char *prefix = "", *suffix = "", *grey = "";
 414                 char *local_t;
 415
 416 #ifndef OS_IS_WIN32
 417                 /* Yes indeed. Useless, but fun! */
 418                 if ((_flags & PA_LOG_COLORS) && isatty(STDERR_FILENO)) {
 419                     if (level <= PA_LOG_ERROR)
 420                         prefix = "\x1B[1;31m";
 421                     else if (level <= PA_LOG_WARN)
 422                         prefix = "\x1B[1m";
 423
 424                     if (bt)
 425                         grey = "\x1B[2m";
 426
 427                     if (grey[0] || prefix[0])
 428                         suffix = "\x1B[0m";
 429                 }
 430 #endif
 431
 432                 /* We shouldn't be using dynamic allocation here to
 433                  * minimize the hit in RT threads */
 434                 if ((local_t = pa_utf8_to_locale(t)))
 435                     t = local_t;
 436
 437                 if (_flags & PA_LOG_PRINT_LEVEL)
 438                     fprintf(stderr, "%s%c: %s%s%s%s%s%s\n", timestamp, level_to_char[level], location, prefix, t, grey, pa_strempty(bt), suffix);
 439                 else
 440                     fprintf(stderr, "%s%s%s%s%s%s%s\n", timestamp, location, prefix, t, grey, pa_strempty(bt), suffix);
 441 #ifdef OS_IS_WIN32
 442                 fflush(stderr);
 443 #endif
 444
 445                 pa_xfree(local_t);
 446
 447                 break;
 448             }
 449
 450 #ifdef HAVE_SYSLOG_H
 451             case PA_LOG_SYSLOG: {
 452                 char *local_t;
 453
 454                 openlog(ident, LOG_PID, LOG_USER);
 455
 456                 if ((local_t = pa_utf8_to_locale(t)))
 457                     t = local_t;
 458
 459                 syslog(level_to_syslog[level], "%s%s%s%s", timestamp, location, t, pa_strempty(bt));
 460                 pa_xfree(local_t);
 461
 462                 break;
 463             }
 464 #endif
 465
 466             case PA_LOG_FILE:
 467             case PA_LOG_NEWFILE: {
 468                 if (log_fd >= 0) {
 469                     char metadata[256];
 470
 471                     pa_snprintf(metadata, sizeof(metadata), "\n%c %s %s", level_to_char[level], timestamp, location);
 472
 473                     if ((write(log_fd, metadata, strlen(metadata)) < 0) || (write(log_fd, t, strlen(t)) < 0)) {
 474                         pa_log_target new_target = { .type = PA_LOG_STDERR, .file = NULL };
 475                         saved_errno = errno;
 476                         fprintf(stderr, "%s\n", "Error writing logs to a file descriptor. Redirect log messages to console.");
 477                         fprintf(stderr, "%s %s\n", metadata, t);
 478                         pa_log_set_target(&new_target);
 479                     }
 480                 }
 481
 482                 break;
 483             }
 484             case PA_LOG_NULL:
 485             default:
 486                 break;
 487         }
 488     }
 489
 490     pa_xfree(bt);
 491     errno = saved_errno;
 492 }
 493
 494 void pa_log_level_meta(
 495         pa_log_level_t level,
 496         const char*file,
 497         int line,
 498         const char *func,
 499         const char *format, ...) {
 500
 501     va_list ap;
 502     va_start(ap, format);
 503     pa_log_levelv_meta(level, file, line, func, format, ap);
 504     va_end(ap);
 505 }
 506
 507 void pa_log_levelv(pa_log_level_t level, const char *format, va_list ap) {
 508     pa_log_levelv_meta(level, NULL, 0, NULL, format, ap);
 509 }
 510
 511 void pa_log_level(pa_log_level_t level, const char *format, ...) {
 512     va_list ap;
 513
 514     va_start(ap, format);
 515     pa_log_levelv_meta(level, NULL, 0, NULL, format, ap);
 516     va_end(ap);
 517 }
 518
 519 bool pa_log_ratelimit(pa_log_level_t level) {
 520     /* Not more than 10 messages every 5s */
 521     static PA_DEFINE_RATELIMIT(ratelimit, 5 * PA_USEC_PER_SEC, 10);
 522
 523     init_defaults();
 524
 525     if (no_rate_limit)
 526         return true;
 527
 528     return pa_ratelimit_test(&ratelimit, level);
 529 }
 530
 531 pa_log_target *pa_log_target_new(pa_log_target_type_t type, const char *file) {
 532     pa_log_target *t = NULL;
 533
 534     t = pa_xnew(pa_log_target, 1);
 535
 536     t->type = type;
 537     t->file = pa_xstrdup(file);
 538
 539     return t;
 540 }
 541
 542 void pa_log_target_free(pa_log_target *t) {
 543     pa_assert(t);
 544
 545     pa_xfree(t->file);
 546     pa_xfree(t);
 547 }
 548
 549 pa_log_target *pa_log_parse_target(const char *string) {
 550     pa_log_target *t = NULL;
 551
 552     pa_assert(string);
 553
 554     if (pa_streq(string, "stderr"))
 555         t = pa_log_target_new(PA_LOG_STDERR, NULL);
 556     else if (pa_streq(string, "syslog"))
 557         t = pa_log_target_new(PA_LOG_SYSLOG, NULL);
 558     else if (pa_streq(string, "null"))
 559         t = pa_log_target_new(PA_LOG_NULL, NULL);
 560     else if (pa_startswith(string, "file:"))
 561         t = pa_log_target_new(PA_LOG_FILE, string + 5);
 562     else if (pa_startswith(string, "newfile:"))
 563         t = pa_log_target_new(PA_LOG_NEWFILE, string + 8);
 564     else
 565         pa_log(_("Invalid log target."));
 566
 567     return t;
 568 }
 569
 570 char *pa_log_target_to_string(const pa_log_target *t) {
 571     char *string = NULL;
 572
 573     pa_assert(t);
 574
 575     switch (t->type) {
 576         case PA_LOG_STDERR:
 577             string = pa_xstrdup("stderr");
 578             break;
 579         case PA_LOG_SYSLOG:
 580             string = pa_xstrdup("syslog");
 581             break;
 582         case PA_LOG_NULL:
 583             string = pa_xstrdup("null");
 584             break;
 585         case PA_LOG_FILE:
 586             string = pa_sprintf_malloc("file:%s", t->file);
 587             break;
 588         case PA_LOG_NEWFILE:
 589             string = pa_sprintf_malloc("newfile:%s", t->file);
 590             break;
 591     }
 592
 593     return string;
 594 }