fix(victauri-test): timestamp-based IPC checkpoints survive the log window cap

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

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<Vec<Value>, 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<Vec<Value>, 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<usize, TestError> {
-        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) ────────────────────────────────────

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<Value> = (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<Value> = (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:?}"
+    );
+}