A guest test waits for a kernel record and for a program's line each, where it read one off a capture the other ended

[Japabu]

A guest test that read a kernel record off a capture a program's line ended, or the reverse, now waits for each. Six sites had the shape: machine_shutdown_short_stop, the one seen red, and five found by reading.

The defect, as recorded

Recorded in issues/machine-shutdown-short-stop-asserts-a-program-line-it-never-waited-for.md on wt/toyos-oneboot-b1 (#785, not landed), which main never held. What it recorded:

• The load. Seen red once, beside machine_shutdown and acpi_power_button in one filtered run, on a host at load 51 (1 min) running other worktrees' builds. Alone, two minutes later at load 45 on the same tree, it passed in 12 s. The branch it was seen on changed no line of tests/common/power.rs.
• The failing line. FAIL machine_shutdown_short_stop: "acpiserver: armed: power button served, embedded controller none" never reached the boot: over a capture that held the kernel's record stamped 15.521 s and no program's line stamped after 15.175 s.
• The cause. The test waited for the kernel's record power: S5 is PM1a 0x604 with SLP_TYPa=0, and asserted acpiserver's armed line on the capture that wait ended. The two reach the console by different roads: a kernel record goes on the wire as klogd drains the kernel's ring, and a program's line only once logkeeper has read that program's ring on its cadence and queued the line. klogd takes at most CHUNK = 8 records and then 8 queued lines per hold of the wire (kernel/src/log/console.rs), so neither kind waits for the other, in either direction, and a capture that ends at one need not hold the other.

#785 is asked to delete its issue file when it merges main: this change meets its exit condition.

The fix

Each site waits on its own marker with qemu::await_marker, which is await_guest: ended by the marker, by GUEST_QUIET of silence, or by budget(GUEST_WEDGED). No flat wait, and no new helper or test. A marker that never comes is STALLED: waiting for <what>, by name.

site	read off a capture that ended at	now waits for
machine_shutdown_short_stop (tests/common/power.rs)	the kernel's power: S5 is record	acpiserver's armed line, then the record
acpi_power_button (tests/common/power.rs)	acpiserver's armed line	the kernel's ACPI-mode record, made at the claim
virt_reboot_refused_without_psci (tests/toyos.rs)	test-runner's ===TEST_END reboot	the kernel's reboot: … refused record
virt_smp, virt_el1_smp (tests/toyos.rs)	test-runner's ===TEST_END unmap_touch	each CPU's CPU n: joining scheduler, said after the machine is released
virt_job, seven tests (tests/toyos.rs)	test-runner's ===TEST_END <job>	the kernel's record of logkeeper's spawn, which bootlog::one_clock owes
iommu_virtio_platform (tests/common/iommu.rs)	the daemons' lines	with them, the kernel's records of the claim: the BAR moved and MSI-X armed where there is a unit, the two NOT HANDED OVER where there is none

The first row is round 1's; the second and third are the review's; the last three are this round's sweep. Vs main: +52 -21 in three test files, and the one issue file below; nothing ships.

In machine_shutdown_short_stop the ACPI-mode record is still read off the capture: it and the record just waited for are both the kernel's, the earlier committed before the later is reserved, on one CPU.

The sweep

The criterion: a kernel record asserted on a capture that a program's line ended, or the reverse, with no code ordering the two. Two things do order them, and a site that rests on one is not the shape:

• Before klogd. Every record kernel_main makes is drained inline by its producer (kernel/src/log/mod.rs, Drain::Inline): klogd is started as kernel_main's last act before the idle loop, and no task runs before that. Such a record is on the wire before any program exists. An AP's control-register line is among them: it is logged before the AP's echo, and the boot CPU logs after the echo.
• The stop. Every stop is the supervisor's (toyos/src/power.rs): it has logkeeper flush, which feeds the console, before it asks the kernel. The kernel stops every thread and puts every queued line on the wire (drain_for_the_stop) before it logs the last word, and settle's records come after that.

Every wait in tests/common/ and tests/toyos.rs was read (await_guest, await_marker, drain_until, await_exit, run_test, and each reader of boot_log()). Beside the six fixed:

tests/common/qemu.rs

• boot_with_options, on the boot log that ends at ===READY===: boot: root= is kernel_main's; the build line is the supervisor's, a program's beside a program's.
• run_test_paced: a result's stdout holds programs' lines only (push_user_half files a kernel line out), and its window already moves the kernel's spawn record in by name.

tests/common/faults.rs

• nested_nmi_is_loud: the fatal path's own raw lines up to its own arm line; no program's.

tests/common/iommu.rs

• declining_is_not_free, on the boot log: Boot: complete, the refused feature sets and the console's access_platform=y are all kernel_main's device bring-up.
• iommu_virtio_platform, the rest: Boot: complete, the PCI walk and the kernel's own VirtIO: PCI lines are kernel_main's; netstack's feature line was already waited for.

tests/common/power.rs

• machine_shutdown: waits for the kernel's record and asserts nothing else on that capture.
• ended, and what follows it in acpi_power_button, machine_shutdown_short_stop and ended_through_psci's callers (virt_smp, virt_reboot, virt_off_names_the_cpus_left_on): read after QEMU has exited, past the stop.
• Every metal judge here and in metal.rs, audio.rs, claims.rs, isa.rs, usb.rs, irqcensus.rs: a readback, which is a finished boot.

tests/toyos.rs

• judge_virt_job: the job's line and test-runner's end of it, both programs'.
• acpi_mediated_access: waits for the kernel's lock record of the stop, which settle makes after the last word; the probe's lines went on the wire before that word.
• acpi_supply_outlives_holder, virt_mask_windows: wait for the last word.
• virt_failed_ap_leaves_no_hole: the SMP: lines are kernel_main's. (virt_smp's PSCI: and SMP: lines and its control-register lines likewise; only the joins were not.)
• console_image_boots: waits for the console's line and asserts only absences.
• virt_selftest, virt_user_mode, the_others_halt_first, virt_early_panic, virt_el2_drop, virt_early_fault: kernel records only.
• screen_loader_clears: the loader's lines only. screen_panic_muted, screen_fatal_halt_composited: no console. screen_fatal_behind_a_painter: read after QEMU has exited.
• netstack_socket_churn, bar_map_again: a program's line waited for, then run_test.
• run_debug_mode: asserts nothing.

Nothing was found outside the fence, so no issue is filed for the shape.

Gates, at 0c0a348e1 (this branch, main at 6776714db merged)

The head is f9006e888: git diff 0c0a348e1 f9006e888 --stat is that one issue file, +37 -2, so nothing below was run again. At it, cargo test --lib sourcegate exits 0 (10 passed).

Logs are named by round and step; each opens with its command and ends with its exit code. The host is a 14-core machine in power-saving mode running other worktrees' builds; an x86-64 guest and the EL2 virt profile run under TCG on it.

step	command	exit
r3-01	cargo test --test toyos-build -- --nocapture over the 14 tests the change reaches (below)	1: 13 passed, virt_smp stalled
r3-01b	cargo test --test toyos-build -- --nocapture virt_smp, alone	0
r3-05	cargo test --test toyos-checks	0
r3-06	cargo run -- --clippy	0
r3-07	cargo run -- --ci host	0 (Host: 78 step(s), all green)
r3-08	git status --porcelain --ignore-submodules=none after everything	0, prints nothing
r3-09	the 14 again	0: 14 passed, 14 total

The 14: machine_shutdown, machine_shutdown_short_stop, acpi_power_button, iommu_virtio_platform, and on the profiles tests/toyos.rs registers them under, virt_reboot_refused_without_psci, virt_smp, virt_el1_smp, virt_timer_preempts, virt_fp_isolation, virt_first_entry, virt_unmap_touch, virt_debug_refused, virt_readonly_copyout, virt_ring0_timer_in_syscall.

The red in r3-01, recorded with its load

FAIL virt_smp: STALLED: waiting for the job test_rs_counters_read to end — it went quiet, with nothing said while it was waited on. The guest, 8 CPUs under TCG, had passed every wait this change adds: its last lines are ===TEST_END unmap_touch exit=0===, ===TEST_START test_rs_counters_read=== and the kernel's spawn record of that job at 13.737 s, and then silence. Host load (1 min) was 30.40 when the run began and 50.09 when it ended, from other worktrees' builds; the guest booted after twelve of the other guests had ended, beside virt_el1_smp, the other 8-CPU TCG guest, which passed 11 s before this verdict. Alone a minute later at load 52.19 (r3-01b) it passed in 9 s, that job's line 0.4 s of guest time after the one before it; in the same group at load 24.75 (r3-09) it passed. It is a hang ceiling and not a line this change reads: the wait it stalled in is judge_virt_job's, which this branch does not touch, and no harness wait can reach into the guest. By CLAUDE.md a red seen only under load is a defect all the same. It is main's, and issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md already recorded it once, on virt_el1_smp; that file gains this occurrence here (f9006e888), with the line, the load, the wait, what differs from the first, and what is and is not known.

The negative controls

Round 3, the marker withheld at each of the two sites the review named: an uncommitted patch to the kernel each, posted below as a comment, applied with git apply --check, run once and reversed, r3-04 showing the tree clean after.

step	staging	exit	what it said	load (1 min) before, after
r3-02	C: sys_reboot refuses without its record	1	FAIL virt_reboot_refused_without_psci: STALLED: waiting for the kernel's refusal of the reboot — it went quiet, with ===TEST_END reboot exit=1=== on the console	47.86, 36.89
r3-03	D: the claim says nothing of ACPI mode	1	FAIL acpi_power_button: STALLED: waiting for the kernel's record of the mode it was handed over in — it went quiet, with the server's armed line on the console	36.89, 25.53

Each shows the new wait is the one that reads the record, and that it is bounded: the other marker came, the record did not, and the test ended by name after the guest's silence. Neither stages the race itself: a kernel record cannot be made late on the wire without changing klogd.

Round 2, at 50947bc56, staged the race for the short stop in acpiserver, and stands for the first row: the armed line said 3 s late turned the reverted fix red with the recorded failure word for word (r2-03, exit 1) and the fix green (r2-04, exit 0); the line withheld was STALLED: waiting for the ACPI server arming (r2-05, exit 1). r2-08 ran the three x86-64 power guests five times in a row at loads 49 to 63, each exit 0.

Why these stay guest tests

No test's behaviour changed: each judges what it judged, on QEMU's own machine. Only what the harness waits for before it reads moved.

Unsure of

• The three sweep sites were found by reading and never seen red. What held them is margin: each record is committed long before the program's line that ended the capture is queued. They are fixed because nothing in the code bounds how far klogd trails, which is the review's argument for the two it named.
• An absence read off a capture that ends at a program's line can miss a late record: virt_failed_ap_leaves_no_hole's "no CPU past the failed one joined", and must_be_clean on a boot log. That is a possible false green, not this criterion's false red, and is left.
• Two programs' lines with no cause between them, such as the supervisor's started netstack beside netstack's own lines in iommu_virtio_platform, rest on logkeeper writing in stamp order; left, as round 1's review judged that order sound.
• Two kernel records from different CPUs: drain_ordered skips a shard whose head is not yet committed, so their order on the wire is the stamps' only once both are committed. No site read here rests on it that I found.
• The stop's order rests on logkeeper answering the supervisor's flush inside its bound; where it does not, the supervisor says so and stops without it.
• Not run: the whole guest suite, and nothing on the T14.

🤖 Generated with Claude Code

https://claude.ai/code/session_01RvnWQFcMuGqTHYhvSnTe8A

[Japabu]

The negative control's patches (r1-03 to r1-06, r2-03 to r2-06), none committed. Each arm: git apply --check, git apply, cargo test --test toyos-build -- --nocapture machine_shutdown_short_stop, then git checkout -- of both files; the tree is clean after (r2-06, r2-10).

Stage A, the armed line said 3 s after \_S5 is handed (r2-03 with the fix reverted: exit 1; r2-04 with the fix: exit 0):

--- a/userland/acpiserver/src/main.rs
+++ b/userland/acpiserver/src/main.rs
@@ -102,6 +102,8 @@
     };
     server.arm();
     server.power_off = aml::load(&Claim(&server.dev), server.info.rsdp).handed;
+    std::thread::sleep(Duration::from_secs(3));
+    println!("acpiserver: armed: power button served, embedded controller none");
     server.serve();
 }
 
@@ -172,14 +174,6 @@
             self.run_queued();
         }
         self.dev.ack().expect("acpiserver: the claim's acknowledgement");
-        println!(
-            "acpiserver: armed: power button {}, embedded controller {}",
-            if self.served.power_button { "served" } else { "not the fixed one, so not served" },
-            match self.served.ec_gpe {
-                Some(gpe) => format!("on GPE {gpe:#x} at {:#x}/{:#x}", self.info.ec_command.port, self.info.ec_data.port),
-                None => "none".into(),
-            },
-        );
     }
 
     fn serve(&mut self) -> ! {

Stage B, the armed line never said (r2-05 with the fix: exit 1, STALLED: waiting for the ACPI server arming):

--- a/userland/acpiserver/src/main.rs
+++ b/userland/acpiserver/src/main.rs
@@ -172,14 +172,6 @@
             self.run_queued();
         }
         self.dev.ack().expect("acpiserver: the claim's acknowledgement");
-        println!(
-            "acpiserver: armed: power button {}, embedded controller {}",
-            if self.served.power_button { "served" } else { "not the fixed one, so not served" },
-            match self.served.ec_gpe {
-                Some(gpe) => format!("on GPE {gpe:#x} at {:#x}/{:#x}", self.info.ec_command.port, self.info.ec_data.port),
-                None => "none".into(),
-            },
-        );
     }
 
     fn serve(&mut self) -> ! {

The fix reverted is this branch's own diff of tests/common/power.rs, applied with git apply -R:

diff --git a/tests/common/power.rs b/tests/common/power.rs
index 7ba2ad806..43de9bf0d 100644
--- a/tests/common/power.rs
+++ b/tests/common/power.rs
@@ -92,10 +92,14 @@ pub fn machine_shutdown_short_stop(test_config: &Path) -> Result<(), String> {
     let boot = serial::Serial::boot(&qemu);
     boot.must_be_clean()?;
     let mut console = boot.text().to_string();
+    // A wait each: the server's line reaches the console through `logkeeper`
+    // and the kernel's record does not, so a capture that ends at either need
+    // not hold the other.
+    qemu::await_marker(&mut qemu, &mut console, ACPI_ARMED, "the ACPI server arming")?;
     qemu::await_marker(&mut qemu, &mut console, Q35_S5_SUPPLIED, "the ACPI server to hand the kernel \\_S5")?;
-    let armed = serial::Serial::named("boot", console.clone());
-    armed.must_say(ACPI_ARMED)?;
-    armed.must_say("acpi: the firmware handed this machine over in ACPI mode, so nothing is written")?;
+    // The kernel's own record, committed before the one just waited for.
+    serial::Serial::named("boot", console.clone())
+        .must_say("acpi: the firmware handed this machine over in ACPI mode, so nothing is written")?;
 
     let mut stop = qemu::QmpShutdown::open(qemu.qmp_socket(), qemu.budget(qemu::GUEST_QUIET));
     writeln!(qemu.stdin_mut(), "run test_rs_stop_short").expect("write to QEMU stdin");

[Japabu]

Review of wt/toyos-shortstop at 50947bc56 against origin/main at 6776714db (round 1). Read: both commits, the diff, tests/common/power.rs whole, the waits in tests/common/qemu.rs, kernel/src/log/console.rs and read.rs, userland/logkeeper/src/main.rs's round, userland/acpiserver/src/main.rs, the callers in tests/toyos.rs, and step logs r2-01 to r2-10. Nothing was built or run.

Net lines: +7 -3, all in tests; production 0.

BLOCKER

• tests/common/power.rs:621-625 — acpi_power_button still reads a kernel record off the capture its wait for a program's line ended, and no code orders the two — it is the defect this pull request fixes, mirrored. klogd takes at most CHUNK = 8 records and then up to 8 queued lines per hold of the wire (kernel/src/log/console.rs:121, :418-419), so a queued program line goes on the wire ahead of every record past the eighth pending, however long ago that record was committed; nothing bounds how far klogd trails. logkeeper reads the kernel's ring on its own cursor and never waits on klogd's. What holds the order today is margin, not a guarantee: the record is committed at the supervisor's claim, and the armed line reaches the queue only after the server is spawned, arms, and a logkeeper round has written and made the file durable (logkeeper/src/main.rs:277-287, write then feed_console). Measured on the step logs, not staged: in all 36 boots of r1-02, r1-08, r2-02, r2-08 (host load 42 to 110) no kernel record stamped before the armed line reached the console after it, so klogd trailed by 0 records each time. That is why it has not been seen red; it is not what makes it unable to be. A test whose verdict rests on a scheduling margin is red under some load, and the fix is the one this branch already makes four lines up: wait for the record (qemu::await_marker on the ACPI-mode line), then read it.
• tests/toyos.rs:2200-2203 — virt_reboot_refused_without_psci has the same shape and the body clears it with the same argument ("the kernel's road is the shorter one"): it waits for test-runner's ===TEST_END reboot and then demands REBOOT_REFUSED, a kernel record (kernel/src/syscall/machine.rs:163), on that capture. Same CHUNK interleave, same absence of a guarantee, same one-line wait. The body's sweep says one site had the defect; by the code it is three.

Judged and found sound

• The fix adds no flat wait. Both waits are await_marker → await_guest, ended by the marker, by GUEST_QUIET of silence, or by budget(GUEST_WEDGED); the only fixed interval is the harness's existing 200 ms drain slice.
• In machine_shutdown_short_stop itself the remaining snapshot read is an order the code guarantees: the ACPI-mode record and the power: S5 is record are both kernel records, the first is committed before the claim returns and so before the second is reserved, the guest has one CPU and so one shard, and drain_ordered hands a shard's records out in sequence and stops at the first uncommitted one (kernel/src/log/read.rs:180-222). A capture that holds the second holds the first.
• The negative control stands. r2-03 (fix reverted, stage A): exit 1, "acpiserver: armed: power button served, embedded controller none" never reached the boot:, with the kernel's record on the console and the armed line not. r2-04 (fix, stage A, same staged server binary, 1001992 bytes in both): exit 0, record at 13.898, armed line at 16.904, ===TEST_START test_rs_stop_short=== after it. r2-05 (fix, stage B): exit 1, STALLED: waiting for the ACPI server arming — it went quiet, 15 s after ===READY===. r2-06 and r2-10: tree clean.
• Sweep, spot-checked: machine_shutdown asserts nothing on its waited capture; power::ended reads after QEMU exits; judge_virt_job compares two programs' lines, which logkeeper's round orders by stamp under its cut (logkeeper/src/main.rs:367-462). Those three hold. The two above do not.
• Evidence at 50947bc56: r2-01 exit 0 (36 passed), r2-02 exit 0 (3 passed), r2-07 exit 0 (24 invocations clean), r2-08 runs 1 to 5 exit 0 (3 passed each), r2-09 cargo run -- --ci host exit 0 (Host: 78 step(s), all green). The body's load figures match the logs. The merge base is origin/main's tip.

NOTE

• Pull request body, "The same shape elsewhere" — "One site had the defect, the one fixed" is false of the tree once the two sites above are counted; the orchestrator corrects it with the new head.

What the landing head must show

The fix changes the head, so every measurement is retaken there: cargo run -- --ci host exit 0, and acpi_power_button, machine_shutdown, machine_shutdown_short_stop and virt_reboot_refused_without_psci green, the last on the profile tests/toyos.rs runs it under. On GitHub, at that exact head SHA: host concluded success (today it is SKIPPED, a draft, which is not a measurement), and guest / suite concluded success with those four tests PASS by name in its log, read from the job's log and not from the check's colour. guest / suite under KVM says nothing about the race either way; the staged control is what does, and it stands for the short stop. With the two waits added and a round 2 that closes both BLOCKERs, the orchestrator may land on reading those two checks; the whole guest suite need not be run locally for a change confined to three tests' waits.

SEND BACK

[Japabu]

Answer to the round-1 review, at 0c0a348e1 (was 50947bc56). The body is rewritten for this head; step logs are r3-*.

BLOCKER 1: acpi_power_button reads the kernel's ACPI-mode record off the capture its armed-line wait ended

Fixed as named. After the wait for acpiserver's armed line it waits for the record with qemu::await_marker (the line now a constant, HANDED_OVER_IN_ACPI_MODE, which machine_shutdown_short_stop reads too) and the snapshot must_say is gone. Measured: acpi_power_button PASS in r3-01 and r3-09; with the record withheld (stage D below, r3-03) exit 1, STALLED: waiting for the kernel's record of the mode it was handed over in, the server's armed line on the console.

BLOCKER 2: virt_reboot_refused_without_psci demands REBOOT_REFUSED on the capture its TEST_END wait ended

Fixed as named: a second await_marker on REBOOT_REFUSED, then the exit code read off the job's end. Measured on VirtEl2, the profile tests/toyos.rs registers it under: PASS in r3-01 and r3-09; with the record withheld (stage C below, r3-02) exit 1, STALLED: waiting for the kernel's refusal of the reboot, ===TEST_END reboot exit=1=== on the console.

The sweep, with the review's criterion

Every wait in tests/common/ and tests/toyos.rs read again; the body lists each site and why it is or is not the shape. Three more had it and are fixed the same way:

• virt_smp, virt_el1_smp: each CPU's CPU n: joining scheduler, said after the machine is released, read off the capture ===TEST_END unmap_touch ended.
• virt_job (seven tests): the kernel's record of logkeeper's spawn, which bootlog::one_clock owes, read off the capture ===TEST_END <job> ended.
• iommu_virtio_platform: the kernel's records of the claim, read off the capture the daemons' lines ended; they join the lines its one wait already asked for.

What the sweep cleared, it cleared on one of two orders the code does make: a record kernel_main makes is drained inline before klogd and any program exist, and a stop puts every queued line on the wire before the kernel's last word. Round 1's "the kernel's road is the shorter one" is gone from the body.

NOTE: "One site had the defect"

Corrected: the body says six, and which were seen red (one) and which found by reading (five).

Measured at 0c0a348e1

step	what	exit
r3-01	the 14 guest tests the change reaches	1: 13 passed, virt_smp stalled
r3-01b	virt_smp alone	0
r3-02	stage C, virt_reboot_refused_without_psci	1, by name
r3-03	stage D, acpi_power_button	1, by name
r3-04	tree after the controls	clean
r3-05	cargo test --test toyos-checks	0
r3-06	cargo run -- --clippy	0
r3-07	cargo run -- --ci host	0
r3-09	the 14 again	0: 14 passed

The red in r3-01 is virt_smp: STALLED: waiting for the job test_rs_counters_read to end — it went quiet: the guest went silent after the kernel's spawn record of that job, past every wait this change adds, at host load 30 rising to 50. It is a hang ceiling in a wait this branch does not touch; the body records it with its load, and it is not yet in issues/, which is outside this branch's fence.

The control patches

Neither is committed. Each was applied with git apply --check, run once, and reversed.

Stage C, the reboot's refusal record withheld:

--- a/kernel/src/syscall/machine.rs
+++ b/kernel/src/syscall/machine.rs
@@ -160,7 +160,6 @@
         return e.refuse();
     }
     if !power::can_reboot() {
-        log!("reboot: this machine has no reset this kernel performs — refused");
         return SyscallError::NotSupported.to_u64();
     }
     if let Err(e) = quiesce("Rebooting.") {

Stage D, the ACPI-mode record withheld:

--- a/kernel/src/arch/x86_64/acpi_mode.rs
+++ b/kernel/src/arch/x86_64/acpi_mode.rs
@@ -352,7 +352,6 @@
         if ENABLED.load(Ordering::Relaxed) {
             log!("acpi: this machine is still in ACPI mode after an ACPI_DISABLE its firmware did not act on, so nothing is written");
         } else {
-            log!("acpi: the firmware handed this machine over in ACPI mode, so nothing is written");
         }
         return Ok(());
     }

[Japabu]

Review of wt/toyos-shortstop at 0c0a348e1 against origin/main at 6776714db (round 2). Read: git diff 50947bc56 0c0a348e1, the commit, tests/common/iommu.rs whole, the changed functions and their callers in tests/toyos.rs and tests/common/power.rs, await_guest and Liveness in tests/common/qemu.rs, klogd's loop in kernel/src/log/console.rs, ap_idle in kernel/src/process.rs, the tail of kernel_main, bootlog::one_clock, issues/, and step logs r3-00 to r3-09. Nothing was built or run.

Net lines against main: +52 -21 in three files, all tests; production 0. Accepted: each added wait is the one the defect needs, and not_handed_over replaces two spellings of one line with one.

Round 1's findings

• BLOCKER 1, acpi_power_button — CLOSED. tests/common/power.rs:627-628 waits for the armed line and then for HANDED_OVER_IN_ACPI_MODE; the snapshot read is gone. r3-01 and r3-09: PASS acpi_power_button. r3-03 (stage D, the record withheld): exit 1, STALLED: waiting for the kernel's record of the mode it was handed over in — it went quiet, with acpiserver: armed: power button served, embedded controller none on that console at 10.887. r3-04: tree clean.
• BLOCKER 2, virt_reboot_refused_without_psci — CLOSED. tests/toyos.rs:2210-2215 waits for the job's end and then for REBOOT_REFUSED, and reads the exit code off the capture. r3-01 and r3-09: PASS. r3-02 (stage C): exit 1, STALLED: waiting for the kernel's refusal of the reboot — it went quiet, with ===TEST_END reboot exit=1=== on that console at 6.892.
• NOTE, "One site had the defect" — CLOSED. The body says six and which was seen red.

The three sweep sites

Each is the same defect, fixed the same way, and none adds a wait that can stall a healthy boot.

• virt_smp, virt_el1_smp (tests/toyos.rs:1974-1977). The record is klogd's and not kernel_main's: kernel_main starts klogd and then calls smp::set_ready(), and ap_idle logs joining scheduler only after smp::is_ready() (kernel/src/process.rs:1849-1872). It was read off the capture ===TEST_END unmap_touch ended. The wait is now the assertion; the three kinds of line left on the snapshot (PSCI:, SMP:, the control registers) are made before klogd exists.
• virt_job (tests/toyos.rs:1674). one_clock owes the kernel's spawn: /system/bin/logkeeper record once the boot said Boot: complete; the supervisor makes that spawn, so it is klogd's, and it was read off the capture ===TEST_END <job> ended. one_clock still judges it.
• iommu_virtio_platform (tests/common/iommu.rs:71-85). The four kernel records added to the one wait are exactly the four the judges below must_say (bar_moved, msix_armed; the two NOT HANDED OVER), so the wait asks for nothing a passing boot did not already owe.

No flat wait: every one is await_marker or await_guest, ended by its marker, by GUEST_QUIET of silence or by budget(GUEST_WEDGED). None can stall a healthy boot: a wait whose marker is already in the capture returns at await_guest's first test without draining, and one whose record is still behind klogd is waiting on a klogd that re-arms and drains again while anything is pending (console.rs:446-451), so the guest is talking, not quiet. Every marker waited for is one the test already required.

The red in r3-01

The implementer is right, and the log settles it without inference.

• virt_smp was that run's [serial 14]. Its seven CPU n: joining scheduler records reached the harness at 00:03:37 (guest 11.723 to 11.762), before ===READY=== (00:03:38) and before ===TEST_END unmap_touch exit=0=== (00:03:39). All seven were in serial when judge_virt_job("unmap_touch") returned, so each of this round's seven waits returned at its first test: no drain, no time, nothing read.
• The harness printed [virt] 8 CPUs entered at EL2, started through SMC, and scheduling at 00:03:39. That line follows the new waits, so the test was past every line this branch changed.
• The stall is judge_virt_job(…, "test_rs_counters_read", …) at tests/toyos.rs:1985: FAIL at 00:03:54, fifteen seconds after 00:03:39, with what the guest said while it was waited on empty. The last line the guest ever put on the wire is [13.737 cpu4 kernel] spawn: /system/bin/test_rs_counters_read pid=13.
• A new wait cannot have consumed or reordered what that wait needs: serial is one string that only grows, every await_marker scans it from byte 0, and a drain appends. Nor can it have used up a quiet bound: each await_guest builds its own Liveness, whose 15 s count from that wait's own start.

It is already in issues/, on main: issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md, kind: defect, opened 2026-10-04 — test_rs_counters_read in tests/virtsmpcase, 8 vCPUs under TCG, load 38 to 53, the 15 s quiet bound. No new issue is filed: a second file would be a sibling of that one. That file gains this occurrence, stating:

• The line: FAIL virt_smp: STALLED: waiting for the job test_rs_counters_read to end — it went quiet, at 0c0a348e1, whose diff touches no line of that wait and none the guest runs.
• The load: 14 tests 12 wide on the 14-core host, 1-minute load 30.40 when the run began and 50.09 when it ended, from other worktrees' builds; liveness ceilings paid at 4.98x; workers 1440 s building against 1072 s testing.
• The wait: judge_virt_job's await_marker on ===TEST_END test_rs_counters_read , ended by GUEST_QUIET, which is 15 s of wall clock and is not paid out for host speed or guest width as GUEST_WEDGED is.
• What is new against the file: it is the first on virt_smp (EL2, SMC), where the recorded silent one was virt_el1_smp; and the silence begins straight after the job's first spawn record, with no thread's exit on the console, where the recorded one showed two exits first.
• What is known: virt_el1_smp, the same case booted one second later beside it, did the same step in about one second of wall clock (its end of the job at guest 15.908) and had exited by 00:03:43, so for the last eleven seconds of the silence no other guest of that run was alive. virt_smp alone at load 52.19 (r3-01b) and in the same group at load 24.75 (r3-09) passed: one silent boot in the five of that case this round.
• What is not known: whether the guest was running, spinning or not being scheduled by the host, and whether it was the guest or its console that stopped. No register capture exists, which is the one thing that file's exit asks for, so this occurrence adds a count and a second profile and moves the exit no closer.

It may be its own pull request and need not be in this one: the defect is main's, this branch neither causes nor touches it, and issues/ is outside this branch's fence. It is owed before the r3-01 log is removed, since that log is the only copy of the evidence.

NOTE

• Pull request body, "The red in r3-01" — "this one is not yet in issues/" is false of the tree: issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md records it. The orchestrator corrects the sentence to name that file.

What the landing head must show

Local evidence at 0c0a348e1 stands: r3-07 cargo run -- --ci host exit 0 (Host: 78 step(s), all green); r3-09 exit 0, 14 passed, 14 total, each of the 14 PASS by name; r3-05 exit 0; r3-06 exit 0; r3-08 clean. main has not moved since.

On GitHub, at the exact head SHA that lands: host concluded success, and guest / suite concluded success, both today SKIPPED on a draft, which is not a measurement. In the suite's log, read from the job and not from the check's colour, PASS by name for machine_shutdown, machine_shutdown_short_stop, acpi_power_button, iommu_virtio_platform, virt_reboot_refused_without_psci, virt_smp, virt_el1_smp, virt_timer_preempts, virt_fp_isolation, virt_first_entry, virt_unmap_touch, virt_debug_refused, virt_readonly_copyout and virt_ring0_timer_in_syscall. A red naming any wait this branch adds comes back to this branch. A red on the job test_rs_counters_read to end is the issue above: it is recorded there with the runner's load and is not re-run into a green. With both checks green and those fourteen read, the orchestrator may land; the whole guest suite need not be run locally for a change confined to tests' waits.

LAND

[Japabu]

CI at f9006e888, read from each job's own log (the orchestrator). host: [ci] Host: 79 step(s), all green. guest / suite: test result: ok. 36 passed, 36 total, with the fourteen tests the review named each PASS by name: machine_shutdown, machine_shutdown_short_stop, acpi_power_button, iommu_virtio_platform, virt_reboot_refused_without_psci, virt_smp, virt_el1_smp, virt_timer_preempts, virt_fp_isolation, virt_first_entry, virt_unmap_touch, virt_debug_refused, virt_readonly_copyout, virt_ring0_timer_in_syscall. No FAIL line. Queued.