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