From 0efe03f1481f2246c6ca61bd6ca1b7d6fb85f67d Mon Sep 17 00:00:00 2001 From: JF Date: Tue, 20 Oct 2026 08:50:23 -0400 Subject: [PATCH 1/2] fix(proxy): the DAP connect window ends with the adapter's exit or the parent's deadline, and the worker's stdout pipe is drained (#963) `DapConnectionManager.connectWithRetry` was a fixed 60 attempts (~12.5 s) for every adapter, alive or dead, unrelated to the parent's 30 s init ceiling: an adapter that took longer to listen (rdbg on a loaded Windows runner, 2 of 5 CI runs on 2026-10-19) failed the launch with ECONNREFUSED while still booting. The parent's deadline now travels in the init payload (`initializationTimeoutMs`); in spawn mode the loop runs until the adapter process exits (an AbortSignal from its exit handler, the error quoting the exit and stderr tail) or 500 ms past the parent's deadline, whose stage-aware message is the one a slow boot gets. Connect mode and legacy payloads keep the historical window as the default; the cadence is unchanged. Found by the new 14 s integration case: `ProxyManager` spawned the worker with a piped stdout it never read. Outside the server CLI (which silences console output) the worker's console transport filled the 64 KB pipe and the worker blocked solid, deaf to IPC. The parent now drains stdout like stderr, logged at debug and sanitized. The stdio-client test suites log to logs/tests/stdio/, so their proxy logs reach the Windows CI diagnostics artifact. Co-Authored-By: Claude Fable 5.1 Claude-Session: https://claude.ai/code/session_01Y3ULnoVSoCZ5t2Y8d98Ctv --- changelog.d/963.fixed.md | 1 + docs/logging-format-specification.md | 2 + docs/patterns/event-management.md | 8 + docs/troubleshooting.md | 3 +- src/proxy/dap-proxy-connection-manager.ts | 164 +++++++++++++++--- src/proxy/dap-proxy-interfaces.ts | 9 + src/proxy/dap-proxy-message-parser.ts | 12 ++ src/proxy/dap-proxy-worker.ts | 38 +++- src/proxy/proxy-manager.ts | 27 +++ .../adversarial-adapter.test.ts | 31 ++++ tests/proxy/dap-proxy-worker.test.ts | 109 +++++++++++- tests/test-utils/helpers/mcp-stdio-client.ts | 7 +- .../dap-proxy-connection-manager.test.ts | 110 ++++++++++-- .../proxy/dap-proxy-message-parser.test.ts | 10 ++ tests/unit/proxy/proxy-manager.start.test.ts | 44 +++++ 15 files changed, 527 insertions(+), 48 deletions(-) create mode 100644 changelog.d/963.fixed.md diff --git a/changelog.d/963.fixed.md b/changelog.d/963.fixed.md new file mode 100644 index 000000000..5f15e0fb0 --- /dev/null +++ b/changelog.d/963.fixed.md @@ -0,0 +1 @@ +A launch whose debug adapter takes longer than ~12 s to start listening (rdbg on a loaded Windows runner) no longer fails with `Failed to connect DAP client: connect ECONNREFUSED` while the adapter is still booting. The proxy's connect window used to be a fixed 60 attempts; it now ends only when the adapter process exits (at once, quoting the exit code and its last stderr lines) or when the launch's 30 s initialization deadline passes, whose stage-aware message the caller then gets. Direct-connect attaches (a remote rdbg/debugpy already listening) keep the previous 12.5 s window. Found on the way: the proxy worker's stdout pipe was never read by the parent, so an embedder that does not silence console output (the server CLI does) had a worker that blocked solid, deaf to IPC, once its console transport had written 64 KB; the parent now drains it (logged at debug, sanitized like stderr). diff --git a/docs/logging-format-specification.md b/docs/logging-format-specification.md index 2ecf886de..340efae3f 100644 --- a/docs/logging-format-specification.md +++ b/docs/logging-format-specification.md @@ -213,6 +213,8 @@ Truncation is applied in targeted locations rather than as a generic deep traver 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) +4. **Proxy stdout**: the worker's stdout carries only its console transport (active when console output is not silenced, i.e. outside the server CLI); the parent drains it so the worker can never block on a full pipe (issue #963) and logs each line as `[ProxyManager STDOUT] …` at `debug`, sanitized with the same `sanitizeStderr`. Nothing from stdout is captured into error reports. + There is no generic array truncation (e.g., "show first 5 items") applied across all log entries. ## Parsing Guidelines for TUI diff --git a/docs/patterns/event-management.md b/docs/patterns/event-management.md index a38724bbf..ed9156939 100644 --- a/docs/patterns/event-management.md +++ b/docs/patterns/event-management.md @@ -172,6 +172,14 @@ private setupEventHandlers(): void { this.logger.error(`[ProxyManager STDERR] ${data.toString().trim()}`); }); + // Drain stdout as well (issue #963): the worker's protocol rides the IPC + // channel and stdout carries only its console transport, but a piped stream + // nobody reads blocks the worker solid once the OS buffer fills (64 KB on + // Windows). Logged at debug, sanitized like stderr. + this.proxyProcess.stdout?.on('data', (data: Buffer | string) => { + this.logger.debug(`[ProxyManager STDOUT] ${data.toString().trim()}`); + }); + // Handle exit this.proxyProcess.on('exit', (code: number | null, signal: string | null) => { this.logger.info(`[ProxyManager] Proxy exited. Code: ${code}, Signal: ${signal}`); diff --git a/docs/troubleshooting.md b/docs/troubleshooting.md index 5346b92a3..f3efce410 100644 --- a/docs/troubleshooting.md +++ b/docs/troubleshooting.md @@ -227,7 +227,8 @@ app, or any other host. The message's second sentence tells you which stage stalled — it is derived from live progress facts, not a guess: - **"…failed to start or is not properly configured"** — nothing ever spawned or connected: verify the language's toolchain (`mcp-debugger doctor`). -- **"…spawned (PID N) but the DAP connection was never established"** — the adapter process is up but its port never accepted: check for port conflicts or loopback firewalling. +- **"…spawned (PID N) but the DAP connection was never established"** — the adapter process is up but its port never accepted within the whole 30 s: check for port conflicts or loopback firewalling. The proxy keeps trying to connect for as long as the adapter process is alive and the deadline has not passed (issue #963), so an adapter that is merely slow to start — rdbg on a loaded machine has taken past 13 s — connects when it is ready instead of failing early with `ECONNREFUSED`. +- **"Critical initialization error: Failed to connect DAP client: the adapter process exited (code N) before it started listening…"** — the adapter died while the proxy was waiting for it to listen; the message quotes its last stderr lines (a missing module, a refused toolchain). **"…nothing accepted a connection on host:port within 12.5s"** is the direct-connect form (a remote rdbg/debugpy attach): nothing listened on the address you gave within the attach's window. - **"…the \"X\" request never received a response … an adapter-side protocol stall, not a missing install"** — the adapter connected and then went quiet mid-handshake. Retrying usually succeeds; if it recurs, capture a `DAP_TRACE=1` trace of the failing launch. The failed `start_debugging` result's `data` carries the same facts structurally (`initProgress`, `proxyLogPath`). For a worked example of diagnosing this class of failure (an rdbg launch that emitted the `initialized` event but never the `initialize` response), see the [rdbg initialize-response stall case study](./case-studies/rdbg-initialize-response-stall.md). diff --git a/src/proxy/dap-proxy-connection-manager.ts b/src/proxy/dap-proxy-connection-manager.ts index fa113c3f3..ae5ca261f 100644 --- a/src/proxy/dap-proxy-connection-manager.ts +++ b/src/proxy/dap-proxy-connection-manager.ts @@ -13,19 +13,95 @@ import { import type { AdapterPolicy } from '@debugmcp/shared'; import { sanitizePayloadForLogging, toWireSourceBreakpoint, type BreakpointFields } from '@debugmcp/shared'; +/** Wait before the first connect attempt: most adapters are not listening yet. */ +const INITIAL_CONNECT_DELAY_MS = 500; +/** Wait between connect attempts. */ +const CONNECT_RETRY_INTERVAL_MS = 200; +/** + * The connect window when the caller names none: the historical 60-attempt + * equivalent (500 ms + 60 × 200 ms). Connect mode — a DAP server that is + * already listening (remote rdbg/debugpy attach) — and legacy init payloads + * without the parent's deadline still get exactly this (issue #963). + */ +export const DEFAULT_CONNECT_BUDGET_MS = INITIAL_CONNECT_DELAY_MS + 60 * CONNECT_RETRY_INTERVAL_MS; +/** + * What spawn mode adds to the parent's init deadline for its connect window: + * the parent's timer was armed first and its stage-aware message is the one a + * slow adapter boot should get, so the loop outlives the deadline by this much + * and ends promptly after it (the parent's stop() kills the worker anyway). + */ +export const PARENT_DEADLINE_TIE_MS = 500; + +/** + * Why the adapter process ended while the connect loop was waiting for it to + * listen — the `reason` the worker aborts the loop's signal with (issue #963). + */ +export interface AdapterExitReason { + code: number | null; + signal: NodeJS.Signals | null; + /** The adapter's last stderr lines, when it wrote any. */ + stderrTail?: string[]; +} + +export interface ConnectRetryOptions { + /** + * Wall-clock window from the call, in ms; `DEFAULT_CONNECT_BUDGET_MS` when + * absent. The loop makes at least one attempt however small it is. + */ + budgetMs?: number; + /** + * Aborting ends the loop at once (the adapter process exited: nothing will + * ever listen). The signal's `reason`, an {@link AdapterExitReason} when the + * worker aborts it, is quoted in the error. + */ + abort?: AbortSignal; +} + +/** A sleep that ends early when the signal aborts. */ +function sleep(ms: number, abort?: AbortSignal): Promise { + return new Promise((resolve) => { + if (abort?.aborted) { + resolve(); + return; + } + const onAbort = () => { + clearTimeout(timer); + resolve(); + }; + const timer = setTimeout(() => { + abort?.removeEventListener('abort', onAbort); + resolve(); + }, ms); + abort?.addEventListener('abort', onAbort, { once: true }); + }); +} + +/** + * The exit, worded for the error: ` (code N[, signal S])` / ` (signal S)` / + * nothing, plus the stderr tail sentence. A bare `abort()` carries an + * AbortError (a DOMException, whose own `code` is 20), not an exit: nothing. + */ +function describeAdapterExit(reason: unknown): { how: string; tail: string } { + const exit = reason && typeof reason === 'object' && !(reason instanceof Error) + ? (reason as Partial) + : undefined; + const code = typeof exit?.code === 'number' ? exit.code : null; + const signal = typeof exit?.signal === 'string' ? exit.signal : null; + const how = code !== null ? ` (code ${code}${signal ? `, signal ${signal}` : ''})` : signal ? ` (signal ${signal})` : ''; + const tail = Array.isArray(exit?.stderrTail) && exit.stderrTail.length > 0 + ? `. Its last stderr lines: ${exit.stderrTail.join(' | ')}` + : ''; + return { how, tail }; +} + export class DapConnectionManager { - // Increased initial delay to give debugpy more time to start - // This is especially important in CI/test environments - private readonly INITIAL_CONNECT_DELAY = 500; - private readonly MAX_CONNECT_ATTEMPTS = 60; - private readonly CONNECT_RETRY_INTERVAL = 200; private policy?: AdapterPolicy; constructor( private dapClientFactory: IDapClientFactory, private logger: ILogger ) {} - + /** * Set the adapter policy for creating DAP clients */ @@ -34,28 +110,69 @@ export class DapConnectionManager { } /** - * Connect to DAP adapter with retry logic + * Connect to the DAP adapter, retrying every 200 ms after a 500 ms first + * wait, until one of three things happens (issue #963): + * + * - the connect succeeds — the client is returned; + * - `options.abort` fires — the adapter process exited, so the loop ends at + * once and the error quotes the exit (code/signal, last stderr lines); + * - `options.budgetMs` runs out — the error says nothing accepted a + * connection on host:port within the window, with the attempt count and + * the last socket error. + * + * The window is wall clock, not an attempt count: a fixed 60 attempts + * (~12.5 s) used to fail a launch whose adapter was still booting on a + * loaded runner, 17.5 s before the parent's own 30 s deadline would have + * given up. In spawn mode the worker sizes the window from that deadline, + * so the loop has no budget of its own there; connect mode and legacy + * payloads keep the historical window as the default. */ - async connectWithRetry(host: string, port: number): Promise { - this.logger.info(`[ConnectionManager] Waiting ${this.INITIAL_CONNECT_DELAY}ms before first DAP connect attempt.`); - await new Promise(resolve => setTimeout(resolve, this.INITIAL_CONNECT_DELAY)); + async connectWithRetry(host: string, port: number, options: ConnectRetryOptions = {}): Promise { + const budgetMs = options.budgetMs ?? DEFAULT_CONNECT_BUDGET_MS; + const abort = options.abort; + const startedAt = Date.now(); + const deadline = startedAt + budgetMs; + const budgetSeconds = (budgetMs / 1000).toFixed(1); + + const initialDelay = Math.min(INITIAL_CONNECT_DELAY_MS, budgetMs); + this.logger.info(`[ConnectionManager] Waiting ${initialDelay}ms before first DAP connect attempt (window ${budgetSeconds}s).`); + await sleep(initialDelay, abort); // Create client with policy if available - const client = this.policy + const client = this.policy ? this.dapClientFactory.create(host, port, this.policy) : this.dapClientFactory.create(host, port); - + // Temporary error handler to prevent unhandled 'error' event crashes during connect attempts const tempErrorHandler = (err: Error) => { this.logger.debug(`[ConnectionManager] DAP client emitted 'error' during connection phase (expected for retries): ${err.message}`); }; client.on('error', tempErrorHandler); + const fail = (reason: string): never => { + this.logger.error(`[ConnectionManager] ${reason}`); + client.off('error', tempErrorHandler); + // The failed connects' sockets have destroyed themselves; this leaves the + // client itself terminal so nothing can reuse it. + client.disconnect(); + throw new Error(`Failed to connect DAP client: ${reason}`); + }; + + const failOnAdapterExit = (): never => { + const { how, tail } = describeAdapterExit(abort?.reason); + return fail(`the adapter process exited${how} before it started listening on ${host}:${port}${tail}`); + }; + let connectAttempts = 0; + let lastError = 'none'; for (;;) { + if (abort?.aborted) { + failOnAdapterExit(); + } + connectAttempts++; try { - this.logger.info(`[ConnectionManager] Attempting DAP client connect (attempt ${connectAttempts + 1}/${this.MAX_CONNECT_ATTEMPTS}) to ${host}:${port}`); + this.logger.info(`[ConnectionManager] Attempting DAP client connect (attempt ${connectAttempts}, ${Date.now() - startedAt}ms into a ${budgetSeconds}s window) to ${host}:${port}`); await client.connect(); this.logger.info('[ConnectionManager] DAP client connected to adapter successfully.'); @@ -63,18 +180,19 @@ export class DapConnectionManager { client.off('error', tempErrorHandler); return client; } catch (err) { - connectAttempts++; - const errMessage = err instanceof Error ? err.message : String(err); - - if (connectAttempts >= this.MAX_CONNECT_ATTEMPTS) { - this.logger.error(`[ConnectionManager] Failed to connect DAP client after ${this.MAX_CONNECT_ATTEMPTS} attempts. Last error: ${errMessage}`); - client.off('error', tempErrorHandler); - throw new Error(`Failed to connect DAP client: ${errMessage}`); - } + lastError = err instanceof Error ? err.message : String(err); + } - this.logger.warn(`[ConnectionManager] DAP client connect attempt ${connectAttempts} failed: ${errMessage}. Retrying in ${this.CONNECT_RETRY_INTERVAL}ms...`); - await new Promise(resolve => setTimeout(resolve, this.CONNECT_RETRY_INTERVAL)); + if (abort?.aborted) { + failOnAdapterExit(); } + const remainingMs = deadline - Date.now(); + if (remainingMs <= 0) { + fail(`nothing accepted a connection on ${host}:${port} within ${budgetSeconds}s (${connectAttempts} attempts; last error: ${lastError})`); + } + + this.logger.warn(`[ConnectionManager] DAP client connect attempt ${connectAttempts} failed: ${lastError}. Retrying in ${CONNECT_RETRY_INTERVAL_MS}ms...`); + await sleep(Math.min(CONNECT_RETRY_INTERVAL_MS, remainingMs), abort); } } diff --git a/src/proxy/dap-proxy-interfaces.ts b/src/proxy/dap-proxy-interfaces.ts index 7ef86c8c2..83eb9f348 100644 --- a/src/proxy/dap-proxy-interfaces.ts +++ b/src/proxy/dap-proxy-interfaces.ts @@ -34,6 +34,15 @@ export interface ProxyInitPayload { logLevel?: string; /** Abstract break-on-exception mode; resolved to concrete DAP filters via the adapter policy (issue #220) */ breakOnExceptions?: 'uncaught' | 'all' | 'none'; + /** + * The parent's initialization deadline (ms), the one `ProxyManager.start` + * holds the whole init to. The worker sizes its DAP connect window from it + * in spawn mode (issue #963): the window ends when the adapter exits or just + * after this deadline, never before — a slow adapter boot gets the parent's + * stage-aware timeout message, not a premature `ECONNREFUSED`. Absent on + * legacy payloads, where the connect window keeps its historical ~12.5 s. + */ + initializationTimeoutMs?: number; launchConfig?: LanguageSpecificLaunchConfig; // Adapter command info for language-agnostic adapter spawning adapterCommand?: { diff --git a/src/proxy/dap-proxy-message-parser.ts b/src/proxy/dap-proxy-message-parser.ts index 460f545bc..b205e39ec 100644 --- a/src/proxy/dap-proxy-message-parser.ts +++ b/src/proxy/dap-proxy-message-parser.ts @@ -85,6 +85,18 @@ export class MessageParser { throw new Error(`Init payload 'language' must be a string if provided`); } + // The parent's init deadline (issue #963): a positive finite number of ms, + // coerced from a numeric string like adapterPort. + if (obj.initializationTimeoutMs !== undefined) { + const deadline = typeof obj.initializationTimeoutMs === 'string' + ? Number(obj.initializationTimeoutMs) + : obj.initializationTimeoutMs; + if (typeof deadline !== 'number' || !Number.isFinite(deadline) || deadline <= 0) { + throw new Error(`Init payload invalid 'initializationTimeoutMs': ${obj.initializationTimeoutMs}`); + } + obj.initializationTimeoutMs = deadline; + } + if (obj.scriptArgs !== undefined && !Array.isArray(obj.scriptArgs)) { throw new Error(`Init payload 'scriptArgs' must be an array if provided`); } diff --git a/src/proxy/dap-proxy-worker.ts b/src/proxy/dap-proxy-worker.ts index 8e58985de..0c90b04e1 100644 --- a/src/proxy/dap-proxy-worker.ts +++ b/src/proxy/dap-proxy-worker.ts @@ -27,7 +27,12 @@ import type { IDapMirrorServer, MirrorEndpoint } from './dap-mirror-server.js'; import { CallbackRequestTracker } from './dap-proxy-request-tracker.js'; import { GenericAdapterManager, AdapterStdioSource, AdapterStdioLineInfo } from './dap-proxy-adapter-manager.js'; import { dapTracePathFor, proxyLogPathFor } from './session-log-layout.js'; -import { DapConnectionManager } from './dap-proxy-connection-manager.js'; +import { + DapConnectionManager, + PARENT_DEADLINE_TIE_MS, + type AdapterExitReason, + type ConnectRetryOptions +} from './dap-proxy-connection-manager.js'; import { validateProxyInitPayload } from '../utils/type-guards.js'; @@ -571,6 +576,23 @@ export class DapProxyWorker { throw new Error(`Adapter policy ${this.adapterPolicy.name} does not provide spawn configuration`); } + // Spawn mode's connect window (issue #963): the loop ends when the adapter + // exits (this controller) or just after the parent's init deadline, whose + // stage-aware message is the one a slow adapter boot should get — the + // +500 ms lets the parent's timer, armed first, win the tie while the + // worker still ends its loop promptly (the parent's stop() kills the + // worker anyway). Connect mode has nothing booting: no controller, no + // budget of its own, the historical default window. + const adapterExit = new AbortController(); + const connectOptions: ConnectRetryOptions | undefined = spawnConfig.mode === 'spawn' + ? { + abort: adapterExit.signal, + ...(typeof payload.initializationTimeoutMs === 'number' + ? { budgetMs: payload.initializationTimeoutMs + PARENT_DEADLINE_TIE_MS } + : {}) + } + : undefined; + if (spawnConfig.mode === 'spawn') { // In container mode, default adapter cwd to workspace root so that // relative paths in DAP launch args (classpath, cwd, etc.) resolve @@ -616,6 +638,13 @@ export class DapProxyWorker { // Recorded synchronously: the terminated slot's synthesis wait may // resolve on this very event (issue #258) this.adapterExitCode = code; + // A connect loop still waiting for this process to listen ends now, + // quoting the exit (issue #963). + adapterExit.abort({ + code, + signal, + stderrTail: this.adapterRecentStderr?.() + } satisfies AdapterExitReason); this.enqueueTerminalSignal('adapter_exited', async () => { await this.waitForAdapterStdioDrain(); await this.settleAdapterStderr(); @@ -641,10 +670,9 @@ export class DapProxyWorker { // Connect to adapter try { - this.dapClient = await this.connectionManager!.connectWithRetry( - spawnConfig.host, - spawnConfig.port - ); + this.dapClient = connectOptions + ? await this.connectionManager!.connectWithRetry(spawnConfig.host, spawnConfig.port, connectOptions) + : await this.connectionManager!.connectWithRetry(spawnConfig.host, spawnConfig.port); // Record the break-on-exception mode on the client so DAP child // sessions (js-debug) can apply the same filters (issue #220). diff --git a/src/proxy/proxy-manager.ts b/src/proxy/proxy-manager.ts index 8356de68f..1e4773bb9 100644 --- a/src/proxy/proxy-manager.ts +++ b/src/proxy/proxy-manager.ts @@ -384,6 +384,9 @@ export class ProxyManager extends EventEmitter implements IProxyManager { debuggerOff: config.debuggerOff, logLevel: config.logLevel, breakOnExceptions: config.breakOnExceptions, + // The deadline this start() is held to; the worker's DAP connect window + // in spawn mode ends just after it, not before (issue #963). + initializationTimeoutMs: this.initializationTimeoutMs, launchConfig: config.launchConfig, // Pass adapter command info for language-agnostic adapter spawning adapterCommand: config.adapterCommand @@ -1041,6 +1044,30 @@ export class ProxyManager extends EventEmitter implements IProxyManager { track(stderr, 'close', flushStderr); } + // Drain stdout too. The worker's protocol rides the IPC channel; its + // stdout carries only its console transport, which is active outside the + // server CLI (that silences console output). A piped stdout nobody reads + // blocks the worker solid once the OS buffer fills (64 KB on Windows): + // deaf to IPC, its DAP socket unread — found by a 14 s connect loop that + // logged past the buffer (issue #963). Logged at debug: the proxy log + // already carries these lines. Sanitized like stderr: a console line can + // quote a launch environment. + const stdout = this.proxyProcess.stdout as unknown as RemovableEmitter | null; + if (stdout) { + const stdoutLineBuffer = new LineBuffer(); + const recordStdoutLines = (lines: string[]) => { + for (const line of sanitizeStderr(lines.filter(line => line.trim().length > 0))) { + this.logger.debug(`[ProxyManager STDOUT] ${line}`); + } + }; + track(stdout, 'data', (data: Buffer | string) => { + recordStdoutLines(stdoutLineBuffer.append(data.toString())); + }); + const flushStdout = () => recordStdoutLines(stdoutLineBuffer.flush()); + track(stdout, 'end', flushStdout); + track(stdout, 'close', flushStdout); + } + // Handle exit track(proc, 'exit', (code: number | null, signal: string | null) => { this.logger.info(`[ProxyManager] Proxy exited. Code: ${code}, Signal: ${signal}`); diff --git a/tests/integration/adversarial-dap/adversarial-adapter.test.ts b/tests/integration/adversarial-dap/adversarial-adapter.test.ts index 5cd17f62c..96a6afd99 100644 --- a/tests/integration/adversarial-dap/adversarial-adapter.test.ts +++ b/tests/integration/adversarial-dap/adversarial-adapter.test.ts @@ -23,6 +23,7 @@ interface ScenarioRule { interface Scenario { neverListen?: boolean; + listenDelayMs?: number; commands?: Record; } @@ -124,6 +125,11 @@ describe.sequential('adversarial TCP DAP adapter', () => { }); afterAll(() => { + // ADVERSARIAL_KEEP_TMP=1 keeps the scenarios and proxy logs for a look. + if (process.env.ADVERSARIAL_KEEP_TMP === '1') { + console.log(`[adversarial-adapter] kept ${tempDir}`); + return; + } fs.rmSync(tempDir, { recursive: true, force: true }); }); @@ -225,6 +231,31 @@ describe.sequential('adversarial TCP DAP adapter', () => { expect(error.message).toMatch(/closed|disconnect|exited|terminated|proxy/i); }); + // A slow adapter boot (rdbg on a loaded Windows runner took past 13 s): the + // worker's connect window used to be a fixed 60 attempts, ~12.5 s, so an + // adapter that started listening at 14 s failed the launch with ECONNREFUSED + // while it was still booting, 17.5 s before the parent's deadline. The + // window now ends with the adapter's exit or the parent's deadline (#963). + it('connects to an adapter that starts listening after the old 12.5 s window (issue #963)', async () => { + const { manager, config } = await createManager({ + listenDelayMs: 14_000, + commands: { + initialize: { eventsAfterResponse: [{ event: 'initialized' }] } + } + }, 25_000); + + // On a failure, the worker's connect timeline is the fact that settles it. + const failure = await manager.start(config).then(() => undefined, (error: Error) => error); + if (failure) { + const proxyLog = path.join(config.logDir, `proxy-${config.sessionId}.log`); + const timeline = fs.existsSync(proxyLog) + ? fs.readFileSync(proxyLog, 'utf8').split('\n').filter(line => /ConnectionManager|Adapter process|Adapter spawned/.test(line)).slice(-10).join('\n') + : '(no proxy log)'; + throw new Error(`${failure.message}\n--- proxy log, connect lines:\n${timeline}`); + } + expect(manager.isRunning()).toBe(true); + }, 30_000); + it('distinguishes an adapter process that spawned but never listened', async () => { const { manager, config } = await createManager({ neverListen: true }, 1800); diff --git a/tests/proxy/dap-proxy-worker.test.ts b/tests/proxy/dap-proxy-worker.test.ts index 20f4e6720..ae9363770 100644 --- a/tests/proxy/dap-proxy-worker.test.ts +++ b/tests/proxy/dap-proxy-worker.test.ts @@ -1114,7 +1114,14 @@ describe('DapProxyWorker', () => { await (worker as any).startAdapterAndConnect(payload); expect(processStub.spawn).toHaveBeenCalledTimes(1); - expect(connectionStub.connectWithRetry).toHaveBeenCalledWith(payload.adapterHost, payload.adapterPort); + // Spawn mode: the connect loop is told when the adapter exits; a legacy + // payload without the parent's deadline keeps the default budget (#963). + expect(connectionStub.connectWithRetry).toHaveBeenCalledWith( + payload.adapterHost, + payload.adapterPort, + expect.objectContaining({ abort: expect.any(AbortSignal) }) + ); + expect(connectionStub.connectWithRetry.mock.calls[0][2].budgetMs).toBeUndefined(); const statusCall = mockMessageSender.send.mock.calls.find( ([message]) => message.type === 'status' && message.status === 'adapter_connected' ); @@ -1122,6 +1129,106 @@ describe('DapProxyWorker', () => { expect(worker.getState()).toBe(ProxyState.CONNECTED); }); + // The connect window has no budget of its own in spawn mode (issue #963): + // it ends when the adapter exits or just after the parent's deadline, whose + // stage-aware message ("adapter process spawned … DAP connection was never + // established") is the one a slow boot should get. The +500 ms is the tie. + it('sizes the connect window from the parent deadline the init payload carries (issue #963)', async () => { + const payload: ProxyInitPayload = { + cmd: 'init', + sessionId: 'js-session-963', + executablePath: 'node', + adapterHost: 'localhost', + adapterPort: 9229, + logDir: '/logs', + scriptPath: '/path/to/script.js', + initializationTimeoutMs: 30000, + adapterCommand: { command: 'node', args: ['adapter.js'] } + }; + const processStub = { + spawn: vi.fn().mockResolvedValue({ process: new EventEmitter() as unknown as ChildProcess, pid: 321 }), + shutdown: vi.fn().mockResolvedValue(undefined) + }; + const connectionStub = { + connectWithRetry: vi.fn().mockResolvedValue(mockDapClient), + setAdapterPolicy: vi.fn(), + setupEventHandlers: vi.fn(), + initializeSession: vi.fn(), + sendLaunchRequest: vi.fn(), + setBreakpoints: vi.fn(), + sendConfigurationDone: vi.fn(), + disconnect: vi.fn() + }; + (worker as any).logger = mockLogger; + (worker as any).processManager = processStub; + (worker as any).connectionManager = connectionStub; + (worker as any).adapterPolicy = JsDebugAdapterPolicy; + (worker as any).adapterState = JsDebugAdapterPolicy.createInitialState(); + (worker as any).currentInitPayload = payload; + (worker as any).state = ProxyState.INITIALIZING; + + await (worker as any).startAdapterAndConnect(payload); + + expect(connectionStub.connectWithRetry).toHaveBeenCalledWith( + 'localhost', + 9229, + expect.objectContaining({ budgetMs: 30500, abort: expect.any(AbortSignal) }) + ); + }); + + it('aborts the connect wait with the exit when the adapter process dies while it is still connecting (issue #963)', async () => { + const payload: ProxyInitPayload = { + cmd: 'init', + sessionId: 'js-session-963-exit', + executablePath: 'node', + adapterHost: 'localhost', + adapterPort: 9229, + logDir: '/logs', + scriptPath: '/path/to/script.js', + initializationTimeoutMs: 30000, + adapterCommand: { command: 'node', args: ['adapter.js'] } + }; + const adapterProcess = new EventEmitter() as unknown as ChildProcess; + const processStub = { + spawn: vi.fn().mockResolvedValue({ process: adapterProcess, pid: 321, recentStderr: () => ['Error: Cannot find module adapter.js'] }), + shutdown: vi.fn().mockResolvedValue(undefined) + }; + let observed: AbortSignal | undefined; + const connectionStub = { + // The real loop rejects when its signal fires; the stub does the same. + connectWithRetry: vi.fn((_host: string, _port: number, options: { abort: AbortSignal }) => { + observed = options.abort; + return new Promise((_resolve, reject) => { + options.abort.addEventListener('abort', () => reject(new Error('Failed to connect DAP client: the adapter process exited')), { once: true }); + }); + }), + setAdapterPolicy: vi.fn(), + setupEventHandlers: vi.fn(), + initializeSession: vi.fn(), + sendLaunchRequest: vi.fn(), + setBreakpoints: vi.fn(), + sendConfigurationDone: vi.fn(), + disconnect: vi.fn() + }; + (worker as any).logger = mockLogger; + (worker as any).processManager = processStub; + (worker as any).connectionManager = connectionStub; + (worker as any).adapterPolicy = JsDebugAdapterPolicy; + (worker as any).adapterState = JsDebugAdapterPolicy.createInitialState(); + (worker as any).currentInitPayload = payload; + (worker as any).state = ProxyState.INITIALIZING; + + const started = (worker as any).startAdapterAndConnect(payload); + const failure = expect(started).rejects.toThrow('the adapter process exited'); + await vi.waitFor(() => expect(observed).toBeDefined()); + + adapterProcess.emit('exit', 1, null); + + await failure; + expect(observed!.aborted).toBe(true); + expect(observed!.reason).toEqual({ code: 1, signal: null, stderrTail: ['Error: Cannot find module adapter.js'] }); + }); + it('reports adapter_configured_and_launched once the js-debug child is adopted (issue #704)', async () => { const payload: ProxyInitPayload = { cmd: 'init', diff --git a/tests/test-utils/helpers/mcp-stdio-client.ts b/tests/test-utils/helpers/mcp-stdio-client.ts index ae02172ae..1c15e30be 100644 --- a/tests/test-utils/helpers/mcp-stdio-client.ts +++ b/tests/test-utils/helpers/mcp-stdio-client.ts @@ -106,9 +106,14 @@ export interface StdioClientHandle { */ export async function startStdioClient(options: StdioClientOptions): Promise { const client = new Client({ name: options.name, version: '1' }); + // The server's log, and beside it the per-session proxy logs, under + // logs/tests/ — the path CI's Windows diagnostics artifact collects. Without + // --log-file they land in os.tmpdir(), where a failing launch's connect + // timeline is lost with the runner (issue #963). + const logFile = path.join(REPO_ROOT, 'logs', 'tests', 'stdio', `${options.name}-${process.pid}-${Date.now()}.log`); const transport = new StdioClientTransport({ command: process.execPath, - args: [path.join(REPO_ROOT, 'dist/index.js'), 'stdio'], + args: [path.join(REPO_ROOT, 'dist/index.js'), 'stdio', '--log-file', logFile], cwd: options.cwd ?? REPO_ROOT, env: serverEnvironment(options), stderr: 'pipe' diff --git a/tests/unit/proxy/dap-proxy-connection-manager.test.ts b/tests/unit/proxy/dap-proxy-connection-manager.test.ts index 8f486cdce..856da9419 100644 --- a/tests/unit/proxy/dap-proxy-connection-manager.test.ts +++ b/tests/unit/proxy/dap-proxy-connection-manager.test.ts @@ -103,28 +103,104 @@ describe('DapConnectionManager', () => { expect(result).toBe(mockDapClient); }); - it('should fail after maximum retry attempts', async () => { - mockDapClient.connect.mockRejectedValue(new Error('ECONNREFUSED')); + // The window is a wall-clock budget, not an attempt count (issue #963): a + // slow adapter boot on a loaded runner used to run out of the 60 attempts + // (~12.5 s) while the adapter was still starting, 17.5 s before the + // parent's own 30 s deadline would have given up. + it('keeps attempting past the old 60-attempt ceiling while the budget remains (issue #963)', async () => { + let attempts = 0; + mockDapClient.connect.mockImplementation(() => { + attempts++; + return attempts < 90 ? Promise.reject(new Error('ECONNREFUSED')) : Promise.resolve(); + }); + + const resultPromise = connectionManager.connectWithRetry('localhost', 5678, { budgetMs: 25_000 }); + + await vi.advanceTimersByTimeAsync(500); + await waitForRetries(89); + + await expect(resultPromise).resolves.toBe(mockDapClient); + expect(mockDapClient.connect).toHaveBeenCalledTimes(90); + }); + + it('gives up when the budget expires with nothing listening, saying what expired (issue #963)', async () => { + mockDapClient.connect.mockRejectedValue(new Error('connect ECONNREFUSED 127.0.0.1:5678')); // Create expectation immediately to attach rejection handler const expectation = expect( - connectionManager.connectWithRetry('localhost', 5678) - ).rejects.toThrow('Failed to connect DAP client: ECONNREFUSED'); - - // Wait for initial delay + connectionManager.connectWithRetry('127.0.0.1', 5678) + ).rejects.toThrow( + 'Failed to connect DAP client: nothing accepted a connection on 127.0.0.1:5678 within 12.5s' + ); + + // Wait for initial delay, then out the default budget (today's 60-attempt equivalent). await vi.advanceTimersByTimeAsync(500); - - // Wait for all 60 retries - await waitForRetries(60); - - // Await the expectation + await waitForRetries(61); + await expectation; - - expect(mockDapClient.connect).toHaveBeenCalledTimes(60); + + expect(mockDapClient.connect.mock.calls.length).toBeGreaterThanOrEqual(60); expect(mockDapClient.off).toHaveBeenCalledWith('error', expect.any(Function)); + expect(mockDapClient.disconnect).toHaveBeenCalledTimes(1); expect(mockLogger.error).toHaveBeenCalledWith( - expect.stringContaining('Failed to connect DAP client after 60 attempts') + expect.stringContaining('last error: connect ECONNREFUSED 127.0.0.1:5678') + ); + }); + + it('makes at least one attempt however small the budget (issue #963)', async () => { + mockDapClient.connect.mockRejectedValue(new Error('ECONNREFUSED')); + + const expectation = expect( + connectionManager.connectWithRetry('127.0.0.1', 5678, { budgetMs: 100 }) + ).rejects.toThrow('within 0.1s'); + + await vi.advanceTimersByTimeAsync(100); + await expectation; + + expect(mockDapClient.connect).toHaveBeenCalledTimes(1); + }); + + it('ends the wait at once when the adapter process exits, quoting the exit (issue #963)', async () => { + mockDapClient.connect.mockRejectedValue(new Error('ECONNREFUSED')); + const adapterExit = new AbortController(); + + const expectation = expect( + connectionManager.connectWithRetry('127.0.0.1', 5678, { budgetMs: 30_500, abort: adapterExit.signal }) + ).rejects.toThrow( + 'Failed to connect DAP client: the adapter process exited (code 1) before it started listening on 127.0.0.1:5678. Its last stderr lines: rdbg: command not found' ); + + await vi.advanceTimersByTimeAsync(500); + await waitForRetries(3); + const attemptsBeforeExit = mockDapClient.connect.mock.calls.length; + expect(attemptsBeforeExit).toBeGreaterThan(0); + + adapterExit.abort({ code: 1, signal: null, stderrTail: ['rdbg: command not found'] }); + await expectation; + + // No further attempts after the exit, however long the budget had left. + await vi.advanceTimersByTimeAsync(5_000); + expect(mockDapClient.connect.mock.calls.length).toBe(attemptsBeforeExit); + expect(mockDapClient.off).toHaveBeenCalledWith('error', expect.any(Function)); + expect(mockDapClient.disconnect).toHaveBeenCalledTimes(1); + }); + + it('names a signal-terminated adapter and copes with an abort that carries no reason (issue #963)', async () => { + mockDapClient.connect.mockRejectedValue(new Error('ECONNREFUSED')); + + const killed = new AbortController(); + killed.abort({ code: null, signal: 'SIGKILL' }); + await expect( + connectionManager.connectWithRetry('127.0.0.1', 5678, { abort: killed.signal }) + ).rejects.toThrow('the adapter process exited (signal SIGKILL) before it started listening on 127.0.0.1:5678'); + // Already exited before the first wait: no attempt is made. + expect(mockDapClient.connect).not.toHaveBeenCalled(); + + const bare = new AbortController(); + bare.abort(); + await expect( + connectionManager.connectWithRetry('127.0.0.1', 5678, { abort: bare.signal }) + ).rejects.toThrow('the adapter process exited before it started listening on 127.0.0.1:5678'); }); it('should handle temporary error events during connection', async () => { @@ -211,11 +287,11 @@ describe('DapConnectionManager', () => { ).rejects.toThrow('Failed to connect DAP client'); await vi.advanceTimersByTimeAsync(500); - await waitForRetries(60); - + await waitForRetries(61); + // Await the expectation await expectation; - + // Verify error handler was removed expect(mockDapClient.off).toHaveBeenCalledWith('error', expect.any(Function)); }); diff --git a/tests/unit/proxy/dap-proxy-message-parser.test.ts b/tests/unit/proxy/dap-proxy-message-parser.test.ts index b9071d6db..b18ae1cc3 100644 --- a/tests/unit/proxy/dap-proxy-message-parser.test.ts +++ b/tests/unit/proxy/dap-proxy-message-parser.test.ts @@ -343,6 +343,16 @@ describe('MessageParser', () => { expect((result as any).adapterPort).toBe(58000); }); + it('accepts initializationTimeoutMs as a positive finite number, coercing a numeric string (issue #963)', () => { + expect(MessageParser.validateInitPayload({ ...basePayload, initializationTimeoutMs: 30000 }).initializationTimeoutMs).toBe(30000); + expect(MessageParser.validateInitPayload({ ...basePayload, initializationTimeoutMs: '30000' }).initializationTimeoutMs).toBe(30000); + expect(MessageParser.validateInitPayload(basePayload).initializationTimeoutMs).toBeUndefined(); + for (const invalid of [0, -1, Number.NaN, Number.POSITIVE_INFINITY, 'soon', null]) { + expect(() => MessageParser.validateInitPayload({ ...basePayload, initializationTimeoutMs: invalid })) + .toThrow("Init payload invalid 'initializationTimeoutMs'"); + } + }); + it('should coerce stopOnEntry from string "true" to boolean', () => { const payload = { ...basePayload, stopOnEntry: 'true' }; const result = MessageParser.validateInitPayload(payload); diff --git a/tests/unit/proxy/proxy-manager.start.test.ts b/tests/unit/proxy/proxy-manager.start.test.ts index 84237fd95..3aedad160 100644 --- a/tests/unit/proxy/proxy-manager.start.test.ts +++ b/tests/unit/proxy/proxy-manager.start.test.ts @@ -117,6 +117,7 @@ describe('ProxyManager.start', () => { // Detach the fake first so any straggling emit finds no manager handlers. fakeProcess.removeAllListeners(); (fakeProcess.stderr as unknown as EventEmitter | null)?.removeAllListeners(); + (fakeProcess.stdout as unknown as EventEmitter | null)?.removeAllListeners(); proxyManager.removeAllListeners(); // Flush this test's stray macrotasks inside its own attribution window. await new Promise((resolve) => setImmediate(resolve)); @@ -179,6 +180,49 @@ describe('ProxyManager.start', () => { ); }); + // The worker sizes its DAP connect window from this deadline (issue #963): + // the parent's stage-aware timeout is the message a slow adapter boot gets. + it('tells the worker the initialization deadline it is held to (issue #963)', async () => { + await proxyManager.start(baseConfig); + + expect(fakeProcess.sendCommand).toHaveBeenCalledWith( + expect.objectContaining({ cmd: 'init', initializationTimeoutMs: DEFAULT_PROXY_INITIALIZATION_TIMEOUT_MS }) + ); + }); + + it('tells the worker an injected initialization deadline (issue #963)', async () => { + proxyManager = new ProxyManager(null, proxyProcessLauncher, fileSystem, logger, undefined, { initializationTimeoutMs: 1250 }); + + await proxyManager.start(baseConfig); + + expect(fakeProcess.sendCommand).toHaveBeenCalledWith( + expect.objectContaining({ cmd: 'init', initializationTimeoutMs: 1250 }) + ); + }); + + // The worker is spawned with a piped stdout that only this manager can + // drain. Its protocol rides the IPC channel; stdout carries its console + // transport, active outside the server CLI (which silences console output). + // A pipe nobody reads blocks the worker solid once the OS buffer fills + // (64 KB on Windows): deaf to IPC, its DAP socket unread. Found by a 14 s + // connect loop that logged past the buffer (issue #963). + it('drains the worker stdout pipe, logging its lines, so a chatty worker cannot block on it (issue #963)', async () => { + const stdout = new EventEmitter(); + fakeProcess.stdout = stdout as unknown as NodeJS.ReadableStream; + + await proxyManager.start(baseConfig); + + expect(stdout.listenerCount('data')).toBe(1); + stdout.emit('data', Buffer.from('{"level":"info","message":"[ConnectionManager] attempt 61"}\nGITHUB_PAT=github_pat_supersecret1234567890\npartial')); + expect(logger.debug).toHaveBeenCalledWith('[ProxyManager STDOUT] {"level":"info","message":"[ConnectionManager] attempt 61"}'); + // Sanitized like stderr: the worker's console lines can carry a launch env. + expect(logger.debug).not.toHaveBeenCalledWith(expect.stringContaining('github_pat_supersecret')); + expect(logger.debug).toHaveBeenCalledWith('[ProxyManager STDOUT] [REDACTED — line contained sensitive data]'); + // The trailing partial line is flushed when the stream ends. + stdout.emit('end'); + expect(logger.debug).toHaveBeenCalledWith('[ProxyManager STDOUT] partial'); + }); + it('sends breakOnExceptions as undefined in the init command when not set', async () => { await proxyManager.start(baseConfig); From eb4cabef8f93c8389c63e41fd09c9ff6529ece36 Mon Sep 17 00:00:00 2001 From: JF Date: Tue, 20 Oct 2026 09:21:56 -0400 Subject: [PATCH 2/2] fix(proxy): cap and date the stderr quoted for an adapter that exited mid-connect; state the elapsed time on expiry (#963) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Own-PR review follow-ups. The exited-adapter error quoted the worker's whole 20-line stderr tail (up to ~8 KB); it now quotes the parent's documented 10 lines / 2000 characters, most recent first to go, and says the lines are those seen by the time the process exited — the snapshot is taken in the exit handler, before the pipe has settled, because waiting would hand the race to the parent's generic exit message. The expiry message states the elapsed time beside the window (one connect can outlive it: a remote host that drops SYNs answers ETIMEDOUT after the OS's ~21 s). client.disconnect() on the failure path is guarded so it can never mask the reason. The start test pins that the stdout drain's listeners detach with the rest; the stdio test helper sweeps entries older than a day from logs/tests/stdio, which nothing else cleans; the event-management doc sample sanitizes as its comment says. Co-Authored-By: Claude Fable 5.1 Claude-Session: https://claude.ai/code/session_01Y3ULnoVSoCZ5t2Y8d98Ctv --- docs/patterns/event-management.md | 6 +- src/proxy/dap-proxy-connection-manager.ts | 38 +++++++++-- tests/test-utils/helpers/mcp-stdio-client.ts | 38 +++++++++-- .../dap-proxy-connection-manager.test.ts | 68 ++++++++++++++++++- tests/unit/proxy/proxy-manager.start.test.ts | 6 ++ 5 files changed, 140 insertions(+), 16 deletions(-) diff --git a/docs/patterns/event-management.md b/docs/patterns/event-management.md index ed9156939..c1f167e08 100644 --- a/docs/patterns/event-management.md +++ b/docs/patterns/event-management.md @@ -175,9 +175,11 @@ private setupEventHandlers(): void { // Drain stdout as well (issue #963): the worker's protocol rides the IPC // channel and stdout carries only its console transport, but a piped stream // nobody reads blocks the worker solid once the OS buffer fills (64 KB on - // Windows). Logged at debug, sanitized like stderr. + // Windows). Logged at debug, through the same sanitizer as stderr. this.proxyProcess.stdout?.on('data', (data: Buffer | string) => { - this.logger.debug(`[ProxyManager STDOUT] ${data.toString().trim()}`); + for (const line of sanitizeStderr([data.toString().trim()])) { + this.logger.debug(`[ProxyManager STDOUT] ${line}`); + } }); // Handle exit diff --git a/src/proxy/dap-proxy-connection-manager.ts b/src/proxy/dap-proxy-connection-manager.ts index ae5ca261f..fd1b151ff 100644 --- a/src/proxy/dap-proxy-connection-manager.ts +++ b/src/proxy/dap-proxy-connection-manager.ts @@ -76,10 +76,20 @@ function sleep(ms: number, abort?: AbortSignal): Promise { }); } +/** The stderr embedding caps the parent uses for its own init-exit error. */ +const QUOTED_STDERR_LINES = 10; +const QUOTED_STDERR_CHARS = 2000; + /** * The exit, worded for the error: ` (code N[, signal S])` / ` (signal S)` / * nothing, plus the stderr tail sentence. A bare `abort()` carries an * AbortError (a DOMException, whose own `code` is 20), not an exit: nothing. + * + * The tail is the worker's snapshot at the process's `exit` event; the pipe + * can still hold the adapter's final line then (issue #897 waits it out for + * the `adapter_exited` status, this error cannot without losing the race with + * the parent's generic exit message), so the wording says when it was taken. + * The whole tail is in the proxy log. */ function describeAdapterExit(reason: unknown): { how: string; tail: string } { const exit = reason && typeof reason === 'object' && !(reason instanceof Error) @@ -88,10 +98,14 @@ function describeAdapterExit(reason: unknown): { how: string; tail: string } { const code = typeof exit?.code === 'number' ? exit.code : null; const signal = typeof exit?.signal === 'string' ? exit.signal : null; const how = code !== null ? ` (code ${code}${signal ? `, signal ${signal}` : ''})` : signal ? ` (signal ${signal})` : ''; - const tail = Array.isArray(exit?.stderrTail) && exit.stderrTail.length > 0 - ? `. Its last stderr lines: ${exit.stderrTail.join(' | ')}` - : ''; - return { how, tail }; + if (!Array.isArray(exit?.stderrTail) || exit.stderrTail.length === 0) { + return { how, tail: '' }; + } + let quoted = exit.stderrTail.slice(-QUOTED_STDERR_LINES).join(' | '); + if (quoted.length > QUOTED_STDERR_CHARS) { + quoted = `…${quoted.slice(quoted.length - QUOTED_STDERR_CHARS)}`; + } + return { how, tail: `. Its last stderr lines by the time it exited: ${quoted}` }; } export class DapConnectionManager { @@ -153,8 +167,13 @@ export class DapConnectionManager { this.logger.error(`[ConnectionManager] ${reason}`); client.off('error', tempErrorHandler); // The failed connects' sockets have destroyed themselves; this leaves the - // client itself terminal so nothing can reuse it. - client.disconnect(); + // client itself terminal so nothing can reuse it. Never let it mask the + // reason (the same guard disconnect() below applies). + try { + client.disconnect(); + } catch (e) { + this.logger.warn(`[ConnectionManager] client.disconnect() after a failed connect threw: ${e instanceof Error ? e.message : String(e)}`); + } throw new Error(`Failed to connect DAP client: ${reason}`); }; @@ -188,7 +207,12 @@ export class DapConnectionManager { } const remainingMs = deadline - Date.now(); if (remainingMs <= 0) { - fail(`nothing accepted a connection on ${host}:${port} within ${budgetSeconds}s (${connectAttempts} attempts; last error: ${lastError})`); + // The elapsed time is stated beside the window: one attempt can + // outlive it (a remote host that drops SYNs answers ETIMEDOUT after + // the OS's own ~21 s), and the message must not read as if the loop + // had stopped at the window. + const elapsedSeconds = ((Date.now() - startedAt) / 1000).toFixed(1); + fail(`nothing accepted a connection on ${host}:${port} within ${budgetSeconds}s (${elapsedSeconds}s elapsed, ${connectAttempts} attempts; last error: ${lastError})`); } this.logger.warn(`[ConnectionManager] DAP client connect attempt ${connectAttempts} failed: ${lastError}. Retrying in ${CONNECT_RETRY_INTERVAL_MS}ms...`); diff --git a/tests/test-utils/helpers/mcp-stdio-client.ts b/tests/test-utils/helpers/mcp-stdio-client.ts index 1c15e30be..abe0e903b 100644 --- a/tests/test-utils/helpers/mcp-stdio-client.ts +++ b/tests/test-utils/helpers/mcp-stdio-client.ts @@ -11,6 +11,7 @@ * `callToolSafely` that swallows errors — the opposite contract from `call` * below, which asserts); this is the integration-project counterpart. */ +import fs from 'node:fs'; import path from 'node:path'; import { fileURLToPath } from 'node:url'; import { expect } from 'vitest'; @@ -20,6 +21,27 @@ import { StdioClientTransport } from '@modelcontextprotocol/sdk/client/stdio.js' /** The repository root (this file lives at tests/test-utils/helpers/). */ const REPO_ROOT = fileURLToPath(new URL('../../../', import.meta.url)); +/** Remove the direct children of `dir` whose mtime is older than `maxAgeMs`; best effort. */ +function sweepStaleEntries(dir: string, maxAgeMs: number): void { + let entries: string[]; + try { + entries = fs.readdirSync(dir); + } catch { + return; + } + const cutoff = Date.now() - maxAgeMs; + for (const entry of entries) { + const full = path.join(dir, entry); + try { + if (fs.statSync(full).mtimeMs < cutoff) { + fs.rmSync(full, { recursive: true, force: true }); + } + } catch { + // A concurrent suite may be writing here; leave it. + } + } +} + /** * Variables the spawned server must never inherit from the test runner: * vitest's own NODE_OPTIONS, the exit-code shim's channel (#731), debug @@ -106,11 +128,17 @@ export interface StdioClientHandle { */ export async function startStdioClient(options: StdioClientOptions): Promise { const client = new Client({ name: options.name, version: '1' }); - // The server's log, and beside it the per-session proxy logs, under - // logs/tests/ — the path CI's Windows diagnostics artifact collects. Without - // --log-file they land in os.tmpdir(), where a failing launch's connect - // timeline is lost with the runner (issue #963). - const logFile = path.join(REPO_ROOT, 'logs', 'tests', 'stdio', `${options.name}-${process.pid}-${Date.now()}.log`); + // --log-file puts the server's session directory — the per-session proxy + // logs, with a launch's connect timeline — beside the file, under + // logs/tests/, the path CI's Windows diagnostics artifact collects. Without + // it they land in os.tmpdir() and leave with the runner (issue #963). (The + // CLI's own early lines still go to the per-pid default log; it is the + // session directory that matters here.) Nothing else sweeps this directory, + // so entries older than a day go first: the pre-push hook runs these suites + // on every push. + const stdioLogDir = path.join(REPO_ROOT, 'logs', 'tests', 'stdio'); + sweepStaleEntries(stdioLogDir, 24 * 60 * 60 * 1000); + const logFile = path.join(stdioLogDir, `${options.name}-${process.pid}-${Date.now()}.log`); const transport = new StdioClientTransport({ command: process.execPath, args: [path.join(REPO_ROOT, 'dist/index.js'), 'stdio', '--log-file', logFile], diff --git a/tests/unit/proxy/dap-proxy-connection-manager.test.ts b/tests/unit/proxy/dap-proxy-connection-manager.test.ts index 856da9419..03ddadb85 100644 --- a/tests/unit/proxy/dap-proxy-connection-manager.test.ts +++ b/tests/unit/proxy/dap-proxy-connection-manager.test.ts @@ -142,11 +142,75 @@ describe('DapConnectionManager', () => { expect(mockDapClient.connect.mock.calls.length).toBeGreaterThanOrEqual(60); expect(mockDapClient.off).toHaveBeenCalledWith('error', expect.any(Function)); expect(mockDapClient.disconnect).toHaveBeenCalledTimes(1); + // The elapsed time is stated beside the window: one attempt can outlive + // the window (a remote attach host that drops SYNs answers ETIMEDOUT + // after the OS's own ~21 s), and the message must not read as if the + // loop had stopped at 12.5 s. expect(mockLogger.error).toHaveBeenCalledWith( - expect.stringContaining('last error: connect ECONNREFUSED 127.0.0.1:5678') + expect.stringContaining('within 12.5s (12.5s elapsed, 61 attempts; last error: connect ECONNREFUSED 127.0.0.1:5678)') ); }); + it('states the real elapsed time when a single attempt outlives the window (issue #963)', async () => { + // One connect that only settles after 21 s, as a dropped SYN does. + mockDapClient.connect.mockImplementation( + () => new Promise((_resolve, reject) => setTimeout(() => reject(new Error('connect ETIMEDOUT 10.0.0.9:5678')), 21_000)) + ); + + const expectation = expect( + connectionManager.connectWithRetry('10.0.0.9', 5678) + ).rejects.toThrow('nothing accepted a connection on 10.0.0.9:5678 within 12.5s (21.5s elapsed, 1 attempts; last error: connect ETIMEDOUT 10.0.0.9:5678)'); + + await vi.advanceTimersByTimeAsync(500 + 21_000); + await expectation; + }); + + it('keeps reporting the real reason when the client refuses to disconnect (issue #963)', async () => { + mockDapClient.connect.mockRejectedValue(new Error('ECONNREFUSED')); + mockDapClient.disconnect.mockImplementation(() => { + throw new Error('disconnect exploded'); + }); + + const expectation = expect( + connectionManager.connectWithRetry('127.0.0.1', 5678, { budgetMs: 100 }) + ).rejects.toThrow('nothing accepted a connection on 127.0.0.1:5678'); + + await vi.advanceTimersByTimeAsync(100); + await expectation; + + expect(mockLogger.warn).toHaveBeenCalledWith(expect.stringContaining('disconnect exploded')); + }); + + it('quotes at most the last ten stderr lines of an exited adapter, as seen at its exit (issue #963)', async () => { + mockDapClient.connect.mockRejectedValue(new Error('ECONNREFUSED')); + const adapterExit = new AbortController(); + const stderrTail = Array.from({ length: 15 }, (_unused, index) => `line ${index + 1} of the tail`); + adapterExit.abort({ code: 1, signal: null, stderrTail }); + + const failure = await connectionManager.connectWithRetry('127.0.0.1', 5678, { abort: adapterExit.signal }) + .then(() => undefined, (error: Error) => error); + + expect(failure).toBeDefined(); + expect(failure!.message).toContain('Its last stderr lines by the time it exited: line 6 of the tail | '); + expect(failure!.message).not.toContain('line 5 of the tail'); + expect(failure!.message).toContain('line 15 of the tail'); + }); + + it('caps the quoted stderr at the parent\'s 2000 characters, keeping the most recent (issue #963)', async () => { + mockDapClient.connect.mockRejectedValue(new Error('ECONNREFUSED')); + const adapterExit = new AbortController(); + const stderrTail = Array.from({ length: 10 }, (_unused, index) => `line ${index + 1} ${'x'.repeat(300)}`); + adapterExit.abort({ code: 1, signal: null, stderrTail }); + + const failure = await connectionManager.connectWithRetry('127.0.0.1', 5678, { abort: adapterExit.signal }) + .then(() => undefined, (error: Error) => error); + + expect(failure).toBeDefined(); + expect(failure!.message).toContain('line 10 '); + expect(failure!.message).not.toContain('line 1 '); + expect(failure!.message.length).toBeLessThan(2300); + }); + it('makes at least one attempt however small the budget (issue #963)', async () => { mockDapClient.connect.mockRejectedValue(new Error('ECONNREFUSED')); @@ -167,7 +231,7 @@ describe('DapConnectionManager', () => { const expectation = expect( connectionManager.connectWithRetry('127.0.0.1', 5678, { budgetMs: 30_500, abort: adapterExit.signal }) ).rejects.toThrow( - 'Failed to connect DAP client: the adapter process exited (code 1) before it started listening on 127.0.0.1:5678. Its last stderr lines: rdbg: command not found' + 'Failed to connect DAP client: the adapter process exited (code 1) before it started listening on 127.0.0.1:5678. Its last stderr lines by the time it exited: rdbg: command not found' ); await vi.advanceTimersByTimeAsync(500); diff --git a/tests/unit/proxy/proxy-manager.start.test.ts b/tests/unit/proxy/proxy-manager.start.test.ts index 3aedad160..110b05d6a 100644 --- a/tests/unit/proxy/proxy-manager.start.test.ts +++ b/tests/unit/proxy/proxy-manager.start.test.ts @@ -1936,6 +1936,9 @@ describe('ProxyManager.start', () => { it('detaches proxy process listeners when start times out awaiting readiness', async () => { vi.useFakeTimers(); try { + // The stdout drain's listeners are tracked like every other (issue #963). + const stdout = new EventEmitter(); + fakeProcess.stdout = stdout as unknown as NodeJS.ReadableStream; fakeProcess.sendCommand.mockImplementation((cmd: { cmd?: string; sessionId?: string }) => { if (cmd.cmd === 'init') { setTimeout(() => { @@ -1955,6 +1958,9 @@ describe('ProxyManager.start', () => { expect(fakeProcess.listenerCount('exit')).toBe(0); expect(fakeProcess.listenerCount('message')).toBe(0); + expect(stdout.listenerCount('data')).toBe(0); + expect(stdout.listenerCount('end')).toBe(0); + expect(stdout.listenerCount('close')).toBe(0); } finally { vi.useRealTimers(); }