From 3122aa23502ec0345c4f58127e1073e36479e00f Mon Sep 17 00:00:00 2001 From: japabu Date: Mon, 14 Sep 2026 23:36:51 +0200 Subject: [PATCH 1/4] File four findings from the T14 hang investigation MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A read-only investigation into why the T14 does not come back after lancase-family boots (runs 36, 49, 52, 54, 55) turned up four things worth tracking, none of them explained by the tree under suspicion (6276fc87..4d604c86 is a no-op on the shipping boot but for two argv scans that return false, and run 36 hung on a tip that predates it entirely). `issues/build/a-hung-boots-log-partition-is-wiped-by-the-next-runs-flash.md` — `src/metal.rs`'s `flash` wipes and reflashes the stick at the *start* of every run, before that run's own `read_log` can run. A run that hangs never reaches `read_log` itself, and the next run's `flash` overwrites the partition before anything else does. No hung boot's own `/log` has ever been read as a result. `issues/kernel/eiac-and-ivar-are-msi-x-registers-on-an-msi-only-i219.md` — `toyos-i219` cites the 82574 datasheet throughout and writes `EIAC`/`IVAR` unconditionally in `open`, though the datasheet states `IVAR` is only valid in MSI-X mode. The T14's I219 has been measured (on a sibling branch, not yet in this tree) to be an MSI part, and separately, two runs on that branch show the write going through anyway — evidence only that some word landed where the driver looked, not that the register does anything documented. `issues/panic-path/no-watchdog-outlives-exitbootservices-and-a-hang-seals-nothing.md` — the firmware's own boot watchdog is disabled once `ExitBootServices` runs (the loader's own log line says so), and `halt_all_cpus` unconditionally disarms the kernel's own boot-progress deadline and hard-lockup NMI before it holds the panel — which are also the only two callers of the black-box `seal_wedge` path. A machine whose FADT names no reset register, or whose reset has never been observed to fire, is left with no bound on a panic at all and no record of one either. `issues/isolation/a-reboot-quiesces-xhci-and-leaves-a-claimed-i219-armed.md` — the reboot/shutdown path quiesces xHCI only; a claimed PCI function's own teardown (`pcidev::release`) is reached from exactly one place, a claim's `Drop`, which only runs when its holding process exits. `netd` never exits on a `lancase` boot, so the I219 warm-resets with bus mastering, MSI and both rings still armed. Every citation was verified with `sed -n`/`git show` against this worktree; where a fact was measured only on a sibling, unmerged branch, the finding says so and cites the commit rather than presenting it as merged. Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_014iqcj4jDKpaiDX8B7CMvmK --- ...rtition-is-wiped-by-the-next-runs-flash.md | 48 +++++++++++++ ...es-xhci-and-leaves-a-claimed-i219-armed.md | 55 ++++++++++++++ ...are-msi-x-registers-on-an-msi-only-i219.md | 56 +++++++++++++++ ...itbootservices-and-a-hang-seals-nothing.md | 71 +++++++++++++++++++ 4 files changed, 230 insertions(+) create mode 100644 issues/build/a-hung-boots-log-partition-is-wiped-by-the-next-runs-flash.md create mode 100644 issues/isolation/a-reboot-quiesces-xhci-and-leaves-a-claimed-i219-armed.md create mode 100644 issues/kernel/eiac-and-ivar-are-msi-x-registers-on-an-msi-only-i219.md create mode 100644 issues/panic-path/no-watchdog-outlives-exitbootservices-and-a-hang-seals-nothing.md diff --git a/issues/build/a-hung-boots-log-partition-is-wiped-by-the-next-runs-flash.md b/issues/build/a-hung-boots-log-partition-is-wiped-by-the-next-runs-flash.md new file mode 100644 index 0000000000..e77f340c38 --- /dev/null +++ b/issues/build/a-hung-boots-log-partition-is-wiped-by-the-next-runs-flash.md @@ -0,0 +1,48 @@ +--- +status: open +kind: tooling +opened: 2026-09-14 +--- + +# A hung boot's log partition is wiped by the next run's flash, before anyone reads it + +`src/metal.rs`'s `Driver::flash` (`:1000-1002`) opens every run with +`self.as_root("wiping the old signatures", Job::Wipe, …)` followed immediately +by `self.as_root("flashing the stick", Job::Flash, …)` — `wipefs --all` then +`dd` over the whole disk, unconditionally, before that run's own boot has +happened. `run` (`:1416`) calls `driver.flash(&image)` at `:1471`, and only +after the reboot does it read anything back: `ride_the_reboot` at `:1483`, +`wait_for_the_stick` at `:1487`, `read_log` at `:1489`. + +**So a run's own log is read only if that run comes back.** `wait_for_the_stick` +refuses `Refusal::Stick` (`:1107`) and the underlying `wait` refuses +`Refusal::Silent` (`:1121`) — both return before `read_log` (`:1489`) is ever +reached. A run that hangs writes nothing to disk that its own invocation goes +on to read, and the *next* invocation's `flash` destroys the partition before +anything else touches it. + +## What this cost + +Runs 36, 52, 54 and 55 (`lancase`-family, `t14-run*/` logs) hung past their +420 s deadline (`Refusal::Silent`); run 49 wedged the stick instead +(`Refusal::Stick`, back at 303 s). All five never reached `read_log`, and every +one of the five was followed by another run whose own `flash` — `wipefs` then +`dd` — overwrote the partition before it was ever read from outside the loop. +**No hung boot's own `/log` has ever been read.** That is the single largest +recoverable gap in diagnosing why the T14 does not come back: the record a +`logd` batch would have committed up to the instant of the hang (durability is +per-batch `fsync`, `userland/logd/src/main.rs:58`) is destroyed by the loop's +own next step rather than by anything the hang did. + +## What would answer it + +`read_log` already exists and already tolerates the stick being unreachable +(it is called after `wait_for_the_stick`). What is missing is a call to it — or +to the raw-sector read `raw_log` already takes for `--fat32-check` +(`run`, `:1489`-area) — **before** `flash`'s `wipefs`/`dd` at the *start* of the +next run, so the previous run's partition is read (and saved, where +`--readback` names a directory) before it is wiped rather than never. + +**Exit condition**: `toyos-metal` reads and saves the stick's existing log +partition before `flash` wipes and overwrites it, so a run that hangs leaves a +partition the very next invocation captures instead of destroys. diff --git a/issues/isolation/a-reboot-quiesces-xhci-and-leaves-a-claimed-i219-armed.md b/issues/isolation/a-reboot-quiesces-xhci-and-leaves-a-claimed-i219-armed.md new file mode 100644 index 0000000000..460e1e9c9f --- /dev/null +++ b/issues/isolation/a-reboot-quiesces-xhci-and-leaves-a-claimed-i219-armed.md @@ -0,0 +1,55 @@ +--- +status: open +kind: defect +opened: 2026-09-14 +--- + +# A reboot quiesces xHCI and nothing else; a device whose holder never exits keeps bus mastering across it + +Every reset this kernel performs goes through `acpi::reboot` +(`kernel/src/drivers/acpi.rs:283`) or `acpi::shutdown` (`:325`), and both call +`stop::before_reset()` (`:313`, `:331`) before touching a register — that +`stop` is `kernel/src/drivers/xhci/stop::before_reset`, one device class. +Nothing else in the reset path — `kernel/src/arch/syscall/machine.rs`'s +`quiesce` (`:47`), which `sys_reboot` (`:113`) and `sys_shutdown` calls before +`acpi::reboot()` (`:122`) / `acpi::shutdown()` (`:108`) — tears down any other +device a process still holds. + +**A PCI function's own teardown exists, and it is reached from exactly one +place.** `pcidev::release` (`kernel/src/pcidev/mod.rs:782`) calls +`tear_down` (`:796`), which disables bus mastering (`:797`), masks the +function's MSI/MSI-X entry (`:798`), drops its IOMMU domain +(`:799`, `note_user_owned(…, None)`), and only then resets the function +(`:809`). The one caller of `pcidev::release` in the whole kernel +(`rg -n pcidev::release kernel/src/`, one hit) is `kernel/src/device.rs:75`, +inside `Claim`'s `Drop` — reached when a process's PCI-function handle is +dropped, which for an ordinary claim is when the holding process's handle +table is torn down, i.e. when it exits. + +**So on any boot where the claiming process never exits, a reboot or shutdown +leaves that function exactly as it was.** `netd` holds the I219's claim for +the whole life of a `lancase`-family boot and does not exit on `SYS_REBOOT` — +nothing in `quiesce` asks it to — so the syscall that resets the machine never +runs `Claim`'s `Drop` for that slot, `pcidev::release` is never called, and the +I219 warm-resets with bus mastering on, its MSI still enabled, both rings still +programmed and `IMS` still set from whatever `toyos-i219`'s `open` last wrote. + +## What this costs + +A machine that resets with an armed, bus-mastering NIC still holding queue +addresses from the boot that just ended hands the next boot (Ubuntu, on the +bench) a device in a state its own driver did not put it in. Distinguishing +"the kernel never got far enough to come back" from "the kernel came back but +the wire the harness polls did not" is exactly the ambiguity this leaves at +the bench: a probe that only checks whether the machine answers `ssh` again +cannot tell the two apart, and nothing tears the NIC down to make them +distinguishable. + +## What would answer it + +Either `quiesce` tears down every device claim before the reset it precedes — +which is the general form `issues/kernel/quiesce-runs-while-userland-still-does-io.md` +already asks for, for a different reason (in-flight I/O rather than device +state) — or the reset path calls each claimed function's own `tear_down` +directly, the way it already does for xHCI through `stop::before_reset`, +instead of relying on a `Drop` a live process is never asked to run. diff --git a/issues/kernel/eiac-and-ivar-are-msi-x-registers-on-an-msi-only-i219.md b/issues/kernel/eiac-and-ivar-are-msi-x-registers-on-an-msi-only-i219.md new file mode 100644 index 0000000000..a6884ca016 --- /dev/null +++ b/issues/kernel/eiac-and-ivar-are-msi-x-registers-on-an-msi-only-i219.md @@ -0,0 +1,56 @@ +--- +status: open +kind: finding +opened: 2026-09-14 +--- + +# `toyos-i219` cites the 82574 throughout, and writes two MSI-X-only registers to a part measured to be MSI + +`toyos-i219/src/regs.rs:1-8` states the file's whole citation policy: "Every +offset and every bit below is cited to the *Intel 82574 GbE Controller Family +Datasheet* … Nothing here has behaviour, and a number that is not in the +datasheet does not belong in this file." `toyos-i219/src/lib.rs:4-9` says why: +the driver runs against the T14's `8086:15fc` I219, whose register file is +taken to be the 82574's — "the datasheet this file cites throughout is the +82574's rather than the I219's own, which describes the part and not the +register set." + +Two of those cited registers are conditional on a mode the datasheet names by +name. `regs::EIAC` (`0x000DC`, `regs.rs:27`) and `regs::IVAR` (`0x000E4`, +`regs.rs:30`, doc: "Interrupt Vector Allocation (§10.2.4.9, `0x000E4`), which +'is only valid in MSI-X mode'") are both written unconditionally in `open` +(`lib.rs:399`): `EIAC = 0` at `lib.rs:477`, then `IVAR` written and read back +at `lib.rs:502-503`, with `accepted()` (`lib.rs:542`) refusing +`Refusal::NotAccepted` if the readback does not carry the bits written. Any +`Err` out of `open` reaches `userland/netd/src/main.rs`'s `Card::intel` +(`:87-91`), which turns it into a panic: `Card::undrivable` at `:83-84`. + +**The T14's `00:1f.6` has been measured to be an MSI part, not MSI-X.** That +measurement is not yet in this tree's copy of +`issues/hardware/the-t14-answers-only-through-a-usb-stick.md` — it was made and +recorded on a sibling, unmerged branch (`git show 0a5717f5:issues/hardware/the-t14-answers-only-through-a-usb-stick.md`): +"`/proc/interrupts` names its interrupt `IR-PCI-MSI-0000:00:1f.6` and +`msi_irqs/162` reads `mode=msi`." Read together with `regs.rs`'s own citation, +`IVAR` is a register this driver writes and requires a readback from on a part +the datasheet's own §10.2.4.9 says the register is not defined for outside +MSI-X mode. + +**And the write has been observed to go through anyway.** On that same branch, +bench runs 42 and 51 (`lancase`/`lancase-placement`, `t14-run42`, `t14-run51`) +carry no `exit: netd` record at all — and a `Refusal` out of `open` panics +`netd` by name, so its absence means `accepted(regs::IVAR, …)` returned `Ok` +there: the T14 took the write and echoed the bits back, on a register its own +family's datasheet does not define for the mode the function is in. That the +readback matched is not evidence the register does what §10.2.4.9 documents; +it is evidence only that *some* word landed where the driver looked for it. + +## What would answer it + +Whether `0x000DC` and `0x000E4` do anything defined on an I219 outside MSI-X +mode is not in the 82574 datasheet this file cites, and the I219's own +datasheet — which `lib.rs:8` already says this driver does not use — is the +document that would say. Until that is read, this file's own citation policy +("a number that is not in the datasheet does not belong in this file") is +already violated by two rows whose behaviour outside MSI-X mode is +undocumented by the datasheet named, and the readback guard the driver relies +on to catch a wrong register file has been measured not to catch this one. diff --git a/issues/panic-path/no-watchdog-outlives-exitbootservices-and-a-hang-seals-nothing.md b/issues/panic-path/no-watchdog-outlives-exitbootservices-and-a-hang-seals-nothing.md new file mode 100644 index 0000000000..f1771e9939 --- /dev/null +++ b/issues/panic-path/no-watchdog-outlives-exitbootservices-and-a-hang-seals-nothing.md @@ -0,0 +1,71 @@ +--- +status: open +kind: defect +opened: 2026-09-14 +--- + +# Past `ExitBootServices` nothing times a hang but the FADT reset register, and `halt_all_cpus` disarms the one thing that would say so + +**The firmware watchdog does not survive the handoff.** `bootloader/src/main.rs` +arms `set_watchdog_timer` before anything else (`:798-799`) and says why at +`:864`: *"Firmware watchdog: `{FIRMWARE_WATCHDOG_SECS}` s, until +`ExitBootServices` disables it"* — that timer only guards a loader that never +calls `ExitBootServices`. Once the kernel is running, the only bounds left are +the ones it arms itself — the boot-progress deadline `deadline::stand_down` +disarms and the per-CPU hard-lockup NMI `hardlockup::stand_down` disarms +(`kernel/src/deadline.rs`, `kernel/src/hardlockup/mod.rs`) — and optionally the +chipset's own TCO watchdog if a boot's command line arms it +(`bootloader/src/watchdog.rs`) — which `issues/hardware/an-armed-tco-has-never-reset-the-t14.md` +records as never having reset this machine at any bound reached so far. + +**And a fatal kernel event disarms both of the kernel's own bounds before it +holds the panel.** `apic::halt_all_cpus` (`kernel/src/arch/apic.rs:228`) opens +with `crate::hardlockup::stand_down()` and `crate::deadline::stand_down()` +(`:235-236`), then arms one conditional bound — +`crate::panic_reboot::arm(true)` (`:244`) — and hands off to +`panic_console::page_forever` (`:262`), which for every "cannot paint" +branch and for a successful paint alike ends in `hold_the_panel` +(`kernel/src/drivers/panic_console/mod.rs:610-620,647`): `while +bound.is_armed()` (`:649`), which never exits on its own. + +`panic_reboot::arm` (`kernel/src/panic_reboot.rs:110`) returns `Bound::At` +(`:132`) only where both a clock is available *and* `acpi::can_reboot()` holds +— `RESET_PORT != 0` (`kernel/src/drivers/acpi.rs:277-278`), the FADT's reset +register and nothing else, no fallback by design — and `Bound::Held` +otherwise: once for no reset register (`:144`) and once for no usable clock +(`:155`). Either is the branch `hold_the_panel` spins on forever. A keypress +also retires the bound (the panel is designed for a machine with someone in +front of it), which is exactly wrong for an unattended bench run. + +**The one channel that would say a hang happened is disarmed by the same +stand-down.** `seal_wedge` (`kernel/src/drivers/panic_console/mod.rs:597`) has +exactly two callers in the whole kernel — `kernel/src/deadline.rs:214` and +`kernel/src/hardlockup/mod.rs:319` — and both are the `stand_down` calls +`halt_all_cpus` makes before it ever reaches `hold_the_panel`. So a fatal event +that reaches `halt_all_cpus` writes its panic report to the panel and to +serial (where one exists), but never reaches the black-box path that a +`WEDGED` seal would leave for the *next* boot's loader to print — and on a +machine that never resets, there is no next boot to print it to anyway. + +## What this means on the T14 + +`RESET_PORT` is whatever the FADT named — unverified as arming on this +machine independent of the TCO question — and the TCO path is separately +recorded as never having fired. So a kernel panic on the T14 disarms the two +bounds that could have ended the boot, arms a third whose one working +precondition is unproven on this hardware, and forecloses the one record that +would have said which of the two outcomes happened. The observable result — +silence past whatever deadline the harness gives it, with neither the panel +nor the log partition readable afterward — is indistinguishable at the bench +from a machine that simply never got that far. This has not yet been read off +a boot: `issues/build/a-hung-boots-log-partition-is-wiped-by-the-next-runs-flash.md` +is why no hung boot's own `/log` or panel state has been captured yet. + +## What would answer it + +Either the panel hold gets a bound that does not rest on the FADT register (so +an unattended machine ends the boot on its own within a stated time), or a boot +that reaches `halt_all_cpus` on a machine that cannot reset says so somewhere +that survives to the next boot regardless of whether the panel is ever +retired. Until one of those lands, a fatal kernel event past `ExitBootServices` +on this machine is timed by nothing this tree has verified to fire. From 065dcc80698bfdd999b969f06105d29315e1d54a Mon Sep 17 00:00:00 2001 From: japabu Date: Mon, 14 Sep 2026 23:42:33 +0200 Subject: [PATCH 2/4] Fold a refuted panic-path finding; file the deadline overrun it obscured MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit `issues/panic-path/no-watchdog-outlives-exitbootservices-and-a-hang-seals-nothing.md` claimed the T14 has no bound past `ExitBootServices` that this tree has verified to fire. Measurement refutes it: the FADT reset register at 0xCF9 (`kernel/src/drivers/acpi.rs:282`), the 120 s boot deadline, and the 60 s hard-lockup NMI and panic-reboot bounds (`toyos_tco::PANIC_BOUND_MS`, `toyos-tco/src/lib.rs:122`) all exist, and in run 55/56 the deadline fired, the reset path ran, the black box sealed, and the next loader pass printed it — `t14-run56/lancase-repeat.log` line 26, "Black box: the record below is from the boot armed at 2026-09-14-205457", is that print. No citation of the file remained anywhere in the tree, so nothing else needs to move. That same black box is itself new evidence, and it says something the deleted file did not: the deadline fired 132859 ms past the 120000 ms bound it was armed with, while cpu0 spent the run's first several seconds deep in the xHCI mass-storage recovery loop (`lancase-repeat.log` line 28's "reached at 252859 ms", and lines 210-211's `Stopped, recovering` / `Set TR Dequeue timed out` two seconds apart). Filed as `issues/kernel/a-boot-deadline-of-120000-ms-fired-132859-ms-late-behind-an-xhci-storm-on-cpu0.md`. Co-Authored-By: Claude Sonnet 5 Claude-Session: https://claude.ai/code/session_014iqcj4jDKpaiDX8B7CMvmK --- ...59-ms-late-behind-an-xhci-storm-on-cpu0.md | 43 +++++++++++ ...itbootservices-and-a-hang-seals-nothing.md | 71 ------------------- 2 files changed, 43 insertions(+), 71 deletions(-) create mode 100644 issues/kernel/a-boot-deadline-of-120000-ms-fired-132859-ms-late-behind-an-xhci-storm-on-cpu0.md delete mode 100644 issues/panic-path/no-watchdog-outlives-exitbootservices-and-a-hang-seals-nothing.md diff --git a/issues/kernel/a-boot-deadline-of-120000-ms-fired-132859-ms-late-behind-an-xhci-storm-on-cpu0.md b/issues/kernel/a-boot-deadline-of-120000-ms-fired-132859-ms-late-behind-an-xhci-storm-on-cpu0.md new file mode 100644 index 0000000000..8756046613 --- /dev/null +++ b/issues/kernel/a-boot-deadline-of-120000-ms-fired-132859-ms-late-behind-an-xhci-storm-on-cpu0.md @@ -0,0 +1,43 @@ +--- +status: open +kind: defect +opened: 2026-09-14 +--- + +# A 120000 ms boot deadline fired 132859 ms late, with cpu0 deep in an xHCI recovery loop + +`kernel/src/deadline.rs:1-2` states the whole promise of this mechanism: "the +one bound on this machine that nothing running on it can hold off." `:11-13` +says how: armed off the parameter line and "polled from the timer interrupt +entry, on every CPU, in both rings" — "its whole requirement is that some CPU +still takes an interrupt." The bound itself is checked in `poll` +(`kernel/src/deadline.rs:194-199`): one relaxed load of `AT_TSC` and an +`rdtsc` compare, called from the timer entry. + +A T14 boot armed with `boot-deadline=120000` measured otherwise. The black +box `expire` seals read: + + the boot deadline expired: a bound of 120000 ms, reached at 252859 ms, with this machine in `complete`. + +252859 ms is 132859 ms past the 120000 ms bound the image was armed with — +over two minutes late, not the one tick a poll running on every CPU's timer +entry should cost. The same ring tail's own `irq:` census reads: + + irq: cpu0 total=1741 timer=9 xhci=1729 userdev=0 sound=0 i8042=0 dmafault=0 hda=0 tlb=0 nmi=3 spurious=0 unclaimed=0 + +nine timer ticks against 1729 xHCI interrupts on cpu0. In the same window the +ring tail carries the mass-storage recovery loop that produced them, ending in: + + [3.556 cpu0] xHCI: 00:14.0 slot 5 endpoint 3 is Stopped, recovering + [5.556 cpu0] xHCI: Set TR Dequeue timed out + +a two-second wait between the stop and the timeout that follows it, on the +same CPU whose timer count the census names as nine. + +## What would answer it + +A test that arms the deadline, drives one CPU into the same shape — many +interrupts serviced, few timer ticks taken — and asserts the machine still +reaches `expire` within one timer tick of the armed bound regardless of what +that CPU is doing, rather than however much later some other path happens to +notice. diff --git a/issues/panic-path/no-watchdog-outlives-exitbootservices-and-a-hang-seals-nothing.md b/issues/panic-path/no-watchdog-outlives-exitbootservices-and-a-hang-seals-nothing.md deleted file mode 100644 index f1771e9939..0000000000 --- a/issues/panic-path/no-watchdog-outlives-exitbootservices-and-a-hang-seals-nothing.md +++ /dev/null @@ -1,71 +0,0 @@ ---- -status: open -kind: defect -opened: 2026-09-14 ---- - -# Past `ExitBootServices` nothing times a hang but the FADT reset register, and `halt_all_cpus` disarms the one thing that would say so - -**The firmware watchdog does not survive the handoff.** `bootloader/src/main.rs` -arms `set_watchdog_timer` before anything else (`:798-799`) and says why at -`:864`: *"Firmware watchdog: `{FIRMWARE_WATCHDOG_SECS}` s, until -`ExitBootServices` disables it"* — that timer only guards a loader that never -calls `ExitBootServices`. Once the kernel is running, the only bounds left are -the ones it arms itself — the boot-progress deadline `deadline::stand_down` -disarms and the per-CPU hard-lockup NMI `hardlockup::stand_down` disarms -(`kernel/src/deadline.rs`, `kernel/src/hardlockup/mod.rs`) — and optionally the -chipset's own TCO watchdog if a boot's command line arms it -(`bootloader/src/watchdog.rs`) — which `issues/hardware/an-armed-tco-has-never-reset-the-t14.md` -records as never having reset this machine at any bound reached so far. - -**And a fatal kernel event disarms both of the kernel's own bounds before it -holds the panel.** `apic::halt_all_cpus` (`kernel/src/arch/apic.rs:228`) opens -with `crate::hardlockup::stand_down()` and `crate::deadline::stand_down()` -(`:235-236`), then arms one conditional bound — -`crate::panic_reboot::arm(true)` (`:244`) — and hands off to -`panic_console::page_forever` (`:262`), which for every "cannot paint" -branch and for a successful paint alike ends in `hold_the_panel` -(`kernel/src/drivers/panic_console/mod.rs:610-620,647`): `while -bound.is_armed()` (`:649`), which never exits on its own. - -`panic_reboot::arm` (`kernel/src/panic_reboot.rs:110`) returns `Bound::At` -(`:132`) only where both a clock is available *and* `acpi::can_reboot()` holds -— `RESET_PORT != 0` (`kernel/src/drivers/acpi.rs:277-278`), the FADT's reset -register and nothing else, no fallback by design — and `Bound::Held` -otherwise: once for no reset register (`:144`) and once for no usable clock -(`:155`). Either is the branch `hold_the_panel` spins on forever. A keypress -also retires the bound (the panel is designed for a machine with someone in -front of it), which is exactly wrong for an unattended bench run. - -**The one channel that would say a hang happened is disarmed by the same -stand-down.** `seal_wedge` (`kernel/src/drivers/panic_console/mod.rs:597`) has -exactly two callers in the whole kernel — `kernel/src/deadline.rs:214` and -`kernel/src/hardlockup/mod.rs:319` — and both are the `stand_down` calls -`halt_all_cpus` makes before it ever reaches `hold_the_panel`. So a fatal event -that reaches `halt_all_cpus` writes its panic report to the panel and to -serial (where one exists), but never reaches the black-box path that a -`WEDGED` seal would leave for the *next* boot's loader to print — and on a -machine that never resets, there is no next boot to print it to anyway. - -## What this means on the T14 - -`RESET_PORT` is whatever the FADT named — unverified as arming on this -machine independent of the TCO question — and the TCO path is separately -recorded as never having fired. So a kernel panic on the T14 disarms the two -bounds that could have ended the boot, arms a third whose one working -precondition is unproven on this hardware, and forecloses the one record that -would have said which of the two outcomes happened. The observable result — -silence past whatever deadline the harness gives it, with neither the panel -nor the log partition readable afterward — is indistinguishable at the bench -from a machine that simply never got that far. This has not yet been read off -a boot: `issues/build/a-hung-boots-log-partition-is-wiped-by-the-next-runs-flash.md` -is why no hung boot's own `/log` or panel state has been captured yet. - -## What would answer it - -Either the panel hold gets a bound that does not rest on the FADT register (so -an unattended machine ends the boot on its own within a stated time), or a boot -that reaches `halt_all_cpus` on a machine that cannot reset says so somewhere -that survives to the next boot regardless of whether the panel is ever -retired. Until one of those lands, a fatal kernel event past `ExitBootServices` -on this machine is timed by nothing this tree has verified to fire. From 2a8cb4e78af45fb366b5835eaf97a1f9e1a348d6 Mon Sep 17 00:00:00 2001 From: japabu Date: Wed, 16 Sep 2026 15:15:53 +0200 Subject: [PATCH 3/4] The cause leaves the deadline slug, the I219 finding takes its reading, and the reset graph is the tree's MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Round 2 of the review of this branch: every CODE finding upheld, and each answered in the file it was found in. `issues/build/a-hung-boots-log-partition-is-wiped-by-the-next-runs-flash.md` claimed no hung boot's partition had ever been read. Run 55's was: copied whole from `/dev/sda3` at 21:15:16Z, after its loop refused at 21:02:01Z and before run 56 flashed at 21:29:39Z. The copy held `loader.log` (the loader's first pass alone) and `attempts`, and no file logd wrote — that boot's ring tail carries `exit: logd pid=4 code=-1` at 3.471 s, so for the one hung partition ever captured the flash would have destroyed nothing logd wrote. The file now says what the tree shows: the loop's own sequence flashes (`src/metal.rs:1471`) before it reads (`:1489`, `:1496`), so a hung boot's partition survives only if something outside the loop read it first; and the loop cannot read a wedged stick at all — `read_log` and `raw_log` refuse (`:1131-1162`, `:1184-1190`) — so the remedy is a pre-flash save that records rather than refuses when the stick does not answer. Every citation is an exact line; the "-area" hedge is gone. The deadline issue is renamed to `issues/kernel/a-120000-ms-boot-deadline-fired-132859-ms-late-on-the-t14.md`. "Behind an xHCI storm on cpu0" was a cause the file's own census refutes: cpu4 took 215 timer interrupts in the 3.47 s in which cpu0 took 9, and `poll` runs on every CPU's timer entry. The census is quoted whole, both blocks. The hard-lockup bound armed off the same parameter at 60000 ms (`kernel/src/deadline.rs:182`, `toyos-tco/src/lib.rs:154-156`) was silent on the same boot, and the file says so. The instrument that measures this — `deadline_lateness_ms` (`src/metal.rs:1591`), priced at ceiling 10000 in `tests/metal-profile.toml:409-414` and judged in `tests/common/metal.rs:895-919` — is cited instead of a second one proposed: 132859 is 13x that ceiling on a boot (`lancase`) the profile does not name and this tree does not have. The record was run 55's boot's (armed 20:54:57Z, the unmerged `i219-delivery` at 4d604c86, whose deadline, hardlockup and acpi sources are byte-identical to this tree's), read by run 56's loader pass, which printed it and ended the chain without booting a kernel (`bootloader/src/main.rs:857-860`). Run 56 came back — to Ubuntu, after 100 s, having booted no kernel. `issues/kernel/a-job-list-hangs-with-interrupts-on-and-the-deadline-ends-it.md` is closed. Its exit condition was "a `loader.log` from a T14 boot that ran to its deadline, with the ring tail naming what the machine was doing when it stopped", and run 56's readback is that: the tail names the boot stick's READ(10) transport breaking at 3.47 s, logd and netd dying on faults over file bytes the device would not read, the test runner failing to load, and the disk going offline at 5.556 s, after which nothing was written until the expiry at 252.859 s. Its durable line — a deadline that fires is a machine on which some CPU took a timer interrupt — is already `deadline.rs:86-87`'s, so no header line is owed; what this record adds, that it can fire 133 s after the bound, is the successor's subject. Its one citation, in `issues/kernel/an-xhci-storm-starves-the-cpu-that-takes-it.md`, moves to the successor; no other pointer at the slug or the path exists in the tree. `issues/hardware/a-t14-boot-wedges-after-a-jobs-exit-and-nothing-said-why.md` waits for a record of a different shape and is not closed by this one; the successor cites it and says why. The tree-checkable defect the deadline file obscured is filed on its own: `issues/kernel/the-deadline-header-promises-any-interrupt-and-only-the-timer-entry-polls.md`. `deadline.rs:11-13` says "some CPU still takes an interrupt"; `poll`'s two call sites are the timer entry's (`kernel/src/arch/idt/timer.rs:71,96`) and `:185-186` says so; `hardlockup/mod.rs:4-5` repeats the wide claim. Filed, not fixed: this branch touches `issues/` only. `issues/kernel/eiac-and-ivar-are-msi-x-registers-on-an-msi-only-i219.md` is folded into `issues/kernel/a-claimed-function-must-have-msi-x-and-the-i219-may-not.md` and deleted: that finding already carried the claim, the §10.2.4.9 argument and an exit condition asking for exactly the mode reading the new file supplied. This is that finding's next review, so it is promoted to a defect and assigned to PR #442 (`lan-metal`), whose `pcidev` arms MSI where MSI-X is absent. The fold keeps IVAR only — nothing cited says EIAC is MSI-X-only — quotes `toyos-i219/src/lib.rs:496-503` whole, comment included, and says in so many words that the write is unreachable in this tree (`kernel/src/pcidev/mod.rs:544` refuses the function before `open` runs) and that runs 42 and 51, which armed MSI, were of unmerged branches (tips 4204e090 and 6276fc87, both carrying the same write and readback). The "citation policy violated" paragraph is dropped: both offsets are in the datasheet, and the policy is about the number. `issues/isolation/a-reboot-quiesces-xhci-and-leaves-a-claimed-i219-armed.md` is renamed to `issues/isolation/a-reset-stops-xhci-and-leaves-every-claimed-pci-function-armed.md` and rewritten around the call graph the tree has: `deadline::expire` (`deadline.rs:224`) and `hardlockup::locked_up` (`hardlockup/mod.rs:326`) call `acpi::reset_now` directly, and `panic_reboot::reboot_now` reaches `acpi::reboot` without `quiesce` — five paths, not two. The claim that the function's armed state survives the 0xCF9 write is stated as unmeasured, with what would measure it, and nothing rests on it. The general defect is this tree's today: `netd` holds a virtio-net function (`system.toml:70-72`) and nothing between `SYS_REBOOT` and the port write asks it to let go. The I219 is the instance the tree reaches when PR #442 lands — `lancase` is that branch's — and on run 55's boot the function had already been released by netd's death before the reset. Every number in the issue files is quoted from the bench transcripts into the file itself; the private paths those transcripts live under are cited nowhere. Every file:line was read in this worktree with `sed -n`. Co-Authored-By: Claude Fable 5.1 Claude-Session: https://claude.ai/code/session_014iqcj4jDKpaiDX8B7CMvmK --- ...rtition-is-wiped-by-the-next-runs-flash.md | 113 ++++++++----- ...es-xhci-and-leaves-a-claimed-i219-armed.md | 55 ------- ...leaves-every-claimed-pci-function-armed.md | 88 ++++++++++ ...eadline-fired-132859-ms-late-on-the-t14.md | 150 ++++++++++++++++++ ...59-ms-late-behind-an-xhci-storm-on-cpu0.md | 43 ----- ...on-must-have-msi-x-and-the-i219-may-not.md | 88 +++++++--- ...-interrupts-on-and-the-deadline-ends-it.md | 35 ---- ...hci-storm-starves-the-cpu-that-takes-it.md | 2 +- ...are-msi-x-registers-on-an-msi-only-i219.md | 56 ------- ...nterrupt-and-only-the-timer-entry-polls.md | 43 +++++ 10 files changed, 422 insertions(+), 251 deletions(-) delete mode 100644 issues/isolation/a-reboot-quiesces-xhci-and-leaves-a-claimed-i219-armed.md create mode 100644 issues/isolation/a-reset-stops-xhci-and-leaves-every-claimed-pci-function-armed.md create mode 100644 issues/kernel/a-120000-ms-boot-deadline-fired-132859-ms-late-on-the-t14.md delete mode 100644 issues/kernel/a-boot-deadline-of-120000-ms-fired-132859-ms-late-behind-an-xhci-storm-on-cpu0.md delete mode 100644 issues/kernel/a-job-list-hangs-with-interrupts-on-and-the-deadline-ends-it.md delete mode 100644 issues/kernel/eiac-and-ivar-are-msi-x-registers-on-an-msi-only-i219.md create mode 100644 issues/kernel/the-deadline-header-promises-any-interrupt-and-only-the-timer-entry-polls.md diff --git a/issues/build/a-hung-boots-log-partition-is-wiped-by-the-next-runs-flash.md b/issues/build/a-hung-boots-log-partition-is-wiped-by-the-next-runs-flash.md index e77f340c38..226fd2754a 100644 --- a/issues/build/a-hung-boots-log-partition-is-wiped-by-the-next-runs-flash.md +++ b/issues/build/a-hung-boots-log-partition-is-wiped-by-the-next-runs-flash.md @@ -1,48 +1,75 @@ --- status: open kind: tooling -opened: 2026-09-14 +opened: 2026-09-16 --- -# A hung boot's log partition is wiped by the next run's flash, before anyone reads it - -`src/metal.rs`'s `Driver::flash` (`:1000-1002`) opens every run with -`self.as_root("wiping the old signatures", Job::Wipe, …)` followed immediately -by `self.as_root("flashing the stick", Job::Flash, …)` — `wipefs --all` then -`dd` over the whole disk, unconditionally, before that run's own boot has -happened. `run` (`:1416`) calls `driver.flash(&image)` at `:1471`, and only -after the reboot does it read anything back: `ride_the_reboot` at `:1483`, -`wait_for_the_stick` at `:1487`, `read_log` at `:1489`. - -**So a run's own log is read only if that run comes back.** `wait_for_the_stick` -refuses `Refusal::Stick` (`:1107`) and the underlying `wait` refuses -`Refusal::Silent` (`:1121`) — both return before `read_log` (`:1489`) is ever -reached. A run that hangs writes nothing to disk that its own invocation goes -on to read, and the *next* invocation's `flash` destroys the partition before -anything else touches it. - -## What this cost - -Runs 36, 52, 54 and 55 (`lancase`-family, `t14-run*/` logs) hung past their -420 s deadline (`Refusal::Silent`); run 49 wedged the stick instead -(`Refusal::Stick`, back at 303 s). All five never reached `read_log`, and every -one of the five was followed by another run whose own `flash` — `wipefs` then -`dd` — overwrote the partition before it was ever read from outside the loop. -**No hung boot's own `/log` has ever been read.** That is the single largest -recoverable gap in diagnosing why the T14 does not come back: the record a -`logd` batch would have committed up to the instant of the hang (durability is -per-batch `fsync`, `userland/logd/src/main.rs:58`) is destroyed by the loop's -own next step rather than by anything the hang did. - -## What would answer it - -`read_log` already exists and already tolerates the stick being unreachable -(it is called after `wait_for_the_stick`). What is missing is a call to it — or -to the raw-sector read `raw_log` already takes for `--fat32-check` -(`run`, `:1489`-area) — **before** `flash`'s `wipefs`/`dd` at the *start* of the -next run, so the previous run's partition is read (and saved, where -`--readback` names a directory) before it is wiped rather than never. - -**Exit condition**: `toyos-metal` reads and saves the stick's existing log -partition before `flash` wipes and overwrites it, so a run that hangs leaves a -partition the very next invocation captures instead of destroys. +# A hung boot's log partition is wiped by the next run's flash, and survives only if something outside the loop read it first + +`src/metal.rs`'s `run` (`:1416`) is one sequence: `driver.flash(&image)` at +`:1471`, the reboot at `:1475`, `ride_the_reboot` at `:1483`, +`wait_for_the_stick` at `:1487`, `read_log` at `:1489` and, under +`--fat32-check`, `raw_log` at `:1496`. `flash` (`:1000-1002`) is `wipefs --all` +and then `dd` over the whole disk (`Job::Wipe` and `Job::Flash`, `:519-520`), +unconditionally, before anything in the same invocation reads a byte. So the +loop reads a partition only after its own boot came back, and a run whose boot +does not come back reaches neither read: `wait` returns `Refusal::Silent` at +`:1121` and `wait_for_the_stick` returns `Refusal::Stick` at `:1107`, both +before `:1489`. The next invocation opens with `flash` again. The previous +boot's partition therefore survives to be read exactly when something outside +the loop reads it between the two invocations — and nothing in the loop does. + +**And the loop cannot read a wedged stick at all.** `read_log` `?`s on the +`mkdir` and the mount (`:1131-1132`) and `read_mounted` on the listing and +every `cat` (`:1152-1162`); `raw_log` (`:1173`) refuses a short read by name +(`Refusal::Landed`, `:1184-1190`). Both are reached only after +`wait_for_the_stick` has seen the block node for up to `STICK_SECS` (`:68`, +30 s) — which is not tolerance of an unreachable stick but the reason neither +is asked to tolerate one. A pre-flash call to either, as written, would refuse +every run whose predecessor left the stick unenumerable (run 49's mode, below) +instead of recording that it did. + +## What was and was not lost + +Five `lancase`-family boots on the bench did not come back: runs 36, 52, 54 +and 55 past the loop's 420 s bound (`Refusal::Silent`), and run 49 with the +stick unenumerable (`Refusal::Stick`, back at 303 s). `lancase` is PR #442's +boot (branch `lan-metal`) and exists on no branch that has merged; every one +of these runs was of an unmerged branch's binaries, and the loop's sequence +above is the same in this tree. + +Run 55's partition is the one that was read. Its loop's transcript ends at +21:02:01Z with + + toyos-metal: the machine did not come back within 420 s, which is longer than every watchdog a boot runs under plus the time coming back costs; why it did not is what the panel and the log partition say, and neither is readable from here + +and run 56's transcript opens, at 21:29:39Z, with + + run56 = repeat of run 55 (i219del lancase, unarmed, head 4d604c86); owner photographs the screen at hang; previous partition saved at […]/t14-run55/run55-sda3.img + +— a copy of `/dev/sda3` taken from outside the loop at 21:15Z, 35651584 bytes, +which is the log partition's 69632 sectors (`log p3 at 151552+69632`, the +loop's own line about the image) whole. Run 56's `flash` then overwrote it. +The copy held two files, `loader.log` and `attempts`, and no file `logd` +wrote. Its `loader.log` is the loader's first pass alone, 105 lines ending in +`Loader log: the kernel handoff begins, so this file ends here`, and its line +20 reads + + Black box: 0x8000000 armed at 2026-09-14-205457 for [7a, cb, db, a9, 04, 52, 10, 4a, b2, ac, 8c, 55, b4, 43, b5, 90], and the kernel is told so on its parameter line + +— the boot whose `WEDGED` record run 56's loader pass then printed +(`issues/kernel/a-120000-ms-boot-deadline-fired-132859-ms-late-on-the-t14.md`). +So for the one hung boot whose partition was captured, the flash would have +destroyed nothing `logd` wrote, because `logd` wrote nothing: that boot's ring +tail carries `exit: logd pid=4 code=-1 cpu=2143ms` at 3.471 s. What the other +four partitions held is unknown, and the sequence above is why. + +`clear_readback` (`:1646`), called at `:1438-1440` before the flash, removes +the previous run's readback files for the opposite reason — so a refusal does +not leave them for a judge to read as this run's — and copies nothing. + +**Exit condition**: before `flash`, the loop saves the stick's existing log +partition where the stick answers, and where it does not — the block node +absent, the read short — records that in the run's own output rather than +refusing; a run that hangs then leaves a partition the next invocation +captures, and a run that wedges the stick leaves a line saying so. diff --git a/issues/isolation/a-reboot-quiesces-xhci-and-leaves-a-claimed-i219-armed.md b/issues/isolation/a-reboot-quiesces-xhci-and-leaves-a-claimed-i219-armed.md deleted file mode 100644 index 460e1e9c9f..0000000000 --- a/issues/isolation/a-reboot-quiesces-xhci-and-leaves-a-claimed-i219-armed.md +++ /dev/null @@ -1,55 +0,0 @@ ---- -status: open -kind: defect -opened: 2026-09-14 ---- - -# A reboot quiesces xHCI and nothing else; a device whose holder never exits keeps bus mastering across it - -Every reset this kernel performs goes through `acpi::reboot` -(`kernel/src/drivers/acpi.rs:283`) or `acpi::shutdown` (`:325`), and both call -`stop::before_reset()` (`:313`, `:331`) before touching a register — that -`stop` is `kernel/src/drivers/xhci/stop::before_reset`, one device class. -Nothing else in the reset path — `kernel/src/arch/syscall/machine.rs`'s -`quiesce` (`:47`), which `sys_reboot` (`:113`) and `sys_shutdown` calls before -`acpi::reboot()` (`:122`) / `acpi::shutdown()` (`:108`) — tears down any other -device a process still holds. - -**A PCI function's own teardown exists, and it is reached from exactly one -place.** `pcidev::release` (`kernel/src/pcidev/mod.rs:782`) calls -`tear_down` (`:796`), which disables bus mastering (`:797`), masks the -function's MSI/MSI-X entry (`:798`), drops its IOMMU domain -(`:799`, `note_user_owned(…, None)`), and only then resets the function -(`:809`). The one caller of `pcidev::release` in the whole kernel -(`rg -n pcidev::release kernel/src/`, one hit) is `kernel/src/device.rs:75`, -inside `Claim`'s `Drop` — reached when a process's PCI-function handle is -dropped, which for an ordinary claim is when the holding process's handle -table is torn down, i.e. when it exits. - -**So on any boot where the claiming process never exits, a reboot or shutdown -leaves that function exactly as it was.** `netd` holds the I219's claim for -the whole life of a `lancase`-family boot and does not exit on `SYS_REBOOT` — -nothing in `quiesce` asks it to — so the syscall that resets the machine never -runs `Claim`'s `Drop` for that slot, `pcidev::release` is never called, and the -I219 warm-resets with bus mastering on, its MSI still enabled, both rings still -programmed and `IMS` still set from whatever `toyos-i219`'s `open` last wrote. - -## What this costs - -A machine that resets with an armed, bus-mastering NIC still holding queue -addresses from the boot that just ended hands the next boot (Ubuntu, on the -bench) a device in a state its own driver did not put it in. Distinguishing -"the kernel never got far enough to come back" from "the kernel came back but -the wire the harness polls did not" is exactly the ambiguity this leaves at -the bench: a probe that only checks whether the machine answers `ssh` again -cannot tell the two apart, and nothing tears the NIC down to make them -distinguishable. - -## What would answer it - -Either `quiesce` tears down every device claim before the reset it precedes — -which is the general form `issues/kernel/quiesce-runs-while-userland-still-does-io.md` -already asks for, for a different reason (in-flight I/O rather than device -state) — or the reset path calls each claimed function's own `tear_down` -directly, the way it already does for xHCI through `stop::before_reset`, -instead of relying on a `Drop` a live process is never asked to run. diff --git a/issues/isolation/a-reset-stops-xhci-and-leaves-every-claimed-pci-function-armed.md b/issues/isolation/a-reset-stops-xhci-and-leaves-every-claimed-pci-function-armed.md new file mode 100644 index 0000000000..f84fc4332c --- /dev/null +++ b/issues/isolation/a-reset-stops-xhci-and-leaves-every-claimed-pci-function-armed.md @@ -0,0 +1,88 @@ +--- +status: open +kind: defect +opened: 2026-09-16 +--- + +# A reset stops xHCI and nothing else: a claimed PCI function whose holder never exits is left armed when the register is written + +**The reset paths, as the tree has them.** `kernel/src/drivers/acpi.rs:12-14`: +"[`reset_now`] and [`shutdown`] are the only two places this kernel writes a +register that ends the machine, and each stops every xHCI controller +([`stop::before_reset`]) before it does". Five paths reach those two: + +- `sys_reboot` (`kernel/src/arch/syscall/machine.rs:113`) → `quiesce` (`:121`) + → `acpi::reboot` (`:122`; `acpi.rs:283`) → `reset_now` (`acpi.rs:290`); +- `sys_shutdown` (`machine.rs:103`) → `quiesce` (`:107`) → `acpi::shutdown` + (`:108`; `acpi.rs:325`); +- `deadline::expire` (`kernel/src/deadline.rs:208`) → `acpi::reset_now` + (`:224`), no `quiesce`; +- `hardlockup::locked_up` (`kernel/src/hardlockup/mod.rs:313`) → + `acpi::reset_now` (`:326`), no `quiesce`; +- `panic_reboot::reboot_now` (`kernel/src/panic_reboot.rs:162`) → + `acpi::reboot` (`:167`) → `reset_now`, no `quiesce`. + +`reset_now` calls `stop::before_reset` (`acpi.rs:313`) and then writes the +port (`:319`); `shutdown` calls it at `:331`. That stop is +`kernel/src/drivers/xhci/stop.rs`'s: one device class. `quiesce` +(`machine.rs:47-100`) disarms the watchdog, syncs, flushes the USB disks' +caches, waits for the log to be durable, seals `DONE` and calls +`xhci::seal_shut`; it kills no process and takes no device from one. + +**A PCI function's own teardown exists, and it is reached from one place.** +`pcidev::release` (`kernel/src/pcidev/mod.rs:782`) calls `tear_down` (`:796`), +which disables bus mastering (`:797`), masks the function's MSI-X entry +(`:798`), empties its IOMMU domain (`:799`) and only then resets the function +(`:809`). The one caller of `pcidev::release` in the kernel +(`rg -n 'pcidev::release' kernel/src`, one hit) is `kernel/src/device.rs:75`, +inside `Claim`'s `Drop` — a dying process's handle table. + +**So on every one of the five paths, a function whose holder is alive is left +as its holder last wrote it when the register is written.** No process is +asked to exit on any of them, so no `Claim` drops, `release` is not called, +and the function's bus-master enable, its MSI-X vector and both rings' base +addresses are whatever the driver programmed — the device may be mid-DMA into +the holder's memory at the write. This tree is in that state on every boot +that runs `netd` and then `reboot`: `system.toml` starts `netd` (`:24`) with +`devices = ["pci:1af4:1041"]` (`:70-72`), a virtio-net function it holds for +its life, and nothing between `/system/bin/reboot`'s `SYS_REBOOT` and the port +write asks it to let go. + +**The I219 is the instance this file was found on, and this tree does not +reach it.** `pcidev/mod.rs:544` refuses a function without MSI-X, and the +T14's `00:1f.6` has none +(`issues/kernel/a-claimed-function-must-have-msi-x-and-the-i219-may-not.md`); +the boot that puts `netd` in front of it, `tests/lancase`, is defined on +PR #442's branch `lan-metal` and on no branch that has merged. The bench boots +this was read on were of those branches. The one that motivated it — run 55's, +ended by `deadline::expire` → `reset_now` — is a path `quiesce` never runs on, +and on that boot the function had already been released: the sealed tail +reads `exit: netd pid=5 code=-1 cpu=22ms` and then +`pcidev: PCI 00:1f.6 [8086:15fc] released from slot 0` at 3.479 s +(`issues/kernel/a-120000-ms-boot-deadline-fired-132859-ms-late-on-the-t14.md`). +So the I219 went into that reset torn down — by the `Drop` a dying process +reaches and a live one does not. + +**What the write does to the function is unmeasured.** The T14's register is +`0xCF9`: the kernel prints `ACPI: reset register SystemIO 0xcf9 <- 0x06` on +every boot there (`acpi.rs:271`; run 42's and run 51's kernel logs, at +0.000 s). Whether a full reset through that port clears a function's COMMAND +bus-master bit and MSI enable, or leaves them for the next operating system's +driver to find, is a platform question this tree has not asked, and nothing +here claims the next boot sees an armed device. What would measure it: a +ToyOS boot chained straight after a `sys_reboot` on which `netd` held the +function — the loop setting `BootNext` again — whose PCI enumeration prints +the function's COMMAND word and MSI control word before anything writes them, +beside the same print after a cold boot. + +## What would answer it + +Either `quiesce` tears down every live claim before the register — the +general stop of the machine +`issues/kernel/quiesce-runs-while-userland-still-does-io.md` asks for, for a +different reason (in-flight I/O rather than device state) — or the reset path +does for each bound function what it already does for xHCI through +`stop::before_reset`: the register half of `tear_down`, bus mastering off and +the vector masked, written with no lock taken so the two bound-driven paths +can call it too, instead of relying on a `Drop` a live process is never asked +to run. diff --git a/issues/kernel/a-120000-ms-boot-deadline-fired-132859-ms-late-on-the-t14.md b/issues/kernel/a-120000-ms-boot-deadline-fired-132859-ms-late-on-the-t14.md new file mode 100644 index 0000000000..aeb6b9babb --- /dev/null +++ b/issues/kernel/a-120000-ms-boot-deadline-fired-132859-ms-late-on-the-t14.md @@ -0,0 +1,150 @@ +--- +status: open +kind: defect +opened: 2026-09-16 +--- + +# A 120000 ms boot deadline fired 132859 ms late on the T14, and the hard-lockup bound armed beside it was silent too + +`kernel/src/deadline.rs` reads the bound off the parameter line (`claim`, +`:150-162`), turns it into a TSC deadline once there is a clock (`start`, +`:168-183`), and `poll` (`:194-200`) compares one relaxed load of `AT_TSC` +against `rdtsc` from the timer interrupt entry — `kernel/src/arch/idt/timer.rs:71` +(`:79`) in Ring 0 and `:96` in Ring 3 — and calls `expire` (`:208-225`), which +seals the record and writes the reset register through `acpi::reset_now`. +`start` arms the other half of the same parameter at `:182`, +`crate::hardlockup::start(ms)`: a bound of `toyos_tco::hard_lockup_bound_ms`, +`deadline_ms / 2` (`toyos-tco/src/lib.rs:154-156`), sampled by an NMI every +second on every CPU (`kernel/src/hardlockup/mod.rs:1-31`). The two share one +seal (`claim_the_reset`, `deadline.rs:69-71`). + +A boot armed with `boot-deadline=120000` prints both arms at 0.060 s — quoted +from bench run 42's kernel log, the text `deadline.rs:174-177` and +`hardlockup/mod.rs:193-198` write: + + boot deadline: 120000 ms, after which this kernel seals a WEDGED record and writes the reset register itself + hard lockup: 60000 ms, sampled every 1000 ms by each cpu's own performance counter, after which a cpu that has taken no interrupt seals a WEDGED record and resets the machine + +Run 55's boot — armed at 2026-09-14 20:54:57Z, the `lancase` image of the +unmerged branch `i219-delivery` at `4d604c86`, whose `kernel/src/deadline.rs`, +`kernel/src/hardlockup/mod.rs` and `kernel/src/drivers/acpi.rs` are +byte-identical to this tree's (`git diff --stat 4d604c86 HEAD -- ` is +empty) — did not come back inside the loop's 420 s, and its own kernel log +never reached the stick, so its print of the two lines is inferred from +`start` and not read. Its `WEDGED` record was read by run 56's loader pass: +a pass that printed the record and ended the chain without booting a kernel +(`bootloader/src/blackbox.rs:149-154`, `bootloader/src/main.rs:857-860`), so +that the machine came back to Ubuntu after 100 s and the loop read the +stick's `loader.log`, which reads, whole above the ring tail: + + --- the pass after the reset, reading what the boot above left + ToyOS Bootloader 1.0 + Boot attempts: this image has had the machine 0 time(s) without reporting; now 0 + Black box: the record below is from the boot armed at 2026-09-14-205457 + Previous boot's panic: the last boot read WEDGED, so a bound of its own ended it and this chain ends here + | the boot deadline expired: a bound of 120000 ms, reached at 252859 ms, with this machine in `complete`. The tail of the log ring follows ... which is what nothing was draining. + | older records dropped to fit this page: 227 + +252859 − 120000 = 132859 ms: `poll` first ran past its bound 132.859 s after +it. In the same boot the 60000 ms hard-lockup bound sealed nothing — the seal +is the deadline's — and that detector seals only for a CPU whose interrupt +count is stale for its bound *and* whose sampled frame has `IF` clear +(`hardlockup/mod.rs:21-31`). So for 133 s past the bound no CPU's timer entry +ran `poll`, and no CPU met both of the detector's conditions for 60 s, or none +was sampled; which of those is unmeasured. + +## The sealed tail, whole where it bears on this + +The tail's `irq:` census, every line as sealed — printed twice, by two dying +processes' fault reports 8 ms apart: + + | [3.471 cpu4] irq: cpu0 total=1741 timer=9 xhci=1729 userdev=0 sound=0 i8042=0 dmafault=0 hda=0 tlb=0 nmi=3 spurious=0 unclaimed=0 + | [3.471 cpu4] irq: cpu1 total=32 timer=30 xhci=0 userdev=0 sound=0 i8042=0 dmafault=0 hda=0 tlb=2 nmi=0 spurious=0 unclaimed=0 + | [3.471 cpu4] irq: cpu2 total=2 timer=0 xhci=0 userdev=0 sound=0 i8042=0 dmafault=0 hda=0 tlb=2 nmi=0 spurious=0 unclaimed=0 + | [3.471 cpu4] irq: cpu3 total=3 timer=1 xhci=0 userdev=0 sound=0 i8042=0 dmafault=0 hda=0 tlb=2 nmi=0 spurious=0 unclaimed=0 + | [3.471 cpu4] irq: cpu4 total=219 timer=215 xhci=0 userdev=0 sound=0 i8042=0 dmafault=0 hda=0 tlb=2 nmi=2 spurious=0 unclaimed=0 + | [3.471 cpu4] irq: cpu5 total=4 timer=2 xhci=0 userdev=0 sound=0 i8042=0 dmafault=0 hda=0 tlb=2 nmi=0 spurious=0 unclaimed=0 + | [3.471 cpu4] irq: cpu6 total=2 timer=0 xhci=0 userdev=0 sound=0 i8042=0 dmafault=0 hda=0 tlb=2 nmi=0 spurious=0 unclaimed=0 + | [3.471 cpu4] irq: cpu7 total=2 timer=0 xhci=0 userdev=0 sound=0 i8042=0 dmafault=0 hda=0 tlb=2 nmi=0 spurious=0 unclaimed=0 + | [3.479 cpu5] irq: cpu0 total=1741 timer=9 xhci=1729 userdev=0 sound=0 i8042=0 dmafault=0 hda=0 tlb=0 nmi=3 spurious=0 unclaimed=0 + | [3.479 cpu5] irq: cpu1 total=50 timer=48 xhci=0 userdev=0 sound=0 i8042=0 dmafault=0 hda=0 tlb=2 nmi=0 spurious=0 unclaimed=0 + | [3.479 cpu5] irq: cpu2 total=2 timer=0 xhci=0 userdev=0 sound=0 i8042=0 dmafault=0 hda=0 tlb=2 nmi=0 spurious=0 unclaimed=0 + | [3.479 cpu5] irq: cpu3 total=3 timer=1 xhci=0 userdev=0 sound=0 i8042=0 dmafault=0 hda=0 tlb=2 nmi=0 spurious=0 unclaimed=0 + | [3.479 cpu5] irq: cpu4 total=219 timer=215 xhci=0 userdev=0 sound=0 i8042=0 dmafault=0 hda=0 tlb=2 nmi=2 spurious=0 unclaimed=0 + | [3.479 cpu5] irq: cpu5 total=5 timer=3 xhci=0 userdev=0 sound=0 i8042=0 dmafault=0 hda=0 tlb=2 nmi=0 spurious=0 unclaimed=0 + | [3.479 cpu5] irq: cpu6 total=2 timer=0 xhci=0 userdev=0 sound=0 i8042=0 dmafault=0 hda=0 tlb=2 nmi=0 spurious=0 unclaimed=0 + | [3.479 cpu5] irq: cpu7 total=2 timer=0 xhci=0 userdev=0 sound=0 i8042=0 dmafault=0 hda=0 tlb=2 nmi=0 spurious=0 unclaimed=0 + +A snapshot at 3.471 s and 3.479 s, 249 s before the expiry. cpu0 had taken +nine timer interrupts against 1729 xHCI ones; cpu4 had taken 215 and cpu1 30 +in the same 3.47 s. So cpu0's state explains nothing about the bound: `poll` +runs on every CPU's timer entry, and two CPUs were taking theirs at a normal +cadence when the census was taken. What every CPU did between the tail's last +record and the expiry is unrecorded — the records run from 3.471 s to 5.556 s +and stop, and the machine wrote nothing for the next 247 s. + +What the tail names as the machine's state when the records stop: + + | [3.471 cpu4] exit: logd pid=4 code=-1 cpu=2143ms + | [3.479 cpu5] fault: 0x1000004e5c0 is backed by a file byte 0 that the device would not read; leaving the fault unhandled + | [3.479 cpu5] exit: netd pid=5 code=-1 cpu=22ms + | [3.479 cpu1] pcidev: PCI 00:1f.6 [8086:15fc] released from slot 0 + | [3.493 cpu0] spawn: /system/bin/test-runner: ELF: fewer bytes than a file header + | [3.556 cpu0] xHCI: 00:14.0 slot 5 endpoint 3 is Stopped, recovering + | [5.556 cpu0] xHCI: Set TR Dequeue timed out + | [5.556 cpu0] usb-storage: 00:14.0 slot 5 reset recovery failed; disk is offline + | [5.556 cpu0] root: read of block 3 failed + +Between those, cpu5 and then cpu0 repeat `usb-storage: 00:14.0 slot 5 +transport broke on SCSI 0x28` and `SCSI 0x28 broke 3 times running; the +transport is not coming back on its own`: the boot stick's READ(10) transport +broke at 3.47 s, the root filesystem stopped answering, `logd` and `netd` died +on page faults over file bytes the device would not read, the test runner +could not be loaded, and the disk went offline at 5.556 s. A boot with no +runner asks for no reboot; the deadline was the only bound left, and it fired +133 s late. + +## The instrument that measures this already exists + +`src/metal.rs:1591-1597`'s `deadline_lateness_ms` computes exactly +`reached − bound` out of the `DEADLINE_EXPIRED` line (`src/bootlog.rs:28`); +`tests/common/metal.rs:274-275` reads it off every readback and `:895-919` +hands it to `profile.judge` as `boot.