refactor(inject): Use new core thread and log modules

Keep this a separate commit because this also removes
inject's own logging engine and replaces it with the
streamlined core API. The core API provides all the
features of inject's own logging engine which also
performed horribly. The entire logging operation
was locked which included expensive operations
that formatted the log messages and required
memory allocations and copying around data.

The core API's implementation at least only
synchronizes the actual IO operations
(though this can be improved further with an
actual async logging sink, TBD)

src/main/inject/Module.mk

@@ -5,12 +5,12 @@ ldflags_inject  := \
     -lpsapi \
 
 libs_inject     := \
+    core \
     util \
 
 src_inject      := \
     main.c \
     debugger.c \
-    logger.c \
     options.c \
     version.c \
 

src/main/inject/debugger.c

@@ -8,10 +8,11 @@
 #include <stdio.h>
 #include <stdlib.h>
 
-#include "inject/debugger.h"
+#include "core/log-bt.h"
-#include "inject/logger.h"
+#include "core/log.h"
+
+#include "inject/debugger.h"
 
-#include "util/log.h"
 #include "util/mem.h"
 #include "util/proc.h"
 #include "util/signal.h"
@@ -178,6 +179,7 @@ static bool log_debug_str(HANDLE process, const OUTPUT_DEBUG_STRING_INFO *odsi)
     log_assert(odsi);
 
     char *debug_str;
+    size_t debug_str_len;
 
     if (odsi->fUnicode) {
         debug_str = read_debug_wstr(process, odsi);
@@ -186,7 +188,9 @@ static bool log_debug_str(HANDLE process, const OUTPUT_DEBUG_STRING_INFO *odsi)
     }
 
     if (debug_str) {
-        logger_log(debug_str);
+        debug_str_len = strlen(debug_str);
+
+        core_log_bt_direct_sink_write(debug_str, debug_str_len);
 
         free(debug_str);
         return true;

src/main/inject/logger.c

@@ -1,217 +0,0 @@
-#define LOG_MODULE "inject-logger"
-
-#include <stdbool.h>
-#include <stdio.h>
-#include <stdlib.h>
-#include <string.h>
-#include <time.h>
-#include <windows.h>
-
-#include "inject/logger.h"
-#include "inject/version.h"
-
-#include "util/log.h"
-
-static FILE *log_file;
-static HANDLE log_mutex;
-
-static const char *logger_get_formatted_timestamp(void)
-{
-    static char buffer[64];
-    time_t cur = 0;
-    struct tm *tm = NULL;
-
-    cur = time(NULL);
-    tm = localtime(&cur);
-
-    strftime(buffer, sizeof(buffer), "[%Y/%m/%d %H:%M:%S] ", tm);
-
-    return buffer;
-}
-
-static char logger_console_determine_color(const char *str)
-{
-    log_assert(str);
-
-    /* Add some color to make spotting warnings/errors easier.
-        Based on debug output level identifier. */
-
-    /* Avoids colored output on strings like "Windows" */
-    if (str[1] != ':') {
-        return 15;
-    }
-
-    switch (str[0]) {
-        /* green */
-        case 'M':
-            return 10;
-        /* blue */
-        case 'I':
-            return 9;
-        /* yellow */
-        case 'W':
-            return 14;
-        /* red */
-        case 'F':
-            return 12;
-        /* default console color */
-        default:
-            return 15;
-    }
-}
-
-static size_t logger_msg_coloring_len(const char *str)
-{
-    // Expected format example: "I:boot: my log message"
-
-    const char *ptr;
-    size_t len;
-    int colon_count;
-
-    ptr = str;
-    len = 0;
-    colon_count = 0;
-
-    while (true) {
-        // End of string = invalid log format
-        if (*ptr == '\0') {
-            return 0;
-        }
-
-        if (*ptr == ':') {
-            colon_count++;
-        }
-
-        if (colon_count == 2) {
-            // Skip current colon, next char is a space
-            return len + 1;
-        }
-
-        len++;
-        ptr++;
-    }
-
-    return 0;
-}
-
-static void logger_console(
-    void *ctx, const char *chars, size_t nchars, const char *timestamp_str)
-{
-    char color;
-    size_t color_len;
-    // See "util/log.c", has to align
-    char buffer[65536];
-    char tmp;
-
-    color_len = logger_msg_coloring_len(chars);
-
-    // Check if we could detect which part to color, otherwise just write the
-    // whole log message without any coloring logic
-    if (color_len > 0) {
-        color = logger_console_determine_color(chars);
-
-        strcpy(buffer, chars);
-
-        // Mask start of log message for coloring
-        tmp = buffer[color_len];
-        buffer[color_len] = '\0';
-
-        printf("%s", timestamp_str);
-        SetConsoleTextAttribute(GetStdHandle(STD_OUTPUT_HANDLE), color);
-        printf("%s", buffer);
-        SetConsoleTextAttribute(GetStdHandle(STD_OUTPUT_HANDLE), 15);
-
-        // Write actual message non colored
-        buffer[color_len] = tmp;
-        printf("%s", buffer + color_len);
-    } else {
-        printf("%s", chars);
-    }
-}
-
-static void logger_file(
-    void *ctx, const char *chars, size_t nchars, const char *timestamp_str)
-{
-    if (ctx) {
-        fwrite(timestamp_str, 1, strlen(timestamp_str), (FILE *) ctx);
-        fwrite(chars, 1, nchars, (FILE *) ctx);
-        fflush((FILE *) ctx);
-    }
-}
-
-static void logger_writer(void *ctx, const char *chars, size_t nchars)
-{
-    const char *timestamp_str;
-
-    // Different threads logging the same destination, e.g. debugger thread,
-    // main thread
-
-    WaitForSingleObject(log_mutex, INFINITE);
-
-    timestamp_str = logger_get_formatted_timestamp();
-
-    logger_console(ctx, chars, nchars, timestamp_str);
-    logger_file(ctx, chars, nchars, timestamp_str);
-
-    ReleaseMutex(log_mutex);
-}
-
-static void logger_log_header()
-{
-    log_info(
-        "\n"
-        "  _        _           _   \n"
-        " (_)_ __  (_) ___  ___| |_ \n"
-        " | | '_ \\ | |/ _ \\/ __| __|\n"
-        " | | | | || |  __/ (__| |_ \n"
-        " |_|_| |_|/ |\\___|\\___|\\__|\n"
-        "        |__/               ");
-
-    log_info(
-        "Inject build date %s, gitrev %s", inject_build_date, inject_gitrev);
-}
-
-bool logger_init(const char *log_file_path)
-{
-    if (log_file_path) {
-        log_file = fopen(log_file_path, "w+");
-    } else {
-        log_file = NULL;
-    }
-
-    log_to_writer(logger_writer, log_file);
-
-    logger_log_header();
-
-    if (log_file_path) {
-        log_info("Log file: %s", log_file_path);
-
-        if (!log_file) {
-            log_warning(
-                "ERROR: Opening log file %s failed: %s",
-                log_file_path,
-                strerror(errno));
-            return false;
-        }
-    }
-
-    log_mutex = CreateMutex(NULL, FALSE, NULL);
-
-    return true;
-}
-
-void logger_log(const char *str)
-{
-    logger_writer(log_file, str, strlen(str));
-}
-
-void logger_finit()
-{
-    log_misc("Logger finit");
-
-    if (log_file) {
-        fclose(log_file);
-    }
-
-    CloseHandle(log_mutex);
-}

src/main/inject/logger.h

@@ -1,28 +0,0 @@
-#include <stdbool.h>
-
-/**
- * Initialize inject's logger backend.
- *
- * This takes care of hooking and merging the different log
- * streams, e.g. inject's local logging and inject's debugger
- * receiving remote logging events.
- *
- * @param log_file_path Path to the file to log to or NULL to
- *                      disable.
- */
-bool logger_init(const char *log_file_path);
-
-/**
- * Write a message to the logging backend.
- *
- * This is used by inject's debugger to redirect log messages
- * recevied from the remote process.
- *
- * @param str String to log
- */
-void logger_log(const char *str);
-
-/**
- * Shutdown and cleanup the logging backend.
- */
-void logger_finit();

src/main/inject/main.c

@@ -1,3 +1,5 @@
+#define LOG_MODULE "inject"
+
 #include <windows.h>
 
 #include <stdbool.h>
@@ -10,18 +12,67 @@
 #include "cconfig/cconfig-util.h"
 #include "cconfig/cmd.h"
 
+#include "core/log-bt-ext.h"
+#include "core/log-bt.h"
+#include "core/log-sink-file.h"
+#include "core/log-sink-list.h"
+#include "core/log-sink-mutex.h"
+#include "core/log-sink-std.h"
+#include "core/log.h"
+#include "core/thread-crt-ext.h"
+#include "core/thread-crt.h"
+#include "core/thread.h"
+
 #include "inject/debugger.h"
-#include "inject/logger.h"
 #include "inject/options.h"
 #include "inject/version.h"
 
 #include "util/cmdline.h"
-#include "util/log.h"
 #include "util/mem.h"
 #include "util/os.h"
 #include "util/signal.h"
 #include "util/str.h"
 
+static void _inject_log_header()
+{
+    log_info(
+        "\n"
+        "  _        _           _   \n"
+        " (_)_ __  (_) ___  ___| |_ \n"
+        " | | '_ \\ | |/ _ \\/ __| __|\n"
+        " | | | | || |  __/ (__| |_ \n"
+        " |_|_| |_|/ |\\___|\\___|\\__|\n"
+        "        |__/               ");
+
+    log_info(
+        "inject build date %s, gitrev %s", inject_build_date, inject_gitrev);
+}
+
+void _inject_log_init(
+    const char *log_file_path, enum core_log_bt_log_level level)
+{
+    struct core_log_sink sinks[2];
+    struct core_log_sink sink_composed;
+    struct core_log_sink sink_mutex;
+
+    core_log_bt_ext_impl_set();
+
+    if (log_file_path) {
+        core_log_sink_std_out_open(true, &sinks[0]);
+        core_log_sink_file_open(log_file_path, false, true, 10, &sinks[1]);
+        core_log_sink_list_open(sinks, 2, &sink_composed);
+    } else {
+        core_log_sink_std_out_open(true, &sink_composed);
+    }
+
+    // Different threads logging the same destination, e.g. debugger thread,
+    // main thread
+    core_log_sink_mutex_open(&sink_composed, &sink_mutex);
+
+    core_log_bt_init(&sink_mutex);
+    core_log_bt_level_set(level);
+}
+
 static bool init_options(int argc, char **argv, struct options *options)
 {
     options_init(options);
@@ -145,7 +196,7 @@ static bool inject_hook_dlls(uint32_t hooks, char **argv)
 static void signal_shutdown_handler()
 {
     debugger_finit(true);
-    logger_finit();
+    core_log_bt_fini();
 }
 
 int main(int argc, char **argv)
@@ -160,9 +211,14 @@ int main(int argc, char **argv)
         goto init_options_fail;
     }
 
-    if (!logger_init(strlen(options.log_file) > 0 ? options.log_file : NULL)) {
+    core_thread_crt_ext_impl_set();
-        goto init_logger_fail;
+    // TODO expose log level
-    }
+
+    _inject_log_init(
+        strlen(options.log_file) > 0 ? options.log_file : NULL,
+        CORE_LOG_BT_LOG_LEVEL_MISC);
+
+    _inject_log_header();
 
     os_version_log();
 
@@ -214,7 +270,7 @@ int main(int argc, char **argv)
 
     debugger_finit(false);
 
-    logger_finit();
+    core_log_bt_fini();
 
     return EXIT_SUCCESS;
 
@@ -226,7 +282,7 @@ inject_hook_dlls_fail:
 debugger_init_fail:
 verify_2_fail:
 verify_fail:
-    logger_finit();
+    core_log_bt_fini();
 
 init_logger_fail:
 init_options_fail: