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

runtime: std.log for every user binary — kernel-stamped attribution

Browse Source 
library/runtime/log.zig wires std.log to the tagged ring: the root shim
installs std_options for every binary (programs may override), logFn
formats one line per record and emits it with its level via
debug_write — the payload no longer carries the process's name; the
kernel stamps identity structurally and the serial renderer prints the
'<binary path>: ' prefix, so the transcript keeps its shape.

Migrate every writeLine/logLine/log helper family (init, vfs, fat,
device-manager, acpi, pci-bus, ps2-bus x3, usb-hid x2, usb-storage,
usb-xhci-bus, virtio-gpu — 104 call sites) to std.log.info, dropping
the hand-written prefixes. A leveled record is a complete line by
contract (raw emissions may still build lines from pieces). Test
fixtures and the display/input services keep raw writes for now — their
ring records are attributed by the kernel regardless.

Harness regexes follow the renamed prefixes (usb-hid-keyboard,
discovery) and path-named restart lines.
This commit is contained in:
Daniel Samson
2026-07-21 15:39:51 +01:00
parent 9f18d8340e
commit f480c5d790
19 changed files with 172 additions and 193 deletions
Download Patch File Download Diff File Expand all files Collapse all files
system/services/acpi/acpi.zig
+7 -12
View File
@@ -21,11 +21,6 @@ const power = runtime.power_protocol;
/// integer decode names the opcodes instead of bare 0x0A/0x0B/… (docs/coding-standards.md).
const opcodes = aml.opcodes;
fn writeLine(comptime fmt: []const u8, arguments: anytype) void {
var line: [128]u8 = undefined;
_ = runtime.system.write(std.fmt.bufPrint(&line, fmt, arguments) catch return);
}
// The claimed acpi-tables node and the resource index of its broad io_port
// window — the Hal routes every port access through this one claim.
var node_id: u64 = 0;
@@ -163,12 +158,12 @@ pub fn main(init: runtime.process.Init) void {
};
var namespace = result.namespace;
const devices = aml.deviceCount(&namespace);
writeLine("/system/services/acpi: parsed {d} AML blob(s), {d} namespace devices\n", .{ block_count, devices });
std.log.info("parsed {d} AML blob(s), {d} namespace devices", .{ block_count, devices });
if (floor) |minimum| {
if (devices >= minimum) {
_ = runtime.system.write("acpi-parse: ok\n");
} else {
writeLine("acpi-parse: too few (ring-3 {d} < floor {d})\n", .{ devices, minimum });
std.log.info("acpi-parse: too few (ring-3 {d} < floor {d})", .{ devices, minimum });
}
// Self-verify mode is standalone (no manager); stop before reporting.
while (true) runtime.system.sleep(1000);
@@ -216,9 +211,9 @@ fn onInit(endpoint: runtime.ipc.Handle) bool {
const hid = entry.hid[0..entry.hid_len];
const desc = acpi_ids.description(hid);
if (desc.len != 0)
writeLine("/system/services/acpi: reported {s} (device {d}, {d} resources) — {s}\n", .{ hid, entry.device_id, entry.resource_count, desc })
std.log.info("reported {s} (device {d}, {d} resources) — {s}", .{ hid, entry.device_id, entry.resource_count, desc })
else
writeLine("/system/services/acpi: reported {s} (device {d}, {d} resources)\n", .{ hid, entry.device_id, entry.resource_count });
std.log.info("reported {s} (device {d}, {d} resources)", .{ hid, entry.device_id, entry.resource_count });
if (manager) |h| {
var report = protocol.ChildAdded{ .parent = node_id, .bus_address = entry.device_id, .identity = 0, .device_id = entry.device_id };
@memcpy(report.hid[0..entry.hid_len], entry.hid[0..entry.hid_len]);
@@ -226,7 +221,7 @@ fn onInit(endpoint: runtime.ipc.Handle) bool {
_ = runtime.ipc.call(h, std.mem.asBytes(&report), &reply) catch {};
}
}
writeLine("/system/services/acpi: reported {d} device(s) to the manager\n", .{registered_count});
std.log.info("reported {d} device(s) to the manager", .{registered_count});
armPowerButton(endpoint);
return true;
@@ -373,7 +368,7 @@ fn publishNotify(node: *aml.Node, code: u64) void {
const which: power.Event = if (std.mem.eql(u8, hid[0..7], "PNP0C0A")) .battery else if (std.mem.eql(u8, hid[0..7], "ACPI0003")) .ac else if (std.mem.eql(u8, hid[0..7], "PNP0C0D")) .lid else .notify;
var event = power.EventMessage{ .event = @intFromEnum(which), .code = @truncate(code) };
event.hid = hid;
writeLine("power: notify {s} code {d}\n", .{ hid[0..7], code });
std.log.info("power: notify {s} code {d}", .{ hid[0..7], code });
publishEvent(std.mem.asBytes(&event));
}
@@ -500,7 +495,7 @@ fn registerDevice(node: *aml.Node, hid: [8]u8, interpreter: *aml.Interpreter) vo
applyCrs(&descriptor, node, interpreter);
const id = device.register(node_id, &descriptor) orelse {
writeLine("/system/services/acpi: register refused for {s}\n", .{hid[0..@intCast(hid_len)]});
std.log.info("register refused for {s}", .{hid[0..@intCast(hid_len)]});
return;
};
registered[registered_count] = .{ .hid = hid, .hid_len = @intCast(hid_len), .device_id = id, .resource_count = descriptor.resource_count };
system/services/device-manager/device-manager.zig
+15 -23
View File
@@ -24,14 +24,6 @@ const protocol = runtime.device_manager_protocol;
const device = runtime.device;
const system = runtime.system;
/// Format one whole log line and emit it in a single `debug_write`, so output
/// from the drivers this manager starts (which run concurrently) can never land
/// in the middle of it.
fn writeLine(comptime fmt: []const u8, arguments: anytype) void {
var line: [128]u8 = undefined;
_ = runtime.system.write(std.fmt.bufPrint(&line, fmt, arguments) catch return);
}
/// The PCI class/subclass/prog-IF triple of an xHCI (USB 3) host controller —
/// Serial Bus Controller / USB Controller / XHCI — named from pci-class.zig rather
/// than written as the bare 0x0C0330 (docs/coding-standards.md, "Named values").
@@ -223,7 +215,7 @@ fn addChild(parent: u64, bus_address: u64, identity: u64, device_id: u64, report
fn pruneChildrenOf(reporter: u32) void {
for (&children) |*child| {
if (child.used and child.reporter == reporter) {
writeLine("/system/services/device-manager: child removed (device {d} port {d})\n", .{ child.parent, child.bus_address });
std.log.info("child removed (device {d} port {d})", .{ child.parent, child.bus_address });
child.used = false;
const event = protocol.ChildRemoved{ .parent = child.parent, .bus_address = child.bus_address };
publishEvent(std.mem.asBytes(&event));
@@ -270,7 +262,7 @@ fn addDriver(name: []const u8, device_id: u64, speaks_protocol: bool) void {
spawnDriver(driver);
return;
}
writeLine("/system/services/device-manager: driver table full; cannot supervise {s}\n", .{name});
std.log.info("driver table full; cannot supervise {s}", .{name});
}
/// (Re)spawn a driver instance: supervised on the manager's own endpoint, the
@@ -285,7 +277,7 @@ fn spawnDriver(driver: *Driver) void {
argument_count = 1;
}
const child = system.spawnSupervised(driver.name(), arguments[0..argument_count], manager_endpoint) orelse {
writeLine("/system/services/device-manager: failed to spawn {s}\n", .{driver.name()});
std.log.info("failed to spawn {s}", .{driver.name()});
driver.state = .failed;
return;
};
@@ -299,9 +291,9 @@ fn spawnDriver(driver: *Driver) void {
driver.state = .running;
}
if (driver.device_id != protocol.no_device) {
writeLine("/system/services/device-manager: spawned {s} for device {d}\n", .{ driver.name(), driver.device_id });
std.log.info("spawned {s} for device {d}", .{ driver.name(), driver.device_id });
} else {
writeLine("/system/services/device-manager: spawned {s}\n", .{driver.name()});
std.log.info("spawned {s}", .{driver.name()});
}
}
@@ -313,7 +305,7 @@ fn onDriverExit(driver: *Driver) void {
const reason = runtime.process.exitReason(driver.process_id) orelse .fault;
if (reason == .exited) {
driver.state = .stopped;
writeLine("/system/services/device-manager: {s} exited cleanly; not restarting\n", .{driver.name()});
std.log.info("{s} exited cleanly; not restarting", .{driver.name()});
return;
}
const now = system.clock();
@@ -321,13 +313,13 @@ fn onDriverExit(driver: *Driver) void {
driver.restarts = if (alive_ns < fast_death_ns) driver.restarts + 1 else 1;
if (driver.restarts >= crash_loop_cap) {
driver.state = .failed;
writeLine("/system/services/device-manager: {s} is failing repeatedly (crash loop); giving up\n", .{driver.name()});
std.log.info("{s} is failing repeatedly (crash loop); giving up", .{driver.name()});
return;
}
const delay_ms = backoff_base_ms << @intCast(driver.restarts - 1);
driver.state = .restarting;
driver.restart_due_ns = now + delay_ms * 1_000_000;
writeLine("/system/services/device-manager: restarting {s} in {d} ms (died: {s})\n", .{ driver.name(), delay_ms, @tagName(reason) });
std.log.info("restarting {s} in {d} ms (died: {s})", .{ driver.name(), delay_ms, @tagName(reason) });
_ = system.timerOnce(manager_endpoint, delay_ms + 50);
}
@@ -338,7 +330,7 @@ fn onDriverExit(driver: *Driver) void {
fn sweepDeadlines() void {
const now = system.clock();
if (test_kill_pid != 0 and now >= test_kill_due_ns) {
writeLine("/system/services/device-manager: test mode: killing the reporter\n", .{});
std.log.info("test mode: killing the reporter", .{});
_ = system.kill(test_kill_pid);
test_kill_pid = 0;
}
@@ -346,7 +338,7 @@ fn sweepDeadlines() void {
if (!driver.used) continue;
switch (driver.state) {
.awaiting_hello => if (now >= driver.hello_deadline_ns) {
writeLine("/system/services/device-manager: {s} missed its hello deadline\n", .{driver.name()});
std.log.info("{s} missed its hello deadline", .{driver.name()});
_ = system.kill(driver.process_id);
// The exit notification finishes the job via onDriverExit.
},
@@ -423,10 +415,10 @@ fn onMessage(message: []const u8, reply: []u8, sender: u32, capability: ?runtime
var status: i32 = 0;
if (hello.version != protocol.version) {
status = -1;
writeLine("/system/services/device-manager: refused hello (version {d}) from process {d}\n", .{ hello.version, sender });
std.log.info("refused hello (version {d}) from process {d}", .{ hello.version, sender });
} else if (driverByProcess(sender)) |driver| {
driver.state = .running;
writeLine("/system/services/device-manager: hello from {s} (device {d})\n", .{ driver.name(), hello.device_id });
std.log.info("hello from {s} (device {d})", .{ driver.name(), hello.device_id });
// Resilience drill (V6): once, kill the virtio-gpu driver a moment after it hellos, so
// the normal restart policy respawns it — the compositor must survive and re-attach.
if (test_scanout_restart_mode and !test_scanout_killed and std.mem.eql(u8, driver.name(), "/system/drivers/virtio-gpu")) {
@@ -437,7 +429,7 @@ fn onMessage(message: []const u8, reply: []u8, sender: u32, capability: ?runtime
}
} else {
status = -1;
writeLine("/system/services/device-manager: hello from unknown process {d}\n", .{sender});
std.log.info("hello from unknown process {d}", .{sender});
}
const hello_reply = protocol.HelloReply{ .status = status };
@memcpy(reply[0..protocol.reply_size], std.mem.asBytes(&hello_reply));
@@ -453,7 +445,7 @@ fn onChildAdded(message: []const u8, reply: []u8, sender: u32) usize {
var status: i32 = 0;
if (driverByProcess(sender)) |driver| {
if (!addChild(report.parent, report.bus_address, report.identity, report.device_id, sender)) status = -1;
writeLine("/system/services/device-manager: child added (device {d} port {d}, identity {d}) by {s}\n", .{ report.parent, report.bus_address, report.identity, driver.name() });
std.log.info("child added (device {d} port {d}, identity {d}) by {s}", .{ report.parent, report.bus_address, report.identity, driver.name() });
if (status == 0) publishEvent(message[0..protocol.child_added_size]);
// Matching from reports (M19.3): a registered child whose identity
// names a driver gets one, once — re-reports after a bus restart
@@ -519,7 +511,7 @@ fn onChildRemoved(message: []const u8, reply: []u8, sender: u32) usize {
var status: i32 = -1;
for (&children) |*child| {
if (child.used and child.parent == report.parent and child.bus_address == report.bus_address and child.reporter == sender) {
writeLine("/system/services/device-manager: child removed (device {d} port {d})\n", .{ child.parent, child.bus_address });
std.log.info("child removed (device {d} port {d})", .{ child.parent, child.bus_address });
child.used = false;
status = 0;
}
system/services/fat/fat.zig
+2 -7
View File
@@ -16,11 +16,6 @@ const on_disk = @import("on-disk.zig");
const protocol = runtime.vfs_protocol;
const dma = runtime.dma;
fn writeLine(comptime fmt: []const u8, arguments: anytype) void {
var line: [96]u8 = undefined;
_ = runtime.system.write(std.fmt.bufPrint(&line, fmt, arguments) catch return);
}
const mount_point = "/mnt/usb";
// The engine's BlockDevice, backed by the `.block` driver plus a DMA bounce
@@ -104,14 +99,14 @@ fn initialise(endpoint: runtime.ipc.Handle) bool {
_ = runtime.system.write("/system/services/fat: not a FAT filesystem\n");
return false;
};
writeLine("/system/services/fat: mounted FAT ({s}, {d} clusters, partition lba {d})\n", .{ @tagName(filesystem.geometry.fat_type), filesystem.geometry.cluster_count, filesystem.base_lba });
std.log.info("mounted FAT ({s}, {d} clusters, partition lba {d})", .{ @tagName(filesystem.geometry.fat_type), filesystem.geometry.cluster_count, filesystem.base_lba });
// Mount ourselves into the VFS namespace at /mnt/usb (retry while the VFS
// comes up). From here the VFS routes /mnt/usb/... to this server.
var tries: u32 = 0;
while (tries < 100) : (tries += 1) {
if (runtime.fs.mount(mount_point, endpoint)) {
writeLine("/system/services/fat: mounted {s}\n", .{mount_point});
std.log.info("mounted {s}", .{mount_point});
return true;
}
runtime.system.sleep(50);
system/services/init/init.zig
+3 -8
View File
@@ -145,26 +145,21 @@ fn restartChild(id: u32) void {
// An unknown reason (the record aged out) is treated as a crash worth restarting.
const reason = runtime.process.exitReason(id) orelse .fault;
if (reason == .exited) {
logLine("/system/services/init: {s} exited cleanly; not restarting\n", .{service});
std.log.info("{s} exited cleanly; not restarting", .{service});
return;
}
restart_counts[i] += 1;
if (restart_counts[i] > maximum_restarts) {
logLine("/system/services/init: {s} keeps crashing; giving up after {d} restarts\n", .{ service, maximum_restarts });
std.log.info("{s} keeps crashing; giving up after {d} restarts", .{ service, maximum_restarts });
return;
}
logLine("/system/services/init: {s} died ({s}); restarting ({d}/{d})\n", .{ service, @tagName(reason), restart_counts[i], maximum_restarts });
std.log.info("{s} died ({s}); restarting ({d}/{d})", .{ service, @tagName(reason), restart_counts[i], maximum_restarts });
if (runtime.system.spawnSupervised(service, &.{}, supervision_endpoint)) |new_id| child_ids[i] = new_id;
return;
}
// An untracked child (e.g. the log-flush one-shot): nothing to restart.
}
fn logLine(comptime fmt: []const u8, args: anytype) void {
var line: [128]u8 = undefined;
_ = runtime.system.write(std.fmt.bufPrint(&line, fmt, args) catch return);
}
/// Look up the power service and subscribe our endpoint (handed over as the
/// call's capability) so events arrive as buffered messages here.
fn subscribePower() void {
system/services/vfs/vfs.zig
+4 -11
View File
@@ -113,13 +113,6 @@ fn fail(out: []u8) usize {
return writeReply(out, .{ .status = -1 }, &.{});
}
/// Format one whole log line and emit it in a single `debug_write`, so lines from
/// concurrent processes can never land in the middle of it.
fn writeLine(comptime fmt: []const u8, arguments: anytype) void {
var line: [96]u8 = undefined;
_ = runtime.system.write(std.fmt.bufPrint(&line, fmt, arguments) catch return);
}
// --- mount routing ----------------------------------------------------------
/// Forward an open under a mount to its backend and, on success, allocate a local
@@ -211,7 +204,7 @@ fn doMount(out: []u8, prefix: []const u8, backend: ipc.Handle) usize {
for (&mounts) |*m| {
if (m.used and std.mem.eql(u8, m.prefix[0..m.prefix_len], prefix)) {
m.backend = backend;
writeLine("/system/services/vfs: remounted {s}\n", .{prefix});
std.log.info("remounted {s}", .{prefix});
return writeReply(out, .{ .status = 0 }, &.{});
}
}
@@ -222,7 +215,7 @@ fn doMount(out: []u8, prefix: []const u8, backend: ipc.Handle) usize {
@memcpy(m.prefix[0..l], prefix[0..l]);
m.prefix_len = l;
m.backend = backend;
writeLine("/system/services/vfs: mounted {s}\n", .{prefix[0..l]});
std.log.info("mounted {s}", .{prefix[0..l]});
return writeReply(out, .{ .status = 0 }, &.{});
}
}
@@ -233,7 +226,7 @@ fn doUnmount(out: []u8, prefix: []const u8) usize {
for (&mounts) |*m| {
if (m.used and std.mem.eql(u8, m.prefix[0..m.prefix_len], prefix)) {
m.used = false;
writeLine("/system/services/vfs: unmounted {s}\n", .{prefix});
std.log.info("unmounted {s}", .{prefix});
return writeReply(out, .{ .status = 0 }, &.{});
}
}
@@ -252,7 +245,7 @@ fn releaseClientHandles(client: u32) void {
released += 1;
}
}
if (released != 0) writeLine("/system/services/vfs: released {d} handle(s) for dead client {d}\n", .{ released, client });
if (released != 0) std.log.info("released {d} handle(s) for dead client {d}", .{ released, client });
}
/// Handle one request from `sender`; write the reply into `out`, return its length.