feat(cli): add detailed debug logging for CLI execution

- Add debugLog and errorLog utility functions with DEBUG env control - Add logging for tool availability check (TOOL_CHECK) - Add logging for command building (BUILD_CMD) - Add logging for process spawn (SPAWN, STDIN) - Add logging for process completion (CLOSE, STATUS) - Enhance error output with command details, exit code, and stderr - Add troubleshooting hints for common failures - Support DEBUG=true or CCW_DEBUG=true environment variables Closes #46 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-Authored-By: Claude Opus 4.5 <noreply@anthropic.com>
2026-02-05 01:50:27 +08:00 · 2025-12-29 23:17:39 +08:00
parent 2c675ee4db
commit 6efc499c77
4 changed files with 174 additions and 9 deletions
--- a/ccw/src/commands/cli.ts
+++ b/ccw/src/commands/cli.ts
@@ -738,11 +738,39 @@ async function execAction(positionalPrompt: string | undefined, options: CliExec
    } else {
      console.log(chalk.red(`  ✗ Failed (${result.execution.status})`));
      console.log(chalk.gray(`  ID: ${result.execution.id}`));
+      console.log(chalk.gray(`  Duration: ${(result.execution.duration_ms / 1000).toFixed(1)}s`));
+      console.log(chalk.gray(`  Exit Code: ${result.execution.exit_code}`));
+
+      // Show stderr with better formatting
      if (result.stderr) {
-        console.error(chalk.red(result.stderr));
+        console.log();
+        console.log(chalk.red.bold('  Error Output:'));
+        console.log(chalk.gray('  ' + '─'.repeat(60)));
+        // Indent stderr for better readability
+        const stderrLines = result.stderr.split('\n');
+        for (const line of stderrLines.slice(0, 30)) { // Limit to 30 lines
+          console.error(chalk.red(`  ${line}`));
+        }
+        if (stderrLines.length > 30) {
+          console.log(chalk.yellow(`  ... ${stderrLines.length - 30} more lines`));
+        }
+        console.log(chalk.gray('  ' + '─'.repeat(60)));
      }

-      // Notify dashboard: execution failccw cli -p
+      // Show troubleshooting hints
+      console.log();
+      console.log(chalk.yellow.bold('  Troubleshooting:'));
+      console.log(chalk.gray(`    • Check if ${tool} is properly installed: ccw cli status`));
+      console.log(chalk.gray(`    • Enable debug mode: DEBUG=true ccw cli -p "..."  or  set DEBUG=true && ccw cli -p "..."`));
+      console.log(chalk.gray(`    • View full output: ccw cli output ${result.execution.id}`));
+      if (result.stderr?.includes('API key') || result.stderr?.includes('Authentication')) {
+        console.log(chalk.gray(`    • Check API key configuration for ${tool}`));
+      }
+      if (result.stderr?.includes('rate limit')) {
+        console.log(chalk.gray(`    • Wait and retry - rate limit exceeded`));
+      }
+
+      // Notify dashboard: execution failed
      notifyDashboard({
        event: 'completed',
        tool,
@@ -757,7 +785,23 @@ async function execAction(positionalPrompt: string | undefined, options: CliExec
    }
  } catch (error) {
    const err = error as Error;
-    console.error(chalk.red(`  Error: ${err.message}`));
+    console.error(chalk.red.bold(`\n  ✗ Execution Error\n`));
+    console.error(chalk.red(`  ${err.message}`));
+
+    // Parse error message for additional context
+    if (err.message.includes('Failed to spawn')) {
+      console.log();
+      console.log(chalk.yellow.bold('  Troubleshooting:'));
+      console.log(chalk.gray(`    • Check if ${tool} is installed: npm ls -g @google/gemini-cli (or qwen/codex)`));
+      console.log(chalk.gray(`    • Verify PATH includes npm global bin directory`));
+      console.log(chalk.gray(`    • Run: ccw cli status`));
+      console.log(chalk.gray(`    • Enable debug mode: DEBUG=true ccw cli -p "..."`));
+    } else if (err.message.includes('not available')) {
+      console.log();
+      console.log(chalk.yellow.bold('  Troubleshooting:'));
+      console.log(chalk.gray(`    • Install the tool: npm install -g <package-name>`));
+      console.log(chalk.gray(`    • Run: ccw cli status`));
+    }

    // Notify dashboard: execution error
    notifyDashboard({
--- a/ccw/src/tools/cli-executor.ts
+++ b/ccw/src/tools/cli-executor.ts
@@ -10,6 +10,37 @@ import { spawn, ChildProcess } from 'child_process';
 import { existsSync, mkdirSync, readFileSync, writeFileSync, unlinkSync, readdirSync, statSync } from 'fs';
 import { join, relative } from 'path';

+// Debug logging utility
+const DEBUG = process.env.DEBUG === 'true' || process.env.DEBUG === '1' || process.env.CCW_DEBUG === 'true';
+
+function debugLog(category: string, message: string, data?: Record<string, unknown>): void {
+  if (!DEBUG) return;
+  const timestamp = new Date().toISOString();
+  const prefix = `[${timestamp}] [CLI-DEBUG] [${category}]`;
+  if (data) {
+    console.error(`${prefix} ${message}`, JSON.stringify(data, null, 2));
+  } else {
+    console.error(`${prefix} ${message}`);
+  }
+}
+
+function errorLog(category: string, message: string, error?: Error | unknown, context?: Record<string, unknown>): void {
+  const timestamp = new Date().toISOString();
+  const prefix = `[${timestamp}] [CLI-ERROR] [${category}]`;
+  console.error(`${prefix} ${message}`);
+  if (error instanceof Error) {
+    console.error(`${prefix} Error: ${error.message}`);
+    if (DEBUG && error.stack) {
+      console.error(`${prefix} Stack: ${error.stack}`);
+    }
+  } else if (error) {
+    console.error(`${prefix} Error: ${String(error)}`);
+  }
+  if (context) {
+    console.error(`${prefix} Context:`, JSON.stringify(context, null, 2));
+  }
+}
+
 // LiteLLM integration
 import { executeLiteLLMEndpoint } from './litellm-executor.js';
 import { findEndpointById } from '../config/litellm-api-config-manager.js';
@@ -205,9 +236,12 @@ interface ExecutionOutput {
 * Check if a CLI tool is available (with caching)
 */
 async function checkToolAvailability(tool: string): Promise<ToolAvailability> {
+  debugLog('TOOL_CHECK', `Checking availability for tool: ${tool}`);
+
  // Check cache first
  const cached = toolAvailabilityCache.get(tool);
  if (cached && isCacheValid(cached)) {
+    debugLog('TOOL_CHECK', `Cache hit for ${tool}`, { available: cached.result.available, path: cached.result.path });
    return cached.result;
  }

@@ -219,6 +253,8 @@ async function checkToolAvailability(tool: string): Promise<ToolAvailability> {
    const isWindows = process.platform === 'win32';
    const command = isWindows ? 'where' : 'which';

+    debugLog('TOOL_CHECK', `Running ${command} ${tool}`, { platform: process.platform });
+
    // Direct spawn - where/which are system commands that don't need shell wrapper
    const child = spawn(command, [tool], {
      shell: false,
@@ -226,25 +262,31 @@ async function checkToolAvailability(tool: string): Promise<ToolAvailability> {
    });

    let stdout = '';
+    let stderr = '';
    child.stdout!.on('data', (data) => { stdout += data.toString(); });
+    child.stderr?.on('data', (data) => { stderr += data.toString(); });

    child.on('close', (code) => {
      const result: ToolAvailability = code === 0 && stdout.trim()
        ? { available: true, path: stdout.trim().split('\n')[0] }
        : { available: false, path: null };

-      // Only cache positive results to avoid caching transient failures
      if (result.available) {
+        debugLog('TOOL_CHECK', `Tool ${tool} found`, { path: result.path });
+        // Only cache positive results to avoid caching transient failures
        toolAvailabilityCache.set(tool, {
          result,
          timestamp: Date.now()
        });
+      } else {
+        debugLog('TOOL_CHECK', `Tool ${tool} not found`, { exitCode: code, stderr: stderr.trim() || '(empty)' });
      }

      resolve(result);
    });

-    child.on('error', () => {
+    child.on('error', (error) => {
+      errorLog('TOOL_CHECK', `Failed to check tool availability: ${tool}`, error, { command, tool });
      // Don't cache errors - they may be transient
      resolve({ available: false, path: null });
    });
@@ -252,6 +294,7 @@ async function checkToolAvailability(tool: string): Promise<ToolAvailability> {
    // Timeout after 5 seconds
    setTimeout(() => {
      child.kill();
+      debugLog('TOOL_CHECK', `Timeout checking tool ${tool} (5s)`);
      // Don't cache timeouts - they may be transient
      resolve({ available: false, path: null });
    }, 5000);
@@ -279,6 +322,15 @@ function buildCommand(params: {
 }): { command: string; args: string[]; useStdin: boolean } {
  const { tool, prompt, mode = 'analysis', model, dir, include, nativeResume } = params;

+  debugLog('BUILD_CMD', `Building command for tool: ${tool}`, {
+    mode,
+    model: model || '(default)',
+    dir: dir || '(cwd)',
+    include: include || '(none)',
+    nativeResume: nativeResume ? { enabled: nativeResume.enabled, isLatest: nativeResume.isLatest, sessionId: nativeResume.sessionId } : '(none)',
+    promptLength: prompt.length
+  });
+
  let command = tool;
  let args: string[] = [];
  // Default to stdin for all tools to avoid escaping issues on Windows
@@ -418,9 +470,17 @@ function buildCommand(params: {
      break;

    default:
+      errorLog('BUILD_CMD', `Unknown CLI tool: ${tool}`);
      throw new Error(`Unknown CLI tool: ${tool}`);
  }

+  debugLog('BUILD_CMD', `Command built successfully`, {
+    command,
+    args,
+    useStdin,
+    fullCommand: `${command} ${args.join(' ')}${useStdin ? ' (stdin)' : ''}`
+  });
+
  return { command, args, useStdin };
 }

@@ -821,18 +881,42 @@ async function executeCliTool(

  const startTime = Date.now();

+  debugLog('EXEC', `Starting CLI execution`, {
+    tool,
+    mode,
+    workingDir,
+    conversationId,
+    promptLength: finalPrompt.length,
+    hasResume: !!resume,
+    hasCustomId: !!customId
+  });
+
  return new Promise((resolve, reject) => {
    // Windows requires shell: true for npm global commands (.cmd files)
    // Unix-like systems can use shell: false for direct execution
    const isWindows = process.platform === 'win32';
+
+    debugLog('SPAWN', `Spawning process`, {
+      command,
+      args,
+      cwd: workingDir,
+      shell: isWindows,
+      useStdin,
+      platform: process.platform,
+      fullCommand: `${command} ${args.join(' ')}`
+    });
+
    const child = spawn(command, args, {
      cwd: workingDir,
      shell: isWindows,  // Enable shell on Windows for .cmd files
      stdio: [useStdin ? 'pipe' : 'ignore', 'pipe', 'pipe']
    });

+    debugLog('SPAWN', `Process spawned`, { pid: child.pid });
+
    // Write prompt to stdin if using stdin mode (for gemini/qwen)
    if (useStdin && child.stdin) {
+      debugLog('STDIN', `Writing prompt to stdin (${finalPrompt.length} bytes)`);
      child.stdin.write(finalPrompt);
      child.stdin.end();
    }
@@ -864,10 +948,19 @@ async function executeCliTool(
      const endTime = Date.now();
      const duration = endTime - startTime;

+      debugLog('CLOSE', `Process closed`, {
+        exitCode: code,
+        duration: `${duration}ms`,
+        timedOut,
+        stdoutLength: stdout.length,
+        stderrLength: stderr.length
+      });
+
      // Determine status - prioritize output content over exit code
      let status: 'success' | 'error' | 'timeout' = 'success';
      if (timedOut) {
        status = 'timeout';
+        debugLog('STATUS', `Execution timed out after ${duration}ms`);
      } else if (code !== 0) {
        // Non-zero exit code doesn't always mean failure
        // Check if there's valid output (AI response) - treat as success
@@ -877,12 +970,31 @@ async function executeCliTool(
                              stderr.includes('API key') ||
                              stderr.includes('rate limit exceeded');

+        debugLog('STATUS', `Non-zero exit code analysis`, {
+          exitCode: code,
+          hasValidOutput,
+          hasFatalError,
+          stderrPreview: stderr.substring(0, 500)
+        });
+
        if (hasValidOutput && !hasFatalError) {
          // Has output and no fatal errors - treat as success despite exit code
          status = 'success';
+          debugLog('STATUS', `Treating as success (has valid output, no fatal errors)`);
        } else {
          status = 'error';
+          errorLog('EXEC', `CLI execution failed`, undefined, {
+            exitCode: code,
+            tool,
+            command,
+            args,
+            workingDir,
+            stderrFull: stderr,
+            stdoutPreview: stdout.substring(0, 200)
+          });
        }
+      } else {
+        debugLog('STATUS', `Execution successful (exit code 0)`);
      }

      // Create new turn - cache full output when not streaming (default)
@@ -1066,7 +1178,16 @@ async function executeCliTool(

    // Handle errors
    child.on('error', (error) => {
-      reject(new Error(`Failed to spawn ${tool}: ${error.message}`));
+      errorLog('SPAWN', `Failed to spawn process`, error, {
+        tool,
+        command,
+        args,
+        workingDir,
+        fullCommand: `${command} ${args.join(' ')}`,
+        platform: process.platform,
+        path: process.env.PATH?.split(process.platform === 'win32' ? ';' : ':').slice(0, 10).join('\n  ') + '...'
+      });
+      reject(new Error(`Failed to spawn ${tool}: ${error.message}\n  Command: ${command} ${args.join(' ')}\n  Working Dir: ${workingDir}`));
    });

    // Timeout handling (timeout=0 disables internal timeout, controlled by external caller)
--- a/package-lock.json
+++ b/package-lock.json
@@ -1,12 +1,12 @@
 {
  "name": "claude-code-workflow",
-  "version": "6.3.13",
+  "version": "6.3.15",
  "lockfileVersion": 3,
  "requires": true,
  "packages": {
    "": {
      "name": "claude-code-workflow",
-      "version": "6.3.13",
+      "version": "6.3.15",
      "license": "MIT",
      "dependencies": {
        "@modelcontextprotocol/sdk": "^1.0.4",
--- a/package.json
+++ b/package.json
@@ -1,6 +1,6 @@
 {
  "name": "claude-code-workflow",
-  "version": "6.3.14",
+  "version": "6.3.15",
  "description": "JSON-driven multi-agent development framework with intelligent CLI orchestration (Gemini/Qwen/Codex), context-first architecture, and automated workflow execution",
  "type": "module",
  "main": "ccw/src/index.js",