From f4320d83a2f801af34e577585c1abba3a14b9e4c Mon Sep 17 00:00:00 2001 From: Lennart Poettering Date: Tue, 21 Oct 2008 19:13:15 +0200 Subject: Support showing a backtrace on log messages --- configure.ac | 1 + src/pulsecore/log.c | 133 ++++++++++++++++++++++++++++++++++++++++++++++------ src/pulsecore/log.h | 7 ++- 3 files changed, 125 insertions(+), 16 deletions(-) diff --git a/configure.ac b/configure.ac index 2a040763..f93903de 100644 --- a/configure.ac +++ b/configure.ac @@ -297,6 +297,7 @@ AC_CHECK_HEADERS([sys/ioctl.h]) AC_CHECK_HEADERS([byteswap.h]) AC_CHECK_HEADERS([sys/syscall.h]) AC_CHECK_HEADERS([sys/eventfd.h]) +AC_CHECK_HEADERS([execinfo.h]) #### Typdefs, structures, etc. #### diff --git a/src/pulsecore/log.c b/src/pulsecore/log.c index b1de6966..adf2f112 100644 --- a/src/pulsecore/log.c +++ b/src/pulsecore/log.c @@ -30,6 +30,10 @@ #include #include +#ifdef HAVE_EXECINFO_H +#include +#endif + #ifdef HAVE_SYSLOG_H #include #endif @@ -49,11 +53,15 @@ #define ENV_LOGLEVEL "PULSE_LOG" #define ENV_LOGMETA "PULSE_LOG_META" #define ENV_LOGTIME "PULSE_LOG_TIME" +#define ENV_LOGBACKTRACE "PULSE_LOG_BACKTRACE" static char *log_ident = NULL, *log_ident_local = NULL; static pa_log_target_t log_target = PA_LOG_STDERR; static pa_log_func_t user_log_func = NULL; static pa_log_level_t maximal_level = PA_LOG_ERROR; +static unsigned show_backtrace = 0; +static pa_bool_t show_meta = FALSE; +static pa_bool_t show_time = FALSE; #ifdef HAVE_SYSLOG_H static const int level_to_syslog[] = { @@ -105,6 +113,74 @@ void pa_log_set_target(pa_log_target_t t, pa_log_func_t func) { user_log_func = func; } +void pa_log_set_show_meta(pa_bool_t b) { + show_meta = b; +} + +void pa_log_set_show_time(pa_bool_t b) { + show_time = b; +} + +void pa_log_set_show_backtrace(unsigned nlevels) { + show_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; + size_t a; + + if (show_nframes <= 0) + return NULL; + + n_frames = backtrace(trace, PA_ELEMENTSOF(trace)); + + if (n_frames <= 0) + return NULL; + + symbols = backtrace_symbols(trace, n_frames); + + if (!symbols) + return NULL; + + n = PA_MIN((unsigned) n_frames, show_nframes); + + a = 4; + + for (j = 0; j < n; j++) { + if (j > 0) + a += 2; + a += strlen(symbols[j]); + } + + r = pa_xnew(char, a); + + strcpy(r, " ("); + e = r + 2; + + for (j = 0; j < n; j++) { + if (j > 0) { + strcpy(e, "<<"); + e += 2; + } + + strcpy(e, symbols[j]); + e += strlen(symbols[j]); + } + + strcpy(e, ")"); + + free(symbols); + + return r; +} + +#endif + void pa_log_levelv_meta( pa_log_level_t level, const char*file, @@ -116,32 +192,43 @@ void pa_log_levelv_meta( const char *e; char *t, *n; int saved_errno = errno; + char *bt = NULL; + pa_log_level_t ml; +#ifdef HAVE_EXECINFO_H + unsigned show_bt; +#endif /* We don't use dynamic memory allocation here to minimize the hit * in RT threads */ - char text[1024], location[128], timestamp[32]; + char text[4096], location[128], timestamp[32]; pa_assert(level < PA_LOG_LEVEL_MAX); pa_assert(format); - if ((e = getenv(ENV_LOGLEVEL))) - maximal_level = atoi(e); + ml = maximal_level; + + if (PA_UNLIKELY((e = getenv(ENV_LOGLEVEL)))) { + pa_log_level_t eml = (pa_log_level_t) atoi(e); - if (level > maximal_level) { + if (eml > ml) + ml = eml; + } + + if (PA_LIKELY(level > ml)) { errno = saved_errno; return; } pa_vsnprintf(text, sizeof(text), format, ap); - if (getenv(ENV_LOGMETA) && file && line > 0 && func) + if ((show_meta || getenv(ENV_LOGMETA)) && file && line > 0 && func) pa_snprintf(location, sizeof(location), "[%s:%i %s()] ", file, line, func); else if (file) pa_snprintf(location, sizeof(location), "%s: ", pa_path_get_filename(file)); else location[0] = 0; - if (getenv(ENV_LOGTIME)) { + if (show_time || getenv(ENV_LOGTIME)) { static pa_usec_t start, last; pa_usec_t u, a, r; @@ -168,6 +255,19 @@ void pa_log_levelv_meta( } else timestamp[0] = 0; +#ifdef HAVE_EXECINFO_H + show_bt = show_backtrace; + + if ((e = getenv(ENV_LOGBACKTRACE))) { + unsigned ebt = (unsigned) atoi(e); + + if (ebt > show_bt) + show_bt = ebt; + } + + bt = get_backtrace(show_bt); +#endif + if (!pa_utf8_valid(text)) pa_log_level(level, __FILE__": invalid UTF-8 string following below:"); @@ -182,19 +282,22 @@ void pa_log_levelv_meta( switch (log_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 (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 @@ -202,9 +305,9 @@ void pa_log_levelv_meta( * minimize the hit in RT threads */ local_t = pa_utf8_to_locale(t); if (!local_t) - fprintf(stderr, "%s%c: %s%s%s%s\n", timestamp, level_to_char[level], location, prefix, t, suffix); + 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%c: %s%s%s%s\n", timestamp, level_to_char[level], location, prefix, local_t, suffix); + fprintf(stderr, "%s%c: %s%s%s%s%s%s\n", timestamp, level_to_char[level], location, prefix, local_t, grey, pa_strempty(bt), suffix); pa_xfree(local_t); } @@ -219,9 +322,9 @@ void pa_log_levelv_meta( local_t = pa_utf8_to_locale(t); if (!local_t) - syslog(level_to_syslog[level], "%s%s%s", timestamp, location, t); + syslog(level_to_syslog[level], "%s%s%s%s", timestamp, location, t, pa_strempty(bt)); else { - syslog(level_to_syslog[level], "%s%s%s", timestamp, location, local_t); + syslog(level_to_syslog[level], "%s%s%s%s", timestamp, location, local_t, pa_strempty(bt)); pa_xfree(local_t); } diff --git a/src/pulsecore/log.h b/src/pulsecore/log.h index 633227f3..3d66e903 100644 --- a/src/pulsecore/log.h +++ b/src/pulsecore/log.h @@ -25,6 +25,8 @@ #include #include + +#include #include /* A simple logging subsystem */ @@ -54,8 +56,11 @@ typedef void (*pa_log_func_t)(pa_log_level_t t, const char*s); /* Set another log target. If t is PA_LOG_USER you may specify a function that is called every log string */ void pa_log_set_target(pa_log_target_t t, pa_log_func_t func); -/* Minimal log level */ +/* Maximal log level */ void pa_log_set_maximal_level(pa_log_level_t l); +void pa_log_set_show_meta(pa_bool_t b); +void pa_log_set_show_time(pa_bool_t b); +void pa_log_set_show_backtrace(unsigned nlevels); void pa_log_level_meta( pa_log_level_t level, -- cgit