diff --git a/src/core/assistant-message/NativeToolCallParser.ts b/src/core/assistant-message/NativeToolCallParser.ts index c463d4a5cd..fa1ce9589a 100644 --- 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 { 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 | 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 | 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> = {} @@ -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> = { 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 } diff --git a/src/core/assistant-message/presentAssistantMessage.ts b/src/core/assistant-message/presentAssistantMessage.ts index 3282eb90d1..2c65e96986 100644 --- a/src/core/assistant-message/presentAssistantMessage.ts +++ b/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 diff --git a/src/core/task/Task.ts b/src/core/task/Task.ts index 6c17e20121..115b148631 100644 --- a/src/core/task/Task.ts +++ b/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 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 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 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 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 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 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, + }) } } diff --git a/src/core/tools/BaseTool.ts b/src/core/tools/BaseTool.ts index e960b2541f..7ae62c71bb 100644 --- a/src/core/tools/BaseTool.ts +++ b/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 { * @param callbacks - Tool execution callbacks */ async handle(task: Task, block: ToolUse, callbacks: ToolCallbacks): Promise { + 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 { 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 } 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 { } // 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 + } } } diff --git a/src/utils/logging/index.ts b/src/utils/logging/index.ts index 76a4629d24..074f412cdc 100644 --- a/src/utils/logging/index.ts +++ b/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()