From b9ed6eb7c19ab677dd0e18506cb856a575581b89 Mon Sep 17 00:00:00 2001 From: Oleksii Dolhov Date: Wed, 5 Aug 2026 13:30:37 +0300 Subject: [PATCH] fix(ci): give the unit suite a per-test timeout so a hang names itself (#2019) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The workflow installs `pytest-timeout` and never used it, so a single stalled test consumed the whole 25-minute job budget, GitHub cancelled the job, the JUnit upload step was skipped, and the failure surfaced as `##[error]The operation was canceled` on whichever PR happened to be running. Four occurrences in one day across all three seeds and both sides — including the base side, which is plain `dev` and has nothing to do with the PR it reddened. The cost was never the lost minutes; it was that every occurrence had to be read out of a log by hand and produced no evidence about which test was responsible. I misdiagnosed it once for exactly that reason. Both numbers in my own issue were wrong, and measuring fixed them: - **300s, not 60s.** Taken from a green run's JUnit rather than guessed: `test_start_agent_skip_inject`'s two retry cases legitimately run ~60.6s (three real connection retries), then 39.9s and 26.6s in `test_1083_result_callback`. A 60s cap would have failed those two on every PR — the fix would have become the outage. The cap must also survive the runner variance that caused this issue (one shard ran 2.5x slower than its siblings), which puts a 60.6s test near 150s. - **signal, not thread.** `thread` dumps stacks and then kills the process, so the run aborts, the remaining tests never execute and the JUnit is incomplete — the diff job fails anyway, just with a named culprit in the log. `signal` raises inside the test and the suite continues, so the complete JUnit lets the diff job report the hang as an ordinary new failure by name. The logs support that shape: #1952 kept making progress after its 3m37s gap, so these are stalls that release, not one permanent hang. I recommended `thread` on the grounds that SIGALRM cannot interrupt a blocked C call. Tested rather than repeated: a deliberate `socket.connect` to an unroutable address under `--timeout-method=signal` fails by name in 10.2s. `if: always()` on the upload keeps a partial artifact reaching the diff job, which is deliberately fail-closed on a missing one. Scoped to `backend-unit-test.yml`. `backend-unit-nightly.yml` carries the same 25-minute budget and wants the same two lines, but PR #1952 is open against that file and conflicting with it would be a disservice — noted on the PR. 8 guard tests, each mutation-verified (including against the 60s I first proposed). Assertions read the step's command with comments stripped: the step documents its own flags, and an earlier draft stayed green with `|| true` deleted because the comment still mentioned it. Closes #2019 Co-Authored-By: Claude Opus 5 (1M context) --- .github/workflows/backend-unit-test.yml | 37 ++++ tests/registry.json | 12 ++ tests/unit/test_2019_pytest_timeout_guard.py | 208 +++++++++++++++++++ 3 files changed, 257 insertions(+) create mode 100644 tests/unit/test_2019_pytest_timeout_guard.py diff --git a/.github/workflows/backend-unit-test.yml b/.github/workflows/backend-unit-test.yml index def7245d1..1b3bc6c29 100644 --- a/.github/workflows/backend-unit-test.yml +++ b/.github/workflows/backend-unit-test.yml @@ -111,14 +111,51 @@ jobs: # || true: the existing 34 failures + 17 errors documented in #660 # produce a non-zero pytest exit. The diff job (`diff` below) is # what fails this workflow on regression. + # + # --timeout (#2019): without it a single stalled test consumed the whole + # 25-minute job budget, GitHub cancelled the job, the upload step below + # was skipped, and the failure read as `The operation was canceled` on + # whichever PR was running. Four times in one day across all three seeds + # AND both sides — the base side being plain `dev`, i.e. nothing to do + # with the PR it reddened. + # + # 300s, not the 60s this issue first proposed. Measured from a green + # run's JUnit rather than guessed: the slowest legitimate unit tests are + # test_start_agent_skip_inject's two retry cases at ~60.6s (they exercise + # three real connection retries), then 39.9s and 26.6s in + # test_1083_result_callback. A 60s cap would have failed those two on + # every PR. The cap also has to survive the runner variance that caused + # this issue in the first place — a shard ran 2.5x slower than its + # siblings — so a 60.6s test can legitimately reach ~150s. 300s clears + # that with margin and still turns a hang into a named failure: the + # observed stalls were minutes long and the budget fits ~5 of them. + # + # --timeout-method=signal (the default, stated explicitly), NOT thread — + # also a correction. `thread` dumps stacks and then kills the whole + # process, so the run aborts, the remaining tests never execute and the + # JUnit is incomplete: the diff job still fails, just with a named + # culprit in the log. `signal` raises inside the test, the suite + # CONTINUES, and the complete JUnit lets the diff job report the hang as + # an ordinary new failure by name. The logs support that shape — #1952 + # kept making progress after its 3m37s gap, so these are stalls that + # release, not one permanent hang. `signal` cannot interrupt a C call + # holding the GIL; if that ever turns out to be the case here, the + # symptom is another anonymous cancel and `thread` is the fallback. run: | cd tests python -m pytest unit/ -m "not slow" \ + --timeout=300 --timeout-method=signal \ -p randomly --randomly-seed=${{ matrix.seed }} \ --junit-xml="$GITHUB_WORKSPACE/junit-${{ matrix.side }}-${{ matrix.seed }}.xml" \ --tb=no -q || true - name: Upload JUnit XML + # always(): the timeout above should make an abnormal end unreachable, + # but the diff job is deliberately fail-closed on a missing artifact + # (correctly — a silent half-comparison is worse). Uploading whatever + # exists keeps one stalled shard from turning into a second, differently + # worded failure on the diff job (#2019). + if: always() uses: actions/upload-artifact@v7 with: name: junit-${{ matrix.side }}-${{ matrix.seed }} diff --git a/tests/registry.json b/tests/registry.json index eb177c29f..ca36a8c02 100644 --- a/tests/registry.json +++ b/tests/registry.json @@ -1553,6 +1553,18 @@ "parity" ], "description": "The agent server was outside ent#314's YAML sweep (#1965). utils/safe_yaml.py (PR #1961) put every author-controlled YAML reader in the backend behind one hardened loader, and its AST guard walks the whole backend with an EMPTY allowlist - but it walked _BACKEND.rglob only, so docker/base-image/agent_server/ kept six bare yaml.safe_load calls on documents the backend itself assigns REJECT: template.yaml (x2, credential_requirements_service), skill frontmatter (skill_packaging), dashboard.yaml (compatibility/static_checks) and .trinity/persistent-state.yaml. The vector is amplification at SERIALIZATION, not parse - a 416 B level-6 anchor bomb resolves in ~0.001 s and blows up to ~110 MB when something walks the graph - and the backend proxies /info and /dashboard, so the walk happens in-container then again across the wire. Covers: byte-parity of the vendored loader (the credential_paths.py shape, Invariant #5) plus proof the vendored COPY actually behaves - refuses a level-6 bomb under BUDGET, any alias under REJECT, duplicate keys, and still parses an honest document (byte parity is not behaviour parity if the file never imports); each of the four agent-authored sites on the shared loader with its backend counterpart's kind AND policy; /config/agent-config.yaml deliberately BUDGET not REJECT, stated as an exception because the platform writes it and bind-mounts it mode:'ro' so the agent cannot author it, and yaml.dump emits an anchor for any shared object reference - REJECT there would be a self-inflicted outage for no security; no bare safe_load left anywhere in the tree; and HardenedYamlError named in the except arms that previously caught only yaml.YAMLError (it is a ValueError, so without its own arm a refused bomb escapes to the generic handler and surfaces as the unnamed 500 the AC rules out - the trap static_checks._parse_yaml records backend-side). AC #4 end-to-end: a level-6 bomb in a container's template.yaml is refused by BOTH template.yaml readers with the expanded graph never reaching the response, an honest template still serves, and the metrics assertion checks the NAMED refusal rather than has_metrics:False - a bomb parses fine under bare safe_load and yields no metrics: key, so the flag alone passes against the very tree this issue reports. The AST-guard widening itself lives in test_ent314_hardened_yaml.py (both trees, still empty allowlist) rather than here, because splitting a guard across two files is how the second copy stops being run." + }, + { + "file": "unit/test_2019_pytest_timeout_guard.py", + "feature": "#2019", + "added": "2026-08-05", + "categories": [ + "ci", + "unit", + "reliability", + "guard" + ], + "description": "backend-unit-test.yml installs pytest-timeout and never passed --timeout, so one stalled test consumed the whole 25-minute job budget, GitHub cancelled the job, the Upload JUnit XML step was skipped (no if: always()), and the failure read as 'The operation was canceled' against whichever PR was running - four times in one day across all three seeds AND both sides, the base side being plain dev. Guards the fix: a per-test --timeout is present, it is NOT the thread method (thread dumps stacks then kills the process, so the run aborts and the JUnit is incomplete - signal raises inside the test and the suite continues, giving the diff job a complete XML that names the hang as an ordinary new failure), and the value clears the slowest REAL test with room for runner variance. Bounds measured from a green run's JUnit rather than guessed: test_start_agent_skip_inject's two retry cases run ~60.6s, so the 60s the issue originally proposed would have failed them on every PR; a 2.5x-slow runner (the variance that caused #2019) puts them near 150s, hence >=180s, and <=600s so a stall still fails instead of eating the budget. Also pins if: always() on the artifact upload and the load-bearing '|| true' (#660 baseline). Assertions read the step's COMMAND with YAML comments stripped - the step documents its own flags in prose, and an earlier draft passed with '|| true' deleted because the comment still mentioned it (the #1871/ent#314 textual-scan trap, third occurrence). The step slice is indentation-bounded after a name-bounded version ran past the last step and matched the diff job's own 'if: always()'." } ] } diff --git a/tests/unit/test_2019_pytest_timeout_guard.py b/tests/unit/test_2019_pytest_timeout_guard.py new file mode 100644 index 000000000..4b0f4412d --- /dev/null +++ b/tests/unit/test_2019_pytest_timeout_guard.py @@ -0,0 +1,208 @@ +"""#2019 — a hanging unit test must name itself, not kill the shard. + +`backend-unit-test.yml` runs the unit suite under a 25-minute job timeout. It +installs `pytest-timeout` (`tests/requirements-test.txt`) and never used it, so +a single stalled test consumed the whole budget, the job was cancelled by +GitHub, the `Upload JUnit XML` step was skipped, and the failure surfaced as +`##[error]The operation was canceled` against whichever PR happened to be +running. + +Four occurrences in one day across **all three seeds and both sides** (#2010 +head/99999, #1952 base/67890, #1976 base/67890, #2018 head/12345) — including +the base side, which is plain `dev` and therefore nothing to do with the PR +being reddened. Re-running the identical seed passed, so it is timing- rather +than order-dependent: something that usually returns fast and occasionally +blocks. The #1952 log shows a 3m37s gap with zero output between two progress +lines, which is a stall, not a slow runner. + +The cost of the missing flag was not the lost minutes; it was that every +occurrence had to be diagnosed by hand from a log and produced no evidence +about which test was responsible. I misdiagnosed it once for exactly that +reason. + +These tests pin the flag, the method, and the artifact upload, so the guard +cannot be silently dropped in a future edit of the workflow. +""" + +from __future__ import annotations + +import re +from pathlib import Path + +import pytest + +_REPO = Path(__file__).resolve().parents[2] +_WORKFLOW = _REPO / ".github" / "workflows" / "backend-unit-test.yml" + +pytestmark = pytest.mark.unit + + +@pytest.fixture(scope="module") +def workflow() -> str: + assert _WORKFLOW.is_file(), f"{_WORKFLOW} is missing" + return _WORKFLOW.read_text(encoding="utf-8") + + +def _step(workflow: str, title: str) -> str: + """Exactly ONE step's body, bounded by indentation. + + An earlier version of this helper sliced from the step title to the next + `- name:` — which runs off the end of the last step in a job and swallows + the following job. That is not hypothetical: it made the `if: always()` + assertion below match the `diff` job's own `if: always() && ...` and pass + with the guard deleted. Caught by mutation-testing this file. + + Bounding on indentation instead: a step's body is every line indented + deeper than its `- name:` marker. + """ + lines = workflow.splitlines() + start = next(i for i, l in enumerate(lines) if l.strip().startswith(f"- name: {title}")) + indent = len(lines[start]) - len(lines[start].lstrip()) + body = [lines[start]] + for line in lines[start + 1:]: + if line.strip() and (len(line) - len(line.lstrip())) <= indent: + break + body.append(line) + return "\n".join(body) + + +def _command(workflow: str, title: str) -> str: + """A step's runnable lines, with YAML comments stripped. + + Load-bearing, not tidiness. The step this file guards *documents itself* — + its comment block names `--timeout`, `--timeout-method=thread` and + `|| true` while explaining why they are there. A substring assertion over + the raw step therefore passes on the prose after the flag has been deleted + from the command, which is precisely the failure this file exists to + prevent. Caught by mutation-testing: removing `|| true` from the command + left the test green because the comment still said it. + + The same trap is recorded in `docs/memory/learnings.md` for the #1871 + `containers_run` guard and the ent#314 loader sweep. Third occurrence. + """ + out = [] + for line in _step(workflow, title).splitlines(): + stripped = line.strip() + if stripped.startswith("#"): + continue + out.append(line) + return "\n".join(out) + + +def _pytest_step(workflow: str) -> str: + """The `Run unit suite` step's COMMAND, comments removed. + + Scoped rather than searched whole-file: the nightly-style steps and the + self-test invocation also contain `pytest`, and a whole-file grep would + pass on any of them while the suite step itself lost the flag. + """ + return _command(workflow, "Run unit suite") + + +class TestTheTimeoutIsWired: + + def test_the_unit_suite_passes_a_per_test_timeout(self, workflow): + step = _pytest_step(workflow) + assert "--timeout=" in step, ( + "the unit suite runs with no per-test timeout — one hanging test " + "again consumes the 25-minute job budget and dies without naming " + "itself (#2019)" + ) + + def test_the_timeout_does_not_kill_the_run(self, workflow): + """`signal`, NOT `thread` — a correction to what the issue proposed. + + `thread` dumps stacks and then kills the process, so the run aborts, + the remaining tests never execute, and the JUnit is incomplete — the + diff job fails anyway, just with a named culprit in the log. `signal` + raises inside the offending test and the suite CONTINUES, so the + complete JUnit lets the diff job report the hang as an ordinary new + failure by name, which is the outcome worth having. + + The logs support that shape: #1952 kept making progress after its + 3m37s gap, so these are stalls that release rather than one permanent + hang. + """ + step = _pytest_step(workflow) + assert "--timeout-method=thread" not in step, ( + "`thread` aborts the whole run on the first stall, losing the " + "complete JUnit the diff job needs (#2019)" + ) + + def test_the_timeout_clears_the_slowest_real_test(self, workflow): + """The cap has to sit above every legitimate test AND above runner + variance, or it becomes a new source of red. + + Measured from a green run's JUnit, not guessed: the slowest legitimate + unit tests are `test_start_agent_skip_inject`'s two retry cases at + ~60.6s, then 39.9s and 26.6s in `test_1083_result_callback`. The 60s + this issue originally proposed would have failed the first two on every + PR. Runner variance is the whole premise of #2019 — one shard ran 2.5x + slower than its siblings — so a 60.6s test can legitimately reach + ~150s. + + Upper bound: the cap must still be small enough that a stall fails + rather than eating the 25-minute job budget. + """ + step = _pytest_step(workflow) + match = re.search(r"--timeout=(\d+)", step) + assert match, "no numeric --timeout value found" + seconds = int(match.group(1)) + assert seconds >= 180, ( + f"--timeout={seconds}s is under the ~150s a legitimate 60.6s test " + "can reach on a slow runner — this would red every PR" + ) + assert seconds <= 600, ( + f"--timeout={seconds}s is too close to the 25-minute job budget to " + "prevent the failure it is for" + ) + + def test_the_plugin_is_actually_installed(self): + """The flag is inert without the plugin, and pytest ignores unknown + `--timeout` only if some other plugin claims it — so pin the dep.""" + reqs = (_REPO / "tests" / "requirements-test.txt").read_text() + assert "pytest-timeout" in reqs + + +class TestTheArtifactSurvives: + + def test_junit_upload_runs_even_when_pytest_ends_abnormally(self, workflow): + """Without `if: always()` the upload is skipped on cancellation, so the + diff job loses that side's XML entirely and fails a second time with a + different message. The timeout should make this unreachable; belt and + braces, because the diff job is deliberately fail-closed on a missing + artifact and that is the right behaviour to keep.""" + step = _command(workflow, "Upload JUnit XML") + assert "if: always()" in step, ( + "the JUnit upload is skipped when the pytest step is cancelled, so " + "the regression-diff job sees a missing artifact instead of the " + "real result (#2019)" + ) + + +class TestTheSuiteStepIsStillWhatWeThinkItIs: + + def test_the_step_still_runs_the_unit_directory_under_three_seeds(self, workflow): + """Guards the guard: if the step is restructured, the assertions above + could pass against something that no longer runs the unit suite.""" + step = _pytest_step(workflow) + assert "unit/" in step and "--randomly-seed=" in step + + def test_the_step_still_tolerates_the_660_baseline(self, workflow): + """`|| true` is load-bearing — the documented #660 failures make pytest + exit non-zero, and the diff job is what fails the workflow. A timeout + that turned the step fatal would red every PR.""" + step = _pytest_step(workflow) + assert "|| true" in step + + +def test_the_assertions_read_the_command_not_the_comment(workflow): + """The step documents its own flags in prose, so every assertion above is + one careless helper away from testing the comment block instead of the + command. Pin the stripping directly.""" + raw = _step(workflow, "Run unit suite") + cmd = _command(workflow, "Run unit suite") + + assert "#" in raw, "the step no longer carries the comment this guards against" + assert not any(l.strip().startswith("#") for l in cmd.splitlines()) + assert "python -m pytest" in cmd, "comment stripping ate the command"