The problem with the original virLogParseOutputs method was that the way it
parsed the input, walking the string char by char and using absolute jumps
depending on the virLogDestination type, was rather complicated to read.
This patch utilizes virStringSplit method twice, first time to filter out any
spaces and split the input to individual log outputs and then for each
individual output to tokenize it by to the parts according to our
PRIORITY:DESTINATION?(:DATA) format. Also, to STREQLEN for matching destination
was replaced with virDestinationTypeFromString call.
In order to refactor the ugly virLogParseOutputs method, this is a neat way of
finding out whether the destination type (in the form of a string) user
provided is a valid one. As a bonus, if it turns out it is valid, we get the
actual enum which will later be passed to any of virLogAddOutput methods right
away.
Instead of misusing a const string to hold up runtime allocated
data, introduce new variable @hoststr and obey const correctness.
==6879== 15 bytes in 1 blocks are definitely lost in loss record 68 of 1,064
==6879== at 0x4C29F80: malloc (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so)
==6879== by 0xA7DDF97: vasprintf (in /lib64/libc-2.21.so)
==6879== by 0x552BBC6: virVasprintfInternal (virstring.c:493)
==6879== by 0x552BCDB: virAsprintfInternal (virstring.c:514)
==6879== by 0x54FA44C: virLogHostnameString (virlog.c:468)
==6879== by 0x54FAB0F: virLogVMessage (virlog.c:645)
==6879== by 0x54FA680: virLogMessage (virlog.c:531)
==6879== by 0x54FBBF4: virLogParseOutputs (virlog.c:1130)
==6879== by 0x11CB4F: daemonSetupLogging (libvirtd.c:685)
==6879== by 0x11E137: main (libvirtd.c:1297)
Signed-off-by: Michal Privoznik <mprivozn@redhat.com>
Once @hostname is printed into @hoststr we don't need it anymore.
==6879== 5 bytes in 1 blocks are definitely lost in loss record 10 of 1,064
==6879== at 0x4C29F80: malloc (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so)
==6879== by 0xA7ED599: strdup (in /lib64/libc-2.21.so)
==6879== by 0x552C126: virStrdup (virstring.c:726)
==6879== by 0x553B13E: virGetHostnameImpl (virutil.c:720)
==6879== by 0x553B1BF: virGetHostnameQuiet (virutil.c:741)
==6879== by 0x54FA3FD: virLogHostnameString (virlog.c:462)
==6879== by 0x54FAB0F: virLogVMessage (virlog.c:645)
==6879== by 0x54FA680: virLogMessage (virlog.c:531)
==6879== by 0x54FBBF4: virLogParseOutputs (virlog.c:1130)
==6879== by 0x11CB4F: daemonSetupLogging (libvirtd.c:685)
==6879== by 0x11E137: main (libvirtd.c:1297)
Signed-off-by: Michal Privoznik <mprivozn@redhat.com>
On the very first log message we send to any output, we include
the libvirt version number and package string. In some bug reports
we have been given libvirtd.log files that came from a different
host than the corresponding /var/log/libvirt/qemu log files. So
extend the initial log message to include the hostname too.
eg on first log message we would now see:
$ libvirtd
2015-12-04 17:35:36.610+0000: 20917: info : libvirt version: 1.3.0
2015-12-04 17:35:36.610+0000: 20917: info : hostname: dhcp-1-180.lcy.redhat.com
2015-12-04 17:35:36.610+0000: 20917: error : qemuMonitorIO:687 : internal error: End of file from monitor
Signed-off-by: Daniel P. Berrange <berrange@redhat.com>
It is often helpful to know which version of libvirt and QEMU
was present when a guest was first launched. Ensure this info
is written into the QEMU log file for each guest.
Recent changes to the module seemed to have caused Coverity to find a new
issue regarding the failure to check the return from a sendmsg. The code
doesn't seem to care about the return status, so just added an ignore_value
to keep Coverity quiet.
virLogParseDefaultPriority's successful return value is the same as
virLogSetDefaultPriority's successful return value. So it should be 0
rather than the parsed log level.
Signed-off-by: Zhou Yimin <zhouyimin@huawei.com>
A earlier commit changed the global log buffer so that it only
records messages that are explicitly requested via the log
filters setting. This removes the performance burden, and
improves the signal/noise ratio for messages in the global
buffer. At the same time though, it is somewhat pointless, since
all the recorded log messages are already going to be sent to an
explicit log output like syslog, stderr or the journal. The
global log buffer is thus just duplicating this data on stderr
upon crash.
The log_buffer_size config parameter is left in the augeas
lens to prevent breakage for users on upgrade. It is however
completely ignored hereafter.
Signed-off-by: Daniel P. Berrange <berrange@redhat.com>
Currently the log filter strings are used in a string comparison
against the source filename each time log message is emitted.
If no log filters at all are set, there's obviously no string
comparison to be done. If any single log filter is set though,
this imposes a compute burden on every logging call even if logs
from the file in question are disabled. This string comparison
must also be done while the logging mutex is held, which has
implications for concurrency when multiple threads are emitting
log messages.
This changes the log filtering to be done based on the virLogSource
object name. The virLogSource struct is extended to contain
'serial' and 'priority' fields. Any time the global log filter
rules are changed a global serial number is incremented. When a
log message is emitted, the serial in the virLogSource instance
is compared with the global serial number. If out of date, then
the 'priority' field in the virLogSource instance is updated based
on the new filter rules. The 'priority' field is checked to see
whether the log message should be sent to the log outputs.
The comparisons of the 'serial' and 'priority' fields are done
with no locks held. So in the common case each logging call has
an overhead of 2 integer comparisons, with no locks held. Only
if the decision is made to forward the message to the log output,
or if the 'serial' value is out of date do locks need to be
acquired.
Technically the comparisons of the 'serial' and 'priority' fields
should be done with locks held, or using atomic operations. Both
of these options have a notable performance impact, however, and
since all writes a protected by a global mutex, it is believed
that worst case behaviour where the fields are read concurrently
with being written would merely result in an mistaken emission
or dropping of the log message in question. This is an acceptable
tradeoff for the performance benefit of avoiding locking.
As a quick benchmark, a demo program that registers 500 file
descriptors with the event loop (eg equiv of 500 QEMU monitor
commands), creates pending read I/O on every FD, and then runs
virEventRunDefaultImpl() took 4.6 seconds to do 51200 iterations.
After this optimization it only takes 3.3 seconds, with the log
APIs no longer being a relevant factor in the running time.
Signed-off-by: Daniel P. Berrange <berrange@redhat.com>
Any source file which calls the logging APIs now needs
to have a VIR_LOG_INIT("source.name") declaration at
the start of the file. This provides a static variable
of the virLogSource type.
Signed-off-by: Daniel P. Berrange <berrange@redhat.com>
As part of the goal to get away from doing string matching on
filenames when deciding whether to emit a log message, turn
the virLogSource enum into a struct which contains a log
"name". There will eventually be one virLogSource instance
statically declared per source file. To minimise churn in this
commit though, a single global instance is used.
Signed-off-by: Daniel P. Berrange <berrange@redhat.com>
The error reporting code will invoke a callback when any error
is raised and the default callback will print to stderr. The
virRaiseErrorFull method also sends all error messages on to the
logging code, which also prints to stderr by default. To avoid
duplicated data on stderr, the logging code has some logic to
skip emission when no log outputs are configured, which checks
whether the virLogSource == VIR_LOG_FROM_ERROR.
Meanwhile the libvirtd daemon can register another callback which
is used to reduce log message priority from error to a lower level.
When this is used we do want messages to end up on stderr, so the
error code will conditionally use either VIR_LOG_FROM_FILE or
VIR_LOG_FROM_ERROR depending on whether such a callback is provided.
This will all complicate later refactoring. By pushing the checks
for whether a log output is present up a level into the error code,
the special cases can be isolated in one place.
Signed-off-by: Daniel P. Berrange <berrange@redhat.com>
With the vast number of log debug statements in the code, the
logging framework has a measurable performance impact on libvirt
code, particularly in the daemon event loop.
The global log buffer records every single log message triggered
whether anyone cares to see them or not. This makes it impossible
to eliminate the overhead of printf format expansions in any of
the logging code. It is possible to disable the global log buffer
in libvirtd itself, but this doesn't help client side library
code. Also even if disabled by the config file, the existence of
the feature makes other performance improvements in the logging
layer impossible.
Instead of logging every single message to the global buffer, only
log messages that pass the log filters. This if libvirtd is set
to have log_filters="1:libvirt 1:qemu" the global log buffer will
only get filled with those messages instead of everything. This
reduces the performance burden, as well as improving the signal
to noise ratio of the log buffer.
As a quick benchmark, a demo program that registers 500 file
descriptors with the event loop (eg equiv of 500 QEMU monitor
commands), creates pending read I/O on every FD, and then runs
virEventRunDefaultImpl() took 1 minute 40 seconds to do 51200
iterations with nearly all the time shown against the logging
code. After this optimization it only takes 4.6 seconds.
Signed-off-by: Daniel P. Berrange <berrange@redhat.com>
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@redhat.com>
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@redhat.com>
Most of our code base uses space after comma but not before;
fix the remaining uses before adding a syntax check.
* src/util/vircommand.c: Consistently use commas.
* src/util/virlog.c: Likewise.
* src/util/virnetdevbandwidth.c: Likewise.
* src/util/virnetdevmacvlan.c: Likewise.
* src/util/virnetdevvportprofile.c: Likewise.
* src/util/virnetlink.c: Likewise.
* src/util/virpci.c: Likewise.
* src/util/virsysinfo.c: Likewise.
* src/util/virusb.c: Likewise.
Signed-off-by: Eric Blake <eblake@redhat.com>
Unconditional use of getenv is not secure in setuid env.
While not all libvirt code runs in a setuid env (since
much of it only exists inside libvirtd) this is not always
clear to developers. So make all the code paranoid, even
if it only ever runs inside libvirtd.
Signed-off-by: Daniel P. Berrange <berrange@redhat.com>
We must not allow file/syslog/journald log outputs when running
setuid since they can be abused to do bad things. In particular
the 'file' output can be used to overwrite files.
Signed-off-by: Daniel P. Berrange <berrange@redhat.com>
In Fedora 20, libvirt_lxc crashes immediately at startup with a
trace
#0 0x00007f0cddb653ec in free () from /lib64/libc.so.6
#1 0x00007f0ce0e16f4a in virFree (ptrptr=ptrptr@entry=0x7f0ce1830058) at util/viralloc.c:580
#2 0x00007f0ce0e2764b in virResetError (err=0x7f0ce1830030) at util/virerror.c:354
#3 0x00007f0ce0e27a5a in virResetLastError () at util/virerror.c:387
#4 0x00007f0ce0e28858 in virEventRegisterDefaultImpl () at util/virevent.c:233
#5 0x00007f0ce0db47c6 in main (argc=11, argv=0x7fff4596c328) at lxc/lxc_controller.c:2352
Normally virInitialize calls virErrorInitialize and
virThreadInitialize, but we don't link to libvirt.so
in libvirt_lxc, and nor did we ever call the error
or thread initializers.
I have absolutely no idea how this has ever worked, let alone
what caused it to stop working in Fedora 20.
In addition not all code paths from virLogSetFromEnv will
ensure virLogInitialize is called correctly, which is another
possible crash scenario.
Signed-off-by: Daniel P. Berrange <berrange@redhat.com>
The log message regex has been
[0-9]{4}-[0-9]{2}-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}\.[0-9]{3}\+[0-9]{4}: [0-9]+: debug|info|warning|error :
The precedence of '|' is high though, so this is equivalent to matching
[0-9]{4}-[0-9]{2}-[0-9]{2} [0-9]{2}:[0-9]{2}:[0-9]{2}\.[0-9]{3}\+[0-9]{4}: [0-9]+: debug
Or
info
Or
warning
Or
error :
Which is clearly not what it should have done. This caused the code to
skip over things which are not log messages. The solution is to simply
add brackets.
A test case is also added to validate correctness.
Signed-off-by: Daniel P. Berrange <berrange@redhat.com>
The VIR_FREE() macro will cast away any const-ness. This masked a
number of places where we passed a 'const char *' string to
VIR_FREE. Fortunately in all of these cases, the variable was not
in fact const data, but a heap allocated string. Fix all the
variable declarations to reflect this.
Signed-off-by: Daniel P. Berrange <berrange@redhat.com>
The journald code would crash if a NULL was passed for the
filename / funcname in the logging code. This shouldn't
happen in general, but it is better to be safe, since there
have been bugs triggering this.
Signed-off-by: Daniel P. Berrange <berrange@redhat.com>
Convert the type of loop iterators named 'i', 'j', k',
'ii', 'jj', 'kk', to be 'size_t' instead of 'int' or
'unsigned int', also santizing 'ii', 'jj', 'kk' to use
the normal 'i', 'j', 'k' naming
Signed-off-by: Daniel P. Berrange <berrange@redhat.com>
Actually, I'm turning this function into a macro as filename,
function name and line number needs to be passed. The new
function virAsprintfInternal is introduced with the extended set
of arguments.
Call virLogVMessage instead of virLogMessage, since libudev
called us with a va_list object, not a list of arguments.
Honor message priority and strip the trailing newline.
https://bugzilla.redhat.com/show_bug.cgi?id=969152
I noticed several unusual spacings in for loops, and decided to
fix them up. See the next commit for the syntax check that found
all of these.
* examples/domsuspend/suspend.c (main): Fix spacing.
* python/libvirt-override.c: Likewise.
* src/conf/interface_conf.c: Likewise.
* src/security/virt-aa-helper.c: Likewise.
* src/util/virconf.c: Likewise.
* src/util/virhook.c: Likewise.
* src/util/virlog.c: Likewise.
* src/util/virsocketaddr.c: Likewise.
* src/util/virsysinfo.c: Likewise.
* src/util/viruuid.c: Likewise.
* src/vbox/vbox_tmpl.c: Likewise.
* src/xen/xen_hypervisor.c: Likewise.
* tools/virsh-domain-monitor.c (vshDomainStateToString): Drop
default case, to let compiler check us.
* tools/virsh-domain.c (vshDomainVcpuStateToString): Likewise.
Signed-off-by: Eric Blake <eblake@redhat.com>
POSIX says pthread_t is opaque. We can't guarantee if it is scaler
or a pointer, nor what size it is; and BSD differs from Linux.
We've also had reports of gcc complaining on attempts to cast it,
if we use a cast to the wrong type (for example, pointers have to be
cast to void* or intptr_t before being narrowed; while casting a
function return of scalar pthread_t to void* triggers a different
warning).
Give up on casts, and use unions to get at decent bits instead. And
rather than futz around with figuring which 32 bits of a potentially
64-bit pointer are most likely to be unique, convert the rest of
the code base to use 64-bit values when using a debug id.
Based on a report by Guido Günther against kFreeBSD, but with a
fix that doesn't regress commit 4d970fd29 for FreeBSD.
* src/util/virthreadpthread.c (virThreadSelfID, virThreadID): Use
union to get at a decent bit representation of thread_t bits.
* src/util/virthread.h (virThreadSelfID, virThreadID): Alter
signature.
* src/util/virthreadwin32.c (virThreadSelfID, virThreadID):
Likewise.
* src/qemu/qemu_domain.h (qemuDomainJobObj): Alter type of owner.
* src/qemu/qemu_domain.c (qemuDomainObjTransferJob)
(qemuDomainObjSetJobPhase, qemuDomainObjReleaseAsyncJob)
(qemuDomainObjBeginNestedJob, qemuDomainObjBeginJobInternal): Fix
clients.
* src/util/virlog.c (virLogFormatString): Likewise.
* src/util/vireventpoll.c (virEventPollInterruptLocked):
Likewise.
Signed-off-by: Eric Blake <eblake@redhat.com>
The source code base needs to be adapted as well. Some files
include virutil.h just for the string related functions (here,
the include is substituted to match the new file), some include
virutil.h without any need (here, the include is removed), and
some require both.
When we write a log message into a log, we separate thread ID from
timestamp using ": ". However, when storing the message into the ring
buffer, we omitted the separator, e.g.:
2013-02-27 11:49:11.852+00003745: ...
In debug mode, the bug failed to start vm
error: Failed to start domain rhel5u9
error: internal error Out of space while reading console log output:
...
When reading log output from QEMU/LXC we need to skip over any
libvirt log messages. Currently the QEMU driver checks for a
fixed string, but this is better done with a regex. Add a method
virLogProbablyLogMessage to do a regex check
Signed-off-by: Daniel P. Berrange <berrange@redhat.com>
Setting the log output prefix to 0 is not supported and in fact results
in the following message:
warning : virLogParseOutputs:1021 : Ignoring invalid log output setting.
