danos/system/services/logger/logger.zig

//! 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. /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 "<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;
}