From d0c1b3e45bade883829080f5d86bf397df38234a Mon Sep 17 00:00:00 2001
From: Daniel Samson <12231216+daniel-samson@users.noreply.github.com>
Date: Tue, 21 Jul 2026 15:53:45 +0100
Subject: [PATCH] kernel: serialize test markers through the log lock; render
 one write per line
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit

tests.zig wrote markers straight to serial, racing user-process records
rendered on other cores — visible as 16-byte UART-FIFO interleave once
the tagged renderer emitted several writes per record. Markers now go
through kernel log print (same serial sink, now under the log lock), the
renderer composes each line into one buffer and hits each sink once, and
the vfs-client-death needle drops the old self-written 'vfs: ' prefix.
---
 system/kernel/log.zig   | 41 ++++++++++++++++++++++++++++++-----------
 system/kernel/tests.zig | 10 ++++++----
 2 files changed, 36 insertions(+), 15 deletions(-)

diff --git a/system/kernel/log.zig b/system/kernel/log.zig
index e939859..ce1d418 100644
--- a/system/kernel/log.zig
+++ b/system/kernel/log.zig
@@ -139,26 +139,45 @@ fn appendLocked(pid: u32, name: []const u8, level: abi.KlogLevel, now: u64, byte
 fn render(pid: u32, name: []const u8, level: abi.KlogLevel, line: []const u8, line_complete: bool) void {
     if (sink_count == 0) return;
     if (line.len == 0 and !line_complete) return;
+    // Compose the whole rendered piece first and emit it in ONE sink call per
+    // sink: fewer, larger UART writes, and no partial-line window should any
+    // path ever reach a sink without the log lock.
+    var buffer: [render_buffer_size]u8 = undefined;
+    var used: usize = 0;
     if (!at_line_start and open_line_pid != pid) {
-        fanOut("\n");
+        buffer[used] = '\n';
+        used += 1;
         at_line_start = true;
     }
     if (at_line_start and level != .raw) {
-        fanOut(name);
-        fanOut(": ");
-        switch (level) {
-            .err => fanOut("error: "),
-            .warn => fanOut("warning: "),
-            .debug => fanOut("debug: "),
-            .info, .raw => {},
-        }
+        used += place(buffer[used..], name);
+        used += place(buffer[used..], ": ");
+        used += place(buffer[used..], switch (level) {
+            .err => "error: ",
+            .warn => "warning: ",
+            .debug => "debug: ",
+            .info, .raw => "",
+        });
     }
-    fanOut(line);
-    if (line_complete) fanOut("\n");
+    used += place(buffer[used..], line);
+    if (line_complete and used < buffer.len) {
+        buffer[used] = '\n';
+        used += 1;
+    }
+    fanOut(buffer[0..used]);
     at_line_start = line_complete;
     open_line_pid = pid;
 }
 
+/// newline + name + ": warning: " + a full payload line + newline.
+const render_buffer_size = 1 + abi.maximum_process_name + 11 + abi.klog_maximum_message + 1;
+
+fn place(destination: []u8, bytes: []const u8) usize {
+    const n = @min(destination.len, bytes.len);
+    @memcpy(destination[0..n], bytes[0..n]);
+    return n;
+}
+
 fn fanOut(bytes: []const u8) void {
     for (sinks[0..sink_count]) |sink| sink(bytes);
 }
diff --git a/system/kernel/tests.zig b/system/kernel/tests.zig
index b4f6111..0cf6db1 100644
--- a/system/kernel/tests.zig
+++ b/system/kernel/tests.zig
@@ -26,11 +26,13 @@ const irq = @import("irq.zig");
 const sync = @import("sync.zig");
 const process = @import("process.zig");
 const initial_ramdisk = @import("initial-ramdisk");
+const kernel_log = @import("log.zig");
 
-/// Formatted write straight to serial, independent of the framebuffer console.
+/// Formatted test-marker write. Goes through the kernel log (not straight to
+/// serial): the log lock is what keeps marker lines from interleaving with
+/// concurrent user-process records on other cores.
 fn log(comptime fmt: []const u8, args: anytype) void {
-    var buffer: [128]u8 = undefined;
-    architecture.serialWrite(std.fmt.bufPrint(&buffer, fmt, args) catch return);
+    kernel_log.print(fmt, args);
 }
 
 var passed: u32 = 0;
@@ -2171,7 +2173,7 @@ fn vfsClientDeathTest(boot_information: *const BootInformation) void {
     check("the exit notification arrived", badge == abi.notify_badge_bit | abi.notify_exit_bit | client);
 
     // The VFS heard the same published event; its release line is the proof.
-    const released = "vfs: released 1 handle(s) for dead client";
+    const released = "released 1 handle(s) for dead client";
     scheduler.setPriority(1);
     deadline = architecture.millis() + 10000;
     while (architecture.millis() < deadline) {