[libvirt] [PATCH v2 0/4] Reimplement logging wildcards to use full shell glob syntax

This series provides a more generalized support for wildcards in logging and removes the ordering constraint. Changed in v2: - Improve various config file comments (Erik) - Always use fnmatch as performance hit vs strstr will be inconsequential in real world (Dan). Daniel P. Berrangé (4): Revert "util: virlog: Introduce wildcard to log filters" log: rename virLogFlags to virLogFilterFlags to match docs log: support logging using shell wildcard syntax log: update docs for daemons to improve user understanding src/locking/test_virtlockd.aug.in | 2 +- src/locking/virtlockd.conf | 65 +++++++++++++++++++++++++---------- src/logging/test_virtlogd.aug.in | 2 +- src/logging/virtlogd.conf | 68 +++++++++++++++++++++++++----------- src/remote/libvirtd.conf | 72 +++++++++++++++++++++++---------------- src/remote/test_libvirtd.aug.in | 2 +- src/util/virlog.c | 49 +++----------------------- src/util/virlog.h | 3 +- 8 files changed, 146 insertions(+), 117 deletions(-) -- 2.14.3

This reverts commit 8daa593b0741452a78daea76075254ae7d3c6ab6. There are two undesirable aspects to the impl - Only a bare wildcard is permitted - The wildcard match is not performed in the order listed --- src/remote/libvirtd.conf | 4 +--- src/util/virlog.c | 44 +------------------------------------------- src/util/virlog.h | 1 - 3 files changed, 2 insertions(+), 47 deletions(-) diff --git a/src/remote/libvirtd.conf b/src/remote/libvirtd.conf index 7d823cf1ad..9c0080dc06 100644 --- a/src/remote/libvirtd.conf +++ b/src/remote/libvirtd.conf @@ -368,9 +368,7 @@ # Multiple filters can be defined in a single @filters, they just need to be # separated by spaces. Note that libvirt performs "first" match, i.e. if # there are concurrent filters, the first one that matches will be applied, -# given the order in log_filters with the exception of a wildcard filter, since -# that's only taken into account if no other filter has matched, so -# "4:* 1:util.pci" and "1:util.pci 4:*" are equivalent definitions. +# given the order in log_filters. # # e.g. to only get warning or errors from the remote layer and only errors # from the event layer: diff --git a/src/util/virlog.c b/src/util/virlog.c index 81a9dc4395..5810643e1b 100644 --- a/src/util/virlog.c +++ b/src/util/virlog.c @@ -497,38 +497,6 @@ virLogHostnameString(char **rawmsg, return 0; } -/* virLogFiltersFind: - * @filters: haystack - * @nfilters: haystack size - * @key1: primary string 'needle' - * @key2: secondary integer 'needle' - * - * Performs "first match" search on the input set of filters, using @key1 - * (string) and @key2 (integer) as primary and secondary keys respectively. - * Secondary key is only considered if primary key wasn't provided. - * - * Returns a pointer to the matched object or NULL if no match was found. - */ -static virLogFilterPtr -virLogFiltersFind(virLogFilterPtr *filters, - size_t nfilters, - const char *key1, - unsigned int key2) -{ - size_t i; - - if (!key1 && key2 == 0) - return NULL; - - for (i = 0; i < nfilters; i++) { - if ((key1 && STREQ(key1, filters[i]->match)) || - filters[i]->flags == key2) - return filters[i]; - } - - return NULL; -} - static void virLogSourceUpdate(virLogSourcePtr source) @@ -1441,8 +1409,7 @@ virLogFilterNew(const char *match, virLogFilterPtr ret = NULL; char *mdup = NULL; - virCheckFlags(VIR_LOG_STACK_TRACE | - VIR_LOG_WILDCARD, NULL); + virCheckFlags(VIR_LOG_STACK_TRACE, NULL); if (priority < VIR_LOG_DEBUG || priority > VIR_LOG_ERROR) { virReportError(VIR_ERR_INVALID_ARG, _("Invalid log priority %d"), @@ -1561,8 +1528,6 @@ virLogDefineOutputs(virLogOutputPtr *outputs, size_t noutputs) int virLogDefineFilters(virLogFilterPtr *filters, size_t nfilters) { - virLogFilterPtr rc; - if (virLogInitialize() < 0) return -1; @@ -1570,10 +1535,6 @@ virLogDefineFilters(virLogFilterPtr *filters, size_t nfilters) virLogResetFilters(); virLogFilters = filters; virLogNbFilters = nfilters; - - /* if there's a wildcard filter, update default priority */ - if ((rc = virLogFiltersFind(filters, nfilters, NULL, VIR_LOG_WILDCARD))) - virLogDefaultPriority = rc->priority; virLogUnlock(); return 0; @@ -1749,9 +1710,6 @@ virLogParseFilter(const char *src) match++; } - if (STREQ(match, "*")) - flags |= VIR_LOG_WILDCARD; - /* match string cannot comprise just from a single '+' */ if (!*match) { virReportError(VIR_ERR_INVALID_ARG, diff --git a/src/util/virlog.h b/src/util/virlog.h index 07b91f0b0a..8973f83b20 100644 --- a/src/util/virlog.h +++ b/src/util/virlog.h @@ -174,7 +174,6 @@ typedef void (*virLogCloseFunc) (void *data); typedef enum { VIR_LOG_STACK_TRACE = (1 << 0), - VIR_LOG_WILDCARD = (1 << 1) } virLogFlags; int virLogGetNbFilters(void); -- 2.14.3

On 04/23/2018 08:28 AM, Daniel P. Berrangé wrote:
This reverts commit 8daa593b0741452a78daea76075254ae7d3c6ab6.
There are two undesirable aspects to the impl
- Only a bare wildcard is permitted - The wildcard match is not performed in the order listed --- src/remote/libvirtd.conf | 4 +--- src/util/virlog.c | 44 +------------------------------------------- src/util/virlog.h | 1 - 3 files changed, 2 insertions(+), 47 deletions(-)
So that it's not forgotten 0-) before 4.3.0... Reviewed-by: John Ferlan <jferlan@redhat.com> Safe too as long as you also revert: 209d4d6f42a01829c68ef54b042a0c53ef0b22d3 to remove the description from news.xml I believe the rest can wait for 4.4.0, right? John
diff --git a/src/remote/libvirtd.conf b/src/remote/libvirtd.conf index 7d823cf1ad..9c0080dc06 100644 --- a/src/remote/libvirtd.conf +++ b/src/remote/libvirtd.conf @@ -368,9 +368,7 @@ # Multiple filters can be defined in a single @filters, they just need to be # separated by spaces. Note that libvirt performs "first" match, i.e. if # there are concurrent filters, the first one that matches will be applied, -# given the order in log_filters with the exception of a wildcard filter, since -# that's only taken into account if no other filter has matched, so -# "4:* 1:util.pci" and "1:util.pci 4:*" are equivalent definitions. +# given the order in log_filters. # # e.g. to only get warning or errors from the remote layer and only errors # from the event layer: diff --git a/src/util/virlog.c b/src/util/virlog.c index 81a9dc4395..5810643e1b 100644 --- a/src/util/virlog.c +++ b/src/util/virlog.c @@ -497,38 +497,6 @@ virLogHostnameString(char **rawmsg, return 0; }
-/* virLogFiltersFind: - * @filters: haystack - * @nfilters: haystack size - * @key1: primary string 'needle' - * @key2: secondary integer 'needle' - * - * Performs "first match" search on the input set of filters, using @key1 - * (string) and @key2 (integer) as primary and secondary keys respectively. - * Secondary key is only considered if primary key wasn't provided. - * - * Returns a pointer to the matched object or NULL if no match was found. - */ -static virLogFilterPtr -virLogFiltersFind(virLogFilterPtr *filters, - size_t nfilters, - const char *key1, - unsigned int key2) -{ - size_t i; - - if (!key1 && key2 == 0) - return NULL; - - for (i = 0; i < nfilters; i++) { - if ((key1 && STREQ(key1, filters[i]->match)) || - filters[i]->flags == key2) - return filters[i]; - } - - return NULL; -} -
static void virLogSourceUpdate(virLogSourcePtr source) @@ -1441,8 +1409,7 @@ virLogFilterNew(const char *match, virLogFilterPtr ret = NULL; char *mdup = NULL;
- virCheckFlags(VIR_LOG_STACK_TRACE | - VIR_LOG_WILDCARD, NULL); + virCheckFlags(VIR_LOG_STACK_TRACE, NULL);
if (priority < VIR_LOG_DEBUG || priority > VIR_LOG_ERROR) { virReportError(VIR_ERR_INVALID_ARG, _("Invalid log priority %d"), @@ -1561,8 +1528,6 @@ virLogDefineOutputs(virLogOutputPtr *outputs, size_t noutputs) int virLogDefineFilters(virLogFilterPtr *filters, size_t nfilters) { - virLogFilterPtr rc; - if (virLogInitialize() < 0) return -1;
@@ -1570,10 +1535,6 @@ virLogDefineFilters(virLogFilterPtr *filters, size_t nfilters) virLogResetFilters(); virLogFilters = filters; virLogNbFilters = nfilters; - - /* if there's a wildcard filter, update default priority */ - if ((rc = virLogFiltersFind(filters, nfilters, NULL, VIR_LOG_WILDCARD))) - virLogDefaultPriority = rc->priority; virLogUnlock();
return 0; @@ -1749,9 +1710,6 @@ virLogParseFilter(const char *src) match++; }
- if (STREQ(match, "*")) - flags |= VIR_LOG_WILDCARD; - /* match string cannot comprise just from a single '+' */ if (!*match) { virReportError(VIR_ERR_INVALID_ARG, diff --git a/src/util/virlog.h b/src/util/virlog.h index 07b91f0b0a..8973f83b20 100644 --- a/src/util/virlog.h +++ b/src/util/virlog.h @@ -174,7 +174,6 @@ typedef void (*virLogCloseFunc) (void *data);
typedef enum { VIR_LOG_STACK_TRACE = (1 << 0), - VIR_LOG_WILDCARD = (1 << 1) } virLogFlags;
int virLogGetNbFilters(void);

On Fri, Apr 27, 2018 at 09:38:06AM -0400, John Ferlan wrote:
On 04/23/2018 08:28 AM, Daniel P. Berrangé wrote:
This reverts commit 8daa593b0741452a78daea76075254ae7d3c6ab6.
There are two undesirable aspects to the impl
- Only a bare wildcard is permitted - The wildcard match is not performed in the order listed --- src/remote/libvirtd.conf | 4 +--- src/util/virlog.c | 44 +------------------------------------------- src/util/virlog.h | 1 - 3 files changed, 2 insertions(+), 47 deletions(-)
So that it's not forgotten 0-) before 4.3.0...
Reviewed-by: John Ferlan <jferlan@redhat.com>
Safe too as long as you also revert:
209d4d6f42a01829c68ef54b042a0c53ef0b22d3
to remove the description from news.xml
I believe the rest can wait for 4.4.0, right?
Yeah, that's fine with me. Regards, Daniel -- |: https://berrange.com -o- https://www.flickr.com/photos/dberrange :| |: https://libvirt.org -o- https://fstop138.berrange.com :| |: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|

Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- src/util/virlog.c | 2 +- src/util/virlog.h | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/src/util/virlog.c b/src/util/virlog.c index 5810643e1b..5262d613f6 100644 --- a/src/util/virlog.c +++ b/src/util/virlog.c @@ -87,7 +87,7 @@ VIR_ENUM_IMPL(virLogDestination, VIR_LOG_TO_OUTPUT_LAST, struct _virLogFilter { char *match; virLogPriority priority; - unsigned int flags; + unsigned int flags; /* bitwise OR of virLogFilterFlags */ }; static int virLogFiltersSerial = 1; diff --git a/src/util/virlog.h b/src/util/virlog.h index 8973f83b20..35dba16cfe 100644 --- a/src/util/virlog.h +++ b/src/util/virlog.h @@ -174,7 +174,7 @@ typedef void (*virLogCloseFunc) (void *data); typedef enum { VIR_LOG_STACK_TRACE = (1 << 0), -} virLogFlags; +} virLogFilterFlags; int virLogGetNbFilters(void); int virLogGetNbOutputs(void); -- 2.14.3

On 04/23/2018 08:28 AM, Daniel P. Berrangé wrote:
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- src/util/virlog.c | 2 +- src/util/virlog.h | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-)
Looks like your v1 already had an R-b too from Erik... Reviewed-by: John Ferlan <jferlan@redhat.com> John

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 wil 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. Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- src/util/virlog.c | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/src/util/virlog.c b/src/util/virlog.c index 5262d613f6..be9fc0cf78 100644 --- a/src/util/virlog.c +++ b/src/util/virlog.c @@ -40,6 +40,7 @@ #if HAVE_SYS_UN_H # include <sys/un.h> #endif +#include <fnmatch.h> #include "virerror.h" #include "virlog.h" @@ -508,7 +509,7 @@ virLogSourceUpdate(virLogSourcePtr source) size_t i; for (i = 0; i < virLogNbFilters; i++) { - if (strstr(source->name, virLogFilters[i]->match)) { + if (fnmatch(virLogFilters[i]->match, source->name, 0) == 0) { priority = virLogFilters[i]->priority; flags = virLogFilters[i]->flags; break; -- 2.14.3

On 04/23/2018 08:28 AM, Daniel P. Berrangé wrote:
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 wil never be hit, because it
s/wil/will
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.
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- src/util/virlog.c | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-)
Reviewed-by: John Ferlan <jferlan@redhat.com> John BTW: So whether this is available "everywhere" is a bit of an unknown to me - as in strstr would seemingly work on every arch, but fnmatch has this linux-ism wildcard thing going on which leaves a slight bit of doubt in my mind...

On Mon, Apr 30, 2018 at 11:05:48AM -0400, John Ferlan wrote:
On 04/23/2018 08:28 AM, Daniel P. Berrangé wrote:
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 wil never be hit, because it
s/wil/will
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.
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- src/util/virlog.c | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-)
Reviewed-by: John Ferlan <jferlan@redhat.com>
John
BTW: So whether this is available "everywhere" is a bit of an unknown to me - as in strstr would seemingly work on every arch, but fnmatch has this linux-ism wildcard thing going on which leaves a slight bit of doubt in my mind...
NB, we rely on gnulib to provide us fnmatch on all platforms Regards, Daniel -- |: https://berrange.com -o- https://www.flickr.com/photos/dberrange :| |: https://libvirt.org -o- https://fstop138.berrange.com :| |: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|

Strongly recommend against use of the log_levels setting since it creates overly verbose logs and has a serious performance impact. Describe the log filter syntax better and mention use of shell glob syntax. Also provide more realistic example of good settings to use. The libvirtd example is biased towards QEMU, but when the drivers split off each daemon can get its own more appropriate example. Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- src/locking/test_virtlockd.aug.in | 2 +- src/locking/virtlockd.conf | 65 ++++++++++++++++++++++++++----------- src/logging/test_virtlogd.aug.in | 2 +- src/logging/virtlogd.conf | 68 +++++++++++++++++++++++++++------------ src/remote/libvirtd.conf | 68 ++++++++++++++++++++++++--------------- src/remote/test_libvirtd.aug.in | 2 +- 6 files changed, 140 insertions(+), 67 deletions(-) diff --git a/src/locking/test_virtlockd.aug.in b/src/locking/test_virtlockd.aug.in index ad75286be6..f2f6979ef5 100644 --- a/src/locking/test_virtlockd.aug.in +++ b/src/locking/test_virtlockd.aug.in @@ -3,7 +3,7 @@ module Test_virtlockd = test Virtlockd.lns get conf = { "log_level" = "3" } - { "log_filters" = "3:remote 4:event" } + { "log_filters" = "1:locking 4:object 4:json 4:event 1:util" } { "log_outputs" = "3:syslog:virtlockd" } { "max_clients" = "1024" } { "admin_max_clients" = "5" } diff --git a/src/locking/virtlockd.conf b/src/locking/virtlockd.conf index 1a2b27d0b9..20085de9dd 100644 --- a/src/locking/virtlockd.conf +++ b/src/locking/virtlockd.conf @@ -8,46 +8,75 @@ # Logging level: 4 errors, 3 warnings, 2 information, 1 debug # basically 1 will log everything possible +# +# WARNING: USE OF THIS IS STRONGLY DISCOURAGED. +# +# WARNING: It outputs too much information to practically read. +# WARNING: The "log_filters" setting is recommended instead. +# +# WARNING: Journald applies rate limiting of messages and so libvirt +# WARNING: will limit "log_level" to only allow values 3 or 4 if +# WARNING: journald is the current output. +# +# WARNING: USE OF THIS IS STRONGLY DISCOURAGED. #log_level = 3 # Logging filters: # A filter allows to select a different logging level for a given category -# of logs -# The format for a filter is one of: -# x:name -# x:+name -# where name is a string which is matched against source file name, -# e.g., "remote", "qemu", or "util/json", the optional "+" prefix -# tells libvirt to log stack trace for each message matching name, -# and x is the minimal level where matching messages should be logged: +# of logs. The format for a filter is one of: +# +# level:match +# level:+match +# +# where 'match' is a string which is matched against the category +# given in the VIR_LOG_INIT() at the top of each libvirt source +# file, e.g., "remote", "qemu", or "util.json". The 'match' in the +# filter matches using shell wildcard syntax (see 'man glob(7)'). +# The 'match' is always treated a substring match. IOW a match +# string 'foo' is equivalent to '*foo*'. +# +# If 'match' contains the optional "+" prefix, it tells libvirt +# to log stack trace for each message matching name. +# +# 'level' is the minimal level where matching messages should +# be logged: +# # 1: DEBUG # 2: INFO # 3: WARNING # 4: ERROR # -# Multiple filter can be defined in a single @filters, they just need to be -# separated by spaces. +# Multiple filters can be defined in a single @filters, they just need to be +# separated by spaces. Note that libvirt performs "first" match, i.e. if +# there are concurrent filters, the first one that matches will be applied, +# given the order in log_filters. +# +# For the virtlockd daemon, a typical need is to capture information +# from the locking code and some of the utility code. Some utility +# code is very verbose and is generally not desired. A suitable filter +# string for debugging might be to turn off object, json & event logging, +# but enable the rest of the util and the locking code: # -# e.g. to only get warning or errors from the remote layer and only errors -# from the event layer: -#log_filters="3:remote 4:event" +#log_filters="1:locking 4:object 4:json 4:event 1:util" # Logging outputs: # An output is one of the places to save logging information # The format for an output can be: -# x:stderr +# level:stderr # output goes to stderr -# x:syslog:name +# level:syslog:name # use syslog for the output and use the given name as the ident -# x:file:file_path +# level:file:file_path # output to a file, with the given filepath -# In all case the x prefix is the minimal level, acting as a filter +# level:journald +# output to journald logging system +# In all cases 'level' is the minimal priority, acting as a filter # 1: DEBUG # 2: INFO # 3: WARNING # 4: ERROR # -# Multiple output can be defined, they just need to be separated by spaces. +# Multiple outputs can be defined, they just need to be separated by spaces. # e.g. to log all warnings and errors to syslog under the virtlockd ident: #log_outputs="3:syslog:virtlockd" # diff --git a/src/logging/test_virtlogd.aug.in b/src/logging/test_virtlogd.aug.in index 744f3246af..a29e7e3730 100644 --- a/src/logging/test_virtlogd.aug.in +++ b/src/logging/test_virtlogd.aug.in @@ -3,7 +3,7 @@ module Test_virtlogd = test Virtlogd.lns get conf = { "log_level" = "3" } - { "log_filters" = "3:remote 4:event" } + { "log_filters" = "1:logging 4:object 4:json 4:event 1:util" } { "log_outputs" = "3:syslog:virtlogd" } { "max_clients" = "1024" } { "admin_max_clients" = "5" } diff --git a/src/logging/virtlogd.conf b/src/logging/virtlogd.conf index c22b7737ef..8e3e977cdd 100644 --- a/src/logging/virtlogd.conf +++ b/src/logging/virtlogd.conf @@ -8,48 +8,76 @@ # Logging level: 4 errors, 3 warnings, 2 information, 1 debug # basically 1 will log everything possible +# +# WARNING: USE OF THIS IS STRONGLY DISCOURAGED. +# +# WARNING: It outputs too much information to practically read. +# WARNING: The "log_filters" setting is recommended instead. +# +# WARNING: Journald applies rate limiting of messages and so libvirt +# WARNING: will limit "log_level" to only allow values 3 or 4 if +# WARNING: journald is the current output. +# +# WARNING: USE OF THIS IS STRONGLY DISCOURAGED. #log_level = 3 # Logging filters: # A filter allows to select a different logging level for a given category -# of logs -# The format for a filter is one of: -# x:name -# x:+name -# where name is a string which is matched against source file name, -# e.g., "remote", "qemu", or "util/json", the optional "+" prefix -# tells libvirt to log stack trace for each message matching name, -# and x is the minimal level where matching messages should be logged: +# of logs. The format for a filter is one of: +# +# level:match +# level:+match +# +# where 'match' is a string which is matched against the category +# given in the VIR_LOG_INIT() at the top of each libvirt source +# file, e.g., "remote", "qemu", or "util.json". The 'match' in the +# filter matches using shell wildcard syntax (see 'man glob(7)'). +# The 'match' is always treated a substring match. IOW a match +# string 'foo' is equivalent to '*foo*'. +# +# If 'match' contains the optional "+" prefix, it tells libvirt +# to log stack trace for each message matching name. +# +# 'level' is the minimal level where matching messages should +# be logged: +# # 1: DEBUG # 2: INFO # 3: WARNING # 4: ERROR # -# Multiple filter can be defined in a single @filters, they just need to be -# separated by spaces. +# Multiple filters can be defined in a single @filters, they just need to be +# separated by spaces. Note that libvirt performs "first" match, i.e. if +# there are concurrent filters, the first one that matches will be applied, +# given the order in log_filters. +# +# +# For the virtlogd daemon, a typical need is to capture information +# from the logging code and some of the utility code. Some utility +# code is very verbose and is generally not desired. A suitable filter +# string for debugging might be to turn off object, json & event logging, +# but enable the rest of the util and the logging code: # -# e.g. to only get warning or errors from the remote layer and only errors -# from the event layer: -#log_filters="3:remote 4:event" +#log_filters="1:logging 4:object 4:json 4:event 1:util" # Logging outputs: # An output is one of the places to save logging information # The format for an output can be: -# x:stderr +# level:stderr # output goes to stderr -# x:syslog:name +# level:syslog:name # use syslog for the output and use the given name as the ident -# x:file:file_path +# level:file:file_path # output to a file, with the given filepath -# x:journald -# ouput to the systemd journal -# In all case the x prefix is the minimal level, acting as a filter +# level:journald +# output to journald logging system +# In all cases 'level' is the minimal priority, acting as a filter # 1: DEBUG # 2: INFO # 3: WARNING # 4: ERROR # -# Multiple output can be defined, they just need to be separated by spaces. +# Multiple outputs can be defined, they just need to be separated by spaces. # e.g. to log all warnings and errors to syslog under the virtlogd ident: #log_outputs="3:syslog:virtlogd" # diff --git a/src/remote/libvirtd.conf b/src/remote/libvirtd.conf index 9c0080dc06..8cee30832a 100644 --- a/src/remote/libvirtd.conf +++ b/src/remote/libvirtd.conf @@ -338,28 +338,39 @@ # Logging level: 4 errors, 3 warnings, 2 information, 1 debug # basically 1 will log everything possible -# Note: Journald may employ rate limiting of the messages logged -# and thus lock up the libvirt daemon. To use the debug level with -# journald you have to specify it explicitly in 'log_outputs', otherwise -# only information level messages will be logged. +# +# WARNING: USE OF THIS IS STRONGLY DISCOURAGED. +# +# WARNING: It outputs too much information to practically read. +# WARNING: The "log_filters" setting is recommended instead. +# +# WARNING: Journald applies rate limiting of messages and so libvirt +# WARNING: will limit "log_level" to only allow values 3 or 4 if +# WARNING: journald is the current output. +# +# WARNING: USE OF THIS IS STRONGLY DISCOURAGED. #log_level = 3 # Logging filters: # A filter allows to select a different logging level for a given category -# of logs -# The format for a filter is one of: -# x:name -# x:+name - -# where name is a string which is matched against the category -# given in the VIR_LOG_INIT() at the top of each libvirt source -# file, e.g., "remote", "qemu", or "util.json" (the name in the -# filter can be a substring of the full category name, in order -# to match multiple similar categories), the optional "+" prefix -# tells libvirt to log stack trace for each message matching -# name, and x is the minimal level where matching messages should -# be logged: - +# of logs. The format for a filter is one of: +# +# level:match +# level:+match +# +# where 'match' is a string which is matched against the category +# given in the VIR_LOG_INIT() at the top of each libvirt source +# file, e.g., "remote", "qemu", or "util.json". The 'match' in the +# filter matches using shell wildcard syntax (see 'man glob(7)'). +# The 'match' is always treated a substring match. IOW a match +# string 'foo' is equivalent to '*foo*'. +# +# If 'match' contains the optional "+" prefix, it tells libvirt +# to log stack trace for each message matching name. +# +# 'level' is the minimal level where matching messages should +# be logged: +# # 1: DEBUG # 2: INFO # 3: WARNING @@ -370,22 +381,27 @@ # there are concurrent filters, the first one that matches will be applied, # given the order in log_filters. # -# e.g. to only get warning or errors from the remote layer and only errors -# from the event layer: -#log_filters="3:remote 4:event" +# A typical need is to capture information from a hypervisor driver, +# public API entrypoints and some of the utility code. Some utility +# code is very verbose and is generally not desired. Taking the QEMU +# hypervisor as an example, a suitable filter string for debugging +# might be to turn off object, json & event logging, but enable the +# rest of the util code: +# +#log_filters="1:qemu 1:libvirt 4:object 4:json 4:event 1:util" # Logging outputs: # An output is one of the places to save logging information # The format for an output can be: -# x:stderr +# level:stderr # output goes to stderr -# x:syslog:name +# level:syslog:name # use syslog for the output and use the given name as the ident -# x:file:file_path +# level:file:file_path # output to a file, with the given filepath -# x:journald +# level:journald # output to journald logging system -# In all case the x prefix is the minimal level, acting as a filter +# In all cases 'level' is the minimal priority, acting as a filter # 1: DEBUG # 2: INFO # 3: WARNING diff --git a/src/remote/test_libvirtd.aug.in b/src/remote/test_libvirtd.aug.in index 2bd7ec1bd6..527e3d7d0d 100644 --- a/src/remote/test_libvirtd.aug.in +++ b/src/remote/test_libvirtd.aug.in @@ -49,7 +49,7 @@ module Test_libvirtd = { "admin_max_queued_clients" = "5" } { "admin_max_client_requests" = "5" } { "log_level" = "3" } - { "log_filters" = "3:remote 4:event" } + { "log_filters" = "1:qemu 1:libvirt 4:object 4:json 4:event 1:util" } { "log_outputs" = "3:syslog:libvirtd" } { "audit_level" = "2" } { "audit_logging" = "1" } -- 2.14.3

On 04/23/2018 08:28 AM, Daniel P. Berrangé wrote:
Strongly recommend against use of the log_levels setting since it creates overly verbose logs and has a serious performance impact.
Describe the log filter syntax better and mention use of shell glob syntax. Also provide more realistic example of good settings to use. The libvirtd example is biased towards QEMU, but when the drivers split off each daemon can get its own more appropriate example.
Signed-off-by: Daniel P. Berrangé <berrange@redhat.com> --- src/locking/test_virtlockd.aug.in | 2 +- src/locking/virtlockd.conf | 65 ++++++++++++++++++++++++++----------- src/logging/test_virtlogd.aug.in | 2 +- src/logging/virtlogd.conf | 68 +++++++++++++++++++++++++++------------ src/remote/libvirtd.conf | 68 ++++++++++++++++++++++++--------------- src/remote/test_libvirtd.aug.in | 2 +- 6 files changed, 140 insertions(+), 67 deletions(-)
diff --git a/src/locking/test_virtlockd.aug.in b/src/locking/test_virtlockd.aug.in index ad75286be6..f2f6979ef5 100644 --- a/src/locking/test_virtlockd.aug.in +++ b/src/locking/test_virtlockd.aug.in @@ -3,7 +3,7 @@ module Test_virtlockd =
test Virtlockd.lns get conf = { "log_level" = "3" } - { "log_filters" = "3:remote 4:event" } + { "log_filters" = "1:locking 4:object 4:json 4:event 1:util" } { "log_outputs" = "3:syslog:virtlockd" } { "max_clients" = "1024" } { "admin_max_clients" = "5" } diff --git a/src/locking/virtlockd.conf b/src/locking/virtlockd.conf index 1a2b27d0b9..20085de9dd 100644 --- a/src/locking/virtlockd.conf +++ b/src/locking/virtlockd.conf @@ -8,46 +8,75 @@
# Logging level: 4 errors, 3 warnings, 2 information, 1 debug # basically 1 will log everything possible +# +# WARNING: USE OF THIS IS STRONGLY DISCOURAGED. +# +# WARNING: It outputs too much information to practically read. +# WARNING: The "log_filters" setting is recommended instead. +# +# WARNING: Journald applies rate limiting of messages and so libvirt +# WARNING: will limit "log_level" to only allow values 3 or 4 if +# WARNING: journald is the current output. +# +# WARNING: USE OF THIS IS STRONGLY DISCOURAGED. #log_level = 3
# Logging filters: # A filter allows to select a different logging level for a given category -# of logs -# The format for a filter is one of: -# x:name -# x:+name -# where name is a string which is matched against source file name, -# e.g., "remote", "qemu", or "util/json", the optional "+" prefix -# tells libvirt to log stack trace for each message matching name, -# and x is the minimal level where matching messages should be logged: +# of logs. The format for a filter is one of: +# +# level:match +# level:+match +# +# where 'match' is a string which is matched against the category +# given in the VIR_LOG_INIT() at the top of each libvirt source +# file, e.g., "remote", "qemu", or "util.json". The 'match' in the +# filter matches using shell wildcard syntax (see 'man glob(7)'). +# The 'match' is always treated a substring match. IOW a match
s/treated a/treated as a/
+# string 'foo' is equivalent to '*foo*'. +# +# If 'match' contains the optional "+" prefix, it tells libvirt +# to log stack trace for each message matching name. +# +# 'level' is the minimal level where matching messages should +# be logged: +# # 1: DEBUG # 2: INFO # 3: WARNING # 4: ERROR # -# Multiple filter can be defined in a single @filters, they just need to be -# separated by spaces. +# Multiple filters can be defined in a single @filters, they just need to be
Probably should be log_filters not @filters
+# separated by spaces. Note that libvirt performs "first" match, i.e. if +# there are concurrent filters, the first one that matches will be applied, +# given the order in log_filters. +# +# For the virtlockd daemon, a typical need is to capture information +# from the locking code and some of the utility code. Some utility +# code is very verbose and is generally not desired. A suitable filter +# string for debugging might be to turn off object, json & event logging, +# but enable the rest of the util and the locking code: # -# e.g. to only get warning or errors from the remote layer and only errors -# from the event layer: -#log_filters="3:remote 4:event" +#log_filters="1:locking 4:object 4:json 4:event 1:util"
# Logging outputs: # An output is one of the places to save logging information # The format for an output can be: -# x:stderr +# level:stderr # output goes to stderr -# x:syslog:name +# level:syslog:name # use syslog for the output and use the given name as the ident -# x:file:file_path +# level:file:file_path # output to a file, with the given filepath -# In all case the x prefix is the minimal level, acting as a filter +# level:journald +# output to journald logging system +# In all cases 'level' is the minimal priority, acting as a filter # 1: DEBUG # 2: INFO # 3: WARNING # 4: ERROR # -# Multiple output can be defined, they just need to be separated by spaces. +# Multiple outputs can be defined, they just need to be separated by spaces. # e.g. to log all warnings and errors to syslog under the virtlockd ident: #log_outputs="3:syslog:virtlockd" # diff --git a/src/logging/test_virtlogd.aug.in b/src/logging/test_virtlogd.aug.in index 744f3246af..a29e7e3730 100644 --- a/src/logging/test_virtlogd.aug.in +++ b/src/logging/test_virtlogd.aug.in @@ -3,7 +3,7 @@ module Test_virtlogd =
test Virtlogd.lns get conf = { "log_level" = "3" } - { "log_filters" = "3:remote 4:event" } + { "log_filters" = "1:logging 4:object 4:json 4:event 1:util" } { "log_outputs" = "3:syslog:virtlogd" } { "max_clients" = "1024" } { "admin_max_clients" = "5" } diff --git a/src/logging/virtlogd.conf b/src/logging/virtlogd.conf index c22b7737ef..8e3e977cdd 100644 --- a/src/logging/virtlogd.conf +++ b/src/logging/virtlogd.conf @@ -8,48 +8,76 @@
# Logging level: 4 errors, 3 warnings, 2 information, 1 debug # basically 1 will log everything possible +# +# WARNING: USE OF THIS IS STRONGLY DISCOURAGED. +# +# WARNING: It outputs too much information to practically read. +# WARNING: The "log_filters" setting is recommended instead. +# +# WARNING: Journald applies rate limiting of messages and so libvirt +# WARNING: will limit "log_level" to only allow values 3 or 4 if +# WARNING: journald is the current output. +# +# WARNING: USE OF THIS IS STRONGLY DISCOURAGED. #log_level = 3
# Logging filters: # A filter allows to select a different logging level for a given category -# of logs -# The format for a filter is one of: -# x:name -# x:+name -# where name is a string which is matched against source file name, -# e.g., "remote", "qemu", or "util/json", the optional "+" prefix -# tells libvirt to log stack trace for each message matching name, -# and x is the minimal level where matching messages should be logged: +# of logs. The format for a filter is one of: +# +# level:match +# level:+match +# +# where 'match' is a string which is matched against the category +# given in the VIR_LOG_INIT() at the top of each libvirt source +# file, e.g., "remote", "qemu", or "util.json". The 'match' in the +# filter matches using shell wildcard syntax (see 'man glob(7)'). +# The 'match' is always treated a substring match. IOW a match
s/treated a/treated as a/
+# string 'foo' is equivalent to '*foo*'. +# +# If 'match' contains the optional "+" prefix, it tells libvirt +# to log stack trace for each message matching name. +# +# 'level' is the minimal level where matching messages should +# be logged: +# # 1: DEBUG # 2: INFO # 3: WARNING # 4: ERROR # -# Multiple filter can be defined in a single @filters, they just need to be -# separated by spaces. +# Multiple filters can be defined in a single @filters, they just need to be
Probably should be log_filters not @filters
+# separated by spaces. Note that libvirt performs "first" match, i.e. if +# there are concurrent filters, the first one that matches will be applied, +# given the order in log_filters. +# +# +# For the virtlogd daemon, a typical need is to capture information +# from the logging code and some of the utility code. Some utility +# code is very verbose and is generally not desired. A suitable filter +# string for debugging might be to turn off object, json & event logging, +# but enable the rest of the util and the logging code: # -# e.g. to only get warning or errors from the remote layer and only errors -# from the event layer: -#log_filters="3:remote 4:event" +#log_filters="1:logging 4:object 4:json 4:event 1:util"
# Logging outputs: # An output is one of the places to save logging information # The format for an output can be: -# x:stderr +# level:stderr # output goes to stderr -# x:syslog:name +# level:syslog:name # use syslog for the output and use the given name as the ident -# x:file:file_path +# level:file:file_path # output to a file, with the given filepath -# x:journald -# ouput to the systemd journal -# In all case the x prefix is the minimal level, acting as a filter +# level:journald +# output to journald logging system +# In all cases 'level' is the minimal priority, acting as a filter # 1: DEBUG # 2: INFO # 3: WARNING # 4: ERROR # -# Multiple output can be defined, they just need to be separated by spaces. +# Multiple outputs can be defined, they just need to be separated by spaces. # e.g. to log all warnings and errors to syslog under the virtlogd ident: #log_outputs="3:syslog:virtlogd" # diff --git a/src/remote/libvirtd.conf b/src/remote/libvirtd.conf index 9c0080dc06..8cee30832a 100644 --- a/src/remote/libvirtd.conf +++ b/src/remote/libvirtd.conf @@ -338,28 +338,39 @@
# Logging level: 4 errors, 3 warnings, 2 information, 1 debug # basically 1 will log everything possible -# Note: Journald may employ rate limiting of the messages logged -# and thus lock up the libvirt daemon. To use the debug level with -# journald you have to specify it explicitly in 'log_outputs', otherwise -# only information level messages will be logged. +# +# WARNING: USE OF THIS IS STRONGLY DISCOURAGED. +# +# WARNING: It outputs too much information to practically read. +# WARNING: The "log_filters" setting is recommended instead. +# +# WARNING: Journald applies rate limiting of messages and so libvirt +# WARNING: will limit "log_level" to only allow values 3 or 4 if +# WARNING: journald is the current output. +# +# WARNING: USE OF THIS IS STRONGLY DISCOURAGED. #log_level = 3
# Logging filters: # A filter allows to select a different logging level for a given category -# of logs -# The format for a filter is one of: -# x:name -# x:+name - -# where name is a string which is matched against the category -# given in the VIR_LOG_INIT() at the top of each libvirt source -# file, e.g., "remote", "qemu", or "util.json" (the name in the -# filter can be a substring of the full category name, in order -# to match multiple similar categories), the optional "+" prefix -# tells libvirt to log stack trace for each message matching -# name, and x is the minimal level where matching messages should -# be logged: - +# of logs. The format for a filter is one of: +# +# level:match +# level:+match +# +# where 'match' is a string which is matched against the category +# given in the VIR_LOG_INIT() at the top of each libvirt source +# file, e.g., "remote", "qemu", or "util.json". The 'match' in the +# filter matches using shell wildcard syntax (see 'man glob(7)'). +# The 'match' is always treated a substring match. IOW a match
s/treated a/treated as a/
+# string 'foo' is equivalent to '*foo*'. +# +# If 'match' contains the optional "+" prefix, it tells libvirt +# to log stack trace for each message matching name. +# +# 'level' is the minimal level where matching messages should +# be logged: +# # 1: DEBUG # 2: INFO # 3: WARNING
For consistency, the same @filters change to log_filters.
@@ -370,22 +381,27 @@ # there are concurrent filters, the first one that matches will be applied, # given the order in log_filters. # -# e.g. to only get warning or errors from the remote layer and only errors -# from the event layer: -#log_filters="3:remote 4:event" +# A typical need is to capture information from a hypervisor driver, +# public API entrypoints and some of the utility code. Some utility +# code is very verbose and is generally not desired. Taking the QEMU +# hypervisor as an example, a suitable filter string for debugging +# might be to turn off object, json & event logging, but enable the +# rest of the util code: +# +#log_filters="1:qemu 1:libvirt 4:object 4:json 4:event 1:util"
FWIW: I've used 1:conf and 3:file (before 1:util) as a suggestion I found in the wild... The nice part about 3:file is it shows that 3:file would be used before 1:util. IDC whether or not it's added, but thought it may be interesting nonetheless. with the "as a" used.... whether the @filters changes to log_filters is your call. Reviewed-by: John Ferlan <jferlan@redhat.com> John
# Logging outputs: # An output is one of the places to save logging information # The format for an output can be: -# x:stderr +# level:stderr # output goes to stderr -# x:syslog:name +# level:syslog:name # use syslog for the output and use the given name as the ident -# x:file:file_path +# level:file:file_path # output to a file, with the given filepath -# x:journald +# level:journald # output to journald logging system -# In all case the x prefix is the minimal level, acting as a filter +# In all cases 'level' is the minimal priority, acting as a filter # 1: DEBUG # 2: INFO # 3: WARNING diff --git a/src/remote/test_libvirtd.aug.in b/src/remote/test_libvirtd.aug.in index 2bd7ec1bd6..527e3d7d0d 100644 --- a/src/remote/test_libvirtd.aug.in +++ b/src/remote/test_libvirtd.aug.in @@ -49,7 +49,7 @@ module Test_libvirtd = { "admin_max_queued_clients" = "5" } { "admin_max_client_requests" = "5" } { "log_level" = "3" } - { "log_filters" = "3:remote 4:event" } + { "log_filters" = "1:qemu 1:libvirt 4:object 4:json 4:event 1:util" } { "log_outputs" = "3:syslog:libvirtd" } { "audit_level" = "2" } { "audit_logging" = "1" }
participants (2)
-
Daniel P. Berrangé
-
John Ferlan