danos/system/kernel/log.zig

//! The kernel's multi-sink **diagnostic** log — the machine-readable stream of
//! what the kernel is doing, separate from any user-facing display.
//!
//! Output is a *diagnostic convenience, never a correctness dependency* — the
//! kernel must boot and run correctly with zero output channels. So logging fans
//! out to a set of registered **sinks**, each best-effort and self-guarding: the
//! serial UART and the 0xE9 debug console. A message reaches whatever channels
//! exist; if none do, the kernel runs on, silent but correct.
//!
//! Retention is the tagged RING (log-ring.zig): every emission becomes one
//! record per line, stamped with the sender's pid, task name (its binary path),
//! level, sequence number, and monotonic timestamp — attribution is structural,
//! stamped by the kernel, not a naming convention a process could forge. The
//! stamping is per LINE: an embedded '\n' ends the record, so a payload cannot
//! imitate another sender on the line that follows. Oldest records are
//! overwritten when the ring is full; sequence gaps make the loss countable.
//! `klog_read`/`klog_status` expose the stream to userspace (the logger service
//! drains it into per-process files once storage is up).
//!
//! Locking: a dedicated log spinlock, NOT the big kernel lock. `print` is
//! called both inside and outside BKL sections (and from ISRs), so the log
//! lock is taken with interrupts off and nothing inside it ever takes the BKL —
//! lock order is strictly BKL -> log lock, never the reverse. Panic paths use a
//! bounded try-acquire and fall back to sinks-only: a panic must never deadlock
//! on its own diagnostics.
//!
//! The **framebuffer is deliberately not a sink here.** It's a separate output
//! surface (a bootstrap text console today, a graphics device driver later), so
//! the log never assumes the machine is text-based. Two channels bypass the
//! sink list because they must survive even a total-output failure:
//! `checkpoint` (a one-byte POST code) and `recordPanic` (a fixed breadcrumb).

const std = @import("std");
const architecture = @import("architecture");
const abi = @import("abi");
const log_ring = @import("log-ring.zig");
const wall_clock = @import("wall-clock.zig");

pub const SinkFn = *const fn ([]const u8) void;

const maximum_sinks = 8;
var sinks: [maximum_sinks]SinkFn = undefined;
var sink_count: usize = 0;

/// Register an output sink. Every registered sink receives every message; sinks
/// must be self-guarding (safe to call when their device is absent).
pub fn addSink(sink: SinkFn) void {
    if (sink_count < maximum_sinks) {
        sinks[sink_count] = sink;
        sink_count += 1;
    }
}

// --- the log lock ------------------------------------------------------------

var lock_held = std.atomic.Value(u32).init(0);

fn lockAcquire() u64 {
    const flags = architecture.saveInterrupts();
    while (lock_held.cmpxchgWeak(0, 1, .acquire, .monotonic) != null) std.atomic.spinLoopHint();
    return flags;
}

fn lockTryAcquire(spins: usize) ?u64 {
    const flags = architecture.saveInterrupts();
    var i: usize = 0;
    while (i < spins) : (i += 1) {
        if (lock_held.cmpxchgWeak(0, 1, .acquire, .monotonic) == null) return flags;
        std.atomic.spinLoopHint();
    }
    architecture.restoreInterrupts(flags);
    return null;
}

fn lockRelease(flags: u64) void {
    lock_held.store(0, .release);
    architecture.restoreInterrupts(flags);
}

// --- the ring + renderer -----------------------------------------------------

/// 512 KiB: the tagged frames cost ~30% over the raw text, and the ring only
/// needs to cover the pre-mount backlog (a boot is ~15 KiB of text) — the
/// logger service tails it continuously once storage is up.
const ring_capacity = 512 * 1024;
var ring: log_ring.Ring(ring_capacity) = .{};

/// Renderer state: whether the sinks sit at a line start, and which pid's line
/// is currently open — when a different sender interleaves mid-line, the
/// renderer closes the line so serial output can't visually merge two senders.
var at_line_start: bool = true;
var open_line_pid: u32 = 0;

/// Append `bytes` as one tagged record per line and render them to the sinks.
/// The core emission path: `debug_write` calls this with the sender's identity;
/// kernel-internal `write`/`print` funnel here as pid 0 ("kernel", raw).
pub fn append(pid: u32, name: []const u8, level: abi.KlogLevel, bytes: []const u8) void {
    if (bytes.len == 0) return;
    const now = architecture.nanos();
    const flags = lockAcquire();
    defer lockRelease(flags);
    appendLocked(pid, name, level, now, bytes);
}

/// The panic-safe variant: bounded lock wait; on failure, sinks only — the ring
/// entry is lost but the message still reaches serial, and the panic cannot
/// deadlock on a core that died holding the log lock.
pub fn appendPanic(bytes: []const u8) void {
    if (lockTryAcquire(100_000)) |flags| {
        defer lockRelease(flags);
        appendLocked(0, "kernel", .raw, architecture.nanos(), bytes);
    } else {
        for (sinks[0..sink_count]) |sink| sink(bytes);
    }
}

fn appendLocked(pid: u32, name: []const u8, level: abi.KlogLevel, now: u64, bytes: []const u8) void {
    var rest = bytes;
    while (rest.len != 0) {
        const newline = std.mem.indexOfScalar(u8, rest, '\n');
        // The record payload excludes the newline: a record IS a line. Raw
        // emissions may leave a line open (kernel boot tables build lines from
        // pieces); a LEVELED record is a complete line by contract — std.log
        // payloads carry no trailing newline.
        const line = if (newline) |i| rest[0..i] else rest;
        const line_complete = newline != null or level != .raw;
        if (line.len != 0 or line_complete)
            _ = ring.append(pid, name, level, now, line, line.len > abi.klog_maximum_message);
        render(pid, name, level, line, line_complete);
        rest = if (newline) |i| rest[i + 1 ..] else rest[rest.len..];
    }
}

/// Serial/debugcon rendering. Kernel output and legacy raw user output pass
/// through byte-identical to the historical stream (services still write their
/// own "name: " prefixes until the std.log migration). Leveled (std.log)
/// records get a kernel-rendered "<name>: " prefix at line start — err/warn/
/// debug also get their level spelled out.
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) {
        buffer[used] = '\n';
        used += 1;
        at_line_start = true;
    }
    if (at_line_start and level != .raw) {
        used += place(buffer[used..], name);
        used += place(buffer[used..], ": ");
        used += place(buffer[used..], switch (level) {
            .err => "error: ",
            .warn => "warning: ",
            .debug => "debug: ",
            .info, .raw => "",
        });
    }
    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);
}

/// Kernel-internal write — a raw record from "kernel" (pid 0). The signature is
/// unchanged so every existing kernel call site stays as it is.
pub fn write(bytes: []const u8) void {
    append(0, "kernel", .raw, bytes);
}

/// A formatted log line. Truncates past 256 bytes; the buffer is on the stack, so
/// this is safe to call from interrupt context and from a panic.
pub fn print(comptime fmt: []const u8, args: anytype) void {
    var buffer: [256]u8 = undefined;
    write(std.fmt.bufPrint(&buffer, fmt, args) catch return);
}

/// klog_read: copy ring stream bytes from `offset` into `out`. Null when the
/// cursor was overwritten or lies past the end — the reader re-syncs via
/// status(). Zero bytes means caught up.
pub fn readAt(offset: u64, out: []u8) ?usize {
    const flags = lockAcquire();
    defer lockRelease(flags);
    return ring.read(offset, out);
}

/// klog_status: the ring cursors plus the boot wall-clock anchor.
pub fn status() abi.KlogStatus {
    const flags = lockAcquire();
    defer lockRelease(flags);
    var s = ring.status();
    s.boot_unix_seconds = wall_clock.bootSeconds();
    return s;
}

/// Emit a one-byte checkpoint/POST code (I/O port 0x80) — the always-available
/// progress channel for when there is no text output at all. Independent of the
/// sink list, so it works even before any sink is registered.
pub fn checkpoint(code: u8) void {
    architecture.checkpoint(code);
}

// --- persistent panic breadcrumb -------------------------------------------
//
// A fixed record in the kernel image that a panic fills in, so a post-mortem — an
// attached debugger, a RAM dump, or (later) a file/pstore reader — can recover
// what killed the kernel even when there was no live console. `magic` is written
// *last*, so a reader only trusts a fully-written record.

pub const panic_magic: u64 = 0xD1ED_B00B_5EED_F00D;

pub const PanicRecord = extern struct {
    magic: u64 = 0,
    len: u32 = 0,
    _pad: u32 = 0,
    message: [512]u8 = undefined,
};

/// Findable by symbol (`log.panic_record`) for a debugger or RAM dump.
pub var panic_record: PanicRecord = .{};

/// Stamp the panic message into the breadcrumb record.
pub fn recordPanic(message: []const u8) void {
    const n: u32 = @intCast(@min(message.len, panic_record.message.len));
    @memcpy(panic_record.message[0..n], message[0..n]);
    panic_record.len = n;
    panic_record.magic = panic_magic; // set last: a reader sees a complete record
}