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 "inject/logger.h"
+#include "core/log-bt.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)) {
-        goto init_logger_fail;
-    }
+    core_thread_crt_ext_impl_set();
+    // 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:

src/main/util/Module.mk

@@ -9,7 +9,6 @@ src_util        := \
     hex.c \
     iobuf.c \
     list.c \
-    log.c \
     math.c \
     mem.c \
     msg-thread.c \
@@ -18,7 +17,6 @@ src_util        := \
     proc.c \
     signal.c \
     str.c \
-    thread.c \
     time.c \
     winres.c \
 

src/main/util/log.c

@@ -1,134 +0,0 @@
-#include "util/log.h"
-#include "util/str.h"
-
-#include <windows.h>
-
-#include <stdarg.h>
-#include <stdio.h>
-#include <stdlib.h>
-#include <string.h>
-
-static log_writer_t log_writer;
-static void *log_writer_ctx;
-static enum log_level log_level;
-
-static void log_builtin_fatal(const char *module, const char *fmt, ...);
-static void log_builtin_info(const char *module, const char *fmt, ...);
-static void log_builtin_misc(const char *module, const char *fmt, ...);
-static void log_builtin_warning(const char *module, const char *fmt, ...);
-static void log_builtin_format(
-    enum log_level msg_level, const char *module, const char *fmt, va_list ap);
-
-#define IMPLEMENT_SINK(name, msg_level)                        \
-    static void name(const char *module, const char *fmt, ...) \
-    {                                                          \
-        va_list ap;                                            \
-                                                               \
-        va_start(ap, fmt);                                     \
-        log_builtin_format(msg_level, module, fmt, ap);        \
-        va_end(ap);                                            \
-    }
-
-IMPLEMENT_SINK(log_builtin_info, LOG_LEVEL_INFO)
-IMPLEMENT_SINK(log_builtin_misc, LOG_LEVEL_MISC)
-IMPLEMENT_SINK(log_builtin_warning, LOG_LEVEL_WARNING)
-
-static void log_builtin_fatal(const char *module, const char *fmt, ...)
-{
-    va_list ap;
-
-    va_start(ap, fmt);
-    log_builtin_format(LOG_LEVEL_FATAL, module, fmt, ap);
-    va_end(ap);
-
-    DebugBreak();
-    ExitProcess(EXIT_FAILURE);
-}
-
-static void log_builtin_format(
-    enum log_level msg_level, const char *module, const char *fmt, va_list ap)
-{
-    static const char chars[] = "FWIM";
-
-    /* 64k so we can log data dumps of rs232 without crashing */
-    char line[65536];
-    char msg[65536];
-    int result;
-
-    if (msg_level <= log_level) {
-        str_vformat(msg, sizeof(msg), fmt, ap);
-        result = str_format(
-            line, sizeof(line), "%c:%s: %s\n", chars[msg_level], module, msg);
-
-        log_writer(log_writer_ctx, line, result);
-    }
-}
-
-void log_assert_body(const char *file, int line, const char *function)
-{
-    log_impl_fatal("assert", "%s:%d: function `%s'", file, line, function);
-}
-
-void log_to_external(
-    log_formatter_t misc,
-    log_formatter_t info,
-    log_formatter_t warning,
-    log_formatter_t fatal)
-{
-    log_impl_misc = misc;
-    log_impl_info = info;
-    log_impl_warning = warning;
-    log_impl_fatal = fatal;
-}
-
-void log_to_writer(log_writer_t writer, void *ctx)
-{
-    log_impl_misc = log_builtin_misc;
-    log_impl_info = log_builtin_info;
-    log_impl_warning = log_builtin_warning;
-    log_impl_fatal = log_builtin_fatal;
-
-    if (writer != NULL) {
-        log_writer = writer;
-        log_writer_ctx = ctx;
-    } else {
-        log_writer = log_writer_null;
-    }
-}
-
-void log_set_level(enum log_level new_level)
-{
-    log_level = new_level;
-}
-
-void log_writer_debug(void *ctx, const char *chars, size_t nchars)
-{
-    OutputDebugStringA(chars);
-}
-
-void log_writer_stdout(void *ctx, const char *chars, size_t nchars)
-{
-    printf("%s", chars);
-}
-
-void log_writer_stderr(void *ctx, const char *chars, size_t nchars)
-{
-    fprintf(stderr, "%s", chars);
-}
-
-void log_writer_file(void *ctx, const char *chars, size_t nchars)
-{
-    fwrite(chars, 1, nchars, (FILE *) ctx);
-    fflush((FILE *) ctx);
-}
-
-void log_writer_null(void *ctx, const char *chars, size_t nchars)
-{
-}
-
-log_formatter_t log_impl_misc = log_builtin_misc;
-log_formatter_t log_impl_info = log_builtin_info;
-log_formatter_t log_impl_warning = log_builtin_warning;
-log_formatter_t log_impl_fatal = log_builtin_fatal;
-static log_writer_t log_writer = log_writer_null;
-static enum log_level log_level = LOG_LEVEL_MISC;

src/main/util/log.h

@@ -1,90 +0,0 @@
-#ifndef UTIL_LOG_H
-#define UTIL_LOG_H
-
-#include <stddef.h>
-#include <stdlib.h>
-
-#include "bemanitools/glue.h"
-
-#include "util/defs.h"
-
-/* Dynamically retargetable logging system modeled on (and potentially
-   integrateable with) the one found in AVS2 */
-
-/* BUILD_MODULE is passed in as a command-line #define by the makefile */
-
-#ifndef LOG_MODULE
-#define LOG_MODULE STRINGIFY(BUILD_MODULE)
-#endif
-
-#ifndef LOG_SUPPRESS
-
-#define log_misc(...) log_impl_misc(LOG_MODULE, __VA_ARGS__)
-#define log_info(...) log_impl_info(LOG_MODULE, __VA_ARGS__)
-#define log_warning(...) log_impl_warning(LOG_MODULE, __VA_ARGS__)
-
-/* This doesn't really belong here, but it's what libavs does so w/e */
-
-#define log_assert(x)                                          \
-    do {                                                       \
-        if (!(x)) {                                            \
-            log_assert_body(__FILE__, __LINE__, __FUNCTION__); \
-        }                                                      \
-    } while (0)
-
-#else
-
-#define log_misc(...)
-#define log_info(...)
-#define log_warning(...)
-#define log_assert(x) \
-    do {              \
-        if (!(x)) {   \
-            abort();  \
-        }             \
-    } while (0)
-
-#endif
-
-#define log_fatal(...)                           \
-    do {                                         \
-        log_impl_fatal(LOG_MODULE, __VA_ARGS__); \
-        abort();                                 \
-    } while (0)
-
-typedef void (*log_writer_t)(void *ctx, const char *chars, size_t nchars);
-
-extern log_formatter_t log_impl_misc;
-extern log_formatter_t log_impl_info;
-extern log_formatter_t log_impl_warning;
-extern log_formatter_t log_impl_fatal;
-
-enum log_level {
-    LOG_LEVEL_FATAL = 0,
-    LOG_LEVEL_WARNING = 1,
-    LOG_LEVEL_INFO = 2,
-    LOG_LEVEL_MISC = 3,
-};
-
-void log_assert_body(const char *file, int line, const char *function);
-void log_to_external(
-    log_formatter_t misc,
-    log_formatter_t info,
-    log_formatter_t warning,
-    log_formatter_t fatal);
-void log_to_writer(log_writer_t writer, void *ctx);
-
-void log_set_level(enum log_level new_level);
-
-/* I tried to make this API match the function signature of the AVS log writer
-   callback, but then the signature changed and the explicit line breaks
-   being passed to that callback went away. So we don't try to track that API
-   any more. Launcher defines its own custom writer anyway. */
-
-void log_writer_debug(void *ctx, const char *chars, size_t nchars);
-void log_writer_stdout(void *ctx, const char *chars, size_t nchars);
-void log_writer_stderr(void *ctx, const char *chars, size_t nchars);
-void log_writer_file(void *ctx, const char *chars, size_t nchars);
-void log_writer_null(void *ctx, const char *chars, size_t nchars);
-
-#endif

src/main/util/thread.c

@@ -1,92 +0,0 @@
-#include <process.h>
-#include <windows.h>
-
-#include <stddef.h>
-#include <stdint.h>
-
-#include "util/defs.h"
-#include "util/thread.h"
-
-struct shim_ctx {
-    HANDLE barrier;
-    int (*proc)(void *);
-    void *ctx;
-};
-
-thread_create_t thread_impl_create = crt_thread_create;
-thread_join_t thread_impl_join = crt_thread_join;
-thread_destroy_t thread_impl_destroy = crt_thread_destroy;
-
-static unsigned int STDCALL crt_thread_shim(void *outer_ctx)
-{
-    struct shim_ctx *sctx = outer_ctx;
-    int (*proc)(void *);
-    void *inner_ctx;
-
-    proc = sctx->proc;
-    inner_ctx = sctx->ctx;
-
-    SetEvent(sctx->barrier);
-
-    return proc(inner_ctx);
-}
-
-int crt_thread_create(
-    int (*proc)(void *), void *ctx, uint32_t stack_sz, unsigned int priority)
-{
-    struct shim_ctx sctx;
-    uintptr_t thread_id;
-
-    sctx.barrier = CreateEvent(NULL, TRUE, FALSE, NULL);
-    sctx.proc = proc;
-    sctx.ctx = ctx;
-
-    thread_id = _beginthreadex(NULL, stack_sz, crt_thread_shim, &sctx, 0, NULL);
-
-    WaitForSingleObject(sctx.barrier, INFINITE);
-    CloseHandle(sctx.barrier);
-
-    return (int) thread_id;
-}
-
-void crt_thread_destroy(int thread_id)
-{
-    CloseHandle((HANDLE) (uintptr_t) thread_id);
-}
-
-void crt_thread_join(int thread_id, int *result)
-{
-    WaitForSingleObject((HANDLE) (uintptr_t) thread_id, INFINITE);
-
-    if (result) {
-        GetExitCodeThread((HANDLE) (uintptr_t) thread_id, (DWORD *) result);
-    }
-}
-
-void thread_api_init(
-    thread_create_t create, thread_join_t join, thread_destroy_t destroy)
-{
-    if (create == NULL || join == NULL || destroy == NULL) {
-        abort();
-    }
-
-    thread_impl_create = create;
-    thread_impl_join = join;
-    thread_impl_destroy = destroy;
-}
-
-int thread_create(
-    int (*proc)(void *), void *ctx, uint32_t stack_sz, unsigned int priority)
-{
-    return thread_impl_create(proc, ctx, stack_sz, priority);
-}
-
-void thread_join(int thread_id, int *result)
-{
-    thread_impl_join(thread_id, result);
-}
-
-void thread_destroy(int thread_id)
-{
-    thread_impl_destroy(thread_id);
-}

src/main/util/thread.h

@@ -1,20 +0,0 @@
-#ifndef UTIL_THREAD_H
-#define UTIL_THREAD_H
-
-#include <stdint.h>
-
-#include "bemanitools/glue.h"
-
-int crt_thread_create(
-    int (*proc)(void *), void *ctx, uint32_t stack_sz, unsigned int priority);
-void crt_thread_join(int thread_id, int *result);
-void crt_thread_destroy(int thread_id);
-
-void thread_api_init(
-    thread_create_t create, thread_join_t join, thread_destroy_t destroy);
-int thread_create(
-    int (*proc)(void *), void *ctx, uint32_t stack_sz, unsigned int priority);
-void thread_join(int thread_id, int *result);
-void thread_destroy(int thread_id);
-
-#endif