[libvirt] [PATCH 0/2] journald logging rate limit fix

Peter Krempa (2): libvirtd: conf: Mention support for logging into journald daemon: Limit default log level to journald to VIR_LOG_INFO daemon/libvirtd.c | 10 +++++++++- daemon/libvirtd.conf | 6 ++++++ 2 files changed, 15 insertions(+), 1 deletion(-) -- 2.0.2

Our docs didn't mention the explicit option to log into journald. --- daemon/libvirtd.conf | 2 ++ 1 file changed, 2 insertions(+) diff --git a/daemon/libvirtd.conf b/daemon/libvirtd.conf index e5856d4..c73423f 100644 --- a/daemon/libvirtd.conf +++ b/daemon/libvirtd.conf @@ -342,6 +342,8 @@ # use syslog for the output and use the given name as the ident # x:file:file_path # output to a file, with the given filepath +# x:journald +# output to journald logging system # In all case the x prefix is the minimal level, acting as a filter # 1: DEBUG # 2: INFO -- 2.0.2

Libvirt is really chatty when the DEBUG log level is enabled. When a host uses journald we'd enable debug logging to journald when only specifying the debug log level. As journald may employ rate throttling this would lock up the daemon until it's able to flush all debug messages. This patch changes the default log level to VIR_LOG_INFO when using the default (unconfigured) log output to journald. To still allow debug logging to journad the user now has to explicitly specify journald as a log output with priority 1 in the "log_outputs" configuration option. This patch also changes the config file template to be explicit about this change and notify the user about the possible consequence of debug logging into journald. Resolves: https://bugzilla.redhat.com/show_bug.cgi?id=1121955 --- daemon/libvirtd.c | 10 +++++++++- daemon/libvirtd.conf | 4 ++++ 2 files changed, 13 insertions(+), 1 deletion(-) diff --git a/daemon/libvirtd.c b/daemon/libvirtd.c index 946081a..2783c97 100644 --- a/daemon/libvirtd.c +++ b/daemon/libvirtd.c @@ -678,7 +678,15 @@ daemonSetupLogging(struct daemonConfig *config, (godaemon || !isatty(STDIN_FILENO))) { char *tmp; if (access("/run/systemd/journal/socket", W_OK) >= 0) { - if (virAsprintf(&tmp, "%d:journald", virLogGetDefaultPriority()) < 0) + virLogPriority priority = virLogGetDefaultPriority(); + + /* By default we don't want to log too much stuff into journald as + * it may employ rate limiting and thus blocking libvirt execution. + */ + if (priority == VIR_LOG_DEBUG) + priority = VIR_LOG_INFO; + + if (virAsprintf(&tmp, "%d:journald", priority) < 0) goto error; virLogParseOutputs(tmp); VIR_FREE(tmp); diff --git a/daemon/libvirtd.conf b/daemon/libvirtd.conf index c73423f..0560b69 100644 --- a/daemon/libvirtd.conf +++ b/daemon/libvirtd.conf @@ -309,6 +309,10 @@ # 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. #log_level = 3 # Logging filters: -- 2.0.2

On 08/12/2014 08:34 AM, Peter Krempa wrote:
Libvirt is really chatty when the DEBUG log level is enabled. When a host uses journald we'd enable debug logging to journald when only specifying the debug log level. As journald may employ rate throttling this would lock up the daemon until it's able to flush all debug messages.
This patch changes the default log level to VIR_LOG_INFO when using the default (unconfigured) log output to journald.
To still allow debug logging to journad the user now has to explicitly
s/journad/journald/
+ /* By default we don't want to log too much stuff into journald as + * it may employ rate limiting and thus blocking libvirt execution.
s/blocking/block/
+++ b/daemon/libvirtd.conf @@ -309,6 +309,10 @@
# 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
s/ otherwise/, otherwise/ -- Eric Blake eblake redhat com +1-919-301-3266 Libvirt virtualization library http://libvirt.org

On Tue, Aug 12, 2014 at 04:34:37PM +0200, Peter Krempa wrote:
Libvirt is really chatty when the DEBUG log level is enabled. When a host uses journald we'd enable debug logging to journald when only specifying the debug log level. As journald may employ rate throttling this would lock up the daemon until it's able to flush all debug messages.
This patch changes the default log level to VIR_LOG_INFO when using the default (unconfigured) log output to journald.
To still allow debug logging to journad the user now has to explicitly specify journald as a log output with priority 1 in the "log_outputs" configuration option. This patch also changes the config file template to be explicit about this change and notify the user about the possible consequence of debug logging into journald.
Resolves: https://bugzilla.redhat.com/show_bug.cgi?id=1121955 --- daemon/libvirtd.c | 10 +++++++++- daemon/libvirtd.conf | 4 ++++ 2 files changed, 13 insertions(+), 1 deletion(-)
diff --git a/daemon/libvirtd.c b/daemon/libvirtd.c index 946081a..2783c97 100644 --- a/daemon/libvirtd.c +++ b/daemon/libvirtd.c @@ -678,7 +678,15 @@ daemonSetupLogging(struct daemonConfig *config, (godaemon || !isatty(STDIN_FILENO))) { char *tmp; if (access("/run/systemd/journal/socket", W_OK) >= 0) { - if (virAsprintf(&tmp, "%d:journald", virLogGetDefaultPriority()) < 0) + virLogPriority priority = virLogGetDefaultPriority(); + + /* By default we don't want to log too much stuff into journald as + * it may employ rate limiting and thus blocking libvirt execution. + */ + if (priority == VIR_LOG_DEBUG) + priority = VIR_LOG_INFO; + + if (virAsprintf(&tmp, "%d:journald", priority) < 0) goto error; virLogParseOutputs(tmp); VIR_FREE(tmp);
ACK, matches what I suggested we do previously. Regards, Daniel -- |: http://berrange.com -o- http://www.flickr.com/photos/dberrange/ :| |: http://libvirt.org -o- http://virt-manager.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: http://entangle-photo.org -o- http://live.gnome.org/gtk-vnc :|

On 08/12/14 20:03, Daniel P. Berrange wrote:
On Tue, Aug 12, 2014 at 04:34:37PM +0200, Peter Krempa wrote:
Libvirt is really chatty when the DEBUG log level is enabled. When a host uses journald we'd enable debug logging to journald when only specifying the debug log level. As journald may employ rate throttling this would lock up the daemon until it's able to flush all debug messages.
This patch changes the default log level to VIR_LOG_INFO when using the default (unconfigured) log output to journald.
To still allow debug logging to journad the user now has to explicitly specify journald as a log output with priority 1 in the "log_outputs" configuration option. This patch also changes the config file template to be explicit about this change and notify the user about the possible consequence of debug logging into journald.
Resolves: https://bugzilla.redhat.com/show_bug.cgi?id=1121955 --- daemon/libvirtd.c | 10 +++++++++- daemon/libvirtd.conf | 4 ++++ 2 files changed, 13 insertions(+), 1 deletion(-)
diff --git a/daemon/libvirtd.c b/daemon/libvirtd.c index 946081a..2783c97 100644 --- a/daemon/libvirtd.c +++ b/daemon/libvirtd.c @@ -678,7 +678,15 @@ daemonSetupLogging(struct daemonConfig *config, (godaemon || !isatty(STDIN_FILENO))) { char *tmp; if (access("/run/systemd/journal/socket", W_OK) >= 0) { - if (virAsprintf(&tmp, "%d:journald", virLogGetDefaultPriority()) < 0) + virLogPriority priority = virLogGetDefaultPriority(); + + /* By default we don't want to log too much stuff into journald as + * it may employ rate limiting and thus blocking libvirt execution. + */ + if (priority == VIR_LOG_DEBUG) + priority = VIR_LOG_INFO; + + if (virAsprintf(&tmp, "%d:journald", priority) < 0) goto error; virLogParseOutputs(tmp); VIR_FREE(tmp);
ACK, matches what I suggested we do previously.
I've fixed the typos/grammar pointed out by Eric and pushed this series.
Regards, Daniel
Peter

On 08/12/2014 04:34 PM, Peter Krempa wrote:
Peter Krempa (2): libvirtd: conf: Mention support for logging into journald daemon: Limit default log level to journald to VIR_LOG_INFO
daemon/libvirtd.c | 10 +++++++++- daemon/libvirtd.conf | 6 ++++++ 2 files changed, 15 insertions(+), 1 deletion(-)
ACK series. It would be nice to do the same for virtlockd. Jan
participants (4)
-
Daniel P. Berrange
-
Eric Blake
-
Ján Tomko
-
Peter Krempa