From 0574212d453a8f28c8cd9165b280d052480be851 Mon Sep 17 00:00:00 2001 From: japabu Date: Sat, 3 Oct 2026 11:52:51 +0200 Subject: [PATCH 1/5] Two T14 judges judge what their boots stage: the second stream's resume, and this boot's own lease hda_client_stall. The judge wanted two `soundd: resumed` in the job's window, one per stream. On the shared `testcases` boot the job's first stream opens 3 ms after the tone's is removed (5.681 to 5.684 on the T14 run of #638's head), and soundd suspends 20 to 25 ms after a removal, so the first stream joins a running soundd and the window carries one resume: the second stream's, which is the one the job stages. The judge now asks for a resume after the first session's end. The job itself waited a flat 500 ms before closing each stream and a flat 300 ms after it. A stream now plays one more stretch of tone after its last stall and is closed on the callback that ends it, and the second stream opens once soundd's own `inspect` answer reads `suspended`, asked once a period, each wait bounded at 5 s and panicking by name. lan_dhcp_lease. The loop read the address Ubuntu held on the I219 before the flash, pinged it across the reboot, and the judge refused a boot whose lease was another address or whose reply fell outside the boot by the two operating systems' clocks. The bench's router leases ToyOS another address than Ubuntu (192.168.1.48 against .46), so the reply it counted was Ubuntu's, after the reset. The talking boot already tells the host its address: netd answers for the machine's name once it holds a lease, and the loop reads the log served there and pings it. The judge now holds the lease record in netd's own lines to that address and to that ping. With no judge of it left, the ping across the reboot goes: `Ping`, `Reply`, the address and clock-skew reads of `Driver::wire`, four keys of `boot.txt`, `Refusal::Probe`, `bootlog::host_second_inside_this_boot` and its margin. `--nic` still reads the function's MAC, which the judge holds netd's to. `lan_lease_report` printed that ping and judged nothing by it; its boot no longer names the function. Both judges are checked against the T14's own lines: each passes today's capture and reds on it with the resume, the address, the ping or the MAC taken away. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm --- src/bootlog.rs | 182 -------- src/metal.rs | 406 ++---------------- tests/checks.rs | 7 + tests/checks/audio.rs | 35 ++ tests/checks/lan.rs | 73 ++++ tests/checks/metal.rs | 2 +- tests/common/audio.rs | 15 +- tests/common/lan.rs | 96 ++--- tests/common/metal.rs | 19 +- .../src/bin/hda_client_stall.rs | 102 ++++- tests/toyos-rust-tests/src/bin/lan_hold.rs | 7 +- tests/toyos.rs | 17 +- 12 files changed, 288 insertions(+), 673 deletions(-) create mode 100644 tests/checks/lan.rs 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/metal.rs b/src/metal.rs index 5f6381b9c75..31fcbcd2f0a 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,9 @@ 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 and the MAC it holds on the + /// function the flashed image claims. 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 @@ -314,12 +300,7 @@ impl fmt::Display for Refusal { Self::Wire { nic, why } => write!( f, "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}" + image claims: {why}" ), Self::Silent { what, secs } => write!( f, @@ -1058,124 +1039,8 @@ fn lid_policy(text: &str) -> Result<(), Refusal> { #[derive(Debug, Clone, PartialEq, Eq)] pub struct Wire { pub iface: String, - 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 -/// form is ` ...`, and an interface with no address has no -/// third field at all, which is the machine saying the cable is out. -fn brief_address(iface: &str, text: &str) -> Result { - let line = text - .lines() - .find(|l| l.split_whitespace().next() == Some(iface)) - .ok_or_else(|| format!("`ip -4 -brief addr show {iface}` said {text:?}"))?; - let cidr = line - .split_whitespace() - .nth(2) - .ok_or_else(|| format!("{iface} holds no IPv4 address: {line:?}"))?; - cidr.split('/') - .next() - .unwrap_or(cidr) - .parse() - .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. @@ -1229,9 +1094,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 and its MAC. Two reads and not one, so a + /// machine that answers oddly is refused with the read that was odd; + /// neither 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")); @@ -1251,24 +1116,7 @@ impl Driver { &format!("cat {}", shell_word(&format!("/sys/class/net/{iface}/address"))), ) .map_err(|e| bad(e.to_string()))?; - let brief = self - .ssh( - "reading the claimed function's address", - &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)?, - }) + Ok(Wire { iface: iface.to_string(), mac: mac.trim().to_ascii_lowercase() }) } /// The loop refuses to run at all until the rule is on the machine. @@ -1369,26 +1217,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 +1450,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 two `ssh` round trips and a boot whose judges read no MAC + /// would be refused for a fact none of them looks at. 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 +1836,12 @@ 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, because 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 - ); + println!("the claimed function {nic} is {}, MAC {}", wire.iface, wire.mac); Some(wire) } None => None, @@ -2032,7 +1862,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 +1889,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 +1916,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 +2175,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 +2237,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 +2303,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 +2647,13 @@ 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(), mac: "8c:8c:aa:bb:cc:dd".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,96 +2722,6 @@ 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. - #[test] - fn an_interface_with_no_address_is_refused_by_name() { - let up = "enp0s31f6 UP 192.168.1.46/24 \n"; - assert_eq!(brief_address("enp0s31f6", up), Ok("192.168.1.46".parse().unwrap())); - - let down = "enp0s31f6 DOWN \n"; - assert!(brief_address("enp0s31f6", down).unwrap_err().contains("no IPv4 address")); - - // Another interface's line is not this one's answer, however many are - // printed. - let many = "lo UNKNOWN 127.0.0.1/8\n\ - enp0s31f6 UP 192.168.1.46/24\n\ - wlp9s0 UP 192.168.1.244/24\n\ - tailscale0 UNKNOWN 100.92.92.12/32\n"; - assert_eq!(brief_address("enp0s31f6", many), Ok("192.168.1.46".parse().unwrap())); - assert_eq!(brief_address("wlp9s0", many), Ok("192.168.1.244".parse().unwrap())); - 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 +3025,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..8e48eb2e0a7 --- /dev/null +++ b/tests/checks/lan.rs @@ -0,0 +1,73 @@ +//! `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, verbatim: the card's hand-over, what netd +/// said of its MAC, its link and its lease, and init's stop. +const LOG: &str = r"[2026-10-03 06:50:58 1.192 cpu0] pcidev: PCI 00:1f.6 [8086:15fc] handed over on slot 0, vector 0x28 +{2026-10-03 06:51:02 5.727 netd} netd: MAC 38:f3:ab:35:37:3b +[2026-10-03 06:51:05 8.517 cpu4] pcidev: slot 0 took its first message on vector 0x28 +{2026-10-03 06:51:05 8.517 netd} netd: I219: link up at 1000 Mb/s full duplex, 2789 ms after the driver came up +{2026-10-03 06:51:16 19.070 netd} netd: DHCP: lease 192.168.1.48/24 from 192.168.1.1, gateway 192.168.1.1, dns [194.230.55.96 212.98.37.130], 13342 ms after netd came up +{2026-10-03 06:51:16 19.070 netd} netd: ready, at most 103 piped connections (4 MiB each of 16020 MiB total) +{2026-10-03 06:51:17 20.351 init} init: power: the machine stops, and logd makes the log whole first (Reboot) +"; + +/// That boot's `boot.txt`, verbatim: the loop that wrote it also pinged the +/// address Ubuntu held on this MAC, `192.168.1.46`. +const BOOT: &str = "back_secs 70\nstick_secs 0\nmachine_vendor LENOVO\nmachine_product 20W0003AMZ\n\ + machine_bios N34ET71W (1.71 )\nping_addr 192.168.1.46\n\ + wire_mac 38:f3:ab:35:37:3b\nclock_skew 1\nping_secs 64\nping_at 1791010315\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 86\n\ + talk_stream_end open\ntalk_reboot accepted\n"; + +fn judged(log: &str, boot: &str, talk: &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, whatever Ubuntu held before it, and reds +/// where netd's record names another address, where that address answered no +/// ping, 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, TALK), Ok(())); + let refused = |what: &str, log: &str, boot: &str, talk: &str, says: &str| { + let why = judged(log, boot, talk).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, + TALK, + "leased 192.168.1.46 and answered for its name at 192.168.1.48", + ); + refused( + "a leased address that answered no ping", + LOG, + BOOT, + &TALK.replace("talk_ping yes", "talk_ping no"), + "answered no ping of the host's", + ); + refused( + "a MAC that is not the one Ubuntu read", + LOG, + &BOOT.replace("wire_mac 38:f3:ab:35:37:3b", "wire_mac 38:f3:ab:35:37:3c"), + TALK, + "no \"netd: MAC 38:f3:ab:35:37:3c\" record", + ); + 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, TALK, "took no address from its network"); +} diff --git a/tests/checks/metal.rs b/tests/checks/metal.rs index bcfa00b2c6f..1074ed46388 100644 --- a/tests/checks/metal.rs +++ b/tests/checks/metal.rs @@ -49,7 +49,7 @@ 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..07fd9b2aa89 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. 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,29 @@ 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 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, the lease in netd's own lines, and +/// the host's ping of the address that lease names. +/// +/// **The host learns that 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 and pings it. 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 +97,11 @@ pub fn on_metal(back: &metal::Readback) -> Result<(), String> { } } - let mac = format!("{MAC}{}", cable.mac); + let mac = format!("{MAC}{wire_mac}"); if !netd.contains(&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: the card this boot brought up is not the one the operating \ + system before it read on {NIC}" )); } @@ -114,33 +116,27 @@ pub fn on_metal(back: &metal::Readback) -> Result<(), String> { " [lan] leased {}/{} from {} in {} ms, gateway {}, dns {:?}", lease.address, lease.prefix, lease.server, lease.ms, lease.gateway, lease.dns ); - 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 + match heard.ping { + Some(true) => eprintln!( + " [lan] {}, where this boot answered for its name, answered the host's ping", + heard.peer + ), + Some(false) => bad.push(format!( + "{}, where this boot answered for its name, answered no ping of the host's", + heard.peer )), + None => bad.push(format!("the host asked {} for no ping", heard.peer)), } if bad.is_empty() { @@ -154,11 +150,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 +185,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..abcc4cf9d15 100644 --- a/tests/common/metal.rs +++ b/tests/common/metal.rs @@ -57,10 +57,10 @@ 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, where 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 whose + /// judges read no MAC would be refused for a fact none of them looks at. 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 +188,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 +207,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 +216,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/src/bin/hda_client_stall.rs b/tests/toyos-rust-tests/src/bin/hda_client_stall.rs index bc7623d434b..3e0eb99322f 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,13 @@ //! 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::ipc::{FrameRx, RxStep}; +use toyos::poller::{Poller, READABLE}; +use toyos_inspect::{Value, MAX_SNAPSHOT_BYTES, MSG_INSPECT, MSG_SNAPSHOT, SOUND}; const FREQ_HZ: f64 = 440.0; const AMPLITUDE: f64 = 16000.0; @@ -32,25 +34,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 +74,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 +89,62 @@ 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)); + for stretch in 1..=stalls + 1 { + if let Err(why) = stretch_ended.recv_timeout(WITHIN) { + panic!("stretch {stretch} of {} did not end {WITHIN:?} after the one before it: {why}", stalls + 1); + } } - // 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_sound(); + 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)); + } +} + +/// soundd's own `inspect` answer, within [`WITHIN`]. +fn inspect_sound() -> std::collections::BTreeMap { + let conn = toyos::endow::service(SOUND.port).expect("a connection to soundd"); + conn.signal(MSG_INSPECT).expect("soundd takes an inspect request"); + let poller = Poller::new(1); + let mut rx: Box> = Box::new(FrameRx::new()); + let deadline = Instant::now() + WITHIN; + loop { + match rx.pump(&conn) { + RxStep::Frame { msg_type: MSG_SNAPSHOT, payload_len } => { + return toyos_inspect::decode(rx.payload(payload_len), SOUND) + .unwrap_or_else(|why| panic!("soundd's snapshot: {why}")); + } + RxStep::Idle => {} + other => panic!("soundd answered inspect with {other:?}, not a snapshot"), + } + let left = deadline.saturating_duration_since(Instant::now()); + assert!(!left.is_zero(), "soundd did not answer inspect within {WITHIN:?}"); + poller.watch(&conn, READABLE, 0); + poller.wait(1, left.as_nanos() as u64, |_| {}); + } } 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..5dc4f2a5135 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,17 +708,13 @@ 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. -const LANLEASECASE: &[metal::Arm] = &[metal::Arm { - nic: Some(lan::NIC), - ..metal::once(lan::LEASE_BOOT, lan::LEASE_CONFIG, &[], lan::JOBS) -}]; +/// report is on the log volume. +const LANLEASECASE: &[metal::Arm] = + &[metal::once(lan::LEASE_BOOT, lan::LEASE_CONFIG, &[], lan::JOBS)]; /// 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), From 8cf832d07ba8ad1750b089c6b9ccc6af8cd1ef32 Mon Sep 17 00:00:00 2001 From: japabu Date: Sat, 3 Oct 2026 11:57:19 +0200 Subject: [PATCH 2/5] issues: the two judges' issues and the cable judge's two premises close; three flat waits and a printed stream error are filed Closed, each by the judge no longer resting on what it named: - hda-client-stall-reads-one-resume-where-its-judge-wants-two: the judge asks for the second stream's resume. Its exit is the row passing on the T14 run of this head. - the-benchs-router-leases-toyos-another-address-than-ubuntu: the judge holds the lease to the address this boot answered the host at. Its exit is the row passing on the T14 run of this head. - the-cable-judge-spends-two-premises-nothing-has-measured: no judge compares the two operating systems' clocks or addresses any more, and the reads that fed the comparison are gone. Filed, found beside the task and not fixed: - audio/the-tone-client-waits-a-flat-200-ms-for-its-tail - audio/hda-client-stall-prints-a-stream-error-and-passes - build/lan-hold-holds-two-boots-open-for-a-flat-twenty-seconds Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm --- ...-stall-prints-a-stream-error-and-passes.md | 23 +++++ ...ds-one-resume-where-its-judge-wants-two.md | 83 ------------------- ...client-waits-a-flat-200-ms-for-its-tail.md | 22 +++++ ...wo-boots-open-for-a-flat-twenty-seconds.md | 17 ++++ ...eases-toyos-another-address-than-ubuntu.md | 37 --------- ...pends-two-premises-nothing-has-measured.md | 28 ------- 6 files changed, 62 insertions(+), 148 deletions(-) create mode 100644 issues/audio/hda-client-stall-prints-a-stream-error-and-passes.md delete mode 100644 issues/audio/hda-client-stall-reads-one-resume-where-its-judge-wants-two.md create mode 100644 issues/audio/the-tone-client-waits-a-flat-200-ms-for-its-tail.md create mode 100644 issues/build/lan-hold-holds-two-boots-open-for-a-flat-twenty-seconds.md delete mode 100644 issues/hardware/the-benchs-router-leases-toyos-another-address-than-ubuntu.md delete mode 100644 issues/hardware/the-cable-judge-spends-two-premises-nothing-has-measured.md 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..48e180e7ce8 --- /dev/null +++ b/issues/build/lan-hold-holds-two-boots-open-for-a-flat-twenty-seconds.md @@ -0,0 +1,17 @@ +--- +status: open +kind: finding +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. 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`. From c154c22203012bd7c270dbd611b58dd58c91d989 Mon Sep 17 00:00:00 2001 From: japabu Date: Sat, 3 Oct 2026 12:07:48 +0200 Subject: [PATCH 3/5] The stall job's hang names its stretch in one line; the lease check's fixture says what its extra keys are Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm --- tests/checks/lan.rs | 7 ++++--- tests/checks/metal.rs | 8 +++++++- tests/common/lan.rs | 2 +- tests/toyos-rust-tests/src/bin/hda_client_stall.rs | 5 +++-- 4 files changed, 15 insertions(+), 7 deletions(-) diff --git a/tests/checks/lan.rs b/tests/checks/lan.rs index 8e48eb2e0a7..e145faa61d4 100644 --- a/tests/checks/lan.rs +++ b/tests/checks/lan.rs @@ -15,8 +15,8 @@ const LOG: &str = r"[2026-10-03 06:50:58 1.192 cpu0] pcidev: PCI 00:1f.6 [8086:1 {2026-10-03 06:51:17 20.351 init} init: power: the machine stops, and logd makes the log whole first (Reboot) "; -/// That boot's `boot.txt`, verbatim: the loop that wrote it also pinged the -/// address Ubuntu held on this MAC, `192.168.1.46`. +/// That boot's `boot.txt`, verbatim. It also names `192.168.1.46`, the +/// address Ubuntu held on this MAC, which no judge reads. const BOOT: &str = "back_secs 70\nstick_secs 0\nmachine_vendor LENOVO\nmachine_product 20W0003AMZ\n\ machine_bios N34ET71W (1.71 )\nping_addr 192.168.1.46\n\ wire_mac 38:f3:ab:35:37:3b\nclock_skew 1\nping_secs 64\nping_at 1791010315\n"; @@ -68,6 +68,7 @@ pub fn the_lease_judged_is_this_boots_own() { TALK, "no \"netd: MAC 38:f3:ab:35:37:3c\" record", ); - let unleased: String = LOG.lines().filter(|l| !l.contains("DHCP: lease")).map(|l| format!("{l}\n")).collect(); + 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, TALK, "took no address from its network"); } diff --git a/tests/checks/metal.rs b/tests/checks/metal.rs index 1074ed46388..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. -pub(super) 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/lan.rs b/tests/common/lan.rs index 07fd9b2aa89..a3cf7db9a35 100644 --- a/tests/common/lan.rs +++ b/tests/common/lan.rs @@ -25,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. +/// 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 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 3e0eb99322f..69a249e3f5f 100644 --- a/tests/toyos-rust-tests/src/bin/hda_client_stall.rs +++ b/tests/toyos-rust-tests/src/bin/hda_client_stall.rs @@ -89,9 +89,10 @@ fn play(stalls: u64) { .expect("failed to build audio stream"); stream.play().expect("failed to play"); - for stretch in 1..=stalls + 1 { + let stretches = stalls + 1; + for stretch in 1..=stretches { if let Err(why) = stretch_ended.recv_timeout(WITHIN) { - panic!("stretch {stretch} of {} did not end {WITHIN:?} after the one before it: {why}", stalls + 1); + panic!("stretch {stretch} of {stretches} did not end within {WITHIN:?}: {why}"); } } drop(stream); From 92bdd976bbceb7cabcb1d5237a692e0865a273a7 Mon Sep 17 00:00:00 2001 From: japabu Date: Sat, 3 Oct 2026 13:05:35 +0200 Subject: [PATCH 4/5] One inspect asker, the cable refusal back before the flash, and a lease fixture that names nobody Answers the review of c154c2220 on #684. The stall job asked soundd with a copy of `/system/bin/inspect`'s `ask`, without the frame-size assert `toyos-inspect` asks of a reader. `userland/inspect` is now a library and a binary, as `userland/blockd` is: `inspect::ask` is the one asker, the assert stands beside it, and the reader and the job both call it. No SDK change. The job's answer bound is the reader's 2 s where its copy had 5 s. `Driver::wire` reads the claimed function's IPv4 address again and refuses a function that holds none as `Refusal::Wire`, before anything is written: exit 2, the loop's. c154c2220 cut that read with the ping it fed, and a bench whose cable is out would have had both LAN boots flashed and reported red as the boot's. `brief_address` and its test are `main`'s; `Wire` carries the address so a `Wire` without one cannot be built. `lanleasecase` names the function again, so its boot is refused on that bench too. Nothing judges the address: `boot.txt` carries `wire_mac` as before. `lan_dhcp_lease`'s ping arm went: the loop refuses a talking boot whose address answered no ping before any judge is called, so no readback that reaches the judge carries `talk_ping no`, and the ping is `lan_talk`'s. `icmp::wire_is_down`, its arm in `echo` and its test went with the probe they were written for. The one caller left asks an address a stream has just opened from, where a send the host's routing refuses is the host's failing. The lease check's fixture is now the T14's `lantalkcase` readback at c154c2220, which carries none of the four keys the old loop wrote. Its MAC and its two resolvers are stand-ins: a locally administered MAC and RFC 5737 addresses. The tree is public and the judge needs a MAC equal on both sides and a resolver list that parses. `lan::LEASE` lost its last reader outside its module and is private. The `lan_hold` issue is `tooling` with an exit condition. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm --- ...wo-boots-open-for-a-flat-twenty-seconds.md | 8 +- src/icmp.rs | 64 +------------ src/lan.rs | 2 +- src/metal.rs | 91 ++++++++++++++++--- tests/checks/lan.rs | 59 +++++------- tests/common/lan.rs | 23 +---- tests/common/metal.rs | 9 +- tests/toyos-rust-tests/Cargo.lock | 10 ++ tests/toyos-rust-tests/Cargo.toml | 2 + .../src/bin/hda_client_stall.rs | 30 +----- tests/toyos.rs | 9 +- userland/inspect/Cargo.toml | 6 ++ userland/inspect/src/lib.rs | 69 ++++++++++++++ userland/inspect/src/main.rs | 72 ++------------- 14 files changed, 226 insertions(+), 228 deletions(-) create mode 100644 userland/inspect/src/lib.rs 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 index 48e180e7ce8..ba34e6b9664 100644 --- 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 @@ -1,6 +1,6 @@ --- status: open -kind: finding +kind: tooling opened: 2026-10-03 --- @@ -15,3 +15,9 @@ is a fixed delay standing in for an event the job does not wait on, which root 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/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 31fcbcd2f0a..79c0d3d43d4 100644 --- a/src/metal.rs +++ b/src/metal.rs @@ -151,8 +151,9 @@ 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 name the interface and the MAC it holds on the - /// function the flashed image claims. + /// 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 }, /// The machine did not go down, or did not come back. Silent { what: &'static str, secs: u64 }, @@ -300,7 +301,7 @@ impl fmt::Display for Refusal { Self::Wire { nic, why } => write!( f, "the machine says nothing usable about PCI function {nic}, which the flashed \ - image claims: {why}" + image claims and a boot of it could answer on: {why}" ), Self::Silent { what, secs } => write!( f, @@ -1039,10 +1040,32 @@ 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, } +/// `ip -4 -brief addr show `'s one line, as `Wire` needs it: the brief +/// form is ` ...`, and an interface with no address has no +/// third field at all, which is the machine saying the cable is out. +fn brief_address(iface: &str, text: &str) -> Result { + let line = text + .lines() + .find(|l| l.split_whitespace().next() == Some(iface)) + .ok_or_else(|| format!("`ip -4 -brief addr show {iface}` said {text:?}"))?; + let cidr = line + .split_whitespace() + .nth(2) + .ok_or_else(|| format!("{iface} holds no IPv4 address: {line:?}"))?; + cidr.split('/') + .next() + .unwrap_or(cidr) + .parse() + .map_err(|_| format!("{iface}'s address reads {cidr:?}")) +} + /// The loop, over one target. struct Driver { target: Target, @@ -1094,9 +1117,9 @@ impl Driver { } /// What this machine holds on the function the flashed image claims: the - /// interface Ubuntu gave it and its MAC. Two reads and not one, so a - /// machine that answers oddly is refused with the read that was odd; - /// neither 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")); @@ -1116,7 +1139,17 @@ impl Driver { &format!("cat {}", shell_word(&format!("/sys/class/net/{iface}/address"))), ) .map_err(|e| bad(e.to_string()))?; - Ok(Wire { iface: iface.to_string(), mac: mac.trim().to_ascii_lowercase() }) + let brief = self + .ssh( + "reading the claimed function's address", + &format!("ip -4 -brief addr show {}", shell_word(iface)), + ) + .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(), + }) } /// The loop refuses to run at all until the rule is on the machine. @@ -1451,8 +1484,8 @@ pub struct Args { fat32_check: bool, /// The PCI function this boot's image claims, in `/sys/bus/pci/devices`'s /// spelling. **A boot names it or the function is not read at all**: the - /// reads cost two `ssh` round trips and a boot whose judges read no MAC - /// would be refused for a fact none of them looks at. + /// 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 @@ -1836,12 +1869,16 @@ 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 operating system that is still up is the - // one reader of this function's MAC that is not the driver under test. + // 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 {}, MAC {}", wire.iface, wire.mac); + println!( + "the claimed function {nic} is {} at {}, MAC {}", + wire.iface, wire.addr, wire.mac + ); Some(wire) } None => None, @@ -2652,7 +2689,11 @@ mod tests { 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(), mac: "8c:8c:aa:bb:cc:dd".to_string() }; + 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)); } @@ -2722,6 +2763,30 @@ mod tests { assert_eq!(written(), Err(unheard.to_string().trim_end().to_string())); } + /// **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. + #[test] + fn an_interface_with_no_address_is_refused_by_name() { + let up = "enp0s31f6 UP 192.168.1.46/24 \n"; + assert_eq!(brief_address("enp0s31f6", up), Ok("192.168.1.46".parse().unwrap())); + + let down = "enp0s31f6 DOWN \n"; + assert!(brief_address("enp0s31f6", down).unwrap_err().contains("no IPv4 address")); + + // Another interface's line is not this one's answer, however many are + // printed. + let many = "lo UNKNOWN 127.0.0.1/8\n\ + enp0s31f6 UP 192.168.1.46/24\n\ + wlp9s0 UP 192.168.1.244/24\n\ + tailscale0 UNKNOWN 100.92.92.12/32\n"; + assert_eq!(brief_address("enp0s31f6", many), Ok("192.168.1.46".parse().unwrap())); + assert_eq!(brief_address("wlp9s0", many), Ok("192.168.1.244".parse().unwrap())); + assert!(brief_address("enp0s31f7", many).unwrap_err().contains("ip -4 -brief")); + } + #[test] fn a_node_is_a_whole_scsi_or_nvme_disk_and_nothing_else() { for name in [ diff --git a/tests/checks/lan.rs b/tests/checks/lan.rs index e145faa61d4..f9a70386b91 100644 --- a/tests/checks/lan.rs +++ b/tests/checks/lan.rs @@ -4,33 +4,32 @@ use super::*; use toyos_build::metal::{READBACK_BOOT, READBACK_STREAM, READBACK_TALK}; -/// The T14's `lantalkcase` boot, verbatim: the card's hand-over, what netd -/// said of its MAC, its link and its lease, and init's stop. -const LOG: &str = r"[2026-10-03 06:50:58 1.192 cpu0] pcidev: PCI 00:1f.6 [8086:15fc] handed over on slot 0, vector 0x28 -{2026-10-03 06:51:02 5.727 netd} netd: MAC 38:f3:ab:35:37:3b -[2026-10-03 06:51:05 8.517 cpu4] pcidev: slot 0 took its first message on vector 0x28 -{2026-10-03 06:51:05 8.517 netd} netd: I219: link up at 1000 Mb/s full duplex, 2789 ms after the driver came up -{2026-10-03 06:51:16 19.070 netd} netd: DHCP: lease 192.168.1.48/24 from 192.168.1.1, gateway 192.168.1.1, dns [194.230.55.96 212.98.37.130], 13342 ms after netd came up -{2026-10-03 06:51:16 19.070 netd} netd: ready, at most 103 piped connections (4 MiB each of 16020 MiB total) -{2026-10-03 06:51:17 20.351 init} init: power: the machine stops, and logd makes the log whole first (Reboot) +/// 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`, verbatim. It also names `192.168.1.46`, the -/// address Ubuntu held on this MAC, which no judge reads. -const BOOT: &str = "back_secs 70\nstick_secs 0\nmachine_vendor LENOVO\nmachine_product 20W0003AMZ\n\ - machine_bios N34ET71W (1.71 )\nping_addr 192.168.1.46\n\ - wire_mac 38:f3:ab:35:37:3b\nclock_skew 1\nping_secs 64\nping_at 1791010315\n"; +/// 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 86\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, talk: &str) -> Result<(), String> { +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)] { + 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"); @@ -38,37 +37,27 @@ fn judged(log: &str, boot: &str, talk: &str) -> Result<(), String> { } /// The lease judged is the one this boot took: the T14's boot passes on the -/// address it answered the host at, whatever Ubuntu held before it, and reds -/// where netd's record names another address, where that address answered no -/// ping, where netd read another MAC than Ubuntu did, and with no lease. +/// 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, TALK), Ok(())); - let refused = |what: &str, log: &str, boot: &str, talk: &str, says: &str| { - let why = judged(log, boot, talk).expect_err(what); + 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, - TALK, "leased 192.168.1.46 and answered for its name at 192.168.1.48", ); - refused( - "a leased address that answered no ping", - LOG, - BOOT, - &TALK.replace("talk_ping yes", "talk_ping no"), - "answered no ping of the host's", - ); refused( "a MAC that is not the one Ubuntu read", LOG, - &BOOT.replace("wire_mac 38:f3:ab:35:37:3b", "wire_mac 38:f3:ab:35:37:3c"), - TALK, - "no \"netd: MAC 38:f3:ab:35:37:3c\" record", + &BOOT.replace("wire_mac 02:00:00:00:00:01", "wire_mac 02:00:00:00:00:02"), + "no \"netd: MAC 02:00:00:00:00:02\" record", ); 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, TALK, "took no address from its network"); + refused("a boot that took no lease", &unleased, BOOT, "took no address from its network"); } diff --git a/tests/common/lan.rs b/tests/common/lan.rs index a3cf7db9a35..6f3b5969ebd 100644 --- a/tests/common/lan.rs +++ b/tests/common/lan.rs @@ -51,16 +51,15 @@ pub fn delivered_on_metal(back: &metal::Readback) -> Result<(), String> { const ID: &str = "8086:15fc"; /// The PCI function that card is, as `/sys/bus/pci/devices` spells it: where -/// the metal loop reads the card's MAC before the flash. +/// 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 in netd's own lines, and -/// the host's ping of the address that lease names. +/// The T14's judge: the claim, the card, and the lease in netd's own lines. /// -/// **The host learns that address from the boot**: netd answers for the +/// **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 and pings it. The lease record is held -/// to that address here, so no lease but this boot's own is judged. +/// 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(); @@ -127,18 +126,6 @@ pub fn on_metal(back: &metal::Readback) -> Result<(), String> { Err(why) => bad.push(why), } - match heard.ping { - Some(true) => eprintln!( - " [lan] {}, where this boot answered for its name, answered the host's ping", - heard.peer - ), - Some(false) => bad.push(format!( - "{}, where this boot answered for its name, answered no ping of the host's", - heard.peer - )), - None => bad.push(format!("the host asked {} for no ping", heard.peer)), - } - if bad.is_empty() { return Ok(()); } diff --git a/tests/common/metal.rs b/tests/common/metal.rs index abcc4cf9d15..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 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 whose - /// judges read no MAC 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 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 69a249e3f5f..80bed5bcfa4 100644 --- a/tests/toyos-rust-tests/src/bin/hda_client_stall.rs +++ b/tests/toyos-rust-tests/src/bin/hda_client_stall.rs @@ -17,9 +17,7 @@ use std::sync::mpsc; use std::time::{Duration, Instant}; use cpal::traits::{DeviceTrait, HostTrait, StreamTrait}; -use toyos::ipc::{FrameRx, RxStep}; -use toyos::poller::{Poller, READABLE}; -use toyos_inspect::{Value, MAX_SNAPSHOT_BYTES, MSG_INSPECT, MSG_SNAPSHOT, SOUND}; +use toyos_inspect::{Value, SOUND}; const FREQ_HZ: f64 = 440.0; const AMPLITUDE: f64 = 16000.0; @@ -107,7 +105,8 @@ fn play(stalls: u64) { fn await_suspended() { let deadline = Instant::now() + WITHIN; loop { - let sound = inspect_sound(); + 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"), @@ -126,26 +125,3 @@ fn await_suspended() { std::thread::sleep(Duration::from_nanos(1_000_000_000 * frames / rate)); } } - -/// soundd's own `inspect` answer, within [`WITHIN`]. -fn inspect_sound() -> std::collections::BTreeMap { - let conn = toyos::endow::service(SOUND.port).expect("a connection to soundd"); - conn.signal(MSG_INSPECT).expect("soundd takes an inspect request"); - let poller = Poller::new(1); - let mut rx: Box> = Box::new(FrameRx::new()); - let deadline = Instant::now() + WITHIN; - loop { - match rx.pump(&conn) { - RxStep::Frame { msg_type: MSG_SNAPSHOT, payload_len } => { - return toyos_inspect::decode(rx.payload(payload_len), SOUND) - .unwrap_or_else(|why| panic!("soundd's snapshot: {why}")); - } - RxStep::Idle => {} - other => panic!("soundd answered inspect with {other:?}, not a snapshot"), - } - let left = deadline.saturating_duration_since(Instant::now()); - assert!(!left.is_zero(), "soundd did not answer inspect within {WITHIN:?}"); - poller.watch(&conn, READABLE, 0); - poller.wait(1, left.as_nanos() as u64, |_| {}); - } -} diff --git a/tests/toyos.rs b/tests/toyos.rs index 5dc4f2a5135..7ccdc6930f9 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -708,9 +708,12 @@ 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. -const LANLEASECASE: &[metal::Arm] = - &[metal::once(lan::LEASE_BOOT, lan::LEASE_CONFIG, &[], lan::JOBS)]; +/// 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) +}]; /// 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, 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> { From 9e709f7a2b8236c719c75812c0681515d908825b Mon Sep 17 00:00:00 2001 From: japabu Date: Sat, 3 Oct 2026 13:06:10 +0200 Subject: [PATCH 5/5] The metal loop and the lease judge print neither the MAC nor the resolvers The owner's ruling on #684: nothing that identifies his machines or network goes into this repository or onto a pull request. A run's log and a judge's lines are what a pull request quotes, and three of them carried one or the other: the loop's `the claimed function ... MAC ...` line, the lease judge's `[lan] leased ... dns [...]` line on every pass, and its red for a MAC that is not the one the operating system before the boot read, which quoted that MAC. The loop's line now names the interface and the address it holds, which is a private one; the MAC still crosses in `boot.txt`. The judge counts the resolvers, and its red names where both MACs are read instead of quoting one. netd's own records in a boot's log carry both, as before: those are the product's lines and a readback is not committed. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_013UDZQ6fSKw14e4w2TKTRfm --- src/metal.rs | 7 +++---- tests/checks/lan.rs | 2 +- tests/common/lan.rs | 20 ++++++++++++++------ 3 files changed, 18 insertions(+), 11 deletions(-) diff --git a/src/metal.rs b/src/metal.rs index 79c0d3d43d4..66bf690e8f9 100644 --- a/src/metal.rs +++ b/src/metal.rs @@ -1875,10 +1875,9 @@ pub fn run(args: &Args) -> Result, Refusal> { 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, diff --git a/tests/checks/lan.rs b/tests/checks/lan.rs index f9a70386b91..c82439df912 100644 --- a/tests/checks/lan.rs +++ b/tests/checks/lan.rs @@ -55,7 +55,7 @@ pub fn the_lease_judged_is_this_boots_own() { "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 02:00:00:00:00:02\" record", + "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(); diff --git a/tests/common/lan.rs b/tests/common/lan.rs index 6f3b5969ebd..b531fe13106 100644 --- a/tests/common/lan.rs +++ b/tests/common/lan.rs @@ -96,11 +96,13 @@ pub fn on_metal(back: &metal::Readback) -> Result<(), String> { } } - let mac = format!("{MAC}{wire_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 the operating \ - system before it read on {NIC}" + "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 )); } @@ -111,9 +113,15 @@ 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 != heard.peer { bad.push(format!(