diff --git a/changelog.d/963.fixed.md b/changelog.d/963.fixed.md new file mode 100644 index 00000000..5f15e0fb --- /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 2ecf886d..340efae3 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 a38724bb..c1f167e0 100644 --- a/docs/patterns/event-management.md +++ b/docs/patterns/event-management.md @@ -172,6 +172,16 @@ 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, through the same sanitizer as stderr. + this.proxyProcess.stdout?.on('data', (data: Buffer | string) => { + for (const line of sanitizeStderr([data.toString().trim()])) { + this.logger.debug(`[ProxyManager STDOUT] ${line}`); + } + }); + // 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 5346b92a..f3efce41 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 fa113c3f..fd1b151f 100644 --- a/src/proxy/dap-proxy-connection-manager.ts +++ b/src/proxy/dap-proxy-connection-manager.ts @@ -13,19 +13,109 @@ 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 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) + ? (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})` : ''; + 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 { - // 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 +124,74 @@ 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. 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}`); + }; + + 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 +199,24 @@ 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) { + // 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...`); + 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 7ef86c8c..83eb9f34 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 460f545b..b205e39e 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 8e58985d..0c90b04e 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 8356de68..1e4773bb 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 5cd17f62..96a6afd9 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 20f4e672..ae936377 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 ae02172a..abe0e903 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,9 +128,20 @@ export interface StdioClientHandle { */ export async function startStdioClient(options: StdioClientOptions): Promise { const client = new Client({ name: options.name, version: '1' }); + // --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'], + 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 8f486cdc..03ddadb8 100644 --- a/tests/unit/proxy/dap-proxy-connection-manager.test.ts +++ b/tests/unit/proxy/dap-proxy-connection-manager.test.ts @@ -103,30 +103,170 @@ 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); + // 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('Failed to connect DAP client after 60 attempts') + 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')); + + 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 by the time it exited: 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 () => { let tempErrorHandler: ((error: Error) => void) | undefined; mockDapClient.on.mockImplementation((event: string, handler: (error: Error) => void) => { @@ -211,11 +351,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 b9071d6d..b18ae1cc 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 84237fd9..110b05d6 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); @@ -1892,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(() => { @@ -1911,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(); }