diff --git a/packages/platform-apple/src/runner/__tests__/runner-command-busy-resend.test.ts b/packages/platform-apple/src/runner/__tests__/runner-command-busy-resend.test.ts new file mode 100644 index 0000000000..3c5fa48440 --- /dev/null +++ b/packages/platform-apple/src/runner/__tests__/runner-command-busy-resend.test.ts @@ -0,0 +1,243 @@ +import { beforeEach, test, vi } from 'vitest'; +import assert from 'node:assert/strict'; +import { IOS_SIMULATOR } from './device-fixtures.ts'; +import { createTestRequestCancellation, makeRunnerSession } from './runner-session-fixtures.ts'; +import { AppError, isRequestCanceledError } from '@agent-device/kernel/errors'; +import { appleRunnerTestHost } from '../test-host.ts'; + +// The read-only resend policy around a `RUNNER_BUSY` refusal. The runner refuses fast while +// watchdog-abandoned XCTest work drains, so the daemon's resend has to outlast that drain, keep +// the old three-attempt budget for transport failures, and stay cancellable across the seconds it +// may now wait. + +const { + mockEnsureRunnerSession, + mockExecuteRunnerCommandWithSession, + mockReadRunnerSessionLiveness, + mockInvalidateRunnerSession, +} = vi.hoisted(() => ({ + mockEnsureRunnerSession: vi.fn(), + mockExecuteRunnerCommandWithSession: vi.fn(), + mockReadRunnerSessionLiveness: vi.fn(), + mockInvalidateRunnerSession: vi.fn(), +})); + +vi.mock('../runner-session.ts', async () => { + const actual = + await vi.importActual('../runner-session.ts'); + return { + ...actual, + ensureRunnerSession: mockEnsureRunnerSession, + executeRunnerCommandWithSession: mockExecuteRunnerCommandWithSession, + readRunnerSessionLiveness: mockReadRunnerSessionLiveness, + invalidateRunnerSession: mockInvalidateRunnerSession, + }; +}); + +import { runAppleRunnerCommand } from '../runner-client.ts'; +import { buildRunnerResponseError } from '../runner-contract.ts'; +import { resetRunnerRecycleLedgerForTests } from '../runner-recycle-ledger.ts'; + +const requestCancellation = createTestRequestCancellation(); + +beforeEach(() => { + vi.resetAllMocks(); + vi.useRealTimers(); + resetRunnerRecycleLedgerForTests(); + requestCancellation.reset(); + appleRunnerTestHost.update({ + emitDiagnostic: vi.fn(), + isRequestCanceled: requestCancellation.isRequestCanceled, + getRequestSignal: () => undefined, + }); + const session = makeRunnerSession({ state: 'ready' }); + mockEnsureRunnerSession.mockResolvedValue(session); + // A live session, or `executeRunnerCommand` reads the resend as a recycle boot and charges the + // per-request recycle budget instead of resending. + mockReadRunnerSessionLiveness.mockReturnValue({ + sessionId: session.sessionId, + liveness: 'ready', + }); +}); + +/** The runner's live refusal, exactly as the transport decodes it. */ +function busyRefusal(): AppError { + return buildRunnerResponseError({ + ok: false, + error: { code: 'RUNNER_BUSY', message: 'The iOS runner is still finishing a previous command' }, + }); +} + +function sentCommands(): string[] { + return mockExecuteRunnerCommandWithSession.mock.calls.map((call) => call[2].command); +} + +test('read-only commands wait out RUNNER_BUSY past the transport resend backoff', async () => { + // Three busy answers spaced 200/400/800ms apart, then the runner answers. The default three + // attempts stopped after the second delay, before the abandoned work had drained. + vi.useFakeTimers(); + mockExecuteRunnerCommandWithSession + .mockRejectedValueOnce(busyRefusal()) + .mockRejectedValueOnce(busyRefusal()) + .mockRejectedValueOnce(busyRefusal()) + .mockResolvedValueOnce({ nodes: [], truncated: false }); + + const pending = runAppleRunnerCommand(IOS_SIMULATOR, { command: 'snapshot' }); + await vi.advanceTimersByTimeAsync(6_000); + const result = await pending; + + assert.deepEqual(result, { nodes: [], truncated: false }); + assert.equal(mockInvalidateRunnerSession.mock.calls.length, 0); + // A structured refusal already says the command did not run, so no status probe sits between + // the resends. + assert.deepEqual(sentCommands(), ['snapshot', 'snapshot', 'snapshot', 'snapshot']); +}); + +test('a RUNNER_BUSY resend still ends when the refusals outlast the window', async () => { + vi.useFakeTimers(); + mockExecuteRunnerCommandWithSession.mockImplementation(async () => { + throw busyRefusal(); + }); + + const pending = runAppleRunnerCommand(IOS_SIMULATOR, { command: 'snapshot' }); + const settled = pending.then( + () => undefined, + (error: unknown) => error, + ); + await vi.advanceTimersByTimeAsync(20_000); + const error = await settled; + + assert.ok(error instanceof AppError); + assert.equal(error.details?.runnerErrorCode, 'RUNNER_BUSY'); + assert.equal(error.details?.recovery, undefined, 'the raw refusal reaches the caller unwrapped'); + assert.deepEqual(sentCommands(), Array(8).fill('snapshot')); +}); + +test('read-only transport failures keep the three-attempt resend budget', async () => { + mockExecuteRunnerCommandWithSession + .mockRejectedValueOnce(new AppError('COMMAND_FAILED', 'fetch failed')) + .mockResolvedValueOnce({ lifecycleState: 'started' }) + .mockRejectedValueOnce(new AppError('COMMAND_FAILED', 'fetch failed')) + .mockResolvedValueOnce({ lifecycleState: 'started' }) + .mockRejectedValueOnce(new AppError('COMMAND_FAILED', 'fetch failed')) + .mockResolvedValueOnce({ lifecycleState: 'started' }) + .mockResolvedValueOnce({ nodes: [], truncated: false }); + + await assert.rejects( + () => runAppleRunnerCommand(IOS_SIMULATOR, { command: 'snapshot' }), + (error: unknown) => { + assert.ok(error instanceof AppError); + assert.equal(error.message, 'fetch failed'); + return true; + }, + ); + + assert.equal(sentCommands().filter((command) => command === 'snapshot').length, 3); +}); + +test('a wait deadline landing mid-window rethrows the last RUNNER_BUSY refusal, not a cancel', async () => { + // `wait` bounds each poll with its own abort signal (runWithinWaitDeadline) and keeps the last + // typed refusal as the wait's cause. The refusal must therefore survive the deadline: a bare + // cancellation would make the wait report a stalled capture and drop the runner's own code. + vi.useFakeTimers(); + const deadline = new AbortController(); + mockExecuteRunnerCommandWithSession + .mockRejectedValueOnce(busyRefusal()) + .mockResolvedValue({ nodes: [], truncated: false }); + + const pending = runAppleRunnerCommand( + IOS_SIMULATOR, + { command: 'snapshot' }, + { requestId: 'req-wait', signal: deadline.signal }, + ); + const settled = pending.then( + () => undefined, + (error: unknown) => error, + ); + await vi.advanceTimersByTimeAsync(50); + deadline.abort(new DOMException('Wait deadline exceeded', 'TimeoutError')); + await vi.advanceTimersByTimeAsync(0); + const error = await settled; + + assert.ok(error instanceof AppError, `expected the refusal, got ${String(error)}`); + assert.equal(error.details?.runnerErrorCode, 'RUNNER_BUSY'); + assert.equal(error.details?.retriable, true); + assert.deepEqual(sentCommands(), ['snapshot']); +}); + +test('a wait deadline landing mid-fetch during a resend still rethrows the RUNNER_BUSY refusal', async () => { + vi.useFakeTimers(); + const deadline = new AbortController(); + mockExecuteRunnerCommandWithSession.mockRejectedValueOnce(busyRefusal()).mockImplementationOnce( + (_device, _session, _command, _logPath, _timeoutMs, signal: AbortSignal | undefined) => + new Promise((_resolve, reject) => { + signal?.addEventListener('abort', () => reject(signal.reason), { once: true }); + }), + ); + + const pending = runAppleRunnerCommand( + IOS_SIMULATOR, + { command: 'snapshot' }, + { requestId: 'req-wait-mid-fetch', signal: deadline.signal }, + ); + const settled = pending.then( + () => undefined, + (error: unknown) => error, + ); + // Past the first 200ms delay: the second send is in flight when the deadline lands. + await vi.advanceTimersByTimeAsync(250); + deadline.abort(new DOMException('Wait deadline exceeded', 'TimeoutError')); + await vi.advanceTimersByTimeAsync(0); + const error = await settled; + + assert.ok(error instanceof AppError, `expected the refusal, got ${String(error)}`); + assert.equal(error.details?.runnerErrorCode, 'RUNNER_BUSY'); + assert.deepEqual(sentCommands(), ['snapshot', 'snapshot']); +}); + +test('a cancelled request wakes the RUNNER_BUSY delay and reports the cancellation', async () => { + vi.useFakeTimers(); + const request = new AbortController(); + appleRunnerTestHost.update({ getRequestSignal: () => request.signal }); + mockExecuteRunnerCommandWithSession + .mockRejectedValueOnce(busyRefusal()) + .mockResolvedValue({ nodes: [], truncated: false }); + + const pending = runAppleRunnerCommand( + IOS_SIMULATOR, + { command: 'snapshot' }, + { requestId: 'req-cancelled' }, + ); + const settled = pending.then( + () => undefined, + (error: unknown) => error, + ); + // Inside the first 200ms delay; the next attempt would otherwise succeed at the timer. + await vi.advanceTimersByTimeAsync(50); + requestCancellation.markRequestCanceled('req-cancelled'); + request.abort(); + await vi.advanceTimersByTimeAsync(0); + const error = await settled; + + assert.ok(isRequestCanceledError(error), `expected a canceled request, got ${String(error)}`); + assert.deepEqual(sentCommands(), ['snapshot']); +}); + +test('a mutating command meets RUNNER_BUSY once, with no status probe and no resend', async () => { + // The status-recovery bypass for structured replies reaches mutating commands too: the refusal + // says the tap did not run, so there is nothing to recover and nothing is replayed. + mockExecuteRunnerCommandWithSession.mockRejectedValueOnce(busyRefusal()); + + await assert.rejects( + () => runAppleRunnerCommand(IOS_SIMULATOR, { command: 'tap', x: 120, y: 240 }), + (error: unknown) => { + assert.ok(error instanceof AppError); + assert.equal(error.details?.runnerErrorCode, 'RUNNER_BUSY'); + assert.equal(error.details?.recovery, undefined); + return true; + }, + ); + + assert.deepEqual(sentCommands(), ['tap']); + assert.equal(mockInvalidateRunnerSession.mock.calls.length, 0); +}); diff --git a/packages/platform-apple/src/runner/__tests__/runner-error-classification.test.ts b/packages/platform-apple/src/runner/__tests__/runner-error-classification.test.ts index f1936ad802..64b379f792 100644 --- a/packages/platform-apple/src/runner/__tests__/runner-error-classification.test.ts +++ b/packages/platform-apple/src/runner/__tests__/runner-error-classification.test.ts @@ -8,6 +8,7 @@ import { import { RUNNER_ERROR_RULES, isRetryableRunnerError, + isRunnerBusyError, resolveRunnerFatalErrorReason, shouldRebuildCachedRunnerArtifact, shouldRestartRunnerAfterReadinessPreflight, @@ -301,3 +302,27 @@ test('a refused screen capture keeps the runner reason and stays off the wire co assert.equal(classified.details.retriable, undefined); } }); + +// --- busy refusal (isRunnerBusyError) --- + +test('only the typed RUNNER_BUSY refusal reads as busy', () => { + assert.equal( + isRunnerBusyError(commandFailed('runner is busy', { runnerErrorCode: 'RUNNER_BUSY' })), + true, + ); + // The stalling command's own timeout already spent its wait: not a refusal to resend. + assert.equal( + isRunnerBusyError( + commandFailed('main thread execution timed out', { runnerErrorCode: 'MAIN_THREAD_TIMEOUT' }), + ), + false, + ); + assert.equal( + isRunnerBusyError( + commandFailed('The iOS runner is still finishing a previous command', { retriable: true }), + ), + false, + ); + assert.equal(isRunnerBusyError(commandFailed('RUNNER_BUSY')), false); + assert.equal(isRunnerBusyError(new Error('RUNNER_BUSY')), false); +}); diff --git a/packages/platform-apple/src/runner/runner-client.ts b/packages/platform-apple/src/runner/runner-client.ts index a32b352463..76bcc29388 100644 --- a/packages/platform-apple/src/runner/runner-client.ts +++ b/packages/platform-apple/src/runner/runner-client.ts @@ -1,4 +1,4 @@ -import { retryWithPolicy, emitDiagnostic } from './host.ts'; +import { retryWithPolicy, emitDiagnostic, getRequestSignal, isRequestCanceled } from './host.ts'; import { isIosFamily, type DeviceInfo } from '@agent-device/kernel/device'; import { ensureRunnerSession, @@ -9,10 +9,11 @@ import { } from './runner-session.ts'; import { assertRunnerRequestActive, + resolveRunnerRequestSignal, withRunnerCommandId, type RunnerCommand, } from './runner-contract.ts'; -import { isRetryableRunnerError } from './runner-error-classification.ts'; +import { isRetryableRunnerError, isRunnerBusyError } from './runner-error-classification.ts'; import { isReadOnlyRunnerCommand } from './runner-command-traits.ts'; import { createLocalAppleRunnerProvider, @@ -32,6 +33,45 @@ import { RUNNER_COMMAND_TIMEOUT_MS } from './runner-transport.ts'; // --- Runner command execution --- +/** + * Attempts a read-only command may spend on one error class; 1 means no resend. A `RUNNER_BUSY` + * refusal is the runner refusing fast on purpose while it drains abandoned XCTest work (#1105), so + * that budget has to outlast the drain. The window is a heuristic, not a measurement: 200ms doubling + * to a 1s cap, no jitter, is 5.4s of delay across eight attempts before round trips, and a drain + * that outlives it still surfaces as `RUNNER_BUSY` (the runner's own `abandonedForSeconds=` marker + * in runner.log is the evidence for tuning it). Transport failures keep the pre-existing three + * attempts. The budget is positional: the error on each attempt sets how many attempts the loop may + * reach in total, so three busy refusals followed by a transport failure resend no further. + */ +const RUNNER_BUSY_RESEND_ATTEMPTS = 8; +const TRANSPORT_RESEND_ATTEMPTS = 3; +const READ_ONLY_RESEND_POLICY = { + maxAttempts: RUNNER_BUSY_RESEND_ATTEMPTS, + baseDelayMs: 200, + maxDelayMs: 1_000, + jitter: 0, +}; + +function readOnlyResendBudget(error: unknown): number { + if (isRunnerBusyError(error)) return RUNNER_BUSY_RESEND_ATTEMPTS; + return isRetryableRunnerError(error) ? TRANSPORT_RESEND_ATTEMPTS : 1; +} + +/** + * Whether the caller's own deadline ended this command, as opposed to the request being cancelled. + * A `wait` bounds each poll with an abort signal whose reason is a `TimeoutError` + * (`runWithinWaitDeadline`); a cancelled request aborts through the registered request signal or + * the cancellation registry. The typed reason decides, so a deadline that lands mid-fetch (surfacing + * as whatever the transport threw on abort) is read the same way as one that wakes a delay. + */ +function callerDeadlineExpired(options: AppleRunnerCommandOptions): boolean { + if (isRequestCanceled(options.requestId) || getRequestSignal(options.requestId)?.aborted) { + return false; + } + const reason: unknown = options.signal?.aborted ? options.signal.reason : undefined; + return reason instanceof DOMException && reason.name === 'TimeoutError'; +} + export async function runAppleRunnerCommand( device: DeviceInfo, command: RunnerCommand, @@ -41,21 +81,35 @@ export async function runAppleRunnerCommand( assertRunnerRequestActive(options.requestId); const runnerCommand = withRunnerCommandId(command); const provider = resolveAppleRunnerRuntime(device, options); - if (isReadOnlyRunnerCommand(runnerCommand)) { - return retryWithPolicy( + if (!isReadOnlyRunnerCommand(runnerCommand)) { + return provider.runCommand(device, runnerCommand, options); + } + let lastBusyRefusal: unknown; + try { + return await retryWithPolicy( () => { assertRunnerRequestActive(options.requestId); return provider.runCommand(device, runnerCommand, options); }, { - shouldRetry: (error) => { + ...READ_ONLY_RESEND_POLICY, + shouldRetry: (error, attempt) => { assertRunnerRequestActive(options.requestId); - return isRetryableRunnerError(error); + if (isRunnerBusyError(error)) lastBusyRefusal = error; + return attempt < readOnlyResendBudget(error); }, }, + // The busy window is seconds long, so an abort must wake the delay instead of sleeping it + // out and sending one more attempt. + { signal: resolveRunnerRequestSignal(options) }, ); + } catch (error) { + // A caller's deadline (a `wait` poll bounding this capture) that lands mid-window still has an + // answer: the runner refused, and that typed refusal is what the caller can act on. Only a + // cancelled request reports as a bare cancellation. + if (lastBusyRefusal && callerDeadlineExpired(options)) throw lastBusyRefusal; + throw error; } - return provider.runCommand(device, runnerCommand, options); } export async function notifyIosRunnerAppRelaunched( diff --git a/packages/platform-apple/src/runner/runner-error-classification.ts b/packages/platform-apple/src/runner/runner-error-classification.ts index 9d5fca5d2c..aa8e1c072b 100644 --- a/packages/platform-apple/src/runner/runner-error-classification.ts +++ b/packages/platform-apple/src/runner/runner-error-classification.ts @@ -72,6 +72,8 @@ type RunnerErrorMatch = { const hasRetriableFlag: RunnerErrorDetailsMatch = (details) => details.retriable === true; const hasAppNotRunningRunnerCode: RunnerErrorDetailsMatch = (details) => details.runnerErrorCode === APP_NOT_RUNNING_RUNNER_CODE; +const hasRunnerBusyCode: RunnerErrorDetailsMatch = (details) => + details.runnerErrorCode === RUNNER_BUSY_RUNNER_CODE; /** * The host's own `DevToolsSecurity -status` read, published as typed details by the probe that * takes it. The build-failure rule below keys on this field and never on the probe's message, so @@ -95,8 +97,14 @@ const hasReadinessPreflightFailure: RunnerErrorDetailsMatch = (details) => details.runnerReadinessPreflightFailed === true && !isRequestCanceledDetails(details); type RunnerErrorVerdicts = { - /** isRetryableRunnerError: transport error worth a same-session resend. */ + /** + * isRetryableRunnerError: worth a same-session resend, either a transport failure or a structured + * refusal that executed nothing. Whether a lost response needs status recovery is a separate + * question ({@link isStructuredRunnerFailure}). + */ retryable?: boolean; + /** isRunnerBusyError: the runner refused fast while abandoned main-thread work drains. */ + drainResend?: boolean; /** shouldRetryRunnerConnectError: connect loop may keep waiting for the runner. */ connectRetry?: boolean; /** Session-fatal classification: invalidate the cached runner session with this reason. */ @@ -219,6 +227,13 @@ export const RUNNER_ERROR_RULES: readonly RunnerErrorRule[] = [ match: { code: 'COMMAND_FAILED', details: hasAppNotRunningRunnerCode }, verdicts: { retryable: false, connectRetry: false }, }, + { + // Named before the generic retriable flag so diagnostics say what refused, not that a flag + // was set. Nothing ran: the runner answered before dispatching the command (#1105). + reason: 'runner_busy_refusal', + match: { code: 'COMMAND_FAILED', details: hasRunnerBusyCode }, + verdicts: { retryable: true, connectRetry: true, drainResend: true }, + }, { reason: 'flagged_retriable', match: { code: 'COMMAND_FAILED', details: hasRetriableFlag }, @@ -512,14 +527,31 @@ export function isRetryableRunnerError(err: unknown): boolean { * `details.runnerErrorCode`), so family policy reads the typed detail rather than the message. */ export function isRunnerMainThreadOccupiedError(error: unknown): boolean { - if (!(error instanceof AppError)) return false; - const runnerErrorCode = error.details?.runnerErrorCode; + if (isRunnerBusyError(error)) return true; return ( - runnerErrorCode === RUNNER_BUSY_RUNNER_CODE || - runnerErrorCode === MAIN_THREAD_TIMEOUT_RUNNER_CODE + error instanceof AppError && error.details?.runnerErrorCode === MAIN_THREAD_TIMEOUT_RUNNER_CODE ); } +/** + * True when the runner refused this command outright because watchdog-abandoned XCTest work still + * occupies its main thread (`RUNNER_BUSY`). Nothing was executed, so a read-only caller may resend + * once the work drains; `MAIN_THREAD_TIMEOUT` is deliberately excluded because that command already + * spent its wait. + */ +export function isRunnerBusyError(error: unknown): boolean { + return runnerErrorVerdict(error, 'drainResend') ?? false; +} + +/** + * True when the runner answered with a structured failure: the reply itself carries the runner's + * payload, so the command's outcome is known and no lifecycle status probe is needed to recover it. + * A transport-shaped failure (aborted body, malformed payload, refused connection) answered nothing. + */ +export function isStructuredRunnerFailure(error: unknown): boolean { + return error instanceof AppError && error.details?.runner !== undefined; +} + /** * True when usbmuxd answered and the device is simply not attached by cable. * A CoreDevice-backed device falls back to its network tunnel; an XCTest-backed diff --git a/packages/platform-apple/src/runner/runner-lifecycle.ts b/packages/platform-apple/src/runner/runner-lifecycle.ts index aa06dcd967..1cb4884a6f 100644 --- a/packages/platform-apple/src/runner/runner-lifecycle.ts +++ b/packages/platform-apple/src/runner/runner-lifecycle.ts @@ -21,6 +21,7 @@ import { } from './runner-contract.ts'; import { isRetryableRunnerError, + isStructuredRunnerFailure, shouldRebuildCachedRunnerArtifact, shouldRestartRunnerAfterReadinessPreflight, shouldRestartRunnerBeforeCommandSend, @@ -327,7 +328,10 @@ export async function executeRunnerCommand( recoveredDiagnosticPhase: 'ios_runner_readiness_preflight_recovered', }); } - if (session && isRetryableRunnerError(appErr)) { + // Status recovery answers "did the command I lost the response to run?". A structured reply + // (a RUNNER_BUSY refusal, for one) already answered, so it is rethrown for the caller's own + // resend policy instead of paying a status round trip per attempt. + if (session && isRetryableRunnerError(appErr) && !isStructuredRunnerFailure(appErr)) { return await handleRunnerTransportErrorAfterCommandSend({ device, session, @@ -394,7 +398,7 @@ async function restartSessionAndRunCommand(params: { return recovered; } catch (error) { const retryAppErr = asAppError(error, 'COMMAND_FAILED'); - if (isRetryableRunnerError(retryAppErr)) { + if (isRetryableRunnerError(retryAppErr) && !isStructuredRunnerFailure(retryAppErr)) { try { return await handleRunnerTransportErrorAfterCommandSend({ device, diff --git a/packages/platform-apple/src/runner/runner-session.ts b/packages/platform-apple/src/runner/runner-session.ts index e27b692034..c8f655733b 100644 --- a/packages/platform-apple/src/runner/runner-session.ts +++ b/packages/platform-apple/src/runner/runner-session.ts @@ -43,6 +43,7 @@ import { import { resolveRunnerFatalErrorReason, isRunnerMainThreadOccupiedError, + isStructuredRunnerFailure, enrichRunnerStartupFailureWithDeviceStates, } from './runner-error-classification.ts'; import { @@ -977,10 +978,6 @@ function readRunnerMainThreadBusy(data: Record): boolean | unde return typeof data.runnerMainThreadBusy === 'boolean' ? data.runnerMainThreadBusy : undefined; } -function isStructuredRunnerFailure(error: unknown): boolean { - return error instanceof AppError && error.details?.runner !== undefined; -} - function markSkippedPreflightTransportError( error: unknown, session: RunnerSession,