From 57a537f3af8e51ba5b1cf77bb194e50104e35581 Mon Sep 17 00:00:00 2001 From: audit Date: Tue, 11 Aug 2026 23:03:40 +1000 Subject: [PATCH] fix(victauri-test): timestamp-based IPC checkpoints survive the log window cap create_ipc_checkpoint snapshotted the IPC log LENGTH and ipc_calls_since did skip(length) - but the server's log tools return a capped sliding window of the NEWEST entries (default 100). On any app with more than ~100 logged IPC calls the checkpoint equals the window size and calls_since is silently ALWAYS empty. Found live on 4DA during the rmcp 3.1.2 verification: its dogfood suite's ipc_integrity_healthy and parallel_ipc_burst canary assertions failed ("calls since checkpoint: []") while a manual canary repro proved capture itself worked - the client arithmetic was the bug. Latent since the 0.7.10 log-capping change; unrelated to rmcp. Fix: the checkpoint is now the newest entry timestamp (epoch ms); calls_since filters by it over a 1000-entry read - immune to window position. Signatures unchanged (usize). Entries without a timestamp are included only for the zero checkpoint. Verified: the two failing 4DA dogfood tests pass against live 4DA with this client (153/165 suite, all remaining failures 4DA-side drift); two new mock-server regression tests pin the sliding-window scenario; existing ipc_checkpoint_tracks_new_calls stays green; fmt/clippy/full workspace tests clean. Co-Authored-By: Claude Fable 5 Claude-Session: https://claude.ai/code/session_01KSa8Fdy8xgexFYYx47DkAg --- CHANGELOG.md | 12 ++++ crates/victauri-test/src/client.rs | 64 +++++++++++------ crates/victauri-test/tests/client_tests.rs | 81 ++++++++++++++++++++++ 3 files changed, 137 insertions(+), 20 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 632f38c..f585bb0 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,18 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Fixed + +- **`victauri-test`: IPC checkpoints survive the log's sliding-window cap.** `create_ipc_checkpoint` + snapshotted the IPC log *length* and `ipc_calls_since` did `skip(length)` — but the server's log + tools return a capped sliding window of the newest entries (default 100), so on any app with more + than ~100 logged IPC calls the checkpoint equalled the window size and `calls_since` was silently + ALWAYS empty (found live on 4DA during the rmcp 3.1.2 verification: every canary assertion in its + dogfood suite failed). The checkpoint is now the newest entry `timestamp` (epoch ms) and + `calls_since` filters by it with a 1000-entry read — immune to the window's position. Method + signatures unchanged; verified live (the two failing 4DA dogfood tests pass with the fix, plus two + new mock-server regression tests). + ### Changed - **MCP infrastructure upgraded to rmcp 3.1.2 (MCP protocol `2026-07-28`).** The embedded MCP diff --git a/crates/victauri-test/src/client.rs b/crates/victauri-test/src/client.rs index cb42f7a..c8cd204 100644 --- a/crates/victauri-test/src/client.rs +++ b/crates/victauri-test/src/client.rs @@ -1320,15 +1320,34 @@ impl VictauriClient { /// Returns errors from [`VictauriClient::call_tool`]. #[deprecated(since = "0.2.0", note = "renamed to get_ipc_calls_since")] pub async fn ipc_calls_since(&mut self, checkpoint: usize) -> Result, TestError> { - let log = self.get_ipc_log(None).await?; - let entries = if let Some(arr) = log.as_array() { - arr.clone() + // Timestamp filter, NOT positional skip: the server's log tools return a + // capped sliding window of the NEWEST entries (default 100), so + // `skip(checkpoint_length)` silently yields nothing the moment a busy app + // exceeds the cap (found live on 4DA, 2026-08-11). Entries without a + // timestamp are included only for the zero checkpoint (nothing to order by). + let entries = self.ipc_log_entries().await?; + Ok(entries + .into_iter() + .filter(|e| { + e.get("timestamp") + .and_then(Value::as_u64) + .map_or(checkpoint == 0, |t| t > checkpoint as u64) + }) + .collect()) + } + + /// Fetch the IPC log with the checkpoint read limit and normalize its shape. + async fn ipc_log_entries(&mut self) -> Result, TestError> { + // Explicit high limit: the tool's default window (100) is too small for a + // busy app's checkpoint arithmetic; 1000 matches the JS-side log capacity. + let log = self.get_ipc_log(Some(1000)).await?; + if let Some(arr) = log.as_array() { + Ok(arr.clone()) } else if let Some(entries) = log.get("entries").and_then(Value::as_array) { - entries.clone() + Ok(entries.clone()) } else { - return Ok(Vec::new()); - }; - Ok(entries.into_iter().skip(checkpoint).collect()) + Ok(Vec::new()) + } } /// Filter the IPC log for calls to a specific command. @@ -1383,7 +1402,7 @@ impl VictauriClient { // ── Deprecated Aliases (Phase 4C) ──────────────────────────────────────── - /// Snapshot the current IPC log length, for use with `ipc_calls_since`. + /// Snapshot the newest IPC-log timestamp, for use with `ipc_calls_since`. /// /// Prefer [`VictauriClient::create_ipc_checkpoint`] — this alias exists /// for backwards compatibility. @@ -1396,25 +1415,30 @@ impl VictauriClient { self.create_ipc_checkpoint().await } - /// Snapshot the current IPC log length, for use with `ipc_calls_since`. + /// Snapshot the newest IPC-log timestamp, for use with `ipc_calls_since`. /// - /// Returns the number of IPC calls recorded so far. Pass this value to + /// Returns the maximum entry `timestamp` (epoch milliseconds) currently + /// visible in the IPC log, or `0` when the log is empty. Pass this value to /// [`VictauriClient::ipc_calls_since`] to get only the calls that occurred - /// after the checkpoint. + /// after the checkpoint. Timestamp-based rather than length-based because + /// the server's log tools return a capped sliding window of the newest + /// entries — a positional checkpoint stops working once a busy app exceeds + /// the cap. /// /// # Errors /// /// Returns errors from [`VictauriClient::call_tool`]. pub async fn create_ipc_checkpoint(&mut self) -> Result { - let log = self.get_ipc_log(None).await?; - let len = if let Some(arr) = log.as_array() { - arr.len() - } else if let Some(entries) = log.get("entries").and_then(Value::as_array) { - entries.len() - } else { - 0 - }; - Ok(len) + // The checkpoint is the NEWEST entry timestamp (epoch ms), not the log + // length: the log tools serve a capped sliding window, so a length + // snapshot breaks (always-empty `calls_since`) once the app has logged + // more calls than the cap. Timestamps are window-position-independent. + let entries = self.ipc_log_entries().await?; + Ok(entries + .iter() + .filter_map(|e| e.get("timestamp").and_then(Value::as_u64)) + .max() + .unwrap_or(0) as usize) } // ── Typed Response Methods (Phase 4E) ──────────────────────────────────── diff --git a/crates/victauri-test/tests/client_tests.rs b/crates/victauri-test/tests/client_tests.rs index f4d9371..13afdb0 100644 --- a/crates/victauri-test/tests/client_tests.rs +++ b/crates/victauri-test/tests/client_tests.rs @@ -1110,3 +1110,84 @@ async fn call_tool_recovery_is_bounded_and_reports_rest_fallback() { // Bounded: exactly one re-initialization (2 handshakes), no infinite loop. assert_eq!(state.initialize_count.load(Ordering::Relaxed), 2); } + +// ── IPC Checkpoint vs Sliding-Window Log Cap ────────────────────────────── + +#[tokio::test] +async fn ipc_checkpoint_survives_sliding_window_cap() { + // The server's `logs ipc` tool returns a capped sliding WINDOW of the + // NEWEST entries (default 100). The old length-based checkpoint did + // `skip(len)` over that window, so once a busy app logged more calls than + // the cap, `calls_since` was ALWAYS empty and every canary assertion + // failed (found live on 4DA, 2026-08-11: log ≥200 entries, checkpoint=100, + // window stays 100 → skip(100) = []). The checkpoint is now the newest + // timestamp and `calls_since` filters by it, which is immune to the + // window's position. + let state = MockState::new(); + let port = start_mock_server(state.clone()).await; + let mut client = VictauriClient::connect(port).await.unwrap(); + + // Window BEFORE: the log is already AT the cap — 100 entries, ts 1..=100. + let w1: Vec = (1..=100u64) + .map(|t| json!({"command": "noise", "timestamp": t})) + .collect(); + *state.response_override.lock().await = Some(json!({ + "content": [{"type": "text", "text": serde_json::to_string(&w1).unwrap()}] + })); + let cp = client.create_ipc_checkpoint().await.unwrap(); + assert_eq!( + cp, 100, + "checkpoint must be the newest timestamp, not the window length" + ); + + // Window AFTER: 5 new calls landed, the window slid — ts 6..=105, canary last. + let w2: Vec = (6..=104u64) + .map(|t| json!({"command": "noise", "timestamp": t})) + .chain(std::iter::once( + json!({"command": "canary", "timestamp": 105u64}), + )) + .collect(); + *state.response_override.lock().await = Some(json!({ + "content": [{"type": "text", "text": serde_json::to_string(&w2).unwrap()}] + })); + let since = client.get_ipc_calls_since(cp).await.unwrap(); + assert_eq!( + since.len(), + 5, + "exactly the 5 post-checkpoint entries must be returned, got: {since:?}" + ); + assert!( + since.iter().any(|c| c["command"] == "canary"), + "the canary call landed after the checkpoint and must be visible" + ); +} + +#[tokio::test] +async fn ipc_checkpoint_empty_log_returns_all_later_entries() { + // Zero checkpoint (empty log at checkpoint time): everything that appears + // later is "since" — including entries that carry no timestamp field. + let state = MockState::new(); + let port = start_mock_server(state.clone()).await; + let mut client = VictauriClient::connect(port).await.unwrap(); + + *state.response_override.lock().await = Some(json!({ + "content": [{"type": "text", "text": "[]"}] + })); + let cp = client.create_ipc_checkpoint().await.unwrap(); + assert_eq!(cp, 0, "empty log must produce the zero checkpoint"); + + *state.response_override.lock().await = Some(json!({ + "content": [{"type": "text", "text": + serde_json::to_string(&vec![ + json!({"command": "first", "timestamp": 10u64}), + json!({"command": "no_ts_entry"}), + ]).unwrap() + }] + })); + let since = client.get_ipc_calls_since(cp).await.unwrap(); + assert_eq!( + since.len(), + 2, + "zero checkpoint returns every entry, incl. timestamp-less ones: {since:?}" + ); +}