From e641eae4259afe39a6f44fd06c2371d898c4e262 Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 1 Oct 2026 04:19:59 +0200 Subject: [PATCH 1/3] Redlist: twelve reds on main, each disabled with the issue that owns it The orchestrator stops re-running reds on a quiet host. Every red below is on main's code, so each is disabled now, and its issue says what it is and what ends it. Defects already on main: - process_stats: a connection park charged 0 ns to ipc and to pipe, at process_stats.rs:280 on wt/toyos-loaderlines 6e0d7da82 (fastest boot 480 ms) and at :263 on wt/toyos-proclife1 60ec86df3. Neither branch touches the test or the charge. The existing issue takes both sightings and becomes expected-red. - lan_dhcp_lease: the test awaits the lease and asserts netd's ready line after it, but the capture ends at test-runner's ===READY===, which can come first (wt/toyos-tight 59940c452, ceilings at 1.00x). - root_candidate_malformed: wait_for_ready reads a 16550 ready marker off QEMU's log file while the loader is still writing the line, and the test got "Slot A: REFUSED, its root is" (same run). - redirty_mid_flush: the guest went silent after spawning its child (wt/toyos-proclife 6e9d6a4df). The branch's own kernel change is two retired-syscall lines; the test passed at the branch's previous head and in every other kept whole-suite log. Verdicts the host's speed decided: - update_boots_the_new_kernel, update_falls_back_from_a_dying_kernel, update_floor_is_the_images_own, update_refusals_boot_the_other_slot: 15 s of silence across the firmware reset reads as a stall at load average 84, on #648's run and again on #642's. - guest_dies_with_its_harness: the owner's boot is judged at an unscaled 20 s on the host's clock. - syscall_window_nmi_controls: the spinner stops after ten seconds of the guest's clock and the storm waits for a million syscalls; starved, it made 950000. - virt_smp: an AP has 100 ms to echo, and a starved vCPU did not. src/redlist.rs's whole-name test probed `_controls` against None; with syscall_window_nmi and syscall_window_nmi_controls both disabled that probe finds the second row, so it now asserts only that the probe does not find the row it extends. The old assertion reds on this table (checked: EXIT=101), the new one passes. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- ...-reads-a-starved-guest-as-a-stopped-one.md | 37 ++++++++++++++++ ...550-file-can-end-the-boot-wait-mid-line.md | 25 +++++++++++ ...serts-a-line-its-wait-does-not-wait-for.md | 25 +++++++++++ ...ess-stats-exits-101-beside-other-guests.md | 18 +++++++- ...-scheduled-for-100-ms-is-booted-without.md | 28 ++++++++++++ ...sh-went-silent-after-spawning-its-child.md | 35 +++++++++++++++ ...mes-its-victim-by-the-guests-wall-clock.md | 26 +++++++++++ src/redlist.rs | 43 ++++++++++++++++++- 8 files changed, 235 insertions(+), 2 deletions(-) create mode 100644 issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md create mode 100644 issues/build/a-ready-marker-read-off-the-16550-file-can-end-the-boot-wait-mid-line.md create mode 100644 issues/build/lan-dhcp-lease-asserts-a-line-its-wait-does-not-wait-for.md create mode 100644 issues/kernel/an-ap-its-host-has-not-scheduled-for-100-ms-is-booted-without.md create mode 100644 issues/kernel/redirty-mid-flush-went-silent-after-spawning-its-child.md create mode 100644 issues/kernel/the-syscall-window-storm-times-its-victim-by-the-guests-wall-clock.md diff --git a/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md b/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md new file mode 100644 index 00000000000..9b0937972b7 --- /dev/null +++ b/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md @@ -0,0 +1,37 @@ +--- +status: expected-red +kind: tooling +opened: 2026-10-01 +--- + +# A harness wait reads a starved guest as a stopped one + +Every wait the harness puts on a guest is measured on the host's wall clock. +On a loaded host a TCG guest's QEMU sits runnable and unserved, so a guest that +is slow reads as one that stopped, and the host's load decides the verdict: + +- `update_boots_the_new_kernel`, `update_falls_back_from_a_dying_kernel`, + `update_floor_is_the_images_own` and `update_refusals_boot_the_other_slot` + STALLED in the same run (`648-648-whole.log`, `wt/toyos-proclife1` + `60ec86df3`, load average 84 on 14 cores): "the console and the 16550 both + went quiet for 15 s", each just after the loader's "this pass resets the + machine". `await_machine` (`tests/common/update.rs`) ends on 15 s of silence + alone, and the firmware between that reset and the loader's next line is + silent. The same run's `boot_from_power_on` read "power-on to loader 17387 + ms", against 5021 ms on a quiet host. `update_boots_the_new_kernel` STALLED + the same way on `wt/toyos-proclife` `6e9d6a4df` (`642r2-642-whole.log`). +- `guest_dies_with_its_harness` (same 648 run, 21 s): "Boot timed out waiting + for ===READY===; the console carried: nothing at all". The owner process has + measured no boot, so its `wait_for_ready` ceiling is the unscaled 20 s, and + its 16550 had reached "ROOT: read into memory" — a guest still working. + +The opposite error has the same cause. `budget` multiplies a test's ceiling by +the phase width and by `host_scale`, two stand-ins for the host's load, so a +guest that stops at once is waited on for 37 times its budget: +`redirty_mid_flush` (`642r2-642-whole.log`) said nothing after its first second +and was called stalled at "4474s of guard expired": its 120 s × 12 wide × a +`host_scale` of 3.1 (4474 / 1440), the fastest boot the run had seen when the +test began. + +**Exit**: every wait on a guest reads time the guest had, with the host's +steal taken out, and no ceiling scales by the host's load; then these rows go. diff --git a/issues/build/a-ready-marker-read-off-the-16550-file-can-end-the-boot-wait-mid-line.md b/issues/build/a-ready-marker-read-off-the-16550-file-can-end-the-boot-wait-mid-line.md new file mode 100644 index 00000000000..abfa2374a27 --- /dev/null +++ b/issues/build/a-ready-marker-read-off-the-16550-file-can-end-the-boot-wait-mid-line.md @@ -0,0 +1,25 @@ +--- +status: expected-red +kind: tooling +opened: 2026-10-01 +--- + +# A ready marker read off the 16550 file can end the boot wait mid-line + +`638L-638r5-whole.log` (`wt/toyos-tight` `59940c452`, "ceilings paid at +1.00x"): `root_candidate_malformed` — "the loader did not refuse a ROOT its +signature does not cover: Slot A: REFUSED, its root is". The loader's line is +"Slot A: REFUSED, its root is not the bytes its signed header names" +(`648-648-whole.log`, the same test passing), so the capture holds the first +half of it. + +`wait_for_ready` (`tests/common/qemu.rs`), for a marker other than the +default, looks for it in the 16550's log file once a second, and that file is +QEMU's, written a byte at a time while the loader prints. `ROOT_REFUSED` is +"Slot A: REFUSED, ", so a read between those bytes and the rest of the line +ends the wait, and `boot_expecting_root_refusal` hands back a line cut short. +Every test booted to a 16550 marker can read one; this is the one that has. +The `aio failed: Input/output error` beside it in the log is +`root_chunk_refused`'s injected bad sector, not this test's. + +**Exit**: the boot wait ends on a whole line; then the row goes. diff --git a/issues/build/lan-dhcp-lease-asserts-a-line-its-wait-does-not-wait-for.md b/issues/build/lan-dhcp-lease-asserts-a-line-its-wait-does-not-wait-for.md new file mode 100644 index 00000000000..7d67f0d0001 --- /dev/null +++ b/issues/build/lan-dhcp-lease-asserts-a-line-its-wait-does-not-wait-for.md @@ -0,0 +1,25 @@ +--- +status: expected-red +kind: tooling +opened: 2026-10-01 +--- + +# `lan_dhcp_lease` asserts a line its wait does not wait for + +`638L-638r5-whole.log` (`wt/toyos-tight` `59940c452`, "ceilings paid at +1.00x"): `"netd: ready, at most " never reached the the lan boot after "netd: +DHCP: lease "`. The capture ends at the harness's ready marker: + +``` +{1.281 netd} netd: DHCP: lease 10.0.2.15/24 from 10.0.2.2, gateway 10.0.2.2, dns [10.0.2.3], 43 ms after netd came up +{1.290 test-runner} ===READY=== +``` + +`tests/common/lan.rs`'s `lan_dhcp_lease` awaits the lease line, drops the +guest, and then holds the capture to `READY` coming after `LEASE`. The boot +log already carries the lease, so the await returns at once and the capture is +whatever arrived before `===READY===`; netd says it is ready after its lease, +and test-runner's marker can come first. The branch does not touch the test, +netd's lease path or the boot's order, and the race is the same on `main`. + +**Exit**: the test waits for the line it asserts; then the row goes. diff --git a/issues/build/process-stats-exits-101-beside-other-guests.md b/issues/build/process-stats-exits-101-beside-other-guests.md index 3ffe2ddfe30..1a3387b2bd4 100644 --- a/issues/build/process-stats-exits-101-beside-other-guests.md +++ b/issues/build/process-stats-exits-101-beside-other-guests.md @@ -1,5 +1,5 @@ --- -status: open +status: expected-red kind: defect opened: 2026-09-06 --- @@ -23,3 +23,19 @@ Exit: a rate — the same suite run repeatedly with and without a second worktree's build on the host — that says whether this is contention the harness should schedule around or a defect the guest has, and the name is fixed at the cause. + +**2026-10-01: two more, each with its assertion.** `640r3-loaderlines-r3-whole.log` +(`wt/toyos-loaderlines` `6e0d7da82`, "fastest boot 480 ms … ceilings paid at +1.00x") at `process_stats.rs:280`: "a child that parked writing a full +connection charged 0 ns to ipc and 0 ns to pipe". `648-648-whole.log` +(`wt/toyos-proclife1` `60ec86df3`, load average 84) at `process_stats.rs:263`: +"a child that parked reading a connection charged 0 ns to ipc and 0 ns to +pipe". Neither branch touches the test, `WaitClass` or the charge. The +premise both arms read is `roster::await_true` seeing the child's main thread +`BLOCKED`, and nothing ties that park to the connection: a park on anything +else before the child reaches its `read` or `write` satisfies it, the parent +releases, and the connection's wait never parks. The assertion prints two of +the five classes, so which park was charged is not on record. + +Exit: the arm waits for a park it can name as the connection's, or the +assertion prints every class and a red names the park; then the row goes. diff --git a/issues/kernel/an-ap-its-host-has-not-scheduled-for-100-ms-is-booted-without.md b/issues/kernel/an-ap-its-host-has-not-scheduled-for-100-ms-is-booted-without.md new file mode 100644 index 00000000000..c086e661240 --- /dev/null +++ b/issues/kernel/an-ap-its-host-has-not-scheduled-for-100-ms-is-booted-without.md @@ -0,0 +1,28 @@ +--- +status: expected-red +kind: defect +opened: 2026-10-01 +--- + +# An AP its host has not scheduled for 100 ms is booted without + +`virt_smp` red in `636r2-virt.log` (`wt/toyos-rulesbatch` `8f142ba9e`, TCG, +`VirtEl2`, a loaded host, "liveness ceilings paid at 1.93x"): + +``` +[kernel 0.236 cpu0] SMP: cpu6 mpidr=0x6 online +[kernel 0.368 cpu0] SMP: cpu7 mpidr=0x7 did not echo within 100ms (the machine boots with the CPUs that came up before the first that did not); the rest stay off +[kernel 0.372 cpu0] SMP: 7 of 8 MADT CPUs online +``` + +`time::AP_START` gives an AP 100 ms between `CPU_ON` (or the SIPIs) and its +echo, and its expiry boots the machine without that CPU for good. On metal an +AP that is alive answers in microseconds; under any hypervisor a vCPU its host +has not scheduled answers late, and 100 ms of steal reads as a dead CPU. Linux +waits 5 s for the same echo on arm64 (`arch/arm64/kernel/smp.c`, `__cpu_up`: +`wait_for_completion_timeout(&cpu_running, msecs_to_jiffies(5000))`) and 10 s +in its generic bring-up (`kernel/cpu.c`, `cpuhp_wait_for_sync_state`). + +**Exit**: the bound is one on a dead CPU — the span this kernel already holds a +live CPU to (`time::DEAF_CPU`) — and `virt_smp` is green on a loaded host; then +the row goes. diff --git a/issues/kernel/redirty-mid-flush-went-silent-after-spawning-its-child.md b/issues/kernel/redirty-mid-flush-went-silent-after-spawning-its-child.md new file mode 100644 index 00000000000..1396bd70242 --- /dev/null +++ b/issues/kernel/redirty-mid-flush-went-silent-after-spawning-its-child.md @@ -0,0 +1,35 @@ +--- +status: expected-red +kind: defect +opened: 2026-10-01 +--- + +# `redirty_mid_flush` went silent after spawning its child + +`642r2-642-whole.log` (`wt/toyos-proclife` `6e9d6a4df`, "ceilings paid at +1.29x", 5882 s for the run): the guest's last words were the child's spawn, +and nothing came after them — not a line from the test, not the kernel's own +ten-second `sched:` lines: + +``` +[kernel 1.447 cpu1] spawn: /system/bin/test_rs_redirty_mid_flush pid=9 ... +[kernel 1.690 cpu1] spawn: /system/bin/test_rs_redirty_mid_flush pid=10 ... + STALL redirty_mid_flush (4484s) +``` + +The boot is `Profile::Metal` with `test-small-caches`, and `/log` — the file +the two processes race fsyncs on — is the boot stick's, behind xHCI and the +kernel's mass-storage driver. A kernel whose every CPU is inside a call on a +held disk takes no pass and prints nothing +(`issues/kernel/a-held-disk-waits-for-a-pass-no-cpu-takes-when-every-cpu-is-in-a-call-on-it.md`), +and a loaded host is what breaks a stick's transport in its 2000 ms data-phase +budget (`issues/build/smp-ap-hole-and-log-reserve-window-red-under-a-loaded-host.md`); +that is a reading, not a measurement, because the capture holds no kernel line +to confirm it. The test passed in every other whole-suite log kept for this +job, `wt/toyos-proclife` `a8acd2aaa` among them; between that head and +`6e9d6a4df` the branch's own kernel change is two retired-syscall lines, and +the rest is `main`'s merge, which rewrote `drivers/xhci/wait/msc.rs`. + +**Exit**: a sighting whose capture names where every CPU was — the next one +needs the console the guard's verdict carries, or a QMP register dump of a +silent guest — and the defect fixed; then the row goes. diff --git a/issues/kernel/the-syscall-window-storm-times-its-victim-by-the-guests-wall-clock.md b/issues/kernel/the-syscall-window-storm-times-its-victim-by-the-guests-wall-clock.md new file mode 100644 index 00000000000..ddf8866a517 --- /dev/null +++ b/issues/kernel/the-syscall-window-storm-times-its-victim-by-the-guests-wall-clock.md @@ -0,0 +1,26 @@ +--- +status: expected-red +kind: tooling +opened: 2026-10-01 +--- + +# The syscall-window storm times its victim by the guest's wall clock + +`syscall_window_nmi_controls` red at 446 s in `648-648-whole.log` +(`wt/toyos-proclife1` `60ec86df3`, load average 84 on 14 cores): "the capture +has no `syscall-window-nmi: held cpu=` line and no `syscall-window-nmi: held +nobody` line". The storm never fired. It fires once one CPU has counted a +million syscalls (`nmi_gate::SPINNING_SYSCALLS`), and the spinner stops after +ten seconds of the guest's clock: under TCG that is the host's, and the +starved spinner said `950000 syscalls` (`syscalls: pid=9 total=950009 ... +cpu=9997ms`) — the dev host's quiet rate is a million in about 190 ms. + +The storm's own waits on its victim are the same mistake at 100 ms each: +`HOLD_ACK_NS` for the held CPU's acknowledgement, `HELD_DELIVERY_NS` for the +aimed NMI to be taken, and `HOLD_ACK_NS` again for the released CPU's next +syscall. A vCPU the host has not scheduled for 100 ms answers none of them, +and the control's held arrival is then not the one the hold arranged. + +**Exit**: the spinner spins until the storm is over, and every wait the storm +puts on its victim is a bound on a dead CPU and not on a starved one; then the +row goes. diff --git a/src/redlist.rs b/src/redlist.rs index c08804b93d1..9c4025fafd3 100644 --- a/src/redlist.rs +++ b/src/redlist.rs @@ -30,6 +30,10 @@ pub const DISABLED: &[Disabled] = &[ issue: "issues/build/the-console-input-path-can-stop-after-a-ps2-overflow.md", }, Disabled { test: "desktop_window_child", issue: "issues/kernel/desktop-window-child-freeze.md" }, + Disabled { + test: "guest_dies_with_its_harness", + issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", + }, Disabled { test: "handle_basic", issue: "issues/kernel/deferred-release-outlives-its-syscall.md" }, Disabled { test: "handle_kill_policy", @@ -41,6 +45,10 @@ pub const DISABLED: &[Disabled] = &[ issue: "issues/hardware/i8042-mouse-ends-four-packets-short-with-a-clean-exit.md", }, Disabled { test: "kill_while_blocked", issue: "issues/kernel/deferred-release-outlives-its-syscall.md" }, + Disabled { + test: "lan_dhcp_lease", + issue: "issues/build/lan-dhcp-lease-asserts-a-line-its-wait-does-not-wait-for.md", + }, Disabled { test: "log_ring_keeps_the_owners_slots", issue: "issues/kernel/a-log-rings-owner-is-named-only-when-logd-reads-its-registration.md", @@ -53,6 +61,7 @@ pub const DISABLED: &[Disabled] = &[ test: "partition_claim_departure", issue: "issues/boot-media/partition-claim-departure-exits-clean-with-none-of-its-refusals-said.md", }, + Disabled { test: "process_stats", issue: "issues/build/process-stats-exits-101-beside-other-guests.md" }, Disabled { test: "quiesce_stops_the_machine", issue: "issues/kernel/a-quiesce-writers-first-pass-outlasts-the-jobs-five-second-spin-up.md", @@ -65,6 +74,14 @@ pub const DISABLED: &[Disabled] = &[ test: "quiesce_wakes_on_the_last_teardown", issue: "issues/kernel/quiesce-wakes-on-the-last-park-gave-up-on-one-thread-beside-the-held-one.md", }, + Disabled { + test: "redirty_mid_flush", + issue: "issues/kernel/redirty-mid-flush-went-silent-after-spawning-its-child.md", + }, + Disabled { + test: "root_candidate_malformed", + issue: "issues/build/a-ready-marker-read-off-the-16550-file-can-end-the-boot-wait-mid-line.md", + }, Disabled { test: "root_chunk_refused_on_a_usb_stick", issue: "issues/boot-media/an-unreadable-sector-on-a-usb-boot-stick-hangs-the-loader-past-the-firmware-watchdog.md", @@ -85,6 +102,26 @@ pub const DISABLED: &[Disabled] = &[ test: "syscall_window_nmi", issue: "issues/kernel/syscall-window-nmi-shortfalls-on-a-contended-host.md", }, + Disabled { + test: "syscall_window_nmi_controls", + issue: "issues/kernel/the-syscall-window-storm-times-its-victim-by-the-guests-wall-clock.md", + }, + Disabled { + test: "update_boots_the_new_kernel", + issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", + }, + Disabled { + test: "update_falls_back_from_a_dying_kernel", + issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", + }, + Disabled { + test: "update_floor_is_the_images_own", + issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", + }, + Disabled { + test: "update_refusals_boot_the_other_slot", + issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", + }, Disabled { test: "usb_transport_break", issue: "issues/kernel/a-held-disk-waits-for-a-pass-no-cpu-takes-when-every-cpu-is-in-a-call-on-it.md", @@ -93,6 +130,10 @@ pub const DISABLED: &[Disabled] = &[ test: "user_copy_races_munmap", issue: "issues/kernel/copy-meets-a-remap-holds-a-cpu-the-thread-it-waits-on-may-be-queued-behind.md", }, + Disabled { + test: "virt_smp", + issue: "issues/kernel/an-ap-its-host-has-not-scheduled-for-100-ms-is-booted-without.md", + }, ]; /// The row of `rows` that disables `test`, matched by the whole name. @@ -257,7 +298,7 @@ mod tests { fn a_row_disables_its_whole_name_and_nothing_that_extends_it() { for row in DISABLED { assert_eq!(disabled(DISABLED, row.test), Some(row)); - assert_eq!(disabled(DISABLED, &format!("{}_controls", row.test)), None); + assert_ne!(disabled(DISABLED, &format!("{}_controls", row.test)), Some(row)); } assert_eq!(disabled(DISABLED, ""), None); } From dc153d6da9adb5be33c70f3f20013b5335d6cd78 Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 1 Oct 2026 05:18:05 +0200 Subject: [PATCH 2/3] Redlist: iommu_virtio_platform and loader_watchdog_arms, from a libc-only branch's run Both went red in 650-libcllvm-whole.log on wt/toyos-libcllvm, whose diff is userland/libc alone, at load average 66-74. - iommu_virtio_platform is a defect on main. It reads netd's claim line and netd's feature negotiation off a boot log that ends at test-runner's ===READY===, and netd starts before test-runner but speaks after it. The same race reds in two wordings on 634r2, 637r2 and 641f-r3, each on a branch that does not touch it. #639 carries a fix (d773a4306). - loader_watchdog_arms timed out its boot at 132 s of wall clock, which is 10 s x 12 wide x host_scale. The console stood at "BdsDxe: starting Boot0001". Its 50-odd other runs in the kept logs passed in 6-34 s. It goes under the harness-wait issue, which now carries this sighting and 650's two update STALLs. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- ...-reads-a-starved-guest-as-a-stopped-one.md | 8 +++++ ...es-off-a-boot-log-that-ends-before-them.md | 31 +++++++++++++++++++ src/redlist.rs | 8 +++++ 3 files changed, 47 insertions(+) create mode 100644 issues/build/iommu-virtio-platform-reads-netds-lines-off-a-boot-log-that-ends-before-them.md diff --git a/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md b/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md index 9b0937972b7..3b10e2922b1 100644 --- a/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md +++ b/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md @@ -24,6 +24,14 @@ is slow reads as one that stopped, and the host's load decides the verdict: for ===READY===; the console carried: nothing at all". The owner process has measured no boot, so its `wait_for_ready` ceiling is the unscaled 20 s, and its 16550 had reached "ROOT: read into memory" — a guest still working. +- `650-libcllvm-whole.log` (`wt/toyos-libcllvm`, libc only, load average + 66–74, image builds in the same run): `update_refusals_boot_the_other_slot` + and `update_boots_the_new_kernel` STALLED as above, and `loader_watchdog_arms` + timed out its boot at 132 s of wall clock — 10 s × 12 wide × `host_scale` — + with the console at "BdsDxe: starting Boot0001". Its 50-odd other runs in + the kept logs passed in 6–34 s. Whether that guest was starved or the loader + stalled before its first line is what a wait on the guest's own time + separates. The opposite error has the same cause. `budget` multiplies a test's ceiling by the phase width and by `host_scale`, two stand-ins for the host's load, so a diff --git a/issues/build/iommu-virtio-platform-reads-netds-lines-off-a-boot-log-that-ends-before-them.md b/issues/build/iommu-virtio-platform-reads-netds-lines-off-a-boot-log-that-ends-before-them.md new file mode 100644 index 00000000000..1054677390d --- /dev/null +++ b/issues/build/iommu-virtio-platform-reads-netds-lines-off-a-boot-log-that-ends-before-them.md @@ -0,0 +1,31 @@ +--- +status: expected-red +kind: tooling +opened: 2026-10-01 +--- + +# `iommu_virtio_platform` reads netd's lines off a boot log that ends before them + +Red on four branches that do not touch it, in two words of one race: + +- `650-libcllvm-whole.log` (`wt/toyos-libcllvm`, libc only) and + `634r2-whole.log` (`wt/toyos-sk6` `fb0fc7b56`): `"netd: this claim answers + 4096 bytes of configuration space and refuses every access outside them" + never reached the boot console`. +- `637r2-whole-suite.log` (`wt/toyos-libcxx` `26a4bfbe1`) and + `641f-r3-whole.log` (`wt/toyos-tonefix` `597d60a4e`): `QEMU created 3 virtio + function(s) … and the guest negotiated features with 2`, the missing one + being netd's own function. + +`tests/common/iommu.rs`'s `iommu_virtio_platform` judges `Serial::boot`, the +capture `wait_for_ready` ends at test-runner's `===READY===`. init starts netd +before test-runner, and netd's claim and its feature negotiation come after +netd starts, so test-runner's marker can come first: in the 650 run netd +started at 4.905 and the marker came at 5.098 with neither of netd's lines +before it. + +`wt/toyos-noredlist` (#639) carries a fix, `d773a4306`: each arm waits on the +guest for the daemons' lines it reads. + +**Exit**: the test waits for netd's lines rather than reading them off the +boot log; then the row goes. diff --git a/src/redlist.rs b/src/redlist.rs index 9c4025fafd3..5e2254c7084 100644 --- a/src/redlist.rs +++ b/src/redlist.rs @@ -44,11 +44,19 @@ pub const DISABLED: &[Disabled] = &[ test: "i8042_mouse", issue: "issues/hardware/i8042-mouse-ends-four-packets-short-with-a-clean-exit.md", }, + Disabled { + test: "iommu_virtio_platform", + issue: "issues/build/iommu-virtio-platform-reads-netds-lines-off-a-boot-log-that-ends-before-them.md", + }, Disabled { test: "kill_while_blocked", issue: "issues/kernel/deferred-release-outlives-its-syscall.md" }, Disabled { test: "lan_dhcp_lease", issue: "issues/build/lan-dhcp-lease-asserts-a-line-its-wait-does-not-wait-for.md", }, + Disabled { + test: "loader_watchdog_arms", + issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", + }, Disabled { test: "log_ring_keeps_the_owners_slots", issue: "issues/kernel/a-log-rings-owner-is-named-only-when-logd-reads-its-registration.md", From 703d9703eb87d0852535acb4dc05e53d0b8b27a4 Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 1 Oct 2026 05:41:51 +0200 Subject: [PATCH 3/3] Redlist: three more from the libc-only run, each on main's code 650-libcllvm-whole.log, wt/toyos-libcllvm, whose diff is userland/libc alone; load average 66-87, with the run reporting ceilings at 1.01x. - metal_sim_window_drag and usb_boot_stick_pulled timed out their boots at 21 and 22 s in the serial tail, the 20 s a phase of one guest gets. Each had the loader still printing its segments. They go under the harness-wait issue, which now also says why the run's 1.01x could not see the load. - blockd_serves_partitions: the bench passed and its process exited at 35.978 s, then no ===TEST_END=== came for 3559 s, while the kernel kept logging with every CPU idle. Either test-runner's wait on the job missed the exit's post, or logd stopped forwarding. The new issue says which evidence the next sighting needs, and names #655's poller shape as the logd reading. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- ...-reads-a-starved-guest-as-a-stopped-one.md | 7 +++- ...ob-that-exited-was-never-reported-ended.md | 37 +++++++++++++++++++ src/redlist.rs | 12 ++++++ 3 files changed, 55 insertions(+), 1 deletion(-) create mode 100644 issues/kernel/a-job-that-exited-was-never-reported-ended.md diff --git a/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md b/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md index 3b10e2922b1..ef5ab906c40 100644 --- a/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md +++ b/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md @@ -31,7 +31,12 @@ is slow reads as one that stopped, and the host's load decides the verdict: with the console at "BdsDxe: starting Boot0001". Its 50-odd other runs in the kept logs passed in 6–34 s. Whether that guest was starved or the loader stalled before its first line is what a wait on the guest's own time - separates. + separates. In the serial tail of the same run, `metal_sim_window_drag` and + `usb_boot_stick_pulled` timed out their boots at 21 and 22 s — the 20 s a + phase of one guest gets — with the loader still printing its segments. The + run reported "fastest boot 1331 ms against the reference 1320 ms — liveness + ceilings paid at 1.01x" at a load average of 66–87: the fastest boot is + taken at the run's quietest moment, so `host_scale` cannot see the load. The opposite error has the same cause. `budget` multiplies a test's ceiling by the phase width and by `host_scale`, two stand-ins for the host's load, so a diff --git a/issues/kernel/a-job-that-exited-was-never-reported-ended.md b/issues/kernel/a-job-that-exited-was-never-reported-ended.md new file mode 100644 index 00000000000..136b6aa17b9 --- /dev/null +++ b/issues/kernel/a-job-that-exited-was-never-reported-ended.md @@ -0,0 +1,37 @@ +--- +status: expected-red +kind: defect +opened: 2026-10-01 +--- + +# A job that exited was never reported ended + +`650-libcllvm-whole.log` (`wt/toyos-libcllvm`, userland/libc alone): +`blockd_serves_partitions` — "role bench exited None" after 3559 s, ended by +hand. The bench passed and its process ended: + +``` +{35.962 pid=11 test-runner} blockd_io: PASS bench +[kernel 35.969 cpu0] exit: blockd pid=12 code=137 cpu=1450ms +[kernel 35.978 cpu0 tid=1] exit: test_rs_blockd_io pid=11 code=0 cpu=23247ms +``` + +and `===TEST_END test_rs_blockd_io exit=0===` never came. From 35.978 s to +3540 s the only lines are the kernel's own ten-second `sched:` and `PMM:` +lines, every CPU `ready=0` with its threads parked. test-runner prints the +marker after `child.wait()` (SYS_PROCESS_WAIT, parked on the process object's +watch until `publish_exit` posts it), and its line reaches the console +through logd. So either the wait missed the post, or the marker was written +and logd stopped forwarding: every userland line stops at 35.962, and the +capture cannot tell which. + +logd reads its sources through a poller. #655 (`wt/toyos-winitstall`) found +that a poller can report a source readable again for data already read, and +a blocking read after it then waits forever. That shape would stop logd +silently while the kernel's lines go on. blockd finished its bench and was +killed after it, so the blockd ring-reset ordering #643 fixes is not on this +path. + +**Exit**: the parked thread named — the next sighting needs a blocked-task +dump of a guest whose kernel still logs — and the defect fixed; then the row +goes. diff --git a/src/redlist.rs b/src/redlist.rs index 5e2254c7084..86b2b496c8f 100644 --- a/src/redlist.rs +++ b/src/redlist.rs @@ -25,6 +25,10 @@ pub struct Disabled { /// Every disabled test. pub const DISABLED: &[Disabled] = &[ + Disabled { + test: "blockd_serves_partitions", + issue: "issues/kernel/a-job-that-exited-was-never-reported-ended.md", + }, Disabled { test: "console_locale_detect", issue: "issues/build/the-console-input-path-can-stop-after-a-ps2-overflow.md", @@ -61,6 +65,10 @@ pub const DISABLED: &[Disabled] = &[ test: "log_ring_keeps_the_owners_slots", issue: "issues/kernel/a-log-rings-owner-is-named-only-when-logd-reads-its-registration.md", }, + Disabled { + test: "metal_sim_window_drag", + issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", + }, Disabled { test: "netd_refused_accept", issue: "issues/hardware/netd-refused-accept-hung-waiting-for-a-wake-that-never-came.md", @@ -130,6 +138,10 @@ pub const DISABLED: &[Disabled] = &[ test: "update_refusals_boot_the_other_slot", issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", }, + Disabled { + test: "usb_boot_stick_pulled", + issue: "issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md", + }, Disabled { test: "usb_transport_break", issue: "issues/kernel/a-held-disk-waits-for-a-pass-no-cpu-takes-when-every-cpu-is-in-a-call-on-it.md",