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

* diagnose(1874): instrument synthesized commit wait and add stall loop workflow

* diagnose(1874): fix empty-array expansion under set -u; raise default iterations

* diagnose(1874): add arm64 matrix leg to isolate the Rosetta factor

* ci: build the iOS runner for the native arm64 slice

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.

* diagnose(1874): keep commit-wait cadence evidence value-free

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.

* diagnose(1874): narrow the log-format match for typecheck

* diagnose(1874): route cadence evidence through a typed value-free boundary

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.
This commit is contained in:
Michał Pierzchała
2026-08-22 13:39:09 +02:00
committed by GitHub
parent cb65d6ca1f
commit e5bfde3d13
10 changed files with 303 additions and 8 deletions
+112
View File
@@ -0,0 +1,112 @@
name: 1874 Diagnose
on:
workflow_dispatch:
inputs:
iterations:
description: 'Loop iterations per job'
required: false
default: '25'
push:
branches:
- diagnose/1874-commit-stall
permissions:
contents: read
concurrency:
group: ${{ github.workflow }}-${{ github.ref }}
cancel-in-progress: true
jobs:
stall-loop:
name: ${{ matrix.arch }} ${{ matrix.mode }} stall loop
runs-on: macos-26
timeout-minutes: 90
strategy:
fail-fast: false
matrix:
mode: [isolated, pair]
arch: [x86_64, arm64]
env:
IOS_RUNTIME_VERSION: '26.2'
AGENT_DEVICE_IOS_RUNNER_DERIVED_PATH: ${{ github.workspace }}/.tmp/ios-runner-derived
AGENT_DEVICE_XCUITEST_INCLUDE_UNIT_TESTS: '1'
AGENT_DEVICE_XCUITEST_ARCHS: ${{ matrix.arch }}
steps:
- uses: actions/checkout@v4
- name: Setup toolchain
uses: ./.github/actions/setup-node-pnpm
- name: Restore and build iOS XCTest runner
uses: ./.github/actions/setup-apple-runner-build
with:
derived-path: ${{ env.AGENT_DEVICE_IOS_RUNNER_DERIVED_PATH }}
cache-key-prefix: ios-runner-prebuilt
cache-key-suffix: -ios-${{ env.IOS_RUNTIME_VERSION }}-1874-${{ matrix.arch }}
gate: swift-runner-ios
xcuitest-platform: ios
xcuitest-destination: generic/platform=iOS Simulator
- name: Boot iOS test simulator
id: ios-simulator
uses: ./.github/actions/boot-ios-test-simulator
with:
runtime-version: ${{ env.IOS_RUNTIME_VERSION }}
preferred-device-name: iPhone 17 Pro
- name: Stall loop
run: |
set -euo pipefail
XCTESTRUN_PATH="$(find "$AGENT_DEVICE_IOS_RUNNER_DERIVED_PATH/Build/Products" -maxdepth 1 -name '*.xctestrun' -print -quit)"
test -n "$XCTESTRUN_PATH"
UDID="${{ steps.ios-simulator.outputs.simulator-udid }}"
ITER="${{ github.event.inputs.iterations || '25' }}"
if [ "${{ matrix.mode }}" = "pair" ]; then
EXTRA_ONLY_TESTING=(-only-testing:AgentDeviceRunnerUITests/RunnerTests/testBareDelayedTypeFailsWhenTappedInputDisappearsMidCommand)
else
EXTRA_ONLY_TESTING=()
fi
sys_prof="$(system_profiler SPHardwareDataType 2>/dev/null | grep -E 'Chip|Cores|Memory' || true)"
echo "HOST: $sys_prof" | tee stall-summary.txt
pass=0; fail=0
for i in $(seq 1 "$ITER"); do
LOG=".tmp/stall-run-$i.log"
set +e
xcodebuild test-without-building \
-xctestrun "$XCTESTRUN_PATH" \
-destination "platform=iOS Simulator,id=$UDID" \
-only-testing:AgentDeviceRunnerUITests/RunnerTests/testBareTypeUsesTappedInputWhenSoftwareKeyboardIsHidden \
${EXTRA_ONLY_TESTING[@]+"${EXTRA_ONLY_TESTING[@]}"} \
> "$LOG" 2>&1
rc=$?
set -e
if grep -q "testBareTypeUsesTappedInputWhenSoftwareKeyboardIsHidden]' passed" "$LOG"; then
pass=$((pass+1)); verdict=pass
else
fail=$((fail+1)); verdict=STALL
fi
phase="$(grep -o 'phase=type-all durationMs=[0-9.]*' "$LOG" | tail -1)"
polls="$(grep -c 'DEBUG-1874] poll' "$LOG" || true)"
echo "iter=$i verdict=$verdict rc=$rc $phase polls=$polls" | tee -a stall-summary.txt
if [ "$verdict" = "STALL" ]; then
grep 'DEBUG-1874' "$LOG" | head -40 | tee -a stall-summary.txt
cp "$LOG" ".tmp/stall-failure-$i.log"
fi
done
echo "RESULT arch=${{ matrix.arch }} mode=${{ matrix.mode }}: $pass passed, $fail stalled of $ITER" | tee -a stall-summary.txt
- name: Upload stall evidence
if: always()
uses: actions/upload-artifact@v4
with:
name: stall-evidence-${{ matrix.arch }}-${{ matrix.mode }}
path: |
stall-summary.txt
.tmp/stall-failure-*.log
if-no-files-found: ignore
@@ -45,6 +45,7 @@ jobs:
timeout-minutes: 90
env:
IOS_RUNTIME_VERSION: '26.2'
AGENT_DEVICE_XCUITEST_ARCHS: 'arm64'
AGENT_DEVICE_STATE_DIR: ${{ github.workspace }}/.tmp/agent-device-state
AGENT_DEVICE_IOS_RUNNER_DERIVED_PATH: ${{ github.workspace }}/.tmp/ios-runner-derived
steps:
@@ -59,7 +60,7 @@ jobs:
with:
derived-path: ${{ env.AGENT_DEVICE_IOS_RUNNER_DERIVED_PATH }}
cache-key-prefix: ios-runner-prebuilt
cache-key-suffix: -ios-${{ env.IOS_RUNTIME_VERSION }}
cache-key-suffix: -ios-${{ env.IOS_RUNTIME_VERSION }}-arm64
gate: swift-runner-ios
xcuitest-platform: ios
xcuitest-destination: generic/platform=iOS Simulator
+6 -1
View File
@@ -74,6 +74,11 @@ jobs:
AGENT_DEVICE_IOS_RUNNER_DERIVED_PATH: ${{ github.workspace }}/.tmp/ios-runner-derived
AGENT_DEVICE_IOS_PREPARE_TIMEOUT_MS: '420000'
AGENT_DEVICE_XCUITEST_INCLUDE_UNIT_TESTS: '1'
# A generic simulator destination leaves the active arch undefined and Xcode 26.6
# defaults it to x86_64, which runs the whole runner under Rosetta on arm64 hosts.
# Pin the native slice: measured ~30% faster commits on identical CI hardware
# (#1874 diagnosis, PR #1941).
AGENT_DEVICE_XCUITEST_ARCHS: 'arm64'
AGENT_DEVICE_IOS_APP_EVENT_URL_TEMPLATE: agent-device-test-app:///automation?event={event}&payload={payload}
steps:
- name: Checkout
@@ -113,7 +118,7 @@ jobs:
with:
derived-path: ${{ env.AGENT_DEVICE_IOS_RUNNER_DERIVED_PATH }}
cache-key-prefix: ios-runner-prebuilt
cache-key-suffix: -ios-${{ env.IOS_RUNTIME_VERSION }}
cache-key-suffix: -ios-${{ env.IOS_RUNTIME_VERSION }}-arm64
gate: swift-runner-ios
xcuitest-platform: ios
xcuitest-destination: generic/platform=iOS Simulator
+2 -1
View File
@@ -32,6 +32,7 @@ jobs:
timeout-minutes: 80
env:
IOS_RUNTIME_VERSION: '26.2'
AGENT_DEVICE_XCUITEST_ARCHS: 'arm64'
AGENT_DEVICE_STATE_DIR: ${{ github.workspace }}/.tmp/agent-device-state
AGENT_DEVICE_IOS_RUNNER_DERIVED_PATH: ${{ github.workspace }}/.tmp/ios-runner-derived
AGENT_DEVICE_IOS_PREPARE_TIMEOUT_MS: '420000'
@@ -47,7 +48,7 @@ jobs:
with:
derived-path: ${{ env.AGENT_DEVICE_IOS_RUNNER_DERIVED_PATH }}
cache-key-prefix: ios-runner-prebuilt
cache-key-suffix: -ios-${{ env.IOS_RUNTIME_VERSION }}
cache-key-suffix: -ios-${{ env.IOS_RUNTIME_VERSION }}-arm64
gate: swift-runner-ios
xcuitest-platform: ios
xcuitest-destination: generic/platform=iOS Simulator
+2 -1
View File
@@ -91,6 +91,7 @@ jobs:
timeout-minutes: 80
env:
IOS_RUNTIME_VERSION: '26.2'
AGENT_DEVICE_XCUITEST_ARCHS: 'arm64'
AGENT_DEVICE_STATE_DIR: ${{ github.workspace }}/.tmp/agent-device-state
AGENT_DEVICE_IOS_RUNNER_DERIVED_PATH: ${{ github.workspace }}/.tmp/ios-runner-derived
AGENT_DEVICE_IOS_PREPARE_TIMEOUT_MS: '420000'
@@ -111,7 +112,7 @@ jobs:
with:
derived-path: ${{ env.AGENT_DEVICE_IOS_RUNNER_DERIVED_PATH }}
cache-key-prefix: ios-runner-prebuilt
cache-key-suffix: -ios-${{ env.IOS_RUNTIME_VERSION }}
cache-key-suffix: -ios-${{ env.IOS_RUNTIME_VERSION }}-arm64
gate: swift-runner-ios
xcuitest-platform: ios
xcuitest-destination: generic/platform=iOS Simulator
+4 -2
View File
@@ -78,8 +78,10 @@ jobs:
# methods exist at all. Dropping it would build a different variant (cache miss) whose
# bundle contains no tests, and `xcodebuild` reports running zero tests as success — the
# "silent 0-test green" this lane would then be. The test-count assertion below is the
# backstop for exactly that.
# backstop for exactly that. AGENT_DEVICE_XCUITEST_ARCHS rides the cache key too: dropping
# it silently reverts the runner to Xcode's x86_64 default under Rosetta.
IOS_RUNTIME_VERSION: '26.2'
AGENT_DEVICE_XCUITEST_ARCHS: 'arm64'
AGENT_DEVICE_XCUITEST_INCLUDE_UNIT_TESTS: '1'
AGENT_DEVICE_IOS_RUNNER_DERIVED_PATH: ${{ github.workspace }}/.tmp/ios-runner-derived
RESULT_BUNDLE_PATH: ${{ github.workspace }}/.tmp/xctest-nightly/RunnerTests.xcresult
@@ -103,7 +105,7 @@ jobs:
with:
derived-path: ${{ env.AGENT_DEVICE_IOS_RUNNER_DERIVED_PATH }}
cache-key-prefix: ios-runner-prebuilt
cache-key-suffix: -ios-${{ env.IOS_RUNTIME_VERSION }}
cache-key-suffix: -ios-${{ env.IOS_RUNTIME_VERSION }}-arm64
gate: swift-runner-ios
xcuitest-platform: ios
xcuitest-destination: generic/platform=iOS Simulator
@@ -40,9 +40,14 @@ extension RunnerTests {
replacingExistingText: Bool
) -> SynthesizedTextEntryAction {
#if os(iOS)
let postStartedAt = Date()
let result = replacingExistingText
? RunnerSynthesizedTextEntry.replaceText(withApplication: app, text: text)
: RunnerSynthesizedTextEntry.synthesizeText(withApplication: app, text: text)
NSLog(
"[DEBUG-1874] synthesize posted %d chars status=%d tookMs=%.0f",
text.count, result.status.rawValue, postStartedAt.timeIntervalSinceNow * -1000
)
return Self.action(status: result.status, message: result.message)
#else
return .fallback
@@ -184,6 +189,47 @@ extension RunnerTests {
return expectedText.hasPrefix(observedText) ? .pending : .diverged
}
/// Length of the shared prefix of two strings. Feeds value-free commit-wait logging: the
/// expected-prefix walk over time distinguishes throttled delivery (grows slowly) from a
/// wedged pipeline (freezes) without ever logging the field's contents.
static func commonPrefixLength(_ lhs: String, _ rhs: String) -> Int {
var length = 0
for (l, r) in zip(lhs, rhs) {
if l != r { break }
length += 1
}
return length
}
/// The emitted cadence line, as a pure function so its output is assertable. Only lengths and
/// a timestamp are representable here; there is no String parameter, so observed field
/// contents cannot reach runner.log through this boundary whatever they contain.
static func commitCadenceLogLine(
elapsedMs: Int,
observedLen: Int,
expectedPrefixLen: Int
) -> String {
"[DEBUG-1874] poll t=\(elapsedMs)ms observedLen=\(observedLen) expectedPrefixLen=\(expectedPrefixLen)"
}
/// The typed boundary for commit-wait cadence evidence. The poll path must log through this
/// function and never through a raw NSLog: every parameter is an Int, so the polled value's
/// contents are unrepresentable at the call site.
static func logCommitCadence(
elapsedMs: Int,
observedLen: Int,
expectedPrefixLen: Int
) {
NSLog(
"%@",
commitCadenceLogLine(
elapsedMs: elapsedMs,
observedLen: observedLen,
expectedPrefixLen: expectedPrefixLen
)
)
}
/// How the commit wait ended. Distinct from `SynthesizedTextCommitProgress`, which classifies a
/// single observation: this is the whole wait's verdict, and it exists so the deadline can be
/// told apart from success. The wait used to return `Void`, which made an expired deadline
@@ -265,20 +311,37 @@ extension RunnerTests {
let expectedText = textBefore + typedText
let placeholder = resolveTextEntryElement(app: app, target: target)?.placeholderValue
let deadline = Date().addingTimeInterval(TextEntryTiming.synthesizedCommitTimeout)
return Self.awaitSynthesizedCommitOutcome(
let waitStartedAt = Date()
NSLog("[DEBUG-1874] wait start expectedLen=%ld", expectedText.count)
let outcome = Self.awaitSynthesizedCommitOutcome(
expectedText: expectedText,
placeholder: placeholder,
isExpired: { Date() >= deadline },
observe: {
editableTextValue(
let observedText = editableTextValue(
for: resolveTextEntryElement(app: app, target: target),
treatingPlaceholderAsEmpty: true
)
// Cadence evidence stays value-free: the polled value is user content typed through
// `type` and must never reach runner.log. Lengths and the expected-prefix walk are
// enough to distinguish throttling (prefix grows slowly) from a wedge (it freezes).
Self.logCommitCadence(
elapsedMs: Int(waitStartedAt.timeIntervalSinceNow * -1000),
observedLen: observedText?.count ?? -1,
expectedPrefixLen: observedText.map { Self.commonPrefixLength($0, expectedText) } ?? -1
)
return observedText
},
// XCUI resolution shares the automation channel with the in-flight synthesized event.
// Sparse reads let the target consume that event instead of continuously interrupting it.
waitForNextObservation: { sleepFor(TextEntryTiming.synthesizedCommitPollInterval) }
)
NSLog(
"[DEBUG-1874] wait outcome=%@ elapsedMs=%.0f",
String(describing: outcome),
waitStartedAt.timeIntervalSinceNow * -1000
)
return outcome
}
static func shouldUseResolvedCoordinateTextEntryRoute(
@@ -308,6 +308,31 @@ extension RunnerTests {
XCTAssertFalse(result.repaired)
XCTAssertEqual(result.textEntryRoute, "synthesized-first-responder-replacement")
}
func testCommonPrefixLengthWalksTheExpectedPrefixOnly() {
XCTAssertEqual(Self.commonPrefixLength("hardware-keyboard", "hardware-keyboard"), 17)
XCTAssertEqual(Self.commonPrefixLength("h", "hardware-keyboard"), 1)
XCTAssertEqual(Self.commonPrefixLength("ha", "hardware-keyboard"), 2)
XCTAssertEqual(Self.commonPrefixLength("", "hardware-keyboard"), 0)
// Divergence stops the count: the app transformed the input, and the walk must not
// resume matching after the first differing character.
XCTAssertEqual(Self.commonPrefixLength("hx", "hardware-keyboard"), 1)
XCTAssertEqual(Self.commonPrefixLength("hardware-keyboarx", "hardware-keyboard"), 15)
}
func testCommitCadenceLogLineEmitsLengthsOnlyNeverContents() {
// Sentinel secret: even when the polled field holds credential-shaped content, the only
// channel into runner.log is this line, and its inputs are lengths. The exact-equality
// assert fails if any content-bearing parameter or interpolation is ever added.
let secret = "hunter2-typed-credential"
let line = Self.commitCadenceLogLine(
elapsedMs: 42,
observedLen: secret.count,
expectedPrefixLen: 8
)
XCTAssertEqual(line, "[DEBUG-1874] poll t=42ms observedLen=24 expectedPrefixLen=8")
XCTAssertFalse(line.contains(secret))
}
#endif
#endif
}
+9
View File
@@ -138,6 +138,14 @@ if is_truthy "${AGENT_DEVICE_XCUITEST_INCLUDE_UNIT_TESTS:-}"; then
SWIFT_FLAGS="$SWIFT_FLAGS -D AGENT_DEVICE_RUNNER_UNIT_TESTS"
fi
# Optional arch override. A generic simulator destination leaves the active arch
# undefined; Xcode versions differ on the default (26.6 picks x86_64, which runs
# under Rosetta on arm64 hosts). Set AGENT_DEVICE_XCUITEST_ARCHS=arm64 to pin it.
ARCH_BUILD_SETTINGS=""
if [ -n "${AGENT_DEVICE_XCUITEST_ARCHS:-}" ]; then
ARCH_BUILD_SETTINGS="ARCHS=$AGENT_DEVICE_XCUITEST_ARCHS"
fi
node --experimental-strip-types scripts/swift-toolchain-tmpdir.ts xcodebuild build-for-testing \
-project "$PROJECT_PATH" \
-scheme "$SCHEME" \
@@ -154,6 +162,7 @@ node --experimental-strip-types scripts/swift-toolchain-tmpdir.ts xcodebuild bui
-IDEPackageSupportDisablePluginExecutionSandbox=1 \
ENABLE_USER_SCRIPT_SANDBOXING=NO \
OTHER_SWIFT_FLAGS="$SWIFT_FLAGS" \
$ARCH_BUILD_SETTINGS \
$SIGNING_BUILD_SETTINGS
node --experimental-strip-types scripts/patch-xcuitest-runner-icon.ts "$DERIVED_PATH"
@@ -0,0 +1,76 @@
import assert from 'node:assert/strict';
import fs from 'node:fs';
import path from 'node:path';
import { fileURLToPath } from 'node:url';
import { test } from 'vitest';
const repoRoot = path.resolve(path.dirname(fileURLToPath(import.meta.url)), '../..');
const synthesizedTextEntryPath = path.join(
repoRoot,
'apple/runner/AgentDeviceRunner/AgentDeviceRunnerUITests/RunnerTests+SynthesizedTextEntry.swift',
);
// The synthesized bare-type commit wait polls the target field's live value on the shipped
// `type` path. That value is user content — a `type` command may carry credentials, tokens, or
// PII — and runner.log persists across the session. Cadence evidence must stay value-free.
//
// The enforcement is a typed Swift boundary (`logCommitCadence`), whose parameters are Ints
// only, so observed contents are unrepresentable at the call site; its emitted line is pinned
// by a sentinel-secret test in the host-lane policy tests. This guard is structural: it fails
// if the boundary disappears or if the poll path logs any other way. It deliberately does not
// parse Swift format strings — that review shape let raw values slip through interpolation.
const boundarySignature =
/static func commitCadenceLogLine\(\s*elapsedMs: Int,\s*observedLen: Int,\s*expectedPrefixLen: Int\s*\) -> String/;
const loggingBoundarySignature =
/static func logCommitCadence\(\s*elapsedMs: Int,\s*observedLen: Int,\s*expectedPrefixLen: Int\s*\)/;
function extractObserveClosure(source: string): string {
const start = source.indexOf('observe: {');
assert.ok(start !== -1, 'commit wait must inject an observe closure');
const end = source.indexOf('waitForNextObservation:', start);
assert.ok(end !== -1, 'commit wait must keep its waitForNextObservation seam');
return source.slice(start, end);
}
test('commit-wait cadence logging goes through the typed value-free boundary', () => {
const source = fs.readFileSync(synthesizedTextEntryPath, 'utf8');
assert.match(
source,
boundarySignature,
'commitCadenceLogLine must accept only lengths/timestamps (Int parameters)',
);
assert.match(
source,
loggingBoundarySignature,
'logCommitCadence is the only sanctioned logging entry for the poll path',
);
const observeClosure = extractObserveClosure(source);
const directNSLogs = observeClosure.match(/NSLog\(/g) ?? [];
assert.deepEqual(
directNSLogs,
[],
'the poll path must log through logCommitCadence, never through a raw NSLog',
);
assert.match(
observeClosure,
/Self\.logCommitCadence\(/,
'the poll path must emit its cadence evidence through the typed boundary',
);
// Cheap extra: no NSLog anywhere in the module interpolates the raw observed binding.
for (
let index = source.indexOf('NSLog(');
index !== -1;
index = source.indexOf('NSLog(', index + 1)
) {
const window = source.slice(index, index + 400);
assert.doesNotMatch(
window,
/NSLog\([^)]*\bobservedText\b/,
'raw observedText must never reach NSLog',
);
}
});