[libvirt] [PATCH] logging: remove concept of default log priority
The logging framework has categories which can be selectively enabled/disabled by setting a suitable LIBVIRT_LOG_FILTERS environment variable or config file setting. Along side that we also have the LIBVIRT_DEBUG environment variable which unconditionally enables every single category at DEBUG level. With the amount of logging produced by libvirt these days, the signal/noise ratio in the output from setting LIBVIRT_DEBUG is to poor for it to be useful. Originally the LIBVIRT_DEBUG env variable had a very specific use case - it resulted in logging of anything in our public API entrypoints. eg it turned on src/libvirt.c debugging and nothing else. Additionally it would always result in log messages being sent to stderr. When applied to any of the daemons, the log output no longers gets sent to stderr, but rather to whatever default log output has been configured by the daemon. If no log_outputs setting or LIBVIRT_LOG_OUTPUTS env is set, then messages will often go to the systemd journal or a /var/log/libvirt/libvirtd.log file rather than stderr. These factors have conspired to make the LIBVIRT_DEBUG env and/or default log priority to be pretty useless in the real world. This change attempts to take us back towards the original semantics of the LIBVIRT_DEBUG env variable as follows. If LIBVIRT_DEBUG is set to a plain integer, or log level string, then it will turn on logging for the "libvirt" log category at that level. Any other string will be parsed in the same way as LIBVIRT_LOG_FILTERS would be. In all cases use of LIBVIRT_DEBUG will result in an explicit output being added for stderr. This ensures that messages always go to stderr, even if other outputs are already configured. IOW, LIBVIRT_DEBUG=1 virsh or LIBVIRT_DEBUG=1 libvirtd will both result in printing logs of libvirt public API calls to stderr. Meanwhile setting LIBVIRT_DEBUG="1:qemu" is equivalent to setting LIBVIRT_LOG_FILTERS="1:qemu" and LIBVIRT_LOG_OUTPUTS="1:stderr" Signed-off-by: Daniel P. Berrange <berrange@redhat.com> --- daemon/libvirtd.c | 27 ++++++------ src/libvirt_private.syms | 1 + src/libxl/libxl_conf.c | 3 +- src/locking/lock_daemon.c | 29 ++++++------- src/logging/log_daemon.c | 29 ++++++------- src/lxc/lxc_process.c | 7 ---- src/util/vircommand.c | 4 -- src/util/virlog.c | 104 +++++++++++++++++++--------------------------- src/util/virlog.h | 11 ++--- tests/eventtest.c | 6 +-- 10 files changed, 97 insertions(+), 124 deletions(-) diff --git a/daemon/libvirtd.c b/daemon/libvirtd.c index cc5190f..e88a982 100644 --- a/daemon/libvirtd.c +++ b/daemon/libvirtd.c @@ -668,6 +668,8 @@ daemonSetupLogging(struct daemonConfig *config, bool verbose, bool godaemon) { + int level = VIR_LOG_WARN; + virLogReset(); /* @@ -684,9 +686,6 @@ daemonSetupLogging(struct daemonConfig *config, * level has been set, we must process variables in the opposite * order, each one overriding the previous. */ - if (config->log_level != 0) - virLogSetDefaultPriority(config->log_level); - virLogSetFromEnv(); if (virLogGetNbFilters() == 0) @@ -695,11 +694,14 @@ daemonSetupLogging(struct daemonConfig *config, if (virLogGetNbOutputs() == 0) virLogParseOutputs(config->log_outputs); - /* - * Command line override for --verbose - */ - if ((verbose) && (virLogGetDefaultPriority() > VIR_LOG_INFO)) - virLogSetDefaultPriority(VIR_LOG_INFO); + if (config->log_level != 0 || verbose) { + level = config->log_level; + if (verbose && level > VIR_LOG_INFO) + level = VIR_LOG_INFO; + virLogDefineFilter("libvirt", level, 0); + if (virLogGetNbOutputs() == 0) + virLogParseOutputs("1:stderr"); + } /* * If no defined outputs, and either running @@ -711,7 +713,7 @@ daemonSetupLogging(struct daemonConfig *config, (godaemon || !isatty(STDIN_FILENO))) { char *tmp; if (access("/run/systemd/journal/socket", W_OK) >= 0) { - virLogPriority priority = virLogGetDefaultPriority(); + virLogPriority priority = level; /* By default we don't want to log too much stuff into journald as * it may employ rate limiting and thus block libvirt execution. */ @@ -735,8 +737,7 @@ daemonSetupLogging(struct daemonConfig *config, if (godaemon) { if (privileged) { if (virAsprintf(&tmp, "%d:file:%s/log/libvirt/libvirtd.log", - virLogGetDefaultPriority(), - LOCALSTATEDIR) == -1) + level, LOCALSTATEDIR) == -1) goto error; } else { char *logdir = virGetUserCacheDirectory(); @@ -753,14 +754,14 @@ daemonSetupLogging(struct daemonConfig *config, umask(old_umask); if (virAsprintf(&tmp, "%d:file:%s/libvirtd.log", - virLogGetDefaultPriority(), logdir) == -1) { + level, logdir) == -1) { VIR_FREE(logdir); goto error; } VIR_FREE(logdir); } } else { - if (virAsprintf(&tmp, "%d:stderr", virLogGetDefaultPriority()) < 0) + if (virAsprintf(&tmp, "%d:stderr", level) < 0) goto error; } virLogParseOutputs(tmp); diff --git a/src/libvirt_private.syms b/src/libvirt_private.syms index a980a32..5586d8b 100644 --- a/src/libvirt_private.syms +++ b/src/libvirt_private.syms @@ -1801,6 +1801,7 @@ virLogProbablyLogMessage; virLogReset; virLogSetDefaultPriority; virLogSetFromEnv; +virLogSourceGetPriority; virLogUnlock; virLogVMessage; diff --git a/src/libxl/libxl_conf.c b/src/libxl/libxl_conf.c index d927b37..51d6037 100644 --- a/src/libxl/libxl_conf.c +++ b/src/libxl/libxl_conf.c @@ -52,6 +52,7 @@ #define VIR_FROM_THIS VIR_FROM_LIBXL VIR_LOG_INIT("libxl.libxl_conf"); +VIR_LOG_INIT_FULL("libxl.libxl_context", virLogLibXL); /* see xen-unstable.hg/xen/include/asm-x86/cpufeature.h */ #define LIBXL_X86_FEATURE_PAE_MASK 0x40 @@ -1724,7 +1725,7 @@ libxlDriverConfigNew(void) } VIR_FREE(log_file); - switch (virLogGetDefaultPriority()) { + switch (virLogSourceGetPriority(&virLogLibXL)) { case VIR_LOG_DEBUG: log_level = XTL_DEBUG; break; diff --git a/src/locking/lock_daemon.c b/src/locking/lock_daemon.c index f889a34..426fe6b 100644 --- a/src/locking/lock_daemon.c +++ b/src/locking/lock_daemon.c @@ -454,6 +454,8 @@ virLockDaemonSetupLogging(virLockDaemonConfigPtr config, bool verbose, bool godaemon) { + int level = VIR_LOG_WARN; + virLogReset(); /* @@ -470,9 +472,6 @@ virLockDaemonSetupLogging(virLockDaemonConfigPtr config, * level has been set, we must process variables in the opposite * order, each one overriding the previous. */ - if (config->log_level != 0) - virLogSetDefaultPriority(config->log_level); - virLogSetFromEnv(); if (virLogGetNbFilters() == 0) @@ -481,6 +480,15 @@ virLockDaemonSetupLogging(virLockDaemonConfigPtr config, if (virLogGetNbOutputs() == 0) virLogParseOutputs(config->log_outputs); + if (config->log_level != 0 || verbose) { + level = config->log_level; + if (verbose && level > VIR_LOG_INFO) + level = VIR_LOG_INFO; + virLogDefineFilter("libvirt", level, 0); + if (virLogGetNbOutputs() == 0) + virLogParseOutputs("1:stderr"); + } + /* * If no defined outputs, and either running * as daemon or not on a tty, then first try @@ -491,7 +499,7 @@ virLockDaemonSetupLogging(virLockDaemonConfigPtr config, (godaemon || !isatty(STDIN_FILENO))) { char *tmp; if (access("/run/systemd/journal/socket", W_OK) >= 0) { - if (virAsprintf(&tmp, "%d:journald", virLogGetDefaultPriority()) < 0) + if (virAsprintf(&tmp, "%d:journald", level) < 0) goto error; virLogParseOutputs(tmp); VIR_FREE(tmp); @@ -508,8 +516,7 @@ virLockDaemonSetupLogging(virLockDaemonConfigPtr config, if (godaemon) { if (privileged) { if (virAsprintf(&tmp, "%d:file:%s/log/libvirt/virtlockd.log", - virLogGetDefaultPriority(), - LOCALSTATEDIR) == -1) + level, LOCALSTATEDIR) == -1) goto error; } else { char *logdir = virGetUserCacheDirectory(); @@ -527,26 +534,20 @@ virLockDaemonSetupLogging(virLockDaemonConfigPtr config, umask(old_umask); if (virAsprintf(&tmp, "%d:file:%s/virtlockd.log", - virLogGetDefaultPriority(), logdir) == -1) { + level, logdir) == -1) { VIR_FREE(logdir); goto error; } VIR_FREE(logdir); } } else { - if (virAsprintf(&tmp, "%d:stderr", virLogGetDefaultPriority()) < 0) + if (virAsprintf(&tmp, "%d:stderr", level) < 0) goto error; } virLogParseOutputs(tmp); VIR_FREE(tmp); } - /* - * Command line override for --verbose - */ - if ((verbose) && (virLogGetDefaultPriority() > VIR_LOG_INFO)) - virLogSetDefaultPriority(VIR_LOG_INFO); - return 0; error: diff --git a/src/logging/log_daemon.c b/src/logging/log_daemon.c index 90f8427..f344ba2 100644 --- a/src/logging/log_daemon.c +++ b/src/logging/log_daemon.c @@ -377,6 +377,8 @@ virLogDaemonSetupLogging(virLogDaemonConfigPtr config, bool verbose, bool godaemon) { + int level = VIR_LOG_WARN; + virLogReset(); /* @@ -393,9 +395,6 @@ virLogDaemonSetupLogging(virLogDaemonConfigPtr config, * level has been set, we must process variables in the opposite * order, each one overriding the previous. */ - if (config->log_level != 0) - virLogSetDefaultPriority(config->log_level); - virLogSetFromEnv(); if (virLogGetNbFilters() == 0) @@ -404,6 +403,15 @@ virLogDaemonSetupLogging(virLogDaemonConfigPtr config, if (virLogGetNbOutputs() == 0) virLogParseOutputs(config->log_outputs); + if (config->log_level != 0 || verbose) { + level = config->log_level; + if (verbose && level > VIR_LOG_INFO) + level = VIR_LOG_INFO; + virLogDefineFilter("libvirt", level, 0); + if (virLogGetNbOutputs() == 0) + virLogParseOutputs("1:stderr"); + } + /* * If no defined outputs, and either running * as daemon or not on a tty, then first try @@ -414,7 +422,7 @@ virLogDaemonSetupLogging(virLogDaemonConfigPtr config, (godaemon || !isatty(STDIN_FILENO))) { char *tmp; if (access("/run/systemd/journal/socket", W_OK) >= 0) { - if (virAsprintf(&tmp, "%d:journald", virLogGetDefaultPriority()) < 0) + if (virAsprintf(&tmp, "%d:journald", level) < 0) goto error; virLogParseOutputs(tmp); VIR_FREE(tmp); @@ -431,8 +439,7 @@ virLogDaemonSetupLogging(virLogDaemonConfigPtr config, if (godaemon) { if (privileged) { if (virAsprintf(&tmp, "%d:file:%s/log/libvirt/virtlogd.log", - virLogGetDefaultPriority(), - LOCALSTATEDIR) == -1) + level, LOCALSTATEDIR) == -1) goto error; } else { char *logdir = virGetUserCacheDirectory(); @@ -450,26 +457,20 @@ virLogDaemonSetupLogging(virLogDaemonConfigPtr config, umask(old_umask); if (virAsprintf(&tmp, "%d:file:%s/virtlogd.log", - virLogGetDefaultPriority(), logdir) == -1) { + level, logdir) == -1) { VIR_FREE(logdir); goto error; } VIR_FREE(logdir); } } else { - if (virAsprintf(&tmp, "%d:stderr", virLogGetDefaultPriority()) < 0) + if (virAsprintf(&tmp, "%d:stderr", level) < 0) goto error; } virLogParseOutputs(tmp); VIR_FREE(tmp); } - /* - * Command line override for --verbose - */ - if ((verbose) && (virLogGetDefaultPriority() > VIR_LOG_INFO)) - virLogSetDefaultPriority(VIR_LOG_INFO); - return 0; error: diff --git a/src/lxc/lxc_process.c b/src/lxc/lxc_process.c index 8981d9a..9fca007 100644 --- a/src/lxc/lxc_process.c +++ b/src/lxc/lxc_process.c @@ -918,9 +918,6 @@ virLXCProcessBuildControllerCmd(virLXCDriverPtr driver, /* The controller may call ip command, so we have to retain PATH. */ virCommandAddEnvPassBlockSUID(cmd, "PATH", "/bin:/usr/bin"); - virCommandAddEnvFormat(cmd, "LIBVIRT_DEBUG=%d", - virLogGetDefaultPriority()); - if (virLogGetNbFilters() > 0) { filterstr = virLogGetFilters(); if (!filterstr) { @@ -943,10 +940,6 @@ virLXCProcessBuildControllerCmd(virLXCDriverPtr driver, virCommandAddEnvPair(cmd, "LIBVIRT_LOG_OUTPUTS", outputstr); VIR_FREE(outputstr); } - } else { - virCommandAddEnvFormat(cmd, - "LIBVIRT_LOG_OUTPUTS=%d:stderr", - virLogGetDefaultPriority()); } virCommandAddArgList(cmd, "--name", vm->def->name, NULL); diff --git a/src/util/vircommand.c b/src/util/vircommand.c index 027cb64..07cd005 100644 --- a/src/util/vircommand.c +++ b/src/util/vircommand.c @@ -342,8 +342,6 @@ virFork(void) } else { /* child process */ - - int logprio; size_t i; /* Remove any error callback so errors in child now get sent @@ -354,9 +352,7 @@ virFork(void) /* Make sure any hook logging is sent to stderr, since child * process may close the logfile FDs */ - logprio = virLogGetDefaultPriority(); virLogReset(); - virLogSetDefaultPriority(logprio); /* Clear out all signal handlers from parent so nothing * unexpected can happen in our child once we unblock diff --git a/src/util/virlog.c b/src/util/virlog.c index 738eaac..82fb4dc 100644 --- a/src/util/virlog.c +++ b/src/util/virlog.c @@ -112,11 +112,6 @@ typedef virLogOutput *virLogOutputPtr; static virLogOutputPtr virLogOutputs; static int virLogNbOutputs; -/* - * Default priorities - */ -static virLogPriority virLogDefaultPriority = VIR_LOG_DEFAULT; - static int virLogResetFilters(void); static int virLogResetOutputs(void); static void virLogOutputToFd(virLogSourcePtr src, @@ -175,7 +170,6 @@ virLogOnceInit(void) return -1; virLogLock(); - virLogDefaultPriority = VIR_LOG_DEFAULT; if (VIR_ALLOC_QUIET(virLogRegex) >= 0) { if (regcomp(virLogRegex, VIR_LOG_REGEX, REG_EXTENDED) != 0) @@ -205,35 +199,10 @@ virLogReset(void) virLogLock(); virLogResetFilters(); virLogResetOutputs(); - virLogDefaultPriority = VIR_LOG_DEFAULT; virLogUnlock(); return 0; } -/** - * virLogSetDefaultPriority: - * @priority: the default priority level - * - * Set the default priority level, i.e. any logged data of a priority - * equal or superior to this level will be logged, unless a specific rule - * was defined for the log category of the message. - * - * Returns 0 if successful, -1 in case of error. - */ -int -virLogSetDefaultPriority(virLogPriority priority) -{ - if ((priority < VIR_LOG_DEBUG) || (priority > VIR_LOG_ERROR)) { - VIR_WARN("Ignoring invalid log level setting."); - return -1; - } - if (virLogInitialize() < 0) - return -1; - - virLogDefaultPriority = priority; - return 0; -} - /** * virLogResetFilters: @@ -472,7 +441,7 @@ virLogSourceUpdate(virLogSourcePtr source) { virLogLock(); if (source->serial < virLogFiltersSerial) { - unsigned int priority = virLogDefaultPriority; + unsigned int priority = VIR_LOG_DEFAULT; unsigned int flags = 0; size_t i; @@ -1310,18 +1279,6 @@ virLogParseFilters(const char *filters) /** - * virLogGetDefaultPriority: - * - * Returns the current logging priority level. - */ -virLogPriority -virLogGetDefaultPriority(void) -{ - return virLogDefaultPriority; -} - - -/** * virLogGetFilters: * * Returns a string listing the current filters, in the format originally @@ -1423,35 +1380,53 @@ virLogGetNbOutputs(void) /** - * virLogParseDefaultPriority: + * virLogParseDebug: * @priority: string defining the desired logging level * - * Parses and sets the default log priority level. It can take a string or - * number corresponding to the following levels: + * This method is a shortcut for setting a filter + * along with output to stderr. + * + * It can take one of the following strings or numbers: + * * 1: DEBUG * 2: INFO * 3: WARNING * 4: ERROR * + * in which case it will set the priority level on the + * "libvirt" log source filter. If it does not match any + * of these standard strings it will be treated as a full + * filter string. + * + * In all cases an output to stderr will be defined. + * * Returns 0 if successful, -1 in case of error. */ int -virLogParseDefaultPriority(const char *priority) +virLogParseDebug(const char *debug) { - int ret = -1; + unsigned int priority = VIR_LOG_DEFAULT; + if (STREQ(debug, "1") || STREQ(debug, "debug")) + priority = VIR_LOG_DEBUG; + else if (STREQ(debug, "2") || STREQ(debug, "info")) + priority = VIR_LOG_INFO; + else if (STREQ(debug, "3") || STREQ(debug, "warning")) + priority = VIR_LOG_WARN; + else if (STREQ(debug, "4") || STREQ(debug, "error")) + priority = VIR_LOG_ERROR; + + if (priority == VIR_LOG_DEFAULT) { + if (virLogParseFilters(debug) < 0) + return -1; + } else { + if (virLogDefineFilter("libvirt", priority, 0) < 0) + return -1; + } - if (STREQ(priority, "1") || STREQ(priority, "debug")) - ret = virLogSetDefaultPriority(VIR_LOG_DEBUG); - else if (STREQ(priority, "2") || STREQ(priority, "info")) - ret = virLogSetDefaultPriority(VIR_LOG_INFO); - else if (STREQ(priority, "3") || STREQ(priority, "warning")) - ret = virLogSetDefaultPriority(VIR_LOG_WARN); - else if (STREQ(priority, "4") || STREQ(priority, "error")) - ret = virLogSetDefaultPriority(VIR_LOG_ERROR); - else - VIR_WARN("Ignoring invalid log level setting"); + if (virLogParseOutputs("1:stderr") < 0) + return -1; - return ret; + return 0; } @@ -1471,7 +1446,7 @@ virLogSetFromEnv(void) debugEnv = virGetEnvAllowSUID("LIBVIRT_DEBUG"); if (debugEnv && *debugEnv) - virLogParseDefaultPriority(debugEnv); + virLogParseDebug(debugEnv); debugEnv = virGetEnvAllowSUID("LIBVIRT_LOG_FILTERS"); if (debugEnv && *debugEnv) virLogParseFilters(debugEnv); @@ -1495,3 +1470,10 @@ bool virLogProbablyLogMessage(const char *str) ret = true; return ret; } + + +int virLogSourceGetPriority(virLogSourcePtr source) +{ + virLogSourceUpdate(source); + return source->priority; +} diff --git a/src/util/virlog.h b/src/util/virlog.h index 3ad00d4..aace409 100644 --- a/src/util/virlog.h +++ b/src/util/virlog.h @@ -73,13 +73,14 @@ struct _virLogSource { * log statements in a file are conditionally disabled * at compile time due to configure options. */ -# define VIR_LOG_INIT(n) \ - static ATTRIBUTE_UNUSED virLogSource virLogSelf = { \ +# define VIR_LOG_INIT_FULL(n, _var) \ + static ATTRIBUTE_UNUSED virLogSource _var = { \ .name = "" n "", \ .priority = VIR_LOG_ERROR, \ .serial = 0, \ .flags = 0, \ }; +# define VIR_LOG_INIT(n) VIR_LOG_INIT_FULL(n, virLogSelf) /* * If configured with --enable-debug=yes then library calls @@ -174,8 +175,6 @@ int virLogGetNbFilters(void); int virLogGetNbOutputs(void); char *virLogGetFilters(void); char *virLogGetOutputs(void); -virLogPriority virLogGetDefaultPriority(void); -int virLogSetDefaultPriority(virLogPriority priority); void virLogSetFromEnv(void); int virLogDefineFilter(const char *match, virLogPriority priority, @@ -195,7 +194,7 @@ int virLogDefineOutput(virLogOutputFunc f, void virLogLock(void); void virLogUnlock(void); int virLogReset(void); -int virLogParseDefaultPriority(const char *priority); +int virLogParseDebug(const char *debug); int virLogParseFilters(const char *filters); int virLogParseOutputs(const char *output); int virLogPriorityFromSyslog(int priority); @@ -217,4 +216,6 @@ void virLogVMessage(virLogSourcePtr source, bool virLogProbablyLogMessage(const char *str); +int virLogSourceGetPriority(virLogSourcePtr source); + #endif diff --git a/tests/eventtest.c b/tests/eventtest.c index c4be606..0a31672 100644 --- a/tests/eventtest.c +++ b/tests/eventtest.c @@ -310,11 +310,7 @@ mymain(void) if (virThreadInitialize() < 0) return EXIT_FAILURE; - char *debugEnv = getenv("LIBVIRT_DEBUG"); - if (debugEnv && *debugEnv && (virLogParseDefaultPriority(debugEnv) == -1)) { - fprintf(stderr, "Invalid log level setting.\n"); - return EXIT_FAILURE; - } + virLogSetFromEnv(); virEventPollInit(); -- 2.5.5
On Wed, May 11, 2016 at 15:12:27 +0100, Daniel P. Berrange wrote:
The logging framework has categories which can be selectively enabled/disabled by setting a suitable LIBVIRT_LOG_FILTERS environment variable or config file setting.
Along side that we also have the LIBVIRT_DEBUG environment variable which unconditionally enables every single category at DEBUG level. With the amount of logging produced by libvirt these days, the signal/noise ratio in the output from setting LIBVIRT_DEBUG is to poor for it to be useful.
Originally the LIBVIRT_DEBUG env variable had a very specific use case - it resulted in logging of anything in our public API entrypoints. eg it turned on src/libvirt.c debugging and nothing else. Additionally it would always result in log messages being sent to stderr.
When applied to any of the daemons, the log output no longers gets sent to stderr, but rather to whatever default log output has been configured by the daemon. If no log_outputs setting or LIBVIRT_LOG_OUTPUTS env is set, then messages will often go to the systemd journal or a /var/log/libvirt/libvirtd.log file rather than stderr.
These factors have conspired to make the LIBVIRT_DEBUG env and/or default log priority to be pretty useless in the real world.
This change attempts to take us back towards the original semantics of the LIBVIRT_DEBUG env variable as follows.
If LIBVIRT_DEBUG is set to a plain integer, or log level string, then it will turn on logging for the "libvirt" log category at that level. Any other string will be parsed in the same way as LIBVIRT_LOG_FILTERS would be. In all cases use of LIBVIRT_DEBUG will result in an explicit output being added for stderr. This ensures that messages always go to stderr, even if other outputs are already configured.
IOW, LIBVIRT_DEBUG=1 virsh or LIBVIRT_DEBUG=1 libvirtd will both result in printing logs of libvirt public API calls to stderr. Meanwhile setting LIBVIRT_DEBUG="1:qemu" is equivalent to setting LIBVIRT_LOG_FILTERS="1:qemu" and LIBVIRT_LOG_OUTPUTS="1:stderr"
Hmm, this looks like it's going to break existing valid configurations, such as log_level = 1 log_filters="3:util.log 3:rpc.keepalive 3:rpc 3:remote 3:util.json" log_outputs="1:file:/var/log/libvirt/libvirtd.log" Shouldn't log_level = 1 add an all matching filter rather than the one matching just libvirt? Jirka
On 11.05.2016 16:12, Daniel P. Berrange wrote:
The logging framework has categories which can be selectively enabled/disabled by setting a suitable LIBVIRT_LOG_FILTERS environment variable or config file setting.
Along side that we also have the LIBVIRT_DEBUG environment variable which unconditionally enables every single category at DEBUG level. With the amount of logging produced by libvirt these days, the signal/noise ratio in the output from setting LIBVIRT_DEBUG is to poor for it to be useful.
Originally the LIBVIRT_DEBUG env variable had a very specific use case - it resulted in logging of anything in our public API entrypoints. eg it turned on src/libvirt.c debugging and nothing else. Additionally it would always result in log messages being sent to stderr.
When applied to any of the daemons, the log output no longers gets sent to stderr, but rather to whatever default log output has been configured by the daemon. If no log_outputs setting or LIBVIRT_LOG_OUTPUTS env is set, then messages will often go to the systemd journal or a /var/log/libvirt/libvirtd.log file rather than stderr.
These factors have conspired to make the LIBVIRT_DEBUG env and/or default log priority to be pretty useless in the real world.
This change attempts to take us back towards the original semantics of the LIBVIRT_DEBUG env variable as follows.
If LIBVIRT_DEBUG is set to a plain integer, or log level string, then it will turn on logging for the "libvirt" log category at that level. Any other string will be parsed in the same way as LIBVIRT_LOG_FILTERS would be. In all cases use of LIBVIRT_DEBUG will result in an explicit output being added for stderr. This ensures that messages always go to stderr, even if other outputs are already configured.
IOW, LIBVIRT_DEBUG=1 virsh or LIBVIRT_DEBUG=1 libvirtd will both result in printing logs of libvirt public API calls to stderr. Meanwhile setting LIBVIRT_DEBUG="1:qemu" is equivalent to setting LIBVIRT_LOG_FILTERS="1:qemu" and LIBVIRT_LOG_OUTPUTS="1:stderr"
Signed-off-by: Daniel P. Berrange <berrange@redhat.com> --- daemon/libvirtd.c | 27 ++++++------ src/libvirt_private.syms | 1 + src/libxl/libxl_conf.c | 3 +- src/locking/lock_daemon.c | 29 ++++++------- src/logging/log_daemon.c | 29 ++++++------- src/lxc/lxc_process.c | 7 ---- src/util/vircommand.c | 4 -- src/util/virlog.c | 104 +++++++++++++++++++--------------------------- src/util/virlog.h | 11 ++--- tests/eventtest.c | 6 +-- 10 files changed, 97 insertions(+), 124 deletions(-)
diff --git a/daemon/libvirtd.c b/daemon/libvirtd.c index cc5190f..e88a982 100644 --- a/daemon/libvirtd.c +++ b/daemon/libvirtd.c @@ -668,6 +668,8 @@ daemonSetupLogging(struct daemonConfig *config, bool verbose, bool godaemon) { + int level = VIR_LOG_WARN; + virLogReset();
/* @@ -684,9 +686,6 @@ daemonSetupLogging(struct daemonConfig *config, * level has been set, we must process variables in the opposite * order, each one overriding the previous. */ - if (config->log_level != 0) - virLogSetDefaultPriority(config->log_level); - virLogSetFromEnv();
if (virLogGetNbFilters() == 0) @@ -695,11 +694,14 @@ daemonSetupLogging(struct daemonConfig *config, if (virLogGetNbOutputs() == 0) virLogParseOutputs(config->log_outputs);
- /* - * Command line override for --verbose - */ - if ((verbose) && (virLogGetDefaultPriority() > VIR_LOG_INFO)) - virLogSetDefaultPriority(VIR_LOG_INFO); + if (config->log_level != 0 || verbose) { + level = config->log_level; + if (verbose && level > VIR_LOG_INFO) + level = VIR_LOG_INFO; + virLogDefineFilter("libvirt", level, 0); + if (virLogGetNbOutputs() == 0) + virLogParseOutputs("1:stderr"); + }
I've noticed this code being copied over and over. Is it worth putting into a function, say virLogSetDefaultLevel(config->log_level, verbose)?
/* * If no defined outputs, and either running @@ -711,7 +713,7 @@ daemonSetupLogging(struct daemonConfig *config, (godaemon || !isatty(STDIN_FILENO))) { char *tmp; if (access("/run/systemd/journal/socket", W_OK) >= 0) { - virLogPriority priority = virLogGetDefaultPriority(); + virLogPriority priority = level;
/* By default we don't want to log too much stuff into journald as * it may employ rate limiting and thus block libvirt execution. */ @@ -735,8 +737,7 @@ daemonSetupLogging(struct daemonConfig *config, if (godaemon) { if (privileged) { if (virAsprintf(&tmp, "%d:file:%s/log/libvirt/libvirtd.log", - virLogGetDefaultPriority(), - LOCALSTATEDIR) == -1) + level, LOCALSTATEDIR) == -1) goto error; } else { char *logdir = virGetUserCacheDirectory(); @@ -753,14 +754,14 @@ daemonSetupLogging(struct daemonConfig *config, umask(old_umask);
if (virAsprintf(&tmp, "%d:file:%s/libvirtd.log", - virLogGetDefaultPriority(), logdir) == -1) { + level, logdir) == -1) { VIR_FREE(logdir); goto error; } VIR_FREE(logdir); } } else { - if (virAsprintf(&tmp, "%d:stderr", virLogGetDefaultPriority()) < 0) + if (virAsprintf(&tmp, "%d:stderr", level) < 0) goto error; } virLogParseOutputs(tmp); diff --git a/src/libvirt_private.syms b/src/libvirt_private.syms index a980a32..5586d8b 100644 --- a/src/libvirt_private.syms +++ b/src/libvirt_private.syms @@ -1801,6 +1801,7 @@ virLogProbablyLogMessage; virLogReset; virLogSetDefaultPriority; virLogSetFromEnv; +virLogSourceGetPriority; virLogUnlock; virLogVMessage;
diff --git a/src/util/virlog.c b/src/util/virlog.c index 738eaac..82fb4dc 100644 --- a/src/util/virlog.c +++ b/src/util/virlog.c @@ -112,11 +112,6 @@ typedef virLogOutput *virLogOutputPtr; static virLogOutputPtr virLogOutputs; static int virLogNbOutputs;
-/* - * Default priorities - */ -static virLogPriority virLogDefaultPriority = VIR_LOG_DEFAULT; - static int virLogResetFilters(void); static int virLogResetOutputs(void); static void virLogOutputToFd(virLogSourcePtr src, @@ -175,7 +170,6 @@ virLogOnceInit(void) return -1;
virLogLock(); - virLogDefaultPriority = VIR_LOG_DEFAULT;
if (VIR_ALLOC_QUIET(virLogRegex) >= 0) { if (regcomp(virLogRegex, VIR_LOG_REGEX, REG_EXTENDED) != 0) @@ -205,35 +199,10 @@ virLogReset(void) virLogLock(); virLogResetFilters(); virLogResetOutputs(); - virLogDefaultPriority = VIR_LOG_DEFAULT; virLogUnlock(); return 0; }
-/** - * virLogSetDefaultPriority: - * @priority: the default priority level - * - * Set the default priority level, i.e. any logged data of a priority - * equal or superior to this level will be logged, unless a specific rule - * was defined for the log category of the message. - * - * Returns 0 if successful, -1 in case of error. - */ -int -virLogSetDefaultPriority(virLogPriority priority) -{ - if ((priority < VIR_LOG_DEBUG) || (priority > VIR_LOG_ERROR)) { - VIR_WARN("Ignoring invalid log level setting."); - return -1; - } - if (virLogInitialize() < 0) - return -1; - - virLogDefaultPriority = priority; - return 0; -} -
This should be also removed from libvirt_private.syms.
/** * virLogResetFilters: @@ -472,7 +441,7 @@ virLogSourceUpdate(virLogSourcePtr source) { virLogLock(); if (source->serial < virLogFiltersSerial) { - unsigned int priority = virLogDefaultPriority; + unsigned int priority = VIR_LOG_DEFAULT; unsigned int flags = 0; size_t i;
@@ -1310,18 +1279,6 @@ virLogParseFilters(const char *filters)
/** - * virLogGetDefaultPriority: - * - * Returns the current logging priority level. - */ -virLogPriority -virLogGetDefaultPriority(void) -{ - return virLogDefaultPriority; -} - -
This is still used in src/security/security_apparmor.c and also after fixing that place should be removed from libvirt_private.syms.
-/** * virLogGetFilters: * * Returns a string listing the current filters, in the format originally @@ -1423,35 +1380,53 @@ virLogGetNbOutputs(void)
/** - * virLogParseDefaultPriority: + * virLogParseDebug: * @priority: string defining the desired logging level * - * Parses and sets the default log priority level. It can take a string or - * number corresponding to the following levels: + * This method is a shortcut for setting a filter + * along with output to stderr. + * + * It can take one of the following strings or numbers: + * * 1: DEBUG * 2: INFO * 3: WARNING * 4: ERROR * + * in which case it will set the priority level on the + * "libvirt" log source filter. If it does not match any + * of these standard strings it will be treated as a full + * filter string. + * + * In all cases an output to stderr will be defined. + * * Returns 0 if successful, -1 in case of error. */ int -virLogParseDefaultPriority(const char *priority) +virLogParseDebug(const char *debug)
Yet again, this requires changes in libvirt_private.syms. I belive our 'make check' would have caught this.
{ - int ret = -1; + unsigned int priority = VIR_LOG_DEFAULT; + if (STREQ(debug, "1") || STREQ(debug, "debug")) + priority = VIR_LOG_DEBUG; + else if (STREQ(debug, "2") || STREQ(debug, "info")) + priority = VIR_LOG_INFO; + else if (STREQ(debug, "3") || STREQ(debug, "warning")) + priority = VIR_LOG_WARN; + else if (STREQ(debug, "4") || STREQ(debug, "error")) + priority = VIR_LOG_ERROR; + + if (priority == VIR_LOG_DEFAULT) { + if (virLogParseFilters(debug) < 0) + return -1; + } else { + if (virLogDefineFilter("libvirt", priority, 0) < 0) + return -1; + }
- if (STREQ(priority, "1") || STREQ(priority, "debug")) - ret = virLogSetDefaultPriority(VIR_LOG_DEBUG); - else if (STREQ(priority, "2") || STREQ(priority, "info")) - ret = virLogSetDefaultPriority(VIR_LOG_INFO); - else if (STREQ(priority, "3") || STREQ(priority, "warning")) - ret = virLogSetDefaultPriority(VIR_LOG_WARN); - else if (STREQ(priority, "4") || STREQ(priority, "error")) - ret = virLogSetDefaultPriority(VIR_LOG_ERROR); - else - VIR_WARN("Ignoring invalid log level setting"); + if (virLogParseOutputs("1:stderr") < 0) + return -1;
- return ret; + return 0; }
Otherwise looking good. ACK if you fix all the nits I've raised. Michal
On 11/05/16 16:12, Daniel P. Berrange wrote:
The logging framework has categories which can be selectively enabled/disabled by setting a suitable LIBVIRT_LOG_FILTERS environment variable or config file setting.
Along side that we also have the LIBVIRT_DEBUG environment variable which unconditionally enables every single category at DEBUG level. With the amount of logging produced by libvirt these days, the signal/noise ratio in the output from setting LIBVIRT_DEBUG is to poor for it to be useful.
Originally the LIBVIRT_DEBUG env variable had a very specific use case - it resulted in logging of anything in our public API entrypoints. eg it turned on src/libvirt.c debugging and nothing else. Additionally it would always result in log messages being sent to stderr.
When applied to any of the daemons, the log output no longers gets sent to stderr, but rather to whatever default log output has been configured by the daemon. If no log_outputs setting or LIBVIRT_LOG_OUTPUTS env is set, then messages will often go to the systemd journal or a /var/log/libvirt/libvirtd.log file rather than stderr.
These factors have conspired to make the LIBVIRT_DEBUG env and/or default log priority to be pretty useless in the real world.
This change attempts to take us back towards the original semantics of the LIBVIRT_DEBUG env variable as follows.
If LIBVIRT_DEBUG is set to a plain integer, or log level string, then it will turn on logging for the "libvirt" log category at that level. Any other string will be parsed in the same way as LIBVIRT_LOG_FILTERS would be. In all cases use of LIBVIRT_DEBUG will result in an explicit output being added for stderr. This ensures that messages always go to stderr, even if other outputs are already configured.
IOW, LIBVIRT_DEBUG=1 virsh or LIBVIRT_DEBUG=1 libvirtd will both result in printing logs of libvirt public API calls to stderr. Meanwhile setting LIBVIRT_DEBUG="1:qemu" is equivalent to setting LIBVIRT_LOG_FILTERS="1:qemu" and LIBVIRT_LOG_OUTPUTS="1:stderr"
Signed-off-by: Daniel P. Berrange <berrange@redhat.com> --- daemon/libvirtd.c | 27 ++++++------ src/libvirt_private.syms | 1 + src/libxl/libxl_conf.c | 3 +- src/locking/lock_daemon.c | 29 ++++++------- src/logging/log_daemon.c | 29 ++++++------- src/lxc/lxc_process.c | 7 ---- src/util/vircommand.c | 4 -- src/util/virlog.c | 104 +++++++++++++++++++--------------------------- src/util/virlog.h | 11 ++--- tests/eventtest.c | 6 +-- 10 files changed, 97 insertions(+), 124 deletions(-)
[...]
- /* - * Command line override for --verbose - */ - if ((verbose) && (virLogGetDefaultPriority() > VIR_LOG_INFO)) - virLogSetDefaultPriority(VIR_LOG_INFO); + if (config->log_level != 0 || verbose) { + level = config->log_level; + if (verbose && level > VIR_LOG_INFO) + level = VIR_LOG_INFO; + virLogDefineFilter("libvirt", level, 0); + if (virLogGetNbOutputs() == 0) + virLogParseOutputs("1:stderr"); + }
I wonder about the meaning of --verbose after this ^^ change. According to the man page it enables verbose messages. My expectations on a utility's output if provided with --verbose option would be to log more information than when run without it. This used to be true prior to your change, but wouldn't be anymore. There would be no difference between using and not using verbose on libvirtd with the default config, since the logic above only affects libvirt module, where we only use VIR_DEBUG (not counting errors on purpose because those will be logged in all modules normally...). I can't tell if there's someone actually using --verbose, but using it should IMHO make a difference. [...]
diff --git a/src/libvirt_private.syms b/src/libvirt_private.syms index a980a32..5586d8b 100644 --- a/src/libvirt_private.syms +++ b/src/libvirt_private.syms @@ -1801,6 +1801,7 @@ virLogProbablyLogMessage; virLogReset; virLogSetDefaultPriority; virLogSetFromEnv; +virLogSourceGetPriority; virLogUnlock; virLogVMessage;
diff --git a/src/libxl/libxl_conf.c b/src/libxl/libxl_conf.c index d927b37..51d6037 100644 --- a/src/libxl/libxl_conf.c +++ b/src/libxl/libxl_conf.c @@ -52,6 +52,7 @@ #define VIR_FROM_THIS VIR_FROM_LIBXL
VIR_LOG_INIT("libxl.libxl_conf"); +VIR_LOG_INIT_FULL("libxl.libxl_context", virLogLibXL);
I think this is more of an enhancement (of the logging configuration), rather than removing a concept as the subject suggests. You also don't mention this in your commit message so it took me some time to figure out why it was here. I think this change, along with introducing the virLogSourceGetPriority function might be better in a separate patch prior removing anything that was related to the global logging level.
/* see xen-unstable.hg/xen/include/asm-x86/cpufeature.h */ #define LIBXL_X86_FEATURE_PAE_MASK 0x40 @@ -1724,7 +1725,7 @@ libxlDriverConfigNew(void) } VIR_FREE(log_file);
- switch (virLogGetDefaultPriority()) { + switch (virLogSourceGetPriority(&virLogLibXL)) { case VIR_LOG_DEBUG: log_level = XTL_DEBUG; break; diff --git a/src/locking/lock_daemon.c b/src/locking/lock_daemon.c index f889a34..426fe6b 100644 --- a/src/locking/lock_daemon.c +++ b/src/locking/lock_daemon.c @@ -454,6 +454,8 @@ virLockDaemonSetupLogging(virLockDaemonConfigPtr config, bool verbose, bool godaemon) { + int level = VIR_LOG_WARN; + virLogReset();
I also agree with Jiri [1] who pointed out that with this change we will no longer support blacklisting which is a valid configuration. [1] https://www.redhat.com/archives/libvir-list/2016-May/msg00762.html Erik
On Tue, May 31, 2016 at 10:52:35AM +0200, Erik Skultety wrote:
On 11/05/16 16:12, Daniel P. Berrange wrote:
The logging framework has categories which can be selectively enabled/disabled by setting a suitable LIBVIRT_LOG_FILTERS environment variable or config file setting.
Along side that we also have the LIBVIRT_DEBUG environment variable which unconditionally enables every single category at DEBUG level. With the amount of logging produced by libvirt these days, the signal/noise ratio in the output from setting LIBVIRT_DEBUG is to poor for it to be useful.
Originally the LIBVIRT_DEBUG env variable had a very specific use case - it resulted in logging of anything in our public API entrypoints. eg it turned on src/libvirt.c debugging and nothing else. Additionally it would always result in log messages being sent to stderr.
When applied to any of the daemons, the log output no longers gets sent to stderr, but rather to whatever default log output has been configured by the daemon. If no log_outputs setting or LIBVIRT_LOG_OUTPUTS env is set, then messages will often go to the systemd journal or a /var/log/libvirt/libvirtd.log file rather than stderr.
These factors have conspired to make the LIBVIRT_DEBUG env and/or default log priority to be pretty useless in the real world.
This change attempts to take us back towards the original semantics of the LIBVIRT_DEBUG env variable as follows.
If LIBVIRT_DEBUG is set to a plain integer, or log level string, then it will turn on logging for the "libvirt" log category at that level. Any other string will be parsed in the same way as LIBVIRT_LOG_FILTERS would be. In all cases use of LIBVIRT_DEBUG will result in an explicit output being added for stderr. This ensures that messages always go to stderr, even if other outputs are already configured.
IOW, LIBVIRT_DEBUG=1 virsh or LIBVIRT_DEBUG=1 libvirtd will both result in printing logs of libvirt public API calls to stderr. Meanwhile setting LIBVIRT_DEBUG="1:qemu" is equivalent to setting LIBVIRT_LOG_FILTERS="1:qemu" and LIBVIRT_LOG_OUTPUTS="1:stderr"
Signed-off-by: Daniel P. Berrange <berrange@redhat.com>
FYI, I'm still thinking about how to proceed with this patch given the feedback so far....so consider this "on hold" until I come up with a better idea. In the meantime we must not make the problem worse. ie we should *not* expose the default logging level config via the admin API. Only expose log filters + outputs. 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 16/06/16 15:37, Daniel P. Berrange wrote:
On Tue, May 31, 2016 at 10:52:35AM +0200, Erik Skultety wrote:
On 11/05/16 16:12, Daniel P. Berrange wrote:
The logging framework has categories which can be selectively enabled/disabled by setting a suitable LIBVIRT_LOG_FILTERS environment variable or config file setting.
Along side that we also have the LIBVIRT_DEBUG environment variable which unconditionally enables every single category at DEBUG level. With the amount of logging produced by libvirt these days, the signal/noise ratio in the output from setting LIBVIRT_DEBUG is to poor for it to be useful.
Originally the LIBVIRT_DEBUG env variable had a very specific use case - it resulted in logging of anything in our public API entrypoints. eg it turned on src/libvirt.c debugging and nothing else. Additionally it would always result in log messages being sent to stderr.
When applied to any of the daemons, the log output no longers gets sent to stderr, but rather to whatever default log output has been configured by the daemon. If no log_outputs setting or LIBVIRT_LOG_OUTPUTS env is set, then messages will often go to the systemd journal or a /var/log/libvirt/libvirtd.log file rather than stderr.
These factors have conspired to make the LIBVIRT_DEBUG env and/or default log priority to be pretty useless in the real world.
This change attempts to take us back towards the original semantics of the LIBVIRT_DEBUG env variable as follows.
If LIBVIRT_DEBUG is set to a plain integer, or log level string, then it will turn on logging for the "libvirt" log category at that level. Any other string will be parsed in the same way as LIBVIRT_LOG_FILTERS would be. In all cases use of LIBVIRT_DEBUG will result in an explicit output being added for stderr. This ensures that messages always go to stderr, even if other outputs are already configured.
IOW, LIBVIRT_DEBUG=1 virsh or LIBVIRT_DEBUG=1 libvirtd will both result in printing logs of libvirt public API calls to stderr. Meanwhile setting LIBVIRT_DEBUG="1:qemu" is equivalent to setting LIBVIRT_LOG_FILTERS="1:qemu" and LIBVIRT_LOG_OUTPUTS="1:stderr"
Signed-off-by: Daniel P. Berrange <berrange@redhat.com>
FYI, I'm still thinking about how to proceed with this patch given the feedback so far....so consider this "on hold" until I come up with a better idea.
In the meantime we must not make the problem worse. ie we should *not* expose the default logging level config via the admin API. Only expose log filters + outputs.
Regards, Daniel
Sure, that works for me just fine. Erik
participants (4)
-
Daniel P. Berrange -
Erik Skultety -
Jiri Denemark -
Michal Privoznik