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