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
  33 #ifdef HAVE_EXECINFO_H
  34 #include <execinfo.h>
  35 #endif
  36
  37 #ifdef HAVE_SYSLOG_H
  38 #include <syslog.h>
  39 #endif
  40
  41 #include <pulse/gccmacro.h>
  42 #include <pulse/rtclock.h>
  43 #include <pulse/utf8.h>
  44 #include <pulse/xmalloc.h>
  45 #include <pulse/util.h>
  46 #include <pulse/timeval.h>
  47
  48 #include <pulsecore/macro.h>
  49 #include <pulsecore/core-util.h>
  50 #include <pulsecore/once.h>
  51 #include <pulsecore/ratelimit.h>
  52 #include <pulsecore/thread.h>
  53
  54 #include "log.h"
  55
  56 #ifdef USE_DLOG
  57 #include <dlog.h>
  58 #define DLOG_TAG        "PULSEAUDIO"
  59
  60 #define COLOR_BLACK             30
  61 #define COLOR_RED               31
  62 #define COLOR_GREEN             32
  63 #define COLOR_BLUE              34
  64 #define COLOR_MAGENTA           35
  65 #define COLOR_CYAN              36
  66 #define COLOR_WHITE             97
  67 #define COLOR_B_GRAY            100
  68 #define COLOR_B_RED             101
  69 #define COLOR_B_GREEN           102
  70 #define COLOR_B_YELLOW          103
  71 #define COLOR_B_BLUE            104
  72 #define COLOR_B_MAGENTA 105
  73 #define COLOR_B_CYAN            106
  74 #define COLOR_REVERSE           7
  75
  76 #endif
  77
  78 #define ENV_LOG_SYSLOG "PULSE_LOG_SYSLOG"
  79 #define ENV_LOG_LEVEL "PULSE_LOG"
  80 #define ENV_LOG_COLORS "PULSE_LOG_COLORS"
  81 #define ENV_LOG_PRINT_TIME "PULSE_LOG_TIME"
  82 #define ENV_LOG_PRINT_FILE "PULSE_LOG_FILE"
  83 #define ENV_LOG_PRINT_META "PULSE_LOG_META"
  84 #define ENV_LOG_PRINT_LEVEL "PULSE_LOG_LEVEL"
  85 #define ENV_LOG_BACKTRACE "PULSE_LOG_BACKTRACE"
  86 #define ENV_LOG_BACKTRACE_SKIP "PULSE_LOG_BACKTRACE_SKIP"
  87 #define ENV_LOG_NO_RATELIMIT "PULSE_LOG_NO_RATE_LIMIT"
  88
  89 static char *ident = NULL; /* in local charset format */
  90 static pa_log_target_t target = PA_LOG_STDERR, target_override;
  91 static pa_bool_t target_override_set = FALSE;
  92 static pa_log_level_t maximum_level = PA_LOG_ERROR, maximum_level_override = PA_LOG_ERROR;
  93 static unsigned show_backtrace = 0, show_backtrace_override = 0, skip_backtrace = 0;
  94 static pa_log_flags_t flags = 0, flags_override = 0;
  95 static pa_bool_t no_rate_limit = FALSE;
  96 static int log_fd = -1;
  97
  98 #ifdef HAVE_SYSLOG_H
  99 static const int level_to_syslog[] = {
 100     [PA_LOG_ERROR] = LOG_ERR,
 101     [PA_LOG_WARN] = LOG_WARNING,
 102     [PA_LOG_NOTICE] = LOG_NOTICE,
 103     [PA_LOG_INFO] = LOG_INFO,
 104     [PA_LOG_DEBUG] = LOG_DEBUG
 105 };
 106 #endif
 107
 108 static const char level_to_char[] = {
 109     [PA_LOG_ERROR] = 'E',
 110     [PA_LOG_WARN] = 'W',
 111     [PA_LOG_NOTICE] = 'N',
 112     [PA_LOG_INFO] = 'I',
 113     [PA_LOG_DEBUG] = 'D'
 114 };
 115
 116 void pa_log_set_ident(const char *p) {
 117     pa_xfree(ident);
 118
 119     if (!(ident = pa_utf8_to_locale(p)))
 120         ident = pa_ascii_filter(p);
 121 }
 122
 123 /* To make valgrind shut up. */
 124 static void ident_destructor(void) PA_GCC_DESTRUCTOR;
 125 static void ident_destructor(void) {
 126     if (!pa_in_valgrind())
 127         return;
 128
 129     pa_xfree(ident);
 130 }
 131
 132 void pa_log_set_level(pa_log_level_t l) {
 133     pa_assert(l < PA_LOG_LEVEL_MAX);
 134
 135     maximum_level = l;
 136 }
 137
 138 void pa_log_set_target(pa_log_target_t t) {
 139     pa_assert(t < PA_LOG_TARGET_MAX);
 140
 141     target = t;
 142 }
 143
 144 void pa_log_set_flags(pa_log_flags_t _flags, pa_log_merge_t merge) {
 145     pa_assert(!(_flags & ~(PA_LOG_COLORS|PA_LOG_PRINT_TIME|PA_LOG_PRINT_FILE|PA_LOG_PRINT_META|PA_LOG_PRINT_LEVEL)));
 146
 147     if (merge == PA_LOG_SET)
 148         flags |= _flags;
 149     else if (merge == PA_LOG_UNSET)
 150         flags &= ~_flags;
 151     else
 152         flags = _flags;
 153 }
 154
 155 void pa_log_set_fd(int fd) {
 156     if (fd >= 0)
 157         log_fd = fd;
 158     else if (log_fd >= 0) {
 159         pa_close(log_fd);
 160         log_fd = -1;
 161     }
 162 }
 163
 164 void pa_log_set_show_backtrace(unsigned nlevels) {
 165     show_backtrace = nlevels;
 166 }
 167
 168 void pa_log_set_skip_backtrace(unsigned nlevels) {
 169     skip_backtrace = nlevels;
 170 }
 171
 172 #ifdef HAVE_EXECINFO_H
 173
 174 static char* get_backtrace(unsigned show_nframes) {
 175     void* trace[32];
 176     int n_frames;
 177     char **symbols, *e, *r;
 178     unsigned j, n, s;
 179     size_t a;
 180
 181     pa_assert(show_nframes > 0);
 182
 183     n_frames = backtrace(trace, PA_ELEMENTSOF(trace));
 184
 185     if (n_frames <= 0)
 186         return NULL;
 187
 188     symbols = backtrace_symbols(trace, n_frames);
 189
 190     if (!symbols)
 191         return NULL;
 192
 193     s = skip_backtrace;
 194     n = PA_MIN((unsigned) n_frames, s + show_nframes);
 195
 196     a = 4;
 197
 198     for (j = s; j < n; j++) {
 199         if (j > s)
 200             a += 2;
 201         a += strlen(pa_path_get_filename(symbols[j]));
 202     }
 203
 204     r = pa_xnew(char, a);
 205
 206     strcpy(r, " (");
 207     e = r + 2;
 208
 209     for (j = s; j < n; j++) {
 210         const char *sym;
 211
 212         if (j > s) {
 213             strcpy(e, "<<");
 214             e += 2;
 215         }
 216
 217         sym = pa_path_get_filename(symbols[j]);
 218
 219         strcpy(e, sym);
 220         e += strlen(sym);
 221     }
 222
 223     strcpy(e, ")");
 224
 225     free(symbols);
 226
 227     return r;
 228 }
 229
 230 #endif
 231
 232 static void init_defaults(void) {
 233     PA_ONCE_BEGIN {
 234
 235         const char *e;
 236
 237         if (!ident) {
 238             char binary[256];
 239             if (pa_get_binary_name(binary, sizeof(binary)))
 240                 pa_log_set_ident(binary);
 241         }
 242
 243         if (getenv(ENV_LOG_SYSLOG)) {
 244             target_override = PA_LOG_SYSLOG;
 245             target_override_set = TRUE;
 246         }
 247
 248         if ((e = getenv(ENV_LOG_LEVEL))) {
 249             maximum_level_override = (pa_log_level_t) atoi(e);
 250
 251             if (maximum_level_override >= PA_LOG_LEVEL_MAX)
 252                 maximum_level_override = PA_LOG_LEVEL_MAX-1;
 253         }
 254
 255         if (getenv(ENV_LOG_COLORS))
 256             flags_override |= PA_LOG_COLORS;
 257
 258         if (getenv(ENV_LOG_PRINT_TIME))
 259             flags_override |= PA_LOG_PRINT_TIME;
 260
 261         if (getenv(ENV_LOG_PRINT_FILE))
 262             flags_override |= PA_LOG_PRINT_FILE;
 263
 264         if (getenv(ENV_LOG_PRINT_META))
 265             flags_override |= PA_LOG_PRINT_META;
 266
 267         if (getenv(ENV_LOG_PRINT_LEVEL))
 268             flags_override |= PA_LOG_PRINT_LEVEL;
 269
 270         if ((e = getenv(ENV_LOG_BACKTRACE))) {
 271             show_backtrace_override = (unsigned) atoi(e);
 272
 273             if (show_backtrace_override <= 0)
 274                 show_backtrace_override = 0;
 275         }
 276
 277         if ((e = getenv(ENV_LOG_BACKTRACE_SKIP))) {
 278             skip_backtrace = (unsigned) atoi(e);
 279
 280             if (skip_backtrace <= 0)
 281                 skip_backtrace = 0;
 282         }
 283
 284         if (getenv(ENV_LOG_NO_RATELIMIT))
 285             no_rate_limit = TRUE;
 286
 287     } PA_ONCE_END;
 288 }
 289
 290 void pa_log_levelv_meta(
 291         pa_log_level_t level,
 292         const char*file,
 293         int line,
 294         const char *func,
 295         const char *format,
 296         va_list ap) {
 297
 298     char *t, *n;
 299     int saved_errno = errno;
 300     char *bt = NULL;
 301     pa_log_target_t _target;
 302     pa_log_level_t _maximum_level;
 303     unsigned _show_backtrace;
 304     pa_log_flags_t _flags;
 305
 306     /* We don't use dynamic memory allocation here to minimize the hit
 307      * in RT threads */
 308     char text[16*1024], location[128], timestamp[32];
 309
 310     pa_assert(level < PA_LOG_LEVEL_MAX);
 311     pa_assert(format);
 312
 313     init_defaults();
 314
 315     _target = target_override_set ? target_override : target;
 316     _maximum_level = PA_MAX(maximum_level, maximum_level_override);
 317     _show_backtrace = PA_MAX(show_backtrace, show_backtrace_override);
 318     _flags = flags | flags_override;
 319
 320     if (PA_LIKELY(level > _maximum_level)) {
 321         errno = saved_errno;
 322         return;
 323     }
 324
 325     pa_vsnprintf(text, sizeof(text), format, ap);
 326
 327     if ((_flags & PA_LOG_PRINT_META) && file && line > 0 && func)
 328         pa_snprintf(location, sizeof(location), "[%s][%s:%i %s()] ", pa_thread_get_name(pa_thread_self()), file, line, func);
 329     else if ((_flags & (PA_LOG_PRINT_META|PA_LOG_PRINT_FILE)) && file)
 330         pa_snprintf(location, sizeof(location), "[%s] %s: ", pa_thread_get_name(pa_thread_self()), pa_path_get_filename(file));
 331     else
 332         location[0] = 0;
 333
 334     if (_flags & PA_LOG_PRINT_TIME) {
 335         static pa_usec_t start, last;
 336         pa_usec_t u, a, r;
 337
 338         u = pa_rtclock_now();
 339
 340         PA_ONCE_BEGIN {
 341             start = u;
 342             last = u;
 343         } PA_ONCE_END;
 344
 345         r = u - last;
 346         a = u - start;
 347
 348         /* This is not thread safe, but this is a debugging tool only
 349          * anyway. */
 350         last = u;
 351
 352         pa_snprintf(timestamp, sizeof(timestamp), "(%4llu.%03llu|%4llu.%03llu) ",
 353                     (unsigned long long) (a / PA_USEC_PER_SEC),
 354                     (unsigned long long) (((a / PA_USEC_PER_MSEC)) % 1000),
 355                     (unsigned long long) (r / PA_USEC_PER_SEC),
 356                     (unsigned long long) (((r / PA_USEC_PER_MSEC)) % 1000));
 357
 358     } else
 359         timestamp[0] = 0;
 360
 361 #ifdef HAVE_EXECINFO_H
 362     if (_show_backtrace > 0)
 363         bt = get_backtrace(_show_backtrace);
 364 #endif
 365
 366     if (!pa_utf8_valid(text))
 367         pa_logl(level, "Invalid UTF-8 string following below:");
 368
 369     for (t = text; t; t = n) {
 370         if ((n = strchr(t, '\n'))) {
 371             *n = 0;
 372             n++;
 373         }
 374
 375         /* We ignore strings only made out of whitespace */
 376         if (t[strspn(t, "\t ")] == 0)
 377             continue;
 378
 379         switch (_target) {
 380
 381             case PA_LOG_STDERR: {
 382                 const char *prefix = "", *suffix = "", *grey = "";
 383                 char *local_t;
 384
 385 #ifndef OS_IS_WIN32
 386                 /* Yes indeed. Useless, but fun! */
 387                 if ((_flags & PA_LOG_COLORS) && isatty(STDERR_FILENO)) {
 388                     if (level <= PA_LOG_ERROR)
 389                         prefix = "\x1B[1;31m";
 390                     else if (level <= PA_LOG_WARN)
 391                         prefix = "\x1B[1m";
 392
 393                     if (bt)
 394                         grey = "\x1B[2m";
 395
 396                     if (grey[0] || prefix[0])
 397                         suffix = "\x1B[0m";
 398                 }
 399 #endif
 400
 401                 /* We shouldn't be using dynamic allocation here to
 402                  * minimize the hit in RT threads */
 403                 if ((local_t = pa_utf8_to_locale(t)))
 404                     t = local_t;
 405
 406                 if (_flags & PA_LOG_PRINT_LEVEL)
 407                     fprintf(stderr, "%s%c: %s%s%s%s%s%s\n", timestamp, level_to_char[level], location, prefix, t, grey, pa_strempty(bt), suffix);
 408                 else
 409                     fprintf(stderr, "%s%s%s%s%s%s%s\n", timestamp, location, prefix, t, grey, pa_strempty(bt), suffix);
 410 #ifdef OS_IS_WIN32
 411                 fflush(stderr);
 412 #endif
 413
 414                 pa_xfree(local_t);
 415
 416                 break;
 417             }
 418
 419 #ifdef HAVE_SYSLOG_H
 420             case PA_LOG_SYSLOG: {
 421                 char *local_t;
 422
 423                 openlog(ident, LOG_PID, LOG_USER);
 424
 425                 if ((local_t = pa_utf8_to_locale(t)))
 426                     t = local_t;
 427
 428                 syslog(level_to_syslog[level], "%s%s%s%s", timestamp, location, t, pa_strempty(bt));
 429                 pa_xfree(local_t);
 430
 431                 break;
 432             }
 433 #endif
 434
 435             case PA_LOG_FD: {
 436                 if (log_fd >= 0) {
 437                     char metadata[256];
 438
 439                     pa_snprintf(metadata, sizeof(metadata), "\n%c %s %s", level_to_char[level], timestamp, location);
 440
 441                     if ((write(log_fd, metadata, strlen(metadata)) < 0) || (write(log_fd, t, strlen(t)) < 0)) {
 442                         saved_errno = errno;
 443                         pa_log_set_fd(-1);
 444                         fprintf(stderr, "%s\n", "Error writing logs to a file descriptor. Redirect log messages to console.");
 445                         fprintf(stderr, "%s %s\n", metadata, t);
 446                         pa_log_set_target(PA_LOG_STDERR);
 447                     }
 448                 }
 449
 450                 break;
 451             }
 452 #ifdef USE_DLOG
 453             case PA_LOG_DLOG: {
 454                 char *local_t;
 455
 456                 openlog(ident, LOG_PID, LOG_USER);
 457
 458                 if ((local_t = pa_utf8_to_locale(t)))
 459                     t = local_t;
 460
 461                 switch (level)
 462                 {
 463                                         case PA_LOG_DEBUG:
 464                                                 SLOG (LOG_DEBUG, DLOG_TAG, "%s%s%s%s",  timestamp, location, t, pa_strempty(bt));
 465                                                 break;
 466                                         case PA_LOG_INFO:
 467                                         case PA_LOG_NOTICE:     // no notice category in dlog, use info instead.
 468                                                 SLOG (LOG_INFO, DLOG_TAG, "%s%s%s%s", timestamp, location, t, pa_strempty(bt));
 469                                                 break;
 470                                         case PA_LOG_WARN:
 471                                                 SLOG (LOG_WARN, DLOG_TAG, "%s%s%s%s", timestamp, location, t, pa_strempty(bt));
 472                                                 break;
 473                                         case PA_LOG_ERROR:
 474                                                 SLOG (LOG_ERROR, DLOG_TAG, "%s%s%s%s", timestamp, location, t, pa_strempty(bt));
 475                                                 break;
 476                                         default:
 477                                                 SLOG (LOG_DEBUG, DLOG_TAG, "%s%s%s%s", timestamp, location, t, pa_strempty(bt));
 478                                                 break;
 479                 }
 480
 481                 pa_xfree(local_t);
 482
 483                 break;
 484             }
 485             case PA_LOG_DLOG_COLOR: {
 486                                 char *local_t;
 487
 488                                 openlog(ident, LOG_PID, LOG_USER);
 489
 490                                 if ((local_t = pa_utf8_to_locale(t)))
 491                                         t = local_t;
 492
 493                                 switch (level)
 494                                 {
 495                                         case PA_LOG_DEBUG:
 496                                                 SLOG (LOG_DEBUG, DLOG_TAG, "\033[%dm%s%s%s%s\033[0m", COLOR_GREEN, timestamp, location, t, pa_strempty(bt));
 497                                                 break;
 498                                         case PA_LOG_INFO:
 499                                         case PA_LOG_NOTICE:     // no notice category in dlog, use info instead.
 500                                                 SLOG (LOG_INFO, DLOG_TAG, "\033[%dm%s%s%s%s\033[0m", COLOR_BLUE, timestamp, location, t, pa_strempty(bt));
 501                                                 break;
 502                                         case PA_LOG_WARN:
 503                                                 SLOG (LOG_WARN, DLOG_TAG, "\033[%dm%s%s%s%s\033[0m", COLOR_MAGENTA, timestamp, location, t, pa_strempty(bt));
 504                                                 break;
 505                                         case PA_LOG_ERROR:
 506                                                 SLOG (LOG_ERROR, DLOG_TAG, "\033[%dm%s%s%s%s\033[0m", COLOR_RED, timestamp, location, t, pa_strempty(bt));
 507                                                 break;
 508                                         default:
 509                                                 SLOG (LOG_DEBUG, DLOG_TAG, "%s%s%s%s", timestamp, location, t, pa_strempty(bt));
 510                                                 break;
 511                                 }
 512
 513                                 pa_xfree(local_t);
 514
 515                                 break;
 516                         }
 517
 518 #endif
 519             case PA_LOG_NULL:
 520             default:
 521                 break;
 522         }
 523     }
 524
 525     pa_xfree(bt);
 526     errno = saved_errno;
 527 }
 528
 529 void pa_log_level_meta(
 530         pa_log_level_t level,
 531         const char*file,
 532         int line,
 533         const char *func,
 534         const char *format, ...) {
 535
 536     va_list ap;
 537     va_start(ap, format);
 538     pa_log_levelv_meta(level, file, line, func, format, ap);
 539     va_end(ap);
 540 }
 541
 542 void pa_log_levelv(pa_log_level_t level, const char *format, va_list ap) {
 543     pa_log_levelv_meta(level, NULL, 0, NULL, format, ap);
 544 }
 545
 546 void pa_log_level(pa_log_level_t level, const char *format, ...) {
 547     va_list ap;
 548
 549     va_start(ap, format);
 550     pa_log_levelv_meta(level, NULL, 0, NULL, format, ap);
 551     va_end(ap);
 552 }
 553
 554 pa_bool_t pa_log_ratelimit(pa_log_level_t level) {
 555     /* Not more than 10 messages every 5s */
 556     static PA_DEFINE_RATELIMIT(ratelimit, 5 * PA_USEC_PER_SEC, 10);
 557
 558     init_defaults();
 559
 560     if (no_rate_limit)
 561         return TRUE;
 562
 563     return pa_ratelimit_test(&ratelimit, level);
 564 }