From 548563956e484e0e43e9a66a89bdda0f95930108 Mon Sep 17 00:00:00 2001 From: "Daniel P. Berrange" Date: Wed, 9 May 2012 15:18:56 +0100 Subject: [PATCH] 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 --- 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 a6894ae21a..9c356c9326 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 22b5422b10..87e22920a6 100644 --- a/docs/logging.html.in +++ b/docs/logging.html.in @@ -114,8 +114,10 @@

The syntax for filters and outputs is the same for both types of variables.

-

The format for a filter is:

- 
x:name
+

The format for a filter is one of:

+ 
+  x:name  (log message only)
+  x:+name (log message + stack trace)

where name is a match string e.g. remote or qemu and the x is the minimal level where matching messages should be logged:

diff --git a/src/util/logging.c b/src/util/logging.c index 48a056d4b2..110ad7e7d5 100644 --- a/src/util/logging.c +++ b/src/util/logging.c @@ -34,6 +34,9 @@ #if HAVE_SYSLOG_H # include #endif +#ifdef HAVE_EXECINFO_H +# include +#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 2343de0aae..a6fa63ec5e 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 6eb40ed6e2..98595adf23 100644 --- a/tests/testutils.c +++ b/tests/testutils.c @@ -44,6 +44,8 @@ # include #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); } -- GitLab