From 127ea2dad9c828132f56671979ca3b5af9bf2526 Mon Sep 17 00:00:00 2001 From: Daniel Samson <12231216+daniel-samson@users.noreply.github.com> Date: Tue, 21 Jul 2026 16:05:46 +0100 Subject: [PATCH] logger: per-process log files under /var/log// MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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). --- build.zig | 4 +- library/runtime/fs.zig | 7 +- library/runtime/system.zig | 6 + system/services/init/init.zig | 48 +--- system/services/log-flush/log-flush.zig | 66 ------ system/services/logger/logger.zig | 297 ++++++++++++++++++++++++ test/qemu_test.py | 15 +- 7 files changed, 325 insertions(+), 118 deletions(-) delete mode 100644 system/services/log-flush/log-flush.zig create mode 100644 system/services/logger/logger.zig diff --git a/build.zig b/build.zig index 8ea68db..a5343de 100644 --- a/build.zig +++ b/build.zig @@ -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() }, diff --git a/library/runtime/fs.zig b/library/runtime/fs.zig index 8616655..84dd8f1 100644 --- a/library/runtime/fs.zig +++ b/library/runtime/fs.zig @@ -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 diff --git a/library/runtime/system.zig b/library/runtime/system.zig index 05d42a6..71b85ec 100644 --- a/library/runtime/system.zig +++ b/library/runtime/system.zig @@ -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 diff --git a/system/services/init/init.zig b/system/services/init/init.zig index 525e674..25efbe5 100644 --- a/system/services/init/init.zig +++ b/system/services/init/init.zig @@ -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; diff --git a/system/services/log-flush/log-flush.zig b/system/services/log-flush/log-flush.zig deleted file mode 100644 index 836a09b..0000000 --- a/system/services/log-flush/log-flush.zig +++ /dev/null @@ -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); -} diff --git a/system/services/logger/logger.zig b/system/services/logger/logger.zig new file mode 100644 index 0000000..b2a8ff3 --- /dev/null +++ b/system/services/logger/logger.zig @@ -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: +//! +//! //.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 "/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; +} diff --git a/test/qemu_test.py b/test/qemu_test.py index e285ee4..d65e8a6 100644 --- a/test/qemu_test.py +++ b/test/qemu_test.py @@ -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 +