9:22 a.m.
From: "Daniel P. Berrange" <berrange(a)redhat.com>
Sometimes it is useful to see the callpath for log messages.
This change enhances the log filter syntax so that stck 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(a)redhat.com>
---
configure.ac | 2 +-
docs/logging.html.in | 6 +++--
src/util/logging.c | 67 +++++++++++++++++++++++++++++++++++++++++---------
src/util/logging.h | 9 ++++++-
tests/testutils.c | 1 +
5 files changed, 70 insertions(+), 15 deletions(-)
diff --git a/configure.ac b/configure.ac
index 30eff91..c1bf57b 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..062917d 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,30 @@ 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, sizeof(array)/sizeof(array[0]));
+ backtrace_symbols_fd(array + STRIP_DEPTH, size - STRIP_DEPTH, fd);
+ ignore_value(safewrite(fd, "\n", 1));
+#else
+ const char *msg = "stack trace not available on this platform";
+ ignore_value(safewrite(fd, msg, strlen(msg)));
+#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 +835,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,6 +875,7 @@ 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 ATTRIBUTE_UNUSED,
const char *str,
void *data ATTRIBUTE_UNUSED)
{
@@ -1024,12 +1059,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 +1078,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 +1112,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 4e8484f..57cf84c 100644
--- a/tests/testutils.c
+++ b/tests/testutils.c
@@ -469,6 +469,7 @@ virtTestLogOutput(const char *category ATTRIBUTE_UNUSED,
const char *funcname ATTRIBUTE_UNUSED,
long long lineno ATTRIBUTE_UNUSED,
const char *timestamp,
+ unsigned int flags ATTRIBUTE_UNUSED,
const char *str,
void *data)
{
--
1.7.10.1