Re: [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(a)redhat.com&gt; --- 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/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; }