[libvirt] [PATCH] logging: remove concept of default log priority

[Erik Skultety]

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