[libvirt] [PATCH v2] Allow stack traces to be included with log messages

Daniel P. Berrange berrange at redhat.com
Tue May 15 14:14:21 UTC 2012


From: "Daniel P. Berrange" <berrange at redhat.com>

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 at redhat.com>
---
 configure.ac         |    2 +-
 docs/logging.html.in |    6 +++--
 src/util/logging.c   |   73 ++++++++++++++++++++++++++++++++++++++++++--------
 src/util/logging.h   |    9 ++++++-
 tests/testutils.c    |    4 +++
 5 files changed, 79 insertions(+), 15 deletions(-)

diff --git a/configure.ac b/configure.ac
index a6894ae..9c356c9 100644
--- 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 22b5422..87e2292 100644
--- 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 48a056d..110ad7e 100644
--- 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 2343de0..a6fa63e 100644
--- 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 6eb40ed..98595ad 100644
--- 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);
 }
-- 
1.7.10.1




More information about the libvir-list mailing list