diff --git a/.github/workflows/1874-diagnose.yml b/.github/workflows/1874-diagnose.yml index 9c7bd6e5c..a0e9ee0a0 100644 --- a/.github/workflows/1874-diagnose.yml +++ b/.github/workflows/1874-diagnose.yml @@ -1,5 +1,18 @@ name: 1874 Diagnose +# Under the lane rule in #1781: +# +# - Catches: iOS text-entry commit episodes on CI hardware — the dispatched test looped on both +# arches, with and without the neighbour test that shares the simulator. An absorbed episode +# surfaces as a slow pass, so the cadence is kept for passes too. +# - Evidence: the 2026-08-21 dispatch passed 50/50 and still caught an episode (`type-all` +# 2487 ms across 5 polls) that no PR lane would report; it does not reproduce locally. +# - Cost: manual dispatch and the `diagnose/1874-commit-stall` branch only — never a PR or `main`. +# One dispatch is four macOS slots, each a runner build plus `iterations` iterations of +# simulator time. +# - Kill criterion: delete when #2080 closes. It is the last open text-entry question this loop +# is the CI reproduction path for, and nothing else reads these artifacts. + on: workflow_dispatch: inputs: @@ -7,6 +20,10 @@ on: description: 'Loop iterations per job' required: false default: '25' + test: + description: 'RunnerTests method to loop' + required: false + default: testBareTypeUsesTappedInputWhenSoftwareKeyboardIsHidden push: branches: - diagnose/1874-commit-stall @@ -57,12 +74,17 @@ jobs: preferred-device-name: iPhone 17 Pro - name: Stall loop + env: + ITERATIONS_INPUT: ${{ github.event.inputs.iterations }} + TEST_INPUT: ${{ github.event.inputs.test }} 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' }}" + ITER="${ITERATIONS_INPUT:-25}" + TEST_NAME="${TEST_INPUT:-testBareTypeUsesTappedInputWhenSoftwareKeyboardIsHidden}" + mkdir -p .tmp if [ "${{ matrix.mode }}" = "pair" ]; then EXTRA_ONLY_TESTING=(-only-testing:AgentDeviceRunnerUITests/RunnerTests/testBareDelayedTypeFailsWhenTappedInputDisappearsMidCommand) @@ -73,33 +95,30 @@ jobs: 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 + pass=0; skipped=0; failed=0; noresult=0; runfailed=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 \ + -only-testing:"AgentDeviceRunnerUITests/RunnerTests/$TEST_NAME" \ ${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 + verdict="$(node --experimental-strip-types scripts/diagnose-1874-iteration.ts \ + "$LOG" "$TEST_NAME" "$i" "$rc")" + case "$verdict" in + passed) pass=$((pass+1)) ;; + skipped) skipped=$((skipped+1)) ;; + no-result) noresult=$((noresult+1)) ;; + run-failed) runfailed=$((runfailed+1)) ;; + *) failed=$((failed+1)) ;; + esac done - echo "RESULT arch=${{ matrix.arch }} mode=${{ matrix.mode }}: $pass passed, $fail stalled of $ITER" | tee -a stall-summary.txt + echo "RESULT arch=${{ matrix.arch }} mode=${{ matrix.mode }}: $pass passed, $skipped skipped, $failed failed, $noresult no-result, $runfailed run-failed of $ITER" | tee -a stall-summary.txt - name: Upload stall evidence if: always() @@ -109,5 +128,5 @@ jobs: include-hidden-files: true path: | stall-summary.txt - .tmp/stall-failure-*.log + .tmp/stall-evidence-*.log if-no-files-found: ignore diff --git a/scripts/__tests__/diagnose-1874-iteration.test.ts b/scripts/__tests__/diagnose-1874-iteration.test.ts new file mode 100644 index 000000000..350fdf21e --- /dev/null +++ b/scripts/__tests__/diagnose-1874-iteration.test.ts @@ -0,0 +1,157 @@ +import { execFileSync } from 'node:child_process'; +import fs from 'node:fs'; +import os from 'node:os'; +import path from 'node:path'; +import { fileURLToPath } from 'node:url'; +import { expect, test } from 'vitest'; +import { readIteration, type IterationReport } from '../diagnose-1874-iteration.ts'; + +const root = path.join(path.dirname(fileURLToPath(import.meta.url)), '../..'); +const script = path.join(root, 'scripts/diagnose-1874-iteration.ts'); +const WORKFLOW = path.join(root, '.github/workflows/1874-diagnose.yml'); +const NAME = 'testBareTypeUsesTappedInputWhenSoftwareKeyboardIsHidden'; +const POLL = '[DEBUG-1874] poll t=1ms observedLen=0 expectedPrefixLen=0'; +const CADENCE = [ + '[DEBUG-1874] wait start expectedLen=17', + POLL, + '[DEBUG-1874] wait outcome=settled', +]; + +const verdictLine = (test: string, word: string) => + `Test Case '-[X.RunnerTests ${test}]' ${word} (1.0 seconds).`; +const phases = (typeAllMs: string) => + [ + `phase=focus durationMs=644.6`, + `phase=type-all durationMs=${typeAllMs}`, + `phase=total durationMs=7379.7`, + ].map((phase) => `AGENT_DEVICE_RUNNER_TEXT_ENTRY_PHASE commandId=c ${phase} chars=17`); + +const SHAPES: readonly (Partial & { name: string; log: string[]; rc?: number })[] = + [ + { + name: 'healthy pass', + log: [verdictLine(NAME, 'passed'), ...phases('796.1'), ...CADENCE], + verdict: 'passed', + keepEvidence: false, + lines: ['iter=1 verdict=passed rc=0 durationMs=796.1 polls=1'], + }, + { + name: 'slow pass — an absorbed episode, which is the evidence #1874 wants', + log: [verdictLine(NAME, 'passed'), ...phases('14146.4'), ...CADENCE], + verdict: 'passed', + keepEvidence: true, + lines: ['iter=1 verdict=passed rc=0 durationMs=14146.4 polls=1', ...CADENCE], + }, + { + name: 'a pass a tenth of a millisecond over the slow threshold is still slow', + log: [verdictLine(NAME, 'passed'), ...phases('2000.1'), ...CADENCE], + verdict: 'passed', + keepEvidence: true, + }, + { + name: 'skipped — an environment flip, not a stall', + log: [verdictLine(NAME, 'skipped')], + verdict: 'skipped', + keepEvidence: true, + lines: ['iter=1 verdict=skipped rc=0 durationMs=0 polls=0'], + }, + { + name: 'no verdict at all — ours to own, not the product’s', + log: ['Executed 0 tests, with 0 failures (0 unexpected) in 0.000 seconds'], + verdict: 'no-result', + keepEvidence: true, + }, + { + name: 'a verdict word this loop does not model is not a stall either', + log: [verdictLine(NAME, 'errored')], + verdict: 'no-result', + }, + { + name: 'pair mode — the neighbour test logs first', + log: [ + verdictLine('testBareDelayedTypeFailsWhenTappedInputDisappearsMidCommand', 'passed'), + 'AGENT_DEVICE_RUNNER_TEXT_ENTRY_PHASE commandId=n phase=type-all durationMs=5000.0 chars=17', + verdictLine(NAME, 'passed'), + ...phases('812.0'), + ], + verdict: 'passed', + keepEvidence: false, + }, + { + name: 'restarted — the final word is the outcome', + log: [verdictLine(NAME, 'failed'), ...phases('900.0'), verdictLine(NAME, 'passed')], + verdict: 'passed', + keepEvidence: false, + }, + { + name: 'measured test passed, xcodebuild did not', + log: [verdictLine(NAME, 'passed'), ...phases('796.1'), ...CADENCE], + rc: 65, + verdict: 'run-failed', + keepEvidence: true, + }, + { + name: 'louder than the cadence cap', + log: [verdictLine(NAME, 'failed'), ...Array.from({ length: 45 }, () => POLL)], + verdict: 'failed', + keepEvidence: true, + lines: [ + 'iter=1 verdict=failed rc=0 durationMs=0 polls=45', + ...Array.from({ length: 40 }, () => POLL), + '… 5 more DEBUG-1874 lines (full log in the artifact)', + ], + }, + ]; + +test.each(SHAPES)('reads a $name iteration', (shape) => { + const report = readIteration(shape.log.join('\n'), NAME, 1, shape.rc ?? 0); + expect(report.verdict).toBe(shape.verdict); + if (shape.keepEvidence !== undefined) expect(report.keepEvidence).toBe(shape.keepEvidence); + if (shape.lines) expect(report.lines).toEqual(shape.lines); +}); + +test('the workflow forwards the exit status xcodebuild actually returned', () => { + const workflow = fs.readFileSync(WORKFLOW, 'utf8'); + expect(workflow).toContain('rc=$?'); + expect(workflow).toMatch(/diagnose-1874-iteration\.ts \\\n\s*"\$LOG" "\$TEST_NAME" "\$i" "\$rc"/); +}); + +test('the test name is matched literally, not as a pattern', () => { + const log = verdictLine('testAXB', 'passed'); + expect(readIteration(log, 'testA.B', 1, 0).verdict).toBe('no-result'); + expect(readIteration(log, 'testAXB', 1, 0).verdict).toBe('passed'); +}); + +test.each([ + { label: 'slow pass', rc: 0, verdict: 'passed' }, + { label: 'nonzero exit over a green measured test', rc: 65, verdict: 'run-failed' }, +])( + 'the entry point writes, keeps evidence and prints the verdict for a $label', + ({ rc, verdict }) => { + const cwd = fs.mkdtempSync(path.join(os.tmpdir(), 'diagnose-1874-')); + try { + fs.mkdirSync(path.join(cwd, '.tmp')); + const log = path.join(cwd, 'iteration.log'); + fs.writeFileSync( + log, + [verdictLine(NAME, 'passed'), ...phases('14146.4'), ...CADENCE].join('\n'), + ); + + const printed = execFileSync( + process.execPath, + ['--experimental-strip-types', script, log, NAME, '7', `${rc}`], + { cwd, encoding: 'utf8' }, + ); + + expect(printed).toBe(verdict); + expect(fs.readFileSync(path.join(cwd, 'stall-summary.txt'), 'utf8')).toBe( + [`iter=7 verdict=${verdict} rc=${rc} durationMs=14146.4 polls=1`, ...CADENCE, ''].join( + '\n', + ), + ); + expect(fs.existsSync(path.join(cwd, '.tmp', 'stall-evidence-7.log'))).toBe(true); + } finally { + fs.rmSync(cwd, { recursive: true, force: true }); + } + }, +); diff --git a/scripts/diagnose-1874-iteration.ts b/scripts/diagnose-1874-iteration.ts new file mode 100644 index 000000000..6913042a4 --- /dev/null +++ b/scripts/diagnose-1874-iteration.ts @@ -0,0 +1,80 @@ +import fs from 'node:fs'; +import path from 'node:path'; +import { pathToFileURL } from 'node:url'; + +const SLOW_PASS_MS = 2000; +const CADENCE_LIMIT = 40; +const SUMMARY = 'stall-summary.txt'; +const EVIDENCE_DIR = '.tmp'; + +type MeasuredVerdict = 'passed' | 'skipped' | 'failed'; + +export type IterationReport = { + readonly verdict: MeasuredVerdict | 'no-result' | 'run-failed'; + readonly keepEvidence: boolean; + readonly lines: readonly string[]; +}; + +export function readIteration( + log: string, + testName: string, + iteration: number, + rc: number, +): IterationReport { + const lines = log.split('\n'); + const marker = `${testName}]' `; + const word = lines + .filter((line) => line.includes(marker)) + .map((line) => line.slice(line.indexOf(marker) + marker.length).split(' ')[0]) + .at(-1); + const measured = isMeasuredVerdict(word) ? word : 'no-result'; + const exitContradictsMeasured = rc !== 0 && measured !== 'failed' && measured !== 'no-result'; + const verdict = exitContradictsMeasured ? 'run-failed' : measured; + const durationMs = Number( + lines + .flatMap((line) => /phase=type-all durationMs=(\d+(?:\.\d+)?)/.exec(line)?.[1] ?? []) + .at(-1) ?? 0, + ); + const cadence = lines.filter((line) => line.includes('[DEBUG-1874]')); + const keepEvidence = verdict !== 'passed' || durationMs > SLOW_PASS_MS; + + const polls = cadence.filter((line) => line.includes('] poll')).length; + const summary = `iter=${iteration} verdict=${verdict} rc=${rc} durationMs=${durationMs} polls=${polls}`; + const dropped = cadence.length - CADENCE_LIMIT; + return { + verdict, + keepEvidence, + lines: !keepEvidence + ? [summary] + : [ + summary, + ...cadence.slice(0, CADENCE_LIMIT), + ...(dropped > 0 ? [`… ${dropped} more DEBUG-1874 lines (full log in the artifact)`] : []), + ], + }; +} + +function isMeasuredVerdict(word: string | undefined): word is MeasuredVerdict { + return word === 'passed' || word === 'skipped' || word === 'failed'; +} + +function main(): number { + const [logPath, testName, iteration, rc] = process.argv.slice(2); + if (!logPath || !testName || !iteration || !rc) { + throw new Error('usage: diagnose-1874-iteration.ts '); + } + const report = readIteration( + fs.readFileSync(logPath, 'utf8'), + testName, + Number(iteration), + Number(rc), + ); + fs.appendFileSync(SUMMARY, `${report.lines.join('\n')}\n`); + if (report.keepEvidence) { + fs.copyFileSync(logPath, path.join(EVIDENCE_DIR, `stall-evidence-${iteration}.log`)); + } + process.stdout.write(report.verdict); + return 0; +} + +if (import.meta.url === pathToFileURL(process.argv[1] ?? '').href) process.exit(main()); diff --git a/vitest.config.ts b/vitest.config.ts index f7303c7e1..5b0814e18 100644 --- a/vitest.config.ts +++ b/vitest.config.ts @@ -153,6 +153,7 @@ export default defineConfig({ // Parses CI configuration only, so this action guard needs no device or subprocess lane. 'test/ci/upload-agent-device-artifacts.test.ts', 'test/ci/upload-artifact-hidden-paths.test.ts', + 'scripts/__tests__/diagnose-1874-iteration.test.ts', // The size reporter is preserved across a base checkout; its entrypoint and imported // modules must move as one directory or the Bundle Size lane fails before measuring. 'test/ci/size-workflow.test.ts',