From 88d956e1acbdf5622fe155ccc8f12f71bef923da Mon Sep 17 00:00:00 2001 From: draw me an elephant <68925779+drawmeanelephant@users.noreply.github.com> Date: Mon, 14 Sep 2026 20:44:00 -0400 Subject: [PATCH] #1261 probes: exception entry, spurious ack, timer re-arm, console-free sample MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit All inert unless `forensics on`; each is pinned by the extended live-forensics gate so deleting a call site fails the gate instead of silently zeroing the reading a dying boot is read for. - `entry` at exc_dispatch entry, BEFORE any GIC state is consumed — cadence vs the post-ack `irq` probe separates "not delivered" from "delivered but acked spurious". - `spur` on the spurious-ack early return in irq_dispatch — a spurious storm was previously indistinguishable from silence. Reported in the gate census, not required (a healthy boot acks zero). - `rearm` in timer.arm, arg = the programmed comparator delta — a steady rearm cadence with no `entry` says the comparator fires but the exception is never taken; a rearm gap says the source stopped. - `shot` from the shell idle loop, self-draining, one per 4 s of wall-clock time: proves the guest is still executing with no console traffic to ride on. Clock choice is measured, not assumed. Two candidates were tried and rejected with live evidence: `scheduler.tick_count` (per-quantum, not per-second: 6,212 samples in one gate boot) and `timer.irq_ticks` (shared by both cores' PPIs and reset by re-init paths: went 1 -> 0 during early boot and advanced ~2/s, flooding at ~47 samples/s — the gate census `shot: 6624` caught it before merge). The shipped clock is `timer.cntpct() / timer.freq`: monotonic-by-contract, exact seconds, host-test-deterministic (freq is a parameter). The counter itself is NOT monotonic for the first ~0.9 s under VZ on this host (observed twice: a ~0.1 s backward step at t≈0.89 s), so the elapsed computation saturates instead of underflowing, and any trace that sorts `t=` across the first second of a boot is misordered — a finding for #1261, recorded where the guard is. Measured on the nudge dying-boot scratch tree: samples on a 4.0 s cadence to the end of a 120 s boot, spurious acks zero, beat deltas 1.000-1.002 s, `entry` cadence matching the 1 Hz timer — the PPIs are delivered AND recorded to the end. Full finding on issue #1261. Gate: live-forensics PASS 1/1 — census entry 245 / irq 238 / rearm 238 / rotate 121 / shot 32 on a 120 s boot, shot args 4->8->...->124 exact. 🤖 Generated with Codebuff Co-Authored-By: Codebuff --- docs/gate-fleet-inventory.md | 2 +- kernel/src/exceptions.zig | 7 ++ kernel/src/forensics.zig | 102 +++++++++++++++++++++++++++ kernel/src/main.zig | 9 ++- kernel/src/shell.zig | 11 +++ kernel/src/timer.zig | 6 ++ tools/gate/specs/live-forensics.spec | 23 ++++-- 7 files changed, 154 insertions(+), 6 deletions(-) diff --git a/docs/gate-fleet-inventory.md b/docs/gate-fleet-inventory.md index 987a1b98..e7fa792b 100644 --- a/docs/gate-fleet-inventory.md +++ b/docs/gate-fleet-inventory.md @@ -91,7 +91,7 @@ of them with `just verify-vz`. | spec | `live-filemanager-props` | 1 run / 5 assert | live-filemanager-props.spec -- M25 Lane A F2: properties inspector on VZ. | | spec | `live-filemanager-recent` | 1 run / 7 assert | live-filemanager-recent.spec -- M25 Lane B F5: recent ring on VZ. | | spec | `live-font-sizes` | 1 run / 6 assert | live-font-sizes.spec -- milestone-twenty card U1 class-B gate | -| spec | `live-forensics` | 1 run / 10 assert | live-forensics.spec -- #1278 class-B gate: the last-words recorder. | +| spec | `live-forensics` | 1 run / 13 assert | live-forensics.spec -- #1278 class-B gate: the last-words recorder. | | spec | `live-fs` | 2 run / 12 assert | live-fs.spec -- host-share storage (M34 HF6): run A writes | | spec | `live-gfs` | 2 run / 10 assert | live-gfs.spec -- the general store IS the host share: `mount` | | spec | `live-glob` | 1 run / 6 assert | live-glob.spec -- shell globbing: *, ?, and [...] all expand to | diff --git a/kernel/src/exceptions.zig b/kernel/src/exceptions.zig index 956c1c58..9e934536 100644 --- a/kernel/src/exceptions.zig +++ b/kernel/src/exceptions.zig @@ -45,6 +45,7 @@ const scheduler = @import("scheduler.zig"); const svclock = @import("svclock.zig"); // claim 9498 follow-on: demand-paging faults gate only the KERNEL domain (mmap-region/registry state) const memmap = @import("memmap.zig"); const userspace = @import("userspace.zig"); +const forensics = @import("forensics.zig"); // #1261: exception-entry probe (inert unless `forensics on`) // --------------------------------------------------------------------------- // Exception kinds (the x5 value each stub passes; also the vector offset's @@ -915,6 +916,12 @@ pub export fn exc_dispatch( ) callconv(.c) Resume { const cid = resume_core(); // per-core resume handoff (issue #810) handled_count_value[cid] += 1; // per-core: secondary-core IRQs fire in parallel + // #1261: record exception ENTRY, before any GIC state is consumed. The + // post-ack `irq` probe cannot distinguish "the interrupt stopped being + // delivered" from "it was delivered but acked as spurious"; this one + // fires the instant C code takes control, and its cadence vs the `irq` + // cadence and the `rearm` cadence separates the two. + forensics.note(.entry, kind); resume_frame[cid] = @intFromPtr(frame); resume_sp_el0[cid] = source_sp_el0(frame, spsr); // Claim 7948: taken IRQs route to the registered dispatcher (GIC ack diff --git a/kernel/src/forensics.zig b/kernel/src/forensics.zig index 75716d9e..cc3e4ebd 100644 --- a/kernel/src/forensics.zig +++ b/kernel/src/forensics.zig @@ -59,6 +59,23 @@ pub const Site = enum(u8) { wake = 2, console_line = 3, shot = 4, + /// #1261: exception ENTRY, recorded before `gic.ack()`. The `irq` probe + /// sits after the ack and the spurious check, so "no irq records" in a + /// silent tail is ambiguous between "no interrupt was delivered" and "no + /// interrupt was acked-and-true". `entry` removes the ambiguity: it fires + /// the instant C code takes control, before any GIC state is consumed. + /// `arg` carries the exception KIND (the vector class, not an INTID). + entry = 5, + /// #1261: the comparator was (re-)programmed. A gap in `rearm` records + /// means the timer hardware was never given a new deadline — the PPIs + /// stopped at the SOURCE — while a steady `rearm` cadence with no `entry` + /// records means the comparator fires but the core never takes the + /// exception. `arg` is the programmed comparator delta in counter ticks. + rearm = 6, + /// #1261: `gic.ack()` returned a spurious INTID. "Signaled but not a real + /// interrupt" — the record that makes a spurious storm visible instead of + /// silently collapsing into the same tail as no interrupts at all. + spur = 7, pub fn name(self: Site) []const u8 { return switch (self) { @@ -67,6 +84,9 @@ pub const Site = enum(u8) { .wake => "wake", .console_line => "line", .shot => "shot", + .entry => "entry", + .rearm => "rearm", + .spur => "spur", }; } }; @@ -213,12 +233,64 @@ pub fn drain(con: console.Console) void { if (n > 0) con.write(buf[0..n]); } +/// #1261: a console-FREE liveness sample. The recorder's emission is coupled +/// to console writes, so "the trace stopped" is always confounded with "the +/// console stopped" — on the nudge tree the last 47k serial lines print with +/// no `irq` record, and that alone cannot separate delivery from recording. +/// +/// This probe produces a record no console line needs to exist for: it notes +/// the sample, then *drains it inline* through its own `con.write`. It runs +/// from the shell idle loop (main context, the same rules as +/// `maybe_heartbeat`), once per `sample_period_secs` of wall-clock time, so a +/// guest that is still executing keeps appending `fxs:` lines to the serial +/// log no matter what the console traffic looks like. +pub const sample_period_secs: u64 = 4; +var last_sample_secs: ?u64 = null; + +/// The clock is the free-running hardware counter (`timer.cntpct()`) divided +/// by the programmed frequency (`timer.freq`) — monotonic by definition and +/// exact in wall-clock seconds. Two clock choices were measured and rejected: +/// +/// - `scheduler.tick_count` advances per scheduling quantum, not per second +/// (6,212 records in one gate boot — a trace flood, not a heartbeat). +/// - `timer.irq_ticks` is a SHARED counter, incremented by BOTH cores' 1 Hz +/// PPIs and reset by timer re-init paths: it went 1 -> 0 during early boot +/// and advanced ~2/s, so the `== 0` bypass plus the shared increments +/// produced 5,575 samples in a 119 s boot (~47/s, bursts 50 µs apart). +/// +/// `freq == 0` (counter not yet programmed) suppresses the sample rather than +/// guessing a rate. `arg` of the `shot` record is the whole wall-clock second. +pub fn sample(con: console.Console, counter: u64, freq: u64) void { + if (!enabled or draining) return; + if (freq == 0) return; + const secs = counter / freq; + if (last_sample_secs) |ls| { + // Saturation, not subtraction: the counter itself is NOT monotonic + // for the first ~0.9 s of a boot under VZ on this host (observed + // twice: a ~0.1 s backward step at t≈0.89 s, shell read ≥24M ticks + // while the recorder's read 54 µs later was 21.5M). A bare `secs - + // ls` would underflow there — Debug panics, ReleaseFast silently + // wraps. On a backward step, restart the cadence from the new base. + const elapsed = if (secs > ls) secs - ls else 0; + if (elapsed < sample_period_secs) return; + } + last_sample_secs = secs; + note(.shot, secs); + // Inline drain of JUST what is pending, reentrancy-guarded as `drain` is. + draining = true; + defer draining = false; + var buf: [max_per_drain * 64]u8 = undefined; + const n = format_pending(buf[0..]); + if (n > 0) con.write(buf[0..n]); +} + /// Reset for a fresh capture (the `forensics reset` command). pub fn reset() void { records = [_]Record{.{}} ** capacity; next = [_]u64{0} ** smp.max_cores; emitted = 0; truncated = 0; + last_sample_secs = null; } // --------------------------------------------------------------------------- @@ -351,3 +423,33 @@ test "forensics: reset drops what was recorded and emits nothing stale" { try std.testing.expect(std.mem.indexOf(u8, buf[0..n], "seq=0 t=0 arg=13") != null); enabled = false; } + +test "forensics: the idle sample fires once per period of wall-clock seconds, not per tick" { + reset(); + enabled = true; + var mock = console.MockConsole(4096){}; + const con = mock.console(); + const freq: u64 = 24_000_000; + // The first call at freq=0 (counter not yet programmed) must be suppressed: + // an unprogrammed clock must not guess a rate. + sample(con, 1_000_000, 0); + try std.testing.expectEqual(@as(usize, 0), mock.contents().len); + try std.testing.expectEqual(@as(usize, 0), pending()); + // First live sample at t=1s fires immediately (no last_sample_secs yet). + sample(con, freq, freq); + try std.testing.expectEqual(@as(usize, 1), std.mem.count(u8, mock.contents(), "fx: ")); + // Within the period: every call, even thousands of them, adds nothing — + // the flood regression (5,575 samples in a 119 s boot) is pinned here. + var t: u64 = freq; + while (t < (sample_period_secs - 1) * freq) : (t += 1_000) { + sample(con, t, freq); + } + try std.testing.expectEqual(@as(usize, 1), std.mem.count(u8, mock.contents(), "fx: ")); + // Crossing the period boundary fires exactly once more (5 - 1 = 4 >= 4), + // with arg = the whole wall-clock second. + sample(con, (sample_period_secs + 1) * freq, freq); + const text = mock.contents(); + try std.testing.expectEqual(@as(usize, 2), std.mem.count(u8, text, "fx: ")); + try std.testing.expect(std.mem.indexOf(u8, text, "site=shot core=0 seq=1 t=0 arg=5") != null); + enabled = false; +} diff --git a/kernel/src/main.zig b/kernel/src/main.zig index 490d2902..263b3aa6 100644 --- a/kernel/src/main.zig +++ b/kernel/src/main.zig @@ -1914,7 +1914,14 @@ fn process_stdout(text: []const u8) void { /// fires. fn irq_dispatch() void { const intid = gic.ack(); - if (gic.is_spurious(intid)) return; + if (gic.is_spurious(intid)) { + // #1261: a spurious ack means the interrupt was SIGNALED but not + // delivered as a real one (or was raced to zero by another core). + // Invisible after this point — without this record a storm of + // spurious acks is indistinguishable from silence. + forensics.note(.spur, intid); + return; + } gic.note_irq(intid); // #1278: record the delivery itself. This runs in IRQ context, which is // exactly why `note` may not print — the record is emitted by whatever diff --git a/kernel/src/shell.zig b/kernel/src/shell.zig index 51e82c35..b8479115 100644 --- a/kernel/src/shell.zig +++ b/kernel/src/shell.zig @@ -48,6 +48,7 @@ pub const clipboard = @import("clipboard.zig"); // M18 T2 (issue #405): shared c pub const virtio_file = @import("virtio_file.zig"); const svclock = @import("svclock.zig"); // claim 9498 follow-on: the idle loop's service-state brackets (NET/WIN+EV/FILE) const trust = @import("trust.zig"); // M50 TS2 (#1136, ADR 0024 D4): the kernel-actor gate for history/env +const forensics = @import("forensics.zig"); // #1261: console-free liveness sample from the idle loop /// M18 T4: path for persistent shell history file. const history_path = "HISTORY.TXT"; @@ -3706,6 +3707,16 @@ fn park_body(mon: *monitor.Monitor) callconv(.c) void { timer.maybe_heartbeat(&mon.console); scheduler.maybe_report(&mon.console); userspace.maybe_report(&mon.console); + // #1261: the console-free liveness sample. If the guest is still + // executing, `fxs:` lines keep appearing in the serial log every + // `forensics.sample_period_secs` seconds regardless of what the + // console traffic is doing — the cleanest way to tell "the guest + // stopped" from "the recorder had nothing to ride on". The clock + // is the free-running hardware counter divided by the programmed + // frequency: monotonic, wall-clock, shared by both cores (an + // earlier choice, `timer.irq_ticks`, is shared and resettable and + // flooded the trace at ~47 samples/s). + forensics.sample(mon.console, timer.cntpct(), timer.freq); // M19 P7 (issue #296): reap finished background jobs — the // `[N] Done:` line prints from the same idle path as every // other asynchronous report above. diff --git a/kernel/src/timer.zig b/kernel/src/timer.zig index cfa43c34..843b88a3 100644 --- a/kernel/src/timer.zig +++ b/kernel/src/timer.zig @@ -28,6 +28,7 @@ const std = @import("std"); const builtin = @import("builtin"); const mmio = @import("mmio.zig"); const console = @import("console.zig"); +const forensics = @import("forensics.zig"); // #1261: comparator re-arm probe (inert unless `forensics on`) /// Conventional EL1 physical-timer PPI when the GTDT is absent or silent. pub const ppi_default: u32 = 30; @@ -141,6 +142,11 @@ pub fn arm() void { if (comptime builtin.cpu.arch != .aarch64) return; if (period_ticks == 0) return; const cval = cntpct() + period_ticks; + // #1261: record that the hardware was given a deadline, and what it was. + // A steady `rearm` cadence with no `entry` records says the comparator + // fires but the exception is never taken; a `rearm` gap says the source + // itself stopped. The delta is what exposes a clobbered `period_ticks`. + forensics.note(.rearm, period_ticks); asm volatile ("msr cntp_cval_el0, %[v]" : : [v] "r" (cval), diff --git a/tools/gate/specs/live-forensics.spec b/tools/gate/specs/live-forensics.spec index b3e4efc4..f6b0a1de 100644 --- a/tools/gate/specs/live-forensics.spec +++ b/tools/gate/specs/live-forensics.spec @@ -22,6 +22,14 @@ # run (`vm-stop: state=… reason=…`). A healthy boot must say VZ reported no # reason, which is the one line that disappears if the VZVirtualMachine # delegate stops being installed. +# +# 4. THE #1261 PROBES ARE WIRED. `entry` (exception entry, before GIC +# consumption), `rearm` (comparator programmed, arg = the delta) and +# `shot` (the console-free idle-loop sample) must all be present: each +# one is a call site whose silent deletion would zero exactly the +# reading a dying boot is read for. `spur` is deliberately NOT required +# here -- a healthy boot legitimately acks zero spurious interrupts -- +# but it is still reported in the site census. vgate_name live-forensics "#1278 -- last-words recorder: off by default, records reach serial" vgate_share seed @@ -45,6 +53,10 @@ vgate_assert 01 serial-contains 'forensics: enabled=0 pending=0 emitted=0 trunca # (2) It reaches serial once armed. vgate_assert 01 serial-contains 'fx: site=irq' vgate_assert 01 serial-contains 'fx: site=rotate' +# (4) The #1261 probes reach serial too. +vgate_assert 01 serial-contains 'fx: site=entry' +vgate_assert 01 serial-contains 'fx: site=rearm' +vgate_assert 01 serial-contains 'fx: site=shot' vgate_assert 01 serial-contains 'forensics: dump wrote=' vgate_assert 01 serial-contains 'fx-ok' # (3) The HOST half is wired. The runner now reports a stop verdict on every @@ -69,10 +81,13 @@ sites = {} for site, core, _seq, _t, _arg in rows: sites[site] = sites.get(site, 0) + 1 -# The two sites a silent death lands between: the interrupt that was being -# serviced, and the switch that was in flight (with the task it left behind -- -# the half an after-the-fact "who is current" dump can never recover). -for required in ("irq", "rotate"): +# The sites a silent death lands between, plus the #1261 probes: the +# interrupt being serviced, the switch in flight, the exception ENTRY before +# any GIC state is consumed, the comparator re-arm (arg = the programmed +# delta), and the console-free idle sample. Each required site fails the gate +# if its call site is deleted. `spur` is reported but not required: a healthy +# boot acks zero spurious interrupts. +for required in ("irq", "rotate", "entry", "rearm", "shot"): if sites.get(required, 0) == 0: print("no %s records: %r" % (required, sites), file=sys.stderr) sys.exit(1)