X-Git-Url: https://code.delx.au/pulseaudio/blobdiff_plain/1bc62d5ec671bf3edab5263fdc8015c0a701ce81..8534149fbe87c63a5af85f5610c0f62b45500d90:/src/pulsecore/log.c?ds=sidebyside diff --git a/src/pulsecore/log.c b/src/pulsecore/log.c index 8bc673e5..7ba41ee9 100644 --- a/src/pulsecore/log.c +++ b/src/pulsecore/log.c @@ -1,18 +1,19 @@ -/* $Id$ */ - /*** This file is part of PulseAudio. - + + Copyright 2004-2006 Lennart Poettering + Copyright 2006 Pierre Ossman 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 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 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, write to the Free Software Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 @@ -23,31 +24,52 @@ #include #endif -#include #include #include #include #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[] = { @@ -59,27 +81,177 @@ static const int level_to_syslog[] = { }; #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) { - if (log_ident) - pa_xfree(log_ident); - if (log_ident_local) - pa_xfree(log_ident_local); - - log_ident = pa_xstrdup(p); - log_ident_local = pa_utf8_to_locale(log_ident); - if (!log_ident_local) - log_ident_local = pa_xstrdup(log_ident); + 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; +} + +void pa_log_set_target(pa_log_target_t t) { + pa_assert(t < PA_LOG_TARGET_MAX); + + target = t; } -void pa_log_set_maximal_level(pa_log_level_t l) { - assert(l < PA_LOG_LEVEL_MAX); - maximal_level = l; +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_target(pa_log_target_t t, void (*func)(pa_log_level_t l, const char*s)) { - assert(t == PA_LOG_USER || !func); - log_target = t; - user_log_func = func; +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; + } + + 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( @@ -89,28 +261,77 @@ void pa_log_levelv_meta( const char *func, const char *format, va_list ap) { - - const char *e; - char *text, *t, *n, *location = pa_xstrdup(""); - - assert(level < PA_LOG_LEVEL_MAX); - assert(format); - - if ((e = getenv(ENV_LOGLEVEL))) - maximal_level = atoi(e); - - if (level > maximal_level) + + 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[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; + _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:%i %s()] ", file, line, func); + 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; - text = pa_vsprintf_malloc(format, ap); + r = u - last; + a = u - start; - if (getenv(ENV_LOGMETA) && file && line > 0 && func) - location = pa_sprintf_malloc("[%s:%i %s()] ", file, line, func); - else if (file) - location = pa_sprintf_malloc("%s: ", pa_path_get_filename(file)); + /* 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'))) { @@ -118,75 +339,71 @@ 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 +#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 - local_t = pa_utf8_to_locale(t); - if (!local_t) - fprintf(stderr, "%s%s%s%s\n", location, prefix, t, suffix); - else { - fprintf(stderr, "%s%s%s%s\n", location, prefix, local_t, suffix); - pa_xfree(local_t); - } + /* 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); + + pa_xfree(local_t); break; } - -#ifdef HAVE_SYSLOG_H + +#ifdef HAVE_SYSLOG_H case PA_LOG_SYSLOG: { char *local_t; - openlog(log_ident_local ? log_ident_local : "???", LOG_PID, LOG_USER); + openlog(ident, 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); - } + 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); - closelog(); - break; - } -#endif - - case PA_LOG_USER: { - char *x; - - x = pa_sprintf_malloc("%s%s", location, t); - user_log_func(level, x); - pa_xfree(x); - break; } - +#endif + case PA_LOG_NULL: default: break; } } - pa_xfree(text); - pa_xfree(location); + pa_xfree(bt); + errno = saved_errno; } void pa_log_level_meta( @@ -195,7 +412,7 @@ void pa_log_level_meta( 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); @@ -208,7 +425,20 @@ void pa_log_levelv(pa_log_level_t level, const char *format, va_list 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); } + +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); +}