From 41bc14e652ba39a93e0863dd8b85a2ffd9f98aa0 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Micha=C5=82=20Pierzcha=C5=82a?= Date: Thu, 27 Aug 2026 20:14:50 +0200 Subject: [PATCH] ci(1874): declare the diagnose lane and read its iterations honestly MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The loop that #1874 is investigated with could not tell the truth about itself. It classified every non-`passed` iteration as a stall, which after #2035 gave the looped test an XCTSkipIf meant an environment flip would report a 100% stall rate; it captured cadence only for failures, though an absorbed episode now passes; and it read its logs with shell pipelines whose exit status means "did this match", so an iteration that legitimately matched nothing killed the job before it could be summarized. scripts/diagnose-1874-iteration.ts reads one iteration: xcodebuild's own verdict, the `type-all` duration, and the cadence worth keeping. A nonzero exit outranks a green measured test — in `pair` mode the neighbour or the runner can fail while the measured test passes — and a run that produced no verdict is named as ours rather than counted as a stall. The workflow gains the #1781 lane declaration it never had. Its kill criterion names #2080, which the loop can now serve rather than merely claim to: the looped test is a dispatch input, so the fill route that #2080 traces loops the same way. One test pins the contract the script cannot check about itself — that the workflow hands it the status xcodebuild returned rather than a literal. Closes #1874. Both filed symptoms are resolved. `smoke:form-input` was root-caused and fixed in #2035: the fixture's placeholder was identical to the value every suite filled, so `fill` could never be verified on the penalized route — deterministic, not a flake, and only visible under load because that route is gated on a penalized XCTest channel. The targeted XCTest is mitigated by the progress-aware commit budget, with 200 consecutive green loop iterations across two dispatches. The issue's remaining question — why the input pipeline throttles — is answered by the second dispatch, and the premise was wrong: it does not. Posting 17 characters took 484 ms and the commit was observed on the first poll, inside an iteration whose `type-all` measured 14334 ms. The ~12.6 s went to accessibility round-trips before any character was posted, which is #1105's path, not the input pipeline's. --- .github/workflows/1874-diagnose.yml | 53 ++++-- .../__tests__/diagnose-1874-iteration.test.ts | 157 ++++++++++++++++++ scripts/diagnose-1874-iteration.ts | 80 +++++++++ vitest.config.ts | 1 + 4 files changed, 274 insertions(+), 17 deletions(-) create mode 100644 scripts/__tests__/diagnose-1874-iteration.test.ts create mode 100644 scripts/diagnose-1874-iteration.ts 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',