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