Four T14 bench issues filed, and three standing ones corrected by the same readback

issues/build/a-hung-boots-log-partition-is-wiped-by-the-next-runs-flash.md

@@ -0,0 +1,75 @@
+---
+status: open
+kind: tooling
+opened: 2026-09-16
+---
+
+# 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.

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.

issues/kernel/a-120000-ms-boot-deadline-fired-132859-ms-late-on-the-t14.md

@@ -0,0 +1,152 @@
+---
+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 -- <those>` 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.<label>.deadline_lateness_ms`;
+`tests/metal-profile.toml:409-414` prices that row for `deadlinewedge` —
+ceiling 10000 ms, "the widest true bound before [the timer period] has been"
+measured, `measured = 61`. 132859 is 13x that ceiling, on a boot the profile
+does not name: `lancase` is not among the labels the file prices, and is not
+in this tree. The arithmetic above is the instrument's own, done by hand
+because the run was `toyos-metal` invoked directly and not the harness. No
+second instrument is owed; a cause is.
+
+## What is known and what is not
+
+- `issues/kernel/an-xhci-storm-starves-the-cpu-that-takes-it.md` carries the
+  same shape, over the 34 s the stick was being written, on run 20's
+  `metaldevicecase` boot at tip `f46f91eb`
+  (`[2026-09-07 08:51:28 34.609 cpu1] irq: cpu0 total=103171 timer=10 xhci=103161 net=0 sound=0 i8042=0 dmafault=0 hda=0 tlb=0 nmi=0 spurious=0 unclaimed=0`)
+  and closes with the question this run does not answer: whether an xHCI
+  storm can by itself hold a CPU out of its timer for the whole of a bound.
+  Run 55's census shows cpu0 in that state at 3.47 s and other CPUs not; it
+  does not show what held every CPU's timer entry off `poll` for 133 s.
+- The earlier deadline-ended T14 boot — run 25's `ccorpus`, back after 187 s
+  with no record because the reset left its stick unenumerable — was tracked
+  as a defect whose exit condition was a `loader.log` from a boot that ran to
+  its deadline with the ring tail naming what the machine was doing; this
+  record is that, and the commit that added this file closed it. Its
+  inference — that a deadline which fires is a machine on which some CPU was
+  still taking a timer interrupt — holds for the instant it fired; this record
+  shows the 133 s before it in which none did.
+- `issues/hardware/a-t14-boot-wedges-after-a-jobs-exit-and-nothing-said-why.md`
+  waits for a `WEDGED` record of a different shape — a `testcases-mkdir` or
+  `-readdir` boot stopping between a job's `exit:` and the next `spawn:` —
+  and names a 2 MiB symbol-table read of 512 SCSI READ(10) commands as the
+  one device call in its window; run 55's tail names READ(10) transport
+  breaks on the same stick. Whether those are one defect is unmeasured, and
+  this record is not that file's exit condition.
+- `issues/kernel/the-deadline-header-promises-any-interrupt-and-only-the-timer-entry-polls.md`
+  is the tree-checkable half: the module header's coverage claim is wider
+  than the poll's one call site.
+
+**Exit condition**: the cause of a `poll` that ran 132859 ms past its bound is
+named with evidence and either removed or priced, so that a T14 expiry's
+lateness is held to the row that already exists.