diff --git a/crates/spt/tests/engine_room_bringup_e2e.rs b/crates/spt/tests/engine_room_bringup_e2e.rs index 9f2ce104..bc347d4d 100644 --- a/crates/spt/tests/engine_room_bringup_e2e.rs +++ b/crates/spt/tests/engine_room_bringup_e2e.rs @@ -362,6 +362,70 @@ struct BringupAttempt { rc_stdout: String, rc_stderr: String, brain_log: String, + /// INSTRUMENT ONLY (doyle ruling 2026-08-19, "instrument first"): the ER + /// perch's control+liveness record read at three instants, so the LIFETIME + /// of `driven_by` across this arm is a record rather than a story. Nothing + /// asserts on it — it rides the existing failure messages, and the arms are + /// run with `--success-output immediate` so passing vectors are captured + /// too. Carried out of the rig like every other field, for the same reason: + /// nothing may panic between `spawn_broker` and `reap`. + captures: Vec, +} + +/// The ER perch's control+liveness record at ONE instant, verbatim, stamped with +/// ms since the arm began. +/// +/// Every field the busy gate and its three clear paths touch, printed together: +/// `driven_by` is what `rc`'s `current_driver` reads, `controlled`/`viewer_count` +/// are its siblings in the control triple, and `status`/`rest_state`/`session_id` +/// are the rest triple `terminal_normalize` writes. Printed as a UNIT because the +/// question is which of the two triples moved and which did not. +/// +/// A missing record prints as such rather than as an empty reading — "no +/// `info.json`" and "`driven_by = None`" are different facts and only one of them +/// is about the marker. +fn capture_record(perch_path: &Path, at: &str, t0: Instant) -> String { + let ms = t0.elapsed().as_millis(); + match spt_store::info::read_info(perch_path) { + None => format!("[{at} +{ms}ms] "), + Some(i) => format!( + "[{at} +{ms}ms] driven_by={:?} controlled={} viewer_count={:?} \ + status={:?} rest_state={:?} session_id={:?}", + i.driven_by, i.controlled, i.viewer_count, i.status, i.rest_state, i.session_id, + ), + } +} + +/// Wait for the measured `rc` to either SEAT (a broker session appears) or GIVE +/// UP (the child exits), whichever happens first — the instant capture (ii) is +/// about. +/// +/// Both faces under investigation exit the child: the seat-contention refusal +/// prints and `return Ok(())` in well under a second, and the erhost-not-up face +/// exits after its own 30s bound. A SUCCESSFUL bring-up does neither — the +/// controller stays seated — so the broker-session arm is what ends this loop on +/// the happy path, and the budget is the backstop for both. +/// +/// Deliberately does NOT decide anything: `spawned` is still read by the +/// untouched [`wait_for_broker_session`] below, so this loop cannot change what +/// the cell asserts. It only moves WHEN the record is read. One consequence, +/// stated rather than discovered later: on a failing arm this adds its own wait +/// ahead of the existing 45s poll, so an instrument run's WALL CLOCK is not +/// comparable to the gate's 60–65s band. +fn wait_for_rc_verdict(id: &str, rc: &mut Child, budget: Duration) -> String { + let deadline = Instant::now() + budget; + loop { + if let Ok(Some(status)) = rc.try_wait() { + return format!("rc child exited, code={:?}", status.code()); + } + if broker_session_id(id).is_some() { + return "broker session appeared (rc seated)".to_string(); + } + if Instant::now() >= deadline { + return "budget expired (rc neither exited nor seated)".to_string(); + } + std::thread::sleep(Duration::from_millis(100)); + } } /// One `spt rc --code …` invocation, left running (the controller must stay @@ -489,6 +553,12 @@ fn wait_for_offline_row(perch_path: &Path, budget: Duration) -> Option { /// record, and rc's own output. Nothing here reaches into rc's internal control /// flow, so the seam survives any shape the fix takes. fn attempt_bringup_with_status_row(offline_row: bool) -> BringupAttempt { + // INSTRUMENT: the arm's own clock, so every capture below carries an OFFSET + // rather than a wall time — "late" and "never" are the same reading without + // one. + let t0 = Instant::now(); + let mut captures: Vec = Vec::new(); + let home = tempfile::tempdir().expect("temp home"); std::env::set_var("SPT_HOME", home.path()); @@ -581,6 +651,15 @@ fn attempt_bringup_with_status_row(offline_row: bool) -> BringupAttempt { spt_store::info::read_info(&perch_path).and_then(|i| i.status) }; + // CAPTURE (i) — the precondition the arm believes it has. Taken the instant + // `wait_for_offline_row` returns, because that poll reads `status` ONLY: the + // row it gates on is written by `spt endpoint stop` in the CLI process + // (`cli.rs` → `terminal_normalize`, whose write set is status + rest_state + + // dormant_since_ms), and every clear of `driven_by` lives in the daemon on a + // different schedule. If those two triples disagree here, the arm proceeds on + // a precondition that is only half true — which is the whole hypothesis. + captures.push(capture_record(&perch_path, "i:offline-row-observed", t0)); + // THE STATE THE INSTANT BEFORE THE MEASURED ATTEMPT — broker TRUTH for the // precondition, the record's remembered sid only as the rotation baseline. // A stop is asynchronous, so truth is polled to absence rather than sampled. @@ -598,6 +677,16 @@ fn attempt_bringup_with_status_row(offline_row: bool) -> BringupAttempt { &home.path().join("rc-engine-room"), ); + // CAPTURE (ii) — THE REFUSAL INSTANT. The busy gate fires before any broker + // traffic and `return Ok(())`, so on the seat-contention face the child is + // gone in well under a second; reading the record after the 45s poll below + // would sample it a minute after the decision it is meant to explain. + // The verdict string names WHICH way the loop ended, so a capture can never + // be silently attributed to the wrong face. + let rc_verdict = wait_for_rc_verdict(id, &mut rc.child, Duration::from_secs(40)); + captures.push(format!(" verdict: {rc_verdict}")); + captures.push(capture_record(&perch_path, "ii:rc-verdict", t0)); + let truth_after = wait_for_broker_session(id, Duration::from_secs(45)); let spawned = truth_after.is_some(); let sid_after = @@ -612,6 +701,14 @@ fn attempt_bringup_with_status_row(offline_row: bool) -> BringupAttempt { } reap(home.path(), &spt_bin, &mut broker, brain_pid, &[rc_pid], id); + // CAPTURE (iii) — did the clear EVER land. This is the LATE-vs-MISSING + // discriminator and nothing else can supply it: a clear that runs after the + // reader is indistinguishable from one that never runs, at the reader's own + // granularity. Taken while `home` is still alive — the TempDir owns the + // record being read, and a capture on the far side of its drop would report + // "no record" for a rig that cleaned up correctly. + captures.push(capture_record(&perch_path, "iii:after-reap", t0)); + BringupAttempt { spawned, truth_before, @@ -623,6 +720,7 @@ fn attempt_bringup_with_status_row(offline_row: bool) -> BringupAttempt { rc_stdout: std::fs::read_to_string(&rc.out).unwrap_or_default(), rc_stderr: std::fs::read_to_string(&rc.err).unwrap_or_default(), brain_log: std::fs::read_to_string(&brain_log).unwrap_or_default(), + captures, } } @@ -1157,6 +1255,23 @@ fn a_cleanly_offline_engine_room_is_still_brought_up_by_its_own_gate() { // ARM 2 — the control: identical in every other respect. let cleared = attempt_bringup_with_status_row(false); + // ── INSTRUMENT OUTPUT (no assertion; delete with the instrument) ───────── + // Printed BEFORE the first assert, and unconditionally, so a PASSING run + // yields a vector too — the race reading predicts passes look different at + // capture (i), and a prediction only about failures cannot be refuted by the + // 16 runs in 20 that succeed. nextest shows stdout on failure by default; + // `--success-output immediate` is what surfaces the passing vectors. + for (name, arm) in [("offline", &offline), ("control", &cleared)] { + println!("ER-INSTRUMENT [{name} arm] spawned={}", arm.spawned); + for line in &arm.captures { + println!("ER-INSTRUMENT [{name} arm] {line}"); + } + println!( + "ER-INSTRUMENT [{name} arm] rc stdout: {}", + arm.rc_stdout.trim().replace('\n', " | ") + ); + } + // ── THE DISCRIMINATOR IS PROVEN FIRST, in both directions ─────────────── // Asserted here rather than inside the rig (nothing may panic between the // broker spawning and the reap), and asserted for BOTH arms: an arm that