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: Daniel P. Berrange <berrange@redhat.com>

diff --git a/configure.ac b/configure.ac
index a6894ae21ab54f4e4d18edd2cd3d0e01108ec1ec..9c356c9326f3da76a3ee3468c1470baaf67e30da 100644 (file)
--- a/configure.ac
+++ b/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(

diff --git a/docs/logging.html.in b/docs/logging.html.in
index 22b5422b10088134486fcd70b798bfb67aa912b8..87e22920a6b69e9fd68a6844fa7fe44ad7a00894 100644 (file)
--- a/docs/logging.html.in
+++ b/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>

diff --git a/src/util/logging.c b/src/util/logging.c
index 48a056d4b25ec89e2cf8a931a39f211c3673bd0c..110ad7e7d5be225f14b3b52e1f45c295cd90b9cd 100644 (file)
--- a/src/util/logging.c
+++ b/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();

diff --git a/src/util/logging.h b/src/util/logging.h
index 2343de0aae56f8fb69922e5a997b294187e78cb3..a6fa63ec5ea3b8d3660071efb6ac27fdf6f571bf 100644 (file)
--- a/src/util/logging.h
+++ b/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);

diff --git a/tests/testutils.c b/tests/testutils.c
index 6eb40ed6e2f318f8e459ca83046119b28a11adda..98595adf23fdc2eb9966573b918c60027808ea99 100644 (file)
--- a/tests/testutils.c
+++ b/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);
 }