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