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..ef5ab906c40 --- /dev/null +++ b/issues/build/a-harness-wait-reads-a-starved-guest-as-a-stopped-one.md @@ -0,0 +1,50 @@ +--- +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. +- `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. 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 +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/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/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/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/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..86b2b496c8f 100644 --- a/src/redlist.rs +++ b/src/redlist.rs @@ -25,11 +25,19 @@ 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", }, 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", @@ -40,11 +48,27 @@ 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", }, + 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", @@ -53,6 +77,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 +90,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 +118,30 @@ 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_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", @@ -93,6 +150,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 +318,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); }