Implement deferred logging for thread-safe printf

This implements an asynchronous I/O pattern for printf/puts, eliminating
race conditions in preemptive multitasking.
- Ring buffer: 8 entries × 128 bytes (1KB total)
- Logger task at IDLE priority: drains queue to UART
- Mutex-protected enqueue/dequeue with short critical sections
- UART output outside lock: prevents blocking other tasks during writes
- Graceful degradation: falls back to direct output on queue full

Benefits:
- Lower interrupt latency
- ISRs remain responsive during logging
- No nested critical section issues

Author: jserv

Makefile

@@ -17,7 +17,7 @@ include arch/$(ARCH)/build.mk
 INC_DIRS += -I $(SRC_DIR)/include \
             -I $(SRC_DIR)/include/lib
 
-KERNEL_OBJS := timer.o mqueue.o pipe.o semaphore.o mutex.o error.o syscall.o task.o main.o
+KERNEL_OBJS := timer.o mqueue.o pipe.o semaphore.o mutex.o logger.o error.o syscall.o task.o main.o
 KERNEL_OBJS := $(addprefix $(BUILD_KERNEL_DIR)/,$(KERNEL_OBJS))
 deps += $(KERNEL_OBJS:%.o=%.o.d)
 

app/mutex.c

@@ -18,14 +18,13 @@ static int currently_in_critical_section = 0;
 /* Enhanced Task A */
 void task_a(void)
 {
-    /* WORKAROUND: Printf not thread-safe in preemptive mode - minimize usage */
-
     for (int i = 0; i < MAX_ITERATIONS; i++) {
         mo_sem_wait(binary_mutex);
 
         /* === CRITICAL SECTION START === */
         if (currently_in_critical_section != 0) {
             critical_section_violations++;
+            printf("Task A: VIOLATION detected at iteration %d\n", i);
         }
         currently_in_critical_section = mo_task_id();
 
@@ -37,9 +36,11 @@ void task_a(void)
 
         shared_counter = old_counter + 1;
         task_a_count++;
+        printf("Task A: iteration %d, counter=%d\n", i, shared_counter);
 
         if (currently_in_critical_section != mo_task_id()) {
             critical_section_violations++;
+            printf("Task A: VIOLATION on exit at iteration %d\n", i);
         }
         currently_in_critical_section = 0;
         /* === CRITICAL SECTION END === */
@@ -51,6 +52,8 @@ void task_a(void)
             mo_task_yield();
     }
 
+    printf("Task A completed all iterations\n");
+
     /* Keep running to prevent panic */
     while (1) {
         for (int i = 0; i < 10; i++)
@@ -61,18 +64,18 @@ void task_a(void)
 /* Enhanced Task B */
 void task_b(void)
 {
-    /* WORKAROUND: Printf not thread-safe in preemptive mode - minimize usage */
-
     for (int i = 0; i < MAX_ITERATIONS; i++) {
         /* Try non-blocking first */
         int32_t trylock_result = mo_sem_trywait(binary_mutex);
         if (trylock_result != ERR_OK) {
+            printf("Task B: trylock failed, blocking at iteration %d\n", i);
             mo_sem_wait(binary_mutex);
         }
 
         /* === CRITICAL SECTION START === */
         if (currently_in_critical_section != 0) {
             critical_section_violations++;
+            printf("Task B: VIOLATION detected at iteration %d\n", i);
         }
         currently_in_critical_section = mo_task_id();
 
@@ -84,9 +87,11 @@ void task_b(void)
 
         shared_counter = old_counter + 10;
         task_b_count++;
+        printf("Task B: iteration %d, counter=%d\n", i, shared_counter);
 
         if (currently_in_critical_section != mo_task_id()) {
             critical_section_violations++;
+            printf("Task B: VIOLATION on exit at iteration %d\n", i);
         }
         currently_in_critical_section = 0;
         /* === CRITICAL SECTION END === */
@@ -98,6 +103,8 @@ void task_b(void)
             mo_task_yield();
     }
 
+    printf("Task B completed all iterations\n");
+
     /* Keep running to prevent panic */
     while (1) {
         for (int i = 0; i < 10; i++)
@@ -108,15 +115,16 @@ void task_b(void)
 /* Simple monitor task */
 void monitor_task(void)
 {
-    /* WORKAROUND: Printf not thread-safe - only print at end when tasks idle */
-
     int cycles = 0;
 
+    printf("Monitor: Starting test monitoring\n");
+
     while (cycles < 50) { /* Monitor for reasonable time */
         cycles++;
 
         /* Check if both tasks completed */
         if (task_a_count >= MAX_ITERATIONS && task_b_count >= MAX_ITERATIONS) {
+            printf("Monitor: Both tasks completed, finalizing test\n");
             break;
         }
 
@@ -125,11 +133,11 @@ void monitor_task(void)
             mo_task_yield();
     }
 
-    /* Wait a bit for tasks to fully idle */
+    /* Wait a bit for tasks to fully complete */
     for (int i = 0; i < 50; i++)
         mo_task_yield();
 
-    /* Final report - safe to print when other tasks are idle */
+    /* Final report */
     printf("\n=== FINAL RESULTS ===\n");
     printf("Task A iterations: %d\n", task_a_count);
     printf("Task B iterations: %d\n", task_b_count);
@@ -193,7 +201,9 @@ int32_t app_main(void)
         return false;
     }
 
-    /* CRITICAL FIX: Printf hangs after task_spawn - remove all printf calls */
-    /* Tasks created: A=%d, B=%d, Monitor=%d, Idle=%d */
+    printf("Tasks created: A=%d, B=%d, Monitor=%d, Idle=%d\n", task_a_id,
+           task_b_id, monitor_id, idle_id);
+    printf("Enabling preemptive scheduling mode\n");
+
     return true; /* Enable preemptive scheduling */
 }

include/lib/libc.h

@@ -141,6 +141,7 @@ int random_r(struct random_data *buf, int32_t *result);
 
 /* Character and string output */
 int32_t puts(const char *str);
+int _putchar(int c); /* Low-level character output (used by logger) */
 
 /* Character and string input */
 int getchar(void);

include/linmo.h

@@ -6,6 +6,7 @@
 #include <lib/malloc.h>
 
 #include <sys/errno.h>
+#include <sys/logger.h>
 #include <sys/mqueue.h>
 #include <sys/mutex.h>
 #include <sys/pipe.h>

include/private/error.h

@@ -26,7 +26,7 @@ enum {
     ERR_NOT_OWNER,          /* Operation requires ownership */
 
     /* Memory Protection Errors */
-    ERR_STACK_CHECK, /* Stack overflow or corruption detected */
+    ERR_STACK_CHECK,  /* Stack overflow or corruption detected */
     ERR_HEAP_CORRUPT, /* Heap corruption or invalid free detected */
 
     /* IPC and Synchronization Errors */

include/sys/logger.h

@@ -0,0 +1,60 @@
+#pragma once
+
+/* Deferred logging system for thread-safe printf in preemptive mode.
+ *
+ * Architecture:
+ * - printf/puts format into a buffer and enqueue the complete message
+ * - Logger task dequeues messages and outputs to UART
+ * - Minimal critical sections (only during enqueue/dequeue operations)
+ * - No long interrupt disable periods during UART output
+ *
+ * Benefits:
+ * - Low interrupt latency
+ * - ISRs remain responsive during logging
+ * - No nested critical section issues
+ * - Proper separation between formatting and output
+ */
+
+#include <types.h>
+
+/* Logger Configuration - Optimized for memory efficiency
+ * These values balance memory usage with logging capacity:
+ * - 8 entries handles typical burst logging scenarios
+ * - 128 bytes accommodates most debug messages
+ * Total buffer overhead: 8 × 128 = 1KB (down from 4KB)
+ */
+#define LOG_QSIZE 8      /* Number of log entries in ring buffer */
+#define LOG_ENTRY_SZ 128 /* Maximum length of single log message */
+
+/* Logger Control */
+
+/* Initialize the logger subsystem.
+ * Creates the log queue and spawns the logger task.
+ * Must be called during kernel initialization, after heap and task system init.
+ *
+ * Returns ERR_OK on success, ERR_FAIL on failure
+ */
+int32_t mo_logger_init(void);
+
+/* Enqueue a log message for deferred output.
+ * Non-blocking: if queue is full, message is dropped.
+ * Thread-safe: protected by short critical section.
+ * @msg    : Null-terminated message string
+ * @length : Length of message (excluding null terminator)
+ *
+ * Returns ERR_OK if enqueued, ERR_BUSY if queue full
+ */
+int32_t mo_logger_enqueue(const char *msg, uint16_t length);
+
+/* Get the number of messages currently in the queue.
+ * Useful for monitoring queue depth and detecting overruns.
+ *
+ * Returns number of queued messages
+ */
+uint32_t mo_logger_queue_depth(void);
+
+/* Get the total number of dropped messages due to queue overflow.
+ *
+ * Returns total dropped message count since logger init
+ */
+uint32_t mo_logger_dropped_count(void);

kernel/logger.c

@@ -0,0 +1,151 @@
+/* Deferred logging: async I/O pattern for thread-safe printf.
+ *
+ * Design rationale:
+ * - Ring buffer + mutex
+ * - Logger task at IDLE priority: drains queue without blocking tasks
+ * - UART output outside lock: other tasks enqueue while we output
+ * - Graceful degradation: fallback to direct output on queue full
+ */
+
+#include <lib/libc.h>
+#include <sys/logger.h>
+#include <sys/mutex.h>
+#include <sys/task.h>
+
+#include "private/error.h"
+
+/* Ring buffer entry: fixed-size for O(1) enqueue/dequeue */
+typedef struct {
+    uint16_t length;
+    char data[LOG_ENTRY_SZ];
+} log_entry_t;
+
+/* Logger state: single global instance, no dynamic allocation */
+typedef struct {
+    log_entry_t queue[LOG_QSIZE];
+    uint32_t head, tail, count;
+    uint32_t dropped; /* Diagnostic: tracks queue overflow events */
+    mutex_t lock;     /* Protects queue manipulation, not UART output */
+    int32_t task_id;
+    bool initialized;
+} logger_state_t;
+
+static logger_state_t logger;
+
+/* Logger task: IDLE priority ensures application tasks run first */
+static void logger_task(void)
+{
+    log_entry_t entry;
+
+    while (1) {
+        bool have_message = false;
+
+        /* Critical section: only queue manipulation, not UART I/O */
+        mo_mutex_lock(&logger.lock);
+        if (logger.count > 0) {
+            memcpy(&entry, &logger.queue[logger.tail], sizeof(log_entry_t));
+            logger.tail = (logger.tail + 1) % LOG_QSIZE;
+            logger.count--;
+            have_message = true;
+        }
+        mo_mutex_unlock(&logger.lock);
+
+        if (have_message) {
+            /* Key design: UART output outside lock prevents blocking enqueuers.
+             * shorter UART write does not hold mutex - other tasks enqueue in
+             * parallel.
+             */
+            for (uint16_t i = 0; i < entry.length; i++)
+                _putchar(entry.data[i]);
+        } else {
+            /* Block when idle: sleep 1 tick, scheduler wakes us next period */
+            mo_task_delay(1);
+        }
+    }
+}
+
+/* Call after heap + task system init, before enabling preemption */
+int32_t mo_logger_init(void)
+{
+    if (logger.initialized)
+        return ERR_OK;
+
+    memset(&logger, 0, sizeof(logger_state_t));
+
+    if (mo_mutex_init(&logger.lock) != ERR_OK)
+        return ERR_FAIL;
+
+    /* 512B stack: simple operations only (no printf/recursion/ISR use) */
+    logger.task_id = mo_task_spawn(logger_task, 512);
+    if (logger.task_id < 0) {
+        mo_mutex_destroy(&logger.lock);
+        return ERR_FAIL;
+    }
+
+    /* IDLE priority: runs only when no application tasks are ready */
+    mo_task_priority(logger.task_id, TASK_PRIO_IDLE);
+
+    logger.initialized = true;
+    return ERR_OK;
+}
+
+/* Non-blocking enqueue: returns ERR_TASK_BUSY on overflow, never waits */
+int32_t mo_logger_enqueue(const char *msg, uint16_t length)
+{
+    if (!logger.initialized || !msg || length == 0)
+        return ERR_FAIL;
+
+    /* Defensive check: stdio.c pre-filters, but validate anyway */
+    if (length > LOG_ENTRY_SZ - 1)
+        length = LOG_ENTRY_SZ - 1;
+
+    mo_mutex_lock(&logger.lock);
+
+    /* Drop message on full queue: non-blocking design, caller falls back to
+     * direct I/O
+     */
+    if (logger.count >= LOG_QSIZE) {
+        logger.dropped++;
+        mo_mutex_unlock(&logger.lock);
+        return ERR_TASK_BUSY;
+    }
+
+    log_entry_t *entry = &logger.queue[logger.head];
+    entry->length = length;
+    memcpy(entry->data, msg, length);
+    /* Safety: enables direct string ops on data[] */
+    entry->data[length] = '\0';
+
+    logger.head = (logger.head + 1) % LOG_QSIZE;
+    logger.count++;
+
+    mo_mutex_unlock(&logger.lock);
+
+    return ERR_OK;
+}
+
+/* Diagnostic: monitor queue depth to detect sustained overflow conditions */
+uint32_t mo_logger_queue_depth(void)
+{
+    if (!logger.initialized)
+        return 0;
+
+    mo_mutex_lock(&logger.lock);
+    uint32_t depth = logger.count;
+    mo_mutex_unlock(&logger.lock);
+
+    return depth;
+}
+
+/* Diagnostic: total messages lost since init (non-resettable counter) */
+uint32_t mo_logger_dropped_count(void)
+{
+    if (!logger.initialized)
+        return 0;
+
+    mo_mutex_lock(&logger.lock);
+    uint32_t dropped = logger.dropped;
+    mo_mutex_unlock(&logger.lock);
+
+    return dropped;
+}

kernel/main.c

@@ -1,5 +1,6 @@
 #include <hal.h>
 #include <lib/libc.h>
+#include <sys/logger.h>
 #include <sys/task.h>
 
 #include "private/error.h"
@@ -23,6 +24,17 @@ int32_t main(void)
     printf("Heap initialized, %u bytes available\n",
            (unsigned int) (size_t) &_heap_size);
 
+    /* Initialize deferred logging system.
+     * Must be done after heap init but before app_main() to ensure
+     * application tasks can use thread-safe printf.
+     * Note: Early printf calls (above) use direct output fallback.
+     */
+    if (mo_logger_init() != 0) {
+        printf("Warning: Logger initialization failed, using direct output\n");
+    } else {
+        printf("Logger initialized\n");
+    }
+
     /* Call the application's main entry point to create initial tasks. */
     kcb->preemptive = (bool) app_main();
     printf("Scheduler mode: %s\n",