//! 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. /volumes/usb/system/logs/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 fs = @import("file-system"); const ipc = @import("ipc"); const service = @import("service"); const time = @import("time"); const logging = @import("logging"); /// Where log trees live: the hierarchy path. The kernel VFS routes /system/logs /// to whatever volume the fat server mounted there (today: the /system/logs /// subtree of the USB flash volume) — swapping the persistent medium later /// touches fat's mount calls, never this constant. const base = "/system/logs"; /// 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: [logging.maximum_process_name]u8 = undefined, name_len: usize = 0, file: fs.File = undefined, }; var files: [maximum_files]CachedFile = @splat(.{}); var endpoint: 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 { service.run(64, .{ .init = initialise, .on_message = onMessage, .on_notification = onNotification, .on_terminate = onTerminate, }); } fn initialise(harness_endpoint: ipc.Handle) bool { endpoint = harness_endpoint; const status = logging.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); _ = time.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, arrived: *ipc.Arrival) usize { _ = message; _ = reply; _ = sender; _ = arrived; // nothing here takes a capability: the harness closes what arrives return 0; } fn onNotification(badge: u64) void { if (badge & ipc.notify_timer_bit == 0) return; tick(); _ = time.timerOnce(endpoint, tick_ms); } fn onTerminate() void { // The completeness receipt FIRST: this record enters the ring before the // final drain, so the drain carries it into logger.log — a directory whose // logger.log ends with this marker is complete through shutdown; one that // doesn't was cut early and may be missing tails. _ = logging.write("logger: shutting down; final flush\n"); drain(); closeAll(); // Serial-only epilogue (after the drain, so it reaches no file — by design). var line: [96]u8 = undefined; _ = logging.write(std.fmt.bufPrint(&line, "logger: flushed through sequence {d}\n", .{next_expected_sequence}) catch return); } fn tick() void { if (!storage_ready) { // makePath doubles as the readiness probe: while /system/logs is unmounted the // resolve fails fast (no storage round trip) and the ring buffers; the // first success creates the whole per-boot tree. 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; _ = logging.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 = logging.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 = logging.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 = logging.klog_record_header_size; var offset: usize = 0; while (bytes.len - offset >= header_size) { const header = std.mem.bytesToValue(logging.KlogRecordHeader, bytes[offset..][0..32]); if (header.magic != logging.klog_record_magic) { // Corrupt frame — should not happen; drop the carry and re-sync. carry_len = 0; const status = logging.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: logging.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 & logging.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 + logging.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: logging.KlogRecordHeader) usize { return std.mem.alignForward(usize, logging.klog_record_header_size + header.name_len + header.message_len, logging.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; }