Support showing a backtrace on log messages

This commit is contained in:
Lennart Poettering 2008-10-21 19:13:15 +02:00
parent f92a814118
commit f4320d83a2
3 changed files with 125 additions and 16 deletions

View file

@ -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. ####

View file

@ -30,6 +30,10 @@
#include <string.h>
#include <errno.h>
#ifdef HAVE_EXECINFO_H
#include <execinfo.h>
#endif
#ifdef HAVE_SYSLOG_H
#include <syslog.h>
#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 (level > maximal_level) {
if (PA_UNLIKELY((e = getenv(ENV_LOGLEVEL)))) {
pa_log_level_t eml = (pa_log_level_t) atoi(e);
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);
}

View file

@ -25,6 +25,8 @@
#include <stdarg.h>
#include <stdlib.h>
#include <pulsecore/macro.h>
#include <pulse/gccmacro.h>
/* 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,