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