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