[gjs/wip/3v1n0/toggle-queue-tests: 10/15] log: Make logging thread safe

[Philip Chimento <pchimento src gnome org>]

commit b17361cca27c3a88a1fca228c37de62552861da8
Author: Marco Trevisan (Treviño) <mail 3v1n0 net>
Date:   Wed Apr 28 17:08:18 2021 +0200

    log: Make logging thread safe
    
    ThreadSanitizer is complaining that we may set and use static values in
    a racy way, and that's true.
    
    So, handle this in an init/cleanup functions that we set and unset at
    context creation and cleanup.

 gjs/context.cpp |   8 +++
 util/log.cpp    | 179 ++++++++++++++++++++++++++++----------------------------
 util/log.h      |   3 +
 3 files changed, 102 insertions(+), 88 deletions(-)
---
diff --git a/gjs/context.cpp b/gjs/context.cpp
index c9de371b..532bf6d9 100644
--- a/gjs/context.cpp
+++ b/gjs/context.cpp
@@ -212,6 +212,7 @@ setup_dump_heap(void)
 static void
 gjs_context_init(GjsContext *js_context)
 {
+    gjs_log_init();
     gjs_context_make_current(js_context);
 }
 
@@ -221,6 +222,8 @@ gjs_context_class_init(GjsContextClass *klass)
     GObjectClass *object_class = G_OBJECT_CLASS (klass);
     GParamSpec *pspec;
 
+    gjs_log_init();
+
     object_class->dispose = gjs_context_dispose;
     object_class->finalize = gjs_context_finalize;
 
@@ -446,6 +449,11 @@ gjs_context_finalize(GObject *object)
     GjsContextPrivate* gjs = GjsContextPrivate::from_object(object);
     gjs->~GjsContextPrivate();
     G_OBJECT_CLASS(gjs_context_parent_class)->finalize(object);
+
+    g_mutex_lock(&contexts_lock);
+    if (!all_contexts)
+        gjs_log_cleanup();
+    g_mutex_unlock(&contexts_lock);
 }
 
 static void
diff --git a/util/log.cpp b/util/log.cpp
index c515aab8..64730da6 100644
--- a/util/log.cpp
+++ b/util/log.cpp
@@ -2,10 +2,15 @@
 // SPDX-License-Identifier: MIT OR LGPL-2.0-or-later
 // SPDX-FileCopyrightText: 2008 litl, LLC
 
+#include <atomic>  // for atomic_bool
+#include <string>  // for string
+#include <type_traits>  // for remove_reference<>::type
+
 #include <errno.h>
 #include <stdarg.h>
 #include <stdio.h>   // for FILE, fprintf, fflush, fopen, fputs, fseek
 #include <string.h>  // for strchr, strcmp
+#include "gjs/jsapi-util.h"
 
 #ifdef _WIN32
 # include <io.h>
@@ -22,32 +27,98 @@
 #include "util/log.h"
 #include "util/misc.h"
 
+static std::atomic_bool s_initialized = ATOMIC_VAR_INIT(false);
+static bool s_debug_log_enabled = false;
+static bool s_print_thread = false;
+static const char* s_topics = nullptr;
+static FILE* s_logfp = nullptr;
+static GjsAutoStrv s_prefixes;
+static GjsAutoPointer<GTimer, GTimer, g_timer_destroy> s_timer;
+
+void gjs_log_init() {
+    bool expected = false;
+    if (!s_initialized.compare_exchange_strong(expected, true))
+        return;
+
+    s_topics = g_getenv("GJS_DEBUG_TOPICS");
+    if (s_topics)
+        s_prefixes = g_strsplit(s_topics, ";", -1);
+
+    if (gjs_environment_variable_is_set("GJS_DEBUG_TIMESTAMP"))
+        s_timer = g_timer_new();
+
+    s_print_thread = gjs_environment_variable_is_set("GJS_DEBUG_THREAD");
+
+    const char* debug_output = g_getenv("GJS_DEBUG_OUTPUT");
+    if (debug_output && g_str_equal(debug_output, "stderr")) {
+        s_debug_log_enabled = true;
+    } else if (debug_output) {
+        std::string log_file;
+        char* c;
+
+        /* Allow debug-%u.log for per-pid logfiles as otherwise log
+         * messages from multiple processes can overwrite each other.
+         *
+         * (printf below should be safe as we check '%u' is the only format
+         * string)
+         */
+        c = strchr(const_cast<char*>(debug_output), '%');
+        if (c && c[1] == 'u' && !strchr(c + 1, '%')) {
+            GjsAutoChar file_name;
+#if defined(__clang__) || __GNUC__ > 4 || (__GNUC__ == 4 && __GNUC_MINOR__ >= 6)
+            _Pragma("GCC diagnostic push")
+                _Pragma("GCC diagnostic ignored \"-Wformat-nonliteral\"")
+#endif
+                    file_name = g_strdup_printf(debug_output, getpid());
+#if defined(__clang__) || __GNUC__ > 4 || (__GNUC__ == 4 && __GNUC_MINOR__ >= 6)
+            _Pragma("GCC diagnostic pop")
+#endif
+                log_file = file_name.get();
+        } else {
+            log_file = debug_output;
+        }
+
+        /* avoid truncating in case we're using shared logfile */
+        s_logfp = fopen(log_file.c_str(), "a");
+        if (!s_logfp)
+            fprintf(stderr, "Failed to open log file `%s': %s\n",
+                    log_file.c_str(), g_strerror(errno));
+
+        s_debug_log_enabled = true;
+    }
+
+    if (!s_logfp)
+        s_logfp = stderr;
+}
+
+void gjs_log_cleanup() {
+    bool expected = true;
+    if (!s_initialized.compare_exchange_strong(expected, false))
+        return;
+
+    if (s_logfp && s_logfp != stderr) {
+        fclose(s_logfp);
+        s_logfp = nullptr;
+    }
+
+    s_timer = nullptr;
+    s_prefixes = nullptr;
+}
+
 /* prefix is allowed if it's in the ;-delimited environment variable
  * GJS_DEBUG_TOPICS or if that variable is not set.
  */
 static bool
 is_allowed_prefix (const char *prefix)
 {
-    static const char *topics = NULL;
-    static char **prefixes = NULL;
     bool found = false;
     int i;
 
-    if (topics == NULL) {
-        topics = g_getenv("GJS_DEBUG_TOPICS");
-
-        if (!topics)
-            return true;
-
-        /* We never really free this, should be gone when the process exits */
-        prefixes = g_strsplit(topics, ";", -1);
-    }
-
-    if (!prefixes)
+    if (!s_prefixes)
         return true;
 
-    for (i = 0; prefixes[i] != NULL; i++) {
-        if (!strcmp(prefixes[i], prefix)) {
+    for (i = 0; s_prefixes[i] != NULL; i++) {
+        if (!strcmp(s_prefixes[i], prefix)) {
             found = true;
             break;
         }
@@ -77,79 +148,11 @@ gjs_debug(GjsDebugTopic topic,
           const char   *format,
           ...)
 {
-    static FILE *logfp = NULL;
-    static bool debug_log_enabled = false;
-    static bool checked_for_timestamp = false;
-    static bool print_timestamp = false;
-    static bool checked_for_thread = false;
-    static bool print_thread = false;
-    static GTimer *timer = NULL;
     const char *prefix;
     va_list args;
     char *s;
 
-    if (!checked_for_timestamp) {
-        print_timestamp = gjs_environment_variable_is_set("GJS_DEBUG_TIMESTAMP");
-        checked_for_timestamp = true;
-    }
-
-    if (!checked_for_thread) {
-        print_thread = gjs_environment_variable_is_set("GJS_DEBUG_THREAD");
-        checked_for_thread = true;
-    }
-
-    if (print_timestamp && !timer) {
-        timer = g_timer_new();
-    }
-
-    if (logfp == NULL) {
-        const char *debug_output = g_getenv("GJS_DEBUG_OUTPUT");
-        if (debug_output != NULL &&
-            strcmp(debug_output, "stderr") == 0) {
-            debug_log_enabled = true;
-        } else if (debug_output != NULL) {
-            const char *log_file;
-            char *free_me;
-            char *c;
-
-            /* Allow debug-%u.log for per-pid logfiles as otherwise log
-             * messages from multiple processes can overwrite each other.
-             *
-             * (printf below should be safe as we check '%u' is the only format
-             * string)
-             */
-            c = strchr((char *) debug_output, '%');
-            if (c && c[1] == 'u' && !strchr(c+1, '%')) {
-#if defined(__clang__) || __GNUC__ > 4 || (__GNUC__ == 4 && __GNUC_MINOR__ >= 6)
-_Pragma("GCC diagnostic push")
-_Pragma("GCC diagnostic ignored \"-Wformat-nonliteral\"")
-#endif
-                free_me = g_strdup_printf(debug_output, (guint)getpid());
-#if defined(__clang__) || __GNUC__ > 4 || (__GNUC__ == 4 && __GNUC_MINOR__ >= 6)
-_Pragma("GCC diagnostic pop")
-#endif
-                log_file = free_me;
-            } else {
-                log_file = debug_output;
-                free_me = NULL;
-            }
-
-            /* avoid truncating in case we're using shared logfile */
-            logfp = fopen(log_file, "a");
-            if (!logfp)
-                fprintf(stderr, "Failed to open log file `%s': %s\n",
-                        log_file, g_strerror(errno));
-
-            g_free(free_me);
-
-            debug_log_enabled = true;
-        }
-
-        if (logfp == NULL)
-            logfp = stderr;
-    }
-
-    if (!debug_log_enabled)
+    if (!s_debug_log_enabled)
         return;
 
     switch (topic) {
@@ -222,9 +225,9 @@ _Pragma("GCC diagnostic pop")
     s = g_strdup_vprintf (format, args);
     va_end (args);
 
-    if (print_timestamp) {
+    if (s_timer) {
         static gdouble previous = 0.0;
-        gdouble total = g_timer_elapsed(timer, NULL) * 1000.0;
+        gdouble total = g_timer_elapsed(s_timer, NULL) * 1000.0;
         gdouble since = total - previous;
         const char *ts_suffix;
         char *s2;
@@ -247,13 +250,13 @@ _Pragma("GCC diagnostic pop")
         previous = total;
     }
 
-    if (print_thread) {
+    if (s_print_thread) {
         char *s2 = g_strdup_printf("(thread %p) %s", g_thread_self(), s);
         g_free(s);
         s = s2;
     }
 
-    write_to_stream(logfp, prefix, s);
+    write_to_stream(s_logfp, prefix, s);
 
     g_free(s);
 }
diff --git a/util/log.h b/util/log.h
index 10e34444..d56dda3d 100644
--- a/util/log.h
+++ b/util/log.h
@@ -147,6 +147,9 @@ typedef enum {
 #    define gjs_debug_gsignal(...) ((void)0)
 #endif
 
+void gjs_log_init();
+void gjs_log_cleanup();
+
 [[gnu::format(printf, 2, 3)]] void gjs_debug(GjsDebugTopic topic,
                                              const char* format, ...);