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 bool 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 bool 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                         t->file, t->file, t->file, t->file, 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()] ",
 367                     pa_strnull(pa_thread_get_name(pa_thread_self())), file, line, func);
 368     else if ((_flags & (PA_LOG_PRINT_META|PA_LOG_PRINT_FILE)) && file)
 369         pa_snprintf(location, sizeof(location), "[%s] %s: ",
 370                     pa_strnull(pa_thread_get_name(pa_thread_self())), pa_path_get_filename(file));
 371     else
 372         location[0] = 0;
 373
 374     if (_flags & PA_LOG_PRINT_TIME) {
 375         static pa_usec_t start, last;
 376         pa_usec_t u, a, r;
 377
 378         u = pa_rtclock_now();
 379
 380         PA_ONCE_BEGIN {
 381             start = u;
 382             last = u;
 383         } PA_ONCE_END;
 384
 385         r = u - last;
 386         a = u - start;
 387
 388         /* This is not thread safe, but this is a debugging tool only
 389          * anyway. */
 390         last = u;
 391
 392         pa_snprintf(timestamp, sizeof(timestamp), "(%4llu.%03llu|%4llu.%03llu) ",
 393                     (unsigned long long) (a / PA_USEC_PER_SEC),
 394                     (unsigned long long) (((a / PA_USEC_PER_MSEC)) % 1000),
 395                     (unsigned long long) (r / PA_USEC_PER_SEC),
 396                     (unsigned long long) (((r / PA_USEC_PER_MSEC)) % 1000));
 397
 398     } else
 399         timestamp[0] = 0;
 400
 401 #ifdef HAVE_EXECINFO_H
 402     if (_show_backtrace > 0)
 403         bt = get_backtrace(_show_backtrace);
 404 #endif
 405
 406     if (!pa_utf8_valid(text))
 407         pa_logl(level, "Invalid UTF-8 string following below:");
 408
 409     for (t = text; t; t = n) {
 410         if ((n = strchr(t, '\n'))) {
 411             *n = 0;
 412             n++;
 413         }
 414
 415         /* We ignore strings only made out of whitespace */
 416         if (t[strspn(t, "\t ")] == 0)
 417             continue;
 418
 419         switch (_target) {
 420
 421             case PA_LOG_STDERR: {
 422                 const char *prefix = "", *suffix = "", *grey = "";
 423                 char *local_t;
 424
 425 #ifndef OS_IS_WIN32
 426                 /* Yes indeed. Useless, but fun! */
 427                 if ((_flags & PA_LOG_COLORS) && isatty(STDERR_FILENO)) {
 428                     if (level <= PA_LOG_ERROR)
 429                         prefix = "\x1B[1;31m";
 430                     else if (level <= PA_LOG_WARN)
 431                         prefix = "\x1B[1m";
 432
 433                     if (bt)
 434                         grey = "\x1B[2m";
 435
 436                     if (grey[0] || prefix[0])
 437                         suffix = "\x1B[0m";
 438                 }
 439 #endif
 440
 441                 /* We shouldn't be using dynamic allocation here to
 442                  * minimize the hit in RT threads */
 443                 if ((local_t = pa_utf8_to_locale(t)))
 444                     t = local_t;
 445
 446                 if (_flags & PA_LOG_PRINT_LEVEL)
 447                     fprintf(stderr, "%s%c: %s%s%s%s%s%s\n", timestamp, level_to_char[level], location, prefix, t, grey, pa_strempty(bt), suffix);
 448                 else
 449                     fprintf(stderr, "%s%s%s%s%s%s%s\n", timestamp, location, prefix, t, grey, pa_strempty(bt), suffix);
 450 #ifdef OS_IS_WIN32
 451                 fflush(stderr);
 452 #endif
 453
 454                 pa_xfree(local_t);
 455
 456                 break;
 457             }
 458
 459 #ifdef HAVE_SYSLOG_H
 460             case PA_LOG_SYSLOG: {
 461                 char *local_t;
 462
 463                 openlog(ident, LOG_PID, LOG_USER);
 464
 465                 if ((local_t = pa_utf8_to_locale(t)))
 466                     t = local_t;
 467
 468                 syslog(level_to_syslog[level], "%s%s%s%s", timestamp, location, t, pa_strempty(bt));
 469                 pa_xfree(local_t);
 470
 471                 break;
 472             }
 473 #endif
 474
 475             case PA_LOG_FILE:
 476             case PA_LOG_NEWFILE: {
 477                 if (log_fd >= 0) {
 478                     char metadata[256];
 479
 480                     pa_snprintf(metadata, sizeof(metadata), "\n%c %s %s", level_to_char[level], timestamp, location);
 481
 482                     if ((write(log_fd, metadata, strlen(metadata)) < 0) || (write(log_fd, t, strlen(t)) < 0)) {
 483                         pa_log_target new_target = { .type = PA_LOG_STDERR, .file = NULL };
 484                         saved_errno = errno;
 485                         pa_log_set_fd(-1);
 486                         fprintf(stderr, "%s\n", "Error writing logs to a file descriptor. Redirect log messages to console.");
 487                         fprintf(stderr, "%s %s\n", metadata, t);
 488                         pa_log_set_target(&new_target);
 489                     }
 490                 }
 491
 492                 break;
 493             }
 494             case PA_LOG_NULL:
 495             default:
 496                 break;
 497         }
 498     }
 499
 500     pa_xfree(bt);
 501     errno = saved_errno;
 502 }
 503
 504 void pa_log_level_meta(
 505         pa_log_level_t level,
 506         const char*file,
 507         int line,
 508         const char *func,
 509         const char *format, ...) {
 510
 511     va_list ap;
 512     va_start(ap, format);
 513     pa_log_levelv_meta(level, file, line, func, format, ap);
 514     va_end(ap);
 515 }
 516
 517 void pa_log_levelv(pa_log_level_t level, const char *format, va_list ap) {
 518     pa_log_levelv_meta(level, NULL, 0, NULL, format, ap);
 519 }
 520
 521 void pa_log_level(pa_log_level_t level, const char *format, ...) {
 522     va_list ap;
 523
 524     va_start(ap, format);
 525     pa_log_levelv_meta(level, NULL, 0, NULL, format, ap);
 526     va_end(ap);
 527 }
 528
 529 bool pa_log_ratelimit(pa_log_level_t level) {
 530     /* Not more than 10 messages every 5s */
 531     static PA_DEFINE_RATELIMIT(ratelimit, 5 * PA_USEC_PER_SEC, 10);
 532
 533     init_defaults();
 534
 535     if (no_rate_limit)
 536         return true;
 537
 538     return pa_ratelimit_test(&ratelimit, level);
 539 }
 540
 541 pa_log_target *pa_log_target_new(pa_log_target_type_t type, const char *file) {
 542     pa_log_target *t = NULL;
 543
 544     t = pa_xnew(pa_log_target, 1);
 545
 546     t->type = type;
 547     t->file = pa_xstrdup(file);
 548
 549     return t;
 550 }
 551
 552 void pa_log_target_free(pa_log_target *t) {
 553     pa_assert(t);
 554
 555     pa_xfree(t->file);
 556     pa_xfree(t);
 557 }
 558
 559 pa_log_target *pa_log_parse_target(const char *string) {
 560     pa_log_target *t = NULL;
 561
 562     pa_assert(string);
 563
 564     if (pa_streq(string, "stderr"))
 565         t = pa_log_target_new(PA_LOG_STDERR, NULL);
 566     else if (pa_streq(string, "syslog"))
 567         t = pa_log_target_new(PA_LOG_SYSLOG, NULL);
 568     else if (pa_streq(string, "null"))
 569         t = pa_log_target_new(PA_LOG_NULL, NULL);
 570     else if (pa_startswith(string, "file:"))
 571         t = pa_log_target_new(PA_LOG_FILE, string + 5);
 572     else if (pa_startswith(string, "newfile:"))
 573         t = pa_log_target_new(PA_LOG_NEWFILE, string + 8);
 574     else
 575         pa_log(_("Invalid log target."));
 576
 577     return t;
 578 }
 579
 580 char *pa_log_target_to_string(const pa_log_target *t) {
 581     char *string = NULL;
 582
 583     pa_assert(t);
 584
 585     switch (t->type) {
 586         case PA_LOG_STDERR:
 587             string = pa_xstrdup("stderr");
 588             break;
 589         case PA_LOG_SYSLOG:
 590             string = pa_xstrdup("syslog");
 591             break;
 592         case PA_LOG_NULL:
 593             string = pa_xstrdup("null");
 594             break;
 595         case PA_LOG_FILE:
 596             string = pa_sprintf_malloc("file:%s", t->file);
 597             break;
 598         case PA_LOG_NEWFILE:
 599             string = pa_sprintf_malloc("newfile:%s", t->file);
 600             break;
 601     }
 602
 603     return string;
 604 }