logger: per-process log files under /var/log/<boot-stamp>/

The logger service drains the tagged ring every 250 ms and demultiplexes
it into one file per process on the flash volume:

    /mnt/usb/var/log/2026-07-21T150434Z/system/services/fat.log
    [     0.214] mounted FAT (fat32, 128992 clusters, partition lba 0)

The boot stamp is the wall-clock anchor from klog_status (FAT-safe, no
colons); the kernel's records go to kernel.log; each line carries the
record's monotonic timestamp and level. Storage is best-effort and
late — the ring buffers a whole boot until the mount appears, then the
first drain writes the backlog, storage-stack records included. Lost
records surface as '-- N records lost --' from sequence gaps. Files
close (= fat's device cache flush) after a 2 s quiet period, bounding
data-at-risk without per-record flush thrash. The logger announces
itself once — a periodic status line would feed the stream it drains.

init spawns the logger last, so the reverse-order shutdown stops it
first and its final drain runs over a live storage chain; log-flush and
init's own DANOS.LOG shutdown flush retire (superseded). runtime.fs
makePath treats components at or above a mount point as router names —
create is best-effort per prefix, the final verdict is exists(path).
This commit is contained in:
Daniel Samson
2026-07-21 16:05:46 +01:00
parent 30d6ea622a
commit 127ea2dad9
7 changed files with 325 additions and 118 deletions
+2 -2
View File
@@ -581,7 +581,7 @@ pub fn build(b: *std.Build) void {
const input_test_exe = addUserBinary(b, kernel_target, runtime_module, mmio_module, xkeyboard_config_module, acpi_ids_module, "input-test", "system/services/input-test/input-test.zig");
const args_echo_exe = addUserBinary(b, kernel_target, runtime_module, mmio_module, xkeyboard_config_module, acpi_ids_module, "args-echo", "system/services/args-echo/args-echo.zig");
const process_test_exe = addUserBinary(b, kernel_target, runtime_module, mmio_module, xkeyboard_config_module, acpi_ids_module, "process-test", "system/services/process-test/process-test.zig");
const log_flush_exe = addUserBinary(b, kernel_target, runtime_module, mmio_module, xkeyboard_config_module, acpi_ids_module, "log-flush", "system/services/log-flush/log-flush.zig");
const logger_exe = addUserBinary(b, kernel_target, runtime_module, mmio_module, xkeyboard_config_module, acpi_ids_module, "logger", "system/services/logger/logger.zig");
// The first multi-threaded binary: exercises runtime.Thread over the thread ABI
// (docs/threading.md). Built threaded so its shared-memory poll is real.
const thread_test_exe = addThreadedUserBinary(b, kernel_target, runtime_module, mmio_module, xkeyboard_config_module, acpi_ids_module, "thread-test", "system/services/thread-test/thread-test.zig");
@@ -601,7 +601,7 @@ pub fn build(b: *std.Build) void {
.{ .path = "system/services/device-manager", .binary = device_manager_exe.getEmittedBin() },
.{ .path = "system/services/input", .binary = input_exe.getEmittedBin() },
.{ .path = "system/services/discovery", .binary = discovery_exe.getEmittedBin() },
.{ .path = "system/services/log-flush", .binary = log_flush_exe.getEmittedBin() },
.{ .path = "system/services/logger", .binary = logger_exe.getEmittedBin() },
.{ .path = "system/drivers/ps2-bus", .binary = ps2_bus_exe.getEmittedBin() },
.{ .path = "system/drivers/ps2-keyboard", .binary = ps2_keyboard_exe.getEmittedBin() },
.{ .path = "system/drivers/ps2-mouse", .binary = ps2_mouse_exe.getEmittedBin() },
+5 -2
View File
@@ -247,9 +247,12 @@ pub fn makePath(path: []const u8) bool {
while (end < path.len and path[end] != '/') end += 1;
const prefix = path[0..end];
if (prefix.len == 0 or (prefix.len == 1 and prefix[0] == '/')) continue;
if (!exists(prefix) and !makeDirectory(prefix)) return false;
// Best-effort per prefix: components at or above a mount point ("/mnt")
// are router names, not filesystem nodes — they neither exist as nodes
// nor accept mkdir, and that is fine. Only the final verdict counts.
if (!exists(prefix)) _ = makeDirectory(prefix);
}
return true;
return exists(path);
}
/// Remove the file at `path`. Returns true on success. Directories are refused
+6
View File
@@ -26,6 +26,12 @@ pub fn yield() void {
pub const KlogLevel = abi.KlogLevel;
pub const KlogStatus = abi.KlogStatus;
pub const KlogRecordHeader = abi.KlogRecordHeader;
pub const klog_record_header_size = abi.klog_record_header_size;
pub const klog_record_alignment = abi.klog_record_alignment;
pub const klog_record_magic = abi.klog_record_magic;
pub const klog_flag_truncated = abi.klog_flag_truncated;
pub const klog_maximum_message = abi.klog_maximum_message;
pub const maximum_process_name = abi.maximum_process_name;
/// Write raw bytes to the kernel log (bring-up/panic diagnostics; ordinary
/// output goes through std.log -> writeRecord). The kernel stamps the record
+7 -41
View File
@@ -22,11 +22,6 @@ const runtime = @import("runtime");
const power = runtime.power_protocol;
const build_options = @import("build_options");
/// Where the kernel boot log is persisted on the USB FAT volume — an 8.3 name at
/// the mount root (see system/services/log-flush). init writes it at shutdown;
/// the log-flush one-shot writes it once at boot.
const log_path = "/mnt/usb/DANOS.LOG";
/// The system services init brings up at boot, in order, by binary path. This is
/// init's policy — the microkernel keeps such choices in user space, not the
/// kernel. Drivers are absent on purpose: the device manager owns those. (A
@@ -39,6 +34,10 @@ const boot_services = [_][]const u8{
"/system/services/fat",
"/system/services/display",
"/system/services/display-demo",
// Last: at shutdown children stop in reverse order, so the logger goes down
// FIRST — its final drain still has the fat server (and the whole storage
// chain) alive underneath it.
"/system/services/logger",
};
/// The live process id of each boot service (0 = not running), indexed by its position
@@ -86,14 +85,6 @@ pub fn main() void {
if (runtime.system.spawnSupervised(service, &.{}, supervision_endpoint)) |id| child_ids[i] = id;
}
// Once the storage stack is up, a one-shot copies the boot log to the USB
// volume (/mnt/usb/DANOS.LOG) so it can be read on another machine — the only
// way to see it on a headless/real board with no host capturing serial. Fire
// and forget: it polls for the mount itself, and is deliberately NOT one of
// init's supervised children (a transient one-shot must not be stopped-and-
// waited-for during shutdown).
_ = runtime.system.spawn("/system/services/log-flush");
// Subscribe to power events (retry: the power service registers well after
// init starts). Best-effort — without it, a `terminate` signal still
// triggers the same shutdown path.
@@ -178,30 +169,6 @@ fn subscribePower() void {
_ = runtime.ipc.callCap(h, std.mem.asBytes(&request), &reply, supervision_endpoint) catch {};
}
/// Copy the whole kernel log to /mnt/usb/DANOS.LOG (the same file log-flush
/// writes at boot), so a poweroff captures the fullest log. Best-effort: if the
/// USB volume is not mounted, the open fails and it does nothing. Must run while
/// the storage services are still alive (see shutDown).
fn flushKernelLog() void {
// Truncate on open so this fuller flush replaces the boot-time one cleanly.
var file = runtime.fs.open(log_path, .{ .create = true, .truncate = true }) orelse return; // no USB volume
defer file.close();
var chunk: [4096]u8 = undefined;
// Interim (until the logger service in M-E): the stream is now framed
// records, so the file holds raw frames rather than plain text. Start at
// the ring's tail — offset 0 is gone once the ring has wrapped.
var offset: u64 = if (runtime.system.klogStatus()) |s| s.tail else 0;
const start = offset;
while (true) {
const got = runtime.system.klogRead(offset, &chunk) orelse break; // cursor lost
if (got == 0) break; // caught up
if (file.writeAll(chunk[0..got]) == null) break; // storage went away
offset += got;
}
var line: [96]u8 = undefined;
_ = runtime.system.write(std.fmt.bufPrint(&line, "/system/services/init: flushed log to {s} ({d} bytes)\n", .{ log_path, offset - start }) catch "");
}
/// The stop sequence: persist the log while storage is still up, then terminate
/// each child in reverse spawn order (vfs last — other services may flush through
/// it), waiting up to a deadline for each to exit before killing it, then ask the
@@ -209,10 +176,9 @@ fn flushKernelLog() void {
fn shutDown() void {
shutting_down = true; // the stop loop below kills children — those deaths aren't crashes
_ = runtime.system.write("/system/services/init: shutting down\n");
// Persist the fullest log to the USB volume BEFORE tearing anything down: the
// reverse-order stop loop below kills the fat server first, so /mnt/usb must be
// written while it is still mounted.
flushKernelLog();
// Log persistence is the logger service's job: it is the LAST boot service,
// so the reverse-order stop below terminates it first and its final drain
// runs while the whole storage chain is still alive.
var i = boot_services.len;
while (i > 0) {
i -= 1;
-66
View File
@@ -1,66 +0,0 @@
//! system/services/log-flush — a one-shot that copies the kernel's in-memory
//! diagnostic log to a file on the mounted USB FAT volume, so the boot log
//! survives to be read on another machine. On a headless or real board there is
//! no host capturing serial, so without this the log is lost at power-off; this
//! is the on-disk equivalent of QEMU's `-serial file:`.
//!
//! It reads the whole kernel log back through `klog_read` (the RAM sink in
//! system/kernel/log.zig) and writes it to /mnt/usb/DANOS.LOG. The name is 8.3
//! (FAT short-name rule: base <= 8, extension <= 3) and lives at the mount root
//! (there is no mkdir on the FAT path yet). init spawns this once the boot
//! services are up; init itself repeats the flush at shutdown for a fuller log.
//!
//! If no USB volume is mounted — no stick, or the initial-ramdisk sweep that
//! spawns every bundled binary bare with no VFS — it waits briefly, then exits
//! silently, deranging no other test's output.
const std = @import("std");
const runtime = @import("runtime");
const fs = runtime.fs;
const log_path = "/mnt/usb/DANOS.LOG";
/// Copy the whole kernel log to the open file, looping klog_read -> write until
/// the log is exhausted. Returns the number of bytes written.
fn drainKernelLog(file: *fs.File) usize {
var chunk: [4096]u8 = undefined;
// Interim (until the logger service in M-E): the stream is now framed
// records, so the file holds raw frames rather than plain text. Start at
// the ring's tail — offset 0 is gone once the ring has wrapped.
var offset: u64 = if (runtime.system.klogStatus()) |s| s.tail else 0;
const start = offset;
while (true) {
const got = runtime.system.klogRead(offset, &chunk) orelse break; // cursor lost
if (got == 0) break; // caught up
if (file.writeAll(chunk[0..got]) == null) break; // storage went away
offset += got;
}
return offset - start;
}
pub fn main() void {
// Wait for the fat server to mount /mnt/usb (it must bring up the whole USB
// storage chain first, so it races us at boot). Bounded: if the mount never
// appears — no volume, or the no-VFS ramdisk sweep — give up silently.
var ready = false;
var tries: u32 = 0;
while (tries < 1400) : (tries += 1) {
if (fs.openDirectory("/mnt/usb")) |directory| {
var dir = directory;
dir.close();
ready = true;
break;
}
runtime.system.sleep(50);
}
if (!ready) return; // /mnt/usb never became available — nothing to persist to
// Truncate on open: each flush replaces the file, so a shorter log on a later
// boot of the same stick leaves no stale tail from a previous, longer one.
var file = fs.open(log_path, .{ .create = true, .truncate = true }) orelse return;
const written = drainKernelLog(&file);
file.close();
var line: [96]u8 = undefined;
_ = runtime.system.write(std.fmt.bufPrint(&line, "log-flush: wrote {d} bytes to {s}\n", .{ written, log_path }) catch return);
}
+297
View File
@@ -0,0 +1,297 @@
//! The logger service — the per-process log persister.
//!
//! Drains the tagged kernel log ring (`klog_read`/`klog_status`) and
//! demultiplexes it into **one file per process** on the flash volume:
//!
//! <base>/<boot-stamp>/<binary-path>.log
//! e.g. /mnt/usb/var/log/2026-07-21T101530Z/system/services/fat.log
//!
//! The boot stamp is the wall-clock time of boot (from klog_status), so one
//! boot session is one self-contained directory; the kernel's own records go to
//! kernel.log. Records carry the sender's pid and binary path, stamped by the
//! kernel — the logger trusts the ring, never the payload.
//!
//! Storage is best-effort and late: until the FAT volume mounts, the ring
//! simply buffers (it holds a full boot many times over), and the first drain
//! writes the whole backlog. The storage stack's own records are captured the
//! same way — services never write their own log files (the fat service
//! logging through itself would rendezvous-deadlock; the ring sidesteps that
//! by design).
//!
//! The logger announces itself ONCE (a periodic status line would feed the
//! very stream it drains — self-sustaining churn). Lost records surface as an
//! explicit "-- N records lost --" line derived from sequence-number gaps.
//!
//! Durability: files are opened create-once and kept open across a burst, then
//! all closed after a quiet period (~2 s) — each close is the fat server's
//! SCSI SYNCHRONIZE CACHE, so data-at-risk is bounded by the last busy burst
//! without thrashing the device on every record. `on_terminate` does a final
//! drain and closes everything, so an orderly shutdown loses nothing (init
//! stops the logger FIRST — reverse boot order — while fat is still up).
const std = @import("std");
const runtime = @import("runtime");
const system = runtime.system;
const fs = runtime.fs;
/// Where log trees live. Flips to "/var/log" when the kernel VFS routes /var
/// to the flash volume (M-G); today the FAT service mounts at /mnt/usb only.
const base = "/mnt/usb/var/log";
/// Drain cadence and the quiet period after which files are closed (flushed).
const tick_ms = 250;
const quiet_close_ticks = 8; // 8 * 250 ms = 2 s
/// One cached open file per source process path. Sized above the practical
/// process count; the fat server's global open-node table (32) is the real
/// ceiling, so stay comfortably below it.
const maximum_files = 24;
const CachedFile = struct {
used: bool = false,
name: [system.maximum_process_name]u8 = undefined,
name_len: usize = 0,
file: fs.File = undefined,
};
var files: [maximum_files]CachedFile = @splat(.{});
var endpoint: runtime.ipc.Handle = 0;
/// The drain cursor into the ring's byte stream, and loss accounting.
var cursor: u64 = 0;
var next_expected_sequence: u64 = 0;
/// Carry buffer: a record can straddle two klog_read chunks.
var carry: [carry_capacity]u8 = undefined;
var carry_len: usize = 0;
const carry_capacity = 64 + 256 + 64; // header + payload + name, padded generously
/// The per-boot directory, formatted once storage appears.
var boot_directory: [base.len + 1 + 19]u8 = undefined;
var boot_directory_len: usize = 0;
var storage_ready = false;
var announced = false;
var ticks_since_record: u32 = 0;
pub fn main() void {
runtime.service.run(64, .{
.init = initialise,
.on_message = onMessage,
.on_notification = onNotification,
.on_terminate = onTerminate,
});
}
fn initialise(harness_endpoint: runtime.ipc.Handle) bool {
endpoint = harness_endpoint;
const status = system.klogStatus() orelse return false;
cursor = status.tail;
// Sequence expectations start at the tail record's sequence — discovered on
// the first drain; 0 is right for a fresh boot either way.
formatBootDirectory(status.boot_unix_seconds);
_ = system.timerOnce(endpoint, tick_ms);
return true;
}
/// The logger serves no protocol; the ping is answered by the harness.
fn onMessage(message: []const u8, reply: []u8, sender: u32, capability: ?runtime.ipc.Handle) usize {
_ = message;
_ = reply;
_ = sender;
_ = capability;
return 0;
}
fn onNotification(badge: u64) void {
if (badge & runtime.ipc.notify_timer_bit == 0) return;
tick();
_ = system.timerOnce(endpoint, tick_ms);
}
fn onTerminate() void {
// Final drain: everything still in the ring, then close (= flush) all files.
drain();
closeAll();
var line: [96]u8 = undefined;
_ = system.write(std.fmt.bufPrint(&line, "logger: flushed through sequence {d}\n", .{next_expected_sequence}) catch return);
}
fn tick() void {
if (!storage_ready) {
// Probe the mount; the ring buffers until it appears. `exists` on the
// mount root is the documented readiness check.
if (!fs.exists("/mnt/usb")) return;
if (!fs.makePath(boot_directory[0..boot_directory_len])) return;
storage_ready = true;
if (!announced) {
announced = true; // once — a periodic line would feed the stream we drain
var line: [128]u8 = undefined;
_ = system.write(std.fmt.bufPrint(&line, "logger: logging to {s}\n", .{boot_directory[0..boot_directory_len]}) catch "");
}
}
drain();
// Quiet-period close: one device cache flush per burst.
ticks_since_record += 1;
if (ticks_since_record == quiet_close_ticks) closeAll();
}
fn drain() void {
if (!storage_ready) return;
var chunk: [4096]u8 = undefined;
while (true) {
@memcpy(chunk[0..carry_len], carry[0..carry_len]);
const got = system.klogRead(cursor, chunk[carry_len..]) orelse {
// Cursor overwritten: re-sync to the ring tail; the sequence gap is
// reported by the next record's header.
const status = system.klogStatus() orelse return;
cursor = status.tail;
carry_len = 0;
continue;
};
if (got == 0) return; // caught up (any partial record stays carried)
cursor += got;
consume(chunk[0 .. carry_len + got]);
}
}
/// Parse whole records out of `bytes`; keep any trailing partial in `carry`.
fn consume(bytes: []u8) void {
const header_size = system.klog_record_header_size;
var offset: usize = 0;
while (bytes.len - offset >= header_size) {
const header = std.mem.bytesToValue(system.KlogRecordHeader, bytes[offset..][0..32]);
if (header.magic != system.klog_record_magic) {
// Corrupt frame — should not happen; drop the carry and re-sync.
carry_len = 0;
const status = system.klogStatus() orelse return;
cursor = status.head;
return;
}
const record_len = recordLength(header);
if (bytes.len - offset < record_len) break; // partial — carry it
const name = bytes[offset + header_size ..][0..header.name_len];
const message = bytes[offset + header_size + header.name_len ..][0..header.message_len];
deliver(header, name, message);
offset += record_len;
}
const rest = bytes.len - offset;
if (rest > carry_capacity) {
carry_len = 0; // cannot happen with sane frames; drop rather than overflow
return;
}
@memcpy(carry[0..rest], bytes[offset..]);
carry_len = rest;
}
fn deliver(header: system.KlogRecordHeader, name: []const u8, message: []const u8) void {
ticks_since_record = 0;
const file = fileFor(if (header.pid == 0 or name.len == 0) "kernel" else name) orelse return;
if (header.sequence != next_expected_sequence and next_expected_sequence != 0) {
var gap_line: [64]u8 = undefined;
const lost = header.sequence - next_expected_sequence;
if (std.fmt.bufPrint(&gap_line, "-- {d} records lost --\n", .{lost})) |line| {
_ = file.writeAll(line);
} else |_| {}
}
next_expected_sequence = header.sequence + 1;
// [+ssssss.mmm] level: payload
var stamp: [48]u8 = undefined;
const seconds = header.timestamp_ns / 1_000_000_000;
const millis = (header.timestamp_ns / 1_000_000) % 1000;
const level: []const u8 = switch (header.level) {
.err => "error: ",
.warn => "warning: ",
.debug => "debug: ",
.info, .raw => "",
};
if (std.fmt.bufPrint(&stamp, "[{d:>6}.{d:0>3}] {s}", .{ seconds, millis, level })) |prefix| {
_ = file.writeAll(prefix);
} else |_| {}
_ = file.writeAll(message);
if (header.flags & system.klog_flag_truncated != 0) _ = file.writeAll("~");
_ = file.writeAll("\n");
}
/// The cached (or freshly opened) file for a source name. The file path is the
/// binary path with its leading '/' stripped, ".log" appended, under the
/// per-boot directory; parents are created on first use.
fn fileFor(name: []const u8) ?*fs.File {
for (&files) |*cached| {
if (cached.used and std.mem.eql(u8, cached.name[0..cached.name_len], name)) return &cached.file;
}
var slot: ?*CachedFile = null;
for (&files) |*cached| {
if (!cached.used) {
slot = cached;
break;
}
}
const cached = slot orelse evictOne() orelse return null;
var path: [base.len + 1 + 19 + 1 + system.maximum_process_name + 4]u8 = undefined;
const relative = if (name.len != 0 and name[0] == '/') name[1..] else name;
const full = std.fmt.bufPrint(&path, "{s}/{s}.log", .{ boot_directory[0..boot_directory_len], relative }) catch return null;
// Parent directories: everything up to the final slash.
if (std.mem.lastIndexOfScalar(u8, full, '/')) |last| {
if (!fs.makePath(full[0..last])) return null;
}
var file = fs.open(full, .{ .create = true }) orelse return null;
// Append: land after whatever an earlier open of this boot wrote.
if (file.attributes()) |attributes| file.seekTo(attributes.size);
cached.* = .{ .used = true, .file = file };
@memcpy(cached.name[0..name.len], name);
cached.name_len = name.len;
return &cached.file;
}
fn evictOne() ?*CachedFile {
// All slots busy: close the first (oldest-created) and reuse it. Simple and
// rare — the process count sits well under the cache size.
for (&files) |*cached| {
if (cached.used) {
cached.file.close();
cached.used = false;
return cached;
}
}
return null;
}
fn closeAll() void {
for (&files) |*cached| {
if (cached.used) {
cached.file.close();
cached.used = false;
}
}
}
fn recordLength(header: system.KlogRecordHeader) usize {
return std.mem.alignForward(usize, system.klog_record_header_size + header.name_len + header.message_len, system.klog_record_alignment);
}
/// Format the per-boot directory "<base>/YYYY-MM-DDTHHMMSSZ" from the boot
/// wall-clock anchor. No colons — FAT names cannot carry them. A dead RTC
/// (anchor 0) yields the 1970 epoch directory, which is still a valid,
/// distinct-per-boot-rarely name and better than refusing to log.
fn formatBootDirectory(boot_unix_seconds: u64) void {
const epoch_seconds = std.time.epoch.EpochSeconds{ .secs = boot_unix_seconds };
const year_day = epoch_seconds.getEpochDay().calculateYearDay();
const month_day = year_day.calculateMonthDay();
const day_seconds = epoch_seconds.getDaySeconds();
const written = std.fmt.bufPrint(&boot_directory, "{s}/{d:0>4}-{d:0>2}-{d:0>2}T{d:0>2}{d:0>2}{d:0>2}Z", .{
base,
year_day.year,
month_day.month.numeric(),
@as(u32, month_day.day_index) + 1,
day_seconds.getHoursIntoDay(),
day_seconds.getMinutesIntoHour(),
day_seconds.getSecondsIntoMinute(),
}) catch return;
boot_directory_len = written.len;
}
+8 -7
View File
@@ -553,17 +553,18 @@ CASES = [
r"power: entering S5",
"fail": r"power: S5 write did not take|DANOS-TEST-RESULT: FAIL"},
# M8: the boot log is persisted to the USB FAT volume. Reuses the orderly-
# shutdown build (full tree + power button): init spawns log-flush at boot,
# which copies the kernel log to /mnt/usb/DANOS.LOG once /mnt/usb is mounted
# (first marker); then the power button drives init's own pre-teardown flush
# (second marker), proving both triggers write the file while storage is up.
{"name": "log-flush",
# shutdown build (full tree + power button): the logger service announces its
# per-boot directory once storage mounts (first marker), then the power
# button drives the orderly stop — the logger, stopped first, final-drains
# and reports the flush (second marker) before S5.
{"name": "logger",
"build_case": "orderly-shutdown",
"smp": 4,
"timeout": 150,
"qmp_after": {"delay": 8, "command": "system_powerdown"},
"expect": r"log-flush: wrote \d+ bytes to /mnt/usb/DANOS\.LOG[\s\S]*"
r"init: flushed log to /mnt/usb/DANOS\.LOG[\s\S]*"
"expect": r"logger: logging to /mnt/usb/var/log/\d{4}-\d{2}-\d{2}T\d{6}Z[\s\S]*"
r"init: shutting down[\s\S]*"
r"logger: flushed through sequence \d+[\s\S]*"
r"power: entering S5",
"fail": r"DANOS-TEST-RESULT: FAIL"},
# M20.2: the acpi service evaluates _CRS/_STA in ring 3 and registers +