Support showing a backtrace on log messages

diff --git a/configure.ac b/configure.ac
index 2a04076..f93903d 100644 (file)
--- 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 b1de696..adf2f11 100644 (file)
--- a/src/pulsecore/log.c
+++ b/src/pulsecore/log.c
@@ -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 (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 633227f..3d66e90 100644 (file)
--- a/src/pulsecore/log.h
+++ b/src/pulsecore/log.h
@@ -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,