diff --git a/issues/audio/hda-client-stall-prints-a-stream-error-and-passes.md b/issues/audio/hda-client-stall-prints-a-stream-error-and-passes.md new file mode 100644 index 00000000000..b3dbc33cb3b --- /dev/null +++ b/issues/audio/hda-client-stall-prints-a-stream-error-and-passes.md @@ -0,0 +1,23 @@ +--- +status: open +kind: tooling +opened: 2026-10-03 +--- + +# `hda_client_stall` prints a stream error and passes + +`tests/toyos-rust-tests/src/bin/hda_client_stall.rs` hands cpal an error +callback that prints `audio error: …` and does nothing else. The fork reports +two things through it: a stream whose signal pipe went away, and a dropped +stream soundd did not let go of within its fade and a ring of periods. Either +leaves the job exiting 0, and the `hda_client_stall` T14 row reads the job's +exit code. `tone.rs`'s `play_tone` asserts on the same callback. + +The `testcases` readback of the T14 run of #638's head carries no +`audio error` line. Whether the T14 ever reports one under this job is not +measured. + +## Exit condition + +The job fails when its stream reports an error, and `hda_client_stall` passes +on a T14 run of that head. diff --git a/issues/audio/hda-client-stall-reads-one-resume-where-its-judge-wants-two.md b/issues/audio/hda-client-stall-reads-one-resume-where-its-judge-wants-two.md deleted file mode 100644 index 61070a4c295..00000000000 --- a/issues/audio/hda-client-stall-reads-one-resume-where-its-judge-wants-two.md +++ /dev/null @@ -1,83 +0,0 @@ ---- -status: open -kind: defect -opened: 2026-09-29 ---- - -# `hda_client_stall` reads one resume on the T14 where its judge wants two - -The T14 run of `wt/toyos-metaljudges` at `6737a442` reds the row with: - -``` -FAIL hda_client_stall: soundd resumed 0 time(s) — the second stream did not find a suspended daemon, so nothing here tests a resume: -``` - -The job itself exits 0 and prints `stalled 8 then 2 times, soundd survived`. - -## Measured - -The `testcases` boot's log, from the job's spawn to its end, in order: - -``` -{… 6.275 soundd} soundd: client 0 removed (closed) -[… 6.276 cpu6] spawn: /system/bin/test_rs_hda_client_stall pid=9 … -{… 6.276 soundd} soundd: wakes=662 … clients=0 … -{… 6.333 tid=1 soundd} soundd: opening stream: 44100Hz 2ch fmt=0 -{… 6.333 soundd} soundd: client 0 connected (id=1) -{… 8.565 soundd} soundd: client 1 removed (closed) -{… 8.565 soundd} soundd: wakes=126 … clients=0 … -{… 8.585 soundd} soundd: suspended -{… 8.836 tid=1 soundd} soundd: opening stream: 44100Hz 2ch fmt=0 -{… 8.836 soundd} soundd: client 0 connected (id=2) -{… 8.836 soundd} soundd: resumed -{… 9.755 soundd} soundd: wakes=480 … clients=0 … -{… 9.780 soundd} soundd: suspended -``` - -- The window `tests/common/audio.rs`'s `job_window` cut for two sessions ends - at the `8.565` stats line: the `clients=0` stats line at `6.276`, after the - spawn and before the first stream opens, is counted as the first session's - end. The printed window carries no `soundd: resumed`. -- Across the job's whole span the log carries one `soundd: resumed`, at the - second stream. The first stream opens with no `soundd: suspended` between - the previous client's removal at `6.275` and its open at `6.333`, so - `client_stall_on_metal`'s `resumes < 2` reds on that span too. - -## Measured once a job's stream is gone before the job exits - -The `testcases` boot of the orchestrator's T14 `--metal hda_tone` run at -`1621eb5f0` (#641), from the tone's removal to the stall's end, in order: - -``` -{… 5.670 soundd} soundd: client 0 removed (closed) -{… 5.670 soundd} soundd: wakes=645 … clients=0 … -[… 5.670 cpu4] exit: test_rs_audio_tone pid=11 code=0 cpu=2ms -[… 5.672 cpu7] spawn: /system/bin/test_rs_hda_client_stall pid=12 … -{… 5.673 tid=1 soundd} soundd: opening stream: 44100Hz 2ch fmt=0 -{… 5.673 soundd} soundd: client 0 connected (id=1) -{… 7.830 soundd} soundd: client 1 removed (closed) -{… 7.830 soundd} soundd: wakes=79 … clients=0 … -{… 7.854 soundd} soundd: suspended -{… 8.130 tid=1 soundd} soundd: opening stream: 44100Hz 2ch fmt=0 -{… 8.131 soundd} soundd: client 0 connected (id=2) -{… 8.131 soundd} soundd: resumed -{… 9.040 soundd} soundd: client 2 removed (closed) -{… 9.040 soundd} soundd: wakes=465 … clients=0 … -{… 9.063 soundd} soundd: suspended -``` - -- The tone's stream is removed, and its session flushed, before its job - exits; the stall's first stream opens 3 ms after that exit. -- soundd suspends 20 to 25 ms after the last removal: `7.830`→`7.854` and - `9.040`→`9.063` here, `8.565`→`8.585` and `9.755`→`9.780` above. -- So the first stream opens on a soundd that has not suspended, which is not - the premise `client_stall_on_metal` asks of it. The judge reads this log as: - -``` -FAIL hda_client_stall: soundd resumed 1 time(s) — the second stream did not find a suspended daemon, so nothing here tests a resume: -``` - -## Exit condition - -`hda_client_stall` PASS on the orchestrator's T14 run of the head that lands -the fix, and this file is deleted. diff --git a/issues/audio/the-tone-client-waits-a-flat-200-ms-for-its-tail.md b/issues/audio/the-tone-client-waits-a-flat-200-ms-for-its-tail.md new file mode 100644 index 00000000000..52bcbea3a42 --- /dev/null +++ b/issues/audio/the-tone-client-waits-a-flat-200-ms-for-its-tail.md @@ -0,0 +1,22 @@ +--- +status: open +kind: tooling +opened: 2026-10-03 +--- + +# The tone client waits a flat 200 ms for its tail, and for its end with no bound + +`tests/toyos-rust-tests/src/tone.rs`'s `play_tone` is what `test_rs_audio_tone` +and `test_rs_soundd_log_stall` play, so the `hda_tone` and `soundd_log_stall` +T14 rows ride it. It sleeps 50 ms at a time until its callback has written the +tone's last sample, with no bound of its own, and then sleeps a flat 200 ms for +the tail to drain through soundd and the device before it drops the stream. + +Root `CLAUDE.md` allows neither: a wait is on the event, bounded by a timeout +that fails loudly. + +## Exit condition + +`play_tone` holds no sleep: what it waits on is an event, bounded by a timeout +that panics by name, and `hda_tone` and `soundd_log_stall` pass on a T14 run +of that head. diff --git a/issues/build/lan-hold-holds-two-boots-open-for-a-flat-twenty-seconds.md b/issues/build/lan-hold-holds-two-boots-open-for-a-flat-twenty-seconds.md new file mode 100644 index 00000000000..ba34e6b9664 --- /dev/null +++ b/issues/build/lan-hold-holds-two-boots-open-for-a-flat-twenty-seconds.md @@ -0,0 +1,23 @@ +--- +status: open +kind: tooling +opened: 2026-10-03 +--- + +# `lan_hold` holds two boots open for a flat twenty seconds + +`tests/toyos-rust-tests/src/bin/lan_hold.rs` sleeps `toyos_tco::LEASE_BOUND_MS` +and exits. Two T14 boots run it as their one job: `lanleasecase`, so the boot +does not end before netd's `--exit-with-lease` has, and `testcases-deaf`, so +it does not end before the `dump-deaf-cpu` actuator has armed and dumped. Each +is a fixed delay standing in for an event the job does not wait on, which root +`CLAUDE.md` forbids in a test. + +On the T14 run of #638's head netd exited at 19.212 s of the `lanleasecase` +boot and init stopped the machine at 21.202 s. + +## Exit condition + +Neither boot's one job holds a sleep: each waits on the event it is held open +for, bounded by a timeout that panics by name, and `lan_lease_report` and +`dump_nmi_probe` pass on a T14 run of that head. diff --git a/issues/hardware/the-benchs-router-leases-toyos-another-address-than-ubuntu.md b/issues/hardware/the-benchs-router-leases-toyos-another-address-than-ubuntu.md deleted file mode 100644 index a52c6efa3cb..00000000000 --- a/issues/hardware/the-benchs-router-leases-toyos-another-address-than-ubuntu.md +++ /dev/null @@ -1,37 +0,0 @@ ---- -status: open -kind: tooling -opened: 2026-09-29 ---- - -# The bench's router leases ToyOS another address than Ubuntu, so `lan_dhcp_lease` reds on the router - -`lan::on_metal` (`tests/common/lan.rs`) pings the address Ubuntu held on the -I219's MAC before the flash, and refuses a boot whose lease is another one. -This is the second premise of -`issues/hardware/the-cable-judge-spends-two-premises-nothing-has-measured.md`, -and this run measured it false: the router gave ToyOS `.49` twice and Ubuntu -`.46`, on one MAC. - -## Measured - -The full T14 run of `main` at `7e151819` -(EXIT=1), boot `lancase`: - -``` - [lan] leased 192.168.1.49/24 from 192.168.1.1 in 13315 ms, gateway 192.168.1.1, dns [194.230.55.96, 212.98.37.130] - FAIL lan_dhcp_lease: 2 finding(s): - this boot leased 192.168.1.49 and the host pinged 192.168.1.46, which the router hands this MAC under the operating system before it — so either something else answered or that server does not repeat a lease across the two - nothing answered a ping at 192.168.1.46 while this machine was between its two operating systems -``` - -`lancase/boot.txt` records `ping_addr 192.168.1.46` and -`wire_mac 38:f3:ab:35:37:3b`; `netd: MAC 38:f3:ab:35:37:3b` is the MAC the -lease went to. The `lantalkcase` boot of the same run leased -`192.168.1.49` again (`talk_peer 192.168.1.49`). What the router keys the -lease on is not measured. - -## Exit condition - -The judge's verdict no longer rests on the router repeating one lease across -the two operating systems, and a T14 run passes `lan_dhcp_lease`; then this file is deleted. 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 deleted file mode 100644 index ac9f6844a72..00000000000 --- a/issues/hardware/the-cable-judge-spends-two-premises-nothing-has-measured.md +++ /dev/null @@ -1,28 +0,0 @@ ---- -status: open -kind: tooling -opened: 2026-09-13 ---- - -# The cable judge spends two premises nothing has measured - -`tests/common/lan.rs`'s `on_metal` decides whether a ping the metal loop saw was -this boot's, and two of its steps rest on readings nobody has taken. - -**The T14's RTC is unchanged across the reset.** `Driver::wire` reads -`date -u +%s` under Ubuntu before the flash and -`bootlog::host_second_inside_this_boot` spends that offset on records ToyOS wrote -after it; a machine whose firmware or whose kernel moved the counter would be -judged against a clock that no longer exists. Closed by one boot: a ToyOS -record's wall clock read back against `date -u +%s` on the machine after it, with -the loop's own skew applied — or by the judge ceasing to compare the two -operating systems' clocks at all. - -**The router repeats the lease across the two operating systems.** The same -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. - -The router-lease measurement falsifies this premise: -`issues/hardware/the-benchs-router-leases-toyos-another-address-than-ubuntu.md`. diff --git a/src/bootlog.rs b/src/bootlog.rs index dcf6947b0ce..0d67da44022 100644 --- a/src/bootlog.rs +++ b/src/bootlog.rs @@ -369,37 +369,6 @@ pub fn record_millis(line: &str) -> Option { toyos_logstream::record_ms(line) } -/// The UTC second one record line carries, as seconds since the epoch. -/// -/// `logd` writes the wall clock and the panel writes none, so a line without one -/// answers `None` rather than reading the milliseconds field as a date. -fn record_unix_secs(line: &str) -> Option { - // A kernel record's bracket or a program line's head: `logd` stamps both - // with the same wall clock in the same place. - let mut fields = line - .strip_prefix('[') - .or_else(|| line.strip_prefix(toyos_logstream::OPEN))? - .split_whitespace(); - let (year, rest) = fields.next()?.split_once('-')?; - let (month, day) = rest.split_once('-')?; - let (hour, rest) = fields.next()?.split_once(':')?; - let (min, sec) = rest.split_once(':')?; - if [year, month, day, hour, min, sec].map(str::len) != [4, 2, 2, 2, 2, 2] { - return None; - } - let civil = toyos_wallclock::Civil { - year: year.parse().ok()?, - month: month.parse().ok()?, - day: day.parse().ok()?, - hour: hour.parse().ok()?, - min: min.parse().ok()?, - sec: sec.parse().ok()?, - }; - // logd renders this field from the same `Civil`, so one it refuses is not - // a field logd wrote. - civil.is_valid().then(|| civil.to_unix_secs()) -} - /// Whether `source` declares a constant whose value is exactly `rhs`, wrapped /// or not. /// @@ -422,61 +391,6 @@ pub fn declares(source: &str, rhs: &str) -> bool { joined.lines().any(|line| line.trim_end().ends_with(&tail)) } -/// The daylight a host second needs on either side before it is this boot's. -/// -/// **A judge reading whole seconds does not get to decide at one.** `skew` is a -/// difference of two floored clocks across a round trip its reader holds to a -/// second, which is three of these; the second the host read and the second the -/// record carries are floored too, which is the fourth; and the fifth is what -/// makes a refusal a distance rather than a coin. -pub const MARGIN: u64 = 5; - -/// Whether a second on the *host's* clock fell inside the boot this log is of, -/// clear of [`MARGIN`] on both the record `after` names and the reset. -/// -/// **The records are the one place a host clock and a boot's clock meet.** -/// `skew` is this machine's clock minus the host's as the caller measured the -/// two against each other; how far into a host-side window an observation came -/// separates nothing, because such a window holds the operating system that -/// left and the one that came back as well as this boot. -pub fn host_second_inside_this_boot( - log: &str, - skew: i64, - after: &str, - at: u64, -) -> Result<(), String> { - let dated = |line: Option<&str>| line.and_then(record_unix_secs).map(i128::from); - let began = dated(log.lines().find(|l| l.contains(after))) - .ok_or_else(|| format!("this log carries no dated {after:?} record"))?; - let ended = dated(stopping_line(log)).ok_or_else(|| { - format!( - "this log carries no dated {STOPPING:?} line, so nothing in it says when this boot \ - handed the machine back" - ) - })?; - let at = i128::from( - at.checked_add_signed(skew) - .ok_or_else(|| format!("a host second of {at} and a skew of {skew} is no second"))?, - ); - if at - began < i128::from(MARGIN) { - return Err(format!( - "the host saw it at {at} on this machine's clock and this boot's {after:?} record is \ - at {began}, {} s apart: nothing closer than {MARGIN} s past that record is this \ - boot's, because these clocks are whole seconds", - at - began - )); - } - if ended - at < i128::from(MARGIN) { - return Err(format!( - "the host saw it at {at} on this machine's clock and this boot's {STOPPING:?} line \ - is at {ended}, {} s apart: nothing closer than {MARGIN} s before that line is this \ - boot's, so it belongs to the operating system on the other side of the reset", - ended - at - )); - } - Ok(()) -} - /// When the last record in `log` was written, in milliseconds since boot. pub fn last_record_millis(log: &str) -> Option { log.lines().rev().find_map(record_millis) @@ -759,100 +673,4 @@ mod record_time_tests { assert_eq!(last_record_millis(log), Some(2_500)); assert_eq!(last_record_millis("nothing\n"), None); } - - const BOOT: &str = concat!( - "[2026-09-08 16:08:21 0.000 cpu0 boot] panic console: armed 1920x1080 stride=1920 \ - format=1 at 0x4000000000\n", - "[2026-09-08 16:08:22 1.258 cpu0] Boot: complete (1258ms)\n", - "{2026-09-08 16:08:44 23.340 init} init: power: the machine stops, and logd makes the log \ - whole first (Reboot)\n", - ); - - /// That boot's first record, which every second below is placed against. - fn first() -> u64 { - record_unix_secs(BOOT.lines().next().expect("a record")).expect("a wall clock") - } - - /// **[`MARGIN`] decides both edges**, and one second short of either is - /// refused rather than read as inside. - #[test] - fn a_second_clear_of_this_boots_records_by_the_margin_is_this_boots() { - let first = first(); - for at in [first + MARGIN + 1, first + 23 - MARGIN] { - assert_eq!(host_second_inside_this_boot(BOOT, 0, "Boot: complete", at), Ok(()), "{at}"); - } - let why = host_second_inside_this_boot(BOOT, 0, "Boot: complete", first + MARGIN) - .expect_err("a second short of the margin past the record it is anchored on"); - assert!(why.contains(&format!("closer than {MARGIN} s past")), "{why}"); - let why = host_second_inside_this_boot(BOOT, 0, "Boot: complete", first + 24 - MARGIN) - .expect_err("a second short of the margin before the reset"); - assert!(why.contains(&format!("closer than {MARGIN} s before")), "{why}"); - } - - /// **The one reply this judge exists to refuse.** The loop wrote it 57 s - /// into a window opening no earlier than its own run, whose first line is - /// 33 s before this boot's first record; it is anchored here on the earliest - /// record the boot carries, which is the most favourable anchor there is, - /// and no skew the measurement can be wrong by brings it inside. - #[test] - fn that_reply_is_refused_at_every_skew_the_measurement_can_be_wrong_by() { - let earliest_window = first() - 33; - for skew in -3..=3 { - let why = - host_second_inside_this_boot(BOOT, skew, "Boot: complete", earliest_window + 57) - .expect_err("a skew of this size does not place that reply inside the boot"); - assert!(why.contains(&format!("closer than {MARGIN} s before")), "{skew}: {why}"); - } - } - - /// **A boot that never reached its reset brackets nothing**, and neither - /// does one that never wrote the record the caller anchors on. - #[test] - fn a_log_missing_either_record_is_refused_rather_than_widened() { - let first = first(); - let unfinished: String = BOOT.lines().take(2).map(|l| format!("{l}\n")).collect(); - let why = host_second_inside_this_boot(&unfinished, 0, "Boot: complete", first + 10) - .expect_err("a log with no reset says nothing about when this boot ended"); - assert!(why.contains(&format!("no dated {STOPPING:?} line")), "{why}"); - let why = host_second_inside_this_boot(BOOT, 0, "netd: DHCP: lease ", first + 10) - .expect_err("this boot took no lease"); - assert!(why.contains("no dated \"netd: DHCP: lease \" record"), "{why}"); - let why = host_second_inside_this_boot("[1.000 cpu0] first\n", 0, "first", 0) - .expect_err("a panel log carries no wall clock"); - assert!(why.contains("no dated \"first\" record"), "{why}"); - } - - /// **The measured skew is the whole of what places a host second.** The - /// same reading is this boot's on one clock and the next operating system's - /// on another. - #[test] - fn the_measured_skew_is_what_the_host_second_is_read_through() { - let first = first(); - assert_eq!(host_second_inside_this_boot(BOOT, 30, "Boot: complete", first - 20), Ok(())); - let why = host_second_inside_this_boot(BOOT, -30, "Boot: complete", first + 10) - .expect_err("thirty seconds the other way is before this boot began"); - assert!(why.contains(&format!("closer than {MARGIN} s past")), "{why}"); - } - - /// The panel writes no wall clock, and its milliseconds field must not be - /// read as one: `[1.000 cpu0]` would otherwise parse `1.000` as a date and - /// answer some second in 1970. - #[test] - fn a_line_with_no_wall_clock_answers_none() { - assert_eq!(record_unix_secs("[1.000 cpu0] first"), None); - assert_eq!(record_unix_secs("not a record"), None); - assert_eq!(record_unix_secs("[2026-09-08 25:00:00 0.000 cpu0] x"), None); - assert_eq!(record_unix_secs("[2026-02-31 10:00:00 0.000 cpu0] x"), None); - } - - /// A leap day and a month's end are counted as the days they are. - #[test] - fn a_wall_clock_across_a_leap_day_and_a_month_is_its_seconds() { - let at = |line| record_unix_secs(line).expect("a wall clock"); - assert_eq!(at("[1970-01-01 00:00:00 0.000 cpu0] x"), 0); - assert_eq!(at("[2024-02-28 23:59:59 0.000 cpu0] x"), 1_709_164_799); - assert_eq!(at("[2024-02-29 00:00:00 0.000 cpu0] x"), 1_709_164_800); - assert_eq!(at("[2024-03-01 00:00:00 0.000 cpu0] x"), 1_709_164_800 + 86_400); - assert_eq!(record_unix_secs("[2023-02-29 00:00:00 0.000 cpu0] x"), None); - } } diff --git a/src/icmp.rs b/src/icmp.rs index d776f64de6b..e5c95976032 100644 --- a/src/icmp.rs +++ b/src/icmp.rs @@ -3,8 +3,6 @@ //! **A host that cannot ask and an address that did not answer are different //! answers**, and the caller gets them as `Err` and `Ok(false)`: a socket the //! host refuses would otherwise red a boot for this machine's configuration. -//! A send the host's own routing refuses is the *second* of those and not the -//! first — [`wire_is_down`] is where that line is drawn. use std::io; use std::net::{IpAddr, Ipv4Addr, UdpSocket}; @@ -35,15 +33,9 @@ pub fn echo(addr: Ipv4Addr, wait: Duration) -> Result { let token = token(); let request = request(&token); let deadline = Instant::now() + wait; - if let Err(e) = socket.send_to(&request, (addr, 0)) { - // The address this probe watches is down for the whole span it is asked - // across, so the host's own routing has nowhere to put the request: that - // is a second nothing answered, which is what `Ok(false)` already says. - if wire_is_down(&e) { - return Ok(false); - } - return Err(format!("this host could not send an ICMP echo request to {addr}: {e}")); - } + socket + .send_to(&request, (addr, 0)) + .map_err(|e| format!("this host could not send an ICMP echo request to {addr}: {e}"))?; let mut buf = [0u8; MOST]; loop { let Some(left) = deadline.checked_duration_since(Instant::now()) else { @@ -73,21 +65,6 @@ pub fn echo(addr: Ipv4Addr, wait: Duration) -> Result { } } -/// Whether a send failed because the wire is down right now, rather than -/// because this host cannot ask the question at all. -/// -/// **Three errnos and no fourth, each named.** A send with nowhere to go is -/// refused by the kernel by name — `EHOSTUNREACH` where the address has no -/// neighbour to hand the frame to, `ENETUNREACH` where no route covers it, -/// `ENETDOWN` where the interface itself is gone — and across the span this -/// probe is asked over, every one of them is the machine being down, which is -/// the silence [`echo`] answers `Ok(false)` for. Everything else stays this -/// host's failing: a permission the kernel withheld, a socket that is closed, -/// a message it would not take. -fn wire_is_down(e: &io::Error) -> bool { - matches!(e.raw_os_error(), Some(libc::EHOSTUNREACH | libc::ENETUNREACH | libc::ENETDOWN)) -} - /// The socket, or why this host would not open one. fn open() -> Result { // SAFETY: `socket` answers a fresh descriptor or -1, and the descriptor it @@ -229,41 +206,6 @@ mod tests { assert!(is_reply(HOST.into(), HOST, &headed, &token)); } - /// **A wire that is down right now is a second nothing answered, and - /// nothing else is.** - /// - /// The case, off the bench: the loop flashed the stick, set `BootNext` and - /// rebooted the machine, the address's neighbour entry lapsed while it was - /// down, and the send earned `No route to host (os error 65)` — which the - /// loop read as a host that could not ask and ended the run at exit 2, with - /// the boot itself complete on the stick. The host was on the LAN either - /// side of it. The three the kernel refuses a routeless send with are this - /// probe's subject; the errnos below it are not, and a run that widened the - /// first set into the second would spend its whole window calling a host - /// with no socket a machine that never answered. - #[test] - fn a_wire_that_is_down_right_now_is_not_a_host_that_cannot_ask() { - for errno in [libc::EHOSTUNREACH, libc::ENETUNREACH, libc::ENETDOWN] { - assert!(wire_is_down(&io::Error::from_raw_os_error(errno)), "{errno}"); - } - // The recorded failure's own number, as this host spells it. - #[cfg(target_os = "macos")] - assert_eq!(libc::EHOSTUNREACH, 65); - for errno in [ - libc::EPERM, - libc::EACCES, - libc::EBADF, - libc::ENOTSOCK, - libc::EAFNOSUPPORT, - libc::EMSGSIZE, - libc::EINVAL, - ] { - assert!(!wire_is_down(&io::Error::from_raw_os_error(errno)), "{errno}"); - } - // An error with no errno behind it is none of the three either. - assert!(!wire_is_down(&io::Error::other("no errno"))); - } - /// Everything that carries the bytes and is not this probe's answer. #[test] fn nothing_but_the_reply_to_this_probe_counts() { diff --git a/src/lan.rs b/src/lan.rs index 06129ec5212..66aaa5029eb 100644 --- a/src/lan.rs +++ b/src/lan.rs @@ -13,7 +13,7 @@ use crate::bootlog::message; /// The records both arms are written against, spelled once. pub const MAC: &str = "netd: MAC "; -pub const LEASE: &str = "netd: DHCP: lease "; +const LEASE: &str = "netd: DHCP: lease "; pub const LINK_UP: &str = "netd: I219: link up at "; pub const READY: &str = "netd: ready, at most "; diff --git a/src/metal.rs b/src/metal.rs index 5f6381b9c75..66bf690e8f9 100644 --- a/src/metal.rs +++ b/src/metal.rs @@ -63,18 +63,6 @@ pub fn return_secs() -> u64 { /// 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; - -const PING_WAIT_MS: u64 = 1_000; - -/// How long the address has to answer *nothing* before a reply counts as this -/// boot's. -/// -/// **`ssh` stops answering before the network does**: `reboot` takes `sshd` down -/// first and the interface seconds later, so a reply before the silence is the -/// operating system that is leaving rather than the image this loop wrote. -const PING_SILENCE_SECS: u64 = 5; - /// How long the boot stick gets to be there again once Ubuntu is up. /// /// **The bench's own device is the one judge there is of whether a reset left a @@ -163,11 +151,10 @@ pub enum Refusal { /// A lid key that no longer reads `ignore`, which is what keeps the machine up. Lid { key: &'static str, got: String }, Remote { what: String, status: String, stderr: String }, - /// The machine could not say what address it holds on the function the - /// flashed image claims, so the boot could not be reached over the cable. + /// The machine could not name the interface, the MAC and an IPv4 address it + /// holds on the function the flashed image claims. No address is a cable + /// that is out, and a boot flashed onto that bench is red for the bench. Wire { nic: String, why: String }, - /// This host could not run the probe, which is a fact about the host. - Probe { why: String }, /// The machine did not go down, or did not come back. Silent { what: &'static str, secs: u64 }, /// The machine came back and the boot stick did not: the boot before this @@ -316,11 +303,6 @@ impl fmt::Display for Refusal { "the machine says nothing usable about PCI function {nic}, which the flashed \ image claims and a boot of it could answer on: {why}" ), - Self::Probe { why } => write!( - f, - "this host could not ask the one question this loop can put to a boot that is \ - still up: {why}" - ), Self::Silent { what, secs } => write!( f, "the machine did not {what} within {secs} s, which is longer than every watchdog \ @@ -1058,11 +1040,11 @@ fn lid_policy(text: &str) -> Result<(), Refusal> { #[derive(Debug, Clone, PartialEq, Eq)] pub struct Wire { pub iface: String, + /// What the interface holds before the flash: that it holds one is the + /// cable being in. A boot leases its own, so no judge reads this. pub addr: std::net::Ipv4Addr, /// Lower case, colon separated, as `/sys/class/net//address` writes it. pub mac: String, - /// This machine's clock minus this host's, in seconds. - pub skew: i64, } /// `ip -4 -brief addr show `'s one line, as `Wire` needs it: the brief @@ -1084,100 +1066,6 @@ fn brief_address(iface: &str, text: &str) -> Result .map_err(|_| format!("{iface}'s address reads {cidr:?}")) } -/// This machine's clock minus this host's, from `date -u +%s` and the host's own -/// reading at each end of that round trip. -/// -/// **A whole second either side and a round trip in between**, which is where -/// [`crate::bootlog::MARGIN`]'s first three seconds come from; a round trip -/// longer than that, or a host clock that stepped backwards inside it, is -/// refused rather than spent. -fn clock_skew(before: u64, said: &str, after: u64) -> Result { - let took = after.checked_sub(before).ok_or_else(|| { - format!("this host's clock read {before} before the machine's and {after} after it") - })?; - if took > 1 { - return Err(format!( - "this host's clock read {before} before the machine's and {after} after it, and a \ - skew read across {took} s is worth less than the judge it feeds" - )); - } - let machine: i64 = said.trim().parse().map_err(|_| format!("`date -u +%s` said {said:?}"))?; - i64::try_from(before) - .ok() - .and_then(|before| machine.checked_sub(before)) - .ok_or_else(|| format!("`date -u +%s` said {said:?} against a host second of {before}")) -} - -/// The first reply after the silence: how far into the window it came, and when -/// it came on this host's clock. -#[derive(Clone, Copy, Debug, PartialEq, Eq)] -pub struct Reply { - pub secs: u64, - /// Seconds since the epoch, UTC, taken when the probe answered. The probe - /// waits up to a second for its reply, so this is late by at most that. - pub at: u64, -} - -struct Ping { - first: std::sync::Arc, String>>>, - stop: std::sync::Arc, - thread: std::thread::JoinHandle<()>, -} - -impl Ping { - /// Begin, now: the caller has just watched the machine stop answering `ssh`. - fn start(addr: std::net::Ipv4Addr) -> Self { - let first = std::sync::Arc::new(std::sync::Mutex::new(Ok(None))); - let stop = std::sync::Arc::new(std::sync::atomic::AtomicBool::new(false)); - let (mine, theirs) = (std::sync::Arc::clone(&first), std::sync::Arc::clone(&stop)); - let thread = std::thread::Builder::new() - .name("metal-ping".into()) - .spawn(move || { - let began = std::time::Instant::now(); - let mut quiet_since: Option = None; - let silence = std::time::Duration::from_secs(PING_SILENCE_SECS); - let wait = std::time::Duration::from_millis(PING_WAIT_MS); - while !theirs.load(std::sync::atomic::Ordering::SeqCst) { - let answered = match crate::icmp::echo(addr, wait) { - Ok(answered) => answered, - Err(why) => { - *mine.lock().expect("the ping's answer") = Err(why); - return; - } - }; - if answered { - if quiet_since.is_some_and(|at| at.elapsed() >= silence) { - *mine.lock().expect("the ping's answer") = - Ok(Some(Reply { secs: began.elapsed().as_secs(), at: unix_now() })); - return; - } - quiet_since = None; - } else if quiet_since.is_none() { - quiet_since = Some(std::time::Instant::now()); - } - std::thread::sleep(std::time::Duration::from_secs(PING_EVERY_SECS)); - } - }) - .expect("the metal loop's ping probe could not be started"); - Self { first, stop, thread } - } - - /// Stop probing, and answer what the first reply after the silence was. - fn end(self) -> Result, Refusal> { - self.stop.store(true, std::sync::atomic::Ordering::SeqCst); - let _ = self.thread.join(); - let answer = self.first.lock().expect("the ping's answer").clone(); - answer.map_err(|why| Refusal::Probe { why }) - } -} - -fn unix_now() -> u64 { - std::time::SystemTime::now() - .duration_since(std::time::UNIX_EPOCH) - .expect("a host clock before 1970 is a host to fix") - .as_secs() -} - /// The loop, over one target. struct Driver { target: Target, @@ -1229,9 +1117,9 @@ impl Driver { } /// What this machine holds on the function the flashed image claims: the - /// interface Ubuntu gave it, its address, its MAC, and how far its own clock - /// stands from this host's. Four reads and not one, so a machine that - /// answers oddly is refused with the read that was odd; none writes. + /// interface Ubuntu gave it, its MAC and its address. Three reads and not + /// one, so a machine that answers oddly is refused with the read that was + /// odd; none writes. fn wire(&self, nic: &str) -> Result { let bad = |why: String| Refusal::Wire { nic: nic.to_string(), why }; let at = shell_word(&format!("/sys/bus/pci/devices/{nic}/net")); @@ -1257,17 +1145,10 @@ impl Driver { &format!("ip -4 -brief addr show {}", shell_word(iface)), ) .map_err(|e| bad(e.to_string()))?; - // The host's own clock at both ends of the read, so what the answer is - // worth is this round trip and not the width of some window. - let before = unix_now(); - let said = self - .ssh("reading the machine's own clock", "date -u +%s") - .map_err(|e| bad(e.to_string()))?; Ok(Wire { iface: iface.to_string(), addr: brief_address(iface, &brief).map_err(bad)?, mac: mac.trim().to_ascii_lowercase(), - skew: clock_skew(before, &said, unix_now()).map_err(bad)?, }) } @@ -1369,26 +1250,11 @@ impl Driver { /// the machine is watched down before it is watched back up: a probe that /// caught dying Ubuntu would read a stick ToyOS had never booted. /// - /// [`Ping`] asks the cable across the span between the two, on the boots - /// that name a function to ask it over and on no other. /// `down` runs the moment the machine has gone down. - fn ride_the_reboot( - &self, - secs: u64, - addr: Option, - down: impl FnOnce(), - ) -> Result<(u64, Option), Refusal> { + fn ride_the_reboot(&self, secs: u64, down: impl FnOnce()) -> Result { self.wait(GOING_DOWN_SECS, "go down", false)?; down(); - let Some(addr) = addr else { - return Ok((self.wait(secs, "come back", true)?, None)); - }; - let ping = Ping::start(addr); - let back = self.wait(secs, "come back", true); - let reply = ping.end(); - // The boot's own failure before this loop's: a machine that never came - // back is that, whatever this host's probe could or could not do. - Ok((back?, reply?)) + self.wait(secs, "come back", true) } /// Wait for the log partition's device node, and say how long it took. @@ -1617,9 +1483,9 @@ pub struct Args { /// volume in this tree that is not the family of code that wrote it. fat32_check: bool, /// The PCI function this boot's image claims, in `/sys/bus/pci/devices`'s - /// spelling. **A boot names it or the cable is not asked at all**: the reads - /// cost four `ssh` round trips and a boot whose judges read no cable would - /// be refused for a fact none of them looks at. + /// spelling. **A boot names it or the function is not read at all**: the + /// reads cost three `ssh` round trips, and a boot that needs no cable would + /// be refused for one that is out. nic: Option, /// The private key the image authorizes, and the ask to talk to the boot /// over its cable: once the machine has gone down, read the log it serves @@ -2003,15 +1869,15 @@ pub fn run(args: &Args) -> Result, Refusal> { let machine = Machine::parse(&driver.ssh("reading the machine's SMBIOS", Machine::QUERY)?) .map_err(Refusal::Machine)?; println!("machine {} {}, BIOS {}", machine.vendor, machine.product, machine.bios); - // Before the flash, because the address a boot of this image could answer - // on is one only the operating system that is still up can be asked for. + // Before the flash: a cable that is out is refused while nothing is + // written, and the operating system that is still up is the one reader of + // this function's MAC that is not the driver under test. let wire = match &args.nic { Some(nic) => { let wire = driver.wire(nic)?; - println!( - "the claimed function {nic} is {} at {}, MAC {}", - wire.iface, wire.addr, wire.mac - ); + // The MAC goes to the readback and not to this log, which is + // quoted in public. + println!("the claimed function {nic} is {} at {}", wire.iface, wire.addr); Some(wire) } None => None, @@ -2032,7 +1898,7 @@ pub fn run(args: &Args) -> 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), || { + let ridden = driver.ride_the_reboot(args.wait_secs, || { if let Some(cable) = &cable { talking = Some(cable.start(std::time::Duration::from_secs(args.wait_secs))); } @@ -2059,18 +1925,8 @@ pub fn run(args: &Args) -> Result, Refusal> { } _ => None, }; - let (back, replied) = ridden?; + let back = ridden?; println!("the machine answered ssh again after {back} s"); - if let Some(wire) = &wire { - match replied { - Some(reply) => println!( - "{} answered a ping {} s into the window, after {PING_SILENCE_SECS} s of \ - silence, at {} UTC seconds", - wire.addr, reply.secs, reply.at - ), - None => println!("nothing answered a ping at {} while the machine was down", wire.addr), - } - } // Before the mount, so the stick's own answer is a number rather than // the reason a mount failed. let stick = driver.wait_for_the_stick()?; @@ -2096,7 +1952,7 @@ pub fn run(args: &Args) -> Result, Refusal> { } println!("toyos-fat32-check: the log partition's {} bytes check out", bytes.len()); } - let boot = boot_file(back, stick, &machine, wire.as_ref(), replied); + let boot = boot_file(back, stick, &machine, wire.as_ref()); judge_and_write_readback(&armed, &loader, &log, heard.as_ref(), args.readback.as_deref(), &boot) .map(Some) } @@ -2355,19 +2211,9 @@ pub const VENDOR_KEY: &str = "machine_vendor"; pub const PRODUCT_KEY: &str = "machine_product"; pub const BIOS_KEY: &str = "machine_bios"; -/// The cable: the address this loop pinged, the MAC of the function holding it, -/// and how far the machine's own clock stood from this host's. **All three -/// together or none**: a judge reading two of them places an observation -/// against a clock it cannot see. -pub const PING_ADDR_KEY: &str = "ping_addr"; +/// The MAC of the function the image claims, as the operating system before +/// the flash read it; absent on a boot that named no function. pub const WIRE_MAC_KEY: &str = "wire_mac"; -pub const CLOCK_SKEW_KEY: &str = "clock_skew"; - -/// How far into that window the first reply came, and when it came on this -/// host's clock. **Both or neither**: an absent pair is `no` said where a zero -/// would be a reply in the first second, and the seconds alone place nothing. -pub const PING_SECS_KEY: &str = "ping_secs"; -pub const PING_AT_KEY: &str = "ping_at"; /// Every file a readback directory carries, so a run that writes none of them /// leaves none of the last run's behind. @@ -2427,26 +2273,14 @@ fn write_readback( /// [`READBACK_BOOT`]'s text: what the host measured about the boot, and the /// machine it ran on. -fn boot_file( - back: u64, - stick: u64, - machine: &Machine, - wire: Option<&Wire>, - replied: Option, -) -> String { +fn boot_file(back: u64, stick: u64, machine: &Machine, wire: Option<&Wire>) -> String { let mut boot = format!( "{BACK_SECS} {back}\n{STICK_SECS_KEY} {stick}\n{VENDOR_KEY} {}\n{PRODUCT_KEY} {}\n\ {BIOS_KEY} {}\n", machine.vendor, machine.product, machine.bios ); if let Some(wire) = wire { - boot.push_str(&format!( - "{PING_ADDR_KEY} {}\n{WIRE_MAC_KEY} {}\n{CLOCK_SKEW_KEY} {}\n", - wire.addr, wire.mac, wire.skew - )); - if let Some(reply) = replied { - boot.push_str(&format!("{PING_SECS_KEY} {}\n{PING_AT_KEY} {}\n", reply.secs, reply.at)); - } + boot.push_str(&format!("{WIRE_MAC_KEY} {}\n", wire.mac)); } boot } @@ -2505,61 +2339,10 @@ pub fn machine(text: &str) -> Result { } } -/// What one boot's readback says about the cable, or `None` where the loop was -/// not asked to reach one. -#[derive(Debug, Clone, PartialEq, Eq)] -pub struct Cable { - pub addr: std::net::Ipv4Addr, - /// The MAC of the function that held that address, as the operating system - /// before this boot reported it. - pub mac: String, - /// That machine's clock minus this host's, in seconds, before the flash. - pub skew: i64, - pub reply: Option, -} - -/// The cable a readback carries, **refusing every partial set by name**: a -/// readback naming a reply and no address is one no judge can read, and -/// answering `None` for it would report a boot that answered as one nothing did. -pub fn cable(text: &str) -> Result, String> { - let addr = word(text, PING_ADDR_KEY); - let mac = word(text, WIRE_MAC_KEY); - let skew: Option = key(text, CLOCK_SKEW_KEY); - let secs: Option = key(text, PING_SECS_KEY); - let at: Option = key(text, PING_AT_KEY); - let named: Vec<&str> = [ - (addr.is_some(), PING_ADDR_KEY), - (mac.is_some(), WIRE_MAC_KEY), - (skew.is_some(), CLOCK_SKEW_KEY), - (secs.is_some(), PING_SECS_KEY), - (at.is_some(), PING_AT_KEY), - ] - .iter() - .filter_map(|(has, name)| has.then_some(*name)) - .collect(); - if named.is_empty() { - return Ok(None); - } - let (Some(addr), Some(mac), Some(skew)) = (addr, mac, skew) else { - return Err(format!( - "this readback names {named:?} and a cable is {PING_ADDR_KEY}, {WIRE_MAC_KEY} and \ - {CLOCK_SKEW_KEY} together" - )); - }; - let addr = addr - .parse() - .map_err(|_| format!("this readback's {PING_ADDR_KEY} reads {addr:?}, which is no address"))?; - let reply = match (secs, at) { - (Some(secs), Some(at)) => Some(Reply { secs, at }), - (None, None) => None, - _ => { - return Err(format!( - "this readback names {named:?}: a reply is {PING_SECS_KEY} and {PING_AT_KEY} \ - together, and the seconds alone place it in neither operating system" - )); - } - }; - Ok(Some(Cable { addr, mac, skew, reply })) +/// The MAC a readback names for the function its image claims, or `None` +/// where the loop was not asked to read one. +pub fn wire_mac(text: &str) -> Option { + word(text, WIRE_MAC_KEY) } fn word(text: &str, name: &str) -> Option { @@ -2900,10 +2683,17 @@ mod tests { #[test] fn the_machine_crosses_in_the_boot_file() { let t14 = Machine::parse("LENOVO\n20W0003AMZ\nN34ET71W (1.71 )\n").expect("three lines"); - let boot = boot_file(47, 0, &t14, None, None); - assert_eq!(machine(&boot), Ok(t14)); + let boot = boot_file(47, 0, &t14, None); + assert_eq!(machine(&boot), Ok(t14.clone())); assert_eq!(back_secs(&boot), Some(47)); assert!(machine("back_secs 47\nmachine_vendor LENOVO\n").is_err()); + assert_eq!(wire_mac(&boot), None); + let wire = Wire { + iface: "enp0s31f6".to_string(), + addr: "192.168.1.46".parse().unwrap(), + mac: "02:00:00:00:00:01".to_string(), + }; + assert_eq!(wire_mac(&boot_file(47, 0, &t14, Some(&wire))), Some(wire.mac)); } /// A judge reading the readback later rules on the boot as the loop did. @@ -2972,56 +2762,11 @@ mod tests { assert_eq!(written(), Err(unheard.to_string().trim_end().to_string())); } - /// **A boot the cable did not answer is not a boot that answered in the - /// first second, and neither is a boot that was never asked.** - #[test] - fn a_ping_nothing_answered_is_written_as_no_answer() { - let asked = "back_secs 61\nstick_secs 2\nping_addr 192.168.1.46\n\ - wire_mac 8c:8c:aa:bb:cc:dd\nclock_skew -3\n"; - let answered = format!("{asked}ping_secs 17\nping_at 1757347715\n"); - let answered_cable = cable(&answered).expect("a whole cable").expect("a cable"); - assert_eq!(answered_cable.addr, std::net::Ipv4Addr::new(192, 168, 1, 46)); - assert_eq!(answered_cable.mac, "8c:8c:aa:bb:cc:dd"); - assert_eq!(answered_cable.skew, -3); - assert_eq!(answered_cable.reply, Some(Reply { secs: 17, at: 1_757_347_715 })); - // A window nothing answered carries neither number. - let silent = cable(asked).expect("a whole cable").expect("a cable"); - assert_eq!(silent.reply, None); - // A boot that named no function to ask over carries none of it. - assert_eq!(cable("back_secs 46\nstick_secs 2\n"), Ok(None)); - assert_eq!(back_secs(&answered), Some(61)); - assert_eq!(stick_secs(&answered), Some(2)); - } - - /// **Every partial set is refused by name**, and the seconds without their - /// wall clock are the one that would otherwise read as no answer at all. - #[test] - fn half_a_cable_is_refused_rather_than_read_as_none() { - let whole = "ping_addr 192.168.1.46\nwire_mac 8c:8c:aa:bb:cc:dd\nclock_skew 0\n"; - for text in [format!("{whole}ping_secs 57\n"), format!("{whole}ping_at 1757347715\n")] { - let why = cable(&text).expect_err("half a reply is not a reply"); - assert!(why.contains("place it in neither operating system"), "{why}"); - } - for text in [ - "ping_addr 1.2.3.4\nwire_mac aa:bb\n", - "ping_addr 1.2.3.4\nclock_skew 1\n", - "ping_secs 57\nping_at 1757347715\n", - "ping_addr 192.168.1.46\n", - ] { - let why = cable(text).expect_err("half a cable is not a cable"); - assert!(why.contains("together"), "{why}"); - } - // A whole set whose address is not one is refused rather than judged. - let why = cable("ping_addr enp0s31f6\nwire_mac aa:bb\nclock_skew 0\n") - .expect_err("an interface name is not an address"); - assert!(why.contains("which is no address"), "{why}"); - } - /// **The address is the one on the function the image claims, and an /// interface with none is refused rather than read as the next one's.** /// `ip -4 -brief` prints the name, the state and then the addresses, and an /// interface whose cable is out prints the first two and stops — which is - /// exactly the machine this loop must not go on to flash and then ping. + /// exactly the machine this loop must not go on to flash. #[test] fn an_interface_with_no_address_is_refused_by_name() { let up = "enp0s31f6 UP 192.168.1.46/24 \n"; @@ -3041,27 +2786,6 @@ mod tests { assert!(brief_address("enp0s31f7", many).unwrap_err().contains("ip -4 -brief")); } - /// **A host clock that stepped backwards across the round trip is the - /// condition this guard exists for**, and it is a refusal by name and not - /// the subtraction overflow it would otherwise be. - #[test] - fn a_skew_read_across_a_clock_this_host_moved_is_refused() { - assert_eq!(clock_skew(1_757_347_700, "1757347703\n", 1_757_347_700), Ok(3)); - assert_eq!(clock_skew(1_757_347_700, "1757347698", 1_757_347_701), Ok(-2)); - - let why = clock_skew(1_757_347_701, "1757347700", 1_757_347_700) - .expect_err("the second read is before the first"); - assert!(why.contains("1757347701 before"), "{why}"); - let why = clock_skew(1_757_347_700, "1757347700", 1_757_347_705) - .expect_err("five seconds is no round trip to spend a judge on"); - assert!(why.contains("across 5 s"), "{why}"); - let why = clock_skew(1_757_347_700, "Tue Sep 9 10:00:00 UTC 2026", 1_757_347_700) - .expect_err("a date is not a count of seconds"); - assert!(why.contains("`date -u +%s` said"), "{why}"); - // A machine answering a second no host second can be subtracted from. - assert!(clock_skew(1_757_347_700, &i64::MIN.to_string(), 1_757_347_700).is_err()); - } - #[test] fn a_node_is_a_whole_scsi_or_nvme_disk_and_nothing_else() { for name in [ @@ -3365,13 +3089,11 @@ mod tests { assert!(!Refusal::Sudo("a password is required".to_string()).about_the_boot()); assert!(!Refusal::Landed { what: "dd".to_string(), want: 1, got: 2 }.about_the_boot()); assert!(!Refusal::NoHome.about_the_boot()); - // The cable's two, which are the machine under the operating system - // before the boot and this host's own binary: neither is the boot. + // The machine under the operating system before the boot is not the boot. assert!( !Refusal::Wire { nic: "0000:00:1f.6".to_string(), why: "x".to_string() } .about_the_boot() ); - assert!(!Refusal::Probe { why: "no ICMP socket".to_string() }.about_the_boot()); } #[test] diff --git a/tests/checks.rs b/tests/checks.rs index 5139e977a76..1ff598bfb2d 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -14,6 +14,8 @@ mod checks { mod audio_checks; #[path = "clock.rs"] mod clock_checks; + #[path = "lan.rs"] + mod lan_checks; #[path = "metal.rs"] mod metal_checks; #[path = "qemu.rs"] @@ -793,6 +795,11 @@ mod checks { usb_checks::transport_break_verdict() } + #[test] + fn metal_lease_judged_is_this_boots_own() { + lan_checks::the_lease_judged_is_this_boots_own(); + } + #[test] fn metal_stop_owes_its_record_and_leaves_no_operation_open() { metal_checks::the_stop_owes_its_record_and_leaves_no_operation_open(); diff --git a/tests/checks/audio.rs b/tests/checks/audio.rs index df340713435..18201a799d0 100644 --- a/tests/checks/audio.rs +++ b/tests/checks/audio.rs @@ -128,6 +128,15 @@ pub fn judges_verdict() -> Result<(), String> { &stall(second.clone(), &format!("{{2.500 soundd}} soundd: repeated completion for free buffer\n{next}")), false, )?; + judged("the T14's stalled client", client_stall_on_metal, T14_STALL, true)?; + judged( + "the T14's stalled client, its second stream opened on a running soundd", + client_stall_on_metal, + &T14_STALL + .replace("{2026-10-03 07:05:06 7.865 soundd} soundd: suspended\n", "") + .replace("{2026-10-03 07:05:07 8.143 soundd} soundd: resumed\n", ""), + false, + )?; let departures = |second: &str| { format!( @@ -195,3 +204,29 @@ pub fn judges_verdict() -> Result<(), String> { judged("a log stall that counted nothing unwritten", log_stall_on_metal, &stalled(64, 0, 11), false)?; Ok(()) } + +/// The T14's `testcases` boot, verbatim: the tone's last records, and the +/// stalled client's from its spawn to its exit. Its first stream opens 3 ms +/// after the tone's left, on a soundd that has not suspended. +const T14_STALL: &str = r"{2026-10-03 07:05:04 5.681 soundd} soundd: client 0 removed (closed) +{2026-10-03 07:05:04 5.681 soundd} soundd: wakes=573 completions=415 submitted=415 underruns=0 drains=0 max_wake_lat_us=2307 max_batch=2 clients=0 deferred=0 starve_max=0 worst_irq_late_us=2288 worst_pickup_us=18 worst_empty=0 worst_batch=2 late_wakes=0 +[2026-10-03 07:05:04 5.682 cpu4] exit: test_rs_audio_tone pid=11 code=0 cpu=2ms +[2026-10-03 07:05:04 5.683 cpu7] spawn: /system/bin/test_rs_hda_client_stall pid=12 tid=0 dst=6 base=0x10000000000 entry=0x1000003df40 root=0x83d6000 symbols=2048KiB (layout=0ms relocs=0ms deps=0ms tls=0ms total=1ms) +{2026-10-03 07:05:04 5.684 tid=1 soundd} soundd: opening stream: 44100Hz 2ch fmt=0 +{2026-10-03 07:05:04 5.684 soundd} soundd: client 0 connected (id=1) +{2026-10-03 07:05:06 7.685 soundd} soundd: wakes=842 completions=690 submitted=690 underruns=104 drains=0 max_wake_lat_us=1746 max_batch=2 clients=1 deferred=0 starve_max=13 worst_irq_late_us=1724 worst_pickup_us=22 worst_empty=0 worst_batch=2 late_wakes=0 +{2026-10-03 07:05:06 7.842 soundd} soundd: client 1 removed (closed) +{2026-10-03 07:05:06 7.842 soundd} soundd: wakes=85 completions=54 submitted=54 underruns=0 drains=0 max_wake_lat_us=70 max_batch=1 clients=0 deferred=0 starve_max=0 worst_irq_late_us=17 worst_pickup_us=53 worst_empty=1 worst_batch=1 late_wakes=0 +[2026-10-03 07:05:06 7.842 cpu7 tid=1] exit: test_rs_hda_client_stall tid=1 code=0 cpu=15ms +{2026-10-03 07:05:06 7.865 soundd} soundd: suspended +{2026-10-03 07:05:07 8.142 tid=1 soundd} soundd: opening stream: 44100Hz 2ch fmt=0 +{2026-10-03 07:05:07 8.142 soundd} soundd: client 0 connected (id=2) +{2026-10-03 07:05:07 8.143 soundd} soundd: resumed +{2026-10-03 07:05:08 9.051 soundd} soundd: client 2 removed (closed) +{2026-10-03 07:05:08 9.051 soundd} soundd: wakes=425 completions=313 submitted=321 underruns=26 drains=0 max_wake_lat_us=88 max_batch=1 clients=0 deferred=0 starve_max=13 worst_irq_late_us=53 worst_pickup_us=34 worst_empty=1 worst_batch=1 late_wakes=0 +[2026-10-03 07:05:08 9.051 cpu0 tid=2] exit: test_rs_hda_client_stall tid=2 code=0 cpu=3ms +{2026-10-03 07:05:08 9.079 soundd} soundd: suspended +{2026-10-03 07:05:08 9.079 soundd} soundd: idle wake 1 (1 records) +{2026-10-03 07:05:08 9.351 pid=12 test-runner} stalled 8 then 2 times, soundd survived +[2026-10-03 07:05:08 9.352 cpu6] exit: test_rs_hda_client_stall pid=12 code=0 cpu=2ms +"; diff --git a/tests/checks/lan.rs b/tests/checks/lan.rs new file mode 100644 index 00000000000..c82439df912 --- /dev/null +++ b/tests/checks/lan.rs @@ -0,0 +1,63 @@ +//! `lan_dhcp_lease`'s judge over the T14's own talking boot, planted as the +//! loop writes one and read as a run reads one. + +use super::*; +use toyos_build::metal::{READBACK_BOOT, READBACK_STREAM, READBACK_TALK}; + +/// The T14's `lantalkcase` boot: the card's hand-over, what netd said of its +/// MAC, its link and its lease, and init's stop. The MAC and the two resolvers +/// are stand-ins that name nobody; every other byte is the machine's. +const LOG: &str = r"[2026-10-03 10:20:01 1.192 cpu0] pcidev: PCI 00:1f.6 [8086:15fc] handed over on slot 0, vector 0x28 +{2026-10-03 10:20:05 5.727 netd} netd: MAC 02:00:00:00:00:01 +[2026-10-03 10:20:08 8.499 cpu4] pcidev: slot 0 took its first message on vector 0x28 +{2026-10-03 10:20:08 8.499 netd} netd: I219: link up at 1000 Mb/s full duplex, 2772 ms after the driver came up +{2026-10-03 10:20:19 19.053 netd} netd: DHCP: lease 192.168.1.48/24 from 192.168.1.1, gateway 192.168.1.1, dns [192.0.2.53 198.51.100.53], 13326 ms after netd came up +{2026-10-03 10:20:19 19.053 netd} netd: ready, at most 103 piped connections (4 MiB each of 16022 MiB total) +{2026-10-03 10:20:20 20.249 init} init: power: the machine stops, and logd makes the log whole first (Reboot) +"; + +/// That boot's `boot.txt`, under the same stand-in. +const BOOT: &str = "back_secs 63\nstick_secs 0\nmachine_vendor LENOVO\nmachine_product 20W0003AMZ\n\ + machine_bios N34ET71W (1.71 )\nwire_mac 02:00:00:00:00:01\n"; + +/// That boot's `talk.txt`, verbatim. +const TALK: &str = "talk_peer 192.168.1.48\ntalk_ping yes\ntalk_exec_status 0\n\ + talk_exec_stdout \"the T14 answers over its own cable\\n\"\ntalk_exec_ms 77\n\ + talk_stream_end open\ntalk_reboot accepted\n"; + +fn judged(log: &str, boot: &str) -> Result<(), String> { + let dir = toyos_tmpdir::TempDir::new("lan-readback"); + metal_checks::plant(&dir, lan::TALK_BOOT, "", log, None); + let home = metal::at(&dir, lan::TALK_BOOT); + for (name, text) in [(READBACK_BOOT, boot), (READBACK_TALK, TALK), (READBACK_STREAM, log)] { + fs::write(home.join(name), text).expect("a planted file"); + } + let back = metal::read_readback(&dir, lan::TALK_BOOT).expect("a planted readback"); + metal_judge("lan_dhcp_lease")(&[&back]) +} + +/// The lease judged is the one this boot took: the T14's boot passes on the +/// address it answered the host at, and reds where netd's record names another +/// address, where netd read another MAC than Ubuntu did, and with no lease. +pub fn the_lease_judged_is_this_boots_own() { + assert_eq!(judged(LOG, BOOT), Ok(())); + let refused = |what: &str, log: &str, boot: &str, says: &str| { + let why = judged(log, boot).expect_err(what); + assert!(why.contains(says), "{what}: {why}"); + }; + refused( + "a lease record naming an address the boot did not answer at", + &LOG.replace("lease 192.168.1.48/24", "lease 192.168.1.46/24"), + BOOT, + "leased 192.168.1.46 and answered for its name at 192.168.1.48", + ); + refused( + "a MAC that is not the one Ubuntu read", + LOG, + &BOOT.replace("wire_mac 02:00:00:00:00:01", "wire_mac 02:00:00:00:00:02"), + "no \"netd: MAC \" record names the MAC the operating system before this boot read", + ); + let unleased: String = + LOG.lines().filter(|l| !l.contains("DHCP: lease")).map(|l| format!("{l}\n")).collect(); + refused("a boot that took no lease", &unleased, BOOT, "took no address from its network"); +} diff --git a/tests/checks/metal.rs b/tests/checks/metal.rs index bcfa00b2c6f..bcf499e6658 100644 --- a/tests/checks/metal.rs +++ b/tests/checks/metal.rs @@ -49,7 +49,13 @@ fn expired_at(reached: i64) -> String { } /// One boot's readback as the loop writes it. -fn plant(dir: &Path, label: &str, page: &str, kernel: &str, verdict: Option<&Refusal>) { +pub(super) fn plant( + dir: &Path, + label: &str, + page: &str, + kernel: &str, + verdict: Option<&Refusal>, +) { let home = metal::at(dir, label); fs::create_dir_all(&home).expect("a readback directory"); let boot = format!( diff --git a/tests/common/audio.rs b/tests/common/audio.rs index ec089233663..b065cf7dd74 100644 --- a/tests/common/audio.rs +++ b/tests/common/audio.rs @@ -106,14 +106,19 @@ pub(crate) const DEVICE_STARTED: &str = "soundd: resumed"; /// buffer it completes, so soundd has to fill the periods the client did not /// cover (`underruns`) and may hold none of them back (`deferred`), across a /// suspend and a resume. +/// +/// The resume is the second stream's, which the job stages. Whether the first +/// stream finds soundd suspended is the job before it: on a shared boot it can +/// open while soundd still plays that job's tail out. pub fn client_stall_on_metal(log: &Serial) -> Result<(), String> { + const JOB: &str = "test_rs_hda_client_stall"; log.must_not_say("repeated completion for free buffer")?; - let window = job_window(log.text(), "test_rs_hda_client_stall", 2)?; - let resumes = window.matches("soundd: resumed").count(); - if resumes < 2 { + let first = job_window(log.text(), JOB, 1)?; + let window = job_window(log.text(), JOB, 2)?; + if !window[first.len()..].contains(DEVICE_STARTED) { return Err(format!( - "soundd resumed {resumes} time(s) — the second stream did not find a suspended \ - daemon, so nothing here tests a resume:\n{window}" + "no `{DEVICE_STARTED}` after the first stream's end — the second stream did not find \ + a suspended daemon, so nothing here tests a resume:\n{window}" )); } if !window.contains("soundd: wakes=") { diff --git a/tests/common/lan.rs b/tests/common/lan.rs index 052e9eeff62..b531fe13106 100644 --- a/tests/common/lan.rs +++ b/tests/common/lan.rs @@ -6,11 +6,7 @@ //! ring — or the one file netd leaves beside them, the lease probe's //! report. The judge reads netd's lines by that name and no other program's. -use toyos_build::bootlog; -use toyos_build::lan::{ - lease_in, link_up_ms, LEASE, LINK_UP, MAC, - READY, -}; +use toyos_build::lan::{lease_in, link_up_ms, LINK_UP, MAC, READY}; use toyos_i219::lease::{self, Event, Verdict}; use super::metal; @@ -29,7 +25,7 @@ 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. +/// The one job on that boot: it holds the machine up. pub const JOBS: &[&str] = &["test_rs_lan_hold"]; /// The boot the host talks to over its own cable: the log it serves, sshd, and @@ -54,22 +50,28 @@ pub fn delivered_on_metal(back: &metal::Readback) -> Result<(), String> { /// The card the T14 arm claims, as the kernel and the manifest spell it. const ID: &str = "8086:15fc"; -/// The PCI function that card is, as `/sys/bus/pci/devices` spells it: the -/// cable the metal loop reaches this boot over while it runs. +/// The PCI function that card is, as `/sys/bus/pci/devices` spells it: where +/// the metal loop reads the cable and the card's MAC before the flash. pub const NIC: &str = "0000:00:1f.6"; -/// The T14's judge: the claim, the card, the lease, and the host's own ping. +/// The T14's judge: the claim, the card, and the lease in netd's own lines. +/// +/// **The host learns the leased address from the boot**: netd answers for the +/// machine's name once it holds a lease, and the loop reads the log served at +/// the address the name answered with. The lease record is held to that +/// address here, so no lease but this boot's own is judged. pub fn on_metal(back: &metal::Readback) -> Result<(), String> { let kernel = back.kernel(); let text = kernel.text(); let mut bad: Vec = Vec::new(); - let cable = back.cable.as_ref().ok_or_else(|| { + let wire_mac = back.wire_mac.as_ref().ok_or_else(|| { format!( - "{}'s readback carries no cable: this boot was driven by a loop that was not asked \ - to reach it over one, so nothing here is about the network", + "{}'s readback names no MAC: this boot was driven by a loop that was not told the \ + function its image claims", back.label ) })?; + let (heard, _) = back.talk()?; // A boot with no hand-over line carries the kernel's refusal instead, and // quoting that is the whole diagnosis. @@ -94,12 +96,13 @@ pub fn on_metal(back: &metal::Readback) -> Result<(), String> { } } - let mac = format!("{MAC}{}", cable.mac); - if !netd.contains(&mac) { + // Neither MAC is printed: a judge's lines are quoted in public. + if !netd.contains(&format!("{MAC}{wire_mac}")) { bad.push(format!( - "no {mac:?} record: the card this boot brought up is not the one that held {} \ - before it", - cable.addr + "no {MAC:?} record names the MAC the operating system before this boot read on \ + {NIC}, which is `{}` in its `{}`: the card this boot brought up is not that one", + toyos_build::metal::WIRE_MAC_KEY, + toyos_build::metal::READBACK_BOOT )); } @@ -110,39 +113,27 @@ pub fn on_metal(back: &metal::Readback) -> Result<(), String> { match lease_in(&netd) { Ok(lease) => { + // The resolvers are counted and not printed, for the same reason. eprintln!( - " [lan] leased {}/{} from {} in {} ms, gateway {}, dns {:?}", - lease.address, lease.prefix, lease.server, lease.ms, lease.gateway, lease.dns + " [lan] leased {}/{} from {} in {} ms, gateway {}, {} resolver(s)", + lease.address, + lease.prefix, + lease.server, + lease.ms, + lease.gateway, + lease.dns.len() ); - if lease.address != cable.addr { + if lease.address != heard.peer { bad.push(format!( - "this boot leased {} and the host pinged {}, which the router hands this \ - MAC under the operating system before it — so either something else \ - answered or that server does not repeat a lease across the two", - lease.address, cable.addr + "this boot leased {} and answered for its name at {}: the address the host \ + reached it at is not the one netd says it leased", + lease.address, heard.peer )); } } Err(why) => bad.push(why), } - match cable.reply { - Some(reply) => { - eprintln!( - " [lan] {} answered the host's ping {} s into the window", - cable.addr, reply.secs - ); - bad.extend( - bootlog::host_second_inside_this_boot(log.text(), cable.skew, LEASE, reply.at).err(), - ); - } - None => bad.push(format!( - "nothing answered a ping at {} while this machine was between its two operating \ - systems", - cable.addr - )), - } - if bad.is_empty() { return Ok(()); } @@ -154,11 +145,6 @@ pub fn on_metal(back: &metal::Readback) -> Result<(), String> { /// 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 @@ -194,31 +180,6 @@ pub fn leased_on_metal(back: &metal::Readback) -> Result<(), String> { 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(()) } diff --git a/tests/common/metal.rs b/tests/common/metal.rs index aadefabdf8a..178444ee2c7 100644 --- a/tests/common/metal.rs +++ b/tests/common/metal.rs @@ -57,10 +57,11 @@ pub struct Arm { /// kernel, and that is what most of the suite wants: it is the artifact the /// owner flashes. pub features: &'static [&'static str], - /// The PCI function this boot's image claims, where the loop reaches the - /// boot over its cable while it runs. **`None` on every boot that does not - /// ask**: a boot whose judges read no cable would be refused for a fact - /// none of them looks at. + /// The PCI function this boot's image claims: the loop refuses, before the + /// flash, a machine holding no address on it, and a judge holds the MAC the + /// boot's driver read to the one the operating system before the flash + /// read off it. **`None` on every boot that does not ask**: a boot that + /// needs no cable would be refused for one that is out. pub nic: Option<&'static str>, /// **The boot is talked to over its own cable.** Its image authorizes a /// key minted beside it, and the loop — told `--talk` — reads the log the @@ -188,10 +189,10 @@ pub struct Readback { pub back_secs: u64, /// How long after that the boot stick's own partition was there again. pub stick_secs: u64, - /// What the host asked the cable while the machine was between its two - /// operating systems, and `None` on every boot that named no function to - /// ask over. - pub cable: Option, + /// The MAC of the function this boot's image claims, as the operating + /// system before the flash read it, and `None` on every boot that named no + /// function. + pub wire_mac: Option, /// The machine the loop read before the flash. pub machine: Result, /// What this boot's judges measured, for the machine's record to judge. @@ -207,7 +208,6 @@ impl Readback { .ok_or_else(|| format!("{label}'s boot file names no `back_secs`: {boot:?}"))?; let stick_secs = toyos_build::metal::stick_secs(boot) .ok_or_else(|| format!("{label}'s boot file names no `stick_secs`: {boot:?}"))?; - let cable = toyos_build::metal::cable(boot).map_err(|why| format!("{label}: {why}"))?; Ok(Readback { label: label.to_string(), home, @@ -217,7 +217,7 @@ impl Readback { log, back_secs, stick_secs, - cable, + wire_mac: toyos_build::metal::wire_mac(boot), machine: toyos_build::metal::machine(boot) .map_err(|why| format!("{label}'s boot file {why}")), numbers: RefCell::new(BTreeMap::new()), diff --git a/tests/toyos-rust-tests/Cargo.lock b/tests/toyos-rust-tests/Cargo.lock index a7acd1875f0..15c89bcf765 100644 --- a/tests/toyos-rust-tests/Cargo.lock +++ b/tests/toyos-rust-tests/Cargo.lock @@ -770,6 +770,15 @@ dependencies = [ "generic-array", ] +[[package]] +name = "inspect" +version = "0.1.0" +dependencies = [ + "toyos", + "toyos-abi", + "toyos-inspect", +] + [[package]] name = "itoa" version = "1.0.18" @@ -2149,6 +2158,7 @@ version = "0.1.0" dependencies = [ "blockd", "cpal", + "inspect", "libloading 0.8.9 (git+https://github.com/ToyOSOrg/rust_libloading?branch=toyos-sdk-0.12)", "memmap2", "rustls", diff --git a/tests/toyos-rust-tests/Cargo.toml b/tests/toyos-rust-tests/Cargo.toml index cffc67a0f95..f4179106954 100644 --- a/tests/toyos-rust-tests/Cargo.toml +++ b/tests/toyos-rust-tests/Cargo.toml @@ -12,6 +12,8 @@ toyos-tco = { path = "../../toyos-tco" } toyos-quiesce = { path = "../../toyos-quiesce" } toyos-i219 = { path = "../../toyos-i219" } toyos-inspect = { path = "../../toyos-inspect" } +# The reader's asker, for `hda_client_stall`. +inspect = { path = "../../userland/inspect" } # blockd's client and its NVMe driver, for `blockd_io`, and the FAT32 crate it # writes a volume through a session with. blockd = { path = "../../userland/blockd" } diff --git a/tests/toyos-rust-tests/src/bin/hda_client_stall.rs b/tests/toyos-rust-tests/src/bin/hda_client_stall.rs index bc7623d434b..80bed5bcfa4 100644 --- a/tests/toyos-rust-tests/src/bin/hda_client_stall.rs +++ b/tests/toyos-rust-tests/src/bin/hda_client_stall.rs @@ -13,11 +13,11 @@ //! run measured). This one empties it on purpose, for longer than the ring //! takes to come round. -use std::sync::atomic::{AtomicU64, Ordering}; -use std::sync::Arc; -use std::time::Duration; +use std::sync::mpsc; +use std::time::{Duration, Instant}; use cpal::traits::{DeviceTrait, HostTrait, StreamTrait}; +use toyos_inspect::{Value, SOUND}; const FREQ_HZ: f64 = 440.0; const AMPLITUDE: f64 = 16000.0; @@ -32,25 +32,33 @@ const STALL: Duration = Duration::from_millis(60); const STALLS: u64 = 8; const CALLBACKS_BETWEEN_STALLS: u64 = 60; +/// How long each wait here has before it panics by name. A hang ceiling: what +/// each waits on is a quarter of a second or a lap of the ring away. +const WITHIN: Duration = Duration::from_secs(5); + fn main() { - let first = play(STALLS); + play(STALLS); // A second stream over the same device, after soundd has drained and // suspended: on a ring the drain gives the periods up rather than holding // them, so what the resume primes and where in the ring it starts are both // state the first stream left behind. - let second = play(2); - println!("stalled {first} then {second} times, soundd survived"); + await_suspended(); + play(2); + println!("stalled {STALLS} then 2 times, soundd survived"); } -fn play(stalls_wanted: u64) -> u64 { +/// One stream of `stalls + 1` stretches of tone with a stall after each but +/// the last, closed when the last has played: the laps of the ring that follow +/// the last stall are played to a client that is still there, as every other +/// stall's are. +fn play(stalls: u64) { let host = cpal::default_host(); let device = host.default_output_device().expect("no audio output device"); let config = device.default_output_config().expect("no audio config"); let sample_rate = config.sample_rate() as f64; let channels = config.channels() as usize; - let stalls = Arc::new(AtomicU64::new(0)); - let stalls_cb = stalls.clone(); + let (ended, stretch_ended) = mpsc::channel(); let mut n: u64 = 0; let mut callbacks: u64 = 0; @@ -64,12 +72,14 @@ fn play(stalls_wanted: u64) -> u64 { n += 1; } callbacks += 1; - if callbacks % CALLBACKS_BETWEEN_STALLS == 0 - && stalls_cb.load(Ordering::Relaxed) < stalls_wanted - { - stalls_cb.fetch_add(1, Ordering::Relaxed); + let stretch = callbacks / CALLBACKS_BETWEEN_STALLS; + if callbacks % CALLBACKS_BETWEEN_STALLS != 0 || stretch > stalls + 1 { + return; + } + if stretch <= stalls { std::thread::sleep(STALL); } + ended.send(()).expect("`play` holds the receiver until the last stretch ends"); }, |err| eprintln!("audio error: {err}"), None, @@ -77,14 +87,41 @@ fn play(stalls_wanted: u64) -> u64 { .expect("failed to build audio stream"); stream.play().expect("failed to play"); - while stalls.load(Ordering::Relaxed) < stalls_wanted { - std::thread::sleep(Duration::from_millis(50)); + let stretches = stalls + 1; + for stretch in 1..=stretches { + if let Err(why) = stretch_ended.recv_timeout(WITHIN) { + panic!("stretch {stretch} of {stretches} did not end within {WITHIN:?}: {why}"); + } } - // Long enough for the pipeline to play out and soundd to suspend: the - // drain is one lap of the ring and the second stream has to find a - // suspended daemon for the resume to be the thing under test. - std::thread::sleep(Duration::from_millis(500)); drop(stream); - std::thread::sleep(Duration::from_millis(300)); - stalls.load(Ordering::Relaxed) +} + +/// Wait until soundd says its device stream is stopped. +/// +/// soundd tells no client that it suspended: its `inspect` answer is the one +/// place a client reads it. The mix loop publishes that once a wake, and the +/// device playing its tail out wakes it once a period, so a period is how +/// often it is asked. +fn await_suspended() { + let deadline = Instant::now() + WITHIN; + loop { + let sound = + inspect::ask(SOUND).unwrap_or_else(|why| panic!("soundd's inspect answer: {why}")); + let (Some(Value::Text(state)), Some(&Value::U64(frames)), Some(&Value::U64(rate))) = ( + sound.get("sound.stream.state"), + sound.get("sound.period_frames"), + sound.get("sound.rate_hz"), + ) else { + panic!("soundd's snapshot names no stream state and period: {sound:?}"); + }; + if state == "suspended" { + return; + } + assert!( + Instant::now() < deadline, + "soundd's stream still reads `{state}` {WITHIN:?} after its only client closed, so \ + the second stream has no suspended daemon to resume" + ); + std::thread::sleep(Duration::from_nanos(1_000_000_000 * frames / rate)); + } } diff --git a/tests/toyos-rust-tests/src/bin/lan_hold.rs b/tests/toyos-rust-tests/src/bin/lan_hold.rs index feb9350eada..480d238c6b8 100644 --- a/tests/toyos-rust-tests/src/bin/lan_hold.rs +++ b/tests/toyos-rust-tests/src/bin/lan_hold.rs @@ -1,7 +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. +//! Hold the boot open, 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; diff --git a/tests/toyos.rs b/tests/toyos.rs index 097e00fe3f9..7ccdc6930f9 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -94,8 +94,7 @@ const RUST_SKIP: &[&str] = &[ // does not give: the `process_tree` metal row runs it on tests/proctreecase. "process_tree", // It asserts nothing at all: it holds a `tests/lanleasecase` boot open for - // twenty seconds so the host can reach this machine over the cable. On a - // shared boot it would be twenty seconds of nothing. + // 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 // unless the host's `reboot` over ssh ends it first. `lan_talk` rides it. @@ -210,7 +209,7 @@ const METAL: &[(&str, metal::Metal)] = &[ ), ( // 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. + // stick. "lan_lease_report", metal::Metal { arms: LANLEASECASE, judge: |b| lan::leased_on_metal(b[0]) }, ), @@ -709,8 +708,8 @@ const PROCTREECASE: &[metal::Arm] = /// netd in front of the T14's I219 with its 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 [`LANTALKCASE`] does. +/// report is on the log volume. It names the I219, so the loop refuses a cable +/// that is out before it flashes, as [`LANTALKCASE`] does. const LANLEASECASE: &[metal::Arm] = &[metal::Arm { nic: Some(lan::NIC), ..metal::once(lan::LEASE_BOOT, lan::LEASE_CONFIG, &[], lan::JOBS) @@ -718,8 +717,7 @@ const LANLEASECASE: &[metal::Arm] = &[metal::Arm { /// 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. +/// runs a command on it and tells it to reboot. const LANTALKCASE: &[metal::Arm] = &[metal::Arm { talk: true, nic: Some(lan::NIC), diff --git a/userland/inspect/Cargo.toml b/userland/inspect/Cargo.toml index 55a04b24f39..90cdbe67045 100644 --- a/userland/inspect/Cargo.toml +++ b/userland/inspect/Cargo.toml @@ -4,6 +4,12 @@ version = "0.1.0" edition = "2024" license = "MIT OR Apache-2.0" +# The library is the question the reader puts to one owner, so a program that +# waits on an owner's state asks as the reader does; the reader is +# `src/main.rs`. +[lib] +doctest = false + [dependencies] toyos = { path = "../../toyos" } toyos-abi = { path = "../../toyos-abi" } diff --git a/userland/inspect/src/lib.rs b/userland/inspect/src/lib.rs new file mode 100644 index 00000000000..9e7586b9213 --- /dev/null +++ b/userland/inspect/src/lib.rs @@ -0,0 +1,69 @@ +//! The reader's one question: an owner's snapshot, asked through the connector +//! this process was given for that owner's port. `/system/bin/inspect` is +//! `src/main.rs` beside this; a library so a program that waits on an owner's +//! state asks as the reader does. + +use std::collections::BTreeMap; +use std::time::{Duration, Instant}; + +use toyos::endow::{self, EndowError}; +use toyos::ipc::{self, FrameRx, RxStep}; +use toyos::poller::{Poller, READABLE}; +use toyos_inspect::{Owner, Value, MAX_SNAPSHOT_BYTES, MSG_INSPECT, MSG_SNAPSHOT}; + +/// How long one owner has to answer. +/// +/// Policy, and generous: an owner answers on its next loop pass, and every +/// owner's pass is bounded by a frame or a period. What this bounds is an owner +/// that is wedged, which the reader names instead of joining it. +const ANSWER_BOUND: Duration = Duration::from_secs(2); + +const _: () = assert!( + MAX_SNAPSHOT_BYTES == ipc::MAX_FRAME_LEN as usize, + "a snapshot is one frame, so its bound is the frame's" +); + +/// One owner's snapshot, or why there is none. +pub fn ask(owner: Owner) -> Result, String> { + let conn = endow::service(owner.port).map_err(|e| match e { + EndowError::NotEndowed => format!( + "this program holds no `{}` connector, so {} is not its to read", + owner.port, owner.root + ), + EndowError::ServerGone => format!("`{}` is not running: its port is closed", owner.port), + EndowError::Refused(e) => format!("the kernel refused a connection to `{}` ({e:?})", owner.port), + })?; + conn.signal(MSG_INSPECT) + .map_err(|e| format!("`{}` would not take the request ({e:?})", owner.port))?; + + let poller = Poller::new(1); + let mut rx: Box> = Box::new(FrameRx::new()); + let deadline = Instant::now() + ANSWER_BOUND; + loop { + match rx.pump(&conn) { + RxStep::Frame { msg_type: MSG_SNAPSHOT, payload_len } => { + return toyos_inspect::decode(rx.payload(payload_len), owner) + .map_err(|why| format!("`{}` answered something that is not a snapshot: {why}", owner.port)); + } + RxStep::Frame { msg_type, .. } => { + return Err(format!("`{}` answered message {msg_type:#x}, not a snapshot", owner.port)); + } + RxStep::Eof => { + return Err(format!( + "`{}` closed the connection without answering", + owner.port + )); + } + RxStep::Malformed => { + return Err(format!("`{}` sent a frame this protocol cannot describe", owner.port)); + } + RxStep::Idle => {} + } + let left = deadline.saturating_duration_since(Instant::now()); + if left.is_zero() { + return Err(format!("`{}` did not answer within {ANSWER_BOUND:?}", owner.port)); + } + poller.watch(&conn, READABLE, 0); + poller.wait(1, left.as_nanos() as u64, |_| {}); + } +} diff --git a/userland/inspect/src/main.rs b/userland/inspect/src/main.rs index e0b5a07682b..cb71ae4373e 100644 --- a/userland/inspect/src/main.rs +++ b/userland/inspect/src/main.rs @@ -5,37 +5,24 @@ //! selector can reach, through the connector this process was given for that //! owner's port, and prints the paths the selector matches as `path = value` //! lines sorted by path, or as one JSON object. The grammar, the wire form and -//! the renderings are `toyos-inspect`'s; this file is the connections. +//! the renderings are `toyos-inspect`'s, and the question put to one owner is +//! [`inspect::ask`]; this file is which owners are asked, and the inventory. //! //! **An owner this process holds no connector for is a refusal, not a gap**: //! it is named on stderr and the run exits 2, so a pipe never mistakes a partial //! answer for a whole one. The same for an owner whose port is closed, one that -//! does not answer within [`ANSWER_BOUND`], and one whose answer is not a -//! snapshot for its own root. Exit 1 is every owner answering and nothing +//! does not answer within [`inspect::ask`]'s bound, and one whose answer is not +//! a snapshot for its own root. Exit 1 is every owner answering and nothing //! matching, as `grep` says it. use std::collections::BTreeMap; use std::io::Write; -use std::time::{Duration, Instant}; -use toyos::endow::{self, EndowError, Endowments, SYSCAP_LABEL}; +use inspect::ask; +use toyos::endow::{Endowments, SYSCAP_LABEL}; use toyos::syscap::SysCap; use toyos_abi::inventory::{RawRecord, Record}; -use toyos::ipc::{self, FrameRx, RxStep}; -use toyos::poller::{Poller, READABLE}; -use toyos_inspect::{Invocation, Owner, Value, MAX_SNAPSHOT_BYTES, MSG_INSPECT, MSG_SNAPSHOT}; - -/// How long one owner has to answer. -/// -/// Policy, and generous: an owner answers on its next loop pass, and every -/// owner's pass is bounded by a frame or a period. What this bounds is an owner -/// that is wedged, which the reader names instead of joining it. -const ANSWER_BOUND: Duration = Duration::from_secs(2); - -const _: () = assert!( - MAX_SNAPSHOT_BYTES == ipc::MAX_FRAME_LEN as usize, - "a snapshot is one frame, so its bound is the frame's" -); +use toyos_inspect::{Invocation, Value}; const USAGE: &str = "usage: inspect [--json] [SELECTOR]"; @@ -93,51 +80,6 @@ fn main() { }); } -/// One owner's snapshot, or why there is none. -fn ask(owner: Owner) -> Result, String> { - let conn = endow::service(owner.port).map_err(|e| match e { - EndowError::NotEndowed => format!( - "this program holds no `{}` connector, so {} is not its to read", - owner.port, owner.root - ), - EndowError::ServerGone => format!("`{}` is not running: its port is closed", owner.port), - EndowError::Refused(e) => format!("the kernel refused a connection to `{}` ({e:?})", owner.port), - })?; - conn.signal(MSG_INSPECT) - .map_err(|e| format!("`{}` would not take the request ({e:?})", owner.port))?; - - let poller = Poller::new(1); - let mut rx: Box> = Box::new(FrameRx::new()); - let deadline = Instant::now() + ANSWER_BOUND; - loop { - match rx.pump(&conn) { - RxStep::Frame { msg_type: MSG_SNAPSHOT, payload_len } => { - return toyos_inspect::decode(rx.payload(payload_len), owner) - .map_err(|why| format!("`{}` answered something that is not a snapshot: {why}", owner.port)); - } - RxStep::Frame { msg_type, .. } => { - return Err(format!("`{}` answered message {msg_type:#x}, not a snapshot", owner.port)); - } - RxStep::Eof => { - return Err(format!( - "`{}` closed the connection without answering", - owner.port - )); - } - RxStep::Malformed => { - return Err(format!("`{}` sent a frame this protocol cannot describe", owner.port)); - } - RxStep::Idle => {} - } - let left = deadline.saturating_duration_since(Instant::now()); - if left.is_zero() { - return Err(format!("`{}` did not answer within {ANSWER_BOUND:?}", owner.port)); - } - poller.watch(&conn, READABLE, 0); - poller.wait(1, left.as_nanos() as u64, |_| {}); - } -} - /// The kernel's inventory, asked with this process's `SysCap`, and the /// machine `SYS_SYSINFO`'s ambient header describes, as `dev.*` paths. fn inventory() -> Result, String> {