The systemd journal accepts arbitrary user specified log fields. These can be passed into virLogMessage via the virLogMetadata structure. Allow up to 5 custom fields to be reported by libvirt callers. Signed-off-by: Daniel P. Berrange <berrange(a)redhat.com&gt; --- src/util/virlog.c | 18 ++++++++++++++++-- 1 file changed, 16 insertions(+), 2 deletions(-) diff --git a/src/util/virlog.c b/src/util/virlog.c index 32714ce..b8f539e 100644 --- a/src/util/virlog.c +++ b/src/util/virlog.c @@ -1153,7 +1153,7 @@ virLogOutputToJournald(virLogSource source, int linenr, const char *funcname, const char *timestamp ATTRIBUTE_UNUSED, - virLogMetadataPtr metadata ATTRIBUTE_UNUSED, + virLogMetadataPtr metadata, unsigned int flags, const char *rawstr, const char *str ATTRIBUTE_UNUSED, @@ -1172,8 +1172,11 @@ virLogOutputToJournald(virLogSource source, * be a tmpfs, and one that is available from early boot on * and where unprivileged users can create files. */ char path[] = "/dev/shm/journal.XXXXXX"; + size_t nmetadata = 0; -# define NUM_FIELDS 6 +# define NUM_FIELDS_CORE 6 +# define NUM_FIELDS_META 5 +# define NUM_FIELDS (NUM_FIELDS_CORE + NUM_FIELDS_META) struct iovec iov[NUM_FIELDS * 5]; char iov_bufs[NUM_FIELDS][JOURNAL_BUF_SIZE]; struct journalState state; @@ -1192,6 +1195,17 @@ virLogOutputToJournald(virLogSource source, journalAddInt(&state, "CODE_LINE", linenr); if (funcname) journalAddString(&state, "CODE_FUNC", funcname); + if (metadata != NULL) { + while (metadata->key != NULL && + nmetadata < NUM_FIELDS_META) { + if (metadata->s != NULL) + journalAddString(&state, metadata->key, metadata->s); + else + journalAddInt(&state, metadata->key, metadata->iv); + metadata++; + nmetadata++; + } + } memset(&sa, 0, sizeof(sa)); sa.sun_family = AF_UNIX; -- 1.8.5.3

The systemd journal expects log record PRIORITY values to be encoded using the syslog compatible numbering scheme, not libvirt's own native numbering scheme. We must therefore apply a conversion. Signed-off-by: Daniel P. Berrange <berrange(a)redhat.com&gt; --- src/util/virlog.c | 22 ++++++++++++++++++++-- 1 file changed, 20 insertions(+), 2 deletions(-) diff --git a/src/util/virlog.c b/src/util/virlog.c index b8f539e..68af0f3 100644 --- a/src/util/virlog.c +++ b/src/util/virlog.c @@ -1000,7 +1000,22 @@ virLogAddOutputToFile(virLogPriority priority, } -#if HAVE_SYSLOG_H +#if HAVE_SYSLOG_H || USE_JOURNALD + +/* Compat in case we build with journald, but no syslog */ +# ifndef LOG_DEBUG +# define LOG_DEBUG 7 +# endif +# ifndef LOG_INFO +# define LOG_INFO 6 +# endif +# ifndef LOG_WARNING +# define LOG_WARNING 4 +# endif +# ifndef LOG_ERR +# define LOG_ERR 3 +# endif + static int virLogPrioritySyslog(virLogPriority priority) { @@ -1017,8 +1032,10 @@ virLogPrioritySyslog(virLogPriority priority) return LOG_ERR; } } +#endif /* HAVE_SYSLOG_H || USE_JOURNALD */ +#if HAVE_SYSLOG_H static void virLogOutputToSyslog(virLogSource source ATTRIBUTE_UNUSED, virLogPriority priority, @@ -1187,7 +1204,8 @@ virLogOutputToJournald(virLogSource source, state.bufs_end = iov_bufs + ARRAY_CARDINALITY(iov_bufs); journalAddString(&state, "MESSAGE", rawstr); - journalAddInt(&state, "PRIORITY", priority); + journalAddInt(&state, "PRIORITY", + virLogPrioritySyslog(priority)); journalAddString(&state, "LIBVIRT_SOURCE", virLogSourceTypeToString(source)); if (filename) -- 1.8.5.3

The logging docs went straight from <h1> to <h3> header level, skipping out <h2>. Signed-off-by: Daniel P. Berrange <berrange(a)redhat.com&gt; --- docs/logging.html.in | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/docs/logging.html.in b/docs/logging.html.in index 1cd15a1..ac415f8 100644 --- a/docs/logging.html.in +++ b/docs/logging.html.in @@ -24,9 +24,9 @@ <a href="#log_examples">Examples</a> </li> </ul> - <h3> + <h2> <a name="log_library">Logging in the library</a> - </h3> + </h2> <p>The logging functionalities in libvirt are based on 3 key concepts, similar to the one present in other generic logging facilities like log4j:</p> @@ -58,9 +58,9 @@ default is 64 kB. This can be used when debugging the library (see the virLogBuffer variable content).</p> - <h3> + <h2> <a name="log_config">Configuring logging in the library</a> - </h3> + </h2> <p>The library configuration of logging is through 3 environment variables allowing to control the logging behaviour:</p> <ul> @@ -79,9 +79,9 @@ you specify an invalid value, it will be ignored with a warning. If you have an error in a filter or output string, some of the settings may be applied up to the point at which libvirt encountered the error.</p> - <h3> + <h2> <a name="log_daemon">Logging in the daemon</a> - </h3> + </h2> <p>Similarly the daemon logging behaviour can be tuned using 3 config variables, stored in the configuration file:</p> <ul> @@ -110,9 +110,9 @@ by default) in case of crash, this can also be activated explicitly for debugging purposes by sending the daemon a USR2 signal:</p> <pre>killall -USR2 libvirtd</pre> - <h3> + <h2> <a name="log_syntax">Syntax for filters and output values</a> - </h3> + </h2> <p>The syntax for filters and outputs is the same for both types of variables.</p> <p>The format for a filter is one of:</p> @@ -159,9 +159,9 @@ will log all warnings and errors to syslog under the libvirtd ident but also log all debug and information included in the file <code>/tmp/libvirt.log</code></p> - <h3> + <h2> <a name="log_examples">Examples</a> - </h3> + </h2> <p>For example setting up the following:</p> <pre>export LIBVIRT_DEBUG=1 export LIBVIRT_LOG_OUTPUTS="1:file:virsh.log"</pre> -- 1.8.5.3

The logging doc had a hand-written table of contents instead of using the automatic XSL generated one. Signed-off-by: Daniel P. Berrange <berrange(a)redhat.com&gt; --- docs/logging.html.in | 21 ++++----------------- 1 file changed, 4 insertions(+), 17 deletions(-) diff --git a/docs/logging.html.in b/docs/logging.html.in index ac415f8..08bbd70 100644 --- a/docs/logging.html.in +++ b/docs/logging.html.in @@ -3,27 +3,14 @@ <html xmlns="http://www.w3.org/1999/xhtml"> <body> <h1 >Logging in the library and the daemon</h1> + <p>Libvirt includes logging facilities starting from version 0.6.0, this complements the <a href="errors.html">error handling</a> mechanism and APIs to allow tracing through the execution of the library as well as in the libvirtd daemon.</p> - <ul> - <li> - <a href="#log_library">Logging in the library</a> - </li> - <li> - <a href="#log_config">Configuring logging in the library</a> - </li> - <li> - <a href="#log_daemon">Logging in the daemon</a> - </li> - <li> - <a href="#log_syntax">Syntax for filters and output values</a> - </li> - <li> - <a href="#log_examples">Examples</a> - </li> - </ul> + + <ul id="toc"/> + <h2> <a name="log_library">Logging in the library</a> </h2> -- 1.8.5.3

Document the various fields that libvirt will emit for journal log records. Signed-off-by: Daniel P. Berrange <berrange(a)redhat.com&gt; --- docs/logging.html.in | 35 ++++++++++++++++++++++++++++++++--- 1 file changed, 32 insertions(+), 3 deletions(-) diff --git a/docs/logging.html.in b/docs/logging.html.in index 08bbd70..08afa5c 100644 --- a/docs/logging.html.in +++ b/docs/logging.html.in @@ -85,9 +85,13 @@ <p>When starting the libvirt daemon, any logging environment variable settings will override settings in the config file. Command line options take precedence over all. If no outputs are defined for libvirtd, it - defaults to logging to /var/log/libvirt/libvirtd.log (before 0.9.0 - it was using syslog) when it is running as a daemon, or to - stderr when it is running in the foreground.</p> + will try to use</p> + <ul> + <li>0.10.0 or later: systemd journal, if <code>/run/systemd/journal/socket</code> exists</li> + <li>0.9.0 or later: file <code>/var/log/libvirt/libvirtd.log</code> if running as a daemon</li> + <li>before 0.9.0: syslog if running as a daemon</li> + <li>all version: to stderr stream if running in the foreground</li> + </ul> <p>Libvirtd does not reload its logging configuration when issued a SIGHUP. If you want to reload the configuration, you must do a <code>service libvirtd restart</code> or manually stop and restart the daemon @@ -133,6 +137,7 @@ given <code>name</code> as the ident</li> <li><code>x:file:file_path</code> output to a file, with the given filepath</li> + <li><code>x:journald</code> output goes to systemd journal</li> </ul> <p>In all cases the x prefix is the minimal level, acting as a filter:</p> <ul> @@ -146,6 +151,30 @@ will log all warnings and errors to syslog under the libvirtd ident but also log all debug and information included in the file <code>/tmp/libvirt.log</code></p> + + <h2><a name="journald">Systemd journal fields</a></h2> + + <p> + When logging to the systemd journal, the following fields + are defined, in addition to any automatically recorded + <a href="http://www.freedesktop.org/software/systemd/man/systemd.journa... fields</a>: + </p> + + <dl> + <dt><code>MESSAGE</code></dt> + <dd>The log message string</dd> + <dt><code>PRIORITY</code></dt> + <dd>The log priority value</dd> + <dt><code>LIBVIRT_SOURCE</code></dt> + <dd>The source type, one of "file", "error", "audit", "trace", "library"</dd> + <dt><code>CODE_FILE</code></dt> + <dd>The name of the file emitting the log record</dd> + <dt><code>CODE_LINE</code></dt> + <dd>The line number of the file emitting the log record</dd> + <dt><code>CODE_FUNC</code></dt> + <dd>The name of the function emitting the log record</dd> + </dl> + <h2> <a name="log_examples">Examples</a> </h2> -- 1.8.5.3

When a virError is raised, pass the error domain and code onto the systemd journald using metadata fields. This allows error messages to be queried by code eg $ journalctl LIBVIRT_CODE=43 Signed-off-by: Daniel P. Berrange <berrange(a)redhat.com&gt; --- docs/logging.html.in | 4 ++++ src/util/virerror.c | 8 +++++++- 2 files changed, 11 insertions(+), 1 deletion(-) diff --git a/docs/logging.html.in b/docs/logging.html.in index 08afa5c..f8c57f8 100644 --- a/docs/logging.html.in +++ b/docs/logging.html.in @@ -173,6 +173,10 @@ <dd>The line number of the file emitting the log record</dd> <dt><code>CODE_FUNC</code></dt> <dd>The name of the function emitting the log record</dd> + <dt><code>LIBVIRT_DOMAIN</code></dt> + <dd>The libvirt error domain (values from virErrorDomain enum), if LIBVIRT_SOURCE="error"</dd> + <dt><code>LIBVIRT_CODE</code></dt> + <dd>The libvirt error code (values from virErrorCode enum), if LIBVIRT_SOURCE="error"</dd> </dl> <h2> diff --git a/src/util/virerror.c b/src/util/virerror.c index 74c6807..820e1ad 100644 --- a/src/util/virerror.c +++ b/src/util/virerror.c @@ -649,6 +649,11 @@ virRaiseErrorFull(const char *filename ATTRIBUTE_UNUSED, virErrorPtr to; char *str; int priority; + virLogMetadata meta[] = { + { .key = "LIBVIRT_DOMAIN", .s = NULL, .iv = domain }, + { .key = "LIBVIRT_CODE", .s = NULL, .iv = code }, + { .key = NULL }, + }; /* * All errors are recorded in thread local storage @@ -703,10 +708,11 @@ virRaiseErrorFull(const char *filename ATTRIBUTE_UNUSED, priority = virErrorLevelPriority(level); if (virErrorLogPriorityFilter) priority = virErrorLogPriorityFilter(to, priority); + virLogMessage(virErrorLogPriorityFilter ? VIR_LOG_FROM_FILE : VIR_LOG_FROM_ERROR, priority, filename, linenr, funcname, - NULL, "%s", str); + meta, "%s", str); errno = save_errno; } -- 1.8.5.3

Signed-off-by: Daniel P. Berrange <berrange(a)redhat.com&gt; --- src/util/virlog.h | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/util/virlog.h b/src/util/virlog.h index f400824..6ba2daa 100644 --- a/src/util/virlog.h +++ b/src/util/virlog.h @@ -45,11 +45,11 @@ typedef enum { } virLogDestination; typedef enum { - VIR_LOG_FROM_FILE, - VIR_LOG_FROM_ERROR, - VIR_LOG_FROM_AUDIT, - VIR_LOG_FROM_TRACE, - VIR_LOG_FROM_LIBRARY, + VIR_LOG_FROM_FILE, /* General debugging */ + VIR_LOG_FROM_ERROR, /* Errors reported */ + VIR_LOG_FROM_AUDIT, /* Audit operations */ + VIR_LOG_FROM_TRACE, /* DTrace probe pointers */ + VIR_LOG_FROM_LIBRARY, /* 3rd party libraries */ VIR_LOG_FROM_LAST, } virLogSource; -- 1.8.5.3

When probing QEMU capabilities fails for a binary generate a log message with MESSAGE_ID==8ae2f3fb-2dbe-498e-8fbd-012d40afa361. This can be directly queried from journald based on the UUID instead of needing string grep. This lets tools like libguestfs' bug reporting tool trivially do automated sanity tests on the host they're running on. $ journalctl MESSAGE_ID=8ae2f3fb-2dbe-498e-8fbd-012d40afa361 Feb 21 17:11:01 localhost.localdomain lt-libvirtd[9196]: Failed to probe capabilities for /bin/qemu-system-alpha: internal error: Child process (LC_ALL=C LD_LIBRARY_PATH= /home/berrange/src/virt/libvirt/src/.libs PATH=/usr/lib64/ ccache:/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin: /usr/bin:/root/bin HOME=/root USER=root LOGNAME=root /bin/qemu-system-alpha -help) unexpected exit status 127: /bin/qemu-system-alpha: error while loading shared libraries: libglapi.so.0: cannot open shared object file: No such file or directory $ journalctl MESSAGE_ID=8ae2f3fb-2dbe-498e-8fbd-012d40afa361 --output=json { ...snip... "LIBVIRT_SOURCE" : "file", "PRIORITY" : "3", "CODE_FILE" : "qemu/qemu_capabilities.c", "CODE_LINE" : "2770", "CODE_FUNC" : "virQEMUCapsLogProbeFailure", "MESSAGE_ID" : "8ae2f3fb-2dbe-498e-8fbd-012d40afa361", "LIBVIRT_QEMU_BINARY" : "/bin/qemu-system-xtensa", "MESSAGE" : "Failed to probe capabilities for /bin/qemu-system-xtensa: internal error: Child process (LC_ALL=C LD_LIBRARY_PATH=/home/berrange /src/virt/libvirt/src/.libs PATH=/usr/lib64/ccache:/usr/local/sbin: /usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin:/root/bin HOME=/root USER=root LOGNAME=root /bin/qemu-system-xtensa -help) unexpected exit status 127: /bin/qemu-system-xtensa: error while loading shared libraries: libglapi.so.0: cannot open shared object file: No such file or directory\n" } Signed-off-by: Daniel P. Berrange <berrange(a)redhat.com&gt; --- docs/logging.html.in | 44 ++++++++++++++++++++++++++++++++++++++++++++ src/qemu/qemu_capabilities.c | 30 ++++++++++++++++++++++++++++-- 2 files changed, 72 insertions(+), 2 deletions(-) diff --git a/docs/logging.html.in b/docs/logging.html.in index f8c57f8..ed8e7e3 100644 --- a/docs/logging.html.in +++ b/docs/logging.html.in @@ -179,6 +179,50 @@ <dd>The libvirt error code (values from virErrorCode enum), if LIBVIRT_SOURCE="error"</dd> </dl> + <h3><a name="journaldids">Well known message ID values</a></h3> + + <p> + Certain areas of the code will emit log records tagged with well known + unique id values, which are guaranteed never to change in the future. + This allows applications to identify critical log events without doing + string matching on the <code>MESSAGE</code> field. + </p> + + <dl> + <dt><code>MESSAGE_ID=8ae2f3fb-2dbe-498e-8fbd-012d40afa361</code></dt> + <dd>Generated by the QEMU driver when it identifies a QEMU system + emulator binary, but is unable to extract information about its + capabilities. This is usually an indicator of a broken QEMU + build or installation. When this is emitted, the <code>LIBVIRT_QEMU_BINARY</code> + message field will provide the full path of the QEMU binary that failed. + </dd> + </dl> + + <p> + The <code>journalctl</code> commnd can be used to search the journal + matching on specific message ID values + </p> + + <pre> + $ journalctl MESSAGE_ID=8ae2f3fb-2dbe-498e-8fbd-012d40afa361 --output=json + { ...snip... + "LIBVIRT_SOURCE" : "file", + "PRIORITY" : "3", + "CODE_FILE" : "qemu/qemu_capabilities.c", + "CODE_LINE" : "2770", + "CODE_FUNC" : "virQEMUCapsLogProbeFailure", + "MESSAGE_ID" : "8ae2f3fb-2dbe-498e-8fbd-012d40afa361", + "LIBVIRT_QEMU_BINARY" : "/bin/qemu-system-xtensa", + "MESSAGE" : "Failed to probe capabilities for /bin/qemu-system-xtensa:" \ + "internal error: Child process (LC_ALL=C LD_LIBRARY_PATH=/home/berrange" \ + "/src/virt/libvirt/src/.libs PATH=/usr/lib64/ccache:/usr/local/sbin:" \ + "/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin:/root/bin HOME=/root " \ + "USER=root LOGNAME=root /bin/qemu-system-xtensa -help) unexpected " \ + "exit status 127: /bin/qemu-system-xtensa: error while loading shared " \ + "libraries: libglapi.so.0: cannot open shared object file: No such " \ + "file or directory\n" } + </pre> + <h2> <a name="log_examples">Examples</a> </h2> diff --git a/src/qemu/qemu_capabilities.c b/src/qemu/qemu_capabilities.c index d618b3f..76a8c73 100644 --- a/src/qemu/qemu_capabilities.c +++ b/src/qemu/qemu_capabilities.c @@ -2754,6 +2754,28 @@ cleanup: } +#define MESSAGE_ID_CAPS_PROBE_FAILURE "8ae2f3fb-2dbe-498e-8fbd-012d40afa361" + +static void +virQEMUCapsLogProbeFailure(const char *binary) +{ + virLogMetadata meta[] = { + { .key = "MESSAGE_ID", .s = MESSAGE_ID_CAPS_PROBE_FAILURE, .iv = 0 }, + { .key = "LIBVIRT_QEMU_BINARY", .s = binary, .iv = 0 }, + { .key = NULL }, + }; + virErrorPtr err = virGetLastError(); + + virLogMessage(VIR_LOG_FROM_FILE, + VIR_LOG_WARN, + __FILE__, __LINE__, __func__, + meta, + _("Failed to probe capabilities for %s: %s"), + binary, err && err->message ? err->message : + _("unknown failure")); +} + + virQEMUCapsPtr virQEMUCapsNewForBinary(const char *binary, const char *libDir, uid_t runUid, @@ -2785,12 +2807,16 @@ virQEMUCapsPtr virQEMUCapsNewForBinary(const char *binary, goto error; } - if ((rv = virQEMUCapsInitQMP(qemuCaps, libDir, runUid, runGid)) < 0) + if ((rv = virQEMUCapsInitQMP(qemuCaps, libDir, runUid, runGid)) < 0) { + virQEMUCapsLogProbeFailure(binary); goto error; + } if (!qemuCaps->usedQMP && - virQEMUCapsInitHelp(qemuCaps, runUid, runGid) < 0) + virQEMUCapsInitHelp(qemuCaps, runUid, runGid) < 0) { + virQEMUCapsLogProbeFailure(binary); goto error; + } return qemuCaps; -- 1.8.5.3