diff options
| -rw-r--r-- | .claude/skills/hil/SKILL.md | 11 | ||||
| -rw-r--r-- | .claude/skills/usbtest/SKILL.md | 2 | ||||
| -rw-r--r-- | .pre-commit-config.yaml | 2 | ||||
| -rw-r--r-- | docs/superpowers/followup/pr3803-hil-blindness-reporting.md | 186 | ||||
| -rw-r--r-- | docs/superpowers/followup/pr3803-usbtest-recovery-reserve.md | 175 | ||||
| -rw-r--r-- | docs/superpowers/followup/pr3840-mret-board-result.md | 9 | ||||
| -rw-r--r-- | docs/superpowers/specs/2026-07-30-hil-usbtest-fleet-wedge-design.md | 115 | ||||
| -rw-r--r-- | test/hil/helper/hil_health.py | 6 | ||||
| -rwxr-xr-x | test/hil/helper/hil_lock.py | 15 | ||||
| -rw-r--r-- | test/hil/helper/hil_pool_check.py | 51 | ||||
| -rw-r--r-- | test/hil/helper/hil_report.py | 22 | ||||
| -rw-r--r-- | test/hil/helper/hil_util.py | 369 | ||||
| -rwxr-xr-x | test/hil/hil_flash.py | 4 | ||||
| -rwxr-xr-x | test/hil/hil_test.py | 332 | ||||
| -rw-r--r-- | test/hil/test/stubs/hid.py | 2 | ||||
| -rw-r--r-- | test/hil/test/test_hil_bounded.py | 789 | ||||
| -rw-r--r-- | test/hil/test/test_hil_health.py | 75 | ||||
| -rw-r--r-- | test/hil/test/test_hil_report.py | 11 | ||||
| -rw-r--r-- | test/hil/test/test_hil_util.py | 257 | ||||
| -rwxr-xr-x | test/hil/usbtest.py | 274 |
20 files changed, 1212 insertions, 1495 deletions
diff --git a/.claude/skills/hil/SKILL.md b/.claude/skills/hil/SKILL.md index d9010d28d..03a462ce6 100644 --- a/.claude/skills/hil/SKILL.md +++ b/.claude/skills/hil/SKILL.md @@ -65,8 +65,8 @@ hooks: `test_ci_select.py` covers only selection, `test_ci_metrics.py` only the plumbing. The containment work --- bounded reads, the kill ladders, the build and pool guards --- lives in `test_hil_bounded.py`, `test_hil_health.py` and `test_hil_util.py`, so run all five when changing `test/hil`: -`for f in test/hil/test/test_*.py; do python3 "$f"; done` (~84s, of which -`test_hil_bounded.py` is ~76s of deliberate hang/timeout simulation; the two `test_ci_*` +`for f in test/hil/test/test_*.py; do python3 "$f"; done` (~48s, of which +`test_hil_bounded.py` is ~30s of deliberate hang/timeout simulation; the two `test_ci_*` suites are ~4s together). ## Pre-flight rig health check @@ -137,8 +137,8 @@ The user-facing answer to a HIL run IS the tool's summary table: paste the compl table (and footer counts) verbatim — never truncate rows or reduce it to a prose digest; at most one line of commentary below it. -**First check what sits above the table.** Seven banners can appear there; match on a -PREFIX, since each carries trailing detail and one is a blockquote: +**First check what sits above the table.** Six banners can appear there; match on a +PREFIX, since each carries trailing detail and two are blockquotes: - `**HIL run abandoned: worker pool timed out after …s.**` — no results were collected this attempt, so any table below is a PREVIOUS attempt's. Report the abandonment, never those @@ -159,9 +159,6 @@ PREFIX, since each carries trailing detail and one is a blockquote: - `> **Rig dirty.**` — a process survived SIGKILL and still holds a probe or usbfs node into the NEXT job. The table below is this run's and can be reported, but say the rig is dirty: the next job starts degraded and nothing in the harness can clear it. -- `> **Not all verdicts are evidence.**` — one or more workers went blind on sysfs, so - "device not found" from the named boards means "could not tell". Do NOT report their red - cells as broken boards. On failure, retry once with `-v` — from the `<config>.failed` spec the run just wrote, which already begins with `--accumulate` and restricts each board to its failed tests. A hand-scoped diff --git a/.claude/skills/usbtest/SKILL.md b/.claude/skills/usbtest/SKILL.md index 4d7c6e5ab..606b379b5 100644 --- a/.claude/skills/usbtest/SKILL.md +++ b/.claude/skills/usbtest/SKILL.md @@ -30,7 +30,7 @@ python3 test/hil/usbtest.py --serial <uid> --keep-binding --tests 29 # one case ``` - **Always `--keep-binding`**: the cleanup unbind path has wedged host xHCIs (`usb_hcd_alloc_bandwidth`). -- CI (`hil_test.py`) additionally passes `--budget`, `--outer-timeout` and +- CI (`hil_test.py`) additionally passes `--budget` and `--recover-board`/`--recover-fw`: on a HUNG case the battery aborts, RESETS the DUT through its roster probe (non-destructive, ~130 ms) and reflashes only if that does not clear the wedge (see usb-kernel-recover). Manual runs without those flags leave a HUNG diff --git a/.pre-commit-config.yaml b/.pre-commit-config.yaml index 9ac2de228..537ed3bc4 100644 --- a/.pre-commit-config.yaml +++ b/.pre-commit-config.yaml @@ -51,7 +51,7 @@ repos: # Two hooks, split by what each suite RUNS, not by what it reads: discovery is # disjoint (test_hil*.py vs the two named suites) so nothing runs twice, but the # file patterns overlap where both suites care. hil-test runs test_hil*.py only - # (~80s: deliberate hang and timeout simulations) and is scoped to the rig harness + # (~45s: deliberate hang and timeout simulations) and is scoped to the rig harness # that owns them. The one part of it the selector depends on - the BottomLayer # stdlib-closure AST guard over tools/ci_select.py and its imports - is named # explicitly by ci-select-test instead, so a tools/ or workflow edit costs 4s diff --git a/docs/superpowers/followup/pr3803-hil-blindness-reporting.md b/docs/superpowers/followup/pr3803-hil-blindness-reporting.md deleted file mode 100644 index 374ee62c7..000000000 --- a/docs/superpowers/followup/pr3803-hil-blindness-reporting.md +++ /dev/null @@ -1,186 +0,0 @@ -# Blindness Reporting Gaps Implementation Plan - -> **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking. - -**Goal:** Make a HIL worker's sysfs blindness reach the report in the two cases where it -currently does not — an untested producer, and a board that raises. - -**Architecture:** A worker returns `hil_util.sysfs_blind()` as the last field of its result -tuple; `_blind_note()` turns that into a report banner. Two holes: nothing tests the -producer, and a board that raises returns no tuple at all, so its blindness is lost. - -**Tech Stack:** Python 3.13 stdlib, multiprocessing Pool with `maxtasksperchild=1`. - -## Global Constraints - -- A blind worker answers `SYSFS_UNKNOWN` for every attribute, so its "device not found" - means "could not tell". The report must say so or a red cell reads as a broken board. -- `maxtasksperchild=1`: one worker per board, so the flag is per-board and must not be - smeared across boards. -- Tests: `cd test/hil && python3 test/test_hil_bounded.py`. - -## What is already established - -- `hil_test.test_board` returns `(..., hil_util.sysfs_blind(), stray)`; `_blind_note(mret)` - renders the banner; wired into all three report paths. -- **The producer is provably untested**: replacing `hil_util.sysfs_blind()` with `False` in - the return leaves all tests green. Nothing drives `test_board` — it needs a board dict, a - real flock, a flasher and `test_example` per test. -- Blindness fired for real on ci.lan: four workers went blind in one run, and cells failed - *because* of it (`Printer device not found ... (this worker is blind)`). - -**Why this is a separate PR:** closing it means making `test_board` testable, which is a -refactor of the harness's orchestration layer — a different scope from the containment -work, and the reason the gap was accepted rather than papered over. - -## File Structure - -- `test/hil/hil_test.py` — extract the result-tuple assembly from `test_board` so it can be - built and asserted without running a board; carry blindness out of the raise path. -- `test/hil/test/test_hil_bounded.py` — tests for both. - ---- - -### Task 1: Make the result tuple assembly testable - -**Files:** -- Modify: `test/hil/hil_test.py` (`test_board`, the `return (name, err_count, ...)` at the - end of the try block) -- Test: `test/hil/test/test_hil_bounded.py` - -**Interfaces:** -- Produces: `_board_result(name, err_count, failed_tests, rows, t_total, board_wide_fail)` - returning the 7-tuple `(name, err_count, failed, rows, t_total, blind, stray)`, reading - `hil_util.sysfs_blind()` and `hil_health.kill_own_children()` itself. - -- [ ] **Step 1: Write the failing test** - -```python -class BoardResultCarriesBlindness(unittest.TestCase): - def test_a_blind_worker_reports_it(self): - from helper import hil_util, hil_health - self.addCleanup(setattr, hil_util, 'sysfs_blind', hil_util.sysfs_blind) - self.addCleanup(setattr, hil_health, 'kill_own_children', hil_health.kill_own_children) - hil_util.sysfs_blind = lambda: True - hil_health.kill_own_children = lambda: 0 - row = hil_test._board_result('b', 0, [], [], 1.0, False) - self.assertTrue(row[5], 'blindness did not reach the result tuple') - self.assertIn('b', hil_test._blind_note([row])) - - def test_a_sighted_worker_does_not(self): - from helper import hil_util, hil_health - self.addCleanup(setattr, hil_util, 'sysfs_blind', hil_util.sysfs_blind) - self.addCleanup(setattr, hil_health, 'kill_own_children', hil_health.kill_own_children) - hil_util.sysfs_blind = lambda: False - hil_health.kill_own_children = lambda: 0 - row = hil_test._board_result('b', 0, [], [], 1.0, False) - self.assertFalse(row[5]) - self.assertEqual(hil_test._blind_note([row]), '') -``` - -- [ ] **Step 2: Run test to verify it fails** - -Run: `cd test/hil && python3 test/test_hil_bounded.py BoardResultCarriesBlindness -v` -Expected: FAIL — `module 'hil_test' has no attribute '_board_result'` - -- [ ] **Step 3: Write minimal implementation** - -```python -def _board_result(name, err_count, failed_tests, rows, t_total, board_wide_fail): - """Assemble a worker's result tuple. Separate from test_board so the two fields only - the WORKER can answer -- its process-global blindness latch and what it could not kill - -- are testable without running a board.""" - stray = hil_health.kill_own_children() - return (name, err_count, [] if board_wide_fail else sorted(set(failed_tests)), - rows, t_total, hil_util.sysfs_blind(), stray) -``` - -Replace the tail of `test_board` with: - -```python - return _board_result(name, err_count, failed_tests, rows, t_total, board_wide_fail) -``` - -- [ ] **Step 4: Run test to verify it passes** - -Run: `cd test/hil && python3 test/test_hil_bounded.py -v` -Expected: PASS, and the existing `BlindWorkerReachesTheReport` tests still pass. - -- [ ] **Step 5: Verify the mutation is now caught** - -Replace `hil_util.sysfs_blind()` with `False` inside `_board_result` and re-run; the suite -MUST fail. Restore it. - -- [ ] **Step 6: Commit** - -```bash -git add test/hil/hil_test.py test/hil/test/test_hil_bounded.py -git commit -m "test/hil: make the worker result tuple testable, covering blindness" -``` - ---- - -### Task 2: Carry blindness out of the worker-raise path - -**Files:** -- Modify: `test/hil/hil_test.py` (`test_board`'s except/finally, and `main`'s worker-raise - handler that builds synthetic rows) -- Test: `test/hil/test/test_hil_bounded.py` - -**Interfaces:** -- Consumes: `_board_result` from Task 1. -- Produces: a board that raises still contributes a row whose blindness field is accurate. - -- [ ] **Step 1: Write the failing test** - -```python - def test_a_board_that_raises_still_reports_blindness(self): - """The result tuple is returned inside a try whose finally only releases the lock, - so a board that dies by exception contributed nothing -- and its blindness, the - thing that most explains its failure, was lost with it.""" - from helper import hil_util - self.addCleanup(setattr, hil_util, 'sysfs_blind', hil_util.sysfs_blind) - hil_util.sysfs_blind = lambda: True - row = hil_test._board_result_on_error('b', RuntimeError('boom')) - self.assertTrue(row[5]) - self.assertIn('b', hil_test._blind_note([row])) -``` - -- [ ] **Step 2: Run test to verify it fails** - -Run: `cd test/hil && python3 test/test_hil_bounded.py BoardResultCarriesBlindness -v` -Expected: FAIL — no `_board_result_on_error` - -- [ ] **Step 3: Write minimal implementation** - -```python -def _board_result_on_error(name, exc): - """A row for a board that died by exception. err_count 1, no per-test detail, but the - blindness and stray fields are still accurate -- they explain the failure more often - than the exception text does.""" - rows = [(name, {hil_report.BOUNDARY_CELL: - f'{hil_report.REPORT_CELL["fail"]} {type(exc).__name__}'}, None)] - return _board_result(name, 1, [], rows, 0.0, True) -``` - -Wrap the body of `test_board` so the exception path returns it instead of propagating. - -- [ ] **Step 4: Run test to verify it passes** - -Run: `cd test/hil && python3 test/test_hil_bounded.py -v` -Expected: PASS - -- [ ] **Step 5: Commit** - -```bash -git add test/hil/hil_test.py test/hil/test/test_hil_bounded.py -git commit -m "test/hil: keep a raising board's blindness in the report" -``` - ---- - -## Caution - -`test_board`'s `finally` releases the board flock. Any restructuring MUST keep that -release on every path, including the new error path — a leaked flock locks the board until -the host reboots. diff --git a/docs/superpowers/followup/pr3803-usbtest-recovery-reserve.md b/docs/superpowers/followup/pr3803-usbtest-recovery-reserve.md deleted file mode 100644 index eb8959520..000000000 --- a/docs/superpowers/followup/pr3803-usbtest-recovery-reserve.md +++ /dev/null @@ -1,175 +0,0 @@ -# usbtest Recovery Reserve Implementation Plan - -> **For agentic workers:** REQUIRED SUB-SKILL: Use superpowers:subagent-driven-development (recommended) or superpowers:executing-plans to implement this plan task-by-task. Steps use checkbox (`- [ ]`) syntax for tracking. - -**Goal:** Make the post-hang recovery reserve a derived, asserted property instead of an -accident of four independently-set constants. - -**Architecture:** `hil_test` passes `--budget` and `--outer-timeout` to `usbtest.py`, which -decides at runtime whether a recovery still fits. Today the reserve survives only because -the four numbers happen to line up; nothing ties them together or fails when they stop. - -**Tech Stack:** Python 3.13 stdlib. - -## Global Constraints - -- `usbtest.py`: `RECOVER_FLASH_TIMEOUT = 90`, `RECOVER_RESET_TIMEOUT = 30`. -- `hil_test.py`: `USBTEST_BATTERY_BUDGET = 260`, `USBTEST_RECOVERY_BUDGET = 250`, - `USBTEST_OVERSHOOT = 120`; `outer = BATTERY_BUDGET + (RECOVERY_BUDGET if recovery else - OVERSHOOT)`, used for both the child's `--outer-timeout` and the parent's `run_cmd` bound. -- All five are env-overridable via `hil_util.pos_int_env`, so a rig can change them. -- Tests: `cd test/hil && python3 test/test_hil_health.py` and `test_hil_bounded.py`. - -## What is already established - -The reserve holds at the shipped values, checked by hand: - -- The battery checks its budget BEFORE dispatching a case, so it can overshoot by one - case — worst case `260 + 60 + 5 = 325 s`. -- Recovery is gated on `_time_left() >= RECOVER_RESET_TIMEOUT`, where - `_time_left() = outer_timeout - elapsed - 35`; with `outer = 510` that allows recovery - until `elapsed = 445 s`, and the reflash until `385 s`. -- So ~60 s of margin survives, and recovery does fire. - -**The defect is structural, not arithmetic:** lower `--outer-timeout`, raise `--timeout`, or -raise `USBTEST_BATTERY_BUDGET` via the env and the reserve silently disappears. The failure -mode is a skipped reflash that leaves the D-state holder for the next job — the exact thing -the containment exists to prevent — with no error anywhere. - -**Why this is a separate PR:** it changes the timing contract between `hil_test` and -`usbtest.py`, which affects every board's run duration, so it wants its own review and a -full rig run. - -## File Structure - -- `test/hil/usbtest.py` — a `reserve_ok()` predicate plus a startup assertion. -- `test/hil/hil_test.py` — derive the battery budget from the outer bound rather than - setting both independently. -- `test/hil/test/test_hil_health.py` — tests. - ---- - -### Task 1: Assert the reserve at startup - -**Files:** -- Modify: `test/hil/usbtest.py` (constants block, and `main()` after argparse) -- Test: `test/hil/test/test_hil_health.py` - -**Interfaces:** -- Produces: `usbtest.reserve_ok(budget, outer, case_timeout)` returning bool. - -- [ ] **Step 1: Write the failing test** - -```python -class RecoveryReserveIsChecked(unittest.TestCase): - """The battery may overshoot its budget by ONE already-started case, so the outer bound - must leave room for that overshoot AND a bounded recovery afterwards.""" - - def setUp(self): - import usbtest - self.u = usbtest - - def test_the_shipped_numbers_leave_room(self): - self.assertTrue(self.u.reserve_ok(budget=260, outer=510, case_timeout=60)) - - def test_a_tighter_outer_bound_is_rejected(self): - self.assertFalse(self.u.reserve_ok(budget=260, outer=380, case_timeout=60)) - - def test_a_longer_case_timeout_is_rejected(self): - self.assertFalse(self.u.reserve_ok(budget=260, outer=510, case_timeout=200)) -``` - -- [ ] **Step 2: Run test to verify it fails** - -Run: `cd test/hil && python3 test/test_hil_health.py RecoveryReserveIsChecked -v` -Expected: FAIL — `module 'usbtest' has no attribute 'reserve_ok'` - -- [ ] **Step 3: Write minimal implementation** - -```python -def reserve_ok(budget: int, outer: int, case_timeout: int) -> bool: - """Does `outer` leave room for the battery's worst case AND a bounded recovery? - - The budget is checked BEFORE dispatch, so the battery can run to - `budget + case_timeout + 5` (the +5 is run_case's reap). _time_left() subtracts a - further 35 s of fixed tail. A reflash needs RECOVER_FLASH_TIMEOUT beyond that. - """ - worst_case_end = budget + case_timeout + 5 - return outer - worst_case_end - 35 >= RECOVER_FLASH_TIMEOUT -``` - -In `main()`, after parsing args: - -```python - if args.budget and args.outer_timeout and not reserve_ok( - args.budget, args.outer_timeout, args.timeout): - print(f'warning: --outer-timeout {args.outer_timeout} leaves no room for a bounded ' - f'recovery after a --budget {args.budget} battery with --timeout ' - f'{args.timeout} cases; a HUNG board will be left wedged', file=sys.stderr) -``` - -Warn, do not exit: a caller that deliberately runs without recovery is legitimate. - -- [ ] **Step 4: Run test to verify it passes** - -Run: `cd test/hil && python3 test/test_hil_health.py RecoveryReserveIsChecked -v` -Expected: PASS - -- [ ] **Step 5: Commit** - -```bash -git add test/hil/usbtest.py test/hil/test/test_hil_health.py -git commit -m "usbtest: check the recovery reserve instead of assuming it" -``` - ---- - -### Task 2: Derive the outer bound from one place - -**Files:** -- Modify: `test/hil/hil_test.py` (constants block ~line 227, and `test_device_usbtest`) -- Test: `test/hil/test/test_hil_bounded.py` - -**Interfaces:** -- Consumes: `usbtest.reserve_ok` semantics (duplicate the arithmetic, do not import - usbtest — `hil_test` must not import it). -- Produces: an assertion at module import that the shipped constants satisfy the reserve. - -- [ ] **Step 1: Write the failing test** - -```python - def test_the_shipped_constants_satisfy_the_reserve(self): - """Whatever the env overrides, the pair hil_test computes must leave recovery room: - outer - (budget + case_timeout + 5) - 35 >= 90.""" - outer = hil_test.USBTEST_BATTERY_BUDGET + hil_test.USBTEST_RECOVERY_BUDGET - self.assertGreaterEqual(outer - (hil_test.USBTEST_BATTERY_BUDGET + 60 + 5) - 35, 90) -``` - -- [ ] **Step 2: Run test to verify it fails** - -Temporarily set `HIL_USBTEST_RECOVERY_BUDGET=100` and run; expect FAIL. Unset. - -- [ ] **Step 3: Add the guard** - -```python -# The recovery reserve is a PROPERTY of these two, not a coincidence: the battery may -# overshoot its budget by one already-started case (checked before dispatch), and a bounded -# reflash needs 90 s after a 35 s fixed tail. Env overrides make this checkable at import -# rather than discoverable when a wedge is left unrecovered. -if USBTEST_RECOVERY_BUDGET - 60 - 5 - 35 < 90: - print(f'warning: HIL_USBTEST_RECOVERY_BUDGET={USBTEST_RECOVERY_BUDGET} leaves no room ' - f'for a bounded reflash after a one-case overshoot; HUNG boards will stay wedged', - file=sys.stderr) -``` - -- [ ] **Step 4: Run tests to verify they pass** - -Run: `cd test/hil && python3 test/test_hil_bounded.py -v` -Expected: PASS - -- [ ] **Step 5: Commit** - -```bash -git add test/hil/hil_test.py test/hil/test/test_hil_bounded.py -git commit -m "hil: warn when the timeout constants leave no recovery reserve" -``` diff --git a/docs/superpowers/followup/pr3840-mret-board-result.md b/docs/superpowers/followup/pr3840-mret-board-result.md index 7b8da7b9c..77b76b605 100644 --- a/docs/superpowers/followup/pr3840-mret-board-result.md +++ b/docs/superpowers/followup/pr3840-mret-board-result.md @@ -3,6 +3,15 @@ **Origin:** split out of PR #3840 (making `hil_report.md` a rendering of `hil_report.json`). Delete this file when its own PR lands. +> **SUPERSEDED IN PART (2026-08-26).** Written against a 7-field tuple whose index 5 was +> `blind`. The sysfs blindness subsystem is gone: `test_board` now returns **6** fields with +> `stray` at index 5, and its board-locked early return is 5 wide. The problem described +> below is unchanged and still worth fixing — three producers, three widths, and +> `len(r) > 5 and r[5]` reads a WRONG SLOT rather than raising. But drop the `blind` field +> from the proposed NamedTuple and re-derive every index from `hil_test.test_board` before +> executing, or `_stray_note` starts reading a duration as a stray count. +> `StrayNoteSurvivesTheTupleWidth` pins the current shape. + ## What is established `test_board()` returns a bare tuple that three producers build and fourteen call sites read diff --git a/docs/superpowers/specs/2026-07-30-hil-usbtest-fleet-wedge-design.md b/docs/superpowers/specs/2026-07-30-hil-usbtest-fleet-wedge-design.md index 3ed0c1519..a34848f06 100644 --- a/docs/superpowers/specs/2026-07-30-hil-usbtest-fleet-wedge-design.md +++ b/docs/superpowers/specs/2026-07-30-hil-usbtest-fleet-wedge-design.md @@ -1,9 +1,9 @@ # HIL fleet-wedge containment Date: 2026-07-30 -Status: implemented, then superseded in part — addendum last checked 2026-08-12 -against the shipped code; where they disagree the CODE and the usb-kernel-recover -skill win, never this document. +Status: implemented, then superseded in part, then TRIMMED (2026-08-25 — see the +addendum at the end). Last checked against the shipped code 2026-08-25; where they +disagree the CODE and the usb-kernel-recover skill win, never this document. - **Pool guard.** A single constant, not the flat 4200s below and not a derivation: `POOL_TIMEOUT = pos_int_env('HIL_POOL_TIMEOUT', 3600)`. A per-controller model briefly @@ -17,7 +17,9 @@ skill win, never this document. - **Job ceilings.** 90/90/120 min (build.yml), not 60/60/90 and not the 85/115 below. They must clear the 3600s guard plus the pre-pool checkout/artifact merge and the post-guard sweep and report upload. No job pins `HIL_POOL_TIMEOUT`. -- **Battery budgets.** `USBTEST_BATTERY_BUDGET` 260s, `USBTEST_RECOVERY_BUDGET` 250s. +- **Battery budgets.** `USBTEST_BATTERY_BUDGET` 260s. The recovery reserve is no longer a + constant: `usbtest.recovery_reserve(flasher)` derives it per flasher (RP-target openocd 390s, + other openocd/jlink/stlink 190s, esptool/lm4flash 150s) — see the trim addendum. The 200s-with-a-197s-floor derivation recorded here was never shipped; the floor assertion was removed with it. - **HUNG recovery.** Reflash of the DUT through its roster flasher @@ -234,3 +236,108 @@ a stuck run and explain it without anyone touching the rig. the board or flashing `board_test` by hand resolves it without any code change. - **An unattended PVE watchdog** that detects the wedge and power-cycles the host. Declined: more moving parts, and it can cut a running CI job. + +--- + +## Trim addendum — 2026-08-25 + +The containment above grew past what one maintainer could hold. This records what was +removed and, more importantly, the rule that decided it, so the next reader does not +re-derive the deleted layers from the incident above. + +### The dividing principle + +**The CI job ceiling bounds how long a run can burn. It does nothing about state that +outlives the run.** Cut what the ceiling contains; keep what it does not. + +- Contained by the ceiling: a worker blocked on a wedged device. `drain_pool` keeps the + boards that finished, `_write_failed_spec` names the one in flight, `_abandon_exit` + writes and uploads the report, and the job dies at `timeout-minutes` regardless. The + cost is one pool slot. +- **Not** contained: a D-state holder left on a usbfs node, or an unswept stray still + holding a probe. The job dies and those survive it, on a self-hosted runner, into the + next run. That is the original incident. + +### Removed + +- **The sysfs blindness subsystem.** `SYSFS_UNKNOWN`, the `_SysfsUnknown` sentinel, the + path→inode strand memo with its `_STRAND_MISS` miss-sentinel, the four-credit blindness + cap, `sysfs_blind()`/`sysfs_blind_note()`, `note_sysfs_strand()`, `bounded_open()`, + `usb_scan`'s `(list, bool)` return, usbtest's `inconclusive` abort, and `_blind_note`'s + report banner. `read_sysfs` is an ordinary `open().read()` returning `str | None`. + + It was a three-valued contract five files had to reason about, and misreading unknown as + absence was silent — a healthy board reported as a firmware regression. It existed for + exactly one attribute that can block. Verified against v6.12.96 `sysfs.c`: only + `usb_string_attr` (`product`/`manufacturer`/`serial`, sysfs.c:141-143) takes + `usb_lock_device_interruptible`; `idVendor`, `idProduct`, `bcdDevice`, `busnum`, + `devnum` and `speed` are lock-free `sysfs_emit` from cached fields. Two of the five + `read_sysfs` call sites read attributes that cannot block at all. + + **The bound stayed, and it is not opt-in.** An early cut of this trim made `read_sysfs` + unbounded on the theory that a blocked worker costs one pool slot. That is false: + `usb_scan` reads `serial` on every device matching the VID to find the one it wants, and + `hil_lock.controller_of` does exactly that from `controller_permit`, on essentially every + board — so one wedged DUT would stall *every* worker and the pool guard would take the + whole run. `read_sysfs` and `usb_scan` are bounded by `SYSFS_READ_GRACE` by default; + three call sites forgot an opt-in version within a single sitting, and a unit test now + pins the default. + + What is gone is the *contract*, not the bound: no third value, no process-wide blindness + latch, no `(list, bool)` return, no report banner. A give-up reads as None like any + unreadable attribute, and the cost is confined to the device that is actually wedged. + + **`hil_pool_check` is why the memo has to be exact.** It is a standalone + ThreadPoolExecutor tool with no guard behind it, run precisely when a device is suspected + wedged, and it polls (`wait_device` re-scans every 0.5 s). The bounded read gives up and + remembers + the path so a poll loop cannot leak a thread and an fd per pass. That memo is keyed by + **kernfs inode, not by path**: a busport does not change when a board returns to the same + physical port, so a path-only blacklist would outlive the wedge and make the tool's own + recovery flow (reset/reflash → `wait_device` polls for the new inode) never see the board + again. A changed inode is the all-clear; `os.stat` is safe on a wedged device because it + does not invoke `->show()`. A give-up reads as None + — the same as unreadable — and `sysfs_stranded()` lets the footer warn that a "missing" + row may be the tool losing sight of healthy hardware. One local bound with a warning + line, not the five-file three-valued contract that was removed. + +- **The recovery budget arithmetic.** `recovery_steps()`, `_time_left()` and its three + per-step gates. The reserve was an independent 250s — one number for the whole fleet — + that could not contain the ladder it + reserved for (reset 30 + reflash 90 + Rescue-DP POR 90 + retry 90 + settles), which is + why the child re-decided before every step — with a bare `- 35` for downstream costs + that nobody could re-derive. Between them they produced a recovery that skipped its own + steps for most real hangs. The reserve now counts `hil_util.REAP_GRACE` **per bounded + step** — `run_cmd` spends that reaping a child it had to SIGKILL, on top of the step's own + timeout — which is what the `- 35` was standing in for. Undersizing it is worse than not + recovering at all: the outer killpg lands mid-reflash and orphans the flasher on the + probe. A unit test asserts the reserve covers the ladder. `USBTEST_RECOVERY_BUDGET` is now derived from + `usbtest.RECOVER_*` **per flasher and per target**: the Rescue-DP legs are openocd-only + (`rescue_openocd` refuses anything else) and a stub reset is screened out, so an esptool + board no longer reserves 200s it can never spend. The child runs the ladder straight + through, and `--outer-timeout` — parsed but unused once the gates went — is deleted. + +### Deliberately kept + +- The pool guard, `drain_pool`, the re-run spec, `_abandon_exit`, the CI ceilings. +- `hil_health`'s sweep **including** `_kill_and_confirm`. SIGKILL is queued, not delivered, + for a task in uninterruptible sleep, and a healthy in-flight testusb sits in exactly that + state — so `os.kill` returning success proves nothing, and the recheck is the only honest + answer to "is the rig dirty for the next job?". +- usbtest's reset→check→reflash ladder and the `convoy_safe` gate. This is the only thing + that unpoisons the rig mid-run, and PR #3832 extends it from 11 to 18 of 27 boards. +- `mtp_test.py` as a separate process — one job, a clean boundary, and runnable by hand + against a board while debugging. + +### Structural changes with no behaviour change + +- Blocking device IO now runs in a child process everywhere, not just where it was noticed + first. The printer WRITE half joined the read half (`usblp_open` ignores `O_NONBLOCK` and + stalls in `usb_autopm_get_interface()` holding the driver-global `usblp_mutex`), and the + HID echo followed (`hid.enumerate()` reads `manufacturer`/`product` for every HID device + it lists, both under the device lock). `test_device_midi_test` is NOT in that set: ALSA + rawmidi honours `O_NONBLOCK` on open (v6.12.96 rawmidi.c:489), unlike usblp. +- `main()`'s two abort paths were near-identical 40-line blocks; `_abort_report` holds that + shape once. The controller-hint cache and pool construction moved to their own helpers. +- The unit suite stopped sleeping 54 of its 78 seconds — mostly one named-and-zeroable + post-flash settle paid by ten tests against a fake rig. diff --git a/test/hil/helper/hil_health.py b/test/hil/helper/hil_health.py index b9c05c236..d78d0f220 100644 --- a/test/hil/helper/hil_health.py +++ b/test/hil/helper/hil_health.py @@ -246,10 +246,8 @@ def _kill_kids(kids: dict, seen: set) -> int: if denied: _p(f'warning: could not kill {sorted(denied)}; they still hold whatever they ' f'had open (probe, usbfs node) into the next job', flush=True) - # SURVIVORS, not the signalled-child count: the caller needs to know the rig is dirty - # for the next job, and a count of what we successfully signalled cannot tell it that. - # (They are different units anyway -- a killpg is counted once per child sharing the - # group -- so the old return was never comparable to anything.) + # SURVIVORS, not the count we signalled: the caller needs to know the rig is dirty for + # the next job, and a killpg is counted once per child sharing the group anyway. return len(denied) diff --git a/test/hil/helper/hil_lock.py b/test/hil/helper/hil_lock.py index 7757ef17d..91f05ca86 100755 --- a/test/hil/helper/hil_lock.py +++ b/test/hil/helper/hil_lock.py @@ -175,13 +175,12 @@ def controller_of(uid: str): if cached: return cached # vid='cafe' first: the target is always a TinyUSB DUT, and the VID is a lock-free - # descriptor field. Without it this read every probe's and hub's `serial` -- the - # attribute served under device_lock -- so a HEALTHY peer mid-usbtest would strand a - # reader here and spend one of this worker's four blindness credits. - devs, _ = hil_util.usb_scan(vid='cafe', serial=uid) + # descriptor field. Without it this reads every probe's and hub's `serial` -- the one + # attribute served under device_lock -- so a wedged peer would block us here. + devs = hil_util.usb_scan(vid='cafe', serial=uid) for dev in devs: busnum = hil_util.read_sysfs(os.path.join(dev['dir'], 'busnum')) - if busnum is None or busnum is hil_util.SYSFS_UNKNOWN: + if busnum is None: continue try: root = os.path.realpath(f'/sys/bus/usb/devices/usb{int(busnum)}') @@ -212,7 +211,7 @@ def controller_slot(pci: str) -> int: # Unresolved boards budget in a slot of their OWN, one past the real ones, and that slot # holds exactly ONE permit whatever the per-controller width is. Neither neighbour works: # a permit on every slot (the old fail-closed rule) serialized the whole fleet the moment -# a worker went blind, while a full private budget let unknown boards run a second +# one board could not be resolved, while a full private budget let unknown boards run a second # controller's worth of batteries on top of the resolved ones -- doubling the load on # whichever physical controller they actually sit on, which is the saturation the # uPD720201 deaths above are attributed to. Width 1 caps the over-subscription at +1. @@ -252,8 +251,8 @@ class controller_permit: if pci is None: pci = controller_of(uid) if pci is None and warn_unknown: - log(f'warning: cannot resolve {uid} to a host controller' - f'{hil_util.sysfs_blind_note()}; budgeting it in the unknown bucket') + log(f'warning: cannot resolve {uid} to a host controller; ' + f'budgeting it in the unknown bucket') self.slots = [controller_slot(pci) if pci else UNKNOWN_SLOT] def __enter__(self): diff --git a/test/hil/helper/hil_pool_check.py b/test/hil/helper/hil_pool_check.py index 4623ce45f..d98b92bd4 100644 --- a/test/hil/helper/hil_pool_check.py +++ b/test/hil/helper/hil_pool_check.py @@ -54,7 +54,7 @@ ENUM_WAIT_RETRY = 8 # s, uid wait after a recovery reset/re-flash SERIAL_WAIT = 6 # s, host-board serial-output wait print_mutex = threading.Lock() -_UNKNOWN_WARNED = False # scan_usb's caveat: once per process, not once per poll +_STRANDED_WARNED = False # scan_usb's caveat: once per process, not once per poll t0 = time.monotonic() @@ -72,20 +72,20 @@ def scan_usb() -> dict: USB-Serial-JTAG bridge and the cafe device it flashes both derive it from the same MAC), and one dict slot would silently drop whichever lost the race.""" found = {} - # `unknown` matters BEFORE the blindness latch trips: one wedged device is the normal - # reason this tool is run, and its serial read stranding makes it absent from `devs`. - # Reported as fact, that is "probe MISSING" for hardware that is physically present. - devs, unknown = hil_util.usb_scan() - # ONCE per process: this is called from 0.5s poll loops across 4 worker threads and - # ~26 boards, so warning per call buried the table it exists to qualify under 600+ - # identical lines. The memo in read_sysfs makes the condition sticky, so one line is - # as true as six hundred. - global _UNKNOWN_WARNED - if unknown and not _UNKNOWN_WARNED: - _UNKNOWN_WARNED = True - say('WARNING: at least one device did not answer a bounded read; rows below that ' - 'say a probe or board is missing may be this scan losing sight of healthy ' - 'hardware. Find the wedged device (usb-kernel-recover) and re-run.') + # usb_scan's `serial` read is bounded by default (see hil_util.read_sysfs) -- this tool + # has no pool guard behind it and is run exactly when a device is suspected wedged. A + # device that will not answer is simply absent from the table; the footer says so. + devs = hil_util.usb_scan() + # ONCE per process, at SCAN time, not only in the footer: this tool prints rows as it + # goes over minutes, so a board dropped from the scan says "probe MISSING" within + # seconds while the only qualification would arrive after the final counts -- and an + # operator acting on the streaming output, or a run cut short by ^C, never sees it. + global _STRANDED_WARNED + if hil_util.sysfs_stranded() and not _STRANDED_WARNED: + _STRANDED_WARNED = True + say('WARNING: a bounded sysfs read gave up; rows below that say a probe or board ' + 'is missing may be this scan losing sight of healthy hardware. Find the ' + 'wedged device (usb-kernel-recover) and re-run.') for dev in devs: try: found[dev['busport']] = { @@ -1045,17 +1045,16 @@ def main() -> None: counts[r.get('status', 'failed')] += 1 print(f'\n{counts["ok"]} ok · {counts["flash-failed"]} flash-failed · {counts["failed"]} failed ' f'· {counts["locked"]} locked · in {time.monotonic() - t0:.0f}s') - if hil_util.sysfs_blind(): - # Without this the table is the worst kind of wrong: once the process latches - # blind, every read answers SYSFS_UNKNOWN, scan_usb() returns {}, and EVERY board - # prints "probe MISSING"/"off bus" -- a clean-looking report declaring the whole - # fleet dead, produced during exactly the incident this tool is run to diagnose, - # and it sends the operator to power-cycle a rig where one device is wedged. - print('WARNING: this scan lost sight of the bus' - f'{hil_util.sysfs_blind_note()}. Rows above that say a probe or board is ' - f'missing may be this tool losing sight of healthy hardware, not absent ' - f'hardware. Find the wedged device (see the usb-kernel-recover skill) and ' - f're-run before acting on the table.') + if hil_util.sysfs_stranded(): + # Without this the table is the worst kind of wrong: a device whose `serial` never + # answered is absent from the scan, which prints as "probe MISSING"/"off bus" for + # hardware that is physically present -- during exactly the incident this tool is + # run to diagnose, and it sends the operator to power-cycle a healthy rig. + print('WARNING: at least one sysfs read did not answer within ' + f'{hil_util.SYSFS_READ_GRACE:.0f}s, so rows above that say a probe or board ' + f'is missing may be this tool losing sight of healthy hardware rather than ' + f'absent hardware. Find the wedged device (see the usb-kernel-recover ' + f'skill) and re-run before acting on the table.') sys.exit(min(counts['flash-failed'] + counts['failed'], 125)) diff --git a/test/hil/helper/hil_report.py b/test/hil/helper/hil_report.py index d059c62c9..c93c8e6a1 100644 --- a/test/hil/helper/hil_report.py +++ b/test/hil/helper/hil_report.py @@ -63,6 +63,10 @@ LOCKED_CELL = 'board-locked' # A pseudo-test column, not a real one: write_timeout_report marks the boards that were # still dispatched when the pool guard fired. accumulate_report clears it on a retry. POOL_TIMEOUT_CELL = 'pool-timeout' +# The other way a board can fail to report: the pool did not expire, a worker RAISED. Same +# shape, different cause, and naming the cause is the whole point of the column -- a board +# marked pool-timeout by an abort that never timed out sends the reader after the guard. +RUN_ABORTED_CELL = 'run-aborted' def _load(report_dir: Path) -> tuple: @@ -352,6 +356,7 @@ def accumulate_report(mret: list, report_dir: Path, fresh: bool, scope: str = '' # never reported, and update() below MERGES, so without this a board that # passed clean on the retry kept a red cell for ever. stale[0].pop(POOL_TIMEOUT_CELL, None) + stale[0].pop(RUN_ABORTED_CELL, None) if not stale[0]: # variant-keyed boards never repopulate the board-name row, so drop it # or it renders as a blank ghost row @@ -360,6 +365,7 @@ def accumulate_report(mret: list, report_dir: Path, fresh: bool, scope: str = '' row = acc.setdefault(row_label, [{}, None]) # a row that ran is no longer pool-timed-out, whatever it is keyed by row[0].pop(POOL_TIMEOUT_CELL, None) + row[0].pop(RUN_ABORTED_CELL, None) # the boundary cell is only ever written on failure, so a re-run of this # variant that cleared the boundary must drop the previous attempt's ❌ if BOUNDARY_CELL not in cells: @@ -409,7 +415,8 @@ def _write_stuck_over_prior_md(report_dir: Path, doc: dict) -> None: def write_timeout_report(report_dir: Path, boards, secs: int, - banner: str = '', prefix: str = '') -> None: + banner: str = '', prefix: str = '', + cell: str = POOL_TIMEOUT_CELL) -> None: """Leave a report behind when the worker pool has to be abandoned. map_async is all-or-nothing, so a timeout loses every per-board result and the report @@ -427,7 +434,7 @@ def write_timeout_report(report_dir: Path, boards, secs: int, caveat = banner or ( f'**HIL run abandoned: worker pool timed out after {secs}s.**\n\n' f'No per-board results could be collected for this attempt. Rows other than ' - f'the {POOL_TIMEOUT_CELL} cells below are from an earlier attempt. Boards ' + f'the {cell} cells below are from an earlier attempt. Boards ' f'dispatched:\n\n' + '\n'.join(f'- {n}' for n in names) + '\n') doc, readable = _load(report_dir) rows = doc['rows'] @@ -435,13 +442,13 @@ def write_timeout_report(report_dir: Path, boards, secs: int, for name in names: row = by_board.get(name) if row is None: - rows.append({'board': name, 'cells': {POOL_TIMEOUT_CELL: 'fail'}, + rows.append({'board': name, 'cells': {cell: 'fail'}, 'duration': None}) else: # _load guarantees `cells` is a dict, so a null-cells row from an uploaded # sidecar can no longer send this down the fallback and publish a board # that ate the whole pool guard as a pass. - row['cells'][POOL_TIMEOUT_CELL] = 'fail' + row['cells'][cell] = 'fail' out = {'rows': rows, 'scope': doc['scope'], 'caveat': caveat, 'banner': ((doc['banner'] + prefix) if prefix not in doc['banner'] else doc['banner'])} @@ -517,8 +524,11 @@ def summarize(cfg: dict, boards: list, report: dict) -> dict: # a wedge outranks lock contention: `locked` short-circuits `detail` below, so a # stale board-locked cell from an earlier attempt used to mask the pool-timeout # cell the retry added -- publishing a board that hung the rig as LOCKED, which - # hil-validate.js then RE-RUNS, paying another pool guard on it. - wedged = any(POOL_TIMEOUT_CELL in cells for cells in mine.values()) + # hil-validate.js then RE-RUNS, paying another pool guard on it. RUN_ABORTED_CELL + # is written by the same _abort_report path for a board the guard never reached, + # and must outrank it for the same reason. + wedged = any(POOL_TIMEOUT_CELL in cells or RUN_ABORTED_CELL in cells + for cells in mine.values()) locked = not wedged and any(LOCKED_CELL in cells for cells in mine.values()) bad = [] for vname, cells in sorted(mine.items()): diff --git a/test/hil/helper/hil_util.py b/test/hil/helper/hil_util.py index f279cfa77..6f84c143d 100644 --- a/test/hil/helper/hil_util.py +++ b/test/hil/helper/hil_util.py @@ -90,6 +90,10 @@ def pos_float_env(name: str, default: float) -> float: CMD_TIMEOUT = pos_int_env('HIL_CMD_TIMEOUT', 180) +# Post-SIGKILL reap, spent ON TOP of a run_cmd timeout whenever the child has to be killed. +# A caller budgeting several bounded steps must add one of these PER STEP, or its own outer +# bound fires mid-step -- for a flasher, orphaning it on the probe. +REAP_GRACE = 10 TINYUSB_ROOT = Path(__file__).resolve().parents[3] # test/hil/helper/ -> repo root @@ -158,74 +162,119 @@ def _print_banner(title: str, out: Any, err: Any) -> None: print(_banner_body(out, err)) -SYSFS_READ_GRACE = 2.0 # bound on one attribute read of a possibly-wedged device -SYSFS_STUCK_MAX = 4 # stranded readers tolerated before read_sysfs goes blind -_sysfs_stuck = 0 # each costs a thread + an fd for the life of the process -_sysfs_stuck_lock = threading.Lock() -_sysfs_blind_logged = False +SYSFS_READ_GRACE = 2.0 # default bound on one attribute read; see read_sysfs +# path -> the kernfs inode the node had when its bounded read gave up. Keyed by INODE, not +# by path alone: a busport does not change when a board returns to the same physical port, +# so a path-only blacklist outlives the wedge -- hil_pool_check resets or reflashes the +# board, wait_device polls that busport for the new inode, and the scan it polls through +# would never look at the device again. A re-enumeration destroys the kernfs node and makes +# a new one, so a CHANGED inode is the all-clear. os.stat is safe on a wedged device: it +# does not call ->show(), so it cannot block on the lock the reader is stuck behind. +_stranded: dict = {} +_strand_hits: dict = {} # path -> how many times it has stranded, ever +_refused: set = set() # paths answered None WITHOUT reading, once past _STRAND_MAX +_strand_lock = threading.Lock() +_ever_stranded = False -class _SysfsUnknown: - """Sentinel: the read did not answer. NOT "the attribute is absent" -- reading it as - absence turns a healthy board into a firmware regression in the report.""" - __slots__ = () +# Each strand costs a thread AND an fd for the life of the process -- on sysfs the open() +# SUCCEEDS and only the read blocks. Two ceilings, because they bound different things: +# +# _PATH_STRAND_MAX -- a device that FLAPS while still wedged re-enumerates, clears the +# inode memo, and strands again. Per path, so one sick board cannot leak without bound. +# After this many it stays memoised whatever its inode says. +# _STRAND_MAX -- a whole-process backstop against RLIMIT_NOFILE or the thread ceiling, +# which would raise inside a worker and lose every board's result. Counted PER PATH, not +# per reader: hil_pool_check runs four poll threads over one bus, and counting each +# reader let four threads on ONE wedged device spend four credits between them. With +# per-path counting a 27-board rig cannot approach this. +_PATH_STRAND_MAX = 4 +_STRAND_MAX = 64 - def __bool__(self) -> bool: - return False - def __repr__(self) -> str: - return 'SYSFS_UNKNOWN' +def sysfs_stranded() -> bool: + """True once any bounded read has given up, and it STAYS true. + A sticky, process-wide fact, so it answers exactly one question: "could anything in + this process's output be the tool losing sight of healthy hardware?" -- which is what + hil_pool_check's footer needs. It canNOT answer "is THIS device unreadable" for a + caller deciding what a single missing device means; use path_stranded() for that. + """ + return _ever_stranded -SYSFS_UNKNOWN = _SysfsUnknown() +def strand_note() -> str: + """Suffix for an absence claim, so "not found" never reads as proven absence. -def sysfs_blind() -> bool: - """True once this process has stranded SYSFS_STUCK_MAX readers: every later read - answers SYSFS_UNKNOWN, so nothing it reports about a device is a fact any more.""" - return _sysfs_stuck >= SYSFS_STUCK_MAX + Lives here because every caller that can say "not found" needs the same sentence, and + the one that had to re-invent it got missed: a wedged-but-enumerated printer was + reported as an enumeration failure, sending a maintainer after firmware. + """ + return (' (a bounded sysfs read gave up, so "not found" here means "could not tell"' + ' -- see the usb-kernel-recover skill)') if sysfs_stranded() else '' -def sysfs_blind_note() -> str: - """Suffix for a failure message, so a blind worker's verdict never reads as hardware.""" - return (f' (this worker is blind: {SYSFS_STUCK_MAX} sysfs reads stranded on a wedged ' - f'device, so the check could not see the bus)') if sysfs_blind() else '' +def path_stranded(path: str) -> bool: + """Whether THIS attribute is currently memoised as unreadable. + The per-device question sysfs_stranded() cannot answer. usbtest uses it to tell a DUT + whose `serial` is held under device_lock from one that genuinely left the bus, because + the difference decides whether it performs driver-registry writes that take the + UNINTERRUPTIBLE device_lock. + """ + with _strand_lock: + return path in _stranded or path in _refused -def read_sysfs(path: str, grace: float = SYSFS_READ_GRACE) -> str | None | _SysfsUnknown: - """Read a sysfs attribute with a WALL-CLOCK bound. - The value, None when the attribute is genuinely unreadable (OSError), or SYSFS_UNKNOWN - when the read did not answer -- it timed out, or this process is already blind. Callers - MUST keep those apart: absence is a fact, unknown is not. +def read_sysfs(path: str, timeout: float = SYSFS_READ_GRACE) -> str | None: + """A sysfs attribute's value, or None when it did not answer. - usb_string_attr (serial/product/manufacturer) is served under the device lock a wedged - usbfs ioctl holds, so a plain open().read() blocks for as long as the wedge lasts, on - exactly the board an incident is about. The reader sleeps INTERRUPTIBLY (every read - takes usb_lock_device_interruptible, v6.12.96 sysfs.c:124-139 -- uninterruptible is the - ioctl holder, not us), so it dies with a SIGKILLed worker; what it costs meanwhile is a - thread and an fd for this process's life, because on sysfs the open() SUCCEEDS and only - the read blocks. Measured: 20 blocking reads leave 20 live threads. + BOUNDED BY DEFAULT, and it has to be. `serial` is served by usb_string_attr, which + takes usb_lock_device_interruptible (v6.12.96 sysfs.c:141-143) -- the same lock a + wedged usbfs ioctl holds. Every OTHER attribute the harness reads (idVendor, idProduct, + bcdDevice, busnum, devnum, speed) is a lock-free sysfs_emit from a cached field and + cannot block. - Hence the cap: callers rescan (hil_lock's controller_of re-reads every unresolved - device on EVERY permit), and hitting RLIMIT_NOFILE or the thread ceiling raises inside - the worker and loses every board's result -- worse than the hang this prevents. + "Only the wedged board's own worker pays" is FALSE, which is why the bound is not + opt-in: usb_scan reads `serial` on every device matching the VID to find the one it + wants, so resolving MY board touches every peer's locked attribute. hil_lock's + controller_of does that from controller_permit, on essentially every board -- one + wedged DUT would stall every worker, not one. hil_pool_check has no guard at all. + + A give-up reads as None, the same as unreadable: there is no third value and no + per-attribute blindness. The memo is keyed by inode so the cost stays on the device + that is actually wedged; path_stranded() tells a caller which device that was. """ - if sysfs_blind(): - return SYSFS_UNKNOWN - # Known-stranded? Re-reading costs another permanent thread+fd and a blindness credit - # to learn what we already know. Lives HERE, not at the call sites: a call-site memo - # has to be remembered by every new scanner, and twice it was not. - was = _sysfs_stranded.get(path, _STRAND_MISS) - if was is not _STRAND_MISS: - if was is None: - return SYSFS_UNKNOWN # stranded, inode unknown: never re-read it + with _strand_lock: + was = _stranded.get(path) + stuck_for_good = _strand_hits.get(path, 0) >= _PATH_STRAND_MAX + budget_spent = len(_stranded) >= _STRAND_MAX + if was is not None: try: if os.stat(path).st_ino == was: - return SYSFS_UNKNOWN # same node, still wedged + return None # same kernfs node, still wedged except OSError: - pass # gone: fall through, the read reports it - _sysfs_stranded.pop(path, None) # replaced or gone -> re-read it + pass # gone: let the read below report it + if stuck_for_good: + return None # flapped too many times; see _PATH_STRAND_MAX + with _strand_lock: + _stranded.pop(path, None) # a different inode is the all-clear + elif budget_spent: + # see _STRAND_MAX. Recorded, not just returned: usbtest fails CLOSED on + # path_stranded() before the lock-taking cleanup, and a path we declined to read + # is exactly the case it must not be told is readable-and-absent. + with _strand_lock: + _refused.add(path) + return None + + # BEFORE the read, not after: a node that re-enumerates DURING the grace would + # otherwise have its brand-new HEALTHY inode recorded as the wedged one, and only a + # second re-enumeration could ever clear it. If it cannot be stat'd there is no key to + # memoise against, so the path is simply re-read next time -- the open fails fast. + try: + ino = os.stat(path).st_ino + except OSError: + ino = None out: dict = {} def _read(): @@ -233,96 +282,70 @@ def read_sysfs(path: str, grace: float = SYSFS_READ_GRACE) -> str | None | _Sysf with open(path) as f: out['v'] = f.read().strip() except (OSError, ValueError): - pass # no such attribute, or not text: unreadable, and that IS a fact + pass t = threading.Thread(target=_read, daemon=True) t.start() - t.join(grace) - # `out` FIRST, not is_alive() alone: a reader can deposit its value and still be alive - # for a moment afterwards, and counting that as a strand memoises a healthy attribute as - # unreadable and spends one of four blindness credits. bounded_open has always checked - # its box for the same reason. + t.join(timeout) + # `out` FIRST: a reader can deposit its value and still be alive for a moment + # afterwards, and counting that as a strand blacklists a healthy attribute forever + if 'v' in out: + # a path that answered is not refused any more: _refused feeds path_stranded(), + # and a stale entry makes usbtest read a LATER genuine disconnect as "cannot tell" + with _strand_lock: + _refused.discard(path) if t.is_alive() and 'v' not in out: - # Count the PATH once, not once per reader. hil_pool_check runs -j4 by default, - # which equals SYSFS_STUCK_MAX, so four threads hitting ONE wedged device used to - # spend the entire blindness budget between them -- latching blind on the single - # wedge the tool was run to find. The strand is real for each thread, but the - # DEVICE is what the cap is about. - # Under the SAME lock as the counter: check-then-act here is a race, and - # hil_pool_check runs a ThreadPoolExecutor of exactly SYSFS_STUCK_MAX workers in - # ONE process, so four threads on one wedged path could each see `first` before any - # of them recorded it -- spending the whole blindness budget on a single device, - # which is what this memo exists to prevent. note_sysfs_strand takes the lock - # itself, so call it after releasing. - with _sysfs_stuck_lock: - first = path not in _sysfs_stranded - if first: - try: - # stat, never the thread's own open(): stat does not call ->show(), so - # it cannot block on the device lock the reader is stuck behind - _sysfs_stranded[path] = os.stat(path).st_ino - except OSError: - _sysfs_stranded[path] = None # unstattable, but still known-stranded - if first: - note_sysfs_strand() - return SYSFS_UNKNOWN + global _ever_stranded + announce = False + if ino is None: + # the pre-read stat lost a race the open then won -- the node was replaced + # between them. Re-stat now: the reader is blocked on whatever node exists, + # so this is the key it is stuck on. Without a key nothing is memoised and + # every later poll starts another permanent thread and fd for this path. + try: + ino = os.stat(path).st_ino + except OSError: + pass + with _strand_lock: + _ever_stranded = True + if ino is not None: + first = path not in _stranded # count the PATH once, not each reader + _stranded[path] = ino + if first: + _strand_hits[path] = _strand_hits.get(path, 0) + 1 + announce = len(_stranded) == _STRAND_MAX + else: + _refused.add(path) # unkeyable: at least do not vouch for it + if announce: + print(f'warning: {_STRAND_MAX} devices have unreadable sysfs attributes; ' + f'refusing to start more bounded readers, so later reads answer None ' + f'without looking. Find the wedged device (usb-kernel-recover skill).', + file=sys.stderr, flush=True) + return None return out.get('v') -def note_sysfs_strand() -> None: - """Record ONE stranded sysfs reader. Shared by read_sysfs and bounded_open so both - account against a single counter -- the report caveat keys off it.""" - global _sysfs_stuck, _sysfs_blind_logged - with _sysfs_stuck_lock: - _sysfs_stuck += 1 - announce = sysfs_blind() and not _sysfs_blind_logged - _sysfs_blind_logged = _sysfs_blind_logged or announce - if announce: - # once per process, on stderr: a worker's stdout is compacted into one report - # row, where this would be lost among the test output - print(f'warning: {SYSFS_STUCK_MAX} sysfs reads stranded on a wedged device; ' - f'this process is now blind and answers SYSFS_UNKNOWN for every ' - f'attribute -- its verdicts about device presence are not evidence', - file=sys.stderr, flush=True) - - -# path -> the inode it had when its read stranded. A stranded attribute stays -# stranded until the DEVICE is replaced, and a re-enumeration destroys the kernfs -# node and makes a new one -- so a changed inode is the all-clear. Keyed by path -# alone it would outlive the wedge: a busport does not change when a board comes -# back on the same port, so the HUNG reflash this branch performs would recover a -# board the harness could then never see again. -_sysfs_stranded: dict = {} -# A stranded path whose inode could not be read is stored as None, so a plain .get() cannot -# tell 'known stranded, inode unknown' from 'never seen' -- and treating the first as the -# second re-reads it, stranding another permanent thread and fd every call. Distinct miss -# sentinel, so None keeps its own meaning. -_STRAND_MISS = object() - - -def usb_scan(vid_pid=None, serial=None, vid=None) -> tuple[list, bool]: - """Enumerated USB devices matching the filters, and whether anything is unknown. - - Returns ([{busport, dir, vid, pid, serial}], unknown). `unknown` True means a bounded - read did not answer, so absence is NOT proven -- the same contract as read_sysfs. +def usb_scan(vid_pid=None, serial=None, vid=None, timeout=SYSFS_READ_GRACE) -> list: + """Enumerated USB devices matching the filters: [{busport, dir, vid, pid, serial}]. Three rules, one implementation for every caller: * Root hubs excluded (glob `*-*`): no DUT is one, and scans including them measured seconds slower (observation, no mechanism -- the "autosuspend wake" explanation was - wrong; usb_string_attr reads a cached string, sysfs.c:124-139). + wrong; usb_string_attr reads a cached string, sysfs.c:141-143). * idVendor/idProduct first: lock-free `sysfs_emit` from udev->descriptor (sysfs.c:688-705), so they rule out nearly every device for free. - * `serial` last and bounded: it is served under the lock a wedged ioctl holds, and a - path that already stranded is never re-read (each strand costs a thread and an fd - for this process's life). + * `serial` LAST and BOUNDED: it is the only attribute here served under the device + lock, so it is the only one that can block. Filtering on the lock-free pair first + keeps most devices out of it, but a scan for ONE board still reads the serial of + every peer that shares its VID -- so the bound is what stops one wedged DUT from + stalling every caller (see read_sysfs). """ out = [] - unknown = False for d in glob.glob('/sys/bus/usb/devices/*-*'): - # Interfaces are '<busport>:<cfg>.<ifnum>' (e.g. 2-4:1.0) -- they CONTAIN the - # colon, they do not end with it, so the original endswith() never fired and every - # scan opened idVendor/idProduct on all of them (measured: 31 of 44 matches). + # `in`, not endswith: an interface is '<busport>:<cfg>.<ifnum>' (2-4:1.0), which + # CONTAINS the colon rather than ending with it. Screening them out here is worth + # real time -- they were 31 of 44 matches on this rig. if ':' in os.path.basename(d): continue try: @@ -336,106 +359,14 @@ def usb_scan(vid_pid=None, serial=None, vid=None) -> tuple[list, bool]: continue # ruled out for free, without touching the locked attribute if vid is not None and dev_vid != vid: continue # same, for callers that know the VID but not the PID - sn = read_sysfs(os.path.join(d, 'serial')) - if sn is SYSFS_UNKNOWN: - unknown = True # read_sysfs memoises it; a repeat scan costs nothing - continue + sn = read_sysfs(os.path.join(d, 'serial'), timeout) if sn is None: - continue # no serial attribute: a fact + continue # no serial attribute if serial is not None and sn.lower() != serial.lower(): continue out.append({'busport': os.path.basename(d), 'dir': d, 'vid': dev_vid, 'pid': dev_pid, 'serial': sn}) - return out, unknown - - -def bounded_open(path: str, flags: int, timeout: float = SYSFS_READ_GRACE): - """os.open() with a wall-clock bound. - - The fd, None when the open genuinely FAILED (OSError: EBUSY, ENOENT, EACCES), or - SYSFS_UNKNOWN when it did not answer -- the same three-valued contract as read_sysfs, - and for the same reason: folding a fact into an unknown made an ordinary EBUSY read as - a wedged device and sent the operator hunting hardware that is healthy. - - An open CAN block on a wedged device -- not on O_NONBLOCK, which usblp_open never - consults, but on usb_autopm_get_interface(), a runtime-PM resume that does I/O - (v6.12.96 drivers/usb/class/usblp.c). It holds usblp_mutex while it waits, and that - mutex is driver-GLOBAL, so one wedged printer blocks opens of every usblp node. - - Unlike read_sysfs the stranded thread cleans up after itself: if we have given up it - closes the fd it eventually got, so only the thread leaks. Both sides take `handoff` - -- "store or close" and "abandon and drain" are a check-then-act pair that can - interleave into an fd stored after the box was drained, which would leak it into a - node that allows a SINGLE opener (usblp_open returns -EBUSY when usblp->used). - """ - # Same short-circuit as read_sysfs: once blind, another stranded thread buys nothing - # and the cap exists precisely to stop them accumulating. - if sysfs_blind(): - return SYSFS_UNKNOWN - # Known-stranded? Re-opening costs another thread, another fd and another blindness - # credit to learn what we already know -- and the printer test re-opens ONE lp node on - # every retry. Same memo and same inode check as read_sysfs. - was = _sysfs_stranded.get(path, _STRAND_MISS) - if was is not _STRAND_MISS: - if was is None: - return SYSFS_UNKNOWN # stranded, inode unknown: never re-read it - try: - if os.stat(path).st_ino == was: - return SYSFS_UNKNOWN - except OSError: - pass - _sysfs_stranded.pop(path, None) - box: dict = {} - done, abandoned = threading.Event(), threading.Event() - handoff = threading.Lock() - - def _open(): - try: - fd = os.open(path, flags) - except OSError: - done.set() - return - with handoff: - stored = not abandoned.is_set() - if stored: - box['fd'] = fd - if not stored: - try: - os.close(fd) - except OSError: - pass - done.set() - - threading.Thread(target=_open, daemon=True).start() - if not done.wait(timeout): - with handoff: - abandoned.set() - fd = box.pop('fd', None) # completed in the gap between timeout and flag - if fd is not None: - # It DID open, just after our deadline -- the thread finished, so nothing is - # stranded. Report unknown (we already gave up on it) but do not spend a - # blindness credit, and do not call a merely-slow node wedged. - try: - os.close(fd) - except OSError: - pass - return SYSFS_UNKNOWN - # counted like a stranded read_sysfs: the thread and (eventually) its fd are gone - # for the life of the process, and the cap exists to stop that reaching the - # thread/fd ceiling -- an exception there escapes the worker and loses every board. - # Memoised by inode so a retry of the same node does not pay again. - # same lock as read_sysfs, same reason - with _sysfs_stuck_lock: - first = path not in _sysfs_stranded - if first: - try: - _sysfs_stranded[path] = os.stat(path).st_ino - except OSError: - _sysfs_stranded[path] = None - if first: - note_sysfs_strand() - return SYSFS_UNKNOWN - return box.get('fd') + return out def _close_pipes(p: subprocess.Popen) -> None: @@ -478,7 +409,7 @@ def run_alongside(argv: list, work, timeout: int) -> subprocess.CompletedProcess except OSError: p.kill() try: - out, err = p.communicate(timeout=5) + out, err = p.communicate(timeout=REAP_GRACE) except subprocess.TimeoutExpired: # Outlasted SIGKILL: uninterruptible, still holding whatever it opened. # Abandoned like any other stray -- but as a real child in its own @@ -575,7 +506,7 @@ def run_cmd(cmd: str | list, cwd: str | None = None, timeout: int | None = None, # close and the rc-124 return this handler exists for. pass try: - out, err = p.communicate(timeout=10) + out, err = p.communicate(timeout=REAP_GRACE) except subprocess.TimeoutExpired: # Something in the group outlived SIGKILL: D state (truly unkillable), or # root-owned because sudo FORKS rather than execs, so the wrapper dies and its diff --git a/test/hil/hil_flash.py b/test/hil/hil_flash.py index c4d4e6552..15f476ccd 100755 --- a/test/hil/hil_flash.py +++ b/test/hil/hil_flash.py @@ -237,7 +237,7 @@ def convoy_safe(flasher: dict) -> bool: return True # EXACT, not startswith: rescue_openocd and usbtest's # getattr(hil_flash, f'flash_{name}') both require the exact name, so an - # 'openocd_wch'-style entry would pass this gate, reserve USBTEST_RECOVERY_BUDGET, + # 'openocd_wch'-style entry would pass this gate, reserve the Rescue-DP legs, # and then find no recovery path at all -- paying for a path that cannot fire, which # is the precise cost this gate exists to avoid. if name != 'openocd': @@ -270,7 +270,7 @@ def flash_esptool(board: Board, firmware: str, timeout=None) -> subprocess.Compl def reset_esptool(board): # NO-OP, and marked as one: esptool's reset would be `--after hard_reset`, which is not # wired here. Returning rc 0 without resetting is why callers must never read the exit - # code as proof -- recovery_steps skips a primitive carrying `no_op`. + # code as proof -- usbtest's recovery skips a primitive carrying `no_op`. return subprocess.CompletedProcess(args=['dummy'], returncode=0) diff --git a/test/hil/hil_test.py b/test/hil/hil_test.py index 233627ec7..b2b74b13c 100755 --- a/test/hil/hil_test.py +++ b/test/hil/hil_test.py @@ -44,7 +44,6 @@ import itertools import os import random import re -import select import signal import shlex import sys @@ -64,6 +63,7 @@ from multiprocessing import TimeoutError as MpTimeoutError sys.path.insert(0, os.path.dirname(os.path.abspath(__file__))) # PYTHONSAFEPATH drops it import hil_flash +import usbtest # for the recovery bounds only; hil_test runs it as a subprocess from helper import hil_health, hil_lock, hil_report, hil_util from helper.hil_util import device_tests, dual_tests, host_test @@ -221,13 +221,17 @@ class HilConfig(TypedDict): POOL_TIMEOUT = hil_util.pos_int_env('HIL_POOL_TIMEOUT', 3600) -# Headroom on top of a battery's own budget so ONE HUNG recovery (case timeout, SIGKILL -# wait, bounded reflash, settle) can finish. Only spent when cases actually time out. -USBTEST_RECOVERY_BUDGET = hil_util.pos_int_env('HIL_USBTEST_RECOVERY_BUDGET', 250) +# The post-hang recovery reserve is PER BOARD and lives in usbtest.recovery_reserve(), +# derived from the ladder that file itself declares. Reserved whole, which is what lets the +# child run the ladder straight through instead of asking "does the next step still fit?" +# before each step. It only ELAPSES when cases actually time out; a healthy battery returns +# in ~200s and never touches it. + # How long usbtest.py may keep starting new cases (--budget). The outer run_cmd timeout is -# always this PLUS the recovery headroom, never a separate literal, or lowering one eats -# the reserve the recovery needs. 0 is refused (usbtest.py reads it as "no limit"); the -# margin over a healthy battery (~200s) keeps contention from becoming BUDGET entries. +# always this PLUS the overshoot PLUS the recovery reserve when one can run, never a +# separate literal, or lowering one eats the room the other needs. 0 is refused (usbtest.py +# reads it as "no limit"); the margin over a healthy battery (~200s) keeps contention from +# becoming BUDGET entries. USBTEST_BATTERY_BUDGET = hil_util.pos_int_env('HIL_USBTEST_BATTERY_BUDGET', 260) # The battery checks its budget BEFORE dispatching a case, so it can overshoot by one @@ -235,9 +239,9 @@ USBTEST_BATTERY_BUDGET = hil_util.pos_int_env('HIL_USBTEST_BATTERY_BUDGET', 260) # as it goes to print its JSON, turning ~29 real per-case verdicts into "usbtest did not # run" and re-paying the whole battery on retry. # Worst case, from usbtest.py: --timeout 60 (the case) + 5s post-SIGKILL reap + -# dmesg_tail(), which is bounded by HELPER_TIMEOUT=30 and runs on BOTH the FAIL and HUNG -# timeout paths = 95s. 120 leaves a margin; 75 (my first estimate, taken before checking -# dmesg_tail) was 20s SHORT and would have killed the battery mid-print. +# dmesg_tail(), bounded by HELPER_TIMEOUT=30 and run on BOTH the FAIL and HUNG timeout +# paths = 95s. 120 leaves a margin. Re-derive it if any of those three moves -- dmesg_tail +# is the one easily missed, and without it the estimate lands 20s short. USBTEST_OVERSHOOT = 120 # Named, not a literal, so the unit tests can zero it: every test that drives # test_device_usbtest against a fake rig otherwise pays a real 3s (ten of them, 30s a run). @@ -408,6 +412,30 @@ try: finally: h.close() """ +# The write half, same shape and same reason: usblp_open() ignores O_NONBLOCK and stalls in +# usb_autopm_get_interface() on a wedged device, holding the driver-global usblp_mutex. A +# blocked THREAD cannot be abandoned without keeping the fd, and usblp allows a single opener +# (v6.12.96 usblp.c), so the next open of this node returns -EBUSY for the life of the worker. +# A killed process takes its fd with it. O_NONBLOCK is kept because usblp DOES honour it on +# write, which is what the select()/partial-write loop below relies on. +LP_WRITER = ( + 'import os, random, select, sys\n' + 'lp, payload_path, ready = sys.argv[1], sys.argv[2], sys.argv[3]\n' + 'data = open(payload_path, "rb").read()\n' + 'fd = os.open(lp, os.O_WRONLY | os.O_NONBLOCK)\n' + # readiness marker, as in LP_READER: the parent must not read CDC before the node is open + 'open(ready, "w").close()\n' + 'off = 0\n' + 'while off < len(data):\n' + ' n = min(random.randint(1, 64), len(data) - off)\n' + ' buf, w = data[off:off + n], 0\n' + ' while w < len(buf):\n' + ' _, wr, _ = select.select([], [fd], [], 5.0)\n' + ' if not wr:\n' + ' sys.exit("printer write timeout (firmware not draining OUT endpoint)")\n' + ' w += os.write(fd, buf[w:])\n' + ' off += n\n' +) MTYPE_TIMEOUT = 30 # a README-sized read is <1 s; bounds a D-state hang on a wedged device @@ -461,12 +489,8 @@ def get_printer_dev(id: str, vendor_str, product_str, ifnum: int): product_str = product_str.replace(' ', '_') if product_str else '' for lp in glob.glob('/sys/class/usbmisc/lp*'): try: - # bounded: same device_lock() exposure as the sibling reads (see read_sysfs) sn = hil_util.read_sysfs(f'{lp}/device/../serial') - # UNKNOWN is not None: the sentinel has no __eq__, so an unanswered read - # would fall through both tests and read as 'not this board' -- the exact - # absence/unknown conflation read_sysfs exists to prevent. - if sn is None or sn is hil_util.SYSFS_UNKNOWN: + if sn is None: continue if sn == id: return f'/dev/usb/{os.path.basename(lp)}' @@ -483,7 +507,7 @@ def open_printer_dev(id: str, vendor_str, product_str, ifnum: int) -> str: lp_dev = wait_until(try_find) assert lp_dev, (f'Printer device not found for {id} if{ifnum:02d}' - + hil_util.sysfs_blind_note()) + + hil_util.strand_note()) return lp_dev @@ -882,9 +906,9 @@ def test_device_cdc_msc_freertos(board): def link_is_fs(speed) -> bool: - """Payload scaling from a `speed` attribute. Anything not positively read as high speed - counts as FS -- including None and SYSFS_UNKNOWN: the FS payload merely tests an HS - board less, while the HS payload hard-fails a healthy FS board.""" + """Payload scaling from a `speed` attribute. Anything not positively read as high + speed counts as FS, None included: the FS payload merely tests an HS board less, while + the HS payload hard-fails a healthy FS board.""" return speed not in ('480', '5000', '10000') @@ -923,16 +947,15 @@ def test_device_cdc_msc_throughput(board): # Detect speed (12 Mbps FS / 480 Mbps HS) for payload scaling; a device we never find # keeps the FS payload (see link_is_fs) - # usb_scan, not a private glob: it skips root hubs and remembers paths that already - # stranded, so one wedged peer cannot spend this worker's blindness budget four reads - # at a time. + # usb_scan, not a private glob: it skips root hubs and filters on the lock-free + # descriptor pair before touching `serial`. is_fs = True speed_known = False - devs, _ = hil_util.usb_scan(vid='cafe', serial=uid) + devs = hil_util.usb_scan(vid='cafe', serial=uid) if devs: speed = hil_util.read_sysfs(os.path.join(devs[0]['dir'], 'speed')) is_fs = link_is_fs(speed) - speed_known = speed not in (None, hil_util.SYSFS_UNKNOWN) + speed_known = speed is not None # Put tty in raw mode so dd sees pure binary throughput. rs = hil_util.run_cmd(f'timeout 30 stty -F {tty} raw -echo') @@ -1105,45 +1128,81 @@ def test_device_printer_to_cdc(board): ser.reset_input_buffer() # Test 1: Printer -> CDC with multiple sizes, write in random 1-64 byte chunks - LP_WRITE_TIMEOUT = 5.0 # seconds; firmware may stall draining the printer OUT endpoint + # The write runs in a PROCESS for the same reason the read below does: see LP_WRITER. for size in sizes: test_data = rand_ascii(size) ser.reset_input_buffer() - rd = b'' - offset = 0 - # bounded: O_NONBLOCK does NOT save us -- usblp_open() takes the device mutex - # first -- and this open runs on the worker itself, with no thread to abandon - lp_fd = hil_util.bounded_open(lp_dev, os.O_WRONLY | os.O_NONBLOCK, 5) - # Three-valued on purpose: an OSError here is a FACT about the node (EBUSY from - # usblp's single-opener rule, ENOENT from a re-enumeration race, EACCES from a - # udev gap) and must not be reported as a wedge -- that sends the operator to - # usb-kernel-recover for hardware that is fine. - assert lp_fd is not hil_util.SYSFS_UNKNOWN, ( - f'printer: opening {lp_dev} for write blocked (device wedged)' - f'{hil_util.sysfs_blind_note()}') - assert lp_fd is not None, f'printer: {lp_dev} could not be opened for write' + rd = bytearray() + + payload = Path(tempfile.gettempdir()) / f'hil-lp-tx-{os.getpid()}-{size}' + ready = Path(tempfile.gettempdir()) / f'hil-lp-ready-{os.getpid()}-{size}' + payload.write_bytes(test_data) + ready.unlink(missing_ok=True) + # +5 like write_cdc's sibling wait below: the bound is on the OPEN, and the child + # must first fork, exec and boot CPython, which on a loaded rig routinely exceeds + # LP_OPEN_TIMEOUT on its own. A tighter wait here reports a slow interpreter start + # as a wedged node. + open_deadline = time.monotonic() + LP_OPEN_TIMEOUT + 5 + saw_ready = False + + def read_cdc(): + # WAIT for the writer to have the node open, as Test 2's write_cdc does: the + # child has to fork, exec and boot CPython, and reading before it starts just + # burns the serial timeout. + # ONE deadline, shared with the child's bound below. Two different ones let + # the writer open after the parent gave up: it writes the whole payload with + # nobody reading, exits 0, and the byte-compare reports FIRMWARE DATA + # CORRUPTION for a board whose only problem was a slow open. + nonlocal saw_ready + while not ready.exists(): + if time.monotonic() > open_deadline: + return # never opened; the assert below reports THAT, not data + time.sleep(0.02) + saw_ready = True + # fullspeed devices may need extra time; ser.read is bounded by + # SERIAL_READ_TIMEOUT, so an empty return means the stream went quiet + while len(rd) < size: + chunk = ser.read(size - len(rd)) + if not chunk: + break + rd.extend(chunk) # in place: `rd +=` would rebind it as a local + try: - while offset < size: - chunk_size = min(random.randint(1, 64), size - offset) - buf = test_data[offset:offset + chunk_size] - written = 0 - while written < len(buf): - _, wr, _ = select.select([], [lp_fd], [], LP_WRITE_TIMEOUT) - assert wr, f'Printer write timeout after {LP_WRITE_TIMEOUT}s (firmware not draining OUT endpoint)' - n = os.write(lp_fd, buf[written:]) - written += n - rd += ser.read(chunk_size) - offset += chunk_size + r = hil_util.run_alongside( + [sys.executable, '-c', LP_WRITER, lp_dev, str(payload), str(ready)], + read_cdc, LP_OPEN_TIMEOUT + 12) finally: - os.close(lp_fd) - # read any remaining bytes (fullspeed devices may need extra time) - while len(rd) < size: - remaining = ser.read(size - len(rd)) - if not remaining: - break - rd += remaining - assert rd == test_data, (f'Printer->CDC wrong data ({size} bytes):\n' - f' expected: {test_data[:64]}\n received: {rd[:64]}') + ready.unlink(missing_ok=True) + payload.unlink(missing_ok=True) + # rc 124 is run_alongside's kill, i.e. the open blocked -- and stderr is EMPTY + # there, so without the fallback the cell reads 'failed (32 bytes, rc 124):' and + # nothing, for the one failure this conversion exists to contain. An OSError is a + # FACT about the node (EBUSY from usblp's single-opener rule, ENOENT from a + # re-enumeration race) and must not send the operator to usb-kernel-recover. + # The bound covers the open AND the whole write, so rc 124 alone does not mean a + # wedged node. `ready` is written on the line after os.open() returns, so its + # ABSENCE is what says the open never completed -- the case that sends an operator + # to usb-kernel-recover. Anything else killed on the bound was a slow drain. + detail = hil_util.cmd_stdout_text(r.stderr).strip()[:200] + # FIRST: a child that exited on its OWN carries the concrete errno, and only one + # we KILLED (rc 124) can be diagnosed as an open that never completed. Asserting + # the marker before this reported EBUSY/ENOENT as a wedged node -- the conflation + # the comment above exists to prevent. rc is in the message because a child killed + # by a signal leaves `detail` empty. + assert r.returncode in (0, 124), ( + f'Printer->CDC writer failed ({size} bytes, rc {r.returncode}): {detail}') + # saw_ready, not ready.exists(): a marker that appeared AFTER read_cdc gave up + # means the child wrote with nobody reading, and the byte-compare below would call + # that firmware data corruption. Report the slow open instead. + assert saw_ready, (f'printer: {lp_dev} was not opened for write within ' + f'{LP_OPEN_TIMEOUT + 5}s (device wedged, or the writer never ' + f'started); rc {r.returncode}') + assert r.returncode == 0, ( + f'Printer->CDC writer killed on its bound after opening {lp_dev} ' + f'(rc {r.returncode}): the firmware stopped draining the OUT endpoint') + assert bytes(rd) == test_data, (f'Printer->CDC wrong data ({size} bytes):\n' + f' expected: {test_data[:64]}\n' + f' received: {bytes(rd)[:64]}') # Test 2: CDC -> Printer with multiple sizes, write in random 1-64 byte chunks. # The lp read runs in a PROCESS, not a thread: /dev/usb/lp* blocks on read, usblp @@ -1437,31 +1496,26 @@ def test_device_usbtest(board): uid = board['uid'] def usbtest_enumerated(): - """True, False, or None when a bounded read did not answer -- absence unproven.""" # vid_pid FIRST: right after flashing, the previous example's enumeration (same # serial, different PID) can linger and would fail usbtest.py's lookup -- and # filtering on the two lock-free descriptor fields rules out every other device - # on the bus before the one read that can block. usb_scan memoises paths that - # already stranded, so one wedged peer cannot spend the blindness budget here. - devs, unknown = hil_util.usb_scan(vid_pid=('cafe', '4010'), serial=uid) - if devs: - return True - return None if unknown else False + # on the bus before the one read that can block. + return bool(hil_util.usb_scan(vid_pid=('cafe', '4010'), serial=uid)) end = time.monotonic() + enum_timeout() seen = usbtest_enumerated() - while time.monotonic() < end and seen is not True: + while time.monotonic() < end and not seen: time.sleep(0.2) seen = usbtest_enumerated() # fail before usbtest_permit: an absent device would otherwise queue on the battery # mutex for minutes behind real batteries just to have usbtest.py report "no device" - if seen is not True: + if not seen: # 0/30 rather than a bare cell: the battery never ran (30 = standard case count) - raise TestFail( - f'no cafe:4010 device with serial {uid}' if seen is False else - f'cannot tell whether cafe:4010 {uid} is present: the bounded sysfs reads did ' - f'not answer{hil_util.sysfs_blind_note()}', - metric=f'{hil_report.REPORT_CELL["fail"]} 0/30') + # maxtasksperchild=1, so this worker only ever handled THIS board: a give-up here + # is about this device. Without the caveat a wedged-but-present DUT reads as a + # positive absence claim -- the conflation this whole path exists to avoid. + raise TestFail(f'no cafe:4010 device with serial {uid}{hil_util.strand_note()}', + metric=f'{hil_report.REPORT_CELL["fail"]} 0/30') # settle: right after flashing the enumeration can bounce once (and on dual-port parts # the other port's stale node — same serial and PID — lingers), and testusb run into # that gap sees the device drop mid-case @@ -1481,8 +1535,9 @@ def test_device_usbtest(board): # Post-hang recovery reflashes the DUT through its own probe, NEVER a root-port cycle # (one board reached instead of every fixture under the port; see usb-kernel-recover). # _current_fw is the artifact test_example flashed for THIS test: re-deriving it from - # board['name'] reflashes the wrong build on variant-only boards. --outer-timeout lets - # usbtest skip a reflash it cannot finish before our run_cmd kill, which would orphan + # board['name'] reflashes the wrong build on variant-only boards. Our run_cmd bound + # below RESERVES the whole ladder (usbtest.recovery_reserve), which is what lets the + # child run it straight through without an outer kill landing mid-flash and orphaning # the flasher (own session) on the probe. Never under --skip-flash -- and say so: a # HUNG case then holds the DUT's usbfs lock for the rest of the run, and a probe reset # is no substitute (the DWC2 pullup survives a core halt). @@ -1494,14 +1549,12 @@ def test_device_usbtest(board): # same probe convoy-safely without changing how the board is normally flashed. _rec_flasher = hil_flash.recover_flasher(board) recovery = bool(_current_fw and not skip_flash and hil_flash.convoy_safe(_rec_flasher)) - # ONE bound, computed here and used for BOTH the child's --outer-timeout and our own - # run_cmd kill below. Three separate expressions disagreed: --skip-flash appended no - # --outer-timeout at all (usbtest reads 0 as "no limit"), and the no-recovery branch - # narrowed only the CHILD's view while run_cmd still waited the full reserve -- so a - # board that cannot recover held a pool worker AND its battery permit idle for - # USBTEST_RECOVERY_BUDGET it had no way to spend, under a usbtest width of 2. - outer = USBTEST_BATTERY_BUDGET + (USBTEST_RECOVERY_BUDGET if recovery - else USBTEST_OVERSHOOT) + # ONE bound: run_cmd's kill below. It carries the recovery reserve only when a + # recovery can actually run, and only what THIS flasher's ladder can spend -- a board + # that cannot recover used to hold a pool worker AND its battery permit idle for a + # reserve it had no way to spend, under a usbtest width of 2. + outer = USBTEST_BATTERY_BUDGET + USBTEST_OVERSHOOT + ( + usbtest.recovery_reserve(_rec_flasher) if recovery else 0) if _current_fw and skip_flash: print('note: --skip-flash disables usbtest hang recovery; a HUNG case will leave ' 'the device wedged until it is reflashed', flush=True) @@ -1510,12 +1563,11 @@ def test_device_usbtest(board): f'usbfs node, so usbtest hang recovery is disabled for {board["name"]}; a ' f'HUNG case will leave it wedged for the rest of the run', flush=True) if recovery: - # ship the RECOVERY flasher as `flasher`: usbtest.py, recovery_steps and - # convoy_safe all read board['flasher'], so substituting here keeps the entire - # child side unaware that a second roster entry exists + # ship the RECOVERY flasher as `flasher`: usbtest.py and convoy_safe both read + # board['flasher'], so substituting here keeps the entire child side unaware that + # a second roster entry exists rb = json.dumps({'name': board['name'], 'flasher': _rec_flasher}) cmd += f' --recover-board {shlex.quote(rb)} --recover-fw {shlex.quote(_current_fw)}' - cmd += f' --outer-timeout {outer}' # The reserve above USBTEST_BATTERY_BUDGET exists because the battery can overrun by # one already-started case, and a hang there needs room for the recovery (whose reflash # is bounded by usbtest.RECOVER_FLASH_TIMEOUT, not HIL_CMD_TIMEOUT). Without it run_cmd @@ -1579,7 +1631,7 @@ def _usbtest_verdict(board: Board, data: dict, out: str, passed: int, failed: in # in the caller, and the two diverge as soon as a roster carries the # optional `flasher_recover` key -- naming the wrong one sends the operator to the # wrong probe. The wording stays on what usbtest actually reported ("still wedged"), - # because unrecovered_hang is also set by the ambiguous/inconclusive aborts, where + # because unrecovered_hang is also set by the ambiguous abort, where # nothing hung and the old text was false on both clauses. board_wedged = (f'{board["name"]}: usbtest reports the device still wedged ' + (f'after a recovery reflash via {rec_flasher["name"]}' if recovery @@ -1590,7 +1642,7 @@ def _usbtest_verdict(board: Board, data: dict, out: str, passed: int, failed: in notrun = int(data.get('notrun', 0)) total = passed + failed + notrun if board_wedged and failed == 0 and notrun == 0: - # Every case passed and the device STILL wedged -- usbtest's inconclusive/ambiguous + # Every case passed and the device STILL wedged -- usbtest's ambiguous # abort fires after the last case, so nothing back-fills a BUDGET entry. Reporting # the pass would exit 0 with a D-state holder on the rig and the board absent from # the re-run spec. parsed=True: a retry re-pays the whole battery to re-observe a @@ -1855,10 +1907,9 @@ def _tests_for(board: Board) -> list: def test_board(board: Board) -> tuple: - # (name, err_count, failed_tests, rows, duration[, blind, strays]) -- the board-LOCKED - # early return is 5 wide, the normal one 7. _blind_note and _stray_note index 5 and 6 - # behind a len() guard, so a field inserted before them reads a WRONG SLOT rather than - # raising: a duration would report as a stray count. + # (name, err_count, failed_tests, rows, duration[, strays]) -- the board-LOCKED early + # return is 5 wide, the normal one 6. _stray_note reads index 5 behind a len() guard, + # so a field inserted anywhere before it silently reports a duration as a stray count. swept = False name = board['name'] flasher = board['flasher'] @@ -1984,12 +2035,10 @@ def test_board(board: Board) -> tuple: stray = hil_health.kill_own_children() swept = True - # LAST fields: whether this worker ran out of bounded-read budget, and what it could - # not kill. Only the worker can answer either -- the blindness latch is - # process-global and this is a separate process -- and the result tuple already - # crosses back, so no Manager round-trip. + # LAST field: what this worker could not kill. Only the worker can answer it, and + # the result tuple already crosses back, so no Manager round-trip. return (name, err_count, [] if board_wide_fail else sorted(set(failed_tests)), - rows, t_total, hil_util.sysfs_blind(), stray) + rows, t_total, stray) finally: # A raise skips the sweep above, and maxtasksperchild=1 retires this process # immediately afterwards -- reparenting its flasher to init and erasing the ppid @@ -2108,7 +2157,7 @@ def _stray_note(mret: list) -> str: runs AFTER accumulate_report on both abort paths, so a banner appended there was written to a variable nobody read again. """ - dirty = [(r[0], r[6]) for r in mret if len(r) > 6 and r[6]] + dirty = [(r[0], r[5]) for r in mret if len(r) > 5 and r[5]] if not dirty: return '' total = sum(n for _, n in dirty) @@ -2117,28 +2166,6 @@ def _stray_note(mret: list) -> str: f'{", ".join(f"{b} ({n})" for b, n in dirty)}.\n') -def _blind_note(mret: list) -> str: - """Name the boards whose worker went blind, for the report banner. - - A blind worker answers SYSFS_UNKNOWN for every attribute, so its "device not found" is - "could not tell". That already reaches the log and the per-cell failure text, but the - TABLE is what gets quoted -- and a red cell there is read as a broken board. Seen live - (run 31794359407): four workers blind, several cells red because of it, and a report - that said nothing. - - Per-board, not global: maxtasksperchild=1 gives every board a fresh worker, so a board - that ran on a healthy one is not smeared by a neighbour's wedge. Rows synthesised by - the timeout path are 5 fields wide and have nothing to report. - """ - blind = [r[0] for r in mret if len(r) > 5 and r[5]] - if not blind: - return '' - return (f'> **Not all verdicts are evidence.** {len(blind)} board(s) ran on a worker ' - f'that went blind on sysfs -- too many bounded reads stranded on a wedged ' - f'device -- so "not found" from them means "could not tell": ' - f'{", ".join(blind)}. See the usb-kernel-recover skill.\n') - - # containment paths print through hil_health._p: stdout may already be a dead pipe (a # dropped ssh session), and a BrokenPipeError there would skip os._exit _p = hil_health._p @@ -2236,8 +2263,8 @@ def _save_controller_hints(hints: dict, mret: list, uid_of: dict, cmap) -> None: merged = {k: v for k, v in cur.items() if isinstance(v, dict)} except (OSError, ValueError): pass - # onto what the CACHE now holds, not onto our startup snapshot: another HIL job may - # have written a newer duration/pci for these boards since we read it + # overlay onto what the CACHE now holds, not onto our startup snapshot: another HIL + # job may have written a newer duration/pci for these boards since we read it for name, *_ in mret: uid = uid_of.get(name) if uid is not None and uid in hints: @@ -2271,41 +2298,49 @@ def _abort_report(reason: str, mret: list, config_boards: list, failed_fname: Pa _write_failed_spec(failed_fname, report_dir, [(n, 1, [], None, 0) for n in stuck] + [r for r in mret if r[1] > 0]) - except Exception as werr: # noqa: BLE001 - it mkdir()s and open()s the report dir - # letting it raise here REPLACES the caller's RuntimeError, so the operator never - # sees the 'pool timed out' line and no report is written at all + except Exception as werr: # noqa: BLE001 - it mkdir()s and open()s the very report dir + # the fallback below is FOR an unwritable/root-owned report dir; letting the spec + # raise here replaces the caller's RuntimeError, so the operator never sees the + # 'pool timed out' line and no report is written at all print(f'warning: re-run spec failed: {type(werr).__name__}: {werr}', flush=True) banner = (f"**HIL run {reason}.** {len(mret)} board(s) below finished and are this " f"run's; {len(stuck)} never reported and are NOT in the table: " f"{', '.join(stuck)}. The re-run spec covers those.\n") try: hil_report.accumulate_report(mret, report_dir, fresh, '', - health_banner + _blind_note(mret) - + _stray_note(mret), caveat=banner) + health_banner + _stray_note(mret), caveat=banner) return except Exception as rerr: # noqa: BLE001 - the caller's raise must still happen print(f'warning: partial report failed: {type(rerr).__name__}: {rerr}' - + ('; falling back to the board list' if timeout_secs else ''), flush=True) - if timeout_secs is None: - return + + '; falling back to the board list', flush=True) try: + # banner=, or write_timeout_report's default caveat publishes 'No per-board + # results could be collected' onto a report where mret DID hold finished rows + # the CELL names the cause: a board the pool guard never reached did not + # "pool-timeout", and marking it so sends the reader after a guard that did not fire hil_report.write_timeout_report( report_dir, [b for b in config_boards if b['name'] in stuck], - timeout_secs, prefix=health_banner) + timeout_secs or 0, banner=banner, prefix=health_banner, + cell=(hil_report.POOL_TIMEOUT_CELL if timeout_secs + else hil_report.RUN_ABORTED_CELL)) except Exception as re2: # noqa: BLE001 print(f'warning: fallback report failed too: {type(re2).__name__}: {re2}', flush=True) -def _start_pool(seed: str, hints_by_uid: dict): - """(mgr, cmap, pool). Split out so main()'s try/finally reads as one shape. +def _start_pool(mgr, seed: str, hints_by_uid: dict): + """(cmap, pool). Split out so main()'s try/finally reads as one shape. + + The Manager is created by the CALLER and passed in: Pool() forks, and after a convoy + that fork is what hits EAGAIN/ENOMEM. Creating the Manager here too would leave main() + with `mgr` still None while a live SyncManager child exists -- os._exit skips its + finalizer and the orphan holds the runner's stdout, so the job step never completes. maxtasksperchild=1: a fresh worker per board makes cross-board contamination structural rather than dependent on every module global being reset by hand (board_wedged, _current_fw, hil_flash's warn-once sets). The extra fork is noise against a flash+test cycle. """ - mgr = Manager() cmap = mgr.dict() initargs = (Lock(), seed, hil_lock.make_permit_sems(Semaphore, hil_lock.USBTEST_PARALLEL), @@ -2313,7 +2348,7 @@ def _start_pool(seed: str, hints_by_uid: dict): cmap, Lock(), hints_by_uid) pool = Pool(processes=os.cpu_count() or 1, initializer=init_worker, initargs=initargs, maxtasksperchild=1) - return mgr, cmap, pool + return cmap, pool def main() -> None: @@ -2524,7 +2559,11 @@ def main() -> None: (report_dir / f).unlink(missing_ok=True) failed_fname.unlink(missing_ok=True) try: - mgr, cmap, pool = _start_pool(seed, hints_by_uid) + # BOUND FIRST, in main's own scope: a Pool fork failure inside _start_pool must + # still leave a live Manager reachable by the finally below, or its child is + # orphaned holding the runner's stdout. + mgr = Manager() + cmap, pool = _start_pool(mgr, seed, hints_by_uid) # OUTER: encloses the pool block too, not just the reporting below. An exception # escaping async_ret.get() (a worker exception, a Ctrl-C) runs the pool finally and # then propagates straight out of main(); with _abandon_exit in a sibling try it @@ -2565,20 +2604,16 @@ def main() -> None: err_count = build_err + sum(e[1] for e in mret) _write_failed_spec(failed_fname, report_dir, mret) finally: - # Not `with Pool(...)`: its __exit__ joins the workers unbounded, hanging on + # Not `with Pool(...)`: its __exit__ joins the workers unbounded and hangs on # any worker in uninterruptible sleep. shutdown_pool bounds the same terminate() - # by a grace period, so the pool is NOT cleanly closed/joined when it returns - # False. Record the outcome but never exit here: the report below is the only - # record of a run that otherwise passed. + # and returns False when the pool is NOT cleanly closed. # - # Same ordering as the timeout path: what the workers spawned must be - # snapshotted and killed while its parent is alive, or terminate() reparents it - # out of reach. + # Sweep BEFORE shutdown: what the workers spawned must be snapshotted and + # killed while its parent is alive, or terminate() reparents it out of reach. # - # Both calls must stay guarded: a raise here skips accumulate_report(), so a run - # whose boards ALL passed publishes an empty report dir -- and both can raise - # for reasons unrelated to the results. pool_abandoned stays fail-CLOSED, so - # _abandon_exit still arms. + # Both calls stay guarded and neither exits: a raise here would skip + # accumulate_report and publish an empty report dir for a run whose boards all + # passed. pool_abandoned is fail-CLOSED, so _abandon_exit still arms. try: # Still worth running for the TIMEOUT path, where the workers are # genuinely stuck mid-task and their children are still reachable through @@ -2623,8 +2658,7 @@ def main() -> None: scoped = sorted(set(args.board) | set(board_test)) scope = f'{len(scoped)} board(s) — {", ".join(scoped)}' if scoped else '' report = hil_report.accumulate_report(mret, report_dir, fresh, scope, - health_banner + _blind_note(mret) - + _stray_note(mret)) + health_banner + _stray_note(mret)) print() print(report) print(f'\nReport written to {(report_dir / hil_report.REPORT_MD).resolve()}') diff --git a/test/hil/test/stubs/hid.py b/test/hil/test/stubs/hid.py index e72aeea57..20a6cccef 100644 --- a/test/hil/test/stubs/hid.py +++ b/test/hil/test/stubs/hid.py @@ -47,6 +47,8 @@ class device: self._last = b'' def open(self, vid, pid, serial): + # HID_ECHO really does call this, and usb_autopm/hidraw can block in it, so the + # child must be bounded here too -- exercised by test_a_wedged_open_is_killed. if _MODE == 'wedged_open': while True: time.sleep(3600) diff --git a/test/hil/test/test_hil_bounded.py b/test/hil/test/test_hil_bounded.py index 6da65543f..c30c58cbd 100644 --- a/test/hil/test/test_hil_bounded.py +++ b/test/hil/test/test_hil_bounded.py @@ -39,7 +39,6 @@ serial_stub.SerialTimeoutException = type('SerialTimeoutException', (Exception,) sys.modules.setdefault('serial', serial_stub) import hil_flash import hil_test -from helper import hil_report def write_script(path: Path, body: str) -> None: @@ -151,37 +150,60 @@ class CompactOutput(unittest.TestCase): class UsbtestRecovery(unittest.TestCase): def test_recovery_flags_and_flash_bound_fit_the_reserve(self): """The post-hang reflash plumbing: the CLI flags exist, and the bounded reflash - plus the fixed recovery costs (60s case timeout + 5s kill wait + 5s settle) - fits inside USBTEST_RECOVERY_BUDGET -- otherwise the outer run_cmd kill lands - mid-flash and orphans the flasher (own session) on the probe.""" + and the reserve that pays for them is derived per flasher (see the two tests + below), not pinned.""" import subprocess hil_dir = Path(TEST_DIR).parents[0] r = subprocess.run([sys.executable, str(hil_dir / 'usbtest.py'), '--help'], capture_output=True, text=True, timeout=30) self.assertEqual(r.returncode, 0, r.stderr) - for flag in ('--recover-board', '--recover-fw', '--outer-timeout'): + for flag in ('--recover-board', '--recover-fw'): self.assertIn(flag, r.stdout) - def test_the_bounded_reflash_actually_fits_the_reserve(self): - """The arithmetic the docstring above claims but never checked -- the two - constants never met in any test, so bumping either silently broke the promise. - Overrun means run_cmd's outer kill lands MID-FLASH and orphans the flasher - (start_new_session, so killpg misses it) holding the probe.""" - import re + def test_the_reserve_covers_every_step_of_its_own_ladder(self): + """Enumerated from the SIDE EFFECTS usbtest performs, so dropping a step from + recovery_reserve() fails here. Overrun means run_cmd's outer kill lands MID-FLASH + and orphans the flasher (start_new_session, so killpg misses it) on the probe. + """ import usbtest - hil_dir = Path(TEST_DIR).parents[0] - # read the case timeout hil_test actually passes, so this cannot drift silently - src = (hil_dir / 'hil_test.py').read_text() - m = re.search(r'--timeout (\d+) --budget', src) - self.assertIsNotNone(m, 'usbtest invocation changed shape; re-derive this bound') - case_timeout = int(m.group(1)) - kill_wait, settle, time_left_reserve = 5, 5, 35 # usbtest.py's fixed costs - worst = (case_timeout + kill_wait + usbtest.RECOVER_FLASH_TIMEOUT - + settle + time_left_reserve) - self.assertLessEqual( - worst, hil_test.USBTEST_RECOVERY_BUDGET, - f'a HUNG case needs {worst}s to recover but only ' - f'{hil_test.USBTEST_RECOVERY_BUDGET}s is reserved') + from helper import hil_util as _hu + # each bounded step costs its timeout PLUS run_cmd's post-SIGKILL reap + flash = usbtest.RECOVER_FLASH_TIMEOUT + _hu.REAP_GRACE + reset = usbtest.RECOVER_RESET_TIMEOUT + _hu.REAP_GRACE + fixed = 2 * usbtest.RECOVER_SETTLE + usbtest.RECOVER_OVERHEAD + rp = {'name': 'openocd', 'args': '-f target/rp2040.cfg'} + for flasher, steps in ( + # an RP openocd board: reset, reflash, then Rescue-DP POR + one retry + (rp, reset + flash + 2 * flash + fixed), + # openocd on a NON-RP target: rescue_openocd has no RESCUE_CFG entry for + # it, so its two legs are time the board can never spend + ({'name': 'openocd', 'args': '-f target/wch-riscv.cfg'}, + reset + flash + fixed), + # esptool: reset_esptool is a stub (no_op) and rescue refuses a + # non-openocd flasher, so ONE reflash is all it can ever spend + ({'name': 'esptool', 'args': ''}, flash + fixed)): + self.assertEqual(usbtest.recovery_reserve(flasher), steps, + f'{flasher} reserves time it cannot spend, or too little') + + def test_the_reserve_leaves_room_for_the_work_no_step_bounds(self): + """The ladder's step timeouts do not cover the two /proc walks, the roster + json.loads, the child's first import, or the JSON print. With zero margin any + env-overridable bound moving up puts the outer killpg inside the reflash.""" + import usbtest + self.assertGreater(usbtest.RECOVER_OVERHEAD, 0) + rp = {'name': 'openocd', 'args': '-f target/rp2350.cfg'} + bounded = (usbtest.RECOVER_RESET_TIMEOUT + 3 * usbtest.RECOVER_FLASH_TIMEOUT) + self.assertGreaterEqual(usbtest.recovery_reserve(rp) - bounded, + usbtest.RECOVER_OVERHEAD, + 'the reserve equals its own worst case with no margin') + + def test_a_flasher_reserves_nothing_for_a_rescue_it_cannot_run(self): + """rescue_openocd returns False for anything but openocd, so reserving its two + legs elsewhere holds a pool worker AND a usbtest permit for 200s of dead time.""" + import usbtest + self.assertLess(usbtest.recovery_reserve({'name': 'esptool', 'args': ''}), + usbtest.recovery_reserve({'name': 'openocd', + 'args': '-f target/rp2040.cfg'})) class UsbtestRunHelper(unittest.TestCase): @@ -414,185 +436,9 @@ class ConvoySafeFlasher(unittest.TestCase): self.assertFalse(self.f(flasher)) -class BoundedOpen(unittest.TestCase): - """hil_util.bounded_open must return rather than block, and must not leak the fd if - the open completes after we gave up (usblp_open takes the device mutex before it - consults O_NONBLOCK, so a wedged node blocks the open uninterruptibly).""" - - def setUp(self): - from helper import hil_util - self.hil_util = hil_util - self.tmp = TemporaryDirectory() - self.addCleanup(self.tmp.cleanup) - # bounded_open counts its stranded threads now, and the counter is process-global - # with no decrement: three wedged-FIFO tests here reach SYSFS_STUCK_MAX and every - # later test in this file reads SYSFS_UNKNOWN for perfectly good attributes - self.addCleanup(setattr, hil_util, '_sysfs_stuck', hil_util._sysfs_stuck) - - def test_opens_a_normal_file(self): - f = Path(self.tmp.name) / 'plain' - f.write_text('x') - fd = self.hil_util.bounded_open(str(f), os.O_RDONLY, 5) - self.assertIsNotNone(fd) - os.close(fd) - - def test_missing_path_returns_none_without_raising(self): - self.assertIsNone(self.hil_util.bounded_open( - str(Path(self.tmp.name) / 'nope'), os.O_RDONLY, 5)) - - def test_blocking_open_gives_up_and_does_not_leak_fds(self): - """A reader-less FIFO blocks open(O_WRONLY) forever -- the closest portable - stand-in for a wedged usblp node.""" - fifo = Path(self.tmp.name) / 'fifo' - os.mkfifo(fifo) - before = len(os.listdir('/proc/self/fd')) - t0 = time.monotonic() - for _ in range(5): - self.assertIs(self.hil_util.bounded_open(str(fifo), os.O_WRONLY, 0.2), - self.hil_util.SYSFS_UNKNOWN) - self.assertLess(time.monotonic() - t0, 10, 'bounded_open did not bound') - self.assertLessEqual(len(os.listdir('/proc/self/fd')) - before, 1, - 'bounded_open leaked fds on the blocking path') - - def test_open_completing_during_the_abandon_does_not_leak(self): - """The window the handoff lock exists for: the worker is at its store-or-close - decision when the caller gives up and drains the box. - - The `abandoned` Event is instrumented to park the worker there, because timing - alone never reaches that window -- 1500 tries against the unlocked version leaked - nothing, so a test that merely completes the open late proves nothing. An empty - `hit` means the instrumentation no longer bites and the window is untested.""" - hil_util = self.hil_util - fifo = Path(self.tmp.name) / 'fifo' - os.mkfifo(fifo) - caller = threading.current_thread() - drained, hit = threading.Event(), [] - - class RacingEvent(threading.Event): - def is_set(self): - v = super().is_set() - if not v and not hit and threading.current_thread() is not caller: - hit.append(True) - # bounded: the fixed bounded_open holds the lock across this call, so - # the caller cannot reach its abandon (and set drained) until we return - drained.wait(0.3) - return v - - shim = types.ModuleType('threading_shim') - shim.__dict__.update(threading.__dict__) - shim.Event = RacingEvent - hil_util.threading = shim - self.addCleanup(setattr, hil_util, 'threading', threading) - - before = len(os.listdir('/proc/self/fd')) - rd = os.open(fifo, os.O_RDONLY | os.O_NONBLOCK) # the O_WRONLY open completes at once - try: - self.assertIs(hil_util.bounded_open(str(fifo), os.O_WRONLY, 0.05), - hil_util.SYSFS_UNKNOWN) - drained.set() - time.sleep(0.1) # let an abandoned worker act on what it saw - self.assertTrue(hit, 'the abandon window was never entered') - self.assertLessEqual(len(os.listdir('/proc/self/fd')) - before, 1, - 'bounded_open stored the fd after the caller drained the box') - finally: - drained.set() - os.close(rd) - - -class SysfsUnknownIsNotAbsent(unittest.TestCase): - """read_sysfs must tell "no such attribute" (a fact) from "the read did not answer" - (not a fact). Every caller that concluded absence from the latter reported a healthy - board as a firmware regression.""" - - def setUp(self): - from helper import hil_util - self.hil_util = hil_util - self.saved = (hil_util._sysfs_stuck, hil_util._sysfs_blind_logged) - self.tmp = TemporaryDirectory() - self.addCleanup(self.tmp.cleanup) - - def tearDown(self): - # a blocked read strands a counted daemon thread; leaving the count raised would - # blind every later test in this process - self.hil_util._sysfs_stuck, self.hil_util._sysfs_blind_logged = self.saved - - def test_readable_attribute_returns_its_value(self): - p = Path(self.tmp.name) / 'serial' - p.write_text('CAFE01\n') - self.assertEqual(self.hil_util.read_sysfs(str(p)), 'CAFE01') - - def test_missing_attribute_is_none(self): - self.assertIsNone(self.hil_util.read_sysfs(str(Path(self.tmp.name) / 'nope'))) - - def test_blocking_read_is_unknown_not_absent(self): - """A reader-less FIFO stands in for the wedged device whose sysfs read never - returns; None here would read as "the board is gone".""" - fifo = Path(self.tmp.name) / 'fifo' - os.mkfifo(fifo) - t0 = time.monotonic() - v = self.hil_util.read_sysfs(str(fifo), grace=0.3) - self.assertLess(time.monotonic() - t0, 10, 'read_sysfs did not bound') - self.assertIs(v, self.hil_util.SYSFS_UNKNOWN) - self.assertIsNotNone(v) - - def test_blind_process_answers_unknown_for_a_readable_attribute(self): - p = Path(self.tmp.name) / 'serial' - p.write_text('CAFE01') - self.hil_util._sysfs_stuck = self.hil_util.SYSFS_STUCK_MAX - self.assertTrue(self.hil_util.sysfs_blind()) - self.assertIs(self.hil_util.read_sysfs(str(p)), self.hil_util.SYSFS_UNKNOWN) - self.assertIn('blind', self.hil_util.sysfs_blind_note()) - - def test_unknown_is_falsy_but_not_none(self): - # call sites use `(v or '')` idioms; the sentinel must keep working there while - # still being distinguishable from a real absence - self.assertFalse(self.hil_util.SYSFS_UNKNOWN) - self.assertIsNotNone(self.hil_util.SYSFS_UNKNOWN) - - -class UsbtestEnumerationVerdict(unittest.TestCase): - """test_device_usbtest must not report a healthy board as "no cafe:4010 device" just - because its own sysfs reads stopped answering.""" - - def setUp(self): - from helper import hil_util - self.hil_util = hil_util - self.td = TemporaryDirectory() - self.addCleanup(self.td.cleanup) - # a real device dir: usb_scan reads idVendor/idProduct with a plain open (they are - # lock-free descriptor fields), and only `serial` through the bounded reader - dev = Path(self.td.name) / '1-2' - dev.mkdir() - (dev / 'idVendor').write_text('cafe\n') - (dev / 'idProduct').write_text('4010\n') - (dev / 'serial').write_text('CAFE01\n') - for obj, name, val in ((hil_util, 'read_sysfs', hil_util.read_sysfs), - (hil_util, 'glob', hil_util.glob), - (hil_util, '_sysfs_stranded', {}), - (hil_test, '_enum_timeout', 1)): - self.addCleanup(setattr, obj, name, getattr(obj, name)) - setattr(obj, name, val) - hil_util.glob = types.SimpleNamespace(glob=lambda pat: [str(dev)]) - - def _fail(self, reader): - self.hil_util.read_sysfs = reader - with self.assertRaises(hil_test.TestFail) as cm: - hil_test.test_device_usbtest({'uid': 'CAFE01', 'name': 'fake', 'flasher': {}}) - return str(cm.exception) - - def test_unknown_reads_do_not_claim_the_device_is_absent(self): - msg = self._fail(lambda p, *a, **kw: self.hil_util.SYSFS_UNKNOWN) - self.assertNotIn('no cafe:4010 device', msg) - self.assertIn('did not answer', msg) - - def test_a_readable_bus_without_the_device_still_says_absent(self): - msg = self._fail(lambda p, *a, **kw: 'OTHERUID') - self.assertIn('no cafe:4010 device', msg) - - class UnresolvedControllerBucket(unittest.TestCase): """An unresolved controller must budget in ONE bucket. Taking a permit on every slot - serialized the whole fleet the moment a worker went blind.""" + serialized the whole fleet the moment a single board could not be resolved.""" def setUp(self): import threading @@ -652,8 +498,7 @@ class ThroughputPayloadBound(unittest.TestCase): payload actually requested.""" def test_only_a_read_high_speed_gets_the_big_payload(self): - from helper import hil_util - for speed in (None, hil_util.SYSFS_UNKNOWN, '12', '1.5'): + for speed in (None, '12', '1.5'): self.assertTrue(hil_test.link_is_fs(speed), f'{speed!r} must scale as FS') for speed in ('480', '5000', '10000'): self.assertFalse(hil_test.link_is_fs(speed)) @@ -710,61 +555,6 @@ class FindDeviceCache(unittest.TestCase): self.assertEqual(self.usbtest.find_device('BBBB')['sysname'], '1-3') -class EnumPollDoesNotReReadAWedgedPath(unittest.TestCase): - """usbtest_enumerated re-globs every device each 0.2 s pass. One wedged peer therefore - strands a fresh bounded reader thread per pass, and SYSFS_STUCK_MAX=4 of those blind - the WHOLE worker for the rest of the run -- measured at 8 s of polling. A path that - already stranded is known-unknown; reading it again buys nothing and costs the - blindness budget.""" - - def test_a_stranded_path_is_read_at_most_once(self): - from contextlib import contextmanager - from helper import hil_lock, hil_util - - td = TemporaryDirectory() - self.addCleanup(td.cleanup) - # A REAL device dir: usb_scan reads idVendor/idProduct with a plain open and - # `continue`s on OSError, so a bare FIFO is skipped before the bounded read is ever - # reached -- this test passed identically with the memo deleted until the ids were - # added. The FIFO must be the `serial` of a device that survives the cheap filter. - devdir = Path(td.name) / '1-2' - devdir.mkdir() - (devdir / 'idVendor').write_text('cafe\n') - (devdir / 'idProduct').write_text('4010\n') - wedged = devdir / 'serial' - os.mkfifo(wedged) # open() blocks forever: no writer, ever - - def patch(obj, name, value): - self.addCleanup(setattr, obj, name, getattr(obj, name)) - setattr(obj, name, value) - - def _permit(uid): - yield - - from helper import hil_util as _hu2 - patch(_hu2, 'glob', types.SimpleNamespace(glob=lambda p: [str(devdir)])) - patch(_hu2, '_sysfs_stranded', {}) - patch(hil_lock, 'usbtest_permit', contextmanager(_permit)) - # Long enough for several 2 s reads, but under the blindness cap -- past the cap - # sysfs_blind() short-circuits reads on its own and would mask the memo entirely. - patch(hil_test, '_enum_timeout', 8) - # the blindness counter is process-global and never decrements: restore it or this - # test blinds every test that runs after it - patch(hil_util, '_sysfs_stuck', hil_util._sysfs_stuck) - - # Count LEAKED THREADS, not _sysfs_stuck: a strand is booked only the first time a - # path is seen, so the counter is deduped by the memo's own bookkeeping and stays 1 - # even when the memo is broken. Each re-read blocks a fresh thread on the FIFO - # forever and leaks its fd -- which is the cost the memo exists to avoid, and the - # only thing here that actually moves when it regresses. - before = threading.active_count() - with self.assertRaises(hil_test.TestFail): # never enumerates, by construction - hil_test.test_device_usbtest({'name': 'b', 'uid': 'UID1', - 'flasher': {'name': 'openocd'}}) - self.assertLessEqual(threading.active_count() - before, 1, - 'the poll re-read a path it already knew was stranded') - - class ReRunSpecNamesOnlyWhatFailed(unittest.TestCase): """The pool-guard path used to leave this unwritten -- and a fresh run has already unlinked it -- so build.yml's re-run step found nothing and GitHub re-tested all ~26 @@ -817,44 +607,6 @@ class WedgedPidsFailsClosed(unittest.TestCase): self.assertFalse(complete, 'a hidden holder was reported as absent') [email protected](sys.version_info < (3, 11), 'fake-pymtp steering needs PYTHONSAFEPATH') -class StrandMemoRemembersUnstattablePaths(unittest.TestCase): - """A stranded path whose inode could not be read is stored as None -- which dict.get() - also returns for a MISS. Testing `is not None` therefore treats 'known stranded' as - 'never seen', and every later call strands ANOTHER permanent thread and fd on a path we - already know is wedged. That is the exact unbounded growth SYSFS_STUCK_MAX exists to - stop, and it is invisible: `first = path not in _sysfs_stranded` is False, so the - blindness counter does not advance either.""" - - def setUp(self): - from helper import hil_util - self.hil_util = hil_util - self.addCleanup(hil_util._sysfs_stranded.clear) - hil_util._sysfs_stranded.clear() - self.addCleanup(setattr, hil_util, '_sysfs_stuck', hil_util._sysfs_stuck) - hil_util._sysfs_stuck = 0 - self.td = TemporaryDirectory(); self.addCleanup(self.td.cleanup) - self.fifo = os.path.join(self.td.name, 'serial') - os.mkfifo(self.fifo) # open() succeeds, read() never returns - - def test_an_unstattable_strand_is_not_re_read(self): - self.hil_util._sysfs_stranded[self.fifo] = None # as the record path stores it - before = threading.active_count() - self.assertIs(self.hil_util.read_sysfs(self.fifo, grace=0.5), - self.hil_util.SYSFS_UNKNOWN) - self.assertEqual(threading.active_count(), before, - 'a known-stranded path was re-read, stranding another thread') - - def test_a_live_strand_is_still_re_read_when_the_node_is_replaced(self): - """The memo must not become permanent blindness: a NEW inode at the same path is a - different device and has to be read.""" - self.hil_util._sysfs_stranded[self.fifo] = 999999999 # inode that is not this one - with open(os.path.join(self.td.name, 'other'), 'w') as f: - f.write('ok\n') - os.replace(os.path.join(self.td.name, 'other'), self.fifo) - self.assertEqual(self.hil_util.read_sysfs(self.fifo, grace=0.5), 'ok') - - class MtpGioOrdering(_MtpFakeRig, unittest.TestCase): """gio must not run until the device is READY. @@ -982,55 +734,6 @@ class RunWhileContract(unittest.TestCase): self.assertNotEqual(pgids['child'], os.getpgid(0)) -class StrandedPathMemoInvalidates(unittest.TestCase): - """The memo lives in read_sysfs, so every bounded reader gets it -- call-site memos - meant each new scanner had to remember (get_printer_dev and the throughput probe did - not). And it MUST expire on re-enumeration: the key is a bus path, which does not - change when a device comes back on the same port, so a memo that never invalidates - makes a board the branch's own HUNG reflash just recovered permanently invisible.""" - - def setUp(self): - from helper import hil_util - self.hil_util = hil_util - self.td = TemporaryDirectory() - self.addCleanup(self.td.cleanup) - for name in ('_sysfs_stranded', '_sysfs_stuck'): - self.addCleanup(setattr, hil_util, name, getattr(hil_util, name)) - hil_util._sysfs_stranded = {} - hil_util._sysfs_stuck = 0 - - def test_a_stranded_path_is_not_re_read(self): - f = Path(self.td.name) / 'serial' - os.mkfifo(f) # never answers - self.assertIs(self.hil_util.read_sysfs(str(f), 0.3), self.hil_util.SYSFS_UNKNOWN) - after_first = self.hil_util._sysfs_stuck - t0 = time.monotonic() - for _ in range(3): - self.assertIs(self.hil_util.read_sysfs(str(f), 0.3), - self.hil_util.SYSFS_UNKNOWN) - self.assertLess(time.monotonic() - t0, 0.3, 'the memo did not short-circuit') - self.assertEqual(self.hil_util._sysfs_stuck, after_first, - 'repeat reads spent more of the blindness budget') - - def test_re_enumeration_clears_it(self): - """A new device on the same busport gets a fresh sysfs node, hence a fresh inode. - Without this the memo outlives the wedge it recorded.""" - f = Path(self.td.name) / 'serial' - os.mkfifo(f) - self.assertIs(self.hil_util.read_sysfs(str(f), 0.3), self.hil_util.SYSFS_UNKNOWN) - f.unlink() - f.write_text('CAFE01\n') # same path, new inode = re-enumerated - self.assertEqual(self.hil_util.read_sysfs(str(f), 0.3), 'CAFE01', - 'a recovered device stayed invisible') - - def test_a_vanished_path_is_not_remembered_as_stranded(self): - f = Path(self.td.name) / 'serial' - os.mkfifo(f) - self.assertIs(self.hil_util.read_sysfs(str(f), 0.3), self.hil_util.SYSFS_UNKNOWN) - f.unlink() - self.assertIsNone(self.hil_util.read_sysfs(str(f), 0.3)) - - class UsbScanIsTheOneWalk(unittest.TestCase): """Three call sites each had a different subset of the three things this must get right; none had all three. The expensive read is `serial` -- served under the device @@ -1051,19 +754,13 @@ class UsbScanIsTheOneWalk(unittest.TestCase): return real(path, *a, **k) self.addCleanup(setattr, hil_util, 'read_sysfs', real) hil_util.read_sysfs = counting - self.addCleanup(setattr, hil_util, '_sysfs_stranded', - dict(hil_util._sysfs_stranded)) - self.addCleanup(setattr, hil_util, '_sysfs_stuck', hil_util._sysfs_stuck) - def _dev(self, name, vid, pid, serial='S1', fifo=False): + def _dev(self, name, vid, pid, serial='S1'): d = self.root / name d.mkdir() (d / 'idVendor').write_text(vid + '\n') (d / 'idProduct').write_text(pid + '\n') - if fifo: - os.mkfifo(d / 'serial') # a read that never answers - else: - (d / 'serial').write_text(serial + '\n') + (d / 'serial').write_text(serial + '\n') return d def _scan(self, **kw): @@ -1074,85 +771,16 @@ class UsbScanIsTheOneWalk(unittest.TestCase): return self.hil_util.usb_scan(**kw) def test_a_mismatched_vid_pid_costs_no_serial_read(self): + """`serial` is the ONE attribute here served under the device lock, so it is the + one that can block on a wedged device. Filtering on the lock-free descriptor pair + first is what keeps a scan for our board off every other board's locked read.""" self._dev('1-1', '1234', '5678') self._dev('1-2', 'cafe', '4010', serial='UID1') - devs, unknown = self._scan(vid_pid=('cafe', '4010')) + devs = self._scan(vid_pid=('cafe', '4010')) self.assertEqual([d['serial'] for d in devs], ['UID1']) - self.assertFalse(unknown) # the ruled-out device's locked attribute was never touched self.assertNotIn(str(self.root / '1-1' / 'serial'), self.reads) - def test_a_wedged_device_stays_unproven_on_every_scan(self): - """The memo lives in read_sysfs now, so usb_scan still CALLS it each pass -- what - must not repeat is the cost. StrandedPathMemoInvalidates covers the short-circuit; - here the invariant is that the device stays out of the results and absence stays - unproven, however many times we look.""" - from helper import hil_util - self._dev('1-1', 'cafe', '4010', fifo=True) - first = None - t0 = time.monotonic() - for _ in range(3): - devs, unknown = self._scan() - self.assertTrue(unknown, 'a stranded read must leave absence unproven') - self.assertEqual(devs, []) - if first is None: - first = hil_util._sysfs_stuck - self.assertEqual(hil_util._sysfs_stuck, first, - 'repeat scans spent more of the blindness budget') - self.assertLess(time.monotonic() - t0, 3.0, 'repeat scans re-paid the grace') - - -class BoundedOpenTellsAbsentFromUnknown(unittest.TestCase): - """Same contract as read_sysfs, in the sibling function of the same file: a real - OSError is a FACT (EBUSY, ENOENT, EACCES), a blocked open is UNKNOWN. Folding both - into None made an ordinary EBUSY report as a USB wedge, sending the operator to - usb-kernel-recover for healthy hardware -- and left the stranded thread uncounted, - so the cap that exists to stop the fd/thread ceiling never saw it.""" - - def setUp(self): - from helper import hil_util - self.hil_util = hil_util - self.td = TemporaryDirectory() - self.addCleanup(self.td.cleanup) - - def test_a_real_oserror_is_a_fact(self): - missing = str(Path(self.td.name) / 'nope') - self.assertIsNone(self.hil_util.bounded_open(missing, os.O_RDONLY, 1)) - - def test_a_blocked_open_is_unknown_and_counted(self): - fifo = Path(self.td.name) / 'fifo' - os.mkfifo(fifo) # no reader: O_WRONLY blocks forever - self.addCleanup(setattr, self.hil_util, '_sysfs_stuck', - self.hil_util._sysfs_stuck) - before = self.hil_util._sysfs_stuck - got = self.hil_util.bounded_open(str(fifo), os.O_WRONLY, 0.3) - self.assertIs(got, self.hil_util.SYSFS_UNKNOWN) - self.assertEqual(self.hil_util._sysfs_stuck, before + 1, - 'a stranded open is invisible to the blindness budget') - - -class UsbtestSysfsReadIsCapped(unittest.TestCase): - """find_device re-scans every cafe:4010 peer after EVERY case, so the local twin -- - which had no SYSFS_STUCK_MAX -- stranded a thread and an fd per wedged peer per case. - Delegating to hil_util gets the cap, and the deferred import keeps usbtest.py - importable standalone.""" - - def test_a_stranded_read_counts_against_the_shared_cap(self): - import usbtest - from helper import hil_util - td = TemporaryDirectory() - self.addCleanup(td.cleanup) - wedged = Path(td.name) / 'serial' - os.mkfifo(wedged) # no writer: open() never returns - self.addCleanup(setattr, hil_util, '_sysfs_stuck', hil_util._sysfs_stuck) - before = hil_util._sysfs_stuck - # UNKNOWN, not None: folding them made a blinded scan read as "device dropped - # off the bus", which aborts past the HUNG reflash - self.assertIs(usbtest._read_sysfs_bounded(wedged, grace=0.5), - hil_util.SYSFS_UNKNOWN) - self.assertEqual(hil_util._sysfs_stuck, before + 1, - 'usbtest reads are invisible to the blindness budget') - class AbandonExitSurvivesAFailedFork(unittest.TestCase): """Pool() forks, and after a convoy -- every stranded read holding a thread and an fd -- @@ -1198,11 +826,9 @@ class AbandonExitSurvivesAFailedFork(unittest.TestCase): class UsbtestOuterBoundIsOneValue(unittest.TestCase): - """The bound usbtest is TOLD and the bound run_cmd ENFORCES must be the same number. - Three separate expressions disagreed: --skip-flash appended no --outer-timeout at all - (usbtest reads 0 as no limit), and the no-recovery branch narrowed only the CHILD's - view while run_cmd still waited for a recovery reserve nothing on that path can - spend -- a pool worker and its battery permit idle for the difference.""" + """run_cmd's kill is the ONE bound, and it must carry a recovery reserve only when a + recovery can actually run. Otherwise a board on a path that cannot recover holds a pool + worker and its battery permit idle for the difference, under a usbtest width of 2.""" def _invoke(self, flasher, skip_flash=False): from contextlib import contextmanager @@ -1231,10 +857,6 @@ class UsbtestOuterBoundIsOneValue(unittest.TestCase): from helper import hil_util as _hu patch(_hu, 'glob', types.SimpleNamespace(glob=lambda p: [str(dev)])) - # the blindness latch and the stranded memo are process-global: another class's - # wedged-FIFO test would otherwise make every read here answer SYSFS_UNKNOWN - patch(_hu, '_sysfs_stuck', 0) - patch(_hu, '_sysfs_stranded', {}) patch(hil_test, 'USBTEST_SETTLE', 0) # see no_settle patch(hil_lock, 'usbtest_permit', contextmanager(_permit)) patch(hil_test, 'skip_flash', skip_flash) @@ -1244,24 +866,30 @@ class UsbtestOuterBoundIsOneValue(unittest.TestCase): hil_test.test_device_usbtest({'name': 'b', 'uid': 'UID1', 'flasher': flasher}) return seen - def _outer_flag(self, cmd): - toks = cmd.split() - self.assertIn('--outer-timeout', toks, 'usbtest reads a missing bound as UNLIMITED') - return int(toks[toks.index('--outer-timeout') + 1]) - def test_a_recoverable_board_reserves_the_recovery_budget(self): - seen = self._invoke({'name': 'openocd', 'vid_pid': '0x1366 0x1024'}) - want = hil_test.USBTEST_BATTERY_BUDGET + hil_test.USBTEST_RECOVERY_BUDGET - self.assertEqual(self._outer_flag(seen['cmd']), want) + import usbtest + flasher = {'name': 'openocd', 'vid_pid': '0x1366 0x1024', + 'args': '-f target/rp2040.cfg'} + seen = self._invoke(flasher) + want = (hil_test.USBTEST_BATTERY_BUDGET + hil_test.USBTEST_OVERSHOOT + + usbtest.recovery_reserve(flasher)) self.assertEqual(seen['timeout'], want) + def test_the_reserve_follows_the_board_not_a_fleet_constant(self): + """Two convoy-safe openocd boards, one RP and one not: the non-RP board cannot + run rescue_openocd, so reserving its two legs holds a pool worker and a usbtest + permit for 200s of dead time.""" + rp = self._invoke({'name': 'openocd', 'vid_pid': '0x1366 0x1024', + 'args': '-f target/rp2040.cfg'}) + wch = self._invoke({'name': 'openocd', 'vid_pid': '0x1366 0x1024', + 'args': '-f target/wch-riscv.cfg'}) + self.assertLess(wch['timeout'], rp['timeout']) + def test_a_board_with_no_recovery_does_not_pay_for_one(self): seen = self._invoke({'name': 'stlink', 'uid': 'X'}) # never convoy_safe - outer = self._outer_flag(seen['cmd']) - self.assertEqual(seen['timeout'], outer, 'the two bounds disagree') - # It does not carry the RECOVERY reserve it cannot spend... - self.assertLess(outer, hil_test.USBTEST_BATTERY_BUDGET - + hil_test.USBTEST_RECOVERY_BUDGET) + # It does not carry the RECOVERY reserve it cannot spend + self.assertEqual(seen['timeout'], + hil_test.USBTEST_BATTERY_BUDGET + hil_test.USBTEST_OVERSHOOT) # ...but it MUST still exceed the child's own --budget. The battery checks the # budget before dispatching, so it can overshoot by one already-started case; an # equal bound SIGKILLs it just as it goes to print, turning ~29 real per-case @@ -1269,12 +897,15 @@ class UsbtestOuterBoundIsOneValue(unittest.TestCase): toks = seen['cmd'].split() budget = int(toks[toks.index('--budget') + 1]) case_timeout = int(toks[toks.index('--timeout') + 1]) - self.assertGreaterEqual(outer - budget, case_timeout, + self.assertGreaterEqual(seen['timeout'] - budget, case_timeout, 'the outer kill can land mid-case, before the JSON') def test_skip_flash_still_bounds_the_child(self): + """--skip-flash disables recovery, so the child must not be given a reserve it + cannot spend -- but it MUST still be bounded.""" seen = self._invoke({'name': 'openocd', 'vid_pid': '0x1366 0x1024'}, skip_flash=True) - self.assertEqual(self._outer_flag(seen['cmd']), seen['timeout']) + self.assertEqual(seen['timeout'], + hil_test.USBTEST_BATTERY_BUDGET + hil_test.USBTEST_OVERSHOOT) class UsbtestRetryPolicy(unittest.TestCase): @@ -1673,60 +1304,6 @@ class StagingCoversEveryBoardForm(unittest.TestCase): "last run's re-run spec survived a green run") -class BlindWorkerReachesTheReport(unittest.TestCase): - """A worker that exhausts its bounded-read budget answers SYSFS_UNKNOWN for every - attribute, so its "device not found" means "could not tell". That reached the log and - the per-cell failure text but NOT the table -- and the table is what gets pasted into - the PR. Seen live: run 31794359407 went blind in 4 workers and published 26 red cells - with no mention of it, several of them caused by the blindness rather than the board.""" - - def test_no_note_when_every_worker_could_see(self): - mret = [('boardA', 0, [], [], 1.0, False), ('boardB', 0, [], [], 1.0, False)] - self.assertEqual(hil_test._blind_note(mret), '') - - def test_the_note_names_the_boards_whose_verdicts_are_not_evidence(self): - mret = [('boardA', 0, [], [], 1.0, True), ('boardB', 0, [], [], 1.0, False), - ('boardC', 1, [], [], 1.0, True)] - note = hil_test._blind_note(mret) - self.assertIn('boardA', note) - self.assertIn('boardC', note) - self.assertNotIn('boardB', note) # it could see; do not smear its result - self.assertTrue(note.endswith('\n'), 'banners are line-oriented') - - def test_both_row_widths_survive_the_report_writers(self): - """The blindness flag widened the worker's result tuple to 6, but the pool-timeout - path still synthesises 5-field rows for boards that never reported and feeds them - to the same two writers. A fixed-width unpack in either one raises INSIDE the - containment path, which is where a raise costs every board's results.""" - td = TemporaryDirectory() - self.addCleanup(td.cleanup) - rd = Path(td.name) - wide = ('boardA', 1, ['device/cdc_msc'], [('boardA', {'cdc_msc': '❌'}, '2s')], 2.0, True) - narrow = ('stuck', 1, [], None, 0) # what the timeout path builds - hil_test._write_failed_spec(rd / 'x.failed', rd, [wide, narrow]) - md = hil_report.accumulate_report([wide], rd, True, '', hil_test._blind_note([wide])) - self.assertIn('boardA', md) - self.assertIn('not all verdicts are evidence', md.lower()) - - def test_the_stray_note_names_the_board_and_survives_narrow_rows(self): - """Survivors ride back on the result tuple because main()'s own sweep runs after - the report is written on both abort paths -- the banner appended there was - computed and discarded.""" - wide = ('boardA', 0, [], [], 1.0, False, 2) - clean = ('boardB', 0, [], [], 1.0, False, 0) - note = hil_test._stray_note([wide, clean]) - self.assertIn('boardA', note) - self.assertNotIn('boardB', note) - self.assertIn('2', note) - self.assertEqual(hil_test._stray_note([clean]), '') - self.assertEqual(hil_test._stray_note([('stuck', 1, [], None, 0)]), '') - - def test_the_timeout_paths_synthetic_rows_do_not_crash_it(self): - """The pool-timeout path builds (name, 1, [], None, 0) for boards that never - reported -- five fields, no blindness to report -- and hands those around.""" - self.assertEqual(hil_test._blind_note([('stuck', 1, [], None, 0)]), '') - - class PoolGuardKeepsWhatFinished(unittest.TestCase): """The guard's 30-minute predecessor fired on 5 of the last 8 HIL jobs, so this is the common failure, not an edge case: map_async discarded every board that had finished and @@ -1831,7 +1408,7 @@ class WedgedBoardCosts(unittest.TestCase): class WedgeVerdictReachesTheLatch(unittest.TestCase): """usbtest computes `unrecovered_hang` but never reported it, so hil_test inferred the latch from `not recovery and 'HUNG' in out` and missed three cases: recovery ran and - FAILED (convoy-safe boards -- max32666fthr HUNG in the 08-14 run), the `inconclusive` + FAILED (convoy-safe boards -- max32666fthr HUNG in the 08-14 run), the `ambiguous` abort (which sets the flag but leaves no case at status HUNG), and an unparsable JSON, which is the outer-timeout kill and the case where a wedge is most likely.""" @@ -1881,7 +1458,7 @@ class WedgedBoardCannotReportAPass(unittest.TestCase): battery that still wedged returned `PASS 30/30`. That board then contributes 0 to err_count, is omitted from the .failed re-run spec (which keys on err > 0), and the job exits 0 with a D-state holder on the rig -- the exact silence this branch exists to end. - usbtest's `inconclusive` and `ambiguous` aborts fire AFTER the last case, so nothing + usbtest's `ambiguous` abort fires AFTER the last case, so nothing back-fills a BUDGET entry to make failed/notrun non-zero.""" def setUp(self): @@ -2040,5 +1617,205 @@ class HidEchoRunsInAChild(unittest.TestCase): self.assertIn('short read', self._stderr(r)) +class StrayNoteSurvivesTheTupleWidth(unittest.TestCase): + """_stray_note reads r[5] -- and three producers build this tuple at three widths, so + `len(r) > 5 and r[5]` reads a WRONG SLOT rather than raising if a field is ever + inserted. The live handoff pr3840-mret-board-result.md proposes exactly that, and the + report would then say "no strays" while probes and usbfs nodes stay held into the next + job. The index changed once already in this branch (r[6] -> r[5]).""" + + def test_it_names_the_board_and_the_count(self): + wide = ('dirty', 1, [], [], 9.0, 2) + clean = ('fine', 0, [], [], 8.0, 0) + note = hil_test._stray_note([wide, clean]) + self.assertIn('dirty (2)', note) + self.assertIn('2 process(es)', note) + self.assertNotIn('fine', note, 'a clean board must not appear in the note') + + def test_a_narrow_row_from_the_timeout_path_is_not_misread(self): + """The abort paths synthesise 5-field rows for boards that never reported.""" + self.assertEqual(hil_test._stray_note([('stuck', 1, [], None, 0)]), '') + self.assertEqual(hil_test._stray_note([('fine', 0, [], [], 8.0, 0)]), '') + + def test_the_slot_it_reads_is_the_slot_test_board_writes(self): + """Pins the index against the producer, so inserting a field fails HERE rather + than silently reporting a duration as a stray count.""" + import ast + src = (Path(TEST_DIR).parents[0] / 'hil_test.py').read_text() + fn = next(n for n in ast.walk(ast.parse(src)) + if isinstance(n, ast.FunctionDef) and n.name == 'test_board') + widths = sorted({len(n.value.elts) for n in ast.walk(fn) + if isinstance(n, ast.Return) and isinstance(n.value, ast.Tuple)}) + # the board-LOCKED early return is 5 wide and carries no stray count; the normal + # one is 6, with strays last + self.assertEqual(widths, [5, 6], + 'the result tuple changed width; _stray_note reads index 5') + + +class MixedWidthRowsSurviveTheReportWriters(unittest.TestCase): + """_abort_report hands `[(n, 1, [], None, 0) for n in stuck] + [r for r in mret ...]` + to both writers -- 5-field synthetic rows mixed with 6-field worker rows. Every other + test uses uniform widths, so replacing either `*_` unpack with a fixed-width one keeps + the suite green and raises only INSIDE the containment path, where a raise costs every + board's results.""" + + def _mixed(self): + return [('stuck', 1, [], None, 0), # synthetic, 5 wide + ('ran', 1, ['device/dfu'], + [('ran', {'device/dfu': '❌ boom'}, '8s')], 8.0, 2)] # worker, 6 wide + + def test_the_rerun_spec_accepts_both_widths(self): + with TemporaryDirectory() as td: + rd = Path(td) + hil_test._write_failed_spec(rd / 'c.json.failed', rd, self._mixed()) + spec = (rd / 'c.json.failed').read_text() + self.assertIn('stuck', spec) + self.assertIn('ran', spec) + + def test_the_cell_names_the_cause_of_the_abort(self): + """A board the pool guard never reached did not "pool-timeout". Marking it so + sends whoever reads the table after a guard that never fired.""" + from helper import hil_report + real = hil_report.accumulate_report + + def render(reason, secs): + hil_report.accumulate_report = lambda *a, **k: (_ for _ in ()).throw( + OSError('report dir unwritable')) + try: + with TemporaryDirectory() as td: + rd = Path(td) + hil_test._abort_report(reason, [], [{'name': 'boardA'}], + rd / 'c.failed', rd, True, '', + timeout_secs=secs) + return (rd / hil_report.REPORT_MD).read_text() + finally: + hil_report.accumulate_report = real + + guard = render('abandoned: worker pool timed out after 3600s', 3600) + self.assertIn(hil_report.POOL_TIMEOUT_CELL, guard) + raised = render('aborted: a worker raised ValueError: x', None) + self.assertIn(hil_report.RUN_ABORTED_CELL, raised) + self.assertNotIn(hil_report.POOL_TIMEOUT_CELL, raised, + 'a run that aborted on a raise is not a pool timeout') + # and the fallback must still fire on BOTH paths -- that is what it is for + for md in (guard, raised): + self.assertIn('boardA', md) + + def test_only_the_rerun_spec_sees_the_synthetic_rows(self): + """accumulate_report gets `mret` alone -- worker rows, always 4th field a real + list. Widening _abort_report to hand it the synthetic list too would crash the + containment path: those rows carry rows=None and render_matrix iterates it.""" + import ast + src = (Path(TEST_DIR).parents[0] / 'hil_test.py').read_text() + fn = next(n for n in ast.walk(ast.parse(src)) + if isinstance(n, ast.FunctionDef) and n.name == '_abort_report') + calls = {ast.unparse(n.func): ast.unparse(n) + for n in ast.walk(fn) if isinstance(n, ast.Call) + and ast.unparse(n.func).endswith(('_write_failed_spec', + 'accumulate_report'))} + self.assertEqual( + ast.unparse(ast.parse(calls['hil_report.accumulate_report']).body[0] + ).split('(', 1)[1].split(',')[0], 'mret', + 'accumulate_report must receive worker rows only -- the synthetic rows carry ' + 'rows=None and render_matrix iterates that field') + self.assertIn('stuck', calls['_write_failed_spec'], + 'the re-run spec must still name the boards that never reported') + + +class UsbtestAbsentDeviceVerdict(unittest.TestCase): + """The arm that fails BEFORE usbtest_permit: an absent device must not queue on the + battery mutex for minutes just to have usbtest.py report "no device", and the cell + needs the 0/30 denominator or the row reads as a bare failure.""" + + def setUp(self): + self.addCleanup(setattr, hil_test, 'board_wedged', hil_test.board_wedged) + hil_test.board_wedged = '' + no_settle(self) + from helper import hil_lock, hil_util + self.addCleanup(setattr, hil_util, 'usb_scan', hil_util.usb_scan) + hil_util.usb_scan = lambda **k: [] # a readable bus, no such device + self.addCleanup(setattr, hil_test, '_enum_timeout', hil_test._enum_timeout) + hil_test._enum_timeout = 0 + self.addCleanup(setattr, hil_lock, 'usbtest_permit', hil_lock.usbtest_permit) + from contextlib import contextmanager + + def boom(uid): + raise AssertionError('took the battery permit for an absent device') + yield + hil_lock.usbtest_permit = contextmanager(boom) + + def test_a_readable_bus_without_the_device_says_absent_with_a_denominator(self): + with self.assertRaises(hil_test.TestFail) as cm: + hil_test.test_device_usbtest({'name': 'b', 'uid': 'NOPE', + 'flasher': {'name': 'stlink', 'uid': 'X'}}) + self.assertIn('no cafe:4010 device', str(cm.exception)) + self.assertIn('0/30', cm.exception.metric) + + def test_a_scan_that_gave_up_says_could_not_tell_instead(self): + """The conflation this whole path exists to avoid: an unreadable DUT is not an + absent one, and the bare string sends a maintainer after a firmware regression on + hardware that is merely wedged.""" + from helper import hil_util + self.addCleanup(setattr, hil_util, '_ever_stranded', hil_util._ever_stranded) + hil_util._ever_stranded = True + with self.assertRaises(hil_test.TestFail) as cm: + hil_test.test_device_usbtest({'name': 'b', 'uid': 'NOPE', + 'flasher': {'name': 'stlink', 'uid': 'X'}}) + self.assertIn('could not tell', str(cm.exception)) + + +class UsbtestStartupDoesNotClaimAbsenceBlind(unittest.TestCase): + """usbtest.py's own startup lookup, the sibling of the arm above. hil_test relays its + stderr verbatim into the report cell, so a positive 'no cafe:4010 device' from a scan + that gave up is the same conflation one process further out. Structural because the + exit sits mid-main(), behind argparse and the testusb probe.""" + + def test_the_sysfs_backed_absence_claims_carry_the_note(self): + """Both claims that a bounded read can turn into a false absence. The printer one + was missed: read_sysfs folds a timed-out `serial` into None, so a wedged-but- + enumerated printer read as 'Printer device not found' -- an enumeration verdict for + hardware that is merely unreadable. The MIDI lookup is deliberately NOT here: it + globs /dev/snd/by-id and readlinks it, so no bounded read can blind it.""" + import ast + tree = ast.parse(Path(hil_test.__file__).read_text()) + claims = [ast.unparse(n) for n in ast.walk(tree) + if isinstance(n, (ast.Assert, ast.Raise)) + and ('Printer device not found' in ast.unparse(n) + or 'no cafe:4010 device' in ast.unparse(n))] + self.assertEqual(len(claims), 2, 'a sysfs-backed absence claim moved or was added') + for c in claims: + self.assertIn('strand_note', c, f'absence claimed without the note: {c[:70]}') + + def test_the_absence_exit_carries_the_stranded_caveat(self): + import ast + import usbtest + tree = ast.parse(Path(usbtest.__file__).read_text()) + exits = [n for n in ast.walk(tree) + if isinstance(n, ast.Call) and ast.unparse(n.func) == 'sys.exit' + and 'no {VID}:{PID} device' in ast.unparse(n)] + self.assertEqual(len(exits), 1, 'the absence exit moved; retarget this test') + self.assertIn('strand_note', ast.unparse(exits[0]), + 'usbtest claims absence without consulting sysfs_stranded()') + + +class UsbtestGlobalCleanupStaysProcessWide(unittest.TestCase): + """The strand flag has TWO consumers at different scopes. The per-case verdict is + per-DUT -- a peer that stranded must not make OUR board report wedged. But the finally + block's cleanup is GLOBAL: remove_id plus an unbind of every interface under the + usbtest driver, including that peer's. Those writes take the uninterruptible + device_lock, so the global path has to stay gated on the process-wide question.""" + + def test_the_global_unbind_consults_the_process_wide_flag(self): + import ast + import usbtest + tree = ast.parse(Path(usbtest.__file__).read_text()) + fins = [n for n in ast.walk(tree) if isinstance(n, ast.Try) and n.finalbody + and 'remove_id' in ast.unparse(ast.Module(body=n.finalbody, type_ignores=[]))] + self.assertEqual(len(fins), 1, 'the cleanup finally moved; retarget this test') + body = ast.unparse(ast.Module(body=fins[0].finalbody, type_ignores=[])) + self.assertIn('sysfs_stranded', body, + 'global remove_id/unbind runs without the process-wide strand gate') + + if __name__ == '__main__': unittest.main() diff --git a/test/hil/test/test_hil_health.py b/test/hil/test/test_hil_health.py index c7864f568..ceecc8d37 100644 --- a/test/hil/test/test_hil_health.py +++ b/test/hil/test/test_hil_health.py @@ -515,51 +515,54 @@ class PermitReleasesOnlyWhatItTook(unittest.TestCase): 'the permit released a slot it never acquired: width grew') -class RecoveryPrefersResetOverReflash(unittest.TestCase): - """Probe reset is the preferred cure: non-destructive (the wedged firmware survives for - autopsy), no flash wear, no risk of a bad park image (a wfe/wfi park has bricked SWD on - mimxrt1064_evk and max32666fthr through a power cycle), and measured at 128-129 ms - against a full erase+program. It also fits in budgets a reflash does not.""" +class RecoveryUsesAResetOnlyWhenThereIsARealOne(unittest.TestCase): + """usbtest's recovery runs the reset unconditionally before the reflash -- it is + non-destructive (the wedged firmware survives for autopsy), writes no flash, cannot + brick SWD the way a bad park image has (mimxrt1064_evk, max32666fthr), and is measured + at 128-129 ms against a full erase+program. + + Two things still gate it, and both are what this pins: a flasher may have no reset + primitive at all, and reset_esptool/reset_lm4flash return rc 0 WITHOUT resetting + anything. Running those makes the log say "resetting <board> via <flasher>" for a step + that did nothing. wedged_pids() arbitrates either way, so behaviour was always right -- + the record was not, and a false record is what keeps having to be unpicked.""" def setUp(self): import usbtest # test/hil is already on sys.path (see top of file) - self.u = usbtest - - def test_reset_is_attempted_before_the_reflash(self): - steps = self.u.recovery_steps('openocd', time_left=600) - self.assertEqual([s[0] for s in steps], ['reset', 'flash']) - - def test_a_budget_too_small_to_reflash_still_gets_the_reset(self): - """The old gate skipped recovery whole when a reflash did not fit, leaving the - holder in place; a reset needs a fraction of the budget.""" - steps = self.u.recovery_steps('openocd', time_left=self.u.RECOVER_FLASH_TIMEOUT - 1) - self.assertEqual([s[0] for s in steps], ['reset']) + # PRODUCTION, not a copy: re-implementing the screen here let the real gate be + # deleted with the suite still green, which is the failure mode this pins. + self._reset_fn = usbtest.reset_primitive - def test_no_budget_at_all_yields_nothing(self): - self.assertEqual(self.u.recovery_steps('openocd', time_left=1), []) + def test_a_stub_that_resets_nothing_is_not_claimed(self): + for name in ('esptool', 'lm4flash'): + self.assertIsNone(self._reset_fn(name), + f'reset_{name} returns rc 0 without resetting; claiming it ' + f'puts a step that did nothing in the record') - def test_a_flasher_with_no_reset_primitive_goes_straight_to_reflash(self): - steps = self.u.recovery_steps('nosuchflasher', time_left=600) - self.assertEqual([s[0] for s in steps], ['flash']) + def test_a_real_reset_primitive_is_used(self): + for name in ('openocd', 'jlink', 'stlink'): + self.assertIsNotNone(self._reset_fn(name)) + def test_a_flasher_with_no_reset_primitive_goes_straight_to_the_reflash(self): + self.assertIsNone(self._reset_fn('nosuchflasher')) -class RecoveryDoesNotClaimAResetItDidNotDo(unittest.TestCase): - """reset_esptool and reset_lm4flash return rc 0 without resetting anything, so a plan - that includes them makes the log say "resetting <board> via <flasher>" for a step that - did nothing. wedged_pids() arbitrates, so behaviour was already right -- the record was - not, and a false record is what this branch keeps having to unpick.""" - - def setUp(self): + def test_the_reset_is_attempted_before_the_reflash(self): + """Order matters and now lives only in main()'s inline ladder, where no test + reaches it -- swapping the two blocks kept the suite green. Reset first is + non-destructive: the firmware under test survives for autopsy, no flash is + written, and it cannot brick SWD the way a bad park image has on mimxrt1064_evk + and max32666fthr.""" + import ast import usbtest - self.u = usbtest - - def test_a_no_op_reset_primitive_is_not_scheduled(self): - self.assertEqual([k for k, _ in self.u.recovery_steps('esptool', 600)], ['flash']) - self.assertEqual([k for k, _ in self.u.recovery_steps('lm4flash', 600)], ['flash']) + src = Path(usbtest.__file__).read_text() + fn = next(n for n in ast.walk(ast.parse(src)) + if isinstance(n, ast.FunctionDef) and n.name == 'main') + seg = ast.get_source_segment(src, fn) + reset_at = seg.index('reset_fn = reset_primitive(') + flash_at = seg.index("flash_fn(board, args.recover_fw") + self.assertLess(reset_at, flash_at, + 'the reflash is attempted before the non-destructive reset') - def test_a_real_reset_primitive_still_is(self): - self.assertEqual([k for k, _ in self.u.recovery_steps('openocd', 600)], - ['reset', 'flash']) class SudoSoftNeverRaises(unittest.TestCase): diff --git a/test/hil/test/test_hil_report.py b/test/hil/test/test_hil_report.py index 9ab39bde3..7c7a097ef 100644 --- a/test/hil/test/test_hil_report.py +++ b/test/hil/test/test_hil_report.py @@ -962,6 +962,17 @@ class PoolTimeoutOutranksAStaleLock(unittest.TestCase): self.assertFalse(r['locked'], 'a wedge was published as lock contention') self.assertFalse(r['pass']) + def test_a_run_aborted_board_is_not_published_as_lock_contention(self): + """run-aborted is written by the same _abort_report path as pool-timeout, for a + board the guard never reached. It has to outrank a stale lock cell for the same + reason -- otherwise hil-validate.js re-runs a board whose worker RAISED.""" + doc = {'rows': [{'board': 'boardX', + 'cells': {'board-locked': 'fail', 'run-aborted': 'fail'}, + 'duration': None}], 'banner': '', 'caveat': '', 'scope': ''} + r = hil_report.summarize({'boards': [{'name': 'boardX'}]}, ['boardX'], doc)['results'][0] + self.assertFalse(r['locked'], 'an aborted run was published as lock contention') + self.assertFalse(r['pass']) + class NoBoardsExitRespectsFreshness(unittest.TestCase): def test_a_fresh_run_does_not_republish_the_previous_rows(self): diff --git a/test/hil/test/test_hil_util.py b/test/hil/test/test_hil_util.py index 1a283bda7..17abe52aa 100644 --- a/test/hil/test/test_hil_util.py +++ b/test/hil/test/test_hil_util.py @@ -6,11 +6,11 @@ # python3 test/hil/test/test_hil_util.py import io import os -import shutil -import tempfile import sys import time +import threading import unittest +from tempfile import TemporaryDirectory from contextlib import redirect_stdout from pathlib import Path @@ -167,52 +167,6 @@ class BottomLayer(unittest.TestCase): f'{mod}.py imports {root}, not stdlib/local - breaks the bare CI runner') -class BoundedReadBookkeeping(unittest.TestCase): - """Two ways the strand accounting lied, both of which cost a blindness credit -- and - the process goes blind after four.""" - - def test_a_value_that_arrived_at_the_deadline_is_not_a_strand(self): - """join() returns, is_alive() is still True, but the reader HAS deposited its - value. read_sysfs booked a strand from is_alive() alone, so a merely-slow healthy - read was memoised as unreadable forever. bounded_open already gets this right.""" - import threading, time as _t - before = hil_util._sysfs_stuck - self.addCleanup(setattr, hil_util, '_sysfs_stuck', before) - real_thread = threading.Thread - - class Lingering(real_thread): - """Deposits the value, then outlives the join by a hair.""" - def run(self): - super().run() - _t.sleep(0.6) # still alive when join(grace) returns - - self.addCleanup(setattr, threading, 'Thread', real_thread) - threading.Thread = Lingering - with tempfile.NamedTemporaryFile('w', suffix='_attr', delete=False) as fh: - fh.write('cafe\n') - path = fh.name - self.addCleanup(os.unlink, path) - hil_util.read_sysfs(path, grace=0.2) - self.assertEqual(hil_util._sysfs_stuck, before, - 'a value that arrived was still counted as a strand') - - def test_bounded_open_does_not_re_strand_a_known_path(self): - """Same rule read_sysfs has: re-opening a path known to hang costs another thread, - another fd and another blindness credit to learn what we already know. The printer - test re-opens ONE lp node on every retry.""" - d = tempfile.mkdtemp() - self.addCleanup(shutil.rmtree, d, True) - fifo = os.path.join(d, 'lp0') - os.mkfifo(fifo) # open() blocks: no writer, ever - self.addCleanup(setattr, hil_util, '_sysfs_stuck', hil_util._sysfs_stuck) - self.addCleanup(setattr, hil_util, '_sysfs_stranded', dict(hil_util._sysfs_stranded)) - before = hil_util._sysfs_stuck - for _ in range(3): - hil_util.bounded_open(fifo, os.O_WRONLY, 0.3) - self.assertLessEqual(hil_util._sysfs_stuck - before, 1, - 'each retry spent another blindness credit on the same path') - - class RunAlongsideKeepsStderrOffThePayload(unittest.TestCase): """test_device_printer_to_cdc byte-compares run_alongside's stdout against the payload it wrote. Merging stderr into that stream turns any stray child stderr byte -- a @@ -283,5 +237,212 @@ class RunCmdCleanupShape(unittest.TestCase): 'the interrupt path must re-raise, or Ctrl-C is swallowed') +class BoundedReadForGuardlessCallers(unittest.TestCase): + """`serial` is served under the device lock a wedged usbfs ioctl holds, so the read is + bounded BY DEFAULT -- not opt-in. usb_scan reads it on every device matching the VID to + find the one it wants, and hil_lock.controller_of does that from controller_permit on + essentially every board, so one wedged DUT would stall every worker rather than one. + hil_pool_check has no guard behind it at all.""" + + def setUp(self): + from helper import hil_util + self.hil_util = hil_util + # the pre-commit hook runs all four suites in ONE interpreter, so capture and + # restore rather than assuming these start (or end) empty + for name in ('_stranded', '_strand_hits'): + self.addCleanup(setattr, hil_util, name, dict(getattr(hil_util, name))) + getattr(hil_util, name).clear() + self.addCleanup(setattr, hil_util, '_ever_stranded', hil_util._ever_stranded) + hil_util._ever_stranded = False + self.td = TemporaryDirectory() + self.addCleanup(self.td.cleanup) + self.fifo = os.path.join(self.td.name, 'serial') + os.mkfifo(self.fifo) # a read that never answers + + def test_a_wedged_attribute_gives_up_instead_of_hanging(self): + t0 = time.monotonic() + self.assertIsNone(self.hil_util.read_sysfs(self.fifo, timeout=0.3)) + self.assertLess(time.monotonic() - t0, 5, 'the bounded read did not give up') + + def test_the_bound_is_the_default_not_an_opt_in(self): + """usb_scan reads `serial` on every device matching the VID to find the one it + wants, and hil_lock's controller_of does that from controller_permit on + essentially every board -- so an opt-in bound that ONE call site forgets lets a + single wedged DUT stall every worker, not one. Three call sites forgot it once.""" + import inspect + for fn in (self.hil_util.read_sysfs, self.hil_util.usb_scan): + default = inspect.signature(fn).parameters['timeout'].default + self.assertEqual(default, self.hil_util.SYSFS_READ_GRACE, + f'{fn.__name__} must be bounded without being asked') + t0 = time.monotonic() + self.assertIsNone(self.hil_util.read_sysfs(self.fifo)) # no timeout= passed + self.assertLess(time.monotonic() - t0, 5, 'the default path did not bound') + + def test_a_node_that_returns_during_the_grace_is_not_memoised_as_wedged(self): + """The inode must be captured BEFORE the reader starts. Stat it afterwards and a + board that came back mid-read has its brand-new HEALTHY inode recorded as the + wedged one -- only a SECOND re-enumeration could ever clear it, and hil_pool_check + would report a successful recovery as still off the bus.""" + def swap(): + time.sleep(0.15) + os.unlink(self.fifo) + Path(self.fifo).write_text('CAFE01\n') + + threading.Thread(target=swap, daemon=True).start() + self.hil_util.read_sysfs(self.fifo, timeout=0.6) + self.assertEqual(self.hil_util.read_sysfs(self.fifo, timeout=1), 'CAFE01', + 'the healthy new inode was recorded as the wedged one') + + def test_concurrent_readers_of_one_path_spend_one_credit(self): + """hil_pool_check polls one bus from four threads. Counting each READER let four + threads on ONE wedged device spend four of the process budget between them -- + latching on the single wedge the tool was run to find.""" + ts = [threading.Thread(target=lambda: self.hil_util.read_sysfs(self.fifo, timeout=0.3)) + for _ in range(4)] + [t.start() for t in ts] + [t.join() for t in ts] + self.assertEqual(len(self.hil_util._stranded), 1) + self.assertEqual(self.hil_util._strand_hits[self.fifo], 1, + 'four readers of one path spent four credits') + + def test_a_flapping_wedged_device_cannot_leak_without_bound(self): + """The inode all-clear re-arms on every re-enumeration, so a device that flaps + while STILL wedged strands again each pass -- a thread and an fd per cycle.""" + for _ in range(self.hil_util._PATH_STRAND_MAX + 4): + self.hil_util.read_sysfs(self.fifo, timeout=0.2) + os.unlink(self.fifo) + os.mkfifo(self.fifo) # back on the same path, still wedged + self.assertEqual(self.hil_util._strand_hits[self.fifo], + self.hil_util._PATH_STRAND_MAX, + 'a flapping device kept stranding past its per-path cap') + + def test_a_value_that_arrived_at_the_deadline_is_not_a_strand(self): + """`out` is checked BEFORE is_alive(): a reader can deposit its value and still be + alive for a moment after join() returns. Counting that as a strand blacklists a + healthy attribute by inode forever AND latches sysfs_stranded for the process.""" + good = Path(self.td.name) / 'idVendor' + good.write_text('cafe\n') + real_thread = threading.Thread + + class Lingering(real_thread): # deposits, then outlives the join + def run(self): + super().run() + time.sleep(2) + + self.hil_util.threading.Thread = Lingering + self.addCleanup(setattr, self.hil_util.threading, 'Thread', real_thread) + self.assertEqual(self.hil_util.read_sysfs(str(good), timeout=0.3), 'cafe') + self.assertNotIn(str(good), self.hil_util._stranded) + self.assertFalse(self.hil_util.sysfs_stranded()) + + def test_path_stranded_answers_per_device_not_per_process(self): + """usbtest decides whether to run lock-taking cleanup on this result; the sticky + process-wide flag would let any peer's wedge answer for our board.""" + other = Path(self.td.name) / 'peer' + other.write_text('PEER\n') + self.hil_util.read_sysfs(self.fifo, timeout=0.3) + self.assertTrue(self.hil_util.path_stranded(self.fifo)) + self.assertFalse(self.hil_util.path_stranded(str(other))) + self.assertTrue(self.hil_util.sysfs_stranded(), 'the process-wide flag is sticky') + + def test_a_refused_read_is_stranded_not_vouched_for(self): + """usbtest fails CLOSED on path_stranded() before running remove_id/unbind, which + take the uninterruptible device_lock. Past _STRAND_MAX read_sysfs answers None + WITHOUT looking -- so answering False there hands that guard a fabricated + all-clear for a device nobody read, and the lock-taking cleanup runs on a wedge.""" + self.hil_util._stranded.update( + {f'/sys/fake/{i}': i for i in range(self.hil_util._STRAND_MAX)}) + self.assertIsNone(self.hil_util.read_sysfs(self.fifo, timeout=0.3)) + self.assertTrue(self.hil_util.path_stranded(self.fifo), + 'a path the reader refused to open was reported readable-and-absent') + + def test_a_stat_that_races_the_reader_still_memoises(self): + """The pre-read stat is the memo KEY, and it can fail while the open that follows + succeeds and blocks -- a node replaced between the two. Without a key the give-up + records nothing, so hil_pool_check's next poll starts another permanent thread and + fd for the same path, and repeats it every pass.""" + real_stat = self.hil_util.os.stat + calls = [] + + def flaky(path, *a, **kw): + calls.append(path) + if len(calls) == 1: # only the pre-read stat loses the race + raise OSError('vanished between stat and open') + return real_stat(path, *a, **kw) + + self.addCleanup(setattr, self.hil_util.os, 'stat', real_stat) + self.hil_util.os.stat = flaky + self.assertIsNone(self.hil_util.read_sysfs(self.fifo, timeout=0.3)) + self.assertIn(self.fifo, self.hil_util._stranded, + 'a lost stat race leaks a fresh reader on every later poll') + + def test_a_successful_read_clears_an_earlier_refusal(self): + """_refused feeds path_stranded(), which usbtest reads to tell "cannot tell" from + a real disconnect. Left sticky, a board that recovered and then genuinely left the + bus is classified as an unrecovered wedge for the rest of the process.""" + good = Path(self.td.name) / 'serial2' + good.write_text('ABC123\n') + self.hil_util._refused.add(str(good)) + self.addCleanup(self.hil_util._refused.discard, str(good)) + self.assertEqual(self.hil_util.read_sysfs(str(good), timeout=0.3), 'ABC123') + self.assertFalse(self.hil_util.path_stranded(str(good)), + 'a path that answered is still reported unreadable') + + def test_a_recovered_device_is_seen_again_on_the_same_busport(self): + """THE recovery flow: hil_pool_check resets or reflashes a wedged board, then + wait_device polls find_device -> scan_usb for the NEW inode. A busport does not + change when the board comes back on the same physical port, so a path-only + blacklist would make that poll look at everything except the device it is waiting + for -- the board recovers physically and the tool reports it gone for the rest of + the run. A re-enumeration destroys the kernfs node, so a changed inode is the + all-clear.""" + self.assertIsNone(self.hil_util.read_sysfs(self.fifo, timeout=0.3)) + # re-enumeration: same path, new node + os.unlink(self.fifo) + Path(self.fifo).write_text('CAFE01\n') + self.assertEqual(self.hil_util.read_sysfs(self.fifo, timeout=1), 'CAFE01', + 'a board that came back on the same busport stayed blacklisted') + + def test_the_caveat_stays_true_after_a_recovery(self): + """Rows collected while the device was unreadable keep whatever they said, so the + footer must still warn even once the memo has cleared.""" + self.hil_util.read_sysfs(self.fifo, timeout=0.3) + os.unlink(self.fifo) + Path(self.fifo).write_text('CAFE01\n') + self.hil_util.read_sysfs(self.fifo, timeout=1) + self.assertTrue(self.hil_util.sysfs_stranded()) + + def test_a_stranded_path_is_never_read_twice(self): + """Each expiry strands a thread and an fd for the life of the process, and + hil_pool_check POLLS -- wait_device re-scans every 0.5s until its budget runs + out. Re-reading would leak one pair per poll.""" + self.hil_util.read_sysfs(self.fifo, timeout=0.3) + t0 = time.monotonic() + for _ in range(5): + self.assertIsNone(self.hil_util.read_sysfs(self.fifo, timeout=0.3)) + self.assertLess(time.monotonic() - t0, 0.3, + 'repeat reads of a known-stranded path paid the grace again') + + def test_the_caller_can_say_the_table_may_be_wrong(self): + self.assertFalse(self.hil_util.sysfs_stranded()) + self.hil_util.read_sysfs(self.fifo, timeout=0.3) + self.assertTrue(self.hil_util.sysfs_stranded(), + 'nothing would tell the operator a missing row may be this tool ' + 'losing sight of healthy hardware') + + def test_a_healthy_attribute_is_not_blacklisted(self): + good = os.path.join(self.td.name, 'idVendor') + Path(good).write_text('cafe\n') + for _ in range(3): + self.assertEqual(self.hil_util.read_sysfs(good, timeout=1), 'cafe') + self.assertFalse(self.hil_util.sysfs_stranded()) + + def test_without_a_timeout_the_read_stays_plain(self): + good = os.path.join(self.td.name, 'busnum') + Path(good).write_text('3\n') + self.assertEqual(self.hil_util.read_sysfs(good), '3') + self.assertIsNone(self.hil_util.read_sysfs(os.path.join(self.td.name, 'nope'))) + + if __name__ == '__main__': unittest.main() diff --git a/test/hil/usbtest.py b/test/hil/usbtest.py index 485e9e0e4..d23217417 100755 --- a/test/hil/usbtest.py +++ b/test/hil/usbtest.py @@ -47,31 +47,65 @@ RECOVER_FLASH_TIMEOUT = 90 # bound on the post-hang reflash; typical flash is 1 RECOVER_RESET_TIMEOUT = 30 # bound on the post-hang probe reset; ResetTarget measures ~130ms -def recovery_steps(flasher_name: str, time_left: float) -> list: - """Ordered (kind, bound) recovery attempts that fit in `time_left`. +RECOVER_SETTLE = 5 # after each step, to let a freed ioctl unwind +# The ladder's UNBOUNDED work, which no step timeout covers: two wedged_pids() /proc walks, +# json.loads of the roster entry, the child's first `import hil_flash`, convoy_safe, the +# BUDGET back-fill and the JSON print. The deleted _time_left() carried this as a bare +# '- 35'. Without it the reserve equals its own worst case exactly, and HIL_CMD_TIMEOUT and +# HIL_USBTEST_BATTERY_BUDGET are both env-overridable -- any of them moving up puts +# run_cmd's killpg back inside the reflash, orphaning the flasher on the probe. +RECOVER_OVERHEAD = 40 - RESET FIRST, reflash second. A probe reset fails the in-flight URB at the source just - as a park-flash does, but it is non-destructive -- the firmware under test survives, so - the wedge can still be autopsied -- writes no flash, and cannot brick SWD the way a bad - park image has on mimxrt1064_evk and max32666fthr (survived a power cycle). Measured - 128-129 ms against a full erase+program, and it works on i.MX RT and on DWC2 alike - (stm32f407disco, 2026-08-16: `r; g` -> USB disconnect, re-enumerated 325 ms later). - The reset also fits budgets a reflash does not: the old gate skipped recovery entirely - when RECOVER_FLASH_TIMEOUT did not fit, which left the holder in place for the next - job. Whether either worked is decided by wedged_pids(), never by the exit code -- a - clean flash only proves the probe wrote the MCU. +def recovery_reserve(flasher: dict | str) -> int: + """Seconds this flasher's post-hang ladder can actually spend. + + Every bounded step can cost its own timeout PLUS run_cmd's post-SIGKILL reap, so the + caller must count REAP_GRACE per step or its outer killpg lands mid-reflash and + ORPHANS the flasher on the probe. Derived rather than pinned: the predecessor was an + independent 250s that could not contain its own ladder, which is why the child used to + re-decide before every step and skipped most of them on a real hang. + + Per FLASHER, not one number for the fleet: the Rescue-DP legs are openocd-only + (hil_flash.rescue_openocd returns False for anything else), and a stub reset is + screened out by reset_primitive -- so an esptool board reserving them would hold a + pool worker and a usbtest permit for 200s it can never spend. """ import hil_flash - steps = [] - reset_fn = getattr(hil_flash, f'reset_{flasher_name.lower()}', None) - if getattr(reset_fn, 'no_op', False): - reset_fn = None # a stub that returns rc 0 without resetting: do not claim it - if reset_fn and time_left >= RECOVER_RESET_TIMEOUT: - steps.append(('reset', RECOVER_RESET_TIMEOUT)) - if time_left >= RECOVER_FLASH_TIMEOUT: - steps.append(('flash', RECOVER_FLASH_TIMEOUT)) - return steps + from helper import hil_util + if isinstance(flasher, str): + flasher = {'name': flasher, 'args': ''} + name = (flasher.get('name') or '').lower() + + def step(bound): + return bound + hil_util.REAP_GRACE + + total = step(RECOVER_FLASH_TIMEOUT) + 2 * RECOVER_SETTLE + RECOVER_OVERHEAD + if reset_primitive(name): + total += step(RECOVER_RESET_TIMEOUT) + # The ARGS, not just the name: rescue_openocd also needs the target cfg to be an RP + # one (RESCUE_CFG), so the five WCH/max32666 openocd boards on this rig can never run + # it. Reserving its two legs for them holds a pool worker and a usbtest permit for + # 200s of dead time -- the same waste the esptool case exists to remove. + if name == 'openocd' and any(cfg in (flasher.get('args') or '') + for cfg in hil_flash.RESCUE_CFG): + total += 2 * step(RECOVER_FLASH_TIMEOUT) # Rescue-DP POR + one retry + return total + + +def reset_primitive(flasher_name: str): + """The flasher's probe-reset callable, or None when there is nothing real to run. + + Two things gate it. A flasher may have no reset_* at all, and reset_esptool / + reset_lm4flash return rc 0 WITHOUT resetting anything -- running those makes the log + say "resetting <board> via <flasher>" for a step that did nothing. wedged_pids() + arbitrates the outcome either way, so behaviour was always right; the RECORD was not. + """ + import hil_flash # deferred: stdlib-only unless recovery actually runs + fn = getattr(hil_flash, f'reset_{flasher_name.lower()}', None) + return None if getattr(fn, 'no_op', False) else fn + + HELPER_TIMEOUT = 30 # default bound for sudo helpers (dmesg/modprobe/setpci/tee) # Battery per tier, in run order: control sanity, simple bulk, queued, unaligned, unlink, @@ -190,18 +224,21 @@ def sysfs_write(path, data, check=True): return r.returncode == 0 -def _read_sysfs_bounded(path, grace=1.0): - """Bounded sysfs attribute read. The value, or None, or hil_util.SYSFS_UNKNOWN. +def _hu(): + """The helper module, imported lazily like every other helper use in this file.""" + from helper import hil_util + return hil_util - Delegates to hil_util.read_sysfs (imported here, like every helper import in this - file) so both properties hold: the strand cap -- find_device re-scans after EVERY - case, so a 30-case battery against a wedged peer would otherwise strand dozens of - threads and fds -- and UNKNOWN kept distinct from None. Folding UNKNOWN into None made - a blinded scan read as "device dropped off the bus", which aborts down a path that - skips the HUNG recovery entirely. - """ + +SERIAL_GRACE = 1.0 # tighter than hil_util's shared default on purpose: find_device + # re-scans every cafe:4010 peer after each of ~30 cases and inside + # the 8s startup poll, so N unreadable peers cost N x this per scan + + +def _read_sysfs(path): + """The attribute's value, or None. See hil_util.read_sysfs for why `serial` can block.""" from helper import hil_util - return hil_util.read_sysfs(str(path), grace) + return hil_util.read_sysfs(str(path), SERIAL_GRACE) _DEV_CACHE: dict = {} # serial -> sysname, see find_device @@ -222,7 +259,7 @@ def _reread(sysname, serial): if ((d / 'idVendor').read_text().strip() != VID or (d / 'idProduct').read_text().strip() != PID): return None - dev_serial = _read_sysfs_bounded(d / 'serial') + dev_serial = _read_sysfs(d / 'serial') if not isinstance(dev_serial, str) or dev_serial.lower() != serial.lower(): return None # gone, mismatched, or unconfirmable -> full scan decides return { @@ -253,19 +290,16 @@ def find_device(serial, first=False): if hit: return hit _DEV_CACHE.pop(serial.lower(), None) - matches, inconclusive = [], [] + matches = [] for dev in SYS_USB.iterdir(): try: if (dev / 'idVendor').read_text().strip() != VID or \ (dev / 'idProduct').read_text().strip() != PID: continue - # BOUNDED: idVendor/idProduct are cached descriptors, but `serial` is served - # under device_lock(), so an unbounded read blocks us in D state on exactly the - # DUT whose hang we are here to report, losing every verdict collected so far. - dev_serial = _read_sysfs_bounded(dev / 'serial') - if dev_serial is not None and not isinstance(dev_serial, str): - inconclusive.append(dev.name) # unknown: NOT proof it is not ours - continue + # idVendor/idProduct are cached descriptors; `serial` is served under + # device_lock(), so on a wedged DUT this read blocks until the wedge clears. + # Contained by the caller's bound, not prevented here -- see hil_util.read_sysfs. + dev_serial = _read_sysfs(dev / 'serial') if dev_serial is None: continue if serial and dev_serial.lower() != serial.lower(): @@ -281,10 +315,7 @@ def find_device(serial, first=False): except (OSError, ValueError): continue if not matches: - # "could not tell" is not "gone". The caller aborts the battery on a falsy return - # and that path skips the HUNG reflash, so a blinded scan would report the wedge - # we exist to recover from as a physical disconnect. - return {'inconclusive': inconclusive} if inconclusive else None + return None if serial and len(matches) == 1: _DEV_CACHE[serial.lower()] = matches[0]['sysname'] if len(matches) > 1 and not first: @@ -533,13 +564,11 @@ def main(): p.add_argument('--recover-board', help='board JSON (name + flasher) for the post-hang ' 'reflash recovery; without it a HUNG case leaves the device wedged') p.add_argument('--recover-fw', help='firmware path reflashed by the post-hang recovery') - p.add_argument('--outer-timeout', type=int, default=0, - help='the caller\'s total bound on this process; a reflash that cannot ' - 'finish before it is skipped rather than orphaned mid-flash') p.add_argument('--budget', type=int, default=0, help='stop starting new cases after this many seconds (0 = no limit). ' - 'Callers that impose their own outer timeout set this to reserve ' - 'the remainder for the post-hang recovery path') + 'Callers that impose their own outer bound set this BELOW it, ' + 'reserving the remainder for the post-hang recovery -- see ' + 'recovery_reserve() for what that ladder costs') args = p.parse_args() t_start = time.monotonic() sys.stdout.reconfigure(line_buffering=True) # per-case results visible when piped/logged @@ -554,23 +583,23 @@ def main(): deadline = time.monotonic() + 8 while True: dev = find_device(args.serial) - # find_device is THREE-valued: a device, {'ambiguous': [...]}, or - # {'inconclusive': [...]} when bounded reads could not rule a device out. Screening - # only for 'ambiguous' let the inconclusive marker through as if it were a device, - # and the next statement subscripts dev['tier'] -> KeyError, no JSON on stdout, and - # hil_test reports "usbtest did not run / 0-30" for a merely-unreadable bus. - if dev and not ({'ambiguous', 'inconclusive'} & dev.keys()): + # find_device returns a device or {'ambiguous': [...]}. Screening for the marker + # matters: without it the next statement subscripts dev['tier'] -> KeyError, no + # JSON on stdout, and hil_test reports "usbtest did not run / 0-30". + if dev and 'ambiguous' not in dev: break if time.monotonic() > deadline: if dev and 'ambiguous' in dev: sys.exit(f"multiple devices with serial {args.serial}: {', '.join(dev['ambiguous'])} " '— stale enumeration from another port? replug or retry') - if dev and 'inconclusive' in dev: - from helper import hil_util as _hu - sys.exit(f"cannot tell whether {VID}:{PID} is present: bounded sysfs reads " - f"did not answer for {', '.join(dev['inconclusive'])}" - f"{_hu.sysfs_blind_note()}") - sys.exit(f'no {VID}:{PID} device' + (f' with serial {args.serial}' if args.serial else '')) + # a bounded `serial` read that gave up looks exactly like a disconnect from + # here, and hil_test relays this line verbatim into the report cell. The + # sticky process-wide flag is the RIGHT question at startup -- nothing but + # this scan has read anything yet -- unlike mid-battery, where a peer that + # stranded at case 2 would answer for our board at case 29. + sys.exit(f'no {VID}:{PID} device' + + (f' with serial {args.serial}' if args.serial else '') + + _hu().strand_note()) time.sleep(0.5) # a stale/foreign device advertising an out-of-range tier must not silently run an @@ -638,31 +667,16 @@ def main(): print('no --recover-board/--recover-fw: the device stays wedged and ' 'cleanup is skipped', file=sys.stderr) break - # The reflash is bounded to RECOVER_FLASH_TIMEOUT and skipped when the - # caller's outer bound cannot contain it: the flasher runs in its own - # session, so an outer killpg mid-flash would ORPHAN it on the probe. Gate - # each step on the time actually LEFT -- reserving for the worst case up - # front skipped recovery for nearly every real hang, since the hang-prone - # cases run late in the tier order. - def _time_left(): - if not args.outer_timeout: - return float('inf') - # what still runs after a step: run_cmd's post-kill reap (10s), - # the settle (5s), the sudo-escalated descendant reap run_case may - # have just paid (up to 7s) and the JSON write - return args.outer_timeout - (time.monotonic() - t_start) - 35 - - if _time_left() < RECOVER_RESET_TIMEOUT: - print('insufficient time before the outer bound for even a bounded ' - 'reset; the device stays wedged and cleanup is skipped', - file=sys.stderr) - break + # Both steps are bounded (RECOVER_RESET_TIMEOUT / RECOVER_FLASH_TIMEOUT) + # and the caller RESERVES room for both -- hil_test derives its + # bound from recovery_reserve(). No re-derivation here: + # the old per-step "does it still fit?" arithmetic carried an unexplained + # 35s fudge for costs paid downstream, and nobody could re-derive it. try: board = json.loads(args.recover_board) bname, fname = board['name'], board['flasher']['name'] import hil_flash # deferred: stdlib-only unless recovery actually runs flash_fn = getattr(hil_flash, f'flash_{fname.lower()}') - reset_fn = getattr(hil_flash, f'reset_{fname.lower()}', None) except Exception as e: # malformed/short json, import failure, unknown flasher print(f'reflash recovery unavailable ({e})', file=sys.stderr) break @@ -680,25 +694,33 @@ def main(): f'openocd flasher to enable recovery for this board.', file=sys.stderr) break - # RESET FIRST (see recovery_steps). Non-destructive, ~130 ms, and it - # clears the wedge by the same mechanism as the reflash. wedged_pids is the - # arbiter: reset_esptool is a stub that returns rc 0 without resetting - # anything, so an exit code here proves nothing. - steps = recovery_steps(fname, _time_left()) - if reset_fn and any(k == 'reset' for k, _ in steps): + # RESET FIRST: a probe reset fails the in-flight URB at the source just + # as a reflash does, but it is non-destructive -- the firmware under test + # survives for autopsy -- writes no flash, and cannot brick SWD the way a + # bad park image has (mimxrt1064_evk, max32666fthr). Measured ~130 ms. + # wedged_pids is the arbiter either way: reset_esptool is a stub that + # returns rc 0 without resetting anything, so an exit code proves nothing. + reset_fn = reset_primitive(fname) + if reset_fn: print(f'auto-recovering: resetting {bname} via {fname} probe ' f'(non-destructive; reflash only if this does not clear it)', file=sys.stderr) + # Inspect the signature rather than catching TypeError around the + # call: a TypeError raised INSIDE the primitive would re-run it with + # no bound (run_cmd's 180s CMD_TIMEOUT, against a 40s reserve), and a + # raise from that retry does not reach the sibling except Exception -- + # it unwinds past the recovery block, so the battery exits on a + # traceback with no JSON and ~29 real verdicts are discarded. + import inspect + kw = ({'timeout': RECOVER_RESET_TIMEOUT} + if 'timeout' in inspect.signature(reset_fn).parameters else {}) try: with redirect_stdout(sys.stderr): - reset_fn(board, timeout=RECOVER_RESET_TIMEOUT) - except TypeError: - with redirect_stdout(sys.stderr): - reset_fn(board) # older primitives take no bound + reset_fn(board, **kw) except Exception as e: print(f'probe reset raised: {e}; falling through to the reflash', file=sys.stderr) - time.sleep(5) # let the freed ioctl unwind + time.sleep(RECOVER_SETTLE) # let the freed ioctl unwind stuck, complete = wedged_pids(dev['node']) if complete and not stuck: print('probe reset cleared the wedge; skipping the reflash ' @@ -706,10 +728,6 @@ def main(): file=sys.stderr) unrecovered_hang = False break - if _time_left() < RECOVER_FLASH_TIMEOUT: - print('reset did not clear it and no budget left for a reflash; ' - 'the device stays wedged', file=sys.stderr) - break print(f'auto-recovering: reflashing {bname} via ' f'{fname} (see .claude/skills/usb-kernel-recover). ' f'Unbudgeted by flash_permit, like the root-cycle it replaced: the ' @@ -734,10 +752,9 @@ def main(): # still fits before the outer kill rescued = False try: - if _time_left() >= 2 * RECOVER_FLASH_TIMEOUT: - with redirect_stdout(sys.stderr): - rescued = hil_flash.rescue_openocd( - board, out_txt, timeout=RECOVER_FLASH_TIMEOUT) + with redirect_stdout(sys.stderr): + rescued = hil_flash.rescue_openocd( + board, out_txt, timeout=RECOVER_FLASH_TIMEOUT) if rescued: print('DAP wedged; rescued via Rescue DP, retrying reflash', file=sys.stderr) @@ -754,7 +771,7 @@ def main(): # settle even on a non-zero exit: the reset may have landed before the # flasher failed, and the freed ioctl needs a moment to unwind before # wedged_pids samples - time.sleep(5) + time.sleep(RECOVER_SETTLE) # Authoritative either way: a clean flash only proves the probe wrote the # MCU, not that the D-state holder let go. stuck, complete = wedged_pids(dev['node']) @@ -788,16 +805,24 @@ def main(): f'({", ".join(live["ambiguous"])}) after case {num}') unrecovered_hang = True break - if live and live.get('inconclusive'): - # bounded reads stopped answering, so we cannot say the device left -- - # treat it as the wedge it probably is, which keeps the HUNG reflash and - # the lock-safe cleanup in play - from helper import hil_util as _hu - abort_reason = ('cannot tell whether the device is still present: bounded ' - 'sysfs reads stopped answering' + _hu.sysfs_blind_note()) - unrecovered_hang = True - break if not live: + # ABSENT vs UNREADABLE: a bounded `serial` read that gave up looks exactly + # like a disconnect from here, and the difference decides whether the + # cleanup below runs. remove_id/unbind take the UNINTERRUPTIBLE + # device_lock (see the driver-registry note above), so performing them + # against a device that is merely unreadable -- i.e. probably wedged -- + # deadlocks the bus rather than tidying up. Fail CLOSED: if anything gave + # up during this scan, treat it as the wedge it probably is, which also + # keeps the recovery and the board_wedged latch in play. + # OUR device's own attribute, not the process-wide sysfs_stranded(): + # that flag is sticky and every DUT here is cafe:4010, so a peer that + # stranded at case 2 would make a genuine disconnect at case 29 report as + # an unrecovered wedge for the rest of the run. + if _hu().path_stranded(str(SYS_USB / dev['sysname'] / 'serial')): + abort_reason = (f'cannot tell whether the device is still present ' + f'after case {num}: its serial read gave up') + unrecovered_hang = True + break # no second entry for `num`: run_case already recorded it, and a duplicate # inflates the denominator (31/30) and reports a PASSing case as failed abort_reason = f'device dropped off the bus after case {num}' @@ -830,12 +855,27 @@ def main(): 'power cycle (a VM reboot is not reliable — hubs latch up across the PCIe reset)', file=sys.stderr) elif not args.keep_binding: - sysfs_write(DRIVER / 'remove_id', f'{VID} {PID}', check=False) - # release every claimed interface: another device sharing the VID:PID - # (stale example firmware) may have been grabbed on probe and would stay - # bound to usbtest until re-plugged, hijacking the next test's device - for intf in DRIVER.glob('*:*'): - sysfs_write(DRIVER / 'unbind', intf.name, check=False) + # PROCESS-WIDE, unlike the per-case verdict above. That one is per-DUT on + # purpose -- a peer that stranded must not make OUR board report wedged. + # This cleanup is GLOBAL: it unbinds every interface under the driver, + # including the peer we could not read, and unbind takes the + # uninterruptible device_lock. Narrowing this gate to path_stranded() + # would add a driver-registry writer to an existing wedge. + # INSIDE keep_binding rather than before it: hil_test always passes that + # flag, so a check further out announced a skip of cleanup that was never + # going to run -- one line of noise ahead of the real cause in every + # stranded row. ONE line for the same reason: the finally runs before + # SystemExit's message reaches stderr. + if _hu().sysfs_stranded(): + print('cleanup skipped: a sysfs read gave up, so unbind could take a ' + 'wedged device lock', file=sys.stderr) + else: + sysfs_write(DRIVER / 'remove_id', f'{VID} {PID}', check=False) + # release every claimed interface: another device sharing the VID:PID + # (stale example firmware) may have been grabbed on probe and would + # stay bound to usbtest until re-plugged, hijacking the next test + for intf in DRIVER.glob('*:*'): + sysfs_write(DRIVER / 'unbind', intf.name, check=False) except SystemExit: pass @@ -849,7 +889,7 @@ def main(): if args.json: # `wedged` is the verdict this process ALREADY computed; without it the caller had # to infer one from 'HUNG' in our stdout, which misses a recovery that ran and - # failed, the inconclusive abort (no case reaches status HUNG), and any battery + # failed, the ambiguous abort (no case reaches status HUNG), and any battery # killed before it printed. print(json.dumps({'serial': dev['serial'], 'speed': dev['speed'], 'tier': tier, 'passed': ran - len(failed) - len(notrun), |