Skip to content

fix(logs): keep an early iOS simulator logs stop from hanging the session - #3892

Merged
thymikee merged 4 commits into
mainfrom
fix/ios-sim-logs-stop-hang
Oct 22, 2026
Merged

thymikee merged 4 commits into
mainfrom
fix/ios-sim-logs-stop-hang

Conversation

@thymikee

@thymikee thymikee commented Oct 22, 2026 •

Copy link
Copy Markdown
Member

Summary

On an Apple simulator, a logs stop sent ~400 ms after logs start could hang the session (found by #3885).

Root cause: simctl spawn … log stream forwards a stop signal only after the in-simulator log process has launched. An earlier SIGINT ended simctl, and the orphaned log process kept the output pipes open, so the managed app-log wait never settled.

  • Simulator logs start returns once the stream writes output. If that takes more than 10 s, it fails with details.reason: "simulator-log-stream-launch-timeout".
  • Managed app-log termination now releases pipes that a process outside the child's tree still holds.

6 files plus a commands.md note.

Validation

Head 872985b93d.

  • New tests fail on base. Removing the stream release fails the real-process test.
  • Live at 872985b93d (iOS 27.0 sim, Xcode 27.1, host load 380–930 on 12 cores), see this comment:
    • start → 400 ms → stop → appstate: 24 runs. Stop never hung: 0.8 / 1.8 / 6.2 s (min/median/max). 0 in-sim and 0 host leftovers.
    • 1/24 starts hit the 10 s launch timeout. It failed with the typed reason and left the session clean.
    • Mid-launch cancels: 8 runs, 0 leftovers, session continued.
  • Earlier, at 0d3c327, base b74fcebdc1 hung 2 times in 10 runs.
  • check:affected --run --head 872985b93d: format, lint, and typecheck passed. Vitest passed 1299/1300. Its one failure (apple-platform-output-guard record timeout) also fails on main e3ed027a1d at load ~900. CI Integration Tests passes.

🤖 Generated with Claude Code

@github-actions

github-actions Bot commented Oct 22, 2026 •

Copy link
Copy Markdown
Contributor

Size Report

Metric Base Current Diff
Installed (including dependencies) 5.53 MB 5.54 MB +926 B
Package (unpacked) 5.53 MB 5.54 MB +926 B
Package (download) 1.68 MB 1.68 MB +375 B

Startup median (7 runs, lower is better):

Scenario Base Current Diff
CLI --version 40.8 ms 41.0 ms +0.3 ms
CLI --help 81.9 ms 84.7 ms +2.8 ms

@github-actions

github-actions Bot commented Oct 22, 2026 •

Copy link
Copy Markdown
Contributor
PR Preview Action v1.8.1
Preview removed because the pull request was closed.
2026-10-22 09:42 UTC

thymikee and others added 2 commits October 22, 2026 07:06
…sion

`xcrun simctl spawn` forwards a stop signal to the in-simulator `log stream`
only after the launch completes. A `logs stop` sent during the launch ended
simctl, the orphaned stream kept the output pipes open, and the managed wait
never settled, so the stop and every later session request hung.

Simulator `logs start` now returns once the stream writes its first output,
and managed app-log termination releases output pipes that a process outside
the child's tree still holds after the child exits.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
A simulator log stream that never writes output now fails logs start with
reason simulator-log-stream-launch-timeout after 10 s instead of holding the
session until the client envelope resets the daemon. The process-host test
double now models a child that exits while a descendant keeps its pipes.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@thymikee
thymikee force-pushed the fix/ios-sim-logs-stop-hang branch from 0d3c327 to 5f9f5f2 Compare October 22, 2026 05:07
@thymikee

Copy link
Copy Markdown
Member Author

I rebased this onto main and force-pushed it (5f9f5f2). The branch had been cut from #3881's head, so it carried #3881's six commits. That's why the size report showed −5.1 kB. The two logs commits are unchanged. The related logs tests pass after the rebase (54/54).

@thymikee

Copy link
Copy Markdown
Member Author

The fix looks correct at 5f9f5f2. I found nothing that needs a change before merge, but the live evidence is still short of what I can confirm. The reported live runs were at 0d3c327, and I could not confirm they match the rebased patch. No run artifacts are linked. Please link them, or rerun on 5f9f5f2 and show that an early logs stop on an iOS simulator returns promptly and leaves no hung session.

I did not run the tests. I judged that they fail on the base by reading the base code paths. The escaped-descendant test mocks exec.run with a hand-built wait and does not go through runCmdBackground. So only the live run supports the claim that destroying the stdio sockets fires Node's close. The readiness gate also relies on log stream --style compact printing its "Filtering the log data" header promptly. I did not check this on every Xcode version. A predicate stream that prints nothing would hit the 10 s timeout.

Not blocking: host-kit already owns the rule that a killed command settles when its direct child exits, in createCommandKillSettlement, while the managed host kills the child directly and adds a timer-based stream destroy beside it. Also, the docs line at commands.md:1065 says "On iOS simulators", but the gate in start.ts covers every Apple simulator, so "Apple simulators" is more accurate. You can take or leave both.

Could the readiness gate in start.ts stay as it is, and termination abort a per-process AbortController passed to runCmdBackground with kill {signal: 'SIGINT', graceMs: 2000}? The existing kill settlement would then settle the wait on simctl's exit and destroy the streams. That would remove the second 2 s window and the hand-rolled destroy, and stop would settle when the child exits instead of after a fixed 4 s. An abort-settled background wait rejects with a request-cancelled error today (exec.ts:768). So host-kit would first need a terminate path that resolves with the exit result, or the managed host would need to map its own abort to a resolved exit, before finish() can await it without reporting cleanup-pending. Please answer this, or explain why the current approach is better.

Lint, Typecheck & Package fails on the line cap in packages/platform-apple/src/snapshot-route.test.ts:1003. That failure is on main (#3890), and this PR does not touch that file or the snapshot route, so it looks unrelated. Rebase once #3890 lands. I know of no conflicts. Before merge, the live evidence above and the answer on the host-kit reuse question are the remaining items.

thymikee and others added 2 commits October 22, 2026 10:08
* origin/main:
  feat(test-app): add a Bluesky-depth heavy feed screen (#3884)
  fix(android): read a child that vanished mid-read as gone (#3901)
  feat(ios): route iPad Simulator snapshots through the host AX bridge (#3895)
…log host

Drive the escaped-descendant termination test through the real
runCmdBackground with a shell whose background loop keeps the inherited
pipes open, so it exercises Node's close on stream release. Name the
simulator gate after every Apple simulator in the docs and error text.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@thymikee

Copy link
Copy Markdown
Member Author

Follow-up for the 2026-10-22 review. Head is now 872985b93d: 5f9f5f2 merged with origin/main (edb34803a6), plus test(logs): settle a real escaped descendant…. The only production edit since 5f9f5f2 is the timeout message text.

1. Live evidence at 872985b93d

Setup: own iPhone 17 Pro simulator, iOS 27.0, Xcode 27.1 (27A9275), com.apple.Preferences session, isolated --state-dir. Each run did logs start, waited 400 ms, ran logs stop, then appstate, each under a 30 s deadline. After each run I counted log stream --style compact processes under this simulator's launchd_sim, and simctl spawn <udid> log stream processes on the host. Host load average was 380–930 on 12 cores during the runs, so the times are inflated and include CLI startup.

Scenario Runs Result
start → 400 ms → stop → appstate 24 23/24 clean. Stop exit 0 every time: 766 / 1761 / 6204 ms (min/median/max). Next command exit 0: 592 / 1220 / 4950 ms. No hang. 0 in-sim and 0 host leftovers after every run.
↳ run 21 1 logs start hit the 10 s launch deadline (13.6 s wall clock at load ~500). It returned details.reason: "simulator-log-stream-launch-timeout" and rolled back with 0/0 leftovers. logs stop correctly said no app log stream active, and the session continued.
logs start client killed after 300 ms–4 s 8 6 reached the daemon and ended request canceled 0.2–2.5 s into the request. The other 2 were killed before the client sent the request. The next appstate passed 8/8. Leftovers were 0/0 right after it, 0/0 6 s later, and 0/0 after a follow-up start/stop.
↳ follow-up logs start 8 6/8 OK. 2 failed on xcrun simctl get_app_container timing out after 4000 ms. That is the existing app-container lookup at load ~900, before the stream launches, and this PR does not touch it.

Request logs are kept only for failed requests. All 12 (the timeout, the 6 cancels, the 3 no app log stream active, the 2 get_app_container timeouts) agree with the table. The raw per-run summaries are below.

Readiness signal and quiet predicates. On Xcode 27.1 / iOS 27.0, the first bytes from the in-simulator log are a stderr line, getpwuid_r did not find a match for uid 501, followed by the Filtering the log data using … header on stdout. Both come from the launched in-simulator process, and the gate accepts the first write on either stream. Neither line depends on a predicate match. With a predicate that never matches (subsystem == "dev.agent-device.never-logs"), the first byte arrived in 1.0–5.6 s over 5 runs, so a quiet stream does not hit the 10 s timeout. The remaining risk is host load: at load ~500 on 12 cores, 1 of 24 launches took more than 10 s. That failure is typed and clean. I left the deadline at 10 s. If you want more headroom on loaded hosts, I can raise it.

2. Host-kit kill settlement

I kept the current approach. Concretely:

  • The managed host terminates children that host-kit did not launch. createManagedAppLogProcesses is also the Android provider transport (src/platform-runtime-app-log-android-transport.ts). That transport passes the launch signal to a provider spawn, and the provider decides what abort means there: AndroidAdbSpawnOptions has no kill or grace contract. Its wait also settles on close. If termination aborted a per-process controller, the local launcher would settle through createCommandKillSettlement, but provider children would still need child.kill. That would give the managed host two termination owners, or need a new public provider contract.
  • In host-kit, abort means cancel. An aborted background wait rejects with request-cancelled and drops the exit result (exec.ts:768). To use it, host-kit would need a new terminate path that resolves with the exit, or the managed host would need to rebuild an exit result from child state behind a typed cancel check. Either one is more code than the 6-line fallback here, which uses the kill/stdout/stderr surface that every launcher already provides.
  • The fixed 4 s applies only when something outside the child's tree still holds the pipes after the child exits. With the readiness gate, that is only a start cancelled mid-launch. A normal stop settles on close, as the stop times above show. The cancel runs above all finished with 0 leftovers.

On test fidelity: I replaced the hand-built-wait test. The new test goes through the real runCmdBackground. It runs sh -c '(while echo tick; do sleep 0.1; done) & exec sleep 30', where SIGINT reaches only the direct child and the background loop keeps the inherited pipes open. Removing the two destroy() calls makes it fail (terminated stays false). With the fix, Node emits close, the wait resolves, the marker is cleared, and the loop dies on SIGPIPE, the same way the in-simulator log does. It uses fake setTimeout, so it takes no wall-clock seconds. 5/5 local file runs passed.

3. Docs: applied. The line now says "On Apple simulators". I also renamed the timeout message from "iOS simulator log stream…" to "Simulator log stream…" for the same reason.

Validation: pnpm check:affected --run --head 872985b93d (exactCommit) ran format, lint, typecheck, and the related vitest suite. Vitest passed 1299/1300. The one failure is provider-scenarios/apple-platform-output-guard.test.ts (Command "record" did not return within 20s). It reproduced solo on this head, and identically on unchanged origin/main e3ed027a1d in an isolated checkout, at host load ~900. So it is base-blocked locally and not caused by this PR. CI's Integration Tests job passes at 872985b93d.

Raw per-run summary: start → 400 ms → stop → appstate (24 runs)
head 872985b93d9cc96399c338a15500b3a562071cbf
run=1 start_exit=0 start_ms=3639 stop_exit=0 stop_ms=928 next_exit=0 next_ms=937 leftover(in-sim/host)=0/0
run=2 start_exit=0 start_ms=8222 stop_exit=0 stop_ms=4736 next_exit=0 next_ms=2543 leftover(in-sim/host)=0/0
run=3 start_exit=0 start_ms=4429 stop_exit=0 stop_ms=1398 next_exit=0 next_ms=592 leftover(in-sim/host)=0/0
run=4 start_exit=0 start_ms=2776 stop_exit=0 stop_ms=2863 next_exit=0 next_ms=1045 leftover(in-sim/host)=0/0
run=5 start_exit=0 start_ms=5373 stop_exit=0 stop_ms=2198 next_exit=0 next_ms=1120 leftover(in-sim/host)=0/0
run=6 start_exit=0 start_ms=3692 stop_exit=0 stop_ms=1084 next_exit=0 next_ms=1728 leftover(in-sim/host)=0/0
run=7 start_exit=0 start_ms=2976 stop_exit=0 stop_ms=827 next_exit=0 next_ms=1862 leftover(in-sim/host)=0/0
run=8 start_exit=0 start_ms=3056 stop_exit=0 stop_ms=1308 next_exit=0 next_ms=1503 leftover(in-sim/host)=0/0
run=9 start_exit=0 start_ms=2802 stop_exit=0 stop_ms=1761 next_exit=0 next_ms=988 leftover(in-sim/host)=0/0
run=10 start_exit=0 start_ms=4720 stop_exit=0 stop_ms=1146 next_exit=0 next_ms=1061 leftover(in-sim/host)=0/0
run=11 start_exit=0 start_ms=1914 stop_exit=0 stop_ms=1722 next_exit=0 next_ms=621 leftover(in-sim/host)=0/0
run=12 start_exit=0 start_ms=1994 stop_exit=0 stop_ms=1568 next_exit=0 next_ms=626 leftover(in-sim/host)=0/0
run=13 start_exit=0 start_ms=8096 stop_exit=0 stop_ms=1922 next_exit=0 next_ms=1673 leftover(in-sim/host)=0/0
run=14 start_exit=0 start_ms=6364 stop_exit=0 stop_ms=2907 next_exit=0 next_ms=1489 leftover(in-sim/host)=0/0
run=15 start_exit=0 start_ms=12084 stop_exit=0 stop_ms=4155 next_exit=0 next_ms=2638 leftover(in-sim/host)=0/0
run=16 start_exit=0 start_ms=6031 stop_exit=0 stop_ms=2968 next_exit=0 next_ms=1091 leftover(in-sim/host)=0/0
run=17 start_exit=0 start_ms=6483 stop_exit=0 stop_ms=766 next_exit=0 next_ms=961 leftover(in-sim/host)=0/0
run=18 start_exit=0 start_ms=5168 stop_exit=0 stop_ms=4753 next_exit=0 next_ms=3528 leftover(in-sim/host)=0/0
run=19 start_exit=0 start_ms=10767 stop_exit=0 stop_ms=6204 next_exit=0 next_ms=4950 leftover(in-sim/host)=0/0
run=20 start_exit=0 start_ms=11441 stop_exit=0 stop_ms=3879 next_exit=0 next_ms=1269 leftover(in-sim/host)=0/0
run=21 start_exit=1 start_ms=13556 stop_exit=1 stop_ms=3420 next_exit=0 next_ms=2550 leftover(in-sim/host)=0/0
run=22 start_exit=0 start_ms=6471 stop_exit=0 stop_ms=2531 next_exit=0 next_ms=1167 leftover(in-sim/host)=0/0
run=23 start_exit=0 start_ms=3139 stop_exit=0 stop_ms=934 next_exit=0 next_ms=1220 leftover(in-sim/host)=0/0
run=24 start_exit=0 start_ms=8647 stop_exit=0 stop_ms=1598 next_exit=0 next_ms=1258 leftover(in-sim/host)=0/0

leftover(in-sim/host) counts log stream --style compact children of this simulator's launchd_sim, then host simctl spawn <udid> log stream processes.

Raw per-run summary: mid-launch cancels (client killed after delay_ms)
head 872985b93d9cc96399c338a15500b3a562071cbf
cancel=1 delay_ms=300 start_exit=143 next_exit=0 next_ms=1557 leftover_after_next=0/0 leftover_after_6s=0/0 restart_exit=0 restart_ms=1788 restop_exit=0 leftover_end=0/0
cancel=2 delay_ms=600 start_exit=143 next_exit=0 next_ms=393 leftover_after_next=0/0 leftover_after_6s=0/0 restart_exit=0 restart_ms=10314 restop_exit=0 leftover_end=0/0
cancel=3 delay_ms=900 start_exit=143 next_exit=0 next_ms=719 leftover_after_next=0/0 leftover_after_6s=0/0 restart_exit=1 restart_ms=10070 restop_exit=1 leftover_end=0/0
cancel=4 delay_ms=1200 start_exit=143 next_exit=0 next_ms=4867 leftover_after_next=0/0 leftover_after_6s=0/0 restart_exit=0 restart_ms=6031 restop_exit=0 leftover_end=0/0
cancel=5 delay_ms=1600 start_exit=143 next_exit=0 next_ms=748 leftover_after_next=0/0 leftover_after_6s=0/0 restart_exit=0 restart_ms=10589 restop_exit=0 leftover_end=0/0
cancel=6 delay_ms=2200 start_exit=143 next_exit=0 next_ms=552 leftover_after_next=0/0 leftover_after_6s=0/0 restart_exit=1 restart_ms=5775 restop_exit=1 leftover_end=0/0
cancel=7 delay_ms=3000 start_exit=143 next_exit=0 next_ms=2427 leftover_after_next=0/0 leftover_after_6s=0/0 restart_exit=0 restart_ms=2122 restop_exit=0 leftover_end=0/0
cancel=8 delay_ms=4000 start_exit=143 next_exit=0 next_ms=859 leftover_after_next=0/0 leftover_after_6s=0/0 restart_exit=0 restart_ms=1635 restop_exit=0 leftover_end=0/0

Exit 143 means the harness killed the client with SIGTERM. Restart exit 1 in runs 3 and 6 is xcrun simctl get_app_container … timed out after 4000ms.

Run 21 launch-timeout response
{"code":"COMMAND_FAILED","message":"Simulator log stream did not start within 10000ms","hint":"Check that the simulator finished booting, then retry logs start.","details":{"reason":"simulator-log-stream-launch-timeout","timeoutMs":10000}}

Request log: request_start at 08:31:46.791Z, request_failed at 08:31:58.056Z.

@thymikee

Copy link
Copy Markdown
Member Author

The findings from the earlier review are fixed at 872985b, and I found no new problems in the code. I did not run the new escaped-descendant test or any other test. I judged it from the close-only settle path in host-kit at this commit.

The live runs are the author's, with inline summaries. I could not re-run them, and no artifacts are linked. The readiness signal (first output byte from the in-simulator log process) is checked only on Xcode 27.1 and iOS 27.0, so older runtimes such as the iOS 26.2 runtime in CI are not covered. The author's run under host load of about 500 on 12 cores had 1 of 24 launches pass the 10 s deadline and fail with the typed reason. That is correct behavior, but the deadline's headroom on loaded CI hosts is not measured.

Smoke Tests is still running and has not failed. The iOS smoke route replays 01-settings.ad and gesture-pan-duration.ad and does not call logs start or stop, so this diff does not overlap it. The author reports Integration Tests passing at this commit. The only remaining step before merge is for Smoke Tests to finish green. No code change is needed.

@thymikee thymikee added the ready-for-human Valid work that needs human implementation, judgment, or maintainer merge label Oct 22, 2026
@thymikee
thymikee merged commit b862685 into main Oct 22, 2026
19 checks passed
@thymikee
thymikee deleted the fix/ios-sim-logs-stop-hang branch October 22, 2026 09:40
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

ready-for-human Valid work that needs human implementation, judgment, or maintainer merge

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant