diff --git a/src/proxy/proxy-manager.ts b/src/proxy/proxy-manager.ts index 86bee51d..1f8a6436 100644 --- a/src/proxy/proxy-manager.ts +++ b/src/proxy/proxy-manager.ts @@ -691,64 +691,88 @@ export class ProxyManager extends EventEmitter implements IProxyManager { const delays = [500, 1000, 2000, 4000, 8000]; // More generous backoff for Windows CI let lastError: Error | undefined; - for (let attempt = 0; attempt <= maxRetries; attempt++) { - const timeoutMs = delays[Math.min(attempt, delays.length - 1)]; - - try { - const received = await new Promise((resolve, reject) => { - let resolved = false; - - const handler = () => { - if (resolved) return; - resolved = true; - // Detach on success too — this listener is registered with on(), - // and each un-removed acknowledgment handler would otherwise stay - // on the manager for its lifetime (issue #420). - cleanup(); - resolve(true); - }; - - const cleanup = () => { - this.removeListener('init-received', handler); - if (timer) clearTimeout(timer); - }; - - this.on('init-received', handler); - - const timer = setTimeout(() => { - if (resolved) return; - resolved = true; - this.removeListener('init-received', handler); - resolve(false); - }, timeoutMs); - - try { - this.sendCommand(initCommand); - } catch (error) { - cleanup(); - reject(error); - } - }); + // Latch the ack for the whole retry sequence (issue #512): the worker + // acks exactly once, and on a slow boot (>500ms — inspected or heavily + // loaded host) that ack lands between attempt windows. A per-attempt + // listener silently drops it, and for a worker that then exits (dry-run) + // every remaining retry fails against a process that already did its job. + let acked = false; + const onAck = () => { + acked = true; + }; + this.on('init-received', onAck); + + // Wait up to ms, ending early (true) the moment the ack arrives — or + // immediately when it was already latched by the long-lived listener + const waitForAck = (ms: number): Promise => + new Promise((resolve) => { + if (acked) { + resolve(true); + return; + } + let settled = false; + const settle = (value: boolean) => { + if (settled) return; + settled = true; + clearTimeout(timer); + this.removeListener('init-received', onAckNow); + resolve(value); + }; + const onAckNow = () => settle(true); + this.on('init-received', onAckNow); + const timer = setTimeout(() => settle(false), ms); + }); - if (received) { - this.logger.info(`[ProxyManager] Init command acknowledged on attempt ${attempt + 1}`); + try { + for (let attempt = 0; attempt <= maxRetries; attempt++) { + if (acked) { + this.logger.info(`[ProxyManager] Init command acknowledged before attempt ${attempt + 1}`); return; } + const timeoutMs = delays[Math.min(attempt, delays.length - 1)]; + + let sendFailed = false; + try { + this.sendCommand(initCommand); + } catch (error) { + lastError = error as Error; + sendFailed = true; + this.logger.warn( + `[ProxyManager] Error sending init on attempt ${attempt + 1}: ${lastError.message}` + ); + // Once the worker has exited without acking, no ack can arrive — + // fail fast with the detailed exit message instead of burning the + // remaining retries against a process that is gone (issue #512) + if (this.lastExitDetails) { + break; + } + } - this.logger.warn( - `[ProxyManager] Init not acknowledged, attempt ${attempt + 1}/${maxRetries + 1}` - ); - } catch (error) { - lastError = error as Error; - this.logger.warn( - `[ProxyManager] Error sending init on attempt ${attempt + 1}: ${lastError.message}` - ); - } + // A failed send delivered nothing to wait for; an earlier attempt's + // late ack is still caught by the latch during the backoff below + if (!sendFailed) { + if (await waitForAck(timeoutMs)) { + this.logger.info(`[ProxyManager] Init command acknowledged on attempt ${attempt + 1}`); + return; + } + + this.logger.warn( + `[ProxyManager] Init not acknowledged, attempt ${attempt + 1}/${maxRetries + 1}` + ); + } - if (attempt < maxRetries) { - const waitMs = delays[Math.min(attempt, delays.length - 1)]; - await new Promise((resolve) => setTimeout(resolve, waitMs)); + if (attempt < maxRetries) { + const waitMs = delays[Math.min(attempt, delays.length - 1)]; + if (await waitForAck(waitMs)) { + this.logger.info( + `[ProxyManager] Init command acknowledged during backoff after attempt ${attempt + 1}` + ); + return; + } + } } + } finally { + this.removeListener('init-received', onAck); } let detailMessage = `Failed to initialize proxy after ${maxRetries + 1} attempts. ${ diff --git a/tests/unit/proxy/proxy-manager.handshake.test.ts b/tests/unit/proxy/proxy-manager.handshake.test.ts index a9e016ea..8d488a30 100644 --- a/tests/unit/proxy/proxy-manager.handshake.test.ts +++ b/tests/unit/proxy/proxy-manager.handshake.test.ts @@ -61,31 +61,93 @@ describe('ProxyManager sendInitWithRetry', () => { expect(sendCommandMock).toHaveBeenCalledTimes(1); }); - it('retries when acknowledgement arrives after the first timeout', async () => { + it('latches an acknowledgement that lands between attempt windows (issue #512)', async () => { + vi.useFakeTimers(); + // The worker acks once, 600ms after the init send — after attempt 1's + // 500ms window expired, during the backoff sleep. Pre-#512 this ack was + // dropped (its listener had been removed) and the whole launch failed if + // the worker then exited; now it resolves the retry loop without a resend. + const sendCommandMock = vi + .spyOn(manager as unknown as { sendCommand: (command: object) => void }, 'sendCommand') + .mockImplementationOnce(() => { + setTimeout(() => (manager as unknown as EventEmitter).emit('init-received'), 600); + }); + + const initPromise = (manager as unknown as { sendInitWithRetry: (command: object) => Promise }).sendInitWithRetry( + { cmd: 'init' } + ); + + vi.advanceTimersByTime(500); // attempt 1 window expires without the ack + await Promise.resolve(); + vi.advanceTimersByTime(100); // ack fires during the backoff sleep + await Promise.resolve(); + await initPromise; + + expect(sendCommandMock).toHaveBeenCalledTimes(1); + }); + + it('retries and resolves when only a later attempt is acknowledged', async () => { vi.useFakeTimers(); let attempt = 0; const sendCommandMock = vi .spyOn(manager as unknown as { sendCommand: (command: object) => void }, 'sendCommand') .mockImplementation(() => { attempt += 1; - const delay = attempt === 1 ? 600 : 100; - setTimeout(() => (manager as unknown as EventEmitter).emit('init-received'), delay); + if (attempt === 2) { + setTimeout(() => (manager as unknown as EventEmitter).emit('init-received'), 100); + } + // attempt 1: message lost entirely — no ack ever fires for it }); const initPromise = (manager as unknown as { sendInitWithRetry: (command: object) => Promise }).sendInitWithRetry( { cmd: 'init' } ); - vi.advanceTimersByTime(600); // first ack (lost) + first timeout (500) + vi.advanceTimersByTime(500); // attempt 1 window expires await Promise.resolve(); vi.advanceTimersByTime(500); // backoff before retry await Promise.resolve(); - vi.advanceTimersByTime(100); // second attempt acknowledges + vi.advanceTimersByTime(100); // attempt 2 acknowledges await Promise.resolve(); await initPromise; expect(sendCommandMock).toHaveBeenCalledTimes(2); }); + it('fails fast once the worker has exited without acking (issue #512)', async () => { + vi.useFakeTimers(); + let attempt = 0; + const sendCommandMock = vi + .spyOn(manager as unknown as { sendCommand: (command: object) => void }, 'sendCommand') + .mockImplementation(() => { + attempt += 1; + if (attempt > 1) { + // Worker exited between attempts; ProxyManager recorded the exit + (manager as unknown as { lastExitDetails: unknown }).lastExitDetails = { + code: 1, + signal: null, + timestamp: Date.now(), + capturedStderr: ['boom'], + }; + throw new Error('Proxy process not available'); + } + }); + + const initPromise = (manager as unknown as { sendInitWithRetry: (command: object) => Promise }).sendInitWithRetry( + { cmd: 'init' } + ); + const rejection = expect(initPromise).rejects.toThrow('Proxy exit details -> code=1'); + + vi.advanceTimersByTime(500); // attempt 1 window expires + await Promise.resolve(); + vi.advanceTimersByTime(500); // backoff, then attempt 2's send throws + await Promise.resolve(); + + // No further windows/backoffs are burned: the loop breaks on the dead + // worker instead of retrying four more times over ~15s + await rejection; + expect(sendCommandMock).toHaveBeenCalledTimes(2); + }); + it('throws after exhausting retries when acknowledgement never arrives', async () => { vi.useFakeTimers(); const sendCommandMock = vi diff --git a/tests/unit/proxy/proxy-manager.start.test.ts b/tests/unit/proxy/proxy-manager.start.test.ts index 6a13f095..181930c6 100644 --- a/tests/unit/proxy/proxy-manager.start.test.ts +++ b/tests/unit/proxy/proxy-manager.start.test.ts @@ -491,36 +491,33 @@ describe('ProxyManager.start', () => { expect(logger.warn).toHaveBeenCalledWith(expect.stringContaining('Error sending init on attempt 1')); }); - it('surfaces detailed error after exhausting init retries', async () => { + it('surfaces detailed error and fails fast once the worker exited without acking (issue #512)', async () => { fakeProcess.sendCommand.mockReset(); - fakeProcess.sendCommand.mockImplementation(() => { - throw new Error('ipc failure'); - }); - - (proxyManager as unknown as { - lastExitDetails: { - code: number | null; - signal: string | null; - timestamp: number; - capturedStderr: string[]; - }; - }).lastExitDetails = { - code: 12, - signal: 'SIGTERM', - timestamp: Date.now(), - capturedStderr: ['fatal: adapter crashed'] - }; + fakeProcess.sendCommand + .mockImplementationOnce(() => { + // First init is delivered but never acked; the worker dies shortly + // after — handleProxyExit records lastExitDetails + setTimeout(() => fakeProcess.emit('exit', 12, 'SIGTERM'), 100); + }) + .mockImplementation(() => { + throw new Error('Proxy process not available'); + }); const startPromise = proxyManager.start(baseConfig); // Attach the rejection expectation BEFORE driving the rejection: the // async fake-timer loop yields through real ticks, where an unhandled // rejection would otherwise be flagged (issue #420). - const rejection = expect(startPromise).rejects.toThrow(/Failed to initialize proxy after 6 attempts\. Last error: ipc failure/); - await vi.advanceTimersByTimeAsync(16500); + // With exit details recorded, retrying is pointless (no ack can arrive + // from an exited worker) — the failure surfaces on attempt 2's failed + // send instead of burning ~15s of retries (issue #512), and carries + // the exit details. + const rejection = expect(startPromise).rejects.toThrow(/Failed to initialize proxy after 6 attempts\. Last error: Proxy process not available[\s\S]*code=12 signal=SIGTERM/); + await vi.advanceTimersByTimeAsync(8000); await rejection; - expect(logger.warn).toHaveBeenCalledWith(expect.stringContaining('Error sending init on attempt 6')); + expect(logger.warn).toHaveBeenCalledWith(expect.stringContaining('Error sending init on attempt 2')); + expect(logger.warn).not.toHaveBeenCalledWith(expect.stringContaining('Error sending init on attempt 3')); }); });