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