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