From 6452a67ce2696bc39a321aabab9a2f03b6058f4c Mon Sep 17 00:00:00 2001 From: JF Date: Fri, 21 Aug 2026 22:48:07 -0400 Subject: [PATCH] perf(observability): opt-in DAP trace + proxy logger honors effective log level Two always-on observability defaults made every debug session pay for diagnostics almost nobody reads (issue #403): - Per-frame DAP tracing (synchronous appendFileSync of every frame, both directions, uncapped) is now opt-in: DAP_TRACE=1 enables the standard per-session dap-trace-.ndjson, an explicit DAP_TRACE_FILE is honored as-is, default is off. When enabled the trace is capped at 50 MB (one truncation marker, then silence) matching the main logger's maxsize. Sync writes are retained deliberately: tracing is now an opt-in crash- triage tool, and a buffered queue would lose the final frames exactly when the process dies. - The per-session proxy-.log level is no longer hardcoded to 'debug': the effective level (CLI --log-level / DEBUG_MCP_LOG_LEVEL) rides the init payload (ProxyConfig.logLevel -> ProxyInitPayload.logLevel -> ILoggerFactory level param). Legacy parents that send no level keep the historical debug default. Stale session-run log sweeping is deferred to the #399 startup-janitor refactor (session logs live under os.tmpdir()/debug-mcp-server/sessions, out of reach of the flat logger sweeper). Co-Authored-By: Claude Fable 5 --- CLAUDE.md | 3 +- docs/development/setup-guide.md | 2 + src/proxy/dap-proxy-dependencies.ts | 8 ++- src/proxy/dap-proxy-interfaces.ts | 5 +- src/proxy/dap-proxy-worker.ts | 14 +++- src/proxy/minimal-dap.ts | 36 +++++++--- src/proxy/proxy-config.ts | 2 + src/proxy/proxy-manager.ts | 1 + src/session/session-manager-operations.ts | 5 ++ .../session/session-manager-workflow.test.ts | 14 ++++ tests/proxy/dap-proxy-worker.test.ts | 67 +++++++++++++++++++ .../unit/proxy/dap-proxy-dependencies.test.ts | 27 ++++++++ tests/unit/proxy/minimal-dap.test.ts | 25 +++++++ tests/unit/proxy/proxy-manager.start.test.ts | 11 +++ 14 files changed, 206 insertions(+), 14 deletions(-) diff --git a/CLAUDE.md b/CLAUDE.md index 4668ee9c..1dafd085 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -299,9 +299,10 @@ The project uses Vitest with three test levels: When debugging issues: 1. Enable debug logging: `DEBUG=debug-mcp:* node dist/index.js` -2. Check proxy process output in logs +2. Check proxy process output in logs (the per-session `proxy-.log` follows the server's `--log-level`/`DEBUG_MCP_LOG_LEVEL`) 3. Verify language-specific requirements (e.g., `python -m debugpy --version`) 4. Use `dryRunSpawn: true` in `start_debugging` tool arguments to test configuration without starting a real debug session +5. Set `DAP_TRACE=1` to capture every DAP frame to a per-session `dap-trace-.ndjson` (off by default; capped at 50 MB; `DAP_TRACE_FILE=` chooses an explicit file) ## Adding New Language Adapters diff --git a/docs/development/setup-guide.md b/docs/development/setup-guide.md index e6696ff2..0d981581 100644 --- a/docs/development/setup-guide.md +++ b/docs/development/setup-guide.md @@ -312,6 +312,8 @@ TEST_TIMEOUT=30000 | `NETCOREDBG_PATH` | Path to netcoredbg (.NET) | Auto-detected | | `JAVA_HOME` | Path to JDK installation (Java) | Auto-detected | | `DEBUG` | Enable debug output (e.g., `DEBUG=debug-mcp:*`) | Not set | +| `DAP_TRACE` | Set to `1` to trace every DAP frame to a per-session `dap-trace-.ndjson` (capped at 50 MB) | Not set | +| `DAP_TRACE_FILE` | Explicit DAP trace file path (implies tracing on) | Not set | ## Troubleshooting Setup Issues diff --git a/src/proxy/dap-proxy-dependencies.ts b/src/proxy/dap-proxy-dependencies.ts index 11f75500..7a59ecb3 100644 --- a/src/proxy/dap-proxy-dependencies.ts +++ b/src/proxy/dap-proxy-dependencies.ts @@ -24,11 +24,13 @@ import type { ProcessLike } from '../interfaces/process-interfaces.js'; export function createProductionDependencies( proc: Pick = process ): DapProxyDependencies { - // Logger factory for delayed initialization - const loggerFactory: ILoggerFactory = async (sessionId: string, logDir: string) => { + // Logger factory for delayed initialization. The level comes from the init + // payload (CLI --log-level / DEBUG_MCP_LOG_LEVEL, issue #403); legacy parents + // that send no level keep the historical 'debug'. + const loggerFactory: ILoggerFactory = async (sessionId: string, logDir: string, level?: string) => { const logPath = path.join(logDir, `proxy-${sessionId}.log`); return createLogger(`dap-proxy:${sessionId}`, { - level: 'debug', + level: level ?? 'debug', file: logPath }); }; diff --git a/src/proxy/dap-proxy-interfaces.ts b/src/proxy/dap-proxy-interfaces.ts index 6abb93f6..9d9257d7 100644 --- a/src/proxy/dap-proxy-interfaces.ts +++ b/src/proxy/dap-proxy-interfaces.ts @@ -28,6 +28,9 @@ export interface ProxyInitPayload { initialBreakpoints?: { file: string; line: number; condition?: string; logMessage?: string; suspendPolicy?: 'all' | 'thread' }[]; initialFunctionBreakpoints?: { name: string; condition?: string }[]; dryRunSpawn?: boolean; + /** Effective log level for the per-session proxy logger; absent on legacy + * payloads, where the worker keeps its historical 'debug' default (issue #403) */ + logLevel?: string; /** Abstract break-on-exception mode; resolved to concrete DAP filters via the adapter policy (issue #220) */ breakOnExceptions?: 'uncaught' | 'all' | 'none'; launchConfig?: LanguageSpecificLaunchConfig; @@ -200,7 +203,7 @@ export interface IMessageSender { * Logger factory for delayed initialization */ export interface ILoggerFactory { - (sessionId: string, logDir: string): Promise; + (sessionId: string, logDir: string, level?: string): Promise; } // ===== Configuration Types ===== diff --git a/src/proxy/dap-proxy-worker.ts b/src/proxy/dap-proxy-worker.ts index bf8f67f4..19193424 100644 --- a/src/proxy/dap-proxy-worker.ts +++ b/src/proxy/dap-proxy-worker.ts @@ -140,7 +140,19 @@ export class DapProxyWorker { process.exit(code); }); + // Per-frame DAP tracing is opt-in (issue #403): every frame is written + // synchronously to an uncapped ndjson file, so it must never be the + // default. DAP_TRACE=1 enables it with the standard per-session path; an + // explicit DAP_TRACE_FILE (inherited via the spawn env) is honored as-is. this.traceFileFactory = hooks.createTraceFile ?? ((sessionId: string, logDir: string) => { + const explicit = process.env.DAP_TRACE_FILE; + if (explicit) { + return explicit; + } + const flag = (process.env.DAP_TRACE ?? '').toLowerCase(); + if (flag !== '1' && flag !== 'true') { + return undefined; + } const tracePath = path.join(logDir, `dap-trace-${sessionId}.ndjson`); process.env.DAP_TRACE_FILE = tracePath; return tracePath; @@ -281,7 +293,7 @@ export class DapProxyWorker { // Create logger const logPath = path.join(payload.logDir, `proxy-${payload.sessionId}.log`); await this.dependencies.fileSystem.ensureDir(path.dirname(logPath)); - this.logger = await this.dependencies.loggerFactory(payload.sessionId, payload.logDir); + this.logger = await this.dependencies.loggerFactory(payload.sessionId, payload.logDir, payload.logLevel); this.logger.info(`[Worker] DAP Proxy worker initialized for session ${payload.sessionId}`); this.logger.info(`[Worker] Using adapter policy: ${this.adapterPolicy.name}`); diff --git a/src/proxy/minimal-dap.ts b/src/proxy/minimal-dap.ts index 59bff77d..34ad1b2b 100644 --- a/src/proxy/minimal-dap.ts +++ b/src/proxy/minimal-dap.ts @@ -29,8 +29,13 @@ type MinimalDapClientOptions = { setTimeout: typeof setTimeout; clearTimeout: typeof clearTimeout; }; + /** Byte cap for the opt-in DAP trace file; injectable for tests (issue #403) */ + traceMaxBytes?: number; }; +/** Trace cap consistent with the main logger's maxsize (issue #403). */ +const DEFAULT_TRACE_MAX_BYTES = 50 * 1024 * 1024; + export class MinimalDapClient extends EventEmitter { private socket: Socket | null = null; private decoder = new DapFrameDecoder({ @@ -52,6 +57,9 @@ export class MinimalDapClient extends EventEmitter { private host: string; private port: number; private traceFile?: string = process.env.DAP_TRACE_FILE; + private traceMaxBytes: number = DEFAULT_TRACE_MAX_BYTES; + private traceBytesWritten = 0; + private traceTruncated = false; private adoptedTargets = new Set(); private childSessions = new Map(); private activeChild: MinimalDapClient | null = null; @@ -81,6 +89,7 @@ export class MinimalDapClient extends EventEmitter { setTimeout, clearTimeout }; + this.traceMaxBytes = options?.traceMaxBytes ?? DEFAULT_TRACE_MAX_BYTES; // Initialize ChildSessionManager for policies that support child sessions if (this.policy.supportsReverseStartDebugging) { const createChildSessionManager = @@ -291,15 +300,26 @@ export class MinimalDapClient extends EventEmitter { } private appendTrace(direction: 'in' | 'out', payload: unknown): void { - if (!this.traceFile) return; + if (!this.traceFile || this.traceTruncated) return; try { - fs.appendFileSync( - this.traceFile, - // env objects are redacted: the trace file persists next to the logs - // and the launch request embeds the debuggee's full environment - JSON.stringify({ ts: new Date().toISOString(), direction, payload: sanitizePayloadForLogging(payload) }) + '\n', - 'utf8' - ); + // env objects are redacted: the trace file persists next to the logs + // and the launch request embeds the debuggee's full environment + const line = + JSON.stringify({ ts: new Date().toISOString(), direction, payload: sanitizePayloadForLogging(payload) }) + '\n'; + const lineBytes = Buffer.byteLength(line, 'utf8'); + if (this.traceBytesWritten + lineBytes > this.traceMaxBytes) { + // One marker, then stop for the client's lifetime — the trace must + // never grow without bound (issue #403). + this.traceTruncated = true; + fs.appendFileSync( + this.traceFile, + JSON.stringify({ ts: new Date().toISOString(), truncated: true, reason: `trace byte cap ${this.traceMaxBytes} reached` }) + '\n', + 'utf8' + ); + return; + } + fs.appendFileSync(this.traceFile, line, 'utf8'); + this.traceBytesWritten += lineBytes; } catch { // ignore trace errors } diff --git a/src/proxy/proxy-config.ts b/src/proxy/proxy-config.ts index 5f14fdf5..1d9f78d1 100644 --- a/src/proxy/proxy-config.ts +++ b/src/proxy/proxy-config.ts @@ -20,6 +20,8 @@ export interface ProxyConfig { initialBreakpoints?: Array<{ file: string; line: number; condition?: string; logMessage?: string; suspendPolicy?: 'all' | 'thread' }>; initialFunctionBreakpoints?: Array<{ name: string; condition?: string }>; dryRunSpawn?: boolean; + /** Effective log level for the per-session proxy logger (issue #403) */ + logLevel?: string; breakOnExceptions?: ExceptionBreakMode; launchConfig?: LanguageSpecificLaunchConfig; attachMode?: boolean; // True for attach sessions; direct-connect attach skips local toolchain probing diff --git a/src/proxy/proxy-manager.ts b/src/proxy/proxy-manager.ts index b7214178..37c6fc49 100644 --- a/src/proxy/proxy-manager.ts +++ b/src/proxy/proxy-manager.ts @@ -239,6 +239,7 @@ export class ProxyManager extends EventEmitter implements IProxyManager { initialBreakpoints: config.initialBreakpoints, initialFunctionBreakpoints: config.initialFunctionBreakpoints, dryRunSpawn: config.dryRunSpawn, + logLevel: config.logLevel, breakOnExceptions: config.breakOnExceptions, launchConfig: config.launchConfig, // Pass adapter command info for language-agnostic adapter spawning diff --git a/src/session/session-manager-operations.ts b/src/session/session-manager-operations.ts index efa06831..885c2f15 100644 --- a/src/session/session-manager-operations.ts +++ b/src/session/session-manager-operations.ts @@ -424,6 +424,11 @@ export abstract class SessionManagerOperations extends SessionManagerData { initialBreakpoints, initialFunctionBreakpoints, dryRunSpawn: dryRunSpawn === true, + // ILogger doesn't declare level, but the injected logger is the winston + // instance whose level already resolves CLI --log-level and + // DEBUG_MCP_LOG_LEVEL (issue #403); mocks without it fall back to the + // worker's legacy default. + logLevel: (this.logger as { level?: string }).level, breakOnExceptions, launchConfig: launchConfigData, adapterCommand, // Pass the adapter command diff --git a/tests/core/unit/session/session-manager-workflow.test.ts b/tests/core/unit/session/session-manager-workflow.test.ts index 91d4bac1..6f52f0e4 100644 --- a/tests/core/unit/session/session-manager-workflow.test.ts +++ b/tests/core/unit/session/session-manager-workflow.test.ts @@ -113,6 +113,20 @@ describe('SessionManager - Debug Session Workflow', () => { expect(dependencies.mockProxyManager.startCalls[0].dryRunSpawn).toBe(true); }); + it('propagates the effective log level into the proxy config (issue #403)', async () => { + (dependencies.mockLogger as { level?: string }).level = 'warn'; + const session = await sessionManager.createSession({ + language: DebugLanguage.MOCK, + pythonPath: 'python' + }); + + const startPromise = sessionManager.startDebugging(session.id, 'test.py', [], {}, true); + await vi.runAllTimersAsync(); + await startPromise; + + expect(dependencies.mockProxyManager.startCalls[0].logLevel).toBe('warn'); + }); + it('should handle stopOnEntry=false workflow', async () => { const session = await sessionManager.createSession({ language: DebugLanguage.MOCK, diff --git a/tests/proxy/dap-proxy-worker.test.ts b/tests/proxy/dap-proxy-worker.test.ts index 63eb807f..dce15dad 100644 --- a/tests/proxy/dap-proxy-worker.test.ts +++ b/tests/proxy/dap-proxy-worker.test.ts @@ -453,6 +453,73 @@ describe('DapProxyWorker', () => { vi.useRealTimers(); }); + it('default trace factory leaves tracing off when DAP_TRACE is not set (issue #403)', async () => { + vi.useFakeTimers(); + vi.stubEnv('DAP_TRACE', ''); + vi.stubEnv('DAP_TRACE_FILE', ''); + try { + worker = new DapProxyWorker(dependencies, { exit: vi.fn() }); + await worker.handleCommand(basePayload); + vi.clearAllTimers(); + + expect(process.env.DAP_TRACE_FILE || '').toBe(''); + } finally { + vi.unstubAllEnvs(); + vi.useRealTimers(); + } + }); + + it('default trace factory enables tracing when DAP_TRACE=1 (issue #403)', async () => { + vi.useFakeTimers(); + vi.stubEnv('DAP_TRACE', '1'); + vi.stubEnv('DAP_TRACE_FILE', ''); + try { + worker = new DapProxyWorker(dependencies, { exit: vi.fn() }); + await worker.handleCommand(basePayload); + vi.clearAllTimers(); + + expect(process.env.DAP_TRACE_FILE).toBe( + path.join(basePayload.logDir, `dap-trace-${basePayload.sessionId}.ndjson`) + ); + } finally { + vi.unstubAllEnvs(); + vi.useRealTimers(); + } + }); + + it('default trace factory honors an explicit DAP_TRACE_FILE without renaming it (issue #403)', async () => { + vi.useFakeTimers(); + vi.stubEnv('DAP_TRACE', ''); + vi.stubEnv('DAP_TRACE_FILE', '/tmp/explicit-trace.ndjson'); + try { + worker = new DapProxyWorker(dependencies, { exit: vi.fn() }); + await worker.handleCommand(basePayload); + vi.clearAllTimers(); + + expect(process.env.DAP_TRACE_FILE).toBe('/tmp/explicit-trace.ndjson'); + } finally { + vi.unstubAllEnvs(); + vi.useRealTimers(); + } + }); + + it('passes the payload logLevel through to the logger factory (issue #403)', async () => { + vi.useFakeTimers(); + try { + worker = new DapProxyWorker(dependencies, { exit: vi.fn() }); + await worker.handleCommand({ ...basePayload, logLevel: 'info' }); + vi.clearAllTimers(); + + expect(dependencies.loggerFactory).toHaveBeenCalledWith( + basePayload.sessionId, + basePayload.logDir, + 'info' + ); + } finally { + vi.useRealTimers(); + } + }); + it('invokes custom exit hook when initialization fails critically', async () => { vi.useFakeTimers(); diff --git a/tests/unit/proxy/dap-proxy-dependencies.test.ts b/tests/unit/proxy/dap-proxy-dependencies.test.ts index 1a65c282..41f34788 100644 --- a/tests/unit/proxy/dap-proxy-dependencies.test.ts +++ b/tests/unit/proxy/dap-proxy-dependencies.test.ts @@ -11,8 +11,15 @@ import { createProductionDependencies, createConsoleLogger } from '../../../src/proxy/dap-proxy-dependencies.js'; +import { createLogger } from '../../../src/utils/logger.js'; import { FakeCurrentProcess } from '../../test-utils/mocks/fake-current-process.js'; +vi.mock('../../../src/utils/logger.js', () => ({ + createLogger: vi.fn().mockReturnValue({ + info: vi.fn(), warn: vi.fn(), error: vi.fn(), debug: vi.fn() + }) +})); + /* ------------------------------------------------------------------ */ /* createProductionDependencies */ /* ------------------------------------------------------------------ */ @@ -32,6 +39,26 @@ describe('createProductionDependencies', () => { expect(typeof deps.loggerFactory).toBe('function'); }); + it('loggerFactory passes the requested level through to createLogger (issue #403)', async () => { + const deps = createProductionDependencies(); + await deps.loggerFactory('sess-1', '/logs', 'info'); + + expect(vi.mocked(createLogger)).toHaveBeenCalledWith( + 'dap-proxy:sess-1', + expect.objectContaining({ level: 'info' }) + ); + }); + + it('loggerFactory keeps the legacy debug level when no level is given', async () => { + const deps = createProductionDependencies(); + await deps.loggerFactory('sess-2', '/logs'); + + expect(vi.mocked(createLogger)).toHaveBeenCalledWith( + 'dap-proxy:sess-2', + expect.objectContaining({ level: 'debug' }) + ); + }); + it('fileSystem has ensureDir and pathExists', () => { const deps = createProductionDependencies(); expect(typeof deps.fileSystem.ensureDir).toBe('function'); diff --git a/tests/unit/proxy/minimal-dap.test.ts b/tests/unit/proxy/minimal-dap.test.ts index 18780dbe..0576f869 100644 --- a/tests/unit/proxy/minimal-dap.test.ts +++ b/tests/unit/proxy/minimal-dap.test.ts @@ -1746,6 +1746,31 @@ describe('MinimalDapClient', () => { }); }); + describe('Trace file byte cap (issue #403)', () => { + it('stops writing after the cap and records a single truncation marker', () => { + vi.stubEnv('DAP_TRACE_FILE', 'trace.ndjson'); + const appended: string[] = []; + const appendSpy = vi.spyOn(fs, 'appendFileSync').mockImplementation((_path, data) => { + appended.push(String(data)); + }); + try { + const client = new MinimalDapClient('localhost', 5678, undefined, { traceMaxBytes: 150 }); + + (client as any).appendTrace('out', { small: 'first' }); // fits under the cap + (client as any).appendTrace('out', { small: 'second' }); // would exceed → marker + (client as any).appendTrace('out', { small: 'third' }); // silently dropped + + expect(appended).toHaveLength(2); + expect(appended[0]).toContain('"small":"first"'); + expect(appended[1]).toContain('truncated'); + expect(appended[1]).not.toContain('third'); + } finally { + appendSpy.mockRestore(); + vi.unstubAllEnvs(); + } + }); + }); + describe('Trace file error handling', () => { it('swallows fs.appendFileSync errors so requests still complete', async () => { vi.stubEnv('DAP_TRACE_FILE', 'trace.ndjson'); diff --git a/tests/unit/proxy/proxy-manager.start.test.ts b/tests/unit/proxy/proxy-manager.start.test.ts index 2920905c..9dad53ed 100644 --- a/tests/unit/proxy/proxy-manager.start.test.ts +++ b/tests/unit/proxy/proxy-manager.start.test.ts @@ -136,6 +136,17 @@ describe('ProxyManager.start', () => { ); }); + it('includes logLevel in the init command when set (issue #403)', async () => { + await proxyManager.start({ ...baseConfig, logLevel: 'info' }); + + expect(fakeProcess.sendCommand).toHaveBeenCalledWith( + expect.objectContaining({ + cmd: 'init', + logLevel: 'info' + }) + ); + }); + it('sends breakOnExceptions as undefined in the init command when not set', async () => { await proxyManager.start(baseConfig);