Skip to content

diagnose(1874): instrument the synthesized commit wait and add a dispatchable stall loop - #1941

Open
thymikee wants to merge 7 commits into
mainfrom
diagnose/1874-commit-stall
Open

diagnose(1874): instrument the synthesized commit wait and add a dispatchable stall loop#1941
thymikee wants to merge 7 commits into
mainfrom
diagnose/1874-commit-stall

Conversation

@thymikee

@thymikee thymikee commented Aug 21, 2026

Copy link
Copy Markdown
Member

Refs #1874, #1844. Follow-up to #1924 (merged): production now reports TEXT_INPUT_COMMIT_NOT_OBSERVED instead of ok: true over a partial commit. This PR ships the diagnosis tooling for the remaining question — why synthesized-event delivery occasionally stalls on CI.

What we know (evidence from 2026-08-18..21 failures)

  • The stall is delayed delivery, not dropped events: run 32176591415 typed "hardware-keyboard", held "ha" at failure time, and the field read "hardware-key" ~40s later with nobody typing. The burst drains late.
  • During stall windows everything touching the input system is slow: AX value reads took ~12s, subsequent focus took 2.6–13s.
  • CI runs the test bundle as x86_64 under Rosetta on M1 Virtual, 3-core, 7 GB runners (macos-26-arm64 image; Xcode 26.6 builds x86_64 from -destination generic/platform=iOS Simulator).
  • Not reproduced by: local arm64/x86_64 runs, 10-core synthetic load, Rosetta on iOS 18.6, or running after the disappearing-input predecessor.
  • A 50-iteration instrumented loop on the real CI image (run 32485228371) passed 50/50 but caught one sub-critical episode: type-all 2487ms across 5 polls — the same mechanism at recoverable severity. Episodes that outlast the 3s commit window are the rare failures (~4 in days of full-suite runs).

Conclusion: transient throttling of the synthesized input pipeline on CI VMs; most episodes recover inside the commit window, the tail does not.

What this PR adds

  1. [DEBUG-1874] instrumentation in awaitSynthesizedFirstResponderCommit: per-poll timestamp, observed length, and expected-prefix length through the real injected observe closure, plus post time of the synthesize call and the final outcome — value-free by construction (typed Int-only boundary, sentinel-tested). Any future red lane now carries a cadence trace instead of a bare value mismatch, and no typed field content reaches runner.log.
  2. .github/workflows/1874-diagnose.ymlworkflow_dispatch matrix (isolated vs pair-after-predecessor) looping the bare-type test N times on the CI image, with per-iteration verdicts and stall evidence artifacts.

Validation

  • pnpm gate swift-runner-ios** TEST BUILD SUCCEEDED **; local run prints [DEBUG-1874] poll ... outcome=settled elapsedMs=34.
  • pnpm check:affected --run — all runnable checks passed.
  • The workflow itself executed twice on this branch (runs 32479566150, 32485228371); the second completed 50/50 green with evidence artifacts.

Intent

Keep the workflow dispatchable until #1874's underlying stall is root-caused; when a lane goes red again, its logs will show whether the prefix walks slowly (delivery throttling) or freezes (queue wedge). Remove both once resolved.

Mitigation shipped in this PR

The 2×2 matrix (runs 32485228371, 32497125475) measured native arm64 at ~30% faster commits than Rosetta x86_64 on identical CI hardware (mean type-all ~860ms vs ~1150ms), with slow-delivery episodes occurring on both architectures. Rosetta amplifies episode severity; it is not the fundamental cause. This PR pins AGENT_DEVICE_XCUITEST_ARCHS=arm64 across every lane that builds the iOS runner (ios.yml, xctest-nightly, perf-nightly, conformance-differential, replays-manual) via the new build-script override, and bumps derived-data cache suffixes. TEXT_INPUT_COMMIT_NOT_OBSERVED (#1924) remains the backstop for episodes that outlast the commit window.

Cleanup ownership

This instrumentation and the dispatchable workflow are temporary. Removal trigger: #1874 (reopened — the delivery throttle is not root-caused) identifies the mechanism, at which point the [DEBUG-1874] boundary, its guard tests, and 1874-diagnose.yml are deleted in one commit. Owner: the iOS runner maintainers; the reopened issue is the tracking thread.

@github-actions

github-actions Bot commented Aug 21, 2026

Copy link
Copy Markdown

Size Report

Metric Base Current Diff
JS raw 2.36 MB 2.36 MB 0 B
JS gzip 790.2 kB 790.2 kB 0 B
npm tarball 907.2 kB 908.0 kB +814 B
npm unpacked 3.14 MB 3.15 MB +2.6 kB

npm unpacked components

Component Base Current Diff
JS / dist source 2.50 MB 2.50 MB 0 B
Apple runner source/project 543.4 kB 546.0 kB +2.6 kB
macOS helper source 54.5 kB 54.5 kB 0 B
Android helper artifacts 0 B 0 B 0 B
Other package files 41.9 kB 41.9 kB 0 B

Startup median (7 runs, lower is better):

Scenario Base Current Diff
CLI --version 25.1 ms 24.9 ms -0.2 ms
CLI --help 70.3 ms 71.7 ms +1.4 ms

Top changed chunks: no changes in the largest emitted chunks.

Top changed packed files

Packed file Base Current Diff
dist/apple/runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+SynthesizedTextEntry.swift 10.5 kB 13.1 kB +2.6 kB

@thymikee

Copy link
Copy Markdown
Member Author

P1 — the diagnostic instrumentation writes raw observed field contents to NSLog on the shipped synthesized-text path: observedText.prefix(40). This is not confined to the workflow or unit-test build, so ordinary type commands can persist credentials/PII in runner.log; the diagnostic workflow then uploads those logs on a stall. Please keep the cadence evidence value-free (for example observed length, expected-prefix match length, progress state, and timestamps), or gate any raw fixture-only trace behind a compile-time diagnostic build that cannot ship. Add a regression/source guard that makes reintroducing raw observed text into runner logging fail.

A generic simulator destination leaves the active arch undefined; Xcode 26.6
defaults it to x86_64, running the whole runner under Rosetta on arm64 hosts.
Pin ARCHS=arm64 across every lane that builds the iOS runner and bump the
derived-data cache suffixes. Measured ~30% faster commits on identical CI
hardware; delivery-throttle episodes still occur but start from a lower base.
The per-poll trace logged the observed field's contents (prefix(40)) on the
shipped type path; that value is user content and runner.log persists. Log
lengths and the expected-prefix walk instead, allowlist every
string-interpolating NSLog format in the module behind a source-scan guard,
and pin commonPrefixLength in the host-lane policy tests.
@thymikee

Copy link
Copy Markdown
Member Author

Addressed in 634367f. The per-poll trace now logs only t, observedLen, and expectedPrefixLen — lengths and the expected-prefix walk, no field contents; same evidence for discriminating throttle (prefix grows) from wedge (prefix freezes). Every string-interpolating NSLog format in the module is allowlisted by src/__tests__/apple-runner-log-redaction.test.ts, which fails on any new %@ format — reintroducing raw observed text requires editing that allowlist, i.e. a reviewed change. Guard verified red against the pre-fix revision (unreviewed string-interpolating log format "[DEBUG-1874] poll t=%.0fms observed=%@") and green after; commonPrefixLength is pinned in the host-lane policy tests. The diagnostic workflow's uploaded logs therefore contain no typed field values from this path.

@thymikee

Copy link
Copy Markdown
Member Author

P1 — The shipped poll path is value-free now, but the new guard does not enforce that invariant. It only reviews literal NSLog formats containing %@, so Swift interpolation of observedText is skipped entirely, and passing observedText to an already-allowlisted %@ format also passes. Please put cadence logging behind a typed value-free boundary that accepts only lengths, timestamps, and enums, then test its emitted output with a sentinel secret instead of partially parsing Swift format strings. Update the PR body too: item 1 still says the trace includes the observed value, which is no longer true. Finally, #1874 and #1844 are both closed while the PR says this temporary instrumentation remains until #1874 is root-caused; reopen the cleanup issue or name an active owner and removal trigger before shipping it.

…ndary

logCommitCadence accepts Int lengths and a timestamp only, so observed field
contents are unrepresentable at the poll call site; its emitted line is pinned
by a sentinel-secret test in the host-lane policy tests. The source guard
becomes structural — boundary present, poll path logs through it, no raw NSLog
in the observe closure — instead of parsing Swift format strings. #1874 is
reopened as the removal-tracking thread for this temporary instrumentation.
@thymikee

Copy link
Copy Markdown
Member Author

Addressed in e7524f9.

  1. Typed boundary: cadence logging now goes through logCommitCadence(elapsedMs:observedLen:expectedPrefixLen:) — Int-only parameters, so observed contents are unrepresentable at the poll call site. Its emitted line is a pure function (commitCadenceLogLine) pinned by a sentinel-secret test in the host-lane policy tests: exact-equality on the output for sentinel inputs, asserting no content channel exists.
  2. Guard: rewritten as structural — boundary signature present, poll path logs through it, zero raw NSLog inside the observe closure. No Swift format-string parsing. Verified red against the pre-boundary revision, green after.
  3. PR body updated (item 1 now describes value-free evidence) and ios: testBareTypeUsesTappedInputWhenSoftwareKeyboardIsHidden fails intermittently on unrelated branches (blocking ios.yml PR gate) #1874 reopened as the removal-tracking thread: the PR names it as owner of the cleanup — instrumentation, guard tests, and the workflow go in one commit once the throttle mechanism is identified.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant