Allow stack traces to be included with log messages

Sometimes it is useful to see the callpath for log messages.
This change enhances the log filter syntax so that stack traces
can be show by setting '1:+NAME' instead of '1:NAME'.

This results in output like:

2012-05-09 14:18:45.136+0000: 13314: debug : virInitialize:414 : register drivers
/home/berrange/src/virt/libvirt/src/.libs/libvirt.so.0(virInitialize+0xd6)[0x7f89188ebe86]
/home/berrange/src/virt/libvirt/tools/.libs/lt-virsh[0x431921]
/lib64/libc.so.6(__libc_start_main+0xf5)[0x3a21e21735]
/home/berrange/src/virt/libvirt/tools/.libs/lt-virsh[0x40a279]

2012-05-09 14:18:45.136+0000: 13314: debug : virRegisterDriver:775 : driver=0x7f8918d02760 name=Test
/home/berrange/src/virt/libvirt/src/.libs/libvirt.so.0(virRegisterDriver+0x6b)[0x7f89188ec717]
/home/berrange/src/virt/libvirt/src/.libs/libvirt.so.0(+0x11b3ad)[0x7f891891e3ad]
/home/berrange/src/virt/libvirt/src/.libs/libvirt.so.0(virInitialize+0xf3)[0x7f89188ebea3]
/home/berrange/src/virt/libvirt/tools/.libs/lt-virsh[0x431921]
/lib64/libc.so.6(__libc_start_main+0xf5)[0x3a21e21735]
/home/berrange/src/virt/libvirt/tools/.libs/lt-virsh[0x40a279]

* docs/logging.html.in: Document new syntax
* configure.ac: Check for execinfo.h
* src/util/logging.c, src/util/logging.h: Add support for
  stack traces
* tests/testutils.c: Adapt to API change
Signed-off-by: NDaniel P. Berrange <berrange@redhat.com>

configure.ac

@@ -158,7 +158,7 @@ dnl Availability of various common headers (non-fatal if missing).
 AC_CHECK_HEADERS([pwd.h paths.h regex.h sys/un.h \
   sys/poll.h syslog.h mntent.h net/ethernet.h linux/magic.h \
   sys/un.h sys/syscall.h netinet/tcp.h ifaddrs.h libtasn1.h \
-  net/if.h])
+  net/if.h execinfo.h])
 
 AC_MSG_CHECKING([for struct ifreq in net/if.h])
 AC_COMPILE_IFELSE([AC_LANG_PROGRAM(

docs/logging.html.in

@@ -114,8 +114,10 @@
     </h3>
     <p>The syntax for filters and outputs is the same for both types of
        variables.</p>
-    <p>The format for a filter is:</p>
-    <pre>x:name</pre>
+    <p>The format for a filter is one of:</p>
+    <pre>
+  x:name  (log message only)
+  x:+name (log message + stack trace)</pre>
     <p>where <code>name</code> is a match string e.g. <code>remote</code> or
     <code>qemu</code> and the x is the minimal level where matching messages
     should be logged:</p>

src/util/logging.c

@@ -34,6 +34,9 @@
 #if HAVE_SYSLOG_H
 # include <syslog.h>
 #endif
+#ifdef HAVE_EXECINFO_H
+# include <execinfo.h>
+#endif
 
 #include "ignore-value.h"
 #include "virterror_internal.h"
@@ -64,6 +67,7 @@ static int virLogEnd = 0;
 struct _virLogFilter {
     const char *match;
     int priority;
+    unsigned int flags;
 };
 typedef struct _virLogFilter virLogFilter;
 typedef virLogFilter *virLogFilterPtr;
@@ -99,7 +103,9 @@ static int virLogResetFilters(void);
 static int virLogResetOutputs(void);
 static int virLogOutputToFd(const char *category, int priority,
                             const char *funcname, long long linenr,
-                            const char *timestamp, const char *str,
+                            const char *timestamp,
+                            unsigned int flags,
+                            const char *str,
                             void *data);
 
 /*
@@ -472,7 +478,7 @@ static int virLogResetFilters(void) {
  * virLogDefineFilter:
  * @match: the pattern to match
  * @priority: the priority to give to messages matching the pattern
- * @flags: extra flag, currently unused
+ * @flags: extra flags, see virLogFilterFlags enum
  *
  * Defines a pattern used for log filtering, it allow to select or
  * reject messages independently of the default priority.
@@ -487,7 +493,7 @@ int virLogDefineFilter(const char *match, int priority,
     int i;
     char *mdup = NULL;
 
-    virCheckFlags(0, -1);
+    virCheckFlags(VIR_LOG_STACK_TRACE, -1);
 
     if ((match == NULL) || (priority < VIR_LOG_DEBUG) ||
         (priority > VIR_LOG_ERROR))
@@ -514,6 +520,7 @@ int virLogDefineFilter(const char *match, int priority,
     }
     virLogFilters[i].match = mdup;
     virLogFilters[i].priority = priority;
+    virLogFilters[i].flags = flags;
     virLogNbFilters++;
 cleanup:
     virLogUnlock();
@@ -530,7 +537,8 @@ cleanup:
  *
  * Returns 0 if not matched or the new priority if found.
  */
-static int virLogFiltersCheck(const char *input) {
+static int virLogFiltersCheck(const char *input,
+                              unsigned int *flags) {
     int ret = 0;
     int i;
 
@@ -538,6 +546,7 @@ static int virLogFiltersCheck(const char *input) {
     for (i = 0;i < virLogNbFilters;i++) {
         if (strstr(input, virLogFilters[i].match)) {
             ret = virLogFilters[i].priority;
+            *flags = virLogFilters[i].flags;
             break;
         }
     }
@@ -691,6 +700,7 @@ void virLogMessage(const char *category, int priority, const char *funcname,
     int saved_errno = errno;
     int emit = 1;
     va_list ap;
+    unsigned int filterflags = 0;
 
     if (!virLogInitialized)
         virLogStartup();
@@ -701,7 +711,7 @@ void virLogMessage(const char *category, int priority, const char *funcname,
     /*
      * check against list of specific logging patterns
      */
-    fprio = virLogFiltersCheck(category);
+    fprio = virLogFiltersCheck(category, &filterflags);
     if (fprio == 0) {
         if (priority < virLogDefaultPriority)
             emit = 0;
@@ -753,13 +763,14 @@ void virLogMessage(const char *category, int priority, const char *funcname,
                 if (virLogVersionString(&ver) >= 0)
                     virLogOutputs[i].f(category, VIR_LOG_INFO,
                                        __func__, __LINE__,
-                                       timestamp, ver,
+                                       timestamp, 0, ver,
                                        virLogOutputs[i].data);
                 VIR_FREE(ver);
                 virLogOutputs[i].logVersion = false;
             }
             virLogOutputs[i].f(category, priority, funcname, linenr,
-                               timestamp, msg, virLogOutputs[i].data);
+                               timestamp, filterflags,
+                               msg, virLogOutputs[i].data);
         }
     }
     if ((virLogNbOutputs == 0) && (flags != 1)) {
@@ -768,13 +779,14 @@ void virLogMessage(const char *category, int priority, const char *funcname,
             if (virLogVersionString(&ver) >= 0)
                 virLogOutputToFd(category, VIR_LOG_INFO,
                                  __func__, __LINE__,
-                                 timestamp, ver,
+                                 timestamp, 0, ver,
                                  (void *) STDERR_FILENO);
             VIR_FREE(ver);
             logVersionStderr = false;
         }
         virLogOutputToFd(category, priority, funcname, linenr,
-                         timestamp, msg, (void *) STDERR_FILENO);
+                         timestamp, filterflags,
+                         msg, (void *) STDERR_FILENO);
     }
     virLogUnlock();
 
@@ -783,11 +795,34 @@ cleanup:
     errno = saved_errno;
 }
 
+
+static void virLogStackTraceToFd(int fd)
+{
+#ifdef HAVE_EXECINFO_H
+    void *array[100];
+    int size;
+
+# define STRIP_DEPTH 3
+
+    size = backtrace(array, ARRAY_CARDINALITY(array));
+    backtrace_symbols_fd(array +  STRIP_DEPTH, size - STRIP_DEPTH, fd);
+    ignore_value(safewrite(fd, "\n", 1));
+#else
+    static bool doneWarning = false;
+    const char *msg = "Stack trace not available on this platform\n";
+    if (!doneWarning) {
+        ignore_value(safewrite(fd, msg, strlen(msg)));
+        doneWarning = true;
+    }
+#endif
+}
+
 static int virLogOutputToFd(const char *category ATTRIBUTE_UNUSED,
                             int priority ATTRIBUTE_UNUSED,
                             const char *funcname ATTRIBUTE_UNUSED,
                             long long linenr ATTRIBUTE_UNUSED,
                             const char *timestamp,
+                            unsigned int flags,
                             const char *str,
                             void *data)
 {
@@ -804,6 +839,9 @@ static int virLogOutputToFd(const char *category ATTRIBUTE_UNUSED,
     ret = safewrite(fd, msg, strlen(msg));
     VIR_FREE(msg);
 
+    if (flags & VIR_LOG_STACK_TRACE)
+        virLogStackTraceToFd(fd);
+
     return ret;
 }
 
@@ -841,11 +879,14 @@ static int virLogOutputToSyslog(const char *category ATTRIBUTE_UNUSED,
                                 const char *funcname ATTRIBUTE_UNUSED,
                                 long long linenr ATTRIBUTE_UNUSED,
                                 const char *timestamp ATTRIBUTE_UNUSED,
+                                unsigned int flags,
                                 const char *str,
                                 void *data ATTRIBUTE_UNUSED)
 {
     int prio;
 
+    virCheckFlags(VIR_LOG_STACK_TRACE, -1);
+
     switch (priority) {
         case VIR_LOG_DEBUG:
             prio = LOG_DEBUG;
@@ -1024,12 +1065,17 @@ int virLogParseFilters(const char *filters) {
 
     virSkipSpaces(&cur);
     while (*cur != 0) {
+        unsigned int flags = 0;
         prio= virParseNumber(&cur);
         if ((prio < VIR_LOG_DEBUG) || (prio > VIR_LOG_ERROR))
             goto cleanup;
         if (*cur != ':')
             goto cleanup;
         cur++;
+        if (*cur == '+') {
+            flags |= VIR_LOG_STACK_TRACE;
+            cur++;
+        }
         str = cur;
         while ((*cur != 0) && (!IS_SPACE(cur)))
             cur++;
@@ -1038,7 +1084,7 @@ int virLogParseFilters(const char *filters) {
         name = strndup(str, cur - str);
         if (name == NULL)
             goto cleanup;
-        if (virLogDefineFilter(name, prio, 0) >= 0)
+        if (virLogDefineFilter(name, prio, flags) >= 0)
             count++;
         VIR_FREE(name);
         virSkipSpaces(&cur);
@@ -1072,7 +1118,12 @@ char *virLogGetFilters(void) {
 
     virLogLock();
     for (i = 0; i < virLogNbFilters; i++) {
-        virBufferAsprintf(&filterbuf, "%d:%s ", virLogFilters[i].priority,
+        const char *sep = ":";
+        if (virLogFilters[i].flags & VIR_LOG_STACK_TRACE)
+            sep = ":+";
+        virBufferAsprintf(&filterbuf, "%d%s%s ",
+                          virLogFilters[i].priority,
+                          sep,
                           virLogFilters[i].match);
     }
     virLogUnlock();

src/util/logging.h

@@ -79,6 +79,7 @@ typedef enum {
  * @funcname: the function emitting the message
  * @linenr: line where the message was emitted
  * @timestamp: zero terminated string with timestamp of the message
+ * @flags: flags associated with the message
  * @str: the message to log, preformatted and zero terminated
  * @data: extra output logging data
  *
@@ -88,7 +89,9 @@ typedef enum {
  */
 typedef int (*virLogOutputFunc) (const char *category, int priority,
                                  const char *funcname, long long linenr,
-                                 const char *timestamp, const char *str,
+                                 const char *timestamp,
+                                 unsigned int flags,
+                                 const char *str,
                                  void *data);
 
 /**
@@ -99,6 +102,10 @@ typedef int (*virLogOutputFunc) (const char *category, int priority,
  */
 typedef void (*virLogCloseFunc) (void *data);
 
+typedef enum {
+    VIR_LOG_STACK_TRACE = (1 << 0),
+} virLogFlags;
+
 extern int virLogGetNbFilters(void);
 extern int virLogGetNbOutputs(void);
 extern char *virLogGetFilters(void);

tests/testutils.c

@@ -44,6 +44,8 @@
 # include <paths.h>
 #endif
 
+#define VIR_FROM_THIS VIR_FROM_NONE
+
 #define GETTIMEOFDAY(T) gettimeofday(T, NULL)
 #define DIFF_MSEC(T, U)                                 \
     ((((int) ((T)->tv_sec - (U)->tv_sec)) * 1000000.0 + \
@@ -469,10 +471,12 @@ virtTestLogOutput(const char *category ATTRIBUTE_UNUSED,
                   const char *funcname ATTRIBUTE_UNUSED,
                   long long lineno ATTRIBUTE_UNUSED,
                   const char *timestamp,
+                  unsigned int flags,
                   const char *str,
                   void *data)
 {
     struct virtTestLogData *log = data;
+    virCheckFlags(VIR_LOG_STACK_TRACE, -1);
     virBufferAsprintf(&log->buf, "%s: %s", timestamp, str);
     return strlen(timestamp) + 2 + strlen(str);
 }