log: Use glib for logging

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@redhat.com>

2 files changed, 112 insertions, 60 deletions

diff --git a/common/log.c b/common/log.c
index df394d2..607aa82 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>
@@ -29,37 +30,9 @@
 #include "log.h"
 #include "backtrace.h"
 
-static int debug_level = -1;
+static int glib_debug_level = 0;
 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,127 @@ 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)
 {
-    const char *level = spice_log_level_to_string(log_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];
+}
 
-    if (debug_level == -1) {
-        debug_level = getenv("SPICE_DEBUG_LEVEL") ? atoi(getenv("SPICE_DEBUG_LEVEL")) : SPICE_LOG_LEVEL_WARNING;
+static void spice_log_set_debug_level(void)
+{
+    if (glib_debug_level == 0) {
+        char *debug_str = getenv("SPICE_DEBUG_LEVEL");
+        if (debug_str != NULL) {
+            int debug_level;
+            char *debug_env;
+
+            /* FIXME: To be removed after enough deprecation time */
+            g_warning("Setting SPICE_DEBUG_LEVEL is deprecated, use G_MESSAGES_DEBUG instead");
+            debug_level = atoi(debug_str);
+            glib_debug_level = spice_log_level_to_glib(debug_level);
+
+            /* If the debug level is too high, make sure we don't try to enable
+             * display of glib debug logs */
+            if (debug_level < SPICE_LOG_LEVEL_INFO)
+                return;
+
+            /* Make sure GLib default log handler will show the debug messages. Messing with
+             * environment variables like this is ugly, but this only happens when the legacy
+             * SPICE_DEBUG_LEVEL is used
+             */
+            debug_env = (char *)g_getenv("G_MESSAGES_DEBUG");
+            if (debug_env == NULL) {
+                g_setenv("G_MESSAGES_DEBUG", SPICE_LOG_DOMAIN, FALSE);
+            } else {
+                debug_env = g_strconcat(debug_env, ":", SPICE_LOG_DOMAIN, NULL);
+                g_setenv("G_MESSAGES_DEBUG", SPICE_LOG_DOMAIN, FALSE);
+                g_free(debug_env);
+            }
+        }
     }
+}
+
+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;
+
+            /* FIXME: To be removed after enough deprecation time */
+            g_warning("Setting SPICE_ABORT_LEVEL is deprecated, use G_DEBUG instead");
+            abort_level = atoi(abort_str);
+            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;
-
-    fprintf(stderr, "(%s:%d): ", getenv("_"), getpid());
-
-    if (log_domain) {
-        fprintf(stderr, "%s-", log_domain);
+static void spice_logger(const gchar *log_domain,
+                         GLogLevelFlags log_level,
+                         const gchar *message,
+                         gpointer user_data)
+{
+    if (glib_debug_level != 0) {
+        if ((log_level & G_LOG_LEVEL_MASK) > glib_debug_level)
+            return; // do not print anything
     }
-    if (level) {
-        fprintf(stderr, "%s **: ", level);
+    g_log_default_handler(log_domain, log_level, message, NULL);
+}
+
+static inline void spice_log_init_once(void)
+{
+    static gsize logging_initialized = FALSE;
+
+    if (g_once_init_enter(&logging_initialized)) {
+        spice_log_set_debug_level();
+        spice_log_set_abort_level();
+        g_once_init_leave (&logging_initialized, TRUE);
+        g_log_set_handler(SPICE_LOG_DOMAIN,
+                          G_LOG_LEVEL_MASK | G_LOG_FLAG_FATAL | G_LOG_FLAG_RECURSION,
+                          spice_logger, NULL);
     }
+}
+
+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;
+
+    spice_log_init_once();
+
+    g_return_if_fail(spice_log_level_to_glib(log_level) != 0);
+
+    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 38a7988..a56105a 100644
--- a/common/log.h
+++ b/common/log.h
@@ -40,13 +40,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,