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