From 8cf6215a635940b1d916f83ef31388a005dd4db2 Mon Sep 17 00:00:00 2001 From: onevcat Date: Sun, 4 Oct 2026 10:54:15 +0900 Subject: [PATCH] Stop a hung CI test run and keep evidence of where it hangs A hung xcodebuild test pass printed nothing for 39 minutes until the job timeout, and the cancelled job kept no result bundle. A watchdog now runs beside the CI tasks. After 10 minutes without test output it samples xcodebuild and the test processes into build/ci-logs/hang and sends SIGINT to xcodebuild. The interrupted xcodebuild still writes the result bundle, which marks the running test as canceled, so the step fails early and names the hung test. The xcresult bundle is also uploaded when the job is cancelled. --- .github/workflows/test.yml | 23 ++- .../016-dev-build-and-ci-workflow/000-plan.md | 3 + .../009-test-hang-watchdog.md | 46 ++++++ docs-ai/README.md | 2 +- scripts/ci-test-watchdog.py | 147 ++++++++++++++++++ scripts/test_ci_test_watchdog.py | 60 +++++++ 6 files changed, 277 insertions(+), 4 deletions(-) create mode 100644 docs-ai/016-dev-build-and-ci-workflow/009-test-hang-watchdog.md create mode 100644 scripts/ci-test-watchdog.py create mode 100644 scripts/test_ci_test_watchdog.py 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()