feat: add comprehensive debug logging for native tool call handling

- Enable production logging with configurable log levels via environment variables
- Add debug logging to NativeToolCallParser for tool call parsing
- Add debug logging to Task.ts for native tool call reception
- Add debug logging to presentAssistantMessage.ts for tool execution flow
- Add debug logging to BaseTool for parameter parsing and execution

Environment variables:
- ROO_DEBUG_LOGGING: Set to "false" to disable all logging
- ROO_LOG_LEVEL: Set to "debug", "info", "warn", "error", or "fatal" (default: "info")

This helps diagnose issues with native tool calls, particularly for models like Kimi K2 Thinking.

Fixes #9551

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 { logger } from "../../utils/logging"
 
 /**
  * Helper type to extract properly typed native arguments for a given tool.
@@ -28,13 +29,25 @@ export class NativeToolCallParser {
 		name: TName
 		arguments: string
 	}): ToolUse<TName> | null {
+		const log = logger.child({ ctx: "NativeToolCallParser" })
+
+		log.debug(`Parsing native tool call`, {
+			id: toolCall.id,
+			name: toolCall.name,
+			argumentsLength: toolCall.arguments?.length || 0,
+		})
+
 		// Check if this is a dynamic MCP tool (mcp_serverName_toolName)
 		if (typeof toolCall.name === "string" && toolCall.name.startsWith("mcp_")) {
+			log.debug(`Detected dynamic MCP tool: ${toolCall.name}`)
 			return this.parseDynamicMcpTool(toolCall) as ToolUse<TName> | null
 		}
 
 		// Validate tool name
 		if (!toolNames.includes(toolCall.name as ToolName)) {
+			log.error(`Invalid tool name: ${toolCall.name}`, {
+				validToolNames: toolNames,
+			})
 			console.error(`Invalid tool name: ${toolCall.name}`)
 			console.error(`Valid tool names:`, toolNames)
 			return null
@@ -44,6 +57,31 @@ export class NativeToolCallParser {
 			// Parse the arguments JSON string
 			const args = JSON.parse(toolCall.arguments)
 
+			log.debug(`Parsed arguments for ${toolCall.name}`, {
+				argKeys: Object.keys(args),
+				hasNativeSupport:
+					toolCall.name in
+					[
+						"read_file",
+						"attempt_completion",
+						"execute_command",
+						"insert_content",
+						"apply_diff",
+						"ask_followup_question",
+						"browser_action",
+						"codebase_search",
+						"fetch_instructions",
+						"generate_image",
+						"list_code_definition_names",
+						"run_slash_command",
+						"search_files",
+						"switch_mode",
+						"update_todo_list",
+						"write_to_file",
+						"use_mcp_tool",
+					],
+			})
+
 			// Build legacy params object for backward compatibility with XML protocol and UI.
 			// Native execution path uses nativeArgs instead, which has proper typing.
 			const params: Partial<Record<ToolParamName, string>> = {}
@@ -58,6 +96,9 @@ export class NativeToolCallParser {
 
 				// Validate parameter name
 				if (!toolParamNames.includes(key as ToolParamName)) {
+					log.warn(`Unknown parameter '${key}' for tool '${toolCall.name}'`, {
+						validParamNames: toolParamNames,
+					})
 					console.warn(`Unknown parameter '${key}' for tool '${toolCall.name}'`)
 					console.warn(`Valid param names:`, toolParamNames)
 					continue
@@ -246,8 +287,17 @@ export class NativeToolCallParser {
 				nativeArgs,
 			}
 
+			log.debug(`Successfully parsed tool call ${toolCall.name}`, {
+				hasNativeArgs: !!nativeArgs,
+				paramCount: Object.keys(params).length,
+			})
+
 			return result
 		} catch (error) {
+			log.error(`Failed to parse tool call arguments for ${toolCall.name}`, {
+				error: error instanceof Error ? error.message : String(error),
+				arguments: toolCall.arguments,
+			})
 			console.error(`Failed to parse tool call arguments:`, error)
 			console.error(`Error details:`, error instanceof Error ? error.message : String(error))
 			return null
@@ -265,6 +315,12 @@ export class NativeToolCallParser {
 		arguments: string
 	}): ToolUse<"use_mcp_tool"> | null {
 		try {
+			const log = logger.child({ ctx: "NativeToolCallParser.parseDynamicMcpTool" })
+			log.debug(`Parsing dynamic MCP tool`, {
+				name: toolCall.name,
+				id: toolCall.id,
+			})
+
 			const args = JSON.parse(toolCall.arguments)
 
 			// Extract server_name and tool_name from the arguments
@@ -274,10 +330,20 @@ export class NativeToolCallParser {
 			const toolInputProps = args.toolInputProps
 
 			if (!serverName || !toolName) {
+				log.error(`Missing server_name or tool_name in dynamic MCP tool`, {
+					serverName,
+					toolName,
+				})
 				console.error(`Missing server_name or tool_name in dynamic MCP tool`)
 				return null
 			}
 
+			log.debug(`Parsed dynamic MCP tool`, {
+				serverName,
+				toolName,
+				hasToolInputProps: !!toolInputProps,
+			})
+
 			// Build params for backward compatibility with XML protocol
 			const params: Partial<Record<string, string>> = {
 				server_name: serverName,
@@ -303,8 +369,18 @@ export class NativeToolCallParser {
 				nativeArgs,
 			}
 
+			log.debug(`Successfully parsed dynamic MCP tool`, {
+				serverName: nativeArgs.server_name,
+				toolName: nativeArgs.tool_name,
+			})
+
 			return result
 		} catch (error) {
+			const log = logger.child({ ctx: "NativeToolCallParser.parseDynamicMcpTool" })
+			log.error(`Failed to parse dynamic MCP tool`, {
+				error: error instanceof Error ? error.message : String(error),
+				name: toolCall.name,
+			})
 			console.error(`Failed to parse dynamic MCP tool:`, error)
 			return null
 		}

src/core/assistant-message/presentAssistantMessage.ts

@@ -40,6 +40,7 @@ import { experiments, EXPERIMENT_IDS } from "../../shared/experiments"
 import { applyDiffTool as applyDiffToolClass } from "../tools/ApplyDiffTool"
 import { isNativeProtocol } from "@roo-code/types"
 import { resolveToolProtocol } from "../../utils/resolveToolProtocol"
+import { logger } from "../../utils/logging"
 
 /**
  * Processes and presents assistant message content to the user interface.
@@ -169,7 +170,16 @@ export async function presentAssistantMessage(cline: Task) {
 			await cline.say("text", content, undefined, block.partial)
 			break
 		}
-		case "tool_use":
+		case "tool_use": {
+			const log = logger.child({ ctx: "presentAssistantMessage.tool_use", taskId: cline.taskId })
+			log.debug("Processing tool_use block", {
+				toolName: block.name,
+				toolId: block.id,
+				isPartial: block.partial,
+				hasNativeArgs: !!block.nativeArgs,
+				paramKeys: block.params ? Object.keys(block.params) : [],
+			})
+
 			const toolDescription = (): string => {
 				switch (block.name) {
 					case "execute_command":
@@ -311,10 +321,20 @@ export async function presentAssistantMessage(cline: Task) {
 			const toolCallId = (block as any).id
 			const toolProtocol = toolCallId ? TOOL_PROTOCOL.NATIVE : TOOL_PROTOCOL.XML
 
+			log.debug("Determined tool protocol", {
+				toolCallId,
+				toolProtocol,
+				toolName: block.name,
+			})
+
 			const pushToolResult = (content: ToolResponse) => {
 				if (toolProtocol === TOOL_PROTOCOL.NATIVE) {
 					// For native protocol, only allow ONE tool_result per tool call
 					if (hasToolResult) {
+						log.warn("Skipping duplicate tool_result for native protocol", {
+							toolCallId,
+							toolName: block.name,
+						})
 						console.warn(
 							`[presentAssistantMessage] Skipping duplicate tool_result for tool_use_id: ${toolCallId}`,
 						)
@@ -339,6 +359,12 @@ export async function presentAssistantMessage(cline: Task) {
 							"(tool did not return anything)"
 					}
 
+					log.debug("Adding tool_result to user message content", {
+						toolCallId,
+						contentLength: resultContent.length,
+						hasImages: imageBlocks.length > 0,
+					})
+
 					// Add tool_result with text content only
 					cline.userMessageContent.push({
 						type: "tool_result",
@@ -490,6 +516,10 @@ export async function presentAssistantMessage(cline: Task) {
 			}
 
 			if (!block.partial) {
+				log.debug("Recording tool usage (non-partial)", {
+					toolName: block.name,
+					toolProtocol,
+				})
 				cline.recordToolUsage(block.name)
 				TelemetryService.instance.captureToolUsage(cline.taskId, block.name, toolProtocol)
 			}
@@ -553,6 +583,13 @@ export async function presentAssistantMessage(cline: Task) {
 				}
 			}
 
+			log.debug("Executing tool handler", {
+				toolName: block.name,
+				toolProtocol,
+				hasApprovalCallback: !!askApproval,
+				hasErrorHandler: !!handleError,
+			})
+
 			switch (block.name) {
 				case "write_to_file":
 					await checkpointSaveAndMark(cline)
@@ -795,7 +832,13 @@ export async function presentAssistantMessage(cline: Task) {
 					break
 			}
 
+			log.debug("Tool execution completed", {
+				toolName: block.name,
+				didRejectTool: cline.didRejectTool,
+				didAlreadyUseTool: cline.didAlreadyUseTool,
+			})
 			break
+		}
 	}
 
 	// Seeing out of bounds is fine, it means that the next too call is being

src/core/task/Task.ts

@@ -99,6 +99,7 @@ import { type AssistantMessageContent, presentAssistantMessage } from "../assist
 import { AssistantMessageParser } from "../assistant-message/AssistantMessageParser"
 import { NativeToolCallParser } from "../assistant-message/NativeToolCallParser"
 import { manageContext } from "../context-management"
+import { logger } from "../../utils/logging"
 import { ClineProvider } from "../webview/ClineProvider"
 import { MultiSearchReplaceDiffStrategy } from "../diff/strategies/multi-search-replace"
 import { MultiFileSearchReplaceDiffStrategy } from "../diff/strategies/multi-file-search-replace"
@@ -2337,6 +2338,13 @@ export class Task extends EventEmitter<TaskEvents> implements TaskLike {
 								}
 								break
 							case "tool_call": {
+								const log = logger.child({ ctx: "Task.tool_call", taskId: this.taskId })
+								log.debug("Received native tool call chunk", {
+									id: chunk.id,
+									name: chunk.name,
+									argumentsLength: chunk.arguments?.length || 0,
+								})
+
 								// Convert native tool call to ToolUse format
 								const toolUse = NativeToolCallParser.parseToolCall({
 									id: chunk.id,
@@ -2345,6 +2353,11 @@ export class Task extends EventEmitter<TaskEvents> implements TaskLike {
 								})
 
 								if (!toolUse) {
+									log.error("Failed to parse tool call", {
+										chunkId: chunk.id,
+										chunkName: chunk.name,
+										arguments: chunk.arguments,
+									})
 									console.error(`Failed to parse tool call for task ${this.taskId}:`, chunk)
 									break
 								}
@@ -2353,6 +2366,13 @@ export class Task extends EventEmitter<TaskEvents> implements TaskLike {
 								// This is needed to create tool_result blocks that reference the correct tool_use_id
 								toolUse.id = chunk.id
 
+								log.debug("Successfully parsed tool call, adding to assistant message content", {
+									toolName: toolUse.name,
+									toolId: toolUse.id,
+									hasNativeArgs: !!toolUse.nativeArgs,
+									contentLength: this.assistantMessageContent.length,
+								})
+
 								// Add the tool use to assistant message content
 								this.assistantMessageContent.push(toolUse)
 
@@ -2360,6 +2380,7 @@ export class Task extends EventEmitter<TaskEvents> implements TaskLike {
 								this.userMessageContentReady = false
 
 								// Present the tool call to user
+								log.debug("Presenting tool call to user via presentAssistantMessage")
 								presentAssistantMessage(this)
 								break
 							}
@@ -2772,6 +2793,12 @@ export class Task extends EventEmitter<TaskEvents> implements TaskLike {
 
 					// Add tool_use blocks with their IDs for native protocol
 					const toolUseBlocks = this.assistantMessageContent.filter((block) => block.type === "tool_use")
+					const log = logger.child({ ctx: "Task.buildAssistantContent", taskId: this.taskId })
+
+					log.debug("Processing tool use blocks for API history", {
+						toolUseCount: toolUseBlocks.length,
+					})
+
 					for (const toolUse of toolUseBlocks) {
 						// Get the tool call ID that was stored during parsing
 						const toolCallId = (toolUse as any).id
@@ -2779,12 +2806,23 @@ export class Task extends EventEmitter<TaskEvents> implements TaskLike {
 							// nativeArgs is already in the correct API format for all tools
 							const input = toolUse.nativeArgs || toolUse.params
 
+							log.debug("Adding tool_use to assistant content", {
+								toolName: toolUse.name,
+								toolId: toolCallId,
+								hasNativeArgs: !!toolUse.nativeArgs,
+								usingNativeArgs: !!toolUse.nativeArgs,
+							})
+
 							assistantContent.push({
 								type: "tool_use" as const,
 								id: toolCallId,
 								name: toolUse.name,
 								input,
 							})
+						} else {
+							log.warn("Tool use block missing ID (likely XML protocol)", {
+								toolName: toolUse.name,
+							})
 						}
 					}
 

src/core/tools/BaseTool.ts

@@ -8,6 +8,7 @@ import type {
 	NativeToolArgs,
 } from "../../shared/tools"
 import type { ToolName, ToolProtocol } from "@roo-code/types"
+import { logger } from "../../utils/logging"
 
 /**
  * Callbacks passed to tool execution
@@ -132,11 +133,24 @@ export abstract class BaseTool<TName extends ToolName> {
 	 * @param callbacks - Tool execution callbacks
 	 */
 	async handle(task: Task, block: ToolUse<TName>, callbacks: ToolCallbacks): Promise<void> {
+		const log = logger.child({ ctx: `BaseTool.${this.name}`, taskId: task.taskId })
+
+		log.debug("Tool handler invoked", {
+			isPartial: block.partial,
+			hasNativeArgs: !!block.nativeArgs,
+			protocol: callbacks.toolProtocol,
+			blockId: (block as any).id,
+		})
+
 		// Handle partial messages
 		if (block.partial) {
 			try {
+				log.debug("Handling partial tool message")
 				await this.handlePartial(task, block)
 			} catch (error) {
+				log.error("Error in handlePartial", {
+					error: error instanceof Error ? error.message : String(error),
+				})
 				console.error(`Error in handlePartial:`, error)
 				await callbacks.handleError(
 					`handling partial ${this.name}`,
@@ -152,12 +166,23 @@ export abstract class BaseTool<TName extends ToolName> {
 			if (block.nativeArgs !== undefined) {
 				// Native protocol: typed args provided by NativeToolCallParser
 				// TypeScript knows nativeArgs is properly typed based on TName
+				log.debug("Using native args (native protocol)", {
+					argKeys: typeof block.nativeArgs === "object" ? Object.keys(block.nativeArgs) : [],
+				})
 				params = block.nativeArgs as ToolParams<TName>
 			} else {
 				// XML/legacy protocol: parse string params into typed params
+				log.debug("Parsing legacy params (XML protocol)", {
+					paramKeys: Object.keys(block.params),
+				})
 				params = this.parseLegacy(block.params)
 			}
 		} catch (error) {
+			log.error("Failed to parse tool parameters", {
+				error: error instanceof Error ? error.message : String(error),
+				hasNativeArgs: !!block.nativeArgs,
+				params: block.params,
+			})
 			console.error(`Error parsing parameters:`, error)
 			const errorMessage = `Failed to parse ${this.name} parameters: ${error instanceof Error ? error.message : String(error)}`
 			await callbacks.handleError(`parsing ${this.name} args`, new Error(errorMessage))
@@ -166,6 +191,15 @@ export abstract class BaseTool<TName extends ToolName> {
 		}
 
 		// Execute with typed parameters
-		await this.execute(params, task, callbacks)
+		log.debug("Executing tool with parsed parameters")
+		try {
+			await this.execute(params, task, callbacks)
+			log.debug("Tool execution completed successfully")
+		} catch (error) {
+			log.error("Tool execution failed", {
+				error: error instanceof Error ? error.message : String(error),
+			})
+			throw error
+		}
 	}
 }

src/utils/logging/index.ts

@@ -1,12 +1,13 @@
 /**
  * @fileoverview Main entry point for the compact logging system
- * Provides a default logger instance with Jest environment detection
+ * Provides a default logger instance with environment-based configuration
  */
 
 import { CompactLogger } from "./CompactLogger"
+import { CompactTransport } from "./CompactTransport"
 
 /**
- * No-operation logger implementation for production environments
+ * No-operation logger implementation for environments where logging is disabled
  */
 const noopLogger = {
 	debug: () => {},
@@ -19,7 +20,32 @@ const noopLogger = {
 }
 
 /**
- * Default logger instance
- * Uses CompactLogger for normal operation, switches to noop logger in Jest test environment
+ * Create logger instance based on environment and configuration
+ * - Test environment: Uses CompactLogger for test visibility
+ * - Production: Uses CompactLogger with configurable log level
+ * - Can be disabled via ROO_DEBUG_LOGGING environment variable
  */
-export const logger = process.env.NODE_ENV === "test" ? new CompactLogger() : noopLogger
+function createLogger() {
+	// Always use CompactLogger in test environment
+	if (process.env.NODE_ENV === "test") {
+		return new CompactLogger()
+	}
+
+	// Check if debug logging is explicitly disabled
+	if (process.env.ROO_DEBUG_LOGGING === "false") {
+		return noopLogger
+	}
+
+	// Create logger with configurable level (default to 'info')
+	const logLevel = process.env.ROO_LOG_LEVEL || "info"
+	const transport = new CompactTransport({ level: logLevel as any })
+	return new CompactLogger(transport)
+}
+
+/**
+ * Default logger instance
+ * Configured based on environment variables:
+ * - ROO_DEBUG_LOGGING: Set to "false" to disable all logging
+ * - ROO_LOG_LEVEL: Set to "debug", "info", "warn", "error", or "fatal" (default: "info")
+ */
+export const logger = createLogger()