diff options
Diffstat (limited to 'src/pulsecore/log.c')
| -rw-r--r-- | src/pulsecore/log.c | 685 |
1 files changed, 685 insertions, 0 deletions
diff --git a/src/pulsecore/log.c b/src/pulsecore/log.c new file mode 100644 index 0000000..2ea8862 --- /dev/null +++ b/src/pulsecore/log.c @@ -0,0 +1,685 @@ +/*** + This file is part of PulseAudio. + + Copyright 2004-2006 Lennart Poettering + Copyright 2006 Pierre Ossman <ossman@cendio.se> for Cendio AB + + PulseAudio is free software; you can redistribute it and/or modify + it under the terms of the GNU Lesser General Public License as + published by the Free Software Foundation; either version 2.1 of the + License, or (at your option) any later version. + + PulseAudio is distributed in the hope that it will be useful, but + WITHOUT ANY WARRANTY; without even the implied warranty of + MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU + General Public License for more details. + + You should have received a copy of the GNU Lesser General Public + License along with PulseAudio; if not, see <http://www.gnu.org/licenses/>. +***/ + +#ifdef HAVE_CONFIG_H +#include <config.h> +#endif + +#include <stdarg.h> +#include <stdio.h> +#include <unistd.h> +#include <string.h> +#include <errno.h> +#include <fcntl.h> +#include <sys/stat.h> + +#ifdef HAVE_EXECINFO_H +#include <execinfo.h> +#endif + +#ifdef HAVE_SYSLOG_H +#include <syslog.h> +#endif + +#ifdef HAVE_SYSTEMD_JOURNAL + +/* sd_journal_send() implicitly add fields for the source file, + * function name and code line from where it's invoked. As the + * correct code location fields CODE_FILE, CODE_LINE and + * CODE_FUNC are already handled by this module, we do not want + * the automatic values supplied by the systemd journal API. + * + * Without suppressing these, both the actual log event source + * and the call to sd_journal_send() will be logged. */ +#define SD_JOURNAL_SUPPRESS_LOCATION + +#include <systemd/sd-journal.h> +#endif + +#include <pulse/gccmacro.h> +#include <pulse/rtclock.h> +#include <pulse/utf8.h> +#include <pulse/xmalloc.h> +#include <pulse/util.h> +#include <pulse/timeval.h> + +#include <pulsecore/macro.h> +#include <pulsecore/core-util.h> +#include <pulsecore/core-error.h> +#include <pulsecore/once.h> +#include <pulsecore/ratelimit.h> +#include <pulsecore/thread.h> +#include <pulsecore/i18n.h> + +#include "log.h" + +#define ENV_LOG_SYSLOG "PULSE_LOG_SYSLOG" +#define ENV_LOG_JOURNAL "PULSE_LOG_JOURNAL" +#define ENV_LOG_LEVEL "PULSE_LOG" +#define ENV_LOG_COLORS "PULSE_LOG_COLORS" +#define ENV_LOG_PRINT_TIME "PULSE_LOG_TIME" +#define ENV_LOG_PRINT_FILE "PULSE_LOG_FILE" +#define ENV_LOG_PRINT_META "PULSE_LOG_META" +#define ENV_LOG_PRINT_LEVEL "PULSE_LOG_LEVEL" +#define ENV_LOG_BACKTRACE "PULSE_LOG_BACKTRACE" +#define ENV_LOG_BACKTRACE_SKIP "PULSE_LOG_BACKTRACE_SKIP" +#define ENV_LOG_NO_RATELIMIT "PULSE_LOG_NO_RATE_LIMIT" +#define LOG_MAX_SUFFIX_NUMBER 99 + +static char *ident = NULL; /* in local charset format */ +static pa_log_target target = { PA_LOG_STDERR, NULL }; +static pa_log_target_type_t target_override; +static bool target_override_set = false; +static pa_log_level_t maximum_level = PA_LOG_ERROR, maximum_level_override = PA_LOG_ERROR; +static unsigned show_backtrace = 0, show_backtrace_override = 0, skip_backtrace = 0; +static pa_log_flags_t flags = 0, flags_override = 0; +static bool no_rate_limit = false; +static int log_fd = -1; +static int write_type = 0; + +#ifdef HAVE_SYSLOG_H +static const int level_to_syslog[] = { + [PA_LOG_ERROR] = LOG_ERR, + [PA_LOG_WARN] = LOG_WARNING, + [PA_LOG_NOTICE] = LOG_NOTICE, + [PA_LOG_INFO] = LOG_INFO, + [PA_LOG_DEBUG] = LOG_DEBUG +}; +#endif + +/* These are actually equivalent to the syslog ones + * but we don't want to depend on syslog.h */ +#ifdef HAVE_SYSTEMD_JOURNAL +static const int level_to_journal[] = { + [PA_LOG_ERROR] = 3, + [PA_LOG_WARN] = 4, + [PA_LOG_NOTICE] = 5, + [PA_LOG_INFO] = 6, + [PA_LOG_DEBUG] = 7 +}; +#endif + +static const char level_to_char[] = { + [PA_LOG_ERROR] = 'E', + [PA_LOG_WARN] = 'W', + [PA_LOG_NOTICE] = 'N', + [PA_LOG_INFO] = 'I', + [PA_LOG_DEBUG] = 'D' +}; + +void pa_log_set_ident(const char *p) { + pa_xfree(ident); + + if (!(ident = pa_utf8_to_locale(p))) + ident = pa_ascii_filter(p); +} + +/* To make valgrind shut up. */ +static void ident_destructor(void) PA_GCC_DESTRUCTOR; +static void ident_destructor(void) { + if (!pa_in_valgrind()) + return; + + pa_xfree(ident); +} + +void pa_log_set_level(pa_log_level_t l) { + pa_assert(l < PA_LOG_LEVEL_MAX); + + maximum_level = l; +} + +int pa_log_set_target(pa_log_target *t) { + int fd = -1; + int old_fd; + + pa_assert(t); + + switch (t->type) { + case PA_LOG_STDERR: + case PA_LOG_SYSLOG: +#ifdef HAVE_SYSTEMD_JOURNAL + case PA_LOG_JOURNAL: +#endif + case PA_LOG_NULL: + break; + case PA_LOG_FILE: + if ((fd = pa_open_cloexec(t->file, O_WRONLY | O_TRUNC | O_CREAT, S_IRUSR | S_IWUSR)) < 0) { + pa_log(_("Failed to open target file '%s'."), t->file); + return -1; + } + break; + case PA_LOG_NEWFILE: { + char *file_path; + char *p; + unsigned version; + + file_path = pa_sprintf_malloc("%s.xx", t->file); + p = file_path + strlen(t->file); + + for (version = 0; version <= LOG_MAX_SUFFIX_NUMBER; version++) { + memset(p, 0, 3); /* Overwrite the ".xx" part in file_path with zero bytes. */ + + if (version > 0) + pa_snprintf(p, 4, ".%u", version); /* Why 4? ".xx" + termitating zero byte. */ + + if ((fd = pa_open_cloexec(file_path, O_WRONLY | O_TRUNC | O_CREAT | O_EXCL, S_IRUSR | S_IWUSR)) >= 0) + break; + } + + if (version > LOG_MAX_SUFFIX_NUMBER) { + pa_log(_("Tried to open target file '%s', '%s.1', '%s.2' ... '%s.%d', but all failed."), + t->file, t->file, t->file, t->file, LOG_MAX_SUFFIX_NUMBER); + pa_xfree(file_path); + return -1; + } else + pa_log_debug("Opened target file %s\n", file_path); + + pa_xfree(file_path); + break; + } + } + + target.type = t->type; + pa_xfree(target.file); + target.file = pa_xstrdup(t->file); + + old_fd = log_fd; + log_fd = fd; + + if (old_fd >= 0) + pa_close(old_fd); + + return 0; +} + +void pa_log_set_flags(pa_log_flags_t _flags, pa_log_merge_t merge) { + pa_assert(!(_flags & ~(PA_LOG_COLORS|PA_LOG_PRINT_TIME|PA_LOG_PRINT_FILE|PA_LOG_PRINT_META|PA_LOG_PRINT_LEVEL))); + + if (merge == PA_LOG_SET) + flags |= _flags; + else if (merge == PA_LOG_UNSET) + flags &= ~_flags; + else + flags = _flags; +} + +void pa_log_set_show_backtrace(unsigned nlevels) { + show_backtrace = nlevels; +} + +void pa_log_set_skip_backtrace(unsigned nlevels) { + skip_backtrace = nlevels; +} + +#ifdef HAVE_EXECINFO_H + +static char* get_backtrace(unsigned show_nframes) { + void* trace[32]; + int n_frames; + char **symbols, *e, *r; + unsigned j, n, s; + size_t a; + + pa_assert(show_nframes > 0); + + n_frames = backtrace(trace, PA_ELEMENTSOF(trace)); + + if (n_frames <= 0) + return NULL; + + symbols = backtrace_symbols(trace, n_frames); + + if (!symbols) + return NULL; + + s = skip_backtrace; + n = PA_MIN((unsigned) n_frames, s + show_nframes); + + a = 4; + + for (j = s; j < n; j++) { + if (j > s) + a += 2; + a += strlen(pa_path_get_filename(symbols[j])); + } + + r = pa_xnew(char, a); + + strcpy(r, " ("); + e = r + 2; + + for (j = s; j < n; j++) { + const char *sym; + + if (j > s) { + strcpy(e, "<<"); + e += 2; + } + + sym = pa_path_get_filename(symbols[j]); + + strcpy(e, sym); + e += strlen(sym); + } + + strcpy(e, ")"); + + free(symbols); + + return r; +} + +#endif + +static void init_defaults(void) { + PA_ONCE_BEGIN { + + const char *e; + + if (!ident) { + char binary[256]; + if (pa_get_binary_name(binary, sizeof(binary))) + pa_log_set_ident(binary); + } + + if (getenv(ENV_LOG_SYSLOG)) { + target_override = PA_LOG_SYSLOG; + target_override_set = true; + } + +#ifdef HAVE_SYSTEMD_JOURNAL + if (getenv(ENV_LOG_JOURNAL)) { + target_override = PA_LOG_JOURNAL; + target_override_set = true; + } +#endif + + if ((e = getenv(ENV_LOG_LEVEL))) { + maximum_level_override = (pa_log_level_t) atoi(e); + + if (maximum_level_override >= PA_LOG_LEVEL_MAX) + maximum_level_override = PA_LOG_LEVEL_MAX-1; + } + + if (getenv(ENV_LOG_COLORS)) + flags_override |= PA_LOG_COLORS; + + if (getenv(ENV_LOG_PRINT_TIME)) + flags_override |= PA_LOG_PRINT_TIME; + + if (getenv(ENV_LOG_PRINT_FILE)) + flags_override |= PA_LOG_PRINT_FILE; + + if (getenv(ENV_LOG_PRINT_META)) + flags_override |= PA_LOG_PRINT_META; + + if (getenv(ENV_LOG_PRINT_LEVEL)) + flags_override |= PA_LOG_PRINT_LEVEL; + + if ((e = getenv(ENV_LOG_BACKTRACE))) { + show_backtrace_override = (unsigned) atoi(e); + + if (show_backtrace_override <= 0) + show_backtrace_override = 0; + } + + if ((e = getenv(ENV_LOG_BACKTRACE_SKIP))) { + skip_backtrace = (unsigned) atoi(e); + + if (skip_backtrace <= 0) + skip_backtrace = 0; + } + + if (getenv(ENV_LOG_NO_RATELIMIT)) + no_rate_limit = true; + + } PA_ONCE_END; +} + +#ifdef HAVE_SYSLOG_H +static void log_syslog(pa_log_level_t level, char *t, char *timestamp, char *location, char *bt) { + char *local_t; + + openlog(ident, LOG_PID, LOG_USER); + + if ((local_t = pa_utf8_to_locale(t))) + t = local_t; + + syslog(level_to_syslog[level], "%s%s%s%s", timestamp, location, t, pa_strempty(bt)); + pa_xfree(local_t); +} +#endif + +void pa_log_levelv_meta( + pa_log_level_t level, + const char*file, + int line, + const char *func, + const char *format, + va_list ap) { + + char *t, *n; + int saved_errno = errno; + char *bt = NULL; + pa_log_target_type_t _target; + pa_log_level_t _maximum_level; + unsigned _show_backtrace; + pa_log_flags_t _flags; + + /* We don't use dynamic memory allocation here to minimize the hit + * in RT threads */ + char text[16*1024], location[128], timestamp[32]; + + pa_assert(level < PA_LOG_LEVEL_MAX); + pa_assert(format); + + init_defaults(); + + _target = target_override_set ? target_override : target.type; + _maximum_level = PA_MAX(maximum_level, maximum_level_override); + _show_backtrace = PA_MAX(show_backtrace, show_backtrace_override); + _flags = flags | flags_override; + + if (PA_LIKELY(level > _maximum_level)) { + errno = saved_errno; + return; + } + + pa_vsnprintf(text, sizeof(text), format, ap); + + if ((_flags & PA_LOG_PRINT_META) && file && line > 0 && func) + pa_snprintf(location, sizeof(location), "[%s][%s:%i %s()] ", + pa_strnull(pa_thread_get_name(pa_thread_self())), file, line, func); + else if ((_flags & (PA_LOG_PRINT_META|PA_LOG_PRINT_FILE)) && file) + pa_snprintf(location, sizeof(location), "[%s] %s: ", + pa_strnull(pa_thread_get_name(pa_thread_self())), pa_path_get_filename(file)); + else + location[0] = 0; + + if (_flags & PA_LOG_PRINT_TIME) { + static pa_usec_t start, last; + pa_usec_t u, a, r; + + u = pa_rtclock_now(); + + PA_ONCE_BEGIN { + start = u; + last = u; + } PA_ONCE_END; + + r = u - last; + a = u - start; + + /* This is not thread safe, but this is a debugging tool only + * anyway. */ + last = u; + + pa_snprintf(timestamp, sizeof(timestamp), "(%4llu.%03llu|%4llu.%03llu) ", + (unsigned long long) (a / PA_USEC_PER_SEC), + (unsigned long long) (((a / PA_USEC_PER_MSEC)) % 1000), + (unsigned long long) (r / PA_USEC_PER_SEC), + (unsigned long long) (((r / PA_USEC_PER_MSEC)) % 1000)); + + } else + timestamp[0] = 0; + +#ifdef HAVE_EXECINFO_H + if (_show_backtrace > 0) + bt = get_backtrace(_show_backtrace); +#endif + + if (!pa_utf8_valid(text)) + pa_logl(level, "Invalid UTF-8 string following below:"); + + for (t = text; t; t = n) { + if ((n = strchr(t, '\n'))) { + *n = 0; + n++; + } + + /* We ignore strings only made out of whitespace */ + if (t[strspn(t, "\t ")] == 0) + continue; + + switch (_target) { + + case PA_LOG_STDERR: { + const char *prefix = "", *suffix = "", *grey = ""; + char *local_t; + +#ifndef OS_IS_WIN32 + /* Yes indeed. Useless, but fun! */ + if ((_flags & PA_LOG_COLORS) && isatty(STDERR_FILENO)) { + if (level <= PA_LOG_ERROR) + prefix = "\x1B[1;31m"; + else if (level <= PA_LOG_WARN) + prefix = "\x1B[1m"; + + if (bt) + grey = "\x1B[2m"; + + if (grey[0] || prefix[0]) + suffix = "\x1B[0m"; + } +#endif + + /* We shouldn't be using dynamic allocation here to + * minimize the hit in RT threads */ + if ((local_t = pa_utf8_to_locale(t))) + t = local_t; + + if (_flags & PA_LOG_PRINT_LEVEL) + fprintf(stderr, "%s%c: %s%s%s%s%s%s\n", timestamp, level_to_char[level], location, prefix, t, grey, pa_strempty(bt), suffix); + else + fprintf(stderr, "%s%s%s%s%s%s%s\n", timestamp, location, prefix, t, grey, pa_strempty(bt), suffix); +#ifdef OS_IS_WIN32 + fflush(stderr); +#endif + + pa_xfree(local_t); + + break; + } + +#ifdef HAVE_SYSLOG_H + case PA_LOG_SYSLOG: + log_syslog(level, t, timestamp, location, bt); + break; +#endif + +#ifdef HAVE_SYSTEMD_JOURNAL + case PA_LOG_JOURNAL: + if (sd_journal_send("MESSAGE=%s", t, + "PRIORITY=%i", level_to_journal[level], + "CODE_FILE=%s", file, + "CODE_FUNC=%s", func, + "CODE_LINE=%d", line, + "PULSE_BACKTRACE=%s", pa_strempty(bt), + NULL) < 0) { +#ifdef HAVE_SYSLOG_H + pa_log_target new_target = { .type = PA_LOG_SYSLOG, .file = NULL }; + + syslog(level_to_syslog[PA_LOG_ERROR], "%s%s%s", timestamp, __FILE__, + "Error writing logs to the journal. Redirect log messages to syslog."); + log_syslog(level, t, timestamp, location, bt); +#else + pa_log_target new_target = { .type = PA_LOG_STDERR, .file = NULL }; + + saved_errno = errno; + fprintf(stderr, "%s\n", "Error writing logs to the journal. Redirect log messages to console."); + fprintf(stderr, "%s\n", t); +#endif + pa_log_set_target(&new_target); + } + break; +#endif + + case PA_LOG_FILE: + case PA_LOG_NEWFILE: { + char *local_t; + + if ((local_t = pa_utf8_to_locale(t))) + t = local_t; + + if (log_fd >= 0) { + char metadata[256]; + + if (_flags & PA_LOG_PRINT_LEVEL) + pa_snprintf(metadata, sizeof(metadata), "%s%c: %s", timestamp, level_to_char[level], location); + else + pa_snprintf(metadata, sizeof(metadata), "%s%s", timestamp, location); + + if ((pa_write(log_fd, metadata, strlen(metadata), &write_type) < 0) + || (pa_write(log_fd, t, strlen(t), &write_type) < 0) + || (bt && pa_write(log_fd, bt, strlen(bt), &write_type) < 0) + || (pa_write(log_fd, "\n", 1, &write_type) < 0)) { + pa_log_target new_target = { .type = PA_LOG_STDERR, .file = NULL }; + saved_errno = errno; + fprintf(stderr, "%s\n", "Error writing logs to a file descriptor. Redirect log messages to console."); + fprintf(stderr, "%s %s\n", metadata, t); + pa_log_set_target(&new_target); + } + } + + pa_xfree(local_t); + + break; + } + case PA_LOG_NULL: + default: + break; + } + } + + pa_xfree(bt); + errno = saved_errno; +} + +void pa_log_level_meta( + pa_log_level_t level, + const char*file, + int line, + const char *func, + const char *format, ...) { + + va_list ap; + va_start(ap, format); + pa_log_levelv_meta(level, file, line, func, format, ap); + va_end(ap); +} + +void pa_log_levelv(pa_log_level_t level, const char *format, va_list ap) { + pa_log_levelv_meta(level, NULL, 0, NULL, format, ap); +} + +void pa_log_level(pa_log_level_t level, const char *format, ...) { + va_list ap; + + va_start(ap, format); + pa_log_levelv_meta(level, NULL, 0, NULL, format, ap); + va_end(ap); +} + +bool pa_log_ratelimit(pa_log_level_t level) { + /* Not more than 10 messages every 5s */ + static PA_DEFINE_RATELIMIT(ratelimit, 5 * PA_USEC_PER_SEC, 10); + + init_defaults(); + + if (no_rate_limit) + return true; + + return pa_ratelimit_test(&ratelimit, level); +} + +pa_log_target *pa_log_target_new(pa_log_target_type_t type, const char *file) { + pa_log_target *t = NULL; + + t = pa_xnew(pa_log_target, 1); + + t->type = type; + t->file = pa_xstrdup(file); + + return t; +} + +void pa_log_target_free(pa_log_target *t) { + pa_assert(t); + + pa_xfree(t->file); + pa_xfree(t); +} + +pa_log_target *pa_log_parse_target(const char *string) { + pa_log_target *t = NULL; + + pa_assert(string); + + if (pa_streq(string, "stderr")) + t = pa_log_target_new(PA_LOG_STDERR, NULL); + else if (pa_streq(string, "syslog")) + t = pa_log_target_new(PA_LOG_SYSLOG, NULL); +#ifdef HAVE_SYSTEMD_JOURNAL + else if (pa_streq(string, "journal")) + t = pa_log_target_new(PA_LOG_JOURNAL, NULL); +#endif + else if (pa_streq(string, "null")) + t = pa_log_target_new(PA_LOG_NULL, NULL); + else if (pa_startswith(string, "file:")) + t = pa_log_target_new(PA_LOG_FILE, string + 5); + else if (pa_startswith(string, "newfile:")) + t = pa_log_target_new(PA_LOG_NEWFILE, string + 8); + else + pa_log(_("Invalid log target.")); + + return t; +} + +char *pa_log_target_to_string(const pa_log_target *t) { + char *string = NULL; + + pa_assert(t); + + switch (t->type) { + case PA_LOG_STDERR: + string = pa_xstrdup("stderr"); + break; + case PA_LOG_SYSLOG: + string = pa_xstrdup("syslog"); + break; +#ifdef HAVE_SYSTEMD_JOURNAL + case PA_LOG_JOURNAL: + string = pa_xstrdup("journal"); + break; +#endif + case PA_LOG_NULL: + string = pa_xstrdup("null"); + break; + case PA_LOG_FILE: + string = pa_sprintf_malloc("file:%s", t->file); + break; + case PA_LOG_NEWFILE: + string = pa_sprintf_malloc("newfile:%s", t->file); + break; + } + + return string; +} |