[*] cool new multithreaded logging infrastructure!

src/ax.h

@@ -19,7 +19,9 @@ void ax_free(struct ax_ctxt* ax);
 const char* ax_get_error(struct ax_ctxt* ax);
 
 void ax_set_logger(struct ax_ctxt* ax, int fd, bool auto_close);
-void ax_log(struct ax_ctxt* ax, const char* string);
+void ax_log(struct ax_ctxt* ax, const char* str);
+void ax_logf(struct ax_ctxt* ax, const char* fmt_str, ...)
+    __attribute__( (format (printf, 2, 3)) );
 
 /* -----------------------------------------------------------------------------
  * Themes

src/backend.h

@@ -6,6 +6,7 @@
 
 struct rgn;
 struct msgq;
+struct log;
 struct ax_backend;
 struct ax_theme;
 
@@ -16,6 +17,7 @@ extern size_t ax__backend_desired_region_size;
 
 int ax__backend_new(
     struct rgn* init_rgn,
+    struct log* lg,
     struct ax_backend** out_bac,
     const char** out_err);
 

src/backend/sdl.c

@@ -4,6 +4,7 @@
 #include "../util.h"
 #include "../util/region.h"
 #include "../util/functions.h"
+#include "../util/log.h"
 #include "../concurrent/msg.h"
 #include "../concurrent/msgq.h"
 #include "../concurrent/pubsub.h"
@@ -23,6 +24,7 @@ size_t ax__backend_desired_region_size = MEDIUM;
 
 struct ax_backend {
     struct rgn* rgn;
+    struct log* lg;
     struct msgq* inbox;
     struct pubsub* events;
     bool shutdown;
@@ -37,6 +39,7 @@ static void backend_cleanup(struct ax_backend* bac);
 
 int ax__backend_new(
     struct rgn* init_rgn,
+    struct log* lg,
     struct ax_backend** out_bac,
     const char** out_err)
 {
@@ -54,6 +57,7 @@ int ax__backend_new(
     rgn_pin(init_rgn, bac, (void*) backend_cleanup);
 
     bac->rgn = init_rgn;
+    bac->lg = log_derived(lg, "SDL");
     bac->inbox = msgq_new(init_rgn);
     bac->events = pubsub_new(init_rgn);
     bac->shutdown = false;
@@ -62,7 +66,7 @@ int ax__backend_new(
     if (out_bac != NULL) {
         *out_bac = bac;
     }
-    printf("hello from SDL\n");
+    log_writelnf(bac->lg, "hello from SDL");
     return 0;
 
 fail:
@@ -74,9 +78,9 @@ fail:
 
 static void backend_cleanup(struct ax_backend* bac)
 {
+    log_writelnf(bac->lg, "bye from SDL");
     TTF_Quit();
     SDL_Quit();
-    printf("bye from SDL\n");
 }
 
 struct msgq* ax__backend_msgq(struct ax_backend* bac)
@@ -170,7 +174,9 @@ void ax__backend_step(struct ax_backend* bac)
 
         default:
             nmsg++;
-            printf("Got a weird message: `%s'\n", ax__msg_name(m_type));
+            log_writelnf(bac->lg,
+                         "Got a weird message: `%s'",
+                         ax__msg_name(m_type));
             break;
     }
     msgq_end_recv(bac->inbox);
@@ -193,10 +199,10 @@ struct ax_font_h {
 };
 
 static int load_font(
-    struct rgn* rgn, const char* path, size_t size,
+    struct rgn* rgn, struct log* lg, const char* path, size_t size,
     struct ax_font_h** out_fh, const char** out_err)
 {
-    printf("loading `%s' (size %zu)\n", path, size);
+    log_writelnf(lg, "loading `%s' (size %zu)", path, size);
     struct ax_font_h* fh = ralloc_typed(rgn, struct ax_font_h, 1);
     if ((fh->font = TTF_OpenFont(path, size)) == NULL) {
         *out_err = TTF_GetError();
@@ -215,6 +221,7 @@ static void load_fonts(struct ax_backend* bac, struct font_list* fl)
         struct ax_theme* thm = fl->thm;
         struct ax_font_h* fh;
         if ((rv = load_font(bac->rgn,
+                            bac->lg,
                             thm->font_path[fl->cat],
                             thm->font_size[fl->cat],
                             &fh, &err)) != 0) {

src/concurrent/pubsub.c

@@ -96,7 +96,7 @@ void* pubsub_begin_pub(struct pubsub* src, int type, size_t payload_size)
     }
     msg_init(msg, msg_rgn, type, rc);
     src->msg_rgn = msg_rgn;
-    printf("[pubsub] sending message to %zu subscribers.\n", rc);
+    // printf("[pubsub] sending message to %zu subscribers.\n", rc);
     return msg->payload;
 }
 
@@ -123,7 +123,7 @@ static void msg_release(struct pubsub_msg* msg)
 {
     size_t rc = atomic_fetch_sub(&msg->rc, 1);
     if (rc == 1) {
-        printf("[pubsub] destroying message object %p\n", msg);
+        // printf("[pubsub] destroying message object %p\n", msg);
         rgn_cleanup(msg->rgn);
     }
 }
@@ -157,7 +157,7 @@ void* sub_recv1(struct sub* sub, int* out_type)
         if (out_type != NULL) {
             *out_type = msg->type;
         }
-        printf("[pubsub] received message object %p\n", msg);
+        // printf("[pubsub] received message object %p\n", msg);
         return msg->payload;
     }
 }

src/ctxt.h

@@ -12,13 +12,14 @@ struct ax_window_builder;
 struct ax_backend;
 struct ax_evt_list;
 struct ax_graphics;
+struct log;
 
 struct ax_ctxt {
     struct rgn* init_rgn;
 
     // logging
-    FILE* log_out;
+    struct log* root_lg;
-    bool log_auto_close;
+    struct log* user_lg;
 
     // errors
     struct rgn* err_rgn;

src/ctxt/ctxt.c

@@ -5,6 +5,7 @@
 #include "../concurrent/pubsub.h"
 #include "../ctxt.h"
 #include "../util.h"
+#include "../util/log.h"
 #include "theme.h"
 #include "window.h"
 #include <unistd.h>
@@ -42,17 +43,16 @@ const char* ax_get_error(struct ax_ctxt* ax)
 
 static void spawn_backend(
     struct rgn* init_rgn,
+    struct log* init_lg,
     pthread_t* out_thid,
     struct ax_backend** out_backend);
 
 void ax__ctxt_init(struct ax_ctxt* ax, struct rgn* init_rgn)
 {
-    /* init simple stuff */
-
     ax->init_rgn = init_rgn;
 
-    ax->log_out = NULL;
+    ax->root_lg = log_new(init_rgn, "ax");
-    ax->log_auto_close = false;
+    ax->user_lg = log_derived(ax->root_lg, "user");
 
     ax->err_rgn = rgn_new(init_rgn, SMALL);
     ax->err = "";
@@ -66,7 +66,8 @@ void ax__ctxt_init(struct ax_ctxt* ax, struct rgn* init_rgn)
     ax->sel_win = NULL;
 
     ax->bac = NULL;
-    spawn_backend(init_rgn, &ax->bac_thid, &ax->bac);
+    struct log* bac_lg = log_derived(ax->root_lg, "backend");
+    spawn_backend(init_rgn, bac_lg, &ax->bac_thid, &ax->bac);
     ASSERT(ax->bac != NULL, "backend wasn't initialized");
 }
 
@@ -75,10 +76,6 @@ static void shutdown(struct msgq* mq, pthread_t thid);
 void ax__ctxt_cleanup(struct ax_ctxt* ax)
 {
     shutdown(ax__backend_msgq(ax->bac), ax->bac_thid);
-
-    if (ax->log_auto_close) {
-        fclose(ax->log_out);
-    }
 }
 
 /* -----------------------------------------------------------------------------
@@ -87,18 +84,20 @@ void ax__ctxt_cleanup(struct ax_ctxt* ax)
 
 void ax_set_logger(struct ax_ctxt* ax, int fd, bool auto_close)
 {
-    if (ax->log_auto_close) {
+    log_set_fd(ax->root_lg, fd, auto_close);
-        fclose(ax->log_out);
-    }
-    ax->log_out = fdopen(fd, "w");
-    ax->log_auto_close = auto_close;
 }
 
 void ax_log(struct ax_ctxt* ax, const char* string)
 {
-    if (ax->log_out != NULL) {
+    ax_logf(ax, "%s", string);
-        fprintf(ax->log_out, "[LOG] %s\n", string);
+}
-    }
+
+void ax_logf(struct ax_ctxt* ax, const char* fmt_str, ...)
+{
+    va_list vl;
+    va_start(vl, fmt_str);
+    log_writelnvf(ax->user_lg, fmt_str, vl);
+    va_end(vl);
 }
 
 /* -----------------------------------------------------------------------------
@@ -114,7 +113,7 @@ void ax_begin_theme(struct ax_ctxt* ax)
 struct ax_theme* ax_end_theme(struct ax_ctxt* ax)
 {
     if (ax->thmb == NULL) {
-        ax_log(ax, "`ax_end_theme' called while not building a theme");
+        log_writelnf(ax->root_lg, "`ax_end_theme' called while not building a theme");
         return NULL;
     }
     struct ax_theme* thm = ax__theme_builder_finish(
@@ -130,7 +129,7 @@ void ax_set_theme_color(
     struct ax_ctxt* ax, const char* cat_name, int64_t rgb)
 {
     if (ax->thmb == NULL) {
-        ax_log(ax, "`ax_set_theme_color' called while not building a theme");
+        log_writelnf(ax->root_lg, "`ax_set_theme_color' called while not building a theme");
         return;
     }
     enum ax_color_cat cat;
@@ -146,7 +145,7 @@ void ax_set_theme_font(
     struct ax_ctxt* ax, const char* cat_name, const char* fnt_path, size_t fnt_size)
 {
     if (ax->thmb == NULL) {
-        ax_log(ax, "`ax_set_theme_font' called while not building a theme");
+        log_writelnf(ax->root_lg, "`ax_set_theme_font' called while not building a theme");
         return;
     }
     enum ax_font_cat cat;
@@ -161,7 +160,7 @@ void ax_set_theme_font(
 void ax_set_theme_iconset(struct ax_ctxt* ax, const char* iconset_dir)
 {
     if (ax->thmb == NULL) {
-        ax_log(ax, "`ax_set_theme_iconset' called while not building a theme");
+        log_writelnf(ax->root_lg, "`ax_set_theme_iconset' called while not building a theme");
         return;
     }
     UNIMPLEMENTED();
@@ -177,7 +176,7 @@ void ax_theme_wait_until_loaded(struct ax_ctxt* ax, struct ax_theme* thm)
         SUB_RECV_ALL(sub) { default: break; }
         sub_end_recv(sub);
     } else {
-        ax_log(ax, "subscriber is NULL, this means the theme is already loaded");
+        log_writelnf(ax->root_lg, "subscriber is NULL, this means the theme is already loaded");
     }
     rgn_cleanup(&rgn);
 }
@@ -194,7 +193,7 @@ int ax_select_theme(struct ax_ctxt* ax, struct ax_theme* thm)
         return AX_ERR_THEME_LOADING;
     }
     ax->sel_thm = thm;
-    ax_log(ax, "theme selected");
+    log_writelnf(ax->root_lg, "selected theme %p", thm);
     return 0;
 }
 
@@ -212,7 +211,7 @@ void ax_set_window_title(
     struct ax_ctxt* ax, const char* text)
 {
     if (ax->winb == NULL) {
-        ax_log(ax, "`ax_set_window_title' called while not building a window");
+        log_writelnf(ax->root_lg, "`ax_set_window_title' called while not building a window");
         return;
     }
     ax__window_set_title(ax->winb, text);
@@ -222,7 +221,7 @@ void ax_set_window_size(
     struct ax_ctxt* ax, uint64_t w, uint64_t h, bool resizable)
 {
     if (ax->winb == NULL) {
-        ax_log(ax, "`ax_set_window_size' called while not building a window");
+        log_writelnf(ax->root_lg, "`ax_set_window_size' called while not building a window");
         return;
     }
     ax__window_set_size(ax->winb, w, h);
@@ -232,7 +231,7 @@ void ax_set_window_size(
 struct ax_window* ax_end_window(struct ax_ctxt* ax)
 {
     if (ax->winb == NULL) {
-        ax_log(ax, "`ax_end_window' called while not building a window");
+        log_writelnf(ax->root_lg, "`ax_end_window' called while not building a window");
         return NULL;
     }
     struct ax_window* win =
@@ -249,7 +248,7 @@ int ax_select_window(struct ax_ctxt* ax, struct ax_window* win)
 {
     ASSERT_NON_NULL(win, "window");
     ax->sel_win = win;
-    ax_log(ax, "window selected");
+    log_writelnf(ax->root_lg, "selected window %p", win);
     return 0;
 }
 
@@ -260,6 +259,7 @@ int ax_select_window(struct ax_ctxt* ax, struct ax_window* win)
 struct backend_init_ctxt {
     // "input"
     struct rgn* rgn;
+    struct log* root_lg;
     pthread_mutex_t mx;
     pthread_cond_t cv;
 
@@ -272,12 +272,14 @@ static void* backend_worker(void* arg);
 
 static void spawn_backend(
     struct rgn* init_rgn,
+    struct log* root_lg,
     pthread_t* out_thid,
     struct ax_backend** out_backend)
 {
     pthread_t thid;
     struct backend_init_ctxt init;
     init.rgn = init_rgn;
+    init.root_lg = root_lg;
     init.err = NULL;
     pthread_mutex_init(&init.mx, NULL);
     pthread_cond_init(&init.cv, NULL);
@@ -309,7 +311,7 @@ static void* backend_worker(void* arg)
 
     struct ax_backend* bac;
     const char* err = NULL;
-    int rv = ax__backend_new(bac_rgn, &bac, &err);
+    int rv = ax__backend_new(bac_rgn, init->root_lg, &bac, &err);
 
     pthread_mutex_lock(&init->mx);
     init->backend = bac;

src/util/log.c

@@ -0,0 +1,124 @@
+#include "log.h"
+#include "../util.h"
+#include "region.h"
+#include <stdio.h>
+#include <string.h>
+#include <pthread.h>
+
+struct log_port;
+
+struct log {
+    struct rgn* derive_rgn;  // used to alloc derived loggers
+    struct rgn* tmp_str_rgn; // (re)used for format strings
+
+    struct log_port* port;
+    const char* prefix;
+};
+
+struct log_port {
+    pthread_mutex_t mx;
+    FILE* file;
+    bool autoclose;
+    size_t padding; // TODO: auto-adjust padding
+};
+
+static void init_log_port(struct log_port* lp);
+static void cleanup_log_port(struct log_port* lp);
+static void set_log_port_file(struct log_port* lp, FILE* f, bool ac);
+
+static struct log* make_log(
+    struct rgn* init_rgn, const char* prefix, struct log_port* port)
+{
+    struct log* lg = ralloc_typed(init_rgn, struct log, 1);
+    lg->derive_rgn = rgn_new(init_rgn, SMALL);
+    lg->tmp_str_rgn = rgn_new(init_rgn, SMALL); // TODO: "TINY" page-size
+    lg->prefix = rstrdup(init_rgn, prefix);
+    lg->port = port;
+    return lg;
+}
+
+struct log* log_new(struct rgn* init_rgn, const char* prefix)
+{
+    struct log_port* port = ralloc_typed(init_rgn, struct log_port, 1);
+    rgn_pin(init_rgn, port, (void*) cleanup_log_port);
+    init_log_port(port);
+    return make_log(init_rgn, prefix, port);
+}
+
+struct log* log_derived(struct log* parent, const char* child_suffix)
+{
+    rgn_clear(parent->tmp_str_rgn);
+    return make_log(
+        parent->derive_rgn,
+        rsprintf(parent->tmp_str_rgn,
+                 "%s::%s",
+                 parent->prefix, child_suffix),
+        parent->port);
+}
+
+void log_set_fd(struct log* lg, int fd, bool auto_close)
+{
+    set_log_port_file(lg->port, fdopen(fd, "w"), auto_close);
+}
+
+void log_close(struct log* lg)
+{
+    set_log_port_file(lg->port, NULL, false);
+}
+
+static void init_log_port(struct log_port* lp)
+{
+    pthread_mutex_init(&lp->mx, NULL);
+    lp->file = NULL;
+    lp->autoclose = false;
+    lp->padding = 16;
+}
+
+static void cleanup_log_port(struct log_port* lp)
+{
+    set_log_port_file(lp, NULL, false);
+    pthread_mutex_destroy(&lp->mx);
+}
+
+static void set_log_port_file(struct log_port* lp, FILE* f, bool ac)
+{
+    pthread_mutex_lock(&lp->mx);
+    if (lp->file != NULL && lp->autoclose) {
+        fclose(lp->file);
+    }
+    lp->file = f;
+    lp->autoclose = ac;
+    pthread_mutex_unlock(&lp->mx);
+}
+
+void log_writeln(struct log* lg, const char* str)
+{
+    pthread_mutex_lock(&lg->port->mx);
+    if (lg->port->file) {
+        int pad = lg->port->padding - strlen(lg->prefix);
+        fprintf(lg->port->file, "%*s[%s] %s\n", pad, "", lg->prefix, str);
+        fflush(lg->port->file);
+    }
+    pthread_mutex_unlock(&lg->port->mx);
+}
+
+void log_writelnvf(struct log* lg, const char* fmt_str, va_list vl)
+{
+    va_list vl2;
+    va_copy(vl2, vl);
+    size_t len = vsnprintf(NULL, 0, fmt_str, vl2);
+    va_end(vl2);
+
+    rgn_clear(lg->tmp_str_rgn);
+    char* str = ralloc_typed(lg->tmp_str_rgn, char, len + 1);
+    vsprintf(str, fmt_str, vl);
+    log_writeln(lg, str);
+}
+
+void log_writelnf(struct log* lg, const char* fmt_str, ...)
+{
+    va_list vl;
+    va_start(vl, fmt_str);
+    log_writelnvf(lg, fmt_str, vl);
+    va_end(vl);
+}

src/util/log.h

@@ -0,0 +1,37 @@
+#pragma once
+
+#include <stdbool.h>
+#include <stdarg.h>
+
+//////////////////////////////////////////////////////////////////////////////////////////
+// IMPORTANT NOTES ABOUT THREAD SAFETY:
+// -------
+// functions on a particular logger (e.g., `log_writeln' or `log_derived') are NOT
+// thread-safe, insofar as all access to that logger must be on the same thread. however,
+// once you have created multiple loggers, even if they are derived from eachother, you
+// may access them independently in other threads.
+//
+// as an exception, the `log_set_fd' and `log_close' functions are *thread safe*, so you
+// can call them from any thread you like, on any logger you choose. they will affect all
+// of the loggers derived from the root of the logger you call it on.
+//
+// EXAMPLE: in thread 1 you might create a root loger (via `log_new'), and then create a
+// child logger from that (via `log_derived'). now, you spawn thread 2, use the child
+// logger exclusively in that thread, and use the root logger exclusively in thread 1. it
+// would be unsafe to pass the root logger to thread 2 and try to create a child logger,
+// since `log_derived' is not thread safe.
+//////////////////////////////////////////////////////////////////////////////////////////
+
+struct log;
+struct rgn;
+
+struct log* log_new(struct rgn* dst_rgn, const char* prefix);
+struct log* log_derived(struct log* parent, const char* child_suffix);
+// TODO: tee to multiple files
+void log_set_fd(struct log* lg, int fd, bool auto_close);
+void log_close(struct log* lg);
+
+void log_writeln(struct log* lg, const char* str);
+void log_writelnvf(struct log* lg, const char* fmt_str, va_list vl);
+void log_writelnf(struct log* lg, const char* fmt_str, ...)
+    __attribute__( (format (printf, 2, 3)) );

test/main.c

@@ -54,6 +54,7 @@ int main(void)
 
     ax = ax_new();
     ax_set_logger(ax, fileno(stdout), false);
+    ax_logf(ax, "hello world.");
 
     rgn = rgn_bootstrap_new(SMALL);
 
@@ -64,7 +65,7 @@ int main(void)
     struct ax_theme* thm = make_example_theme();
 
     ax_theme_wait_until_loaded(ax, thm);
-    printf("it loaded!\n");
+    ax_logf(ax, "theme loaded!");
 
     GUARD(ax_select_theme(ax, thm));
     GUARD(ax_select_window(ax, win));
@@ -83,7 +84,7 @@ int main(void)
                });
 
             default:
-                printf("got a message: %s\n", ax__msg_name(m_type));
+                ax_logf(ax, "Got a message: %s", ax__msg_name(m_type));
                 break;
         }
         sub_end_recv(ev_sub);