feat: add debug logging for native tool calls

- Added debugNativeToolCalls configuration option to enable/disable debug logging - Created utility functions for conditional debug logging - Added comprehensive debug logging to NativeToolCallParser - Added debug logging to openai-native provider for tool call processing - Added debug logging to presentAssistantMessage for tool execution flow This helps diagnose issues with native tool calls, particularly for models like Kimi K2 that use special token formats.
2026-10-07 02:58:15 +00:00 · 2025-11-25 02:59:24 +00:00 · 2025-11-25 02:59:24 +00:00 · 8ac8819d40
commit 8ac8819d40
parent cad6145241
5 changed files with 200 additions and 7 deletions
--- a/src/api/providers/openai-native.ts
+++ b/src/api/providers/openai-native.ts
@ -1,5 +1,6 @@
 import { Anthropic } from "@anthropic-ai/sdk"
 import OpenAI from "openai"
+import { debugNativeToolCall } from "../../utils/debugNativeToolCalls"

 import {
 	type ModelInfo,
@ -786,6 +787,13 @@ export class OpenAiNativeHandler extends BaseProvider implements SingleCompletio
 								parsed.type === "response.function_call_arguments.done" ||
 								parsed.type === "response.tool_call_arguments.done"
 							) {
+								debugNativeToolCall("[OpenAI-Native] SSE tool call event:", {
+									type: parsed.type,
+									callId: parsed.call_id || parsed.tool_call_id || parsed.id,
+									hasName: !!(parsed.name || parsed.function_name),
+									hasDelta: !!(parsed.delta || parsed.arguments),
+								})
+
 								// Delegated to processEvent (handles accumulation and completion)
 								for await (const outChunk of this.processEvent(parsed, model)) {
 									yield outChunk
@ -1076,21 +1084,36 @@ export class OpenAiNativeHandler extends BaseProvider implements SingleCompletio
 			event?.type === "response.function_call_arguments.delta"
 		) {
 			const callId = event.call_id || event.tool_call_id || event.id
+			debugNativeToolCall("[OpenAI-Native] Tool call delta received:", {
+				type: event.type,
+				callId,
+				hasName: !!(event.name || event.function_name),
+				hasDelta: !!(event.delta || event.arguments),
+				deltaLength: (event.delta || event.arguments)?.length,
+			})
+
 			if (callId) {
 				if (!this.currentToolCalls.has(callId)) {
 					this.currentToolCalls.set(callId, { name: "", arguments: "" })
+					debugNativeToolCall(`[OpenAI-Native] Created new tool call accumulator for ID: ${callId}`)
 				}
 				const toolCall = this.currentToolCalls.get(callId)!

 				// Update name if present (usually in the first delta)
 				if (event.name || event.function_name) {
 					toolCall.name = event.name || event.function_name
+					debugNativeToolCall(`[OpenAI-Native] Set tool call name: ${toolCall.name} for ID: ${callId}`)
 				}

 				// Append arguments delta
 				if (event.delta || event.arguments) {
 					toolCall.arguments += event.delta || event.arguments
+					debugNativeToolCall(
+						`[OpenAI-Native] Appended arguments delta for ${toolCall.name || "unnamed"}, total length: ${toolCall.arguments.length}`,
+					)
 				}
+			} else {
+				console.warn("[OpenAI-Native] Tool call delta received without call ID:", event)
 			}
 			return
 		}
@ -1100,8 +1123,21 @@ export class OpenAiNativeHandler extends BaseProvider implements SingleCompletio
 			event?.type === "response.function_call_arguments.done"
 		) {
 			const callId = event.call_id || event.tool_call_id || event.id
+			debugNativeToolCall("[OpenAI-Native] Tool call done event:", {
+				type: event.type,
+				callId,
+				hasAccumulated: this.currentToolCalls.has(callId),
+			})
+
 			if (callId && this.currentToolCalls.has(callId)) {
 				const toolCall = this.currentToolCalls.get(callId)!
+				debugNativeToolCall(`[OpenAI-Native] Completing tool call:`, {
+					id: callId,
+					name: toolCall.name,
+					argumentsLength: toolCall.arguments.length,
+					argumentsPreview: toolCall.arguments.substring(0, 200),
+				})
+
 				// Yield the complete tool call
 				yield {
 					type: "tool_call",
@ -1111,6 +1147,9 @@ export class OpenAiNativeHandler extends BaseProvider implements SingleCompletio
 				}
 				// Remove from accumulator
 				this.currentToolCalls.delete(callId)
+				debugNativeToolCall(`[OpenAI-Native] Tool call yielded and removed from accumulator: ${callId}`)
+			} else {
+				console.warn(`[OpenAI-Native] Tool call done event for unknown ID: ${callId}`)
 			}
 			return
 		}
@ -1136,12 +1175,28 @@ export class OpenAiNativeHandler extends BaseProvider implements SingleCompletio
 				) {
 					// Handle complete tool/function call item
 					const callId = item.call_id || item.tool_call_id || item.id
+					debugNativeToolCall("[OpenAI-Native] Output item tool/function call:", {
+						type: item.type,
+						callId,
+						name: item.name || item.function?.name || item.function_name,
+						hasArguments: !!(item.arguments || item.function?.arguments || item.function_arguments),
+					})
+
 					if (callId && !this.currentToolCalls.has(callId)) {
 						const args = item.arguments || item.function?.arguments || item.function_arguments
+						const toolName = item.name || item.function?.name || item.function_name || ""
+
+						debugNativeToolCall(`[OpenAI-Native] Yielding complete tool call from output item:`, {
+							id: callId,
+							name: toolName,
+							argumentsType: typeof args,
+							argumentsLength: typeof args === "string" ? args.length : 0,
+						})
+
 						yield {
 							type: "tool_call",
 							id: callId,
-							name: item.name || item.function?.name || item.function_name || "",
+							name: toolName,
 							arguments: typeof args === "string" ? args : "{}",
 						}
 					}
@ -1154,7 +1209,17 @@ export class OpenAiNativeHandler extends BaseProvider implements SingleCompletio
 		if (event?.type === "response.done" || event?.type === "response.completed") {
 			// Yield any pending tool calls that didn't get a 'done' event (fallback)
 			if (this.currentToolCalls.size > 0) {
+				debugNativeToolCall(
+					`[OpenAI-Native] Response completed with ${this.currentToolCalls.size} pending tool calls (fallback)`,
+				)
+
 				for (const [callId, toolCall] of this.currentToolCalls) {
+					debugNativeToolCall(`[OpenAI-Native] Yielding pending tool call (fallback):`, {
+						id: callId,
+						name: toolCall.name,
+						argumentsLength: toolCall.arguments?.length || 0,
+					})
+
 					yield {
 						type: "tool_call",
 						id: callId,
--- a/src/core/assistant-message/NativeToolCallParser.ts
+++ b/src/core/assistant-message/NativeToolCallParser.ts
@ -1,5 +1,6 @@
 import { type ToolName, toolNames, type FileEntry } from "@roo-code/types"
 import { type ToolUse, type ToolParamName, toolParamNames, type NativeToolArgs } from "../../shared/tools"
+import { debugNativeToolCall } from "../../utils/debugNativeToolCalls"

 /**
 * Helper type to extract properly typed native arguments for a given tool.
@ -28,21 +29,31 @@ export class NativeToolCallParser {
 		name: TName
 		arguments: string
 	}): ToolUse<TName> | null {
+		// Debug: Log incoming tool call
+		debugNativeToolCall("[NativeToolCallParser] Parsing tool call:", {
+			id: toolCall.id,
+			name: toolCall.name,
+			argumentsLength: toolCall.arguments?.length,
+			argumentsPreview: toolCall.arguments?.substring(0, 200),
+		})
+
 		// Check if this is a dynamic MCP tool (mcp_serverName_toolName)
 		if (typeof toolCall.name === "string" && toolCall.name.startsWith("mcp_")) {
+			debugNativeToolCall("[NativeToolCallParser] Detected dynamic MCP tool:", toolCall.name)
 			return this.parseDynamicMcpTool(toolCall) as ToolUse<TName> | null
 		}

 		// Validate tool name
 		if (!toolNames.includes(toolCall.name as ToolName)) {
-			console.error(`Invalid tool name: ${toolCall.name}`)
-			console.error(`Valid tool names:`, toolNames)
+			console.error(`[NativeToolCallParser] Invalid tool name: ${toolCall.name}`)
+			console.error(`[NativeToolCallParser] Valid tool names:`, toolNames)
 			return null
 		}

 		try {
 			// Parse the arguments JSON string
 			const args = JSON.parse(toolCall.arguments)
+			debugNativeToolCall(`[NativeToolCallParser] Parsed arguments for ${toolCall.name}:`, args)

 			// Build legacy params object for backward compatibility with XML protocol and UI.
 			// Native execution path uses nativeArgs instead, which has proper typing.
@ -78,6 +89,8 @@ export class NativeToolCallParser {
 			// will fall back to legacy parameter parsing if supported.
 			let nativeArgs: NativeArgsFor<TName> | undefined = undefined

+			debugNativeToolCall(`[NativeToolCallParser] Building nativeArgs for tool: ${toolCall.name}`)
+
 			switch (toolCall.name) {
 				case "read_file":
 					if (args.files && Array.isArray(args.files)) {
@ -238,6 +251,15 @@ export class NativeToolCallParser {
 					break
 			}

+			// Debug: Log the constructed nativeArgs
+			if (nativeArgs) {
+				debugNativeToolCall(`[NativeToolCallParser] Built nativeArgs for ${toolCall.name}:`, nativeArgs)
+			} else {
+				debugNativeToolCall(
+					`[NativeToolCallParser] No nativeArgs built for ${toolCall.name} (validation failed or not implemented)`,
+				)
+			}
+
 			const result: ToolUse<TName> = {
 				type: "tool_use" as const,
 				name: toolCall.name,
@ -246,10 +268,20 @@ export class NativeToolCallParser {
 				nativeArgs,
 			}

+			debugNativeToolCall(`[NativeToolCallParser] Successfully parsed tool call ${toolCall.name}:`, {
+				hasNativeArgs: !!nativeArgs,
+				paramKeys: Object.keys(params),
+				toolId: toolCall.id,
+			})
+
 			return result
 		} catch (error) {
-			console.error(`Failed to parse tool call arguments:`, error)
-			console.error(`Error details:`, error instanceof Error ? error.message : String(error))
+			console.error(`[NativeToolCallParser] Failed to parse tool call arguments:`, error)
+			console.error(
+				`[NativeToolCallParser] Error details:`,
+				error instanceof Error ? error.message : String(error),
+			)
+			console.error(`[NativeToolCallParser] Raw arguments that failed to parse:`, toolCall.arguments)
 			return null
 		}
 	}
@ -264,8 +296,14 @@ export class NativeToolCallParser {
 		name: string
 		arguments: string
 	}): ToolUse<"use_mcp_tool"> | null {
+		debugNativeToolCall("[NativeToolCallParser] Parsing dynamic MCP tool:", {
+			name: toolCall.name,
+			argumentsLength: toolCall.arguments?.length,
+		})
+
 		try {
 			const args = JSON.parse(toolCall.arguments)
+			debugNativeToolCall("[NativeToolCallParser] Parsed MCP tool arguments:", args)

 			// Extract server_name and tool_name from the arguments
 			// The dynamic tool schema includes these as const properties
@ -274,7 +312,8 @@ export class NativeToolCallParser {
 			const toolInputProps = args.toolInputProps

 			if (!serverName || !toolName) {
-				console.error(`Missing server_name or tool_name in dynamic MCP tool`)
+				console.error(`[NativeToolCallParser] Missing server_name or tool_name in dynamic MCP tool`)
+				console.error(`[NativeToolCallParser] Received args:`, args)
 				return null
 			}

@ -303,9 +342,16 @@ export class NativeToolCallParser {
 				nativeArgs,
 			}

+			debugNativeToolCall(`[NativeToolCallParser] Successfully parsed dynamic MCP tool:`, {
+				serverName,
+				toolName,
+				hasToolInputProps: !!toolInputProps,
+			})
+
 			return result
 		} catch (error) {
-			console.error(`Failed to parse dynamic MCP tool:`, error)
+			console.error(`[NativeToolCallParser] Failed to parse dynamic MCP tool:`, error)
+			console.error(`[NativeToolCallParser] Raw arguments:`, toolCall.arguments)
 			return null
 		}
 	}
--- a/src/core/assistant-message/presentAssistantMessage.ts
+++ b/src/core/assistant-message/presentAssistantMessage.ts
@ -1,6 +1,7 @@
 import cloneDeep from "clone-deep"
 import { serializeError } from "serialize-error"
 import { Anthropic } from "@anthropic-ai/sdk"
+import { debugNativeToolCall } from "../../utils/debugNativeToolCalls"

 import type { ToolName, ClineAsk, ToolProgressStatus } from "@roo-code/types"
 import { TelemetryService } from "@roo-code/telemetry"
@ -170,6 +171,17 @@ export async function presentAssistantMessage(cline: Task) {
 			break
 		}
 		case "tool_use":
+			// Debug: Log tool use block details
+			debugNativeToolCall("[presentAssistantMessage] Processing tool_use block:", {
+				name: block.name,
+				hasId: !!block.id,
+				hasNativeArgs: !!block.nativeArgs,
+				hasParams: !!block.params,
+				partial: block.partial,
+				paramKeys: block.params ? Object.keys(block.params) : [],
+				nativeArgsKeys: block.nativeArgs ? Object.keys(block.nativeArgs) : [],
+			})
+
 			const toolDescription = (): string => {
 				switch (block.name) {
 					case "execute_command":
@ -258,6 +270,12 @@ export async function presentAssistantMessage(cline: Task) {
 					? `Skipping tool ${toolDescription()} due to user rejecting a previous tool.`
 					: `Tool ${toolDescription()} was interrupted and not executed due to user rejecting a previous tool.`

+				debugNativeToolCall(`[presentAssistantMessage] Tool rejected:`, {
+					toolName: block.name,
+					toolCallId,
+					errorMessage,
+				})
+
 				if (toolCallId) {
 					// Native protocol: MUST send tool_result for every tool_use
 					cline.userMessageContent.push({
@ -283,6 +301,12 @@ export async function presentAssistantMessage(cline: Task) {
 				const toolCallId = block.id
 				const errorMessage = `Tool [${block.name}] was not executed because a tool has already been used in this message. Only one tool may be used per message. You must assess the first tool's result before proceeding to use the next tool.`

+				debugNativeToolCall(`[presentAssistantMessage] Tool already used:`, {
+					toolName: block.name,
+					toolCallId,
+					errorMessage,
+				})
+
 				if (toolCallId) {
 					// Native protocol: MUST send tool_result for every tool_use
 					cline.userMessageContent.push({
@ -311,7 +335,20 @@ export async function presentAssistantMessage(cline: Task) {
 			const toolCallId = (block as any).id
 			const toolProtocol = toolCallId ? TOOL_PROTOCOL.NATIVE : TOOL_PROTOCOL.XML

+			debugNativeToolCall(`[presentAssistantMessage] Tool protocol detected:`, {
+				protocol: toolProtocol,
+				toolCallId,
+				toolName: block.name,
+			})
+
 			const pushToolResult = (content: ToolResponse) => {
+				debugNativeToolCall(`[presentAssistantMessage] Pushing tool result:`, {
+					protocol: toolProtocol,
+					toolCallId,
+					contentType: typeof content,
+					hasToolResult,
+				})
+
 				if (toolProtocol === TOOL_PROTOCOL.NATIVE) {
 					// For native protocol, only allow ONE tool_result per tool call
 					if (hasToolResult) {
@ -352,6 +389,11 @@ export async function presentAssistantMessage(cline: Task) {
 					}

 					hasToolResult = true
+					debugNativeToolCall(`[presentAssistantMessage] Native tool_result pushed:`, {
+						toolCallId,
+						resultLength: resultContent.length,
+						imageCount: imageBlocks.length,
+					})
 				} else {
 					// For XML protocol, add as text blocks (legacy behavior)
 					cline.userMessageContent.push({ type: "text", text: `${toolDescription()} Result:` })
@ -490,6 +532,10 @@ export async function presentAssistantMessage(cline: Task) {
 			}

 			if (!block.partial) {
+				debugNativeToolCall(`[presentAssistantMessage] Recording tool usage:`, {
+					toolName: block.name,
+					protocol: toolProtocol,
+				})
 				cline.recordToolUsage(block.name)
 				TelemetryService.instance.captureToolUsage(cline.taskId, block.name, toolProtocol)
 			}
@ -553,6 +599,8 @@ export async function presentAssistantMessage(cline: Task) {
 				}
 			}

+			debugNativeToolCall(`[presentAssistantMessage] Executing tool handler for: ${block.name}`)
+
 			switch (block.name) {
 				case "write_to_file":
 					await checkpointSaveAndMark(cline)
@ -795,6 +843,8 @@ export async function presentAssistantMessage(cline: Task) {
 					break
 			}

+			debugNativeToolCall(`[presentAssistantMessage] Tool handler completed for: ${block.name}`)
+
 			break
 	}

--- a/src/package.json
+++ b/src/package.json
@ -436,6 +436,11 @@
 					"minimum": 1,
 					"maximum": 200,
 					"description": "%settings.codeIndex.embeddingBatchSize.description%"
+				},
+				"roo-cline.debugNativeToolCalls": {
+					"type": "boolean",
+					"default": false,
+					"description": "Enable debug logging for native tool calls to help diagnose issues with tool execution"
 				}
 			}
 		}
--- a/src/utils/debugNativeToolCalls.ts
+++ b/src/utils/debugNativeToolCalls.ts
@ -0,0 +1,27 @@
+import * as vscode from "vscode"
+import { Package } from "../shared/package"
+
+/**
+ * Check if debug logging for native tool calls is enabled
+ */
+export function isNativeToolCallDebugEnabled(): boolean {
+	try {
+		return vscode.workspace.getConfiguration(Package.name).get<boolean>("debugNativeToolCalls", false)
+	} catch {
+		// If there's any error accessing configuration, default to false
+		return false
+	}
+}
+
+/**
+ * Log debug information for native tool calls if debugging is enabled
+ */
+export function debugNativeToolCall(message: string, data?: any): void {
+	if (isNativeToolCallDebugEnabled()) {
+		if (data !== undefined) {
+			console.debug(message, data)
+		} else {
+			console.debug(message)
+		}
+	}
+}