Daniel Samson
bf0595763e
An all-tracks docs-vs-code audit (the same method that caught the storage drift) found 23 confirmed inaccuracies where a doc's build-status claim no longer matches the source — status markers that were never flipped after a track landed, and a few paths left over from completed flag-days. All verified against the code before editing; docs only, no behavior change. The systemic ones: - IOMMU enforcement (driver-model.md, drivers.md): docs said enforcement was not built and "device_claim = ring 0" / "memory-safe is not true yet". It is built (per-device VT-d/AMD-Vi domains programmed at device_claim, -ECONFINE rollback, dma_alloc buffers bound and torn down at death; fail-open only with no IOMMU). Restated; M16 marker flipped to done. - The FHS flag-day paths: /etc/devices.csv -> /system/configuration/devices.csv (devices-csv.md, new-driver-checklist.md, device-manager.md), /var/log -> /system/logs (logging.md, new-driver-checklist.md), /mnt/usb -> /volumes/usb (process-management.md). Following the old paths silently breaks driver match. - protocol-namespace P4 "remaining" -> landed (only P5 remains); shared-fate fan-out "not yet enforced" -> enforced; wall_clock "not built" -> built; SMP affinity + fault-recovery "left" -> built; process_enumerate raw-pointer trust model -> checked copyToUser/EFAULT; bounds.md maximum_devices static hole -> dynamic per-registrar quota; init spawns fat -> volume-manager; config "hardcoded, move to /etc" -> already CSV data files; vdso.md three- value call; zig-self-hosting library/ layout; python argv "new" -> built. Found and fixed by a multi-agent audit across 12 doc clusters, each finding adversarially verified against the source.
101 lines
5.2 KiB
Markdown
101 lines
5.2 KiB
Markdown
# Logging
|
|
|
|
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 with one bootstrap exception: the
|
|
kernel's framebuffer console (`system/kernel/console.zig`) joins the log sinks
|
|
at boot, so the whole transcript shows on screen until the display service
|
|
claims the framebuffer and silences it; after that only panic/fatal messages
|
|
are mirrored to it explicitly (`system/kernel/kernel.zig`).
|
|
|
|
## The pipeline
|
|
|
|
```
|
|
process std.log ──▶ debug_write(level) ──▶ tagged kernel ring ──▶ logger service ──▶ /system/logs/<boot-stamp>/<binary-path>.log
|
|
kernel log.print ─┘ │
|
|
└▶ serial / 0xE9 sinks (QEMU, -Dserial)
|
|
```
|
|
|
|
1. **Emit.** A program calls `std.log.info("mounted {s}", .{path})` — the
|
|
runtime's `logFn` (installed for every binary by the root shim,
|
|
`library/kernel/logging.zig`) formats one line and issues one `debug_write`
|
|
carrying the level. The payload does NOT contain the process's name.
|
|
`logging.write` remains as the raw/bring-up path (panics, test
|
|
fixtures); raw bytes ride the same ring, attributed all the same.
|
|
|
|
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.
|
|
|
|
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.
|
|
|
|
4. **Render.** Registered sinks (serial under `-Dserial`, the 0xE9 debug
|
|
console, and the framebuffer console until the display service claims the
|
|
screen) 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.
|
|
|
|
5. **Persist.** The **logger service** (`system/services/logger`) drains the
|
|
ring every 250 ms and demultiplexes records into one file per source under
|
|
`/system/logs/<boot-stamp>/`, e.g.
|
|
|
|
```
|
|
/system/logs/2026-07-21T150434Z/kernel.log
|
|
/system/logs/2026-07-21T150434Z/system/services/fat.log
|
|
/system/logs/2026-07-21T150434Z/system/drivers/usb-storage.log
|
|
```
|
|
|
|
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.
|
|
|
|
## Why a ring in the kernel, not a logging server
|
|
|
|
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.
|
|
|
|
Two disciplines keep it honest:
|
|
|
|
- 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.
|
|
|
|
## Last-resort channels
|
|
|
|
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.
|
|
- `/system/logs` 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.
|