[Spice-devel] [spice-common v2 1/7] log: Use glib for logging

[Frediano Ziglio]

> 
> spice-common has been duplicating glib logging methods for a long while.
> Now that spice-common is depending on glib, it's more consistent to use
> glib logging too. However, the code base is still using spice logging
> functions.
> This commit aims to make spice logging go through glib logging system,
> while keeping the same behaviour for the SPICE_ABORT_LEVEL and
> SPICE_DEBUG_LEVEL environment variables. They are deprecated however in
> favour of the glib alternatives (G_DEBUG and G_MESSAGES_DEBUG).
> 
> Reviewed-by: Jonathon Jongsma <jjongsma at redhat.com>
> ---
> 
> Changes since v1:
> - fix glib fatal mask
> - use g_log_set_fatal_mask() rather g_log_set_always_fatal()
> 
>  common/log.c | 119
>  +++++++++++++++++++++++++++++++++--------------------------
>  common/log.h |   7 ----
>  2 files changed, 67 insertions(+), 59 deletions(-)
> 
> diff --git a/common/log.c b/common/log.c
> index fc5c129..aee6cc7 100644
> --- a/common/log.c
> +++ b/common/log.c
> @@ -1,5 +1,5 @@
>  /*
> -   Copyright (C) 2012 Red Hat, Inc.
> +   Copyright (C) 2012-2015 Red Hat, Inc.
>  
>     This library is free software; you can redistribute it and/or
>     modify it under the terms of the GNU Lesser General Public
> @@ -19,6 +19,7 @@
>  #include <config.h>
>  #endif
>  
> +#include <glib.h>
>  #include <stdlib.h>
>  #include <stdio.h>
>  #include <sys/types.h>
> @@ -32,34 +33,6 @@
>  static int debug_level = -1;
>  static int abort_level = -1;
>  
> -static const char * spice_log_level_to_string(SpiceLogLevel level)
> -{
> -#ifdef _MSC_VER
> -    /* MSVC++ does not implement C99 */
> -    static const char *to_string[] = {
> -         "ERROR",
> -         "CRITICAL",
> -         "Warning",
> -         "Info",
> -         "Debug"};
> -#else
> -    static const char *to_string[] = {
> -        [ SPICE_LOG_LEVEL_ERROR ] = "ERROR",
> -        [ SPICE_LOG_LEVEL_CRITICAL ] = "CRITICAL",
> -        [ SPICE_LOG_LEVEL_WARNING ] = "Warning",
> -        [ SPICE_LOG_LEVEL_INFO ] = "Info",
> -        [ SPICE_LOG_LEVEL_DEBUG ] = "Debug",
> -    };
> -#endif
> -    const char *str = NULL;
> -
> -    if (level < SPICE_N_ELEMENTS(to_string)) {
> -        str = to_string[level];
> -    }
> -
> -    return str;
> -}
> -
>  #ifndef SPICE_ABORT_LEVEL_DEFAULT
>  #ifdef SPICE_DISABLE_ABORT
>  #define SPICE_ABORT_LEVEL_DEFAULT -1
> @@ -68,41 +41,83 @@ static const char *
> spice_log_level_to_string(SpiceLogLevel level)
>  #endif
>  #endif
>  
> -void spice_logv(const char *log_domain,
> -                SpiceLogLevel log_level,
> -                const char *strloc,
> -                const char *function,
> -                const char *format,
> -                va_list args)
> +static GLogLevelFlags spice_log_level_to_glib(SpiceLogLevel level)
> +{
> +    static GLogLevelFlags glib_levels[] = {
> +        [ SPICE_LOG_LEVEL_ERROR ] = G_LOG_LEVEL_ERROR,
> +        [ SPICE_LOG_LEVEL_CRITICAL ] = G_LOG_LEVEL_CRITICAL,
> +        [ SPICE_LOG_LEVEL_WARNING ] = G_LOG_LEVEL_WARNING,
> +        [ SPICE_LOG_LEVEL_INFO ] = G_LOG_LEVEL_INFO,
> +        [ SPICE_LOG_LEVEL_DEBUG ] = G_LOG_LEVEL_DEBUG,
> +    };
> +    g_return_val_if_fail ((level >= 0) || (level <
> G_N_ELEMENTS(glib_levels)), 0);
> +
> +    return glib_levels[level];
> +}
> +
> +static void spice_log_set_debug_level(void)
>  {
> -    const char *level = spice_log_level_to_string(log_level);
> -
>      if (debug_level == -1) {
> -        debug_level = getenv("SPICE_DEBUG_LEVEL") ?
> atoi(getenv("SPICE_DEBUG_LEVEL")) : SPICE_LOG_LEVEL_WARNING;
> +        char *debug_str = getenv("SPICE_DEBUG_LEVEL");
> +        if (debug_str != NULL) {
> +            g_warning("Setting SPICE_DEBUG_LEVEL is deprecated, use
> G_MESSAGES_DEBUG instead");
> +            debug_level = atoi(getenv("SPICE_DEBUG_LEVEL"));

You can use debug_str here instead of calling again getenv.

> +            g_setenv("G_MESSAGES_DEBUG", "all", FALSE);

Do not set environment in a library.
This affects any usage of g_xxxx logging macros in the process (and
possibly sub processes).

> +        } else {
> +            debug_level = SPICE_LOG_LEVEL_WARNING;
> +        }
>      }
> +}
> +
> +static void spice_log_set_abort_level(void)
> +{
>      if (abort_level == -1) {
> -        abort_level = getenv("SPICE_ABORT_LEVEL") ?
> atoi(getenv("SPICE_ABORT_LEVEL")) : SPICE_ABORT_LEVEL_DEFAULT;
> +        char *abort_str = getenv("SPICE_ABORT_LEVEL");
> +        if (abort_str != NULL) {
> +            GLogLevelFlags glib_abort_level;
> +            g_warning("Setting SPICE_ABORT_LEVEL is deprecated, use G_DEBUG
> instead");
> +            abort_level = atoi(getenv("SPICE_ABORT_LEVEL"));
> +            glib_abort_level = spice_log_level_to_glib(abort_level);
> +            if (glib_abort_level != 0) {
> +                unsigned int fatal_mask = G_LOG_FATAL_MASK;
> +                while (glib_abort_level >= G_LOG_LEVEL_ERROR) {
> +                    fatal_mask |= glib_abort_level;
> +                    glib_abort_level >>= 1;
> +                }
> +                g_log_set_fatal_mask(SPICE_LOG_DOMAIN, fatal_mask);
> +            }
> +        } else {
> +            abort_level = SPICE_ABORT_LEVEL_DEFAULT;
> +        }
>      }
> +}
>  
> -    if (debug_level < (int) log_level)
> -        return;
> +static void spice_logv(const char *log_domain,
> +                       SpiceLogLevel log_level,
> +                       const char *strloc,
> +                       const char *function,
> +                       const char *format,
> +                       va_list args)
> +{
> +    GString *log_msg;
> +    static gsize logging_initialized = FALSE;
>  
> -    fprintf(stderr, "(%s:%d): ", getenv("_"), getpid());
> -
> -    if (log_domain) {
> -        fprintf(stderr, "%s-", log_domain);
> -    }
> -    if (level) {
> -        fprintf(stderr, "%s **: ", level);
> +    g_return_if_fail(spice_log_level_to_glib(log_level) != 0);
> +    if (g_once_init_enter(&logging_initialized)) {
> +        spice_log_set_debug_level();
> +        spice_log_set_abort_level();
> +        g_once_init_leave (&logging_initialized, TRUE);
>      }
> +
> +    log_msg = g_string_new(NULL);
>      if (strloc && function) {
> -        fprintf(stderr, "%s:%s: ", strloc, function);
> +        g_string_append_printf(log_msg, "%s:%s: ", strloc, function);
>      }
>      if (format) {
> -        vfprintf(stderr, format, args);
> +        g_string_append_vprintf(log_msg, format, args);
>      }
> -
> -    fprintf(stderr, "\n");
> +    g_log(log_domain, spice_log_level_to_glib(log_level), "%s",
> log_msg->str);
> +    g_string_free(log_msg, TRUE);
>  
>      if (abort_level != -1 && abort_level >= (int) log_level) {
>          spice_backtrace();
> diff --git a/common/log.h b/common/log.h
> index d9e6023..f336909 100644
> --- a/common/log.h
> +++ b/common/log.h
> @@ -41,13 +41,6 @@ typedef enum {
>      SPICE_LOG_LEVEL_DEBUG,
>  } SpiceLogLevel;
>  
> -void spice_logv(const char *log_domain,
> -                SpiceLogLevel log_level,
> -                const char *strloc,
> -                const char *function,
> -                const char *format,
> -                va_list args) SPICE_ATTR_PRINTF(5, 0);
> -
>  void spice_log(const char *log_domain,
>                 SpiceLogLevel log_level,
>                 const char *strloc,
> --
> 2.5.0

I tried to see the interaction with Qemu and is quite hard to
understand where the logging are going (mostly in Qemu is quite
messy, there are logging to file, stderr, printfs, g_xxxx functions...
quite messy). Staying to spice-common these changes put some logs
to stdout and others to stderr. I don't know what will happen
to solutions like Qemu, libvirt and so on. Are they collecting
stdout and stderr all into a single file? This would make this change
much less worrying me.

Would like also to have some automated tests.

Still I'd wait some Q/A comments on this.

Frediano