diff --git a/.fallowrc.json b/.fallowrc.json index 0b58fe1c5e..84cd610a37 100644 --- a/.fallowrc.json +++ b/.fallowrc.json @@ -93,7 +93,7 @@ "comment": "Runner operations reach the daemon only through the memoized loader in src/platform-runtime-apple-application-tools.ts (one dynamic import per specifier, #2314). Fallow cannot connect a member read off that loader's promise to these re-exports; keep the list to the facade members no static import consumes.", "file": "packages/platform-apple/src/runner-operations-facade.ts", "exports": [ - "detachIosSimulatorRunnerSessionsForShutdown", + "detachIosRunnerSessionsForShutdown", "hasLiveIosRunnerSession", "releaseIosRunnerOnClose", "releaseSpeculativeIosRunnerSessionFor", @@ -159,7 +159,7 @@ "prewarmIosRunnerSession", "prepareIosRunner", "resolveRunnerAppBundleId", - "detachIosSimulatorRunnerSessionsForShutdown", + "detachIosRunnerSessionsForShutdown", "getRunnerSessionSnapshot", "stopIosRunnerSession", "stopAllIosRunnerSessions", diff --git a/.gitignore b/.gitignore index e80fd1177f..efb45dc4ba 100644 --- a/.gitignore +++ b/.gitignore @@ -10,6 +10,7 @@ coverage/ .tmp/ # Per-project agent-device output: test artifacts, metro and tunnel logs /.agent-device/ +.device-evidence/ .DS_Store # Host-local Codex state and embedded worktree clones diff --git a/docs/agents/device-verification.md b/docs/agents/device-verification.md index e802cba382..e2cc38904f 100644 --- a/docs/agents/device-verification.md +++ b/docs/agents/device-verification.md @@ -10,9 +10,12 @@ physical devices. Live verification steps apply when exercising a device-facing - Before any Android verification from source: `pnpm build`, `pnpm build:android`, `pnpm clean:daemon`. `build:android` refreshes and verifies both bundled Android helper artifacts for the current package version. -- `shutdown` hands off a healthy simulator runner; a new daemon may adopt the old binary. After +- Graceful `shutdown` hands off a healthy runner that already answered a command, on the simulator + and physical iOS lanes alike; a new daemon may adopt the old binary. After Swift runner changes, run `pnpm build:xcuitest` before verification. Use the session cleanup - procedure below if ownership is stuck. + procedure below if ownership is stuck. The physical handoff's device steps are + `docs/evidence/ios-physical-runner-handoff-2026-09-19.md`; nothing in it is proven until someone + with a cabled device checks a box. ## Prove the path under test was actually active diff --git a/docs/evidence/ios-physical-runner-handoff-2026-09-19.md b/docs/evidence/ios-physical-runner-handoff-2026-09-19.md new file mode 100644 index 0000000000..ec0a606aea --- /dev/null +++ b/docs/evidence/ios-physical-runner-handoff-2026-09-19.md @@ -0,0 +1,306 @@ +# Physical iOS runner handoff - device verification checklist (#2681) + +Automated tests cover the gates and the lane predicate. What they cannot prove is that a real +`xcodebuild build-for-testing` process on a cabled iPhone survives the daemon that started it and +serves the next daemon. Every claim below needs a physical iOS 17+ device. + +The implementing agent had no device access and proved nothing here. A coordinator with a cabled +iPhone has since run part of this checklist, at head `3a31b6a691` (the two-phase probe); those results +are recorded inline below with that SHA. Anything collected before a code change is re-owed at the +head being merged, so each backfilled section also carries an unchecked re-verification box. + +Device used for the runs below: `thymikee-iphone`, iPhone 17 Pro, iOS 27.0 (build `24A437`), +CoreDevice UUID `50F8E1E1-7658-5550-BB4D-3D2C741AD85A`, hardware UDID +`00008150-001849640CF8401C`, Xcode 26.2 (Build `17C52`). + +## Preconditions + +- [ ] Cabled iPhone, iOS 17+, unlocked, developer mode on, visible to `xcrun devicectl list devices`. +- [ ] `pnpm install --frozen-lockfile && pnpm build && pnpm build:xcuitest && pnpm clean:daemon` + (the daemon does not self-reload; `clean:daemon` drops retained simulator evidence). +- [ ] `pnpm daemon:state-dir` -> note as `$STATE_DIR`. Daemon lifecycle diagnostics: `$STATE_DIR/daemon.log`. +- [ ] `node bin/agent-device.mjs device list --json` -> note the physical iOS entry as `$DEVICE_ID` + (its lease file is named after it) and confirm `iosPhysicalDeviceBackend` is `coredevice`. +- [ ] Lease root: `~/.agent-device/apple-runner/leases/$DEVICE_ID.json` unless + `AGENT_DEVICE_IOS_RUNNER_LEASE_DIR` is set. Note as `$LEASE`. +- [ ] `jq -r .runnerLogPath $LEASE` -> note as `$RUNNER_LOG`. This is the file the runner's own + standard output and error were redirected into at spawn, and the path the next daemon keeps + writing to after adoption. + +Read-only PID inspection below is evidence gathering. It is not the recovery path: ownership +recovery stays on `device status --stale` / `device release --stale` (see +`docs/agents/device-verification.md`). + +## 1. Detach on graceful shutdown (the new path) + +- [ ] `node bin/agent-device.mjs open --platform ios --udid --session p2681 --foreground -i --json` + -> snapshot returns nodes. This is what publishes the session `ready`; without it there is nothing to hand off. +- [ ] Record `$RUNNER_PID`, `$RUNNER_PORT`, `$OWNER_TOKEN` from `$LEASE` (`jq .runnerPid,.port,.ownerToken $LEASE`). +- [ ] `node bin/agent-device.mjs daemon stop` (graceful; never `kill -9`). +- [ ] `$LEASE` `ownerToken` now matches `^detached-owner-`. +- [x] `grep '"phase":"ios_runner_session_detached"' "$STATE_DIR/daemon.log"` -> one line with + `"lane":"physical_coredevice"`, the recorded `runnerPid`, and `runnerLogPath` equal to `$RUNNER_LOG`. + A handoff whose diagnostics are missing is a finding even when the runner survives: diagnostics + are how the next engineer sees why a handoff did or did not happen. +- [x] `ps -p $RUNNER_PID -o pid,etime,comm` -> the same `xcodebuild`/runner process is alive and its + elapsed time spans the restart. + +> **Result, `3a31b6a691`.** One `ios_runner_session_detached` line with `"lane":"physical_coredevice"` +> and the recorded `runnerPid` (50471); `ps` showed the same `xcodebuild` alive across the restart with +> elapsed time spanning it. `ownerToken` prefix and `runnerLogPath` equality were not separately +> asserted in that run, so both stay unchecked. +> **Re-verified at `378d4dbfa3` (all four).** `ownerToken` went `owner-61991-fe098769` -> +> `detached-owner-61991-fe098769`; one `ios_runner_session_detached` line carried +> `"lane":"physical_coredevice"`, `runnerPid` 62408 and a `runnerLogPath` equal to the lease's; `ps` +> showed the same `xcodebuild` alive with elapsed time spanning the restart. +> - [x] Re-run at the head being merged, asserting all four observations. + +## 2. Output still reaches the log after the handoff + +The handoff closes only this daemon's copy of the log descriptor. A runner that dies on its next +write would look like a healthy adoption and then fail minutes later, which is the failure this +section exists to catch. + +- [ ] Nothing a client sends forces `xcodebuild` to write on demand, so take the two moments it does: + unplug the cable for 10 s and replug it, and later (step 3) close the session so the runner + tears itself down. Both make the process write to the descriptor it inherited at spawn. +- [ ] After the replug: `wc -c "$RUNNER_LOG"` grew and `tail -40 "$RUNNER_LOG"` shows new output while + `ps -p $RUNNER_PID -o pid,etime` shows the same process, undisturbed by the handoff. +- [ ] After step 3's `close --session p2681`: the same file ends with the runner's own teardown line. +> **Negative result at `af55e2746b`, so this section is not satisfied by a cable cycle.** Across the +> unplug/replug above, `runner.log` went 78516 -> 78516 bytes: the runner survived, was adopted, and +> wrote nothing. Nothing here disproves the SIGPIPE regression this section guards, but it also does not +> prove output reaches a handed-off log. + +- [ ] If the runner vanished instead: capture `$RUNNER_LOG` and `daemon.log`, and treat it as the + SIGPIPE regression the file-backed stdio restructure was written to remove. + +## 3. Adoption by the next daemon + +- [ ] `node bin/agent-device.mjs snapshot -i --json --session p2681 --platform ios --udid ` (or `open` again). +- [ ] In that request's `$STATE_DIR/sessions/p2681/requests/.ndjson`: + - [x] `"phase":"ios_runner_lease_adopted"` with `"lane":"physical_coredevice"` and `runnerPid` equal to `$RUNNER_PID`. + - [x] No `xctestrun` build phase and no second `launch_xcodebuild` for this request: + `"phase":"ios_runner_session_startup_timings"` carries `data.timings` with + `adopt_detached_runner` and without `build_xctestrun` or `launch_xcodebuild`. + - [x] Wall time is a reclaim, not a rebuild: compare against a cold physical start on this device + (`AGENT_DEVICE_IOS_RUNNER_DETACH=0` on the daemon, then repeat 1 and 3 and time the first command). +- [x] `ps -p $RUNNER_PID` unchanged across both daemons. +- [ ] Then `node bin/agent-device.mjs close --session p2681`, and at least five interaction + round-trips (`press`/`snapshot -i`) on a fresh session to prove the adopted transport is usable + for repeated writes, not only one read. + +> **Result, `3a31b6a691`.** Adoption carried `adopt_detached_runner` only (`{"adopt_detached_runner":122}`) +> with no `build_xctestrun`/`launch_xcodebuild`, same PID across both daemons, and collapsed the +> first-command health check from 6509 ms cold to 3 ms adopted. Adoption was driven by re-`prepare` +> rather than by `snapshot`, and the five post-`close` round-trips were not run, so 58 and 67 stay open. +> **Behaviour re-verified at `378d4dbfa3`.** Re-`prepare` after a graceful stop returned in **1151 ms** +> (`healthCheckMs` 6) against a cold start of **38247 ms** (`healthCheckMs` 36856 - the tunnel had gone +> cold, so this is the worst case for the comparison), with PID 62408 alive across both daemons. A +> launch cannot fit in 1151 ms, so the reclaim is real. +> +> Two boxes deliberately stay open. The `ios_runner_lease_adopted` and `ios_runner_lease_adoption_probe` +> lines were **not** captured for this run: the request records I could attribute to the device instead +> carried `"reason":"lease_absent"`, and `prepare --json` returns no request id, so matching a record to +> a request is mtime guesswork - which is how a physical record was once read as simulator evidence +> (PR #2692). Adoption demonstrably happened while the diagnostics that should show it are this hard to +> pin to a request; that is worth fixing before the probe cap in section 4 is called measured. +> - [x] Capture `ios_runner_lease_adopted` + `ios_runner_lease_adoption_probe` for a physical adoption +> at the head being merged. Done by emptying `requests/`, running exactly one adoption, and +> requiring one file - `--debug` is mandatory for these records to exist at all. +> - [ ] The five post-`close` interaction round-trips (needs an app installed and opened, not just a +> runner session). + +## 4. Physical-lane probe budget + +The physical lane probes the detached runner once, and that one probe is capped higher than every +other lane's: `RUNNER_ADOPTION_PHYSICAL_PROBE_TIMEOUT_MS` (5000 ms) instead of +`RUNNER_ADOPTION_PROBE_TIMEOUT_MS` (500 ms), because the first byte can be preceded by a `devicectl` +tunnel-address lookup. Both are clamped down to whatever the request's startup phase budget has left. +A cap is not a sleep: a runner that answers in 8 ms answers in 8 ms under either cap, so only a +refusal can spend the difference. + +**The physical cap is currently UNMEASURED on hardware.** 5000 ms is a ceiling picked to stay well +under a cold physical rebuild, not a number any device produced. The capture below is what turns it +into a measurement; until a box here is checked, no claim about tunnel wake-up time is proven. + +> One hardware probe timing exists, taken at `3a31b6a691` under the two-phase design it replaced: the +> tight probe answered in **8 ms** on `physical_coredevice`. That is proximity evidence only - the cap +> it ran under is not the cap being merged, so none of the boxes below are ticked by it. + +- [ ] Repeat 1 and 3 after the Mac has been idle long enough to drop the tunnel (or after unplug/replug). +- [ ] Request ndjson shows one `"phase":"ios_runner_lease_adoption_probe"` with + `"lane":"physical_coredevice"`, and record for it: `timeoutMs`, `budgetCapMs`, and `durationMs`. +- [x] Record the measured `durationMs` of that probe here, next to a cold `devicectl` tunnel wake on + this device. An answer that arrives near the cap means the cap is too small; one that arrives + far below it means the cap can come down. Either way the next change to the constant is a + measurement and not a guess. The capture is the request ndjson itself; no separate + `devicectl device info details` export is kept. +- [ ] If the probe fails: `"phase":"ios_runner_lease_adoption_skipped"` with a typed reason + (`probe_failed`, or `probe_budget_exhausted` when the request's own budget was already spent + before any probe was sent), and the next command starts a fresh runner. That is the designed + outcome, not a failure - record the timings and the reason. + +> **Measured at `af55e2746b`, warm tunnel.** One probe, `"lane":"physical_coredevice"`, +> `budgetCapMs` 5000, `timeoutMs` 5000, **`durationMs` 6**, `answered` true, followed by +> `ios_runner_lease_adopted` for PID 80569; the whole `prepare` took 951 ms. Per-request records only +> exist when the command runs with `--debug` - without it `requests/` is created and left empty, which +> is why an earlier pass at this head could not attribute a record to a request at all. +> +> **The cap is wrong in the direction this section worries about.** The probe answered in 6 ms, which +> is 1/800th of the budget. But a cold first command on this same device cost **36856 ms** of health +> check, and that is the cost class the 5000 ms ceiling was raised to absorb. A tunnel that needs +> re-establishing therefore cannot be waited out inside the cap: the probe would refuse at 5 s while the +> thing it is waiting for takes ~37 s. So the physical cap is neither a measured warm-case number (6 ms +> would allow far less) nor sufficient for the cold case it exists for. Either it comes down toward the +> warm measurement and the cold path is declared a rebuild by design, or it goes up an order of +> magnitude - and that is a decision this measurement should force, not one the constant should keep +> making silently. +> - [ ] Decide and record the cap against the cold-wake cost above. + +## 5. A device that changed while the runner was orphaned + +Between detach and adopt the runner is owned by nobody, and the transport it was started on may have +been rebuilt underneath it. Adoption must fail closed into a rebuild rather than hang or half-work. + +- [ ] Unplug the cable after step 1, wait 10 s, replug, then run step 3. Expect the probe to refuse + (`probe_failed`) and the next command to start a fresh runner. Total time to a working snapshot + must be bounded by the probe cap plus one cold start - never an unbounded wait. +- [x] Reboot the iPhone after step 1 and bring it back unlocked, then run step 3. Same expectation. + +> **Measured at `8c5fb73a03`.** Reboot after a graceful detach: the host-side runner (`89944`) had +> already exited, and the next `prepare` skipped adoption with the typed reason +> **`runner_process_dead`** naming that pid, then started a fresh runner (`98537`) and succeeded in +> 20000 ms with `healthCheckMs` 15887 - fail-closed into a rebuild, with the device's post-reboot cost +> a second data point for the cold case above. `runner.log` grew 92592 -> 95799 bytes, but that growth +> is a *new* runner writing to the session log, so it is not evidence for section 2's post-handoff +> claim and does not tick anything there. The probe path itself spent nothing: the refusal came from the +> dead-process check, which fires first, so this row proves that guard and not probe timeout. + +> **Observed at `3a31b6a691`, and it did not match the expectation above.** A short unplug/replug +> (bus loss at 21:26:27, replug 21:26:40) was followed by an adoption that *succeeded*: the probe +> answered, `prepare` completed in about 3 s with `healthCheckMs` 4, and PID 18260 was handed to the new +> daemon. A runner that survives the cable cycle and answers again is a legitimate adoption, so this is +> recorded as an expectation correction rather than a defect - but it means the box above is not +> satisfied by a fast replug, and only the reboot and remount rows can prove fail-closed rebuild here. +> - [ ] Re-run the unplug row at the head being merged with the cable out long enough that the runner is +> genuinely unreachable, and record the typed refusal reason. +- [ ] Force a Developer Mode / DDI remount (reboot into a state where `devicectl` re-pairs the + developer disk image), then run step 3. Same expectation. +- [ ] After any of the three: `grep '"phase":"ios_runner_lease_adopted"' "$STATE_DIR/daemon.log"` shows + no adoption for the dead generation, and `$LEASE` was replaced rather than left `detached-` forever. + +## 6. The orphaned runner must not block the toolchain + +A detached runner holds a device session for as long as it lives. That is affordable only if it does +not make the ordinary toolchain paths wait. + +- [ ] With a detached runner alive and nothing else running, `xcrun devicectl device install app + --device ` completes in its normal time. +- [ ] Same state, `xcrun devicectl device uninstall app --device ` completes. +- [ ] Same state, an unrelated `xcodebuild` for a second scheme/target on the same Mac completes; + the runner does not hold a lock the build waits on. +- [ ] Same state, `node bin/agent-device.mjs device list --json` still lists the device, and an + `open` on a *different* app on the same device is either a normal cold start or a typed + `DEVICE_IN_USE` with the documented recovery - not a timeout. + +## 7. Gates that must keep the runner on the kill path + +- [ ] Mid-startup shutdown: with a cold runner cache (`rm -rf ~/Library/Developer/Xcode/DerivedData/AgentDeviceRunner*`), + `open ...` and run `daemon stop` while xcodebuild is still building. Expect + `"reason":"runner_never_served_a_command"` in `daemon.log`, no `detached-` token in `$LEASE`, + and `$RUNNER_PID` gone. +- [ ] Occupied main thread: start a long-running request (a `replay` or a `--settle` interaction) and + `daemon stop` while it is in flight. Expect `"reason":"main_thread_occupied"`, or + `runner_never_served_a_command` if it had not answered yet - never a handoff of a busy runner. +- [ ] Command abandoned mid-flight: cancel a request after the runner accepted it (Ctrl-C during a + long `replay`) and then `daemon stop`. Expect `"reason":"command_in_flight"` - a refusal based on + work the runner still owes, which the completed-exchange occupancy mirror alone cannot see. +- [ ] That refusal is sticky: after the same cancellation, `daemon stop` again without any further + command and expect the same refusal. Then serve one command on a fresh daemon and cancel nothing; + the next graceful shutdown must hand the runner off, because an answered exchange is what tells + this process the runner is serving again. +- [x] Kill switch: put `AGENT_DEVICE_IOS_RUNNER_DETACH=0` on the environment of the **first command that + spawns the daemon** - there is no `daemon start` subcommand (`daemon` accepts only `stop`), so + prefixing a `daemon start` invocation does nothing and the daemon is later spawned by an + unrelated command without the flag. + repeat 1. Expect no `ios_runner_session_detached` line and the runner killed. +- [ ] Scoped simulator set is unaffected: repeat the same two checks on a simulator with + `--simulator-set-path` and expect `"reason":"simulator_set_redirect"`. +- [ ] `xctest` backend (needs an iOS < 17 device, or one reported with `iosPhysicalDeviceBackend: "xctest"`): + expect `"reason":"xctest_backend"` and the pre-#2681 kill-and-rebuild behaviour. +- [ ] Physical tvOS or visionOS device, if available: expect `"reason":"physical_non_ios_os"`. +- [ ] macOS host target: expect `"reason":"macos_host"`, even though it is `kind: device`. +> **Partial, `fc57f0d39e`, simulator lane.** Kill switch verified: control run with no flag left the +> runner (`36315`) alive across `daemon stop`; with `AGENT_DEVICE_IOS_RUNNER_DETACH=0` the runner +> (`37274`) was killed. Repeated `daemon stop` with no runner at all returned clean three times. The +> `SIGKILL` stale-lease takeover clause below was not exercised, so this row is not closed. + +- [ ] Repeated `daemon stop` with no runner at all stays clean, and a daemon killed with `SIGKILL` + still leaves a stale lease the next daemon takes over (unchanged takeover path). +- [ ] Early-exit diagnosis still reads the log: kill the runner's app process so `xcodebuild` exits + with a failure, and confirm the raised error quotes the tail of `$RUNNER_LOG` rather than an + empty `stdout`. +- [ ] That quote is bounded to one generation: keep a `$RUNNER_LOG` left by an older failed launch, + reproduce a different early exit on top of it, and confirm the error quotes only what this + generation appended. An older boot failure surfacing as this launch's recovery hint means the + generation offset was lost somewhere between spawn and the error. + +## 8. Lanes + +- [ ] `pnpm gate replay-ios-device` (needs the `IOS_UDID` the lane is configured with). +- [ ] `pnpm check:affected --run` - coordinator/CI owns this; it was not run in the implementing phase. + +## 9. Simulator-lane timings against `main` + +Sections 1-8 are physical. This section is the one AC that #2681 states as a *comparison* rather than a +behaviour: detaching and adopting on the simulator lane must not be slower than `main`, against a +threshold said out loud in advance. It was measured by the coordinator on +simulator `apex-2682-proto` (`C2748D97-B92D-4B3B-9C65-AF86494AD904`, iOS 26.2) with +**no** `--simulator-set-path`, which is what makes it eligible for handoff at all: a scoped-set +simulator is refused before any probe is sent (line 175), so a measurement taken there would prove +nothing about the adopting path. + +Threshold, fixed before reading the numbers: the adopted first-command wall +(`connectAfterBuildMs` + `healthCheckMs`) must land within +50 ms **and** under 1.5x of `main`'s +median, and the cold-path total within +25% of `main`'s median. A cap-shaped comparison would be +meaningless here because adoption is a reclaim, not a wait. + +Three adopted cycles per side (graceful `daemon stop`, then `prepare`), runner artifact cached on both +sides so `buildMs` is 0 throughout: + +| Path | `f9a021c290` (adopt) | `be0902eaea` / `main` (adopt) | +| --- | --- | --- | +| `connectAfterBuildMs` | 26, 27, 26 -> median **26** | 37, 26 -> median **31.5** | +| `healthCheckMs` | 3, 4, 3 -> median **3** | 3, 4 -> median **3.5** | +| adopted wall | **29 ms** | **35 ms** | + +| Path | `f9a021c290` (cold) | `main` (cold) | +| --- | --- | --- | +| total, ms | 5005, 3563 -> median **4284** | 4222, 3444 -> median **3833** | + +- [x] Adopted wall is 29 ms against `main`'s 35 ms: 6 ms faster, inside both bounds. The simulator + adoption path is unchanged in behaviour by #2692, which is the expected result - the branch's + subject is the physical lane, and this row exists to prove it did not disturb the lane that + already worked. +- [x] Cold total is 4284 ms against 3833 ms: +11.8%, inside the +25% bound. +- [x] Same PID across the restart on the simulator lane, confirmed by `pgrep` before and after + (`96688` on both sides of `daemon stop`), with `healthCheckMs` 4 adopted against 3941 cold. + +Two recording notes, so the table is read correctly: + +- [x] One cold sample at this head first looked like a regression: `connectAfterBuildMs` **10729** plus + `healthCheckMs` 5033 on the very first cold cycle after `daemon stop --clean`. It did not + reproduce in the two cold cycles measured above (1064/3941, 1030/2533), so it is recorded as + first-cycle variance after a clean, not a branch effect. Both medians above exclude it and the + table shows what repeated. +- [x] `main`'s first cycle returned 1110/3082 - a cold start, not an adoption, because the preceding + `daemon stop --clean` had killed its runner. It is kept out of the adopted median for that reason. + +This section proves nothing about the physical lane: the physical probe cap in section 4, the fail-closed +rows in section 5, and both rows in section 8 remain open until a cabled device is available. + +## Reporting + +For each unchecked box, report the command, the diagnostic `phase`/`reason` seen, and the log path +(`daemon.log`, `$RUNNER_LOG`, or the request ndjson). Do not mark a box from unit-test coverage. diff --git a/packages/platform-apple/src/core/runner-client.ts b/packages/platform-apple/src/core/runner-client.ts index 390930d30a..e064f817ec 100644 --- a/packages/platform-apple/src/core/runner-client.ts +++ b/packages/platform-apple/src/core/runner-client.ts @@ -33,8 +33,8 @@ export const resolveRunnerAppBundleId: AppleRunnerClient['resolveRunnerAppBundle client.resolveRunnerAppBundleId; export const hasCachedAppleRunnerArtifact: AppleRunnerClient['hasCachedAppleRunnerArtifact'] = client.hasCachedAppleRunnerArtifact; -export const detachIosSimulatorRunnerSessionsForShutdown: AppleRunnerClient['detachIosSimulatorRunnerSessionsForShutdown'] = - client.detachIosSimulatorRunnerSessionsForShutdown; +export const detachIosRunnerSessionsForShutdown: AppleRunnerClient['detachIosRunnerSessionsForShutdown'] = + client.detachIosRunnerSessionsForShutdown; export const readRunnerSessionLiveness: AppleRunnerClient['readRunnerSessionLiveness'] = client.readRunnerSessionLiveness; export const releaseIosRunnerOnClose: AppleRunnerClient['releaseIosRunnerOnClose'] = diff --git a/packages/platform-apple/src/runner-operations-facade.ts b/packages/platform-apple/src/runner-operations-facade.ts index 5eeaaf8387..2b51ab4b59 100644 --- a/packages/platform-apple/src/runner-operations-facade.ts +++ b/packages/platform-apple/src/runner-operations-facade.ts @@ -1,6 +1,6 @@ export { applyXctestRunnerAppIconFromDerivedPath, - detachIosSimulatorRunnerSessionsForShutdown, + detachIosRunnerSessionsForShutdown, hasLiveIosRunnerSession, notifyIosRunnerAppRelaunched, prepareIosRunner, diff --git a/packages/platform-apple/src/runner/__tests__/apple-runner-platform.test.ts b/packages/platform-apple/src/runner/__tests__/apple-runner-platform.test.ts index 60dd518aae..537f300afa 100644 --- a/packages/platform-apple/src/runner/__tests__/apple-runner-platform.test.ts +++ b/packages/platform-apple/src/runner/__tests__/apple-runner-platform.test.ts @@ -2,6 +2,7 @@ import { test } from 'vitest'; import assert from 'node:assert/strict'; import { resolveRunnerDestination, + resolveRunnerHandoffTarget, resolveRunnerPlatformName, resolveRunnerSdkName, resolveRunnerXctestrunHints, @@ -105,3 +106,77 @@ test('existing platform xctestrun disallowed hints stay unchanged when visionOS ['xros', 'iphoneos', 'iphonesimulator', 'appletvos', 'appletvsimulator', 'macos'], ); }); + +function iosDevice(overrides: Partial = {}): DeviceInfo { + return { + platform: 'apple', + id: 'device-1', + name: 'iPhone 17 Pro', + kind: 'device', + target: 'mobile', + appleOs: 'ios', + booted: true, + ...overrides, + }; +} + +test('handoff covers Apple simulators, including tvOS simulators as before #2681', () => { + assert.deepEqual(resolveRunnerHandoffTarget(iosSim()), { handoff: true, lane: 'simulator' }); + assert.deepEqual(resolveRunnerHandoffTarget(iosSim({ target: 'tv', appleOs: 'tvos' })), { + handoff: true, + lane: 'simulator', + }); +}); + +test('handoff covers a physical iOS device reached through CoreDevice', () => { + assert.deepEqual(resolveRunnerHandoffTarget(iosDevice()), { + handoff: true, + lane: 'physical_coredevice', + }); + assert.deepEqual( + resolveRunnerHandoffTarget(iosDevice({ iosPhysicalDeviceBackend: 'coredevice' })), + { handoff: true, lane: 'physical_coredevice' }, + ); + assert.deepEqual(resolveRunnerHandoffTarget(iosDevice({ appleOs: 'ipados', name: 'iPad Pro' })), { + handoff: true, + lane: 'physical_coredevice', + }); +}); + +test('the macOS desktop host is refused although it is also kind device', () => { + assert.deepEqual(resolveRunnerHandoffTarget(iosDevice({ appleOs: 'macos', target: 'desktop' })), { + handoff: false, + reason: 'macos_host', + }); +}); + +test('physical tvOS and visionOS runners are refused: kind device is not physical iOS', () => { + assert.deepEqual(resolveRunnerHandoffTarget(iosDevice({ appleOs: 'tvos', target: 'tv' })), { + handoff: false, + reason: 'physical_non_ios_os', + }); + assert.deepEqual(resolveRunnerHandoffTarget(iosDevice({ appleOs: 'visionos' })), { + handoff: false, + reason: 'physical_non_ios_os', + }); +}); + +test('the usbmux-only xctest backend is refused while coredevice is named explicitly', () => { + assert.deepEqual(resolveRunnerHandoffTarget(iosDevice({ iosPhysicalDeviceBackend: 'xctest' })), { + handoff: false, + reason: 'xctest_backend', + }); +}); + +test('a non-Apple target is refused instead of defaulting into the physical lane', () => { + assert.deepEqual( + resolveRunnerHandoffTarget({ + platform: 'android', + id: 'emulator-5554', + name: 'Pixel 8', + kind: 'device', + target: 'mobile', + }), + { handoff: false, reason: 'non_apple_target' }, + ); +}); diff --git a/packages/platform-apple/src/runner/__tests__/runner-adoption-route.test.ts b/packages/platform-apple/src/runner/__tests__/runner-adoption-route.test.ts new file mode 100644 index 0000000000..68ccc6b29e --- /dev/null +++ b/packages/platform-apple/src/runner/__tests__/runner-adoption-route.test.ts @@ -0,0 +1,212 @@ +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 type { DiagnosticEventInput } from '@agent-device/host-kit/diagnostics'; +import { buildRunnerLease, writeRunnerLease, type RunnerLease } from '../runner-lease.ts'; +import { tryAdoptRunnerSessionFromLease } from '../runner-adoption.ts'; +import { clearDeviceTunnelIpCache } from '../runner-command-route.ts'; +import { usbmuxRunnerTransport } from '../runner-usbmux.ts'; +import { createRunnerPhaseBudget } from '../runner-xctestrun.ts'; +import { appleRunnerTestHost } from '../test-host.ts'; +import { usbmuxDeviceUnattachedError } from './runner-transport.fixtures.ts'; +import { runnerResponse } from './runner-session-fixtures.ts'; +import { mkdtempForTestSync } from './tmp-dir.ts'; + +vi.mock('../runner-xctestrun.ts', async (importOriginal) => { + const actual = await importOriginal(); + return { + ...actual, + resolveExpectedRunnerCacheMetadata: vi.fn(() => ({})), + resolveRunnerDerivedPath: vi.fn(() => expectedDerived), + }; +}); +vi.mock('../runner-usbmux.ts', async (importOriginal) => { + const actual = await importOriginal(); + return { + ...actual, + usbmuxRunnerTransport: { postCommand: vi.fn() }, + }; +}); + +// Everything below the route decision is faked: usbmuxd's socket, the `devicectl` tunnel lookup, and +// the network. The route decision itself - which endpoint the adoption probe dials for a physical +// device - is the real code under test here, so a probe that quietly fell back to 127.0.0.1 could +// not pass. `runner-adoption.test.ts` mocks the transport and therefore cannot see this. +const mockUsbmuxPostCommand = vi.mocked(usbmuxRunnerTransport.postCommand); +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'); + +const RUNNER_PID = 424242; +const RUNNER_PORT = 50700; + +const cabledDevice: DeviceInfo = { + platform: 'apple', + id: 'adopt-route-cabled', + name: 'iPhone 17 Pro', + kind: 'device', + target: 'mobile', + appleOs: 'ios', + iosPhysicalDeviceBackend: 'coredevice', + booted: true, +}; + +let leaseDir: string; +let expectedDerived: string; +let fetchUrls: string[]; +let tunnelIp: string | null; +let tunnelLookups: number; +let emittedDiagnostics: DiagnosticEventInput[] = []; + +function adoptionRefusalReason(): unknown { + return emittedDiagnostics + .filter((event) => event.phase === 'ios_runner_lease_adoption_skipped') + .at(-1)?.data?.reason; +} + +function adoptionProbe(): DiagnosticEventInput | undefined { + return emittedDiagnostics.find((event) => event.phase === 'ios_runner_lease_adoption_probe'); +} + +/** A tunnel endpoint that accepts the request and never answers - what a wedged runner looks like. */ +function fetchThatNeverAnswers( + input: string | URL | Request, + init?: RequestInit, +): Promise { + fetchUrls.push(String(input)); + return new Promise((_resolve, reject) => { + init?.signal?.addEventListener('abort', () => reject(init.signal?.reason), { once: true }); + }); +} + +beforeEach(() => { + emittedDiagnostics = []; + leaseDir = mkdtempForTestSync('adopt-route-leases-'); + expectedDerived = path.join(mkdtempForTestSync('adopt-route-derived-'), 'DerivedData'); + fetchUrls = []; + tunnelIp = null; + tunnelLookups = 0; + process.env.AGENT_DEVICE_IOS_RUNNER_LEASE_DIR = leaseDir; + clearDeviceTunnelIpCache(); + mockUsbmuxPostCommand.mockReset(); + mockIsProcessAlive.mockImplementation((pid) => pid === RUNNER_PID); + mockReadProcessCommand.mockReturnValue(null); + appleRunnerTestHost.update({ + isProcessAlive: mockIsProcessAlive, + readProcessCommand: mockReadProcessCommand, + readProcessStartTime: mockReadProcessStartTime, + emitDiagnostic: (event) => { + emittedDiagnostics.push(event); + }, + // Backend classification (coredevice vs xctest) stays the real implementation; the tunnel + // address lookup is the `devicectl` shell-out it hides. + resolveIosPhysicalDeviceControl: (device) => ({ + ...appleRunnerTestHost.defaults().resolveIosPhysicalDeviceControl(device), + resolveTunnel: async () => { + tunnelLookups += 1; + return { tunnelIp }; + }, + }), + }); + vi.stubGlobal( + 'fetch', + vi.fn(async (input: string | URL | Request) => { + fetchUrls.push(String(input)); + return runnerResponse({ uptimeMs: 1 }); + }), + ); +}); + +afterEach(() => { + delete process.env.AGENT_DEVICE_IOS_RUNNER_LEASE_DIR; + vi.unstubAllGlobals(); +}); + +function writeDetachedLease(device: DeviceInfo): void { + const lease: RunnerLease = { + ...buildRunnerLease({ + deviceId: device.id, + sessionId: `${device.id}:${RUNNER_PORT}:1`, + runnerPid: RUNNER_PID, + port: RUNNER_PORT, + xctestrunPath: path.join(expectedDerived, 'Build', 'Products', 'env.session.xctestrun'), + jsonPath: path.join(expectedDerived, 'Build', 'Products', 'env.session.json'), + }), + ownerToken: 'detached-owner-99999-deadbeef', + ownerPid: 99999, + ownerStartTime: 'not-a-real-start-time', + }; + writeRunnerLease(lease); +} + +test('the adoption probe dials usbmux for a cabled CoreDevice device, never loopback', async () => { + writeDetachedLease(cabledDevice); + mockUsbmuxPostCommand.mockResolvedValue(runnerResponse({ uptimeMs: 1 })); + + const session = await tryAdoptRunnerSessionFromLease(cabledDevice, {}); + + expect(session).not.toBeNull(); + expect(mockUsbmuxPostCommand.mock.calls.map(([deviceId, port]) => `${deviceId}:${port}`)).toEqual( + [`${cabledDevice.id}:${RUNNER_PORT}`], + ); + expect(fetchUrls).toEqual([]); + // A cabled device must not pay for the tunnel lookup either (#1403). + expect(tunnelLookups).toBe(0); +}); + +test('a Wi-Fi CoreDevice device is probed at its tunnel address, not at 127.0.0.1', async () => { + // usbmuxd never sees a CoreDevice Wi-Fi device (#1403), so the probe has to fall back to the + // tunnel route the real resolver builds. The loopback endpoint stays in the candidate list as a + // port-forward fallback, and adoption would only reach it if the tunnel address refused the probe. + writeDetachedLease(cabledDevice); + tunnelIp = 'fd18::42'; + mockUsbmuxPostCommand.mockRejectedValue(usbmuxDeviceUnattachedError()); + + const session = await tryAdoptRunnerSessionFromLease(cabledDevice, {}); + + expect(session).not.toBeNull(); + expect(fetchUrls[0]).toBe(`http://[${tunnelIp}]:${RUNNER_PORT}/command`); +}); + +test('a lease from a daemon that left no log path still adopts, and the new lease says none', async () => { + writeDetachedLease(cabledDevice); + mockUsbmuxPostCommand.mockResolvedValue(runnerResponse({ uptimeMs: 1 })); + + const session = await tryAdoptRunnerSessionFromLease(cabledDevice, {}); + + expect(session?.runnerLogPath).toBeUndefined(); + expect(fs.existsSync(path.join(leaseDir, `${cabledDevice.id}.json`))).toBe(true); +}); + +// A refusal that only a real deadline can produce. `runner-adoption.test.ts` fakes the transport, so +// its probe fails instantly and can only show the cap the lane was given; this one runs the actual +// transport, route resolution, and timeout, with only usbmuxd, `devicectl`, and the socket faked. +test('a launched physical probe that runs past its deadline refuses adoption as probe_failed, never as probe_budget_exhausted', async () => { + // The clamp refuses a probe before it sends only when the startup phase is already spent, so a + // probe that got launched and then ran out of time can only report `probe_failed` (#2681). + writeDetachedLease(cabledDevice); + tunnelIp = 'fd18::42'; + mockUsbmuxPostCommand.mockRejectedValue(usbmuxDeviceUnattachedError()); + vi.mocked(fetch).mockImplementationOnce(fetchThatNeverAnswers); + const startedAtMs = Date.now(); + + expect( + await tryAdoptRunnerSessionFromLease(cabledDevice, { + budget: createRunnerPhaseBudget(250, undefined), + }), + ).toBeNull(); + + expect(adoptionRefusalReason()).toBe('probe_failed'); + // The lane cap is what the transport was capped by, and the request's own budget is what ended the + // probe: the deadline reached the socket instead of only being recorded next to it. + expect(adoptionProbe()?.data).toMatchObject({ + lane: 'physical_coredevice', + budgetCapMs: 5_000, + answered: false, + }); + expect(Number(adoptionProbe()?.data?.timeoutMs)).toBeLessThanOrEqual(250); + expect(fetchUrls).toEqual([`http://[${tunnelIp}]:${RUNNER_PORT}/command`]); + expect(Date.now() - startedAtMs).toBeGreaterThanOrEqual(150); + expect(Date.now() - startedAtMs).toBeLessThan(5_000); +}); 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 8364bf5533..a06aedd0c4 100644 --- a/packages/platform-apple/src/runner/__tests__/runner-adoption.test.ts +++ b/packages/platform-apple/src/runner/__tests__/runner-adoption.test.ts @@ -18,6 +18,7 @@ import { resolveExpectedRunnerCacheMetadata, } from '../runner-xctestrun.ts'; import { appleRunnerTestHost } from '../test-host.ts'; +import type { DiagnosticEventInput } from '@agent-device/host-kit/diagnostics'; import { appleToolchainProbeResult } from './apple-toolchain-fixtures.ts'; import { mkdtempForTestSync } from './tmp-dir.ts'; @@ -40,11 +41,37 @@ 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'); +// A refusal only exists as a diagnostic, so the refusal matrix reads what adoption emitted rather +// than what it returned. +let emittedDiagnostics: DiagnosticEventInput[] = []; + +function adoptionRefusalReason(): unknown { + return emittedDiagnostics + .filter((event) => event.phase === 'ios_runner_lease_adoption_skipped') + .at(-1)?.data?.reason; +} + +function adoptionProbeTimeouts(): unknown[] { + return emittedDiagnostics + .filter((event) => event.phase === 'ios_runner_lease_adoption_probe') + .map((event) => event.data?.timeoutMs); +} + +function adoptionProbes(): unknown[] { + return emittedDiagnostics + .filter((event) => event.phase === 'ios_runner_lease_adoption_probe') + .map((event) => `${event.data?.lane}:${event.data?.budgetCapMs}:${event.data?.answered}`); +} + beforeEach(() => { + emittedDiagnostics = []; appleRunnerTestHost.update({ isProcessAlive: mockIsProcessAlive, readProcessCommand: mockReadProcessCommand, readProcessStartTime: mockReadProcessStartTime, + emitDiagnostic: (event) => { + emittedDiagnostics.push(event); + }, }); }); @@ -57,14 +84,33 @@ const simulator: DeviceInfo = { booted: true, }; +// The physical lanes #2681 added: the CoreDevice-backed device handoff covers, and the usbmux-only +// XCTest backend it explicitly refuses. +const physicalCoreDevice: DeviceInfo = { + platform: 'apple', + id: 'adopt-device-1', + name: 'iPhone 17 Pro', + kind: 'device', + target: 'mobile', + appleOs: 'ios', + iosPhysicalDeviceBackend: 'coredevice', + booted: true, +}; + +const physicalXctestDevice: DeviceInfo = { + ...physicalCoreDevice, + id: 'adopt-device-xctest', + iosPhysicalDeviceBackend: 'xctest', +}; + let leaseDir: string; let expectedDerived: string; -function writeStaleLease(overrides: Partial = {}): RunnerLease { +function writeStaleLeaseFor(device: DeviceInfo, overrides: Partial = {}): RunnerLease { const lease: RunnerLease = { ...buildRunnerLease({ - deviceId: simulator.id, - sessionId: `${simulator.id}:50700:1`, + deviceId: device.id, + sessionId: `${device.id}:50700:1`, runnerPid: 424242, port: 50700, xctestrunPath: path.join(expectedDerived, 'Build', 'Products', 'env.session.xctestrun'), @@ -81,6 +127,10 @@ function writeStaleLease(overrides: Partial = {}): RunnerLease { return lease; } +function writeStaleLease(overrides: Partial = {}): RunnerLease { + return writeStaleLeaseFor(simulator, overrides); +} + beforeEach(() => { leaseDir = mkdtempForTestSync('agent-device-lease-test-'); process.env.AGENT_DEVICE_IOS_RUNNER_LEASE_DIR = leaseDir; @@ -148,6 +198,23 @@ test('adoption succeeds for a live, matching, probe-healthy runner', async () => expect(readStaleRunnerLease(simulator.id)).toBeNull(); }); +test('the adopted runner keeps the log file its predecessor opened for it', async () => { + // The runner inherited that descriptor at spawn, so the next daemon has to keep writing to the + // same path a client was already told about (#2681). + const runnerLogPath = path.join(leaseDir, 'runner.log'); + writeStaleLease({ runnerLogPath }); + mockIsProcessAlive.mockReturnValue(true); + mockSendRunnerCommandOnce.mockResolvedValue(new Response(JSON.stringify({ ok: true }))); + + const session = await tryAdoptRunnerSessionFromLease(simulator, {}); + + expect(session?.runnerLogPath).toBe(runnerLogPath); + const restamped = JSON.parse( + fs.readFileSync(path.join(leaseDir, `${simulator.id}.json`), 'utf8'), + ) as RunnerLease; + expect(restamped.runnerLogPath).toBe(runnerLogPath); +}); + 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 @@ -342,3 +409,192 @@ test('adoption is refused when the owner state dir is gone but the owner process expect(await tryAdoptRunnerSessionFromLease(simulator, {})).toBeNull(); expect(mockSendRunnerCommandOnce).not.toHaveBeenCalled(); }); + +// #2681: the physical lane. These are automated refusal decisions over the handoff gate — they are +// not the live-device proof, which `docs/agents/device-verification.md` and +// `docs/evidence/ios-physical-runner-handoff-2026-09-19.md` own. +test('physical coredevice lane adopts the detached runner and names its lane', async () => { + const lease = writeStaleLeaseFor(physicalCoreDevice); + mockIsProcessAlive.mockReturnValue(true); + mockSendRunnerCommandOnce.mockResolvedValue(new Response(JSON.stringify({ ok: true }))); + + const session = await tryAdoptRunnerSessionFromLease(physicalCoreDevice, {}); + + expect(session?.state).toBe('ready'); + expect(session?.child.pid).toBe(lease.runnerPid); + expect(session?.port).toBe(lease.port); + expect( + emittedDiagnostics.find((event) => event.phase === 'ios_runner_lease_adopted')?.data, + ).toMatchObject({ deviceId: physicalCoreDevice.id, lane: 'physical_coredevice' }); + // Ownership transferred: the adopted lease is no longer stale for a third daemon. + expect(readStaleRunnerLease(physicalCoreDevice.id)).toBeNull(); +}); + +test('physical lane refuses the usbmux-only xctest backend before reading anything', async () => { + writeStaleLeaseFor(physicalXctestDevice); + mockIsProcessAlive.mockReturnValue(true); + + expect(await tryAdoptRunnerSessionFromLease(physicalXctestDevice, {})).toBeNull(); + expect(adoptionRefusalReason()).toBe('xctest_backend'); + expect(mockSendRunnerCommandOnce).not.toHaveBeenCalled(); +}); + +test('physical lane refuses the macOS host, which is kind device too', async () => { + const macHost: DeviceInfo = { ...physicalCoreDevice, id: 'host-macos', appleOs: 'macos' }; + + expect(await tryAdoptRunnerSessionFromLease(macHost, {})).toBeNull(); + expect(adoptionRefusalReason()).toBe('macos_host'); + expect(mockSendRunnerCommandOnce).not.toHaveBeenCalled(); +}); + +test('physical refusal matrix: no lease on disk', async () => { + mockIsProcessAlive.mockReturnValue(true); + + expect(await tryAdoptRunnerSessionFromLease(physicalCoreDevice, {})).toBeNull(); + expect(adoptionRefusalReason()).toBe('lease_absent'); +}); + +test('physical refusal matrix: the lease is not stale because its owner is alive', async () => { + const liveStateDir = mkdtempForTestSync('agent-device-adopt-owner-live-'); + appleRunnerTestHost.update({ leaseOwnerStateDir: () => liveStateDir }); + writeStaleLeaseFor(physicalCoreDevice, { + ownerToken: 'owner-foreign-live', + ownerPid: process.pid, + ownerStartTime: appleRunnerTestHost.defaults().readProcessStartTime(process.pid), + ownerStateDir: liveStateDir, + }); + mockIsProcessAlive.mockReturnValue(true); + + expect(await tryAdoptRunnerSessionFromLease(physicalCoreDevice, {})).toBeNull(); + expect(adoptionRefusalReason()).toBe('lease_owner_live'); + expect(mockSendRunnerCommandOnce).not.toHaveBeenCalled(); +}); + +test('physical refusal matrix: the leased runner pid is dead', async () => { + writeStaleLeaseFor(physicalCoreDevice); + mockIsProcessAlive.mockReturnValue(false); + + expect(await tryAdoptRunnerSessionFromLease(physicalCoreDevice, {})).toBeNull(); + expect(adoptionRefusalReason()).toBe('runner_process_dead'); + expect(mockSendRunnerCommandOnce).not.toHaveBeenCalled(); +}); + +test('physical refusal matrix: the leased runner pid was recycled', async () => { + writeStaleLeaseFor(physicalCoreDevice, { runnerStartTime: 'runner-original-start' }); + mockIsProcessAlive.mockReturnValue(true); + + expect(await tryAdoptRunnerSessionFromLease(physicalCoreDevice, {})).toBeNull(); + expect(adoptionRefusalReason()).toBe('runner_pid_recycled'); + expect(mockSendRunnerCommandOnce).not.toHaveBeenCalled(); +}); + +test('physical refusal matrix: the artifact fingerprint moved', async () => { + writeStaleLeaseFor(physicalCoreDevice, { + xctestrunPath: '/somewhere/else/Build/Products/env.xctestrun', + }); + mockIsProcessAlive.mockReturnValue(true); + + expect(await tryAdoptRunnerSessionFromLease(physicalCoreDevice, {})).toBeNull(); + expect(adoptionRefusalReason()).toBe('artifact_fingerprint_mismatch'); + expect(mockSendRunnerCommandOnce).not.toHaveBeenCalled(); +}); + +test('physical refusal matrix: the caller expected another runner session', async () => { + writeStaleLeaseFor(physicalCoreDevice); + mockIsProcessAlive.mockReturnValue(true); + + expect( + await tryAdoptRunnerSessionFromLease(physicalCoreDevice, { + expectedRunnerSessionId: 'some-other-runner-session', + }), + ).toBeNull(); + expect(adoptionRefusalReason()).toBe('session_identity_mismatch'); + expect(mockSendRunnerCommandOnce).not.toHaveBeenCalled(); +}); + +test('physical refusal matrix: the owner is alive with its owner-state dir gone', async () => { + // Stale enough for the force-stop path to reclaim, never for adoption: adopting a runner whose + // live owner still believes it owns it would create two masters. + const goneStateDir = mkdtempForTestSync('agent-device-adopt-dir-gone-device-'); + fs.rmSync(goneStateDir, { recursive: true, force: true }); + writeStaleLeaseFor(physicalCoreDevice, { + ownerToken: 'owner-foreign-dir-gone', + ownerPid: process.pid, + // classifyOwnerLiveness runs unmocked, so it reads this process's REAL start time. + ownerStartTime: appleRunnerTestHost.defaults().readProcessStartTime(process.pid), + ownerStateDir: goneStateDir, + }); + mockIsProcessAlive.mockReturnValue(true); + + expect(await tryAdoptRunnerSessionFromLease(physicalCoreDevice, {})).toBeNull(); + expect(adoptionRefusalReason()).toBe('lease_owner_state_dir_gone'); + expect(mockSendRunnerCommandOnce).not.toHaveBeenCalled(); +}); + +test('physical refusal matrix: an unreachable device spends one probe and its own cap', async () => { + writeStaleLeaseFor(physicalCoreDevice); + mockIsProcessAlive.mockReturnValue(true); + mockSendRunnerCommandOnce.mockRejectedValue(new Error('connection refused')); + const lease = readStaleRunnerLease(physicalCoreDevice.id); + + expect(await tryAdoptRunnerSessionFromLease(physicalCoreDevice, {})).toBeNull(); + // One probe, on the lane's cap - which is the whole reason the physical lane needs a bigger cap + // than the simulator lane: the tunnel address may have to be looked up inside it (#2681). + expect(adoptionProbeTimeouts()).toEqual([5_000]); + expect(adoptionProbes()).toEqual(['physical_coredevice:5000:false']); + expect(adoptionRefusalReason()).toBe('probe_failed'); + expect(readStaleRunnerLease(physicalCoreDevice.id)?.ownerToken).toBe(lease?.ownerToken); +}); + +test('a simulator spends the tight probe cap it spent before #2681', async () => { + writeStaleLease(); + mockIsProcessAlive.mockReturnValue(true); + mockSendRunnerCommandOnce.mockRejectedValue(new Error('connection refused')); + + expect(await tryAdoptRunnerSessionFromLease(simulator, {})).toBeNull(); + expect(adoptionProbeTimeouts()).toEqual([500]); + expect(adoptionProbes()).toEqual(['simulator:500:false']); +}); + +test('the probe spends the startup budget it was handed instead of getting a fresh one', async () => { + // Adoption runs inside the request's lease lock, so an unclamped probe could hold it for five + // seconds after the request itself had seconds left (#2422). + writeStaleLeaseFor(physicalCoreDevice); + mockIsProcessAlive.mockReturnValue(true); + mockSendRunnerCommandOnce.mockRejectedValue(new Error('connection refused')); + + expect( + await tryAdoptRunnerSessionFromLease(physicalCoreDevice, { + budget: createRunnerPhaseBudget(1_200, undefined), + }), + ).toBeNull(); + + const [timeoutMs] = adoptionProbeTimeouts() as number[]; + expect(timeoutMs).toBeGreaterThan(0); + expect(timeoutMs).toBeLessThan(5_000); +}); + +test('a budget the fingerprint check already spent refuses adoption instead of probing at zero', async () => { + writeStaleLeaseFor(physicalCoreDevice); + mockIsProcessAlive.mockReturnValue(true); + const lease = readStaleRunnerLease(physicalCoreDevice.id); + + expect( + await tryAdoptRunnerSessionFromLease(physicalCoreDevice, { + budget: createRunnerPhaseBudget(0, undefined), + }), + ).toBeNull(); + + expect(mockSendRunnerCommandOnce).not.toHaveBeenCalled(); + expect(adoptionRefusalReason()).toBe('probe_budget_exhausted'); + expect(readStaleRunnerLease(physicalCoreDevice.id)?.ownerToken).toBe(lease?.ownerToken); +}); + +test('the kill switch disables the physical lane too', async () => { + writeStaleLeaseFor(physicalCoreDevice); + mockIsProcessAlive.mockReturnValue(true); + process.env.AGENT_DEVICE_IOS_RUNNER_DETACH = '0'; + + expect(await tryAdoptRunnerSessionFromLease(physicalCoreDevice, {})).toBeNull(); + expect(mockSendRunnerCommandOnce).not.toHaveBeenCalled(); +}); diff --git a/packages/platform-apple/src/runner/__tests__/runner-command-recovery.test.ts b/packages/platform-apple/src/runner/__tests__/runner-command-recovery.test.ts index 7b502c76b6..bb9d55942c 100644 --- a/packages/platform-apple/src/runner/__tests__/runner-command-recovery.test.ts +++ b/packages/platform-apple/src/runner/__tests__/runner-command-recovery.test.ts @@ -35,6 +35,8 @@ function makeRunnerSession(port: number): RunnerSession { testPromise: new Promise(() => {}), child: { pid: process.pid, exitCode: null }, state: 'ready', + inFlightCommands: 0, + hasAbandonedCommands: false, }; } diff --git a/packages/platform-apple/src/runner/__tests__/runner-disposal.test.ts b/packages/platform-apple/src/runner/__tests__/runner-disposal.test.ts index 9c2e2e99f1..ffbba4293f 100644 --- a/packages/platform-apple/src/runner/__tests__/runner-disposal.test.ts +++ b/packages/platform-apple/src/runner/__tests__/runner-disposal.test.ts @@ -201,6 +201,8 @@ function makeRunnerSession( testPromise, child: { pid: 42, exitCode: null }, state: 'ready', + inFlightCommands: 0, + hasAbandonedCommands: false, ...overrides, }; } diff --git a/packages/platform-apple/src/runner/__tests__/runner-early-exit-diagnosis.test.ts b/packages/platform-apple/src/runner/__tests__/runner-early-exit-diagnosis.test.ts index a04f9a583e..4afff5b787 100644 --- a/packages/platform-apple/src/runner/__tests__/runner-early-exit-diagnosis.test.ts +++ b/packages/platform-apple/src/runner/__tests__/runner-early-exit-diagnosis.test.ts @@ -1,14 +1,18 @@ import assert from 'node:assert/strict'; +import fs from 'node:fs'; +import path from 'node:path'; import { test } from 'vitest'; import type { AppError } from '@agent-device/kernel/errors'; import type { ExecBackgroundResult } from '@agent-device/host-kit/command'; import { buildRunnerEarlyExitError } from '../runner-contract.ts'; +import { readRunnerLogTail } from '../runner-io.ts'; import type { RunnerSession } from '../runner-session-types.ts'; +import { mkdtempForTestSync } from './tmp-dir.ts'; // Verbatim xcodebuild output from an iPhone that was not in the signing account. // macOS localizes the installer prose, so the machine-readable anchors are the // CoreDevice error code and the English framework strings around it. -const PROVISIONING_FAILURE_STDERR = [ +const PROVISIONING_FAILURE_LOG = [ 'AgentDeviceRunnerUITests-Runner encountered an error (Failed to install or launch the test runner.', '(Underlying Error: Nie można zainstalować „AgentDeviceRunnerUITests-Runner”.', 'Failed to install embedded profile for com.callstack.agentdevice.runner.uitests.xctrunner :', @@ -16,11 +20,15 @@ const PROVISIONING_FAILURE_STDERR = [ '** TEST EXECUTE FAILED **', ].join('\n'); +// Production shape since #2681: xcodebuild writes its own log file and the exec result carries only +// the exit code, so the file is what an early-exit error has to quote. function sessionFailingWith( - stdout: string, - stderr: string, + log: string, + generationStartOffset = 0, startupDeviceStates?: RunnerSession['startupDeviceStates'], ): RunnerSession { + const runnerLogPath = path.join(mkdtempForTestSync('runner-early-exit-'), 'runner.log'); + fs.writeFileSync(runnerLogPath, log); return { sessionId: 'early-exit-session', device: { platform: 'apple', id: 'device-1', name: 'iPhone', kind: 'device', booted: true }, @@ -28,10 +36,15 @@ function sessionFailingWith( port: 8100, xctestrunPath: '/tmp/runner.xctestrun', jsonPath: '/tmp/runner.json', - testPromise: Promise.resolve({ exitCode: 1, stdout, stderr }), + runnerLogPath, + readLogTail: (maxBytes) => + readRunnerLogTail({ logPath: runnerLogPath, startOffset: generationStartOffset }, maxBytes), + testPromise: Promise.resolve({ exitCode: 1, stdout: '', stderr: '' }), child: { pid: 4242, exitCode: 1 } as ExecBackgroundResult['child'], state: 'starting', startupDeviceStates, + inFlightCommands: 0, + hasAbandonedCommands: false, }; } @@ -46,7 +59,7 @@ test('the early-exit error a user actually receives names the provisioning cause // separately and always returned connect-timeout guidance, so the shipped // error still told people to retry a runner that can never install. const error = (await buildRunnerEarlyExitError({ - session: sessionFailingWith('', PROVISIONING_FAILURE_STDERR), + session: sessionFailingWith(PROVISIONING_FAILURE_LOG), port: 8100, })) as AppError; @@ -61,7 +74,7 @@ test('the early-exit error a user actually receives names the provisioning cause test('an ordinary early exit still gets connect-timeout and cache-recovery guidance', async () => { const error = (await buildRunnerEarlyExitError({ - session: sessionFailingWith('', 'xcodebuild: error: Timed out waiting for the test runner'), + session: sessionFailingWith('xcodebuild: error: Timed out waiting for the test runner'), port: 8100, })) as AppError; @@ -72,21 +85,54 @@ test('an ordinary early exit still gets connect-timeout and cache-recovery guida test('a busy connecting device keeps its own targeted hint', async () => { const error = (await buildRunnerEarlyExitError({ - session: sessionFailingWith('', 'The device is busy: connecting to device'), + session: sessionFailingWith('The device is busy: connecting to device'), port: 8100, })) as AppError; assert.match(String(error.details?.hint), /still connecting/); }); +test('the quoted tail is the end of the log, not its beginning', async () => { + // A runner that retried for minutes writes far more than an error detail may carry; the anchors are + // in what it said last, so a bound that kept the head would classify every boot as a timeout. + const log = `${'Compiling swift module AgentDeviceRunnerUITests\n'.repeat(4_000)}${PROVISIONING_FAILURE_LOG}`; + const error = (await buildRunnerEarlyExitError({ + session: sessionFailingWith(log), + port: 8100, + })) as AppError; + + assert.equal(error.details?.reason, 'IOS_RUNNER_DEVICE_NOT_PROVISIONED'); + const quoted = (error.details?.xcodebuild as { stderr?: string } | undefined)?.stderr ?? ''; + assert.ok(quoted.length <= 64 * 1024); + assert.match(quoted, /TEST EXECUTE FAILED/); +}); + +test('a failure from an older runner generation is not quoted as this launch output', async () => { + // The log is append-only across runner generations, so an unbounded tail reaches into whichever + // runner failed last: a device unregistered months ago would keep handing its provisioning hint to + // every later boot failure, however unrelated (#2681). + const error = (await buildRunnerEarlyExitError({ + session: sessionFailingWith( + `${PROVISIONING_FAILURE_LOG}\nxcodebuild: error: Timed out waiting for the test runner`, + PROVISIONING_FAILURE_LOG.length + 1, + ), + port: 8100, + })) as AppError; + + assert.equal(error.details?.reason, 'IOS_RUNNER_CONNECT_TIMEOUT'); + const quoted = (error.details?.xcodebuild as { stderr?: string } | undefined)?.stderr ?? ''; + assert.doesNotMatch(quoted, /provisioning profile/); + assert.match(quoted, /Timed out waiting for the test runner/); +}); + test('an early exit carries the disk-image state the device was read in (#2683)', async () => { // A locked iPhone lets the build finish and kills `xcodebuild test-without-building` instead, so // the startup build catch never runs and the readiness facts read before the build would be // dropped. Captured on hardware: this is the failure an image-down locked phone actually produces. const error = (await buildRunnerEarlyExitError({ session: sessionFailingWith( - '', 'xcodebuild: error: Timed out waiting for the test runner', + 0, IMAGE_DOWN_STATES, ), port: 8100, @@ -98,8 +144,8 @@ test('an early exit carries the disk-image state the device was read in (#2683)' test('an early exit that already names a cause keeps it, and only gains the fact (#2683)', async () => { const error = (await buildRunnerEarlyExitError({ session: sessionFailingWith( - '', 'xcodebuild: error: Timed out waiting for the test runner', + 0, IMAGE_DOWN_STATES, ), port: 8100, @@ -113,7 +159,7 @@ test('an early exit that already names a cause keeps it, and only gains the fact test('a session that never probed the device publishes no disk-image claim (#2683)', async () => { const error = (await buildRunnerEarlyExitError({ - session: sessionFailingWith('', 'xcodebuild: error: Timed out waiting for the test runner'), + session: sessionFailingWith('xcodebuild: error: Timed out waiting for the test runner'), port: 8100, })) as AppError; diff --git a/packages/platform-apple/src/runner/__tests__/runner-io.test.ts b/packages/platform-apple/src/runner/__tests__/runner-io.test.ts new file mode 100644 index 0000000000..5d5529000a --- /dev/null +++ b/packages/platform-apple/src/runner/__tests__/runner-io.test.ts @@ -0,0 +1,145 @@ +import assert from 'node:assert/strict'; +import fs from 'node:fs'; +import path from 'node:path'; +import { test } from 'vitest'; +import { + createRunnerLogFile, + readRunnerLogTail, + tailRunnerLogFile, + type RunnerLogFile, +} from '../runner-io.ts'; +import { mkdtempForTestSync } from './tmp-dir.ts'; + +function logPathIn(prefix = 'runner-log-tail-'): string { + return path.join(mkdtempForTestSync(prefix), 'runner.log'); +} + +function handleAtEndOf(logPath: string): RunnerLogFile { + return { logPath, startOffset: fs.statSync(logPath).size }; +} + +async function waitFor(assertion: () => void, timeoutMs = 2_000): Promise { + const deadline = Date.now() + timeoutMs; + let lastError: unknown; + for (;;) { + try { + assertion(); + return; + } catch (error) { + lastError = error; + } + if (Date.now() > deadline) throw lastError; + await new Promise((resolve) => setTimeout(resolve, 10)); + } +} + +test('the tail starts where the handle says its generation starts', async () => { + const logPath = logPathIn(); + fs.writeFileSync(logPath, 'previous generation output\n'); + const chunks: string[] = []; + const tail = tailRunnerLogFile({ + file: handleAtEndOf(logPath), + onOutput: (chunk) => chunks.push(chunk), + }); + + fs.appendFileSync(logPath, 'this generation\n'); + await waitFor(() => assert.equal(chunks.join(''), 'this generation\n')); + + tail.stop(); +}); + +test('the tail follows a file its writer keeps appending to', async () => { + const logPath = logPathIn(); + const chunks: string[] = []; + const tail = tailRunnerLogFile({ + file: { logPath, startOffset: 0 }, + onOutput: (chunk) => chunks.push(chunk), + }); + + fs.appendFileSync(logPath, 'one\n'); + await waitFor(() => assert.match(chunks.join(''), /one/)); + fs.appendFileSync(logPath, 'two\n'); + await waitFor(() => assert.match(chunks.join(''), /two/)); + + tail.stop(); + const seenAfterStop = chunks.join(''); + fs.appendFileSync(logPath, 'three\n'); + await new Promise((resolve) => setTimeout(resolve, 120)); + assert.equal(chunks.join(''), seenAfterStop); +}); + +test('a tail whose file disappears stops on its own instead of throwing', async () => { + const logPath = logPathIn(); + fs.writeFileSync(logPath, ''); + const tail = tailRunnerLogFile({ file: { logPath, startOffset: 0 }, onOutput: () => {} }); + fs.rmSync(logPath); + + await new Promise((resolve) => setTimeout(resolve, 120)); + + // Writing a fresh file must not restart a tail that already gave up. + fs.writeFileSync(logPath, 'AGENT_DEVICE_RUNNER_LISTENER_READY\n'); + await new Promise((resolve) => setTimeout(resolve, 120)); + tail.drain(); +}); + +test('drain reads what the file gained and then stops following it', async () => { + const logPath = logPathIn(); + const chunks: string[] = []; + const tail = tailRunnerLogFile({ + file: { logPath, startOffset: 0 }, + onOutput: (chunk) => chunks.push(chunk), + }); + + fs.appendFileSync(logPath, 'tail bytes\n'); + tail.drain(); + + assert.equal(chunks.join(''), 'tail bytes\n'); +}); + +test('the log tail an error can quote is the end of the file, bounded', () => { + const logPath = logPathIn(); + fs.writeFileSync(logPath, `${'x'.repeat(500)}SIGNATURE-TEXT`); + + assert.equal( + readRunnerLogTail({ logPath, startOffset: 0 }, 64), + `${'x'.repeat(50)}SIGNATURE-TEXT`, + ); + assert.equal( + readRunnerLogTail({ logPath, startOffset: 0 }, 4_096).endsWith('SIGNATURE-TEXT'), + true, + ); + assert.equal(readRunnerLogTail(undefined, 64), ''); + assert.equal(readRunnerLogTail({ logPath: `${logPath}.missing`, startOffset: 0 }, 64), ''); +}); + +test('a quoted tail never reaches back before its own generation', () => { + // The file is append-only across runner generations: an older generation's failure text sitting + // under this one's bytes would otherwise be quoted as this launch's output (#2681). + const logPath = logPathIn(); + fs.writeFileSync(logPath, 'Boot failure of an older runner generation\n'); + const file = handleAtEndOf(logPath); + + fs.appendFileSync(logPath, 'this generation said hello\n'); + + assert.equal(readRunnerLogTail(file, 4_096), 'this generation said hello\n'); +}); + +test('a generation that has written nothing yet has no tail to quote', () => { + const logPath = logPathIn(); + fs.writeFileSync(logPath, 'older generation\n'); + + assert.equal(readRunnerLogTail(handleAtEndOf(logPath), 4_096), ''); +}); + +test('createRunnerLogFile records where the append descriptor sits', () => { + const logPath = logPathIn(); + fs.writeFileSync(logPath, 'older generation\n'); + const fd = fs.openSync(logPath, 'a'); + try { + assert.equal(createRunnerLogFile(logPath, fd).startOffset, 'older generation\n'.length); + } finally { + fs.closeSync(fd); + } + + assert.equal(createRunnerLogFile(logPath, fd).startOffset, 0); +}); diff --git a/packages/platform-apple/src/runner/__tests__/runner-listener-ready.test.ts b/packages/platform-apple/src/runner/__tests__/runner-listener-ready.test.ts index 982dfb2d45..2eb2da04c4 100644 --- a/packages/platform-apple/src/runner/__tests__/runner-listener-ready.test.ts +++ b/packages/platform-apple/src/runner/__tests__/runner-listener-ready.test.ts @@ -2,28 +2,35 @@ import assert from 'node:assert/strict'; import { test } from 'vitest'; import { createRunnerListenerReadySignal } from '../runner-listener-ready.ts'; -test('runner listener readiness survives process-output chunk boundaries', async () => { +// The runner writes one merged log file, so chunk boundaries still matter and stream boundaries no +// longer exist. + +test('runner listener readiness survives log read boundaries', async () => { const signal = createRunnerListenerReadySignal(); - signal.observe('stderr', 'noise AGENT_DEVICE_RUNNER_LISTENER_'); + signal.observe('noise AGENT_DEVICE_RUNNER_LISTENER_'); assert.equal(signal.wake.aborted, false); - signal.observe('stderr', 'READY more noise'); + signal.observe('READY more noise'); assert.equal(signal.wake.aborted, true); }); test('runner listener readiness ignores unrelated output', async () => { const signal = createRunnerListenerReadySignal(); - signal.observe('stdout', 'AGENT_DEVICE_RUNNER_WAITING'); + signal.observe('AGENT_DEVICE_RUNNER_WAITING'); assert.equal(signal.wake.aborted, false); }); -test('runner listener readiness does not combine unrelated process streams', async () => { +test('runner listener readiness only carries the marker across one read', async () => { + // The retained suffix is the shortest tail that can complete the marker, so a first half that no + // longer abuts the next read is forgotten rather than matched against output from elsewhere. const signal = createRunnerListenerReadySignal(); - signal.observe('stdout', 'AGENT_DEVICE_RUNNER_LISTENER_'); - signal.observe('stderr', 'READY'); + signal.observe('AGENT_DEVICE_RUNNER_LISTENER_'); + signal.observe(`${'x'.repeat(100)}`); + signal.observe('READY'); + assert.equal(signal.wake.aborted, false); }); diff --git a/packages/platform-apple/src/runner/__tests__/runner-process-launch.test.ts b/packages/platform-apple/src/runner/__tests__/runner-process-launch.test.ts index ce6c1dfa08..240fce06e9 100644 --- a/packages/platform-apple/src/runner/__tests__/runner-process-launch.test.ts +++ b/packages/platform-apple/src/runner/__tests__/runner-process-launch.test.ts @@ -1,38 +1,147 @@ import assert from 'node:assert/strict'; +import fs from 'node:fs'; +import path from 'node:path'; import { beforeEach, test, vi } from 'vitest'; import { IOS_SIMULATOR } from './device-fixtures.ts'; import { makeBackgroundRunner } from './runner-session-fixtures.ts'; +import { mkdtempForTestSync } from './tmp-dir.ts'; import { appleRunnerTestHost } from '../test-host.ts'; import { launchRunnerProcess } from '../runner-process-launch.ts'; const mockRunCmdBackground = vi.fn(); +function runnerLogPath(): string { + return path.join(mkdtempForTestSync('runner-launch-'), 'runner.log'); +} + beforeEach(() => { appleRunnerTestHost.update({ runCmdBackground: mockRunCmdBackground }); + mockRunCmdBackground.mockReset(); }); -test('runner process launch exposes the listener-ready marker from xcodebuild output', async () => { - const background = { - ...makeBackgroundRunner(4242), - wait: new Promise<{ stdout: string; stderr: string; exitCode: number }>(() => {}), - }; - mockRunCmdBackground.mockReturnValue(background); +test("the runner is spawned detached onto its own log file, not onto this process's pipes", async () => { + mockRunCmdBackground.mockReturnValue(makeBackgroundRunner(4242)); - const launched = await launchRunnerProcess({ + launchRunnerProcess({ device: IOS_SIMULATOR, port: 8123, xctestrunPath: '/tmp/runner.xctestrun', derivedPath: '/tmp/runner-derived', + logPath: runnerLogPath(), }); - background.child.stderr.emit('data', 'AGENT_DEVICE_RUNNER_LISTENER_'); - background.child.stderr.emit('data', 'READY'); - assert.equal(launched.startupRetryWake.aborted, true); assert.equal(mockRunCmdBackground.mock.calls[0]?.[0], 'xcodebuild'); + const options = mockRunCmdBackground.mock.calls[0]?.[2] as { + detached?: boolean; + stdio?: (string | number)[]; + captureOutput?: boolean; + env?: NodeJS.ProcessEnv; + }; + // A detached runner that outlives this daemon must not hold a pipe this daemon can close under it: + // SIGPIPE would then arrive on the runner's next write, minutes into the next daemon's session. + assert.equal(options.detached, true); + assert.equal(options.captureOutput, false); + assert.equal(options.stdio?.[0], 'ignore'); + const [stdoutFd, stderrFd] = [options.stdio?.[1], options.stdio?.[2]]; + assert.equal(typeof stdoutFd, 'number'); + assert.equal(stdoutFd, stderrFd); + assert.equal(options.env?.AGENT_DEVICE_RUNNER_PORT, '8123'); + const args = mockRunCmdBackground.mock.calls[0]?.[1] as string[]; assert.equal(args[args.indexOf('-xctestrun') + 1], '/tmp/runner.xctestrun'); assert.equal(args[args.indexOf('-derivedDataPath') + 1], '/tmp/runner-derived'); - assert.equal(mockRunCmdBackground.mock.calls[0]?.[2]?.env?.AGENT_DEVICE_RUNNER_PORT, '8123'); +}); + +test('the listener-ready marker is read back from the runner log file', async () => { + const logPath = runnerLogPath(); + mockRunCmdBackground.mockReturnValue({ + ...makeBackgroundRunner(4242), + wait: new Promise<{ stdout: string; stderr: string; exitCode: number }>(() => {}), + }); + + const launched = launchRunnerProcess({ + device: IOS_SIMULATOR, + port: 8123, + xctestrunPath: '/tmp/runner.xctestrun', + derivedPath: '/tmp/runner-derived', + logPath, + }); + // What a real xcodebuild does: append to the file its descriptor points at. + fs.appendFileSync(logPath, 'AGENT_DEVICE_RUNNER_LISTENER_'); + await waitFor(() => assert.equal(launched.startupRetryWake.aborted, false)); + fs.appendFileSync(logPath, 'READY\n'); + + await waitFor(() => assert.equal(launched.startupRetryWake.aborted, true)); +}); + +test('output an older runner generation left in the same log file does not wake startup', async () => { + const logPath = runnerLogPath(); + fs.writeFileSync(logPath, 'AGENT_DEVICE_RUNNER_LISTENER_READY\n'); + mockRunCmdBackground.mockReturnValue({ + ...makeBackgroundRunner(4242), + wait: new Promise<{ stdout: string; stderr: string; exitCode: number }>(() => {}), + }); + + const launched = launchRunnerProcess({ + device: IOS_SIMULATOR, + port: 8123, + xctestrunPath: '/tmp/runner.xctestrun', + derivedPath: '/tmp/runner-derived', + logPath, + }); + await waitFor(() => assert.equal(launched.startupRetryWake.aborted, false)); + + assert.equal(launched.startupRetryWake.aborted, false); +}); + +test('a listener marker written during the spawn call still wakes startup', async () => { + // A runner that reaches its listener can write before `runCmdBackground` hands the child back. The + // generation offset has to come from the descriptor at open time, or that first line is already + // below it and startup waits on a marker this generation actually printed (#2681). + const logPath = runnerLogPath(); + mockRunCmdBackground.mockImplementation(() => { + fs.appendFileSync(logPath, 'AGENT_DEVICE_RUNNER_LISTENER_READY\n'); + return { + ...makeBackgroundRunner(4242), + wait: new Promise<{ stdout: string; stderr: string; exitCode: number }>(() => {}), + }; + }); + + const launched = launchRunnerProcess({ + device: IOS_SIMULATOR, + port: 8123, + xctestrunPath: '/tmp/runner.xctestrun', + derivedPath: '/tmp/runner-derived', + logPath, + }); + + await waitFor(() => assert.equal(launched.startupRetryWake.aborted, true)); +}); + +test('a boot failure written during the spawn call is quotable from this generation', () => { + // The same window seen from the other reader: the runner that dies instantly writes its failure + // into it, and an error that could not quote those bytes ships a runner failure with an empty tail. + const logPath = runnerLogPath(); + fs.writeFileSync(logPath, '** TEST EXECUTE FAILED ** of an older generation\n'); + mockRunCmdBackground.mockImplementation(() => { + fs.appendFileSync(logPath, 'Failed to install embedded profile for the runner\n'); + return { + ...makeBackgroundRunner(4242), + wait: new Promise<{ stdout: string; stderr: string; exitCode: number }>(() => {}), + }; + }); + + const launched = launchRunnerProcess({ + device: IOS_SIMULATOR, + port: 8123, + xctestrunPath: '/tmp/runner.xctestrun', + derivedPath: '/tmp/runner-derived', + logPath, + }); + + const quoted = launched.readLogTail(4_096); + assert.match(quoted, /Failed to install embedded profile/); + assert.doesNotMatch(quoted, /older generation/); }); test('runner process exit wakes startup probing without a listener marker', async () => { @@ -42,19 +151,60 @@ test('runner process exit wakes startup probing without a listener marker', asyn rejectProcessExit = reject; }, ); - mockRunCmdBackground.mockReturnValue({ - ...makeBackgroundRunner(4242), - wait: processExit, - }); + mockRunCmdBackground.mockReturnValue({ ...makeBackgroundRunner(4242), wait: processExit }); const launched = launchRunnerProcess({ device: IOS_SIMULATOR, port: 8123, xctestrunPath: '/tmp/runner.xctestrun', derivedPath: '/tmp/runner-derived', + logPath: runnerLogPath(), }); rejectProcessExit(new Error('xcodebuild exited')); await Promise.resolve(); assert.equal(launched.startupRetryWake.aborted, true); }); + +test("ending output observation stops the tail and closes this process's descriptor", async () => { + const logPath = runnerLogPath(); + mockRunCmdBackground.mockReturnValue({ + ...makeBackgroundRunner(4242), + wait: new Promise<{ stdout: string; stderr: string; exitCode: number }>(() => {}), + }); + + const launched = launchRunnerProcess({ + device: IOS_SIMULATOR, + port: 8123, + xctestrunPath: '/tmp/runner.xctestrun', + derivedPath: '/tmp/runner-derived', + logPath, + }); + const options = mockRunCmdBackground.mock.calls[0]?.[2] as { stdio: (string | number)[] }; + const logFd = options.stdio[1] as number; + assert.equal(fs.fstatSync(logFd).size >= 0, true); + + launched.endOutputObservation(); + launched.endOutputObservation(); + + // The runner keeps its own descriptor, so closing this process's copy is the whole handoff: no + // signal is sent and nothing the runner writes later can fail (#2681). + assert.throws(() => fs.fstatSync(logFd), /bad file descriptor|EBADF/); + fs.appendFileSync(logPath, 'AGENT_DEVICE_RUNNER_LISTENER_READY\n'); + await waitFor(() => assert.equal(launched.startupRetryWake.aborted, false)); +}); + +async function waitFor(assertion: () => void, timeoutMs = 2_000): Promise { + const deadline = Date.now() + timeoutMs; + let lastError: unknown; + for (;;) { + try { + assertion(); + return; + } catch (error) { + lastError = error; + } + if (Date.now() > deadline) throw lastError; + await new Promise((resolve) => setTimeout(resolve, 10)); + } +} diff --git a/packages/platform-apple/src/runner/__tests__/runner-recovery-wiring.test.ts b/packages/platform-apple/src/runner/__tests__/runner-recovery-wiring.test.ts index 5fddb1624e..662d1d503a 100644 --- a/packages/platform-apple/src/runner/__tests__/runner-recovery-wiring.test.ts +++ b/packages/platform-apple/src/runner/__tests__/runner-recovery-wiring.test.ts @@ -96,6 +96,8 @@ function makeRunnerSession(port: number, sessionId = `wiring:${port}`): RunnerSe testPromise: new Promise(() => {}), child: { pid: process.pid, exitCode: null }, state: 'ready', + inFlightCommands: 0, + hasAbandonedCommands: false, }; return session; } diff --git a/packages/platform-apple/src/runner/__tests__/runner-session-fixtures.ts b/packages/platform-apple/src/runner/__tests__/runner-session-fixtures.ts index 413b81b8c7..2fa54f1694 100644 --- a/packages/platform-apple/src/runner/__tests__/runner-session-fixtures.ts +++ b/packages/platform-apple/src/runner/__tests__/runner-session-fixtures.ts @@ -25,6 +25,8 @@ export function makeRunnerSession(overrides: Partial = {}): Runne testPromise: Promise.resolve({ exitCode: 0, stdout: '', stderr: '' }), child: { pid: 1234, exitCode: null }, state: 'ready', + inFlightCommands: 0, + hasAbandonedCommands: false, ...overrides, } as RunnerSession; } diff --git a/packages/platform-apple/src/runner/__tests__/runner-session-lifecycle.test.ts b/packages/platform-apple/src/runner/__tests__/runner-session-lifecycle.test.ts index e6672efb35..cbb75e7ccc 100644 --- a/packages/platform-apple/src/runner/__tests__/runner-session-lifecycle.test.ts +++ b/packages/platform-apple/src/runner/__tests__/runner-session-lifecycle.test.ts @@ -1,13 +1,20 @@ import assert from 'node:assert/strict'; +import fs from 'node:fs'; +import path from 'node:path'; import { beforeEach, test, vi } from 'vitest'; -import { IOS_SIMULATOR } from './device-fixtures.ts'; +import type { DeviceInfo } from '@agent-device/kernel/device'; +import { IOS_DEVICE, IOS_SIMULATOR, MACOS_DEVICE } from './device-fixtures.ts'; import { appleRunnerTestHost } from '../test-host.ts'; +import { resolveRunnerLaunchLogPath } from '../runner-io.ts'; +import type { RunnerSession } from '../runner-session-types.ts'; import { + captureDiagnostics, makeClassifyOwnerLivenessViaMocks, assertRunnerCommand, makeBackgroundRunner, runnerResponse, redirectHandle, + redirectRelease, } from './runner-session-fixtures.ts'; import { mkdtempForTestSync } from './tmp-dir.ts'; @@ -125,7 +132,7 @@ import { disposeRunnerSession } from '../runner-disposal.ts'; import { hasLiveIosRunnerSession } from '../runner-client.ts'; import { abortAllIosRunnerSessions, - detachIosSimulatorRunnerSessionsForShutdown, + detachIosRunnerSessionsForShutdown, ensureRunnerSession, executeRunnerCommandWithSession, invalidateRunnerSession, @@ -185,7 +192,12 @@ beforeEach(async () => { }); mockResolveExpectedRunnerCacheMetadata.mockReturnValue({ schemaVersion: 1 }); mockResolveRunnerDerivedPath.mockReturnValue('/tmp/derived'); - mockAcquireXcodebuildSimulatorSetRedirect.mockResolvedValue(redirectHandle); + // Faithful to `acquireXcodebuildSimulatorSetRedirect`, which never holds a redirect for a + // non-simulator. Tests covering the default simulator set, where the real helper also returns + // no handle, override with null (#2681). + mockAcquireXcodebuildSimulatorSetRedirect.mockImplementation(async (device: DeviceInfo) => + device.kind === 'simulator' ? redirectHandle : null, + ); mockRunCmdBackground.mockReturnValue(makeBackgroundRunner(4242)); mockRunAppleToolCommand.mockResolvedValue({ exitCode: 0, stdout: '', stderr: '' }); mockIsProcessAlive.mockReturnValue(true); @@ -340,16 +352,266 @@ test('shutdown detach moves a handed-off session to stopped without killing its const device = { ...IOS_SIMULATOR, id: 'runner-lifecycle-detach' }; mockAcquireXcodebuildSimulatorSetRedirect.mockResolvedValue(null); const session = await ensureRunnerSession(device, {}); + await serveOneCommand(device, session); const runnerPid = session.child.pid; assert.ok(runnerPid); runnerStateTransitions.length = 0; - assert.equal(await detachIosSimulatorRunnerSessionsForShutdown(), 1); + assert.equal(await detachIosRunnerSessionsForShutdown(), 1); assert.equal(session.state, 'stopped'); assert.deepEqual(runnerStateTransitions, ['stopped']); assert.equal(readRunnerSessionLiveness(device.id), null); assert.equal(mockIsProcessAlive(runnerPid), true); + assert.match(leaseRaw(device.id), /"ownerToken": "detached-owner-/); +}); + +test('a scoped simulator-set session stays on the kill path that restores the redirect', async () => { + const device = { + ...IOS_SIMULATOR, + id: 'runner-lifecycle-detach-scoped-sim', + simulatorSetPath: '/tmp/custom-device-set', + }; + const session = await ensureRunnerSession(device, {}); + await serveOneCommand(device, session); + assert.equal(mockAcquireXcodebuildSimulatorSetRedirect.mock.calls.length, 1); + + const diagnostics = await captureDiagnostics(async () => { + assert.equal(await detachIosRunnerSessionsForShutdown(), 0); + }); + + // The redirect-holding session must stay for disposal, which restores the + // XCTestDevices symlink; detach never releases the redirect itself. + assert.match(diagnostics, /"reason":"simulator_set_redirect"/); + assert.ok(readRunnerSessionLiveness(device.id)); + assert.equal(redirectRelease.mock.calls.length, 0); +}); + +// #2681: the handoff lanes and every gate that keeps a runner on the kill path. +async function serveOneCommand(device: DeviceInfo, session: RunnerSession): Promise { + mockWaitForRunner.mockResolvedValueOnce(runnerResponse({ nodes: [], truncated: false })); + await executeRunnerCommandWithSession( + device, + session, + { command: 'snapshot', appBundleId: 'com.example.demo' }, + '/tmp/runner.log', + 30_000, + ); +} + +function leaseRaw(deviceId: string): string { + return fs.readFileSync( + path.join(process.env.AGENT_DEVICE_IOS_RUNNER_LEASE_DIR ?? '', `${deviceId}.json`), + 'utf8', + ); +} + +test('a runner that served a command is handed off on the physical lane', async () => { + const device: DeviceInfo = { ...IOS_DEVICE, id: 'runner-lifecycle-detach-device' }; + const session = await ensureRunnerSession(device, {}); + await serveOneCommand(device, session); + runnerStateTransitions.length = 0; + + const diagnostics = await captureDiagnostics(async () => { + assert.equal(await detachIosRunnerSessionsForShutdown(), 1); + }); + + assert.equal(session.state, 'stopped'); + assert.equal(readRunnerSessionLiveness(device.id), null); + assert.match(leaseRaw(device.id), /"ownerToken": "detached-owner-/); + assert.match(diagnostics, /"phase":"ios_runner_session_detached"/); + assert.match(diagnostics, /"lane":"physical_coredevice"/); + + // What a client of the next daemon is told to read, so the handoff must name the file and keep it + // writable by the runner this process no longer follows (#2681). + const runnerLogPath = resolveRunnerLaunchLogPath(undefined, device.id); + assert.ok(diagnostics.includes(`"runnerLogPath":${JSON.stringify(runnerLogPath)}`)); + fs.appendFileSync(runnerLogPath, 'written after the handoff\n'); + assert.match(fs.readFileSync(runnerLogPath, 'utf8'), /written after the handoff/); +}); + +test('a runner that never served a command is torn down instead of handed off', async () => { + // Physical startup runs tens of seconds: handing off a runner that never reached its listener + // would give the next daemon a lease over a process that may not be serving at all. + const device: DeviceInfo = { ...IOS_DEVICE, id: 'runner-lifecycle-shutdown-mid-startup' }; + const session = await ensureRunnerSession(device, {}); + assert.equal(session.state, 'starting'); + + const diagnostics = await captureDiagnostics(async () => { + assert.equal(await detachIosRunnerSessionsForShutdown(), 0); + }); + + assert.deepEqual(readRunnerSessionLiveness(device.id), { + sessionId: session.sessionId, + liveness: 'starting', + }); + assert.match(diagnostics, /"reason":"runner_never_served_a_command"/); + + // The shutdown's own stop path, which runs right after the detach pass, is what tears it down. + await abortAllIosRunnerSessions(); + assert.equal(session.state, 'stopped'); + assert.equal(readRunnerSessionLiveness(device.id), null); +}); + +test('a runner reporting main-thread work still draining is not handed off', async () => { + const device: DeviceInfo = { ...IOS_DEVICE, id: 'runner-lifecycle-detach-busy' }; + const session = await ensureRunnerSession(device, {}); + mockWaitForRunner.mockResolvedValueOnce( + runnerResponse({ nodes: [], truncated: false, runnerMainThreadBusy: true }), + ); + await executeRunnerCommandWithSession( + device, + session, + { command: 'snapshot', appBundleId: 'com.example.demo' }, + '/tmp/runner.log', + 30_000, + ); + assert.equal(session.state, 'ready'); + + const diagnostics = await captureDiagnostics(async () => { + assert.equal(await detachIosRunnerSessionsForShutdown(), 0); + }); + + assert.match(diagnostics, /"reason":"main_thread_occupied"/); + assert.ok(readRunnerSessionLiveness(device.id)); +}); + +test('a session that still owes a response is not handed off', async () => { + // The occupancy mirror only describes the last COMPLETED exchange, so a command abandoned while the + // runner holds it would otherwise hand off a runner with work on its main thread (#2681). + const device: DeviceInfo = { ...IOS_DEVICE, id: 'runner-lifecycle-detach-in-flight' }; + const session = await ensureRunnerSession(device, {}); + await serveOneCommand(device, session); + // `terminate` answers the preflight gate itself, so the only exchange left hanging is the one the + // runner is holding. + mockSendRunnerCommandOnce.mockImplementation( + () => new Promise(() => {}) as Promise, + ); + const inFlight = executeRunnerCommandWithSession( + device, + session, + { command: 'terminate', appBundleId: 'com.example.demo' }, + '/tmp/runner.log', + 30_000, + ); + void inFlight.catch(() => {}); + // The charge lands behind the preflight and deadline awaits, so wait for it instead of betting on a + // single macrotask: a loaded runner can sit anywhere on that path, and a session that had not been + // charged yet would look identical to one whose charge was wrongly dropped (#2681). + for (let tick = 0; tick < 500 && session.inFlightCommands === 0; tick += 1) { + await new Promise((resolve) => setTimeout(resolve, 1)); + } + assert.equal(session.inFlightCommands, 1); + + const diagnostics = await captureDiagnostics(async () => { + assert.equal(await detachIosRunnerSessionsForShutdown(), 0); + }); + + assert.match(diagnostics, /"reason":"command_in_flight"/); + assert.ok(readRunnerSessionLiveness(device.id)); +}); + +test('a command abandoned by a cancelled transport keeps the runner occupied', async () => { + // Cancelling ends every wait this side holds, but the runner is still executing what it took, so a + // shutdown that read only live waits would hand off a runner with work on its main thread. The + // charge is sticky until an answered exchange proves the runner serves requests again (#2681). + const device: DeviceInfo = { ...IOS_DEVICE, id: 'runner-lifecycle-detach-abandoned' }; + const session = await ensureRunnerSession(device, {}); + await serveOneCommand(device, session); + const controller = new AbortController(); + mockSendRunnerCommandOnce.mockImplementationOnce(async () => { + controller.abort(); + throw new Error('Request was aborted'); + }); + + await assert.rejects( + executeRunnerCommandWithSession( + device, + session, + { command: 'terminate', appBundleId: 'com.example.demo' }, + '/tmp/runner.log', + 30_000, + controller.signal, + ), + ); + assert.equal(session.hasAbandonedCommands, true); + + const refused = await captureDiagnostics(async () => { + assert.equal(await detachIosRunnerSessionsForShutdown(), 0); + }); + assert.match(refused, /"reason":"command_in_flight"/); + + // Any answered exchange forgives the abandoned charge: the runner is serving again, and stamps + // whatever is still draining onto that very reply. + await serveOneCommand(device, session); + assert.equal(session.inFlightCommands, 0); + assert.equal(session.hasAbandonedCommands, false); + assert.equal(await detachIosRunnerSessionsForShutdown(), 1); +}); + +test('the macOS host runner is never handed off, although it is kind device', async () => { + const device: DeviceInfo = { ...MACOS_DEVICE, id: 'runner-lifecycle-detach-macos' }; + const session = await ensureRunnerSession(device, {}); + await serveOneCommand(device, session); + + const diagnostics = await captureDiagnostics(async () => { + assert.equal(await detachIosRunnerSessionsForShutdown(), 0); + }); + + assert.match(diagnostics, /"reason":"macos_host"/); + assert.ok(readRunnerSessionLiveness(device.id)); +}); + +test('a physical tvOS runner is never handed off, although it is kind device too', async () => { + const device: DeviceInfo = { + ...IOS_DEVICE, + id: 'runner-lifecycle-detach-tv-device', + name: 'Apple TV', + target: 'tv', + appleOs: 'tvos', + }; + const session = await ensureRunnerSession(device, {}); + await serveOneCommand(device, session); + + const diagnostics = await captureDiagnostics(async () => { + assert.equal(await detachIosRunnerSessionsForShutdown(), 0); + }); + + assert.match(diagnostics, /"reason":"physical_non_ios_os"/); + assert.ok(readRunnerSessionLiveness(device.id)); +}); + +test('a usbmux-only xctest backend runner is never handed off', async () => { + const device: DeviceInfo = { + ...IOS_DEVICE, + id: 'runner-lifecycle-detach-xctest-backend', + iosPhysicalDeviceBackend: 'xctest', + }; + const session = await ensureRunnerSession(device, {}); + await serveOneCommand(device, session); + + const diagnostics = await captureDiagnostics(async () => { + assert.equal(await detachIosRunnerSessionsForShutdown(), 0); + }); + + assert.match(diagnostics, /"reason":"xctest_backend"/); + assert.ok(readRunnerSessionLiveness(device.id)); +}); + +test("the handoff releases this daemon's log bookkeeping only after the lease says so", async () => { + const device: DeviceInfo = { ...IOS_DEVICE, id: 'runner-lifecycle-detach-order' }; + const session = await ensureRunnerSession(device, {}); + await serveOneCommand(device, session); + // What a release done too early would show: the lease this callback reads back is still owned. + const tokenWhenReleased: string[] = []; + session.endOutputObservation = () => { + tokenWhenReleased.push(leaseRaw(device.id)); + }; + + assert.equal(await detachIosRunnerSessionsForShutdown(), 1); + + assert.equal(tokenWhenReleased.length, 1); + assert.match(tokenWhenReleased[0]!, /"ownerToken": "detached-owner-/); }); test('a registered runner whose process died is recycled instead of reused', async () => { diff --git a/packages/platform-apple/src/runner/__tests__/runner-session.test.ts b/packages/platform-apple/src/runner/__tests__/runner-session.test.ts index a47b8166b9..4419e5ed3b 100644 --- a/packages/platform-apple/src/runner/__tests__/runner-session.test.ts +++ b/packages/platform-apple/src/runner/__tests__/runner-session.test.ts @@ -121,7 +121,6 @@ vi.mock('../runner-xctestrun.ts', async () => { import { abortAllIosRunnerSessions, cancelIosRunnerIdleStop, - detachIosSimulatorRunnerSessionsForShutdown, ensureRunnerSession, scheduleIosRunnerIdleStop, executeRunnerCommandWithSession, @@ -459,42 +458,6 @@ test('idle stop is disabled when the window is zero', async () => { } }); -test('shutdown detach hands off default-set simulator runner sessions', async () => { - const device = { ...IOS_SIMULATOR, id: 'runner-session-detach-default-sim' }; - // Default simulator set: no XCTestDevices redirect is held. - mockAcquireXcodebuildSimulatorSetRedirect.mockResolvedValue(null); - await ensureRunnerSession(device, {}); - - const detached = await detachIosSimulatorRunnerSessionsForShutdown(); - - assert.equal(detached, 1); - assert.equal(readRunnerSessionLiveness(device.id), null); - const leaseRaw = fs.readFileSync( - path.join(process.env.AGENT_DEVICE_IOS_RUNNER_LEASE_DIR ?? '', `${device.id}.json`), - 'utf8', - ); - const lease = JSON.parse(leaseRaw) as { ownerToken: string }; - assert.match(lease.ownerToken, /^detached-owner-/); -}); - -test('shutdown detach keeps scoped simulator-set runner sessions for the kill path', async () => { - const device = { - ...IOS_SIMULATOR, - id: 'runner-session-detach-scoped-sim', - simulatorSetPath: '/tmp/custom-device-set', - }; - await ensureRunnerSession(device, {}); - assert.equal(mockAcquireXcodebuildSimulatorSetRedirect.mock.calls.length, 1); - - const detached = await detachIosSimulatorRunnerSessionsForShutdown(); - - // The redirect-holding session must stay for disposal, which restores the - // XCTestDevices symlink; detach never releases the redirect itself. - assert.equal(detached, 0); - assert.ok(readRunnerSessionLiveness(device.id)); - assert.equal(redirectRelease.mock.calls.length, 0); -}); - test('runner session startup kills legacy ownerless xcodebuild before launching a new runner', async () => { const device = { ...IOS_SIMULATOR, id: 'runner-session-startup-stale-sim' }; diff --git a/packages/platform-apple/src/runner/__tests__/runner-startup-transport.test.ts b/packages/platform-apple/src/runner/__tests__/runner-startup-transport.test.ts index 35afe0eb64..07d9128185 100644 --- a/packages/platform-apple/src/runner/__tests__/runner-startup-transport.test.ts +++ b/packages/platform-apple/src/runner/__tests__/runner-startup-transport.test.ts @@ -27,8 +27,12 @@ vi.mock('../runner-usbmux.ts', async (importOriginal) => { }; }); +import fs from 'node:fs'; +import path from 'node:path'; import { clearDeviceTunnelIpCache } from '../runner-command-route.ts'; +import { readRunnerLogTail } from '../runner-io.ts'; import { waitForRunner } from '../runner-startup-transport.ts'; +import { mkdtempForTestSync } from './tmp-dir.ts'; beforeEach(() => { clearDeviceTunnelIpCache(); @@ -211,6 +215,13 @@ test('waitForRunner invalidates cached tunnel IP when localhost fallback succeed }); test('waitForRunner preserves xcodebuild diagnostics when the runner exits during the final probe', async () => { + // Production shape since #2681: xcodebuild appends its own output to the session log, and the + // exec result carries nothing, so the log is what the early-exit error can quote. + const runnerLogPath = path.join(mkdtempForTestSync('runner-early-exit-'), 'runner.log'); + fs.writeFileSync( + runnerLogPath, + 'The application could not be launched because the Developer App Certificate is not trusted.\n', + ); const session: RunnerSession = { sessionId: 'starting-device-session', device: xctestIosDevice, @@ -218,14 +229,14 @@ test('waitForRunner preserves xcodebuild diagnostics when the runner exits durin port: 8100, xctestrunPath: '/tmp/runner.xctestrun', jsonPath: '/tmp/runner.json', - testPromise: Promise.resolve({ - exitCode: 65, - stdout: '', - stderr: - 'The application could not be launched because the Developer App Certificate is not trusted.', - }), + runnerLogPath, + readLogTail: (maxBytes) => + readRunnerLogTail({ logPath: runnerLogPath, startOffset: 0 }, maxBytes), + testPromise: Promise.resolve({ exitCode: 65, stdout: '', stderr: '' }), child: { pid: 1234, exitCode: null } as ExecBackgroundResult['child'], state: 'starting', + inFlightCommands: 0, + hasAbandonedCommands: false, }; mockUsbmuxPostCommand.mockImplementation(async () => { (session.child as { exitCode: number | null }).exitCode = 65; @@ -266,6 +277,8 @@ test('waitForRunner carries the disk-image state when the runner is still alive testPromise: new Promise(() => {}), child: { pid: 1234, exitCode: null } as ExecBackgroundResult['child'], state: 'starting', + inFlightCommands: 0, + hasAbandonedCommands: false, startupDeviceStates: { developerMode: 'enabled', developerDiskImage: 'unavailable', @@ -348,5 +361,7 @@ function makeReadyRunnerSession(): RunnerSession { testPromise: Promise.resolve({ exitCode: 0, stdout: '', stderr: '' }), child: { pid: 1234, exitCode: null } as ExecBackgroundResult['child'], state: 'ready', + inFlightCommands: 0, + hasAbandonedCommands: false, }; } diff --git a/packages/platform-apple/src/runner/apple-runner-platform.ts b/packages/platform-apple/src/runner/apple-runner-platform.ts index 72fbbea11d..5bf365141f 100644 --- a/packages/platform-apple/src/runner/apple-runner-platform.ts +++ b/packages/platform-apple/src/runner/apple-runner-platform.ts @@ -3,6 +3,7 @@ import { isMacOs, isApplePlatform, resolveApplePlatformName, + resolveDeviceAppleOs, type DeviceInfo, } from '@agent-device/kernel/device'; @@ -141,6 +142,58 @@ export function resolveRunnerPlatformName(device: DeviceInfo): RunnerApplePlatfo return resolveApplePlatformName(device.target, device.appleOs); } +export type RunnerHandoffLane = 'simulator' | 'physical_coredevice'; + +/** Why a runner is not eligible to be handed to the next daemon. */ +export type RunnerHandoffRefusal = + /** Not an Apple target at all: only Apple runners take leases. */ + | 'non_apple_target' + /** The macOS desktop target, which is `kind: 'device'` too. */ + | 'macos_host' + /** A physical tvOS/visionOS runner: never exercised across a daemon restart. */ + | 'physical_non_ios_os' + /** An XCTest-backed physical iOS device: usbmux-only, and never exercised across a restart. */ + | 'xctest_backend'; + +export type RunnerHandoffTarget = + | { handoff: true; lane: RunnerHandoffLane } + | { handoff: false; reason: RunnerHandoffRefusal }; + +/** + * Which runner processes a daemon shutdown may hand to the next daemon (#2681). `kind === 'device'` + * is not "physical iOS": the macOS desktop host and physical tvOS/visionOS are that same kind, so + * the lanes are named from the OS discriminant and the physical backend instead. + * + * - `simulator`: every Apple-family Simulator, exactly as before #2681. Scoped simulator sets are a + * second gate at the handoff itself, not here. + * - `physical_coredevice`: a physical iOS/iPadOS device whose runner is reached through CoreDevice. + * + * macOS keeps its runner under the daemon that built it, and physical tvOS/visionOS plus the + * usbmux-only `xctest` backend keep the kill-and-rebuild path: #2681 has no handoff evidence for + * them, and an unexercised handoff is worse than a rebuild. + */ +export function resolveRunnerHandoffTarget(device: DeviceInfo): RunnerHandoffTarget { + if (!isApplePlatform(device.platform)) { + return { handoff: false, reason: 'non_apple_target' }; + } + if (device.kind === 'simulator') { + return { handoff: true, lane: 'simulator' }; + } + if (isMacOs(device)) { + return { handoff: false, reason: 'macos_host' }; + } + // `resolveDeviceAppleOs` defaults a legacy record to iOS, matching the runner profile + // `resolveRunnerPlatformName` picks for it. + const appleOs = resolveDeviceAppleOs(device); + if (appleOs !== 'ios' && appleOs !== 'ipados') { + return { handoff: false, reason: 'physical_non_ios_os' }; + } + if (device.iosPhysicalDeviceBackend === 'xctest') { + return { handoff: false, reason: 'xctest_backend' }; + } + return { handoff: true, lane: 'physical_coredevice' }; +} + export function resolveRunnerSdkName( platformName: RunnerApplePlatformName, deviceKind: DeviceInfo['kind'], diff --git a/packages/platform-apple/src/runner/client.ts b/packages/platform-apple/src/runner/client.ts index 31d02c73f9..d1a7e253b4 100644 --- a/packages/platform-apple/src/runner/client.ts +++ b/packages/platform-apple/src/runner/client.ts @@ -17,7 +17,7 @@ import { import { runnerLeaseCleanupAdapter } from './runner-disposal.ts'; import { runApplePressSeries } from './runner-sequence.ts'; import { - detachIosSimulatorRunnerSessionsForShutdown, + detachIosRunnerSessionsForShutdown, readRunnerSessionLiveness, releaseIosRunnerOnClose, stopAllIosRunnerSessions, @@ -42,7 +42,7 @@ export type AppleRunnerClient = { prepareIosRunner: typeof prepareIosRunner; resolveRunnerAppBundleId: typeof resolveRunnerAppBundleId; hasCachedAppleRunnerArtifact: typeof hasCachedAppleRunnerArtifact; - detachIosSimulatorRunnerSessionsForShutdown: typeof detachIosSimulatorRunnerSessionsForShutdown; + detachIosRunnerSessionsForShutdown: typeof detachIosRunnerSessionsForShutdown; readRunnerSessionLiveness: typeof readRunnerSessionLiveness; releaseIosRunnerOnClose: typeof releaseIosRunnerOnClose; stopIosRunnerSession: typeof stopIosRunnerSession; @@ -73,7 +73,7 @@ export function createAppleRunnerClient(host: AppleRunnerHost): AppleRunnerClien prepareIosRunner, resolveRunnerAppBundleId, hasCachedAppleRunnerArtifact, - detachIosSimulatorRunnerSessionsForShutdown, + detachIosRunnerSessionsForShutdown, readRunnerSessionLiveness, releaseIosRunnerOnClose, stopIosRunnerSession, diff --git a/packages/platform-apple/src/runner/runner-adoption.ts b/packages/platform-apple/src/runner/runner-adoption.ts index 3abaa07638..e76df1c702 100644 --- a/packages/platform-apple/src/runner/runner-adoption.ts +++ b/packages/platform-apple/src/runner/runner-adoption.ts @@ -8,6 +8,11 @@ import { import type { ExecResult } from '@agent-device/host-kit/command'; import type { DeviceInfo } from '@agent-device/kernel/device'; import { isRequestCanceledError } from '@agent-device/kernel/errors'; +import { + resolveRunnerHandoffTarget, + type RunnerHandoffLane, + type RunnerHandoffRefusal, +} from './apple-runner-platform.ts'; import { sendRunnerCommandOnce } from './runner-transport.ts'; import { decodeRunnerResponseBody, @@ -16,10 +21,12 @@ import { } from './runner-contract.ts'; import { buildRunnerLease, - readStaleRunnerLease, + isLeaseRunnerProcessIntact, + readRunnerLeaseForAdoption, verifyLeaseRunnerPidIdentity, writeRunnerLease, type RunnerLease, + type RunnerLeaseAdoptionRefusal, } from './runner-lease.ts'; import { requireRunnerPhaseRemainingMs, @@ -39,21 +46,45 @@ import { // where giving up fast matters — the probe runs under the lease lock, in // series before the restart it would otherwise avoid. const RUNNER_ADOPTION_PROBE_TIMEOUT_MS = 500; + +// What the physical lane gets instead, because its probe may have to resolve the device's tunnel +// address through `devicectl device info details` before any byte reaches the runner. A cap is not +// a sleep: a runner that answers in 8 ms answers in 8 ms under either cap, so only the refusal path +// spends the difference, and it spends it once (#2681). +const RUNNER_ADOPTION_PHYSICAL_PROBE_TIMEOUT_MS = 5_000; + const RUNNER_ADOPTION_EXIT_POLL_INTERVAL_MS = 1_000; // Kill switch for the runner handoff across daemon restarts: disables both -// detaching healthy simulator runners on graceful shutdown and adopting them -// on the next startup. +// detaching healthy runners on graceful shutdown and adopting them on the next +// startup, in every handoff lane (#2681). export function isIosRunnerDetachEnabled(env: NodeJS.ProcessEnv = process.env): boolean { return parseBooleanLiteral(env.AGENT_DEVICE_IOS_RUNNER_DETACH ?? '') !== false; } +type RunnerAdoptionRefusal = + | RunnerHandoffRefusal + | 'simulator_set_redirect' + | 'lease_absent' + | RunnerLeaseAdoptionRefusal + | 'session_identity_mismatch' + | 'runner_pid_missing' + | 'runner_process_dead' + | 'runner_pid_recycled' + | 'expected_derived_unresolved' + | 'artifact_fingerprint_mismatch' + | 'probe_failed' + /** The runner answered but its lease could not be re-stamped, so nothing may claim it. */ + | 'lease_write_failed' + /** The startup phase had nothing left to probe with, so the rebuild starts on its own clock. */ + | 'probe_budget_exhausted'; + // Adopts a still-running runner left behind by a dead daemon (crash or -// graceful detach) instead of killing and restarting it: the lease must be -// stale, the xcodebuild process alive, the artifact fingerprint current, and -// the runner must answer an uptime probe. Any miss returns null and the -// normal cleanup-and-start path takes over. Must run under the runner lease -// lock, like the rest of session startup. +// graceful detach) instead of killing and restarting it: the device is a +// handoff target, the lease is stale and identity-verifiable, the artifact +// fingerprint is current, and the runner answers an uptime probe. Any miss +// reports its reason and the normal cleanup-and-start path takes over. Must run +// under the runner lease lock, like the rest of session startup. export async function tryAdoptRunnerSessionFromLease( device: DeviceInfo, options: { @@ -65,65 +96,55 @@ export async function tryAdoptRunnerSessionFromLease( expectedRunnerSessionId?: string; }, ): Promise { - if (device.kind !== 'simulator' || !isIosRunnerDetachEnabled()) return null; - // Custom simulator sets run behind the XCTestDevices redirect, whose - // symlink+lock lifetime is bound to the owning session and cannot be - // carried across daemons; scoped-set runners always restart fresh. - if (resolveIosSimulatorDeviceSetPath(device.simulatorSetPath)) return null; - const lease = readStaleRunnerLease(device.id); - if (!lease) return null; - - const skip = (reason: string): null => { + if (!isIosRunnerDetachEnabled()) return null; + const target = resolveRunnerHandoffTarget(device); + const skip = (reason: RunnerAdoptionRefusal, lease?: RunnerLease): null => { emitDiagnostic({ level: 'debug', phase: 'ios_runner_lease_adoption_skipped', - data: { deviceId: device.id, runnerPid: lease.runnerPid, port: lease.port, reason }, + data: { + deviceId: device.id, + lane: target.handoff ? target.lane : undefined, + runnerPid: lease?.runnerPid, + port: lease?.port, + reason, + }, }); return null; }; - - if ( - options.expectedRunnerSessionId !== undefined && - lease.sessionId !== options.expectedRunnerSessionId - ) { - return skip('session_identity_mismatch'); - } - - const runnerPid = lease.runnerPid; - if (!runnerPid) return skip('runner_pid_missing'); - if (!isProcessAlive(runnerPid)) return skip('runner_process_dead'); - // The adopted session later signals this pid on disposal — and adoption - // re-stamps the lease with the live pid's start time — so a pid that cannot - // be proven to still be the leased runner must never be adopted, even if - // some process answers the leased port. Legacy leases without a recorded - // start time fall back to the runner-shaped command-line check. - if (!verifyLeaseRunnerPidIdentity(lease, runnerPid)) { - return skip('runner_pid_recycled'); - } - const expectedDerived = resolveExpectedDerivedPath(device, options.budget); - if (!expectedDerived) return skip('expected_derived_unresolved'); - if (!lease.xctestrunPath.startsWith(`${expectedDerived}${path.sep}`)) { - return skip('artifact_fingerprint_mismatch'); - } - if (!(await probeRunnerAnswersUptime(device, lease.port))) return skip('probe_failed'); + const eligible = resolveHandoffLane(device, target); + if ('refusal' in eligible) return skip(eligible.refusal); + const leaseVerdict = readRunnerLeaseForAdoption(device.id); + if (leaseVerdict.type === 'absent') return skip('lease_absent'); + if (leaseVerdict.type === 'refused') return skip(leaseVerdict.reason, leaseVerdict.lease); + const lease = leaseVerdict.lease; + const leased = verifyLeasedRunnerProcess(lease, options.expectedRunnerSessionId); + if ('refusal' in leased) return skip(leased.refusal, lease); + const fingerprint = verifyLeaseArtifactFingerprint(device, lease, options.budget); + if ('refusal' in fingerprint) return skip(fingerprint.refusal, lease); + const runnerPid = leased.value; + const expectedDerived = fingerprint.value; + const probe = await probeRunnerAnswersUptime(device, lease.port, eligible.value, options.budget); + if (probe !== 'answered') return skip(probe, lease); // The probe awaited network I/O — the xcodebuild can have exited and its pid // been recycled while the old port still answers. Re-verify before the // adopted lease re-stamps the pid; everything below is synchronous. - if (!isProcessAlive(runnerPid) || !verifyLeaseRunnerPidIdentity(lease, runnerPid)) { - return skip('runner_pid_recycled'); + if (!isLeaseRunnerProcessIntact(lease, runnerPid)) { + return skip('runner_pid_recycled', lease); } const session = buildAdoptedRunnerSession(device, lease, runnerPid, expectedDerived, options); try { writeRunnerLease(session.lease); } catch { - return null; + return skip('lease_write_failed', lease); } emitDiagnostic({ level: 'info', phase: 'ios_runner_lease_adopted', data: { deviceId: device.id, + lane: eligible.value, sessionId: session.sessionId, runnerPid, port: lease.port, @@ -133,20 +154,126 @@ export async function tryAdoptRunnerSessionFromLease( return session; } -async function probeRunnerAnswersUptime(device: DeviceInfo, port: number): Promise { +/** A guard group's verdict: the value adoption needs next, or the typed reason it stopped. */ +type RunnerAdoptionCheck = { value: Value } | { refusal: RunnerAdoptionRefusal }; + +/** + * Which lane this device hands a runner through, if it may hand one across daemons at all. Answers it + * before any lease is read, so an ineligible device never touches lease state. + */ +function resolveHandoffLane( + device: DeviceInfo, + target: ReturnType, +): RunnerAdoptionCheck { + if (!target.handoff) return { refusal: target.reason }; + // Custom simulator sets run behind the XCTestDevices redirect, whose + // symlink+lock lifetime is bound to the owning session and cannot be + // carried across daemons; scoped-set runners always restart fresh. + if (target.lane === 'simulator' && resolveIosSimulatorDeviceSetPath(device.simulatorSetPath)) { + return { refusal: 'simulator_set_redirect' }; + } + return { value: target.lane }; +} + +/** + * Whether the leased pid is a runner this daemon may take over, and the one adoption will adopt. + * The adopted session later signals this pid on disposal — and adoption re-stamps the lease with the + * live pid's start time — so a pid that cannot be proven to still be the leased runner must never be + * adopted, even if some process answers the leased port. Legacy leases without a recorded start time + * fall back to the runner-shaped command-line check. + */ +function verifyLeasedRunnerProcess( + lease: RunnerLease, + expectedRunnerSessionId: string | undefined, +): RunnerAdoptionCheck { + if (expectedRunnerSessionId !== undefined && lease.sessionId !== expectedRunnerSessionId) { + return { refusal: 'session_identity_mismatch' }; + } + const runnerPid = lease.runnerPid; + if (!runnerPid) return { refusal: 'runner_pid_missing' }; + if (!isProcessAlive(runnerPid)) return { refusal: 'runner_process_dead' }; + if (!verifyLeaseRunnerPidIdentity(lease, runnerPid)) return { refusal: 'runner_pid_recycled' }; + return { value: runnerPid }; +} + +/** + * Whether the leased build product is the one this platform would itself have built, so a runner left + * behind by a different artifact is rebuilt rather than adopted and served to a mismatched request. + */ +function verifyLeaseArtifactFingerprint( + device: DeviceInfo, + lease: RunnerLease, + budget: RunnerPhaseBudget | undefined, +): RunnerAdoptionCheck { + const expectedDerived = resolveExpectedDerivedPath(device, budget); + if (!expectedDerived) return { refusal: 'expected_derived_unresolved' }; + if (!lease.xctestrunPath.startsWith(`${expectedDerived}${path.sep}`)) { + return { refusal: 'artifact_fingerprint_mismatch' }; + } + return { value: expectedDerived }; +} + +/** + * Probes with the lane's cap, spent from the startup phase's budget (#2422): the probe runs inside + * the request's lease lock, so a wedged runner must not get to stretch the phase past what the + * request already allowed, and a cancelled request has to be able to reach a probe mid-flight. + */ +async function probeRunnerAnswersUptime( + device: DeviceInfo, + port: number, + lane: RunnerHandoffLane, + budget: RunnerPhaseBudget | undefined, +): Promise { + const capMs = + lane === 'physical_coredevice' + ? RUNNER_ADOPTION_PHYSICAL_PROBE_TIMEOUT_MS + : RUNNER_ADOPTION_PROBE_TIMEOUT_MS; + const timeoutMs = runnerProbeTimeoutMs(budget, capMs); + if (timeoutMs <= 0) return 'probe_budget_exhausted'; + const startedAtMs = Date.now(); + let answered = false; try { const response = await sendRunnerCommandOnce( device, port, withRunnerCommandId({ command: 'uptime' }), - RUNNER_ADOPTION_PROBE_TIMEOUT_MS, + timeoutMs, + budget?.signal, ); - return isRunnerResponseOk(decodeRunnerResponseBody(await response.text())); - } catch { - return false; + answered = isRunnerResponseOk(decodeRunnerResponseBody(await response.text())); + return answered ? 'answered' : 'probe_failed'; + } catch (error) { + // A cancelled request is not a runner that failed to answer: the caller must not rebuild on it. + if (isRequestCanceledError(error)) throw error; + return 'probe_failed'; + } finally { + // What the probe was allowed to spend and what it actually cost is the evidence #2681 sizes + // these caps against, so it is recorded rather than only reasoned about. + emitDiagnostic({ + level: 'debug', + phase: 'ios_runner_lease_adoption_probe', + durationMs: Date.now() - startedAtMs, + data: { + deviceId: device.id, + port, + lane, + budgetCapMs: capMs, + timeoutMs, + answered, + }, + }); } } +/** `'answered'`, or the refusal the caller reports for what kept the runner from answering. */ +type RunnerProbeOutcome = 'answered' | 'probe_failed' | 'probe_budget_exhausted'; + +/** The probe's own cap, cut down to whatever the startup phase still has. */ +function runnerProbeTimeoutMs(budget: RunnerPhaseBudget | undefined, capMs: number): number { + if (!budget?.deadline) return capMs; + return Math.min(capMs, Math.floor(budget.deadline.remainingMs())); +} + function resolveExpectedDerivedPath( device: DeviceInfo, budget: RunnerPhaseBudget | undefined, @@ -191,8 +318,13 @@ function buildAdoptedRunnerSession( jsonPath: lease.jsonPath, testPromise: wait, child, + // The runner appends to this file for its whole life, so the log the previous daemon handed over + // is still the one worth quoting; a lease from before #2681 has none (#2681). + runnerLogPath: lease.runnerLogPath, // The probe already proved the runner answers commands. state: 'ready', + inFlightCommands: 0, + hasAbandonedCommands: false, startupTimeoutMs: normalizeRunnerStartupTimeoutMs( requireRunnerPhaseRemainingMs(options.budget, 'runner_session_adoption'), ), @@ -203,6 +335,7 @@ function buildAdoptedRunnerSession( port: lease.port, xctestrunPath: lease.xctestrunPath, jsonPath: lease.jsonPath, + runnerLogPath: lease.runnerLogPath, }), }; } diff --git a/packages/platform-apple/src/runner/runner-contract.ts b/packages/platform-apple/src/runner/runner-contract.ts index 2724c8ad01..bd1848724a 100644 --- a/packages/platform-apple/src/runner/runner-contract.ts +++ b/packages/platform-apple/src/runner/runner-contract.ts @@ -26,6 +26,10 @@ import { import type { BootFailureReason } from '@agent-device/provision-kit/boot-diagnostics'; import type { RunnerSession } from './runner-session-types.ts'; +// What an early-exit error quotes of the runner's own log: enough for the boot-failure anchors +// (signing, tunneld, device busy), bounded so a wedged xcodebuild cannot ship a megabyte in details. +const RUNNER_EARLY_EXIT_LOG_TAIL_BYTES = 64 * 1024; + /** * The runner's own code for "an earlier command exceeded the execution watchdog and its abandoned * main-thread work is still draining" (#1105). It is transient by construction — past the wedge @@ -842,10 +846,13 @@ export async function buildRunnerEarlyExitError(params: { const { session, port, logPath } = params; const result = await session.testPromise; const message = 'Runner did not accept connection (xcodebuild exited early)'; + // The runner writes its own output file, so the exec result holds nothing for a file-backed + // child; that file is what an early exit can quote (#2681). + const output = session.readLogTail?.(RUNNER_EARLY_EXIT_LOG_TAIL_BYTES) ?? ''; const reason = classifyBootFailure({ message, - stdout: result.stdout, - stderr: result.stderr, + stdout: output, + stderr: output, context: { platform: 'ios', phase: 'connect' }, }); // exec-guard-allow: xcodebuild can exit 0 and still count as an early exit; @@ -853,14 +860,17 @@ export async function buildRunnerEarlyExitError(params: { // `reason`/`hint` above — not a process-exit wrap. const error = new AppError('COMMAND_FAILED', message, { port, - logPath, + // The quote always comes from the runner's own file, so that is the file the error has to name; + // pointing at the request's log would advertise a file that does not contain what is quoted (#2681). + logPath: session.runnerLogPath ?? logPath, xcodebuild: { exitCode: result.exitCode, - stdout: result.stdout, - stderr: result.stderr, + // One merged file since #2681: the tail is reported under `stderr`, which is where readers + // already look, next to the file it came from. + stderr: output, }, reason, - hint: resolveRunnerEarlyExitHint(message, result.stdout, result.stderr, reason), + hint: resolveRunnerEarlyExitHint(message, output, output, reason), }); // The build catch is not the only way a runner stops before serving a command. A locked phone lets // the build finish and kills `xcodebuild test-without-building` instead, so nothing reaches that diff --git a/packages/platform-apple/src/runner/runner-io.ts b/packages/platform-apple/src/runner/runner-io.ts index 03cd303067..dd447dcb61 100644 --- a/packages/platform-apple/src/runner/runner-io.ts +++ b/packages/platform-apple/src/runner/runner-io.ts @@ -1,4 +1,5 @@ import fs from 'node:fs'; +import os from 'node:os'; import path from 'node:path'; import net from 'node:net'; import { AppError } from '@agent-device/kernel/errors'; @@ -125,3 +126,150 @@ export function cleanupTempFile(filePath: string): void { if (fs.existsSync(filePath)) fs.unlinkSync(filePath); } catch {} } + +/** + * The file a runner generation writes its own output to, handed to the child as its stdout/stderr + * so a detached runner never owns a pipe this process can close under it (#2681). + * + * A request always carries the session's `runner.log`. A runner started without one still needs a + * file rather than a pipe, so it gets the shared per-device scratch log. + */ +export function resolveRunnerLaunchLogPath(logPath: string | undefined, deviceId: string): string { + if (logPath) return logPath; + const safeDeviceId = deviceId.replaceAll(/[^A-Za-z0-9._-]/g, '_'); + return path.join(os.tmpdir(), 'agent-device', 'apple-runner', 'logs', `${safeDeviceId}.log`); +} + +const RUNNER_LOG_TAIL_DEFAULT_POLL_MS = 50; +const RUNNER_LOG_TAIL_CHUNK_BYTES = 64 * 1024; + +/** + * One runner generation's view of the log file it was launched onto (#2681). + * + * The file outlives the generation that appended to it, so every reader needs to know where its + * own generation began: bytes below `startOffset` were written by an older runner, and quoting them + * as this one's output would classify a boot failure this launch never produced. + */ +export type RunnerLogFile = Readonly<{ + logPath: string; + startOffset: number; +}>; + +/** + * Opens one generation's view of a log file from the append-mode descriptor it was launched with: + * an append descriptor opens at end-of-file, so the size behind it is this generation's start. + */ +export function createRunnerLogFile(logPath: string, outputFd: number): RunnerLogFile { + let startOffset = 0; + try { + startOffset = fs.fstatSync(outputFd).size; + } catch {} + return { logPath, startOffset }; +} + +export type RunnerLogTail = Readonly<{ + /** Reads whatever the file gained since the last read, then stops polling. */ + drain(): void; + /** Stops following the file and releases this process's read side of it. */ + stop(): void; +}>; + +/** + * Follows a log file the runner writes itself, starting where its generation starts. + * + * The child owns the write end, so the host reads the file back to see the listener-ready marker. + * The tail is a latency hint, not a readiness proof — a file that cannot be read stops the tail and + * startup ends on its own budget instead. + */ +export function tailRunnerLogFile(input: { + file: RunnerLogFile; + onOutput(chunk: string): void; + pollMs?: number; +}): RunnerLogTail { + const pollMs = input.pollMs ?? RUNNER_LOG_TAIL_DEFAULT_POLL_MS; + const buffer = Buffer.alloc(RUNNER_LOG_TAIL_CHUNK_BYTES); + let offset = input.file.startOffset; + let readFd: number | null = null; + let timer: NodeJS.Timeout | null = null; + let stopped = false; + + const drain = (): void => { + if (stopped) return; + try { + readFd ??= fs.openSync(input.file.logPath, 'r'); + let size = fs.fstatSync(readFd).size; + // A truncated or replaced log restarts the tail rather than reading across the gap. + if (size < offset) offset = 0; + while (offset < size) { + const wanted = Math.min(buffer.length, size - offset); + const read = fs.readSync(readFd, buffer, 0, wanted, offset); + if (read <= 0) break; + offset += read; + input.onOutput(buffer.toString('utf8', 0, read)); + size = fs.fstatSync(readFd).size; + } + } catch { + stop(); + } + }; + + const schedule = (): void => { + if (stopped) return; + timer = setTimeout(() => { + drain(); + schedule(); + }, pollMs); + timer.unref?.(); + }; + + function stop(): void { + if (stopped) return; + stopped = true; + if (timer) clearTimeout(timer); + timer = null; + if (readFd !== null) { + try { + fs.closeSync(readFd); + } catch {} + readFd = null; + } + } + + schedule(); + return { + drain: () => { + drain(); + stop(); + }, + stop, + }; +} + +/** + * The tail of one generation's runner log: what an early-exit error can quote when the runner's + * output went to the file instead of a pipe (#2681). Bounded to the bytes this generation wrote — + * an older runner's boot failure in the same file must not become this launch's recovery hint — and + * to `maxBytes` from there. Empty when the file is unreadable or this generation wrote nothing. + */ +export function readRunnerLogTail(file: RunnerLogFile | undefined, maxBytes: number): string { + if (!file) return ''; + let fd: number | null = null; + try { + fd = fs.openSync(file.logPath, 'r'); + const size = fs.fstatSync(fd).size; + const from = Math.max(file.startOffset, size - maxBytes); + const wanted = size - from; + if (wanted <= 0) return ''; + const buffer = Buffer.alloc(wanted); + const read = fs.readSync(fd, buffer, 0, wanted, from); + return buffer.toString('utf8', 0, Math.max(read, 0)); + } catch { + return ''; + } finally { + if (fd !== null) { + try { + fs.closeSync(fd); + } catch {} + } + } +} diff --git a/packages/platform-apple/src/runner/runner-lease.ts b/packages/platform-apple/src/runner/runner-lease.ts index 20d857491c..3f3f683bd2 100644 --- a/packages/platform-apple/src/runner/runner-lease.ts +++ b/packages/platform-apple/src/runner/runner-lease.ts @@ -51,6 +51,12 @@ export type RunnerLease = { port: number; xctestrunPath: string; jsonPath: string; + /** + * Where the leased runner's own output goes. The runner appends to this file for its whole life, + * including across a daemon handoff, so the daemon that adopts it can point at it (#2681). + * Absent on leases written before the runner's stdio moved onto a file. + */ + runnerLogPath?: string; createdAtMs: number; /** * The owner arbitrates device ownership through host-global device claims @@ -96,7 +102,9 @@ export function buildRunnerLease(params: { port: number; xctestrunPath: string; jsonPath: string; + runnerLogPath?: string; }): RunnerLease { + const runnerLogPath = readOptionalNonEmptyString(params.runnerLogPath); return { schemaVersion: RUNNER_LEASE_SCHEMA_VERSION, deviceId: params.deviceId, @@ -110,6 +118,7 @@ export function buildRunnerLease(params: { port: params.port, xctestrunPath: params.xctestrunPath, jsonPath: params.jsonPath, + ...(runnerLogPath ? { runnerLogPath } : {}), createdAtMs: Date.now(), deviceClaimProtocol: 1, }; @@ -296,15 +305,39 @@ function formatEnvAssignment(name: string, value: string): string { // dies, so crash-orphans and deliberate handoffs share one recovery path. // Adoption is strictly PID-dead-gated: an owner whose state dir is gone but // whose process is still alive may still hold a live connection to the -// runner, so adopting it would create two masters. Those leases return null +// runner, so adopting it would create two masters. Those leases are refused // here and go through prepareRunnerLeaseForStartup's force-stop path (kill // the leased runner processes, then rebuild) instead. -export function readStaleRunnerLease(deviceId: string): RunnerLease | null { +export type RunnerLeaseAdoptionRefusal = + | 'lease_owned_by_this_daemon' + | 'lease_owner_live' + | 'lease_owner_state_dir_gone'; + +export type RunnerLeaseAdoptionVerdict = + | { type: 'adoptable'; lease: RunnerLease } + | { type: 'absent' } + | { type: 'refused'; reason: RunnerLeaseAdoptionRefusal; lease: RunnerLease }; + +/** The one classification adoption reads, so a refused lease reports why it was refused. */ +export function readRunnerLeaseForAdoption(deviceId: string): RunnerLeaseAdoptionVerdict { const state = classifyRunnerLease(readRunnerLease(deviceId)); - return state.type === 'stale' && - (state.staleReason === 'owner-process-dead' || state.staleReason === 'owner-process-reused') - ? state.lease - : null; + switch (state.type) { + case 'empty': + return { type: 'absent' }; + case 'owned': + return { type: 'refused', reason: 'lease_owned_by_this_daemon', lease: state.lease }; + case 'busy': + return { type: 'refused', reason: 'lease_owner_live', lease: state.lease }; + case 'stale': + return state.staleReason === 'owner-state-dir-gone' + ? { type: 'refused', reason: 'lease_owner_state_dir_gone', lease: state.lease } + : { type: 'adoptable', lease: state.lease }; + } +} + +export function readStaleRunnerLease(deviceId: string): RunnerLease | null { + const verdict = readRunnerLeaseForAdoption(deviceId); + return verdict.type === 'adoptable' ? verdict.lease : null; } // Marks a lease as handed off during graceful shutdown: the token no longer @@ -436,6 +469,7 @@ function normalizeRunnerLease(value: unknown, deviceId: string): RunnerLease | n ownerStateDir: readOptionalString(raw.ownerStateDir) ?? undefined, runnerPid: readPositiveInteger(raw.runnerPid), runnerStartTime: readOptionalString(raw.runnerStartTime), + runnerLogPath: readOptionalNonEmptyString(raw.runnerLogPath), ...(raw.deviceClaimProtocol === 1 ? { deviceClaimProtocol: 1 as const } : {}), }; } @@ -460,6 +494,10 @@ function readNonEmptyString(value: unknown): string | null { return typeof value === 'string' && value.length > 0 ? value : null; } +function readOptionalNonEmptyString(value: unknown): string | undefined { + return readNonEmptyString(value) ?? undefined; +} + function readOptionalString(value: unknown): string | null { return typeof value === 'string' ? value : null; } @@ -518,6 +556,15 @@ async function cleanupLeasedRunnerProcesses( * pattern-based xcodebuild pkill in the cleanup adapter is unaffected and * still collects genuinely stray runner processes. */ +/** + * Whether a live pid is provably still the leased runner. The one place this contract is written, so + * the pid a caller is willing to signal and the pid adoption is willing to take over cannot drift + * apart (#2681). + */ +export function isLeaseRunnerProcessIntact(lease: RunnerLease, runnerPid: number): boolean { + return isProcessAlive(runnerPid) && verifyLeaseRunnerPidIdentity(lease, runnerPid); +} + function resolveVerifiedLeaseRunnerPid(lease: RunnerLease): number | undefined { const pid = lease.runnerPid ?? undefined; if (!pid || !isProcessAlive(pid)) return undefined; diff --git a/packages/platform-apple/src/runner/runner-listener-ready.ts b/packages/platform-apple/src/runner/runner-listener-ready.ts index 05fe56479b..2fdc3fb066 100644 --- a/packages/platform-apple/src/runner/runner-listener-ready.ts +++ b/packages/platform-apple/src/runner/runner-listener-ready.ts @@ -2,37 +2,35 @@ const RUNNER_LISTENER_READY_MARKER = 'AGENT_DEVICE_RUNNER_LISTENER_READY'; export type RunnerListenerReadySignal = Readonly<{ wake: AbortSignal; - observe(source: 'stdout' | 'stderr', chunk: string): void; + observe(chunk: string): void; finish(): void; }>; /** * Turns the runner's authoritative NWListener-ready log marker into a one-shot host signal. - * xcodebuild may split one log line across process-output chunks, so the scanner retains only the - * shortest suffix that can complete the marker on the next chunk. + * A line can straddle two reads of the runner's output, so the scanner retains only the shortest + * suffix that can complete the marker on the next one. */ export function createRunnerListenerReadySignal(): RunnerListenerReadySignal { const wake = new AbortController(); let settled = false; - const tails = { stdout: '', stderr: '' }; + let tail = ''; return { wake: wake.signal, - observe: (source, chunk) => { + observe: (chunk) => { if (settled) return; - const candidate = tails[source] + chunk; + const candidate = tail + chunk; if (candidate.includes(RUNNER_LISTENER_READY_MARKER)) { settled = true; - tails.stdout = ''; - tails.stderr = ''; + tail = ''; wake.abort(); return; } - tails[source] = candidate.slice(-(RUNNER_LISTENER_READY_MARKER.length - 1)); + tail = candidate.slice(-(RUNNER_LISTENER_READY_MARKER.length - 1)); }, finish: () => { settled = true; - tails.stdout = ''; - tails.stderr = ''; + tail = ''; wake.abort(); }, }; diff --git a/packages/platform-apple/src/runner/runner-process-launch.ts b/packages/platform-apple/src/runner/runner-process-launch.ts index a4d944272d..cf95c9f966 100644 --- a/packages/platform-apple/src/runner/runner-process-launch.ts +++ b/packages/platform-apple/src/runner/runner-process-launch.ts @@ -1,9 +1,16 @@ +import fs from 'node:fs'; +import path from 'node:path'; import type { DeviceInfo } from '@agent-device/kernel/device'; import { runCmdBackground } from './host.ts'; import type { ExecBackgroundResult } from '@agent-device/host-kit/command'; import { resolveRunnerDestination } from './apple-runner-platform.ts'; import { resolveRunnerMaxConcurrentDestinationsFlag } from './runner-cache-metadata.ts'; -import { logChunk } from './runner-io.ts'; +import { + createRunnerLogFile, + logChunk, + readRunnerLogTail, + tailRunnerLogFile, +} from './runner-io.ts'; import { createRunnerListenerReadySignal } from './runner-listener-ready.ts'; const RUNNER_DESTINATION_TIMEOUT_SECONDS = 20; @@ -13,54 +20,114 @@ type LaunchRunnerProcessInput = Readonly<{ port: number; xctestrunPath: string; derivedPath: string; + /** Where the runner's own output goes. The child owns this file for its whole life (#2681). */ + logPath: string; signal?: AbortSignal; - logPath?: string; traceLogPath?: string; verbose?: boolean; }>; export type LaunchedRunnerProcess = ExecBackgroundResult & - Readonly<{ startupRetryWake: AbortSignal }>; + Readonly<{ + startupRetryWake: AbortSignal; + /** Gives up this process's sides of the runner's log; see {@link launchRunnerProcess}. */ + endOutputObservation: () => void; + /** Reads the end of the runner's log, which the runner itself keeps writing to (#2681). */ + readLogTail(maxBytes: number): string; + }>; -/** Launches xcodebuild and projects its authoritative listener-ready marker as a host signal. */ +/** + * Launches xcodebuild and projects its authoritative listener-ready marker as a host signal. + * + * The runner's stdout/stderr are this file, not pipes: a detached runner outlives the daemon that + * started it, and a pipe hands it a reader whose death raises SIGPIPE on the runner's next write, + * minutes into the next daemon's session (#2681). Readiness is projected from that same file, so the + * marker still wakes startup retries, and process exit still wakes them on its own. + */ export function launchRunnerProcess(input: LaunchRunnerProcessInput): LaunchedRunnerProcess { + const logPath = input.logPath; + fs.mkdirSync(path.dirname(logPath), { recursive: true }); + const outputFd = fs.openSync(logPath, 'a'); + // An append descriptor opens at end-of-file, so the size behind it is where this generation's + // output starts. It is read here rather than after the spawn because a runner that dies + // immediately writes its failure into exactly this window: bytes landed during the spawn would + // otherwise sit below the offset and reach neither the readiness tail nor an error's quote. + const logFile = createRunnerLogFile(logPath, outputFd); + const closeOutputFd = once(() => { + try { + fs.closeSync(outputFd); + } catch {} + }); const listenerReady = createRunnerListenerReadySignal(); - const launched = runCmdBackground( - 'xcodebuild', - [ - 'test-without-building', - '-only-testing', - 'AgentDeviceRunnerUITests/RunnerTests/testCommand', - '-parallel-testing-enabled', - 'NO', - '-test-timeouts-enabled', - 'NO', - '-collect-test-diagnostics', - 'never', - resolveRunnerMaxConcurrentDestinationsFlag(input.device), - '1', - '-destination-timeout', - String(RUNNER_DESTINATION_TIMEOUT_SECONDS), - '-xctestrun', - input.xctestrunPath, - '-derivedDataPath', - input.derivedPath, - '-destination', - resolveRunnerDestination(input.device), - ], - { - allowFailure: true, - env: { ...process.env, AGENT_DEVICE_RUNNER_PORT: String(input.port) }, - detached: true, - signal: input.signal, - }, - ); - const observeOutput = (source: 'stdout' | 'stderr', chunk: string): void => { - listenerReady.observe(source, chunk); - logChunk(chunk, input.logPath, input.traceLogPath, input.verbose); + try { + const launched = runCmdBackground( + 'xcodebuild', + [ + 'test-without-building', + '-only-testing', + 'AgentDeviceRunnerUITests/RunnerTests/testCommand', + '-parallel-testing-enabled', + 'NO', + '-test-timeouts-enabled', + 'NO', + '-collect-test-diagnostics', + 'never', + resolveRunnerMaxConcurrentDestinationsFlag(input.device), + '1', + '-destination-timeout', + String(RUNNER_DESTINATION_TIMEOUT_SECONDS), + '-xctestrun', + input.xctestrunPath, + '-derivedDataPath', + input.derivedPath, + '-destination', + resolveRunnerDestination(input.device), + ], + { + allowFailure: true, + env: { ...process.env, AGENT_DEVICE_RUNNER_PORT: String(input.port) }, + detached: true, + signal: input.signal, + stdio: ['ignore', outputFd, outputFd], + captureOutput: false, + }, + ); + const logTail = tailRunnerLogFile({ + file: logFile, + onOutput: (chunk) => { + listenerReady.observe(chunk); + if (input.traceLogPath || input.verbose) { + logChunk(chunk, undefined, input.traceLogPath, input.verbose); + } + }, + }); + const endOutputObservation = once(() => { + logTail.stop(); + closeOutputFd(); + }); + const onProcessSettled = () => { + logTail.drain(); + closeOutputFd(); + listenerReady.finish(); + }; + void launched.wait.then(onProcessSettled, onProcessSettled); + return { + ...launched, + startupRetryWake: listenerReady.wake, + endOutputObservation, + readLogTail: (maxBytes) => readRunnerLogTail(logFile, maxBytes), + }; + } catch (error) { + closeOutputFd(); + throw error; + } +} + +function once(task: () => void): () => void { + let done = false; + return () => { + if (done) return; + done = true; + task(); }; - launched.child.stdout?.on('data', (chunk: string) => observeOutput('stdout', chunk)); - launched.child.stderr?.on('data', (chunk: string) => observeOutput('stderr', chunk)); - void launched.wait.then(listenerReady.finish, listenerReady.finish); - return { ...launched, startupRetryWake: listenerReady.wake }; } diff --git a/packages/platform-apple/src/runner/runner-session-types.ts b/packages/platform-apple/src/runner/runner-session-types.ts index 68a05e52b9..f599eea468 100644 --- a/packages/platform-apple/src/runner/runner-session-types.ts +++ b/packages/platform-apple/src/runner/runner-session-types.ts @@ -58,13 +58,44 @@ export type RunnerSession = { xctestrunPath: string; xctestrunArtifact?: RunnerXctestrunArtifact; jsonPath: string; + /** + * Where this runner's own output goes: the file handed to the child as its stdout/stderr, which + * the runner keeps appending to across a daemon handoff (#2681). A session adopted from an older + * lease has none, because that runner wrote into pipes its own daemon held. + */ + runnerLogPath?: string; testPromise: Promise; child: RunnerProcessHandle; + /** + * Gives up this daemon's sides of the runner's log: the tail it follows and its copy of the log's + * write end. Only a session this process launched has either. The runner keeps its own descriptor, + * so handing off is a bookkeeping step and cannot disturb a running runner (#2681). + */ + endOutputObservation?: () => void; + /** + * Reads the end of {@link runnerLogPath}. The module that opened the file answers for it, so the + * code quoting a runner's failure does not have to know how the log is stored (#2681). + */ + readLogTail?: (maxBytes: number) => string; /** Moves only through {@link advanceRunnerSessionState}. */ state: RunnerSessionState; /** Wakes one startup retry when the listener becomes ready or its process exits. */ startupRetryWake?: AbortSignal; startupTimeoutMs?: number; + /** + * Commands the runner accepted that this process has not seen answered. It comes down only when a + * response is decoded: an aborted or dropped exchange leaves the command running on the runner, + * and nothing in this process learns when that ends, so the count is what keeps such a runner off + * the handoff path (#2681). + */ + inFlightCommands: number; + /** + * Whether an exchange this process gave up on is among {@link inFlightCommands} — the sticky half + * of the occupancy report, since a cancellation or transport drop resets every live wait while the + * runner keeps working. An answered exchange forgives them (the runner is demonstrably serving + * again, and stamps any work still draining onto its reply) and clears this. + */ + hasAbandonedCommands: boolean; // Records the last allowlisted mutating interaction that the runner confirmed // healthy (parsed ok, non-runnerFatal) for a given app bundle. Lives only on // the session object so it dies with every invalidation/restart (#702). @@ -102,8 +133,8 @@ export type RunnerSession = { // so a runner cannot be revived by a late answer and a finished teardown never runs again. Both // live states reach `stopped` without a `draining` step on the graceful-shutdown handoff, where // the runner keeps serving the next daemon and this session's ownership simply ends. That handoff -// covers a session that has not answered yet: a daemon shutting down during a startup has a -// running runner and a valid lease to hand off exactly as it does for an answered one. +// covers only a `ready` session (#2681): a daemon shutting down during a startup has a runner that +// never proved it serves requests, so it is torn down by the shutdown's own stop path instead. const RUNNER_SESSION_STATE_SUCCESSORS: Record = { starting: ['ready', 'draining', 'stopped'], ready: ['draining', 'stopped'], @@ -132,6 +163,58 @@ export function canWorkWithRunnerSession(session: RunnerSessionStateHolder): boo return session.state === 'starting' || session.state === 'ready'; } +/** + * Whether the runner reported main-thread XCTest work still draining as of its last exchange + * (#2552). Retention and handoff both refuse a runner that is still draining, and both must read + * the runner's report — the lifecycle state says nothing about what the main thread is doing. + */ +export function isRunnerMainThreadOccupied( + session: Pick | undefined, +): boolean { + return session?.runnerMainThreadBusy === true; +} + +/** Why a graceful shutdown must stop this session's runner instead of handing it over. */ +export type RunnerDetachRefusal = + /** The runner never answered a command, so nothing proves it serves requests (#2681). */ + | 'runner_never_served_a_command' + /** A command is still owed a response, so the runner is busy whatever its last report says (#2681). */ + | 'command_in_flight' + /** The runner reported main-thread work still draining as of its last exchange. */ + | 'main_thread_occupied'; + +export type RunnerDetachDecision = + | { detach: true } + | { detach: false; reason: RunnerDetachRefusal }; + +/** + * Whether this session's runner may be handed to the next daemon by a graceful shutdown (#2681). + * `ready` is the only state that proves the runner serves requests: physical startup runs tens of + * seconds, so a shutdown mid-boot would otherwise hand off a runner that never reached its listener + * and make the next daemon pay a rebuild it cannot detect. A command the runner accepted without + * this process seeing an answer is refused outright — including one this process abandoned to a + * cancellation or a dropped transport, which outlives every wait this side holds. Occupancy is + * decided by the runner's own report, because a runner still draining abandoned work refuses every + * command the next daemon sends it. + */ +export function resolveRunnerDetachDecision( + session: Pick< + RunnerSession, + 'state' | 'runnerMainThreadBusy' | 'inFlightCommands' | 'hasAbandonedCommands' + >, +): RunnerDetachDecision { + if (session.state !== 'ready') { + return { detach: false, reason: 'runner_never_served_a_command' }; + } + if (session.inFlightCommands > 0 || session.hasAbandonedCommands) { + return { detach: false, reason: 'command_in_flight' }; + } + if (isRunnerMainThreadOccupied(session)) { + return { detach: false, reason: 'main_thread_occupied' }; + } + return { detach: true }; +} + /** The liveness of a registered session, read against the process probe held beside its state. */ export function resolveRunnerSessionLiveness( session: Readonly<{ state: RunnerSessionState; processRunning: boolean }>, diff --git a/packages/platform-apple/src/runner/runner-session.ts b/packages/platform-apple/src/runner/runner-session.ts index 4e1d3bf753..7c0e124cad 100644 --- a/packages/platform-apple/src/runner/runner-session.ts +++ b/packages/platform-apple/src/runner/runner-session.ts @@ -10,9 +10,14 @@ import { } from './host.ts'; import type { ExecResult } from '@agent-device/host-kit/command'; import { isApplePlatform, type DeviceInfo } from '@agent-device/kernel/device'; +import { + resolveRunnerHandoffTarget, + type RunnerHandoffLane, + type RunnerHandoffRefusal, +} from './apple-runner-platform.ts'; import type { RunnerLogicalLeaseContext } from '@agent-device/contracts/runner-lease-context'; import type { AppleRunnerLifecycleOptions } from './runner-provider.ts'; -import { getFreePort } from './runner-io.ts'; +import { flushRunnerLogAppends, getFreePort, resolveRunnerLaunchLogPath } from './runner-io.ts'; import { waitForRunner, RUNNER_STARTUP_TIMEOUT_MS } from './runner-startup-transport.ts'; import { sendRunnerCommandOnce } from './runner-transport.ts'; import { @@ -72,8 +77,11 @@ import { advanceRunnerSessionState, buildRunnerSessionId, canWorkWithRunnerSession, + isRunnerMainThreadOccupied, normalizeRunnerStartupTimeoutMs, + resolveRunnerDetachDecision, resolveRunnerSessionLiveness, + type RunnerDetachRefusal, type RunnerSession, type RunnerSessionLiveness, type RunnerSessionRegistration, @@ -239,6 +247,7 @@ async function startRunnerSessionWithLease( let simulatorSetRedirect: | Awaited> | undefined; + const runnerLogPath = resolveRunnerLaunchLogPath(options.logPath, device.id); let runnerProcess: LaunchedRunnerProcess; // One catch for everything between here and a runner that answers, because the device's own answer // belongs on all of it (#2690 review): a cold build, a warm derived cache that fails at install, and @@ -283,17 +292,25 @@ async function startRunnerSessionWithLease( message: 'Starting XCTest runner...', }); } - runnerProcess = await measureRunnerStartupStep(startupTimings, 'launch_xcodebuild', () => - launchRunnerProcess({ - device, - port, - xctestrunPath, - derivedPath: xctestrunArtifact.derived, - signal, - logPath: options.logPath, - traceLogPath: options.traceLogPath, - verbose: options.verbose, - }), + runnerProcess = await measureRunnerStartupStep( + startupTimings, + 'launch_xcodebuild', + async () => { + // Build output reaches this same file through an async append queue, so the offset that marks + // where this generation's output starts is only trustworthy once those bytes have landed below + // it; otherwise a queued build line reads as the runner's own failure output (#2681). + await flushRunnerLogAppends(runnerLogPath).catch(() => {}); + return await launchRunnerProcess({ + device, + port, + xctestrunPath, + derivedPath: xctestrunArtifact.derived, + signal, + logPath: runnerLogPath, + traceLogPath: options.traceLogPath, + verbose: options.verbose, + }); + }, ); } catch (error) { await simulatorSetRedirect?.releaseBestEffort(); @@ -307,6 +324,7 @@ async function startRunnerSessionWithLease( port, xctestrunPath, jsonPath, + runnerLogPath, }); const session: RunnerSession = { sessionId, @@ -316,9 +334,14 @@ async function startRunnerSessionWithLease( xctestrunPath, xctestrunArtifact, jsonPath, + runnerLogPath, testPromise: runnerProcess.wait, child: runnerProcess.child, + endOutputObservation: runnerProcess.endOutputObservation, + readLogTail: runnerProcess.readLogTail, state: 'starting', + inFlightCommands: 0, + hasAbandonedCommands: false, startupRetryWake: runnerProcess.startupRetryWake, startupTimeoutMs: normalizeRunnerStartupTimeoutMs(startupTimeoutMs), startupTimings, @@ -664,7 +687,8 @@ export async function releaseIosRunnerOnClose( deviceId: string, options: { retain: boolean }, ): Promise { - if (options.retain && runnerSessions.get(deviceId)?.runnerMainThreadBusy !== true) { + const session = runnerSessions.get(deviceId); + if (options.retain && !isRunnerMainThreadOccupied(session)) { scheduleIosRunnerIdleStop(deviceId); return; } @@ -688,48 +712,111 @@ export async function abortAllIosRunnerSessions(): Promise { } } -// Graceful daemon shutdown hands healthy simulator runners off to the next -// daemon instead of paying the ~5s xcodebuild ramp again: the lease token is -// rewritten to a detached form (so this daemon's own teardown paths no longer -// classify it as owned) and the session simply leaves the in-memory map. Once -// this process exits the lease is stale and the adoption path picks it up. -// Explicit cleanup still works: clean:daemon kills by the lease's runnerPid, -// and the runner's XCTWaiter self-expires after 24h. -export async function detachIosSimulatorRunnerSessionsForShutdown(): Promise { +type RunnerDetachSkippedReason = + | RunnerHandoffRefusal + | RunnerDetachRefusal + | 'simulator_set_redirect' + | 'lease_absent' + | 'runner_process_dead' + | 'lease_write_failed'; + +// Graceful daemon shutdown hands a request-proven runner off to the next daemon instead of paying +// the xcodebuild ramp again: the lease token is rewritten to a detached form (so this daemon's own +// teardown paths no longer classify it as owned), this process gives up its sides of the runner's +// log, and the session simply leaves the in-memory map. Once this process exits the lease is stale +// and the adoption path picks it up. Explicit cleanup still works: clean:daemon kills by the lease's +// runnerPid, and the runner's XCTWaiter self-expires after 24h. +// +// Every gate that keeps a session on the kill path is named and reported, because a handoff that +// silently declines is indistinguishable from a rebuild: the handoff lanes +// (`resolveRunnerHandoffTarget`), a session that never served a command, still owes a response, or +// last reported main-thread work still draining (`resolveRunnerDetachDecision`), a scoped +// simulator-set redirect, a missing or unwritable lease, and a runner this process cannot prove +// alive. What stays in the map is torn down by `stopAllIosRunnerSessions`, which the daemon's +// shutdown runs right after this — so a shutdown during a startup tears that runner down rather than +// handing off one that never reached its listener (#2681). +export async function detachIosRunnerSessionsForShutdown(): Promise { if (!isIosRunnerDetachEnabled()) return 0; let detached = 0; for (const [deviceId, session] of runnerSessions) { - if (session.device.kind !== 'simulator') continue; - // CONSERVATIVE: Scoped simulator sets depend on the global XCTestDevices symlink for their - // whole runner lifetime; handoff could restore the symlink under a live runner or leak the - // redirect lock. Revisit only if simulator-set redirects become runner-owned instead of - // daemon-session-owned. - if (session.simulatorSetRedirect) continue; - if (!session.lease || !isRunnerProcessAlive(session.child.pid)) continue; - if (!canWorkWithRunnerSession(session)) continue; - try { - writeRunnerLease(buildDetachedRunnerLease(session.lease)); - } catch { - continue; // Could not mark the handoff; leave it for the kill path. + const outcome = detachRunnerSessionForShutdown(deviceId, session); + if (!outcome.detached) { + emitDiagnostic({ + level: 'debug', + phase: 'ios_runner_session_detach_skipped', + data: { + deviceId, + sessionId: session.sessionId, + lane: outcome.lane, + reason: outcome.reason, + }, + }); + continue; } - runnerSessions.delete(deviceId); - cancelIosRunnerIdleStop(deviceId); - advanceRunnerSessionState(session, 'stopped'); detached += 1; emitDiagnostic({ level: 'info', phase: 'ios_runner_session_detached', data: { deviceId, + lane: outcome.lane, sessionId: session.sessionId, runnerPid: session.child.pid, port: session.port, + runnerLogPath: session.runnerLogPath, }, }); } return detached; } +type RunnerDetachOutcome = + | { detached: true; lane: RunnerHandoffLane } + | { detached: false; lane: RunnerHandoffLane | undefined; reason: RunnerDetachSkippedReason }; + +function detachRunnerSessionForShutdown( + deviceId: string, + session: RunnerSession, +): RunnerDetachOutcome { + const target = resolveRunnerHandoffTarget(session.device); + if (!target.handoff) { + return { detached: false, lane: undefined, reason: target.reason }; + } + const lane = target.lane; + // CONSERVATIVE: Scoped simulator sets depend on the global XCTestDevices symlink for their + // whole runner lifetime; handoff could restore the symlink under a live runner or leak the + // redirect lock. Reachable only in the simulator lane — `acquireXcodebuildSimulatorSetRedirect` + // returns no handle for any non-simulator — so a physical handoff never waits on it. + if (session.simulatorSetRedirect) { + return { detached: false, lane, reason: 'simulator_set_redirect' }; + } + const decision = resolveRunnerDetachDecision(session); + if (!decision.detach) { + return { detached: false, lane, reason: decision.reason }; + } + const lease = session.lease; + if (!lease) { + return { detached: false, lane, reason: 'lease_absent' }; + } + if (!isRunnerProcessAlive(session.child.pid)) { + return { detached: false, lane, reason: 'runner_process_dead' }; + } + try { + writeRunnerLease(buildDetachedRunnerLease(lease)); + } catch { + return { detached: false, lane, reason: 'lease_write_failed' }; + } + // Only once the lease says the runner is handed over does this process give up its own sides of + // the runner's log: until that write lands the session is still owned, and an owned session that + // stopped following its runner's output is worse off than one that never handed anything off. + // The runner holds its own descriptor, so this cannot disturb it either way (#2681). + session.endOutputObservation?.(); + runnerSessions.delete(deviceId); + cancelIosRunnerIdleStop(deviceId); + advanceRunnerSessionState(session, 'stopped'); + return { detached: true, lane }; +} + export async function stopAllIosRunnerSessions(): Promise { await abortAllIosRunnerSessions(); const pending = Array.from(runnerSessions.keys()); @@ -777,6 +864,12 @@ export function validateRunnerDevice(device: DeviceInfo): void { } } +/** + * Runs one command through a session. The command send charges the session and only a decoded + * response discharges it: an exchange this process abandoned to a cancellation or a dropped + * transport keeps the runner occupied, which is what a graceful shutdown reads before handing it to + * the next daemon (#2681). The readiness preflight's own `uptime` probe is not charged. + */ export async function executeRunnerCommandWithSession( device: DeviceInfo, session: RunnerSession, @@ -829,6 +922,7 @@ export async function executeRunnerCommandWithSession( } try { const data = await parseRunnerResponse(response, session, logAttempt); + settleRunnerCommandAnswered(session); // Mirror the runner's own main-thread occupancy stamped on this response: a runner that // served a read off the XCTest channel (e.g. a private-AX capture) while a tree crawl it // abandoned still grinds reports busy, so the healthy response must not be read as drained. @@ -850,6 +944,9 @@ export async function executeRunnerCommandWithSession( } return data; } catch (error) { + // A structured runner reply is an answer whatever it reports; a transport-shaped failure + // (aborted body read, malformed payload) answered nothing and keeps the runner charged (#2681). + settleRunnerCommandExchange(session, error); // A main-thread occupancy report (`RUNNER_BUSY`, or the `MAIN_THREAD_TIMEOUT` the stalling // command itself returns) marks the runner still draining. Any OTHER structured runner reply was // served off that abandoned work, so it has drained; a transport-shaped error answered nothing @@ -927,24 +1024,68 @@ async function sendRunnerCommandAfterPreflight(params: { } : { command: runnerCommand.command, commandId: runnerCommand.commandId }; - return await withDiagnosticTimer( - 'ios_runner_command_send', - async () => { - if (readOnlyCommand) { - return await waitForRunner( + // From here the runner holds our request, and a shutdown that hands it off would orphan a command + // nobody is waiting for any more. The charge is released only where a response is decoded, so a + // cancellation or transport drop leaves the occupancy it really created (#2681). + session.inFlightCommands += 1; + try { + return await withDiagnosticTimer( + 'ios_runner_command_send', + async () => { + if (readOnlyCommand) { + return await waitForRunner( + device, + session.port, + runnerCommand, + logPath, + remainingMs, + session, + signal, + ); + } + return await sendRunnerCommandOnce( device, session.port, runnerCommand, - logPath, remainingMs, - session, signal, ); - } - return await sendRunnerCommandOnce(device, session.port, runnerCommand, remainingMs, signal); - }, - diagnosticData, - ); + }, + diagnosticData, + ); + } catch (error) { + markRunnerCommandAbandoned(session); + throw error; + } +} + +/** + * The runner answered this exchange, so it is serving again: this command is answered, and so is the + * abandoned charge an earlier cancellation left behind — work still draining is stamped on this very + * reply (#2552, #2681). A run of abandoned exchanges leaves one residue charge per extra exchange, + * which keeps such a runner on the kill path rather than guessing it drained. + */ +function settleRunnerCommandAnswered(session: RunnerSession): void { + const abandonedCharge = session.hasAbandonedCommands ? 1 : 0; + session.inFlightCommands = Math.max(0, session.inFlightCommands - 1 - abandonedCharge); + session.hasAbandonedCommands = false; +} + +/** + * This process stopped waiting without ever seeing an answer. The command may still be executing on + * the runner, so its occupancy stays charged: only an answered exchange clears it (#2681). + */ +function markRunnerCommandAbandoned(session: RunnerSession): void { + session.hasAbandonedCommands = true; +} + +/** + * Settles the charge for an exchange that ended outside the success path. A structured runner reply + * answers even when it reports a failure; a transport-shaped one answers nothing (#2681). + */ +function settleRunnerCommandExchange(session: RunnerSession, error: unknown): void { + if (isStructuredRunnerFailure(error)) settleRunnerCommandAnswered(session); + else markRunnerCommandAbandoned(session); } async function runRunnerReadinessPreflight(params: { diff --git a/src/__tests__/platform-runtime-apple-application-tools.test.ts b/src/__tests__/platform-runtime-apple-application-tools.test.ts index 0d8cdefb28..cde2397032 100644 --- a/src/__tests__/platform-runtime-apple-application-tools.test.ts +++ b/src/__tests__/platform-runtime-apple-application-tools.test.ts @@ -1,7 +1,7 @@ import { expect, test, vi } from 'vitest'; import { createAppleApplicationTools } from '../platform-runtime-apple-application-tools.ts'; -const detachIosSimulatorRunnerSessionsForShutdown = vi.hoisted(() => vi.fn(async () => 0)); +const detachIosRunnerSessionsForShutdown = vi.hoisted(() => vi.fn(async () => 0)); const stopAllIosRunnerSessions = vi.hoisted(() => vi.fn(async () => {})); // The factory awaits the real Apple runner graph on purpose: that wait is what let a second, @@ -10,7 +10,7 @@ const stopAllIosRunnerSessions = vi.hoisted(() => vi.fn(async () => {})); vi.mock('@agent-device/platform-apple/runner/operations', async (importOriginal) => { const actual = await importOriginal(); - return { ...actual, detachIosSimulatorRunnerSessionsForShutdown, stopAllIosRunnerSessions }; + return { ...actual, detachIosRunnerSessionsForShutdown, stopAllIosRunnerSessions }; }); // Two ports of these tools run at once whenever the open path leaves its runner prewarm @@ -26,6 +26,6 @@ test('concurrent runner ports share one module resolution, so the mock always ap tools.finalizeRunnerSessionsForShutdown(), ]); - expect(detachIosSimulatorRunnerSessionsForShutdown).toHaveBeenCalledTimes(1); + expect(detachIosRunnerSessionsForShutdown).toHaveBeenCalledTimes(1); expect(stopAllIosRunnerSessions).toHaveBeenCalledTimes(1); }); diff --git a/src/daemon/__tests__/request-router-open-claim.test.ts b/src/daemon/__tests__/request-router-open-claim.test.ts index c2f0de2d8e..516c7e1725 100644 --- a/src/daemon/__tests__/request-router-open-claim.test.ts +++ b/src/daemon/__tests__/request-router-open-claim.test.ts @@ -16,7 +16,7 @@ vi.mock('@agent-device/platform-apple/runner/operations', async (importOriginal) await importOriginal(); return { ...actual, - detachIosSimulatorRunnerSessionsForShutdown: vi.fn(async () => {}), + detachIosRunnerSessionsForShutdown: vi.fn(async () => {}), notifyIosRunnerAppRelaunched: vi.fn(async () => {}), prewarmAppleRunnerCache: vi.fn(async () => {}), prewarmIosRunner: vi.fn(async () => {}), diff --git a/src/daemon/__tests__/request-router-open.test.ts b/src/daemon/__tests__/request-router-open.test.ts index 3c946449fb..7f874b492e 100644 --- a/src/daemon/__tests__/request-router-open.test.ts +++ b/src/daemon/__tests__/request-router-open.test.ts @@ -29,7 +29,7 @@ vi.mock('@agent-device/platform-apple/runner/operations', async (importOriginal) await importOriginal(); return { ...actual, - detachIosSimulatorRunnerSessionsForShutdown: vi.fn(async () => {}), + detachIosRunnerSessionsForShutdown: vi.fn(async () => {}), notifyIosRunnerAppRelaunched: vi.fn(async () => {}), prewarmAppleRunnerCache: vi.fn(async () => {}), prewarmIosRunnerSession: vi.fn(async () => {}), diff --git a/src/daemon/server/daemon-idle-reap.ts b/src/daemon/server/daemon-idle-reap.ts index a3300f8d46..1b35ba5a46 100644 --- a/src/daemon/server/daemon-idle-reap.ts +++ b/src/daemon/server/daemon-idle-reap.ts @@ -13,11 +13,11 @@ import { isUncommittedRepairSession } from '../session-replay-transaction.ts'; // // The window mirrors the iOS runner idle-stop default // (AGENT_DEVICE_IOS_RUNNER_IDLE_STOP_MS, 5 minutes, see runner-session.ts): -// graceful daemon shutdown already hands off a healthy retained simulator -// runner for the next daemon to adopt (detachIosSimulatorRunnerSessionsForShutdown), -// so reaping the daemon process itself on the same timescale does not force a -// runner rebuild in the common case - it only pays the cheap daemon -// bootstrap (socket/HTTP listen) on the next command. +// graceful daemon shutdown already hands off a healthy retained runner - +// simulator or physical iOS - for the next daemon to adopt +// (detachIosRunnerSessionsForShutdown), so reaping the daemon process itself on +// the same timescale does not force a runner rebuild in the common case - it +// only pays the cheap daemon bootstrap (socket/HTTP listen) on the next command. const DAEMON_IDLE_REAP_DEFAULT_MS = 5 * 60_000; // AGENT_DEVICE_DAEMON_IDLE_TIMEOUT_MS overrides the window; 0 disables idle diff --git a/src/daemon/server/daemon-runtime-lifecycle-shutdown.test.ts b/src/daemon/server/daemon-runtime-lifecycle-shutdown.test.ts index bc1ece564a..5863da1a48 100644 --- a/src/daemon/server/daemon-runtime-lifecycle-shutdown.test.ts +++ b/src/daemon/server/daemon-runtime-lifecycle-shutdown.test.ts @@ -1,4 +1,5 @@ import fs from 'node:fs'; +import path from 'node:path'; import { afterEach, expect, test, vi } from 'vitest'; import { mkdtempForTestSync } from '../../__tests__/test-utils/tmp-dir.ts'; @@ -14,6 +15,14 @@ vi.mock('../../platform-runtime.ts', () => ({ recoverStartupResources: async () => {}, detachForDaemonShutdown: async () => { lifecycleEvents.push('detach'); + // The real diagnostics module, unmocked: what this records is whether a diagnostic raised by + // the handoff reaches disk at all, which only the shutdown's own scope can decide (#2681). + const { emitDiagnostic } = await import('@agent-device/host-kit/diagnostics'); + emitDiagnostic({ + level: 'debug', + phase: 'detach_scope_probe', + data: { lane: 'physical_coredevice' }, + }); }, finalizeDaemonShutdown: async () => { lifecycleEvents.push('finalize'); @@ -70,3 +79,32 @@ test('daemon shutdown detaches before session teardown and force-finalizes only fs.rmSync(stateDir, { recursive: true, force: true }); } }); + +test('a SIGTERM shutdown gives the handoff a diagnostics scope to write its reasons into', async () => { + // Without the scope, `emitDiagnostic` is a no-op outside a request and every detach reason — + // including "why did this runner get killed instead of handed off" — disappears with the daemon. + const stateDir = mkdtempForTestSync('agent-device-daemon-detach-diagnostics-'); + try { + const runtime = await startDaemonRuntime({ + env: { + ...process.env, + AGENT_DEVICE_STATE_DIR: stateDir, + AGENT_DEVICE_DAEMON_IDLE_TIMEOUT_MS: '0', + AGENT_DEVICE_DAEMON_SERVER_MODE: 'http', + }, + exit: () => {}, + registerProcessHandlers: false, + stderr: { write: () => {} }, + stdout: { write: () => {} }, + }); + expect(runtime).not.toBeNull(); + + await runtime?.shutdown(); + + const daemonLog = fs.readFileSync(path.join(stateDir, 'daemon.log'), 'utf8'); + expect(daemonLog).toMatch(/"phase":"detach_scope_probe"/); + expect(daemonLog).toMatch(/"lane":"physical_coredevice"/); + } finally { + fs.rmSync(stateDir, { recursive: true, force: true }); + } +}); diff --git a/src/daemon/server/daemon-runtime.ts b/src/daemon/server/daemon-runtime.ts index 1f725b560a..72b7a4d50d 100644 --- a/src/daemon/server/daemon-runtime.ts +++ b/src/daemon/server/daemon-runtime.ts @@ -587,10 +587,21 @@ export async function startDaemonRuntime( await emitFatalDiagnostic(shutdownOptions.cause); } await closeDaemonServers(servers); - // Hand healthy simulator runners off before durable session teardown. The lifecycle gateway - // later terminates only still-owned generations once all resources have finalized. + // Hand healthy runners off before durable session teardown. The lifecycle gateway later + // terminates only still-owned generations once all resources have finalized. + // + // The scope is what makes this step observable: a SIGTERM shutdown has no request, and therefore + // no diagnostics scope, so `emitDiagnostic` would drop every detach reason. Daemon debug level is + // forced on here because the declines are the point of the record — a handoff that silently + // skipped is indistinguishable from a rebuild (#2681). try { - await applicationLifecycle.detachForDaemonShutdown(); + await withDiagnosticsScope( + { command: 'daemon', session: 'daemon', logPath, debug: true }, + async () => { + await applicationLifecycle.detachForDaemonShutdown(); + flushDiagnosticsToSessionFile({ force: true }); + }, + ); } catch {} expiredProviderLeaseReleaser.beginShutdown(); await teardownDaemonSessions(); diff --git a/src/platform-runtime-apple-application-tools.ts b/src/platform-runtime-apple-application-tools.ts index c69b1e6cd5..35985fe3b0 100644 --- a/src/platform-runtime-apple-application-tools.ts +++ b/src/platform-runtime-apple-application-tools.ts @@ -113,8 +113,8 @@ export function createAppleApplicationTools(): AppleApplicationTools { }, dismissCloseAlerts: async (device, input) => await dismissMacOsCloseAlerts(device, input), detachRunnerSessionsForShutdown: async () => { - const { detachIosSimulatorRunnerSessionsForShutdown } = await loadRunnerOperations(); - await detachIosSimulatorRunnerSessionsForShutdown(); + const { detachIosRunnerSessionsForShutdown } = await loadRunnerOperations(); + await detachIosRunnerSessionsForShutdown(); }, finalizeRunnerSessionsForShutdown: async () => { const { stopAllIosRunnerSessions } = await loadRunnerOperations();