code.delx.au - pulseaudio/blob - 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 #include <fcntl.h>
  33
  34 #ifdef HAVE_EXECINFO_H
  35 #include <execinfo.h>
  36 #endif
  37
  38 #ifdef HAVE_SYSLOG_H
  39 #include <syslog.h>
  40 #endif
  41
  42 #include <pulse/gccmacro.h>
  43 #include <pulse/rtclock.h>
  44 #include <pulse/utf8.h>
  45 #include <pulse/xmalloc.h>
  46 #include <pulse/util.h>
  47 #include <pulse/timeval.h>
  48
  49 #include <pulsecore/macro.h>
  50 #include <pulsecore/core-util.h>
  51 #include <pulsecore/core-error.h>
  52 #include <pulsecore/once.h>
  53 #include <pulsecore/ratelimit.h>
  54 #include <pulsecore/thread.h>
  55 #include <pulsecore/i18n.h>
  56
  57 #include "log.h"
  58
  59 #define ENV_LOG_SYSLOG "PULSE_LOG_SYSLOG"
  60 #define ENV_LOG_LEVEL "PULSE_LOG"
  61 #define ENV_LOG_COLORS "PULSE_LOG_COLORS"
  62 #define ENV_LOG_PRINT_TIME "PULSE_LOG_TIME"
  63 #define ENV_LOG_PRINT_FILE "PULSE_LOG_FILE"
  64 #define ENV_LOG_PRINT_META "PULSE_LOG_META"
  65 #define ENV_LOG_PRINT_LEVEL "PULSE_LOG_LEVEL"
  66 #define ENV_LOG_BACKTRACE "PULSE_LOG_BACKTRACE"
  67 #define ENV_LOG_BACKTRACE_SKIP "PULSE_LOG_BACKTRACE_SKIP"
  68 #define ENV_LOG_NO_RATELIMIT "PULSE_LOG_NO_RATE_LIMIT"
  69 #define LOG_MAX_SUFFIX_NUMBER 99
  70
  71 static char *ident = NULL; /* in local charset format */
  72 static pa_log_target target = { PA_LOG_STDERR, NULL };
  73 static pa_log_target_type_t target_override;
  74 static pa_bool_t target_override_set = FALSE;
  75 static pa_log_level_t maximum_level = PA_LOG_ERROR, maximum_level_override = PA_LOG_ERROR;
  76 static unsigned show_backtrace = 0, show_backtrace_override = 0, skip_backtrace = 0;
  77 static pa_log_flags_t flags = 0, flags_override = 0;
  78 static pa_bool_t no_rate_limit = FALSE;
  79 static int log_fd = -1;
  80
  81 #ifdef HAVE_SYSLOG_H
  82 static const int level_to_syslog[] = {
  83     [PA_LOG_ERROR] = LOG_ERR,
  84     [PA_LOG_WARN] = LOG_WARNING,
  85     [PA_LOG_NOTICE] = LOG_NOTICE,
  86     [PA_LOG_INFO] = LOG_INFO,
  87     [PA_LOG_DEBUG] = LOG_DEBUG
  88 };
  89 #endif
  90
  91 static const char level_to_char[] = {
  92     [PA_LOG_ERROR] = 'E',
  93     [PA_LOG_WARN] = 'W',
  94     [PA_LOG_NOTICE] = 'N',
  95     [PA_LOG_INFO] = 'I',
  96     [PA_LOG_DEBUG] = 'D'
  97 };
  98
  99 void pa_log_set_ident(const char *p) {
 100     pa_xfree(ident);
 101
 102     if (!(ident = pa_utf8_to_locale(p)))
 103         ident = pa_ascii_filter(p);
 104 }
 105
 106 /* To make valgrind shut up. */
 107 static void ident_destructor(void) PA_GCC_DESTRUCTOR;
 108 static void ident_destructor(void) {
 109     if (!pa_in_valgrind())
 110         return;
 111
 112     pa_xfree(ident);
 113 }
 114
 115 void pa_log_set_level(pa_log_level_t l) {
 116     pa_assert(l < PA_LOG_LEVEL_MAX);
 117
 118     maximum_level = l;
 119 }
 120
 121 int pa_log_set_target(pa_log_target *t) {
 122     int fd = -1;
 123     int old_fd;
 124
 125     pa_assert(t);
 126
 127     switch (t->type) {
 128         case PA_LOG_STDERR:
 129         case PA_LOG_SYSLOG:
 130         case PA_LOG_NULL:
 131             break;
 132         case PA_LOG_FILE:
 133             if ((fd = pa_open_cloexec(t->file, O_WRONLY | O_TRUNC | O_CREAT, S_IRUSR | S_IWUSR)) < 0) {
 134                 pa_log(_("Failed to open target file '%s'."), t->file);
 135                 return -1;
 136             }
 137             break;
 138         case PA_LOG_NEWFILE: {
 139             char *file_path;
 140             char *p;
 141             unsigned version;
 142
 143             file_path = pa_sprintf_malloc("%s.xx", t->file);
 144             p = file_path + strlen(t->file);
 145
 146             for (version = 0; version <= LOG_MAX_SUFFIX_NUMBER; version++) {
 147                 memset(p, 0, 3); /* Overwrite the ".xx" part in file_path with zero bytes. */
 148
 149                 if (version > 0)
 150                     pa_snprintf(p, 4, ".%u", version); /* Why 4? ".xx" + termitating zero byte. */
 151
 152                 if ((fd = pa_open_cloexec(file_path, O_WRONLY | O_TRUNC | O_CREAT | O_EXCL, S_IRUSR | S_IWUSR)) >= 0)
 153                     break;
 154             }
 155
 156             if (version > LOG_MAX_SUFFIX_NUMBER) {
 157                 pa_log(_("Tried to open target file '%s', '%s.1', '%s.2' ... '%s.%d', but all failed."),
 158                         file_path, file_path, file_path, file_path, LOG_MAX_SUFFIX_NUMBER);
 159                 pa_xfree(file_path);
 160                 return -1;
 161             } else
 162                 pa_log_debug("Opened target file %s\n", file_path);
 163
 164             pa_xfree(file_path);
 165             break;
 166         }
 167     }
 168
 169     target.type = t->type;
 170     pa_xfree(target.file);
 171     target.file = pa_xstrdup(t->file);
 172
 173     old_fd = log_fd;
 174     log_fd = fd;
 175
 176     if (old_fd >= 0)
 177         pa_close(old_fd);
 178
 179     return 0;
 180 }
 181
 182 void pa_log_set_flags(pa_log_flags_t _flags, pa_log_merge_t merge) {
 183     pa_assert(!(_flags & ~(PA_LOG_COLORS|PA_LOG_PRINT_TIME|PA_LOG_PRINT_FILE|PA_LOG_PRINT_META|PA_LOG_PRINT_LEVEL)));
 184
 185     if (merge == PA_LOG_SET)
 186         flags |= _flags;
 187     else if (merge == PA_LOG_UNSET)
 188         flags &= ~_flags;
 189     else
 190         flags = _flags;
 191 }
 192
 193 void pa_log_set_fd(int fd) {
 194     if (fd >= 0)
 195         log_fd = fd;
 196     else if (log_fd >= 0) {
 197         pa_close(log_fd);
 198         log_fd = -1;
 199     }
 200 }
 201
 202 void pa_log_set_show_backtrace(unsigned nlevels) {
 203     show_backtrace = nlevels;
 204 }
 205
 206 void pa_log_set_skip_backtrace(unsigned nlevels) {
 207     skip_backtrace = nlevels;
 208 }
 209
 210 #ifdef HAVE_EXECINFO_H
 211
 212 static char* get_backtrace(unsigned show_nframes) {
 213     void* trace[32];
 214     int n_frames;
 215     char **symbols, *e, *r;
 216     unsigned j, n, s;
 217     size_t a;
 218
 219     pa_assert(show_nframes > 0);
 220
 221     n_frames = backtrace(trace, PA_ELEMENTSOF(trace));
 222
 223     if (n_frames <= 0)
 224         return NULL;
 225
 226     symbols = backtrace_symbols(trace, n_frames);
 227
 228     if (!symbols)
 229         return NULL;
 230
 231     s = skip_backtrace;
 232     n = PA_MIN((unsigned) n_frames, s + show_nframes);
 233
 234     a = 4;
 235
 236     for (j = s; j < n; j++) {
 237         if (j > s)
 238             a += 2;
 239         a += strlen(pa_path_get_filename(symbols[j]));
 240     }
 241
 242     r = pa_xnew(char, a);
 243
 244     strcpy(r, " (");
 245     e = r + 2;
 246
 247     for (j = s; j < n; j++) {
 248         const char *sym;
 249
 250         if (j > s) {
 251             strcpy(e, "<<");
 252             e += 2;
 253         }
 254
 255         sym = pa_path_get_filename(symbols[j]);
 256
 257         strcpy(e, sym);
 258         e += strlen(sym);
 259     }
 260
 261     strcpy(e, ")");
 262
 263     free(symbols);
 264
 265     return r;
 266 }
 267
 268 #endif
 269
 270 static void init_defaults(void) {
 271     PA_ONCE_BEGIN {
 272
 273         const char *e;
 274
 275         if (!ident) {
 276             char binary[256];
 277             if (pa_get_binary_name(binary, sizeof(binary)))
 278                 pa_log_set_ident(binary);
 279         }
 280
 281         if (getenv(ENV_LOG_SYSLOG)) {
 282             target_override = PA_LOG_SYSLOG;
 283             target_override_set = TRUE;
 284         }
 285
 286         if ((e = getenv(ENV_LOG_LEVEL))) {
 287             maximum_level_override = (pa_log_level_t) atoi(e);
 288
 289             if (maximum_level_override >= PA_LOG_LEVEL_MAX)
 290                 maximum_level_override = PA_LOG_LEVEL_MAX-1;
 291         }
 292
 293         if (getenv(ENV_LOG_COLORS))
 294             flags_override |= PA_LOG_COLORS;
 295
 296         if (getenv(ENV_LOG_PRINT_TIME))
 297             flags_override |= PA_LOG_PRINT_TIME;
 298
 299         if (getenv(ENV_LOG_PRINT_FILE))
 300             flags_override |= PA_LOG_PRINT_FILE;
 301
 302         if (getenv(ENV_LOG_PRINT_META))
 303             flags_override |= PA_LOG_PRINT_META;
 304
 305         if (getenv(ENV_LOG_PRINT_LEVEL))
 306             flags_override |= PA_LOG_PRINT_LEVEL;
 307
 308         if ((e = getenv(ENV_LOG_BACKTRACE))) {
 309             show_backtrace_override = (unsigned) atoi(e);
 310
 311             if (show_backtrace_override <= 0)
 312                 show_backtrace_override = 0;
 313         }
 314
 315         if ((e = getenv(ENV_LOG_BACKTRACE_SKIP))) {
 316             skip_backtrace = (unsigned) atoi(e);
 317
 318             if (skip_backtrace <= 0)
 319                 skip_backtrace = 0;
 320         }
 321
 322         if (getenv(ENV_LOG_NO_RATELIMIT))
 323             no_rate_limit = TRUE;
 324
 325     } PA_ONCE_END;
 326 }
 327
 328 void pa_log_levelv_meta(
 329         pa_log_level_t level,
 330         const char*file,
 331         int line,
 332         const char *func,
 333         const char *format,
 334         va_list ap) {
 335
 336     char *t, *n;
 337     int saved_errno = errno;
 338     char *bt = NULL;
 339     pa_log_target_type_t _target;
 340     pa_log_level_t _maximum_level;
 341     unsigned _show_backtrace;
 342     pa_log_flags_t _flags;
 343
 344     /* We don't use dynamic memory allocation here to minimize the hit
 345      * in RT threads */
 346     char text[16*1024], location[128], timestamp[32];
 347
 348     pa_assert(level < PA_LOG_LEVEL_MAX);
 349     pa_assert(format);
 350
 351     init_defaults();
 352
 353     _target = target_override_set ? target_override : target.type;
 354     _maximum_level = PA_MAX(maximum_level, maximum_level_override);
 355     _show_backtrace = PA_MAX(show_backtrace, show_backtrace_override);
 356     _flags = flags | flags_override;
 357
 358     if (PA_LIKELY(level > _maximum_level)) {
 359         errno = saved_errno;
 360         return;
 361     }
 362
 363     pa_vsnprintf(text, sizeof(text), format, ap);
 364
 365     if ((_flags & PA_LOG_PRINT_META) && file && line > 0 && func)
 366         pa_snprintf(location, sizeof(location), "[%s][%s:%i %s()] ", pa_thread_get_name(pa_thread_self()), file, line, func);
 367     else if ((_flags & (PA_LOG_PRINT_META|PA_LOG_PRINT_FILE)) && file)
 368         pa_snprintf(location, sizeof(location), "[%s] %s: ", pa_thread_get_name(pa_thread_self()), pa_path_get_filename(file));
 369     else
 370         location[0] = 0;
 371
 372     if (_flags & PA_LOG_PRINT_TIME) {
 373         static pa_usec_t start, last;
 374         pa_usec_t u, a, r;
 375
 376         u = pa_rtclock_now();
 377
 378         PA_ONCE_BEGIN {
 379             start = u;
 380             last = u;
 381         } PA_ONCE_END;
 382
 383         r = u - last;
 384         a = u - start;
 385
 386         /* This is not thread safe, but this is a debugging tool only
 387          * anyway. */
 388         last = u;
 389
 390         pa_snprintf(timestamp, sizeof(timestamp), "(%4llu.%03llu|%4llu.%03llu) ",
 391                     (unsigned long long) (a / PA_USEC_PER_SEC),
 392                     (unsigned long long) (((a / PA_USEC_PER_MSEC)) % 1000),
 393                     (unsigned long long) (r / PA_USEC_PER_SEC),
 394                     (unsigned long long) (((r / PA_USEC_PER_MSEC)) % 1000));
 395
 396     } else
 397         timestamp[0] = 0;
 398
 399 #ifdef HAVE_EXECINFO_H
 400     if (_show_backtrace > 0)
 401         bt = get_backtrace(_show_backtrace);
 402 #endif
 403
 404     if (!pa_utf8_valid(text))
 405         pa_logl(level, "Invalid UTF-8 string following below:");
 406
 407     for (t = text; t; t = n) {
 408         if ((n = strchr(t, '\n'))) {
 409             *n = 0;
 410             n++;
 411         }
 412
 413         /* We ignore strings only made out of whitespace */
 414         if (t[strspn(t, "\t ")] == 0)
 415             continue;
 416
 417         switch (_target) {
 418
 419             case PA_LOG_STDERR: {
 420                 const char *prefix = "", *suffix = "", *grey = "";
 421                 char *local_t;
 422
 423 #ifndef OS_IS_WIN32
 424                 /* Yes indeed. Useless, but fun! */
 425                 if ((_flags & PA_LOG_COLORS) && isatty(STDERR_FILENO)) {
 426                     if (level <= PA_LOG_ERROR)
 427                         prefix = "\x1B[1;31m";
 428                     else if (level <= PA_LOG_WARN)
 429                         prefix = "\x1B[1m";
 430
 431                     if (bt)
 432                         grey = "\x1B[2m";
 433
 434                     if (grey[0] || prefix[0])
 435                         suffix = "\x1B[0m";
 436                 }
 437 #endif
 438
 439                 /* We shouldn't be using dynamic allocation here to
 440                  * minimize the hit in RT threads */
 441                 if ((local_t = pa_utf8_to_locale(t)))
 442                     t = local_t;
 443
 444                 if (_flags & PA_LOG_PRINT_LEVEL)
 445                     fprintf(stderr, "%s%c: %s%s%s%s%s%s\n", timestamp, level_to_char[level], location, prefix, t, grey, pa_strempty(bt), suffix);
 446                 else
 447                     fprintf(stderr, "%s%s%s%s%s%s%s\n", timestamp, location, prefix, t, grey, pa_strempty(bt), suffix);
 448 #ifdef OS_IS_WIN32
 449                 fflush(stderr);
 450 #endif
 451
 452                 pa_xfree(local_t);
 453
 454                 break;
 455             }
 456
 457 #ifdef HAVE_SYSLOG_H
 458             case PA_LOG_SYSLOG: {
 459                 char *local_t;
 460
 461                 openlog(ident, LOG_PID, LOG_USER);
 462
 463                 if ((local_t = pa_utf8_to_locale(t)))
 464                     t = local_t;
 465
 466                 syslog(level_to_syslog[level], "%s%s%s%s", timestamp, location, t, pa_strempty(bt));
 467                 pa_xfree(local_t);
 468
 469                 break;
 470             }
 471 #endif
 472
 473             case PA_LOG_FILE:
 474             case PA_LOG_NEWFILE: {
 475                 if (log_fd >= 0) {
 476                     char metadata[256];
 477
 478                     pa_snprintf(metadata, sizeof(metadata), "\n%c %s %s", level_to_char[level], timestamp, location);
 479
 480                     if ((write(log_fd, metadata, strlen(metadata)) < 0) || (write(log_fd, t, strlen(t)) < 0)) {
 481                         pa_log_target new_target = { .type = PA_LOG_STDERR, .file = NULL };
 482                         saved_errno = errno;
 483                         pa_log_set_fd(-1);
 484                         fprintf(stderr, "%s\n", "Error writing logs to a file descriptor. Redirect log messages to console.");
 485                         fprintf(stderr, "%s %s\n", metadata, t);
 486                         pa_log_set_target(&new_target);
 487                     }
 488                 }
 489
 490                 break;
 491             }
 492             case PA_LOG_NULL:
 493             default:
 494                 break;
 495         }
 496     }
 497
 498     pa_xfree(bt);
 499     errno = saved_errno;
 500 }
 501
 502 void pa_log_level_meta(
 503         pa_log_level_t level,
 504         const char*file,
 505         int line,
 506         const char *func,
 507         const char *format, ...) {
 508
 509     va_list ap;
 510     va_start(ap, format);
 511     pa_log_levelv_meta(level, file, line, func, format, ap);
 512     va_end(ap);
 513 }
 514
 515 void pa_log_levelv(pa_log_level_t level, const char *format, va_list ap) {
 516     pa_log_levelv_meta(level, NULL, 0, NULL, format, ap);
 517 }
 518
 519 void pa_log_level(pa_log_level_t level, const char *format, ...) {
 520     va_list ap;
 521
 522     va_start(ap, format);
 523     pa_log_levelv_meta(level, NULL, 0, NULL, format, ap);
 524     va_end(ap);
 525 }
 526
 527 pa_bool_t pa_log_ratelimit(pa_log_level_t level) {
 528     /* Not more than 10 messages every 5s */
 529     static PA_DEFINE_RATELIMIT(ratelimit, 5 * PA_USEC_PER_SEC, 10);
 530
 531     init_defaults();
 532
 533     if (no_rate_limit)
 534         return TRUE;
 535
 536     return pa_ratelimit_test(&ratelimit, level);
 537 }
 538
 539 pa_log_target *pa_log_target_new(pa_log_target_type_t type, const char *file) {
 540     pa_log_target *t = NULL;
 541
 542     t = pa_xnew(pa_log_target, 1);
 543
 544     t->type = type;
 545     t->file = pa_xstrdup(file);
 546
 547     return t;
 548 }
 549
 550 void pa_log_target_free(pa_log_target *t) {
 551     pa_assert(t);
 552
 553     pa_xfree(t->file);
 554     pa_xfree(t);
 555 }
 556
 557 pa_log_target *pa_log_parse_target(const char *string) {
 558     pa_log_target *t = NULL;
 559
 560     pa_assert(string);
 561
 562     if (pa_streq(string, "stderr"))
 563         t = pa_log_target_new(PA_LOG_STDERR, NULL);
 564     else if (pa_streq(string, "syslog"))
 565         t = pa_log_target_new(PA_LOG_SYSLOG, NULL);
 566     else if (pa_streq(string, "null"))
 567         t = pa_log_target_new(PA_LOG_NULL, NULL);
 568     else if (pa_startswith(string, "file:"))
 569         t = pa_log_target_new(PA_LOG_FILE, string + 5);
 570     else if (pa_startswith(string, "newfile:"))
 571         t = pa_log_target_new(PA_LOG_NEWFILE, string + 8);
 572     else
 573         pa_log(_("Invalid log target."));
 574
 575     return t;
 576 }
 577
 578 char *pa_log_target_to_string(const pa_log_target *t) {
 579     char *string = NULL;
 580
 581     pa_assert(t);
 582
 583     switch (t->type) {
 584         case PA_LOG_STDERR:
 585             string = pa_xstrdup("stderr");
 586             break;
 587         case PA_LOG_SYSLOG:
 588             string = pa_xstrdup("syslog");
 589             break;
 590         case PA_LOG_NULL:
 591             string = pa_xstrdup("null");
 592             break;
 593         case PA_LOG_FILE:
 594             string = pa_sprintf_malloc("file:%s", t->file);
 595             break;
 596         case PA_LOG_NEWFILE:
 597             string = pa_sprintf_malloc("newfile:%s", t->file);
 598             break;
 599     }
 600
 601     return string;
 602 }