Skip to content
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
@@ -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.
Original file line number Diff line number Diff line change
@@ -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.
Original file line number Diff line number Diff line change
@@ -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.
Original file line number Diff line number Diff line change
@@ -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.
18 changes: 17 additions & 1 deletion issues/build/process-stats-exits-101-beside-other-guests.md
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
---
status: open
status: expected-red
kind: defect
opened: 2026-09-06
---
Expand All @@ -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.
37 changes: 37 additions & 0 deletions issues/kernel/a-job-that-exited-was-never-reported-ended.md
Original file line number Diff line number Diff line change
@@ -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.
Original file line number Diff line number Diff line change
@@ -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.
Original file line number Diff line number Diff line change
@@ -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.
Original file line number Diff line number Diff line change
@@ -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.
Loading
Loading