Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions changelog.d/963.fixed.md
Original file line number Diff line number Diff line change
@@ -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).
2 changes: 2 additions & 0 deletions docs/logging-format-specification.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
10 changes: 10 additions & 0 deletions docs/patterns/event-management.md
Original file line number Diff line number Diff line change
Expand Up @@ -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}`);
Expand Down
3 changes: 2 additions & 1 deletion docs/troubleshooting.md
Original file line number Diff line number Diff line change
Expand Up @@ -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).
Expand Down
188 changes: 165 additions & 23 deletions src/proxy/dap-proxy-connection-manager.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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<void> {
return new Promise<void>((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<AdapterExitReason>)
: 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
*/
Expand All @@ -34,47 +124,99 @@ 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<IDapClient> {
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<IDapClient> {
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.');

// Remove temporary handler as connection succeeded
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);
}
}

Expand Down
9 changes: 9 additions & 0 deletions src/proxy/dap-proxy-interfaces.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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?: {
Expand Down
12 changes: 12 additions & 0 deletions src/proxy/dap-proxy-message-parser.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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`);
}
Expand Down
Loading
Loading