diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index 272773276..ef76e1e5d 100644 --- a/.github/workflows/test.yml +++ b/.github/workflows/test.yml @@ -23,8 +23,9 @@ concurrency: jobs: build: runs-on: macos-26 - # A green run takes about 15 minutes; a slow runner has taken 2.5x that. - # Without this the default is 6 hours, so a stuck run had to be cancelled by hand. + # A green run takes 6 to 10 minutes, and a slow runner has taken 2.5 times as long. The test + # watchdog stops a hung test run sooner; this limit stops anything else that hangs. Without + # it the default is 6 hours, so a stuck run had to be cancelled by hand. timeout-minutes: 45 permissions: contents: read @@ -77,6 +78,17 @@ jobs: return "$status" } + # A hung test run prints nothing until the job timeout, and a cancelled job keeps no + # result bundle. After 10 minutes without test output, the watchdog samples the test + # processes into build/ci-logs/hang and interrupts xcodebuild. The step then fails, + # and the result bundle marks the running test as canceled. + python3 scripts/ci-test-watchdog.py \ + --logs 'build/test-results/*.xcresult.log' \ + --results "$GITHUB_WORKSPACE/build/test-results/" \ + --products "$PROWL_DERIVED_DATA_PATH/Build/Products" \ + --out build/ci-logs/hang & + pid_watchdog=$! + run_task app-tests make test-app & pid_app=$! # SwiftPM serializes access to .build; keep its checks in one branch. @@ -90,10 +102,14 @@ jobs: wait "$pid_app" || failed=1 wait "$pid_cli" || failed=1 wait "$pid_checks" || failed=1 + kill "$pid_watchdog" 2>/dev/null || true { printf '## Build and test wall time\n\n| Task | Seconds | Exit status |\n| --- | ---: | ---: |\n' cat build/ci-logs/*.timing printf '\nTasks run in parallel; their times must not be added.\n\n' + if [ -d build/ci-logs/hang ]; then + printf '**The test output stopped.** The watchdog interrupted xcodebuild. The xcresult bundle names the canceled test, and ci-logs/hang in the logs artifact has the process samples.\n\n' + fi python3 scripts/summarize-xcode-build.py build/test-results/*.build.json build/test-results/*.action.json } >> "$GITHUB_STEP_SUMMARY" exit "$failed" @@ -123,7 +139,8 @@ jobs: if-no-files-found: ignore retention-days: 7 - name: Upload xcresult bundle (on failure) - if: failure() + # A job that reaches its timeout is cancelled, and its partial results are still useful. + if: failure() || cancelled() uses: actions/upload-artifact@v4 with: name: xcresult-${{ github.run_id }}-${{ github.run_attempt }} diff --git a/docs-ai/016-dev-build-and-ci-workflow/000-plan.md b/docs-ai/016-dev-build-and-ci-workflow/000-plan.md index 2e0c4728a..85507297a 100644 --- a/docs-ai/016-dev-build-and-ci-workflow/000-plan.md +++ b/docs-ai/016-dev-build-and-ci-workflow/000-plan.md @@ -102,3 +102,6 @@ Anchor wave, all landed 2026-04-04/05: CAS from the newest App incremental entry on a miss, save large caches only from main, and run the mirror client jobs only when they change (corrects 007's CAS note) — see [008-cas-fallback-and-cache-scope.md](008-cas-fallback-and-cache-scope.md) +- Updated 2026-10-04: a watchdog samples the test processes and interrupts xcodebuild after 10 + minutes without test output, so a hung run fails early and names the hung test — see + [009-test-hang-watchdog.md](009-test-hang-watchdog.md) diff --git a/docs-ai/016-dev-build-and-ci-workflow/009-test-hang-watchdog.md b/docs-ai/016-dev-build-and-ci-workflow/009-test-hang-watchdog.md new file mode 100644 index 000000000..f9585d1a0 --- /dev/null +++ b/docs-ai/016-dev-build-and-ci-workflow/009-test-hang-watchdog.md @@ -0,0 +1,46 @@ +# 016.009 — Test Hang Watchdog + +## Context + +In run 37164745593 (#851), the `build` job finished the App build with 93% compilation cache +hits, then the first `make test-app` pass printed nothing for 39 minutes until the 45-minute +job timeout cancelled it. The same code had passed one hour earlier. The run kept no evidence +of the hung test: + +- xcodebuild sends test results in bursts, so a hang shows no test lines at all. + `NSUnbufferedIO=YES` does not change this: in a local comparison, the result lines arrived + at the same times with and without it. +- The xcresult upload ran only on `failure()`, and a job that reaches its timeout is + cancelled. +- Nothing sampled the processes while they hung. + +## Change + +- `scripts/ci-test-watchdog.py` runs beside the tasks in the `build` job. When an xcodebuild + that writes to `build/test-results/` runs and no `build/test-results/*.xcresult.log` has + changed for 10 minutes, it: + 1. Prints a GitHub error annotation. + 2. Writes the process table and a 5-second `sample` of xcodebuild, `xctest` and every + process started from `$PROWL_DERIVED_DATA_PATH/Build/Products` (the test host) to + `build/ci-logs/hang/` (it uses `sudo -n` when `sample` alone fails). + 3. Sends SIGINT to xcodebuild, and SIGKILL if it has not stopped after 3 minutes. +- An interrupted xcodebuild prints `** TEST INTERRUPTED **` and still writes the result + bundle. The bundle marks the running test as failed with "Testing was canceled", and + `print-xcresult-failures.sh` prints that test. `make test-app` stops at that pass, so the + step fails about 10 minutes after the last output, not at the job timeout. +- The xcresult upload also runs when the job is cancelled. The step summary says when the + watchdog stopped the run. + +10 minutes is far above the normal gaps: the build prints continuously, and the gaps in +test output are about 2 minutes on a slow runner. + +## Verification (local, iOS 27 simulator) + +A temporary test with `while true { sleep(1) }`, run under the watchdog with a 30-second +limit: the watchdog sampled xcodebuild and the test host, whose stack contains +`WatchdogHangProbeTests.testHangs()`. xcodebuild stopped about 30 seconds after SIGINT, and +the result bundle reported `WatchdogHangProbeTests/testHangs()` with "Testing was canceled". + +## Refs + +PR #851 (the hang), this change. diff --git a/docs-ai/README.md b/docs-ai/README.md index d76d41f11..d8897a45c 100644 --- a/docs-ai/README.md +++ b/docs-ai/README.md @@ -98,7 +98,7 @@ keep the old paths. Use this table to find a file that an old entry names: | 013 | [prowl-cli](013-prowl-cli/000-plan.md) | 2026-03-30 | Contract-first `prowl` CLI: socket service, v1 commands, hardening, agents | | 014 | [terminal-layout-persistence](014-terminal-layout-persistence/000-plan.md) | 2026-03-31 | Layout snapshot save/restore; font-size persistence; launch races | | 015 | [repositories-feature-refactor](015-repositories-feature-refactor/000-plan.md) | 2026-04-03 | TCA decomposition of RepositoriesFeature and later code-health splits | -| 016 | [dev-build-and-ci-workflow](016-dev-build-and-ci-workflow/000-plan.md) | 2026-04-04 | Build/test tooling, CI parallelism, Debug identity, incremental caching, Shared module boundary, CAS fallback and cache save scope | +| 016 | [dev-build-and-ci-workflow](016-dev-build-and-ci-workflow/000-plan.md) | 2026-04-04 | Build/test tooling, CI parallelism, Debug identity, incremental caching, Shared module boundary, CAS fallback and cache save scope, test hang watchdog | | 017 | [upstream-sync-process](017-upstream-sync-process/000-plan.md) | 2026-04-08 | Upstream review discipline, baselines, batch decisions | | 018 | [archived-worktrees](018-archived-worktrees/000-plan.md) | 2026-04-09 | Archived worktree discoverability and auto-delete | | 019 | [worktree-creation-and-lifecycle](019-worktree-creation-and-lifecycle/000-plan.md) | 2026-04-12 | Creation/merge flows, safe deletion, Add-to-Prowl redesign | diff --git a/scripts/ci-test-watchdog.py b/scripts/ci-test-watchdog.py new file mode 100644 index 000000000..3226e2eff --- /dev/null +++ b/scripts/ci-test-watchdog.py @@ -0,0 +1,147 @@ +#!/usr/bin/env python3 +"""Stop a CI test run that hangs, and keep evidence of where it hangs. + +A hung `xcodebuild test` prints nothing until the job timeout, and a cancelled job keeps no +result bundle. When the test logs get no output for `--silence` seconds while xcodebuild +runs, this script samples xcodebuild and the test processes, then interrupts xcodebuild. +An interrupted xcodebuild still writes the result bundle, which marks the running test as +"Testing was canceled", and the step fails long before the job timeout. +""" + +import argparse +import glob +import os +from pathlib import Path +import re +import signal +import subprocess +import time + +XCODEBUILD = re.compile(r"^(?:\S*/)?xcodebuild(?:\s|$)") +XCTEST = re.compile(r"^(?:\S*/)?xctest(?:\s|$)") + + +def stalled(newest, now, silence): + return newest is not None and now - newest >= silence + + +def newest_output(paths): + times = [os.path.getmtime(path) for path in paths if os.path.exists(path)] + return max(times, default=None) + + +def parse_processes(output): + processes = [] + for line in output.splitlines(): + pid, _, args = line.strip().partition(" ") + if pid.isdigit(): + processes.append((int(pid), args.strip())) + return processes + + +def xcodebuild_pids(processes, results): + # The results folder keeps an unrelated xcodebuild (another checkout) out. + return [pid for pid, args in processes if XCODEBUILD.match(args) and results in args] + + +def sample_targets(processes, results, products, own_pid): + builds = set(xcodebuild_pids(processes, results)) + return [ + (pid, args) + for pid, args in processes + if pid != own_pid + and (pid in builds or XCTEST.match(args) or any(path in args for path in products)) + ] + + +def list_processes(): + output = subprocess.run( + ["ps", "-axo", "pid=,args="], capture_output=True, text=True, check=True + ).stdout + return parse_processes(output) + + +def collect(processes, targets, out, log): + out.mkdir(parents=True, exist_ok=True) + table = subprocess.run( + ["ps", "-axo", "pid,ppid,etime,pcpu,state,args"], capture_output=True, text=True + ).stdout + (out / "processes.txt").write_text(table) + for pid, args in targets: + name = re.sub(r"[^A-Za-z0-9.-]+", "-", Path(args.split(" -")[0]).name)[:40] + file = out / f"sample-{pid}-{name}.txt" + command = ["sample", str(pid), "5", "-file", str(file)] + # The hosted runner allows sudo without a password; a local run may not need it. + if subprocess.run(command, capture_output=True).returncode != 0: + result = subprocess.run(["sudo", "-n", *command], capture_output=True, text=True) + if result.returncode != 0: + log(f"could not sample {pid} ({args[:80]}): {result.stderr.strip()}") + + +def interrupt(pids, grace, log): + for pid in pids: + try: + os.kill(pid, signal.SIGINT) + except ProcessLookupError: + pass + deadline = time.time() + grace + while time.time() < deadline: + if not any(alive(pid) for pid in pids): + return + time.sleep(2) + for pid in pids: + if alive(pid): + log(f"xcodebuild {pid} did not stop after SIGINT; sending SIGKILL") + try: + os.kill(pid, signal.SIGKILL) + except ProcessLookupError: + pass + + +def alive(pid): + try: + os.kill(pid, 0) + except ProcessLookupError: + return False + return True + + +def main(): + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument("--logs", action="append", required=True, help="glob of the test logs") + parser.add_argument("--results", required=True, help="result bundle folder in xcodebuild's arguments") + parser.add_argument("--products", action="append", default=[], help="path in the test processes' arguments") + parser.add_argument("--out", type=Path, required=True, help="folder for the process list and samples") + parser.add_argument("--silence", type=float, default=600) + parser.add_argument("--interval", type=float, default=30) + parser.add_argument("--grace", type=float, default=180) + options = parser.parse_args() + + def log(message): + print(f"[watchdog] {message}", flush=True) + + while True: + time.sleep(options.interval) + processes = list_processes() + builds = xcodebuild_pids(processes, options.results) + if not builds: + continue + logs = [path for pattern in options.logs for path in glob.glob(pattern)] + newest = newest_output(logs) + if not stalled(newest, time.time(), options.silence): + continue + silent = int(time.time() - newest) + print( + f"::error title=Test output stopped::No test output for {silent} s. " + f"Sampled the test processes into {options.out} and interrupted xcodebuild.", + flush=True, + ) + targets = sample_targets(processes, options.results, options.products, os.getpid()) + collect(processes, targets, options.out, log) + log(f"sampled {len(targets)} processes; interrupting xcodebuild {builds}") + interrupt(builds, options.grace, log) + return + + +if __name__ == "__main__": + main() diff --git a/scripts/test_ci_test_watchdog.py b/scripts/test_ci_test_watchdog.py new file mode 100644 index 000000000..8f68de9b2 --- /dev/null +++ b/scripts/test_ci_test_watchdog.py @@ -0,0 +1,60 @@ +import importlib.util +import os +from pathlib import Path +import tempfile +import unittest + + +spec = importlib.util.spec_from_file_location( + "ci_test_watchdog", Path(__file__).with_name("ci-test-watchdog.py") +) +module = importlib.util.module_from_spec(spec) + +RESULTS = "/work/Prowl/build/test-results/" +PRODUCTS = "/work/Prowl/build/ci-derived-data/Build/Products" +PS_OUTPUT = f"""\ + 101 /Applications/Xcode.app/Contents/Developer/usr/bin/xcodebuild test -workspace Prowl.xcworkspace -resultBundlePath {RESULTS}prowl-tests.xcresult + 102 tee {RESULTS}prowl-tests.xcresult.log + 103 /bin/sh -c set -euo pipefail; xcodebuild test -resultBundlePath {RESULTS}prowl-tests.xcresult + 104 {PRODUCTS}/Debug/Prowl Debug.app/Contents/MacOS/Prowl Debug -NSTreatUnknownArgumentsAsOpen NO + 105 /Applications/Xcode.app/Contents/Developer/usr/bin/xcodebuild test -project Other.xcodeproj + 106 /Applications/Xcode.app/Contents/Developer/usr/bin/xctest /tmp/Other.xctest + 107 python3 scripts/ci-test-watchdog.py --products {PRODUCTS} +""" + + +class WatchdogTests(unittest.TestCase): + @classmethod + def setUpClass(cls): + spec.loader.exec_module(module) + + def test_output_is_stalled_only_after_the_silence_limit(self): + self.assertFalse(module.stalled(newest=1000, now=1599, silence=600)) + self.assertTrue(module.stalled(newest=1000, now=1600, silence=600)) + + def test_no_output_yet_is_not_a_stall(self): + self.assertFalse(module.stalled(newest=None, now=5000, silence=600)) + + def test_newest_output_uses_the_latest_log(self): + with tempfile.TemporaryDirectory() as tmp: + old = Path(tmp, "a.xcresult.log") + new = Path(tmp, "b.xcresult.log") + old.write_text("old") + new.write_text("new") + os.utime(old, (100, 100)) + os.utime(new, (200, 200)) + self.assertEqual(module.newest_output([str(old), str(new)]), 200) + self.assertIsNone(module.newest_output([])) + + def test_interrupts_only_xcodebuild_runs_that_write_to_the_results_folder(self): + processes = module.parse_processes(PS_OUTPUT) + self.assertEqual(module.xcodebuild_pids(processes, RESULTS), [101]) + + def test_samples_xcodebuild_and_the_test_processes_but_not_itself(self): + processes = module.parse_processes(PS_OUTPUT) + targets = module.sample_targets(processes, RESULTS, [PRODUCTS], own_pid=107) + self.assertEqual([pid for pid, _ in targets], [101, 104, 106]) + + +if __name__ == "__main__": + unittest.main()