docs: per-process logging + the kernel VFS root
logging.md rewritten around the pipeline (std.log -> leveled debug_write -> tagged ring -> logger service -> /var/log/<boot-stamp>/<binary-path>.log), why the buffer is a kernel ring rather than a logging server (the storage stack must log; early boot needs the buffer anyway), the announce-once and counted-loss disciplines, and the accepted gaps. vfs-protocol.md: the router is the kernel (fs_resolve names, backends serve data); endpoint comes from resolve, not a registry lookup; mount/ unmount retired from the wire; the rewrite-prefix mount semantics. vdso.md: klog_status + the fs naming calls join the future table; the no-file-I/O line sharpened (kernel resolves names, never blocks on a filesystem). syscall.md: the placeholder status blurb replaced with the real call families.
This commit is contained in:
Daniel Samson
+78
-86
@@ -1,104 +1,96 @@
|
||||
# Logging: the diagnostic log vs. the display
|
||||
# Logging
|
||||
|
||||
danos separates two things that are easy to conflate: the **diagnostic log** — the
|
||||
machine-readable stream of *what the kernel is doing* — and the **display**, the
|
||||
framebuffer surface the OS draws on. They are different concerns with different
|
||||
lifetimes, so they're different code paths.
|
||||
Output is a *diagnostic convenience, never a correctness dependency*: the kernel
|
||||
and every service must run correctly with zero output channels. On top of that
|
||||
rule, danos has **per-process logging** — every process's output is attributed
|
||||
by the kernel and lands in its own file on the flash volume, which is what makes
|
||||
a headless real machine (no serial port) debuggable. The display (the
|
||||
framebuffer surface) is a separate concern and deliberately not a log sink;
|
||||
`main.zig` mirrors a few user-facing status lines and panics to it explicitly.
|
||||
|
||||
The guiding rule: **output is a diagnostic convenience, never a correctness
|
||||
dependency.** The kernel must boot and run correctly with *zero* output channels —
|
||||
no serial, no screen. Logging that can take the kernel down isn't robust; it's a
|
||||
liability. This is the same [resilience](resilience.md) posture the rest of the
|
||||
kernel follows.
|
||||
|
||||
## The log is multi-sink
|
||||
|
||||
`system/kernel/log.zig` is the diagnostic log. It fans a message out to a set of
|
||||
registered **sinks**, each best-effort and self-guarding:
|
||||
|
||||
```zig
|
||||
log.addSink(arch.serialWrite); // the serial UART
|
||||
if (arch.debugconPresent()) log.addSink(arch.debugconWrite); // 0xE9 debug console
|
||||
// later: log.addSink(fs.logWrite); // a file on a ramdisk / USB / SSD
|
||||
log.write("…"); log.print("x={d}\n", .{x});
|
||||
```
|
||||
|
||||
Properties that matter:
|
||||
|
||||
- **No allocation.** The sink table is a fixed array, so the log works before the
|
||||
heap is up and inside a panic.
|
||||
- **Best-effort.** A sink whose device is absent is a no-op (e.g. writing to a
|
||||
missing UART just goes nowhere — the TX-wait is bounded so it can't hang). A
|
||||
message reaches whatever channels exist; if none do, the kernel runs on, silent.
|
||||
- **Order-independent.** Every registered sink gets every message. Adding the file
|
||||
logger later is one `addSink` call and **zero** changes to call sites.
|
||||
|
||||
## The framebuffer is *not* a log sink
|
||||
|
||||
The framebuffer is a general graphics surface, **not inherently a text terminal**.
|
||||
Today `system/kernel/console.zig` paints a text grid on it as a *bootstrap* console, but
|
||||
that's a stop-gap: once the driver machinery exists the framebuffer becomes a proper
|
||||
**graphics device driver**, and the text crutch goes away. So the log must not assume
|
||||
it — routing the verbose log through a pixel console would bake in "the OS is text".
|
||||
|
||||
Instead the two paths are explicit:
|
||||
## The pipeline
|
||||
|
||||
```
|
||||
verbose diagnostics ──► log ──► serial, debugcon, (file later)
|
||||
user status / panics ──► status() ──► log (above) + framebuffer (if present)
|
||||
process std.log ──▶ debug_write(level) ──▶ tagged kernel ring ──▶ logger service ──▶ /var/log/<boot-stamp>/<binary-path>.log
|
||||
kernel log.print ─┘ │
|
||||
└▶ serial / 0xE9 sinks (QEMU, -Dserial)
|
||||
```
|
||||
|
||||
A handful of user-facing lines (`kernel initialised`, a panic) go through
|
||||
`main.zig`'s `status()` / `statusPrint()`, which write to the log **and** paint the
|
||||
framebuffer when one is present. Everything else uses `log.*` and never touches the
|
||||
screen. `console.write` is a no-op when the firmware gave us no framebuffer.
|
||||
1. **Emit.** A program calls `std.log.info("mounted {s}", .{path})` — the
|
||||
runtime's `logFn` (installed for every binary by the root shim,
|
||||
`library/runtime/log.zig`) formats one line and issues one `debug_write`
|
||||
carrying the level. The payload does NOT contain the process's name.
|
||||
`runtime.system.write` remains as the raw/bring-up path (panics, test
|
||||
fixtures); raw bytes ride the same ring, attributed all the same.
|
||||
|
||||
## Optional framebuffer (headless machines)
|
||||
2. **Stamp.** The kernel wraps every payload LINE in a record stamped with the
|
||||
sender's pid, task name (its binary path, e.g. `/system/services/fat`),
|
||||
level, a per-boot sequence number, and a monotonic timestamp
|
||||
(`system/kernel/log.zig` + `log-ring.zig`). Attribution is structural — a
|
||||
payload cannot forge another sender's tag, and an embedded newline just ends
|
||||
the record, so the forged "prefix" lands inside the forger's own next line.
|
||||
|
||||
A framebuffer is not guaranteed — a headless server exposes no UEFI Graphics Output
|
||||
Protocol. That used to be *fatal* (the loader failed the boot). Now the loader hands
|
||||
over a "no framebuffer" descriptor (`base == 0`) rather than failing, and
|
||||
`Framebuffer.present()` (in `system/boot-handoff.zig`) gates every on-screen path. A headless,
|
||||
serial-less machine boots and runs correctly — it just goes quiet.
|
||||
3. **Retain.** The 512 KiB ring overwrites oldest-first; sequence gaps make any
|
||||
loss countable. `klog_read` (#32) copies stream bytes from a free-running
|
||||
offset; `klog_status` (#45) returns the cursors plus the wall-clock time of
|
||||
boot. The framing (`abi.KlogRecordHeader`) is 32 bytes + name + payload,
|
||||
8-byte aligned.
|
||||
|
||||
## Last-resort channels (no text output at all)
|
||||
4. **Render.** Registered sinks (serial under `-Dserial`, the 0xE9 debug
|
||||
console) get a live transcript: kernel/raw output verbatim, leveled records
|
||||
as `<binary path>: message` — one composed write per line, under the log's
|
||||
own spinlock (never the big kernel lock; panic paths try-acquire with a
|
||||
bound and fall back to sinks-only). Sinks are best-effort and self-guarding;
|
||||
a serial-less machine just goes quiet.
|
||||
|
||||
Two signals bypass the sink list, because they must survive even a total
|
||||
output-channel failure:
|
||||
5. **Persist.** The **logger service** (`system/services/logger`) drains the
|
||||
ring every 250 ms and demultiplexes records into one file per source under
|
||||
`/var/log/<boot-stamp>/`, e.g.
|
||||
|
||||
- **`log.checkpoint(code)`** — a one-byte **POST code** to I/O port `0x80` (a POST
|
||||
card or BMC shows it). `main.zig` emits one at each boot milestone (`cp_paging`,
|
||||
`cp_heap`, …) and on a fault/panic, so "where did it hang?" is answerable with no
|
||||
text output whatsoever. Writing `0x80` is universally safe.
|
||||
- **`log.recordPanic(msg)`** — stamps the panic message into a fixed record
|
||||
(`log.panic_record`, with a `magic` written last). A post-mortem — an attached
|
||||
debugger, a RAM dump, or a future file/pstore reader — recovers *what killed it*
|
||||
even though nothing was on screen.
|
||||
```
|
||||
/var/log/2026-07-21T150434Z/kernel.log
|
||||
/var/log/2026-07-21T150434Z/system/services/fat.log
|
||||
/var/log/2026-07-21T150434Z/system/drivers/usb-storage.log
|
||||
```
|
||||
|
||||
The panic and CPU-exception handlers fan out to every sink, emit a POST code, and
|
||||
drop the breadcrumb — they never assume a console.
|
||||
The boot stamp is the RTC anchor from `klog_status` (FAT-safe: no colons; a
|
||||
dead RTC yields the 1970 directory rather than no logs). Each line carries
|
||||
the record's monotonic timestamp and level. Storage is best-effort and late:
|
||||
the ring buffers a whole boot many times over, and the first successful
|
||||
`makePath` of the per-boot directory (also the readiness probe) triggers a
|
||||
full backlog write. Files close — which is the fat server's SCSI cache
|
||||
flush — after a ~2 s quiet period, bounding data-at-risk without per-record
|
||||
flush thrash. At shutdown init stops the logger FIRST (it is last in the
|
||||
boot order), so its final drain runs over a live storage chain.
|
||||
|
||||
## The 0xE9 debug console
|
||||
## Why a ring in the kernel, not a logging server
|
||||
|
||||
Port `0xE9` is the Bochs/QEMU debug console. It's detected safely: the port returns
|
||||
`0xE9` when read if present, and `0xFF` on real hardware, so `debugconPresent()`
|
||||
only enables the sink when it's really there. Under QEMU it's captured with
|
||||
`-debugcon file:…`, giving CI a log channel independent of `-serial`.
|
||||
The storage stack must be able to log. If the fat server wrote its own log file
|
||||
through the VFS it would rendezvous-deadlock on itself; if processes sent
|
||||
records to a logging server over IPC, early boot would need a buffer that is —
|
||||
a ring, one hop later. The kernel ring is that buffer, placed where every
|
||||
process (and the kernel itself) can reach it with one syscall, before any
|
||||
service exists. The logger service is a *reader*, not a hop.
|
||||
|
||||
## The robustness spectrum
|
||||
Two disciplines keep it honest:
|
||||
|
||||
The result handles every combination — framebuffer only, serial only, both, or
|
||||
**neither**. With no channels at all the kernel still boots and runs; port-`0x80`
|
||||
checkpoints track progress and the panic breadcrumb captures failures. *Runs blind
|
||||
but correct* is the goal, not *always has output*.
|
||||
- the logger announces itself **once** — a periodic status line would feed the
|
||||
very stream it drains;
|
||||
- lost records surface as an explicit `-- N records lost --` line, computed
|
||||
from sequence gaps, never silently.
|
||||
|
||||
## Related
|
||||
## Last-resort channels
|
||||
|
||||
- [framebuffer.md](framebuffer.md) — the display surface itself (pitch, format), the
|
||||
thing that becomes a graphics device driver.
|
||||
- [efi.md](efi.md) — where the loader captures (or, headless, doesn't capture) the
|
||||
framebuffer before `ExitBootServices`.
|
||||
- [device-interrupts.md](device-interrupts.md) — the serial UART bring-up the log's
|
||||
primary sink rides on.
|
||||
- [resilience.md](resilience.md) — why "never let a missing peripheral take the
|
||||
kernel down" is a core design stance.
|
||||
Unchanged, and independent of the sink list so they survive a total output
|
||||
failure: `checkpoint` (a one-byte POST code on port 0x80) and `recordPanic`
|
||||
(a fixed breadcrumb record, `log.panic_record`, findable in a RAM dump; magic
|
||||
written last so a reader only trusts a complete record).
|
||||
|
||||
## Accepted gaps
|
||||
|
||||
- A write-spamming process can evict other processes' unread records from the
|
||||
ring (a per-process quota is future work); the loss is at least visible via
|
||||
sequence gaps in every affected file.
|
||||
- `/var/log` files have no privacy until the VFS grows permissions.
|
||||
- Records emitted after the logger's final shutdown drain reach serial and the
|
||||
ring but not the files.
|
||||
|
||||
Reference in New Issue
Block a user