diff --git a/crates/spt-daemon/tests/sync.rs b/crates/spt-daemon/tests/sync.rs index 07450ed3..18dde988 100644 --- a/crates/spt-daemon/tests/sync.rs +++ b/crates/spt-daemon/tests/sync.rs @@ -99,13 +99,34 @@ fn wait_for_stream_except(brain: &mut Brain, skip: &[u64]) -> (u64, String) { // 10s budget: polls exit early when the stream appears, so the long bound // only pays on a loaded runner (2s flaked on gravity under a parallel // full-workspace run — 2026-06-04). - for _ in 0..400 { + let poll_started = std::time::Instant::now(); + let mut ipc_elapsed = Duration::ZERO; + let mut sleep_elapsed = Duration::ZERO; + let mut streams_seen = 0usize; + let mut streams_skipped = 0usize; + for iteration in 1..=400 { + let ipc_started = std::time::Instant::now(); let reply = brain.net_streams().expect("net-streams"); + ipc_elapsed += ipc_started.elapsed(); + streams_seen = reply.streams.len(); + streams_skipped = reply.streams.iter().filter(|s| skip.contains(&s.stream_id)).count(); if let Some(s) = reply.streams.iter().find(|s| !skip.contains(&s.stream_id)) { + println!( + "[IR95-SYNC] outcome=success iterations={} iteration_budget=400 elapsed_us={} ipc_us={} sleep_us={} last_streams_seen={} last_streams_skipped={}", + iteration, poll_started.elapsed().as_micros(), ipc_elapsed.as_micros(), + sleep_elapsed.as_micros(), streams_seen, streams_skipped + ); return (s.stream_id, s.remote_id_hex.clone()); } + let sleep_started = std::time::Instant::now(); thread::sleep(Duration::from_millis(25)); + sleep_elapsed += sleep_started.elapsed(); } + println!( + "[IR95-SYNC] outcome=expiry iterations=400 iteration_budget=400 elapsed_us={} ipc_us={} sleep_us={} last_streams_seen={} last_streams_skipped={}", + poll_started.elapsed().as_micros(), ipc_elapsed.as_micros(), + sleep_elapsed.as_micros(), streams_seen, streams_skipped + ); panic!("sync stream never appeared at the responder's broker"); } diff --git a/crates/spt/tests/contract_e2e.rs b/crates/spt/tests/contract_e2e.rs index cc52f3df..d4e9b98e 100644 --- a/crates/spt/tests/contract_e2e.rs +++ b/crates/spt/tests/contract_e2e.rs @@ -391,17 +391,45 @@ fn live_agent_lifecycle_e2e() { // and routed whole to the LIVE tier of the tracked two-tier context store. let commune = drops.path().join(format!("{id}-commune.md")); let ctx = spt_store::contextstore::live_context_file(&home.path().join("tracked"), id); - let deadline = std::time::Instant::now() + Duration::from_secs(30); + let poll_started = std::time::Instant::now(); + let deadline = poll_started + Duration::from_secs(30); + let mut poll_iterations = 0u64; loop { - let ingested = !commune.exists() - && std::fs::read_to_string(&ctx) - .map(|s| s.contains("mid-session note")) - .unwrap_or(false); + poll_iterations += 1; + let commune_still_exists = commune.exists(); + let ctx_has_marker = if !commune_still_exists { + Some( + std::fs::read_to_string(&ctx) + .map(|s| s.contains("mid-session note")) + .unwrap_or(false), + ) + } else { + None + }; + let ingested = ctx_has_marker == Some(true); if ingested { + println!( + "[IR95-CONTRACT] outcome=success elapsed_us={} iterations={} budget_ms=30000 commune_still_exists={} ctx_has_marker=true", + poll_started.elapsed().as_micros(), poll_iterations, commune_still_exists + ); break; } + let within_budget = std::time::Instant::now() < deadline; + if !within_budget { + let elapsed = poll_started.elapsed(); + // Preserve short-circuit polling; sample the skipped half only at exit. + let ctx_has_marker = ctx_has_marker.unwrap_or_else(|| { + std::fs::read_to_string(&ctx) + .map(|s| s.contains("mid-session note")) + .unwrap_or(false) + }); + println!( + "[IR95-CONTRACT] outcome=expiry elapsed_us={} iterations={} budget_ms=30000 commune_still_exists={} ctx_has_marker={}", + elapsed.as_micros(), poll_iterations, commune_still_exists, ctx_has_marker + ); + } assert!( - std::time::Instant::now() < deadline, + within_budget, "the brain pulse must ingest the commune into the live context tier" ); std::thread::sleep(Duration::from_millis(50));