From 73ad7e4eaee031a512deac39af0dfef3a3bc9cb4 Mon Sep 17 00:00:00 2001 From: japabu Date: Wed, 30 Sep 2026 16:18:47 +0200 Subject: [PATCH 01/19] Every QEMU ceiling is at most three times what its test was measured to take The rule is stated once, at `qemu::budget_smp`: a ceiling is at most three times the slowest the test it bounds was measured to take in the whole-suite runs on the dev host at the default width, whose times already carry the guests a test shares that host with. A wait is bounded by that multiple of its whole test, the one number measured. `host_scale` still widens it on a slower host and `oversubscription` for a guest wider than the host; nothing else does. The evidence is the orchestrator's six whole-suite logs (536r20, 536r21, 588r3, 633-x86, 633r2, 634: 495-499 tests each, 272-1000 s), the slowest PASS of each test across them. What moved: - The phase width no longer multiplies a ceiling. At 12 wide it made every number in the source twelve times itself; `port_poll_churn`'s 5 s became 263 s of guard (with an early host scale of 4.4) before it was called stalled. The measured times already carry the width, so `WIDTH` and `set_width` are deleted, and `round_trip`, which existed only to not be width-scaled, is `qemu.budget` now. - A guest still talking at twice its ceiling is timed out. The backstop was `ceiling.max(GUEST_WEDGED)`, so every chatty stall cost 300 s. - A boot's ceiling is 30 s, three times the slowest test that is one boot and one trivial command (10 s); it was 10 s times max(width, 2), 120 s at 12 wide. - The shared boot's members: 5 s (every member measured at 1.5 s or under), with mutual_kill 47, poll_wake_pipe 17, process_stats 11, abuse_elf_loader and toybox_file_tools 8; `disk_backtrace`'s 15 s override went (0.15 s at most). C members 2 s (0.54 s at most), from 10. - Every mapped wait: at most three times its test's slowest whole run. Cut where the literal was above that (doom_frames 300 -> 77, metal_sim_* 240 -> 74 and 14, cache_eviction 180 -> 59, blockd's 600 -> 152 and 251, ...); raised where a width-scaled wait sat under its own test's measured time and had only passed on the width's twelve-fold (toolkit_iced 30/60 -> 332, blocking_read_window 30 -> 179, mkdir_cap 60 -> 188, i8042_health 20 -> 164, metal_sim_pointer_churn 20 -> 92, kernel_log_file 10 -> 56). Waits that were never width-scaled keep any literal under the rule, since every measured run passed inside it. - Tests that wait out a deadline arm a shorter one: `boot-deadline=8000` for the wedges (15000), `boot-deadline=12000` for the hard lockup (30000, whose half stays above the probe's 3 s reach). - readdir_bound's `/home` arm lists one past the bound (16,385 files) rather than one past the old walk's doubling (32,769): the doubling is the bcachefs host test `a_tree_past_the_ceiling_is_refused_before_it_materialises`, with the allocator's peak as its instrument. Its ceiling is three times its slowest run, 442 s on #536's file server. Untouched: the redlisted tests (no measurement), `GUEST_WEDGED` and `GUEST_QUIET` (the `Liveness` waits have no per-test number; 300 s is under twice the slowest test that uses one), the QMP plumbing's own bounds, and pacing drains. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- tests/checks.rs | 5 +- tests/checks/qemu.rs | 30 +--- tests/common/blockd.rs | 8 +- tests/common/clang.rs | 2 +- tests/common/console.rs | 2 +- tests/common/devices.rs | 2 +- tests/common/https.rs | 2 +- tests/common/iommu.rs | 4 +- tests/common/lan.rs | 2 +- tests/common/logread.rs | 2 +- tests/common/logstream.rs | 9 +- tests/common/origin.rs | 22 +-- tests/common/partclaim.rs | 8 +- tests/common/pkg.rs | 4 +- tests/common/power.rs | 15 +- tests/common/qemu.rs | 164 +++++------------- tests/common/storage.rs | 4 +- tests/common/swap.rs | 2 +- tests/common/usb.rs | 2 +- tests/common/volumes.rs | 14 +- tests/common/wallclock.rs | 4 +- .../toyos-rust-tests/src/bin/readdir_bound.rs | 17 +- tests/toyos.rs | 152 +++++++--------- 23 files changed, 174 insertions(+), 302 deletions(-) diff --git a/tests/checks.rs b/tests/checks.rs index 4830557dc6a..eabe8b0ca22 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -150,8 +150,9 @@ mod checks { // gate asserting against a string nothing produces any more. let real = format!("{STALLED} waiting for the long tone to start — it went quiet"); let under_a_sentence = format!("the compositor stopped painting\n{real}"); - let past = qemu::GUEST_WEDGED + Duration::from_secs(1); - let backstop = qemu::ceiling_verdict(None, past, qemu::GUEST_WEDGED, Duration::from_secs(1), 900) + let ceiling = Duration::from_secs(5); + let past = ceiling * 2 + Duration::from_secs(1); + let backstop = qemu::ceiling_verdict(None, past, ceiling, Duration::from_secs(1), 900) .ok_or("a guest talking past the backstop was given no verdict")?; let cases: [(&str, Option<&str>, bool); 5] = [ ("an ordinary red", Some("the pointer never moved right"), false), diff --git a/tests/checks/qemu.rs b/tests/checks/qemu.rs index f4b8dd0339e..7ec2308915e 100644 --- a/tests/checks/qemu.rs +++ b/tests/checks/qemu.rs @@ -31,8 +31,7 @@ pub fn host_scale_self_check() -> Result<(), String> { } // Finite in the worst case the suite can reach: eight vCPUs on a single // core is 8x, not unbounded — so a genuine hang still reports in bounded - // time. `budget_smp` composes this with `budget`'s own capped host_scale - // (<=8x) and phase width, and on the `--jobs 1` runner width is 1. + // time. `budget_smp` composes this with the capped host_scale (<=8x). if oversub_ratio(8, 1) != (8, 1) { return Err(format!("the worst suite case must stay finite at 8x, got {:?}", oversub_ratio(8, 1))); } @@ -131,9 +130,9 @@ pub fn ceiling_self_check() -> Result<(), String> { if !stall.starts_with(STALLED) { return Err(format!("a genuine stall stopped reporting as one: {stall}")); } - // And the other end of the same guard: a guest still talking at the ceiling - // was working, and that is a different red. - let Some(slow) = ceiling_verdict(None, CEILING + Duration::from_secs(1), CEILING, talking, 900) + // And the other end of the same guard: a guest still talking at twice the + // ceiling was working, and that is a different red. + let Some(slow) = ceiling_verdict(None, CEILING * 2 + Duration::from_secs(1), CEILING, talking, 900) else { return Err(String::from("an expired guard on a talking guest returned no verdict")); }; @@ -151,8 +150,7 @@ pub fn ceiling_self_check() -> Result<(), String> { // guard still fires, and fast; and the backstop still catches a guest // that talks forever. const TIGHT: Duration = Duration::from_secs(153); - let bstop = TIGHT.max(GUEST_WEDGED); - assert!(TIGHT < bstop, "the case needs a ceiling below the backstop"); + let bstop = TIGHT * 2; // (a) The flake itself: `launcher_refusals` at `192s "still talking 1s ago"` // on a loaded smp:2 runner. Past its 153 s budget, but talking — no // verdict, it runs on. @@ -164,7 +162,8 @@ pub fn ceiling_self_check() -> Result<(), String> { )); } // (b) The backstop still bites a guest that is stuck *and* chatty: past - // `GUEST_WEDGED`, still talking, it is the one thing silence cannot catch. + // twice its ceiling, still talking, it is the one thing silence cannot + // catch. let Some(forever) = ceiling_verdict( None, bstop + Duration::from_secs(1), @@ -179,7 +178,7 @@ pub fn ceiling_self_check() -> Result<(), String> { } // (c) Negative control — the wedge guard still fires, and *fast*: a guest // silent past its budget is caught the moment it passes, at 154 s, not - // held to the 300 s backstop. + // held to the backstop. let Some(wedged) = ceiling_verdict(None, TIGHT + Duration::from_secs(1), TIGHT, GUEST_QUIET, 40) else { return Err(String::from( @@ -200,19 +199,6 @@ pub fn ceiling_self_check() -> Result<(), String> { )); } - // 3c. **The other side of `ceiling.max(GUEST_WEDGED)`**: a ceiling *above* - // `GUEST_WEDGED` must itself be the backstop, not get clamped down to - // the floor. `CEILING` (380 s, from case 1) is such a ceiling; a guest - // talking past `GUEST_WEDGED` (300 s) but still short of `CEILING` is - // not yet at its backstop and must run on. - if ceiling_verdict(None, GUEST_WEDGED + Duration::from_secs(50), CEILING, talking, 40).is_some() - { - return Err(String::from( - "a guest talking past GUEST_WEDGED but short of a higher ceiling was ended anyway — \ - the backstop did not follow a ceiling above GUEST_WEDGED", - )); - } - // 4. **What the verdict carries, which is the half that was missing.** Every // arm above names a death in one sentence; until 2026-08-18 that sentence // was the whole of what a failure arm had, and a `DOUBLE FAULT on CPU 1` diff --git a/tests/common/blockd.rs b/tests/common/blockd.rs index 40520cc34e3..af1925f2f42 100644 --- a/tests/common/blockd.rs +++ b/tests/common/blockd.rs @@ -377,7 +377,7 @@ pub fn blockd_serves_partitions( rust_bins: &[(String, Vec)], ) -> Result<(), String> { let (mut qemu, layout, disk, trace, before) = boot(c_bins, rust_bins, "blockd-serves", &[])?; - let claims = role(&mut qemu, "claims", Duration::from_secs(240))?; + let claims = role(&mut qemu, "claims", Duration::from_secs(152))?; for want in [ "an absent GUID refused with NotFound", "the zero GUID refused with NotFound", @@ -394,7 +394,7 @@ pub fn blockd_serves_partitions( if !cache.contains("present, so a flush issues Flush") { return Err(format!("blockd's controller reports no volatile write cache: {cache}")); } - let bench = role(&mut qemu, "bench", Duration::from_secs(600))?; + let bench = role(&mut qemu, "bench", Duration::from_secs(152))?; let numbers = said(&bench, "blockd_io: bench")?.to_string(); let tail = partclaim::shut_down(qemu); partclaim::no_panic("on the way down", &tail)?; @@ -470,7 +470,7 @@ pub fn blockd_survives_its_death( said(&reset, want)?; } let reset_again = said(&reset, "went out again after the reset")?.to_string(); - let crash = role(&mut qemu, "crash", Duration::from_secs(600))?; + let crash = role(&mut qemu, "crash", Duration::from_secs(251))?; let crash_again = said(&crash, "went out again after the restart")?.to_string(); for want in [ "blockd: WITHHELD the device's answer to a write", @@ -658,7 +658,7 @@ pub fn blockd_lends_within_its_bound( ("dma-bound", "the next refused with ResourceExhausted"), ("dma-churn", "the device then read block 0 into it"), ] { - let result = role(&mut qemu, name, Duration::from_secs(240))?; + let result = role(&mut qemu, name, Duration::from_secs(233))?; lines.push(said(&result, want)?.to_string()); log.push_str(&result.before); log.push_str(&result.serial); diff --git a/tests/common/clang.rs b/tests/common/clang.rs index a0d45102394..d2cab16d15d 100644 --- a/tests/common/clang.rs +++ b/tests/common/clang.rs @@ -59,7 +59,7 @@ pub fn c_hello(rust_bins: &[(String, Vec)]) -> Result<(), String> { let config = root.join("tests/testcases"); let c_tests = [("hello".to_string(), elf)]; let mut qemu = QemuInstance::boot_with_options(&config, &c_tests, rust_bins, BootOptions::default()); - let result = qemu.run_test("test_c_hello", Duration::from_secs(60)); + let result = qemu.run_test("test_c_hello", Duration::from_secs(29)); if let Some(err) = &result.error { return Err(format!("{err}\n{}", result.stdout)); } diff --git a/tests/common/console.rs b/tests/common/console.rs index f81a2ed935e..3d07496ec50 100644 --- a/tests/common/console.rs +++ b/tests/common/console.rs @@ -18,7 +18,7 @@ use super::qemu::{BootOptions, QemuInstance}; /// A liveness guard and never the verdict: it only catches a guest that /// stopped answering. -const CEILING: Duration = Duration::from_secs(60); +const CEILING: Duration = Duration::from_secs(35); /// The last of a capture, for a failure message. fn tail(text: &str) -> String { diff --git a/tests/common/devices.rs b/tests/common/devices.rs index 40c5a1f4e6c..6ace0e63eb4 100644 --- a/tests/common/devices.rs +++ b/tests/common/devices.rs @@ -27,7 +27,7 @@ pub const JOBS: &[&str] = &["usbwrite", "usbread", "fbcheck", "fbfill", "fbread" pub const CONFIG: &str = "tests/metaldevicecase"; pub const BOOT: &str = "metaldevicecase"; -const WAIT: std::time::Duration = std::time::Duration::from_secs(120); +const WAIT: std::time::Duration = std::time::Duration::from_secs(77); /// The T14's judge: every record the inventory owes, every span against its /// ceiling, and the shutdown's own account of what it handed back. diff --git a/tests/common/https.rs b/tests/common/https.rs index 3819d1e024c..e0a2fb14fc0 100644 --- a/tests/common/https.rs +++ b/tests/common/https.rs @@ -244,7 +244,7 @@ fn fetch_in_guest( } fn run_guest(guest: &mut QemuInstance, command: &str) -> Result { - let result = guest.run_test(command, Duration::from_secs(120)); + let result = guest.run_test(command, Duration::from_secs(68)); if let Some(err) = &result.error { return Err(format!("{command}: {err}\n{}", result.stdout)); } diff --git a/tests/common/iommu.rs b/tests/common/iommu.rs index a07825a63ec..4e208dd662c 100644 --- a/tests/common/iommu.rs +++ b/tests/common/iommu.rs @@ -2094,7 +2094,7 @@ pub fn userdev_dma_fault( // And the machine is running. This is the assertion the whole stage is // for: a guest that answers here is one whose scheduler, spawn path and // IPC all survived a device being refused mid-flight. - let result = qemu.run_test("test_rs_log_origin", Duration::from_secs(60)); + let result = qemu.run_test("test_rs_log_origin", Duration::from_secs(56)); if let Some(err) = &result.error { return Err(format!( "the guest stopped answering after the fault: {err}\n{}\n{}", @@ -2167,7 +2167,7 @@ pub fn userdev_residue_is_its_own( ..Default::default() }; let mut qemu = QemuInstance::boot_with_options(test_config, &[], &bins, options); - let result = qemu.run_test("test_rs_userdev_residue", Duration::from_secs(60)); + let result = qemu.run_test("test_rs_userdev_residue", Duration::from_secs(41)); let mut log = Serial::boot(&qemu); log.push(&result.serial); if let Some(err) = &result.error { diff --git a/tests/common/lan.rs b/tests/common/lan.rs index 1c64312111b..85ef76d6846 100644 --- a/tests/common/lan.rs +++ b/tests/common/lan.rs @@ -68,7 +68,7 @@ const TALK_KEY: &str = "lantalk"; /// A liveness guard on a rehearsal guest that never opened its stream, never a /// verdict. -const TALK_CEILING: std::time::Duration = std::time::Duration::from_secs(120); +const TALK_CEILING: std::time::Duration = std::time::Duration::from_secs(41); /// The armed boot's judge: the kernel's own records, tied to the I219's /// hand-over, say whether a message it raised reached a CPU — whatever the PHY diff --git a/tests/common/logread.rs b/tests/common/logread.rs index ba10d353240..ee59fbf25bd 100644 --- a/tests/common/logread.rs +++ b/tests/common/logread.rs @@ -26,7 +26,7 @@ const GATE: &str = "log-gate"; const STORM_GATE: &str = "log-storm"; /// The whole run's ceiling: a gate that never finishes is what it reds. -const CEILING: Duration = Duration::from_secs(60); +const CEILING: Duration = Duration::from_secs(50); /// One boot's storm, as the guest reported it. struct Report { diff --git a/tests/common/logstream.rs b/tests/common/logstream.rs index e991aab264d..c3f468dab2f 100644 --- a/tests/common/logstream.rs +++ b/tests/common/logstream.rs @@ -193,7 +193,7 @@ pub fn stream( // Before any reader exists. let job = "test_rs_log_origin"; - let before = guest.run_test(job, Duration::from_secs(60)); + let before = guest.run_test(job, Duration::from_secs(44)); if before.exit_code != Some(0) { return Err(format!("{job} exited {:?}:\n{}", before.exit_code, before.stdout)); } @@ -208,7 +208,7 @@ pub fn stream( } // And after: a record written once the reader was already reading. let later = "test_rs_empty_dir_stat"; - let after = guest.run_test(later, Duration::from_secs(60)); + let after = guest.run_test(later, Duration::from_secs(44)); if after.exit_code != Some(0) { return Err(format!("{later} exited {:?}:\n{}", after.exit_code, after.stdout)); } @@ -243,9 +243,8 @@ pub fn stream( /// `logd`'s readers on the network at once (`serve.rs`'s `MAX_NETWORK_READERS`). const NETWORK_READERS: usize = 8; -/// A liveness guard on the flood reaching a reader: five megabytes through a -/// TCG guest's netd, as long as the flood job itself is given. -const FLOOD_CEILING: Duration = Duration::from_secs(300); +/// A liveness guard on the flood reaching a reader. +const FLOOD_CEILING: Duration = Duration::from_secs(131); /// What `logd` says as it lets a reader go that took no bytes it was owed. const LET_GO: &str = "logd: letting "; diff --git a/tests/common/origin.rs b/tests/common/origin.rs index fcc8cd09531..7636afa3e26 100644 --- a/tests/common/origin.rs +++ b/tests/common/origin.rs @@ -54,7 +54,7 @@ pub fn line(c_bins: &[(String, Vec)], rust_bins: &[(String, Vec)]) -> Re qemu::await_marker(&mut guest, &mut console, logstream::SERVING, "logd to open its port")?; let reader = logstream::reader(port, "log-program-line.txt")?; - let ran = guest.run_test(ORIGIN_JOB, Duration::from_secs(60)); + let ran = guest.run_test(ORIGIN_JOB, Duration::from_secs(38)); if ran.exit_code != Some(0) { return Err(format!("{ORIGIN_JOB} exited {:?}\n{}", ran.exit_code, ran.stdout)); } @@ -65,12 +65,12 @@ pub fn line(c_bins: &[(String, Vec)], rust_bins: &[(String, Vec)]) -> Re if !headed { return Err(format!("the console never carried {NONCE:?} under {RUNNER:?}\n{}", ran.serial)); } - if !reader.wait_for(NONCE, Duration::from_secs(60)) { + if !reader.wait_for(NONCE, Duration::from_secs(38)) { return Err(format!("the served log never carried {NONCE:?}")); } let file = logstream::shut_down(guest, &mut console, &staged)?; serial::Serial::named("the boot", console.as_str()).must_be_clean()?; - if !reader.wait_ended(Duration::from_secs(60)) { + if !reader.wait_ended(Duration::from_secs(38)) { return Err("the reader's connection had not ended once the guest was down".to_string()); } @@ -155,7 +155,7 @@ fn one_job_armed( /// netd said nothing (this boot runs no netd). A record it stamps `u64::MAX` /// is written before the machine stops, not parked until it does. pub fn forgery(c_bins: &[(String, Vec)], rust_bins: &[(String, Vec)]) -> Result<(), String> { - let (ran, log) = one_job("tests/testcases", "log-program-forgery", FORGER, Duration::from_secs(60), c_bins, rust_bins)?; + let (ran, log) = one_job("tests/testcases", "log-program-forgery", FORGER, Duration::from_secs(26), c_bins, rust_bins)?; if ran.exit_code != Some(FORGER_CODE as i32) { return Err(format!("{FORGER} exited {:?}\n{}", ran.exit_code, ran.stdout)); } @@ -250,7 +250,7 @@ pub fn forgery(c_bins: &[(String, Vec)], rust_bins: &[(String, Vec)]) -> /// one past the program's allowance, and the three add up to every line it /// wrote: a line lost without a count, or one written twice, is red. pub fn flood(c_bins: &[(String, Vec)], rust_bins: &[(String, Vec)]) -> Result<(), String> { - let (ran, log) = one_job("tests/testcases", "log-program-flood", FLOODER, Duration::from_secs(300), c_bins, rust_bins)?; + let (ran, log) = one_job("tests/testcases", "log-program-flood", FLOODER, Duration::from_secs(44), c_bins, rust_bins)?; if ran.exit_code != Some(0) { return Err(format!("{FLOODER} exited {:?}", ran.exit_code)); } @@ -323,7 +323,7 @@ pub fn refused_stop(c_bins: &[(String, Vec)], rust_bins: &[(String, Vec) "log-refused-stop", REFUSED_JOB, &["power-refused-once"], - Duration::from_secs(60), + Duration::from_secs(32), c_bins, rust_bins, )?; @@ -380,7 +380,7 @@ pub fn resume_meets_its_flush(rust_bins: &[(String, Vec)]) -> Result<(), Str ..Default::default() }, ); - let mut stop = qemu::QmpShutdown::open(guest.qmp_socket(), guest.budget(Duration::from_secs(120))); + let mut stop = qemu::QmpShutdown::open(guest.qmp_socket(), guest.budget(Duration::from_secs(74))); let reason = stop.reason(); let tail = guest.drain_serial(Duration::from_secs(20)); drop(guest); @@ -506,7 +506,7 @@ const RETIRED: &str = "syscall 26 is retired"; /// them all in `/log` — and before the kernel's record of its exit. pub fn after_records(c_bins: &[(String, Vec)], rust_bins: &[(String, Vec)]) -> Result<(), String> { let (ran, log) = - one_job("tests/testcases", "log-hold", HOLD_JOB, Duration::from_secs(60), c_bins, rust_bins)?; + one_job("tests/testcases", "log-hold", HOLD_JOB, Duration::from_secs(29), c_bins, rust_bins)?; if ran.exit_code != Some(0) { return Err(format!("{HOLD_JOB} exited {:?}\n{}", ran.exit_code, ran.stdout)); } @@ -570,17 +570,17 @@ pub fn carrier_forgery(c_bins: &[(String, Vec)], rust_bins: &[(String, Vec bool { /// Run one guest command that must succeed, answering its output. fn passed(qemu: &mut QemuInstance, log: &mut String, command: &str) -> Result { - let result = qemu.run_test(command, Duration::from_secs(120)); + let result = qemu.run_test(command, Duration::from_secs(56)); let output = format!("{}{}", result.stdout, result.serial); log.push_str(&result.before); log.push_str(&output); @@ -252,7 +252,7 @@ fn refused( command: &str, says: &str, ) -> Result<(), String> { - let result = qemu.run_test(command, Duration::from_secs(120)); + let result = qemu.run_test(command, Duration::from_secs(56)); let output = format!("{}{}", result.stdout, result.serial); log.push_str(&result.before); log.push_str(&output); diff --git a/tests/common/power.rs b/tests/common/power.rs index 538e5902422..36705712abd 100644 --- a/tests/common/power.rs +++ b/tests/common/power.rs @@ -1366,8 +1366,10 @@ fn silent_guest(qemu: &QemuInstance, tail: &str) -> String { /// here is the poll, the seal and the reset, and the bound is the one thing /// about the mechanism a boot may legitimately differ on. Wide enough that a /// `jobcase` boot reaches its shutdown syscall under TCG first, which -/// [`bootlog::WEDGE_STAGED`] above is the assertion about. -const WEDGE_DEADLINE: &str = "boot-deadline=15000"; +/// [`bootlog::WEDGE_STAGED`] above is the assertion about: several times the +/// latest such a boot has said `Boot: complete` in a whole suite, with its one +/// job after it. +const WEDGE_DEADLINE: &str = "boot-deadline=8000"; /// One CPU that has stopped taking interrupts ends the machine, from its own /// NMI, and the record names where it was standing. @@ -1477,11 +1479,12 @@ pub fn hard_lockup_ends_a_deaf_cpu( /// /// **Wider than [`WEDGE_DEADLINE`] and for the opposite reason.** The staged cpu /// goes deaf once the machine is up, so its bound starts running seconds after -/// the deadline's does; half of 30 s leaves it reaching its own bound with the -/// whole of the deadline's second half still ahead, which is what makes a page +/// the deadline's does; half of it leaves the lockup found with the deadline's +/// second half, less that start, still ahead, which is what makes a page /// reading [`bootlog::LOCKED_UP`] rather than [`bootlog::DEADLINE_EXPIRED`] a -/// fact about this detector and not a race between two of them. -const LOCKUP_DEADLINE: &str = "boot-deadline=30000"; +/// fact about this detector and not a race between two of them. Its half is +/// still longer than the probe's `REACH_THE_LOCK_NS`. +const LOCKUP_DEADLINE: &str = "boot-deadline=12000"; /// A boot that hung is bounded by the stick, and the third boot is free again. /// diff --git a/tests/common/qemu.rs b/tests/common/qemu.rs index 5149182ea10..dc0b662e655 100644 --- a/tests/common/qemu.rs +++ b/tests/common/qemu.rs @@ -192,46 +192,6 @@ pub fn boot_census() -> (u32, u32, Vec) { pub const DECLARED_KERNEL_BUILDS: [&str; 5] = toyos_build::build::TEST_SUITE_KERNEL_BUILDS; -/// How many guests the phase now running may have up at once. -/// -/// The harness's own wall-clock margins are margins on the *host*, and they were -/// all derived when one guest had it to itself. Four guests is a different -/// machine, so such a margin has to be stated against the regime it runs in -/// rather than widened outright — which is what this multiplies. A serial phase -/// sets it back to 1 and gets the number it always had. -static WIDTH: AtomicU32 = AtomicU32::new(1); - -pub fn set_width(width: u32) { - assert!(width >= 1, "a phase runs at least one guest"); - WIDTH.store(width, Ordering::SeqCst); -} - -/// A liveness ceiling, stated for one guest and paid out for the phase's. -/// -/// Every timeout a test hands [`QemuInstance::run_test`] and its relatives is a -/// guard against a wedge, never a verdict: the assertion is what the guest -/// *said*, and a test whose pass depended on a deadline expiring would be -/// asserting on the host's clock. So the number in the source stays the number -/// its author reasoned about — one guest, this host — and the phase multiplies -/// it, exactly as `wait_for_ready` has multiplied the boot timeout since the -/// parallel phase landed. -/// -/// The cost of getting this wrong in the generous direction is that a wedge -/// takes longer to report. The cost in the other direction is a red run that -/// says a guest hung when it was only sharing a machine, which is the failure -/// mode that put the whole shared block in the serial tail. -/// -/// This corrects for width and for how fast the host is, both host-wide facts. -/// It does not correct for a guest being wider than the host — an `smp:8` guest -/// on a four-core runner is oversubscribed and a mostly-serial boot never -/// showed it — which is [`budget_smp`]'s job and [`QemuInstance::budget`]'s -/// default. Callers that hold a guest want that one, so its ceiling reflects -/// the vCPUs it actually asked for. -pub fn budget(one_guest: Duration) -> Duration { - let (num, den) = host_scale(); - one_guest * WIDTH.load(Ordering::SeqCst) * num / den -} - /// The fastest boot-to-ready this run has seen, in milliseconds. /// /// A boot is the one piece of guest work every test does and no test asserts on @@ -242,13 +202,9 @@ pub fn budget(one_guest: Duration) -> Duration { /// is the closest this can get to the machine with nothing else on it. static FASTEST_BOOT_MS: AtomicU32 = AtomicU32::new(u32::MAX); -/// The same measurement on the host every ceiling in this tree was written for. -/// -/// Dev host, M4 Pro, cross-arch TCG, measured 2026-08-08: the fastest of ten -/// boots at `--jobs 1` was 1433 ms against a 1433–2063 ms spread, and the -/// fastest of a whole 291-test suite at width 12 was this. The smaller of the -/// two is the one to hold, because the factor only widens and a reference set -/// too high is a correction that does not happen. +/// The fastest boot of the host the ceilings were measured on: at or above the +/// fastest boot of every run a ceiling in this tree was measured in, so that +/// host pays them at 1×. const REFERENCE_BOOT_MS: u32 = 1320; fn record_boot(took: Duration) { @@ -256,21 +212,12 @@ fn record_boot(took: Duration) { FASTEST_BOOT_MS.fetch_min(ms, Ordering::SeqCst); } -/// How much slower than the host these ceilings were written on this one is, as +/// How much slower than the host these ceilings were measured on this one is, as /// a fraction so that a 1.4× host is not rounded to 1. /// -/// [`budget`] corrects a ceiling for how many guests share the machine. It never -/// corrected for how fast the machine *is*, and that is the other half of the -/// same mistake: a number reasoned about on an M4 Pro is not a liveness ceiling -/// on a four-core Azure vCPU, it is a verdict about which of the two is running -/// the test. 307 bare timeouts were counted in one CI run and every one of -/// them was that. -/// -/// **Only ever upward.** On a faster host the number in the source stands, -/// because it is the number its author reasoned about, and a ceiling that shrank -/// would start reporting wedges that are not there. The ceiling of 8 is because -/// one anomalous boot must not be able to disable every liveness guard in the -/// suite at once. +/// **Only ever upward**, since a ceiling that shrank would report wedges that +/// are not there; and at most 8×, so one anomalous boot cannot disable every +/// guard in the suite at once. fn host_scale() -> (u32, u32) { let fastest = FASTEST_BOOT_MS.load(Ordering::SeqCst); // Before the first boot there is no measurement, and the sentinel must not @@ -351,28 +298,28 @@ fn oversubscription(smp: u32) -> (u32, u32) { oversub_ratio(smp, host_cores()) } -/// [`budget`] widened by a guest's own vCPU oversubscription. +/// A ceiling, paid out for the host and the guest it bounds. /// -/// The guest-agnostic [`budget`] scales by phase width and boot-derived host -/// speed; this multiplies in `smp/cores` on top, so a wide-SMP guest that a -/// mostly-serial boot said little about is given the extra room the derivation -/// above says it needs. `smp <= cores` leaves it exactly [`budget`], which is -/// every guest on the dev host. -pub fn budget_smp(one_guest: Duration, smp: u32) -> Duration { +/// **Every ceiling in this suite is three times the slowest the test it bounds +/// was measured to take**, in whole-suite runs on the host [`REFERENCE_BOOT_MS`] +/// describes, at the suite's default width — so a test's time already carries +/// the guests it shares that host with. A wait is bounded by that multiple of +/// its whole test, the one number measured; a guest still talking at twice its +/// ceiling is past it ([`ceiling_verdict`]). The source states that number, and +/// this pays it out on a slower host ([`host_scale`]) and for a guest wider than +/// this one ([`oversubscription`]), and for nothing else. +/// +/// A ceiling is a guard against a wedge and never a verdict: the assertion is +/// what the guest *said*. +pub fn budget_smp(ceiling: Duration, smp: u32) -> Duration { + let (num, den) = host_scale(); let (onum, oden) = oversubscription(smp); - budget(one_guest) * onum / oden + ceiling * num / den * onum / oden } /// A liveness guard that watches the guest instead of the host's clock. /// -/// [`budget`] corrects a ceiling for how many guests share the machine, which -/// is the part of "how fast is the host today" the harness knows. It does not -/// know the rest, and a retry loop bounded by elapsed time has that ceiling for -/// a *verdict* the moment the rest moves: a guest that is merely late reports -/// exactly what a wedged one reports. -/// -/// The two are distinguishable and the console is what distinguishes them: a -/// guest still printing is a guest still working. So the ceiling here is time in +/// A guest still printing is a guest still working. So the ceiling here is time in /// which **nothing arrived**, and a guest that keeps talking is given as long as /// it needs. That is the whole idea — no number in this type is a statement /// about the host. @@ -437,7 +384,7 @@ impl Liveness { /// second producer: a test's own ceiling is a guard of exactly this kind. pub const STALLED: &str = "STALLED:"; -/// The backstop's red: a guest still talking past [`GUEST_WEDGED`] that never +/// The backstop's red: a guest still talking at twice its ceiling that never /// finished. The ceiling too, and counted with [`STALLED`]'s. pub const TIMED_OUT: &str = "timed out after"; @@ -611,13 +558,10 @@ pub fn ceiling_verdict( ceiling.as_secs() )); } - // The absolute backstop, for a guest that is stuck *and* chatty and so never - // trips the silence guard — a suite that never ends is worse than one that - // reds. Never below the per-test ceiling, so a long test whose own budget - // already exceeds it is not cut short; never below [`GUEST_WEDGED`], the - // vetted stuck-and-chatty number a talking guest is judged by everywhere - // else. Not itself oversubscription-scaled — `ceiling` already carries that. - let backstop = ceiling.max(GUEST_WEDGED); + // The backstop, for a guest that is stuck *and* chatty and so never trips + // the silence guard: twice the ceiling, six times the slowest this test was + // ever measured. + let backstop = ceiling * 2; if elapsed > backstop { return Some(format!( "{TIMED_OUT} {}s, with the guest still talking {quiet:.0?} ago ({lines} \ @@ -3186,12 +3130,9 @@ impl QemuInstance { } /// Keep collecting serial output for `dur` after a test has returned. - /// **Not scaled by the width**, and it is the one duration in this file that - /// is not. Callers use it to *pace* — "let the guest run for 400 ms and tell - /// me what it said" — so multiplying it does not buy a slow guest more room, - /// it buys the test a longer sleep. `metal_sim_pointer_churn` has - /// twenty-four of these; scaled, they made it an 86 s job at width 8 and the - /// critical path of the whole phase. + /// **Not a ceiling, and not paid out as one**: callers use it to *pace* — + /// "let the guest run for 400 ms and tell me what it said" — so scaling it + /// would buy a test a longer sleep and a slow guest nothing. pub fn drain_serial(&mut self, dur: Duration) -> String { self.drain_for(dur, |_| false) } @@ -3273,17 +3214,9 @@ impl QemuInstance { self.sockets.segment.as_ref().expect("segment needs BootOptions { segment: true }").open() } - /// [`budget`] for a host-side wait on *this* guest, widened by the guest's - /// own vCPU oversubscription. - /// - /// A test that polls the framebuffer or drains serial in its own loop — - /// rather than through [`Self::run_test_paced`] — reaches for a deadline, - /// and a deadline is a claim about the host. The free [`budget`] cannot see - /// how wide this guest is; this can, so an `smp:8` guest's poll loop is - /// given the `smp/cores` extra room a mostly-serial boot never priced. On a - /// host with a core per vCPU it is exactly [`budget`]. - pub fn budget(&self, one_guest: Duration) -> Duration { - budget_smp(one_guest, self.smp) + /// [`budget_smp`] for a host-side wait on *this* guest. + pub fn budget(&self, ceiling: Duration) -> Duration { + budget_smp(ceiling, self.smp) } pub fn run_test(&mut self, name: &str, timeout: Duration) -> TestResult { @@ -4730,6 +4663,10 @@ fn publish_line( tx.send(line).is_ok() } +/// A boot's ceiling: [`budget_smp`]'s rule over the tests that are one boot and +/// one trivial command, the slowest of which took 10 s. +const BOOT_CEILING: Duration = Duration::from_secs(30); + /// Returns every line seen on the way to the marker — see [`QemuInstance::boot_log`]. fn wait_for_ready( child: &mut Child, @@ -4740,30 +4677,7 @@ fn wait_for_ready( let no_timeout = options.debug_wait; let ready = options.ready_marker; let panic_aborts = ready == DEFAULT_READY; - // Ten seconds per guest this phase may have up, and never fewer than two - // guests' worth — the tree runs 15-25 suites a day across several agents, - // so one guest on a quiet host stopped being - // the regime some time before this did. Measured on 2026-08-03 with other - // agents building: two boots exceeded the flat ten seconds, one of them in a - // phase running a single guest. - // - // A wedge costs that much longer to report and nothing else. - // - // Scaled by the host too, and the first boot of a run is the one that - // cannot be: nothing has been measured yet, so it gets the flat number and - // every boot after it gets the corrected one. Two boot timeouts in CI run - // `31233476555` were this — `console: ready` and `compositor: ready`, on a - // runner where the same boots take twice what they take here. - // - // And by this guest's own oversubscription: an `smp:8` guest brings up all - // eight vCPUs during boot, so on the four-core runner even the boot is - // `8/4` oversubscribed, which the boot-derived `host_scale` cannot fold in - // because it *is* what boot measured. `oversubscription` says why in terms - // of `vcpus/cores`; on a host with a core per vCPU it multiplies by one. - let (num, den) = host_scale(); - let (onum, oden) = oversubscription(options.smp); - let boot_timeout = - Duration::from_secs(10) * WIDTH.load(Ordering::SeqCst).max(2) * num / den * onum / oden; + let boot_timeout = budget_smp(BOOT_CEILING, options.smp); let start = Instant::now(); let mut seen = String::new(); loop { diff --git a/tests/common/storage.rs b/tests/common/storage.rs index fa49c2120c2..91c880f43a0 100644 --- a/tests/common/storage.rs +++ b/tests/common/storage.rs @@ -478,7 +478,7 @@ pub fn home_overwrite_reads_back( )); } - let result = qemu.run_test("test_rs_home_overwrite_zero", Duration::from_secs(240)); + let result = qemu.run_test("test_rs_home_overwrite_zero", Duration::from_secs(38)); let log = format!("{boot}\n{}{}{}", result.before, result.stdout, result.serial); let said = log.lines().find(|l| l.contains("HOME-OVERWRITE")).map(str::trim).map(String::from); let guest_len: Option = said @@ -579,7 +579,7 @@ pub fn apps_and_home_are_one_filesystem( )); } - let result = qemu.run_test("test_rs_hierarchy_paths", Duration::from_secs(60)); + let result = qemu.run_test("test_rs_hierarchy_paths", Duration::from_secs(47)); if result.exit_code != Some(0) { return Err(format!( "hierarchy_paths guest failed:\n{}\nkernel log while it ran:\n{}{}", diff --git a/tests/common/swap.rs b/tests/common/swap.rs index 2c50ba7d871..204cf2008fc 100644 --- a/tests/common/swap.rs +++ b/tests/common/swap.rs @@ -30,7 +30,7 @@ pub const VIRTIO: Bench = Bench { profile: qemu::Profile::Headless, config: "tests/swapcase", device: "virtio-net" }; /// A liveness guard on a guest that stopped talking, never a verdict. -const CEILING: Duration = Duration::from_secs(120); +const CEILING: Duration = Duration::from_secs(104); /// The swapping boot's one job on the T14: it holds the machine until the /// swap invocation hands it back. diff --git a/tests/common/usb.rs b/tests/common/usb.rs index dd21fa8dac3..7eb1dc5f943 100644 --- a/tests/common/usb.rs +++ b/tests/common/usb.rs @@ -3091,7 +3091,7 @@ pub fn xhci_flap( // Each move waits for the guest to print the one before it. let (mut ready, mut binds, mut mev) = (false, 0usize, 0usize); let mut input: Option = None; - let result = qemu.run_test_paced("test_rs_input_events", Duration::from_secs(60), |socket, line| { + let result = qemu.run_test_paced("test_rs_input_events", Duration::from_secs(47), |socket, line| { let qmp = || socket.expect("xhci_flap needs BootOptions { qmp: true }"); if line.contains("===INPUT_READY===") { ready = true; diff --git a/tests/common/volumes.rs b/tests/common/volumes.rs index 1e3938ebf0e..bf18a652c35 100644 --- a/tests/common/volumes.rs +++ b/tests/common/volumes.rs @@ -303,7 +303,7 @@ pub fn esp_filesystem( )); } - let result = qemu.run_test("test_rs_esp_files", Duration::from_secs(60)); + let result = qemu.run_test("test_rs_esp_files", Duration::from_secs(35)); if let Some(err) = &result.error { return Err(format!("the guest stopped answering: {err}\nserial:\n{}", result.serial)); } @@ -540,7 +540,7 @@ pub fn kernel_log_file( // up, and a stick slower than the runner puts its line after the marker. let opened = "logd: this boot's kernel log is"; if !boot.contains(opened) { - boot.push_str(&qemu.drain_until(Duration::from_secs(10), |line| line.contains(opened))); + boot.push_str(&qemu.drain_until(Duration::from_secs(56), |line| line.contains(opened))); } if !boot.contains(opened) { return Err(format!("logd never opened a file:\n{}", volume_lines(&boot))); @@ -937,7 +937,7 @@ pub fn writeback_durability( )); } - let result = qemu.run_test("test_rs_writeback_durability", Duration::from_secs(60)); + let result = qemu.run_test("test_rs_writeback_durability", Duration::from_secs(26)); if let Some(err) = &result.error { return Err(format!("the guest stopped answering: {err}\nserial:\n{}", result.serial)); } @@ -1225,7 +1225,7 @@ pub fn fat_backing_revoked( )); } - let result = qemu.run_test("test_rs_fat_backing_revoked", Duration::from_secs(60)); + let result = qemu.run_test("test_rs_fat_backing_revoked", Duration::from_secs(59)); if let Some(err) = &result.error { return Err(format!("the guest stopped answering: {err}\nserial:\n{}", result.serial)); } @@ -1422,7 +1422,7 @@ pub fn redirty_mid_flush( )); } - let result = qemu.run_test("test_rs_redirty_mid_flush", Duration::from_secs(120)); + let result = qemu.run_test("test_rs_redirty_mid_flush", Duration::from_secs(80)); if let Some(err) = &result.error { return Err(format!("the guest stopped answering: {err}\nserial:\n{}", result.serial)); } @@ -1635,7 +1635,7 @@ pub fn fs_rename_durable( )); } - let result = qemu.run_test("test_rs_fs_rename_durable", Duration::from_secs(60)); + let result = qemu.run_test("test_rs_fs_rename_durable", Duration::from_secs(56)); if let Some(err) = &result.error { return Err(format!("the guest stopped answering: {err}\nserial:\n{}", result.serial)); } @@ -1752,7 +1752,7 @@ pub fn fs_dirs_durable( )); } - let result = qemu.run_test("test_rs_fs_dirs_durable", Duration::from_secs(60)); + let result = qemu.run_test("test_rs_fs_dirs_durable", Duration::from_secs(56)); if let Some(err) = &result.error { return Err(format!("the guest stopped answering: {err}\nserial:\n{}", result.serial)); } diff --git a/tests/common/wallclock.rs b/tests/common/wallclock.rs index 566685c35bc..16e7908de8d 100644 --- a/tests/common/wallclock.rs +++ b/tests/common/wallclock.rs @@ -477,7 +477,7 @@ fn mtime_boot( if boot.contains("are a tmpfs") { return Err(format!("/home fell back to tmpfs, so no file of it outlives the boot:\n{boot}")); } - let result = qemu.run_test(&format!("test_rs_file_mtime {mode} {MTIME_PATH}"), Duration::from_secs(60)); + let result = qemu.run_test(&format!("test_rs_file_mtime {mode} {MTIME_PATH}"), Duration::from_secs(50)); let printed = printed_mtime(&result); writeln!(qemu.stdin_mut(), "run shutdown").expect("write to QEMU stdin"); qemu.flush_stdin(); @@ -573,7 +573,7 @@ pub fn file_mtime_undated( clock_lines(&boot) )); } - let result = qemu.run_test("test_rs_file_mtime undated", Duration::from_secs(60)); + let result = qemu.run_test("test_rs_file_mtime undated", Duration::from_secs(29)); writeln!(qemu.stdin_mut(), "run shutdown").expect("write to QEMU stdin"); qemu.flush_stdin(); let tail = qemu.drain_serial(Duration::from_secs(20)); diff --git a/tests/toyos-rust-tests/src/bin/readdir_bound.rs b/tests/toyos-rust-tests/src/bin/readdir_bound.rs index c2ab6952483..59126ddd902 100644 --- a/tests/toyos-rust-tests/src/bin/readdir_bound.rs +++ b/tests/toyos-rust-tests/src/bin/readdir_bound.rs @@ -9,9 +9,8 @@ //! success. A bound plus a silent truncation is a quieter version of the same //! defect, so both are asserted here. //! -//! `/home` gets the same class third: its btree walk crossed the kernel's -//! allocation ceiling past 32,768 entries (a panic from ordinary `create`s) -//! and now refuses at the bound first. All below is an ordinary workload. +//! `/home` gets the same bound third, on the btree walk bcachefs lists with. +//! All below is an ordinary workload. use std::fs; use std::process::Command; @@ -26,11 +25,12 @@ const MAX_LIST_ENTRIES: usize = 16_384; /// truncating kernel returns about 4,000 of them. const PLAIN_ENTRIES: usize = 6_000; -/// One past where the unbounded `/home` walk's `Vec` doubled over the kernel's allocation ceiling. -const HOME_ENTRIES: usize = 32_769; +/// One past the bound: the walk is refused at the first entry over it, however +/// many the directory holds. +const HOME_ENTRIES: usize = MAX_LIST_ENTRIES + 1; fn main() { - home_tree_past_the_doubling_is_refused(); + home_past_the_bound_is_refused(); plain_entries_are_all_returned(); subdirectories_at_the_limit(); one_past_the_limit_is_refused(); @@ -40,9 +40,8 @@ fn main() { } /// First, while nothing else holds file-cache entries: the listing bound on -/// `/home` at the count that was a kernel death. The files stay — this boot is -/// the test's own. -fn home_tree_past_the_doubling_is_refused() { +/// `/home`. The files stay — this boot is the test's own. +fn home_past_the_bound_is_refused() { for i in 0..HOME_ENTRIES { fs::write(format!("/home/rb{i}"), b"").expect("create on /home failed"); } diff --git a/tests/toyos.rs b/tests/toyos.rs index 5041a9f4d63..c991375e8b6 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -84,10 +84,7 @@ const DEFAULT_WIDTH: usize = 12; /// tail because at width 4 `allocator_stress` went from 1 s to past its 5 s and /// `demand_paging_sse` past its — but not one of those numbers is an assertion. /// They are liveness guards on a guest that might wedge, and the verdict in -/// every case is the exit code and the expected stdout. [`qemu::budget`] now -/// pays them out per guest the phase may have up, which is what -/// `wait_for_ready`'s boot timeout has done since the phase existed, so the -/// number each author reasoned about is still the number for one guest. +/// every case is the exit code and the expected stdout. /// /// What that leaves is one boot's worth of tests costing about thirteen seconds /// between them, which is far too little to be worth a tail slot of its own: @@ -3639,7 +3636,7 @@ fn virt_selftest( }, ); let said = format!("{param}: "); - let rest = qemu.drain_until(Duration::from_secs(180), |l| l.contains(&said)); + let rest = qemu.drain_until(Duration::from_secs(23), |l| l.contains(&said)); let serial = format!("{}\n{rest}", qemu.boot_log()); let Some(verdict) = serial.lines().find(|l| l.contains(&said)) else { return Err(format!("{param} never reported\nserial:\n{serial}")); @@ -4151,7 +4148,7 @@ fn run_screen_test( metal_sim_argv_check(&qemu::profile_argv(&options))?; let mut qemu = QemuInstance::boot_with_options(&config, &[], &[], options); let console = qemu.boot_log().to_string(); - let dump = qemu.screendump_until(common::volumes::NO_LOG_ALERT, Duration::from_secs(30)); + let dump = qemu.screendump_until(common::volumes::NO_LOG_ALERT, Duration::from_secs(26)); let text = dump.text(); print_screen(name, &text); @@ -4837,7 +4834,7 @@ fn run_screen_test( // `console_type_line`. console_type_line(&mut qemu, &font, "test_rs_test_panic_child 3")?; - let dump = qemu.screendump_until(FATAL_HALT_NONCE, Duration::from_secs(40)); + let dump = qemu.screendump_until(FATAL_HALT_NONCE, Duration::from_secs(32)); let text = dump.text(); print_screen(name, &text); if !text.contains(FATAL_HALT_NONCE) { @@ -4955,8 +4952,8 @@ fn run_screen_test( QemuInstance::boot_with_options(test_config, c_bins, rust_bins, options); // Nothing announces the panic here — there is no console for a // marker to arrive on — so the screen is polled until it carries - // the report. 30s covers firmware plus the root filesystem read off USB. - let dump = qemu.screendump_until("PANIC:", Duration::from_secs(30)); + // the report. + let dump = qemu.screendump_until("PANIC:", Duration::from_secs(29)); let text = dump.text(); print_screen(name, &text); // The arm line is here and nowhere else: this is the machine whose @@ -5001,8 +4998,8 @@ fn run_screen_test( ..Default::default() }, ); - let dump = qemu.screendump_until("EARLY PANIC:", Duration::from_secs(30)); - let rest = qemu.drain_until(Duration::from_secs(10), |l| l.contains(EARLY_PANIC_MESSAGE)); + let dump = qemu.screendump_until("EARLY PANIC:", Duration::from_secs(8)); + let rest = qemu.drain_until(Duration::from_secs(8), |l| l.contains(EARLY_PANIC_MESSAGE)); let serial = format!("{}\n{rest}", qemu.boot_log()); // What stage 3 prints before it panics: every item is a record // only the AArch64 side of the loader or the kernel writes. @@ -5091,9 +5088,9 @@ fn run_screen_test( ..Default::default() }, ); - let dump = qemu.screendump_until("EARLY PANIC:", Duration::from_secs(30)); + let dump = qemu.screendump_until("EARLY PANIC:", Duration::from_secs(5)); const FAULT_MESSAGE: &str = "synchronous from EL1 on SP_EL1: unknown reason (an undefined instruction) at 0x"; - let rest = qemu.drain_until(Duration::from_secs(10), |l| l.contains(FAULT_MESSAGE)); + let rest = qemu.drain_until(Duration::from_secs(5), |l| l.contains(FAULT_MESSAGE)); let serial = format!("{}\n{rest}", qemu.boot_log()); for want in [ "KERNEL PANIC: synchronous from EL1 on SP_EL1: unknown reason (an undefined instruction)", @@ -5129,7 +5126,7 @@ fn run_screen_test( }, ); const SPAWNED: &str = "spawn: /system/bin/logd pid="; - let rest = qemu.drain_until(Duration::from_secs(180), |l| l.contains(SPAWNED)); + let rest = qemu.drain_until(Duration::from_secs(17), |l| l.contains(SPAWNED)); let serial = format!("{}\n{rest}", qemu.boot_log()); for want in [ "paging: the direct map holds memory below", @@ -5608,7 +5605,7 @@ fn run_screen_test( // holding the panel. Without this the test would prove that a // fatal panic paints a screen nobody had taken, which is what the // suite already knew. - let up = qemu.screendump_while(Duration::from_secs(30), Duration::from_millis(200), |d| { + let up = qemu.screendump_while(Duration::from_secs(95), Duration::from_millis(200), |d| { d.fill() != FILL_BOOT }); if up.fill() == FILL_BOOT { @@ -6318,7 +6315,7 @@ fn metal_sim_window_drag(rust_bins: &[(String, Vec)]) -> Result<(), String> let result = qemu.run_test_hooked( "test_rs_window_drag", - Duration::from_secs(120), + Duration::from_secs(53), "===DRAG_READY===", |socket| { let mut input = qemu::QmpInput::open(socket); @@ -6489,7 +6486,7 @@ fn metal_sim_hostile_clipboard(rust_bins: &[(String, Vec)]) -> Result<(), St let result = qemu.run_test_paced( "test_rs_compositor_hostile_clipboard", - Duration::from_secs(240), + Duration::from_secs(35), |socket, line| { if line.contains(PASTE) { let socket = socket.expect("this boot was made with QMP"); @@ -6814,7 +6811,7 @@ fn locale_detect(qemu: &mut QemuInstance) -> Result<(), String> { fn locale_detect_unrecognized(qemu: &mut QemuInstance) -> Result<(), String> { let result = qemu.run_test_hooked( "test_rs_locale_gate detect", - Duration::from_secs(30), + Duration::from_secs(2), "Press the key labelled", |socket| { let mut input = qemu::QmpInput::open(socket); @@ -6838,23 +6835,6 @@ fn locale_detect_unrecognized(qemu: &mut QemuInstance) -> Result<(), String> { Ok(()) } -/// A round trip through a guest that is **demonstrably up**, corrected for how -/// fast this host is and not for how many guests it is running. -/// -/// [`qemu::budget`] is the ceiling on a guest that might be wedged, and it -/// multiplies by the width because a guest with a twelfth of the machine takes -/// longer over everything. This is the other case, and the width is wrong for -/// it: what these callers wait on is the shell echoing a line it has not run -/// yet, which is microseconds of guest time however little of the machine the -/// guest has. Ten of those establishing nothing is a keystroke path that is not -/// working, and a width-scaled ceiling turns that into four minutes of a lane — -/// measured, on the run this was written from: 285 s of a terminal parked on a -/// pipe it had been parked on since 1.4 s. -fn round_trip(one_guest: Duration) -> Duration { - let (_, _, num, den) = qemu::host_speed(); - one_guest * num / den -} - /// Keep collecting serial into `log` until `marker` shows up. /// /// **A pace, not a guard.** The two remaining callers retype at the guest and @@ -6934,9 +6914,7 @@ fn answer_swiss_wizard( /// /// What is being waited for is a shell echoing a line it has not run yet, which /// is a round trip and not work — so this is short, and it is paid only when the -/// line did not arrive. [`shell_type_line`] widens it by the guest's own -/// oversubscription; the two callers that retype at a surface which may not be -/// reading yet scale it per host with [`round_trip`] instead. +/// line did not arrive. const ECHO_TRY: Duration = Duration::from_secs(2); /// How long one burst of typing has to reach the panel. @@ -7343,12 +7321,6 @@ fn shell_echoes( // Retyping rather than waiting longer: a keystroke injected between two of // the terminal's polls is dropped, and a dropped one leaves nothing to wait // for. - // - // **A count of attempts, not a span of host seconds.** This used to be a - // flat twenty, which is a fixed number of round trips on the host it was - // written on and a different number on any other. Ten is the number, and - // each gets a round trip scaled to this host — see [`round_trip`] for why - // that and not the phase width. const TRIES: usize = 10; let mut lost = String::new(); for _ in 0..TRIES { @@ -7356,12 +7328,12 @@ fn shell_echoes( // loop's ordinary step: the surface is up and the shell may still not // be reading, which is what the retype exists for. if let Err(said) = - shell_type_once(qemu, &format!("echo {nonce}"), round_trip(ECHO_TRY), ack) + shell_type_once(qemu, &format!("echo {nonce}"), qemu.budget(ECHO_TRY), ack) { lost = said; continue; } - if serial_until(qemu, log, nonce, round_trip(Duration::from_secs(2))) { + if serial_until(qemu, log, nonce, qemu.budget(ECHO_TRY)) { return Ok(()); } } @@ -7399,8 +7371,7 @@ fn shell_echoes( /// The ceiling is the guest's own liveness rather than a phase-scaled clock, /// and here that cuts both ways: #156 is a *freeze*, so the machine this /// retries against goes silent, and the wait ends in fifteen seconds instead of -/// spending `qemu.budget(20 s)` — up to four minutes at width 12 — hammering -/// GUI+Q at a desktop that has stopped. `issues/design-debt/` names that +/// hammering GUI+Q at a desktop that has stopped. `issues/design-debt/` names that /// cost as a lane this test holds for a quarter of every run, which is what puts /// whichever desktop is dispatched beside it into a red nobody acts on. fn close_focused_window(qemu: &mut QemuInstance, log: &mut String, new: usize) -> bool { @@ -7439,7 +7410,7 @@ fn doom_frames(rust_bins: &[(String, Vec)]) -> Result<(), String> { let root = Path::new(env!("CARGO_MANIFEST_DIR")); let config = root.join("tests/doommusiccase"); let mut qemu = QemuInstance::boot_with_options(&config, &[], rust_bins, BootOptions::default()); - let result = qemu.run_test("test_rs_doom_frames", Duration::from_secs(300)); + let result = qemu.run_test("test_rs_doom_frames", Duration::from_secs(77)); if let Some(err) = &result.error { return Err(format!("{err}\n{}", result.stdout)); } @@ -7725,7 +7696,7 @@ fn toolkit_iced() -> Result<(), String> { // Its exit ends the wait too: an app that dies before it has a window // would otherwise hold the lane for the whole budget. let exited = format!("exit: {app} pid="); - let deadline = Instant::now() + qemu.budget(Duration::from_secs(60)); + let deadline = Instant::now() + qemu.budget(Duration::from_secs(332)); while !log[launched..].contains("compositor: window opened") { if log[launched..].contains(&exited) || Instant::now() >= deadline { return Err(format!("{app} never got a window:\n{}", &log[launched..])); @@ -7735,7 +7706,7 @@ fn toolkit_iced() -> Result<(), String> { let (client, content) = opened_window(&log[launched..]) .ok_or_else(|| format!("the compositor's window line did not parse:\n{}", &log[launched..]))?; - let by = qemu.budget(Duration::from_secs(30)); + let by = qemu.budget(Duration::from_secs(332)); // Two words, so two places: "Decrement" alone carries most of // "Increment"'s ink in its "crement". The word matched best claims its // place, and the other is matched only away from it. @@ -7791,7 +7762,7 @@ fn toolkit_iced() -> Result<(), String> { )); } // `stats` prints the peak last, once the app is gone and waited for. - let by = qemu.budget(Duration::from_secs(30)); + let by = qemu.budget(Duration::from_secs(332)); if !serial_until_new(&mut qemu, log, "peak mem", closing, by) { return Err(format!( "{app} did not leave when its window was closed:\n{}", @@ -7894,7 +7865,7 @@ fn toolkit_window_wake(rust_bins: &[(String, Vec)]) -> Result<(), String> { fn toolkit_winit_loop(rust_bins: &[(String, Vec)]) -> Result<(), String> { let (mut qemu, mut log, launched) = toolkit_launch(rust_bins, "winit_loop", "test_rs_winit_loop")?; let log = &mut log; - let mut live = qemu::Liveness::new(Duration::from_secs(40), Duration::from_secs(240)); + let mut live = qemu::Liveness::new(Duration::from_secs(40), Duration::from_secs(35)); let mut closed = false; while live.working(log) { let said = &log[launched..]; @@ -7956,7 +7927,7 @@ fn toolkit_winit_pace(rust_bins: &[(String, Vec)]) -> Result<(), String> { let (mut qemu, mut log, launched) = toolkit_launch(rust_bins, "winit_pace", "test_rs_winit_pace")?; let log = &mut log; let drew = format!("WINIT-PACE drew {PACE_FRAMES} frames"); - let mut live = qemu::Liveness::new(Duration::from_secs(30), Duration::from_secs(120)); + let mut live = qemu::Liveness::new(Duration::from_secs(30), Duration::from_secs(53)); while live.working(log) && !log[launched..].contains(&drew) { let said = &log[launched..]; if said.contains("WINIT-PACE-FAIL") || said.contains("panicked") { @@ -8461,7 +8432,7 @@ struct PatternServer { impl PatternServer { /// Longest a connection's read or write may stall before `finish` exists /// to end it: the guest's own run bound. - const STALL: Duration = Duration::from_secs(120); + const STALL: Duration = Duration::from_secs(65); const STREAM: u8 = 0; const HELD: u8 = 1; @@ -8677,7 +8648,7 @@ fn netcase_against_host( let mut qemu = QemuInstance::boot_with_options(&config, &[], &bins, options); let mut console = qemu.boot_log().to_string(); let up = await_marker(&mut qemu, &mut console, "netd: ready, at most ", "netd to come up"); - let result = up.map(|_| qemu.run_test(&format!("test_rs_{name} {port}{args}"), Duration::from_secs(120))); + let result = up.map(|_| qemu.run_test(&format!("test_rs_{name} {port}{args}"), Duration::from_secs(65))); let sent = server.finish(); let result = result.map_err(|e| format!("netd never came up, so nothing below means anything: {e}"))?; if let Some(err) = &result.error { @@ -8789,7 +8760,7 @@ fn dns_resolve() -> Result<(), String> { let mut console = qemu.boot_log().to_string(); await_marker(&mut qemu, &mut console, "netd: ready, at most ", "netd to come up")?; - let found = qemu.run_test(&format!("host {DNS_REAL_NAME}"), Duration::from_secs(60)); + let found = qemu.run_test(&format!("host {DNS_REAL_NAME}"), Duration::from_secs(47)); if let Some(err) = &found.error { return Err(format!("{err}\n{}", found.stdout)); } @@ -8809,7 +8780,7 @@ fn dns_resolve() -> Result<(), String> { )); } - let missing = qemu.run_test(&format!("host {DNS_NO_NAME}"), Duration::from_secs(60)); + let missing = qemu.run_test(&format!("host {DNS_NO_NAME}"), Duration::from_secs(47)); if let Some(err) = &missing.error { return Err(format!("{err}\n{}", missing.stdout)); } @@ -8869,7 +8840,7 @@ fn netd_lookup_let_go(rust_bins: &[(String, Vec)]) -> Result<(), String> { } console.push_str(&primed.serial); qemu::QmpDevices::open(qemu.qmp_socket()).hold_outbound("net0"); - let result = qemu.run_test(&format!("test_rs_{NAME}"), Duration::from_secs(180)); + let result = qemu.run_test(&format!("test_rs_{NAME}"), Duration::from_secs(74)); if let Some(err) = &result.error { return Err(format!("{err}\n{}", result.stdout)); } @@ -9557,7 +9528,7 @@ fn metal_sim_window_caps(boot: &mut Boot) -> Result<(), String> { return Err("the compositor derived a cap of zero windows".to_string()); } - let result = boot.qemu.run_test("test_rs_window_caps", Duration::from_secs(120)); + let result = boot.qemu.run_test("test_rs_window_caps", Duration::from_secs(8)); if let Some(err) = &result.error { return Err(format!("{err}\n{}", result.stdout)); } @@ -9597,7 +9568,7 @@ fn metal_sim_window_caps(boot: &mut Boot) -> Result<(), String> { /// nothing. fn metal_sim_ipc_hostile_peer(boot: &mut Boot) -> Result<(), String> { let qemu = &mut boot.qemu; - let result = qemu.run_test("test_rs_ipc_hostile_peer", Duration::from_secs(120)); + let result = qemu.run_test("test_rs_ipc_hostile_peer", Duration::from_secs(1)); if let Some(err) = &result.error { return Err(format!("{err}\n{}", result.stdout)); } @@ -9642,7 +9613,7 @@ fn metal_sim_ipc_hostile_peer(boot: &mut Boot) -> Result<(), String> { /// its own final assertion is that the desktop is still compositing after it. fn metal_sim_compositor_stall(boot: &mut Boot) -> Result<(), String> { let qemu = &mut boot.qemu; - let result = qemu.run_test("test_rs_compositor_stall", Duration::from_secs(240)); + let result = qemu.run_test("test_rs_compositor_stall", Duration::from_secs(74)); if let Some(err) = &result.error { return Err(format!("{err}\n{}", result.stdout)); } @@ -9723,7 +9694,7 @@ fn metal_sim_compositor_stall(boot: &mut Boot) -> Result<(), String> { /// what it should do. fn metal_sim_client_death(boot: &mut Boot) -> Result<(), String> { let qemu = &mut boot.qemu; - let result = qemu.run_test("test_rs_compositor_client_death", Duration::from_secs(240)); + let result = qemu.run_test("test_rs_compositor_client_death", Duration::from_secs(14)); if let Some(err) = &result.error { return Err(format!("{err}\n{}", result.stdout)); } @@ -9971,7 +9942,7 @@ fn run_machine_test( QemuInstance::boot_with_options(test_config, c_bins, rust_bins, options); let boot = qemu.boot_log().to_string(); serial::Serial::named("boot console", boot.as_str()).must_be_clean()?; - let result = qemu.run_test("test_rs_blocking_read_stress", Duration::from_secs(30)); + let result = qemu.run_test("test_rs_blocking_read_stress", Duration::from_secs(179)); if !check_rust_result(&result) { return Err(format!( "blocking_read_window failed:\n{}\nkernel log while it ran:\n{}{}", @@ -11316,8 +11287,7 @@ fn run_machine_test( ); serial::Serial::boot(&qemu).must_be_clean()?; - // 120 s: the `/home` arm alone is 32,769 creates on bcachefs. - let result = qemu.run_test("test_rs_readdir_bound", Duration::from_secs(120)); + let result = qemu.run_test("test_rs_readdir_bound", Duration::from_secs(1328)); if let Some(err) = &result.error { return Err(format!("the guest stopped answering: {err}\nserial:\n{}", result.serial)); } @@ -11345,7 +11315,7 @@ fn run_machine_test( ); serial::Serial::boot(&qemu).must_be_clean()?; - let result = qemu.run_test("test_rs_mkdir_cap", Duration::from_secs(60)); + let result = qemu.run_test("test_rs_mkdir_cap", Duration::from_secs(188)); if let Some(err) = &result.error { return Err(format!("the guest stopped answering: {err}\nserial:\n{}", result.serial)); } @@ -11380,7 +11350,7 @@ fn run_machine_test( let mut qemu = QemuInstance::boot_with_options(test_config, c_bins, rust_bins, one_cpu()); serial::Serial::boot(&qemu).must_be_clean()?; - let result = qemu.run_test("test_rs_fpu_isolation", Duration::from_secs(120)); + let result = qemu.run_test("test_rs_fpu_isolation", Duration::from_secs(59)); if let Some(err) = &result.error { return Err(format!( "the guest stopped answering: {err}\nserial:\n{}", @@ -11406,7 +11376,7 @@ fn run_machine_test( BootOptions { kernel_features: &["fpu-save-nothing"], ..one_cpu() }, ); serial::Serial::boot(&blind).must_be_clean()?; - let negative = blind.run_test("test_rs_fpu_isolation", Duration::from_secs(120)); + let negative = blind.run_test("test_rs_fpu_isolation", Duration::from_secs(59)); if let Some(err) = &negative.error { return Err(format!( "the negative-control guest stopped answering: {err}\nserial:\n{}", @@ -11434,7 +11404,7 @@ fn run_machine_test( let mut qemu = QemuInstance::boot_with_options(test_config, c_bins, rust_bins, one_cpu()); serial::Serial::boot(&qemu).must_be_clean()?; - let result = qemu.run_test("test_rs_gsbase_locked", Duration::from_secs(120)); + let result = qemu.run_test("test_rs_gsbase_locked", Duration::from_secs(74)); if let Some(err) = &result.error { return Err(format!("the guest stopped answering: {err}\nserial:\n{}", result.serial)); } @@ -11460,7 +11430,7 @@ fn run_machine_test( BootOptions { kernel_features: &["user-writable-gsbase"], ..one_cpu() }, ); serial::Serial::boot(&blind).must_be_clean()?; - let negative = blind.run_test("test_rs_gsbase_locked", Duration::from_secs(120)); + let negative = blind.run_test("test_rs_gsbase_locked", Duration::from_secs(74)); if let Some(err) = &negative.error { return Err(format!( "the negative-control guest stopped answering: {err}\nserial:\n{}", @@ -11537,7 +11507,7 @@ fn run_machine_test( // assert that fires there takes the machine down before userland. serial::Serial::boot(&qemu).must_be_clean()?; - let result = qemu.run_test("test_rs_sched_stress", Duration::from_secs(120)); + let result = qemu.run_test("test_rs_sched_stress", Duration::from_secs(29)); if let Some(err) = &result.error { return Err(format!( "the check-build guest stopped answering, which is what a scheduler \ @@ -11945,7 +11915,7 @@ fn run_machine_test( let mut qemu = QemuInstance::boot_with_options(test_config, c_bins, rust_bins, options); serial::Serial::boot(&qemu).must_be_clean()?; - let result = qemu.run_test("test_rs_heap_ceiling", Duration::from_secs(30)); + let result = qemu.run_test("test_rs_heap_ceiling", Duration::from_secs(26)); if let Some(err) = &result.error { return Err(format!("heap_ceiling did not finish: {err}\nserial:\n{}", result.serial)); } @@ -12035,7 +12005,7 @@ fn run_machine_test( )); } - let result = qemu.run_test("test_rs_cache_eviction", Duration::from_secs(180)); + let result = qemu.run_test("test_rs_cache_eviction", Duration::from_secs(59)); if !check_rust_result(&result) { return Err(format!( "a page did not survive being evicted and re-read:\n{}\n{}", @@ -12410,7 +12380,7 @@ fn run_machine_test( } let result = qemu.run_test_hooked( "test_rs_i8042_keyboard", - Duration::from_secs(20), + Duration::from_secs(164), I8042_READY, |socket| { qemu::qmp_send_keys(socket, &[("a", true), ("a", false)]); @@ -13244,7 +13214,7 @@ fn run_machine_test( // A baseline first: churn against a compositor that was never // drawing would be a green run proving nothing. - let deadline = std::time::Instant::now() + qemu.budget(Duration::from_secs(20)); + let deadline = std::time::Instant::now() + qemu.budget(Duration::from_secs(92)); while std::time::Instant::now() < deadline && frames(&console) < 1 { console.push_str(&qemu.drain_serial(Duration::from_millis(250))); } @@ -13296,7 +13266,7 @@ fn run_machine_test( // changed is that a console behind the guest costs wall clock instead // of a verdict. let bindings = |text: &str| text.matches("merges as source").count(); - let deadline = std::time::Instant::now() + qemu.budget(Duration::from_secs(20)); + let deadline = std::time::Instant::now() + qemu.budget(Duration::from_secs(92)); while std::time::Instant::now() < deadline && bindings(&console) < CYCLES { console.push_str(&qemu.drain_serial(Duration::from_millis(250))); } @@ -13331,7 +13301,7 @@ fn run_machine_test( // reporting interval is 2 s, so two of them cannot be satisfied by // frames the compositor produced before the first cycle. let mut after = String::new(); - let deadline = std::time::Instant::now() + qemu.budget(Duration::from_secs(20)); + let deadline = std::time::Instant::now() + qemu.budget(Duration::from_secs(92)); while std::time::Instant::now() < deadline && frames(&after) < 2 { after.push_str(&qemu.drain_serial(Duration::from_millis(250))); } @@ -13787,7 +13757,7 @@ fn run_machine_test( let mut qemu = QemuInstance::boot_with_options(&config, &[], &bins, options); let mut console = qemu.boot_log().to_string(); let _ = await_marker(&mut qemu, &mut console, "netd: ready, at most ", "netd to come up"); - let result = qemu.run_test("test_rs_netd_listener_forgery", Duration::from_secs(60)); + let result = qemu.run_test("test_rs_netd_listener_forgery", Duration::from_secs(35)); if let Some(err) = &result.error { return Err(format!("{err}\n{}", result.stdout)); } @@ -13846,7 +13816,7 @@ fn run_machine_test( return Err(format!("netd never came up on a machine with a NIC:\n{console}")); } - let result = qemu.run_test("test_rs_netd_hostile_peer", Duration::from_secs(120)); + let result = qemu.run_test("test_rs_netd_hostile_peer", Duration::from_secs(44)); if let Some(err) = &result.error { return Err(format!("{err}\n{}", result.stdout)); } @@ -13934,7 +13904,7 @@ fn run_machine_test( let mut console = qemu.boot_log().to_string(); let _ = await_marker(&mut qemu, &mut console, "===READY===", "test-runner to come up"); - let result = qemu.run_test("test_rs_launcher_refusals", Duration::from_secs(120)); + let result = qemu.run_test("test_rs_launcher_refusals", Duration::from_secs(35)); if let Some(err) = &result.error { return Err(format!("{err}\n{}", result.stdout)); } @@ -15918,7 +15888,7 @@ fn input_events_run( let mut input: Option = None; let (mut mev, mut kev) = (0usize, 0usize); let (mut want_mev, mut want_kev) = (0usize, 0usize); - qemu.run_test_paced("test_rs_input_events", Duration::from_secs(60), |socket, line| { + qemu.run_test_paced("test_rs_input_events", Duration::from_secs(50), |socket, line| { if line.contains("===INPUT_READY===") { input = Some(qemu::QmpInput::open( socket.expect("input_events needs BootOptions { qmp: true }"), @@ -16022,12 +15992,13 @@ fn build_test_registry( let mut tests = Vec::new(); for name in discover_rust_tests(rust_bins) { - let timeout = match name.as_str() { - // Writes the child's whole image through bcachefs before it can run - // it, which is the only thing here that is not a spawn. - "disk_backtrace" => Duration::from_secs(15), - _ => Duration::from_secs(5), - }; + let timeout = Duration::from_secs(match name.as_str() { + "mutual_kill" => 47, + "poll_wake_pipe" => 17, + "process_stats" => 11, + "abuse_elf_loader" | "toybox_file_tools" => 8, + _ => 5, + }); tests.push(TestDef { qemu_name: format!("test_rs_{name}"), check: check_for(&name), @@ -16040,7 +16011,7 @@ fn build_test_registry( for name in c_names { tests.push(TestDef { qemu_name: format!("test_c_{name}"), - timeout: Duration::from_secs(10), + timeout: Duration::from_secs(2), check: check_c_result, settle: no_settle, name: name.clone(), @@ -16409,7 +16380,7 @@ impl Tally { if let Some(fastest) = fastest { say(format!( "host: fastest boot {fastest} ms against the reference {reference} ms — liveness \ - ceilings paid at {:.2}x width", + ceilings paid at {:.2}x", f64::from(num) / f64::from(den) )); } @@ -16852,7 +16823,6 @@ fn run_phase( return Vec::new(); } let width = width.clamp(1, tasks.len()); - qemu::set_width(width as u32); let queue = std::sync::Mutex::new(std::collections::VecDeque::from(tasks)); let mut all = Vec::new(); thread::scope(|scope| { From 00941daa0a3d4eb283c2efa97d349c7ab0bc1b09 Mon Sep 17 00:00:00 2001 From: japabu Date: Wed, 30 Sep 2026 16:30:34 +0200 Subject: [PATCH 02/19] The T14's wedge arms end seconds after their wedge, and the loop polls the machine once a second Four cuts to what a full T14 run spends waiting, from the rig research's per-boot budget (three full runs' readbacks) and the latest metal logs. - A boot armed with one of `WEDGE_ARMS` (deadlinewedge, hardlockup, usbload) carries `boot-deadline=` `metal::STAGED_BOUND_MS`, 10 s, instead of the 120 s every other boot keeps for a wedge nobody staged. The T14 stages its wedge 1.505-1.511 s into the kernel (630r4), and those three boots came back in 110-166 s against a ~40-84 s ordinary boot. The lockup's bound is half of it, 5 s, which still outlasts the probe's 3 s reach to its lock; the load sweep simply stops sooner. `bound_for` is the one place the choice is made, in `tests/common/metal.rs`'s build, where the header already said a boot wanting a different bound is a change here and not a field on an arm. The three boots' `complete_ms` rows name the new bound, and the two lateness rows go from 10 s, "a twelfth of the bound", to twice their reading. - `wait` polls `ssh`'s port once a second, and asks `ssh true` only once the port accepts: coming back is still `ssh` answering. It slept 5 s before every probe, and a probe of a machine that is down cost `ConnectTimeout`'s 10 s. - A refusal after `reboot` waits for the machine to answer `ssh` again before it returns, unless the refusal was that wait itself, so the next boot's first `ssh` does not refuse a boot that never happened (the lanleasecase and lanswapcase arms of `issues/hardware/the-t14-stopped-answering-ssh-between- two-lan-boots.md`). The steps after `reboot` move into `after_the_reboot`. - A swapping boot whose own invocation was refused kills its `--swap` invocation instead of letting it dial for the whole 420 s. - The list allowances are twice the slowest per-member mean over five full runs: shared 845 -> 428 ms measured, allowance 1400 -> 860; shared-debug 1926 -> 398, 2900 -> 800; ccorpus 396 -> 127, 600 -> 260. The corpus now fits one boot (130 cases at 207 a boot), so `ccorpus-2` and its six rows go, with the two tests that pinned the old cut. `shared` stays two boots. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- src/metal.rs | 85 +++++++++++++++++++++++++----- src/metalprofile.rs | 39 ++------------ tests/common/metal.rs | 17 +++++- tests/common/qemu.rs | 8 +-- tests/metal-profile.toml | 108 ++++++++++++--------------------------- 5 files changed, 130 insertions(+), 127 deletions(-) diff --git a/src/metal.rs b/src/metal.rs index 3990647ce04..347946a6d9e 100644 --- a/src/metal.rs +++ b/src/metal.rs @@ -59,7 +59,8 @@ pub fn return_secs() -> u64 { longest.div_ceil(1_000) + RETURN_ALLOWANCE_SECS } -const POLL_SECS: u64 = 5; +/// How often the loop asks whether the machine is there. +const POLL: std::time::Duration = std::time::Duration::from_secs(1); const PING_EVERY_SECS: u64 = 1; @@ -871,8 +872,24 @@ pub const FOREIGN_RECORD_ARM: &str = "blackbox-foreign-identity"; /// Whether this image is armed to stop itself, and so owes a sealed record /// rather than `Rebooting.`. -pub fn stages_a_wedge(armed: &[String]) -> bool { - armed.iter().any(|name| WEDGE_ARMS.contains(&name.as_str())) +pub fn stages_a_wedge(armed: &[impl AsRef]) -> bool { + armed.iter().any(|name| WEDGE_ARMS.contains(&name.as_ref())) +} + +/// The bound an image armed with one of [`WEDGE_ARMS`] carries, in +/// milliseconds: the T14 stages its wedge 1.5 s into the kernel, so this ends +/// the machine seconds after it rather than at the bound every other boot keeps +/// for a wedge nobody staged. Its half is the lockup detector's bound, which +/// still outlasts the lockup probe's own reach to its lock. +pub const STAGED_BOUND_MS: u64 = 10_000; + +/// The `boot-deadline=` bound an image armed with `armed` carries. +pub fn bound_for(armed: &[impl AsRef]) -> u64 { + if stages_a_wedge(armed) { + STAGED_BOUND_MS + } else { + toyos_tco::WEDGE_BOUND_MS + } } /// Whether this image is armed so the pass after its reset clears its record @@ -1437,17 +1454,34 @@ impl Driver { } } + /// Poll `ssh`'s port once a [`POLL`], and say how long it took to answer as + /// asked. **Coming back is `ssh` itself answering**: a port that accepts is + /// only asked whether `ssh` does, since a listener can come up before the + /// service behind it. fn wait(&self, secs: u64, what: &'static str, answering: bool) -> Result { let began = std::time::Instant::now(); while began.elapsed().as_secs() < secs { - std::thread::sleep(std::time::Duration::from_secs(POLL_SECS)); - if self.ssh("probing", "true").is_ok() == answering { + let next = std::time::Instant::now() + POLL; + let listening = self.port_accepts(); + let answered = listening && (!answering || self.ssh("probing", "true").is_ok()); + if answered == answering { return Ok(began.elapsed().as_secs()); } + std::thread::sleep(next.saturating_duration_since(std::time::Instant::now())); } Err(Refusal::Silent { what, secs }) } + /// Whether the machine's `ssh` port accepts a connection inside one + /// [`POLL`]; a name that does not resolve is a machine that is not there. + fn port_accepts(&self) -> bool { + use std::net::ToSocketAddrs; + let Ok(mut addrs) = (self.target.host.as_str(), crate::metaltalk::SSH_PORT).to_socket_addrs() else { + return false; + }; + addrs.any(|addr| std::net::TcpStream::connect_timeout(&addr, POLL).is_ok()) + } + /// The loader's own file, and then everything `logd` wrote, in name order: /// a freshly flashed volume holds one boot's files, and its newest file /// alone would miss the continuations `logd` rotates into. @@ -2036,19 +2070,43 @@ pub fn run(args: &Args) -> Result, Refusal> { let entry = driver.boot_entry(&image.esp)?; driver.as_root("setting bootnext", Job::BootNext, Some(&entry), None)?; - driver.as_root("rebooting", Job::Reboot, None, None)?; + let rebooted = driver.as_root("rebooting", Job::Reboot, None, None); if driver.dry_run { + rebooted?; driver.as_root("mounting the log partition", Job::Mount, None, None)?; driver.as_root("unmounting the log partition", Job::Umount, None, None)?; println!("dry run: nothing was written and the machine was not rebooted"); return Ok(None); } + let judged = rebooted + .and_then(|_| after_the_reboot(&driver, args, &image, &armed, cable.as_ref(), wire.as_ref())); + // **A refusal after `reboot` can leave the machine on its way back**, and + // the next invocation's first `ssh` would then refuse a boot that never + // happened. One the machine was already waited out for is not waited again. + if let Err(refused) = &judged { + if !matches!(refused, Refusal::Silent { .. }) { + if let Err(silent) = driver.wait(args.wait_secs, "come back", true) { + println!("after that refusal, {silent}"); + } + } + } + judged +} +/// Everything from the machine going down to the boot's verdict. +fn after_the_reboot( + driver: &Driver, + args: &Args, + image: &Flashable, + armed: &[String], + cable: Option<&Talking>, + wire: Option<&Wire>, +) -> Result, Refusal> { // The conversation runs while the loop watches the machine come back; its // `reboot` is what brings it back before the boot's own hold does. let mut talking = None; - let ridden = driver.ride_the_reboot(args.wait_secs, wire.as_ref().map(|w| w.addr), || { - if let Some(cable) = &cable { + let ridden = driver.ride_the_reboot(args.wait_secs, wire.map(|w| w.addr), || { + if let Some(cable) = cable { talking = Some(cable.start(std::time::Duration::from_secs(args.wait_secs))); } }); @@ -2076,7 +2134,7 @@ pub fn run(args: &Args) -> Result, Refusal> { }; let (back, replied) = ridden?; println!("the machine answered ssh again after {back} s"); - if let Some(wire) = &wire { + if let Some(wire) = wire { match replied { Some(reply) => println!( "{} answered a ping {} s into the window, after {PING_SILENCE_SECS} s of \ @@ -2112,10 +2170,10 @@ pub fn run(args: &Args) -> Result, Refusal> { println!("toyos-fat32-check: the log partition's {} bytes check out", bytes.len()); } if let Some(dir) = &args.readback { - write_readback(dir, &loader, &log, back, stick, wire.as_ref(), replied)?; + write_readback(dir, &loader, &log, back, stick, wire, replied)?; println!("readback written to {}", dir.display()); } - let ms = boot_verdict(&armed, &loader, &log)?; + let ms = boot_verdict(armed, &loader, &log)?; // After the stick's own verdict, which stays the one that names a boot // that never reached its network. if let Some((heard, lines)) = &heard { @@ -2702,6 +2760,7 @@ mod tests { assert_eq!(flash_ruling(arm), Some(Flash::Ok), "{arm} reaches no stick"); assert_eq!(judge_arms(&[arm.to_string(), bound.clone()]), Ok(()), "{arm}"); assert!(stages_a_wedge(&[arm.to_string()]), "{arm}"); + assert_eq!(bound_for(&[arm]), STAGED_BOUND_MS, "{arm}"); // And with no bound behind it, the sharpest refusal names it as the // wedge it is rather than as a plain image. assert_eq!( @@ -2710,8 +2769,10 @@ mod tests { "{arm}" ); } - // The negative half: an arm that stops nothing is not judged as one. + // The negative half: an arm that stops nothing is not judged as one, + // and keeps the bound a wedge nobody staged is ended by. assert!(!stages_a_wedge(&["watchdog".to_string(), bound])); + assert_eq!(bound_for(&["watchdog"]), toyos_tco::WEDGE_BOUND_MS); } /// A row for a name the kernel no longer declares is a ruling about diff --git a/src/metalprofile.rs b/src/metalprofile.rs index f52462b1cea..3b934d45760 100644 --- a/src/metalprofile.rs +++ b/src/metalprofile.rs @@ -197,6 +197,11 @@ mod tests { ("toyos_tco::BOUND_MS", toyos_tco::BOUND_MS), ("toyos_tco::WEDGE_BOUND_MS", toyos_tco::WEDGE_BOUND_MS), ("toyos_tco::HARD_LOCKUP_BOUND_MS", toyos_tco::HARD_LOCKUP_BOUND_MS), + ("toyos_build::metal::STAGED_BOUND_MS", crate::metal::STAGED_BOUND_MS), + ( + "toyos_tco::hard_lockup_bound_ms(toyos_build::metal::STAGED_BOUND_MS)", + toyos_tco::hard_lockup_bound_ms(crate::metal::STAGED_BOUND_MS), + ), ]; /// A row whose ceiling *is* a constant this repository declares carries that @@ -290,40 +295,6 @@ mod sizing_tests { Path::new(env!("CARGO_MANIFEST_DIR")) } - /// **The overrun this rule exists for, in the machine's own numbers.** The - /// `shared` boot's seventy-two members at their committed 845 ms each are - /// 60.8 s inside a 60 s bound, so the runner resets the machine with the - /// tail unrun and each of those is reported as a missing exit record rather - /// than as a list too long for the bound. - #[test] - fn the_shared_list_does_not_fit_one_boot() { - let profile = Profile::load(root()).expect(PATH); - let per = profile.members_per_boot("shared").expect("shared is priced"); - assert!( - per < 72, - "the allowance leaves room for {per} members and the list carries 72" - ); - // Two chunks and not three: a list cut finer costs another minute of - // the machine for nothing. - assert_eq!(72_usize.div_ceil(per), 2, "{per} members a boot"); - let measured = - profile.row(&job_ms_row("shared")).and_then(|r| r.measured).expect("a reading"); - assert!( - 72 * measured > toyos_tco::JOB_BOUND_MS, - "{measured} ms a member over 72 members fits the bound, so this rule cuts nothing" - ); - } - - /// `ccorpus` fits its bound and the same rule still cuts it: four fifths of - /// a bound is no margin for a slower stick, and the price of being wrong is - /// every member after the cut losing its verdict. - #[test] - fn a_corpus_that_fits_its_bound_is_cut_too() { - let profile = Profile::load(root()).expect(PATH); - let per = profile.members_per_boot("ccorpus").expect("ccorpus is priced"); - assert_eq!(118_usize.div_ceil(per), 2, "{per} members a boot"); - } - /// A member priced above the whole bound still gets a boot, rather than a /// division that yields zero and a list that can hold nothing. #[test] diff --git a/tests/common/metal.rs b/tests/common/metal.rs index b67d0f5d34d..dec363bab88 100644 --- a/tests/common/metal.rs +++ b/tests/common/metal.rs @@ -820,7 +820,11 @@ fn build( field on an arm" )); } - let deadline = format!("{}{}", toyos_tco::DEADLINE_PARAM, toyos_tco::WEDGE_BOUND_MS); + let deadline = format!( + "{}{}", + toyos_tco::DEADLINE_PARAM, + toyos_build::metal::bound_for(&batch.params) + ); let mut params: Vec<&str> = batch.params.clone(); params.push(&deadline); // **A talking or swapping boot carries the key the loop will offer**, @@ -1092,7 +1096,16 @@ pub fn run( eprintln!("[metal] {label}: cargo {}", words.join(" ")); let booted = Command::new("cargo").args(&words).current_dir(&root).status(); if let Some(swap) = beside { - match swap.and_then(|mut child| child.wait()) { + // A boot that was refused leaves no machine to dial, and the + // swap would wait out its whole bound for one. + let unbooted = !booted.as_ref().is_ok_and(|status| status.success()); + let swap = swap.and_then(|mut child| { + if unbooted { + child.kill()?; + } + child.wait() + }); + match swap { Ok(status) if status.success() => {} Ok(status) => { refused.insert(label, format!("toyos-metal --swap exited {status}")); diff --git a/tests/common/qemu.rs b/tests/common/qemu.rs index dc0b662e655..461285da066 100644 --- a/tests/common/qemu.rs +++ b/tests/common/qemu.rs @@ -300,8 +300,8 @@ fn oversubscription(smp: u32) -> (u32, u32) { /// A ceiling, paid out for the host and the guest it bounds. /// -/// **Every ceiling in this suite is three times the slowest the test it bounds -/// was measured to take**, in whole-suite runs on the host [`REFERENCE_BOOT_MS`] +/// **Every ceiling in this suite is at most three times the slowest the test it +/// bounds was measured to take**, in whole-suite runs on the host [`REFERENCE_BOOT_MS`] /// describes, at the suite's default width — so a test's time already carries /// the guests it shares that host with. A wait is bounded by that multiple of /// its whole test, the one number measured; a guest still talking at twice its @@ -559,8 +559,8 @@ pub fn ceiling_verdict( )); } // The backstop, for a guest that is stuck *and* chatty and so never trips - // the silence guard: twice the ceiling, six times the slowest this test was - // ever measured. + // the silence guard: twice the ceiling, at most six times the slowest this test + // was ever measured. let backstop = ceiling * 2; if elapsed > backstop { return Some(format!( diff --git a/tests/metal-profile.toml b/tests/metal-profile.toml index ded7ce1d4d4..7d807103da5 100644 --- a/tests/metal-profile.toml +++ b/tests/metal-profile.toml @@ -457,8 +457,8 @@ ceiling_from = "as boot.testcases.stick_secs" [[number]] name = "boot.deadlinewedge.complete_ms" unit = "ms" -ceiling = 120000 -ceiling_from = "toyos_tco::WEDGE_BOUND_MS — on this boot the kernel's own deadline is what runs from boot, so a later `Boot: complete` is a boot the deadline already reset" +ceiling = 10000 +ceiling_from = "toyos_build::metal::STAGED_BOUND_MS — on this boot the kernel's own deadline is what runs from boot, so a later `Boot: complete` is a boot the deadline already reset" measured = 1254 [[number]] @@ -484,8 +484,8 @@ measured = 0 [[number]] name = "boot.deadlinewedge.deadline_lateness_ms" unit = "ms" -ceiling = 10000 -ceiling_from = "the poll's own cadence: the deadline is read on every timer interrupt and an idle CPU re-arms its LAPIC one-shot per fire, so the lateness is one timer period. That period has not been measured on this machine, and ten seconds — a twelfth of the bound — is the widest true bound before it has been" +ceiling = 120 +ceiling_from = "twice the reading beside it, which counts the boot's first 60 ms before the arm into the lateness: the deadline is read on every timer interrupt, so what is left is one timer period" measured = 60 # --- the boot one CPU stops answering on --- @@ -499,8 +499,8 @@ measured = 60 [[number]] name = "boot.hardlockup.complete_ms" unit = "ms" -ceiling = 60000 -ceiling_from = "toyos_tco::HARD_LOCKUP_BOUND_MS — half the deadline and the earlier bound, so a later `Boot: complete` is a boot the detector already reset" +ceiling = 5000 +ceiling_from = "toyos_tco::hard_lockup_bound_ms(toyos_build::metal::STAGED_BOUND_MS) — half the deadline and the earlier bound, so a later `Boot: complete` is a boot the detector already reset" measured = 1206 [[number]] @@ -539,8 +539,8 @@ measured = 0 [[number]] name = "boot.usbload.complete_ms" unit = "ms" -ceiling = 120000 -ceiling_from = "as boot.deadlinewedge.complete_ms, toyos_tco::WEDGE_BOUND_MS — the same bound ends this machine and the runner never reaches its own. Not toyos_tco::HARD_LOCKUP_BOUND_MS, which is half of it: the sweep keeps its CPU taking interrupts so that this bound and not that one is what ends the boot, and the judge refuses a page that names the other" +ceiling = 10000 +ceiling_from = "as boot.deadlinewedge.complete_ms, toyos_build::metal::STAGED_BOUND_MS — the same bound ends this machine and the runner never reaches its own. Not the lockup detector's, which is half of it: the sweep keeps its CPU taking interrupts so that this bound and not that one is what ends the boot, and the judge refuses a page that names the other" measured = 1204 [[number]] @@ -560,7 +560,7 @@ measured = 0 [[number]] name = "boot.usbload.deadline_lateness_ms" unit = "ms" -ceiling = 10000 +ceiling = 120 ceiling_from = "as boot.deadlinewedge.deadline_lateness_ms — the poll's own cadence, read on every timer interrupt, so the lateness is one timer period whichever CPU reaches the bound first" measured = 66 @@ -606,35 +606,29 @@ ceiling_from = "as boot.jobcase.stick_secs. On this arm the stick was sent a Bul [[number]] name = "list.shared.job_ms" unit = "ms" -ceiling = 1400 -ceiling_from = "845 ms measured (25 members spawned between 1.943 s and 23.066 s on run 24's `shared`), and a ceiling above the widest single member on that boot — test_rs_abuse_elf_loader at 1,358 ms — so one heavy member cannot put the mean over it" -measured = 845 +ceiling = 860 +ceiling_from = "twice the slowest mean a member of this list cost over five full runs, the reading beside it" +measured = 428 [[number]] name = "list.shared-2.job_ms" unit = "ms" -ceiling = 1400 +ceiling = 860 ceiling_from = "as list.shared.job_ms — the same list, cut in two" [[number]] name = "list.shared-debug.job_ms" unit = "ms" -ceiling = 2900 -ceiling_from = "1,926 ms measured (8 members between 2.624 s and 18.032 s on run 24's `shared-debug`), and half again: these are the eight binaries that re-execute themselves once per fault, and handle_kill_policy alone spawned 42 children" -measured = 1926 +ceiling = 800 +ceiling_from = "twice the slowest mean a member of this list cost over five full runs, the reading beside it" +measured = 398 [[number]] name = "list.ccorpus.job_ms" unit = "ms" -ceiling = 600 -ceiling_from = "396 ms measured (118 cases between 2.625 s and the reboot job at 49.366 s on run 24's `ccorpus`), and half again. That boot was green at 49.5 s of a 60 s bound — 82 % of it, with no margin for a slower stick — which is why the same rule cuts a list that passed" -measured = 396 - -[[number]] -name = "list.ccorpus-2.job_ms" -unit = "ms" -ceiling = 600 -ceiling_from = "as list.ccorpus.job_ms — the same corpus, cut in two" +ceiling = 260 +ceiling_from = "twice the slowest mean a case of this corpus cost over five full runs, the reading beside it" +measured = 127 [[number]] name = "list.metaldevicecase.job_ms" @@ -645,37 +639,37 @@ ceiling_from = "metalprobe's SHARE_PERCENT of toyos_tco::JOB_BOUND_MS, which is [[number]] name = "list.testcases.job_ms" unit = "ms" -ceiling = 1400 +ceiling = 860 ceiling_from = "as list.shared.job_ms: the same machine spawning the same kind of binary off the same stick" [[number]] name = "list.testcases-mkdir.job_ms" unit = "ms" -ceiling = 1400 +ceiling = 860 ceiling_from = "as list.testcases.job_ms" [[number]] name = "list.testcases-readdir.job_ms" unit = "ms" -ceiling = 1400 +ceiling = 860 ceiling_from = "as list.testcases.job_ms" [[number]] name = "list.testcases-watchdog.job_ms" unit = "ms" -ceiling = 1400 +ceiling = 860 ceiling_from = "as list.testcases.job_ms" [[number]] name = "list.jobcase.job_ms" unit = "ms" -ceiling = 1400 +ceiling = 860 ceiling_from = "as list.testcases.job_ms" [[number]] name = "list.metalcase.job_ms" unit = "ms" -ceiling = 1400 +ceiling = 860 ceiling_from = "as list.testcases.job_ms" [[number]] @@ -687,19 +681,19 @@ ceiling_from = "half of what the members of a list may spend — (toyos_tco::JOB [[number]] name = "list.selftests.job_ms" unit = "ms" -ceiling = 1400 +ceiling = 860 ceiling_from = "as list.testcases.job_ms" [[number]] name = "list.foreignrecord.job_ms" unit = "ms" -ceiling = 1400 +ceiling = 860 ceiling_from = "as list.testcases.job_ms" [[number]] name = "list.logstallcase.job_ms" unit = "ms" -ceiling = 1400 +ceiling = 860 ceiling_from = "as list.testcases.job_ms" [[number]] @@ -717,31 +711,31 @@ ceiling_from = "as list.latencycase.job_ms: one job each of whose pipe waits the [[number]] name = "list.testcases-debug.job_ms" unit = "ms" -ceiling = 2900 +ceiling = 800 ceiling_from = "as list.shared-debug.job_ms: one of the same eight binaries" [[number]] name = "list.deadlinewedge.job_ms" unit = "ms" -ceiling = 1400 +ceiling = 860 ceiling_from = "as list.testcases.job_ms — the list is one job and a wedge, and what ends this boot is the kernel's own deadline rather than the runner's" [[number]] name = "list.hardlockup.job_ms" unit = "ms" -ceiling = 1400 +ceiling = 860 ceiling_from = "as list.deadlinewedge.job_ms" [[number]] name = "list.usbload.job_ms" unit = "ms" -ceiling = 1400 +ceiling = 860 ceiling_from = "as list.deadlinewedge.job_ms — the same list, and what ends this boot is the kernel's own deadline rather than the runner's" [[number]] name = "list.usbbreak.job_ms" unit = "ms" -ceiling = 1400 +ceiling = 860 ceiling_from = "as list.jobcase.job_ms — the same list" # --- the boots the split above adds --- @@ -764,24 +758,6 @@ unit = "s" ceiling = 30 ceiling_from = "as boot.testcases.stick_secs" -[[number]] -name = "boot.ccorpus-2.complete_ms" -unit = "ms" -ceiling = 60000 -ceiling_from = "toyos_tco::JOB_BOUND_MS — as boot.testcases.complete_ms" - -[[number]] -name = "boot.ccorpus-2.back_secs" -unit = "s" -ceiling = 420 -ceiling_from = "toyos_build::metal::return_secs" - -[[number]] -name = "boot.ccorpus-2.stick_secs" -unit = "s" -ceiling = 30 -ceiling_from = "as boot.testcases.stick_secs" - # --- the cable: the boot that runs netd in front of the T14's own I219 --- [[number]] @@ -946,12 +922,6 @@ unit = "us" ceiling = 16667 ceiling_from = "as boot.testcases.panel_max_us" -[[number]] -name = "boot.ccorpus-2.panel_max_us" -unit = "us" -ceiling = 16667 -ceiling_from = "as boot.testcases.panel_max_us" - [[number]] name = "boot.logstallcase.panel_max_us" unit = "us" @@ -1087,12 +1057,6 @@ unit = "us" ceiling = 100000 ceiling_from = "as boot.testcases.panel_us" -[[number]] -name = "boot.ccorpus-2.panel_us" -unit = "us" -ceiling = 100000 -ceiling_from = "as boot.testcases.panel_us" - [[number]] name = "boot.logstallcase.panel_us" unit = "us" @@ -1220,12 +1184,6 @@ unit = "operations" ceiling = 0 ceiling_from = "as boot.testcases.park_open_operations" -[[number]] -name = "boot.ccorpus-2.park_open_operations" -unit = "operations" -ceiling = 0 -ceiling_from = "as boot.testcases.park_open_operations" - [[number]] name = "boot.logstallcase.park_open_operations" unit = "operations" From 12ccc2a71f6fc6af3ad1bfe27b7d63a8c11fabbd Mon Sep 17 00:00:00 2001 From: japabu Date: Wed, 30 Sep 2026 16:40:55 +0200 Subject: [PATCH 03/19] readdir_bound's `/home` arm goes: on the file servers it was refused by `NotFound` at any count The arm created 32,769 files on `/home` and passed on any error from `read_dir("/home")`. Before #536 that error was the listing bound's (`out of memory` on 588r3, 633r2 and 634); on #536's two whole runs it was `entity not found`, and so was `/home`'s own root afterwards, which an empty `/home` answers too. The 32,769 creates through the DATA server were most of readdir_bound's 364 s and 442 s there, against 46-181 s before. So the `/home` arm and the `/home` half of the per-directory check are deleted, and the bound is `/tmp`'s alone, which is still the kernel's `vfs::MAX_LIST_ENTRIES` at its full count. The bcachefs library's own walk past the old doubling stays covered on the host by `a_tree_past_the_ceiling_is_refused_before_it_materialises`. Filed: `issues/filesystem/listing-home-answers-not-found-and-its-bound-has-no-guest-test.md`, for the `NotFound` and for the DATA server's `WINDOW_BYTES` refusal that no guest test now reaches. The ceiling is three times the slowest whole run on the runs where the arm was the kernel's (181 s), an upper bound on the test that is left until a suite measures it: 545 s. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- ...t-found-and-its-bound-has-no-guest-test.md | 34 +++++++++++++++ .../toyos-rust-tests/src/bin/readdir_bound.rs | 42 +++---------------- tests/toyos.rs | 2 +- 3 files changed, 41 insertions(+), 37 deletions(-) create mode 100644 issues/filesystem/listing-home-answers-not-found-and-its-bound-has-no-guest-test.md diff --git a/issues/filesystem/listing-home-answers-not-found-and-its-bound-has-no-guest-test.md b/issues/filesystem/listing-home-answers-not-found-and-its-bound-has-no-guest-test.md new file mode 100644 index 00000000000..b9f870c0183 --- /dev/null +++ b/issues/filesystem/listing-home-answers-not-found-and-its-bound-has-no-guest-test.md @@ -0,0 +1,34 @@ +--- +status: open +kind: defect +opened: 2026-09-30 +--- + +# Listing `/home` itself answers "entity not found", and the listing bound on a served directory has no guest test + +`readdir_bound` asserted that `read_dir("/home")` is refused once `/home` holds +more entries than the listing bound, and it accepted any error. Before the file +servers the refusal was the bound's; since them it is `NotFound`, whatever the +count: + +``` +634-whole.log (main before #536): [readdir]: /home refused at 32769 entries (out of memory) +536r21-whole.log (#536's branch): [readdir]: /home refused at 32769 entries (entity not found) +536r21-whole.log: [readdir]: /home's own root is still refused (entity not found) +``` + +So on `main` the arm created 32,769 files through the DATA server (364 s and +442 s of `readdir_bound` on #536's two whole runs, against 46-181 s before it) +to reach an answer an empty `/home` gives too. The arm is deleted; what is left +untested is the one refusal the DATA server has for a listing too large, the +`WINDOW_BYTES` check in `userland/fsd/src/main.rs`'s `READDIR`. + +## Owner + +The storage track, which moved `/home` behind the DATA server. + +## What would close it + +`read_dir("/home")` on a machine with a DATA volume answers `/home`'s entries, +and a guest test lists a served directory past `WINDOW_BYTES` and is refused +with `ResourceExhausted` by name rather than by any error. diff --git a/tests/toyos-rust-tests/src/bin/readdir_bound.rs b/tests/toyos-rust-tests/src/bin/readdir_bound.rs index 59126ddd902..3543c047428 100644 --- a/tests/toyos-rust-tests/src/bin/readdir_bound.rs +++ b/tests/toyos-rust-tests/src/bin/readdir_bound.rs @@ -7,10 +7,7 @@ //! buffer, stopped, and reported the bytes it had written, which is //! indistinguishable from a complete listing: 4125 entries of 34,816, as //! success. A bound plus a silent truncation is a quieter version of the same -//! defect, so both are asserted here. -//! -//! `/home` gets the same bound third, on the btree walk bcachefs lists with. -//! All below is an ordinary workload. +//! defect, so both are asserted here. All below is an ordinary workload. use std::fs; use std::process::Command; @@ -25,12 +22,7 @@ const MAX_LIST_ENTRIES: usize = 16_384; /// truncating kernel returns about 4,000 of them. const PLAIN_ENTRIES: usize = 6_000; -/// One past the bound: the walk is refused at the first entry over it, however -/// many the directory holds. -const HOME_ENTRIES: usize = MAX_LIST_ENTRIES + 1; - fn main() { - home_past_the_bound_is_refused(); plain_entries_are_all_returned(); subdirectories_at_the_limit(); one_past_the_limit_is_refused(); @@ -39,18 +31,6 @@ fn main() { println!("all readdir bound tests passed"); } -/// First, while nothing else holds file-cache entries: the listing bound on -/// `/home`. The files stay — this boot is the test's own. -fn home_past_the_bound_is_refused() { - for i in 0..HOME_ENTRIES { - fs::write(format!("/home/rb{i}"), b"").expect("create on /home failed"); - } - match fs::read_dir("/home") { - Ok(it) => panic!("listing /home past the limit returned {} entries", it.count()), - Err(e) => println!(" PASS: /home refused at {HOME_ENTRIES} entries ({e})"), - } -} - /// A listing larger than the caller's buffer comes back whole. /// /// Plain file entries, in their own subdirectory, so this exercises the @@ -95,11 +75,10 @@ fn one_past_the_limit_is_refused() { /// The bound belongs to the directory, not to the mount holding it. /// -/// Both mounts are over it by now and neither can list its own root, which is -/// the shape asserted at the end: every directory *in* them still lists, -/// including one holding nothing — the answer a mount-wide bound cannot give, -/// an empty listing and a refusal being the same byte to a caller checking -/// existence. A hash map and an on-disk B+tree, so this is the contract. +/// `/tmp` is over it by now and cannot list its own root, which is the shape +/// asserted at the end: every directory *in* it still lists, including one +/// holding nothing — the answer a mount-wide bound cannot give, an empty +/// listing and a refusal being the same byte to a caller checking existence. fn a_directory_still_lists_in_a_mount_past_the_bound() { let full = fs::read_dir("/tmp/d0").expect("read_dir of a directory in a full tmpfs"); let names: Vec = @@ -111,20 +90,11 @@ fn a_directory_still_lists_in_a_mount_past_the_bound() { assert_eq!(n, 0, "an empty directory listed {n} entries"); println!(" PASS: /tmp serves a directory and an empty one while its own root is refused"); - fs::write("/home/sub/one", b"x").expect("create on /home failed"); - let n = fs::read_dir("/home/sub").expect("read_dir of a directory in a full bcachefs").count(); - assert_eq!(n, 1, "/home/sub listed {n} entries"); - println!(" PASS: /home serves a directory while its own root is refused"); - - // The mount roots are directories too, and theirs is still the same bound. + // The mount root is a directory too, and its bound is still the same one. match fs::read_dir("/tmp") { Ok(it) => panic!("/tmp listed {} entries after the per-directory bound", it.count()), Err(e) => println!(" PASS: /tmp's own root is still refused ({e})"), } - match fs::read_dir("/home") { - Ok(it) => panic!("/home listed {} entries after the per-directory bound", it.count()), - Err(e) => println!(" PASS: /home's own root is still refused ({e})"), - } } /// The refusal cost the caller an error and nothing else. A panic inside diff --git a/tests/toyos.rs b/tests/toyos.rs index 50d551c8bf6..d7aa747ad9d 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -11158,7 +11158,7 @@ fn run_machine_test( ); serial::Serial::boot(&qemu).must_be_clean()?; - let result = qemu.run_test("test_rs_readdir_bound", Duration::from_secs(1328)); + let result = qemu.run_test("test_rs_readdir_bound", Duration::from_secs(545)); if let Some(err) = &result.error { return Err(format!("the guest stopped answering: {err}\nserial:\n{}", result.serial)); } From 94364cbb8e81a67d772fd72d1cba5b415ba0a966 Mon Sep 17 00:00:00 2001 From: japabu Date: Wed, 30 Sep 2026 16:52:52 +0200 Subject: [PATCH 04/19] The three LAN boots ride the talking boot: one T14 flash where there were four `lancase`, `lanicscase` and `lanleasecase` each flashed the stick and booted the machine once more (100-208 s a cycle in the rig's budget) to ask a question the talking boot, `lantalkcase`, now answers: - `lan_dhcp_lease` rides `lantalkcase`, which names the I219's function, so the loop pings the address it held under Ubuntu there as it did on `lancase`. netd's lines cross on the stick since each program has a log ring (#616), and on 630r4's full run `lantalkcase` carried the same MAC, link-up and lease lines `lancase` did. The judge drops `lan_hold`'s exit, which the talking boot's own judge replaces with `lan_talk_hold`'s. `lan.lancase.*` and `boot.lancase.ping_secs` are the talking boot's rows now. - `lan_message_delivery` rides it too, as `delivered_on_metal`. Its issue's exit condition was the shipping boot recording `pcidev: slot N took its first message` without the actuator, and all three LAN boots of 630r4 did, the talking one at 8.498 s. So `--provoke-message` has no question left: it goes from netd, from `toyos-i219` (`provoke_message` and the two tests of it) and from `build.rs`'s Intel-actuator gate, and `issues/hardware/the-lanicscase-boot-is-a-second-t14-flash-for-one-question.md` closes. - `lan_lease_report`'s metal row goes: netd's probe exists for a console line that could not cross, and the lease it reports is `lan_dhcp_lease`'s to judge off netd's own lines. The QEMU registration stays, since its link-flap check reads the probe's report; the issue that tracked the whole probe keeps that half under a slug that says what is left, `issues/diagnostics/netds-lease-probe-answers-a-question-its-lines-already-answer.md`, and `Readback::log_volume_file`, its only reader on the metal side, goes. Deleted with them: the three configs and their `ALL_CONFIGS` rows, their profile rows (the talking and swapping boots' rows that were derived "as lancase" now state that derivation), and `lan::CONFIG`, `BOOT`, `ICS_*`, `LEASE_CONFIG`, `LEASE_BOOT` and `JOBS`. `lan_hold` stays: `testcases-deaf` holds its boot open with it, and the metal-profile check of its window now reads that boot's allowance. The ssh issue's exit condition names the one arm it still owns. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- ...ers-a-question-its-lines-already-answer.md | 34 ++++ ...-is-a-third-t14-flash-for-one-exit-code.md | 43 ----- issues/filesystem/where-everything-lives.md | 7 +- ...-is-a-second-t14-flash-for-one-question.md | 38 ----- ...ped-answering-ssh-between-two-lan-boots.md | 5 +- src/build.rs | 41 ++--- src/metalprofile.rs | 9 +- tests/common/lan.rs | 112 +------------ tests/common/metal.rs | 18 -- tests/lancase/system.toml | 40 ----- tests/lanicscase/system.toml | 42 ----- tests/lanleasecase/system.toml | 40 ----- tests/lantalkcase/system.toml | 4 +- tests/metal-profile.toml | 154 ++---------------- tests/toyos.rs | 45 +---- toyos-i219/src/lib.rs | 11 -- toyos-i219/src/tests.rs | 52 ------ userland/netd/src/i219.rs | 5 - userland/netd/src/main.rs | 62 ++----- 19 files changed, 92 insertions(+), 670 deletions(-) create mode 100644 issues/diagnostics/netds-lease-probe-answers-a-question-its-lines-already-answer.md delete mode 100644 issues/diagnostics/the-lanleasecase-boot-is-a-third-t14-flash-for-one-exit-code.md delete mode 100644 issues/hardware/the-lanicscase-boot-is-a-second-t14-flash-for-one-question.md delete mode 100644 tests/lancase/system.toml delete mode 100644 tests/lanicscase/system.toml delete mode 100644 tests/lanleasecase/system.toml diff --git a/issues/diagnostics/netds-lease-probe-answers-a-question-its-lines-already-answer.md b/issues/diagnostics/netds-lease-probe-answers-a-question-its-lines-already-answer.md new file mode 100644 index 00000000000..ede5b39cf79 --- /dev/null +++ b/issues/diagnostics/netds-lease-probe-answers-a-question-its-lines-already-answer.md @@ -0,0 +1,34 @@ +--- +status: open +kind: tooling +opened: 2026-09-16 +--- + +# netd's lease probe answers a question its own lines already answer + +netd's `--exit-with-lease` brings the card up and serves exactly as the +shipping boot does for a bounded window, leaves `/log/lease.txt` on the log +volume one durable line at a time (the bring-up's own words, every link change, +the lease, what the driver and the MAC counted each way), and ends with +`toyos_i219::lease::Verdict`'s code. It existed because every line netd printed +about the same things was a console write, and on the T14 a console write +reached no file. Every program's lines reach `/log` through its log ring now, +and the talking boot's `lan_dhcp_lease` judge reads the lease off netd's own +lines, so the probe's T14 boot, `tests/lanleasecase`, is gone. What still arms +it is `tests/e1000leasecase` and the `lan_lease_report` QEMU registration, +whose link-flap check reads the report. + +## Owner + +The I219 bring-up's author, and after it the network track. + +## What would close it + +The flap judged off netd's own lines. Then netd's `--exit-with-lease`, +`userland/netd/src/report.rs`, `toyos-i219/src/lease.rs`'s report lines, +`tests/e1000leasecase` and the `lan_lease_report` QEMU registration go. + +An earlier form of this arm, `--exit-with-phy-outcome` on `d409139f^:tests/lanphycase`, +ended right after the bring-up with the PHY's outcome; its codes are still +`Verdict::NotLeased`'s, so a code read off one of its boots means what +`toyos_i219::phy::Outcome` says. diff --git a/issues/diagnostics/the-lanleasecase-boot-is-a-third-t14-flash-for-one-exit-code.md b/issues/diagnostics/the-lanleasecase-boot-is-a-third-t14-flash-for-one-exit-code.md deleted file mode 100644 index 2b1db4a1aa5..00000000000 --- a/issues/diagnostics/the-lanleasecase-boot-is-a-third-t14-flash-for-one-exit-code.md +++ /dev/null @@ -1,43 +0,0 @@ ---- -status: open -kind: tooling -opened: 2026-09-16 ---- - -# `tests/lanleasecase` is a third T14 flash, and it earns it only while netd's console line cannot cross - -`tests/lanleasecase` is `tests/lancase` with one `args` row — netd's -`--exit-with-lease`, under which netd brings the card up and serves exactly as -the shipping boot does for a bounded window, leaves `/log/lease.txt` on the log -volume one durable line at a time (the bring-up's own words, every link change, -the lease, what the driver and the MAC counted each way), and ends with -`toyos_i219::lease::Verdict`'s code. It exists because every line netd prints -about the same things is a console write, and on the T14 a console write -reaches no file -(`issues/diagnostics/the-cable-judge-reads-three-netd-records-that-cannot-arrive-on-the-t14.md`): -the kernel's `exit: netd pid=N code=N` record and a file netd writes itself are -the two words of a process that cross. It is the `lan_lease_report` metal row, -a third image flashed to the stick, a third boot of the machine and six rows of -`tests/metal-profile.toml`. - -## Owner - -The I219 bring-up's author, and after it the network track. - -## What would close it - -Userland's lines reaching the stick, which they do through each program's log -ring (`issues/kernel/logging-records-from-every-producer-and-a-kernel-that-waits-on-nobody.md`), after -which the shipping `lancase` arm carries netd's own lines about the lease and -the probe answers a question already answered. Then the arm is: -`tests/lanleasecase/system.toml`, its row in `src/build.rs`'s `ALL_CONFIGS`, -the `lan_lease_report` metal row in `tests/toyos.rs` with `LANLEASECASE` and -`lan::leased_on_metal`, the six `tests/metal-profile.toml` rows, -`userland/netd/src/report.rs` and `toyos-i219/src/lease.rs`'s report lines — -and netd's `--exit-with-lease` with `tests/e1000leasecase` and the -`lan_lease_report` QEMU registration, the arm that proves the channel. - -An earlier form of this arm, `--exit-with-phy-outcome` on `d409139f^:tests/lanphycase`, -ended right after the bring-up with the PHY's outcome; its codes are still -`Verdict::NotLeased`'s, so a code read off one of its boots means what -`toyos_i219::phy::Outcome` says. diff --git a/issues/filesystem/where-everything-lives.md b/issues/filesystem/where-everything-lives.md index 2695ecbc044..00d90122f67 100644 --- a/issues/filesystem/where-everything-lives.md +++ b/issues/filesystem/where-everything-lives.md @@ -114,7 +114,6 @@ until that lands nothing verifies it. ## Not moved `/log/lease.txt` stays on `/log`. It is not netd's lease: it is the -`--exit-with-lease` bench report the metal loop reads off the stick's FAT log -volume, as it reads `/log/metal-*.bin`, and the DATA volume is not readable -there. It goes with -`issues/diagnostics/the-lanleasecase-boot-is-a-third-t14-flash-for-one-exit-code.md`. +`--exit-with-lease` bench report the harness reads off the image's FAT log +volume, and the DATA volume is not readable there. It goes with +`issues/diagnostics/netds-lease-probe-answers-a-question-its-lines-already-answer.md`. diff --git a/issues/hardware/the-lanicscase-boot-is-a-second-t14-flash-for-one-question.md b/issues/hardware/the-lanicscase-boot-is-a-second-t14-flash-for-one-question.md deleted file mode 100644 index 27b2a5ff9c8..00000000000 --- a/issues/hardware/the-lanicscase-boot-is-a-second-t14-flash-for-one-question.md +++ /dev/null @@ -1,38 +0,0 @@ ---- -status: open -kind: tooling -opened: 2026-09-13 ---- - -# `tests/lanicscase` is a second T14 flash, and it earns it only while the card is silent - -`tests/lanicscase` is `tests/lancase` with one `args` row — netd's -`--provoke-message`, which writes one enabled cause to `ICS` so the kernel's -`pcidev: slot N took its first message` record says whether delivery works at -all. It is the `lan_message_delivery` metal row, a second image flashed to the -stick, a second boot of the machine and six rows of `tests/metal-profile.toml` -(`boot.lanicscase.{complete_ms,back_secs,stick_secs,panel_max_us,panel_us}`, -`list.lanicscase.job_ms`). - -**A count of no messages is two facts** — a part nothing made speak and a -message that reached no CPU — and only this arm separates them. On a card that -raises its own `LSC` it records exactly what `tests/lancase` records, so from -that moment it is a boot of the machine that answers a question already -answered. - -## Owner - -The I219 bring-up's author, and after it the network track. - -## What would close it - -The shipping `lancase` arm recording `pcidev: slot N took its first message` -without the actuator. Then the actuator has no question left and the arm is -four files: `tests/lanicscase/system.toml`, its row in `src/build.rs`'s -`ALL_CONFIGS`, `tests/toyos.rs`'s `lan_message_delivery` row, its `METAL_ONLY` -entry and `LANICSCASE` with the judge `lan::provoked_on_metal`, and the six -`tests/metal-profile.toml` rows. - -Metal run 57 recorded `pcidev: slot 0 took its first message on vector 0x28` -after the I219's hand-over on that slot and vector, so the second fact is read: -a message this function raises reaches a CPU. The arm stands until `lancase` records one without the actuator. diff --git a/issues/hardware/the-t14-stopped-answering-ssh-between-two-lan-boots.md b/issues/hardware/the-t14-stopped-answering-ssh-between-two-lan-boots.md index 2d5d5149f47..daca038b5e0 100644 --- a/issues/hardware/the-t14-stopped-answering-ssh-between-two-lan-boots.md +++ b/issues/hardware/the-t14-stopped-answering-ssh-between-two-lan-boots.md @@ -34,8 +34,7 @@ toyos-metal: the swap did not put the new binary in service: ## Exit condition -`lan_lease_report` and `lan_swap` are owned by this file until it closes. -Three consecutive T14 metal runs each reach both judges, `lanleasecase` and -`lanswapcase`, without an `ssh` timeout before either flash; then this file is +`lan_swap` is owned by this file until it closes. Three consecutive T14 +metal runs each reach `lanswapcase`'s judge without an `ssh` timeout before its flash; then this file is deleted. A red on a judge in any of the three is filed as its own issue file naming that test and its cause before this one closes. diff --git a/src/build.rs b/src/build.rs index 7e43ae2bd8d..88c12b57e11 100644 --- a/src/build.rs +++ b/src/build.rs @@ -3139,9 +3139,6 @@ mod tests { "tests/inspectcase/system.toml", "tests/jobcase/system.toml", "tests/jobdeadlinecase/system.toml", - "tests/lancase/system.toml", - "tests/lanicscase/system.toml", - "tests/lanleasecase/system.toml", "tests/lantalkcase/system.toml", "tests/latencycase/system.toml", "tests/layoutcase/system.toml", @@ -3347,12 +3344,10 @@ mod tests { assert!(one_claimant_per_device(&bad, None).is_err()); } - /// netd's two actuators that only its Intel driver answers, spelled here - /// and held to netd's own declarations by + /// netd's actuators that only its Intel driver answers, spelled here and + /// held to netd's own declarations by /// [`netd_declares_the_flags_this_gate_spells`]. - const PROVOKE_MESSAGE: &str = "--provoke-message"; - const EXIT_WITH_LEASE: &str = "--exit-with-lease"; - const INTEL_ACTUATORS: [&str; 2] = [PROVOKE_MESSAGE, EXIT_WITH_LEASE]; + const INTEL_ACTUATORS: [&str; 1] = ["--exit-with-lease"]; /// netd's main module, which is where both halves of this gate's spelling /// live: nothing links the two crates, so the build system reads the source. @@ -3415,27 +3410,19 @@ mod tests { cards } - /// netd's two Intel-only actuators — `--provoke-message` writes - /// §10.2.4.4's `ICS`, and `--exit-with-lease` reports the Intel driver's - /// bring-up beside the lease — and virtio's driver has neither, so a boot - /// config that arms one on a card netd opens with any other driver is a boot - /// that panics instead of answering the question it was flashed for. One - /// that arms both on one program is refused too: the probe ends the process - /// before the point the other acts at. + /// netd's Intel-only actuators — `--exit-with-lease` reports the Intel + /// driver's bring-up beside the lease — and virtio's driver has none, so a + /// boot config that arms one on a card netd opens with any other driver is + /// a boot that panics instead of answering the question it was built for. fn an_armed_intel_actuator_claims_a_card_the_driver_opens( cfg: &SystemConfig, cards: &[String], ) -> Result<(), String> { for (name, prog) in &cfg.programs { - let armed: Vec<&str> = INTEL_ACTUATORS - .into_iter() - .filter(|flag| prog.args.iter().any(|arg| arg == flag)) - .collect(); - let [flag] = armed[..] else { - if armed.is_empty() { - continue; - } - return Err(format!("`{name}` is armed with {armed:?}, which cannot share a boot")); + let Some(flag) = + INTEL_ACTUATORS.into_iter().find(|flag| prog.args.iter().any(|arg| arg == flag)) + else { + continue; }; if !prog.devices.iter().any(|d| cards.contains(d)) { return Err(format!( @@ -3487,12 +3474,6 @@ mod tests { assert!(armed_on("pci:8086:1502", &one).is_err(), "{flag}"); assert!(armed_on(&cards[0], &one).is_ok(), "{flag}"); } - for (at, one) in INTEL_ACTUATORS.into_iter().enumerate() { - for other in &INTEL_ACTUATORS[at + 1..] { - let both = format!("\"{one}\", \"{other}\""); - assert!(armed_on(&cards[0], &both).is_err(), "{one} beside {other}"); - } - } } /// A device name the ABI does not know renders fine and leaves init with a diff --git a/src/metalprofile.rs b/src/metalprofile.rs index 3b934d45760..bf1a901764b 100644 --- a/src/metalprofile.rs +++ b/src/metalprofile.rs @@ -306,16 +306,15 @@ mod sizing_tests { } /// **`lan_hold` sleeps a bound this file prices.** The guest binary holds - /// the machine up for `toyos_tco::LEASE_BOUND_MS`, and the boot's own job - /// allowance has to outlast it or the runner's deadline cuts the window the - /// host reaches that machine across. + /// the machine up for `toyos_tco::LEASE_BOUND_MS`, and the allowance of the + /// boot it holds open has to outlast it or the runner's deadline cuts it. #[test] fn the_window_lan_hold_sleeps_is_the_window_this_file_prices() { let profile = Profile::load(root()).expect(PATH); let hold = toyos_tco::LEASE_BOUND_MS; - let job = profile.row(&job_ms_row("lancase")).expect("lancase's own allowance"); + let job = profile.row(&job_ms_row("testcases-deaf")).expect("testcases-deaf's own allowance"); assert!(job.ceiling > hold, "{} against a {hold} ms hold", job.ceiling); - for name in ["lan.lancase.link_up_ms", "lan.lancase.lease_ms"] { + for name in ["lan.lantalkcase.link_up_ms", "lan.lantalkcase.lease_ms"] { let row = profile.row(name).unwrap_or_else(|| panic!("{name} is priced")); assert_eq!(row.ceiling, hold, "{name}"); } diff --git a/tests/common/lan.rs b/tests/common/lan.rs index 85ef76d6846..988e5c5aa7e 100644 --- a/tests/common/lan.rs +++ b/tests/common/lan.rs @@ -23,35 +23,13 @@ use super::metal; use super::qemu::{self, BootOptions, QemuInstance}; use super::serial; -/// The boot config the T14 arm flashes, and the name every profile row for that -/// boot is under. -pub const CONFIG: &str = "tests/lancase"; -pub const BOOT: &str = "lancase"; - -/// The same boot with netd's `--provoke-message` armed: the arm that says -/// whether a message the card raises reaches a CPU at all, which no reading of -/// the shipping boot separates from a card that raised none. -pub const ICS_CONFIG: &str = "tests/lanicscase"; -pub const ICS_BOOT: &str = "lanicscase"; - -/// The same boot with netd's `--exit-with-lease` armed: netd brings the card up -/// and serves as that boot does, leaves [`LEASE_FILE`] on the log volume one -/// durable line at a time, and ends with the lease's verdict as its exit code, -/// which the kernel's `exit:` record carries off a machine whose console -/// reaches nobody. -pub const LEASE_CONFIG: &str = "tests/lanleasecase"; -pub const LEASE_BOOT: &str = "lanleasecase"; - -/// The file that report is left in, at the root of the log volume — netd's -/// `report::PATH` under `/log`. +/// The file netd's `--exit-with-lease` leaves its report in, at the root of +/// the log volume — netd's `report::PATH` under `/log`. pub const LEASE_FILE: &str = "lease.txt"; /// netd, as the kernel's `exit:` record names it. const NETD: &str = "netd"; -/// The one job on that boot: it holds the machine up while the host pings it. -pub const JOBS: &[&str] = &["test_rs_lan_hold"]; - /// The boot the host talks to over its own cable: the log it serves, sshd, and /// `reboot` as the way the machine is handed back. pub const TALK_CONFIG: &str = "tests/lantalkcase"; @@ -70,10 +48,9 @@ const TALK_KEY: &str = "lantalk"; /// verdict. const TALK_CEILING: std::time::Duration = std::time::Duration::from_secs(41); -/// The armed boot's judge: the kernel's own records, tied to the I219's -/// hand-over, say whether a message it raised reached a CPU — whatever the PHY -/// did about a link. -pub fn provoked_on_metal(back: &metal::Readback) -> Result<(), String> { +/// The kernel's own records, tied to the I219's hand-over, say a message it +/// raised reached a CPU — whatever the PHY did about a link. +pub fn delivered_on_metal(back: &metal::Readback) -> Result<(), String> { let got = toyos_build::lan::delivered(back.kernel().text())?; eprintln!(" [lan] {}", got.handed.trim()); eprintln!(" [lan] {}", got.took.trim()); @@ -125,7 +102,7 @@ pub fn on_metal(back: &metal::Readback) -> Result<(), String> { Some(line) => format!("the kernel refused this function: {}", line.trim()), None => format!( "no `{handed}` record and no refusal either: nothing on this machine claimed \ - {ID}, so `tests/lancase` was flashed onto a machine that has no such card" + {ID}, so `tests/lantalkcase` was flashed onto a machine that has no such card" ), }), } @@ -206,89 +183,12 @@ pub fn on_metal(back: &metal::Readback) -> Result<(), String> { )), } - if let Err(why) = back.job_passed(JOBS[0]) { - bad.push(why); - } - if bad.is_empty() { return Ok(()); } Err(format!("{} finding(s):\n {}", bad.len(), bad.join("\n "))) } -/// The lease probe's judge: netd's exit code, decoded through the table the -/// driver crate owns, and the report it left on the log volume — the lease, -/// the router, and what the driver and the MAC counted each way. A code that is -/// no lease is a finding by its name, which the shipping boot's silence cannot -/// give. -/// -/// **The host's ping is printed and not judged**: the lease is a server this -/// machine does not control answering it, which is the claim; a reply at the -/// leased address inside this boot is the same claim made from the bench's -/// side, and the loop asks for it only where it was told the cable. -pub fn leased_on_metal(back: &metal::Readback) -> Result<(), String> { - let code = back.exit_code(NETD)?; - let text = back - .log_volume_file(LEASE_FILE)? - .ok_or_else(|| format!("{LEASE_BOOT}'s log volume carries no {LEASE_FILE}"))?; - for line in text.lines() { - eprintln!(" [lan] {LEASE_FILE}: {line}"); - } - let summary = lease::summary(&text).map_err(|why| format!("{LEASE_FILE}: {why}"))?; - if summary.exit != Some(code) { - return Err(format!( - "netd exited {code} and its report ends in {:?}: the two records of one exit disagree", - summary.exit - )); - } - match Verdict::from_exit_code(code) { - Some(Verdict::Leased) => {} - Some(other) => return Err(format!("netd exited {code} on {LEASE_BOOT}: {other}")), - None => { - return Err(format!("netd exited {code} on {LEASE_BOOT}, which is no verdict the probe encodes")) - } - } - let Some((ms, Event::Leased { address, prefix, server, router })) = summary.lease else { - return Err(format!("netd exited leased and {LEASE_FILE} records no lease")); - }; - let counts = summary.counts.ok_or_else(|| format!("{LEASE_FILE} carries no counts"))?; - eprintln!( - " [lan] leased {address}/{prefix} from {server}, router {router:?}, {ms} ms after netd \ - started; the driver counted {} sent and {} received, the MAC {} sent, {} received of \ - {} seen", - counts.sent, counts.received, counts.wire.sent, counts.wire.received, counts.wire.seen - ); - if counts.sent == 0 || counts.received == 0 { - return Err(format!("a lease with {counts:?} is no exchange this card carried")); - } - match back.cable.as_ref() { - None => eprintln!(" [lan] no cable was named, so the host asked nothing of this boot"), - Some(cable) => match cable.reply { - None => eprintln!(" [lan] nothing answered the host's ping at {}", cable.addr), - Some(reply) => { - let handed = format!("[{ID}] handed over on slot"); - match bootlog::host_second_inside_this_boot( - back.kernel().text(), - cable.skew, - &handed, - reply.at, - ) { - Ok(()) => eprintln!( - " [lan] {} answered the host's ping {} s into the window, inside this \ - boot", - cable.addr, reply.secs - ), - Err(why) => eprintln!( - " [lan] {} answered the host's ping, and not inside this boot: {why}", - cable.addr - ), - } - } - }, - } - Ok(()) -} - /// The netdev QEMU's `e1000e` profile names its backend, which the monitor's /// `set_link` is addressed to. const FLAP_NETDEV: &str = "net0"; diff --git a/tests/common/metal.rs b/tests/common/metal.rs index dec363bab88..08666910ad3 100644 --- a/tests/common/metal.rs +++ b/tests/common/metal.rs @@ -298,24 +298,6 @@ impl Readback { Ok((swapped, stream.split_inclusive('\n').map(str::to_string).collect())) } - /// One file off the log volume that is neither the loader's nor `logd`'s, - /// read out of the partition's own bytes; `None` where the volume has no - /// such file. - /// - /// **The loop copies two kinds of file off the mount and this is neither**, - /// so it comes out of `metal::READBACK_VOLUME` — which the loop keeps on - /// every boot that came back, because the outside judge runs on every one. - pub fn log_volume_file(&self, name: &str) -> Result, String> { - let at = self.home.join(toyos_build::metal::READBACK_VOLUME); - let volume = std::fs::read(&at).map_err(|e| format!("{}: {e}", at.display()))?; - let found = super::volumes::read_files(&volume, &[name])?.pop().flatten(); - found - .map(|bytes| { - String::from_utf8(bytes).map_err(|e| format!("{}'s {name}: {e}", self.label)) - }) - .transpose() - } - /// Every `logd` file this boot wrote, as one text, less every program's /// line ([`bootlog::kernel_records`]): no program's line is read as the kernel's. /// It ends where init had `logd` make it whole, so what the kernel writes diff --git a/tests/lancase/system.toml b/tests/lancase/system.toml deleted file mode 100644 index b469a5032a4..00000000000 --- a/tests/lancase/system.toml +++ /dev/null @@ -1,40 +0,0 @@ -# The one boot that runs netd in front of the ThinkPad T14's own NIC. -# -# A directory of its own for the reason `tests/e1000case` is one: a program that -# names a card the machine does not have costs an `init:` refusal line on every -# boot of the config that does, and no machine has both. -# -# Nothing here reaches the internal NVMe. There is no `[disks]` row, and the -# only device any program on this boot claims is the PCI function named below. - -[boot] -start = ["logd", "blockd", "fsd", "netd", "test-runner"] - -[programs.logd] -service = true -syscap = ["logread"] - -[programs.netd] -service = true -serves = ["netd"] -devices = ["pci:8086:15fc"] - -[programs.test-runner] -syscap = ["logread"] - -# The block service: the NVMe controller this machine's DATA is on, driven -# from userland through its claim. Started again when it ends; the claim goes -# back with the process and is minted again for the next. -[programs.blockd] -service = true -restart = true -serves = ["block"] -devices = ["pci:1b36:0010"] - -# The file servers: DATA, the log and the running slot's volume, one process -# each, serving every program the directories of its role. Started again when -# one ends, on the same ports. -[programs.fsd] -restart = true -roles = ["data", "log", "boot"] -receives = ["block"] diff --git a/tests/lanicscase/system.toml b/tests/lanicscase/system.toml deleted file mode 100644 index 6e17dd2b1a6..00000000000 --- a/tests/lanicscase/system.toml +++ /dev/null @@ -1,42 +0,0 @@ -# `tests/lancase` with netd's delivery actuator armed, and nothing else. -# -# A boot whose only reading of the interrupt path is a count of messages cannot -# tell a part nothing made speak from a message that reached no CPU. The -# shipping config next door arms none of it, so its own record still means the -# card spoke on its own. -# -# Nothing here reaches the internal NVMe. There is no `[disks]` row, and the -# only device any program on this boot claims is the PCI function named below. - -[boot] -start = ["logd", "blockd", "fsd", "netd", "test-runner"] - -[programs.logd] -service = true -syscap = ["logread"] - -[programs.netd] -service = true -serves = ["netd"] -devices = ["pci:8086:15fc"] -args = ["--provoke-message"] - -[programs.test-runner] -syscap = ["logread"] - -# The block service: the NVMe controller this machine's DATA is on, driven -# from userland through its claim. Started again when it ends; the claim goes -# back with the process and is minted again for the next. -[programs.blockd] -service = true -restart = true -serves = ["block"] -devices = ["pci:1b36:0010"] - -# The file servers: DATA, the log and the running slot's volume, one process -# each, serving every program the directories of its role. Started again when -# one ends, on the same ports. -[programs.fsd] -restart = true -roles = ["data", "log", "boot"] -receives = ["block"] diff --git a/tests/lanleasecase/system.toml b/tests/lanleasecase/system.toml deleted file mode 100644 index 436ae50ffa3..00000000000 --- a/tests/lanleasecase/system.toml +++ /dev/null @@ -1,40 +0,0 @@ -# `tests/lancase` with netd's lease probe armed, and nothing else: netd brings -# the card up and serves exactly as that boot does, leaves what happened on the -# log volume one durable line at a time, and ends with the lease's verdict as -# its exit code — which the kernel's `exit:` record carries off a machine whose -# console reaches nobody. Like `tests/lancase`, nothing here reaches the -# internal NVMe: no `[disks]` row, and the only device any program claims is -# the PCI function named below. - -[boot] -start = ["logd", "blockd", "fsd", "netd", "test-runner"] - -[programs.logd] -service = true -syscap = ["logread"] - -[programs.netd] -service = true -serves = ["netd"] -devices = ["pci:8086:15fc"] -args = ["--exit-with-lease"] - -[programs.test-runner] -syscap = ["logread"] - -# The block service: the NVMe controller this machine's DATA is on, driven -# from userland through its claim. Started again when it ends; the claim goes -# back with the process and is minted again for the next. -[programs.blockd] -service = true -restart = true -serves = ["block"] -devices = ["pci:1b36:0010"] - -# The file servers: DATA, the log and the running slot's volume, one process -# each, serving every program the directories of its role. Started again when -# one ends, on the same ports. -[programs.fsd] -restart = true -roles = ["data", "log", "boot"] -receives = ["block"] diff --git a/tests/lantalkcase/system.toml b/tests/lantalkcase/system.toml index ef574afd005..b4463db4e88 100644 --- a/tests/lantalkcase/system.toml +++ b/tests/lantalkcase/system.toml @@ -4,8 +4,8 @@ # among them, which is how the host hands the machine back. # # `tests/e1000talkcase` is the same boot in front of QEMU's 82574; the two -# differ by the one `devices` row, for the reason `tests/lancase` and -# `tests/e1000case` do. Nothing here reaches the internal NVMe: no `[disks]` +# differ by the one `devices` row, for the reason `tests/e1000case` is its +# own directory. Nothing here reaches the internal NVMe: no `[disks]` # row, and the only device any program claims is the PCI function below. [boot] diff --git a/tests/metal-profile.toml b/tests/metal-profile.toml index 7d807103da5..a3d776cfc74 100644 --- a/tests/metal-profile.toml +++ b/tests/metal-profile.toml @@ -700,7 +700,7 @@ ceiling_from = "as list.testcases.job_ms" name = "list.testcases-deaf.job_ms" unit = "ms" ceiling = 22000 -ceiling_from = "as list.lancase.job_ms — the same one job" +ceiling_from = "toyos_tco::LEASE_BOUND_MS, which is lan_hold's whole sleep, plus two seconds for the spawn and the exit record around it" [[number]] name = "list.testcases-window.job_ms" @@ -760,80 +760,26 @@ ceiling_from = "as boot.testcases.stick_secs" # --- the cable: the boot that runs netd in front of the T14's own I219 --- -[[number]] -name = "boot.lancase.complete_ms" -unit = "ms" -ceiling = 60000 -ceiling_from = "toyos_tco::JOB_BOUND_MS — as boot.testcases.complete_ms" -measured = 1208 - -[[number]] -name = "boot.lancase.back_secs" -unit = "s" -ceiling = 420 -ceiling_from = "toyos_build::metal::return_secs" -measured = 82 - -[[number]] -name = "boot.lancase.stick_secs" -unit = "s" -ceiling = 30 -ceiling_from = "as boot.testcases.stick_secs" -measured = 0 - # No `measured`: the one ping this row has been offered was answered by the # operating system on the other side of the reset, which the judge refuses, so # no boot has yet given this number a reading. [[number]] -name = "boot.lancase.ping_secs" +name = "boot.lantalkcase.ping_secs" unit = "s" ceiling = 420 ceiling_from = "toyos_build::metal::return_secs — the loop's own wait for the machine to answer ssh again, which bounds the window a reply can fall in" [[number]] -name = "list.lancase.job_ms" -unit = "ms" -ceiling = 22000 -ceiling_from = "toyos_tco::LEASE_BOUND_MS, which is lan_hold's whole sleep, plus two seconds for the spawn and the exit record around it" - -[[number]] -name = "lan.lancase.link_up_ms" +name = "lan.lantalkcase.link_up_ms" unit = "ms" ceiling = 20000 -ceiling_from = "toyos_tco::LEASE_BOUND_MS: a link that comes up later than lan_hold sleeps is a link this boot never had, because the machine has already handed itself back" +ceiling_from = "toyos_tco::LEASE_BOUND_MS: a link later than netd's own dhcp::LEASE_BOUND is a boot whose log has already said it holds no lease" [[number]] -name = "lan.lancase.lease_ms" +name = "lan.lantalkcase.lease_ms" unit = "ms" ceiling = 20000 -ceiling_from = "as lan.lancase.link_up_ms, which is netd's own dhcp::LEASE_BOUND: a boot with no lease by then has already said so in its log" - -# `lanicscase` is `lancase` with one argument added to netd's manifest row, so -# every bound it is under is that boot's. - -[[number]] -name = "boot.lanicscase.complete_ms" -unit = "ms" -ceiling = 60000 -ceiling_from = "as boot.lancase.complete_ms — the same boot config with one netd argument added" - -[[number]] -name = "boot.lanicscase.back_secs" -unit = "s" -ceiling = 420 -ceiling_from = "toyos_build::metal::return_secs" - -[[number]] -name = "boot.lanicscase.stick_secs" -unit = "s" -ceiling = 30 -ceiling_from = "as boot.lancase.stick_secs" - -[[number]] -name = "list.lanicscase.job_ms" -unit = "ms" -ceiling = 22000 -ceiling_from = "as list.lancase.job_ms — the same one job" +ceiling_from = "as lan.lantalkcase.link_up_ms, which is netd's own dhcp::LEASE_BOUND: a boot with no lease by then has already said so in its log" # --- what the on-screen panel cost each boot --- # **The one window a person has into a machine that stopped.** Two numbers, @@ -966,18 +912,6 @@ unit = "us" ceiling = 16667 ceiling_from = "as boot.testcases.panel_max_us" -[[number]] -name = "boot.lancase.panel_max_us" -unit = "us" -ceiling = 16667 -ceiling_from = "as boot.testcases.panel_max_us" - -[[number]] -name = "boot.lanicscase.panel_max_us" -unit = "us" -ceiling = 16667 -ceiling_from = "as boot.testcases.panel_max_us" - [[number]] name = "boot.testcases.panel_us" unit = "us" @@ -1214,24 +1148,6 @@ unit = "operations" ceiling = 0 ceiling_from = "as boot.testcases.park_open_operations" -[[number]] -name = "boot.lancase.park_open_operations" -unit = "operations" -ceiling = 0 -ceiling_from = "as boot.testcases.park_open_operations" - -[[number]] -name = "boot.lanicscase.park_open_operations" -unit = "operations" -ceiling = 0 -ceiling_from = "as boot.testcases.park_open_operations" - -[[number]] -name = "boot.lanleasecase.park_open_operations" -unit = "operations" -ceiling = 0 -ceiling_from = "as boot.testcases.park_open_operations" - [[number]] name = "boot.lantalkcase.park_open_operations" unit = "operations" @@ -1244,55 +1160,7 @@ unit = "us" ceiling = 100000 ceiling_from = "as boot.testcases.panel_us" -[[number]] -name = "boot.lancase.panel_us" -unit = "us" -ceiling = 100000 -ceiling_from = "as boot.testcases.panel_us" - -[[number]] -name = "boot.lanicscase.panel_us" -unit = "us" -ceiling = 100000 -ceiling_from = "as boot.testcases.panel_us" - -[[number]] -name = "boot.lanleasecase.complete_ms" -unit = "ms" -ceiling = 60000 -ceiling_from = "as boot.lancase.complete_ms — the same boot config with one netd argument added" - -[[number]] -name = "boot.lanleasecase.back_secs" -unit = "s" -ceiling = 420 -ceiling_from = "toyos_build::metal::return_secs" - -[[number]] -name = "boot.lanleasecase.stick_secs" -unit = "s" -ceiling = 30 -ceiling_from = "as boot.lancase.stick_secs" - -[[number]] -name = "list.lanleasecase.job_ms" -unit = "ms" -ceiling = 22000 -ceiling_from = "as list.lancase.job_ms — the same one job" - -[[number]] -name = "boot.lanleasecase.panel_max_us" -unit = "us" -ceiling = 16667 -ceiling_from = "as boot.testcases.panel_max_us" - -[[number]] -name = "boot.lanleasecase.panel_us" -unit = "us" -ceiling = 100000 -ceiling_from = "as boot.testcases.panel_us" - -# `lantalkcase` is `lancase` with sshd and its log served, talked to from the +# `lantalkcase` is the cable's boot with sshd and its log served, talked to from the # host until it is told to reboot. Its one job holds the machine only as the # fallback for a host that never says so. @@ -1300,7 +1168,7 @@ ceiling_from = "as boot.testcases.panel_us" name = "boot.lantalkcase.complete_ms" unit = "ms" ceiling = 60000 -ceiling_from = "as boot.lancase.complete_ms" +ceiling_from = "toyos_tco::JOB_BOUND_MS — as boot.testcases.complete_ms" [[number]] name = "boot.lantalkcase.back_secs" @@ -1312,7 +1180,7 @@ ceiling_from = "toyos_build::metal::return_secs" name = "boot.lantalkcase.stick_secs" unit = "s" ceiling = 30 -ceiling_from = "as boot.lancase.stick_secs" +ceiling_from = "as boot.testcases.stick_secs" [[number]] name = "list.lantalkcase.job_ms" @@ -1339,7 +1207,7 @@ ceiling_from = "as boot.testcases.panel_us" name = "boot.lanswapcase.complete_ms" unit = "ms" ceiling = 60000 -ceiling_from = "as boot.lancase.complete_ms" +ceiling_from = "toyos_tco::JOB_BOUND_MS — as boot.testcases.complete_ms" [[number]] name = "boot.lanswapcase.back_secs" @@ -1351,7 +1219,7 @@ ceiling_from = "toyos_build::metal::return_secs" name = "boot.lanswapcase.stick_secs" unit = "s" ceiling = 30 -ceiling_from = "as boot.lancase.stick_secs" +ceiling_from = "as boot.testcases.stick_secs" [[number]] name = "list.lanswapcase.job_ms" diff --git a/tests/toyos.rs b/tests/toyos.rs index d7aa747ad9d..b3f304c36ec 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -258,8 +258,7 @@ const RUST_SKIP: &[&str] = &[ "netd_refused_pipes", "netd_refused_accept", "netd_lookup_let_go", - // It asserts nothing at all: it holds a `tests/lancase` boot open for - // twenty seconds so the host can reach this machine over the cable. On a + // It asserts nothing at all: it holds a boot open for twenty seconds. On a // shared boot it would be twenty seconds of nothing. "lan_hold", // The same for `tests/lantalkcase`, held until the runner's bound is near @@ -1503,19 +1502,11 @@ const METAL: &[(&str, metal::Metal)] = &[ ), ( "lan_dhcp_lease", - metal::Metal::Runs { arms: LANCASE, judge: |b| lan::on_metal(b[0]) }, + metal::Metal::Runs { arms: LANTALKCASE, judge: |b| lan::on_metal(b[0]) }, ), ( - // Folded into `lan_dhcp_lease`'s judge once the PHY is brought up - // (#453): lancase's own first-message record then carries this fact. "lan_message_delivery", - metal::Metal::Runs { arms: LANICSCASE, judge: |b| lan::provoked_on_metal(b[0]) }, - ), - ( - // The first byte: a lease from the bench's own router, read off the - // stick, while the host pings the address this machine had before. - "lan_lease_report", - metal::Metal::Runs { arms: LANLEASECASE, judge: |b| lan::leased_on_metal(b[0]) }, + metal::Metal::Runs { arms: LANTALKCASE, judge: |b| lan::delivered_on_metal(b[0]) }, ), ( "lan_talk", @@ -2087,33 +2078,13 @@ const USB_RESET_BOOTS: &[metal::Arm] = &[ const METALCASE: &[metal::Arm] = &[metal::once("metalcase", "tests/metalcase", &[], &[])]; -/// The cable's own boot: netd in front of the T14's I219, and one job that -/// holds the machine up long enough for the host to reach it. The one arm in -/// this suite that names a PCI function for the loop to reach the boot over. -const LANCASE: &[metal::Arm] = - &[metal::Arm { nic: Some(lan::NIC), ..metal::once(lan::BOOT, lan::CONFIG, &[], lan::JOBS) }]; - -/// The cable's boot with netd's delivery actuator armed. **A count of no -/// messages is two facts** — a part nothing made speak and a message that -/// reached no CPU — so this boot asks the part for a message and `LANCASE` does -/// not. It names no PCI function: its judge reads the kernel's own records and -/// asks the cable nothing. -const LANICSCASE: &[metal::Arm] = &[metal::once(lan::ICS_BOOT, lan::ICS_CONFIG, &[], lan::JOBS)]; - -/// The cable's boot with netd's lease probe armed: netd's exit code is the -/// lease's verdict, read out of the kernel's own `exit:` record, and its report -/// is on the log volume. It names the I219 for the loop to ping over the cable, -/// as [`LANCASE`] does. -const LANLEASECASE: &[metal::Arm] = &[metal::Arm { - nic: Some(lan::NIC), - ..metal::once(lan::LEASE_BOOT, lan::LEASE_CONFIG, &[], lan::JOBS) -}]; - -/// The boot the host talks to over its own cable: the loop reads the log it -/// serves under its name, pings it, runs a command on it and tells it to -/// reboot. +/// The cable's boot, netd in front of the T14's I219, which the host talks to +/// over that cable: the loop reads the log it serves under its name, pings it, +/// runs a command on it and tells it to reboot. It names the PCI function, so +/// the loop also pings the address it held under the operating system before. const LANTALKCASE: &[metal::Arm] = &[metal::Arm { talk: true, + nic: Some(lan::NIC), ..metal::once(lan::TALK_BOOT, lan::TALK_CONFIG, &[], lan::TALK_JOBS) }]; diff --git a/toyos-i219/src/lib.rs b/toyos-i219/src/lib.rs index f2facff1031..a7bd47444b5 100644 --- a/toyos-i219/src/lib.rs +++ b/toyos-i219/src/lib.rs @@ -894,17 +894,6 @@ impl I219 { Ok(nic) } - /// Raise one enabled cause on purpose (§10.2.4.4). - /// - /// **Nothing on a shipping path calls this**: the caller arms it and - /// [`Self::open`] does not, because a driver that raised a message every - /// boot would make the kernel's first-message record read the same on a - /// working card and a dead one. `LSC` is the cause, because acting on it is - /// re-reading `STATUS`, which the next pass does anyway. - pub fn provoke_message(&self) { - self.regs.write(regs::ICS, cause::LSC); - } - /// Pass frames sent to the multicast address `group`: the one bit of the /// Multicast Table Array its hash names on this part ([`regs::mta_bit_82574`], /// [`regs::mta_bit_pch`]) is set, and diff --git a/toyos-i219/src/tests.rs b/toyos-i219/src/tests.rs index 1d8aea9088f..b3ef8522e76 100644 --- a/toyos-i219/src/tests.rs +++ b/toyos-i219/src/tests.rs @@ -678,58 +678,6 @@ fn transmit_descriptors_are_reclaimed_under_batched_write_back() { // --- interrupts and link --- -/// §10.2.4.4: writing a cause to `ICS` sets it in `ICR` as if the event had -/// happened, so a driver can make the part raise a message nothing on the wire -/// caused. That is the whole of the delivery experiment: a claim that takes -/// this message has an interrupt path, whatever the link is doing. -#[test] -fn a_cause_written_to_ics_raises_a_message_the_claim_takes() { - for part in [Part::E82574, Part::I219] { - let nic = - Nic::with(23, part, Permits { spurious_interrupts: false, ..Permits::default() }); - let mut driver = open(&nic); - // The bring-up's own causes first, so what the pass below reads is the - // provoked one and not what `open` left standing. - one_pass(&mut driver); - - driver.provoke_message(); - let pass = one_pass(&mut driver); - assert_eq!( - pass.messages, 1, - "{}", - nic.because("one cause written to ICS once is one message") - ); - // `OTHER` is §10.2.4.1's summary of `LSC` and is set with it; nothing - // else was written, so nothing else may be read. - assert_eq!( - pass.causes & !cause::INT_ASSERTED, - cause::LSC | cause::OTHER, - "{}", - nic.because("the causes read are not exactly the one written") - ); - } -} - -/// The negative control for the test above: the same boot with nothing written -/// to `ICS` takes no message, so a green arm there is the write's doing and not -/// a part that speaks on its own. -#[test] -fn a_pass_with_no_provoked_cause_takes_no_message() { - for part in [Part::E82574, Part::I219] { - let nic = - Nic::with(23, part, Permits { spurious_interrupts: false, ..Permits::default() }); - let mut driver = open(&nic); - one_pass(&mut driver); - - let pass = one_pass(&mut driver); - assert_eq!( - pass.messages, 0, - "{}", - nic.because("a message arrived on a pass nothing asked the part for one") - ); - } -} - /// §10.2.4.1's case 3 says a read of `ICR` with no interrupt asserted "has no /// side affect". A driver that treated the read as the acknowledgement would /// see the same causes for ever, so the causes it acted on are written back. diff --git a/userland/netd/src/i219.rs b/userland/netd/src/i219.rs index 3fdf8bf444d..d57df480eac 100644 --- a/userland/netd/src/i219.rs +++ b/userland/netd/src/i219.rs @@ -277,11 +277,6 @@ impl Nic { &self.claim } - /// `crate::PROVOKE_MESSAGE`: raise one enabled cause on purpose. - pub fn provoke_message(&self) { - self.driver.borrow().provoke_message(); - } - /// Pass frames sent to the multicast address `group`. pub fn accept_multicast(&self, group: [u8; 6]) { self.driver.borrow().accept_multicast(group); diff --git a/userland/netd/src/main.rs b/userland/netd/src/main.rs index 25b7689578b..ba2f3ada983 100644 --- a/userland/netd/src/main.rs +++ b/userland/netd/src/main.rs @@ -27,23 +27,12 @@ mod virtio_net; /// at `00:1f.6`; `8086:10d3` is the 82574L, which QEMU's `e1000e` models. One /// driver takes both, and each row names which part it is because below the /// register file they are not one. -const CARDS: [(PciId, fn(toyos::PciDev, bool) -> Card); 3] = [ - (PciId { vendor: 0x8086, device: 0x15fc }, |c, p| Card::intel(c, Part::I219, p)), - (PciId { vendor: 0x8086, device: 0x10d3 }, |c, p| Card::intel(c, Part::E82574, p)), +const CARDS: [(PciId, fn(toyos::PciDev) -> Card); 3] = [ + (PciId { vendor: 0x8086, device: 0x15fc }, |c| Card::intel(c, Part::I219)), + (PciId { vendor: 0x8086, device: 0x10d3 }, |c| Card::intel(c, Part::E82574)), (PciId { vendor: 0x1af4, device: 0x1041 }, Card::virtio), ]; -/// The actuator that makes the card raise one interrupt on purpose, so a boot -/// whose only reading of the interrupt path is a count of messages can tell a -/// part nothing made speak from a message that reached no CPU. -/// -/// **Nothing a shipped machine runs arms it**: the argument comes from the -/// `[programs.netd] args` row of a boot config, and the one config that carries -/// it is `tests/lanicscase`. A boot that always raised a message would make the -/// kernel's first-message record read the same on a working card and a dead -/// one. -const PROVOKE_MESSAGE: &str = "--provoke-message"; - /// The probe under which this process brings the card up and serves exactly as /// it always does for [`LEASE_WINDOW`], leaves what happened on the log volume /// one durable line at a time (`report::PATH`), and then ends with @@ -51,25 +40,16 @@ const PROVOKE_MESSAGE: &str = "--provoke-message"; /// the window ends, and where none is, what the bring-up and the link said. /// /// **A lease is a frame out and a frame in, answered by a server this machine -/// does not control**, which is the claim the probe is flashed for; the lines -/// beside it say what the driver and the MAC counted each way, and so which -/// half went missing on a boot that got none. Armed the same way as -/// [`PROVOKE_MESSAGE`] and never beside it. +/// does not control**; the lines beside it say what the driver and the MAC +/// counted each way, and so which half went missing on a boot that got none. +/// The argument comes from the `[programs.netd] args` row of a boot config, +/// and nothing a shipped machine runs carries it. const EXIT_WITH_LEASE: &str = "--exit-with-lease"; /// How long [`EXIT_WITH_LEASE`] serves before it ends, counted from this /// process's start. -/// -/// **It ends inside the job that holds its boot open**: `test_rs_lan_hold` -/// sleeps `toyos_tco::LEASE_BOUND_MS` from a start after this process's, so -/// the exit record and the report's last line land before the runner reboots, -/// with two seconds to spare. Every moment of it after the lease is a moment -/// the machine answers the host's ping at the leased address. const LEASE_WINDOW: Duration = Duration::from_millis(toyos_tco::LEASE_BOUND_MS - 2_000); -/// The two, which cannot share a boot. -const ACTUATORS: [&str; 2] = [PROVOKE_MESSAGE, EXIT_WITH_LEASE]; - fn armed(actuator: &str) -> bool { std::env::args().any(|arg| arg == actuator) } @@ -111,25 +91,14 @@ impl Card { panic!("netd: the NIC this program was given is not one it can drive — {why}") } - /// `provoke` is [`PROVOKE_MESSAGE`], carried out once the card is up. - fn intel(claim: toyos::PciDev, part: Part, provoke: bool) -> Self { + fn intel(claim: toyos::PciDev, part: Part) -> Self { match i219::Nic::open(claim, part) { - Ok(nic) => { - if provoke { - nic.provoke_message(); - } - Self::Intel(nic) - } + Ok(nic) => Self::Intel(nic), Err(why) => Self::undrivable(why), } } - /// [`PROVOKE_MESSAGE`] is the Intel driver's: armed here it is refused, not - /// skipped, before `open` touches the card. - fn virtio(claim: toyos::PciDev, provoke: bool) -> Self { - if provoke { - panic!("netd: {PROVOKE_MESSAGE} is the Intel driver's and this card is virtio"); - } + fn virtio(claim: toyos::PciDev) -> Self { match VirtioNet::open(claim) { Ok(nic) => Self::Virtio(nic), Err(why) => Self::undrivable(why), @@ -1610,16 +1579,7 @@ fn main() { }; let acceptor = endow::acceptor("netd") .expect("the manifest declares this program serves `netd`"); - // Before the card is opened, so a boot config that arms both is refused - // before either acts. - let asked_for: Vec<&str> = ACTUATORS.into_iter().filter(|actuator| armed(actuator)).collect(); - if asked_for.len() > 1 { - panic!( - "netd: {asked_for:?} cannot share a boot: a probe ends this process before the \ - point another of them acts at" - ); - } - let nic = open(claim, armed(PROVOKE_MESSAGE)); + let nic = open(claim); let report = armed(EXIT_WITH_LEASE).then(|| { let report = report::Report::open(started); let intel = nic.intel_driver(); From 55ce64b522add3703815758253e2d57a4ac4224f Mon Sep 17 00:00:00 2001 From: japabu Date: Wed, 30 Sep 2026 16:54:21 +0200 Subject: [PATCH 05/19] blockd's bench moves 8 MiB each way, not 32 `blockd_serves_partitions` is 40-50 s on every whole run, and its `bench` role writes and reads its partition twice through blockd, one request at a time and then fifteen at once, with QEMU tracing every NVMe command to a file. What the bench's size buys is the throughput it prints, and a QEMU run judges no time. What the test asserts off the role holds at a quarter of it: every block reads back what was written; 2048 blocks are 64 requests of the ring's 32-block `MAX_REQUEST_BLOCKS`, past the fifteen in flight that make QEMU's trace see more than one command outstanding and more than one submission queue; and `write_all` ends every pass in a flush, so the trace carries a Flush whatever the arena's size. The reset role writes two of the partition's blocks and the survival test counts reissues in its span, neither of which reads its length. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- tests/common/blockd.rs | 2 +- tests/toyos-rust-tests/src/bin/blockd_io.rs | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/tests/common/blockd.rs b/tests/common/blockd.rs index 2a3722254f2..7cb0fa7b382 100644 --- a/tests/common/blockd.rs +++ b/tests/common/blockd.rs @@ -30,7 +30,7 @@ const BENCH: &str = "C3E5A7B9-2D4F-4B68-8C1E-F3A5B7D9F1B2"; const MISALIGNED: &str = "E5A7C9DB-4F6B-4D8A-8E30-B5C7D9FB13D4"; const MISSTART: &str = "F6B8DAEC-5A7C-4E9B-9F41-C6D8EA0C24E5"; const TARGET_BLOCKS: u64 = 2048; -const BENCH_BLOCKS: u64 = 8192; +const BENCH_BLOCKS: u64 = 2048; const FILES: usize = 6; const FILE_BYTES: usize = 48 * 1024; const AFTER: &str = "AFTER.BIN"; diff --git a/tests/toyos-rust-tests/src/bin/blockd_io.rs b/tests/toyos-rust-tests/src/bin/blockd_io.rs index d0f53a4ae1d..5db1fc5fab1 100644 --- a/tests/toyos-rust-tests/src/bin/blockd_io.rs +++ b/tests/toyos-rust-tests/src/bin/blockd_io.rs @@ -70,7 +70,7 @@ const ABSENT: &str = "0A1B2C3D-4E5F-4A6B-8C7D-9E0F1A2B3C4D"; /// Mirrored: the idle slot's length in blocks, and what each block holds. const TARGET_BLOCKS: u64 = 2048; /// Mirrored: what the bench moves each way, each side. -const BENCH_BLOCKS: u64 = 8192; +const BENCH_BLOCKS: u64 = 2048; /// Mirrored: the files the crash role writes before it kills blockd, and the /// bytes each holds. const FILES: usize = 6; From cfd4ba79a7e1d0ddf4e7c5841dc96d9f72d9f136 Mon Sep 17 00:00:00 2001 From: japabu Date: Wed, 30 Sep 2026 16:55:30 +0200 Subject: [PATCH 06/19] The nightly host job's bound is three times its slowest run `host` on `macos-latest` took 11, 13 and 14 minutes on the last three nightly runs that reached their end (36496779560, 36550208853, 36600425263) and was bounded at 90. The other nightly bounds are already within three times their slowest runs over the same four nightlies: `guest` 60 against 27, `tcg` 60 against 18, and `build` and the two `portability` jobs 350 against 184 and 166; the PR gate's `host` is 45 against 27. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- .github/workflows/nightly.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/nightly.yml b/.github/workflows/nightly.yml index 558bcb2bfe1..f9a21309bc2 100644 --- a/.github/workflows/nightly.yml +++ b/.github/workflows/nightly.yml @@ -18,7 +18,7 @@ concurrency: jobs: host: runs-on: macos-latest - timeout-minutes: 90 + timeout-minutes: 42 steps: - uses: actions/checkout@11d5960a326750d5838078e36cf38b85af677262 # v4.4.0 with: From 4ca950e00fbbb85b0c60317ea1f78fe7439d9b50 Mon Sep 17 00:00:00 2001 From: japabu Date: Wed, 30 Sep 2026 16:57:11 +0200 Subject: [PATCH 07/19] The power tests' shared waits are the rule's numbers over the tests that use them Two helper waits in `tests/common/power.rs` sat under the slowest test that reaches them and had passed only on the phase width's twelve-fold: - `WAIT`, the bound on QEMU's shutdown event and the drain after it, was 20 s (240 s at 12 wide). Its callers' slowest whole runs are 23 s (job_deadline_reboots), 25 s (watchdog_resets) and 110 s (quiesce_refuses_a_second_shutdown, on #536's first whole run): 332 s. - `CHAIN_WAIT`, what the boot after a reset has to arrive inside, was `PANIC_FAST_SECS + 60` (780 s at 12 wide). The tests that are one chain took at most 37 s (hard_lockup_ends_a_deaf_cpu), 33 s (boot_deadline_ends_a_wedge), 27 s and 25 s: 113 s, which the multi-chain usb_reset tests take per chain. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- tests/common/power.rs | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) diff --git a/tests/common/power.rs b/tests/common/power.rs index e716c39a620..e8011fdf6ac 100644 --- a/tests/common/power.rs +++ b/tests/common/power.rs @@ -20,7 +20,7 @@ use toyos_xhci::bot::Phase; use super::qemu::{self, BootOptions, QemuInstance}; use super::serial; -const WAIT: Duration = Duration::from_secs(20); +const WAIT: Duration = Duration::from_secs(332); /// What a guest that never stopped means where something asked it to. const ASKED_AND_STAYED_UP: &str = @@ -1067,8 +1067,9 @@ fn after_the_reset(qemu: &mut QemuInstance, until: &str) -> serial::Serial { /// What the boot after a reset has to arrive inside: the bound the first boot /// counts down, plus firmware and a loader. Scaled by `drain_until`, and the -/// predicate is what ends the drain. -const CHAIN_WAIT: Duration = Duration::from_secs(PANIC_FAST_SECS + 60); +/// predicate is what ends the drain. The ceiling rule's number over the tests +/// that are one chain, the slowest of which took 37 s. +const CHAIN_WAIT: Duration = Duration::from_secs(113); /// The chain closes on a panic: the kernel seals what the panel rendered, the /// machine resets itself, and the boot after it is this loader again — which From fe6cfe08ba28d3d0b87cfc346043dbf48a46c281 Mon Sep 17 00:00:00 2001 From: japabu Date: Wed, 30 Sep 2026 16:59:35 +0200 Subject: [PATCH 08/19] The nightly tcg job's bound is three times its slowest run too `tcg` took 11, 17 and 18 minutes on the last nightlies that finished it, so its bound is 54 minutes, not 60. `cfd4ba79a`'s message counted it among the bounds already inside the rule, and it was not. That message also named the wrong runs: the `host` times it gives are nightlies 36696295750 (11.6 min), 36709239346 (13.6), 36600425263 (14.0) and 36597513896 (12.9). Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- .github/workflows/nightly.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/nightly.yml b/.github/workflows/nightly.yml index f9a21309bc2..f61ca8b915f 100644 --- a/.github/workflows/nightly.yml +++ b/.github/workflows/nightly.yml @@ -158,7 +158,7 @@ jobs: tcg: needs: build runs-on: ubuntu-24.04 - timeout-minutes: 60 + timeout-minutes: 54 container: image: *image env: From 16ff502a994d4ecafa33f812a7dcec6c1071e1cf Mon Sep 17 00:00:00 2001 From: japabu Date: Wed, 30 Sep 2026 19:29:44 +0200 Subject: [PATCH 09/19] Answer the review of #638: the backstop waits out a death's silence, and the last 300 s waits go The backstop was `ceiling * 2`, and it ran ahead of the panic and silence arms, which both wait for `GUEST_QUIET` (15 s). Under any ceiling below 7.5 s (the 5 s shared default, the 2 s C members, `ipc_hostile_peer`'s 1 s) a kernel panic or a silent wedge was reported as a slow guest that was still talking. It is now `(ceiling * 2).max(ceiling + GUEST_QUIET)`. `ceiling_self_check` gains the review's two cases: - a panic under a 5 s ceiling, quiet for 10 s at 11 s: no verdict yet. Red at b2ccd1c84's backstop (EXIT=101), green with this one. - the same panic at 21 s, quiet for `GUEST_QUIET`: named. Green at b2ccd1c84 too, because the pure function puts the panic arm first. It reds (EXIT=101) when the backstop is moved ahead of that arm. `a_stall_stays_red` stages a 30 s ceiling instead of 5 s, so its `past` (twice the ceiling, plus one) still clears the backstop. Four waits still bounded by `GUEST_WEDGED` are cut to about three times their slowest whole-suite run: `lan_no_lease` 99 s, `kernel_log_file`'s device poll 54 s, `usb_flush_optional` 99 s, and `guest_dies_with_its_harness` 24 s, which is now host-scaled like the other three. `readdir_bound` is 147 s, three times the 49 s it took at b2ccd1c84 without its `/home` arm. `toolkit_winit_loop`'s `Liveness` had a 40 s quiet guard behind a 35 s total, so the guard could never fire. The loop now runs to a host-scaled 35 s deadline. The i219 model's `ICS` write arm, read arm and register constant go. Nothing has written `ICS` since `--provoke-message` went. `build.rs`'s Intel-actuator gate holds one flag, so it is one `const` and one membership test. Its declaration test is renamed to say "flag". `STAGED_BOUND_MS` moves into `toyos-tco` beside `WEDGE_BOUND_MS`. That crate holds every bound a boot arms. The metal loop's wait is split into `wait_on` and a `port_accepts(host, port)`. A new host test drives them against a loopback listener that accepts and never speaks `ssh`. With `let answered = listening;` the build passes (EXIT=0) and `metal::tests` fails (EXIT=101) on that test alone. The harness kills a swap only when the flashing invocation did not exit 0 or 1. Exit 1 is a boot that ran and was judged red, and its swap is left to finish. The T14's record gains `boot.shared.{complete_ms,panel_max_us,panel_us}` = 1154 / 3608 / 21429. These are the first passing reading of `shared` at its 62 members. Deleted as the review asked: - the backstop's "six times" clause - the measured "slowest of which took" clauses - the staging time of the T14's wedge - `lan_hold`'s docs, which describe a user it no longer has - the restated twenty seconds - two issue sentences that name boots which no longer exist - the two "twice its ceiling" phrasings, which the new backstop makes false for short ceilings Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- ...s-read-by-nothing-but-its-own-assertion.md | 2 +- ...pends-two-premises-nothing-has-measured.md | 2 - ...ped-answering-ssh-between-two-lan-boots.md | 8 +- src/build.rs | 60 +++++------ src/metal.rs | 101 ++++++++++++------ tests/checks.rs | 2 +- tests/checks/qemu.rs | 20 ++++ tests/common/lan.rs | 5 +- tests/common/metal.rs | 12 ++- tests/common/orphan.rs | 6 +- tests/common/power.rs | 2 +- tests/common/qemu.rs | 15 ++- tests/common/usb.rs | 6 +- tests/common/volumes.rs | 5 +- tests/metal/lenovo-20w0003amz.toml | 3 + tests/toyos-rust-tests/src/bin/lan_hold.rs | 7 -- tests/toyos.rs | 9 +- toyos-i219/src/regs.rs | 2 - toyos-i219/src/stub.rs | 7 +- toyos-tco/src/lib.rs | 7 ++ 20 files changed, 159 insertions(+), 122 deletions(-) diff --git a/issues/build/hard-lockup-bound-ms-is-read-by-nothing-but-its-own-assertion.md b/issues/build/hard-lockup-bound-ms-is-read-by-nothing-but-its-own-assertion.md index 919fa5cd9a4..e998f56eff1 100644 --- a/issues/build/hard-lockup-bound-ms-is-read-by-nothing-but-its-own-assertion.md +++ b/issues/build/hard-lockup-bound-ms-is-read-by-nothing-but-its-own-assertion.md @@ -11,7 +11,7 @@ opened: 2026-09-30 and the `const _` beside it is its one reader. Its last other reader was the metal profile's list of declared ceilings, which went with `tests/metal-profile.toml`. The T14's `hardlockup` arm no longer runs under it -either: `metal::bound_for` arms that image with `metal::STAGED_BOUND_MS`, so its +either: `metal::bound_for` arms that image with `toyos_tco::STAGED_BOUND_MS`, so its lockup bound is `hard_lockup_bound_ms(STAGED_BOUND_MS)`. `git grep HARD_LOCKUP_BOUND_MS -- ':!issues'` lists `toyos-tco/src/lib.rs` diff --git a/issues/hardware/the-cable-judge-spends-two-premises-nothing-has-measured.md b/issues/hardware/the-cable-judge-spends-two-premises-nothing-has-measured.md index 9a682f4e52d..ac9f6844a72 100644 --- a/issues/hardware/the-cable-judge-spends-two-premises-nothing-has-measured.md +++ b/issues/hardware/the-cable-judge-spends-two-premises-nothing-has-measured.md @@ -23,8 +23,6 @@ judge refuses a boot whose leased address is not the one the loop pinged, and the one the loop pinged is what Ubuntu held on that MAC. A server that hands the MAC a different address under ToyOS reds the arm for a fact about the router rather than about the boot — a red naming the wrong thing, not a false green. -Closed by a lancase run whose lease record and whose `ping_addr` are compared, -which is the first thing that run prints. The router-lease measurement falsifies this premise: `issues/hardware/the-benchs-router-leases-toyos-another-address-than-ubuntu.md`. diff --git a/issues/hardware/the-t14-stopped-answering-ssh-between-two-lan-boots.md b/issues/hardware/the-t14-stopped-answering-ssh-between-two-lan-boots.md index daca038b5e0..7b3f6711edd 100644 --- a/issues/hardware/the-t14-stopped-answering-ssh-between-two-lan-boots.md +++ b/issues/hardware/the-t14-stopped-answering-ssh-between-two-lan-boots.md @@ -6,11 +6,9 @@ opened: 2026-09-29 # The T14 stopped answering `ssh` between two LAN boots, and the next two arms died before their flash -`lan_lease_report` (boot `lanleasecase`) and `lan_swap` (boot `lanswapcase`) -are the two arms the metal suite flashes after `lanicscase`. On the run below -neither reached the stick: the first `ssh` of each timed out, so neither boot -happened and neither judge ran. The suite measured nothing about either test, -and why the bench's `ssh` went away is not established by anything kept. +On the run below neither reached the stick: the first `ssh` of each timed out, +so neither boot happened and neither judge ran. The suite measured nothing about +either test, and why the bench's `ssh` went away is not established by anything kept. ## Measured diff --git a/src/build.rs b/src/build.rs index e1ae4d03b13..38d1ee78a3c 100644 --- a/src/build.rs +++ b/src/build.rs @@ -3346,10 +3346,10 @@ mod tests { assert!(one_claimant_per_device(&bad, None).is_err()); } - /// netd's actuators that only its Intel driver answers, spelled here and - /// held to netd's own declarations by - /// [`netd_declares_the_flags_this_gate_spells`]. - const INTEL_ACTUATORS: [&str; 1] = ["--exit-with-lease"]; + /// netd's actuator that only its Intel driver answers, spelled here and + /// held to netd's own declaration by + /// [`netd_declares_the_flag_this_gate_spells`]. + const EXIT_WITH_LEASE: &str = "--exit-with-lease"; /// netd's main module, which is where both halves of this gate's spelling /// live: nothing links the two crates, so the build system reads the source. @@ -3363,15 +3363,13 @@ mod tests { /// build system, so the flags both ends spell are held to netd's own /// declarations by reading its source. #[test] - fn netd_declares_the_flags_this_gate_spells() { + fn netd_declares_the_flag_this_gate_spells() { let (at, source) = netd_source(); - for flag in INTEL_ACTUATORS { - assert!( - crate::bootlog::declares(&source, &format!("\"{flag}\"")), - "{} declares no constant equal to \"{flag}\"", - at.display() - ); - } + assert!( + crate::bootlog::declares(&source, &format!("\"{EXIT_WITH_LEASE}\"")), + "{} declares no constant equal to \"{EXIT_WITH_LEASE}\"", + at.display() + ); } /// The four hex digits after `key` on this line. @@ -3421,15 +3419,13 @@ mod tests { cards: &[String], ) -> Result<(), String> { for (name, prog) in &cfg.programs { - let Some(flag) = - INTEL_ACTUATORS.into_iter().find(|flag| prog.args.iter().any(|arg| arg == flag)) - else { + if !prog.args.iter().any(|arg| arg == EXIT_WITH_LEASE) { continue; - }; + } if !prog.devices.iter().any(|d| cards.contains(d)) { return Err(format!( - "`{name}` is armed with `{flag}` and claims {:?}, none of which is one of \ - the {cards:?} netd opens with that driver", + "`{name}` is armed with `{EXIT_WITH_LEASE}` and claims {:?}, none of which \ + is one of the {cards:?} netd opens with that driver", prog.devices )); } @@ -3442,24 +3438,20 @@ mod tests { let (_, source) = netd_source(); let cards = netd_intel_cards(&source); assert!(!cards.is_empty(), "netd's `CARDS` names no card its Intel driver opens"); - let mut armed = [0usize; INTEL_ACTUATORS.len()]; + let mut armed = 0; for cfg in ALL_CONFIGS { let config = load(cfg); - for (count, flag) in armed.iter_mut().zip(INTEL_ACTUATORS) { - *count += config - .programs - .values() - .filter(|p| p.args.iter().any(|arg| arg == flag)) - .count(); - } + armed += config + .programs + .values() + .filter(|p| p.args.iter().any(|arg| arg == EXIT_WITH_LEASE)) + .count(); an_armed_intel_actuator_claims_a_card_the_driver_opens(&config, &cards) .unwrap_or_else(|e| panic!("{cfg}: {e}")); } // A walk that reached no armed program passes on having found nothing, // which is the one way this gate can rot while every config still loads. - for (count, flag) in armed.iter().zip(INTEL_ACTUATORS) { - assert!(*count > 0, "no shipped boot config arms `{flag}` at all"); - } + assert!(armed > 0, "no shipped boot config arms `{EXIT_WITH_LEASE}` at all"); let armed_on = |device: &str, args: &str| { let cfg: SystemConfig = toml::from_str(&format!( "init = []\n[programs.netd]\ndevices = [\"{device}\"]\nargs = [{args}]\n" @@ -3470,12 +3462,10 @@ mod tests { // The card netd drives with the other driver, and an Intel function it // drives with none: a vendor id is not what gives a part an `ICS` or a // PHY behind `MDIC`. - for flag in INTEL_ACTUATORS { - let one = format!("\"{flag}\""); - assert!(armed_on("pci:1af4:1041", &one).is_err(), "{flag}"); - assert!(armed_on("pci:8086:1502", &one).is_err(), "{flag}"); - assert!(armed_on(&cards[0], &one).is_ok(), "{flag}"); - } + let flag = format!("\"{EXIT_WITH_LEASE}\""); + assert!(armed_on("pci:1af4:1041", &flag).is_err()); + assert!(armed_on("pci:8086:1502", &flag).is_err()); + assert!(armed_on(&cards[0], &flag).is_ok()); } /// A device name the ABI does not know renders fine and leaves init with a diff --git a/src/metal.rs b/src/metal.rs index 128142e996a..d69c34f3866 100644 --- a/src/metal.rs +++ b/src/metal.rs @@ -866,17 +866,10 @@ pub fn stages_a_wedge(armed: &[impl AsRef]) -> bool { armed.iter().any(|name| WEDGE_ARMS.contains(&name.as_ref())) } -/// The bound an image armed with one of [`WEDGE_ARMS`] carries, in -/// milliseconds: the T14 stages its wedge 1.5 s into the kernel, so this ends -/// the machine seconds after it rather than at the bound every other boot keeps -/// for a wedge nobody staged. Its half is the lockup detector's bound, which -/// still outlasts the lockup probe's own reach to its lock. -pub const STAGED_BOUND_MS: u64 = 10_000; - /// The `boot-deadline=` bound an image armed with `armed` carries. pub fn bound_for(armed: &[impl AsRef]) -> u64 { if stages_a_wedge(armed) { - STAGED_BOUND_MS + toyos_tco::STAGED_BOUND_MS } else { toyos_tco::WEDGE_BOUND_MS } @@ -1443,32 +1436,16 @@ impl Driver { } } - /// Poll `ssh`'s port once a [`POLL`], and say how long it took to answer as - /// asked. **Coming back is `ssh` itself answering**: a port that accepts is - /// only asked whether `ssh` does, since a listener can come up before the - /// service behind it. + /// [`wait_on`] the machine's `ssh`. fn wait(&self, secs: u64, what: &'static str, answering: bool) -> Result { - let began = std::time::Instant::now(); - while began.elapsed().as_secs() < secs { - let next = std::time::Instant::now() + POLL; - let listening = self.port_accepts(); - let answered = listening && (!answering || self.ssh("probing", "true").is_ok()); - if answered == answering { - return Ok(began.elapsed().as_secs()); - } - std::thread::sleep(next.saturating_duration_since(std::time::Instant::now())); - } - Err(Refusal::Silent { what, secs }) - } - - /// Whether the machine's `ssh` port accepts a connection inside one - /// [`POLL`]; a name that does not resolve is a machine that is not there. - fn port_accepts(&self) -> bool { - use std::net::ToSocketAddrs; - let Ok(mut addrs) = (self.target.host.as_str(), crate::metaltalk::SSH_PORT).to_socket_addrs() else { - return false; - }; - addrs.any(|addr| std::net::TcpStream::connect_timeout(&addr, POLL).is_ok()) + let host = self.target.host.as_str(); + wait_on( + secs, + what, + answering, + || port_accepts(host, crate::metaltalk::SSH_PORT), + || self.ssh("probing", "true").is_ok(), + ) } /// The loader's own file, and then everything `logd` wrote, in name order: @@ -1547,6 +1524,40 @@ impl Driver { } } +/// Poll once a [`POLL`] whether a port `accepts`, and say how long the machine +/// took to answer as asked. **Coming back is `ssh` itself answering**: a port +/// that accepts is only asked whether `ssh` `answers`, since a listener can come +/// up before the service behind it. +fn wait_on( + secs: u64, + what: &'static str, + answering: bool, + mut accepts: impl FnMut() -> bool, + mut answers: impl FnMut() -> bool, +) -> Result { + let began = std::time::Instant::now(); + while began.elapsed().as_secs() < secs { + let next = std::time::Instant::now() + POLL; + let listening = accepts(); + let answered = listening && (!answering || answers()); + if answered == answering { + return Ok(began.elapsed().as_secs()); + } + std::thread::sleep(next.saturating_duration_since(std::time::Instant::now())); + } + Err(Refusal::Silent { what, secs }) +} + +/// Whether `host`'s `port` accepts a connection inside one [`POLL`]; a name +/// that does not resolve is a machine that is not there. +fn port_accepts(host: &str, port: u16) -> bool { + use std::net::ToSocketAddrs; + let Ok(mut addrs) = (host, port).to_socket_addrs() else { + return false; + }; + addrs.any(|addr| std::net::TcpStream::connect_timeout(&addr, POLL).is_ok()) +} + fn unstarted(what: &str, e: &std::io::Error) -> Refusal { Refusal::Remote { what: what.to_string(), @@ -2653,6 +2664,28 @@ mod tests { } } + /// **A port that accepts is not a machine that came back**, and a machine + /// going down is its port closing. Staged through [`port_accepts`] on a + /// listener of this host's own, which accepts and never speaks `ssh`. + #[test] + fn coming_back_is_ssh_answering_and_not_its_port() { + let listener = std::net::TcpListener::bind("127.0.0.1:0").expect("a loopback listener"); + let port = listener.local_addr().expect("its address").port(); + let accepts = || port_accepts("127.0.0.1", port); + let mut asked = 0; + let back = wait_on(1, "come back", true, accepts, || { + asked += 1; + false + }); + assert_eq!(back, Err(Refusal::Silent { what: "come back", secs: 1 })); + assert!(asked > 0, "`ssh` was never asked of a port that accepts"); + assert_eq!(wait_on(1, "come back", true, accepts, || true), Ok(0)); + let up = wait_on(1, "go down", false, accepts, || unreachable!("`ssh` asked of one going down")); + assert_eq!(up, Err(Refusal::Silent { what: "go down", secs: 1 })); + drop(listener); + assert_eq!(wait_on(1, "go down", false, accepts, || unreachable!()), Ok(0)); + } + /// **An image with no bound on its own boot never reaches the stick.** /// /// The case, measured twice: a kernel that hung after its job list, and a @@ -2854,7 +2887,7 @@ mod tests { assert_eq!(flash_ruling(arm), Some(Flash::Ok), "{arm} reaches no stick"); assert_eq!(judge_arms(&[arm.to_string(), bound.clone()]), Ok(()), "{arm}"); assert!(stages_a_wedge(&[arm.to_string()]), "{arm}"); - assert_eq!(bound_for(&[arm]), STAGED_BOUND_MS, "{arm}"); + assert_eq!(bound_for(&[arm]), toyos_tco::STAGED_BOUND_MS, "{arm}"); // And with no bound behind it, the sharpest refusal names it as the // wedge it is rather than as a plain image. assert_eq!( diff --git a/tests/checks.rs b/tests/checks.rs index de17af4c2f8..c5e5a5c4529 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -152,7 +152,7 @@ mod checks { // gate asserting against a string nothing produces any more. let real = format!("{STALLED} waiting for the long tone to start — it went quiet"); let under_a_sentence = format!("the compositor stopped painting\n{real}"); - let ceiling = Duration::from_secs(5); + let ceiling = Duration::from_secs(30); let past = ceiling * 2 + Duration::from_secs(1); let backstop = qemu::ceiling_verdict(None, past, ceiling, Duration::from_secs(1), 900) .ok_or("a guest talking past the backstop was given no verdict")?; diff --git a/tests/checks/qemu.rs b/tests/checks/qemu.rs index 7ec2308915e..2c039e9978e 100644 --- a/tests/checks/qemu.rs +++ b/tests/checks/qemu.rs @@ -198,6 +198,26 @@ pub fn ceiling_self_check() -> Result<(), String> { would red healthy", )); } + // (e) A ceiling under [`GUEST_QUIET`]: a kernel that died is given its + // silence to be named before the backstop calls its guest slow. + const SHORT: Duration = Duration::from_secs(5); + if let Some(cut) = + ceiling_verdict(Some(KERNEL), Duration::from_secs(11), SHORT, Duration::from_secs(10), 40) + { + return Err(format!( + "a kernel death under a {SHORT:?} ceiling was ended before its silence could name it: \ + {cut}" + )); + } + match ceiling_verdict(Some(KERNEL), Duration::from_secs(21), SHORT, GUEST_QUIET, 40) { + Some(named) if named.contains("kernel panic") => {} + other => { + return Err(format!( + "a kernel death under a {SHORT:?} ceiling, silent for {GUEST_QUIET:?}, was not \ + named: {other:?}" + )); + } + } // 4. **What the verdict carries, which is the half that was missing.** Every // arm above names a death in one sentence; until 2026-08-18 that sentence diff --git a/tests/common/lan.rs b/tests/common/lan.rs index 62ddbc855dd..60adf79a4b9 100644 --- a/tests/common/lan.rs +++ b/tests/common/lan.rs @@ -400,12 +400,11 @@ pub fn lan_no_lease( let mut console = guest.boot_log().to_string(); // Drained until netd's `ready` after its give-up, and not awaited: the // guest says nothing at all until netd gives up on its own clock, which - // every wait in this harness reads as a machine that stopped. The ceiling - // is the harness's. + // every wait in this harness reads as a machine that stopped. let gave_up = format!("{NO_LEASE}{HOSTNAME} in "); let given_up = std::cell::Cell::new(false); let served = std::cell::Cell::new(false); - console.push_str(&guest.drain_until(qemu::GUEST_WEDGED, |line| { + console.push_str(&guest.drain_until(std::time::Duration::from_secs(99), |line| { given_up.set(given_up.get() || line.contains(&gave_up)); served.set(given_up.get() && line.contains(READY)); served.get() diff --git a/tests/common/metal.rs b/tests/common/metal.rs index debc900039f..c888dfb9397 100644 --- a/tests/common/metal.rs +++ b/tests/common/metal.rs @@ -1033,11 +1033,15 @@ pub fn run( eprintln!("[metal] {label}: cargo {}", words.join(" ")); let booted = Command::new("cargo").args(&words).current_dir(&root).status(); if let Some(swap) = beside { - // A boot that was refused leaves no machine to dial, and the - // swap would wait out its whole bound for one. - let unbooted = !booted.as_ref().is_ok_and(|status| status.success()); + // Exit 1 is a boot that ran and was judged, whose swap finishes + // on its own. Any other failure is the loop refusing, which + // before the reboot leaves no machine to dial and the swap + // waiting out its whole bound for one. + let loop_refused = !booted + .as_ref() + .is_ok_and(|status| status.success() || status.code() == Some(1)); let swap = swap.and_then(|mut child| { - if unbooted { + if loop_refused { child.kill()?; } child.wait() diff --git a/tests/common/orphan.rs b/tests/common/orphan.rs index 643ba749a8c..c2c10481a20 100644 --- a/tests/common/orphan.rs +++ b/tests/common/orphan.rs @@ -36,10 +36,10 @@ pub fn guest_dies_with_its_harness(test_config: &Path) -> Result<(), String> { let mut owner = Owner::spawn(owner)?; let owner_pid = owner.pid(); let verdict = (|| { - // The owner builds nothing, so its one wait is its boot, whose own - // ceiling ends it well inside the backstop on any wait on a guest. + let within = + qemu::budget_smp(std::time::Duration::from_secs(24), BootOptions::default().smp); let pid: u32 = - owner.said(HELD, qemu::GUEST_WEDGED)?.parse().map_err(|e| format!("the owner's QEMU pid: {e}"))?; + owner.said(HELD, within)?.parse().map_err(|e| format!("the owner's QEMU pid: {e}"))?; owner.killed(&[pid]).map(|()| pid) })(); short.adopt(Path::new(toyos_tmpdir::SHORT_BASE), owner_pid); diff --git a/tests/common/power.rs b/tests/common/power.rs index 4b1f9a4fbcb..ea3040304b3 100644 --- a/tests/common/power.rs +++ b/tests/common/power.rs @@ -1068,7 +1068,7 @@ fn after_the_reset(qemu: &mut QemuInstance, until: &str) -> serial::Serial { /// What the boot after a reset has to arrive inside: the bound the first boot /// counts down, plus firmware and a loader. Scaled by `drain_until`, and the /// predicate is what ends the drain. The ceiling rule's number over the tests -/// that are one chain, the slowest of which took 37 s. +/// that are one chain. const CHAIN_WAIT: Duration = Duration::from_secs(113); /// The chain closes on a panic: the kernel seals what the panel rendered, the diff --git a/tests/common/qemu.rs b/tests/common/qemu.rs index e599e8544b5..aa84ea485d9 100644 --- a/tests/common/qemu.rs +++ b/tests/common/qemu.rs @@ -304,8 +304,7 @@ fn oversubscription(smp: u32) -> (u32, u32) { /// bounds was measured to take**, in whole-suite runs on the host [`REFERENCE_BOOT_MS`] /// describes, at the suite's default width — so a test's time already carries /// the guests it shares that host with. A wait is bounded by that multiple of -/// its whole test, the one number measured; a guest still talking at twice its -/// ceiling is past it ([`ceiling_verdict`]). The source states that number, and +/// its whole test, the one number measured. The source states that number, and /// this pays it out on a slower host ([`host_scale`]) and for a guest wider than /// this one ([`oversubscription`]), and for nothing else. /// @@ -384,8 +383,8 @@ impl Liveness { /// second producer: a test's own ceiling is a guard of exactly this kind. pub const STALLED: &str = "STALLED:"; -/// The backstop's red: a guest still talking at twice its ceiling that never -/// finished. The ceiling too, and counted with [`STALLED`]'s. +/// The backstop's red: a guest still talking that never finished. The ceiling +/// too, and counted with [`STALLED`]'s. pub const TIMED_OUT: &str = "timed out after"; /// How long a guest may say nothing before a wait on it is a stall. @@ -559,9 +558,9 @@ pub fn ceiling_verdict( )); } // The backstop, for a guest that is stuck *and* chatty and so never trips - // the silence guard: twice the ceiling, at most six times the slowest this test - // was ever measured. - let backstop = ceiling * 2; + // the silence guard; never before a guest silent since its ceiling has been + // silent for [`GUEST_QUIET`], so a death is named by the arms above. + let backstop = (ceiling * 2).max(ceiling + GUEST_QUIET); if elapsed > backstop { return Some(format!( "{TIMED_OUT} {}s, with the guest still talking {quiet:.0?} ago ({lines} \ @@ -4698,7 +4697,7 @@ fn publish_line( } /// A boot's ceiling: [`budget_smp`]'s rule over the tests that are one boot and -/// one trivial command, the slowest of which took 10 s. +/// one trivial command. const BOOT_CEILING: Duration = Duration::from_secs(30); /// Returns every line seen on the way to the marker — see [`QemuInstance::boot_log`]. diff --git a/tests/common/usb.rs b/tests/common/usb.rs index da56c717b13..9336a3c258b 100644 --- a/tests/common/usb.rs +++ b/tests/common/usb.rs @@ -816,9 +816,9 @@ fn optional_flush_keeps_the_log( // Mid-run and polled, exactly as `kernel_log_file` does it: the claim is that // the sink is still running, and the only place that is visible is the - // device while the machine is up. The ceiling is the harness's: a stick - // with no write cache that cost the machine its log is a hang here. - let give_up = std::time::Instant::now() + qemu.budget(qemu::GUEST_WEDGED); + // device while the machine is up. A stick with no write cache that cost + // the machine its log is a hang here. + let give_up = std::time::Instant::now() + qemu.budget(Duration::from_secs(99)); loop { let on_device = String::from_utf8_lossy( &super::volumes::newest_log(&image_path, start, len)?.1, diff --git a/tests/common/volumes.rs b/tests/common/volumes.rs index 3188df91ced..927e5a4468d 100644 --- a/tests/common/volumes.rs +++ b/tests/common/volumes.rs @@ -557,10 +557,9 @@ pub fn kernel_log_file( // Mid-run, with the guest still up and nothing shut down. Whatever is here // was put there by `/system/bin/logd` while the machine was running. // - // Polled until logd has written through `Boot: complete`, with the - // harness's ceiling and no deadline of this test's own: when logd writes + // Polled until logd has written through `Boot: complete`: when logd writes // is its own business, and one that never does is a hang. - let give_up = std::time::Instant::now() + qemu.budget(qemu::GUEST_WEDGED); + let give_up = std::time::Instant::now() + qemu.budget(Duration::from_secs(54)); let mut running; let mut running_text; let mut running_name; diff --git a/tests/metal/lenovo-20w0003amz.toml b/tests/metal/lenovo-20w0003amz.toml index e7a89cb4163..53f1d6576f4 100644 --- a/tests/metal/lenovo-20w0003amz.toml +++ b/tests/metal/lenovo-20w0003amz.toml @@ -40,6 +40,9 @@ bios = "N34ET71W (1.71 )" "boot.shared-debug.complete_ms" = 1165 "boot.shared-debug.panel_max_us" = 3791 "boot.shared-debug.panel_us" = 21483 +"boot.shared.complete_ms" = 1154 +"boot.shared.panel_max_us" = 3608 +"boot.shared.panel_us" = 21429 "boot.testcases-deaf.complete_ms" = 1165 "boot.testcases-deaf.panel_max_us" = 5247 "boot.testcases-deaf.panel_us" = 26659 diff --git a/tests/toyos-rust-tests/src/bin/lan_hold.rs b/tests/toyos-rust-tests/src/bin/lan_hold.rs index feb9350eada..31764fb3efd 100644 --- a/tests/toyos-rust-tests/src/bin/lan_hold.rs +++ b/tests/toyos-rust-tests/src/bin/lan_hold.rs @@ -1,13 +1,6 @@ -//! Hold the boot open for as long as the host needs to reach this machine over -//! the cable, and exit. It asserts nothing; the host judges the records netd -//! wrote inside this window, and `dump_nmi_probe`'s metal row the dump its -//! actuator stages inside it. - use std::thread::sleep; use std::time::Duration; -/// **netd's own lease bound**, so this boot cannot hand the machine back before -/// netd has settled whether it has an address. const HOLD: Duration = Duration::from_millis(toyos_tco::LEASE_BOUND_MS); fn main() { diff --git a/tests/toyos.rs b/tests/toyos.rs index f3e9cebe147..d212fe95de6 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -258,8 +258,7 @@ const RUST_SKIP: &[&str] = &[ "netd_refused_pipes", "netd_refused_accept", "netd_lookup_let_go", - // It asserts nothing at all: it holds a boot open for twenty seconds. On a - // shared boot it would be twenty seconds of nothing. + // It asserts nothing at all: it holds a boot open. "lan_hold", // The same for `tests/lantalkcase`, held until the runner's bound is near // unless the host's `reboot` over ssh ends it first. `lan_talk` rides it. @@ -7925,9 +7924,9 @@ fn toolkit_window_wake(rust_bins: &[(String, Vec)]) -> Result<(), String> { fn toolkit_winit_loop(rust_bins: &[(String, Vec)]) -> Result<(), String> { let (mut qemu, mut log, launched) = toolkit_launch(rust_bins, "winit_loop", "test_rs_winit_loop")?; let log = &mut log; - let mut live = qemu::Liveness::new(Duration::from_secs(40), Duration::from_secs(35)); + let give_up = Instant::now() + qemu.budget(Duration::from_secs(35)); let mut closed = false; - while live.working(log) { + while Instant::now() < give_up { let said = &log[launched..]; if said.contains("WINIT-LOOP-OK") { // Up to the kept window's close: a window the app still held is @@ -11257,7 +11256,7 @@ fn run_machine_test( ); serial::Serial::boot(&qemu).must_be_clean()?; - let result = qemu.run_test("test_rs_readdir_bound", Duration::from_secs(545)); + let result = qemu.run_test("test_rs_readdir_bound", Duration::from_secs(147)); if let Some(err) = &result.error { return Err(format!("the guest stopped answering: {err}\nserial:\n{}", result.serial)); } diff --git a/toyos-i219/src/regs.rs b/toyos-i219/src/regs.rs index caa2567ef7e..92cecd1bc59 100644 --- a/toyos-i219/src/regs.rs +++ b/toyos-i219/src/regs.rs @@ -31,8 +31,6 @@ pub const MDIC: usize = 0x00020; pub const ICR: usize = 0x000C0; /// Interrupt Throttling (§10.2.4.2, `0x000C4`). pub const ITR: usize = 0x000C4; -/// Interrupt Cause Set (§10.2.4.4, `0x000C8`), write-only. -pub const ICS: usize = 0x000C8; /// Interrupt Mask Set/Read (§10.2.4.5, `0x000D0`). pub const IMS: usize = 0x000D0; /// Interrupt Mask Clear (§10.2.4.6, `0x000D8`), write-only. diff --git a/toyos-i219/src/stub.rs b/toyos-i219/src/stub.rs index 97aec8f9614..5b2abf517c8 100644 --- a/toyos-i219/src/stub.rs +++ b/toyos-i219/src/stub.rs @@ -1039,9 +1039,8 @@ impl Model { } value } - // §10.2.4.6 and §10.2.4.4: write-only, and a read of one answers - // nothing. - regs::IMC | regs::ICS => 0, + // §10.2.4.6: write-only, and a read answers nothing. + regs::IMC => 0, // The statistics the driver reads: each read takes the count and // clears it. regs::GPTC | regs::GPRC | regs::TPR | regs::MPC | regs::CRCERRS => { @@ -1161,8 +1160,6 @@ impl Model { let held = self.get(regs::IMS); self.set(regs::IMS, held & !value); } - // §10.2.4.4: set a cause, as if the event had happened. - regs::ICS => self.raise(value), // §10.2.4.1: "Writing a 1b to any bit in the register also clears // that bit. Writing a 0b to any bit has no effect on that bit." // `INT_ASSERTED` is not writable and clears with its causes. diff --git a/toyos-tco/src/lib.rs b/toyos-tco/src/lib.rs index bb4c4efccea..4ca017ff5d7 100644 --- a/toyos-tco/src/lib.rs +++ b/toyos-tco/src/lib.rs @@ -141,6 +141,13 @@ pub const WEDGE_BOUND_MS: u64 = JOB_BOUND_MS * 2; /// test is a reset where it should have been a verdict. const _: () = assert!(WEDGE_BOUND_MS > JOB_BOUND_MS); +/// The bound a boot that stages its own wedge carries instead of +/// [`WEDGE_BOUND_MS`], in milliseconds: it ends the machine seconds after the +/// wedge rather than at the bound every other boot keeps for a wedge nobody +/// staged. Its half is the lockup detector's bound, which still outlasts the +/// lockup probe's own reach to its lock. +pub const STAGED_BOUND_MS: u64 = 10_000; + /// The bound one *CPU* gets to take no interrupt at all while it is burning /// cycles, in milliseconds, before that CPU ends the machine from its own NMI. /// From edefd8193a3260615fd5f2a019efbdbb4352e6a0 Mon Sep 17 00:00:00 2001 From: japabu Date: Wed, 30 Sep 2026 19:36:10 +0200 Subject: [PATCH 10/19] The port poll's refusing case dials port 0, not a port just let go `coming_back_is_ssh_answering_and_not_its_port` went red in `cargo run -- --ci host` (EXIT=1). Its last case dialled the loopback listener's port after dropping the listener and found it still accepting for the whole second. Once let go, that port can be another socket's before it is dialled: another test's listener, or a self-connect from an ephemeral source port. Which of the two it was is not established. Port 0 is one nothing listens on. Three runs of `cargo test -p toyos-build --lib` after this change: EXIT=0 each. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- src/metal.rs | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/src/metal.rs b/src/metal.rs index d69c34f3866..856bf28fdb8 100644 --- a/src/metal.rs +++ b/src/metal.rs @@ -2665,8 +2665,10 @@ mod tests { } /// **A port that accepts is not a machine that came back**, and a machine - /// going down is its port closing. Staged through [`port_accepts`] on a - /// listener of this host's own, which accepts and never speaks `ssh`. + /// going down is its port refusing. Staged through [`port_accepts`] on a + /// listener of this host's own, which accepts and never speaks `ssh`, and on + /// port 0, which nothing listens on: a port the listener let go of can be + /// another socket's by the time it is dialled. #[test] fn coming_back_is_ssh_answering_and_not_its_port() { let listener = std::net::TcpListener::bind("127.0.0.1:0").expect("a loopback listener"); @@ -2682,8 +2684,8 @@ mod tests { assert_eq!(wait_on(1, "come back", true, accepts, || true), Ok(0)); let up = wait_on(1, "go down", false, accepts, || unreachable!("`ssh` asked of one going down")); assert_eq!(up, Err(Refusal::Silent { what: "go down", secs: 1 })); - drop(listener); - assert_eq!(wait_on(1, "go down", false, accepts, || unreachable!()), Ok(0)); + let refuses = || port_accepts("127.0.0.1", 0); + assert_eq!(wait_on(1, "go down", false, refuses, || unreachable!()), Ok(0)); } /// **An image with no bound on its own boot never reaches the stick.** From 1c81e3e66a81fb0d1520a463a05a6d0c2bbb49f6 Mon Sep 17 00:00:00 2001 From: japabu Date: Wed, 30 Sep 2026 20:09:39 +0200 Subject: [PATCH 11/19] Answer round 2 of #638: a kernel that dies past its ceiling is named at the backstop The backstop arm of `ceiling_verdict` now names a death it holds before it calls the guest slow. A 5 s ceiling and a kernel death at 7 s read "timed out after 20s, with the guest still talking 14s ago" at edefd8193, because the panic arm waits for `GUEST_QUIET` and the backstop came first; `main`'s 300 s floor named that panic at 22 s. The comment's clause that a death "is named by the arms above" was false for that case and goes. `ceiling_self_check`'s case (e) is two walks under a 5 s ceiling, a second at a time: a guest silent from any second in its budget must first read as `STALLED`, and a kernel dead at any second up to four ceilings must first be named. The old case (e) required only a backstop of 11 s or more, so a backstop of `ceiling + 6 s` passed it. The walk steps the quiet seconds and adds them to the start, where the review's form subtracted a `Duration`, which the host gate's clippy denies (`unchecked_time_subtraction`); the elapsed/quiet pairs are the same. Each arm was a checked patch, shown to build and reversed: - death walk at edefd8193's verdict code: EXIT=101, on `died = 7`. - backstop `(ceiling * 2).max(ceiling + Duration::from_secs(6))`: EXIT=101, the silence walk on `since = 0` ("timed out after 11s"). - backstop `ceiling * 2`: EXIT=101, the silence walk on `since = 0` ("timed out after 10s"). - this commit: EXIT=0. `lan_hold` is `deaf_cpu_hold`: its one runner is `dump_nmi_probe`'s `testcases-deaf` boot, which runs no netd, so its hold is no longer netd's lease bound but its own `PAST_THE_DEAF_WINDOW`, at the same 20 s. `issues/diagnostics/the-cable-judge-reads-three-netd-records-that-cannot-arrive-on-the-t14.md` goes: netd's lease record reached the T14's stick at b2ccd1c84, and the boot and keys it names are deleted by this branch. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- ...d-records-that-cannot-arrive-on-the-t14.md | 38 ------------------- tests/checks/qemu.rs | 33 ++++++++-------- tests/common/qemu.rs | 5 ++- .../toyos-rust-tests/src/bin/deaf_cpu_hold.rs | 11 ++++++ tests/toyos-rust-tests/src/bin/lan_hold.rs | 8 ---- tests/toyos.rs | 7 ++-- 6 files changed, 36 insertions(+), 66 deletions(-) delete mode 100644 issues/diagnostics/the-cable-judge-reads-three-netd-records-that-cannot-arrive-on-the-t14.md create mode 100644 tests/toyos-rust-tests/src/bin/deaf_cpu_hold.rs delete mode 100644 tests/toyos-rust-tests/src/bin/lan_hold.rs diff --git a/issues/diagnostics/the-cable-judge-reads-three-netd-records-that-cannot-arrive-on-the-t14.md b/issues/diagnostics/the-cable-judge-reads-three-netd-records-that-cannot-arrive-on-the-t14.md deleted file mode 100644 index bb3853a34b0..00000000000 --- a/issues/diagnostics/the-cable-judge-reads-three-netd-records-that-cannot-arrive-on-the-t14.md +++ /dev/null @@ -1,38 +0,0 @@ ---- -status: open -kind: defect -opened: 2026-09-13 ---- - -# The cable judge reads three netd records that cannot arrive on the T14 - -The cause was that userland stdout and stderr were console writes and `/log` -carried kernel records only; every program's lines reach `/log` now, through -its log ring (`issues/kernel/logging-records-from-every-producer-and-a-kernel-that-waits-on-nobody.md`). -This is what that cost the one judge written as if it were otherwise. - -`tests/common/lan.rs`'s `on_metal` refuses a boot that carries no `netd: MAC …`, -no `netd: … link up` and no `netd: ready` record, and judges -`lan.lancase.link_up_ms` and `lan.lancase.lease_ms` out of those lines. **It -cannot go green on the machine it was written for**, whatever the driver does. - -Metal run 36 held `tests/lancase` open for twenty seconds with netd alive and -driving the I219, and its readback carries exactly one line with `netd` in it — -the kernel's own `spawn:` record -(`/Users/jan/.claude/jobs/2280e09e/tmp/readbacks/lancase-placement-run36/kernel.log:314`): - -``` -$ grep -a -c 'netd' .../lancase-placement-run36/kernel.log -1 -``` - -The readings that do cross are the kernel's: the hand-over record, -`pcidev: slot N took its first message on vector 0xNN`, and the end-of-boot -`irq:` census. - -## What would close it - -Either §1 of the track above lands, or the judge stops reading netd's lines and -asks netd through its port — the `metalprobe` pattern, a job that exits with a -code encoding the link and the lease. The first is a kernel change and the -second is the harness's; neither is the I219 driver's. diff --git a/tests/checks/qemu.rs b/tests/checks/qemu.rs index 2c039e9978e..b6cfb335884 100644 --- a/tests/checks/qemu.rs +++ b/tests/checks/qemu.rs @@ -198,24 +198,25 @@ pub fn ceiling_self_check() -> Result<(), String> { would red healthy", )); } - // (e) A ceiling under [`GUEST_QUIET`]: a kernel that died is given its - // silence to be named before the backstop calls its guest slow. + // (e) A ceiling under [`GUEST_QUIET`], walked a second at a time: a guest + // silent from any point in its budget is a stall, and a kernel that died + // at any point, before or after its ceiling, is named. const SHORT: Duration = Duration::from_secs(5); - if let Some(cut) = - ceiling_verdict(Some(KERNEL), Duration::from_secs(11), SHORT, Duration::from_secs(10), 40) - { - return Err(format!( - "a kernel death under a {SHORT:?} ceiling was ended before its silence could name it: \ - {cut}" - )); + let first = |dying: Option<&str>, from: u64| { + (0..).map(Duration::from_secs).find_map(|quiet| { + ceiling_verdict(dying, Duration::from_secs(from) + quiet, SHORT, quiet, 40) + }) + }; + for since in 0..=SHORT.as_secs() { + let got = first(None, since); + if !got.as_deref().is_some_and(|v| v.starts_with(STALLED)) { + return Err(format!("silent from {since}s under a {SHORT:?} ceiling: {got:?}")); + } } - match ceiling_verdict(Some(KERNEL), Duration::from_secs(21), SHORT, GUEST_QUIET, 40) { - Some(named) if named.contains("kernel panic") => {} - other => { - return Err(format!( - "a kernel death under a {SHORT:?} ceiling, silent for {GUEST_QUIET:?}, was not \ - named: {other:?}" - )); + for died in 0..=4 * SHORT.as_secs() { + let got = first(Some(KERNEL), died); + if !got.as_deref().is_some_and(|v| v.contains("kernel panic")) { + return Err(format!("a kernel death at {died}s under a {SHORT:?} ceiling: {got:?}")); } } diff --git a/tests/common/qemu.rs b/tests/common/qemu.rs index aa84ea485d9..e692a82c971 100644 --- a/tests/common/qemu.rs +++ b/tests/common/qemu.rs @@ -559,9 +559,12 @@ pub fn ceiling_verdict( } // The backstop, for a guest that is stuck *and* chatty and so never trips // the silence guard; never before a guest silent since its ceiling has been - // silent for [`GUEST_QUIET`], so a death is named by the arms above. + // silent for [`GUEST_QUIET`]. let backstop = (ceiling * 2).max(ceiling + GUEST_QUIET); if elapsed > backstop { + if let Some(line) = dying { + return Some(kernel_died_here(line)); + } return Some(format!( "{TIMED_OUT} {}s, with the guest still talking {quiet:.0?} ago ({lines} \ console line(s) while it ran) — it was working and did not finish", diff --git a/tests/toyos-rust-tests/src/bin/deaf_cpu_hold.rs b/tests/toyos-rust-tests/src/bin/deaf_cpu_hold.rs new file mode 100644 index 00000000000..7e755fe1fc2 --- /dev/null +++ b/tests/toyos-rust-tests/src/bin/deaf_cpu_hold.rs @@ -0,0 +1,11 @@ +use std::thread::sleep; +use std::time::Duration; + +/// Past the window `dump-deaf-cpu` opens a fixed time into the boot and the +/// dump it kicks and probes inside it: an empty job list ends the boot before +/// the actuator arms. +const PAST_THE_DEAF_WINDOW: Duration = Duration::from_secs(20); + +fn main() { + sleep(PAST_THE_DEAF_WINDOW); +} diff --git a/tests/toyos-rust-tests/src/bin/lan_hold.rs b/tests/toyos-rust-tests/src/bin/lan_hold.rs deleted file mode 100644 index 31764fb3efd..00000000000 --- a/tests/toyos-rust-tests/src/bin/lan_hold.rs +++ /dev/null @@ -1,8 +0,0 @@ -use std::thread::sleep; -use std::time::Duration; - -const HOLD: Duration = Duration::from_millis(toyos_tco::LEASE_BOUND_MS); - -fn main() { - sleep(HOLD); -} diff --git a/tests/toyos.rs b/tests/toyos.rs index d212fe95de6..860daff9d61 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -258,8 +258,9 @@ const RUST_SKIP: &[&str] = &[ "netd_refused_pipes", "netd_refused_accept", "netd_lookup_let_go", - // It asserts nothing at all: it holds a boot open. - "lan_hold", + // It asserts nothing at all: it holds `dump_nmi_probe`'s boot open past + // the `dump-deaf-cpu` window. + "deaf_cpu_hold", // The same for `tests/lantalkcase`, held until the runner's bound is near // unless the host's `reboot` over ssh ends it first. `lan_talk` rides it. "lan_talk_hold", @@ -1723,7 +1724,7 @@ const METAL: &[(&str, metal::Metal)] = &[ "testcases-deaf", "tests/testcases", &["dump-deaf-cpu"], - &["test_rs_lan_hold"], + &["test_rs_deaf_cpu_hold"], )], judge: |b| faults::dump_nmi_probe_on_metal(&b[0].kernel()), }, From 09d74fcfbf5f8514c52fe4ee377c0e4bd0832cf5 Mon Sep 17 00:00:00 2001 From: japabu Date: Wed, 30 Sep 2026 22:55:58 +0200 Subject: [PATCH 12/19] Answer round 3 of #638: the backstop walks step at the read loop's poll, and main's new wait is under the rule - `ceiling_self_check`'s two walks step `since`, `died` and `quiet` by 100 ms, the read loop's poll of a silent guest, instead of by whole seconds. At whole seconds a backstop one second short, `(ceiling * 2).max(ceiling + GUEST_QUIET - 1 s)`, passed both walks: at `since = 5` the walk reached 19 s at quiet 14, and 19 is not past 19. It now fails at `since = 4.2 s` ("timed out after 19s"), EXIT=101. - The walks' comment goes: "any point" claimed more than the walk checks, and the rest restated the loops. - `handler_post_without_a_pass`'s drain, from main's #634, was 30 s under the width-scaled budget. The test took 3-4 s in #634's whole runs (4 s in 634r6), so it is 12 s. - `cpal_drop_unreleased`, #641's new shared member, took 111 and 138 ms in #641's whole runs, so the 5 s shared default covers it and it needs no row. - `deaf_cpu_hold` keeps its fixed 20 s. A binary test-runner spawns holds no `logread`: test-runner hands down its namespace, and `logread` is a `SysCap` duplicate, not a namespace entry. logd serves no reader port on `tests/testcases`. The only record the hold could read is logd's file under `/log`, which gives no notification, so waiting on it would be a sleep-and-reread poll. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- tests/checks/qemu.rs | 20 +++++++++----------- tests/toyos.rs | 2 +- 2 files changed, 10 insertions(+), 12 deletions(-) diff --git a/tests/checks/qemu.rs b/tests/checks/qemu.rs index b6cfb335884..a2c38f450ce 100644 --- a/tests/checks/qemu.rs +++ b/tests/checks/qemu.rs @@ -198,25 +198,23 @@ pub fn ceiling_self_check() -> Result<(), String> { would red healthy", )); } - // (e) A ceiling under [`GUEST_QUIET`], walked a second at a time: a guest - // silent from any point in its budget is a stall, and a kernel that died - // at any point, before or after its ceiling, is named. const SHORT: Duration = Duration::from_secs(5); - let first = |dying: Option<&str>, from: u64| { - (0..).map(Duration::from_secs).find_map(|quiet| { - ceiling_verdict(dying, Duration::from_secs(from) + quiet, SHORT, quiet, 40) - }) + // What the read loop polls a silent guest at. + const STEP: Duration = Duration::from_millis(100); + let every = || (0..).map(|n| STEP * n); + let first = |dying: Option<&str>, from: Duration| { + every().find_map(|quiet| ceiling_verdict(dying, from + quiet, SHORT, quiet, 40)) }; - for since in 0..=SHORT.as_secs() { + for since in every().take_while(|&t| t <= SHORT) { let got = first(None, since); if !got.as_deref().is_some_and(|v| v.starts_with(STALLED)) { - return Err(format!("silent from {since}s under a {SHORT:?} ceiling: {got:?}")); + return Err(format!("silent from {since:?} under a {SHORT:?} ceiling: {got:?}")); } } - for died in 0..=4 * SHORT.as_secs() { + for died in every().take_while(|&t| t <= SHORT * 4) { let got = first(Some(KERNEL), died); if !got.as_deref().is_some_and(|v| v.contains("kernel panic")) { - return Err(format!("a kernel death at {died}s under a {SHORT:?} ceiling: {got:?}")); + return Err(format!("a kernel death at {died:?} under a {SHORT:?} ceiling: {got:?}")); } } diff --git a/tests/toyos.rs b/tests/toyos.rs index 4d7d13cc9d4..711bff43da7 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -12120,7 +12120,7 @@ fn run_machine_test( ); let mut log = qemu.boot_log().to_string(); if !log.lines().any(handler_post_said) { - log += &qemu.drain_until(Duration::from_secs(30), handler_post_said); + log += &qemu.drain_until(Duration::from_secs(12), handler_post_said); } handler_post(&log) } From 59940c452e0059ab205d9a801daea3134628afa5 Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 1 Oct 2026 00:09:59 +0200 Subject: [PATCH 13/19] Waits this branch cut to a hard deadline end through ceiling_verdict The orchestrator's whole run at 09d74fcfb (638r4) went red on toolkit_winit_loop "never finished" after 57 s. This branch had replaced main's Liveness(40 s quiet, 240 s total) with a hard `Instant::now() + qemu.budget(35 s)`, and a hard cut does not ask whether the guest is still talking. `qemu::Ceiling` reads a capture its caller keeps and appends to. It takes the guest's silence from when the capture last grew, and a kernel death from the first one appended. The decision is ceiling_verdict's, so every one of these waits ends the way run_test_paced's does: - a guest still talking past its budget waits for the backstop and reds as TIMED_OUT - one silent for GUEST_QUIET past its budget reds as STALLED - a dead kernel is named, with its report `backstop()` is ceiling_verdict's formula, pulled out so a wait with no console can sit behind another wait's ceiling. The waits this branch cut from main's far bound to a tight hard one: - toolkit_winit_loop, 35 s: Liveness(40, 240) on main. - toolkit_winit_pace, 53 s: a Liveness whose total was cut from 120 s. That total is a hard cut however loud the guest is, and it was not host-scaled. A wait it ended also went on to count presents, so a slow guest read as a wrong count. It is now host-scaled, and the ceiling's verdict is the red. - lan_no_lease, 99 s: drain_until(GUEST_WEDGED) on main. The guest is silent until netd gives up, and the ceiling allows silence inside the budget. - kernel_log_file's device poll, 54 s, and usb_flush_optional's, 99 s: budget(GUEST_WEDGED) on main. Each now drains the console between polls instead of sleeping 50 ms, so the ceiling can hear the guest. The lines it reads still reach the shutdown tail's panic check. - guest_dies_with_its_harness, 24 s: GUEST_WEDGED on main. The wait reads the owner's stdout, which carries nothing before HELD. The owner's own boot ceiling (BOOT_CEILING, host scale 1 in a fresh process) names a boot that never came up, and 24 s could cut ahead of that 30 s. The wait now sits at that ceiling's backstop. Not converted: every wait that was already a hard deadline on main and only had its number moved. Among them are the boot ceiling, toolkit_iced's three waits, metal_sim_pointer_churn's three, handler_post_without_a_pass's drain, power's WAIT and CHAIN_WAIT, logstream's FLOOD_CEILING, and the screendump_until/drain_until literals. What the 638r4 capture shows is not a slow guest. The terminal logged stage 1 at 6.534 s and nothing else from the app. Meanwhile the app opened 23 windows, the last being stage 6's at 9.448 s, and every one of those windows is created after a stage line it had printed. CLOSE-ME never arrived. From 11.4 s to 42.8 s every sched line reads ready=0 on every CPU. Under this change that guest still reds, at the backstop as TIMED_OUT instead of at 35 s. That is filed as issues/build/winit-loops-output-stopped-reaching-the-log-after-stage-1.md. metal_sim_client_death's red in the same run was not a cut. Its run_test returned on ===TEST_END with exit 0 after 153 ms. The missing line is its grandchild's, printed after the root had ended. That is filed as issues/build/client-death-ends-before-its-reaped-creators-request-is-served.md. capture_ceiling_self_check stages Ceiling on instants ahead of now: - a capture growing past its ceiling is ended only by the backstop - one that stopped growing is ended by the stall - a kernel death appended after the first read is named, with its report Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L --- ...e-its-reaped-creators-request-is-served.md | 28 ++++++++ ...-stopped-reaching-the-log-after-stage-1.md | 28 ++++++++ tests/checks.rs | 1 + tests/checks/qemu.rs | 64 +++++++++++++++++++ tests/common/lan.rs | 24 +++---- tests/common/orphan.rs | 6 +- tests/common/qemu.rs | 56 ++++++++++++++-- tests/common/usb.rs | 14 ++-- tests/common/volumes.rs | 17 ++--- tests/toyos.rs | 20 ++++-- 10 files changed, 216 insertions(+), 42 deletions(-) create mode 100644 issues/build/client-death-ends-before-its-reaped-creators-request-is-served.md create mode 100644 issues/build/winit-loops-output-stopped-reaching-the-log-after-stage-1.md diff --git a/issues/build/client-death-ends-before-its-reaped-creators-request-is-served.md b/issues/build/client-death-ends-before-its-reaped-creators-request-is-served.md new file mode 100644 index 00000000000..cec32de9f99 --- /dev/null +++ b/issues/build/client-death-ends-before-its-reaped-creators-request-is-served.md @@ -0,0 +1,28 @@ +--- +status: open +kind: tooling +opened: 2026-10-01 +--- + +# `metal_sim_client_death` can end before its reaped creator's request is served + +`test_rs_compositor_client_death`'s root closes the pipe that releases the +grandchild holding the reaped creator's connection, probes the compositor and +goes on to its next case. Nothing it does waits for the grandchild's +`MSG_CREATE_WINDOW` to have been served, although its module header says every +step waits on the one before it. The grandchild's `a reaped creator's +connection still got a window` is the host's non-vacuity witness, and the host +reads it only out of `run_test`'s window, which closes at the root's +`===TEST_END`. + +At `09d74fcfb`, in the orchestrator's whole run `638r4-whole.log` on a host at +load average 43–52 on 14 cores, the root reported all six cases and exited 0. +The compositor's `window opened client=37003 content=928,506 64x64` came after +`6 deaths survived`, and the witness never reached the window, so the run went +red on `the compositor never served a request from a reaped creator`. The +test's ceiling did not fire. The orchestrator counts it as the first red in 34 +runs. + +Exit: the witness is ordered before the verdict. Either the root waits for its +grandchild's line, or the host reads past `===TEST_END` for it under the run's +ceiling. diff --git a/issues/build/winit-loops-output-stopped-reaching-the-log-after-stage-1.md b/issues/build/winit-loops-output-stopped-reaching-the-log-after-stage-1.md new file mode 100644 index 00000000000..811fdd584cc --- /dev/null +++ b/issues/build/winit-loops-output-stopped-reaching-the-log-after-stage-1.md @@ -0,0 +1,28 @@ +--- +status: open +kind: finding +opened: 2026-10-01 +--- + +# `toolkit_winit_loop`'s output stopped reaching the log after stage 1, while the app ran on + +At `09d74fcfb` the orchestrator's whole run `638r4-whole.log` went red on +`toolkit_winit_loop`. The host was at load average 43–52 on 14 cores. The +terminal logged `WINIT-LOOP stage 1` at 6.534 s and nothing else of the app's. + +The app kept going. The compositor opened 23 of its windows by 9.448 s and +closed 22 of them. That is stages 3 to 5 and then stage 6's window, and each +of those windows is created after a `stage` line the app had already printed. +Stage 6 prints `WINIT-LOOP CLOSE-ME` on its first redraw. That line never +reached the log, so the harness never sent GUI+Q. + +From then until the harness gave up at 42.8 s, every `sched:` line on every +CPU reads `ready=0`. The only speaker was the compositor's interval line, +every 2 s. The guest was idle with work outstanding, and it was not starved. +Candidates are a wake lost between the app's stdout, the terminal and logd, or +a terminal that stopped reading its pty. + +In the 33 other whole-suite logs under the orchestrator's `logs/`, all six +stage lines arrive under `{… terminal}` within 0.373 to 2.446 s of the first. + +Exit: the cause, found from a reproduction or from the next capture. diff --git a/tests/checks.rs b/tests/checks.rs index c5e5a5c4529..9a7048ab522 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -26,6 +26,7 @@ mod checks { fn serial_vocabulary() -> Result<(), String> { serial_checks::self_check()?; qemu_checks::ceiling_self_check()?; + qemu_checks::capture_ceiling_self_check()?; qemu_checks::host_scale_self_check()?; one_vocabulary() } diff --git a/tests/checks/qemu.rs b/tests/checks/qemu.rs index a2c38f450ce..8c8bdec4b59 100644 --- a/tests/checks/qemu.rs +++ b/tests/checks/qemu.rs @@ -302,6 +302,70 @@ pub fn ceiling_self_check() -> Result<(), String> { Ok(()) } +/// [`Ceiling`] reading a capture its caller keeps, staged on instants ahead of +/// now so that nothing here sleeps: a capture still growing past its ceiling +/// is ended by the backstop alone, one that stopped growing by the stall, and +/// a kernel death appended after the first read by its own name and report. +pub fn capture_ceiling_self_check() -> Result<(), String> { + const CEILING: Duration = Duration::from_secs(10); + const LINE: &str = "compositor: frames=2\n"; + const REPORT: &str = "rip=0xffffffff80121a40"; + let t0 = Instant::now(); + let at = |secs: u64| t0 + Duration::from_secs(secs); + + let far = backstop(CEILING).as_secs(); + let mut talking = Ceiling::new(CEILING); + let mut capture = String::new(); + for s in 1..=far { + capture.push_str(LINE); + if let Some(cut) = talking.verdict(&capture, at(s)) { + return Err(format!("growing at {s}s under a {CEILING:?} ceiling, and cut: {cut}")); + } + } + capture.push_str(LINE); + let slow = talking.verdict(&capture, at(far + 1)).map(|v| v.to_string()); + if !slow.as_deref().is_some_and(|v| v.starts_with(TIMED_OUT)) { + return Err(format!("growing past the {far}s backstop: {slow:?}")); + } + + let mut stopped = Ceiling::new(CEILING); + let capture = String::from(LINE); + let quiet = GUEST_QUIET.as_secs(); + for s in 2..=quiet + 1 { + if let Some(cut) = stopped.verdict(&capture, at(s)) { + return Err(format!("silent since 2s and cut at {s}s, inside {GUEST_QUIET:?}: {cut}")); + } + } + let stalled = quiet + 3; + let stall = stopped.verdict(&capture, at(stalled)).map(|v| v.to_string()); + if !stall.as_deref().is_some_and(|v| v.starts_with(STALLED)) { + return Err(format!("silent from 2s to {stalled}s under a {CEILING:?} ceiling: {stall:?}")); + } + + let mut dying = Ceiling::new(CEILING); + let mut capture = String::from(LINE); + let early = dying.verdict(&capture, at(1)).is_some(); + capture.push_str(&format!( + "[kernel 1.450 cpu3] PANIC: panicked at kernel/src/sched/reserve.rs:812:9:\n\ + [kernel 1.450 cpu3] {REPORT}\n" + )); + if early || dying.verdict(&capture, at(2)).is_some() { + return Err(format!("a capture 2s into a {CEILING:?} ceiling was ended")); + } + let died = dying.verdict(&capture, at(2 + quiet)).map(|v| v.to_string()); + if !died.as_deref().is_some_and(|v| { + v.starts_with("kernel panic") && v.contains(DIED_SAYING) && v.contains(REPORT) + }) { + return Err(format!("a kernel death appended at 2s, silent since: {died:?}")); + } + + eprintln!( + " [ceiling] a capture growing to {far}s is ended by the backstop alone, one silent \ + since 2s by the stall at {stalled}s, and a death appended later by its name and report" + ); + Ok(()) +} + fn sentence(verdict: &WaitVerdict) -> String { verdict.to_string().lines().next().unwrap_or_default().to_string() } diff --git a/tests/common/lan.rs b/tests/common/lan.rs index 60adf79a4b9..b2df254edcf 100644 --- a/tests/common/lan.rs +++ b/tests/common/lan.rs @@ -399,18 +399,20 @@ pub fn lan_no_lease( let mut guest = QemuInstance::boot_with_options(&case, &[], &[], options); let mut console = guest.boot_log().to_string(); // Drained until netd's `ready` after its give-up, and not awaited: the - // guest says nothing at all until netd gives up on its own clock, which - // every wait in this harness reads as a machine that stopped. + // guest says nothing at all until netd gives up on its own clock, and only + // the ceiling lets a guest be silent inside its budget. let gave_up = format!("{NO_LEASE}{HOSTNAME} in "); - let given_up = std::cell::Cell::new(false); - let served = std::cell::Cell::new(false); - console.push_str(&guest.drain_until(std::time::Duration::from_secs(99), |line| { - given_up.set(given_up.get() || line.contains(&gave_up)); - served.set(given_up.get() && line.contains(READY)); - served.get() - })); - if !served.get() { - return Err(format!("{} waiting for {gave_up:?} and then {READY:?}\n{console}", qemu::STALLED)); + let from = console.len(); + let mut ceiling = qemu::Ceiling::new(guest.budget(std::time::Duration::from_secs(99))); + loop { + let said = &console[from..]; + if said.find(&gave_up).is_some_and(|at| said[at..].contains(READY)) { + break; + } + if let Some(why) = ceiling.verdict(said, std::time::Instant::now()) { + return Err(format!("waiting for {gave_up:?} and then {READY:?}: {why}\n{console}")); + } + console.push_str(&guest.drain_serial(std::time::Duration::from_millis(200))); } let log = serial::Serial::named("the lan boot with no server", console.as_str()); if let Ok(lease) = lease_in(log.text()) { diff --git a/tests/common/orphan.rs b/tests/common/orphan.rs index c2c10481a20..c95cb443290 100644 --- a/tests/common/orphan.rs +++ b/tests/common/orphan.rs @@ -36,8 +36,10 @@ pub fn guest_dies_with_its_harness(test_config: &Path) -> Result<(), String> { let mut owner = Owner::spawn(owner)?; let owner_pid = owner.pid(); let verdict = (|| { - let within = - qemu::budget_smp(std::time::Duration::from_secs(24), BootOptions::default().smp); + // Behind the owner's one wait, its boot, whose own ceiling names a boot + // that never came up. + let boot = qemu::budget_smp(qemu::BOOT_CEILING, BootOptions::default().smp); + let within = qemu::backstop(boot); let pid: u32 = owner.said(HELD, within)?.parse().map_err(|e| format!("the owner's QEMU pid: {e}"))?; owner.killed(&[pid]).map(|()| pid) diff --git a/tests/common/qemu.rs b/tests/common/qemu.rs index e692a82c971..85ade7f1e65 100644 --- a/tests/common/qemu.rs +++ b/tests/common/qemu.rs @@ -557,23 +557,65 @@ pub fn ceiling_verdict( ceiling.as_secs() )); } - // The backstop, for a guest that is stuck *and* chatty and so never trips - // the silence guard; never before a guest silent since its ceiling has been - // silent for [`GUEST_QUIET`]. - let backstop = (ceiling * 2).max(ceiling + GUEST_QUIET); - if elapsed > backstop { + let far = backstop(ceiling); + if elapsed > far { if let Some(line) = dying { return Some(kernel_died_here(line)); } return Some(format!( "{TIMED_OUT} {}s, with the guest still talking {quiet:.0?} ago ({lines} \ console line(s) while it ran) — it was working and did not finish", - backstop.as_secs() + far.as_secs() )); } None } +/// Where [`ceiling_verdict`] ends a wait on a guest that is stuck *and* chatty +/// and so never trips the silence guard; never before a guest silent since +/// `ceiling` has been silent for [`GUEST_QUIET`]. +pub fn backstop(ceiling: Duration) -> Duration { + (ceiling * 2).max(ceiling + GUEST_QUIET) +} + +/// [`ceiling_verdict`] for a wait that keeps its own capture, which it only +/// ever appends to: the time since the capture last grew is the guest's +/// silence, and the first kernel death in it is the one the verdict names. +pub struct Ceiling { + ceiling: Duration, + start: Instant, + grew: Instant, + seen: usize, + dying: Option, +} + +impl Ceiling { + /// `ceiling` already paid out ([`QemuInstance::budget`]), running from now. + pub fn new(ceiling: Duration) -> Self { + let start = Instant::now(); + Self { ceiling, start, grew: start, seen: 0, dying: None } + } + + /// What ended the wait at `now`, if it is over, carrying the capture. + pub fn verdict(&mut self, capture: &str, now: Instant) -> Option { + if capture.len() != self.seen { + if self.dying.is_none() { + self.dying = super::serial::kernel_death(&capture[self.seen..]).map(str::to_string); + } + self.seen = capture.len(); + self.grew = now; + } + let sentence = ceiling_verdict( + self.dying.as_deref(), + now.saturating_duration_since(self.start), + self.ceiling, + now.saturating_duration_since(self.grew), + capture.lines().count(), + )?; + Some(WaitVerdict::new(sentence, &[capture])) + } +} + /// Collect console output until `done` reads true of the whole capture, or the /// guest stops making progress. /// @@ -4701,7 +4743,7 @@ fn publish_line( /// A boot's ceiling: [`budget_smp`]'s rule over the tests that are one boot and /// one trivial command. -const BOOT_CEILING: Duration = Duration::from_secs(30); +pub const BOOT_CEILING: Duration = Duration::from_secs(30); /// Returns every line seen on the way to the marker — see [`QemuInstance::boot_log`]. fn wait_for_ready( diff --git a/tests/common/usb.rs b/tests/common/usb.rs index 9336a3c258b..3b80cca490c 100644 --- a/tests/common/usb.rs +++ b/tests/common/usb.rs @@ -818,7 +818,8 @@ fn optional_flush_keeps_the_log( // the sink is still running, and the only place that is visible is the // device while the machine is up. A stick with no write cache that cost // the machine its log is a hang here. - let give_up = std::time::Instant::now() + qemu.budget(Duration::from_secs(99)); + let mut ceiling = qemu::Ceiling::new(qemu.budget(Duration::from_secs(99))); + let mut during = String::new(); loop { let on_device = String::from_utf8_lossy( &super::volumes::newest_log(&image_path, start, len)?.1, @@ -827,20 +828,19 @@ fn optional_flush_keeps_the_log( if on_device.contains("Boot: complete") { break; } - if std::time::Instant::now() >= give_up { + if let Some(why) = ceiling.verdict(&during, std::time::Instant::now()) { return Err(format!( - "{} waiting for `Boot: complete` in the log on a stick with no write cache: {} \ - bytes there", - qemu::STALLED, + "waiting for `Boot: complete` in the log on a stick with no write cache, {} \ + bytes there: {why}\n{during}", on_device.len() )); } - std::thread::sleep(Duration::from_millis(50)); + during.push_str(&qemu.drain_serial(Duration::from_millis(50))); } writeln!(qemu.stdin_mut(), "run shutdown").expect("write to QEMU stdin"); qemu.flush_stdin(); - let log = format!("{boot}{}", qemu.drain_serial(Duration::from_secs(20))); + let log = format!("{boot}{during}{}", qemu.drain_serial(Duration::from_secs(20))); drop(qemu); for bad in ["PANIC:", "panicked at"] { if log.contains(bad) { diff --git a/tests/common/volumes.rs b/tests/common/volumes.rs index 927e5a4468d..a957d792d9b 100644 --- a/tests/common/volumes.rs +++ b/tests/common/volumes.rs @@ -558,8 +558,10 @@ pub fn kernel_log_file( // was put there by `/system/bin/logd` while the machine was running. // // Polled until logd has written through `Boot: complete`: when logd writes - // is its own business, and one that never does is a hang. - let give_up = std::time::Instant::now() + qemu.budget(Duration::from_secs(54)); + // is its own business, and one that never does is a hang. The console read + // between polls is what tells the ceiling whether the guest still talks. + let mut ceiling = qemu::Ceiling::new(qemu.budget(Duration::from_secs(54))); + let mut during = String::new(); let mut running; let mut running_text; let mut running_name; @@ -569,16 +571,15 @@ pub fn kernel_log_file( if running_text.contains("Boot: complete") { break; } - if std::time::Instant::now() >= give_up { + if let Some(why) = ceiling.verdict(&during, std::time::Instant::now()) { return Err(format!( - "{} waiting for logd to write `Boot: complete` to the device: {} bytes there, \ - starting {:?}", - qemu::STALLED, + "waiting for logd to write `Boot: complete` to the device, {} bytes there and \ + starting {:?}: {why}\n{during}", running.len(), running_text.chars().take(120).collect::() )); } - std::thread::sleep(Duration::from_millis(50)); + during.push_str(&qemu.drain_serial(Duration::from_millis(50))); } if !running_text.contains(&nonce) { return Err(format!( @@ -599,7 +600,7 @@ pub fn kernel_log_file( writeln!(qemu.stdin_mut(), "run shutdown").expect("write to QEMU stdin"); qemu.flush_stdin(); - let tail = qemu.drain_serial(Duration::from_secs(20)); + let tail = format!("{during}{}", qemu.drain_serial(Duration::from_secs(20))); drop(qemu); for bad in ["PANIC:", "panicked at"] { if tail.contains(bad) { diff --git a/tests/toyos.rs b/tests/toyos.rs index 711bff43da7..9c924e0d65a 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -7930,9 +7930,9 @@ fn toolkit_window_wake(rust_bins: &[(String, Vec)]) -> Result<(), String> { fn toolkit_winit_loop(rust_bins: &[(String, Vec)]) -> Result<(), String> { let (mut qemu, mut log, launched) = toolkit_launch(rust_bins, "winit_loop", "test_rs_winit_loop")?; let log = &mut log; - let give_up = Instant::now() + qemu.budget(Duration::from_secs(35)); + let mut ceiling = qemu::Ceiling::new(qemu.budget(Duration::from_secs(35))); let mut closed = false; - while Instant::now() < give_up { + loop { let said = &log[launched..]; if said.contains("WINIT-LOOP-OK") { // Up to the kept window's close: a window the app still held is @@ -7975,9 +7975,11 @@ fn toolkit_winit_loop(rust_bins: &[(String, Vec)]) -> Result<(), String> { } continue; } + if let Some(why) = ceiling.verdict(said, Instant::now()) { + return Err(format!("test_rs_winit_loop never finished: {why}\n{said}")); + } log.push_str(&qemu.drain_serial(Duration::from_millis(200))); } - Err(format!("test_rs_winit_loop never finished:\n{}", &log[launched..])) } /// Redraw pacing: an application that asks for its next frame from inside @@ -7992,8 +7994,8 @@ fn toolkit_winit_pace(rust_bins: &[(String, Vec)]) -> Result<(), String> { let (mut qemu, mut log, launched) = toolkit_launch(rust_bins, "winit_pace", "test_rs_winit_pace")?; let log = &mut log; let drew = format!("WINIT-PACE drew {PACE_FRAMES} frames"); - let mut live = qemu::Liveness::new(Duration::from_secs(30), Duration::from_secs(53)); - while live.working(log) && !log[launched..].contains(&drew) { + let mut ceiling = qemu::Ceiling::new(qemu.budget(Duration::from_secs(53))); + while !log[launched..].contains(&drew) { let said = &log[launched..]; if said.contains("WINIT-PACE-FAIL") || said.contains("panicked") { return Err(format!("the animation failed:\n{said}")); @@ -8001,10 +8003,14 @@ fn toolkit_winit_pace(rust_bins: &[(String, Vec)]) -> Result<(), String> { if said.contains("exit: test_rs_winit_pace pid=") { return Err(format!("test_rs_winit_pace left before it finished drawing:\n{said}")); } + if let Some(why) = ceiling.verdict(said, Instant::now()) { + return Err(format!("the animation never said it was done: {why}\n{said}")); + } log.push_str(&qemu.drain_serial(Duration::from_millis(200))); } - let (client, _) = opened_window(&log[launched..]) - .ok_or_else(|| format!("the animation never said it was done:\n{}", &log[launched..]))?; + let (client, _) = opened_window(&log[launched..]).ok_or_else(|| { + format!("the compositor opened no window for the animation:\n{}", &log[launched..]) + })?; let closing = log.len(); if !close_focused_window(&mut qemu, log, closing) { return Err(format!("GUI+Q never reached the compositor:\n{}", &log[launched..])); From bf28c1e3852cb65c80f19113dbb2187541031219 Mon Sep 17 00:00:00 2001 From: japabu Date: Fri, 2 Oct 2026 23:51:25 +0200 Subject: [PATCH 14/19] metal: the talking boot hands the machine back after its record, and a refused boot says why Carried from #609 (310285359 on wt/toyos-t14lan), which is closed. - metaltalk::hand_back fires `reboot` once the stream has carried this boot's `Boot: complete`, read as the judge reads it, or once CARRIED_WAIT (30 s) has passed. On the T14 the stream stalled at its 217th line on two runs, 262 ms and 595 ms after logd admitted the reader: netd's I219 drops everything past 15 frames in flight, the rest waits for smoltcp's 700 ms retransmit timeout, and `reboot` beat it. That defect is filed as issues/hardware/netds-i219-drops-a-transmit-burst-past-its-ring.md. The talking boot's issue stays until two T14 runs pass `lan_talk`. - A `toyos-metal` run's stderr is echoed and kept, and a failed run's verdict carries the refusal it ended on (metal::said_refusal, through the REFUSAL_HEAD the binary prints). #609 named the constant REFUSED, which main's metal.rs has since given to the readback's verdict file, and wrapped the run in a `Driver` with a reader thread because the swap ran beside it; main deleted the swap, so it is one function that reads the stream and then waits. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm --- ...ing-boots-reboot-outruns-its-log-stream.md | 18 +++-- ...19-drops-a-transmit-burst-past-its-ring.md | 35 ++++++++++ src/bin/toyos-metal.rs | 4 +- src/metal.rs | 29 ++++++++ src/metaltalk.rs | 68 ++++++++++++++++++- tests/common/metal.rs | 41 ++++++++--- 6 files changed, 176 insertions(+), 19 deletions(-) create mode 100644 issues/hardware/netds-i219-drops-a-transmit-burst-past-its-ring.md diff --git a/issues/build/the-talking-boots-reboot-outruns-its-log-stream.md b/issues/build/the-talking-boots-reboot-outruns-its-log-stream.md index 9f5aa185cc7..262014ff8f2 100644 --- a/issues/build/the-talking-boots-reboot-outruns-its-log-stream.md +++ b/issues/build/the-talking-boots-reboot-outruns-its-log-stream.md @@ -6,12 +6,13 @@ opened: 2026-09-29 # The talking boot's `reboot` outruns its log stream, so `lan_talk` reds when the backlog has not crossed -`metaltalk::converse` (`src/metaltalk.rs`) waits for the stream to connect, -pings, runs one command and fires `reboot`; nothing waits on the stream +`metaltalk::converse` (`src/metaltalk.rs`) waited for the stream to connect, +pinged, ran one command and fired `reboot`; nothing waited on the stream carrying the lines `metaltalk::judge` then requires, this boot's `Boot: complete` among them. `logd` serves the boot from its first line, so -the verdict is a race between the backlog crossing and the `reboot` the host -itself sends. +the verdict was a race between the backlog crossing and the `reboot` the host +itself sends. `metaltalk::hand_back` now fires `reboot` once the stream has +carried that record or its bound has passed. ## Measured @@ -33,7 +34,12 @@ first 217 lines, ending at `0.493 ... xHCI: configuration set`; `logd: serving this boot's log to 192.168.1.47:54752` at 20.996 s and init's `power: the machine stops` at 21.591 s: the stream had 595 ms. +The T14 run of PR #609 at `7d2e15c0` gave the same finding at the same 217th +line, with 262 ms between the admit and the stop. The stall is at a fixed +byte count, not a fixed time. netd's I219 drops everything past 15 frames in +flight (`issues/hardware/netds-i219-drops-a-transmit-burst-past-its-ring.md`), +and the rest of the stream waits for a retransmit timeout that `reboot` beat. + ## Exit condition -`converse` fires `reboot` only once the stream has carried `Boot: complete` -or its bound has passed, and two consecutive T14 runs pass `lan_talk`; then this file is deleted. +Two consecutive T14 runs pass `lan_talk`; then this file is deleted. diff --git a/issues/hardware/netds-i219-drops-a-transmit-burst-past-its-ring.md b/issues/hardware/netds-i219-drops-a-transmit-burst-past-its-ring.md new file mode 100644 index 00000000000..36771578727 --- /dev/null +++ b/issues/hardware/netds-i219-drops-a-transmit-burst-past-its-ring.md @@ -0,0 +1,35 @@ +--- +status: open +kind: defect +opened: 2026-09-29 +--- + +# netd's I219 drops a transmit burst past its ring, and only a retransmit timeout recovers it + +`I219::tx` (`userland/netd/src/i219.rs`) writes a frame the driver has no +descriptor for into a scratch buffer and drops it: smoltcp's `TxToken` cannot +refuse. But `Device::transmit` can, by answering `None`, and then smoltcp keeps +the bytes in the socket and sends them on a later poll. netd's `transmit` +(`userland/netd/src/main.rs`) answers `Some` every time. `toyos_i219::TX_RING` +is 16, so 15 frames can be in flight. Every frame after those 15 in one poll is +lost, and TCP gets it back only when its retransmission timeout fires. For +smoltcp 0.12 that timeout starts at 700 ms (`RTTE_INITIAL_RTT` + +4 × `RTTE_INITIAL_DEV`). + +## Measured + +The T14 run of PR #609 at `7d2e15c0`, boot `lantalkcase`. `logd` admitted the +host's stream at 19.141 s. At 19.180 s netd said `9 frame(s) dropped with no +transmit descriptor free`, and `reboot` came at 19.403 s. The host's +`stream.log` is `kernel.log`'s first 217 lines, which is 21890 bytes, and +15 × 1460 = 21900 falls inside line 218. The run of `main` at `7e151819` +stopped at the same 217th line, with 595 ms between the admit and the stop +(`issues/build/the-talking-boots-reboot-outruns-its-log-stream.md`). Both +windows are shorter than the first retransmit timeout. The same count appears +on the `lanswapcase` boot: 11, 18 and 23 frames dropped. + +## Exit + +`transmit` answers `None` when no descriptor is free, and a descriptor coming +free wakes netd's poll. A host test pushes more than `TX_RING` frames' worth +through one poll and asserts that `tx_dropped` stays 0 and every byte leaves. diff --git a/src/bin/toyos-metal.rs b/src/bin/toyos-metal.rs index 76368ae7ada..024be40f829 100644 --- a/src/bin/toyos-metal.rs +++ b/src/bin/toyos-metal.rs @@ -3,7 +3,7 @@ //! two: a boot that failed exits 1 and a loop that could not run exits 2, so //! "the machine is broken" is never read as "the driver is". -use toyos_build::metal::{run, Args}; +use toyos_build::metal::{run, Args, REFUSAL_HEAD}; fn main() { let words: Vec = std::env::args().skip(1).collect(); @@ -15,6 +15,6 @@ fn main() { } Err(refusal) => refusal, }; - eprintln!("toyos-metal: {refusal}"); + eprintln!("{REFUSAL_HEAD}{refusal}"); std::process::exit(if refusal.about_the_boot() { 1 } else { 2 }); } diff --git a/src/metal.rs b/src/metal.rs index a2303142688..490c82697e6 100644 --- a/src/metal.rs +++ b/src/metal.rs @@ -101,6 +101,18 @@ const LOADER: &str = r"\EFI\BOOT\BOOTX64.EFI"; const LID_KEYS: &[&str] = &["HandleLidSwitch", "HandleLidSwitchExternalPower", "HandleLidSwitchDocked"]; +/// What `toyos-metal`'s last words on its stderr begin with when it refuses: +/// the harness reads the refusal back by it, to name it beside the exit status. +pub const REFUSAL_HEAD: &str = "toyos-metal: "; + +/// The refusal a `toyos-metal` run's stderr ends on, from its [`REFUSAL_HEAD`] line +/// to the end, or `None` where it said none. +pub fn said_refusal(stderr: &str) -> Option { + let lines: Vec<&str> = stderr.lines().collect(); + let at = lines.iter().rposition(|line| line.starts_with(REFUSAL_HEAD))?; + Some(lines[at..].join("\n")[REFUSAL_HEAD.len()..].trim_end().to_string()) +} + /// Every way this loop refuses, by name. #[derive(Debug, Clone, PartialEq, Eq)] pub enum Refusal { @@ -2614,6 +2626,23 @@ mod tests { assert_eq!(wait_on(1, "go down", false, refuses, || unreachable!()), Ok(0)); } + /// **The harness names the refusal, not only the exit status.** The + /// stderr is the T14's `lantalkcase` run's, cargo's own lines included, and + /// the refusal it ends on is read back whole, every finding with it. + #[test] + fn a_refusal_is_read_back_off_the_drivers_stderr() { + let stderr = " Blocking waiting for file lock on package cache\n\ + \x20 Finished `dev` profile [optimized + debuginfo] target(s) in 0.19s\n\ + \x20 Running `target/debug/toyos-metal --image /Users/jan/Dev/jan/toyos-t14lan/target/metal/lantalkcase/image.img --readback /Users/jan/Dev/jan/toyos-t14lan/target/metal/lantalkcase --fat32-check --talk /Users/jan/Dev/jan/toyos-t14lan/target/metal/lantalkcase/ssh/id_ed25519`\n\ + toyos-metal: the boot did not say over its own cable what a talking boot owes:\n\ + \x20 217 line(s) arrived over the cable and none is this boot's `Boot: complete`\n"; + let said = Refusal::Talk(vec![ + "217 line(s) arrived over the cable and none is this boot's `Boot: complete`".into(), + ]); + assert_eq!(said_refusal(stderr), Some(said.to_string())); + assert_eq!(said_refusal(&stderr[..stderr.find(REFUSAL_HEAD).unwrap()]), None, "cargo's lines are no refusal"); + } + /// **An image with no bound on its own boot never reaches the stick.** /// /// The case, measured twice: a kernel that hung after its job list, and a diff --git a/src/metaltalk.rs b/src/metaltalk.rs index 2482d7e4214..862d281e6bf 100644 --- a/src/metaltalk.rs +++ b/src/metaltalk.rs @@ -49,6 +49,12 @@ pub const SSH_PORT: u16 = 22; const PING_TRIES: u32 = 10; const PING_WAIT: Duration = Duration::from_secs(1); +/// How long the stream gets to carry this boot's `Boot: complete` before +/// `reboot` is asked regardless, and the judge reds on the record's absence. A +/// liveness bound, inside the boot's own `boot-deadline=` that `reboot` has to +/// beat: the stream stalls only while netd retransmits what its NIC dropped. +const CARRIED_WAIT: Duration = Duration::from_secs(30); + /// How long one connect waits for the machine's answer to its SYN. const CONNECT_WAIT: Duration = Duration::from_secs(5); @@ -277,6 +283,12 @@ impl Stream { self.wait_until(by, |lines| lines.iter().any(|l| l.contains(needle)).then_some(())).is_some() } + /// This boot's `Boot: complete` in milliseconds, read as [`judge`] reads + /// it, once a line carries it, or `None` after `by`. + pub fn wait_for_boot(&self, by: Duration) -> Option { + self.wait_until(by, |lines| lines.iter().find_map(|line| crate::bootlog::boot_millis(line))) + } + /// The peer, once a connection has carried a line, or `None` after `by` /// or once the dial has given up. pub fn wait_connected(&self, by: Duration) -> Option { @@ -954,11 +966,30 @@ pub fn converse( Err(why) => println!(" talk: `{command}` was not answered: {why}"), } - let reboot = ssh.fire(ssh_at, REBOOT); + let reboot = hand_back(stream, began, CARRIED_WAIT, || ssh.fire(ssh_at, REBOOT)); println!(" talk: `{REBOOT}` {reboot:?}"); Ok(Conversation { peer, ping, exec, reboot, exec_ms, stream_end: stream.end() }) } +/// Ask for `reboot` through `fire` once the stream has carried this boot's +/// `Boot: complete`, or once `by` has passed without it. `reboot` ends the +/// stream the judge reads that record off, and `logd` serves the boot from its +/// first line, so the backlog crosses at the network's pace and not the +/// conversation's. +fn hand_back(stream: &Stream, began: Instant, by: Duration, fire: impl FnOnce() -> T) -> T { + match stream.wait_for_boot(by) { + Some(ms) => println!( + " talk: the stream carried `Boot: complete` ({ms} ms), {} ms after it opened", + began.elapsed().as_millis() + ), + None => println!( + " talk: the stream carried no `Boot: complete` in {} ms; `{REBOOT}` is asked regardless", + by.as_millis() + ), + } + fire() +} + /// The keys a conversation is written under, one ` ` per line, in /// the loop's readback beside the host's other facts. const PEER: &str = "talk_peer"; @@ -1439,6 +1470,41 @@ mod tests { ); } + /// **`reboot` is not asked while the stream is stalled short of + /// `Boot: complete`**: it waits out its bound, and the record ends the wait + /// as the judge reads it. The lines are the T14's: its `lantalkcase` stream + /// stopped at `xHCI: configuration set` when `reboot` outran it, and + /// `Boot: complete` was 72 lines further on. + #[test] + fn the_hand_back_waits_for_the_boot_record_the_judge_reads() { + const STALLED_AT: [&str; 2] = [ + "[2026-09-29 14:01:34 0.493 cpu0] xHCI: mass storage iface=0 in=0x81/512 out=0x2/512", + "[2026-09-29 14:01:34 0.493 cpu0] xHCI: configuration set", + ]; + const RECORD: &str = "[2026-09-29 14:01:35 1.166 cpu0] Boot: complete (1166ms)"; + let dir = toyos_tmpdir::TempDir::new("metaltalk-carried"); + let server = TcpListener::bind("127.0.0.1:0").unwrap(); + let at = server.local_addr().unwrap(); + let stream = Stream::connect(Peer::At(at), &dir.join("s.log"), false, Duration::from_secs(5)) + .expect("a loopback reader"); + let (mut conn, _) = server.accept().unwrap(); + for line in STALLED_AT { + writeln!(conn, "{line}").unwrap(); + } + assert!(stream.wait_for("configuration set", Duration::from_secs(5)), "the stalled lines were not read"); + let good = heard(Ok(Exec { stdout: owed(), status: Some(0) }), Ok("accepted".into())); + let bound = Duration::from_millis(100); + let began = Instant::now(); + let (waited, lines) = hand_back(&stream, began, bound, || (began.elapsed(), stream.lines())); + assert!(waited >= bound, "`reboot` was asked {waited:?} into a stall bounded at {bound:?}"); + assert!(judge(&good, &lines).is_err(), "the judge and the wait disagree on the stall"); + + writeln!(conn, "{RECORD}").unwrap(); + let lines = hand_back(&stream, Instant::now(), Duration::from_secs(5), || stream.lines()); + judge(&good, &lines).expect("`reboot` was asked before the stream carried the record"); + assert_eq!(stream.wait_for_boot(Duration::ZERO), Some(1166)); + } + /// The next connection `server` takes, or a panic naming `what` once a /// bound has passed with none: a reader that stopped dialing fails the test /// rather than hanging it. diff --git a/tests/common/metal.rs b/tests/common/metal.rs index c455b7a5157..dbf3c96ddf1 100644 --- a/tests/common/metal.rs +++ b/tests/common/metal.rs @@ -16,9 +16,10 @@ use std::cell::RefCell; use std::collections::btree_map::Entry; use std::collections::{BTreeMap, BTreeSet}; +use std::io::{BufRead, BufReader}; use std::num::NonZeroUsize; use std::path::{Path, PathBuf}; -use std::process::Command; +use std::process::{Command, Stdio}; use toyos_build::bootlog; use toyos_build::metalimage; @@ -799,6 +800,33 @@ fn invocation(image: &Path, home: &Path, nic: Option<&str>, talk: bool) -> Vec Result<(), String> { + let mut child = Command::new("cargo") + .args(words) + .current_dir(root) + .stderr(Stdio::piped()) + .spawn() + .map_err(|e| format!("toyos-metal could not be started: {e}"))?; + let mut stderr = BufReader::new(child.stderr.take().expect("stderr was asked for piped")); + let (mut said, mut line) = (String::new(), Vec::new()); + while stderr.read_until(b'\n', &mut line).map_err(|e| format!("toyos-metal's stderr: {e}"))? > 0 { + let text = String::from_utf8_lossy(&line); + eprint!("{text}"); + said.push_str(&text); + line.clear(); + } + let status = child.wait().map_err(|e| format!("toyos-metal: {e}"))?; + if status.success() { + return Ok(()); + } + Err(match toyos_build::metal::said_refusal(&said) { + Some(refusal) => format!("toyos-metal exited {status}: {refusal}"), + None => format!("toyos-metal exited {status} and said no refusal"), + }) +} + pub fn read_readback(dir: &Path, label: &str) -> Result { let home = at(dir, label); let read = |name: &str| -> Result { @@ -958,15 +986,8 @@ pub fn run( for (label, image) in &images { let words = invocation(image, &at(dir, label), batches[*label].nic, batches[*label].talk); eprintln!("[metal] {label}: cargo {}", words.join(" ")); - let booted = Command::new("cargo").args(&words).current_dir(&root).status(); - match booted { - Ok(status) if status.success() => {} - Ok(status) => { - refused.insert(label, format!("toyos-metal exited {status}")); - } - Err(e) => { - refused.insert(label, format!("toyos-metal could not be started: {e}")); - } + if let Err(why) = drive(&root, &words) { + refused.insert(label, why); } } } From b41440553e2d16449a16b396e40deae959066901 Mon Sep 17 00:00:00 2001 From: japabu Date: Sat, 3 Oct 2026 00:04:26 +0200 Subject: [PATCH 15/19] Every ceiling of the 26-test suite is at most three times its test's slowest run Five whole runs of `cargo test --test toyos-build` at bf28c1e38, 12 wide on the dev host at load average 40 to 59 on 14 cores (guest-m2..m6 in the orchestrator's scratchpad): 26, 25, 26, 26 and 26 passed, in 229.2, 66.8, 37.1, 32.9 and 34.1 s. The slowest pass of each test, in seconds: iommu_virtio_platform 47 virt_first_entry 14 machine_shutdown 20 virt_fp_isolation 14 nested_nmi_is_loud 21 virt_irq_storm 12 screen_fatal_behind_a_painter 29 virt_mask_windows 8 screen_fatal_halt_composited 32 virt_off_names_the_cpus_left_on 16 screen_panic_muted 19 virt_readonly_copyout 18 virt_debug_refused 18 virt_reboot 8 virt_early_fault 2 virt_reboot_refused_without_psci 8 virt_early_panic 2 virt_smp 10 virt_el1_smp 10 virt_timer_floor 9 virt_el2_drop 7 virt_timer_preempts 29 virt_failed_ap_leaves_no_hole 15 virt_unmap_touch 18 virt_fatal_halts_the_others_first 34 virt_user_mode 10 The numbers, each three times the slowest test that waits through it: - BOOT_CEILING 63: nested_nmi_is_loud, the slowest test that is one boot and nothing after it (21). main's was 10 s times the width, 120 s. - GUEST_WEDGED 141, now paid out through `budget`: every wait through `await_guest`, the slowest of which is iommu_virtio_platform (47). `guest_liveness` had one caller and goes. - virt_selftest's drain 36, was 180: virt_irq_storm (12) and virt_timer_floor (9). - virt_user_mode's drain 30, was 180 (10). - virt_early_panic's and virt_early_fault's two waits 6 each, were 30 and 10 (2 each). - screen_fatal_behind_a_painter's second wait 87, was 20, and screen_fatal_halt_composited's first 96, was 30: each sat under its own test's slowest run (29 and 32) and passed on main only because the width multiplied it twelvefold. - Kept, at or above their test's slowest run and under three times it: screen_panic_muted 30 (19), virt_el2_drop 10 (7), the painter's first wait 30 (29), the composited test's second 40 (32). REFERENCE_BOOT_MS is 1424, the largest fastest boot of the five runs (1419, 1424, 1048, 1055, 750 ms), so the measuring host pays every ceiling at 1x. The red of the second run is virt_mask_windows, on an assertion and not a ceiling: nine census lines and eight windows lines for cpu7. The test, the kernel and its judge are main's. Filed as issues/build/virt-mask-windows-read-nine-censuses-and-eight-windows-lines-for-one-cpu.md. The first run after the merge exited 1 with 18 reds before any of these: twelve threads moved the fork checkout to the new pin at once. Filed as issues/build/a-suites-first-run-after-the-fork-pin-moves-races-its-own-checkout.md. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm --- ...e-fork-pin-moves-races-its-own-checkout.md | 36 ++++++++++++++++ ...ses-and-eight-windows-lines-for-one-cpu.md | 41 +++++++++++++++++++ tests/common/qemu.rs | 17 ++++---- tests/toyos.rs | 16 ++++---- 4 files changed, 92 insertions(+), 18 deletions(-) create mode 100644 issues/build/a-suites-first-run-after-the-fork-pin-moves-races-its-own-checkout.md create mode 100644 issues/build/virt-mask-windows-read-nine-censuses-and-eight-windows-lines-for-one-cpu.md diff --git a/issues/build/a-suites-first-run-after-the-fork-pin-moves-races-its-own-checkout.md b/issues/build/a-suites-first-run-after-the-fork-pin-moves-races-its-own-checkout.md new file mode 100644 index 00000000000..8685a5bbfa8 --- /dev/null +++ b/issues/build/a-suites-first-run-after-the-fork-pin-moves-races-its-own-checkout.md @@ -0,0 +1,36 @@ +--- +status: open +kind: tooling +opened: 2026-10-02 +--- + +# A suite's first run after the fork pin moves races its own checkout + +`sysroot::fork_checkout` (`src/sysroot.rs`) moves a linked worktree's `rust/` +to the commit the tree pins when the checkout is behind it, with +`git checkout --detach`. The guest suite boots its tests on twelve threads and +each reaches `fork_checkout` on its own, so the first run after a merge that +moved the gitlink runs that checkout in every thread at once. + +## Measured + +A worktree at `bf28c1e38` whose `rust/` stood at `c4c65e3e8` under a pin of +`95960d6c2`, after a merge of `origin/main`: `cargo test --test toyos-build` +exited 1 with 18 of 26 red in 177 s. Every red is one of two sentences. One is +`git ["checkout", "--detach", "-q", "95960d6c2…"] in …/rust failed`, under +git's `Unable to create '…/modules/rust/worktrees/rust1/index.lock': File +exists`. The other is `…/rust is at c4c65e3e8… with uncommitted work`, from a +thread that read the checkout's status while another thread was moving it. The +checkout ended at the pin, and the next run of the same command did not repeat +either. + +## Owner + +Whoever next changes `sysroot::fork_checkout`. + +## What would close it + +One mover: the checkout is moved under a lock every thread of the process +takes, or once before the suite starts its workers, and +`cargo test --test toyos-build` on a worktree whose checkout is behind its pin +moves it and boots its tests. diff --git a/issues/build/virt-mask-windows-read-nine-censuses-and-eight-windows-lines-for-one-cpu.md b/issues/build/virt-mask-windows-read-nine-censuses-and-eight-windows-lines-for-one-cpu.md new file mode 100644 index 00000000000..db4911a6be6 --- /dev/null +++ b/issues/build/virt-mask-windows-read-nine-censuses-and-eight-windows-lines-for-one-cpu.md @@ -0,0 +1,41 @@ +--- +status: open +kind: defect +opened: 2026-10-03 +--- + +# `virt_mask_windows` read nine census lines and eight windows lines for one CPU + +`virt_mask_windows` (`tests/toyos.rs`) judges the capture `judge_virt_job` +answers, which ends where `===TEST_END unmap_touch` arrived, with +`irqcensus::windows`: every `irq: cpu` census line has its CPU's windows line +beside it. + +## Measured + +A whole guest suite at `bf28c1e38`, whose `virt_mask_windows`, kernel and +`tests/common/irqcensus.rs` are `origin/main`'s at `c59e09ed6`: +`cargo test --test toyos-build`, 12 wide on the 14-core dev host at load +average 43 to 59, exited 1 with this one red in 66.8 s: + +``` +FAIL virt_mask_windows: census lines per cpu {0: 9, 1: 9, 2: 9, 3: 9, 4: 9, 5: 9, 6: 9, 7: 9} and windows lines per cpu {0: 9, 1: 9, 2: 9, 3: 9, 4: 9, 5: 9, 6: 9, 7: 8}: a census went out without its windows, or windows without their census + FAIL virt_mask_windows (10s) +``` + +The whole run before it and the one after it, same tree and same command, +passed it in 8 s and 7 s. The PL011 capture of the red was not kept: the run's +`target/red-run-serial` holds the x86-64 guests' 16550 logs only. + +Two candidates, neither measured: the capture ends at the marker with cpu7's +last windows line still behind it, or the kernel printed a census without its +windows. + +## Owner + +The windows instrument's author (`issues/kernel/the-kernel-is-small-interrupts-post-and-threads-wait.md`). + +## What would close it + +The cause, from a capture of a red: either the judge reads a capture that ends +on a whole report, or the kernel's report is shown to pair its two lines. diff --git a/tests/common/qemu.rs b/tests/common/qemu.rs index b69c29de594..23f4774147d 100644 --- a/tests/common/qemu.rs +++ b/tests/common/qemu.rs @@ -174,7 +174,7 @@ static FASTEST_BOOT_MS: AtomicU32 = AtomicU32::new(u32::MAX); /// The fastest boot of the host the ceilings were measured on: at or above the /// fastest boot of every run a ceiling in this tree was measured in, so that /// host pays them at 1×. -const REFERENCE_BOOT_MS: u32 = 1320; +const REFERENCE_BOOT_MS: u32 = 1424; fn record_boot(took: Duration) { let ms = took.as_millis().min(u32::MAX as u128) as u32; @@ -371,12 +371,9 @@ pub const GUEST_QUIET: Duration = Duration::from_secs(15); /// /// The compositor prints its interval line whatever else has stopped, so /// silence alone cannot end a desktop wait, and a suite that never ends is -/// worse than one that reds. -pub const GUEST_WEDGED: Duration = Duration::from_secs(300); - -pub fn guest_liveness() -> Liveness { - Liveness::new(GUEST_QUIET, GUEST_WEDGED) -} +/// worse than one that reds. [`budget_smp`]'s rule over the tests that wait +/// through [`await_guest`]. +pub const GUEST_WEDGED: Duration = Duration::from_secs(141); /// A kernel line without its `[kernel cpu] ` stamp. fn without_stamp(line: &str) -> &str { @@ -555,7 +552,7 @@ pub fn await_guest( ) -> Result<(), String> { // Where this wait's own evidence starts. let from = log.len(); - let mut live = guest_liveness(); + let mut live = Liveness::new(GUEST_QUIET, qemu.budget(GUEST_WEDGED)); while !done(log) && live.working(log) { let more = qemu.drain_serial(Duration::from_millis(200)); log.push_str(&more); @@ -2312,8 +2309,8 @@ fn publish_line( } /// A boot's ceiling: [`budget_smp`]'s rule over the tests that are one boot and -/// one trivial command. -pub const BOOT_CEILING: Duration = Duration::from_secs(30); +/// nothing after it. +pub const BOOT_CEILING: Duration = Duration::from_secs(63); /// Returns every line seen on the way to the marker — see [`QemuInstance::boot_log`]. fn wait_for_ready( diff --git a/tests/toyos.rs b/tests/toyos.rs index b790af2dc36..86c9c6e5e65 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -1765,7 +1765,7 @@ fn virt_selftest( }, ); let said = format!("{param}: "); - let rest = qemu.drain_until(Duration::from_secs(180), |l| l.contains(&said)); + let rest = qemu.drain_until(Duration::from_secs(36), |l| l.contains(&said)); let serial = format!("{}\n{rest}", qemu.boot_log()); let Some(verdict) = serial.lines().find(|l| l.contains(&said)) else { return Err(format!("{param} never reported\nserial:\n{serial}")); @@ -1855,8 +1855,8 @@ fn run_screen_test(name: &str, profile: qemu::Profile, test_config: &Path) -> Re ..Default::default() }, ); - let dump = qemu.screendump_until("EARLY PANIC:", Duration::from_secs(30)); - let rest = qemu.drain_until(Duration::from_secs(10), |l| l.contains(EARLY_PANIC_MESSAGE)); + let dump = qemu.screendump_until("EARLY PANIC:", Duration::from_secs(6)); + let rest = qemu.drain_until(Duration::from_secs(6), |l| l.contains(EARLY_PANIC_MESSAGE)); let serial = format!("{}\n{rest}", qemu.boot_log()); // What stage 3 prints before it panics: every item is a record // only the AArch64 side of the loader or the kernel writes. @@ -1947,9 +1947,9 @@ fn run_screen_test(name: &str, profile: qemu::Profile, test_config: &Path) -> Re ..Default::default() }, ); - let dump = qemu.screendump_until("EARLY PANIC:", Duration::from_secs(30)); + let dump = qemu.screendump_until("EARLY PANIC:", Duration::from_secs(6)); const FAULT_MESSAGE: &str = "synchronous from EL1 on SP_EL1: unknown reason (an undefined instruction) at 0x"; - let rest = qemu.drain_until(Duration::from_secs(10), |l| l.contains(FAULT_MESSAGE)); + let rest = qemu.drain_until(Duration::from_secs(6), |l| l.contains(FAULT_MESSAGE)); let serial = format!("{}\n{rest}", qemu.boot_log()); for want in [ "KERNEL PANIC: synchronous from EL1 on SP_EL1: unknown reason (an undefined instruction)", @@ -1985,7 +1985,7 @@ fn run_screen_test(name: &str, profile: qemu::Profile, test_config: &Path) -> Re }, ); const SPAWNED: &str = "spawn: /system/bin/logd pid="; - let rest = qemu.drain_until(Duration::from_secs(180), |l| l.contains(SPAWNED)); + let rest = qemu.drain_until(Duration::from_secs(30), |l| l.contains(SPAWNED)); let serial = format!("{}\n{rest}", qemu.boot_log()); for want in [ "paging: the direct map holds memory below", @@ -2074,7 +2074,7 @@ fn run_screen_test(name: &str, profile: qemu::Profile, test_config: &Path) -> Re } // The pager runs only on the CPU that claimed the panel, and it is // the loop that watches the reset bound: a second page is its proof. - let paged = qemu.screendump_while(Duration::from_secs(20), Duration::from_millis(200), |d| { + let paged = qemu.screendump_while(Duration::from_secs(87), Duration::from_millis(200), |d| { d.rows().iter().any(|r| r.contains("[page ")) && d.text() != text }); if paged.text() == text { @@ -2116,7 +2116,7 @@ fn run_screen_test(name: &str, profile: qemu::Profile, test_config: &Path) -> Re // anything else is userland holding the panel. Without this the // test would prove that a fatal panic paints a screen nobody had // taken. - let up = qemu.screendump_while(Duration::from_secs(30), Duration::from_millis(200), |d| { + let up = qemu.screendump_while(Duration::from_secs(96), Duration::from_millis(200), |d| { d.fill() != FILL_BOOT }); if up.fill() == FILL_BOOT { From 4859e8d71ca8004afd17a3b5fd0f0e6dfb3fe911 Mon Sep 17 00:00:00 2001 From: japabu Date: Sat, 3 Oct 2026 00:27:01 +0200 Subject: [PATCH 16/19] issues: the fork-pin race is opened on the day its commit carries Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm --- ...first-run-after-the-fork-pin-moves-races-its-own-checkout.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/issues/build/a-suites-first-run-after-the-fork-pin-moves-races-its-own-checkout.md b/issues/build/a-suites-first-run-after-the-fork-pin-moves-races-its-own-checkout.md index 8685a5bbfa8..f72602fd212 100644 --- a/issues/build/a-suites-first-run-after-the-fork-pin-moves-races-its-own-checkout.md +++ b/issues/build/a-suites-first-run-after-the-fork-pin-moves-races-its-own-checkout.md @@ -1,7 +1,7 @@ --- status: open kind: tooling -opened: 2026-10-02 +opened: 2026-10-03 --- # A suite's first run after the fork pin moves races its own checkout From 4b009e712994bd6fd2ab45bf5a0191ce19fffde1 Mon Sep 17 00:00:00 2001 From: japabu Date: Sat, 3 Oct 2026 01:50:16 +0200 Subject: [PATCH 17/19] Going down is a dial given ssh's own connect; the refusal-wait goes; the shared boots' allowances are named Round 4's review of 4859e8d71 (#638): - metal: `wait_on` dials the port within CONNECT_SECS when it watches the machine go down, what `ssh`'s own ConnectTimeout gives, and within one POLL coming back. A single lost SYN while Ubuntu is still up no longer reads as down. `coming_back_is_ssh_answering_and_not_its_port` records the dial it is handed going down. - metal: the wait for `ssh` after a refusal that followed `reboot`, and `after_the_reboot`'s split, are deleted. No recorded run has the case it was for: the T14 run the body cited timed out on the boot after a pass, and the post-reboot refusals in the kept T14 logs are a machine that never came back, a stick, a ping and a mount, each with the machine already answering or already waited out. `run` is main's again past `bootnext`. - toyos-tco: `RUST_MEMBER_MS` (860) and `C_MEMBER_MS` (260) beside `JOB_BOUND_MS`; `metal::members_fitting` derives `shared`'s and `ccorpus`'s member counts from them, 62 and 207 as before. `shared-debug` keeps main's 18: on a five-member list the count moves nothing. - qemu: `VERDICT_POLL` is the read loop's poll, and the ceiling walk in `tests/checks/qemu.rs` steps by it. - metaltalk: two comments deleted. - issues: owners for the fork-pin race (the tooling track's toolchain stage), the hard-lockup bound's reader (the T14 unattended track, which holds the detector) and the I219 transmit burst (the LAN track's stage 2); the `virt_mask_windows` red moves to `issues/kernel/`; filed: `run_test` and `ceiling_verdict` serve only `--debug`'s `run`, and `host_scale` reads host speed off boots that stop at different markers (491 ms for `virt_early_panic` alone, 3318 ms for `machine_shutdown` alone, same host, same minute). Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm --- ...e-fork-pin-moves-races-its-own-checkout.md | 3 +- ...s-read-by-nothing-but-its-own-assertion.md | 3 +- ...ff-boots-that-stop-at-different-markers.md | 41 +++++++++ ...s-ceiling-verdict-serve-only-debugs-run.md | 36 ++++++++ ...19-drops-a-transmit-burst-past-its-ring.md | 5 ++ ...ses-and-eight-windows-lines-for-one-cpu.md | 0 src/metal.rs | 89 ++++++++----------- src/metaltalk.rs | 6 +- tests/checks/qemu.rs | 4 +- tests/common/metal.rs | 7 ++ tests/common/qemu.rs | 6 +- tests/toyos.rs | 6 +- toyos-tco/src/lib.rs | 5 ++ 13 files changed, 148 insertions(+), 63 deletions(-) create mode 100644 issues/build/host-scale-reads-host-speed-off-boots-that-stop-at-different-markers.md create mode 100644 issues/build/run-test-and-its-ceiling-verdict-serve-only-debugs-run.md rename issues/{build => kernel}/virt-mask-windows-read-nine-censuses-and-eight-windows-lines-for-one-cpu.md (100%) diff --git a/issues/build/a-suites-first-run-after-the-fork-pin-moves-races-its-own-checkout.md b/issues/build/a-suites-first-run-after-the-fork-pin-moves-races-its-own-checkout.md index f72602fd212..8b91d121ed9 100644 --- a/issues/build/a-suites-first-run-after-the-fork-pin-moves-races-its-own-checkout.md +++ b/issues/build/a-suites-first-run-after-the-fork-pin-moves-races-its-own-checkout.md @@ -26,7 +26,8 @@ either. ## Owner -Whoever next changes `sysroot::fork_checkout`. +The toolchain stage of +`issues/build/the-tooling-is-a-review-prompt-and-three-workflows.md`. ## What would close it diff --git a/issues/build/hard-lockup-bound-ms-is-read-by-nothing-but-its-own-assertion.md b/issues/build/hard-lockup-bound-ms-is-read-by-nothing-but-its-own-assertion.md index e998f56eff1..b3b0e5edb03 100644 --- a/issues/build/hard-lockup-bound-ms-is-read-by-nothing-but-its-own-assertion.md +++ b/issues/build/hard-lockup-bound-ms-is-read-by-nothing-but-its-own-assertion.md @@ -19,7 +19,8 @@ alone. ## Owner -Whoever next changes `toyos-tco`. +`issues/hardware/the-t14-boots-toyos-unattended.md`, the track that holds the +hard-lockup detector and its bound. ## What would close it diff --git a/issues/build/host-scale-reads-host-speed-off-boots-that-stop-at-different-markers.md b/issues/build/host-scale-reads-host-speed-off-boots-that-stop-at-different-markers.md new file mode 100644 index 00000000000..62d10d195d8 --- /dev/null +++ b/issues/build/host-scale-reads-host-speed-off-boots-that-stop-at-different-markers.md @@ -0,0 +1,41 @@ +--- +status: open +kind: tooling +opened: 2026-10-03 +--- + +# `host_scale` reads host speed off boots that stop at different markers + +`budget_smp` (`tests/common/qemu.rs`) pays a ceiling out for a slower host by +`host_scale`: the run's fastest boot against `REFERENCE_BOOT_MS`, 1424 ms. +`record_boot` takes each boot's time to its own ready marker, and those differ: +`virt_early_panic`'s and `virt_early_fault`'s is `EARLY PANIC:`, which the +kernel prints before userland, and an x86-64 boot's is `===READY===`, after it. +So the scale says which boots a run held, not how fast the host is: a run with +an early-panic boot in it pays 1× on nearly any host, and with the suite's +width no longer multiplying a ceiling, `host_scale` and `oversubscription` are +the only host corrections `budget_smp` makes. + +## Measured + +On the dev host at load average 3.7 to 3.4, one run after the other on PR +#638's tree: + +| command | its fastest boot | scale | +|---|---|---| +| `cargo test --test toyos-build -- virt_early_panic` | 491 ms | 1.00× | +| `cargo test --test toyos-build -- machine_shutdown` | 3318 ms | 2.33× | + +The whole suite at `4859e8d71`, 12 wide on the same host, read 502 ms and paid +1.00×. + +## Owner + +`issues/build/the-tooling-is-a-review-prompt-and-three-workflows.md`, whose +harness item keeps a piece of the harness only where it sees what reading +cannot. + +## What would close it + +`host_scale` reads only boots that stop at one marker on every host, or it is +deleted with `budget_smp`'s promise of it. diff --git a/issues/build/run-test-and-its-ceiling-verdict-serve-only-debugs-run.md b/issues/build/run-test-and-its-ceiling-verdict-serve-only-debugs-run.md new file mode 100644 index 00000000000..085aff79e40 --- /dev/null +++ b/issues/build/run-test-and-its-ceiling-verdict-serve-only-debugs-run.md @@ -0,0 +1,36 @@ +--- +status: open +kind: tooling +opened: 2026-10-03 +--- + +# `run_test` and its ceiling verdict serve only `--debug`'s `run` + +`QemuInstance::run_test`, `run_test_hooked` and `run_test_paced` +(`tests/common/qemu.rs`), and `ceiling_verdict`, the verdict their read loop +ends a wait on, have one caller: interactive debug mode's `run ` +(`tests/toyos.rs`, `qemu.run_test(test_name, Duration::from_secs(60))`). Every +guest test of the suite waits through `await_guest`, `drain_until` or a +screendump wait instead. So the checks that hold `ceiling_verdict` to its arms +(`tests/checks/qemu.rs`, and `a_stall_stays_red` in `tests/checks.rs`) and the +`run_test` shape `driven_binaries` reads (`tests/checks.rs`) guard that one +path. + +## Measured + +`git grep -c 'run_test(\|run_test_hooked(\|run_test_paced(' -- tests/toyos.rs tests/common` +counts 40 lines in `tests/toyos.rs` and 34 across sixteen other `tests/common` +modules at `06788146b^`, and one in `tests/toyos.rs`, the debug loop's, at +`06788146b`, the commit that cut the guest suite; the five in +`tests/common/qemu.rs` are the three functions' own. + +## Owner + +`issues/build/the-guest-suite-runs-only-what-no-cheaper-tier-reaches.md`, whose +first cut left them that one caller. + +## What would close it + +`--debug`'s `run` reads its test through a wait the suite uses, and +`run_test`, `run_test_hooked`, `run_test_paced`, `ceiling_verdict` and the +checks and readers that exist for them are deleted. diff --git a/issues/hardware/netds-i219-drops-a-transmit-burst-past-its-ring.md b/issues/hardware/netds-i219-drops-a-transmit-burst-past-its-ring.md index 36771578727..b78cdd09eb4 100644 --- a/issues/hardware/netds-i219-drops-a-transmit-burst-past-its-ring.md +++ b/issues/hardware/netds-i219-drops-a-transmit-burst-past-its-ring.md @@ -28,6 +28,11 @@ stopped at the same 217th line, with 595 ms between the admit and the stop windows are shorter than the first retransmit timeout. The same count appears on the `lanswapcase` boot: 11, 18 and 23 frames dropped. +## Owner + +Stage 2 of `issues/hardware/the-lan-is-not-yet-production-grade.md`, a gigabit +driver that holds. + ## Exit `transmit` answers `None` when no descriptor is free, and a descriptor coming diff --git a/issues/build/virt-mask-windows-read-nine-censuses-and-eight-windows-lines-for-one-cpu.md b/issues/kernel/virt-mask-windows-read-nine-censuses-and-eight-windows-lines-for-one-cpu.md similarity index 100% rename from issues/build/virt-mask-windows-read-nine-censuses-and-eight-windows-lines-for-one-cpu.md rename to issues/kernel/virt-mask-windows-read-nine-censuses-and-eight-windows-lines-for-one-cpu.md diff --git a/src/metal.rs b/src/metal.rs index 490c82697e6..372cffa8acc 100644 --- a/src/metal.rs +++ b/src/metal.rs @@ -1413,7 +1413,7 @@ impl Driver { secs, what, answering, - || port_accepts(host, crate::metaltalk::SSH_PORT), + |within| port_accepts(host, crate::metaltalk::SSH_PORT, within), || self.ssh("probing", "true").is_ok(), ) } @@ -1494,21 +1494,25 @@ impl Driver { } } -/// Poll once a [`POLL`] whether a port `accepts`, and say how long the machine -/// took to answer as asked. **Coming back is `ssh` itself answering**: a port -/// that accepts is only asked whether `ssh` `answers`, since a listener can come -/// up before the service behind it. +/// Poll once a [`POLL`] whether a port `accepts` a dial bounded by what it is +/// handed, and say how long the machine took to answer as asked. **Coming back +/// is `ssh` itself answering**: a port that accepts is only asked whether `ssh` +/// `answers`, since a listener can come up before the service behind it. +/// **Going down is a dial refused or unanswered for [`CONNECT_SECS`]**, what +/// `ssh`'s own connect is given: a SYN lost while Ubuntu is still up would +/// otherwise read as down, and the stick be read before ToyOS booted it. fn wait_on( secs: u64, what: &'static str, answering: bool, - mut accepts: impl FnMut() -> bool, + mut accepts: impl FnMut(std::time::Duration) -> bool, mut answers: impl FnMut() -> bool, ) -> Result { + let dial = if answering { POLL } else { std::time::Duration::from_secs(CONNECT_SECS) }; let began = std::time::Instant::now(); while began.elapsed().as_secs() < secs { let next = std::time::Instant::now() + POLL; - let listening = accepts(); + let listening = accepts(dial); let answered = listening && (!answering || answers()); if answered == answering { return Ok(began.elapsed().as_secs()); @@ -1518,14 +1522,14 @@ fn wait_on( Err(Refusal::Silent { what, secs }) } -/// Whether `host`'s `port` accepts a connection inside one [`POLL`]; a name -/// that does not resolve is a machine that is not there. -fn port_accepts(host: &str, port: u16) -> bool { +/// Whether `host`'s `port` accepts a connection `within`; a name that does not +/// resolve is a machine that is not there. +fn port_accepts(host: &str, port: u16, within: std::time::Duration) -> bool { use std::net::ToSocketAddrs; let Ok(mut addrs) = (host, port).to_socket_addrs() else { return false; }; - addrs.any(|addr| std::net::TcpStream::connect_timeout(&addr, POLL).is_ok()) + addrs.any(|addr| std::net::TcpStream::connect_timeout(&addr, within).is_ok()) } fn unstarted(what: &str, e: &std::io::Error) -> Refusal { @@ -2011,45 +2015,19 @@ pub fn run(args: &Args) -> Result, Refusal> { let entry = driver.boot_entry(&image.esp)?; driver.as_root("setting bootnext", Job::BootNext, Some(&entry), None)?; - let rebooted = driver.as_root("rebooting", Job::Reboot, None, None); + driver.as_root("rebooting", Job::Reboot, None, None)?; if driver.dry_run { - rebooted?; driver.as_root("mounting the log partition", Job::Mount, None, None)?; driver.as_root("unmounting the log partition", Job::Umount, None, None)?; println!("dry run: nothing was written and the machine was not rebooted"); return Ok(None); } - let judged = rebooted.and_then(|_| { - after_the_reboot(&driver, args, &image, &armed, &machine, cable.as_ref(), wire.as_ref()) - }); - // **A refusal after `reboot` can leave the machine on its way back**, and - // the next invocation's first `ssh` would then refuse a boot that never - // happened. One the machine was already waited out for is not waited again. - if let Err(refused) = &judged { - if !matches!(refused, Refusal::Silent { .. }) { - if let Err(silent) = driver.wait(args.wait_secs, "come back", true) { - println!("after that refusal, {silent}"); - } - } - } - judged -} -/// Everything from the machine going down to the boot's verdict. -fn after_the_reboot( - driver: &Driver, - args: &Args, - image: &Flashable, - armed: &[String], - machine: &Machine, - cable: Option<&Talking>, - wire: Option<&Wire>, -) -> Result, Refusal> { // The conversation runs while the loop watches the machine come back; its // `reboot` is what brings it back before the boot's own hold does. let mut talking = None; - let ridden = driver.ride_the_reboot(args.wait_secs, wire.map(|w| w.addr), || { - if let Some(cable) = cable { + let ridden = driver.ride_the_reboot(args.wait_secs, wire.as_ref().map(|w| w.addr), || { + if let Some(cable) = &cable { talking = Some(cable.start(std::time::Duration::from_secs(args.wait_secs))); } }); @@ -2077,7 +2055,7 @@ fn after_the_reboot( }; let (back, replied) = ridden?; println!("the machine answered ssh again after {back} s"); - if let Some(wire) = wire { + if let Some(wire) = &wire { match replied { Some(reply) => println!( "{} answered a ping {} s into the window, after {PING_SILENCE_SECS} s of \ @@ -2112,8 +2090,8 @@ fn after_the_reboot( } println!("toyos-fat32-check: the log partition's {} bytes check out", bytes.len()); } - let boot = boot_file(back, stick, machine, wire, replied); - judge_and_write_readback(armed, &loader, &log, heard.as_ref(), args.readback.as_deref(), &boot) + let boot = boot_file(back, stick, &machine, wire.as_ref(), replied); + judge_and_write_readback(&armed, &loader, &log, heard.as_ref(), args.readback.as_deref(), &boot) .map(Some) } @@ -2603,15 +2581,16 @@ mod tests { } /// **A port that accepts is not a machine that came back**, and a machine - /// going down is its port refusing. Staged through [`port_accepts`] on a - /// listener of this host's own, which accepts and never speaks `ssh`, and on - /// port 0, which nothing listens on: a port the listener let go of can be - /// another socket's by the time it is dialled. + /// going down is its port refusing a dial given what `ssh`'s own connect is. + /// Staged through [`port_accepts`] on a listener of this host's own, which + /// accepts and never speaks `ssh`, and on port 0, which nothing listens on: + /// a port the listener let go of can be another socket's by the time it is + /// dialled. #[test] fn coming_back_is_ssh_answering_and_not_its_port() { let listener = std::net::TcpListener::bind("127.0.0.1:0").expect("a loopback listener"); let port = listener.local_addr().expect("its address").port(); - let accepts = || port_accepts("127.0.0.1", port); + let accepts = |within| port_accepts("127.0.0.1", port, within); let mut asked = 0; let back = wait_on(1, "come back", true, accepts, || { asked += 1; @@ -2620,9 +2599,19 @@ mod tests { assert_eq!(back, Err(Refusal::Silent { what: "come back", secs: 1 })); assert!(asked > 0, "`ssh` was never asked of a port that accepts"); assert_eq!(wait_on(1, "come back", true, accepts, || true), Ok(0)); - let up = wait_on(1, "go down", false, accepts, || unreachable!("`ssh` asked of one going down")); + let mut dialled = Vec::new(); + let dial = |within| { + dialled.push(within); + accepts(within) + }; + let up = wait_on(1, "go down", false, dial, || unreachable!("`ssh` asked of one going down")); assert_eq!(up, Err(Refusal::Silent { what: "go down", secs: 1 })); - let refuses = || port_accepts("127.0.0.1", 0); + let connect = std::time::Duration::from_secs(CONNECT_SECS); + assert!( + !dialled.is_empty() && dialled.iter().all(|&within| within == connect), + "going down dialled within {dialled:?}, where `ssh`'s own connect is given {connect:?}" + ); + let refuses = |within| port_accepts("127.0.0.1", 0, within); assert_eq!(wait_on(1, "go down", false, refuses, || unreachable!()), Ok(0)); } diff --git a/src/metaltalk.rs b/src/metaltalk.rs index 862d281e6bf..802a6fee3a8 100644 --- a/src/metaltalk.rs +++ b/src/metaltalk.rs @@ -52,7 +52,7 @@ const PING_WAIT: Duration = Duration::from_secs(1); /// How long the stream gets to carry this boot's `Boot: complete` before /// `reboot` is asked regardless, and the judge reds on the record's absence. A /// liveness bound, inside the boot's own `boot-deadline=` that `reboot` has to -/// beat: the stream stalls only while netd retransmits what its NIC dropped. +/// beat. const CARRIED_WAIT: Duration = Duration::from_secs(30); /// How long one connect waits for the machine's answer to its SYN. @@ -1472,9 +1472,7 @@ mod tests { /// **`reboot` is not asked while the stream is stalled short of /// `Boot: complete`**: it waits out its bound, and the record ends the wait - /// as the judge reads it. The lines are the T14's: its `lantalkcase` stream - /// stopped at `xHCI: configuration set` when `reboot` outran it, and - /// `Boot: complete` was 72 lines further on. + /// as the judge reads it. #[test] fn the_hand_back_waits_for_the_boot_record_the_judge_reads() { const STALLED_AT: [&str; 2] = [ diff --git a/tests/checks/qemu.rs b/tests/checks/qemu.rs index cea8d8dfc0b..616472f932d 100644 --- a/tests/checks/qemu.rs +++ b/tests/checks/qemu.rs @@ -197,9 +197,7 @@ pub fn ceiling_self_check() -> Result<(), String> { )); } const SHORT: Duration = Duration::from_secs(5); - // What the read loop polls a silent guest at. - const STEP: Duration = Duration::from_millis(100); - let every = || (0..).map(|n| STEP * n); + let every = || (0..).map(|n| VERDICT_POLL * n); let first = |dying: Option<&str>, from: Duration| { every().find_map(|quiet| ceiling_verdict(dying, from + quiet, SHORT, quiet, 40)) }; diff --git a/tests/common/metal.rs b/tests/common/metal.rs index dbf3c96ddf1..aadefabdf8a 100644 --- a/tests/common/metal.rs +++ b/tests/common/metal.rs @@ -116,6 +116,13 @@ pub struct SharedBoot { pub links: Vec<(String, String)>, } +/// How many members allowed `allowance_ms` each one shared boot holds: the +/// runner's [`toyos_tco::JOB_BOUND_MS`] less a tenth of it, shared among them. +pub const fn members_fitting(allowance_ms: u64) -> NonZeroUsize { + let members = (toyos_tco::JOB_BOUND_MS - toyos_tco::JOB_BOUND_MS / 10) / allowance_ms; + NonZeroUsize::new(members as usize).expect("a chunk holds a member") +} + /// The name of one chunk of a boot that had to be cut in two. fn chunk_name(boot: &str, index: usize) -> String { if index == 0 { diff --git a/tests/common/qemu.rs b/tests/common/qemu.rs index 23f4774147d..0b7917e87d4 100644 --- a/tests/common/qemu.rs +++ b/tests/common/qemu.rs @@ -469,6 +469,10 @@ impl std::fmt::Display for WaitVerdict { } } +/// How often a test's read loop asks [`ceiling_verdict`] about a guest that +/// has said nothing since it last asked. +pub const VERDICT_POLL: Duration = Duration::from_millis(100); + /// What a test's ceiling caught — the panic, the stall, or the slow test. /// /// `dying` is the line on which the kernel said it was dying, if it ever did, @@ -1568,7 +1572,7 @@ impl QemuInstance { }; } - match self.rx.recv_timeout(Duration::from_millis(100)) { + match self.rx.recv_timeout(VERDICT_POLL) { Ok(line) => { last_line = Instant::now(); lines += 1; diff --git a/tests/toyos.rs b/tests/toyos.rs index 98337972ea2..55f3d7f48e4 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -760,7 +760,7 @@ fn shared_metal(keep: impl Fn(&str) -> bool) -> Vec { config: "tests/testcases", params: &[], features: &[], - members: const { std::num::NonZeroUsize::new(62).expect("a chunk holds a member") }, + members: const { metal::members_fitting(toyos_tco::RUST_MEMBER_MS) }, jobs: shipping .iter() .filter(|n| keep(n)) @@ -779,7 +779,7 @@ fn shared_metal(keep: impl Fn(&str) -> bool) -> Vec { config: "tests/testcases", params: &[], features: toyos_build::build::TEST_KERNEL, - members: const { std::num::NonZeroUsize::new(67).expect("a chunk holds a member") }, + members: const { std::num::NonZeroUsize::new(18).expect("a chunk holds a member") }, jobs: debug.iter().filter(|n| keep(n)).map(|n| format!("test_rs_{n}")).collect(), files: Vec::new(), links: Vec::new(), @@ -850,7 +850,7 @@ fn c_corpus_metal( config: "tests/testcases", params: &[], features: &[], - members: const { std::num::NonZeroUsize::new(207).expect("a chunk holds a member") }, + members: const { metal::members_fitting(toyos_tco::C_MEMBER_MS) }, jobs, files, links, diff --git a/toyos-tco/src/lib.rs b/toyos-tco/src/lib.rs index 4ca017ff5d7..eb7ceb1938e 100644 --- a/toyos-tco/src/lib.rs +++ b/toyos-tco/src/lib.rs @@ -114,6 +114,11 @@ pub const FIRMWARE_BOUND_MS: u64 = 60_000; /// while a job never finishes is no wedge to it and nothing else ends the boot. pub const JOB_BOUND_MS: u64 = 60_000; +/// What one member of a metal shared boot is allowed of [`JOB_BOUND_MS`], in +/// milliseconds: a Rust test on the shipping kernel, and a C corpus case. +pub const RUST_MEMBER_MS: u64 = 860; +pub const C_MEMBER_MS: u64 = 260; + /// The bound netd gives this machine's first DHCP lease before it says it has /// none and serves anyway, in milliseconds. The harness waits it out on a wire /// with no server, so the two read one declaration. From 1ba6b43e3192bf7ce5755e22ab95c6c7cf299dbc Mon Sep 17 00:00:00 2001 From: japabu Date: Sat, 3 Oct 2026 02:16:01 +0200 Subject: [PATCH 18/19] issues: host_scale's boots differ in profile as well as marker, measured in one session The filing at 4b009e712 set an x86-64 boot under TCG beside an AArch64 boot under HVF and named only the marker. At e5daa61ff, one run after the other: virt_early_panic (Virt, HVF, to `EARLY PANIC:`) 479 ms, virt_smp (VirtEl2, TCG, to `SCTLR_EL1=`) 1180 ms, machine_shutdown (x86-64, TCG, to `===READY===`) 3316 ms and 2.33x. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm --- ...ff-boots-that-stop-at-different-markers.md | 29 ++++++++++--------- 1 file changed, 16 insertions(+), 13 deletions(-) diff --git a/issues/build/host-scale-reads-host-speed-off-boots-that-stop-at-different-markers.md b/issues/build/host-scale-reads-host-speed-off-boots-that-stop-at-different-markers.md index 62d10d195d8..d4dfce6f0bc 100644 --- a/issues/build/host-scale-reads-host-speed-off-boots-that-stop-at-different-markers.md +++ b/issues/build/host-scale-reads-host-speed-off-boots-that-stop-at-different-markers.md @@ -10,23 +10,26 @@ opened: 2026-10-03 `host_scale`: the run's fastest boot against `REFERENCE_BOOT_MS`, 1424 ms. `record_boot` takes each boot's time to its own ready marker, and those differ: `virt_early_panic`'s and `virt_early_fault`'s is `EARLY PANIC:`, which the -kernel prints before userland, and an x86-64 boot's is `===READY===`, after it. -So the scale says which boots a run held, not how fast the host is: a run with -an early-panic boot in it pays 1× on nearly any host, and with the suite's -width no longer multiplying a ceiling, `host_scale` and `oversubscription` are -the only host corrections `budget_smp` makes. +kernel prints when it panics early in bring-up; the other AArch64 boots' is +`control registers: SCTLR_EL1=`; an x86-64 boot's is `===READY===`, after +userland starts. The boots also run under different accelerators +(`Profile::accel`). So the scale says which boots a run held, not how fast the +host is: a run with an early-panic boot in it pays 1× on nearly any host. With +the suite's width no longer multiplying a ceiling, `host_scale` and +`oversubscription` are the only host corrections `budget_smp` makes. ## Measured -On the dev host at load average 3.7 to 3.4, one run after the other on PR -#638's tree: +On the dev host, an arm64 Mac, one run after the other at `e5daa61ff`, load +average 1.7 to 2.8: -| command | its fastest boot | scale | -|---|---|---| -| `cargo test --test toyos-build -- virt_early_panic` | 491 ms | 1.00× | -| `cargo test --test toyos-build -- machine_shutdown` | 3318 ms | 2.33× | +| command | the boot | its fastest boot | scale | +|---|---|---|---| +| `cargo test --test toyos-build -- virt_early_panic` | `Virt`, HVF, to `EARLY PANIC:` | 479 ms | 1.00× | +| `cargo test --test toyos-build -- virt_smp` | `VirtEl2`, TCG, to `SCTLR_EL1=` | 1180 ms | 1.00× | +| `cargo test --test toyos-build -- machine_shutdown` | x86-64, TCG, to `===READY===` | 3316 ms | 2.33× | -The whole suite at `4859e8d71`, 12 wide on the same host, read 502 ms and paid +The whole suite at `e5daa61ff`, 12 wide on the same host, read 566 ms and paid 1.00×. ## Owner @@ -37,5 +40,5 @@ cannot. ## What would close it -`host_scale` reads only boots that stop at one marker on every host, or it is +`host_scale` reads only boots of one profile that stop at one marker, or it is deleted with `budget_smp`'s promise of it. From e3094a94a731fe0bd4f54d8764ca04615e9ffd4a Mon Sep 17 00:00:00 2001 From: japabu Date: Sat, 3 Oct 2026 09:33:11 +0200 Subject: [PATCH 19/19] metal: the port test drops the dial-bound wrapper; the talking boot's issue closes Round 5 of #638's review. `coming_back_is_ssh_answering_and_not_its_port` wrapped `accepts` to record the bound `wait_on` hands it going down and asserted that bound was `CONNECT_SECS`. That checks one line of `wait_on` a reader of the diff checks, so the wrapper, its assertion and the doc clause that named it go, and `accepts` is passed directly. `issues/build/the-talking-boots-reboot-outruns-its-log-stream.md` is deleted: its exit, two consecutive T14 runs passing `lan_talk`, is met by the runs at `4859e8d71` (PR comment 5962753432) and at `75dc056f1` (PR comment 5966698095), both with `metaltalk::hand_back` waiting on the stream's `Boot: complete`. The rule it carried is already `hand_back`'s doc. Its one citation, in `issues/hardware/netds-i219-drops-a-transmit-burst-past-its-ring.md`, goes with it. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm --- ...ing-boots-reboot-outruns-its-log-stream.md | 45 ------------------- ...19-drops-a-transmit-burst-past-its-ring.md | 5 +-- src/metal.rs | 14 +----- 3 files changed, 4 insertions(+), 60 deletions(-) delete mode 100644 issues/build/the-talking-boots-reboot-outruns-its-log-stream.md diff --git a/issues/build/the-talking-boots-reboot-outruns-its-log-stream.md b/issues/build/the-talking-boots-reboot-outruns-its-log-stream.md deleted file mode 100644 index 262014ff8f2..00000000000 --- a/issues/build/the-talking-boots-reboot-outruns-its-log-stream.md +++ /dev/null @@ -1,45 +0,0 @@ ---- -status: open -kind: tooling -opened: 2026-09-29 ---- - -# The talking boot's `reboot` outruns its log stream, so `lan_talk` reds when the backlog has not crossed - -`metaltalk::converse` (`src/metaltalk.rs`) waited for the stream to connect, -pinged, ran one command and fired `reboot`; nothing waited on the stream -carrying the lines `metaltalk::judge` then requires, this boot's -`Boot: complete` among them. `logd` serves the boot from its first line, so -the verdict was a race between the backlog crossing and the `reboot` the host -itself sends. `metaltalk::hand_back` now fires `reboot` once the stream has -carried that record or its bound has passed. - -## Measured - -The full T14 run of `main` at `7e151819` -(EXIT=1), boot `lantalkcase`: - -``` -toyos-metal: the boot did not say over its own cable what a talking boot owes: - 217 line(s) arrived over the cable and none is this boot's `Boot: complete` - FAIL lantalkcase: toyos-metal exited exit status: 1 - FAIL lan_talk: toyos-metal exited exit status: 1 -``` - -Its readback: -`talk.txt` says the ping, the command (`status 0`, 495 ms) and the `reboot` -all succeeded, with `talk_stream_end open`. `stream.log` is `kernel.log`'s -first 217 lines, ending at `0.493 ... xHCI: configuration set`; -`Boot: complete (1167ms)` is `kernel.log:289`. `kernel.log` has -`logd: serving this boot's log to 192.168.1.47:54752` at 20.996 s and init's -`power: the machine stops` at 21.591 s: the stream had 595 ms. - -The T14 run of PR #609 at `7d2e15c0` gave the same finding at the same 217th -line, with 262 ms between the admit and the stop. The stall is at a fixed -byte count, not a fixed time. netd's I219 drops everything past 15 frames in -flight (`issues/hardware/netds-i219-drops-a-transmit-burst-past-its-ring.md`), -and the rest of the stream waits for a retransmit timeout that `reboot` beat. - -## Exit condition - -Two consecutive T14 runs pass `lan_talk`; then this file is deleted. diff --git a/issues/hardware/netds-i219-drops-a-transmit-burst-past-its-ring.md b/issues/hardware/netds-i219-drops-a-transmit-burst-past-its-ring.md index b78cdd09eb4..8f56254dea3 100644 --- a/issues/hardware/netds-i219-drops-a-transmit-burst-past-its-ring.md +++ b/issues/hardware/netds-i219-drops-a-transmit-burst-past-its-ring.md @@ -23,9 +23,8 @@ host's stream at 19.141 s. At 19.180 s netd said `9 frame(s) dropped with no transmit descriptor free`, and `reboot` came at 19.403 s. The host's `stream.log` is `kernel.log`'s first 217 lines, which is 21890 bytes, and 15 × 1460 = 21900 falls inside line 218. The run of `main` at `7e151819` -stopped at the same 217th line, with 595 ms between the admit and the stop -(`issues/build/the-talking-boots-reboot-outruns-its-log-stream.md`). Both -windows are shorter than the first retransmit timeout. The same count appears +stopped at the same 217th line, with 595 ms between the admit and the stop. +Both windows are shorter than the first retransmit timeout. The same count appears on the `lanswapcase` boot: 11, 18 and 23 frames dropped. ## Owner diff --git a/src/metal.rs b/src/metal.rs index f7dacc02f25..5f6381b9c75 100644 --- a/src/metal.rs +++ b/src/metal.rs @@ -2587,7 +2587,7 @@ mod tests { } /// **A port that accepts is not a machine that came back**, and a machine - /// going down is its port refusing a dial given what `ssh`'s own connect is. + /// going down is its port refusing. /// Staged through [`port_accepts`] on a listener of this host's own, which /// accepts and never speaks `ssh`, and on port 0, which nothing listens on: /// a port the listener let go of can be another socket's by the time it is @@ -2605,18 +2605,8 @@ mod tests { assert_eq!(back, Err(Refusal::Silent { what: "come back", secs: 1 })); assert!(asked > 0, "`ssh` was never asked of a port that accepts"); assert_eq!(wait_on(1, "come back", true, accepts, || true), Ok(0)); - let mut dialled = Vec::new(); - let dial = |within| { - dialled.push(within); - accepts(within) - }; - let up = wait_on(1, "go down", false, dial, || unreachable!("`ssh` asked of one going down")); + let up = wait_on(1, "go down", false, accepts, || unreachable!("`ssh` asked of one going down")); assert_eq!(up, Err(Refusal::Silent { what: "go down", secs: 1 })); - let connect = std::time::Duration::from_secs(CONNECT_SECS); - assert!( - !dialled.is_empty() && dialled.iter().all(|&within| within == connect), - "going down dialled within {dialled:?}, where `ssh`'s own connect is given {connect:?}" - ); let refuses = |within| port_accepts("127.0.0.1", 0, within); assert_eq!(wait_on(1, "go down", false, refuses, || unreachable!()), Ok(0)); }