From: "Daniel P. Berrange" <berrange@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@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