Skip to content

Latest commit

 

History

History
301 lines (246 loc) · 10.9 KB

File metadata and controls

301 lines (246 loc) · 10.9 KB

MCP Debugger Logging Format Specification

Overview

This document defines the structured logging format used by mcp-debugger for visualization purposes. Main server structured logs are written to debug-mcp-server-<pid>.log in JSON format for easy parsing by the Terminal UI visualizer. The default log file name is per-process (debug-mcp-server-<pid>.log) because multiple server processes sharing one rotating winston log file is unsupported and busy-spins on Windows (issue #121); stale per-pid files from dead processes are cleaned up automatically after 7 days. The default log directory is os.tmpdir()/debug-mcp-server/ — the same OS temp state tree the per-session logs use. (It was previously derived from the module location, <module-dir>/../../logs/, which resolved inside the package tree: packages/logs/ for the bundled CLI in a source checkout, and the consumer's node_modules for an installed CLI — issue #637.) In container mode (MCP_CONTAINER=true), the path is overridden to the fixed /app/logs/debug-mcp-server.log (a container runs a single server process). An explicit --log-file <path> is always honored verbatim. Note: only the main server log follows this structured JSON specification.

Per-session logs live elsewhere, in their own tree. Since #572 one launch attempt gets one directory: <sessionLogBase>/<sessionId>/run-<startedAt>/, holding proxy-<sessionId>.log, <sessionId>.log (adapter) and, when DAP_TRACE=1 is set, dap-trace-<sessionId>.ndjson. Every producer, reader and cleanup predicate derives those names from one module, src/proxy/session-log-layout.ts (sessionRunDirectoryFor, proxyLogPathFor, adapterLogPathFor, dapTracePathFor), so a diagnostic path cannot drift away from the file that was actually written. Read the proxy log without filesystem access through the debug://sessions/{id}/proxy-log MCP resource.

Log Entry Types

1. Tool Call Logs

tool:call

Logged when an MCP tool is invoked.

{
  "timestamp": "2025-01-06T16:15:00.123Z",
  "level": "info",
  "namespace": "debug-mcp:tools",
  "message": "tool:call",
  "tool": "set_breakpoint",
  "sessionId": "abc-123-def-456",
  "sessionName": "My Debug Session",
  "request": {
    "file": "path/to/file.py",
    "line": 42,
    "condition": "x > 10"
  },
}

tool:response

Logged when a tool handler completes without throwing. success mirrors the success boolean inside the tool's own response payload, so a handler that returns { "success": false } (e.g. a failed attach_to_process) is logged with success: false. Payloads that carry no boolean success field are logged as success: true.

{
  "timestamp": "2025-01-06T16:15:00.456Z",
  "level": "info",
  "namespace": "debug-mcp:tools",
  "message": "tool:response",
  "tool": "set_breakpoint",
  "sessionId": "abc-123-def-456",
  "sessionName": "My Debug Session",
  "success": true,
}

tool:error

Logged when a tool encounters an error.

{
  "timestamp": "2025-01-06T16:15:00.789Z",
  "level": "error",
  "namespace": "debug-mcp:tools",
  "message": "tool:error",
  "tool": "start_debugging",
  "sessionId": "abc-123-def-456",
  "sessionName": "My Debug Session",
  "error": "Failed to connect to debugger",
}

2. Debug State Logs

debug:state

Logged when the debugger state changes (paused, running, stopped).

{
  "timestamp": "2025-01-06T16:15:01.123Z",
  "level": "info",
  "namespace": "debug-mcp:state",
  "message": "debug:state",
  "event": "paused",
  "sessionId": "abc-123-def-456",
  "sessionName": "My Debug Session",
  "reason": "breakpoint",
  "location": {
    "file": "/workspace/src/main.py",
    "line": 42,
    "function": "process_data"
  },
  "threadId": 1,
}

State events include:

  • paused - Execution stopped (reasons: breakpoint, step, entry, exception)
  • running - Execution continuing
  • stopped - Debug session terminated

3. Breakpoint Logs

debug:breakpoint

Logged for breakpoint lifecycle events.

{
  "timestamp": "2025-01-06T16:15:02.123Z",
  "level": "info",
  "namespace": "debug-mcp:breakpoint",
  "message": "debug:breakpoint",
  "event": "verified",
  "sessionId": "abc-123-def-456",
  "sessionName": "My Debug Session",
  "breakpointId": "bp-1",
  "file": "/workspace/src/main.py",
  "line": 42,
  "verified": true,
}

Breakpoint events include:

  • set - Breakpoint requested
  • verified - Breakpoint confirmed by debugger
  • hit - Breakpoint triggered execution pause

4. Session Lifecycle Logs

session:created

Logged when a new debug session is created.

{
  "timestamp": "2025-01-06T16:14:50.123Z",
  "level": "info",
  "namespace": "debug-mcp:session",
  "message": "session:created",
  "sessionId": "abc-123-def-456",
  "sessionName": "My Debug Session",
  "language": "python",
  "executablePath": "/usr/bin/python3",
}

session:closed

Logged when a debug session is terminated.

{
  "timestamp": "2025-01-06T16:20:00.123Z",
  "level": "info",
  "namespace": "debug-mcp:session",
  "message": "session:closed",
  "sessionId": "abc-123-def-456",
  "sessionName": "My Debug Session",
  "duration": 310000,
}

5. Debug Output Logs

debug:output

Logged to capture stdout/stderr from the debugged program.

{
  "timestamp": "2025-01-06T16:15:04.123Z",
  "level": "info",
  "namespace": "debug-mcp:output",
  "message": "debug:output",
  "sessionId": "abc-123-def-456",
  "sessionName": "My Debug Session",
  "category": "stdout",
  "output": "Processing item 42...\n",
}

Field Definitions

Common Fields

  • timestamp (ISO 8601 string): Human-readable timestamp for display (e.g. "2025-01-06T16:15:00.123Z")
  • level: Log level (info, debug, error, warn)
  • namespace: Logger namespace for categorization
  • message: Log type identifier for parsing
  • sessionId: Unique session identifier (UUID)
  • sessionName: Human-readable session name

Note: Earlier versions of this spec showed a second timestamp field (Unix milliseconds) alongside the ISO 8601 string. In practice the JSON entries contain a single timestamp field in ISO 8601 format. Use Date.parse() or equivalent for sorting.

Tool-specific Fields

  • tool: Name of the MCP tool
  • request: Tool input parameters (sanitized)
  • response: Tool output data
  • error: Error message string

Debug-specific Fields

  • event: Type of debug event
  • reason: Reason for state change
  • location: Current execution location
  • threadId: Debug thread identifier
  • breakpointId: Unique breakpoint identifier
  • frameId: Stack frame identifier
  • variablesReference: DAP variable reference number
  • variables: Array of variable details

Data Truncation Rules

Truncation is applied in targeted locations rather than as a generic deep traversal:

  1. Variable values in get_variables logging: Individual variable value strings are truncated at 200 characters, and only the first 10 variables are included in the log entry.

  2. Request/Response objects: Targeted sanitization via sanitizePayloadForLogging:

    • adapterCommand.env is replaced wholesale with a count summary (e.g., <57 env vars redacted>) — env values are never logged, since keyword redaction cannot anticipate every secret-bearing key name (issue #146)
    • sanitizeEnvForLogging (for any direct use) redacts values whose key matches a sensitive pattern (e.g., api_key, secret, token, password, credential, auth, session_id, access_key, signing, private_key) or contains a sensitive token after splitting on delimiters and camelCase boundaries (pat, key, pwd, passwd, cred, bearer, oauth, jwt — catches GITHUB_PAT without redacting PATH)
    • Other request/response fields are not generically scrubbed; sanitization is intentionally targeted
  3. Proxy stderr in errors: stderr lines are sanitized at capture (sanitizeStderr redacts lines with sensitive key names like GITHUB_PAT=... or well-known secret value shapes like ghp_..., github_pat_..., sk-..., AKIA..., JWTs, PEM headers), the capture buffer is bounded to 100 lines, and the "Proxy exited during initialization" error embeds at most the last 10 lines (max 2000 chars)

There is no generic array truncation (e.g., "show first 5 items") applied across all log entries.

Parsing Guidelines for TUI

  1. Filtering: Use the message field to filter log types

    const toolCalls = logs.filter(log => log.message === 'tool:call');
    const stateChanges = logs.filter(log => log.message === 'debug:state');
  2. Chronological Ordering: Use the ISO 8601 timestamp string for ordering

    logs.sort((a, b) => Date.parse(a.timestamp) - Date.parse(b.timestamp));
  3. Session Grouping: Group logs by sessionId for multi-session support

    const sessionLogs = logs.reduce((acc, log) => {
      if (!acc[log.sessionId]) acc[log.sessionId] = [];
      acc[log.sessionId].push(log);
      return acc;
    }, {});
  4. Event Correlation: Match tool calls with responses

    const pendingCalls = new Map();
    logs.forEach(log => {
      if (log.message === 'tool:call') {
        pendingCalls.set(`${log.sessionId}-${log.tool}`, log);
      } else if (log.message === 'tool:response') {
        const call = pendingCalls.get(`${log.sessionId}-${log.tool}`);
        // Correlate call and response
      }
    });

Performance Considerations

  1. Log Levels:

    • Use info for user-facing events (tool calls, state changes)
    • Use debug for detailed internal data
    • Configure logger to appropriate level for production vs development
  2. Batching: Consider buffering logs for high-frequency events

  3. File Rotation: File rotation is already implemented: 50MB per file, 3 rotated files maximum (150MB total). The newest logs are always in the base filename (tailable: true).

Security Considerations

  1. No Secrets: Never log passwords, API keys, or tokens
  2. Path Awareness: Host mode requires absolute paths for file-based operations; relative paths are rejected by SimpleFileChecker. Logged paths reflect whatever the caller provided.
  3. PII Protection: Avoid logging personally identifiable information
  4. Input Validation: Sanitize user inputs before logging

Example Usage in Code

Note: The timestamp field in log output is auto-generated by Winston in ISO 8601 format. Do not pass a manual timestamp in the metadata object.

// Tool call logging
logger.info('tool:call', {
  tool: toolName,
  sessionId: args.sessionId,
  sessionName: session?.name,
  request: sanitizeRequest(args),   // src/server/tool-result.ts, called from tool-dispatch.ts
});

// State change logging
logger.info('debug:state', {
  event: 'paused',
  sessionId: sessionId,
  sessionName: session.name,
  reason: stopReason,
  location: {
    file: source.path,
    line: frame.line,
    function: frame.name
  },
  threadId: threadId,
});

Version History

  • v1.0.0 (2025-01-06): Initial specification for TUI visualization support