From 74f7d71721ccfd6d2534195010e57bb5c1ec6810 Mon Sep 17 00:00:00 2001 From: japabu Date: Mon, 28 Sep 2026 08:39:27 +0200 Subject: [PATCH 01/10] A swap's redial dials until logd admits one, bounded by the swap's window alone The netd-swap tests went red with "the stream's redial was turned away 64 time(s), its ceiling of 64, and gave up" on boots whose guest finished every swap: the re-claimed netd leased and init said "in service" or "restored". The red was the host's own dial count, which is neither the event nor a timeout. The event, "logd admits a dial", is seen only by dialing, and each dial already waits on the machine's answer. So `Stream::redial` now dials until a connection carries a line or its bound passes, and loses its ceiling parameter: - the reader's ceiling is the first dial's only (`State::ceiling` is `None` once a redial begins), so `turned_since_dial` and `past_ceiling` go; - a redial whose bound passes with every connection closed before a line now says so (`Stream::unopened`), where it used to go quiet; - `metalswap::swap` bounds the redial by what is left of the swap's window, waits on the admitted connection, prints how long the refusal window was and how many dials it turned away, and returns `Err` naming both when the window passes with none admitted; - the judge's ceiling finding is deleted; `turned_away` stays a reported number; - `TURNED_AWAY_CEILING` now bounds first dials only, so it moves beside the reader in `metaltalk`. The two ceiling tests become tests that a redial asks past 1000 refusals and resets and past 200 closes before a line, and that it ends at its bound alone and says so on both paths. The judge's test now holds 10 000 dials turned away to be no verdict. The diagnostics issue on the redial's spin keeps its exit; what bounds the spin is now the window alone. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01W6rME2DoqwjcYFStYHHY4j --- ...ial-asks-again-with-no-event-to-wait-on.md | 12 +- src/metal.rs | 2 +- src/metalswap.rs | 39 ++-- src/metaltalk.rs | 212 +++++++++++------- tests/common/logstream.rs | 2 +- 5 files changed, 152 insertions(+), 115 deletions(-) diff --git a/issues/diagnostics/a-swaps-redial-asks-again-with-no-event-to-wait-on.md b/issues/diagnostics/a-swaps-redial-asks-again-with-no-event-to-wait-on.md index 99f70c2a3b..3cf1581da2 100644 --- a/issues/diagnostics/a-swaps-redial-asks-again-with-no-event-to-wait-on.md +++ b/issues/diagnostics/a-swaps-redial-asks-again-with-no-event-to-wait-on.md @@ -16,12 +16,10 @@ forward, accepted and closed before a line — is asked again at once. On a LAN that is a question for the name on the link, which the old netd answers at once, and a `connect` per round trip for the whole gap. -What bounds it: every dial turned away is counted, refusals included -(`Stream::turned_away`), and a redial gives up at -`metalswap::TURNED_AWAY_CEILING`, which the swap's judge reds on by name -(`a_redial_counts_every_refusal_and_gives_up_at_its_ceiling`). The T14 is -unmeasured, and a refusal there costs a LAN round trip rather than QEMU's -forward's. +What bounds it: the swap's window alone, `Stream::redial`'s `by`; every dial +turned away is counted and reported (`Stream::turned_away`), never judged. +The T14 is unmeasured, and a refusal there costs a LAN round trip rather than +QEMU's forward's. ## Exit condition @@ -30,4 +28,4 @@ machine sends when `logd` can admit a reader again after a swap of netd — for example `logd` keeping its listener across the swap and holding the connections it accepts until the new netd serves, or netd announcing its exit on a channel that outlives it — and `Stream::redial` dials once per -such event, with the ceiling and the count deleted. +such event, with the count deleted. diff --git a/src/metal.rs b/src/metal.rs index dab449ddb9..3ca5674baa 100644 --- a/src/metal.rs +++ b/src/metal.rs @@ -1791,7 +1791,7 @@ impl Talking { }; println!("asking for {peer:?}'s log"); let at = self.dir.join(file); - crate::metaltalk::Stream::connect(peer, &at, true, by, crate::metalswap::TURNED_AWAY_CEILING) + crate::metaltalk::Stream::connect(peer, &at, true, by, crate::metaltalk::TURNED_AWAY_CEILING) .map_err(Refusal::Cable) } } diff --git a/src/metalswap.rs b/src/metalswap.rs index 80b6aa723e..2f7cd811a8 100644 --- a/src/metalswap.rs +++ b/src/metalswap.rs @@ -46,14 +46,6 @@ const REFUSED_WORD: Duration = Duration::from_secs(10); /// a missing line is a red verdict rather than a longer wait. const CARRIER_WORD: Duration = Duration::from_millis(toyos_swap::ANSWER_MS); -/// How many dials a stream's first dial, or a swap's redial, may have turned -/// away — a failed connect, or a connection closed before a line — before it -/// gives up and the boot or the swap is red. Nothing the machine sends says -/// when `logd` listens again after a swap, so a redial asks again at once and -/// this ceiling is the one thing that stops it spinning unseen: the recorded -/// compromise `issues/diagnostics/a-swaps-redial-asks-again-with-no-event-to-wait-on.md`. -pub const TURNED_AWAY_CEILING: usize = 64; - /// What asking for one swap came to. #[derive(Debug, Clone, PartialEq, Eq)] pub struct Swapped { @@ -133,7 +125,7 @@ fn settled(lines: &[String], mark: usize, service: &str) -> Option<()> { /// `Err` is a boot that never opened the stream within `window`, a binary this /// host cannot read, or a swap of the stream's own carrier whose `logd` never /// said it would turn readers away before `swap` let the swap go without -/// this side. +/// this side, or admitted none of this side's dials again within `window`. pub fn swap( stream: &Stream, ssh: &Ssh, @@ -211,7 +203,22 @@ pub fn swap( } } if accepted && service == toyos_logstream::CARRIER { - stream.redial(window, TURNED_AWAY_CEILING); + let (left, seen, redialed) = (window.saturating_sub(began.elapsed()), stream.connections(), Instant::now()); + stream.redial(left); + if stream.wait_for_connection(seen, left).is_none() { + return Err(format!( + "`logd` admitted no dial of the stream's within the {} s window of the swap of {service}: \ + turned away {} time(s) from the ask, {}", + window.as_secs(), + stream.turned_away() - away, + stream.unopened().unwrap_or_else(|| "the latest dial unanswered at the bound".to_string()) + )); + } + println!( + " swap: `logd` admitted the stream again {} ms after the redial, turned away {} time(s) from the ask", + redialed.elapsed().as_millis(), + stream.turned_away() - away + ); } let mut outcome_ms = None; if let Some(until) = until { @@ -319,13 +326,7 @@ pub fn judge(heard: &Swapped, expect: Expect) -> Result, Vec heard.connections.1 )), } - if heard.turned_away >= TURNED_AWAY_CEILING { - bad.push(format!( - "the stream's redial was turned away {} time(s), its ceiling of {TURNED_AWAY_CEILING}, \ - and gave up", - heard.turned_away - )); - } else if heard.service == toyos_logstream::CARRIER { + if heard.service == toyos_logstream::CARRIER { said.push(format!( "the stream's dials were turned away {} time(s), refusals included, from the ask to \ the end", @@ -605,8 +606,8 @@ mod tests { elsewhere.words.last_mut().unwrap().1 = "/tmp/swap/other/netd as pid 12".into(); assert!(judge(&elsewhere, Expect::InService).is_err()); let mut spun = heard(Expect::InService); - spun.turned_away = TURNED_AWAY_CEILING; - assert!(judge(&spun, Expect::InService).is_err(), "a redial that reached its ceiling"); + spun.turned_away = 10_000; + assert!(judge(&spun, Expect::InService).is_ok(), "how many dials were turned away is no verdict"); } #[test] diff --git a/src/metaltalk.rs b/src/metaltalk.rs index 7e903cfec6..27ae299d59 100644 --- a/src/metaltalk.rs +++ b/src/metaltalk.rs @@ -85,6 +85,11 @@ pub enum Peer { At(SocketAddr), } +/// How many dials a stream's first dial may have turned away — a failed +/// connect, or a connection closed before a line — before it gives up and the +/// boot is red. A redial has none ([`Stream::redial`]). +pub const TURNED_AWAY_CEILING: usize = 64; + /// The log as this host reads it: this host dials `logd`'s port and reads until /// the connection ends. /// @@ -122,10 +127,9 @@ struct State { /// How many dials ended with no line: a connection `logd` turned away, /// one nothing on the machine's side took, or a connect that failed. turned_away: usize, - /// Those of them since the first dial or the latest redial began, and its - /// ceiling. - turned_since_dial: usize, - ceiling: usize, + /// How many of them the first dial gives up at, and `None` once a redial + /// has begun: a redial ends at its bound alone. + ceiling: Option, /// The connection being read, kept so [`Stream::redial`] can end it. current: Option, /// How the latest admitted connection ended, once it has and none has been @@ -133,9 +137,8 @@ struct State { end: Option, /// Why the latest dial ended with no connection that carried a line. unopened: Option, - /// A redial asked for and not yet begun: the instant it gives up by, and - /// how many dials turned away it gives up at. - redial: Option<(Instant, usize)>, + /// A redial asked for and not yet begun: the instant it gives up by. + redial: Option, /// Lines a connection's end cut short, discarded rather than kept: the next /// connection's replay carries the same content whole. torn: usize, @@ -177,7 +180,7 @@ impl Stream { ceiling: usize, ) -> Result { let out = std::fs::File::create(file).map_err(|e| format!("{}: {e}", file.display()))?; - let state = State { ceiling, ..State::default() }; + let state = State { ceiling: Some(ceiling), ..State::default() }; let shared = Arc::new(Shared { state: Mutex::new(state), moved: Condvar::new() }); let theirs = Arc::clone(&shared); std::thread::Builder::new() @@ -239,18 +242,23 @@ impl Stream { } /// End the current connection, and dial again until a connection carries a - /// line, `by` has passed, or `ceiling` dials were turned away: every dial - /// is a wait on the machine's answer, and one it turns away — a connect - /// that failed, or a connection closed before a line — is asked again and - /// counted ([`Stream::turned_away`]). A redial that reaches its ceiling - /// gives up and says so ([`Stream::unopened`]). + /// line or `by` has passed: every dial is a wait on the machine's answer, + /// and one it turns away — a connect that failed, or a connection closed + /// before a line — is asked again at once and counted + /// ([`Stream::turned_away`]), never judged. A redial whose bound passes + /// says so ([`Stream::unopened`]). + /// + /// **The admitted dial is the event, and `by` its only bound**: nothing the + /// machine sends says when `logd` admits a reader again, so how many dials + /// that takes is the length of the machine's gap and no verdict — the + /// recorded compromise `issues/diagnostics/a-swaps-redial-asks-again-with-no-event-to-wait-on.md`. /// /// **For a connection this host knows is going**: a swap of the netd /// carrying it ends it with no FIN and no reset, so nothing but this host /// ever says it has ended. - pub fn redial(&self, by: Duration, ceiling: usize) { + pub fn redial(&self, by: Duration) { let mut state = self.state(); - state.redial = Some((Instant::now() + by, ceiling)); + state.redial = Some(Instant::now() + by); if let Some(conn) = state.current.take() { let _ = conn.shutdown(std::net::Shutdown::Both); } @@ -341,16 +349,19 @@ fn serve(reach: &dyn Reach, peer: &Peer, shared: &Shared, mut out: std::fs::File println!(" stream: reading {peer:?} at {:?}", conn.peer_addr().ok()); } let carried = read(conn, shared, &mut out, echo); - // A connection `logd` turned away, while the redial it answers - // is still inside its bounds: asked again at once, the refusal - // being the event. - if !carried && again && Instant::now() < until { + // A connection `logd` turned away on a redial: asked again at + // once inside the redial's bound, the refusal being the event, + // and the redial's end once past it. + if !carried && again { let mut state = shared.state.lock().expect("the stream's state"); - if state.turned_since_dial >= state.ceiling { - state.unopened = Some(past_ceiling(&state, "the latest connection ended before a line")); + if !state.stop && state.redial.is_none() { + if Instant::now() < until { + continue; + } + state.unopened = Some(format!( + "{peer:?} admitted no connection by the redial's bound: the latest ended before a line" + )); shared.moved.notify_all(); - } else if !state.stop && state.redial.is_none() { - continue; } } } @@ -360,12 +371,11 @@ fn serve(reach: &dyn Reach, peer: &Peer, shared: &Shared, mut out: std::fs::File if state.stop { return; } - if let Some((by, ceiling)) = state.redial.take() { + if let Some(by) = state.redial.take() { until = by; again = true; state.unopened = None; - state.turned_since_dial = 0; - state.ceiling = ceiling; + state.ceiling = None; break; } state = shared.moved.wait(state).expect("the stream's state"); @@ -373,13 +383,16 @@ fn serve(reach: &dyn Reach, peer: &Peer, shared: &Shared, mut out: std::fs::File } } -/// Count one dial that failed against the ceiling, and why the dial gives up -/// where that reaches it. +/// Count one dial that failed, and why the first dial gives up where that +/// reaches its ceiling: the count is the first dial's own, nothing being +/// dialled before it. fn count_or_give_up(shared: &Shared, last: &str) -> Option { let mut state = shared.state.lock().expect("the stream's state"); state.turned_away += 1; - state.turned_since_dial += 1; - (state.turned_since_dial >= state.ceiling).then(|| past_ceiling(&state, last)) + state + .ceiling + .filter(|&ceiling| state.turned_away >= ceiling) + .map(|ceiling| format!("turned away {ceiling} time(s), which is the first dial's ceiling: {last}")) } /// A connect that ended this way may be taken once the machine is up: it was @@ -409,7 +422,8 @@ fn open(reach: &dyn Reach, peer: &Peer, until: Instant, shared: &Shared) -> Resu let addrs = match peer { // No wait between dials: an address carries no name to ask the link // for, and the only event a forward can give is a dial it takes, so - // the dial ceiling, not a wait, bounds a forward that refuses. + // the first dial's ceiling or a redial's bound, never a wait, bounds + // a forward that refuses. Peer::At(at) => vec![*at], Peer::Named { host, port } if on_the_link => match reach.ask(host, until)? { Some(ip) => vec![SocketAddr::from((ip, *port))], @@ -670,20 +684,11 @@ fn read(conn: TcpStream, shared: &Shared, out: &mut std::fs::File, echo: bool) - } if !carried { state.turned_away += 1; - state.turned_since_dial += 1; } shared.moved.notify_all(); carried } -/// Why a dial gave up at its ceiling. -fn past_ceiling(state: &State, last: &str) -> String { - format!( - "turned away {} time(s) since the dial began, which is its ceiling: {last}", - state.turned_since_dial - ) -} - /// How a stream's connection ended. #[derive(Debug, Clone, PartialEq, Eq)] pub struct End { @@ -1449,7 +1454,7 @@ mod tests { let mut first = accepted(&server, "the first dial"); writeln!(first, "[kernel 0.001 cpu0] before the swap").unwrap(); assert!(stream.wait_for("before the swap", Duration::from_secs(5))); - stream.redial(Duration::from_secs(5), 8); + stream.redial(Duration::from_secs(5)); drop(accepted(&server, "the redial")); let mut third = accepted(&server, "the dial after a connection turned away"); writeln!(third, "[kernel 0.001 cpu0] before the swap").unwrap(); @@ -1469,12 +1474,14 @@ mod tests { ); } - /// A machine whose first dial is taken and whose every later one is turned - /// away before a connection exists: refused and reset in turn, the two - /// answers a SYN gets from a machine whose listener is gone or going, - /// depending on when it went. + /// A machine whose first dial is taken, whose dials after it are turned + /// away before a connection exists until `taken_from`, and whose dials from + /// then on are taken: refused and reset in turn, the two answers a SYN gets + /// from a machine whose listener is gone or going, depending on when it + /// went. struct TurnedAway { dials: std::sync::atomic::AtomicUsize, + taken_from: usize, } impl Reach for TurnedAway { @@ -1488,64 +1495,95 @@ mod tests { fn dial(&self, at: SocketAddr) -> std::io::Result { match self.dials.fetch_add(1, std::sync::atomic::Ordering::SeqCst) { - 0 => TcpStream::connect(at), + n if n == 0 || n >= self.taken_from => TcpStream::connect(at), n if n % 2 == 1 => Err(std::io::ErrorKind::ConnectionRefused.into()), _ => Err(std::io::Error::from_raw_os_error(libc::ECONNRESET)), } } } - /// **A redial counts every dial refused or reset, and gives up at its - /// ceiling saying so.** Staged through [`Reach`], so each dial's answer is - /// the one this test gives it and arrives at once: exactly the ceiling's - /// number are counted, and the redial ends long before its time bound. - #[test] - fn a_redial_counts_every_refusal_and_reset_and_gives_up_at_its_ceiling() { - const CEILING: usize = 3; - let dir = toyos_tmpdir::TempDir::new("metaltalk-refused"); - let server = TcpListener::bind("127.0.0.1:0").unwrap(); + /// A reader through `reach` whose first connection from `server` has + /// carried a line, and that connection. + fn read_first(server: &TcpListener, reach: Arc, dir: &Path) -> (Stream, TcpStream) { let at = server.local_addr().unwrap(); - let reach: Arc = Arc::new(TurnedAway { dials: 0.into() }); let stream = Stream::through(reach, Peer::At(at), &dir.join("s.log"), false, Duration::from_secs(5), 8) .expect("a loopback reader"); - let mut first = accepted(&server, "the first dial"); + let mut first = accepted(server, "the first dial"); writeln!(first, "[kernel 0.001 cpu0] before the swap").unwrap(); assert!(stream.wait_for("before the swap", Duration::from_secs(5))); - stream.redial(Duration::from_secs(60), CEILING); - assert_eq!(stream.wait_for_connection(1, Duration::from_secs(5)), None, "nothing listens"); - let why = stream.unopened().expect("the redial gave up within 5 s of its 60 and said why"); - assert!(why.contains("ceiling") && why.contains("refused"), "{why}"); - assert_eq!(stream.turned_away(), CEILING, "every refused or reset dial, and no more"); + (stream, first) } - /// **A redial counts a dial that closes before a line, not only a - /// refusal, and gives up at its ceiling.** The listener admits every - /// connection and drops it before a byte, as a swapped netd's own - /// listener does while nothing on the machine side has yet queued a - /// line: each is turned away and counted, and the redial ends at its - /// ceiling rather than spinning until its time bound. - #[test] - fn a_redial_counts_every_close_before_a_line_and_gives_up_at_its_ceiling() { - const CEILING: usize = 3; - let dir = toyos_tmpdir::TempDir::new("metaltalk-closed"); - let server = TcpListener::bind("127.0.0.1:0").unwrap(); - let at = server.local_addr().unwrap(); - let stream = Stream::connect(Peer::At(at), &dir.join("s.log"), false, Duration::from_secs(5), 8) - .expect("a loopback reader"); - let mut first = accepted(&server, "the first dial"); - writeln!(first, "[kernel 0.001 cpu0] before the swap").unwrap(); - assert!(stream.wait_for("before the swap", Duration::from_secs(5))); - let dropper = server.try_clone().unwrap(); + /// `server` dropping the next `closed` connections before a byte, as + /// QEMU's forward does while `logd` turns readers away, and replaying the + /// boot on the one after, with one line past it. + fn close_then_replay(server: &TcpListener, closed: usize) { + let server = server.try_clone().unwrap(); std::thread::spawn(move || { - while let Ok((conn, _)) = dropper.accept() { - drop(conn); + for _ in 0..closed { + drop(server.accept()); } + let (mut conn, _) = server.accept().unwrap(); + writeln!(conn, "[kernel 0.001 cpu0] before the swap").unwrap(); + writeln!(conn, "[kernel 9.000 cpu0] after the swap").unwrap(); }); - stream.redial(Duration::from_secs(60), CEILING); - assert_eq!(stream.wait_for_connection(1, Duration::from_secs(5)), None, "every dial closed before a line"); - let why = stream.unopened().expect("the redial gave up within 5 s of its 60 and said why"); - assert!(why.contains("ceiling") && why.contains("ended before a line"), "{why}"); - assert_eq!(stream.turned_away(), CEILING, "every closed dial, and no more"); + } + + /// **A redial asks past every dial refused or reset, however many, until + /// one is taken.** Staged through [`Reach`], so each dial's answer is the + /// one this test gives it and arrives at once: far more dials than the + /// first dial's ceiling are turned away, and every one is counted. + #[test] + fn a_redial_asks_past_every_refusal_and_reset_until_a_dial_is_taken() { + const TURNED: usize = 1000; + let dir = toyos_tmpdir::TempDir::new("metaltalk-refused"); + let server = TcpListener::bind("127.0.0.1:0").unwrap(); + let reach = Arc::new(TurnedAway { dials: 0.into(), taken_from: TURNED + 1 }); + let (stream, _first) = read_first(&server, reach, &dir); + close_then_replay(&server, 0); + stream.redial(Duration::from_secs(60)); + assert!(stream.wait_for("after the swap", Duration::from_secs(5)), "{:?}", stream.unopened()); + assert_eq!(stream.turned_away(), TURNED, "every refused or reset dial, and no more"); + assert_eq!(stream.connections(), 2); + } + + /// **A redial asks past every connection closed before a line, however + /// many, until one carries a line**, and counts each. + #[test] + fn a_redial_asks_past_every_close_before_a_line_until_one_carries_a_line() { + const CLOSED: usize = 200; + let dir = toyos_tmpdir::TempDir::new("metaltalk-closed"); + let server = TcpListener::bind("127.0.0.1:0").unwrap(); + let (stream, _first) = read_first(&server, Arc::new(Net), &dir); + close_then_replay(&server, CLOSED); + stream.redial(Duration::from_secs(60)); + assert!(stream.wait_for("after the swap", Duration::from_secs(5)), "{:?}", stream.unopened()); + assert_eq!(stream.turned_away(), CLOSED, "every closed dial, and no more"); + assert_eq!(stream.connections(), 2); + } + + /// **A redial ends at its bound alone, and says so**: dials refused, and + /// connections closed before a line, are asked again until the bound + /// passes, and the reader then names the end rather than going quiet. + #[test] + fn a_redial_ends_at_its_bound_alone_and_says_so() { + const BOUND: Duration = Duration::from_millis(50); + let dir = toyos_tmpdir::TempDir::new("metaltalk-bound"); + let server = TcpListener::bind("127.0.0.1:0").unwrap(); + let reach = Arc::new(TurnedAway { dials: 0.into(), taken_from: usize::MAX }); + let (refused, _first) = read_first(&server, reach, &dir); + refused.redial(BOUND); + assert_eq!(refused.wait_for_connection(1, Duration::from_secs(5)), None, "nothing is taken"); + let why = refused.unopened().expect("the redial ended within 5 s and said why"); + assert!(why.contains("by the bound"), "{why}"); + + let server = TcpListener::bind("127.0.0.1:0").unwrap(); + let (closed, _first) = read_first(&server, Arc::new(Net), &dir); + close_then_replay(&server, usize::MAX); + closed.redial(BOUND); + assert_eq!(closed.wait_for_connection(1, Duration::from_secs(5)), None, "every dial closed before a line"); + let why = closed.unopened().expect("the redial ended within 5 s and said why"); + assert!(why.contains("redial's bound") && why.contains("ended before a line"), "{why}"); } /// A reply macOS's mDNSResponder sent this host's legacy question for its diff --git a/tests/common/logstream.rs b/tests/common/logstream.rs index e58787f688..5aa98515e0 100644 --- a/tests/common/logstream.rs +++ b/tests/common/logstream.rs @@ -109,7 +109,7 @@ fn boot( pub fn reader(port: u16, file: &str) -> Result { let at = SocketAddr::from((Ipv4Addr::LOCALHOST, port)); let path = super::lane::dir().join(file); - let stream = Stream::connect(Peer::At(at), &path, false, CEILING, toyos_build::metalswap::TURNED_AWAY_CEILING)?; + let stream = Stream::connect(Peer::At(at), &path, false, CEILING, toyos_build::metaltalk::TURNED_AWAY_CEILING)?; stream .wait_connected(CEILING) .ok_or_else(|| stream.unopened().unwrap_or_else(|| "the stream never opened".to_string()))?; From 7e06a6570fcb3b9dabd81fd3be0305bff27b38da Mon Sep 17 00:00:00 2001 From: japabu Date: Mon, 28 Sep 2026 13:04:45 +0200 Subject: [PATCH 02/10] A forward's failed connect ends a redial at once, and the three swap tests come off the redlist MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit QEMU's slirp forward takes every connect for as long as QEMU lives, so a refused or reset connect on a `Peer::At` redial means QEMU has exited. With the dial ceiling gone, nothing else stopped that redial spinning a host core until the swap's window passed. `count_or_give_up` now ends a forward's redial at the first failed connect and says why in `unopened`. `a_redial_on_a_forward_that_refuses_ends_at_the_refusal` drops the listener and requires the end within 5 s of a 60 s redial with one dial turned away. It is red at 74f7d717 ("a refusing forward ends the redial at once", exit 101) and red again with only the forward arm deleted. The refusal and reset tests move to `Peer::Named` through a `Reach` that answers the name at once, since that is where refusals are real (the T14). `TURNED_AWAY_CEILING` bounds first dials only, and every caller passed it, so the `ceiling` parameter and `State::ceiling` are gone. The const is private, and `open` is told whether it is redialling. `metalswap::swap` no longer returns an `Err` when the redial admits nothing. No guest run reached it, and the judge already reds on `connections (1, 1)` and the missing word. It prints only the milliseconds to the admission, because the judge's `said` line already carries the count. The bound test's closer thread now ends instead of staying blocked in `accept`. `lan_swap`, `swap_netd` and `swap_crash_rolls_back` come off the redlist, and `issues/build/a-swaps-redial-races-a-hard-dial-ceiling-against-an-unbounded-guest-gap.md` is deleted. Its exit condition was "`Stream::redial` gives up on its time bound alone, never on a dial count, and a swap whose refusal window is staged long is green". The orchestrator's hold-green run at 74f7d717 met it: init held the old netd for 1 s, the swap was turned away 97 times, it was green, and the guest console carried logd's second `serving this boot's log to 10.0.2.2:52608` line. The same hold with the change reverted was red on "turned away 64 time(s), its ceiling of 64". The diagnostics issue records that the T14's redial may ask the link faster than RFC 6762 §5.2's floor between queries. That rate is unmeasured on metal. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01W6rME2DoqwjcYFStYHHY4j --- ...-ceiling-against-an-unbounded-guest-gap.md | 59 ------- ...ial-asks-again-with-no-event-to-wait-on.md | 10 +- src/metal.rs | 3 +- src/metalswap.rs | 17 +- src/metaltalk.rs | 166 +++++++++++------- src/redlist.rs | 12 -- tests/common/logstream.rs | 2 +- 7 files changed, 111 insertions(+), 158 deletions(-) delete mode 100644 issues/build/a-swaps-redial-races-a-hard-dial-ceiling-against-an-unbounded-guest-gap.md diff --git a/issues/build/a-swaps-redial-races-a-hard-dial-ceiling-against-an-unbounded-guest-gap.md b/issues/build/a-swaps-redial-races-a-hard-dial-ceiling-against-an-unbounded-guest-gap.md deleted file mode 100644 index 0df0869b2a..0000000000 --- a/issues/build/a-swaps-redial-races-a-hard-dial-ceiling-against-an-unbounded-guest-gap.md +++ /dev/null @@ -1,59 +0,0 @@ ---- -status: expected-red -kind: defect -opened: 2026-09-28 ---- - -# A swap's redial races a hard dial ceiling against an unbounded guest gap - -One mechanism, six sightings across `lan_swap`, `swap_netd` and -`swap_crash_rolls_back`: - -- `lan_swap`, Fast tier. -- `swap_netd` and `swap_crash_rolls_back`, Fast tier. -- `lan_swap`, PR #535's nightly (run 36314576406, `guest (1)`, `a4f68c5a`, KVM, QEMU 11.1.0). -- `swap_crash_rolls_back`, on origin/main's netd and on a branch's, under ten spinning host threads beside the run. -- `swap_crash_rolls_back`, main's nightly (`1ce71831`, run 36290616312), not seen on the nightly before #527 (run 36285169430). -- `swap_netd`, the rust-lld branch's fast tier (`e4317d3f`, PR #532), the one red of 400 besides `lan_mdns_answer`'s `SUN_LEN`. - -The guest side finished on every sighting that shows a console: today's three -boots reached DHCP lease, `logd` back on port 41337, and init's own -`restored`/`in service` line; `lan_swap`'s nightly guest reached `logd: serving -this boot's log on port 41337` at 1.176 s and `init: swap netd: in service` at -6.141 s, with no second `serving this boot's log to 10.0.2.2:…` line; both -`swap_crash_rolls_back` sightings' consoles show the rollback completing -(`restored`, then `logd` serving again). Only the host's redial gave up first, -every time. Every sighting's `cargo run -- --known-red` answered NO (not -quarantined), and an alone re-run is reliably green: 4 dials turned away on -`lan_swap`'s nightly, `swap_netd` green in 10 s on the rust-lld branch, -`swap_crash_rolls_back` green twice on main's nightly and once with netd -reverted to origin/main. - -## What the code shows - -`metalswap::swap` arms `Stream::redial` after logd's `CARRIER_LEAVING` and the -`go` (`src/metalswap.rs`), and `Stream::redial` opens a plain TCP dial to -`logd`'s log-stream port (`toyos_logstream::CARRIER`). `serve`'s loop -(`src/metaltalk.rs`) counts every dial that is refused, reset, or closes -before a line, and redials **at once** — there is no wait between attempts, -the comment names the refusal itself as the event — until a line arrives or -`metalswap::TURNED_AWAY_CEILING` (64) is reached. So the redial spends a -**fixed count** of dials against a gap whose length the *guest* sets: the old -netd's exit, the new one's spawn and DHCP lease, and init's whole 5000 ms "in -service" probe before it falls back to the one it replaced. This is -`issues/diagnostics/a-swaps-redial-asks-again-with-no-event-to-wait-on.md`'s -compromise. - -## What the measurement shows - -In `swap_netd`, 64 dials were refused in 326 ms between logd's `netd is being -replaced` (3.061 s) and its re-listen (3.387 s), each taking 5 ms or less. -Green swaps in the same runs were refused 3, 6 and 22 times. The dials got -faster on the red runs, not slower, which points at the refusal window logd -holds open while the old netd is still up. - -## Exit condition - -`Stream::redial` gives up on its time bound alone, never on a dial count, and a -swap whose refusal window is staged long is green; the three rows come off with -it. Owner: `src/metaltalk.rs`'s `Stream::redial`; held by the orchestrator. diff --git a/issues/diagnostics/a-swaps-redial-asks-again-with-no-event-to-wait-on.md b/issues/diagnostics/a-swaps-redial-asks-again-with-no-event-to-wait-on.md index 3cf1581da2..6f10b92e6a 100644 --- a/issues/diagnostics/a-swaps-redial-asks-again-with-no-event-to-wait-on.md +++ b/issues/diagnostics/a-swaps-redial-asks-again-with-no-event-to-wait-on.md @@ -16,10 +16,11 @@ forward, accepted and closed before a line — is asked again at once. On a LAN that is a question for the name on the link, which the old netd answers at once, and a `connect` per round trip for the whole gap. -What bounds it: the swap's window alone, `Stream::redial`'s `by`; every dial -turned away is counted and reported (`Stream::turned_away`), never judged. The T14 is unmeasured, and a refusal there costs a LAN round trip rather than -QEMU's forward's. +QEMU's forward's. Its redial asks the name on the link again after every dial +turned away, as soon as the old netd answers the last ask, so its questions +may go out faster than RFC 6762 §5.2's floor between two queries +(`ASK_WAIT`); that rate is unmeasured on metal. ## Exit condition @@ -28,4 +29,5 @@ machine sends when `logd` can admit a reader again after a swap of netd — for example `logd` keeping its listener across the swap and holding the connections it accepts until the new netd serves, or netd announcing its exit on a channel that outlives it — and `Stream::redial` dials once per -such event, with the count deleted. +such event, with the count deleted, so no redial asks the link faster than +§5.2's floor. diff --git a/src/metal.rs b/src/metal.rs index 3ca5674baa..e1f7d6d4bd 100644 --- a/src/metal.rs +++ b/src/metal.rs @@ -1791,8 +1791,7 @@ impl Talking { }; println!("asking for {peer:?}'s log"); let at = self.dir.join(file); - crate::metaltalk::Stream::connect(peer, &at, true, by, crate::metaltalk::TURNED_AWAY_CEILING) - .map_err(Refusal::Cable) + crate::metaltalk::Stream::connect(peer, &at, true, by).map_err(Refusal::Cable) } } diff --git a/src/metalswap.rs b/src/metalswap.rs index 2f7cd811a8..bc5a9cf693 100644 --- a/src/metalswap.rs +++ b/src/metalswap.rs @@ -125,7 +125,7 @@ fn settled(lines: &[String], mark: usize, service: &str) -> Option<()> { /// `Err` is a boot that never opened the stream within `window`, a binary this /// host cannot read, or a swap of the stream's own carrier whose `logd` never /// said it would turn readers away before `swap` let the swap go without -/// this side, or admitted none of this side's dials again within `window`. +/// this side. pub fn swap( stream: &Stream, ssh: &Ssh, @@ -205,20 +205,9 @@ pub fn swap( if accepted && service == toyos_logstream::CARRIER { let (left, seen, redialed) = (window.saturating_sub(began.elapsed()), stream.connections(), Instant::now()); stream.redial(left); - if stream.wait_for_connection(seen, left).is_none() { - return Err(format!( - "`logd` admitted no dial of the stream's within the {} s window of the swap of {service}: \ - turned away {} time(s) from the ask, {}", - window.as_secs(), - stream.turned_away() - away, - stream.unopened().unwrap_or_else(|| "the latest dial unanswered at the bound".to_string()) - )); + if stream.wait_for_connection(seen, left).is_some() { + println!(" swap: `logd` admitted the stream again {} ms after the redial", redialed.elapsed().as_millis()); } - println!( - " swap: `logd` admitted the stream again {} ms after the redial, turned away {} time(s) from the ask", - redialed.elapsed().as_millis(), - stream.turned_away() - away - ); } let mut outcome_ms = None; if let Some(until) = until { diff --git a/src/metaltalk.rs b/src/metaltalk.rs index 27ae299d59..5df905f00d 100644 --- a/src/metaltalk.rs +++ b/src/metaltalk.rs @@ -88,7 +88,7 @@ pub enum Peer { /// How many dials a stream's first dial may have turned away — a failed /// connect, or a connection closed before a line — before it gives up and the /// boot is red. A redial has none ([`Stream::redial`]). -pub const TURNED_AWAY_CEILING: usize = 64; +const TURNED_AWAY_CEILING: usize = 64; /// The log as this host reads it: this host dials `logd`'s port and reads until /// the connection ends. @@ -127,9 +127,6 @@ struct State { /// How many dials ended with no line: a connection `logd` turned away, /// one nothing on the machine's side took, or a connect that failed. turned_away: usize, - /// How many of them the first dial gives up at, and `None` once a redial - /// has begun: a redial ends at its bound alone. - ceiling: Option, /// The connection being read, kept so [`Stream::redial`] can end it. current: Option, /// How the latest admitted connection ended, once it has and none has been @@ -166,22 +163,14 @@ impl Stream { /// /// **A machine not yet reachable is asked again**: a dial refused, or /// answered with its host or network down or unreachable, is counted, and - /// the dial gives up at `ceiling` of them ([`Stream::unopened`]). - pub fn connect(peer: Peer, file: &Path, echo: bool, by: Duration, ceiling: usize) -> Result { - Self::through(Arc::new(Net), peer, file, echo, by, ceiling) - } - - fn through( - reach: Arc, - peer: Peer, - file: &Path, - echo: bool, - by: Duration, - ceiling: usize, - ) -> Result { + /// the dial gives up at `TURNED_AWAY_CEILING` of them ([`Stream::unopened`]). + pub fn connect(peer: Peer, file: &Path, echo: bool, by: Duration) -> Result { + Self::through(Arc::new(Net), peer, file, echo, by) + } + + fn through(reach: Arc, peer: Peer, file: &Path, echo: bool, by: Duration) -> Result { let out = std::fs::File::create(file).map_err(|e| format!("{}: {e}", file.display()))?; - let state = State { ceiling: Some(ceiling), ..State::default() }; - let shared = Arc::new(Shared { state: Mutex::new(state), moved: Condvar::new() }); + let shared = Arc::new(Shared { state: Mutex::new(State::default()), moved: Condvar::new() }); let theirs = Arc::clone(&shared); std::thread::Builder::new() .name("metal-stream".into()) @@ -245,8 +234,9 @@ impl Stream { /// line or `by` has passed: every dial is a wait on the machine's answer, /// and one it turns away — a connect that failed, or a connection closed /// before a line — is asked again at once and counted - /// ([`Stream::turned_away`]), never judged. A redial whose bound passes - /// says so ([`Stream::unopened`]). + /// ([`Stream::turned_away`]), never judged. A redial whose bound passes, + /// or whose [`Peer::At`] forward fails a connect, says so + /// ([`Stream::unopened`]). /// /// **The admitted dial is the event, and `by` its only bound**: nothing the /// machine sends says when `logd` admits a reader again, so how many dials @@ -338,7 +328,7 @@ fn serve(reach: &dyn Reach, peer: &Peer, shared: &Shared, mut out: std::fs::File // which is made while the machine's network is coming back. let mut again = false; loop { - match open(reach, peer, until, shared) { + match open(reach, peer, until, shared, again) { Err(why) => { let mut state = shared.state.lock().expect("the stream's state"); state.unopened = Some(why); @@ -375,7 +365,6 @@ fn serve(reach: &dyn Reach, peer: &Peer, shared: &Shared, mut out: std::fs::File until = by; again = true; state.unopened = None; - state.ceiling = None; break; } state = shared.moved.wait(state).expect("the stream's state"); @@ -383,16 +372,20 @@ fn serve(reach: &dyn Reach, peer: &Peer, shared: &Shared, mut out: std::fs::File } } -/// Count one dial that failed, and why the first dial gives up where that -/// reaches its ceiling: the count is the first dial's own, nothing being -/// dialled before it. -fn count_or_give_up(shared: &Shared, last: &str) -> Option { +/// Count one dial that failed, and why the dial gives up there: a first dial +/// at its ceiling, the count being its own with nothing dialled before it, +/// and a redial of a forward at once, since a forward takes every connect for +/// as long as QEMU lives. +fn count_or_give_up(shared: &Shared, peer: &Peer, again: bool, last: &str) -> Option { let mut state = shared.state.lock().expect("the stream's state"); state.turned_away += 1; - state - .ceiling - .filter(|&ceiling| state.turned_away >= ceiling) - .map(|ceiling| format!("turned away {ceiling} time(s), which is the first dial's ceiling: {last}")) + match peer { + Peer::At(_) if again => Some(format!("{last}; a forward fails a connect only once QEMU has exited")), + _ if !again && state.turned_away >= TURNED_AWAY_CEILING => { + Some(format!("turned away {TURNED_AWAY_CEILING} time(s), which is the first dial's ceiling: {last}")) + } + _ => None, + } } /// A connect that ended this way may be taken once the machine is up: it was @@ -409,7 +402,7 @@ fn not_yet_reachable(e: &std::io::Error) -> bool { /// and so is a connection closed before a line (`read`); an ask of the name is /// a wait on the machine's answer, bounded by `until` alone, and one that /// returns at once is no ask at all and ends the dial. -fn open(reach: &dyn Reach, peer: &Peer, until: Instant, shared: &Shared) -> Result { +fn open(reach: &dyn Reach, peer: &Peer, until: Instant, shared: &Shared, again: bool) -> Result { let stopped = || shared.state.lock().expect("the stream's state").stop; let mut last = String::from("never asked"); // Set by the first failed dial: the resolver's answer may be the one its @@ -421,9 +414,7 @@ fn open(reach: &dyn Reach, peer: &Peer, until: Instant, shared: &Shared) -> Resu } let addrs = match peer { // No wait between dials: an address carries no name to ask the link - // for, and the only event a forward can give is a dial it takes, so - // the first dial's ceiling or a redial's bound, never a wait, bounds - // a forward that refuses. + // for, and the only event a forward can give is a dial it takes. Peer::At(at) => vec![*at], Peer::Named { host, port } if on_the_link => match reach.ask(host, until)? { Some(ip) => vec![SocketAddr::from((ip, *port))], @@ -459,7 +450,7 @@ fn open(reach: &dyn Reach, peer: &Peer, until: Instant, shared: &Shared) -> Resu _ => format!("{at} was not reachable: {e}"), }; on_the_link = true; - if let Some(why) = count_or_give_up(shared, &last) { + if let Some(why) = count_or_give_up(shared, peer, again, &last) { return Err(why); } } @@ -1253,7 +1244,7 @@ mod tests { let dir = toyos_tmpdir::TempDir::new("metaltalk-cut"); let server = TcpListener::bind("127.0.0.1:0").unwrap(); let at = server.local_addr().unwrap(); - let stream = Stream::connect(Peer::At(at), &dir.join("s.log"), false, Duration::from_secs(5), 8) + let stream = Stream::connect(Peer::At(at), &dir.join("s.log"), false, Duration::from_secs(5)) .expect("a loopback reader"); drop(server.accept().unwrap()); assert!(stream.wait_ended(Duration::from_secs(5)), "the close is read as an end"); @@ -1298,7 +1289,7 @@ mod tests { let server = TcpListener::bind("127.0.0.1:0").unwrap(); let port = server.local_addr().unwrap().port(); let peer = Peer::Named { host: "localhost".to_string(), port }; - let stream = Stream::connect(peer, &file, false, Duration::from_secs(10), 8).unwrap(); + let stream = Stream::connect(peer, &file, false, Duration::from_secs(10)).unwrap(); let (mut conn, _) = server.accept().unwrap(); for i in 0..100 { writeln!(conn, "[kernel 0.{i:03} cpu0] line {i}").unwrap(); @@ -1321,16 +1312,15 @@ mod tests { /// the bound. #[test] fn a_refused_first_dial_is_asked_again_up_to_its_ceiling() { - const CEILING: usize = 3; let dir = toyos_tmpdir::TempDir::new("metaltalk-first-refused"); let probe = TcpListener::bind("127.0.0.1:0").unwrap(); let at = probe.local_addr().unwrap(); drop(probe); - let stream = Stream::connect(Peer::At(at), &dir.join("s.log"), false, Duration::from_secs(60), CEILING).unwrap(); + let stream = Stream::connect(Peer::At(at), &dir.join("s.log"), false, Duration::from_secs(60)).unwrap(); assert!(stream.wait_connected(Duration::from_secs(5)).is_none(), "nothing listens"); let why = stream.unopened().expect("the dial gave up within 5 s of its 60 and said why"); assert!(why.contains("ceiling") && why.contains("refused"), "{why}"); - assert_eq!(stream.turned_away(), CEILING, "every refused dial, and no more"); + assert_eq!(stream.turned_away(), TURNED_AWAY_CEILING, "every refused dial, and no more"); } /// A machine rebooting behind the address this host's resolver still @@ -1389,7 +1379,7 @@ mod tests { }); let peer = Peer::Named { host: "toyos-t14.local".to_string(), port: at.port() }; let reach: Arc = net.clone(); - let stream = Stream::through(reach, peer, &dir.join("s.log"), false, Duration::from_secs(5), 8).unwrap(); + let stream = Stream::through(reach, peer, &dir.join("s.log"), false, Duration::from_secs(5)).unwrap(); let mut conn = accepted(&server, "the dial after the name answered"); writeln!(conn, "[kernel 1.216 cpu0] Boot: complete (1216ms)").unwrap(); assert_eq!(stream.wait_connected(Duration::from_secs(5)), Some(at), "{:?}", stream.unopened()); @@ -1409,7 +1399,7 @@ mod tests { let dir = toyos_tmpdir::TempDir::new("metaltalk-quiet"); let server = TcpListener::bind("127.0.0.1:0").unwrap(); let at = server.local_addr().unwrap(); - let stream = Stream::connect(Peer::At(at), &dir.join("s.log"), false, Duration::from_secs(5), 8) + let stream = Stream::connect(Peer::At(at), &dir.join("s.log"), false, Duration::from_secs(5)) .expect("a loopback reader"); let (mut conn, _) = server.accept().unwrap(); writeln!(conn, "[kernel 1.216 cpu0] Boot: complete (1216ms)").unwrap(); @@ -1449,7 +1439,7 @@ mod tests { let dir = toyos_tmpdir::TempDir::new("metaltalk-again"); let server = TcpListener::bind("127.0.0.1:0").unwrap(); let at = server.local_addr().unwrap(); - let stream = Stream::connect(Peer::At(at), &dir.join("s.log"), false, Duration::from_secs(5), 8) + let stream = Stream::connect(Peer::At(at), &dir.join("s.log"), false, Duration::from_secs(5)) .expect("a loopback reader"); let mut first = accepted(&server, "the first dial"); writeln!(first, "[kernel 0.001 cpu0] before the swap").unwrap(); @@ -1474,23 +1464,24 @@ mod tests { ); } - /// A machine whose first dial is taken, whose dials after it are turned - /// away before a connection exists until `taken_from`, and whose dials from - /// then on are taken: refused and reset in turn, the two answers a SYN gets - /// from a machine whose listener is gone or going, depending on when it - /// went. + /// A machine on the link whose first dial is taken, whose dials after it + /// are turned away before a connection exists until `taken_from`, and whose + /// dials from then on are taken: refused and reset in turn, the two answers + /// a SYN gets from a machine whose listener is gone or going, depending on + /// when it went. Its name is answered at once, by the resolver and on the + /// link alike. struct TurnedAway { dials: std::sync::atomic::AtomicUsize, taken_from: usize, } impl Reach for TurnedAway { - fn resolve(&self, _: &str, _: u16) -> std::io::Result> { - unreachable!("the stream is dialled by address") + fn resolve(&self, _: &str, port: u16) -> std::io::Result> { + Ok(vec![SocketAddr::from((Ipv4Addr::LOCALHOST, port))]) } fn ask(&self, _: &str, _: Instant) -> Result, String> { - unreachable!("the stream is dialled by address") + Ok(Some(Ipv4Addr::LOCALHOST)) } fn dial(&self, at: SocketAddr) -> std::io::Result { @@ -1502,12 +1493,16 @@ mod tests { } } - /// A reader through `reach` whose first connection from `server` has - /// carried a line, and that connection. - fn read_first(server: &TcpListener, reach: Arc, dir: &Path) -> (Stream, TcpStream) { - let at = server.local_addr().unwrap(); - let stream = Stream::through(reach, Peer::At(at), &dir.join("s.log"), false, Duration::from_secs(5), 8) - .expect("a loopback reader"); + /// `server`'s port, asked for by name. + fn named(server: &TcpListener) -> Peer { + Peer::Named { host: "toyos-t14.local".to_string(), port: server.local_addr().unwrap().port() } + } + + /// A reader of `peer` through `reach` whose first connection from `server` + /// has carried a line, and that connection. + fn read_first(server: &TcpListener, reach: Arc, peer: Peer, dir: &Path) -> (Stream, TcpStream) { + let stream = + Stream::through(reach, peer, &dir.join("s.log"), false, Duration::from_secs(5)).expect("a loopback reader"); let mut first = accepted(server, "the first dial"); writeln!(first, "[kernel 0.001 cpu0] before the swap").unwrap(); assert!(stream.wait_for("before the swap", Duration::from_secs(5))); @@ -1529,6 +1524,25 @@ mod tests { }); } + /// `server` dropping every connection before a byte until the returned + /// call, which ends the thread doing it. + fn close_every(server: &TcpListener) -> impl FnOnce() { + let (at, server) = (server.local_addr().unwrap(), server.try_clone().unwrap()); + let done = Arc::new(std::sync::atomic::AtomicBool::new(false)); + let theirs = Arc::clone(&done); + let closer = std::thread::spawn(move || { + while !theirs.load(std::sync::atomic::Ordering::SeqCst) { + drop(server.accept()); + } + }); + move || { + done.store(true, std::sync::atomic::Ordering::SeqCst); + // Ends the accept the closer may be blocked in. + drop(TcpStream::connect(at)); + closer.join().unwrap(); + } + } + /// **A redial asks past every dial refused or reset, however many, until /// one is taken.** Staged through [`Reach`], so each dial's answer is the /// one this test gives it and arrives at once: far more dials than the @@ -1539,7 +1553,7 @@ mod tests { let dir = toyos_tmpdir::TempDir::new("metaltalk-refused"); let server = TcpListener::bind("127.0.0.1:0").unwrap(); let reach = Arc::new(TurnedAway { dials: 0.into(), taken_from: TURNED + 1 }); - let (stream, _first) = read_first(&server, reach, &dir); + let (stream, _first) = read_first(&server, reach, named(&server), &dir); close_then_replay(&server, 0); stream.redial(Duration::from_secs(60)); assert!(stream.wait_for("after the swap", Duration::from_secs(5)), "{:?}", stream.unopened()); @@ -1554,7 +1568,8 @@ mod tests { const CLOSED: usize = 200; let dir = toyos_tmpdir::TempDir::new("metaltalk-closed"); let server = TcpListener::bind("127.0.0.1:0").unwrap(); - let (stream, _first) = read_first(&server, Arc::new(Net), &dir); + let at = server.local_addr().unwrap(); + let (stream, _first) = read_first(&server, Arc::new(Net), Peer::At(at), &dir); close_then_replay(&server, CLOSED); stream.redial(Duration::from_secs(60)); assert!(stream.wait_for("after the swap", Duration::from_secs(5)), "{:?}", stream.unopened()); @@ -1562,28 +1577,47 @@ mod tests { assert_eq!(stream.connections(), 2); } - /// **A redial ends at its bound alone, and says so**: dials refused, and - /// connections closed before a line, are asked again until the bound - /// passes, and the reader then names the end rather than going quiet. + /// **A redial ends at its bound alone, and says so**: dials refused on a + /// name, and connections closed before a line, are asked again until the + /// bound passes, and the reader then names the end rather than going quiet. #[test] fn a_redial_ends_at_its_bound_alone_and_says_so() { const BOUND: Duration = Duration::from_millis(50); let dir = toyos_tmpdir::TempDir::new("metaltalk-bound"); let server = TcpListener::bind("127.0.0.1:0").unwrap(); let reach = Arc::new(TurnedAway { dials: 0.into(), taken_from: usize::MAX }); - let (refused, _first) = read_first(&server, reach, &dir); + let (refused, _first) = read_first(&server, reach, named(&server), &dir); refused.redial(BOUND); assert_eq!(refused.wait_for_connection(1, Duration::from_secs(5)), None, "nothing is taken"); let why = refused.unopened().expect("the redial ended within 5 s and said why"); assert!(why.contains("by the bound"), "{why}"); let server = TcpListener::bind("127.0.0.1:0").unwrap(); - let (closed, _first) = read_first(&server, Arc::new(Net), &dir); - close_then_replay(&server, usize::MAX); + let at = server.local_addr().unwrap(); + let (closed, _first) = read_first(&server, Arc::new(Net), Peer::At(at), &dir); + let stop_closing = close_every(&server); closed.redial(BOUND); assert_eq!(closed.wait_for_connection(1, Duration::from_secs(5)), None, "every dial closed before a line"); let why = closed.unopened().expect("the redial ended within 5 s and said why"); assert!(why.contains("redial's bound") && why.contains("ended before a line"), "{why}"); + stop_closing(); + } + + /// **A redial of a forward that fails a connect ends at that failure**: + /// QEMU's forward takes every connect while QEMU lives, so a refusal is + /// its exit, named at once rather than dialled until the bound. + #[test] + fn a_redial_on_a_forward_that_refuses_ends_at_the_refusal() { + let dir = toyos_tmpdir::TempDir::new("metaltalk-forward-gone"); + let server = TcpListener::bind("127.0.0.1:0").unwrap(); + let at = server.local_addr().unwrap(); + let (stream, first) = read_first(&server, Arc::new(Net), Peer::At(at), &dir); + drop((server, first)); + stream.redial(Duration::from_secs(60)); + assert_eq!(stream.wait_for_connection(1, Duration::from_secs(5)), None); + let why = stream.unopened().expect("a refusing forward ends the redial at once"); + assert!(why.contains("refused"), "{why}"); + assert_eq!(stream.turned_away(), 1); } /// A reply macOS's mDNSResponder sent this host's legacy question for its diff --git a/src/redlist.rs b/src/redlist.rs index e16b0bfcaf..d389bdf459 100644 --- a/src/redlist.rs +++ b/src/redlist.rs @@ -47,10 +47,6 @@ pub const DISABLED: &[Disabled] = &[ issue: "issues/hardware/i8042-mouse-ends-four-packets-short-with-a-clean-exit.md", }, Disabled { test: "kill_while_blocked", issue: "issues/kernel/deferred-release-outlives-its-syscall.md" }, - Disabled { - test: "lan_swap", - issue: "issues/build/a-swaps-redial-races-a-hard-dial-ceiling-against-an-unbounded-guest-gap.md", - }, Disabled { test: "latency_wake", issue: "issues/build/latency-wake-reds-on-the-dev-host-at-a-rate.md" }, Disabled { test: "log_ring_keeps_the_owners_slots", @@ -84,14 +80,6 @@ pub const DISABLED: &[Disabled] = &[ test: "so_cache_refusals", issue: "issues/kernel/so-cache-refusals-saw-the-kernel-refuse-nothing-once.md", }, - Disabled { - test: "swap_crash_rolls_back", - issue: "issues/build/a-swaps-redial-races-a-hard-dial-ceiling-against-an-unbounded-guest-gap.md", - }, - Disabled { - test: "swap_netd", - issue: "issues/build/a-swaps-redial-races-a-hard-dial-ceiling-against-an-unbounded-guest-gap.md", - }, Disabled { test: "usb_disk_index_stable", issue: "issues/hardware/usb-disk-index-stable-nothing-enumerates-on-the-first-controller.md", diff --git a/tests/common/logstream.rs b/tests/common/logstream.rs index 5aa98515e0..ec621d8cc6 100644 --- a/tests/common/logstream.rs +++ b/tests/common/logstream.rs @@ -109,7 +109,7 @@ fn boot( pub fn reader(port: u16, file: &str) -> Result { let at = SocketAddr::from((Ipv4Addr::LOCALHOST, port)); let path = super::lane::dir().join(file); - let stream = Stream::connect(Peer::At(at), &path, false, CEILING, toyos_build::metaltalk::TURNED_AWAY_CEILING)?; + let stream = Stream::connect(Peer::At(at), &path, false, CEILING)?; stream .wait_connected(CEILING) .ok_or_else(|| stream.unopened().unwrap_or_else(|| "the stream never opened".to_string()))?; From 992de94cceae9d0fc83331ba75fbd2daeac8213f Mon Sep 17 00:00:00 2001 From: japabu Date: Mon, 28 Sep 2026 15:48:14 +0200 Subject: [PATCH 03/10] Review r2 of #566: the diagnostics issue gains its hold-green cost and an owner, and three NOTEs become their own issues MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The redial's forward cost was a NOTE with no evidence: add hold-green's 8125 dials turned away in 7019 ms, 16231 of the guest's 19034 interrupts on cpu0, and hold the diagnostics issue for the orchestrator alongside it. Three more NOTEs from the round-2 review are filed rather than fixed here: the T14's redial still re-asking mDNS after every refusal below RFC 6762 §5.2's floor, `wait_until` for init's final word never waking once the stream is dead, and a ~6 s guest-side gap after `logd` re-binds that a swap's redial actually pays for. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01W6rME2DoqwjcYFStYHHY4j --- ...ord-never-wakes-once-the-stream-is-dead.md | 29 +++++++++++++++++++ ...d-away-for-6-s-after-logd-listens-again.md | 24 +++++++++++++++ ...ial-asks-again-with-no-event-to-wait-on.md | 8 ++++- ...redial-re-asks-mdns-after-every-refusal.md | 24 +++++++++++++++ 4 files changed, 84 insertions(+), 1 deletion(-) create mode 100644 issues/build/wait-until-for-inits-word-never-wakes-once-the-stream-is-dead.md create mode 100644 issues/design-debt/connects-are-turned-away-for-6-s-after-logd-listens-again.md create mode 100644 issues/hardware/the-t14-redial-re-asks-mdns-after-every-refusal.md diff --git a/issues/build/wait-until-for-inits-word-never-wakes-once-the-stream-is-dead.md b/issues/build/wait-until-for-inits-word-never-wakes-once-the-stream-is-dead.md new file mode 100644 index 0000000000..513ecc305e --- /dev/null +++ b/issues/build/wait-until-for-inits-word-never-wakes-once-the-stream-is-dead.md @@ -0,0 +1,29 @@ +--- +status: open +kind: tooling +opened: 2026-09-28 +--- + +# `wait_until` for init's final word never wakes once the stream is dead + +`Stream::wait_until` (`src/metaltalk.rs:260`) is woken by each line as it +lands, and by nothing else. `wait_for_connection` (`src/metaltalk.rs:289`) +computes its own `dialing` — `redial.is_some() || current.is_some() || +unopened.is_none()` — and returns `None` at once once a redial has ended with +no connection: the stream can never carry another line. `metalswap::swap`'s +call to `wait_until` for init's final word (`src/metalswap.rs:214`) has no +such exit, so it waits out its whole `window` even after the stream has +reached that same dead state. + +Predates this branch: a redial that ends without naming a cause already left +`wait_until` waiting before `src/metaltalk.rs:383` started ending a forward's +redial at its first refusal. + +Evidence: hold-red took 124 s this way, run at PR #566's `7e06a657` +(`566r2-hold-red.log:507`, orchestrator's round-2 review job). + +## Exit condition + +Give `wait_until` the same exit `wait_for_connection` already has: return +`None` once the stream's own `dialing` state goes false, instead of waiting +out `by`. diff --git a/issues/design-debt/connects-are-turned-away-for-6-s-after-logd-listens-again.md b/issues/design-debt/connects-are-turned-away-for-6-s-after-logd-listens-again.md new file mode 100644 index 0000000000..d6a4e3a003 --- /dev/null +++ b/issues/design-debt/connects-are-turned-away-for-6-s-after-logd-listens-again.md @@ -0,0 +1,24 @@ +--- +status: open +kind: defect +opened: 2026-09-28 +--- + +# Connects are turned away for 6 s after `logd` listens again + +In a swap of netd, connects to `logd`'s port keep being turned away for about +6 s after `logd` itself has already re-bound the port and init has said the +new netd is in service. In a hold-red run at PR #566's `7e06a657`, netd +re-bound `41337` at 1.758 s and init said `in service` at 6.739 s +(`566r2-hold-red.log:330`, `:332`); the matching hold-green run (guest- +identical, since the branch's fix is host-only) only had its redial admitted +at 7.721 s (`566r2` hold-green oracle line). That is what makes the redial's +window long after a swap — not `logd`'s closed listener during the swap +itself, which is announced and handled. + +## Exit condition + +Whatever holds a bound listener from accepting for those ~6 s is named, and +either removed or bounded by a measured floor — shown by a run whose +admission time tracks `logd`'s own re-bind and init's `in service`, not +trailing it by seconds. diff --git a/issues/diagnostics/a-swaps-redial-asks-again-with-no-event-to-wait-on.md b/issues/diagnostics/a-swaps-redial-asks-again-with-no-event-to-wait-on.md index 6f10b92e6a..f8bc2558c9 100644 --- a/issues/diagnostics/a-swaps-redial-asks-again-with-no-event-to-wait-on.md +++ b/issues/diagnostics/a-swaps-redial-asks-again-with-no-event-to-wait-on.md @@ -1,11 +1,13 @@ --- -status: open +status: assigned kind: defect opened: 2026-09-25 --- # A swap's redial asks again with no event to wait on +Held by the orchestrator. + A swap of netd ends the host's log stream with no FIN and no reset, and `src/metaltalk.rs`'s `Stream::redial` dials `logd` again. Nothing the machine sends says when `logd` listens again: the stream and the ssh channel both die @@ -22,6 +24,10 @@ turned away, as soon as the old netd answers the last ask, so its questions may go out faster than RFC 6762 §5.2's floor between two queries (`ASK_WAIT`); that rate is unmeasured on metal. +The forward's cost is measured: a hold-green run turned away 8125 dials in +7019 ms, and the guest logged 16231 of its 19034 interrupts over that boot, all +on cpu0. + ## Exit condition The host waits on a guest-side event instead of asking again: something the diff --git a/issues/hardware/the-t14-redial-re-asks-mdns-after-every-refusal.md b/issues/hardware/the-t14-redial-re-asks-mdns-after-every-refusal.md new file mode 100644 index 0000000000..87b3bcd384 --- /dev/null +++ b/issues/hardware/the-t14-redial-re-asks-mdns-after-every-refusal.md @@ -0,0 +1,24 @@ +--- +status: open +kind: defect +opened: 2026-09-28 +--- + +# The T14 redial re-asks mDNS after every refusal + +`open` (`src/metaltalk.rs:383`, `:419`, `:452`) sets `on_the_link` on the +first failed dial and never clears it, so once the old or new netd starts +sending refusals or resets, every dial that follows first asks the link for +the name again (`ask_the_link`) before it redials. Without a dial ceiling to +stop that loop, a gap where the machine keeps answering with a refusal sends +multicast queries at LAN round-trip rate for as long as `wait_secs` runs — +below the RFC 6762 §5.2 floor between two queries (`ASK_WAIT`) that the code +itself cites. + +## Exit condition + +A timer-free fix: set `on_the_link` only on a host-absent failure +(`not_yet_reachable`'s `EHOSTDOWN`, `EHOSTUNREACH`, `ENETUNREACH`, or a +failure seen after `WAITED`). A refusal or reset is the machine answering at +that address, so the next dial goes there again with no new ask, and only a +dial that finds nobody home asks the link once more. From 941f0bda0a234f201d227d11828e4ddf66cdb51d Mon Sep 17 00:00:00 2001 From: japabu Date: Mon, 28 Sep 2026 15:54:18 +0200 Subject: [PATCH 04/10] File the forward redial's negative control as load-flaky, off this round's brief Running the round's own cargo test --lib gate under this machine's current concurrent load reproduced a red on a-redial_on_a_forward_that_refuses_ends_at_the_refusal twice in six runs, always green alone or on a quiet host. Filed rather than fixed: it is not named in this round's ruling. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01W6rME2DoqwjcYFStYHHY4j --- ...unts-a-live-listeners-transient-refusal.md | 41 +++++++++++++++++++ 1 file changed, 41 insertions(+) create mode 100644 issues/build/a-forwards-redial-negative-control-counts-a-live-listeners-transient-refusal.md diff --git a/issues/build/a-forwards-redial-negative-control-counts-a-live-listeners-transient-refusal.md b/issues/build/a-forwards-redial-negative-control-counts-a-live-listeners-transient-refusal.md new file mode 100644 index 0000000000..9dd9424a0b --- /dev/null +++ b/issues/build/a-forwards-redial-negative-control-counts-a-live-listeners-transient-refusal.md @@ -0,0 +1,41 @@ +--- +status: open +kind: tooling +opened: 2026-09-28 +--- + +# A forward's redial negative control counts a live listener's transient refusal + +`metaltalk::tests::a_redial_on_a_forward_that_refuses_ends_at_the_refusal` +(PR #566) asserts `stream.turned_away() == 1` after dropping a live listener +and redialling it. On a host carrying other concurrent suites, `cargo test +--lib` reds on it intermittently: `assertion left == right failed: left: 2, +right: 1` (`src/metaltalk.rs:1620`), reproduced twice in six runs at +`f8283ca0` on a host at load average 6.6–15.1 across 14 cores, running another +worktree's `cargo test --lib` and a QEMU guest at the same time; the same test +passes 5/5 run alone and passes on an otherwise-quiet host. + +`open`'s very first dial (`again` false) retries a failed connect with no +ceiling check below `TURNED_AWAY_CEILING`, so a transient refusal from a +listener that is genuinely live and about to accept — an accept-queue drop +under host contention, not the machine going away — is still counted in +`turned_away` (`count_or_give_up` increments before its match). If that +happens once before `read_first`'s connection is finally accepted, the test's +later, deliberate refusal is the *second* count, and `turned_away() == 1` +does not hold even though the redial itself still ended at its own first +failed connect, as designed. + +Evidence: `flake-red-1.log`, `flake-red-2.log` (both `assertion left == right +failed: left: 2, right: 1`, this test only, all other 385 tests green); five +consecutive isolated runs of the same test green (`retry-1.log`…`retry-5.log`); +two more full-suite runs green (`gate-lib-2.log`, `gate-lib-3.log`). All at +`f8283ca0` on `wt/toyos-redial`, in the job scratchpad. + +## Exit condition + +The test's count no longer conflates a retry against a listener that was +still live when dialled with the deliberate refusal it means to measure — for +example by asserting on the redial's own turned-away count (taken right +before `redial()`, subtracted at the end) rather than the stream's lifetime +total — and is shown green across several runs made to overlap another +`cargo test --lib`. From 33cfc3485f80bcd0e49507b6ae1bc8e8d2f56acf Mon Sep 17 00:00:00 2001 From: japabu Date: Mon, 28 Sep 2026 16:00:39 +0200 Subject: [PATCH 05/10] The forward redial's negative control closes the listener before it redials a_redial_on_a_forward_that_refuses_ends_at_the_refusal went red under host load with turned_away() == 2. The landing round blamed the first dial retrying a transient refusal from a live listener. That cannot happen here: the listener is bound before the dial and never holds more than one pending connection, so a loopback SYN to it is taken, never refused. The real race was in the test helper `accepted`. Its thread accepted on a try_clone of the listener and dropped that clone only after sending the connection back. So the test's drop(server) did not close the listener when the helper thread had not yet run past its send. The redial's connect was then taken into the still-live accept queue, reset once the clone closed (read counts it: a connection ended before a line), dialled again, and refused (count_or_give_up counts it and ends the redial). That makes two counts. The product code counted that sequence correctly; the stimulus was wrong. Holding the window open with a 300 ms sleep after the send reproduced it every time (left: 2, right: 1). With the fix, the same sleep stays green. The helper now drops its clone before it sends, so the listener is closed before `accepted` returns. The test also asserts that the first dial counts nothing before the redial, so the first dial's count and the redial's are measured apart. Deletes issues/build/a-forwards-redial-negative-control-counts-a-live-listeners-transient-refusal.md. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01W6rME2DoqwjcYFStYHHY4j --- ...unts-a-live-listeners-transient-refusal.md | 41 ------------------- src/metaltalk.rs | 12 ++++-- 2 files changed, 9 insertions(+), 44 deletions(-) delete mode 100644 issues/build/a-forwards-redial-negative-control-counts-a-live-listeners-transient-refusal.md diff --git a/issues/build/a-forwards-redial-negative-control-counts-a-live-listeners-transient-refusal.md b/issues/build/a-forwards-redial-negative-control-counts-a-live-listeners-transient-refusal.md deleted file mode 100644 index 9dd9424a0b..0000000000 --- a/issues/build/a-forwards-redial-negative-control-counts-a-live-listeners-transient-refusal.md +++ /dev/null @@ -1,41 +0,0 @@ ---- -status: open -kind: tooling -opened: 2026-09-28 ---- - -# A forward's redial negative control counts a live listener's transient refusal - -`metaltalk::tests::a_redial_on_a_forward_that_refuses_ends_at_the_refusal` -(PR #566) asserts `stream.turned_away() == 1` after dropping a live listener -and redialling it. On a host carrying other concurrent suites, `cargo test ---lib` reds on it intermittently: `assertion left == right failed: left: 2, -right: 1` (`src/metaltalk.rs:1620`), reproduced twice in six runs at -`f8283ca0` on a host at load average 6.6–15.1 across 14 cores, running another -worktree's `cargo test --lib` and a QEMU guest at the same time; the same test -passes 5/5 run alone and passes on an otherwise-quiet host. - -`open`'s very first dial (`again` false) retries a failed connect with no -ceiling check below `TURNED_AWAY_CEILING`, so a transient refusal from a -listener that is genuinely live and about to accept — an accept-queue drop -under host contention, not the machine going away — is still counted in -`turned_away` (`count_or_give_up` increments before its match). If that -happens once before `read_first`'s connection is finally accepted, the test's -later, deliberate refusal is the *second* count, and `turned_away() == 1` -does not hold even though the redial itself still ended at its own first -failed connect, as designed. - -Evidence: `flake-red-1.log`, `flake-red-2.log` (both `assertion left == right -failed: left: 2, right: 1`, this test only, all other 385 tests green); five -consecutive isolated runs of the same test green (`retry-1.log`…`retry-5.log`); -two more full-suite runs green (`gate-lib-2.log`, `gate-lib-3.log`). All at -`f8283ca0` on `wt/toyos-redial`, in the job scratchpad. - -## Exit condition - -The test's count no longer conflates a retry against a listener that was -still live when dialled with the deliberate refusal it means to measure — for -example by asserting on the redial's own turned-away count (taken right -before `redial()`, subtracted at the end) rather than the stream's lifetime -total — and is shown green across several runs made to overlap another -`cargo test --lib`. diff --git a/src/metaltalk.rs b/src/metaltalk.rs index 5df905f00d..917edd3ed8 100644 --- a/src/metaltalk.rs +++ b/src/metaltalk.rs @@ -1417,11 +1417,16 @@ mod tests { /// The next connection `server` takes, or a panic naming `what` once a /// bound has passed with none: a reader that stopped dialing fails the test - /// rather than hanging it. + /// rather than hanging it. The clone accepted on is closed before the + /// connection is returned, so dropping `server` then closes the listener. fn accepted(server: &TcpListener, what: &str) -> TcpStream { let server = server.try_clone().unwrap(); let (took, taken) = std::sync::mpsc::channel(); - std::thread::spawn(move || took.send(server.accept().map(|(conn, _)| conn))); + std::thread::spawn(move || { + let conn = server.accept().map(|(conn, _)| conn); + drop(server); + took.send(conn) + }); taken .recv_timeout(Duration::from_secs(5)) .unwrap_or_else(|_| panic!("{what} never connected")) @@ -1612,12 +1617,13 @@ mod tests { let server = TcpListener::bind("127.0.0.1:0").unwrap(); let at = server.local_addr().unwrap(); let (stream, first) = read_first(&server, Arc::new(Net), Peer::At(at), &dir); + assert_eq!(stream.turned_away(), 0, "the first dial was taken by a live listener"); drop((server, first)); stream.redial(Duration::from_secs(60)); assert_eq!(stream.wait_for_connection(1, Duration::from_secs(5)), None); let why = stream.unopened().expect("a refusing forward ends the redial at once"); assert!(why.contains("refused"), "{why}"); - assert_eq!(stream.turned_away(), 1); + assert_eq!(stream.turned_away(), 1, "the redial's one refused connect"); } /// A reply macOS's mDNSResponder sent this host's legacy question for its From 8cc19ef148b69c3571999768eb76b592606cb1aa Mon Sep 17 00:00:00 2001 From: japabu Date: Mon, 28 Sep 2026 16:08:54 +0200 Subject: [PATCH 06/10] The forward redial's refusal is staged through Reach, not a dropped listener This corrects 33cfc348's root cause, which was incomplete. Closing `accepted`'s clone before its send closed one window (a 300 ms sleep after the send reproduced the red every time). But in the full `--lib` suite under load, that binary still went red on this test 9 times in 41 runs. The pre-fix binary went red 9 times in the same 41, interleaved with it. The listener has a second holder: any child process this test process is spawning. A spawned child holds a copy of every fd until its exec closes the close-on-exec ones, and many lib tests spawn processes (git, cargo, the test binary itself). A scratch probe measured it: bind 127.0.0.1:0, drop, connect, 20000 times. - No concurrent spawn: 0 taken, 0 reset, 20000 refused (twice). - A thread spawning children beside it: 34 taken and 4 reset, then 26 taken and 7 reset. So no test can make a dropped loopback listener provably gone. The redial's connect was taken by the still-open listener and reset once the child's exec closed it, which `read` counts. It was then dialled again and refused, which `count_or_give_up` counts. That makes two counts. The product code counts that sequence correctly and is unchanged. The test now stages the forward through `TurnedAway`, as the other redial tests stage their refusals. The first dial is real and taken, and every dial after it is refused or reset by the test. It asserts that the first dial counts nothing and that the redial counts its one refused connect. The `accepted` change is reverted, since no test depends on a dropped listener closing any more. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01W6rME2DoqwjcYFStYHHY4j --- src/metaltalk.rs | 19 ++++++++----------- 1 file changed, 8 insertions(+), 11 deletions(-) diff --git a/src/metaltalk.rs b/src/metaltalk.rs index 917edd3ed8..60f05721ca 100644 --- a/src/metaltalk.rs +++ b/src/metaltalk.rs @@ -1417,16 +1417,11 @@ mod tests { /// The next connection `server` takes, or a panic naming `what` once a /// bound has passed with none: a reader that stopped dialing fails the test - /// rather than hanging it. The clone accepted on is closed before the - /// connection is returned, so dropping `server` then closes the listener. + /// rather than hanging it. fn accepted(server: &TcpListener, what: &str) -> TcpStream { let server = server.try_clone().unwrap(); let (took, taken) = std::sync::mpsc::channel(); - std::thread::spawn(move || { - let conn = server.accept().map(|(conn, _)| conn); - drop(server); - took.send(conn) - }); + std::thread::spawn(move || took.send(server.accept().map(|(conn, _)| conn))); taken .recv_timeout(Duration::from_secs(5)) .unwrap_or_else(|_| panic!("{what} never connected")) @@ -1610,15 +1605,17 @@ mod tests { /// **A redial of a forward that fails a connect ends at that failure**: /// QEMU's forward takes every connect while QEMU lives, so a refusal is - /// its exit, named at once rather than dialled until the bound. + /// its exit, named at once rather than dialled until the bound. The + /// refusal is staged through [`Reach`]: a listener this process drops + /// still takes connects while any child it is spawning holds the fd. #[test] fn a_redial_on_a_forward_that_refuses_ends_at_the_refusal() { let dir = toyos_tmpdir::TempDir::new("metaltalk-forward-gone"); let server = TcpListener::bind("127.0.0.1:0").unwrap(); let at = server.local_addr().unwrap(); - let (stream, first) = read_first(&server, Arc::new(Net), Peer::At(at), &dir); - assert_eq!(stream.turned_away(), 0, "the first dial was taken by a live listener"); - drop((server, first)); + let reach = Arc::new(TurnedAway { dials: 0.into(), taken_from: usize::MAX }); + let (stream, _first) = read_first(&server, reach, Peer::At(at), &dir); + assert_eq!(stream.turned_away(), 0, "the first dial was taken"); stream.redial(Duration::from_secs(60)); assert_eq!(stream.wait_for_connection(1, Duration::from_secs(5)), None); let why = stream.unopened().expect("a refusing forward ends the redial at once"); From 54ce11ea3854726d02c4cb7153ec1c203ad9d807 Mon Sep 17 00:00:00 2001 From: japabu Date: Mon, 28 Sep 2026 16:34:36 +0200 Subject: [PATCH 07/10] File three lib tests the loaded full suite reddens, found proving the forward redial's fix The proof loop for 8cc19ef1 ran 200 full `--lib` suites of its test binary and of 941f0bda's, interleaved, beside `cargo test --workspace --exclude toyos-build` at one-minute load averages up to 43. Three other tests went red. None is on this round's brief, so all three are filed and not fixed. - a_refused_first_dial_is_asked_again_up_to_its_ceiling: once for 8cc19ef1 and twice for 941f0bda. It dials a dropped listener, which is the measured spawn-held-fd mechanism. - a_redial_ends_at_its_bound_alone_and_says_so: once for 941f0bda. Its reader woke past a 50 ms bound and never dialled. - buildlock's a_key_being_built_is_waited_for_and_another_key_is_not: once for 8cc19ef1. A dropped lock was still held; the cause is unmeasured. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01W6rME2DoqwjcYFStYHHY4j --- ...k-is-still-held-in-the-loaded-lib-suite.md | 27 +++++++++++++ ...ed-listener-a-spawned-child-still-holds.md | 38 +++++++++++++++++++ ...-reader-dials-within-fifty-milliseconds.md | 27 +++++++++++++ 3 files changed, 92 insertions(+) create mode 100644 issues/build/a-dropped-keyed-lock-is-still-held-in-the-loaded-lib-suite.md create mode 100644 issues/build/a-first-dials-ceiling-test-dials-a-dropped-listener-a-spawned-child-still-holds.md create mode 100644 issues/build/a-redials-bound-test-assumes-its-reader-dials-within-fifty-milliseconds.md diff --git a/issues/build/a-dropped-keyed-lock-is-still-held-in-the-loaded-lib-suite.md b/issues/build/a-dropped-keyed-lock-is-still-held-in-the-loaded-lib-suite.md new file mode 100644 index 0000000000..7a75cd70ab --- /dev/null +++ b/issues/build/a-dropped-keyed-lock-is-still-held-in-the-loaded-lib-suite.md @@ -0,0 +1,27 @@ +--- +status: open +kind: tooling +opened: 2026-09-28 +--- + +# A dropped keyed lock is still held in the loaded lib suite + +`buildlock::tests::a_key_being_built_is_waited_for_and_another_key_is_not` +went red once in 200 full `--lib` suite runs, at `8cc19ef1` and one-minute load average +40.1, beside `cargo test --workspace --exclude toyos-build`. It failed at +`src/buildlock.rs:945`: `assertion failed: keyed_idle(&root, Keyed::Sysroot, +"k1").is_some()`, right after `drop(using)`. Evidence: +`l3-staged-171.log` in the job scratchpad `redial-r3/`. + +Unmeasured hypothesis: a `flock` belongs to the open file description, so a +child that another test in the same process is spawning shares `using`'s +lock until its exec closes the fd. `drop(using)` then releases nothing yet. +The same mechanism was measured for a dropped TCP listener, whose accepts +outlive its drop +(`issues/build/a-first-dials-ceiling-test-dials-a-dropped-listener-a-spawned-child-still-holds.md`). + +## Exit condition + +The cause is measured, and the test's release is one no concurrent spawn can +defer. It is shown green across at least 200 full `--lib` suite runs beside +`cargo test --workspace --exclude toyos-build`. diff --git a/issues/build/a-first-dials-ceiling-test-dials-a-dropped-listener-a-spawned-child-still-holds.md b/issues/build/a-first-dials-ceiling-test-dials-a-dropped-listener-a-spawned-child-still-holds.md new file mode 100644 index 0000000000..f2e397defa --- /dev/null +++ b/issues/build/a-first-dials-ceiling-test-dials-a-dropped-listener-a-spawned-child-still-holds.md @@ -0,0 +1,38 @@ +--- +status: open +kind: tooling +opened: 2026-09-28 +--- + +# A first dial's ceiling test dials a dropped listener that a spawned child still holds + +`metaltalk::tests::a_refused_first_dial_is_asked_again_up_to_its_ceiling` +binds `127.0.0.1:0`, drops the listener, and expects every dial to that +address to be refused. That holds only while no other thread in the test +process is spawning a child. A spawned child holds a copy of every fd until +its exec closes the close-on-exec ones, and while it does, the dropped +listener still completes handshakes. Many lib tests spawn processes. + +When one of the stream's first dials is taken, the connection closes before +a line once the child's exec closes the listener. A first dial does not ask +again after that, so `unopened` stays `None`. The test then reds on "the dial +gave up within 5 s of its 60 and said why". + +Evidence, in the job scratchpad `redial-r3/`: +- `l3-staged-109.log`: this red in the full `--lib` suite at `8cc19ef1`, 1 of + 200 full-suite runs, at one-minute load average 42.2, beside + `cargo test --workspace --exclude toyos-build`. `941f0bda`'s test binary, + run interleaved with it, reddened here twice in its 200. +- `fdprobe/`: bind, drop, connect, 20000 times per run. With no concurrent + spawn, 0 were taken in each of two runs. With a thread spawning children + beside it, 34 were taken and 4 reset, then 26 taken and 7 reset. + +PR #566 raised this test's dials from 3 to `TURNED_AWAY_CEILING` (64), which +widens the time its dials span. `a_redial_on_a_forward_that_refuses_ends_at_the_refusal` +had the same shape and now stages its refusal through `Reach`. + +## Exit condition + +The test's refusals come from a staged `Reach` rather than a dropped +listener. It is shown green across at least 200 full `--lib` suite runs beside +`cargo test --workspace --exclude toyos-build`. diff --git a/issues/build/a-redials-bound-test-assumes-its-reader-dials-within-fifty-milliseconds.md b/issues/build/a-redials-bound-test-assumes-its-reader-dials-within-fifty-milliseconds.md new file mode 100644 index 0000000000..6bbd11ce2b --- /dev/null +++ b/issues/build/a-redials-bound-test-assumes-its-reader-dials-within-fifty-milliseconds.md @@ -0,0 +1,27 @@ +--- +status: open +kind: tooling +opened: 2026-09-28 +--- + +# A redial's bound test assumes its reader dials within fifty milliseconds + +`metaltalk::tests::a_redial_ends_at_its_bound_alone_and_says_so` redials with +a 50 ms bound. Its closed-before-a-line arm asserts that the reason names +"redial's bound" and "ended before a line", so the reader must dial at least +once inside those 50 ms. Under load the reader thread can wake after the +bound has passed. `open` then never dials and says so: `At(127.0.0.1:52453) +was not serving its log by the bound: never asked`. That answer is correct +for a redial whose bound passed before a dial. The test's red is its own +assumption about the host's scheduler. + +Seen once in 200 full `--lib` suite runs of `941f0bda`'s test binary, at +one-minute load average 19.7, sampled after the run, beside `cargo test --workspace --exclude +toyos-build`: `l3-prefix-25.log` in the job scratchpad `redial-r3/`. The test +is the same at `8cc19ef1`, which was green in the same 200 runs. + +## Exit condition + +The arm's first dial is an event the test waits on, not one it expects inside +a wall-clock bound. It is shown green across at least 200 full `--lib` suite +runs beside `cargo test --workspace --exclude toyos-build`. From e47d1f064bf3a2ae18d15d934ac7f56628a501d2 Mon Sep 17 00:00:00 2001 From: japabu Date: Mon, 28 Sep 2026 16:48:53 +0200 Subject: [PATCH 08/10] The first dial's ceiling and the redial's bound tests hold without the scheduler Two of this PR's lib tests reddened under load, each 1 in 200 full `--lib` suite runs beside `cargo test --workspace --exclude toyos-build`. `a_refused_first_dial_is_asked_again_up_to_its_ceiling` dialled a dropped listener. A child that another test in the same process is spawning holds a copy of that fd until its exec, and while it does the listener takes connects (8cc19ef1 measured this). Its refusals are now staged through `Reach` by `Refusing`, as the forward test's are. Every dial is refused, and the stage refuses a resolve or an ask loudly, since an address is only dialled. `a_redial_ends_at_its_bound_alone_and_says_so` assumed its reader dials inside a 50 ms bound. The bound is computed in `redial` on the test's thread and read on the reader's, so no test can make that dial happen without a clock seam, and adding one is a production change. The test now accepts either history and checks the reason names what happened. A redial that never dialled ends "by the bound: never asked". A redial that dialled ends on its one close, which `close_every` makes only once the bound has passed since it took the connection, so `serve`'s check ends the redial and names the close. More than one counted dial fails the test. Injecting a 100 ms delay before a redial's first dial reproduces the filed red on the old test (EXIT=101, "never asked") and passes the new one (EXIT=0). Along the way I found a window this test no longer reaches: `serve` continues inside the bound, `open` then re-reads the clock, and a redial that dialled can end saying "never asked". It is filed as issues/diagnostics/a-redial-that-dialled-can-end-saying-never-asked.md. Both issue files are deleted. The keyed-lock issue's citation of the first one goes with it. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01W6rME2DoqwjcYFStYHHY4j --- ...k-is-still-held-in-the-loaded-lib-suite.md | 3 +- ...ed-listener-a-spawned-child-still-holds.md | 38 ------------ ...-reader-dials-within-fifty-milliseconds.md | 27 --------- ...that-dialled-can-end-saying-never-asked.md | 25 ++++++++ src/metaltalk.rs | 59 +++++++++++++++---- 5 files changed, 74 insertions(+), 78 deletions(-) delete mode 100644 issues/build/a-first-dials-ceiling-test-dials-a-dropped-listener-a-spawned-child-still-holds.md delete mode 100644 issues/build/a-redials-bound-test-assumes-its-reader-dials-within-fifty-milliseconds.md create mode 100644 issues/diagnostics/a-redial-that-dialled-can-end-saying-never-asked.md diff --git a/issues/build/a-dropped-keyed-lock-is-still-held-in-the-loaded-lib-suite.md b/issues/build/a-dropped-keyed-lock-is-still-held-in-the-loaded-lib-suite.md index 7a75cd70ab..634e985102 100644 --- a/issues/build/a-dropped-keyed-lock-is-still-held-in-the-loaded-lib-suite.md +++ b/issues/build/a-dropped-keyed-lock-is-still-held-in-the-loaded-lib-suite.md @@ -17,8 +17,7 @@ Unmeasured hypothesis: a `flock` belongs to the open file description, so a child that another test in the same process is spawning shares `using`'s lock until its exec closes the fd. `drop(using)` then releases nothing yet. The same mechanism was measured for a dropped TCP listener, whose accepts -outlive its drop -(`issues/build/a-first-dials-ceiling-test-dials-a-dropped-listener-a-spawned-child-still-holds.md`). +outlive its drop. ## Exit condition diff --git a/issues/build/a-first-dials-ceiling-test-dials-a-dropped-listener-a-spawned-child-still-holds.md b/issues/build/a-first-dials-ceiling-test-dials-a-dropped-listener-a-spawned-child-still-holds.md deleted file mode 100644 index f2e397defa..0000000000 --- a/issues/build/a-first-dials-ceiling-test-dials-a-dropped-listener-a-spawned-child-still-holds.md +++ /dev/null @@ -1,38 +0,0 @@ ---- -status: open -kind: tooling -opened: 2026-09-28 ---- - -# A first dial's ceiling test dials a dropped listener that a spawned child still holds - -`metaltalk::tests::a_refused_first_dial_is_asked_again_up_to_its_ceiling` -binds `127.0.0.1:0`, drops the listener, and expects every dial to that -address to be refused. That holds only while no other thread in the test -process is spawning a child. A spawned child holds a copy of every fd until -its exec closes the close-on-exec ones, and while it does, the dropped -listener still completes handshakes. Many lib tests spawn processes. - -When one of the stream's first dials is taken, the connection closes before -a line once the child's exec closes the listener. A first dial does not ask -again after that, so `unopened` stays `None`. The test then reds on "the dial -gave up within 5 s of its 60 and said why". - -Evidence, in the job scratchpad `redial-r3/`: -- `l3-staged-109.log`: this red in the full `--lib` suite at `8cc19ef1`, 1 of - 200 full-suite runs, at one-minute load average 42.2, beside - `cargo test --workspace --exclude toyos-build`. `941f0bda`'s test binary, - run interleaved with it, reddened here twice in its 200. -- `fdprobe/`: bind, drop, connect, 20000 times per run. With no concurrent - spawn, 0 were taken in each of two runs. With a thread spawning children - beside it, 34 were taken and 4 reset, then 26 taken and 7 reset. - -PR #566 raised this test's dials from 3 to `TURNED_AWAY_CEILING` (64), which -widens the time its dials span. `a_redial_on_a_forward_that_refuses_ends_at_the_refusal` -had the same shape and now stages its refusal through `Reach`. - -## Exit condition - -The test's refusals come from a staged `Reach` rather than a dropped -listener. It is shown green across at least 200 full `--lib` suite runs beside -`cargo test --workspace --exclude toyos-build`. diff --git a/issues/build/a-redials-bound-test-assumes-its-reader-dials-within-fifty-milliseconds.md b/issues/build/a-redials-bound-test-assumes-its-reader-dials-within-fifty-milliseconds.md deleted file mode 100644 index 6bbd11ce2b..0000000000 --- a/issues/build/a-redials-bound-test-assumes-its-reader-dials-within-fifty-milliseconds.md +++ /dev/null @@ -1,27 +0,0 @@ ---- -status: open -kind: tooling -opened: 2026-09-28 ---- - -# A redial's bound test assumes its reader dials within fifty milliseconds - -`metaltalk::tests::a_redial_ends_at_its_bound_alone_and_says_so` redials with -a 50 ms bound. Its closed-before-a-line arm asserts that the reason names -"redial's bound" and "ended before a line", so the reader must dial at least -once inside those 50 ms. Under load the reader thread can wake after the -bound has passed. `open` then never dials and says so: `At(127.0.0.1:52453) -was not serving its log by the bound: never asked`. That answer is correct -for a redial whose bound passed before a dial. The test's red is its own -assumption about the host's scheduler. - -Seen once in 200 full `--lib` suite runs of `941f0bda`'s test binary, at -one-minute load average 19.7, sampled after the run, beside `cargo test --workspace --exclude -toyos-build`: `l3-prefix-25.log` in the job scratchpad `redial-r3/`. The test -is the same at `8cc19ef1`, which was green in the same 200 runs. - -## Exit condition - -The arm's first dial is an event the test waits on, not one it expects inside -a wall-clock bound. It is shown green across at least 200 full `--lib` suite -runs beside `cargo test --workspace --exclude toyos-build`. diff --git a/issues/diagnostics/a-redial-that-dialled-can-end-saying-never-asked.md b/issues/diagnostics/a-redial-that-dialled-can-end-saying-never-asked.md new file mode 100644 index 0000000000..7731049b95 --- /dev/null +++ b/issues/diagnostics/a-redial-that-dialled-can-end-saying-never-asked.md @@ -0,0 +1,25 @@ +--- +status: open +kind: tooling +opened: 2026-09-28 +--- + +# A redial that dialled can end saying it never asked + +`src/metaltalk.rs`'s `serve` asks a redial's connection closed before a line +again while `Instant::now() < until`, and `open` then reads the clock afresh +before its first dial, starting from `last = "never asked"`. When the bound +passes between those two reads, the redial's reason (`Stream::unopened`) is +`… was not serving its log by the bound: never asked`, although it dialled and +counted every close (`Stream::turned_away`). The metal loop records that +reason as the redial's end. Read from the code, not yet observed. + +`metaltalk::tests::a_redial_ends_at_its_bound_alone_and_says_so` holds each +connection past the bound so its redial ends on `serve`'s check, and does not +reach this window. + +## Exit condition + +A redial whose bound passes after it has dialled names what its latest dial +got, and a test that stages the bound passing between the two reads shows +that it does. diff --git a/src/metaltalk.rs b/src/metaltalk.rs index 60f05721ca..ee74b07a58 100644 --- a/src/metaltalk.rs +++ b/src/metaltalk.rs @@ -1309,20 +1309,37 @@ mod tests { /// **A first dial refused is asked again, counted, and ends at its /// ceiling**: a machine still coming up refuses until `logd` listens, and /// one that never does is named at the ceiling rather than waited on to - /// the bound. + /// the bound. The refusals are staged through [`Reach`]: a listener this + /// process drops still takes connects while any child it is spawning holds + /// the fd. #[test] fn a_refused_first_dial_is_asked_again_up_to_its_ceiling() { let dir = toyos_tmpdir::TempDir::new("metaltalk-first-refused"); - let probe = TcpListener::bind("127.0.0.1:0").unwrap(); - let at = probe.local_addr().unwrap(); - drop(probe); - let stream = Stream::connect(Peer::At(at), &dir.join("s.log"), false, Duration::from_secs(60)).unwrap(); + let at = Peer::At(SocketAddr::from((Ipv4Addr::LOCALHOST, toyos_logstream::PORT))); + let stream = Stream::through(Arc::new(Refusing), at, &dir.join("s.log"), false, Duration::from_secs(60)).unwrap(); assert!(stream.wait_connected(Duration::from_secs(5)).is_none(), "nothing listens"); let why = stream.unopened().expect("the dial gave up within 5 s of its 60 and said why"); assert!(why.contains("ceiling") && why.contains("refused"), "{why}"); assert_eq!(stream.turned_away(), TURNED_AWAY_CEILING, "every refused dial, and no more"); } + /// An address nothing listens on: every dial is refused. + struct Refusing; + + impl Reach for Refusing { + fn resolve(&self, _: &str, _: u16) -> std::io::Result> { + unreachable!("an address is dialled, never resolved") + } + + fn ask(&self, _: &str, _: Instant) -> Result, String> { + unreachable!("an address is dialled, never asked for") + } + + fn dial(&self, _: SocketAddr) -> std::io::Result { + Err(std::io::ErrorKind::ConnectionRefused.into()) + } + } + /// A machine rebooting behind the address this host's resolver still /// keeps for it: every dial to `at` fails with its host down, as this /// host's ARP answers for an address nothing holds, until the machine has @@ -1524,15 +1541,26 @@ mod tests { }); } - /// `server` dropping every connection before a byte until the returned - /// call, which ends the thread doing it. - fn close_every(server: &TcpListener) -> impl FnOnce() { + /// Returns once this host's clock has reached `at`. A bound's passing is + /// the event, and only the clock says so. + fn past(at: Instant) { + while let Some(left) = at.checked_duration_since(Instant::now()).filter(|left| !left.is_zero()) { + std::thread::sleep(left); + } + } + + /// `server` closing every connection before a byte, each once `held` has + /// passed since it was taken, until the returned call, which ends the + /// thread doing it. + fn close_every(server: &TcpListener, held: Duration) -> impl FnOnce() { let (at, server) = (server.local_addr().unwrap(), server.try_clone().unwrap()); let done = Arc::new(std::sync::atomic::AtomicBool::new(false)); let theirs = Arc::clone(&done); let closer = std::thread::spawn(move || { while !theirs.load(std::sync::atomic::Ordering::SeqCst) { - drop(server.accept()); + let taken = server.accept(); + past(Instant::now() + held); + drop(taken); } }); move || { @@ -1580,6 +1608,11 @@ mod tests { /// **A redial ends at its bound alone, and says so**: dials refused on a /// name, and connections closed before a line, are asked again until the /// bound passes, and the reader then names the end rather than going quiet. + /// + /// Whether the reader dials inside a 50 ms bound at all is the host + /// scheduler's, and a redial that did not says so too. A connection is + /// closed only once the bound has passed since it was taken, so a redial + /// that dialled ends on its first close, which is past its bound. #[test] fn a_redial_ends_at_its_bound_alone_and_says_so() { const BOUND: Duration = Duration::from_millis(50); @@ -1595,11 +1628,15 @@ mod tests { let server = TcpListener::bind("127.0.0.1:0").unwrap(); let at = server.local_addr().unwrap(); let (closed, _first) = read_first(&server, Arc::new(Net), Peer::At(at), &dir); - let stop_closing = close_every(&server); + let stop_closing = close_every(&server, BOUND); closed.redial(BOUND); assert_eq!(closed.wait_for_connection(1, Duration::from_secs(5)), None, "every dial closed before a line"); let why = closed.unopened().expect("the redial ended within 5 s and said why"); - assert!(why.contains("redial's bound") && why.contains("ended before a line"), "{why}"); + match closed.turned_away() { + 0 => assert!(why.ends_with("by the bound: never asked"), "{why}"), + 1 => assert!(why.contains("redial's bound") && why.contains("ended before a line"), "{why}"), + n => panic!("{n} dials counted, where the first was closed past the bound: {why}"), + } stop_closing(); } From 76cbf2d73a5441dd68e654660bfcad358fdb5fb7 Mon Sep 17 00:00:00 2001 From: japabu Date: Mon, 28 Sep 2026 18:17:55 +0200 Subject: [PATCH 09/10] A redial that dialled names its latest close at the bound, and the tests' closes reach the reader whatever a child holds `serve` read the clock after a connection closed before a line, and `open` read it again before its first dial, starting from "never asked". A bound passing between the two reads ended a redial that had dialled, and counted the close, with "... by the bound: never asked". `serve` no longer reads the bound: it hands the close's reason to `open` as its `last`, so `open`'s one bound check names every redial's end, and `serve`'s second reason format is gone. `read` returns how a connection it counted as turned away ended, in place of a bool. `a_redial_ends_at_its_bound_alone_and_says_so` now requires a redial that dialled once to end with "by the bound: the latest connection ended before a line". Against the unfixed production code it is red on the deleted format; with round 4's m2a on that code, and with the fix's reason not carried, it is red on "by the bound: never asked". The tests' three closes of an accepted connection shut it down before dropping it: on macOS std sets close-on-exec only after `accept` returns, and a child spawned in that window holds a copy that keeps the reader from seeing EOF. `close_every`'s closer ends on the wake-up connection rather than closing it. Deletes issues/diagnostics/a-redial-that-dialled-can-end-saying-never-asked.md, the defect being fixed. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01W6rME2DoqwjcYFStYHHY4j --- ...that-dialled-can-end-saying-never-asked.md | 25 ------- src/metaltalk.rs | 73 +++++++++++-------- 2 files changed, 44 insertions(+), 54 deletions(-) delete mode 100644 issues/diagnostics/a-redial-that-dialled-can-end-saying-never-asked.md diff --git a/issues/diagnostics/a-redial-that-dialled-can-end-saying-never-asked.md b/issues/diagnostics/a-redial-that-dialled-can-end-saying-never-asked.md deleted file mode 100644 index 7731049b95..0000000000 --- a/issues/diagnostics/a-redial-that-dialled-can-end-saying-never-asked.md +++ /dev/null @@ -1,25 +0,0 @@ ---- -status: open -kind: tooling -opened: 2026-09-28 ---- - -# A redial that dialled can end saying it never asked - -`src/metaltalk.rs`'s `serve` asks a redial's connection closed before a line -again while `Instant::now() < until`, and `open` then reads the clock afresh -before its first dial, starting from `last = "never asked"`. When the bound -passes between those two reads, the redial's reason (`Stream::unopened`) is -`… was not serving its log by the bound: never asked`, although it dialled and -counted every close (`Stream::turned_away`). The metal loop records that -reason as the redial's end. Read from the code, not yet observed. - -`metaltalk::tests::a_redial_ends_at_its_bound_alone_and_says_so` holds each -connection past the bound so its redial ends on `serve`'s check, and does not -reach this window. - -## Exit condition - -A redial whose bound passes after it has dialled names what its latest dial -got, and a test that stages the bound passing between the two reads shows -that it does. diff --git a/src/metaltalk.rs b/src/metaltalk.rs index ee74b07a58..3cc2c56ae3 100644 --- a/src/metaltalk.rs +++ b/src/metaltalk.rs @@ -327,8 +327,9 @@ fn serve(reach: &dyn Reach, peer: &Peer, shared: &Shared, mut out: std::fs::File // first dial, where that close is `logd`'s answer, and always on a redial, // which is made while the machine's network is coming back. let mut again = false; + let mut last = String::from("never asked"); loop { - match open(reach, peer, until, shared, again) { + match open(reach, peer, until, shared, again, last) { Err(why) => { let mut state = shared.state.lock().expect("the stream's state"); state.unopened = Some(why); @@ -338,20 +339,14 @@ fn serve(reach: &dyn Reach, peer: &Peer, shared: &Shared, mut out: std::fs::File if echo { println!(" stream: reading {peer:?} at {:?}", conn.peer_addr().ok()); } - let carried = read(conn, shared, &mut out, echo); // A connection `logd` turned away on a redial: asked again at - // once inside the redial's bound, the refusal being the event, - // and the redial's end once past it. - if !carried && again { - let mut state = shared.state.lock().expect("the stream's state"); + // once, the refusal being the event, and named by the dial + // after it should the redial's bound end that one. + if let Some(how) = read(conn, shared, &mut out, echo).filter(|_| again) { + let state = shared.state.lock().expect("the stream's state"); if !state.stop && state.redial.is_none() { - if Instant::now() < until { - continue; - } - state.unopened = Some(format!( - "{peer:?} admitted no connection by the redial's bound: the latest ended before a line" - )); - shared.moved.notify_all(); + last = format!("the latest connection ended before a line: {how}"); + continue; } } } @@ -364,6 +359,7 @@ fn serve(reach: &dyn Reach, peer: &Peer, shared: &Shared, mut out: std::fs::File if let Some(by) = state.redial.take() { until = by; again = true; + last = String::from("never asked"); state.unopened = None; break; } @@ -396,15 +392,22 @@ fn not_yet_reachable(e: &std::io::Error) -> bool { || matches!(e.raw_os_error(), Some(libc::EHOSTDOWN | libc::EHOSTUNREACH | libc::ENETUNREACH)) } -/// The connection, or why there is none by `until`. +/// The connection, or why there is none by `until`, `last` naming what the +/// dial before this one got. /// /// **The ceiling counts dials, not asks.** A connect that failed is counted, /// and so is a connection closed before a line (`read`); an ask of the name is /// a wait on the machine's answer, bounded by `until` alone, and one that /// returns at once is no ask at all and ends the dial. -fn open(reach: &dyn Reach, peer: &Peer, until: Instant, shared: &Shared, again: bool) -> Result { +fn open( + reach: &dyn Reach, + peer: &Peer, + until: Instant, + shared: &Shared, + again: bool, + mut last: String, +) -> Result { let stopped = || shared.state.lock().expect("the stream's state").stop; - let mut last = String::from("never asked"); // Set by the first failed dial: the resolver's answer may be the one its // cache kept, so the name is asked of the machine from then on. let mut on_the_link = false; @@ -609,14 +612,14 @@ fn dns_name(bytes: &[u8], at: usize) -> Option<(String, usize)> { } } -/// Read one connection's lines into the stream until it ends, and whether it -/// carried one. +/// Read one connection's lines into the stream until it ends, and how it ended +/// where it carried none. /// /// **Every connection replays the boot from its first line** (`logd`'s /// `serve.rs`): the lines this reader already has are skipped rather than kept /// twice, and a line the connection ends inside is dropped rather than kept, so /// the same content lands whole on the next connection. -fn read(conn: TcpStream, shared: &Shared, out: &mut std::fs::File, echo: bool) -> bool { +fn read(conn: TcpStream, shared: &Shared, out: &mut std::fs::File, echo: bool) -> Option { let opened = Instant::now(); let at = conn.peer_addr().ok(); let mut skip = { @@ -624,7 +627,7 @@ fn read(conn: TcpStream, shared: &Shared, out: &mut std::fs::File, echo: bool) - // A redial asked for while this connection was being made wants a // connection made after the ask, and this is not one. if state.stop || state.redial.is_some() { - return false; + return Some("this reader dropped it, made before the latest ask".to_string()); } state.current = conn.try_clone().ok(); state.lines.len() @@ -666,6 +669,7 @@ fn read(conn: TcpStream, shared: &Shared, out: &mut std::fs::File, echo: bool) - if echo { println!(" stream: ended {} ms after it opened, {}: {}", end.after_ms, if carried { "admitted" } else { "turned away" }, end.how); } + let turned_away = (!carried).then(|| end.how.clone()); let mut state = shared.state.lock().expect("the stream's state"); state.current = None; // A connection never admitted leaves the latest admitted one's account as @@ -673,11 +677,11 @@ fn read(conn: TcpStream, shared: &Shared, out: &mut std::fs::File, echo: bool) - if carried || state.admitted == 0 { state.end = Some(end); } - if !carried { + if turned_away.is_some() { state.turned_away += 1; } shared.moved.notify_all(); - carried + turned_away } /// How a stream's connection ended. @@ -1169,6 +1173,7 @@ pub fn judge(heard: &Heard, stream: &[String]) -> Result, Vec, reboot: Result) -> Heard { let said = Conversation { @@ -1445,6 +1450,12 @@ mod tests { .unwrap() } + /// Ends `conn` for its reader: a drop alone does not while a child spawned + /// between its accept and its close-on-exec holds a copy. + fn close(conn: TcpStream) { + conn.shutdown(Shutdown::Both).unwrap(); + } + /// **A redial ends the connection it replaces, asks again past every /// connection turned away before a line, and keeps each line once.** The /// first connection is left open, as a swapped netd leaves it; the second @@ -1462,7 +1473,7 @@ mod tests { writeln!(first, "[kernel 0.001 cpu0] before the swap").unwrap(); assert!(stream.wait_for("before the swap", Duration::from_secs(5))); stream.redial(Duration::from_secs(5)); - drop(accepted(&server, "the redial")); + close(accepted(&server, "the redial")); let mut third = accepted(&server, "the dial after a connection turned away"); writeln!(third, "[kernel 0.001 cpu0] before the swap").unwrap(); writeln!(third, "[kernel 9.000 cpu0] after the swap").unwrap(); @@ -1533,7 +1544,7 @@ mod tests { let server = server.try_clone().unwrap(); std::thread::spawn(move || { for _ in 0..closed { - drop(server.accept()); + close(server.accept().unwrap().0); } let (mut conn, _) = server.accept().unwrap(); writeln!(conn, "[kernel 0.001 cpu0] before the swap").unwrap(); @@ -1557,10 +1568,13 @@ mod tests { let done = Arc::new(std::sync::atomic::AtomicBool::new(false)); let theirs = Arc::clone(&done); let closer = std::thread::spawn(move || { - while !theirs.load(std::sync::atomic::Ordering::SeqCst) { - let taken = server.accept(); + loop { + let (taken, _) = server.accept().unwrap(); + if theirs.load(std::sync::atomic::Ordering::SeqCst) { + return; + } past(Instant::now() + held); - drop(taken); + close(taken); } }); move || { @@ -1612,7 +1626,8 @@ mod tests { /// Whether the reader dials inside a 50 ms bound at all is the host /// scheduler's, and a redial that did not says so too. A connection is /// closed only once the bound has passed since it was taken, so a redial - /// that dialled ends on its first close, which is past its bound. + /// that dialled ends on its first close, which is past its bound, and + /// names that close rather than saying it never asked. #[test] fn a_redial_ends_at_its_bound_alone_and_says_so() { const BOUND: Duration = Duration::from_millis(50); @@ -1634,7 +1649,7 @@ mod tests { let why = closed.unopened().expect("the redial ended within 5 s and said why"); match closed.turned_away() { 0 => assert!(why.ends_with("by the bound: never asked"), "{why}"), - 1 => assert!(why.contains("redial's bound") && why.contains("ended before a line"), "{why}"), + 1 => assert!(why.contains("by the bound: the latest connection ended before a line"), "{why}"), n => panic!("{n} dials counted, where the first was closed past the bound: {why}"), } stop_closing(); From fe1c673167fc2dc63406e73c154225631be61cc3 Mon Sep 17 00:00:00 2001 From: japabu Date: Mon, 28 Sep 2026 19:40:02 +0200 Subject: [PATCH 10/10] Round 5 review fixes: read's early-exit carries no unread reason, and the second buildlock red's duplicate issue file is deleted. serve's guard at :347 always fails on the path that leads to read's early exit, so its string was never read; it now returns None, which serve treats the same as a line having been carried. issues/build/a-dropped-keyed-lock-is-still-held-in-the-loaded-lib-suite.md duplicated the record main already keeps under a-key-being-built-is-waited-for-and-another-key-is-not-reds-under-host-load.md for the same test and assertion, and named no owner. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01W6rME2DoqwjcYFStYHHY4j --- ...k-is-still-held-in-the-loaded-lib-suite.md | 26 ------------------- src/metaltalk.rs | 2 +- 2 files changed, 1 insertion(+), 27 deletions(-) delete mode 100644 issues/build/a-dropped-keyed-lock-is-still-held-in-the-loaded-lib-suite.md diff --git a/issues/build/a-dropped-keyed-lock-is-still-held-in-the-loaded-lib-suite.md b/issues/build/a-dropped-keyed-lock-is-still-held-in-the-loaded-lib-suite.md deleted file mode 100644 index 634e985102..0000000000 --- a/issues/build/a-dropped-keyed-lock-is-still-held-in-the-loaded-lib-suite.md +++ /dev/null @@ -1,26 +0,0 @@ ---- -status: open -kind: tooling -opened: 2026-09-28 ---- - -# A dropped keyed lock is still held in the loaded lib suite - -`buildlock::tests::a_key_being_built_is_waited_for_and_another_key_is_not` -went red once in 200 full `--lib` suite runs, at `8cc19ef1` and one-minute load average -40.1, beside `cargo test --workspace --exclude toyos-build`. It failed at -`src/buildlock.rs:945`: `assertion failed: keyed_idle(&root, Keyed::Sysroot, -"k1").is_some()`, right after `drop(using)`. Evidence: -`l3-staged-171.log` in the job scratchpad `redial-r3/`. - -Unmeasured hypothesis: a `flock` belongs to the open file description, so a -child that another test in the same process is spawning shares `using`'s -lock until its exec closes the fd. `drop(using)` then releases nothing yet. -The same mechanism was measured for a dropped TCP listener, whose accepts -outlive its drop. - -## Exit condition - -The cause is measured, and the test's release is one no concurrent spawn can -defer. It is shown green across at least 200 full `--lib` suite runs beside -`cargo test --workspace --exclude toyos-build`. diff --git a/src/metaltalk.rs b/src/metaltalk.rs index 3cc2c56ae3..ccec7cf8dd 100644 --- a/src/metaltalk.rs +++ b/src/metaltalk.rs @@ -627,7 +627,7 @@ fn read(conn: TcpStream, shared: &Shared, out: &mut std::fs::File, echo: bool) - // A redial asked for while this connection was being made wants a // connection made after the ask, and this is not one. if state.stop || state.redial.is_some() { - return Some("this reader dropped it, made before the latest ask".to_string()); + return None; } state.current = conn.try_clone().ok(); state.lines.len()