Instead of having each caller pass in the desired logfile name, pass in
the binary name instead. The logging code can then just derive a logfile
name by appending ".log".
Reviewed-by: Ján Tomko <jtomko@redhat.com>
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
Standardize on putting the _LAST enum value on the second line
of VIR_ENUM_IMPL invocations. Later patches that add string labels
to VIR_ENUM_IMPL will push most of these to the second line anyways,
so this saves some noise.
Signed-off-by: Cole Robinson <crobinso@redhat.com>
Missing semicolon at the end of macros can confuse some analyzers
(like cppcheck <filename>). VIR_ONCE_GLOBAL_INIT is almost
exclusively called without an ending semicolon, but let's
standardize on using one like the other macros.
Add a dummy struct definition at the end of the macro, so
the compiler will require callers to add a semicolon.
Reviewed-by: John Ferlan <jferlan@redhat.com>
Signed-off-by: Cole Robinson <crobinso@redhat.com>
Missing semicolon at the end of macros can confuse some analyzers
(like cppcheck <filename>), and we have a mix of semicolon and
non-semicolon usage through the code. Let's standardize on using
a semicolon for VIR_ENUM_IMPL calls.
Move the verify() statement to the end of the macro and drop
the semicolon, so the compiler will require callers to add a
semicolon.
While we are touching these call sites, standardize on putting
the closing parenth on its own line, as discussed here:
https://www.redhat.com/archives/libvir-list/2019-January/msg00750.html
Reviewed-by: John Ferlan <jferlan@redhat.com>
Signed-off-by: Cole Robinson <crobinso@redhat.com>
Essentially, bring back the old behaviour as of commit eba36a38 which
was later changed by commit ae06048bf5. Even though all the stderr
messages will eventually end up in the journal, we're not making use of
the fields journald provides.
https://bugzilla.redhat.com/show_bug.cgi?id=1592644
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Acked-by: Michal Privoznik <mprivozn@redhat.com>
All of the ones being removed are pulled in by internal.h. The only
exception is sanlock which expects the application to include <stdint.h>
before sanlock's headers, because sanlock prototypes use fixed width
int, but they don't include stdint.h themselves, so we have to leave
that one in place.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Acked-by: Michal Privoznik <mprivozn@redhat.com>
It doesn't really make sense for us to have stdlib.h and string.h but
not stdio.h in the internal.h header.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Acked-by: Michal Privoznik <mprivozn@redhat.com>
Currently, the functions return a pointer to the
destination buffer on success or NULL on failure.
Not only does this kind of error handling look quite
alien in the context of libvirt, where most functions
return zero on success and a negative int on failure,
but it's also somewhat pointless because unless there's
been a failure the returned pointer will be the same
one passed in by the user, thus offering no additional
value.
Change the functions so that they return an int
instead.
Signed-off-by: Andrea Bolognani <abologna@redhat.com>
This convenience macro was created for the simple cases
where the length of the source string and the size of the
destination buffer can be figued out with strlen() and
sizeof() respectively, so we should use it wherever
possible instead of open-coding parts of it.
Signed-off-by: Andrea Bolognani <abologna@redhat.com>
Historically we matched log filters with strstr(), and when switching to
fnmatch in cbb0fd3cfd, it was stated that
we would continue to match substrings, with "foo" being equivalent to
"*foo*". Unfortuntely I forget to provide the code to actually make that
happen. This fixes it to prepend and append "*". We don't bother to
check if the pattern already has a leading/trailing '*', because
"**foo**" will match the same as "*foo*".
Reviewed-by: Erik Skultety <eskultet@redhat.com>
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
Rather than specialcasing handling of the '*' character, use fnmatch()
to get normal shell wildcard syntax, as described in 'man glob(7)'.
To get an indication of the performance impact of using globs instead
of plain string matches, a test program was written. The list of all
260 log categories was extracted from the source. Then a typical log
filters setup was picked by creating an array of the strings "qemu",
"security", "util", "cgroup", "event", "object". Every filter string
was matched against every log category. Timing information showed that
using strstr() this took 8 microseconds, while fnmatch() took 114
microseconds.
IOW, fnmatch is 14 times slower than our existing strstr check. These
numbers show a worst case scenario that will never be hit, because it
is rare that every log category would have data output. The log category
matches are cached, so each category is only checked once no matter how
many log statements are emitted. IOW despite being slower, this will
be lost in the noise and have no consequence on real world logging
performance.
Reviewed-by: John Ferlan <jferlan@redhat.com>
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
This reverts commit 8daa593b07.
There are two undesirable aspects to the impl
- Only a bare wildcard is permitted
- The wildcard match is not performed in the order listed
Reviewed-by: John Ferlan <jferlan@redhat.com>
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
Since the introduction of log tuning capabilities to virt-admin by
@06b91785, this has been a much needed missing improvement on the way to
deprecate the global 'log_level'.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Ensure all enum cases are listed in switch statements.
Reviewed-by: John Ferlan <jferlan@redhat.com>
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
The fix for CVE-2018-6764 introduced a potential deadlock scenario
that gets triggered by the NSS module when virGetHostname() calls
getaddrinfo to resolve the hostname:
#0 0x00007f6e714b57e7 in futex_wait
#1 futex_wait_simple
#2 __pthread_once_slow
#3 0x00007f6e71d16e7d in virOnce
#4 0x00007f6e71d0997c in virLogInitialize
#5 0x00007f6e71d0a09a in virLogVMessage
#6 0x00007f6e71d09ffd in virLogMessage
#7 0x00007f6e71d0db22 in virObjectNew
#8 0x00007f6e71d0dbf1 in virObjectLockableNew
#9 0x00007f6e71d0d3e5 in virMacMapNew
#10 0x00007f6e71cdc50a in findLease
#11 0x00007f6e71cdcc56 in _nss_libvirt_gethostbyname4_r
#12 0x00007f6e724631fc in gaih_inet
#13 0x00007f6e72464697 in __GI_getaddrinfo
#14 0x00007f6e71d19e81 in virGetHostnameImpl
#15 0x00007f6e71d1a057 in virGetHostnameQuiet
#16 0x00007f6e71d09936 in virLogOnceInit
#17 0x00007f6e71d09952 in virLogOnce
#18 0x00007f6e714b5829 in __pthread_once_slow
#19 0x00007f6e71d16e7d in virOnce
#20 0x00007f6e71d0997c in virLogInitialize
#21 0x00007f6e71d0a09a in virLogVMessage
#22 0x00007f6e71d09ffd in virLogMessage
#23 0x00007f6e71d0db22 in virObjectNew
#24 0x00007f6e71d0dbf1 in virObjectLockableNew
#25 0x00007f6e71d0d3e5 in virMacMapNew
#26 0x00007f6e71cdc50a in findLease
#27 0x00007f6e71cdc839 in _nss_libvirt_gethostbyname3_r
#28 0x00007f6e71cdc724 in _nss_libvirt_gethostbyname2_r
#29 0x00007f6e7248f72f in __gethostbyname2_r
#30 0x00007f6e7248f494 in gethostbyname2
#31 0x000056348c30c36d in hosts_keys
#32 0x000056348c30b7d2 in main
Fortunately the extra stuff virGetHostname does is totally irrelevant to
the needs of the logging code, so we can just inline a call to the
native hostname() syscall directly.
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com>
At later point it might not be possible or even safe to use getaddrinfo(). It
can in turn result in a load of NSS module.
Notably, on a LXC container startup we may find ourselves with the guest
filesystem already having replaced the host one. Loading a NSS module
from the guest tree would allow a malicous guest to escape the
confinement of its container environment because libvirt will not yet
have locked it down.
Right-aligning backslashes when defining macros or using complex
commands in Makefiles looks cute, but as soon as any changes is
required to the code you end up with either distractingly broken
alignment or unnecessarily big diffs where most of the changes
are just pushing all backslashes a few characters to one side.
Generated using
$ git grep -El '[[:blank:]][[:blank:]]\\$' | \
grep -E '*\.([chx]|am|mk)$$' | \
while read f; do \
sed -Ei 's/[[:blank:]]*[[:blank:]]\\$/ \\/g' "$f"; \
done
Signed-off-by: Andrea Bolognani <abologna@redhat.com>
Commit 94c465d0 refactored the logging setup phase but introduced an
issue, where the daemon ignores verbose mode when there are no outputs
defined and the default must be used. The problem is that the default
output was determined too early, thus ignoring the potential '--verbose'
option taking effect. This patch postpones the creation of the default
output to the very last moment when nothing else can change. Since the
default output is only created during the init phase, it's safe to leave
the pointer as NULL for a while, but it will be set eventually, thus not
affecting runtime.
Patch also adjusts both the other daemons.
Resolves: https://bugzilla.redhat.com/show_bug.cgi?id=1442947
Signed-off-by: Erik Skultety <eskultet@redhat.com>
With glibc >= 2.25.90 writev() is only available if you explicitly
include sys/uio.h. This matches the documented requirements, but
older glibc and other *NIX pulled in writev indirectly so the bug
wasn't noticed previously.
Signed-off-by: Daniel P. Berrange <berrange@redhat.com>
There was an unhandled 'open' call which resulted in:
"error: Library function returned error but did not set virError"
Even if this happens during the daemon's start when we still don't have
any set of outputs defined yet, we can safely report an error, since we
automatically fallback to stderr which is fine even for both
running as a daemonized process, since this happens before the daemon
forks into the background, and running as a systemd service, since
systemd re-directs std outputs to journald by default.
Resolves: https://bugzilla.redhat.com/show_bug.cgi?id=1436060
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Along with an empty string, it should also be possible for users to pass
NULL to the public APIs which in turn would trigger a routine(future
work) responsible for defining an appropriate default logging output
given the current circumstances.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
These helpers will manage the log destination defaults (fetch/set). The reason
for this is to stay consistent with the current daemon's behaviour with respect
to /etc/libvirt/<daemon>.conf file, since both assignment of an empty string
or not setting the log output variable at all trigger the daemon's decision on
the default log destination which depends on whether the daemon runs daemonized
or not.
This patch also changes the logic of the selection of the default
logging output compared to how it is done now. The main difference though is
that we should only really care if we're running daemonized or not, disregarding
the fact of (not) having a TTY completely (introduced by commit eba36a3878) as
that should be of the libvirtd's parent concern (what FD it will pass to it).
Before:
if (godaemon || !hasTTY):
if (journald):
use journald
if (godaemon):
if (privileged):
use SYSCONFIG/libvirtd.log
else:
use XDG_CONFIG_HOME/libvirtd.log
else:
use stderr
After:
if (godaemon):
if (journald):
use journald
else:
if (privileged):
use SYSCONFIG/libvirtd.log
else:
use XDG_CONFIG_HOME/libvirtd.log
else:
use stderr
Signed-off-by: Erik Skultety <eskultet@redhat.com>
We have couple of functions that operate over NULL terminated
lits of strings. However, our naming sucks:
virStringJoin
virStringFreeList
virStringFreeListCount
virStringArrayHasString
virStringGetFirstWithPrefix
We can do better:
virStringListJoin
virStringListFree
virStringListFreeCount
virStringListHasString
virStringListGetFirstWithPrefix
Signed-off-by: Michal Privoznik <mprivozn@redhat.com>
Not every system out there has syslog, that's why we check for it
in our configure script. However, in 640b58abdf while fixing
another issue, some variables and functions are called that are
defined only when syslog.h is present. But these function
calls/variables were not guarded by #ifdef-s.
Signed-off-by: Michal Privoznik <mprivozn@redhat.com>
In both virLogParseOutput and virLogParseFilter, rather than returning
NULL, goto cleanup since it's possible that for each the first condition
passes, but the || condition doesn't and thus we leak memory.
Handling of outputs and filters has been changed in a way that splits
parsing and defining. Do the same thing for logging priority as well, this
however, doesn't need much of a preparation.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
This is mainly virLogAddOutputTo* which were replaced by virLogNewOutputTo* and
the previously poorly named ones virLogParseAndDefine* functions. All of these
are unnecessary now, since all the original callers were transparently switched
to the new model of separate parsing and defining logic.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Similar to outputs, parser should do parsing only, thus the 'define' logic
is going to be stripped from virLogParseAndDefineFilters by replacing calls to
this method to virLogSetFilters instead.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Since virLogParseAndDefineOutputs is going to be stripped from 'output defining'
logic, replace all relevant occurrences with virLogSetOutputs call to make the
change transparent to all original callers (daemons mostly).
Signed-off-by: Erik Skultety <eskultet@redhat.com>
This method will eventually replace virLogParseAndDefineFilters which
currently does both parsing and defining.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
This API is the entry point to output modification of the logger. Currently,
everything is done by virLogParseAndDefineOutputs. Parsing and defining will be
split into two operations both handled by this method transparently.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Abstraction added over parsing a single filter. The method parses potentially a
set of logging filters, while adding each filter logging object to a
caller-provided array.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Another abstraction added on the top of parsing a single logging output. This
method takes and parses the whole set of outputs, adding each single output
that has already been parsed into a caller-provided array. If the user-supplied
string contained duplicate outputs, only the last occurrence is taken into
account (all the others are removed from the list), so we silently avoid
duplicate logs.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Same as for outputs, introduce a new method, that is basically the same as
virLogParseAndDefineFilter with the difference that it does not define the
filter. It rather returns a newly created object that needs to be inserted into
a list and then defined separately.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Introduce a method to parse an individual logging output. The difference
compared to the virLogParseAndDefineOutput is that this method does not define
the output, instead it makes use of the virLogNewOutputTo* methods introduced
in the previous patch and just returns the virLogOutput object that has to be
added to a list of object which then can be defined as a whole via
virLogDefineOutputs. The idea remains still the same - split parsing and
defining of the logging primitives (outputs, filters).
Additionally, since virLogNewOutputTo* methods are now finally used,
ATTRIBUTE_UNUSED can be successfully removed from the methods' definitions,
since that was just to avoid compiler complaints about unused static functions.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Now that we're in the critical section, syslog connection can be re-opened
by issuing openlog, which is something that cannot be done beforehand, since
syslog keeps its file descriptor private and changing the tag earlier might
introduce a log inconsistency if something went wrong with preparing a new set
of logging outputs in order to replace the existing one.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Continuing with the effort to split output parsing and defining, these new
functions return a logging object reference instead of defining the output.
Eventually, these functions will replace the existing ones (virLogAddOutputTo*)
which will then be dropped.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Prepare a method that only defines a set of filters. It takes a list of
filters, preferably created by virLogParseFilters. The original set of filters
is reset and replaced by the new user-provided set of filters.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Prepare a method that only defines a set of outputs. It takes a list of
outputs, preferably created by virLogParseOutputs. The original set of outputs
is reset and replaced by the new user-provided set of outputs.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Outputs are a bit trickier than filters, since the user(config)-specified
set of outputs can contain duplicates. That would lead to logging the same
message twice. For compatibility reasons, we cannot just error out and forbid
the daemon to start if we find duplicate outputs which do not make sense.
Instead, we could silently take into account only the last occurrence of the
duplicate output and remove all the previous ones, so that the logger will not
try to use them when it is looping over all of its registered outputs.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
In order to later split output parsing and output defining, introduce a new
function which will create a new virLogOutput object which the parser will
insert into a list with the list being eventually defined.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
There is really no reason why we could not keep journald's fd within the
journald output object the same way as we do for regular file-based outputs.
By doing this we later won't have to special case the journald-based output
(due to the fd being globally shared) when replacing the existing set of outputs
with a new one. Additionally, by making this change, we don't need the
virLogCloseJournald routine anymore, plain virLogCloseFd will suffice.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Right now virLogParse* functions are doing both parsing and defining of filters
and outputs which should be two separate operations. Since the naming is
apparently a bit poor this patch renames these functions to
virLogParseAndDefine* which eventually will be replaced by virLogSet*.
Additionally, virLogParse{Filter,Output} will be later (after the split) reused,
so that these functions do exactly what the their name suggests.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
During first stage of virlog.c refactor, commit 0b231195 forgot to remove the
macro definition along with its usage.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
When a new filter is being defined, the return code is not handled properly,
thus triggering OOM error reporting routine (bug introduced by 51b2606f).
Signed-off-by: Erik Skultety <eskultet@redhat.com>
This is just a convenience method for discarding a list of filters instead of
using a 'for' loop everywhere. It is safe to pass -1 as the number of elements
in the list as well as passing NULL as list reference.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Provide a separate method to free a logging filter object. This will come handy
once a method to create an individual logging filter object is introduced.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
This is just a convenience method for discarding a list of outputs instead of
using a 'for' loop everywhere. It is safe to pass -1 as the number of elements
in the list as well as passing NULL as list reference.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Provide a separate method to free a logging output object. This will come handy
once a method to create an individual logging output object is introduced.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Same as with outputs; since the operations will be further divided into smaller
tasks, creating a filter will become a separate operation that will return
a reference to a newly created filter.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Right now, we define outputs one after another. However, the correct flow
should be to define a set of outputs as a whole unit. Therefore each output
should be first created, placed into an array/list and the list will be
defined. Output creation should be a separate operation, so an output will be
returned by a reference. From that perspective, it makes perfect sense to
only store pointers to actual outputs.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
In this particular case, reset is meant as clearing the whole list of
outputs/filters, not resetting it to a predefined default setting. Looking at
it from that perspective, returning the number of records removed doesn't help
the caller in any way (not that any of the callers would actually check for
it). Well, callers could detect an error from the number of successfully
removed records, but the only thing that can fail in virLogReset is force
closing a file descriptor in which case the error isn't propagated back to
virLogReset anyway. Conclusion: there is no practical use for having a return
type of 'int' rather than 'void' in this case.
Signed-off-by: Erik Skultety <eskultet@redhat.com>
Refactor series 0b231195 worked with virLogDestination type which, depending
on the compiler, might be (and probably will be) an unsigned data type.
However, virEnumFromString may return -1 in case of an error. So, when enum
happens to be unsigned, some compilers will naturally complain about foo:
'if (foo < 0)'
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: ...
