diff --git a/devlog/_plan/260829_cursor_tool_continuation_pairing/030_phase4_final_gate.md b/devlog/_plan/260829_cursor_tool_continuation_pairing/030_phase4_final_gate.md new file mode 100644 index 0000000000..1b250980b2 --- /dev/null +++ b/devlog/_plan/260829_cursor_tool_continuation_pairing/030_phase4_final_gate.md @@ -0,0 +1,36 @@ +# 030 — Phase 4: final gate (independent post-merge audit) + +Depends on: the merged change `8df7051201df09113b17da3f71ace992f001d66c` on `origin/dev` (PR #2900). +Scope: audit only. No source change is planned; a finding becomes a follow-up work-phase. + +## Why this phase exists + +The goalplan's quality gate (`cxc loop validate`, schemaVersion 2) requires a recorded +`final_gate` review round before completion can be certified. It is also the honest place to +re-examine the work now that it has landed, because this unit already produced two wrong turns +that only external checks caught: + +1. The first implementation shape (standalone `[Tool Call]` entry) was rejected by the remote + suite's 363-B guard — my own audit had missed it (`002`). +2. The first three live verification runs were routed to the operator's UNPATCHED proxy and + proved nothing; only checking the probe's own diagnostic log exposed it. + +Both were caught by evidence, not by reasoning, which is the argument for one more adversarial +pass rather than declaring done. + +## Audit questions + +| # | Question | How it is answered | +|---|----------|--------------------| +| A1 | Is the landed code on `dev` the code that was verified? | Compare the merge commit's file content against the verified branch head | +| A2 | Does any existing test expectation end up weakened? | `git diff` of the merge against its parent, restricted to `tests/` | +| A3 | Do the post-merge gates pass on the integrated tree? | `bun x tsc --noEmit` and `bun run test` on `ssh lidge` at the merge commit | +| A4 | Is every claim in the recorded evidence supported? | Re-read the goalplan's `capturedEvidence` against the artifacts it cites | +| A5 | Was the operator's environment left as found? | Live check of the launchd proxy and of the unpushed commit `5f4981853` | + +## Accept criteria + +`c8`: a recorded `final_gate` verdict, plus post-merge gate output at the merge commit, with +no regression, no weakened expectation, and no unsupported claim. A failure here appends a +follow-up work-phase rather than being written off. + diff --git a/devlog/_plan/260829_cursor_tool_continuation_pairing/040_phase5_checkpoint_suffix_gap.md b/devlog/_plan/260829_cursor_tool_continuation_pairing/040_phase5_checkpoint_suffix_gap.md new file mode 100644 index 0000000000..0606c5975a --- /dev/null +++ b/devlog/_plan/260829_cursor_tool_continuation_pairing/040_phase5_checkpoint_suffix_gap.md @@ -0,0 +1,166 @@ +# 040 — Phase 5: the checkpoint suffix reopened the same defect + +Depends on: `8df7051201df09113b17da3f71ace992f001d66c` (PR #2900) and +`27c6993c5471958db97c9a4ce1dccc2f591f6094` (PR #2903), both on `origin/dev`. + +## What happened + +A live re-run against merged `dev` reproduced the original symptom the unit had just closed: +12 duplicate `command_execution` items and 5 phantom "interrupted" mentions in one +`codex exec` transcript against `cursor/grok-4.6`. + +The fix was not wrong; it was incomplete. Every run that had verified it used +`continuationMode: "full-replay"`. The failing run used `"checkpoint"` for 13 of its 14 +requests — and the checkpoint path is a second, separate replay site. + +## Root cause + +`buildPreparedCursorRunRequest` handles a stored checkpoint by replaying only the part of +history the checkpoint does not already cover: + +```ts +rawMessages: request.rawMessages.slice(suffixStart) +``` + +Both `rootPromptMessages` and `conversationTurns` then indexed tool calls from **that slice**. +A checkpoint is committed right after the assistant emits its tool call, so the cut normally +falls *between* the call and its result: the call is at `suffixStart - 1`, outside the slice. +The index came back empty, no invocation line was attached, and the result went out orphaned — +byte-for-byte the state the unit had set out to eliminate. + +This is why the earlier verification was clean and the later run was not. Nothing about the +invocation line changed; the code path around it did. + +## The change + +`toolCallsByCallId` now runs over `request.rawMessages` (full history) and the resulting map is +threaded into both replay builders as an optional `knownCalls` parameter. What gets *replayed* +is unchanged — still only the suffix — so covered messages are not re-sent. Only the lookup +widens. + +```text + suffixStart + │ + user ─ assistant(call) ─┤─ toolResult ─ … + └──── covered by checkpoint ────┘ └── replayed ──┘ + ▲ + └─ read for the invocation line; NOT replayed +``` + +Both call sites keep their previous behaviour when `knownCalls` is absent, so the full-replay +path is untouched. + +## Tests + +`tests/cursor-tool-result-invocation.test.ts` gains a second describe block, driven red before +the fix was restored: + +| Test | Red without the fix | +|------|---------------------| +| a result whose call is BEFORE the checkpoint cut still names its invocation | yes | +| the invocation line also reaches the checkpoint suffix turn step | yes | +| covered history is not replayed a second time | no — double-replay guard | +| an id reused in covered history yields no invocation line | no — ambiguity guard | +| native composer keeps checkpoint results off the root prompt | no — native-path guard | +| an ambiguous id resolved from full history is not re-resolved from the suffix | yes — but against `size > 0`, not against the threading | + +### Why the lookup uses `??` and not a `size > 0` check + +A review asked whether passing an empty `knownCalls` map should fall back to indexing the suffix, +since `??` keeps the empty map. It should not, and the distinction is load-bearing. + +An empty map is a *decided* answer — "the full history holds no call that can be named" — not a +missing one. `toolCallsByCallId` deliberately **drops** any id that two different invocations claim, +because a confidently wrong label is worse than none: nothing downstream can detect a mislabel. + +Measured, with two calls sharing one id before the cut and the result belonging to the *first*: + +| Lookup | Invocation line emitted | +|--------|-------------------------| +| `knownCalls ?? …` (shipped) | none — correct, the id is ambiguous | +| `knownCalls.size > 0 ? … : …` | `invoked: exec_command with {"cmd":"echo SECOND"}` — **wrong command** | + +The suffix contains only the second call, so a suffix-only index sees one unambiguous-looking +candidate and names it. `tests/…` case "an ambiguous id resolved from full history is not +re-resolved from the suffix" pins this: it fails with the `size > 0` variant and passes with `??`. + +Worth recording that the first version of this argument cited the wrong test. "an id reused in +covered history yields no invocation line" passes under *both* variants, because there the reused id +is ambiguous within the suffix too. The distinction only shows up when the ambiguity is visible in +full history but not in the suffix, which is what the added case constructs. + +Two assertions fail without the threading and pass with it; the other three are guards that +must hold either way, and they document what the widened lookup must *not* break. + +Two shapes needed care while writing them: + +- An empty `ConversationStateStructure` serializes to **zero bytes**, which the encoder reads as + "no checkpoint" and silently downgrades to full replay. A test seeded that way passes while + exercising the wrong branch. The helper seeds one real root blob instead. +- A turn only opens on a user message, so a suffix of just `[toolResult]` produces **no turns at + all** (measured: `turns=0`). The turn-step assertion therefore uses a suffix that also carries a + later user message, which is the shape that actually reaches that code. + +## Verification + +- `bun test tests/cursor-tool-result-invocation.test.ts tests/cursor-tool-continuation.test.ts tests/cursor-blob.test.ts` — 123 pass, 0 fail. +- `bun x tsc --noEmit` — exit 0. +- Full suite on `ssh lidge`; no local full-suite run was used as a gate. + +## What the live runs did and did NOT prove + +This has to be stated plainly, because the previous phase of this unit recorded a live claim that +turned out not to hold. + +Three live `codex exec` runs against `cursor/grok-4.6` through a patched probe on port 10199, all +confirmed served by that probe (`cursor:run-request` present in its own diagnostic log): + +| Run | Commands requested | Unique `command_execution` items | `interrupted` | Terminated | +|-----|--------------------|----------------------------------|---------------|-----------| +| 1 (3-step) | 3 | 3 | 0 | `ALLDONE`, exit 0 | +| 2 (4-step) | 4 | 3 | 0 | `turn.completed`, no `ALLDONE` | +| 3 (4-step, same prompt as 2) | 4 | 4 | 0 | `ALLDONE`, exit 0 | + +**Every one of the 13 requests across those runs used `continuationMode: "full-replay"`.** The +checkpoint branch this PR changes was never entered, so these runs do NOT verify the fix. They only +establish that it caused no regression on the path they did take — which is expected, since the +full-replay call sites pass no `knownCalls` and are byte-identical in behaviour. + +Checkpoint mode did not engage because every commit was refused. The probe's own diagnostics name +the guard: + +```text +[ocx:cursor:checkpoint-commit-refused] {"replayUnsafe":true,"emittedClientTool":true,…} +``` + +`replayUnsafe` is set by `live-transport.ts` on `local_side_effect`, which native exec pushes before +running a local command. A shell-command repro therefore cannot produce a committable checkpoint, +and the following request falls back with `checkpointInvalidationReason: "missing_ref"`. The +original failing transcript reached checkpoint mode 17 times because its checkpoints were committed +as `toolSuspended` — upstream serialized state while suspended on a client tool call. + +What does verify the fix is the encoder-level evidence, which addresses the same code path directly: +the two red-then-green assertions, and a standalone probe that builds a real 59-byte checkpoint with +the cut between call and result and reports `invoked=true` (`invoked=false` before the change). + +### Run 2 is a sampling artifact, not a regression + +Run 2 stopped after three of four commands, and its final assistant message contained a +**fabricated** `[Tool Result]` envelope as chat text — the model wrote out a plausible-looking result +for `echo DDD` rather than calling the tool. That is the 363-B mimicry failure mode, and it deserved +attribution rather than dismissal. + +It is not caused by this change: + +- The change cannot reach that run. All 13 requests used full replay, whose call sites are unchanged. +- A baseline probe built from `27c6993c5` (`dev` without this PR) ran the identical prompt: 4/4 + commands, `ALLDONE`, no fabrication. +- Re-run 3 on the **patched** probe with the identical prompt: 4/4 commands, `ALLDONE`, no + fabrication. +- The operator's unpatched 2.35.0 proxy ran the same prompt cleanly as well. + +Same code, same prompt, different outcomes across runs 2 and 3, so the variable is model sampling. +The underlying tendency — an external model imitating a replayed result envelope instead of calling +the tool — is a real and known weakness of text-echoed continuation, and it is what the 363-B guard +exists to limit. It is a pre-existing exposure, not something this PR introduces, and it is worth a +separate unit rather than being folded in here. diff --git a/src/adapters/cursor/protobuf-request.ts b/src/adapters/cursor/protobuf-request.ts index 540d3cff31..0ea1c91fc4 100644 --- a/src/adapters/cursor/protobuf-request.ts +++ b/src/adapters/cursor/protobuf-request.ts @@ -204,7 +204,17 @@ function assistantRootText( // [Tool Error] marker so Cursor does not wrap them as `` (#1992). Native resume models // already carry the paired MCP result on turns[], so that marker is omitted from root replay — Auto // few-shot-mimics it as chat text otherwise. Each entry is a SHA-256 blob ID. -function rootPromptMessages(request: CursorRunRequest, requestScope: CursorBlobRequestScopeToken): { +function rootPromptMessages( + request: CursorRunRequest, + requestScope: CursorBlobRequestScopeToken, + /** + * Calls indexed from the FULL history. The checkpoint path replays only a suffix of + * `rawMessages`, so a result in that suffix can have its originating call before the cut; indexing + * from the slice alone silently dropped the invocation line for every checkpoint continuation, + * which is where the defect this line prevents actually reappeared in live use. + */ + knownCalls?: Map>, +): { ids: Uint8Array[]; byteLength: number; historyMessageStart: number; @@ -227,7 +237,7 @@ function rootPromptMessages(request: CursorRunRequest, requestScope: CursorBlobR const echoToolResultInRoot = cursorNeedsExternalToolContinuation(request.modelId); // Replayed results name the invocation that produced them; without it the result is orphaned // (devlog 260829 000_rca). Indexed once per request rather than rescanned per result. - const replayedCalls = echoToolResultInRoot ? toolCallsByCallId(messages) : undefined; + const replayedCalls = echoToolResultInRoot ? (knownCalls ?? toolCallsByCallId(messages)) : undefined; const lastRawIsToolResult = messages.at(-1)?.role === "toolResult"; const activeUserIndex = lastRawIsToolResult ? -1 : lastActionIndex(messages); // Repetition breaker (devlog 260826 gap-9): external full-replay flattens history to text, @@ -931,6 +941,8 @@ function conversationTurns( request: CursorRunRequest, requestScope: CursorBlobRequestScopeToken, historyMessageStart = 0, + /** Calls indexed from the FULL history; see {@link rootPromptMessages}. */ + knownCalls?: Map>, ): Uint8Array[] { const messages = request.rawMessages; if (!messages?.length) return []; @@ -938,7 +950,7 @@ function conversationTurns( const externalModel = isCursorExternalWireModel(request.modelId); const historyEnd = messages.at(-1)?.role === "toolResult" ? messages.length : Math.max(0, end); const start = externalModel ? Math.max(0, historyMessageStart) : 0; - const turnCalls = externalModel ? toolCallsByCallId(messages) : undefined; + const turnCalls = externalModel ? (knownCalls ?? toolCallsByCallId(messages)) : undefined; const turns: Uint8Array[] = []; let current: { userMessage: Uint8Array; steps: Uint8Array[] } | undefined; const pendingToolCalls = new Map>(); @@ -1155,8 +1167,11 @@ function buildPreparedCursorRunRequest( system: [], rawMessages: request.rawMessages.slice(suffixStart), }; - const suffixRoots = rootPromptMessages(suffixRequest, requestScope); - const suffixTurns = conversationTurns(suffixRequest, requestScope, suffixRoots.historyMessageStart); + // Index calls from the FULL history, not the suffix: the cut can fall between a call and + // its result, and a result replayed without its invocation is the orphaned-result defect. + const fullHistoryCalls = toolCallsByCallId(request.rawMessages); + const suffixRoots = rootPromptMessages(suffixRequest, requestScope, fullHistoryCalls); + const suffixTurns = conversationTurns(suffixRequest, requestScope, suffixRoots.historyMessageStart, fullHistoryCalls); const suffixSystemCount = systemPromptBlobs(suffixRequest).length; const suffixHistoryIds = suffixRoots.ids.slice(suffixSystemCount); const suffixHistorySerialized = suffixRoots.serialized.slice(suffixSystemCount); diff --git a/tests/cursor-tool-result-invocation.test.ts b/tests/cursor-tool-result-invocation.test.ts index dfb588ae45..545c1e4ef0 100644 --- a/tests/cursor-tool-result-invocation.test.ts +++ b/tests/cursor-tool-result-invocation.test.ts @@ -1,10 +1,11 @@ import { describe, expect, test } from "bun:test"; -import { create, fromBinary } from "@bufbuild/protobuf"; +import { create, fromBinary, toBinary } from "@bufbuild/protobuf"; import { CURSOR_INVOCATION_ARGUMENTS_BYTE_LIMIT, encodeCursorRunRequest } from "../src/adapters/cursor/protobuf-request"; -import { handleCursorNativeKv } from "../src/adapters/cursor/native-exec"; +import { handleCursorNativeKv, storeCursorBlob } from "../src/adapters/cursor/native-exec"; import { AgentClientMessageSchema, ConversationStepSchema, + ConversationStateStructureSchema, ConversationTurnStructureSchema, GetBlobArgsSchema, KvServerMessageSchema, @@ -87,6 +88,34 @@ function encode(messages: OcxMessage[], modelId: string): Uint8Array { }); } +/** + * The checkpoint continuation path. `suffixStart` is how many leading messages the checkpoint + * already covers, so only `rawMessages.slice(suffixStart)` is replayed onto the root prompt. + * + * The checkpoint must carry at least one root: an EMPTY ConversationStateStructure serializes to + * zero bytes, which the encoder reads as "no checkpoint" and silently downgrades to full replay — + * so a test seeded with an empty state would pass while exercising the wrong branch entirely. + */ +function encodeCheckpoint(messages: OcxMessage[], modelId: string, suffixStart: number): Uint8Array { + // Stored for real so the decoder helper can read every root back, checkpoint-carried included. + const seedRoot = storeCursorBlob(new TextEncoder().encode(JSON.stringify({ + role: "user", + content: [{ type: "text", text: "covered by checkpoint" }], + }))); + return encodeCursorRunRequest({ + modelId, + conversationId: "c_pairing_ckpt", + system: [], + messages: [], + rawMessages: messages, + checkpointBytes: toBinary(ConversationStateStructureSchema, create(ConversationStateStructureSchema, { + rootPromptMessagesJson: [seedRoot], + })), + continuationMode: "checkpoint", + checkpointSuffixStart: suffixStart, + }); +} + function resultRoot(bytes: Uint8Array): string | undefined { return rootTexts(bytes).find(text => text.startsWith("[Tool Result]") || text.startsWith("[Tool Error]")); } @@ -300,3 +329,120 @@ describe("cursor replayed tool results name their invocation", () => { for (const result of results) expect(result).not.toContain("invoked:"); }); }); + +/** + * The live regression that survived the first fix. Once the invocation line shipped, the defect + * still reproduced against merged `dev`: 12 duplicate command_execution items and 5 phantom + * "interrupted" mentions. The passing runs had used full replay; the failing run used CHECKPOINT + * continuation for 13 of its 14 requests. + * + * The checkpoint path replays only `rawMessages.slice(suffixStart)`, and it indexed calls from that + * SAME slice. When the cut fell between an assistant tool call and its result — the normal case, + * since the checkpoint is committed right after the call — the call sat before the cut and the index + * was empty, so the result went out orphaned again. The fix indexes from the full history while + * still replaying only the suffix. + */ +describe("cursor checkpoint continuation names the invocation from covered history", () => { + test("a result whose call is BEFORE the checkpoint cut still names its invocation", () => { + // suffixStart 2 puts the assistant tool call (index 1) inside the covered checkpoint and leaves + // the suffix as just the tool result. + const root = resultRoot(encodeCheckpoint(history(), "grok-4.6-high", 2)); + expect(root).toBeDefined(); + expect(root).toContain(`call_id: ${CALL_ID}`); + expect(root).toContain("invoked: exec_command with"); + expect(root).toContain("echo AAA"); + }); + + // The turn path needs the same full-history index. A turn only opens on a user message, so a + // result-only suffix produces no turns at all (verified: turns=0) and cannot cover this; the + // shape that does is a suffix carrying a later user message plus the result of a covered call. + test("the invocation line also reaches the checkpoint suffix turn step", () => { + const messages: OcxMessage[] = [ + { role: "user", content: "Run echo AAA.", timestamp: 1 }, + { + role: "assistant", + content: [{ type: "toolCall", id: CALL_ID, name: "exec_command", arguments: { cmd: "echo AAA" } }], + timestamp: 2, + }, + { role: "user", content: "and note this", timestamp: 3 }, + { role: "toolResult", toolCallId: CALL_ID, toolName: "exec_command", content: "AAA", isError: false, timestamp: 4 }, + ]; + const step = turnStepTexts(encodeCheckpoint(messages, "grok-4.6-high", 2)) + .find(text => text.startsWith("[Tool Result]")); + expect(step).toBeDefined(); + expect(step).toContain("invoked: exec_command with"); + expect(step).toContain("echo AAA"); + }); + + // Naming a covered call must not drag the covered MESSAGES back into the replay: the checkpoint + // already carries them, and re-appending them is the double-replay this path exists to avoid. + test("covered history is not replayed a second time", () => { + const roots = rootTexts(encodeCheckpoint(history(), "grok-4.6-high", 2)); + expect(roots.some(text => text.includes("Run echo AAA."))).toBe(false); + expect(roots.some(text => text.includes("I will run echo AAA."))).toBe(false); + }); + + // Ambiguity resolution must also read the full history: a call id reused before the cut cannot be + // labelled from the suffix alone, so a suffix-only index would confidently name the wrong command. + test("an id reused in covered history yields no invocation line", () => { + const messages: OcxMessage[] = [ + { role: "user", content: "Run both.", timestamp: 1 }, + { + role: "assistant", + content: [{ type: "toolCall", id: CALL_ID, name: "exec_command", arguments: { cmd: "echo FIRST" } }], + timestamp: 2, + }, + { role: "toolResult", toolCallId: CALL_ID, toolName: "exec_command", content: "FIRST", isError: false, timestamp: 3 }, + { + role: "assistant", + content: [{ type: "toolCall", id: CALL_ID, name: "exec_command", arguments: { cmd: "echo SECOND" } }], + timestamp: 4, + }, + { role: "toolResult", toolCallId: CALL_ID, toolName: "exec_command", content: "SECOND", isError: false, timestamp: 5 }, + ]; + const root = resultRoot(encodeCheckpoint(messages, "grok-4.6-high", 4)); + expect(root).toBeDefined(); + expect(root).not.toContain("invoked:"); + }); + + test("native composer keeps checkpoint results off the root prompt", () => { + const roots = rootTexts(encodeCheckpoint(history(), "composer-2.5-fast", 2)); + expect(roots.some(text => text.startsWith("[Tool Result]"))).toBe(false); + expect(roots.some(text => text.includes("invoked:"))).toBe(false); + }); + + /** + * An EMPTY `knownCalls` map is a decided answer — "the full history contains no call that can be + * named" — not a missing one, so it must be preserved rather than treated as absent. + * + * `toolCallsByCallId` deliberately DROPS an id that two different invocations claim. Here both + * claims sit before the cut, so the full-history index rejects the id and returns nothing for it, + * while the suffix alone sees only the second call. Falling back on an empty map (`size > 0` + * instead of `??`) makes the result confidently claim `echo SECOND` when it actually came from + * `echo FIRST` — a wrong label nothing downstream can detect, which is worse than no label. + */ + test("an ambiguous id resolved from full history is not re-resolved from the suffix", () => { + const messages: OcxMessage[] = [ + { role: "user", content: "Run both.", timestamp: 1 }, + { + role: "assistant", + content: [{ type: "toolCall", id: CALL_ID, name: "exec_command", arguments: { cmd: "echo FIRST" } }], + timestamp: 2, + }, + { + role: "assistant", + content: [{ type: "toolCall", id: CALL_ID, name: "exec_command", arguments: { cmd: "echo SECOND" } }], + timestamp: 3, + }, + { role: "user", content: "keep going", timestamp: 4 }, + // The result belongs to the FIRST invocation. + { role: "toolResult", toolCallId: CALL_ID, toolName: "exec_command", content: "FIRST", isError: false, timestamp: 5 }, + ]; + // The cut leaves the second call inside the suffix, so a suffix-only index would find exactly + // one unambiguous-looking candidate: the wrong one. + const root = resultRoot(encodeCheckpoint(messages, "grok-4.6-high", 2)); + expect(root).toBeDefined(); + expect(root).not.toContain("invoked:"); + expect(root).not.toContain("echo SECOND"); + }); +});