X-Git-Url: https://code.delx.au/pulseaudio/blobdiff_plain/126e4cf89f5ccfe393e60a930c88ab513eeee085..8534149fbe87c63a5af85f5610c0f62b45500d90:/src/pulsecore/log.c diff --git a/src/pulsecore/log.c b/src/pulsecore/log.c index 5eda4f65..7ba41ee9 100644 --- a/src/pulsecore/log.c +++ b/src/pulsecore/log.c @@ -6,7 +6,7 @@ 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 of the + 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 @@ -30,26 +30,46 @@ #include #include +#ifdef HAVE_EXECINFO_H +#include +#endif + #ifdef HAVE_SYSLOG_H #include #endif +#include #include #include #include +#include #include #include +#include +#include +#include #include "log.h" -#define ENV_LOGLEVEL "PULSE_LOG" -#define ENV_LOGMETA "PULSE_LOG_META" - -static char *log_ident = NULL, *log_ident_local = NULL; -static pa_log_target_t log_target = PA_LOG_STDERR; -static void (*user_log_func)(pa_log_level_t l, const char *s) = NULL; -static pa_log_level_t maximal_level = PA_LOG_NOTICE; +#define ENV_LOG_SYSLOG "PULSE_LOG_SYSLOG" +#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" + +static char *ident = NULL; /* in local charset format */ +static pa_log_target_t target = PA_LOG_STDERR, target_override; +static pa_bool_t 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 pa_bool_t no_rate_limit = FALSE; #ifdef HAVE_SYSLOG_H static const int level_to_syslog[] = { @@ -70,32 +90,168 @@ static const char level_to_char[] = { }; void pa_log_set_ident(const char *p) { - pa_xfree(log_ident); - pa_xfree(log_ident_local); + pa_xfree(ident); - log_ident = pa_xstrdup(p); - if (!(log_ident_local = pa_utf8_to_locale(log_ident))) - log_ident_local = pa_xstrdup(log_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) { - pa_xfree(log_ident); - pa_xfree(log_ident_local); + if (!pa_in_valgrind()) + return; + + pa_xfree(ident); } -void pa_log_set_maximal_level(pa_log_level_t l) { +void pa_log_set_level(pa_log_level_t l) { pa_assert(l < PA_LOG_LEVEL_MAX); - maximal_level = l; + maximum_level = l; +} + +void pa_log_set_target(pa_log_target_t t) { + pa_assert(t < PA_LOG_TARGET_MAX); + + target = t; +} + +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_target(pa_log_target_t t, void (*func)(pa_log_level_t l, const char*s)) { - pa_assert(t == PA_LOG_USER || !func); +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; + } + + 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; + } - log_target = t; - user_log_func = func; + 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; } void pa_log_levelv_meta( @@ -106,36 +262,76 @@ void pa_log_levelv_meta( const char *format, va_list ap) { - const char *e; char *t, *n; int saved_errno = errno; + char *bt = NULL; + pa_log_target_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[1024], location[128]; + char text[16*1024], location[128], timestamp[32]; pa_assert(level < PA_LOG_LEVEL_MAX); pa_assert(format); - if ((e = getenv(ENV_LOGLEVEL))) - maximal_level = atoi(e); + init_defaults(); + + _target = target_override_set ? target_override : target; + _maximum_level = PA_MAX(maximum_level, maximum_level_override); + _show_backtrace = PA_MAX(show_backtrace, show_backtrace_override); + _flags = flags | flags_override; - if (level > maximal_level) { + if (PA_LIKELY(level > _maximum_level)) { errno = saved_errno; return; } pa_vsnprintf(text, sizeof(text), format, ap); - if (getenv(ENV_LOGMETA) && file && line > 0 && func) + if ((_flags & PA_LOG_PRINT_META) && file && line > 0 && func) pa_snprintf(location, sizeof(location), "[%s:%i %s()] ", file, line, func); - else if (file) + else if ((_flags & (PA_LOG_PRINT_META|PA_LOG_PRINT_FILE)) && file) pa_snprintf(location, sizeof(location), "%s: ", 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_log_level(level, __FILE__": invalid UTF-8 string following below:"); + pa_logl(level, "Invalid UTF-8 string following below:"); for (t = text; t; t = n) { if ((n = strchr(t, '\n'))) { @@ -143,36 +339,43 @@ void pa_log_levelv_meta( n++; } - if (!*t) + /* We ignore strings only made out of whitespace */ + if (t[strspn(t, "\t ")] == 0) continue; - switch (log_target) { + switch (_target) { + case PA_LOG_STDERR: { - const char *prefix = "", *suffix = ""; + const char *prefix = "", *suffix = "", *grey = ""; char *local_t; #ifndef OS_IS_WIN32 /* Yes indeed. Useless, but fun! */ - if (isatty(STDERR_FILENO)) { - if (level <= PA_LOG_ERROR) { + if ((_flags & PA_LOG_COLORS) && isatty(STDERR_FILENO)) { + if (level <= PA_LOG_ERROR) prefix = "\x1B[1;31m"; - suffix = "\x1B[0m"; - } else if (level <= PA_LOG_WARN) { + 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 */ - local_t = pa_utf8_to_locale(t); - if (!local_t) - fprintf(stderr, "%c: %s%s%s%s\n", level_to_char[level], location, prefix, t, suffix); - else { - fprintf(stderr, "%c: %s%s%s%s\n", level_to_char[level], location, prefix, local_t, suffix); - pa_xfree(local_t); - } + 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); + + pa_xfree(local_t); break; } @@ -181,29 +384,17 @@ void pa_log_levelv_meta( case PA_LOG_SYSLOG: { char *local_t; - openlog(log_ident_local ? log_ident_local : "???", LOG_PID, LOG_USER); - - local_t = pa_utf8_to_locale(t); - if (!local_t) - syslog(level_to_syslog[level], "%s%s", location, t); - else { - syslog(level_to_syslog[level], "%s%s", location, local_t); - pa_xfree(local_t); - } - - closelog(); - break; - } -#endif + openlog(ident, LOG_PID, LOG_USER); - case PA_LOG_USER: { - char x[1024]; + if ((local_t = pa_utf8_to_locale(t))) + t = local_t; - pa_snprintf(x, sizeof(x), "%s%s", location, t); - user_log_func(level, x); + syslog(level_to_syslog[level], "%s%s%s%s", timestamp, location, t, pa_strempty(bt)); + pa_xfree(local_t); break; } +#endif case PA_LOG_NULL: default: @@ -211,6 +402,7 @@ void pa_log_levelv_meta( } } + pa_xfree(bt); errno = saved_errno; } @@ -238,3 +430,15 @@ void pa_log_level(pa_log_level_t level, const char *format, ...) { pa_log_levelv_meta(level, NULL, 0, NULL, format, ap); va_end(ap); } + +pa_bool_t 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); +}