From 96e1a801dc300275b281207a3b379d16aae5b30c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20Pierzcha=C5=82a?= Date: Sun, 6 Sep 2026 10:26:57 +0200 Subject: [PATCH 1/3] feat(wait): carry a per-poll timeline in timeout failures A wait timeout said `reason`, `readableCaptures`, and `waitedMs`, so a failure could not say where its budget went: the runs behind #2343 spent a 10s budget on one poll (5.8s runner findText on a fresh app, 3.4s of target discovery, a fallback cancelled at the deadline) and reported the same `wait_capture_stalled` as a dead runner. The failure details now carry `captures` and `polls[]`, one entry per poll with `startedMs` on the wait's own clock, `durationMs`, and a typed outcome (readable, unreadable, deadline, runner-restart), next to the unchanged reason and the request-log link. Long waits keep the first five and last twenty-five polls so the response stays compact. --- CHANGELOG.md | 4 ++ .../interaction/runtime/wait-polling.test.ts | 58 +++++++++++++++++++ .../interaction/runtime/wait-polling.ts | 34 +++++++++++ website/docs/docs/commands.md | 1 + 4 files changed, 97 insertions(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 22b1f9514b..d704ab9ee5 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,6 +2,10 @@ ## Unreleased +- Added: `wait` timeout errors carry a per-poll timeline in `error.details` (`captures`, + `polls[]` with `startedMs`, `durationMs`, and a typed `outcome`: readable, unreadable, deadline, + runner-restart) next to the unchanged `reason`, so a failure says where its budget went without + opening the request log. Long waits keep the first five and last twenty-five polls. - Fixed: iOS snapshots no longer report `truncated: true` merely because a later backend produced them. The runner stamped every recovered capture as truncated — including a complete private-AX tree taken while the XCTest channel was penalized as slow — so a strict `is absent` / `wait absent` diff --git a/src/commands/interaction/runtime/wait-polling.test.ts b/src/commands/interaction/runtime/wait-polling.test.ts index 0c6c861ffd..1721d7e027 100644 --- a/src/commands/interaction/runtime/wait-polling.test.ts +++ b/src/commands/interaction/runtime/wait-polling.test.ts @@ -41,3 +41,61 @@ test('poll delay observes both runtime and command cancellation', async () => { await assert.rejects(sleeping, reason); } }); + +test('failure evidence carries every poll on the wait clock with its typed outcome', async () => { + let currentMs = 0; + const runtime = { + clock: { now: () => currentMs, sleep: async (_durationMs: number) => {} }, + } as AgentDeviceRuntime; + const unreadable = new Error('content verdict'); + const polling = createWaitPolling(runtime, {}, 60, SELECTOR_PIPELINE_POLICIES.wait, { + isUnreadableError: (error) => error === unreadable, + }); + + await polling.capture(async () => { + currentMs += 20; + return 'seen'; + }); + await polling.capture(async () => { + currentMs += 10; + throw unreadable; + }); + // The third capture outlives the remaining real-time budget: the deadline cancels it. + const last = await polling.capture(async () => { + await new Promise((resolve) => setTimeout(resolve, 120)); + currentMs += 40; + return 'late'; + }); + + assert.equal(last.timedOut, true); + const evidence = polling.failureEvidence(); + assert.equal(evidence.captures, 3); + assert.equal(evidence.readableCaptures, 1); + assert.deepEqual(evidence.polls, [ + { startedMs: 0, durationMs: 20, outcome: 'readable' }, + { startedMs: 20, durationMs: 10, outcome: 'unreadable' }, + { startedMs: 30, durationMs: 40, outcome: 'deadline' }, + ]); +}); + +test('a long wait keeps its first polls and its last polls in the failure evidence', async () => { + let currentMs = 0; + const runtime = { + clock: { now: () => currentMs, sleep: async (_durationMs: number) => {} }, + } as AgentDeviceRuntime; + const polling = createWaitPolling(runtime, {}, 100_000, SELECTOR_PIPELINE_POLICIES.wait); + for (let index = 0; index < 40; index += 1) { + await polling.capture(async () => { + currentMs += 100; + return index; + }); + } + + const evidence = polling.failureEvidence(); + assert.equal(evidence.captures, 40); + assert.equal(evidence.polls.length, 30); + assert.equal(evidence.polls[0]?.startedMs, 0); + assert.equal(evidence.polls[4]?.startedMs, 400); + assert.equal(evidence.polls[5]?.startedMs, 1_500); + assert.equal(evidence.polls.at(-1)?.startedMs, 3_900); +}); diff --git a/src/commands/interaction/runtime/wait-polling.ts b/src/commands/interaction/runtime/wait-polling.ts index ca5738135b..accfc6dce3 100644 --- a/src/commands/interaction/runtime/wait-polling.ts +++ b/src/commands/interaction/runtime/wait-polling.ts @@ -17,9 +17,30 @@ export const DEFAULT_WAIT_TIMEOUT_MS = SELECTOR_PIPELINE_POLICIES.wait.poll.defa export type WaitPollDeadline = 'capture-stalled' | 'capture-truncated' | 'runner-restart-exhausted'; +/** + * How one poll ended: a readable capture, an unreadable content verdict the wait rode out, the + * deadline cancelling the capture in flight, or that cancellation carrying runner-restart + * evidence. Whether a readable capture matched is the caller's verdict, not the poll's. + */ +export type WaitPollOutcome = 'readable' | 'unreadable' | 'deadline' | 'runner-restart'; + +/** One poll on the wait's own clock: when it started after the wait began and how long it ran. */ +export type WaitPollRecord = { + startedMs: number; + durationMs: number; + outcome: WaitPollOutcome; +}; + +/** Keeps a long wait's failure compact: the first polls carry the cold-start cost, the last the end. */ +const WAIT_POLL_TIMELINE_HEAD = 5; +const WAIT_POLL_TIMELINE_TAIL = 25; + export type WaitFailureEvidence = { timeoutMs: number; readableCaptures: number; + /** Every poll attempted, readable or not. */ + captures: number; + polls: WaitPollRecord[]; waitedMs: number; runnerRestarted?: true; runnerRestartReason?: string; @@ -77,12 +98,16 @@ export function createWaitPolling( const timeoutMs = requestedTimeoutMs ?? budget.defaultTimeoutMs; const startedAtMs = now(runtime); const unreadable = createUnreadablePollTracker(classification.isUnreadableError); + const polls: WaitPollRecord[] = []; let timeoutEvidence: Partial = {}; const remainingMs = () => Math.max(0, timeoutMs - (now(runtime) - startedAtMs)); return { capture: async (capture: (signal: AbortSignal) => Promise) => { let captureWasReadable = false; + const startedMs = now(runtime) - startedAtMs; + const recordPoll = (outcome: WaitPollOutcome) => + polls.push({ startedMs, durationMs: now(runtime) - startedAtMs - startedMs, outcome }); const result = await runWithinWaitDeadline( runtime, options, @@ -96,9 +121,11 @@ export function createWaitPolling( ); if (!result.timedOut) { if (captureWasReadable) unreadable.recordReadableCapture(); + recordPoll(captureWasReadable ? 'readable' : 'unreadable'); return result; } const runnerRestart = runnerRestartTimeoutEvidence(result.error); + recordPoll(runnerRestart ? 'runner-restart' : 'deadline'); timeoutEvidence = runnerRestart ?? {}; // A capture that only becomes readable after its deadline is not evidence for this wait. // Count only captures that completed before runWithinWaitDeadline returned a timeout. @@ -119,6 +146,8 @@ export function createWaitPolling( failureEvidence: (): WaitFailureEvidence => ({ timeoutMs, readableCaptures: unreadable.readableCaptures(), + captures: polls.length, + polls: compactPollTimeline(polls), waitedMs: now(runtime) - startedAtMs, ...timeoutEvidence, }), @@ -131,6 +160,11 @@ export function createWaitPolling( }; } +function compactPollTimeline(polls: readonly WaitPollRecord[]): WaitPollRecord[] { + if (polls.length <= WAIT_POLL_TIMELINE_HEAD + WAIT_POLL_TIMELINE_TAIL) return [...polls]; + return [...polls.slice(0, WAIT_POLL_TIMELINE_HEAD), ...polls.slice(-WAIT_POLL_TIMELINE_TAIL)]; +} + function waitCaptureStalledError(message: string, evidence: WaitFailureEvidence): AppError { return new AppError('COMMAND_FAILED', message, { reason: WAIT_REASONS.captureStalled, diff --git a/website/docs/docs/commands.md b/website/docs/docs/commands.md index 1b6b1a3524..94ccd0017e 100644 --- a/website/docs/docs/commands.md +++ b/website/docs/docs/commands.md @@ -419,6 +419,7 @@ agent-device alert dismiss - Because `wait @ref` is text-based after resolution, duplicate labels can match a different element than the original ref target. - `wait` shares the selector/snapshot resolution flow used by `click`, `fill`, `get`, and `is`. - Wait failures carry a structured `error.details.reason` in `--json` output: `wait_target_absent` proves a positive wait never found a match; `wait_target_present` means strict `wait absent` reached its deadline with valid captures that still contained matches; `predicate_failed` means strict `wait absent` could not prove absence because no valid capture arrived, with the final observation/diagnostic preserved; `wait_capture_stalled` means no readable capture arrived and is retriable; `wait_deadline_exceeded` means a later capture consumed the remaining budget after an earlier readable capture; `wait_landmark_identity_mismatch` is a replay destination-guard refusal; and `wait_stable_timeout` means the UI did not settle. Use `readableCaptures`, `waitedMs`, `matches`, and `firstMatch` instead of parsing error text. `firstMatch` carries identity/text evidence only; absence failures do not claim visibility or rect evidence. +- Wait failures also carry `captures` (every poll attempted), `readableCaptures`, and `polls`, one entry per poll with `startedMs` on the wait's own clock, `durationMs`, and `outcome` (`readable`, `unreadable`, `deadline`, or `runner-restart`), so a timeout says where its budget went; long waits keep the first five and last twenty-five polls. `logPath` links the full request log. - `alert` inspects or handles system alerts on iOS simulator, macOS desktop, and Android native/runtime permission dialogs. - `alert` without an action is equivalent to `alert get`. - `accept` and `dismiss` are sent once on every platform. A lost or unconfirmed response is reported as an error and never replayed; run `alert get` before acting again. From cc1add6e2f5020175e573a432e6e9169aa690945 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20Pierzcha=C5=82a?= Date: Sun, 6 Sep 2026 11:07:30 +0200 Subject: [PATCH 2/3] docs(wait): name the polling timeout paths that carry the poll timeline Review follow-up: wait --stable uses its own error builder and a never-readable strict absence preserves its predicate failure, so the timeline is documented for the polling timeout paths that emit it. --- CHANGELOG.md | 8 +++++--- website/docs/docs/commands.md | 2 +- 2 files changed, 6 insertions(+), 4 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index d704ab9ee5..50653241ff 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -2,10 +2,12 @@ ## Unreleased -- Added: `wait` timeout errors carry a per-poll timeline in `error.details` (`captures`, - `polls[]` with `startedMs`, `durationMs`, and a typed `outcome`: readable, unreadable, deadline, +- Added: polling `wait` timeouts (`wait `, `wait text`, `wait @ref`, and `wait absent` + after a readable capture) carry a per-poll timeline in `error.details` (`captures`, `polls[]` + with `startedMs`, `durationMs`, and a typed `outcome`: readable, unreadable, deadline, runner-restart) next to the unchanged `reason`, so a failure says where its budget went without - opening the request log. Long waits keep the first five and last twenty-five polls. + opening the request log. Long waits keep the first five and last twenty-five polls. `wait + --stable` timeouts and a never-readable strict absence keep their existing diagnostics. - Fixed: iOS snapshots no longer report `truncated: true` merely because a later backend produced them. The runner stamped every recovered capture as truncated — including a complete private-AX tree taken while the XCTest channel was penalized as slow — so a strict `is absent` / `wait absent` diff --git a/website/docs/docs/commands.md b/website/docs/docs/commands.md index 94ccd0017e..275fe058bd 100644 --- a/website/docs/docs/commands.md +++ b/website/docs/docs/commands.md @@ -419,7 +419,7 @@ agent-device alert dismiss - Because `wait @ref` is text-based after resolution, duplicate labels can match a different element than the original ref target. - `wait` shares the selector/snapshot resolution flow used by `click`, `fill`, `get`, and `is`. - Wait failures carry a structured `error.details.reason` in `--json` output: `wait_target_absent` proves a positive wait never found a match; `wait_target_present` means strict `wait absent` reached its deadline with valid captures that still contained matches; `predicate_failed` means strict `wait absent` could not prove absence because no valid capture arrived, with the final observation/diagnostic preserved; `wait_capture_stalled` means no readable capture arrived and is retriable; `wait_deadline_exceeded` means a later capture consumed the remaining budget after an earlier readable capture; `wait_landmark_identity_mismatch` is a replay destination-guard refusal; and `wait_stable_timeout` means the UI did not settle. Use `readableCaptures`, `waitedMs`, `matches`, and `firstMatch` instead of parsing error text. `firstMatch` carries identity/text evidence only; absence failures do not claim visibility or rect evidence. -- Wait failures also carry `captures` (every poll attempted), `readableCaptures`, and `polls`, one entry per poll with `startedMs` on the wait's own clock, `durationMs`, and `outcome` (`readable`, `unreadable`, `deadline`, or `runner-restart`), so a timeout says where its budget went; long waits keep the first five and last twenty-five polls. `logPath` links the full request log. +- Polling wait timeouts (`wait `, `wait text`, `wait @ref`, and `wait absent` once a readable capture has been seen) also carry `captures` (every poll attempted), `readableCaptures`, and `polls`, one entry per poll with `startedMs` on the wait's own clock, `durationMs`, and `outcome` (`readable`, `unreadable`, `deadline`, or `runner-restart`), so a timeout says where its budget went; long waits keep the first five and last twenty-five polls. `wait --stable` timeouts and a never-readable strict absence keep their own diagnostics. `logPath` links the full request log. - `alert` inspects or handles system alerts on iOS simulator, macOS desktop, and Android native/runtime permission dialogs. - `alert` without an action is equivalent to `alert get`. - `accept` and `dismiss` are sent once on every platform. A lost or unconfirmed response is reported as an error and never replayed; run `alert get` before acting again. From 1a1003739b3dd946faa8ba2340c96c7ef0ebd293 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20Pierzcha=C5=82a?= Date: Sun, 6 Sep 2026 11:42:48 +0200 Subject: [PATCH 3/3] feat(wait): carry the poll evidence on the replay landmark-mismatch refusal Review follow-up. A replayed selector wait refused for a recorded landmark mismatch threw without the captures/polls evidence, and when its final poll ended in a runner restart the refusal hid that outcome. The refusal now carries the same failure evidence a timeout does, next to its mismatch details; two regressions cover a mismatch followed by a deadline-cancelled capture and by a runner restart. Docs and changelog name the refusal alongside the polling timeout paths. --- CHANGELOG.md | 3 +- .../interaction/runtime/wait-selector.test.ts | 92 +++++++++++++++++++ .../interaction/runtime/wait-selector.ts | 4 +- website/docs/docs/commands.md | 2 +- 4 files changed, 98 insertions(+), 3 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index d99a0bf222..51ca7225be 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -6,7 +6,8 @@ after a readable capture) carry a per-poll timeline in `error.details` (`captures`, `polls[]` with `startedMs`, `durationMs`, and a typed `outcome`: readable, unreadable, deadline, runner-restart) next to the unchanged `reason`, so a failure says where its budget went without - opening the request log. Long waits keep the first five and last twenty-five polls. `wait + opening the request log. Long waits keep the first five and last twenty-five polls. The replay + landmark-mismatch refusal carries the same poll evidence next to its mismatch details; `wait --stable` timeouts and a never-readable strict absence keep their existing diagnostics. - Fixed: the iOS Simulator AX snapshot route bounds how long a capture waits for app discovery and stops starting a discovery per capture. Discovery (`simctl launchctl list` through xcrun) diff --git a/src/commands/interaction/runtime/wait-selector.test.ts b/src/commands/interaction/runtime/wait-selector.test.ts index e3825354a2..e26602449e 100644 --- a/src/commands/interaction/runtime/wait-selector.test.ts +++ b/src/commands/interaction/runtime/wait-selector.test.ts @@ -207,6 +207,98 @@ test('runtime wait fails closed at the deadline when only impostors matched the assert.equal(observed.label, 'Screen X'); const ancestry = error.details?.observedAncestry as Array<{ role: string; label?: string }>; assert.equal(ancestry[0]?.label, 'List Screen'); + assertReadablePollEvidence(error); +}); + +/** The refusal carries the same poll evidence a plain timeout would. */ +function assertReadablePollEvidence(error: AppError): void { + const details = error.details ?? {}; + const polls = details.polls as Array<{ outcome: string }>; + assert.ok(polls.length >= 1); + assert.ok(polls.every((poll) => poll.outcome === 'readable')); + assert.equal(details.captures, polls.length); + assert.equal(details.readableCaptures, polls.length); + assert.equal(typeof details.waitedMs, 'number'); +} + +/** + * An impostor capture, then a capture that outlives the deadline: the refusal still names the + * landmark mismatch, and its poll timeline shows the deadline cutting the last capture short, + * with the runner-restart evidence that capture carried. + */ +async function landmarkRefusalAfter( + finalCapture: () => Promise>, +): Promise { + const recorded = recordedLandmarkFor(landmarkScreen('Detail Screen')); + let call = 0; + const impostor = landmarkScreen('List Screen'); + const device = createAgentDevice({ + backend: { + platform: 'ios', + captureSnapshot: async () => { + call += 1; + if (call === 1) return { snapshot: impostor }; + return { snapshot: await finalCapture() }; + }, + } satisfies AgentDeviceBackend, + artifacts: createLocalArtifactAdapter(), + sessions: createMemorySessionStore([{ name: 'default', snapshot: impostor }]), + policy: localCommandPolicy(), + clock: createFakeClock(100), + }); + const error = await device.selectors + .wait({ + session: 'default', + target: { + kind: 'selector', + selector: 'label="Screen X"', + timeoutMs: 400, + recordedLandmark: recorded, + }, + }) + .then( + () => undefined, + (error: unknown) => error, + ); + assert.ok(error instanceof AppError); + assert.equal(error.details?.reason, WAIT_LANDMARK_MISMATCH_REASON); + return error; +} + +test('landmark refusal after a deadline-cancelled capture keeps the poll timeline', async () => { + const error = await landmarkRefusalAfter(async () => { + await new Promise((resolve) => setTimeout(resolve, 600)); + return landmarkScreen('List Screen'); + }); + + const polls = error.details?.polls as Array<{ outcome: string }>; + assert.deepEqual( + polls.map((poll) => poll.outcome), + ['readable', 'deadline'], + ); + assert.equal(error.details?.readableCaptures, 1); + assert.equal(error.details?.captures, 2); +}); + +test('landmark refusal after a runner restart keeps the restart outcome', async () => { + const error = await landmarkRefusalAfter(async () => { + await new Promise((resolve) => setTimeout(resolve, 600)); + throw new AppError('COMMAND_FAILED', 'runner restarted', { + runnerRestarted: true, + runnerRestartReason: 'runner_readiness_preflight_failed_before_command_send', + }); + }); + + const polls = error.details?.polls as Array<{ outcome: string }>; + assert.deepEqual( + polls.map((poll) => poll.outcome), + ['readable', 'runner-restart'], + ); + assert.equal(error.details?.runnerRestarted, true); + assert.equal( + error.details?.runnerRestartReason, + 'runner_readiness_preflight_failed_before_command_send', + ); }); test('runtime wait with a recorded landmark keeps the plain timeout when the selector never matched', async () => { diff --git a/src/commands/interaction/runtime/wait-selector.ts b/src/commands/interaction/runtime/wait-selector.ts index 1b146eb148..5c07f4d6ac 100644 --- a/src/commands/interaction/runtime/wait-selector.ts +++ b/src/commands/interaction/runtime/wait-selector.ts @@ -119,10 +119,12 @@ export async function waitForSelector( await polling.sleepUntilNextPoll(); } if (deadline !== 'capture-stalled' && landmarkMismatch) { + // The refusal keeps the poll evidence a plain timeout would carry, including a runner + // restart on the final poll: the mismatch is the verdict, not the whole story of the wait. throw new AppError( 'COMMAND_FAILED', `wait matched selector ${selectorExpression} but no candidate carried the recorded landmark identity`, - { reason: WAIT_LANDMARK_MISMATCH_REASON, ...landmarkMismatch }, + { reason: WAIT_LANDMARK_MISMATCH_REASON, ...polling.failureEvidence(), ...landmarkMismatch }, ); } throw waitTimeoutError(`wait timed out for selector: ${selectorExpression}`, polling, deadline); diff --git a/website/docs/docs/commands.md b/website/docs/docs/commands.md index 275fe058bd..1840a8ede4 100644 --- a/website/docs/docs/commands.md +++ b/website/docs/docs/commands.md @@ -419,7 +419,7 @@ agent-device alert dismiss - Because `wait @ref` is text-based after resolution, duplicate labels can match a different element than the original ref target. - `wait` shares the selector/snapshot resolution flow used by `click`, `fill`, `get`, and `is`. - Wait failures carry a structured `error.details.reason` in `--json` output: `wait_target_absent` proves a positive wait never found a match; `wait_target_present` means strict `wait absent` reached its deadline with valid captures that still contained matches; `predicate_failed` means strict `wait absent` could not prove absence because no valid capture arrived, with the final observation/diagnostic preserved; `wait_capture_stalled` means no readable capture arrived and is retriable; `wait_deadline_exceeded` means a later capture consumed the remaining budget after an earlier readable capture; `wait_landmark_identity_mismatch` is a replay destination-guard refusal; and `wait_stable_timeout` means the UI did not settle. Use `readableCaptures`, `waitedMs`, `matches`, and `firstMatch` instead of parsing error text. `firstMatch` carries identity/text evidence only; absence failures do not claim visibility or rect evidence. -- Polling wait timeouts (`wait `, `wait text`, `wait @ref`, and `wait absent` once a readable capture has been seen) also carry `captures` (every poll attempted), `readableCaptures`, and `polls`, one entry per poll with `startedMs` on the wait's own clock, `durationMs`, and `outcome` (`readable`, `unreadable`, `deadline`, or `runner-restart`), so a timeout says where its budget went; long waits keep the first five and last twenty-five polls. `wait --stable` timeouts and a never-readable strict absence keep their own diagnostics. `logPath` links the full request log. +- Polling wait timeouts (`wait `, `wait text`, `wait @ref`, and `wait absent` once a readable capture has been seen) also carry `captures` (every poll attempted), `readableCaptures`, and `polls`, one entry per poll with `startedMs` on the wait's own clock, `durationMs`, and `outcome` (`readable`, `unreadable`, `deadline`, or `runner-restart`), so a timeout says where its budget went; long waits keep the first five and last twenty-five polls. A replayed selector wait refused for a recorded landmark mismatch (`wait_landmark_identity_mismatch`) carries the same poll evidence next to its mismatch details. `wait --stable` timeouts and a never-readable strict absence keep their own diagnostics. `logPath` links the full request log. - `alert` inspects or handles system alerts on iOS simulator, macOS desktop, and Android native/runtime permission dialogs. - `alert` without an action is equivalent to `alert get`. - `accept` and `dismiss` are sent once on every platform. A lost or unconfirmed response is reported as an error and never replayed; run `alert get` before acting again.