daniel/danos
1
0
Fork 0
Code Issues 4 Pull Requests Actions Packages Projects 1 Releases Wiki Activity

kernel: tagged log ring — per-line pid/name/level records, klog_status

Browse Source 
Replace the linear keep-earliest RAM buffer with a 512 KiB ring of
framed records (log-ring.zig, host-tested): every debug_write becomes
one record per payload line, stamped by the kernel with the sender's
pid, task name (its binary path), level, per-boot sequence number, and
monotonic timestamp. Attribution is structural — a payload cannot forge
another sender's tag, and newline injection lands inside the forger's
own next record. Oldest records are overwritten when full; sequence
gaps make the loss countable.

debug_write gains a level argument (err/warn/info/debug/raw; old
two-arg callers clamp to raw). klog_read becomes a stream-offset read
that fails once the cursor falls behind the ring's tail; the new
klog_status (#45) returns the cursors plus the boot wall-clock anchor —
what the logger service will name per-boot log directories with.

The log now guards itself with a dedicated spinlock (BKL -> log lock
order, never the reverse); panic paths use a bounded try-acquire and
fall back to sinks-only. Serial rendering keeps the historical
transcript byte-identical for kernel and legacy raw output; leveled
records get a kernel-rendered name prefix. log-flush/init's interim
drains start at the ring tail and write framed records until the logger
service replaces them.
This commit is contained in:
Daniel Samson
2026-07-21 15:30:28 +01:00
parent 0a84e52bf8
commit 9f18d8340e
10 changed files with 549 additions and 80 deletions
Download Patch File Download Diff File Expand all files Collapse all files
system/kernel/log.zig
+150 -39
View File
@@ -4,22 +4,37 @@
//! 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, the 0xE9 debug console, and — later — a file on a ramdisk/USB/SSD.
//! A message reaches whatever channels exist; if none do, the kernel runs on,
//! silent but correct.
//! 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. `main.zig` mirrors a few
//! user-facing status lines and panics to it explicitly; the verbose log does not.
//!
//! No allocation: the sink table is fixed, so the log works before the heap is up
//! and inside a panic. Two channels don't go through the sink list because they
//! must survive even a total-output failure: `checkpoint` (a one-byte POST code)
//! and `recordPanic` (a breadcrumb in a fixed record).
//! 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;
@@ -36,42 +51,120 @@ pub fn addSink(sink: SinkFn) void {
}
}
/// Fan `bytes` out to every registered sink.
pub fn write(bytes: []const u8) void {
for (sinks[0..sink_count]) |sink| sink(bytes);
// --- 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;
}
// --- the RAM sink: a retained copy of the whole diagnostic stream ------------
//
// A fixed in-image buffer that accumulates every logged byte, so a user program
// (`log-flush`, and init at shutdown) can read it back through `klog_read` and
// persist it to a file — the boot log survives on a headless/real machine that
// has no host capturing serial. It is a *sink like any other*: register it with
// `addSink(ramSink)` at boot. No allocation (works pre-heap and in a panic).
//
// It fills linearly and stops when full: the earliest output — the most valuable
// for diagnosing a boot — is kept, and the tail is still on the live serial sink.
// 256 KiB comfortably holds a full boot plus a long run (a boot is ~15 KiB).
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;
}
const ram_capacity = 256 * 1024;
var ram_buffer: [ram_capacity]u8 = undefined;
var ram_len: usize = 0;
fn lockRelease(flags: u64) void {
lock_held.store(0, .release);
architecture.restoreInterrupts(flags);
}
/// The RAM sink. Best-effort and self-guarding like every sink: appends what fits
/// and silently drops the rest once full. (Concurrency matches the other sinks —
/// the dominant writer, debug_write, already holds the kernel lock; a rare torn
/// append on a kernel-internal line is an accepted diagnostic imperfection.)
pub fn ramSink(bytes: []const u8) void {
const n = @min(ram_buffer.len - ram_len, bytes.len);
if (n != 0) {
@memcpy(ram_buffer[ram_len..][0..n], bytes[0..n]);
ram_len += n;
// --- 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);
}
}
/// The accumulated log so far — what `klog_read` copies out.
pub fn ramSnapshot() []const u8 {
return ram_buffer[0..ram_len];
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 (or the
// open tail of one when the emission didn't end in '\n').
const line = if (newline) |i| rest[0..i] else rest;
const line_complete = newline != null;
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;
if (!at_line_start and open_line_pid != pid) {
fanOut("\n");
at_line_start = true;
}
if (at_line_start and level != .raw) {
fanOut(name);
fanOut(": ");
switch (level) {
.err => fanOut("error: "),
.warn => fanOut("warning: "),
.debug => fanOut("debug: "),
.info, .raw => {},
}
}
fanOut(line);
if (line_complete) fanOut("\n");
at_line_start = line_complete;
open_line_pid = pid;
}
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
@@ -81,6 +174,24 @@ pub fn print(comptime fmt: []const u8, args: anytype) void {
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.