[libvirt] [PATCH 4/4] log: update docs for daemons to improve user understanding

Daniel P. Berrangé posted 4 patches 7 years ago
There is a newer version of this series
[libvirt] [PATCH 4/4] log: update docs for daemons to improve user understanding
Posted by Daniel P. Berrangé 7 years ago
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        | 70 +++++++++++++++++++++++++++----------
 src/logging/test_virtlogd.aug.in  |  2 +-
 src/logging/virtlogd.conf         | 73 ++++++++++++++++++++++++++++-----------
 src/remote/libvirtd.conf          | 70 +++++++++++++++++++++++--------------
 src/remote/test_libvirtd.aug.in   |  2 +-
 6 files changed, 150 insertions(+), 69 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..29cefbd74a 100644
--- a/src/locking/virtlockd.conf
+++ b/src/locking/virtlockd.conf
@@ -8,47 +8,79 @@
 
 # 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 may employ rate limiting of the messages logged
+# WARNING: and thus lock up the libvirt daemon. To use the debug
+# WARNING: level with journald you have to specify it explicitly in
+# WARNING: 'log_outputs', otherwise only information level messages
+# WARNING: will be logged.
+#
+# 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. 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:
 #
-# 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.
-# e.g. to log all warnings and errors to syslog under the virtlockd ident:
+# 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 libvirtd 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..f2078a730c 100644
--- a/src/logging/virtlogd.conf
+++ b/src/logging/virtlogd.conf
@@ -8,49 +8,80 @@
 
 # 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 may employ rate limiting of the messages logged
+# WARNING: and thus lock up the libvirt daemon. To use the debug
+# WARNING: level with journald you have to specify it explicitly in
+# WARNING: 'log_outputs', otherwise only information level messages
+# WARNING: will be logged.
+#
+# 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. 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:
 #
-# 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.
-# e.g. to log all warnings and errors to syslog under the virtlogd ident:
+# 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 libvirtd ident:
 #log_outputs="3:syslog:virtlogd"
 #
 
diff --git a/src/remote/libvirtd.conf b/src/remote/libvirtd.conf
index 9c0080dc06..63b8fdd38d 100644
--- a/src/remote/libvirtd.conf
+++ b/src/remote/libvirtd.conf
@@ -338,28 +338,41 @@
 
 # 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 may employ rate limiting of the messages logged
+# WARNING: and thus lock up the libvirt daemon. To use the debug
+# WARNING: level with journald you have to specify it explicitly in
+# WARNING: 'log_outputs', otherwise only information level messages
+# WARNING: will be logged.
+#
+# 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 +383,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

--
libvir-list mailing list
libvir-list@redhat.com
https://www.redhat.com/mailman/listinfo/libvir-list
Re: [libvirt] [PATCH 4/4] log: update docs for daemons to improve user understanding
Posted by Erik Skultety 7 years ago
On Fri, Apr 20, 2018 at 05:56:39PM +0100, 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        | 70 +++++++++++++++++++++++++++----------
>  src/logging/test_virtlogd.aug.in  |  2 +-
>  src/logging/virtlogd.conf         | 73 ++++++++++++++++++++++++++++-----------
>  src/remote/libvirtd.conf          | 70 +++++++++++++++++++++++--------------
>  src/remote/test_libvirtd.aug.in   |  2 +-
>  6 files changed, 150 insertions(+), 69 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..29cefbd74a 100644
> --- a/src/locking/virtlockd.conf
> +++ b/src/locking/virtlockd.conf
> @@ -8,47 +8,79 @@
>
>  # 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 may employ rate limiting of the messages logged
> +# WARNING: and thus lock up the libvirt daemon. To use the debug
> +# WARNING: level with journald you have to specify it explicitly in
> +# WARNING: 'log_outputs', otherwise only information level messages

So is it really worth mentioning to use debug with journal, since there are
only limitations? How about encouraging to use e.g. file for debug logs and
journald for 3+.

> +# WARNING: will be logged.
> +#
> +# 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

What about users who use libvirt from a distro package, they don't necessary
need to have the sources installed, more importantly they shouldn't really have
to care about the sources to successfully set up logging.
Reporting the categories in some consumable way that could be generated
automatically during libvirt build and shipped afterwards has been on my radar
for quite some time...

> +# 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. 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:
>  #
> -# 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.
> -# e.g. to log all warnings and errors to syslog under the virtlockd ident:
> +# 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 libvirtd 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..f2078a730c 100644
> --- a/src/logging/virtlogd.conf
> +++ b/src/logging/virtlogd.conf
> @@ -8,49 +8,80 @@
>
>  # 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 may employ rate limiting of the messages logged
> +# WARNING: and thus lock up the libvirt daemon. To use the debug
> +# WARNING: level with journald you have to specify it explicitly in
> +# WARNING: 'log_outputs', otherwise only information level messages
> +# WARNING: will be logged.
> +#
> +# 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. 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:

^This paragraph is a copy-paste from virtlockd bits, so this needs to be fixed.

>  #
> -# 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.
> -# e.g. to log all warnings and errors to syslog under the virtlogd ident:
> +# 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 libvirtd ident:

"under libvirt indent" - this doesn't reflect the reality below...
there's one more occurrence of this within this patch...

Erik

--
libvir-list mailing list
libvir-list@redhat.com
https://www.redhat.com/mailman/listinfo/libvir-list
Re: [libvirt] [PATCH 4/4] log: update docs for daemons to improve user understanding
Posted by Daniel P. Berrangé 7 years ago
On Mon, Apr 23, 2018 at 08:49:00AM +0200, Erik Skultety wrote:
> On Fri, Apr 20, 2018 at 05:56:39PM +0100, 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        | 70 +++++++++++++++++++++++++++----------
> >  src/logging/test_virtlogd.aug.in  |  2 +-
> >  src/logging/virtlogd.conf         | 73 ++++++++++++++++++++++++++++-----------
> >  src/remote/libvirtd.conf          | 70 +++++++++++++++++++++++--------------
> >  src/remote/test_libvirtd.aug.in   |  2 +-
> >  6 files changed, 150 insertions(+), 69 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..29cefbd74a 100644
> > --- a/src/locking/virtlockd.conf
> > +++ b/src/locking/virtlockd.conf
> > @@ -8,47 +8,79 @@
> >
> >  # 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 may employ rate limiting of the messages logged
> > +# WARNING: and thus lock up the libvirt daemon. To use the debug
> > +# WARNING: level with journald you have to specify it explicitly in
> > +# WARNING: 'log_outputs', otherwise only information level messages
> 
> So is it really worth mentioning to use debug with journal, since there are
> only limitations? How about encouraging to use e.g. file for debug logs and
> journald for 3+.

Yeah, maybe I'll reword it to

   "Journald applies rate limiting of messages and so libvirt will
    ignore any logging level above 3, if journald is the current
    output."

as that better describes what we're doing.

> > +# WARNING: will be logged.
> > +#
> > +# 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
> 
> What about users who use libvirt from a distro package, they don't necessary
> need to have the sources installed, more importantly they shouldn't really have
> to care about the sources to successfully set up logging.
> Reporting the categories in some consumable way that could be generated
> automatically during libvirt build and shipped afterwards has been on my radar
> for quite some time...

In the majority of debugging scenarios I see with the OpenStack project from
a RHEL support POV, users just do whatever our support / developer engineers
tell them todo and don't try to figure it out themselves.

Even if we had a man page which listed each known logging category, how would
users know which sets of categories are relevant to their problem ? It usually
needs someone who knows the code to make recommendations.

I'd kind of like to figure out a way to be able to extract a list of all
logging categories at runtime from the daemon, but its hard because the
loggnig code doesn't know about categories until a log message is sent.

One idea I had was for VIR_LOG_INIT() to create a function that was marked
with __attribute__((constructor)) that would call virLogRegisterCategory()
so we can build a list of all cats immediately.  Then the virt-admin tool
could list them too

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 :|

--
libvir-list mailing list
libvir-list@redhat.com
https://www.redhat.com/mailman/listinfo/libvir-list
Re: [libvirt] [PATCH 4/4] log: update docs for daemons to improve user understanding
Posted by Kashyap Chamarthy 7 years ago
On Fri, Apr 20, 2018 at 05:56:39PM +0100, 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>
> ---

[...]

Besides couple of ultra minor things, the core change looks good to me.

> +# 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 may employ rate limiting of the messages logged
> +# WARNING: and thus lock up the libvirt daemon. To use the debug
> +# WARNING: level with journald you have to specify it explicitly in
> +# WARNING: 'log_outputs', otherwise only information level messages
> +# WARNING: will be logged.

I see you said in your reply to Erik that you're going to reword the
above.  That said ...

> +# WARNING: USE OF THIS IS STRONGLY DISCOURAGED.
>  #log_level = 3

... the above bit reads slightly confusing, as it implies using
'log_level = 3' is discouraged, while (I think) you mean that use of
'log_level' in general is discouraged.  Unless I'm misreading it.

[...]

> -# 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. 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

OCD comment (applies to all occurrences of this block of text): Either
s/json/JSON to read as a sentence.  Or I'd put them in single quotes:
'object', 'json' & 'event', 'util' to indicate they're special.

> +# rest of the util 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.
> -# e.g. to log all warnings and errors to syslog under the virtlockd ident:
> +# 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 libvirtd ident:

Super nit, pre-existing: s/e.g./E.g./  (Since it's the start of a sentence)

>  #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..f2078a730c 100644
> --- a/src/logging/virtlogd.conf
> +++ b/src/logging/virtlogd.conf
> @@ -8,49 +8,80 @@
>  
>  # 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 may employ rate limiting of the messages logged
> +# WARNING: and thus lock up the libvirt daemon. To use the debug
> +# WARNING: level with journald you have to specify it explicitly in
> +# WARNING: 'log_outputs', otherwise only information level messages
> +# WARNING: will be logged.
> +#
> +# WARNING: USE OF THIS IS STRONGLY DISCOURAGED.
>  #log_level = 3

Here, too.  I'll interpret the above as: "Using 'log_level' is strongly
discouraged".  So probably: s/USE OF/USE OF `log_level`/

[...]

> +#
> +# 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 +383,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

Nit: s/entrypoint/entry points/

Thanks for the patch.

[...]

-- 
/kashyap

--
libvir-list mailing list
libvir-list@redhat.com
https://www.redhat.com/mailman/listinfo/libvir-list