Skip to content

Commit 6bf0809

Browse files
committed
fix(apple): bound the cold toolchain probes by the owning request budget
Three synchronous probes could each retry once at 30 s, so a wedged toolchain host blocked a request for ~180 s with no deadline and no cancellation check. The runner cache decision now takes the owning request's budget (remaining ms + abort signal) and builds one clock per fingerprint read: every attempt runs at min(per-call ceiling, remaining), the retry is skipped once the budget is spent, an exhausted budget fails the decision without starting another probe, and an aborted signal surfaces the cancellation instead of retrying. `ensureXctestrunArtifact` passes the build budget and signal, session reuse passes the startup budget and the request signal, and lease adoption passes the startup budget; a caller with neither is still capped at 45 s total, so the worst case falls from ~180 s to 45 s. Error codes, texts, and the probe hint are unchanged. Both retry classifiers now read the exec layer's structured timeout detail instead of matching "timed out after Nms" in the message. The predicate is exported once from host-kit's command surface and reaches `runner-cache-metadata.ts` through the Apple runner host port, so the file's eager closure is unchanged. Tests use a fake clock that only advances when a probe actually blocks for the timeout it was given, so the exhausted-budget and cancellation cases have to spend the budget to pass; both consumers also pin that an error saying "timed out after 10ms" without the structured detail is not retried. Refs #2422
1 parent 36753f9 commit 6bf0809

13 files changed

Lines changed: 405 additions & 87 deletions

File tree

packages/host-kit/src/command.ts

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@ export {
77
execFailureDetails,
88
type ExecOptions,
99
type ExecResult,
10+
isCommandTimeoutError,
1011
isExecutablePath,
1112
requireExecSuccess,
1213
resolveExecutableOverridePath,

packages/host-kit/src/internal/exec.test.ts

Lines changed: 35 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@ import path from 'node:path';
55
import { flushDiagnosticsToSessionFile, withDiagnosticsScope } from './diagnostics.ts';
66
import {
77
coerceExecResult,
8+
isCommandTimeoutError,
89
requireExecSuccess,
910
runCmd,
1011
runCmdBackground,
@@ -424,3 +425,37 @@ test('coerceExecResult repairs loosely-typed provider results and keeps typed on
424425
} as unknown as ExecResult);
425426
assert.deepEqual(loose, { stdout: '', stderr: '42', exitCode: 1 });
426427
});
428+
429+
test('isCommandTimeoutError reads the structured timeout, not the message text', async () => {
430+
const killedAtTimeout = await runCmd(process.execPath, ['-e', 'setTimeout(() => {}, 10_000)'], {
431+
timeoutMs: 50,
432+
}).then(
433+
() => null,
434+
(error: unknown) => error,
435+
);
436+
assert.ok(isCommandTimeoutError(killedAtTimeout));
437+
438+
assert.ok(
439+
isCommandTimeoutError(
440+
(() => {
441+
try {
442+
runCmdSync(process.execPath, ['-e', 'setTimeout(() => {}, 10_000)'], { timeoutMs: 50 });
443+
return null;
444+
} catch (error) {
445+
return error;
446+
}
447+
})(),
448+
),
449+
);
450+
451+
// A tool that failed on its own and said "timed out" in its output: same
452+
// code, same wording, no timeout we imposed.
453+
assert.equal(
454+
isCommandTimeoutError(
455+
new AppError('COMMAND_FAILED', 'xcodebuild timed out after 10ms', { cmd: 'xcodebuild' }),
456+
),
457+
false,
458+
);
459+
assert.equal(isCommandTimeoutError(new Error('timed out after 10ms')), false);
460+
assert.equal(isCommandTimeoutError(undefined), false);
461+
});

packages/host-kit/src/internal/exec.ts

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -592,6 +592,22 @@ function createTimeoutError(
592592
});
593593
}
594594

595+
/**
596+
* True only for the COMMAND_FAILED error this module raises when it kills a
597+
* command at its own `timeoutMs` — the structured signal both timeout sites
598+
* above stamp on `details.timeoutMs`. Callers that retry a timed-out command
599+
* classify with this instead of matching the message text, so a command whose
600+
* own output happens to say "timed out after 10ms" is not mistaken for a
601+
* timeout the exec layer imposed.
602+
*/
603+
export function isCommandTimeoutError(error: unknown): boolean {
604+
return (
605+
error instanceof AppError &&
606+
error.code === 'COMMAND_FAILED' &&
607+
typeof error.details?.timeoutMs === 'number'
608+
);
609+
}
610+
595611
function createExitError(
596612
executable: string,
597613
cmd: string,

packages/platform-apple/src/core/runner-host.ts

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -3,6 +3,7 @@ import { publishFileSync, acquireProcessLock } from '@agent-device/host-kit/file
33
import { resolveIosSimulatorDeviceSetPath } from '@agent-device/kernel/device-isolation';
44

55
import {
6+
isCommandTimeoutError,
67
requireExecSuccess,
78
runCmdBackground,
89
runCmdStreaming,
@@ -55,6 +56,7 @@ export const appleRunnerHost: AppleRunnerHost = {
5556
runCmdSync,
5657
runCmdBackground,
5758
requireExecSuccess,
59+
isCommandTimeoutError,
5860
emitDiagnostic,
5961
withDiagnosticTimer,
6062
retryWithPolicy,

packages/platform-apple/src/runner/__tests__/runner-cache-metadata.test.ts

Lines changed: 172 additions & 45 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,10 @@
1-
import { expect, test } from 'vitest';
1+
import { beforeEach, describe, expect, test } from 'vitest';
22
import assert from 'node:assert/strict';
3-
import { AppError } from '@agent-device/kernel/errors';
3+
import { AppError, isRequestCanceledError } from '@agent-device/kernel/errors';
4+
import { resetAllProcessMemosForTests } from '@agent-device/kernel/ttl-memo';
45
import { IOS_DEVICE, IOS_SIMULATOR, MACOS_DEVICE } from './device-fixtures.ts';
6+
import { appleRunnerTestHost } from '../test-host.ts';
7+
import type { ExecOptions } from '../host.ts';
58
import {
69
COLD_TOOLCHAIN_PROBE_TIMEOUT_MS,
710
diffComparableRunnerCacheMetadata,
@@ -253,58 +256,182 @@ test('a timed-out probe leaves the toolchain unavailable instead of a comparable
253256

254257
// Apple's syspolicyd signature scan blocks the first xcodebuild/xcrun exec
255258
// after a fresh macOS host boots for roughly 18 to 19 seconds; the immediate
256-
// next exec of the same tool is instant (#2422). These two cases exercise
257-
// the resulting one-retry policy without waiting on a real cold-start stall.
258-
// They use device fixtures untouched by the tests above so the toolchain
259-
// fingerprint cache starts empty for each.
259+
// next exec of the same tool is instant (#2422). These cases exercise the
260+
// resulting one-retry policy, and the budget that bounds it, without waiting
261+
// on a real cold-start stall: the fake clock only moves when a probe actually
262+
// blocks for the timeout it was given, so a case that claims the budget was
263+
// spent had to spend it.
264+
describe('toolchain probe budget', () => {
265+
// Failures are never memoized, but the recovery case below succeeds; each
266+
// case starts from an empty toolchain fingerprint cache so none of them
267+
// reads another's answer.
268+
beforeEach(resetAllProcessMemosForTests);
269+
270+
test('a cold-start probe recovers on retry, and the stall it survived is charged to the budget', () => {
271+
const clock = installFakeToolchainClock();
272+
const xcodebuildTimeouts: number[] = [];
273+
runCmdSync.mockImplementation((command: string, args: string[], options: ExecOptions) => {
274+
if (command !== 'xcodebuild') return appleToolchainProbeResult(command, args);
275+
xcodebuildTimeouts.push(options.timeoutMs ?? 0);
276+
if (xcodebuildTimeouts.length > 1) return appleToolchainProbeResult(command, args);
277+
throw blockForWholeTimeout(clock, command, args, options);
278+
});
279+
runCmdSync.mockClear();
280+
281+
const metadata = resolveExpectedRunnerCacheMetadata(IOS_DEVICE);
282+
283+
assert.equal(metadata.xcodeVersion, '26.2');
284+
assert.equal(metadata.xcodeBuildVersion, '17C52');
285+
// The retry runs on what the shared budget has left, not on a fresh
286+
// per-call ceiling: 45 s total minus the 30 s the first attempt burned.
287+
assert.deepEqual(xcodebuildTimeouts, [COLD_TOOLCHAIN_PROBE_TIMEOUT_MS, 15_000]);
288+
});
260289

261-
test('a cold-start toolchain probe recovers on retry: the first call exceeds the budget, the second returns immediately', () => {
262-
let xcodebuildAttempts = 0;
263-
runCmdSync.mockImplementation((command: string, args: readonly string[]) => {
264-
if (command === 'xcodebuild') {
265-
xcodebuildAttempts += 1;
266-
if (xcodebuildAttempts === 1) {
267-
throw new AppError('COMMAND_FAILED', 'xcodebuild timed out after 30000ms', {
268-
timeoutMs: 30_000,
269-
});
270-
}
271-
}
272-
return appleToolchainProbeResult(command, args);
290+
test('a toolchain host that never returns stops at the shared budget instead of once per probe', () => {
291+
const clock = installFakeToolchainClock();
292+
runCmdSync.mockImplementation((command: string, args: string[], options: ExecOptions) => {
293+
throw blockForWholeTimeout(clock, command, args, options);
294+
});
295+
runCmdSync.mockClear();
296+
297+
assert.throws(
298+
() => resolveExpectedRunnerCacheMetadata(MACOS_DEVICE),
299+
(error: unknown) => {
300+
assert.ok(error instanceof AppError);
301+
assert.equal(error.code, 'COMMAND_FAILED');
302+
assert.equal(error.details?.reason, 'apple_toolchain_probe_unavailable');
303+
assert.equal(error.details?.retriable, true);
304+
expect(error.details?.hint).toContain('xcode-select -p');
305+
expect(error.message).toContain('xcodebuild -version');
306+
// The reported failure is the last attempt: 30 s, then the 15 s the
307+
// budget still had.
308+
expect(error.message).toContain('xcodebuild timed out after 15000ms');
309+
expect(error.message).toContain('request budget');
310+
return true;
311+
},
312+
);
313+
// 30 s + a 15 s retry spends the whole budget on the first probe; the two
314+
// xcrun probes then fail on the budget instead of blocking for 30 s each.
315+
assert.equal(runCmdSync.mock.calls.length, 2);
316+
assert.equal(clock.nowMs, 45_000);
273317
});
274-
runCmdSync.mockClear();
275318

276-
const metadata = resolveExpectedRunnerCacheMetadata(IOS_DEVICE);
319+
test('an owning request with 4 s left gets one 4 s attempt and no retry', () => {
320+
const clock = installFakeToolchainClock();
321+
runCmdSync.mockImplementation((command: string, args: string[], options: ExecOptions) => {
322+
throw blockForWholeTimeout(clock, command, args, options);
323+
});
324+
runCmdSync.mockClear();
325+
326+
assert.throws(
327+
() => resolveExpectedRunnerCacheMetadata(IOS_SIMULATOR, undefined, { timeoutMs: 4_000 }),
328+
(error: unknown) => {
329+
assert.ok(error instanceof AppError);
330+
assert.equal(error.details?.reason, 'apple_toolchain_probe_unavailable');
331+
expect(error.message).toContain('xcodebuild timed out after 4000ms');
332+
expect(error.message).toContain('request budget');
333+
return true;
334+
},
335+
);
336+
assert.equal(runCmdSync.mock.calls.length, 1);
337+
assert.equal(clock.nowMs, 4_000);
338+
});
277339

278-
assert.equal(metadata.xcodeVersion, '26.2');
279-
assert.equal(metadata.xcodeBuildVersion, '17C52');
280-
expect(runCmdSync.mock.calls.filter(([command]) => command === 'xcodebuild')).toHaveLength(2);
281-
});
340+
test('a request canceled while a probe blocked surfaces the cancellation instead of retrying', () => {
341+
const clock = installFakeToolchainClock();
342+
const request = new AbortController();
343+
runCmdSync.mockImplementation((command: string, args: string[], options: ExecOptions) => {
344+
const timeout = blockForWholeTimeout(clock, command, args, options);
345+
request.abort();
346+
throw timeout;
347+
});
348+
runCmdSync.mockClear();
349+
350+
assert.throws(
351+
() =>
352+
resolveExpectedRunnerCacheMetadata(IOS_SIMULATOR, undefined, { signal: request.signal }),
353+
(error: unknown) => isRequestCanceledError(error),
354+
);
355+
assert.equal(runCmdSync.mock.calls.length, 1);
356+
});
282357

283-
test('a toolchain host that never returns still fails at the deadline with the same timeout error', () => {
284-
runCmdSync.mockImplementation((command: string, args: readonly string[]) => {
285-
if (command === 'xcodebuild') {
286-
throw new AppError('COMMAND_FAILED', 'xcodebuild timed out after 30000ms', {
287-
timeoutMs: 30_000,
288-
});
289-
}
290-
return appleToolchainProbeResult(command, args);
358+
test('an already-canceled request runs no toolchain probe at all', () => {
359+
installFakeToolchainClock();
360+
runCmdSync.mockClear();
361+
362+
assert.throws(
363+
() =>
364+
resolveExpectedRunnerCacheMetadata(IOS_SIMULATOR, undefined, {
365+
signal: AbortSignal.abort(),
366+
}),
367+
(error: unknown) => isRequestCanceledError(error),
368+
);
369+
assert.equal(runCmdSync.mock.calls.length, 0);
291370
});
292-
runCmdSync.mockClear();
293371

294-
try {
295-
resolveExpectedRunnerCacheMetadata(MACOS_DEVICE);
296-
assert.fail('expected an always-timing-out toolchain probe to fail the cache decision');
297-
} catch (error) {
298-
assert.ok(error instanceof AppError);
299-
assert.equal(error.code, 'COMMAND_FAILED');
300-
assert.equal(error.details?.retriable, true);
301-
expect(error.message).toContain('xcodebuild -version');
302-
expect(error.message).toContain('xcodebuild timed out after 30000ms');
303-
}
304-
// Exactly one retry, not an unbounded loop: the original attempt plus one retry.
305-
expect(runCmdSync.mock.calls.filter(([command]) => command === 'xcodebuild')).toHaveLength(2);
372+
test('a probe that failed on its own and merely says "timed out" in its message is not retried', () => {
373+
installFakeToolchainClock();
374+
runCmdSync.mockImplementation((command: string, args: string[]) => {
375+
if (command !== 'xcodebuild') return appleToolchainProbeResult(command, args);
376+
// No `timeoutMs` detail: this is the tool reporting its own failure, not
377+
// the exec layer killing it at a timeout we asked for.
378+
throw new AppError('COMMAND_FAILED', 'xcodebuild timed out after 10ms', {
379+
cmd: command,
380+
args,
381+
});
382+
});
383+
runCmdSync.mockClear();
384+
385+
assert.throws(
386+
() => resolveExpectedRunnerCacheMetadata(IOS_SIMULATOR),
387+
(error: unknown) => {
388+
assert.ok(error instanceof AppError);
389+
expect(error.message).toContain('xcodebuild timed out after 10ms');
390+
return true;
391+
},
392+
);
393+
expect(runCmdSync.mock.calls.filter(([command]) => command === 'xcodebuild')).toHaveLength(1);
394+
});
306395
});
307396

397+
/**
398+
* A clock the probes' own budget reads, advanced only by
399+
* {@link blockForWholeTimeout}. Without it a mock that throws immediately
400+
* proves nothing about a deadline: no time passes, so every budget looks
401+
* untouched however many attempts run.
402+
*/
403+
function installFakeToolchainClock(): { nowMs: number } {
404+
const clock = { nowMs: 0 };
405+
appleRunnerTestHost.update({
406+
deadlineFromTimeoutMs: (timeoutMs: number) => {
407+
const startedAtMs = clock.nowMs;
408+
const expiresAtMs = startedAtMs + Math.max(0, timeoutMs);
409+
return {
410+
remainingMs: () => Math.max(0, expiresAtMs - clock.nowMs),
411+
elapsedMs: () => Math.max(0, clock.nowMs - startedAtMs),
412+
isExpired: () => expiresAtMs - clock.nowMs <= 0,
413+
};
414+
},
415+
});
416+
return clock;
417+
}
418+
419+
/** A probe that blocked for its whole timeout and was then killed, as the exec layer reports it. */
420+
function blockForWholeTimeout(
421+
clock: { nowMs: number },
422+
command: string,
423+
args: string[],
424+
options: ExecOptions,
425+
): AppError {
426+
const timeoutMs = options.timeoutMs ?? 0;
427+
clock.nowMs += timeoutMs;
428+
return new AppError('COMMAND_FAILED', `${command} timed out after ${timeoutMs}ms`, {
429+
cmd: command,
430+
args,
431+
timeoutMs,
432+
});
433+
}
434+
308435
test('a failing probe reports its exit status rather than a fabricated SDK version', () => {
309436
runCmdSync.mockImplementation((command: string, args: readonly string[]) =>
310437
command === 'xcrun'

packages/platform-apple/src/runner/host.ts

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -149,6 +149,12 @@ export type AppleRunnerHost = {
149149
message: string,
150150
extra?: Record<string, unknown> | ((result: ExecResult) => Record<string, unknown>),
151151
): ExecResult;
152+
/**
153+
* True only for the error the exec layer raises when it killed a command at
154+
* the `timeoutMs` the caller asked for, read from the structured detail it
155+
* stamps rather than from the message text.
156+
*/
157+
isCommandTimeoutError(error: unknown): boolean;
152158
// Diagnostics (@agent-device/host-kit/diagnostics)
153159
emitDiagnostic(event: DiagnosticEventInput): void;
154160
withDiagnosticTimer<T>(
@@ -277,6 +283,8 @@ export const runCmdBackground: AppleRunnerHost['runCmdBackground'] = (cmd, args,
277283
requireHost().runCmdBackground(cmd, args, options);
278284
export const requireExecSuccess: AppleRunnerHost['requireExecSuccess'] = (result, message, extra) =>
279285
requireHost().requireExecSuccess(result, message, extra);
286+
export const isCommandTimeoutError: AppleRunnerHost['isCommandTimeoutError'] = (error) =>
287+
requireHost().isCommandTimeoutError(error);
280288
export const emitDiagnostic: AppleRunnerHost['emitDiagnostic'] = (event) =>
281289
requireHost().emitDiagnostic(event);
282290
export const withDiagnosticTimer = <T>(

packages/platform-apple/src/runner/runner-adoption.ts

Lines changed: 12 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,7 @@ import {
1919
import {
2020
resolveExpectedRunnerCacheMetadata,
2121
resolveRunnerDerivedPath,
22+
type RunnerCacheProbeBudget,
2223
type RunnerXctestrunArtifact,
2324
} from './runner-xctestrun.ts';
2425
import {
@@ -86,7 +87,9 @@ export async function tryAdoptRunnerSessionFromLease(
8687
if (!verifyLeaseRunnerPidIdentity(lease, runnerPid)) {
8788
return skip('runner_pid_recycled');
8889
}
89-
const expectedDerived = resolveExpectedDerivedPath(device);
90+
const expectedDerived = resolveExpectedDerivedPath(device, {
91+
timeoutMs: options.startupTimeoutMs,
92+
});
9093
if (!expectedDerived) return skip('expected_derived_unresolved');
9194
if (!lease.xctestrunPath.startsWith(`${expectedDerived}${path.sep}`)) {
9295
return skip('artifact_fingerprint_mismatch');
@@ -134,9 +137,15 @@ async function probeRunnerAnswersUptime(device: DeviceInfo, port: number): Promi
134137
}
135138
}
136139

137-
function resolveExpectedDerivedPath(device: DeviceInfo): string | null {
140+
function resolveExpectedDerivedPath(
141+
device: DeviceInfo,
142+
budget: RunnerCacheProbeBudget,
143+
): string | null {
138144
try {
139-
return resolveRunnerDerivedPath(device, resolveExpectedRunnerCacheMetadata(device));
145+
return resolveRunnerDerivedPath(
146+
device,
147+
resolveExpectedRunnerCacheMetadata(device, undefined, budget),
148+
);
140149
} catch {
141150
return null;
142151
}

0 commit comments

Comments
 (0)