Skip to content
Closed
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.
Original file line number Diff line number Diff line change
@@ -0,0 +1,26 @@
---
status: open
kind: tooling
opened: 2026-10-01
---

# An idle guest and a hung one print the same `sched:` line

`blockd_serves_partitions`' guest (`650-libcllvm-whole.log`) logged
`sched: cpu=1 ready=0 … parked=4 current=None` every ten seconds for an hour
with its test's end never reported
(`issues/kernel/a-job-that-exited-was-never-reported-ended.md`). The
harness's ceiling read that as a guest still talking. Only the backstop could
end it, at the test's own 600 s once a stopped guest's clock runs at the
wall's rate.

The line cannot do better. `scheduler::log_health` counts parked threads and
says nothing of what each waits on. A guest waiting out a timer, such as
`lan_no_lease` riding netd's 20 s lease bound or a job asleep under its
deadline, prints the same line as one whose every thread waits on a wake that
will never come. A wait that ended a run on `ready=0` would red the first kind.

**Exit**: the kernel's idle line also counts the parks that carry a deadline,
and a wait on a guest ends, by name, once every CPU has reported `ready=0`
with no such park for the quiet span. The case it ends early is this file's
sighting.
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,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.
10 changes: 5 additions & 5 deletions kernel/src/arch/x86_64/nmi_gate.rs
Original file line number Diff line number Diff line change
Expand Up @@ -60,7 +60,7 @@ pub mod hold {
/// One turn of the entry's spin, in the budget the word carries above the flags.
pub const SPIN: u64 = 1 << 8;
/// Turns an ask grants. A count and not a time, because the entry can read no clock without a register; a bound, not a measurement.
pub const TURNS: u64 = 1 << 25;
pub const TURNS: u64 = 1 << 31;
/// What the storm stores to ask.
pub const ASK: u64 = ASKED | (TURNS * SPIN);
}
Expand Down Expand Up @@ -177,12 +177,12 @@ const ENOUGH: u64 = 64;
/// Wait budget per NMI before the next goes out; a delivery that misses it still counts as sent.
const DELIVERY_BUDGET_NS: u64 = 100_000;

/// Asks before the spray goes out without a held arrival, and how long each waits for the entry's acknowledgement, and a released victim for its next syscall. Bounds, not measurements.
/// Asks before the spray goes out without a held arrival, and how long each waits for the entry's acknowledgement, and a released victim for its next syscall: a bound on a dead CPU and not on one its host has not scheduled, so `DEAF_CPU`'s.
const HOLD_ATTEMPTS: u32 = 10;
const HOLD_ACK_NS: u64 = 100_000_000;
const HOLD_ACK_NS: u64 = crate::time::DEAF_CPU.nanos();

/// How long the held NMI is waited for: the one delivery whose landing is the premise gets a host's scheduling latency rather than [`DELIVERY_BUDGET_NS`], and the held CPU spins with `IF` clear throughout, which keeps this well under `hardlockup`'s bound. A bound, not a measurement.
const HELD_DELIVERY_NS: u64 = 100_000_000;
/// How long the held NMI is waited for: the one delivery whose landing is the premise gets [`HOLD_ACK_NS`]'s bound on a dead CPU rather than [`DELIVERY_BUDGET_NS`], and the held CPU spins with `IF` clear throughout, which keeps this well under `hardlockup`'s bound.
const HELD_DELIVERY_NS: u64 = HOLD_ACK_NS;

// The budget outlasts the storm's longest lawful hold wherever a turn — a `pause`, a locked subtract and a test — takes 3 ns or more, which is an estimate of hardware and not a measurement.
const _: () = assert!(hold::TURNS * 3 >= HELD_DELIVERY_NS);
Expand Down
7 changes: 5 additions & 2 deletions kernel/src/time.rs
Original file line number Diff line number Diff line change
Expand Up @@ -242,9 +242,12 @@ impl fmt::Display for Budget {
}
}

/// How long the boot CPU waits for an AP it started to echo its token.
/// How long the boot CPU waits for an AP it started to echo its token: a bound
/// on a dead CPU and not on a slow one, so [`DEAF_CPU`]'s span — a vCPU its
/// host has not scheduled is slow, and no CPU that is alive goes that long
/// unheard.
pub const AP_START: Budget = Budget::of(
Duration::from_millis(100),
Duration::from_nanos(DEAF_CPU.nanos()),
"the machine boots with the CPUs that came up before the first that did not",
);

Expand Down
23 changes: 22 additions & 1 deletion src/redlist.rs
Original file line number Diff line number Diff line change
Expand Up @@ -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",
Expand All @@ -40,7 +44,15 @@ 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: "log_ring_keeps_the_owners_slots",
issue: "issues/kernel/a-log-rings-owner-is-named-only-when-logd-reads-its-registration.md",
Expand All @@ -53,6 +65,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",
Expand All @@ -65,6 +78,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",
Expand Down Expand Up @@ -257,7 +278,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);
}
Expand Down
11 changes: 11 additions & 0 deletions tests/checks.rs
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,8 @@ mod checks {
mod screen_checks;
#[path = "serial.rs"]
mod serial_checks;
#[path = "steal.rs"]
mod steal_checks;
#[path = "usb.rs"]
mod usb_checks;

Expand Down Expand Up @@ -102,6 +104,15 @@ mod checks {
clock_checks::self_check()
}

/// A guest's clock: the arithmetic, the host's accounting it reads, and a
/// process that is gone.
#[test]
fn steal_clock() -> Result<(), String> {
steal_checks::served_self_check()?;
steal_checks::demand_self_check()?;
steal_checks::gone_self_check()
}

/// What a suspend is worth to a verdict, staged rather than reasoned about.
///
/// `clock_checks::self_check` gates the detector; this gates what the suite
Expand Down
Loading
Loading