#1261 probes: exception entry, spurious ack, timer re-arm, console-free sample

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 |

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

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;
+}

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

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.

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),

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)