Skip to content

Commit 921bf64

Browse files
Copilotdreness
Copilot
and
dreness
committed
Add comprehensive root cause analysis for PR RooCodeInc#11131
Co-authored-by: dreness <5242016+dreness@users.noreply.github.com>
1 parent 76f35cb commit 921bf64

1 file changed

Lines changed: 227 additions & 0 deletions

File tree

‎PR-11131-ROOT-CAUSE-ANALYSIS.md‎

Lines changed: 227 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,227 @@
1+
# PR #11131 Root Cause Analysis: Tool Block ID Sanitization
2+
3+
## Executive Summary
4+
5+
PR #11131 fixed a `ToolResultIdMismatchError` that occurred when tool result IDs didn't match tool use IDs in the API conversation history. The root cause was an **inconsistent application of ID sanitization** between where `tool_use` blocks were saved to history (`Task.ts`) and where `tool_result` blocks were created (`presentAssistantMessage.ts`). This affected approximately **926 occurrences** reported via PostHog telemetry in version 3.46.0.
6+
7+
## Background: The Tool Execution Flow
8+
9+
To understand the problem, it's essential to understand how tool execution and API conversation history work in this codebase:
10+
11+
### 1. Tool Use Block Creation and Storage
12+
13+
When the AI model responds with tool calls:
14+
15+
1. **Streaming Phase** (`Task.ts:3400-3570`): Tool use blocks arrive during streaming
16+
2. **Sanitization** (`Task.ts:3459-3480`): Tool use IDs are sanitized using `sanitizeToolUseId()` before being saved to API history
17+
- Original ID: `functions.read_file:0`
18+
- Sanitized ID: `functions_read_file_0`
19+
3. **Storage** (`Task.ts:3549-3553`): The assistant message with **sanitized** tool_use IDs is added to `apiConversationHistory`
20+
21+
```typescript
22+
const sanitizedId = sanitizeToolUseId(toolCallId)
23+
// ... later ...
24+
await this.addToApiConversationHistory(
25+
{ role: "assistant", content: assistantContent },
26+
reasoningMessage || undefined,
27+
)
28+
```
29+
30+
### 2. Tool Result Block Creation (THE BUG LOCATION)
31+
32+
When tools are executed in `presentAssistantMessage.ts`:
33+
34+
1. **Tool Execution**: Tools run and produce results
35+
2. **Result Creation** (BEFORE PR #11131): Tool result blocks were created with **unsanitized** `toolCallId`:
36+
```typescript
37+
cline.pushToolResultToUserContent({
38+
type: "tool_result",
39+
tool_use_id: toolCallId, // ❌ UNSANITIZED: "functions.read_file:0"
40+
content: resultContent,
41+
})
42+
```
43+
3. **The Mismatch**:
44+
- Tool use ID in history: `functions_read_file_0` (sanitized)
45+
- Tool result ID trying to reference it: `functions.read_file:0` (unsanitized)
46+
- **Result**: `ToolResultIdMismatchError`
47+
48+
### 3. Validation and Error Detection
49+
50+
Before messages are added to API history, they pass through `validateAndFixToolResultIds()`:
51+
52+
- **Location**: Called in `Task.ts:1163` and `Task.ts:1241`
53+
- **Purpose**: Validates that tool_result IDs match tool_use IDs from the previous assistant message
54+
- **Error Tracking**: Reports mismatches to PostHog telemetry as `ToolResultIdMismatchError`
55+
- **Automatic Fixing**: Attempts to fix mismatches by position-based matching, but this is a **workaround** for what should have been prevented
56+
57+
## The Root Cause
58+
59+
The root cause was a **split-brain problem** in ID sanitization:
60+
61+
### Path 1: Tool Use IDs (Correct)
62+
```
63+
AI Model Response → tool_use block created → sanitizeToolUseId() applied
64+
→ Saved to API history with sanitized ID (e.g., "functions_read_file_0")
65+
```
66+
67+
### Path 2: Tool Result IDs (Incorrect - Before PR #11131)
68+
```
69+
Tool execution → tool_result block created → NO SANITIZATION APPLIED
70+
→ Attempted to reference tool_use with unsanitized ID (e.g., "functions.read_file:0")
71+
```
72+
73+
### Why This Happened
74+
75+
The ID sanitization logic was added to `Task.ts` to handle API validation requirements (IDs must match `^[a-zA-Z0-9_-]+$`), but the corresponding sanitization was **not added** to `presentAssistantMessage.ts` where tool results are created. This created an asymmetry in the codebase.
76+
77+
## The Fix (PR #11131)
78+
79+
The fix was surgical and precise:
80+
81+
1. **Import sanitizeToolUseId** in `presentAssistantMessage.ts`:
82+
```typescript
83+
import { sanitizeToolUseId } from "../../utils/tool-id"
84+
```
85+
86+
2. **Apply sanitization at all 7 locations** where tool_result blocks are created:
87+
```typescript
88+
cline.pushToolResultToUserContent({
89+
type: "tool_result",
90+
tool_use_id: sanitizeToolUseId(toolCallId), // ✅ NOW SANITIZED
91+
content: resultContent,
92+
})
93+
```
94+
95+
3. **Added test coverage** for the exact pattern seen in PostHog errors:
96+
```typescript
97+
expect(sanitizeToolUseId("functions.read_file:0")).toBe("functions_read_file_0")
98+
```
99+
100+
## Scope of Change: Relationship to Queued Outgoing User Prompts
101+
102+
### Understanding "Queued Outgoing User Prompts"
103+
104+
The codebase has a message queueing system for handling user prompts that arrive while the task is busy:
105+
106+
1. **Queueing** (`MessageQueueService.ts`): Messages are queued when they arrive during certain task states
107+
2. **Processing** (`Task.ts:4756-4771`): After operations complete, queued messages are dequeued and submitted via `submitUserMessage()`
108+
3. **Flow to History**: These user messages eventually flow through the same `addToApiConversationHistory()` path
109+
110+
### How Tool Block ID Sanitization Relates to Queued Prompts
111+
112+
The relationship is **indirect but critical**:
113+
114+
#### Scenario: Parallel Tool Execution with Queued User Prompts
115+
116+
Consider this sequence:
117+
118+
1. **T=0ms**: AI responds with multiple tool_use blocks (e.g., `read_file`, `new_task`)
119+
2. **T=10ms**: Tools begin executing in parallel during streaming
120+
3. **T=20ms**: User types a new message → **queued** because task is busy
121+
4. **T=30ms**: First tool (`read_file`) completes → `pushToolResultToUserContent()` called
122+
5. **T=40ms**: Second tool (`new_task`) triggers delegation → `flushPendingToolResultsToHistory()` called
123+
6. **T=50ms**: Queued user message is dequeued and processed
124+
125+
#### The Critical Point: ID Validation During Flush
126+
127+
When `flushPendingToolResultsToHistory()` is called (step 5):
128+
129+
```typescript
130+
// Task.ts:1237-1241
131+
const validatedMessage = validateAndFixToolResultIds(userMessage, historyForValidation)
132+
```
133+
134+
This validation compares:
135+
- **Tool result IDs** from `userMessageContent` (accumulated from tool executions)
136+
- **Tool use IDs** from the previous assistant message in `apiConversationHistory`
137+
138+
**Before PR #11131**: The validation would detect a mismatch because:
139+
- Tool use ID in history: `functions_read_file_0` (sanitized)
140+
- Tool result ID in pending content: `functions.read_file:0` (unsanitized)
141+
- Result: `ToolResultIdMismatchError` captured in PostHog
142+
143+
**After PR #11131**: Both IDs are sanitized consistently:
144+
- Tool use ID in history: `functions_read_file_0` (sanitized in Task.ts)
145+
- Tool result ID in pending content: `functions_read_file_0` (sanitized in presentAssistantMessage.ts)
146+
- Result: No mismatch, validation passes
147+
148+
### Why This Matters for Queued Prompts
149+
150+
Queued user prompts are particularly relevant because:
151+
152+
1. **Timing Sensitivity**: When messages are queued, there's a higher likelihood of tool results being flushed to history before the next API request (due to the asynchronous nature of queueing)
153+
154+
2. **Validation Trigger Points**: Queued prompts trigger `submitUserMessage()` which may cause:
155+
- Context condensing (`condenseContext()` → `flushPendingToolResultsToHistory()`)
156+
- New API requests (which flush pending tool results)
157+
158+
3. **Race Condition Exposure**: The queueing mechanism exposes timing-dependent code paths where tool results might be validated against API history at different points than in synchronous execution
159+
160+
## Impact Analysis
161+
162+
### Affected Patterns
163+
164+
The bug affected API providers that generate function call IDs with special characters:
165+
166+
- **Gemini/OpenRouter**: Generate IDs like `functions.read_file:0`, `functions.write_to_file:1`
167+
- **MCP Tools**: Could generate IDs like `mcp.server:tool/name`
168+
169+
### Why PostHog Reported 926 Occurrences
170+
171+
1. **Version 3.46.0**: The issue existed in production
172+
2. **Gemini/OpenRouter Usage**: Users with these providers would hit the issue on every tool call
173+
3. **Validation Catches All**: `validateAndFixToolResultIds()` reports **every** mismatch to PostHog
174+
4. **Multiple Tools Per Turn**: A single AI turn with 3 tools = 3 error reports
175+
176+
### Why It Didn't Break Completely
177+
178+
The validation layer (`validateAndFixToolResultIds()`) served as a **defensive safety net**:
179+
180+
- **Position-based fixing**: Attempts to match tool results to tool uses by position
181+
- **Automatic correction**: Fixes mismatches when possible
182+
- **Error tracking**: Reports to PostHog but doesn't fail the operation
183+
184+
However, this was masking the **root cause** rather than preventing the issue from occurring.
185+
186+
## Technical Debt Implications
187+
188+
### Before PR #11131 (Technical Debt)
189+
190+
1. **Split Responsibility**: ID sanitization logic existed in two places:
191+
- `Task.ts`: Sanitizes before saving to history
192+
- `validateAndFixToolResultIds()`: Attempts to fix mismatches after the fact
193+
194+
2. **Validation as Workaround**: The validation layer was doing **corrective work** that should have been **preventative**
195+
196+
3. **Telemetry Noise**: 926 error reports for what should have been a non-error
197+
198+
### After PR #11131 (Debt Reduced)
199+
200+
1. **Consistent Sanitization**: IDs are sanitized at creation time in both places:
201+
- `Task.ts`: When saving tool_use blocks
202+
- `presentAssistantMessage.ts`: When creating tool_result blocks
203+
204+
2. **Validation as Safety Net**: Now only catches **genuine anomalies** rather than systematic mismatches
205+
206+
3. **Clean Telemetry**: Error reports only for actual problems
207+
208+
## Conclusion
209+
210+
PR #11131 fixed a fundamental architectural inconsistency where tool block IDs were sanitized in one part of the system but not another. The scope of the change is **narrow** (adding sanitization to 7 locations in one file) but the **impact is significant** because:
211+
212+
1. **Prevents Systematic Errors**: Eliminates 926+ PostHog error reports
213+
2. **Ensures API Compliance**: Tool result IDs now always match tool use IDs
214+
3. **Reduces Reliance on Defensive Code**: Validation layer no longer needs to fix preventable issues
215+
4. **Improves Reliability**: Especially important for queued user prompts which can trigger validation at unexpected times
216+
217+
The relationship to queued outgoing user prompts is that they **expose timing-dependent code paths** where tool results are flushed to history and validated. Without consistent ID sanitization, these paths would trigger `ToolResultIdMismatchError` reports, which PR #11131 now prevents.
218+
219+
## References
220+
221+
- **PR #11131**: https://github.com/RooCodeInc/Roo-Code/pull/11131
222+
- **Linear Issue**: EXT-711
223+
- **Key Files Changed**:
224+
- `src/core/assistant-message/presentAssistantMessage.ts` (7 sanitization calls added)
225+
- `src/utils/__tests__/tool-id.spec.ts` (test coverage added)
226+
- **Validation Logic**: `src/core/task/validateToolResultIds.ts`
227+
- **ID Sanitization Utility**: `src/utils/tool-id.ts`

0 commit comments

Comments
 (0)