diff --git a/packages/host-kit/src/command.ts b/packages/host-kit/src/command.ts index 8c56f2d0ed..95e68a8f5a 100644 --- a/packages/host-kit/src/command.ts +++ b/packages/host-kit/src/command.ts @@ -7,6 +7,7 @@ export { execFailureDetails, type ExecOptions, type ExecResult, + isCommandTimeoutError, isExecutablePath, requireExecSuccess, resolveExecutableOverridePath, diff --git a/packages/host-kit/src/internal/exec.test.ts b/packages/host-kit/src/internal/exec.test.ts index dfd8dc0af4..6273a3c457 100644 --- a/packages/host-kit/src/internal/exec.test.ts +++ b/packages/host-kit/src/internal/exec.test.ts @@ -5,6 +5,7 @@ import path from 'node:path'; import { flushDiagnosticsToSessionFile, withDiagnosticsScope } from './diagnostics.ts'; import { coerceExecResult, + isCommandTimeoutError, requireExecSuccess, runCmd, runCmdBackground, @@ -424,3 +425,37 @@ test('coerceExecResult repairs loosely-typed provider results and keeps typed on } as unknown as ExecResult); assert.deepEqual(loose, { stdout: '', stderr: '42', exitCode: 1 }); }); + +test('isCommandTimeoutError reads the structured timeout, not the message text', async () => { + const killedAtTimeout = await runCmd(process.execPath, ['-e', 'setTimeout(() => {}, 10_000)'], { + timeoutMs: 50, + }).then( + () => null, + (error: unknown) => error, + ); + assert.ok(isCommandTimeoutError(killedAtTimeout)); + + assert.ok( + isCommandTimeoutError( + (() => { + try { + runCmdSync(process.execPath, ['-e', 'setTimeout(() => {}, 10_000)'], { timeoutMs: 50 }); + return null; + } catch (error) { + return error; + } + })(), + ), + ); + + // A tool that failed on its own and said "timed out" in its output: same + // code, same wording, no timeout we imposed. + assert.equal( + isCommandTimeoutError( + new AppError('COMMAND_FAILED', 'xcodebuild timed out after 10ms', { cmd: 'xcodebuild' }), + ), + false, + ); + assert.equal(isCommandTimeoutError(new Error('timed out after 10ms')), false); + assert.equal(isCommandTimeoutError(undefined), false); +}); diff --git a/packages/host-kit/src/internal/exec.ts b/packages/host-kit/src/internal/exec.ts index 0e71f66f1a..bb00134573 100644 --- a/packages/host-kit/src/internal/exec.ts +++ b/packages/host-kit/src/internal/exec.ts @@ -592,6 +592,19 @@ function createTimeoutError( }); } +/** + * True only for the COMMAND_FAILED error this module raises when it kills a command at + * its own `timeoutMs`. Callers classify with this rather than matching the message text, + * so a command whose own output says "timed out" is not mistaken for one exec killed. + */ +export function isCommandTimeoutError(error: unknown): boolean { + return ( + error instanceof AppError && + error.code === 'COMMAND_FAILED' && + typeof error.details?.timeoutMs === 'number' + ); +} + function createExitError( executable: string, cmd: string, diff --git a/packages/platform-apple/src/core/runner-host.ts b/packages/platform-apple/src/core/runner-host.ts index d09e13b1fb..6ef48432c9 100644 --- a/packages/platform-apple/src/core/runner-host.ts +++ b/packages/platform-apple/src/core/runner-host.ts @@ -3,6 +3,7 @@ import { publishFileSync, acquireProcessLock } from '@agent-device/host-kit/file import { resolveIosSimulatorDeviceSetPath } from '@agent-device/kernel/device-isolation'; import { + isCommandTimeoutError, requireExecSuccess, runCmdBackground, runCmdStreaming, @@ -55,6 +56,7 @@ export const appleRunnerHost: AppleRunnerHost = { runCmdSync, runCmdBackground, requireExecSuccess, + isCommandTimeoutError, emitDiagnostic, withDiagnosticTimer, retryWithPolicy, diff --git a/packages/platform-apple/src/runner/__tests__/runner-adoption.test.ts b/packages/platform-apple/src/runner/__tests__/runner-adoption.test.ts index 956ebaa495..a965252528 100644 --- a/packages/platform-apple/src/runner/__tests__/runner-adoption.test.ts +++ b/packages/platform-apple/src/runner/__tests__/runner-adoption.test.ts @@ -2,6 +2,8 @@ import fs from 'node:fs'; import path from 'node:path'; import { afterEach, beforeEach, expect, test, vi } from 'vitest'; import type { DeviceInfo } from '@agent-device/kernel/device'; +import { createRequestCanceledError, isRequestCanceledError } from '@agent-device/kernel/errors'; +import { resetAllProcessMemosForTests } from '@agent-device/kernel/ttl-memo'; import { buildDetachedRunnerLease, buildRunnerLease, @@ -11,7 +13,9 @@ import { } from '../runner-lease.ts'; import { isIosRunnerDetachEnabled, tryAdoptRunnerSessionFromLease } from '../runner-adoption.ts'; import { sendRunnerCommandOnce } from '../runner-transport.ts'; +import { resolveExpectedRunnerCacheMetadata } from '../runner-xctestrun.ts'; import { appleRunnerTestHost } from '../test-host.ts'; +import { appleToolchainProbeResult } from './apple-toolchain-fixtures.ts'; import { mkdtempForTestSync } from './tmp-dir.ts'; vi.mock('../runner-transport.ts', async (importOriginal) => { @@ -28,6 +32,7 @@ vi.mock('../runner-xctestrun.ts', async (importOriginal) => { }); const mockSendRunnerCommandOnce = vi.mocked(sendRunnerCommandOnce); +const mockResolveExpectedRunnerCacheMetadata = vi.mocked(resolveExpectedRunnerCacheMetadata); const mockIsProcessAlive = vi.fn((_pid: number) => false); const mockReadProcessCommand = vi.fn((_pid: number): string | null => null); const mockReadProcessStartTime = vi.fn((_pid: number): string | null => 'test-process-start'); @@ -140,6 +145,54 @@ test('adoption succeeds for a live, matching, probe-healthy runner', async () => expect(readStaleRunnerLease(simulator.id)).toBeNull(); }); +test('a request canceled during the fingerprint probe fails adoption instead of skipping it, cold or with the fingerprint cache warm', async () => { + // The fingerprint check runs the same blocking toolchain probes a fresh + // startup would, and it is handed the request's signal. A cancellation from + // there is not an unresolvable derived path: swallowing it would let startup + // walk on past a client that is already gone (#2422). + const lease = writeStaleLease(); + mockIsProcessAlive.mockReturnValue(true); + const request = new AbortController(); + request.abort(); + mockResolveExpectedRunnerCacheMetadata.mockImplementationOnce((_device, _projectRoot, budget) => { + // The probe only cancels because the request's signal reached it. + expect(budget?.signal?.aborted).toBe(true); + throw createRequestCanceledError({ phase: 'apple_toolchain_probe' }); + }); + + await expect( + tryAdoptRunnerSessionFromLease(simulator, { signal: request.signal }), + ).rejects.toSatisfy(isRequestCanceledError); + expect(mockSendRunnerCommandOnce).not.toHaveBeenCalled(); + + // The mock above only proves adoption propagates whatever the fingerprint + // call throws. Exercise the real production code path too: warm the actual + // toolchain fingerprint memo (the module-level cache in + // runner-cache-metadata.ts is a singleton the mock above never touches), + // then adopt again with an already-aborted signal. Before the fix, + // requireRunnerToolchainFingerprint returned the memoized value without + // checking the signal, so a cache hit let adoption go on to probe uptime + // and write the lease for an already-canceled request (#2422 round 4). + resetAllProcessMemosForTests(); + const { resolveExpectedRunnerCacheMetadata: actualResolveExpectedRunnerCacheMetadata } = + await vi.importActual('../runner-xctestrun.ts'); + appleRunnerTestHost.update({ runCmdSync: vi.fn(appleToolchainProbeResult) }); + actualResolveExpectedRunnerCacheMetadata(simulator); + + const warmRequest = new AbortController(); + warmRequest.abort(); + mockResolveExpectedRunnerCacheMetadata.mockImplementationOnce( + actualResolveExpectedRunnerCacheMetadata, + ); + + await expect( + tryAdoptRunnerSessionFromLease(simulator, { signal: warmRequest.signal }), + ).rejects.toSatisfy(isRequestCanceledError); + expect(mockSendRunnerCommandOnce).not.toHaveBeenCalled(); + // Ownership was never transferred: the stale lease is untouched. + expect(readStaleRunnerLease(simulator.id)?.ownerToken).toBe(lease.ownerToken); +}); + test('adoption is skipped for a recycled runner pid (start time mismatch)', async () => { // The live process on the leased pid started at a different time than the // lease recorded — pid recycled since the owner died (#1596). Adopting it diff --git a/packages/platform-apple/src/runner/__tests__/runner-artifact-phase-budget.test.ts b/packages/platform-apple/src/runner/__tests__/runner-artifact-phase-budget.test.ts new file mode 100644 index 0000000000..f641aa4814 --- /dev/null +++ b/packages/platform-apple/src/runner/__tests__/runner-artifact-phase-budget.test.ts @@ -0,0 +1,145 @@ +import assert from 'node:assert/strict'; +import fs from 'node:fs'; +import path from 'node:path'; +import { afterEach, beforeEach, test, vi } from 'vitest'; +import { AppError } from '@agent-device/kernel/errors'; +import { resetAllProcessMemosForTests } from '@agent-device/kernel/ttl-memo'; +import { appleRunnerTestHost } from '../test-host.ts'; +import type { ExecOptions, ExecResult, ExecStreamOptions } from '../host.ts'; +import { ensureXctestrunArtifact } from '../runner-xctestrun.ts'; +import { appleToolchainProbeResult } from './apple-toolchain-fixtures.ts'; +import { MACOS_DEVICE } from './device-fixtures.ts'; +import { mkdtempForTestSync } from './tmp-dir.ts'; + +/** + * The build phase spends one budget, not two (#2422). + * + * `ensureXctestrunArtifact` runs the cache decision's blocking toolchain probes + * before it starts `xcodebuild`. Those probes used to be handed + * `buildTimeoutMs` and the build was then handed the same number again, so a + * cold-start probe stall added its 30 to 45 seconds on top of the phase budget + * instead of coming out of it. These cases pin the shared deadline: the clock + * moves only when a probe actually blocks for the timeout it was handed, so a + * case that claims the budget was spent had to spend it. + */ + +const clock = { nowMs: 0 }; +const runCmdSync = vi.fn(); +const runCmdStreaming = vi.fn(); +let projectRoot: string; + +beforeEach(() => { + resetAllProcessMemosForTests(); + clock.nowMs = 0; + projectRoot = mkdtempForTestSync('agent-device-runner-phase-root-'); + // `buildXctestrunArtifact` refuses to start a build without the runner project. + fs.mkdirSync( + path.join(projectRoot, 'apple', 'runner', 'AgentDeviceRunner', 'AgentDeviceRunner.xcodeproj'), + { recursive: true }, + ); + process.env.AGENT_DEVICE_IOS_RUNNER_DERIVED_PATH = mkdtempForTestSync( + 'agent-device-runner-phase-derived-', + ); + runCmdSync.mockReset().mockImplementation(appleToolchainProbeResult); + runCmdStreaming + .mockReset() + .mockImplementation(async (): Promise => ({ exitCode: 0, stdout: '', stderr: '' })); + appleRunnerTestHost.update({ + runCmdSync, + runCmdStreaming, + findProjectRoot: () => projectRoot, + readVersion: () => '0.0.0-test', + deadlineFromTimeoutMs: (timeoutMs: number) => { + const startedAtMs = clock.nowMs; + const expiresAtMs = startedAtMs + Math.max(0, timeoutMs); + return { + remainingMs: () => Math.max(0, expiresAtMs - clock.nowMs), + elapsedMs: () => Math.max(0, clock.nowMs - startedAtMs), + isExpired: () => expiresAtMs - clock.nowMs <= 0, + }; + }, + }); +}); + +afterEach(() => { + delete process.env.AGENT_DEVICE_IOS_RUNNER_DERIVED_PATH; +}); + +test('a warm toolchain leaves the build the whole phase budget', async () => { + await assert.rejects( + ensureXctestrunArtifact(MACOS_DEVICE, { buildTimeoutMs: 120_000 }), + missingXctestrun, + ); + + assert.equal(clock.nowMs, 0); + assert.equal(buildTimeoutMsGiven(), 120_000); +}); + +test('a cold-start probe stall comes out of the build budget instead of being added to it', async () => { + let xcodebuildProbes = 0; + runCmdSync.mockImplementation((command: string, args: string[], options: ExecOptions) => { + // The syspolicyd stall: the first `xcodebuild` exec blocks for the whole + // timeout it was handed, the immediate next one answers at once. + xcodebuildProbes += command === 'xcodebuild' ? 1 : 0; + if (xcodebuildProbes === 1 && command === 'xcodebuild') { + throw blockForWholeTimeout(command, options); + } + return appleToolchainProbeResult(command, args); + }); + + await assert.rejects( + ensureXctestrunArtifact(MACOS_DEVICE, { buildTimeoutMs: 120_000 }), + missingXctestrun, + ); + + // 30 s of stall, absorbed by the retry -- and charged to the phase, so the + // build is given 90 s rather than a second full 120 s. + assert.equal(clock.nowMs, 30_000); + assert.equal(buildTimeoutMsGiven(), 90_000); +}); + +test('a probe that spends the whole phase fails before xcodebuild is spawned', async () => { + runCmdSync.mockImplementation((command: string, args: string[], options: ExecOptions) => { + // The last of the three probes answers, but only after blocking for + // everything the phase had left. + if (args.includes('--show-sdk-build-version')) clock.nowMs += options.timeoutMs ?? 0; + return appleToolchainProbeResult(command, args); + }); + + await assert.rejects( + ensureXctestrunArtifact(MACOS_DEVICE, { buildTimeoutMs: 30_000 }), + (error: unknown) => + error instanceof AppError && + error.details?.reason === 'runner_phase_budget_exhausted' && + error.details?.phase === 'runner_xctestrun_build', + ); + + assert.equal(clock.nowMs, 30_000); + assert.equal(runCmdStreaming.mock.calls.length, 0); +}); + +/** The fake build writes no `.xctestrun`; the budget it was handed is what these cases read. */ +function missingXctestrun(error: unknown): boolean { + return error instanceof AppError && error.message === 'Failed to locate .xctestrun after build'; +} + +function buildTimeoutMsGiven(): number | undefined { + assert.equal(runCmdStreaming.mock.calls.length, 1); + const [command, , options] = runCmdStreaming.mock.calls[0] as [ + string, + string[], + ExecStreamOptions, + ]; + assert.equal(command, 'xcodebuild'); + return options.timeoutMs; +} + +/** A probe that blocked for its whole timeout and was then killed, as the exec layer reports it. */ +function blockForWholeTimeout(command: string, options: ExecOptions): AppError { + const timeoutMs = options.timeoutMs ?? 0; + clock.nowMs += timeoutMs; + return new AppError('COMMAND_FAILED', `${command} timed out after ${timeoutMs}ms`, { + cmd: command, + timeoutMs, + }); +} diff --git a/packages/platform-apple/src/runner/__tests__/runner-cache-metadata.test.ts b/packages/platform-apple/src/runner/__tests__/runner-cache-metadata.test.ts index dbcba191fe..91415f15a7 100644 --- a/packages/platform-apple/src/runner/__tests__/runner-cache-metadata.test.ts +++ b/packages/platform-apple/src/runner/__tests__/runner-cache-metadata.test.ts @@ -1,8 +1,12 @@ -import { expect, test } from 'vitest'; +import { beforeEach, describe, expect, test } from 'vitest'; import assert from 'node:assert/strict'; -import { AppError } from '@agent-device/kernel/errors'; +import { AppError, isRequestCanceledError } from '@agent-device/kernel/errors'; +import { resetAllProcessMemosForTests } from '@agent-device/kernel/ttl-memo'; import { IOS_DEVICE, IOS_SIMULATOR, MACOS_DEVICE } from './device-fixtures.ts'; +import { appleRunnerTestHost } from '../test-host.ts'; +import type { ExecOptions } from '../host.ts'; import { + createRunnerPhaseDeadline, diffComparableRunnerCacheMetadata, resolveRunnerBundleBuildSettings, resolveRunnerMaxConcurrentDestinationsFlag, @@ -11,6 +15,7 @@ import { resolveRunnerSandboxBuildArgs, resolveExpectedRunnerCacheMetadata, } from '../runner-cache-metadata.ts'; +import { COLD_TOOLCHAIN_PROBE_TIMEOUT_MS } from '../apple-runner-platform.ts'; import { appleToolchainProbeResult, stubAppleToolchainProbes } from './apple-toolchain-fixtures.ts'; const runCmdSync = stubAppleToolchainProbes(); @@ -240,6 +245,221 @@ test('a timed-out probe leaves the toolchain unavailable instead of a comparable assert.deepEqual(unavailableProbes(), [{ probe: 'xcodebuild -version', reason: 'probe_error' }]); }); +// Apple's syspolicyd signature scan blocks the first xcodebuild/xcrun exec +// after a fresh macOS host boots for roughly 18 to 19 seconds; the immediate +// next exec of the same tool is instant (#2422). These cases exercise the +// resulting one-retry policy, and the budget that bounds it, without waiting +// on a real cold-start stall: the fake clock only moves when a probe actually +// blocks for the timeout it was given, so a case that claims the budget was +// spent had to spend it. +describe('toolchain probe budget', () => { + // Failures are never memoized, but the recovery case below succeeds; each + // case starts from an empty toolchain fingerprint cache so none of them + // reads another's answer. + beforeEach(resetAllProcessMemosForTests); + + test('a cold-start probe recovers on retry, and the stall it survived is charged to the budget', () => { + const clock = installFakeToolchainClock(); + const xcodebuildTimeouts: number[] = []; + runCmdSync.mockImplementation((command: string, args: string[], options: ExecOptions) => { + if (command !== 'xcodebuild') return appleToolchainProbeResult(command, args); + xcodebuildTimeouts.push(options.timeoutMs ?? 0); + if (xcodebuildTimeouts.length > 1) return appleToolchainProbeResult(command, args); + throw blockForWholeTimeout(clock, command, args, options); + }); + runCmdSync.mockClear(); + + const metadata = resolveExpectedRunnerCacheMetadata(IOS_DEVICE); + + assert.equal(metadata.xcodeVersion, '26.2'); + assert.equal(metadata.xcodeBuildVersion, '17C52'); + // The retry runs on what the shared budget has left, not on a fresh + // per-call ceiling: 45 s total minus the 30 s the first attempt burned. + assert.deepEqual(xcodebuildTimeouts, [COLD_TOOLCHAIN_PROBE_TIMEOUT_MS, 15_000]); + }); + + test('a toolchain host that never returns stops at the shared budget instead of once per probe', () => { + const clock = installFakeToolchainClock(); + runCmdSync.mockImplementation((command: string, args: string[], options: ExecOptions) => { + throw blockForWholeTimeout(clock, command, args, options); + }); + runCmdSync.mockClear(); + + assert.throws( + () => resolveExpectedRunnerCacheMetadata(MACOS_DEVICE), + // A budget spent before the remaining probes could start is not an + // unreadable toolchain: nothing probed it, so the error says the budget + // ran out rather than pointing at `xcode-select`. + (error: unknown) => expectRunnerPhaseBudgetExhausted(error), + ); + // 30 s + a 15 s retry spends the whole budget on the first probe; the two + // xcrun probes then fail on the budget instead of blocking for 30 s each. + assert.equal(runCmdSync.mock.calls.length, 2); + assert.equal(clock.nowMs, 45_000); + }); + + test('an owning phase with 4 s left gets one 4 s attempt and no retry', () => { + const clock = installFakeToolchainClock(); + const phaseDeadline = createRunnerPhaseDeadline(4_000); + runCmdSync.mockImplementation((command: string, args: string[], options: ExecOptions) => { + throw blockForWholeTimeout(clock, command, args, options); + }); + runCmdSync.mockClear(); + + assert.throws( + () => + resolveExpectedRunnerCacheMetadata(IOS_SIMULATOR, undefined, { deadline: phaseDeadline }), + (error: unknown) => expectRunnerPhaseBudgetExhausted(error), + ); + assert.equal(runCmdSync.mock.calls.length, 1); + // The one attempt was capped by the phase, not by the 30 s per-call ceiling. + assert.equal(runCmdSync.mock.calls[0]?.[2]?.timeoutMs, 4_000); + assert.equal(clock.nowMs, 4_000); + }); + + test('a request canceled while a probe blocked surfaces the cancellation instead of retrying', () => { + const clock = installFakeToolchainClock(); + const request = new AbortController(); + runCmdSync.mockImplementation((command: string, args: string[], options: ExecOptions) => { + const timeout = blockForWholeTimeout(clock, command, args, options); + request.abort(); + throw timeout; + }); + runCmdSync.mockClear(); + + assert.throws( + () => + resolveExpectedRunnerCacheMetadata(IOS_SIMULATOR, undefined, { signal: request.signal }), + (error: unknown) => isRequestCanceledError(error), + ); + assert.equal(runCmdSync.mock.calls.length, 1); + }); + + test('a non-timeout error that also cancels the request on the last probe surfaces cancellation, not an unavailable toolchain', () => { + const request = new AbortController(); + runCmdSync.mockImplementation((command: string, args: string[]) => { + // The final probe: abort the request and fail with a plain command + // error, not the exec layer's structured timeout -- there is no next + // attempt left to catch the cancellation, so the catch here must. + if (command === 'xcrun' && args.includes('--show-sdk-build-version')) { + request.abort(); + throw new AppError('COMMAND_FAILED', 'xcrun: unexpected error', {}); + } + return appleToolchainProbeResult(command, args); + }); + runCmdSync.mockClear(); + + assert.throws( + () => + resolveExpectedRunnerCacheMetadata(IOS_SIMULATOR, undefined, { signal: request.signal }), + (error: unknown) => isRequestCanceledError(error), + ); + assert.equal(runCmdSync.mock.calls.length, 3); + }); + + test('an already-canceled request runs no toolchain probe at all, cold or with the fingerprint cache warm', () => { + installFakeToolchainClock(); + runCmdSync.mockClear(); + + assert.throws( + () => + resolveExpectedRunnerCacheMetadata(IOS_SIMULATOR, undefined, { + signal: AbortSignal.abort(), + }), + (error: unknown) => isRequestCanceledError(error), + ); + assert.equal(runCmdSync.mock.calls.length, 0); + + // Warm the real fingerprint memo with an ordinary request, then repeat + // with an already-aborted signal: the cache-hit path must check + // cancellation before it returns the memoized value, not skip it (#2422). + resolveExpectedRunnerCacheMetadata(IOS_SIMULATOR); + runCmdSync.mockClear(); + + assert.throws( + () => + resolveExpectedRunnerCacheMetadata(IOS_SIMULATOR, undefined, { + signal: AbortSignal.abort(), + }), + (error: unknown) => isRequestCanceledError(error), + ); + assert.equal(runCmdSync.mock.calls.length, 0); + }); + + test('a probe that failed on its own and merely says "timed out" in its message is not retried', () => { + installFakeToolchainClock(); + runCmdSync.mockImplementation((command: string, args: string[]) => { + if (command !== 'xcodebuild') return appleToolchainProbeResult(command, args); + // No `timeoutMs` detail: this is the tool reporting its own failure, not + // the exec layer killing it at a timeout we asked for. + throw new AppError('COMMAND_FAILED', 'xcodebuild timed out after 10ms', { + cmd: command, + args, + }); + }); + runCmdSync.mockClear(); + + assert.throws( + () => resolveExpectedRunnerCacheMetadata(IOS_SIMULATOR), + (error: unknown) => { + assert.ok(error instanceof AppError); + expect(error.message).toContain('xcodebuild timed out after 10ms'); + return true; + }, + ); + expect(runCmdSync.mock.calls.filter(([command]) => command === 'xcodebuild')).toHaveLength(1); + }); +}); + +/** The error a runner phase raises when a step is reached with nothing left to spend. */ +function expectRunnerPhaseBudgetExhausted(error: unknown): boolean { + assert.ok(error instanceof AppError); + assert.equal(error.code, 'COMMAND_FAILED'); + assert.equal(error.details?.reason, 'runner_phase_budget_exhausted'); + assert.equal(error.details?.phase, 'apple_toolchain_probe'); + assert.equal(error.details?.retriable, true); + expect(error.message).toContain('budget ran out'); + return true; +} + +/** + * A clock the probes' own budget reads, advanced only by + * {@link blockForWholeTimeout}. Without it a mock that throws immediately + * proves nothing about a deadline: no time passes, so every budget looks + * untouched however many attempts run. + */ +function installFakeToolchainClock(): { nowMs: number } { + const clock = { nowMs: 0 }; + appleRunnerTestHost.update({ + deadlineFromTimeoutMs: (timeoutMs: number) => { + const startedAtMs = clock.nowMs; + const expiresAtMs = startedAtMs + Math.max(0, timeoutMs); + return { + remainingMs: () => Math.max(0, expiresAtMs - clock.nowMs), + elapsedMs: () => Math.max(0, clock.nowMs - startedAtMs), + isExpired: () => expiresAtMs - clock.nowMs <= 0, + }; + }, + }); + return clock; +} + +/** A probe that blocked for its whole timeout and was then killed, as the exec layer reports it. */ +function blockForWholeTimeout( + clock: { nowMs: number }, + command: string, + args: string[], + options: ExecOptions, +): AppError { + const timeoutMs = options.timeoutMs ?? 0; + clock.nowMs += timeoutMs; + return new AppError('COMMAND_FAILED', `${command} timed out after ${timeoutMs}ms`, { + cmd: command, + args, + timeoutMs, + }); +} + test('a failing probe reports its exit status rather than a fabricated SDK version', () => { runCmdSync.mockImplementation((command: string, args: readonly string[]) => command === 'xcrun' diff --git a/packages/platform-apple/src/runner/__tests__/runner-client.test.ts b/packages/platform-apple/src/runner/__tests__/runner-client.test.ts index 2589a940f1..ba9be5f861 100644 --- a/packages/platform-apple/src/runner/__tests__/runner-client.test.ts +++ b/packages/platform-apple/src/runner/__tests__/runner-client.test.ts @@ -1416,7 +1416,7 @@ test('ensureXctestrunArtifact stress-recovers after a bad restored artifact', as assert.equal(rebuilt.artifact, 'rebuilt'); assert.equal(rebuilt.reason, 'missing_xctestrun'); assert.equal(mockRunCmdStreaming.mock.calls.length, 1); - assert.equal(mockRunCmdStreaming.mock.calls[0]?.[2]?.timeoutMs, 300_000); + assert.equal(Math.ceil(Number(mockRunCmdStreaming.mock.calls[0]?.[2]?.timeoutMs) / 1e3), 300); // phase remainder (#2422) }); test('ensureXctestrunArtifact rethrows unexpected cached macOS runner repair errors', async () => { diff --git a/packages/platform-apple/src/runner/apple-runner-platform.ts b/packages/platform-apple/src/runner/apple-runner-platform.ts index 481547af7f..72fbbea11d 100644 --- a/packages/platform-apple/src/runner/apple-runner-platform.ts +++ b/packages/platform-apple/src/runner/apple-runner-platform.ts @@ -6,6 +6,19 @@ import { type DeviceInfo, } from '@agent-device/kernel/device'; +/** + * Ceiling on one Apple toolchain identity probe attempt (`xcodebuild -version`, `xcrun + * --sdk --show-sdk-version`). On a fresh macOS host Apple's syspolicyd signature + * scan blocks the first `xcodebuild`/`xcrun` exec after boot for roughly 18 to 19 seconds + * at 0% CPU, and the next exec of the same tool is instant; a budget sized for a warm + * toolchain (the old 10 s / 5 s split) trips on that stall and reports a toolchain + * timeout that says nothing about the toolchain (#2422). + * + * It sits beside the SDK names the probes run against so both Apple toolchain probers + * read one value without either owning it. + */ +export const COLD_TOOLCHAIN_PROBE_TIMEOUT_MS = 30_000; + export type RunnerApplePlatformName = 'iOS' | 'tvOS' | 'macOS' | 'visionOS'; type RunnerPlatformDeviceKind = 'simulator' | 'device'; diff --git a/packages/platform-apple/src/runner/host.ts b/packages/platform-apple/src/runner/host.ts index 66ddb41f45..6e17e8fb66 100644 --- a/packages/platform-apple/src/runner/host.ts +++ b/packages/platform-apple/src/runner/host.ts @@ -149,6 +149,8 @@ export type AppleRunnerHost = { message: string, extra?: Record | ((result: ExecResult) => Record), ): ExecResult; + /** True only for the error the exec layer raises when it killed a command at `timeoutMs`. */ + isCommandTimeoutError(error: unknown): boolean; // Diagnostics (@agent-device/host-kit/diagnostics) emitDiagnostic(event: DiagnosticEventInput): void; withDiagnosticTimer( @@ -277,6 +279,8 @@ export const runCmdBackground: AppleRunnerHost['runCmdBackground'] = (cmd, args, requireHost().runCmdBackground(cmd, args, options); export const requireExecSuccess: AppleRunnerHost['requireExecSuccess'] = (result, message, extra) => requireHost().requireExecSuccess(result, message, extra); +export const isCommandTimeoutError: AppleRunnerHost['isCommandTimeoutError'] = (error) => + requireHost().isCommandTimeoutError(error); export const emitDiagnostic: AppleRunnerHost['emitDiagnostic'] = (event) => requireHost().emitDiagnostic(event); export const withDiagnosticTimer = ( diff --git a/packages/platform-apple/src/runner/runner-adoption.ts b/packages/platform-apple/src/runner/runner-adoption.ts index d82bd1a09d..ad97f5e7d9 100644 --- a/packages/platform-apple/src/runner/runner-adoption.ts +++ b/packages/platform-apple/src/runner/runner-adoption.ts @@ -1,12 +1,14 @@ import path from 'node:path'; import { resolveIosSimulatorDeviceSetPath, + type Deadline, emitDiagnostic, isProcessAlive, parseBooleanLiteral, type ExecResult, } from './host.ts'; import type { DeviceInfo } from '@agent-device/kernel/device'; +import { isRequestCanceledError } from '@agent-device/kernel/errors'; import { sendRunnerCommandOnce } from './runner-transport.ts'; import { withRunnerCommandId } from './runner-contract.ts'; import { @@ -17,8 +19,10 @@ import { type RunnerLease, } from './runner-lease.ts'; import { + requireRunnerPhaseRemainingMs, resolveExpectedRunnerCacheMetadata, resolveRunnerDerivedPath, + type RunnerCacheProbeBudget, type RunnerXctestrunArtifact, } from './runner-xctestrun.ts'; import { @@ -49,7 +53,14 @@ export function isIosRunnerDetachEnabled(env: NodeJS.ProcessEnv = process.env): // lock, like the rest of session startup. export async function tryAdoptRunnerSessionFromLease( device: DeviceInfo, - options: { startupTimeoutMs?: number; expectedRunnerSessionId?: string }, + options: { + startupTimeoutMs?: number; + /** The startup phase's clock: the fingerprint check below spends from it (#2422). */ + phaseDeadline?: Deadline; + /** The owning request's cancellation signal, forwarded to those probes. */ + signal?: AbortSignal; + expectedRunnerSessionId?: string; + }, ): Promise { if (device.kind !== 'simulator' || !isIosRunnerDetachEnabled()) return null; // Custom simulator sets run behind the XCTestDevices redirect, whose @@ -86,7 +97,10 @@ export async function tryAdoptRunnerSessionFromLease( if (!verifyLeaseRunnerPidIdentity(lease, runnerPid)) { return skip('runner_pid_recycled'); } - const expectedDerived = resolveExpectedDerivedPath(device); + const expectedDerived = resolveExpectedDerivedPath(device, { + deadline: options.phaseDeadline, + signal: options.signal, + }); if (!expectedDerived) return skip('expected_derived_unresolved'); if (!lease.xctestrunPath.startsWith(`${expectedDerived}${path.sep}`)) { return skip('artifact_fingerprint_mismatch'); @@ -134,10 +148,18 @@ async function probeRunnerAnswersUptime(device: DeviceInfo, port: number): Promi } } -function resolveExpectedDerivedPath(device: DeviceInfo): string | null { +function resolveExpectedDerivedPath( + device: DeviceInfo, + budget: RunnerCacheProbeBudget, +): string | null { try { - return resolveRunnerDerivedPath(device, resolveExpectedRunnerCacheMetadata(device)); - } catch { + return resolveRunnerDerivedPath( + device, + resolveExpectedRunnerCacheMetadata(device, undefined, budget), + ); + } catch (error) { + // An unresolvable fingerprint is a miss the caller starts fresh from; a cancel is not. + if (isRequestCanceledError(error)) throw error; return null; } } @@ -147,7 +169,7 @@ function buildAdoptedRunnerSession( lease: RunnerLease, runnerPid: number, expectedDerived: string, - options: { startupTimeoutMs?: number }, + options: { startupTimeoutMs?: number; phaseDeadline?: Deadline }, ): RunnerSession & { lease: RunnerLease } { const sessionId = lease.sessionId; const artifact: RunnerXctestrunArtifact = { @@ -172,7 +194,13 @@ function buildAdoptedRunnerSession( child, // The probe already proved the runner answers commands. ready: true, - startupTimeoutMs: normalizeRunnerStartupTimeoutMs(options.startupTimeoutMs), + startupTimeoutMs: normalizeRunnerStartupTimeoutMs( + requireRunnerPhaseRemainingMs( + options.phaseDeadline, + options.startupTimeoutMs, + 'runner_session_adoption', + ), + ), lease: buildRunnerLease({ deviceId: device.id, sessionId, diff --git a/packages/platform-apple/src/runner/runner-artifact.ts b/packages/platform-apple/src/runner/runner-artifact.ts index b80182ed52..af7156d46e 100644 --- a/packages/platform-apple/src/runner/runner-artifact.ts +++ b/packages/platform-apple/src/runner/runner-artifact.ts @@ -5,6 +5,7 @@ import os from 'node:os'; import path from 'node:path'; import { runCmdStreaming, + type Deadline, type ExecBackgroundResult, withKeyedLock, emitRequestProgress, @@ -19,9 +20,11 @@ import { assertSafeDerivedCleanup, cleanRunnerDerivedArtifacts, cleanRunnerDerivedBeforeEvaluation, + createRunnerPhaseDeadline, emitRunnerXctestrunDecision, emitRunnerXctestrunRebuildDecision, evaluateExistingXctestrun, + requireRunnerPhaseRemainingMs, resolveExpectedRunnerCacheMetadata, resolveRunnerBundleBuildSettings, resolveRunnerDerivedPath, @@ -68,22 +71,31 @@ export type ExternalXctestRunnerOptions = { iosXctestEnvDir?: string; }; +/** What the build phase reads: its budget, where it logs, and how it is canceled. */ +type RunnerXctestrunBuildOptions = { + verbose?: boolean; + logPath?: string; + traceLogPath?: string; + buildTimeoutMs?: number; + signal?: AbortSignal; +}; + export async function ensureXctestrunArtifact( device: DeviceInfo, - options: { - verbose?: boolean; - logPath?: string; - traceLogPath?: string; - buildTimeoutMs?: number; + options: RunnerXctestrunBuildOptions & { forceRunnerXctestrunRebuild?: boolean; - signal?: AbortSignal; } & ExternalXctestRunnerOptions, ): Promise { const external = resolveExternalXctestrunArtifact(options); if (external) return external; const projectRoot = findProjectRoot(); - const expectedCacheMetadata = resolveExpectedRunnerCacheMetadata(device, projectRoot); + // One clock for the whole build phase: the toolchain probes and the xcodebuild share it. + const phaseDeadline = createRunnerPhaseDeadline(options.buildTimeoutMs); + const expectedCacheMetadata = resolveExpectedRunnerCacheMetadata(device, projectRoot, { + deadline: phaseDeadline, + signal: options.signal, + }); const derived = resolveRunnerDerivedPath(device, expectedCacheMetadata); return await withKeyedLock(runnerXctestrunBuildLocks, derived, async () => { const releaseCacheLock = await acquireRunnerXctestrunCacheLock(derived); @@ -91,6 +103,7 @@ export async function ensureXctestrunArtifact( return await ensureXctestrunUnderCacheLock({ device, options, + phaseDeadline, projectRoot, expectedCacheMetadata, derived, @@ -147,19 +160,14 @@ function resolveExternalXctestDerivedDataPath(xctestrunPath: string): string { async function ensureXctestrunUnderCacheLock(params: { device: DeviceInfo; - options: { - verbose?: boolean; - logPath?: string; - traceLogPath?: string; - buildTimeoutMs?: number; - signal?: AbortSignal; - }; + options: RunnerXctestrunBuildOptions; + phaseDeadline: Deadline | undefined; projectRoot: string; expectedCacheMetadata: RunnerXctestrunCacheMetadata; derived: string; forceRebuild: boolean; }): Promise { - const { device, options, projectRoot, expectedCacheMetadata, derived } = params; + const { device, options, phaseDeadline, projectRoot, expectedCacheMetadata, derived } = params; cleanRunnerDerivedBeforeEvaluation(derived, params.forceRebuild); const existing = await evaluateExistingXctestrunForDevice({ device, @@ -187,6 +195,7 @@ async function ensureXctestrunUnderCacheLock(params: { return await buildXctestrunArtifact({ device, options, + phaseDeadline, projectRoot, expectedCacheMetadata, derived, @@ -223,33 +232,42 @@ async function resolveReusableXctestrunArtifact(params: { async function buildXctestrunArtifact(params: { device: DeviceInfo; - options: { - verbose?: boolean; - logPath?: string; - traceLogPath?: string; - buildTimeoutMs?: number; - signal?: AbortSignal; - }; + options: RunnerXctestrunBuildOptions; + phaseDeadline: Deadline | undefined; projectRoot: string; expectedCacheMetadata: RunnerXctestrunCacheMetadata; derived: string; cache: RunnerXctestrunArtifact['cache']; reason: ExistingXctestrunState['reason']; }): Promise { - const { device, options, projectRoot, expectedCacheMetadata, derived, cache, reason } = params; + const { + device, + options, + phaseDeadline, + projectRoot, + expectedCacheMetadata, + derived, + cache, + reason, + } = params; const projectPath = resolveAppleRunnerProjectPath(projectRoot); if (!fs.existsSync(projectPath)) { throw new AppError('COMMAND_FAILED', 'iOS runner project not found', { projectPath }); } + const buildTimeoutMs = requireRunnerPhaseRemainingMs( + phaseDeadline, + options.buildTimeoutMs, + 'runner_xctestrun_build', + ); const buildStartedAt = Date.now(); emitRequestProgress({ type: 'command', status: 'progress', message: 'Building Apple runner...', }); - await buildRunnerXctestrun(device, projectPath, derived, options); + await buildRunnerXctestrun(device, projectPath, derived, { ...options, buildTimeoutMs }); const buildMs = Math.max(0, Date.now() - buildStartedAt); const built = findXctestrun(derived, device); @@ -455,13 +473,7 @@ async function buildRunnerXctestrun( device: DeviceInfo, projectPath: string, derived: string, - options: { - verbose?: boolean; - logPath?: string; - traceLogPath?: string; - buildTimeoutMs?: number; - signal?: AbortSignal; - }, + options: RunnerXctestrunBuildOptions, ): Promise { const runnerBundleBuildSettings = resolveRunnerBundleBuildSettings(process.env); const signingBuildSettings = resolveRunnerSigningBuildSettings( diff --git a/packages/platform-apple/src/runner/runner-cache-metadata.ts b/packages/platform-apple/src/runner/runner-cache-metadata.ts index a0461ad244..15a402d844 100644 --- a/packages/platform-apple/src/runner/runner-cache-metadata.ts +++ b/packages/platform-apple/src/runner/runner-cache-metadata.ts @@ -2,9 +2,15 @@ import crypto from 'node:crypto'; import os from 'node:os'; import path from 'node:path'; import { isMacOs, type DeviceInfo } from '@agent-device/kernel/device'; -import { AppError } from '@agent-device/kernel/errors'; +import { + AppError, + createRequestCanceledError, + isRequestCanceledError, +} from '@agent-device/kernel/errors'; import { createTtlMemo, + Deadline, + isCommandTimeoutError, isEnvTruthy, findProjectRoot, readVersion, @@ -12,6 +18,7 @@ import { type TtlMemo, } from './host.ts'; import { + COLD_TOOLCHAIN_PROBE_TIMEOUT_MS, resolveRunnerBuildDestinationFamily, resolveRunnerDerivedBaseName, resolveRunnerPlatformName, @@ -24,7 +31,13 @@ const RUNNER_DERIVED_ROOT = path.join(os.homedir(), '.agent-device', 'apple-runn export const RUNNER_CACHE_METADATA_FILE = '.agent-device-runner-cache.json'; const RUNNER_CACHE_SCHEMA_VERSION = 2; const RUNNER_CACHE_METADATA_VALUE_MAX_LENGTH = 300; -const TOOLCHAIN_PROBE_TIMEOUT_MS = 5_000; + +/** + * Ceiling on the wall clock the whole toolchain fingerprint may spend, across all three + * probes and their retries, when the owning phase carries no shorter budget: one stalled + * probe, its warm retry, and the two probes still to run (#2422). + */ +const TOOLCHAIN_FINGERPRINT_BUDGET_MS = 45_000; const TOOLCHAIN_PROBE_MAX_BUFFER = 128 * 1024; const TOOLCHAIN_PROBE_DETAIL_MAX_LENGTH = 200; const TOOLCHAIN_PROBE_HINT = @@ -53,6 +66,85 @@ type ToolchainProbeFailure = { detail: string; }; +/** + * The one clock a runner phase spends, created once per phase and read with + * {@link requireRunnerPhaseRemainingMs}; `undefined` for a caller carrying no budget. + */ +export function createRunnerPhaseDeadline(timeoutMs: number | undefined): Deadline | undefined { + if (timeoutMs === undefined || !Number.isFinite(timeoutMs)) return undefined; + return Deadline.fromTimeoutMs(Math.max(0, timeoutMs)); +} + +/** + * What the phase has left for its next step, or `fallbackTimeoutMs` when it carries no + * deadline. Throws rather than returning zero, so a spent phase fails before it spawns. + */ +export function requireRunnerPhaseRemainingMs( + deadline: Deadline | undefined, + fallbackTimeoutMs: number | undefined, + phase: string, +): number | undefined { + if (!deadline) return fallbackTimeoutMs; + const remainingMs = Math.floor(deadline.remainingMs()); + if (remainingMs <= 0) throw runnerPhaseBudgetExhaustedError(phase); + return remainingMs; +} + +/** Says the phase budget ran out, not that the step it would have run is broken. */ +function runnerPhaseBudgetExhaustedError(phase: string): AppError { + return new AppError('COMMAND_FAILED', 'The Apple runner budget ran out before this step began', { + phase, + reason: 'runner_phase_budget_exhausted', + retriable: true, + }); +} + +/** + * What the phase that wants a runner cache decision has left to spend on it. A caller + * with neither field still gets {@link TOOLCHAIN_FINGERPRINT_BUDGET_MS} as the ceiling. + */ +export type RunnerCacheProbeBudget = { + /** The owning phase's clock, shared with whatever the phase does next. */ + deadline?: Deadline; + /** The owning request's cancellation signal, if it carries one. */ + signal?: AbortSignal; +}; + +/** + * The remaining-time and cancellation view the probes consult: one per fingerprint read, + * so the three probes and their retries share a single budget. + * + * `spawnSync` cannot be interrupted once it has started, so cancellation is observed + * between attempts; the per-attempt cap is what bounds how long that takes. + */ +type ToolchainProbeClock = { + /** Milliseconds the next attempt may block for; 0 once the budget is spent. */ + attemptTimeoutMs(): number; + /** Throws the owning request's cancellation error once it has aborted. */ + throwIfCanceled(): void; +}; + +function createToolchainProbeClock( + budget: RunnerCacheProbeBudget | undefined, +): ToolchainProbeClock { + const phaseDeadline = budget?.deadline; + const deadline = Deadline.fromTimeoutMs( + Math.min( + TOOLCHAIN_FINGERPRINT_BUDGET_MS, + phaseDeadline ? phaseDeadline.remainingMs() : Number.POSITIVE_INFINITY, + ), + ); + return { + attemptTimeoutMs: () => + Math.min(COLD_TOOLCHAIN_PROBE_TIMEOUT_MS, Math.floor(deadline.remainingMs())), + throwIfCanceled: () => { + if (budget?.signal?.aborted) { + throw createRequestCanceledError({ phase: 'apple_toolchain_probe' }); + } + }, + }; +} + type ProbeResult = | { ok: true; value: Value } | { ok: false; failure: ToolchainProbeFailure }; @@ -125,13 +217,14 @@ export const IOS_RUNNER_CONTAINER_BUNDLE_IDS: string[] = resolveRunnerContainerB export function resolveExpectedRunnerCacheMetadata( device: DeviceInfo, projectRoot: string = findProjectRoot(), + budget?: RunnerCacheProbeBudget, ): RunnerXctestrunCacheMetadata { const platformName = resolveRunnerPlatformName(device); return { schemaVersion: RUNNER_CACHE_SCHEMA_VERSION, packageVersion: readVersion(projectRoot), runnerSourceFingerprint: computeRunnerSourceFingerprint(projectRoot), - ...requireRunnerToolchainFingerprint(resolveRunnerSdkName(platformName, device.kind)), + ...requireRunnerToolchainFingerprint(resolveRunnerSdkName(platformName, device.kind), budget), platformName, deviceKind: device.kind, target: device.target ?? 'mobile', @@ -158,15 +251,19 @@ function toolchainFingerprintCache(): TtlMemo { +function runToolchainProbe( + cmd: string, + args: string[], + clock: ToolchainProbeClock, +): ProbeResult { const probe = [cmd, ...args].join(' '); let output: { exitCode: number; stdout: string; stderr: string }; try { - output = runCmdSync(cmd, args, { - allowFailure: true, - timeoutMs: TOOLCHAIN_PROBE_TIMEOUT_MS, - maxBuffer: TOOLCHAIN_PROBE_MAX_BUFFER, - }); + output = runToolchainProbeCommand(cmd, args, clock); } catch (error) { + // A cancellation or a spent budget is the caller's error, not an unreadable toolchain. + clock.throwIfCanceled(); + if (isRequestCanceledError(error) || isRunnerPhaseBudgetExhaustedError(error)) throw error; return probeFailure(probe, 'probe_error', error instanceof Error ? error.message : `${error}`); } if (output.exitCode !== 0) { @@ -242,6 +343,44 @@ function runToolchainProbe(cmd: string, args: string[]): ProbeResult { return value ? { ok: true, value } : probeFailure(probe, 'empty_output', 'no output'); } +/** + * Retries exactly once, and only the exec layer's structured timeout: the stall + * {@link COLD_TOOLCHAIN_PROBE_TIMEOUT_MS} names clears on the next exec of the same tool, + * while a tool that failed on its own and said "timed out" in its output is not it. + */ +function runToolchainProbeCommand( + cmd: string, + args: string[], + clock: ToolchainProbeClock, +): { exitCode: number; stdout: string; stderr: string } { + try { + return attemptToolchainProbe(cmd, args, clock); + } catch (error) { + if (!isCommandTimeoutError(error)) throw error; + return attemptToolchainProbe(cmd, args, clock); + } +} + +/** The one guard site: cancellation and a spent budget both throw here, before any exec. */ +function attemptToolchainProbe( + cmd: string, + args: string[], + clock: ToolchainProbeClock, +): { exitCode: number; stdout: string; stderr: string } { + clock.throwIfCanceled(); + const timeoutMs = clock.attemptTimeoutMs(); + if (timeoutMs <= 0) throw runnerPhaseBudgetExhaustedError('apple_toolchain_probe'); + return runCmdSync(cmd, args, { + allowFailure: true, + timeoutMs, + maxBuffer: TOOLCHAIN_PROBE_MAX_BUFFER, + }); +} + +function isRunnerPhaseBudgetExhaustedError(error: unknown): boolean { + return error instanceof AppError && error.details?.reason === 'runner_phase_budget_exhausted'; +} + function parseXcodeVersionOutput( output: ProbeResult, ): ProbeResult<{ version: string; buildVersion: string }> { diff --git a/packages/platform-apple/src/runner/runner-cache.ts b/packages/platform-apple/src/runner/runner-cache.ts index 94f0431f50..246d6fc532 100644 --- a/packages/platform-apple/src/runner/runner-cache.ts +++ b/packages/platform-apple/src/runner/runner-cache.ts @@ -20,6 +20,8 @@ import { type RunnerXctestrunCacheProductArtifact, } from './runner-cache-metadata.ts'; export { + createRunnerPhaseDeadline, + requireRunnerPhaseRemainingMs, resolveExpectedRunnerCacheMetadata, resolveRunnerBundleBuildSettings, resolveRunnerDerivedPath, diff --git a/packages/platform-apple/src/runner/runner-session.ts b/packages/platform-apple/src/runner/runner-session.ts index 15864c0798..40198d4b61 100644 --- a/packages/platform-apple/src/runner/runner-session.ts +++ b/packages/platform-apple/src/runner/runner-session.ts @@ -19,11 +19,14 @@ import { waitForRunner, RUNNER_STARTUP_TIMEOUT_MS } from './runner-startup-trans import { sendRunnerCommandOnce } from './runner-transport.ts'; import { acquireXcodebuildSimulatorSetRedirect, + createRunnerPhaseDeadline, ensureXctestrunArtifact, IOS_RUNNER_CONTAINER_BUNDLE_IDS, prepareXctestrunWithEnv, + requireRunnerPhaseRemainingMs, resolveExpectedRunnerCacheMetadata, resolveRunnerDerivedPath, + type RunnerCacheProbeBudget, } from './runner-xctestrun.ts'; import { resolveRunnerRequestSignal, @@ -109,16 +112,21 @@ export async function ensureRunnerSession( // from a retained-after-close runner no longer applies. cancelIosRunnerIdleStop(device.id); return await withRunnerSessionLock(device.id, async () => { + // One clock for the whole startup phase: the toolchain probes and the startup share it. + const phaseDeadline = createRunnerPhaseDeadline(options.startupTimeoutMs); const existing = runnerSessions.get(device.id); if (existing) { assertExpectedRunnerSession(existing, options.expectedRunnerSessionId); - const reusable = await resolveReusableRunnerSession(device, existing); + const reusable = await resolveReusableRunnerSession(device, existing, { + deadline: phaseDeadline, + signal: resolveRunnerRequestSignal(options), + }); if (reusable) return reusable; } return await withRunnerLeaseLock( device.id, - async () => await startRunnerSessionWithLease(device, options), + async () => await startRunnerSessionWithLease(device, options, phaseDeadline), ); }); } @@ -126,6 +134,7 @@ export async function ensureRunnerSession( async function startRunnerSessionWithLease( device: DeviceInfo, options: RunnerSessionOptions, + phaseDeadline: Deadline | undefined, ): Promise { const startupTimings: Record = {}; // The owning request's abort signal so a client disconnect kills the blocking @@ -151,6 +160,8 @@ async function startRunnerSessionWithLease( async () => await tryAdoptRunnerSessionFromLease(device, { startupTimeoutMs: options.startupTimeoutMs, + phaseDeadline, + signal, expectedRunnerSessionId: options.expectedRunnerSessionId, }), ); @@ -181,6 +192,12 @@ async function startRunnerSessionWithLease( phase: 'ios_runner_startup_cleanup_stale_bundles_skipped', }); } + // Read before the build, which answers to its own `buildTimeoutMs` deadline (#2422). + const startupTimeoutMs = requireRunnerPhaseRemainingMs( + phaseDeadline, + options.startupTimeoutMs, + 'runner_session_startup', + ); const xctestrunArtifact = await measureRunnerStartupStep( startupTimings, 'ensure_xctestrun', @@ -254,7 +271,7 @@ async function startRunnerSessionWithLease( child: runnerProcess.child, ready: false, startupRetryWake: runnerProcess.startupRetryWake, - startupTimeoutMs: normalizeRunnerStartupTimeoutMs(options.startupTimeoutMs), + startupTimeoutMs: normalizeRunnerStartupTimeoutMs(startupTimeoutMs), startupTimings, logicalLeaseContext, simulatorSetRedirect: simulatorSetRedirect ?? undefined, @@ -307,6 +324,7 @@ function runnerSessionOwnershipChanged(): AppError { async function resolveReusableRunnerSession( device: DeviceInfo, existing: RunnerSession, + cacheProbeBudget: RunnerCacheProbeBudget, ): Promise { if (!isRunnerProcessAlive(existing.child.pid)) { await measureRunnerStartupStep({}, 'stop_stale_session', async () => { @@ -336,7 +354,7 @@ async function resolveReusableRunnerSession( const expectedDerived = resolveRunnerDerivedPath( device, - resolveExpectedRunnerCacheMetadata(device), + resolveExpectedRunnerCacheMetadata(device, undefined, cacheProbeBudget), ); if (existingArtifact?.derived !== expectedDerived) { emitDiagnostic({ diff --git a/packages/platform-apple/src/runner/runner-xctestrun.ts b/packages/platform-apple/src/runner/runner-xctestrun.ts index 7d19f11b29..ca024295fc 100644 --- a/packages/platform-apple/src/runner/runner-xctestrun.ts +++ b/packages/platform-apple/src/runner/runner-xctestrun.ts @@ -12,9 +12,12 @@ export { type RunnerXctestrunCacheKind, } from './runner-cache.ts'; export { + createRunnerPhaseDeadline, IOS_RUNNER_CONTAINER_BUNDLE_IDS, + requireRunnerPhaseRemainingMs, resolveExpectedRunnerCacheMetadata, resolveRunnerAppBundleId, resolveRunnerDerivedPath, + type RunnerCacheProbeBudget, } from './runner-cache-metadata.ts'; export { acquireXcodebuildSimulatorSetRedirect } from './runner-device-set.ts'; diff --git a/packages/platform-apple/src/snapshot-source/cache-identity.test.ts b/packages/platform-apple/src/snapshot-source/cache-identity.test.ts new file mode 100644 index 0000000000..0a81965027 --- /dev/null +++ b/packages/platform-apple/src/snapshot-source/cache-identity.test.ts @@ -0,0 +1,175 @@ +import assert from 'node:assert/strict'; +import { test } from 'vitest'; +import { AppError } from '@agent-device/kernel/errors'; +import { createSnapshotSourceHost } from './host.ts'; +import { readSnapshotSourceToolchain } from './cache-identity.ts'; +import { createSnapshotSourceDeadline, type SnapshotSourceDeadline } from './deadline.ts'; +import { SnapshotSourceError } from './errors.ts'; +import type { ExecOptions, ExecResult } from '@agent-device/host-kit/command'; +import type { SnapshotSourceHost } from './types.ts'; + +// Apple's syspolicyd signature scan blocks the first xcodebuild/xcrun exec +// after a fresh macOS host boots for roughly 18 to 19 seconds; the immediate +// next exec of the same tool is instant (#2422). These cases exercise the +// resulting one-retry policy, and the deadline that bounds it, without waiting +// on a real cold-start stall: the fake clock only moves when a probe actually +// blocks for the timeout it was handed, so a case that claims the budget was +// spent had to spend it. + +test('a cold-start toolchain probe recovers on retry, and the retry gets only what the stall left', async () => { + const clock = { nowMs: 0 }; + const timeouts: number[] = []; + let calls = 0; + const host = fakeToolchainHost((command, args, options) => { + calls += 1; + timeouts.push(options.timeoutMs ?? 0); + if (calls === 1) throw blockForWholeTimeout(clock, command, options); + return toolchainAnswer(command, args); + }); + + const identity = await readSnapshotSourceToolchain( + host, + 'iOS 26.2', + fakeClockDeadline(40_000, clock), + ); + + assert.equal(identity.xcode, 'Xcode 26.2\nBuild version 17C52'); + assert.equal(identity.macosBuild, '24G90'); + assert.equal(identity.architecture, 'arm64'); + assert.equal(identity.simulatorSdk, '26.2'); + // The stalled first attempt is capped at the 30 s per-probe ceiling; the + // retry runs on the 10 s the shared deadline has left, not a second 30 s. + assert.deepEqual(timeouts.slice(0, 2), [30_000, 10_000]); + assert.equal(clock.nowMs, 30_000); + // 5 baseline probes (xcodebuild, sw_vers x2, uname, xcrun) plus the one + // retry that recovered the first, timed-out call. + assert.equal(calls, 6); +}); + +test('a probe that spends the whole deadline is not retried', async () => { + const clock = { nowMs: 0 }; + const timeouts: number[] = []; + const host = fakeToolchainHost((command, _args, options) => { + timeouts.push(options.timeoutMs ?? 0); + throw blockForWholeTimeout(clock, command, options); + }); + + await assert.rejects( + readSnapshotSourceToolchain(host, 'iOS 26.2', fakeClockDeadline(30_000, clock)), + (error: unknown) => + error instanceof AppError && error.message === 'xcodebuild timed out after 30000ms', + ); + // Nothing left to retry on, so the original timeout propagates unchanged. + assert.deepEqual(timeouts, [30_000]); + assert.equal(clock.nowMs, 30_000); +}); + +test('a toolchain host that never returns still fails at the deadline with the same timeout error', async () => { + const clock = { nowMs: 0 }; + const timeouts: number[] = []; + const host = fakeToolchainHost((command, _args, options) => { + timeouts.push(options.timeoutMs ?? 0); + throw blockForWholeTimeout(clock, command, options); + }); + + await assert.rejects( + readSnapshotSourceToolchain(host, 'iOS 26.2', fakeClockDeadline(120_000, clock)), + (error: unknown) => + error instanceof AppError && error.message === 'xcodebuild timed out after 30000ms', + ); + // Exactly one retry, not an unbounded loop, and the retry is charged the + // remainder rather than a fresh ceiling. + assert.deepEqual(timeouts, [30_000, 30_000]); + assert.equal(clock.nowMs, 60_000); +}); + +test('a request canceled while a probe blocked surfaces the cancellation, not the timeout', async () => { + const clock = { nowMs: 0 }; + const request = new AbortController(); + let calls = 0; + const host = fakeToolchainHost((command, _args, options) => { + calls += 1; + const timeout = blockForWholeTimeout(clock, command, options); + // The abort lands while the attempt is still blocked, which is the case the + // deadline alone cannot tell from a plain timeout: it still has room. + request.abort(); + throw timeout; + }); + + await assert.rejects( + readSnapshotSourceToolchain( + host, + 'iOS 26.2', + createSnapshotSourceDeadline(120_000, request.signal, () => clock.nowMs), + ), + (error: unknown) => { + assert.ok(error instanceof SnapshotSourceError); + assert.equal(error.failureKind, 'cancelled'); + assert.equal(error.failureCode, 'abort-signal'); + assert.equal(error.details?.reason, 'request_canceled'); + return true; + }, + ); + // The deadline still had 90 s, so only the cancellation stops the retry. + assert.equal(calls, 1); + assert.equal(clock.nowMs, 30_000); +}); + +test('a probe that failed on its own and merely says "timed out" in its message is not retried', async () => { + const clock = { nowMs: 0 }; + let calls = 0; + const host = fakeToolchainHost((command) => { + calls += 1; + // No `timeoutMs` detail: the tool reported its own failure, the exec layer + // did not kill it at a timeout we asked for. Retrying that just doubles a + // failure the retry cannot fix. + throw new AppError('COMMAND_FAILED', `${command} timed out after 10ms`, { cmd: command }); + }); + + await assert.rejects( + readSnapshotSourceToolchain(host, 'iOS 26.2', fakeClockDeadline(120_000, clock)), + (error: unknown) => + error instanceof AppError && error.message === 'xcodebuild timed out after 10ms', + ); + assert.equal(calls, 1); +}); + +/** A deadline read against a clock only {@link blockForWholeTimeout} advances. */ +function fakeClockDeadline(timeoutMs: number, clock: { nowMs: number }): SnapshotSourceDeadline { + return createSnapshotSourceDeadline(timeoutMs, undefined, () => clock.nowMs); +} + +/** A probe that blocked for its whole timeout and was then killed, as the exec layer reports it. */ +function blockForWholeTimeout( + clock: { nowMs: number }, + command: string, + options: ExecOptions, +): AppError { + const timeoutMs = options.timeoutMs ?? 0; + clock.nowMs += timeoutMs; + return new AppError('COMMAND_FAILED', `${command} timed out after ${timeoutMs}ms`, { timeoutMs }); +} + +function toolchainAnswer(command: string, args: string[]): ExecResult { + const stdout = + command === 'xcodebuild' + ? 'Xcode 26.2\nBuild version 17C52' + : command === 'sw_vers' + ? args.includes('-buildVersion') + ? '24G90' + : '15.6' + : command === 'uname' + ? 'arm64' + : '26.2'; + return { stdout, stderr: '', exitCode: 0 }; +} + +function fakeToolchainHost( + run: (command: string, args: string[], options: ExecOptions) => ExecResult, +): SnapshotSourceHost { + const real = createSnapshotSourceHost(); + return { + ...real, + run: async (command, args, options) => run(command, args, options ?? {}), + }; +} diff --git a/packages/platform-apple/src/snapshot-source/cache-identity.ts b/packages/platform-apple/src/snapshot-source/cache-identity.ts index 0d1fd09f89..785b8708ba 100644 --- a/packages/platform-apple/src/snapshot-source/cache-identity.ts +++ b/packages/platform-apple/src/snapshot-source/cache-identity.ts @@ -1,5 +1,7 @@ import { createHash } from 'node:crypto'; import path from 'node:path'; +import { isCommandTimeoutError, type ExecResult } from '@agent-device/host-kit/command'; +import { COLD_TOOLCHAIN_PROBE_TIMEOUT_MS } from '../runner/apple-runner-platform.ts'; import { snapshotSourceError } from './errors.ts'; import { remainingSnapshotSourceMs, type SnapshotSourceDeadline } from './deadline.ts'; import type { SnapshotSourceHost } from './types.ts'; @@ -84,11 +86,7 @@ async function toolOutput( args: string[], deadline: SnapshotSourceDeadline, ): Promise { - const result = await host.run(command, args, { - allowFailure: true, - signal: deadline.signal, - timeoutMs: Math.min(10_000, remainingSnapshotSourceMs(deadline, 'toolchain-probe-deadline')), - }); + const result = await runToolchainProbe(host, command, args, deadline); if (result.exitCode !== 0) { throw snapshotSourceError('unsupported', 'toolchain-probe-failed', { command, @@ -100,3 +98,40 @@ async function toolOutput( if (!output) throw snapshotSourceError('unsupported', 'toolchain-probe-empty', { command }); return output; } + +/** + * Retries exactly once, and only the exec layer's structured timeout: the stall + * {@link COLD_TOOLCHAIN_PROBE_TIMEOUT_MS} names clears on the next exec of the same tool. + * Both attempts read one deadline, so the retry gets what the stall left. + */ +async function runToolchainProbe( + host: SnapshotSourceHost, + command: string, + args: string[], + deadline: SnapshotSourceDeadline, +): Promise { + try { + return await execToolchainProbe(host, command, args, deadline); + } catch (error) { + if (!isCommandTimeoutError(error)) throw error; + if (deadline.signal?.aborted) throw snapshotSourceError('cancelled', 'abort-signal'); + if (deadline.clock.remainingMs(deadline.now()) <= 0) throw error; + return await execToolchainProbe(host, command, args, deadline); + } +} + +function execToolchainProbe( + host: SnapshotSourceHost, + command: string, + args: string[], + deadline: SnapshotSourceDeadline, +): Promise { + return host.run(command, args, { + allowFailure: true, + signal: deadline.signal, + timeoutMs: Math.min( + COLD_TOOLCHAIN_PROBE_TIMEOUT_MS, + remainingSnapshotSourceMs(deadline, 'toolchain-probe-deadline'), + ), + }); +} diff --git a/packages/platform-apple/src/snapshot-source/deadline.ts b/packages/platform-apple/src/snapshot-source/deadline.ts index ca03e563e7..0e95de0ef4 100644 --- a/packages/platform-apple/src/snapshot-source/deadline.ts +++ b/packages/platform-apple/src/snapshot-source/deadline.ts @@ -3,20 +3,23 @@ import { snapshotSourceError } from './errors.ts'; export type SnapshotSourceDeadline = Readonly<{ clock: Deadline; + /** The clock the deadline is read against; injected so a test can move time (#2422). */ + now: () => number; signal: AbortSignal | undefined; }>; export function createSnapshotSourceDeadline( timeoutMs: number, signal: AbortSignal | undefined, + now: () => number = Date.now, ): SnapshotSourceDeadline { if (signal?.aborted) throw snapshotSourceError('cancelled', 'abort-signal'); - return { clock: Deadline.fromTimeoutMs(timeoutMs), signal }; + return { clock: Deadline.fromTimeoutMs(timeoutMs, now()), now, signal }; } export function remainingSnapshotSourceMs(deadline: SnapshotSourceDeadline, code: string): number { if (deadline.signal?.aborted) throw snapshotSourceError('cancelled', 'abort-signal'); - const remainingMs = deadline.clock.remainingMs(); + const remainingMs = deadline.clock.remainingMs(deadline.now()); if (remainingMs <= 0) throw snapshotSourceError('timeout', code); return Math.max(1, Math.floor(remainingMs)); }