From a3019f95b69da55ace3998569bd58d603cd1ddea Mon Sep 17 00:00:00 2001 From: hathach Date: Thu, 12 Nov 2026 01:32:30 +0700 Subject: [PATCH 01/16] Take HIL board locks through hil_lock.board_task --- .claude/skills/hil-contract/SKILL.md | 23 +- .claude/skills/usbtest/SKILL.md | 9 +- .claude/skills/usbtest/scripts/run_case.py | 143 ++++-- .claude/skills/usbtest/scripts/wedge_drill.py | 95 +++- .claude/test/test_usbtest_run_case.py | 136 +++-- .claude/test/test_usbtest_wedge_drill.py | 82 ++- .claude/test/usbtest_rig_lock.py | 56 ++ test/hil/helper/farm_profile.py | 6 + test/hil/helper/hil_report.py | 20 +- test/hil/hil_flash.py | 24 + test/hil/hil_test.py | 486 ++++++++++-------- test/hil/test/test_hil_bounded.py | 5 +- test/hil/test/test_hil_farm_check.py | 15 + test/hil/test/test_hil_flash.py | 23 + test/hil/test/test_hil_lock.py | 231 ++++++++- test/hil/test/test_hil_report.py | 10 +- test/hil/test/test_hil_sysview_capture.py | 9 +- test/hil/test/test_hil_wedge_sweep.py | 11 +- 18 files changed, 1010 insertions(+), 374 deletions(-) create mode 100644 .claude/test/usbtest_rig_lock.py diff --git a/.claude/skills/hil-contract/SKILL.md b/.claude/skills/hil-contract/SKILL.md index b63dbcd88e..26fe486917 100644 --- a/.claude/skills/hil-contract/SKILL.md +++ b/.claude/skills/hil-contract/SKILL.md @@ -188,14 +188,22 @@ A local `hil_test.py` run has no done record; wait for its completion notificati The `ci` rig also hosts a GitHub Actions runner that flashes boards and runs HIL as part of CI, never stopped (`hil` Board locks). Each board's lock is taken through `test/hil/helper/hil_lock.py`, under its lock name: agentrc's registry `name` for a board with `probe`, whatever this roster calls it, else its roster `name` (`hil_util.lock_name`). `python3 "${AGENTRC_DIR:-$HOME/.claude}"/skills/hil/scripts/hil_boards.py lock ` prints it; the helper's named `hold` and `release` take lock names, never roster names. The harness's shared scripts (the lock mechanics, the bounded sysfs reads and bus scan of `test/hil/helper/usb_observe.py`, the RTT console, and the `hil` skill's Flashers: the bounded command runner behind `test/hil/helper/hil_util.py` and the per-flasher commands and pyOCD launcher behind `test/hil/hil_flash.py`) are loaded by `test/hil/helper/agentrc.py` through agentrc's `hil_load` (one module per file per process) from the agentrc it selects: a `.agentrc/` that `hil_remote.py` staged at the tree's root, else in CI (`CI` or `GITHUB_ACTIONS` true) the commit `test/hil/agentrc.json` pins, fetched into `lib/agentrc` by `python3 test/hil/helper/agentrc.py fetch`, else the installed agentrc, `"${AGENTRC_DIR:-$HOME/.claude}"`, never fetched; `python3 test/hil/helper/agentrc.py check` prints which. Missing, off the pin, of another `agentrc_source.py` API, unlike its staged manifest or lacking a file of its scripts' closure, every HIL entry point refuses before any board access. -The provider's `openocd_esp` flasher (`hil` Flashers) is supported by `hil_test.py` and the farm check; `run_case.py` refuses it, its docstring says why. It is unrostered on ci.lan and refused under a CI job (`RUNNER_TRACKING_ID` or `GITHUB_ACTIONS` set). Both take an `openocd_esp` board's lock with `protected=True`, which marks its record `cleanupOwed`, its group the board alone. Whatever an `openocd_esp` operation leaves not proven ended stops that board's run, with no retry or park. The task ends through agentrc's `hil_lock.end_failed`: it logs the failure with the tracked child receipts and retained sessions in `/tmp/tinyusb-hil-locks/.cleanup.jsonl`, clears its record and releases the flock. The `cleanup-pending` cell names the receipts, log and any logging error; the farm row's cleanup records the release and retained sessions. An interrupt before a receipt is stored is logged with unrecheckable evidence, never as a proven cleanup. A bench board with an open `openocd_esp` cleanup failure must be recovered before another run or farm check accesses it; the free flock does not gate access. +`hil_test.py`, `run_case.py` and `wedge_drill.py` take each board through agentrc's `hil_lock.board_task` (`hil` Board locks), protected for every flasher: the record is marked `cleanupOwed`, its group the board alone, so a task killed before its end leaves it for the next take to log found-left. Under the taken lock, before any hardware access, the busy check (`probe_busy` in `test/hil/hil_flash.py`: agentrc's `hil_flash.probe_users` for the board's flasher and its recovery flasher) refuses the board when it names a live process using the probe, or when it cannot rule one out (`/proc` may hide other users' processes, a read failed, or the flasher has no probe lookup, as `wch_uart_loader`); the lock is then released with nothing logged. The check is a snapshot of probe users, never proof the probe is idle: it misses an `STM32_Programmer_CLI -script` session, a GDB client attached to its server, a process that opens the probe after it, and every DUT-side process; a stray `testusb` on the DUT never refuses admission (Recovery sweeps it inside the run). The farm check's profile exposes the same check as its `busy(board)` hook, which engines older than that hook ignore. Each task ends on one cleanup verdict, its last act under the lock: -A later take admits a free flock and reports the open failures in its handle's `cleanup_failures`, including any stale cleanup-owing record or legacy takeover journal it found. `hil_test.py` logs them before hardware access and reports the latest plus the count of additional open failures in `previous-cleanup-failure`, an informational cell excluded from test counts and verdicts; the farm check uses `previousCleanupFailure` and `openCleanupFailures`. After a successful `device/board_test` park, `hil_test.py` calls `resolve_restored` on the failures its take found: only failures whose own receipts and retained sessions are proven ended close, and the rest stay open. `--skip-flash` never claims restoration. The report retains what the take found even if the task then resolves it. +- `hil_test.py`: restored when the final `device/board_test` park succeeded, a failed test included, and also when an interrupt or exception follows that park (the run still aborts); clean under `--skip-flash` once every operation ended; failed for a pending provider cleanup (below), a wedged board with or without `--skip-flash`, a park that failed or had no firmware, a SystemView capture flash left unparked, or an exception or interrupt before the park. +- `run_case.py`: restored when `--after park` parked; clean for `--after leave` with a complete, unwedged verdict, or a peer found under the lock; failed for a failed flash or park, no enumeration, an incomplete verdict, a wedge, an exception or a SIGTERM. +- `wedge_drill.py`: restored when parked, clean while untouched, failed otherwise; a probe process that may still hold the probe goes in as unrecheckable evidence. + +A failed verdict appends a `failed` event, with its tracked child receipts and retained sessions, to `/tmp/tinyusb-hil-locks/.cleanup.jsonl`, clears the record and releases the flock; a restored one first resolves the open failures its take found whose own evidence is ended. A task that took the lock and did not end as its verdict asked (`BoardTask.ended_cleanly` false: a record not cleared, a failure not logged, a handle not closed) fails the board as a `cleanup-pending` cell `board task ended with errors: ...`, and `run_case.py` and `wedge_drill.py` exit 1 with it in `error` (`run_case.py`'s `pass` false); an interrupt replayed as a task ends aborts it the same way, exit 1, whatever verdict it gave; each publishes its result only after the task ended, deciding on the task's outcome attributes (`taken`, `failure_logged`, `ended_cleanly`), never on its error text. Advisory errors of a clean end (an interrupt hold not installed, a restoration not logged) are only shown: in `previous-cleanup-failure` as `board task notes`, or on the scripts' stderr. A failed park is the next take's notice, not a test failure of its own run. Limit (`hil_lock.BoardTask`'s): a signal that lands as the task's `__exit__` is entered leaves the flock held while the process lives. No entry point goes on after one: `hil_test.py` runs each board in a pool worker of its own (`maxtasksperchild=1`) that ends with its task or its interrupt, and `run_case.py` and `wedge_drill.py` exit after their one task, so the flock goes with the process and the next take logs the record. + +The provider's `openocd_esp` flasher (`hil` Flashers) is supported by `hil_test.py` and the farm check; `run_case.py` refuses it, its docstring says why. It is unrostered on ci.lan and refused under a CI job (`RUNNER_TRACKING_ID` or `GITHUB_ACTIONS` set). Whatever an `openocd_esp` operation leaves not proven ended stops that board's run, with no retry or park, and ends its task failed with the tracked child receipts and the retained sessions, or with the pending detail as unrecheckable evidence when it names neither. The `cleanup-pending` cell names the receipts, log and any logging error; the farm row's cleanup records the release and retained sessions. An interrupt before a receipt is stored is logged with unrecheckable evidence, never as a proven cleanup. A bench board with an open `openocd_esp` cleanup failure must be recovered before another run or farm check accesses it; the free flock does not gate access. + +A later take admits a free flock and reports the open failures in its handle's `cleanup_failures`, including any stale cleanup-owing record or legacy takeover journal it found. `hil_test.py` logs them before hardware access and reports the latest plus the count of additional open failures in `previous-cleanup-failure`, an informational cell excluded from test counts and verdicts; the farm check uses `previousCleanupFailure` and `openCleanupFailures`. A successful `device/board_test` park is `hil_test.py`'s restored verdict, which runs `resolve_restored` on the failures its take found: only failures whose own receipts and retained sessions are proven ended close, and the rest stay open, counted in the cell (`N still open`). `--skip-flash` never claims restoration. The report retains what the take found even if the task then resolves it. Before the flash, `test/hil/hil_flash.py` takes the build's segments and the chip's security state from agentrc (`segments_from_flash_args`, `read_security`), the security read's esptool child run through `run_tracked`: no openocd session starts unless that child is proven ended (`done`), and one `pending`, or `unknown` with its receipt, stops the board as above, its receipt named `esptool child, record `. `read_security` runs the esptool package of the interpreter of the `esptool` on PATH, whatever its version, which its `source` records; the bench ran 5.2.0 and 5.3.1. Another version goes in a versioned venv first on PATH (`python3 -m venv ~/tmp/esptool-5.3.1-venv && ~/tmp/esptool-5.3.1-venv/bin/pip install esptool==5.3.1 'bitstring<5'`, then `PATH=~/tmp/esptool-5.3.1-venv/bin:$PATH` for the run), never over a host's own esptool. The `esptool` flasher's `write_flash` runs the same esptool, and 5.3.1 accepts the underscore spellings it passes (`write_flash`, `--before=default_reset`, a build's `--flash_mode`) with deprecation warnings. -- `hil_test.py` self-locks each board for its flash+test (holder reason `hil_test.py`). A locked board fails immediately (` Failed: board locked: {holder info}`) without flashing — in CI, re-run the failed job later. A board refused by a live legacy cleanup holder (`hil` Board locks) fails the same way but gets a `recovery-blocker` cell naming the holder instead of `board-locked`, and is returned as a blocker, never re-run. -- For usbtest bring-up or case diagnosis, load the `usbtest` skill before a manual case run; its `run_case.py` takes and releases the lock itself. This contract still supplies the lock helper, the lock names and rig selection. +- `hil_test.py` self-locks each board for its flash+test (holder reason `hil_test.py`). A locked board fails immediately (` Failed: board locked: {holder info}`) without flashing — in CI, re-run the failed job later. A board refused by a live legacy cleanup holder (`hil` Board locks) fails the same way but gets a `recovery-blocker` cell naming the holder instead of `board-locked`, and is returned as a blocker, never re-run. A board the busy check refuses fails the same way with a `probe-busy` cell, `❌ probe in use by pid ()` or `❌ probe check: `, and is returned not-run; the take's open failures still go in `previous-cleanup-failure`. +- For usbtest bring-up or case diagnosis, load the `usbtest` skill before a manual case run; its `run_case.py` takes and releases the lock itself, through its board task (above). This contract still supplies the lock helper, the lock names and rig selection. - For hardware work outside `hil_test.py` (JLink/GDB, manual flashing, `usbtest.py`, serial poking), hold the lock first and release it when done — release is mandatory cleanup. Proceed only when the lookup and the hold both succeeded; on a failure stop, with no hardware work and no `release` (it would end another session's holder): ```bash @@ -210,7 +218,7 @@ python3 test/hil/helper/hil_lock.py release "$LOCK" - A manual session on a dev-bench board with no entry in this host's HIL config locks it by an agreed board name, with no config: `hil_lock.py hold BOARD --reason "..."` only reserves that name, so verify the probe serial and board identity yourself. A named-board lock needs no config; config-driven tools (`hil_test.py`, `hil_lock.py hold --all`) still need this host's config, and a farm check off `ci` and `tusb` refuses without one. - Rig-wide operations affect every board, so they hold every board on the host first (`hil` Board locks). A root-port cycle (`usb_recover.sh root-cycle`, rung 2 of `usb-kernel-recover`) runs only through agentrc's `hil_reserve.py`, with every roster on this host: on `ci`, `python3 "${AGENTRC_DIR:-$HOME/.claude}"/skills/hil/scripts/hil_reserve.py run root-cycle --roster test/hil/tinyusb.json --roster /test/hil/ci.json tinyuf2.lock --reason "..."`; on htpc, `test/hil/local.json` and TinyUF2's `test/hil/local.json` with the same selector. It refuses when a device under that root port is not explained by those rosters, holds every board of every roster in one process around the cycle, and releases every lock when it ends. Unless the cycle ended clean with every device back, `end_failed` logs the blocker and unproven receipts on every board; the next task reports them. Other rig-wide operations (a leaf hub's `uhubctl` power cycle) take `hil_lock.py hold --all --reason "..."` (this host's config as the farm check picks it, else `test/hil/local.json`; it refuses when that is missing and no `--config` names one) plus a separate `hil_lock.py hold --reason "..."` for the other project's lock names on a shared host (its contract's Reservation names them), and proceed only when every hold succeeded; on a refusal, `hil_lock.py release` a name of each hold you took, never `release --all`, then wait within the budget or return the holder (`hil` Board locks). A controller operation (`pci-rebind`, `pci-bind`) has no reservation procedure that covers it yet and is refused under this contract until one exists. - `hil_lock.py status` lists holders. Locks auto-release when the holder process dies (kernel flock); `/tmp` clears on reboot. -- Forcing past a lock: `HIL_NO_BOARD_LOCK=1 python3 test/hil/hil_test.py ...` bypasses the guard without killing the holder. It risks colliding with whatever holds it. +- Forcing past a lock: `HIL_NO_BOARD_LOCK=1 python3 test/hil/hil_test.py ...` bypasses the guard without killing the holder. It risks colliding with whatever holds it. The busy check still runs and a failed cleanup is still logged, while a restoration resolves nothing; `run_case.py` and `wedge_drill.py` ignore the variable. ## Results @@ -320,7 +328,8 @@ The caller maps each requested board onto the `hil` verdicts from the copied out - fail: a FAIL cell, or a usbtest FAIL case. A HUNG case the in-run recovery cleared is not a blocker by itself; the row's `wedged` decides. - not-run: `locked`, `build refused`, a `lock-unavailable` cell (the host's lock dir is unusable: rig-side, not - re-admitted until it is repaired), a board not in the config, a run that never started (the + re-admitted until it is repaired), a `probe-busy` cell (a live user of the board's probe, or a busy check that could + not rule one out: re-run once the probe is free), a board not in the config, a run that never started (the cases Results lists); a FAIL cell whose row's output shows the flash failed before any test ran, and a usbtest row red only from NOTRUN or BUDGET cases, though the report folds both as failures (Limits); a skipped test (`Skip (no binary)`), which its row lists in `skipped` and folds @@ -330,7 +339,7 @@ The caller maps each requested board onto the `hil` verdicts from the copied out ## Recovery -A board whose usbtest battery reported the device wedged (a HUNG case the in-run recovery could not clear, or a device it could no longer identify afterwards) gets a `board-wedged` cell and the rest of its examples are skipped for that run; that in-run recovery is a probe reset, or a reflash where the flasher has no reset. No admission marker blocks the next run. Before a board's first flash, a run without `--skip-flash` looks for a D-state `testusb` on that board's usbfs node, which a cancelled or killed run leaves behind, and resets the board through its convoy-safe recovery flasher (`flasher_recover`, else `flasher`); a board it cannot free is reported `board-wedged` without being flashed. A stray on a board outside the run is not swept. Interactively, follow `usb-kernel-recover` from its triage before running it again; a delegated run follows Results. `usb-kernel-recover` shows what a real wedge looks like and how to clear it; `usb-kernel-debug` explains WHY the kernel rejected a device (dmesg analysis). +A board whose usbtest battery reported the device wedged (a HUNG case the in-run recovery could not clear, or a device it could no longer identify afterwards) gets a `board-wedged` cell and the rest of its examples are skipped for that run; that in-run recovery is a probe reset, or a reflash where the flasher has no reset. No admission marker blocks the next run. Before a board's first flash, a run without `--skip-flash` looks for a D-state `testusb` on that board's usbfs node, which a cancelled or killed run leaves behind, and resets the board through its convoy-safe recovery flasher (`flasher_recover`, else `flasher`); a board it cannot free is reported `board-wedged` without being flashed. The sweep is recovery inside the run's board task, after admission: a DUT-side process never refuses the board. A stray on a board outside the run is not swept. Interactively, follow `usb-kernel-recover` from its triage before running it again; a delegated run follows Results. `usb-kernel-recover` shows what a real wedge looks like and how to clear it; `usb-kernel-debug` explains WHY the kernel rejected a device (dmesg analysis). A dispatched recovery action is its own operation, never part of a run: the prompt names one board, its busport, the rung ceiling, the budget and the reservation. Follow `usb-kernel-recover` diff --git a/.claude/skills/usbtest/SKILL.md b/.claude/skills/usbtest/SKILL.md index e16305d0f7..007b3494b5 100644 --- a/.claude/skills/usbtest/SKILL.md +++ b/.claude/skills/usbtest/SKILL.md @@ -43,9 +43,12 @@ python3 .claude/skills/usbtest/scripts/run_case.py --config `--after leave` keeps usbtest running for a debug session. `--variant` is required when the board has several. It refuses with exit 2 and the reason before touching hardware, including on a host -that is not Linux and while any battery or another `run_case.py` runs on the host; pass -`--allow-concurrent` only when another battery's load on the board's host controller does not -matter for what you are measuring. A wedged device is never parked. The last stdout +that is not Linux, while any battery or another `run_case.py` runs on the host, and when the busy +check under the lock names a live user of the board's probe or cannot rule one out; pass +`--allow-concurrent` (it never skips the busy check) only when another battery's load on the board's +host controller does not matter for what you are measuring. A wedged device is never parked, and any +end but a park or a clean `--after leave` is logged as a failed cleanup for the next take to report +(the HIL contract's Reservation). The last stdout line is its JSON verdict; each of its `cases` carries `usbtest.py`'s `detail`, and `stderr` and `dmesg` when it captured them. diff --git a/.claude/skills/usbtest/scripts/run_case.py b/.claude/skills/usbtest/scripts/run_case.py index f9709e8b43..cb219f64d3 100644 --- a/.claude/skills/usbtest/scripts/run_case.py +++ b/.claude/skills/usbtest/scripts/run_case.py @@ -10,14 +10,21 @@ Refuses before touching hardware (exit 2) when: the board or variant is unknown or ambiguous, the board sits in boards-skip, does not run device/usbtest or lacks a uid or flasher name in the -roster, it flashes through openocd_esp (its ordinary, always-released lock cannot be kept through a session left -running; use hil_test.py), the usbtest (or, for --after park, the board_test) firmware is not built, the board lock -is held or unusable, or a testusb, usbtest.py, hil_test.py, wedge_drill.py or other run_case.py -process is alive on this host, checked before and again after taking the lock. That check is -host-wide and does not see a hil_test.py started after it: --allow-concurrent skips it only when -another battery's load on this board's host controller does not matter for what you are measuring. +roster, it flashes through openocd_esp (its verdict would not log a session the provider left running; use +hil_test.py), the usbtest (or, for --after park, the board_test) firmware is not built, the board lock +is held or unusable, the busy check under it (hil_flash.probe_busy) names a live user of the board's probe or cannot +rule one out, or a testusb, usbtest.py, hil_test.py, wedge_drill.py or other run_case.py +process is alive on this host, checked before and again after taking the lock. That peer check is +host-wide and does not see a hil_test.py started after it: --allow-concurrent skips it, never the busy check, only +when another battery's load on this board's host controller does not matter for what you are measuring. A host that is not Linux is refused first, once argparse has accepted the command line. +The lock is agentrc's hil_lock.board_task (protected; HIL_NO_BOARD_LOCK is ignored), ended on the run's cleanup +verdict: restored once parked on board_test, clean when --after leave keeps usbtest running with a complete, +unwedged verdict or a peer refused the run under the lock, failed otherwise (flash, enumeration, an incomplete +verdict, a wedge, a failed park, an exception or SIGTERM), which logs it in the board's cleanup log for the next +take to report until a later restore resolves it. + Flashes with the roster's flasher from cmake-build/cmake-build- (the build skill's --shared --variants layout), waits for 0525:a4a0 with the board's serial, and runs usbtest.py with post-hang recovery when the board's recovery flasher can deliver it. --after park flashes @@ -26,10 +33,11 @@ stdout ends with one JSON line: {"pass", "board", "variant", "tests", "cases", "wedged", "boardState", "error"}, each case with usbtest.py's num, name, status, detail and, when it captured them, stderr and dmesg. Exit 0 every case passed, 1 a case failed or the run failed after the -lock was taken, 2 refused before any hardware action; a command line argparse rejects exits 2 -with its usage on stderr and no JSON line. A SIGTERM (`hil_lock.py release` sends one -to the lock holder) kills the running flasher or usbtest.py, reports boardState unknown with a -verdict line, then releases the lock. +lock was taken or the task's lock did not end as its verdict asked (its errors in "error"), 2 refused before any +hardware action; a command line argparse rejects exits 2 with its usage on stderr and no JSON line. The JSON line +follows the lock's release. A SIGTERM kills the running flasher or usbtest.py, ends the task failed and reports +boardState unknown. A signal that lands as the task's __exit__ is entered leaves the lock held until this process +exits (hil_lock.BoardTask's limit), which follows at once. """ import argparse import json @@ -327,6 +335,16 @@ def finish(code, error=''): signal.signal(signal.SIGTERM, previous) +def refusal(e) -> str: + """Why a board task refused the board before any hardware action: the lock's refusal, or the + busy check under it naming a probe user or unable to rule one out.""" + if isinstance(e, hil_lock.BoardBusy): + return f'probe in use by {hil_flash.users_text(e.users)}' + if isinstance(e, hil_flash.ProbeCheckFailed): + return f'probe check: {e}' + return str(e) if isinstance(e, RuntimeError) else f'{type(e).__name__}: {e}' + + def lock_and_run(args, tests, report, finish): cwd = os.getcwd() # before the lock: nothing after it may fail outside the cleanup try: @@ -337,60 +355,85 @@ def lock_and_run(args, tests, report, finish): park_fw = firmware(variant, 'device/board_test', flasher) if args.after == 'park' else None if not args.allow_concurrent: check_peers() - try: - lock = hil_lock.acquire_board_lock(hil_util.lock_name(board), reason=f'run_case.py usbtest {args.tests}') - except RuntimeError as e: - raise Refused(f'{board["name"]}: {e}') - if lock is None: - raise Refused(f'{board["name"]}: board lock unavailable or bypassed (HIL_NO_BOARD_LOCK)') except Refused as e: return finish(2, str(e)) except Terminated: return finish(2, 'terminated (SIGTERM) before any hardware action') + task = hil_lock.board_task(hil_util.lock_name(board), f'run_case.py usbtest {args.tests}', + busy=lambda: hil_flash.probe_busy(board)) + entered = False try: - if not args.allow_concurrent: - try: - check_peers() # again: a peer may have started before the lock was taken - except Refused as e: - return finish(2, str(e)) - # flash_jlink writes its command file into the cwd: keep it out of the checkout. Cleanup - # runs after run_locked printed the verdict, so its errors must not add a second one. - with tempfile.TemporaryDirectory(prefix='run_case-', ignore_cleanup_errors=True) as workdir: - os.chdir(workdir) - return run_locked(board, fw, park_fw, tests, args.timeout, report, finish) + with task: + entered = True + code, error = run_task(task, board, fw, park_fw, tests, args, report) except Terminated: + if not entered: + return finish(2, 'terminated (SIGTERM) before any hardware action') report['pass'] = False report['boardState'] = 'unknown: terminated (SIGTERM) mid-run' - return finish(1, 'terminated (SIGTERM), e.g. by hil_lock.py release') - except Exception as e: # any failure after the lock still ends with a verdict line - return finish(1, f'{type(e).__name__}: {e}') + code, error = 1, 'terminated (SIGTERM)' + except Exception as e: + if not entered: # admission: the lock, or the busy check under it, refused the board + return finish(2, f'{board["name"]}: {refusal(e)}') + code, error = 1, f'{type(e).__name__}: {e}' # any failure after the lock still ends with a verdict line finally: + os.chdir(cwd) + # published once the task ended, so its finalization counts + code, error = ended(task, code, error) + report['pass'] = report['pass'] and code == 0 + return finish(code, error) + + +def ended(task, code, error): + """(code, error) once the task ended: a lock that did not end as its verdict asked fails the run, + its state and errors in `error`; advisory errors of a clean end only go to stderr.""" + if not task.taken or task.ended_cleanly: + if task.errors: + print(f'board task notes: {"; ".join(task.errors)}', file=sys.stderr) + return code, error + logged = {None: '', True: ', failure logged', False: ', failure NOT logged'}[task.failure_logged] + problem = (f'board task did not end as its verdict asked (lock {"released" if task.released else "NOT released"}' + f'{logged}): {"; ".join(task.errors)}') + return code or 1, f'{error}; {problem}' if error else problem + + +def run_task(task, board, fw, park_fw, tests, args, report): + """The run under the board's task: (exit code, error), the task's cleanup verdict given.""" + if not args.allow_concurrent: try: - os.chdir(cwd) - finally: - release(lock) - - -def release(lock): - hil_lock.clear_record(lock) - lock.close() - - -def run_locked(board, fw, park_fw, tests, timeout, report, finish): + check_peers() # again: a peer may have started before the lock was taken + except Refused as e: + task.clean() + return 2, str(e) + # flash_jlink writes its command file into the cwd: keep it out of the checkout. Cleanup errors + # of the dir must not replace the verdict. + with tempfile.TemporaryDirectory(prefix='run_case-', ignore_cleanup_errors=True) as workdir: + os.chdir(workdir) + return run_locked(task, board, fw, park_fw, tests, args.timeout, report) + + +def run_locked(task, board, fw, park_fw, tests, timeout, report): + """Flash, enumerate, run, then park or leave: (exit code, error). Its last hardware action gives + the task's verdict: restored once parked, clean when usbtest is left running with a complete + unwedged verdict as --after leave asks, failed whenever the board's state is not known good.""" err = flash(board, fw) report['boardState'] = 'flash failed' if err else 'usbtest firmware' if err: - return finish(1, err) + task.failed(detail=f'usbtest flash failed: {err}') + return 1, err if not enumerated(board['uid']): - return finish(1, f'no {usbtest.VID}:{usbtest.PID} device with serial {board["uid"]} ' - f'{ENUM_TIMEOUT}s after flashing') + err = f'no {usbtest.VID}:{usbtest.PID} device with serial {board["uid"]} {ENUM_TIMEOUT}s after flashing' + task.failed(detail=err) + return 1, err data, stderr, killed = battery(board, fw, tests, timeout) if stderr.strip(): print(stderr.rstrip(), file=sys.stderr) if data is None: report['boardState'] = 'usbtest firmware, verdict incomplete' - return finish(1, killed or 'usbtest.py printed no verdict') + err = killed or 'usbtest.py printed no verdict' + task.failed(detail=f'{report["boardState"]}: {err}') + return 1, err report['cases'] = [{k: c[k] for k in ('num', 'name', 'status', 'detail', 'stderr', 'dmesg') if k in c} for c in data.get('cases', [])] report['wedged'] = bool(data.get('wedged')) @@ -403,15 +446,19 @@ def run_locked(board, fw, park_fw, tests, timeout, report, finish): print(' ' + c[k].replace('\n', '\n ')) if report['wedged']: report['boardState'] = 'wedged: recover it (usb-kernel-recover)' - return finish(1) + task.failed(detail=f'usbtest reported the device wedged: {report["boardState"]}') + return 1, '' if park_fw: err = flash(board, park_fw) report['boardState'] = f'park failed: {err}' if err else 'parked on board_test' if err: report['pass'] = False - return finish(1, err) - return finish(0 if report['pass'] else 1) - + task.failed(detail=report['boardState']) + return 1, err + task.restored(evidence='run_case.py: parked on board_test') + else: + task.clean() + return 0 if report['pass'] else 1, '' if __name__ == '__main__': sys.exit(main()) diff --git a/.claude/skills/usbtest/scripts/wedge_drill.py b/.claude/skills/usbtest/scripts/wedge_drill.py index 8c178c054c..663d941bc5 100755 --- a/.claude/skills/usbtest/scripts/wedge_drill.py +++ b/.claude/skills/usbtest/scripts/wedge_drill.py @@ -30,6 +30,12 @@ own reset after a non-pass and never counts as harness recovery. Exit 0 only for a pass with the board parked; 1 otherwise; 2 refused (a command line argparse rejects: its usage on stderr, no JSON line). + +The lock is a board_task as in run_case.py (its busy check runs under --allow-concurrent too), ended +restored once parked, clean while untouched, failed otherwise: a halt process that may still hold the +probe goes in as unrecheckable evidence, which only its recovery ends. The JSON line follows the lock's +release; a lock that did not end as its verdict asked, or a signal replayed as the task ended, exits 1, +its errors in "error". """ import argparse import json @@ -444,6 +450,46 @@ def finish_locked(board, rec_board, park_fw, report): report['error'] = f'park failed: {err}' +def drill_locked(task, board, rec_board, halt_with, fw, park_fw, args, report): + """The drill and its cleanup under the board's task, then the task's verdict; 2 when a peer + refused it under the lock, else None.""" + with tempfile.TemporaryDirectory(prefix='wedge_drill-', ignore_cleanup_errors=True) as workdir: + os.chdir(workdir) + try: + if not args.allow_concurrent: + run_case.check_peers() # again: a peer may have started before the lock + report['drill'] = drill(board, halt_with, fw, args.delay, args.timeout, report) + except Refused as e: + report['error'] = str(e) + task.clean() + return 2 + except (Terminated, KeyboardInterrupt): + report['error'] = 'terminated (signal)' + except Exception as e: + report['error'] = f'{type(e).__name__}: {e}' + try: + finish_locked(board, rec_board, park_fw, report) + except (Terminated, KeyboardInterrupt): + report['error'] = report['error'] or 'terminated (signal) during cleanup' + report['boardState'] = 'unknown, not parked: cleanup interrupted' + drill_verdict(task, report) + return None + + +def drill_verdict(task, report): + """restored once parked, clean while untouched, failed otherwise: a probe process that may still + hold the probe as unrecheckable evidence (only its recovery ends it), any other state for a + later restore to resolve.""" + state = report['boardState'] + if state == 'parked on board_test': + task.restored(evidence='wedge_drill.py: parked on board_test') + elif state == 'untouched': + task.clean() + elif held := report['halt'].get('probeHeld'): + task.failed(detail=state, receipts=[{'unrecheckable': f'probe process {held} may still hold the probe'}]) + else: + task.failed(detail=f'{state}; {report["error"]}' if report['error'] else state) + def main(): args = build_parser().parse_args() report = new_report(args) @@ -475,42 +521,37 @@ def finish(code): park_fw = run_case.firmware(variant, 'device/board_test', flasher) if not args.allow_concurrent: run_case.check_peers() - try: - lock = hil_lock.acquire_board_lock(hil_util.lock_name(board), reason='wedge_drill.py') - except RuntimeError as e: - raise Refused(f'{board["name"]}: {e}') - if lock is None: - raise Refused(f'{board["name"]}: board lock unavailable or bypassed (HIL_NO_BOARD_LOCK)') except Refused as e: report['error'] = str(e) return finish(2) except Terminated: report['error'] = 'terminated before any hardware action' return finish(2) + task = hil_lock.board_task(hil_util.lock_name(board), 'wedge_drill.py', + busy=lambda: hil_flash.probe_busy(board)) + entered, code = False, None try: - with tempfile.TemporaryDirectory(prefix='wedge_drill-', ignore_cleanup_errors=True) as workdir: - os.chdir(workdir) - try: - if not args.allow_concurrent: - run_case.check_peers() # again: a peer may have started before the lock - report['drill'] = drill(board, halt_with, fw, args.delay, args.timeout, report) - except Refused as e: - report['error'] = str(e) - return finish(2) - except (Terminated, KeyboardInterrupt): - report['error'] = 'terminated (signal), e.g. by hil_lock.py release' - except Exception as e: - report['error'] = f'{type(e).__name__}: {e}' - try: - finish_locked(board, rec_board, park_fw, report) - except (Terminated, KeyboardInterrupt): - report['error'] = report['error'] or 'terminated (signal) during cleanup' - report['boardState'] = 'unknown, not parked: cleanup interrupted' + with task: + entered = True + code = drill_locked(task, board, rec_board, halt_with, fw, park_fw, args, report) + except (Terminated, KeyboardInterrupt): + if not entered: + report['error'] = 'terminated before any hardware action' + return finish(2) + report['error'] = report['error'] or 'terminated (signal) as the task ended' + code = code or 1 # aborted, whatever the drill and its cleanup did + except Exception as e: + if not entered: # admission: the lock, or the busy check under it, refused the board + report['error'] = f'{board["name"]}: {run_case.refusal(e)}' + return finish(2) + report['error'] = report['error'] or f'{type(e).__name__}: {e}' finally: os.chdir(cwd) - run_case.release(lock) - parked = report['boardState'] == 'parked on board_test' - return finish(0 if report['drill'] == 'pass' and parked else 1) + if code is None: + code = 0 if report['drill'] == 'pass' and report['boardState'] == 'parked on board_test' else 1 + # published once the task ended, so its finalization counts + code, report['error'] = run_case.ended(task, code, report['error']) + return finish(code) finally: for s, h in previous.items(): signal.signal(s, h) diff --git a/.claude/test/test_usbtest_run_case.py b/.claude/test/test_usbtest_run_case.py index 8cf841be53..8652c492d5 100644 --- a/.claude/test/test_usbtest_run_case.py +++ b/.claude/test/test_usbtest_run_case.py @@ -10,6 +10,7 @@ import sys import tempfile import time +import types import unittest from contextlib import redirect_stderr, redirect_stdout from pathlib import Path @@ -22,6 +23,8 @@ spec = importlib.util.spec_from_file_location('run_case', SCRIPT) run_case = importlib.util.module_from_spec(spec) spec.loader.exec_module(run_case) +sys.path.insert(0, str(Path(__file__).resolve().parent)) +from usbtest_rig_lock import RigLock # noqa: E402 ROSTER = { 'boards': [ @@ -48,16 +51,6 @@ 'cases': [{'num': 29, 'name': 'toggle clear', 'status': 'PASS'}]} -class Lock: - def __init__(self): - self.closed = False - self.cleared = False - self.sigterm = None # the SIGTERM disposition when the lock was released - - def close(self): - self.closed = True - - class Rig: """Stubs for everything run_case.py touches, recording the order of hardware actions.""" @@ -68,8 +61,8 @@ def __init__(self, test): self.enumerates = True self.verdict = (PASS_JSON, '') self.killed = '' - self.lock = Lock() - self.lock_error = None + self.lock = RigLock(test, run_case.hil_lock, run_case.hil_flash, + on_take=lambda name: self.calls.append(('lock', name))) self.peers = ([], True) self.peer_scans = [] # per-scan live_peers results, then peers self.flash_rcs = [] # per-flash return codes, then flash_rc @@ -87,18 +80,6 @@ def flash_fn(board, fw): raise rc return subprocess.CompletedProcess('flash', rc, 'probe says no', '') - def acquire(name, reason): - if isinstance(self.lock_error, BaseException): - raise self.lock_error - if self.lock_error: - raise RuntimeError(self.lock_error) - self.calls.append(('lock', name)) - return self.lock - - def clear(fh): - fh.cleared = True - fh.sigterm = signal.getsignal(signal.SIGTERM) - def battery(board, fw, tests, timeout): self.calls.append(('battery', tuple(tests), fw)) if isinstance(self.verdict, BaseException): @@ -109,8 +90,6 @@ def battery(board, fw, tests, timeout): (run_case.hil_flash, 'find_firmware', lambda variant, example, flasher=None: self.firmware.get(example) and Path(self.firmware[example])), (run_case.hil_flash, 'flash_primitive', lambda name: flash_fn), - (run_case.hil_lock, 'acquire_board_lock', acquire), - (run_case.hil_lock, 'clear_record', clear), (run_case, 'enumerated', lambda uid: self.calls.append(('enumerated', uid)) or self.enumerates), (run_case, 'battery', battery), (run_case, 'live_peers', lambda: self.peer_scans.pop(0) if self.peer_scans else self.peers)): @@ -218,12 +197,25 @@ def test_allow_concurrent_skips_only_the_peer_check(self): def test_lock_held_or_unavailable(self): rig = Rig(self) - rig.lock_error = 'board locked: {"pid": 1, "reason": "hil_test.py"}' + rig.lock.error = 'board locked: {"pid": 1, "reason": "hil_test.py"}' self.refused(rig, '--board', 'solo', '--tests', '29', '--after', 'leave', says='board locked') rig = Rig(self) - rig.lock = None + rig.lock.error = run_case.hil_lock.LockUnavailable('board lock unavailable: [Errno 13] x') self.refused(rig, '--board', 'solo', '--tests', '29', '--after', 'leave', says='lock unavailable') + def test_a_live_probe_user_or_an_inconclusive_check_refuses_under_the_lock(self): + for users, says in (([{'pid': 4242, 'cmd': 'JLinkExe -USB P1'}], 'solo: probe in use by pid 4242 (JLinkExe'), + (run_case.hil_flash.ProbeCheckFailed('RuntimeError: /proc may hide'), + 'solo: probe check: RuntimeError: /proc may hide')): + for extra in ((), ('--allow-concurrent',)): # the busy check is never skipped + with self.subTest(says=says, extra=extra): + rig = Rig(self) + rig.lock.users = users + self.refused(rig, '--board', 'solo', '--tests', '29', '--after', 'park', *extra, says=says) + self.assertEqual(rig.calls, [('lock', 'solo')]) + self.assertTrue(rig.lock.cleared and rig.lock.closed) + self.assertEqual(run_case.hil_lock.cleanup_events('solo'), [], 'a refusal logged an event') + class Chain(unittest.TestCase): def released(self, rig): @@ -369,6 +361,91 @@ def test_an_exception_still_releases_the_lock(self): self.released(rig) +class Verdicts(unittest.TestCase): + """The board task's cleanup verdict: restored once parked, clean when usbtest is left running + as asked, failed for any state not known good, logged where the next take finds it.""" + + def run_solo(self, rig, after='park'): + rc, report, _ = rig.run('--board', 'solo', '--tests', '29', '--after', after) + self.assertTrue(rig.lock.cleared and rig.lock.closed) + return rc, report + + def earlier(self): + return run_case.hil_lock.log_cleanup_failure('solo', 'earlier', detail='killed run') + + def test_a_park_restores_and_resolves_an_earlier_failure(self): + rig = Rig(self) + earlier = self.earlier() + self.assertEqual(self.run_solo(rig)[0], 0) + self.assertEqual([e['failure'] for e in rig.lock.events('restored')], [earlier['id']]) + + def test_a_failed_case_still_restores_once_parked(self): + rig = Rig(self) + rig.verdict = ({**PASS_JSON, 'failed': 1, 'cases': [{'num': 29, 'status': 'FAIL'}]}, '') + earlier = self.earlier() + self.assertEqual(self.run_solo(rig)[0], 1) + self.assertEqual([e['failure'] for e in rig.lock.events('restored')], [earlier['id']]) + + def test_leave_ends_clean(self): + rig = Rig(self) + earlier = self.earlier() + self.assertEqual(self.run_solo(rig, after='leave')[0], 0) + self.assertEqual(run_case.hil_lock.open_cleanup_failures('solo'), [earlier]) + + def test_each_unknown_state_fails_the_cleanup(self): + cases = (('flash', 'usbtest flash failed: flash failed (rc 1)'), ('wedge', 'usbtest reported the device wedged'), + ('incomplete', 'verdict incomplete: usbtest.py printed no verdict'), + ('park', 'park failed: flash failed (rc 1)'), ('raise', 'ended without a cleanup verdict: RuntimeError'), + ('sigterm', 'ended without a cleanup verdict: Terminated')) + for how, detail in cases: + with self.subTest(how=how): + rig = Rig(self) + if how == 'flash': + rig.flash_rc = 1 + elif how == 'wedge': + rig.verdict = ({**PASS_JSON, 'wedged': True}, '') + elif how == 'incomplete': + rig.verdict = (None, '') + elif how == 'park': + rig.flash_rcs = [0, 1] + elif how == 'raise': + rig.verdict = RuntimeError('usb_scan blew up') + else: + rig.verdict = run_case.Terminated() + with mock.patch.object(run_case, 'kill_children'): + self.assertEqual(self.run_solo(rig)[0], 1) + failed, = rig.lock.events('failed') + self.assertIn(detail, failed['detail']) + self.assertEqual((failed['how'], failed['reason']), ('ended-failed', 'run_case.py usbtest 29')) + + def test_a_peer_under_the_lock_ends_clean(self): + rig = Rig(self) + rig.peer_scans = [([], True), ([(4343, 'run_case.py')], True)] + self.assertEqual(self.run_solo(rig)[0], 2) + self.assertEqual(run_case.hil_lock.cleanup_events('solo'), []) + + def test_the_verdict_line_follows_the_release_and_counts_its_errors(self): + rig = Rig(self) + printed = [] + + def clear(fh): + printed.append(sys.stdout.getvalue()) + return False # the record could not be cleared: the task ends failed + with mock.patch.object(run_case.hil_lock, 'clear_record', clear): + rc, report, _ = rig.run('--board', 'solo', '--tests', '29', '--after', 'park') + self.assertNotIn('"pass"', printed[0]) + self.assertEqual((rc, report['pass']), (1, False)) # the battery passed; its lock did not end + self.assertIn('board task did not end as its verdict asked (lock released, failure logged): ' + 'record not cleared', report['error']) + + def test_advisory_task_errors_never_fail_the_run(self): + rig = Rig(self) + broken = types.SimpleNamespace(InterruptHold=mock.Mock(side_effect=OSError('no signal mask'))) + with mock.patch.object(run_case.hil_lock, '_process', return_value=broken): + rc, report, err = rig.run('--board', 'solo', '--tests', '29', '--after', 'park') + self.assertEqual((rc, report['error']), (0, '')) + self.assertIn('board task notes: interrupt hold', err) + class Sigterm(unittest.TestCase): """What `hil_lock.py release` sends the lock holder, raised in-process as on_sigterm would.""" @@ -404,7 +481,7 @@ def test_during_the_flash_is_not_a_failed_flash(self): def test_before_the_lock_is_a_refusal(self): rig = Rig(self) - rig.lock_error = run_case.Terminated() + rig.lock.error = run_case.Terminated() rc, report, _ = rig.run('--board', 'solo', '--tests', '29', '--after', 'park') self.assertEqual((rc, report['boardState'], report['error']), (2, 'untouched', 'terminated (SIGTERM) before any hardware action')) @@ -419,7 +496,6 @@ def test_handler_installed_for_the_run_then_restored(self): lambda *a: during.append(signal.getsignal(signal.SIGTERM)) or battery(*a)): self.assertEqual(rig.run('--board', 'solo', '--tests', '29', '--after', 'park')[0], 0) self.assertEqual(during, [run_case.on_sigterm]) - self.assertIs(rig.lock.sigterm, signal.SIG_IGN) # after the verdict line, before the release self.assertIs(signal.getsignal(signal.SIGTERM), self.previous) def test_a_second_sigterm_is_ignored(self): diff --git a/.claude/test/test_usbtest_wedge_drill.py b/.claude/test/test_usbtest_wedge_drill.py index 2e77717f48..ef4b1d4695 100644 --- a/.claude/test/test_usbtest_wedge_drill.py +++ b/.claude/test/test_usbtest_wedge_drill.py @@ -26,6 +26,8 @@ spec.loader.exec_module(wedge_drill) run_case = wedge_drill.run_case REAL_RESET_PRIMITIVE = run_case.hil_flash.reset_primitive +sys.path.insert(0, str(Path(__file__).resolve().parent)) +from usbtest_rig_lock import RigLock # noqa: E402 ST_HALT = '-f interface/stlink.cfg -f target/stm32l4x.cfg' JLINK_REC = {'name': 'openocd', 'args': '-f interface/jlink.cfg -f target/stm32f4x.cfg'} @@ -49,17 +51,10 @@ 'cases': [{'num': 1, 'status': 'PASS'}]} -class Lock: - closed = False - - def close(self): - self.closed = True - - class Rig: def __init__(self, test): self.calls = [] - self.lock = Lock() + self.lock = RigLock(test, run_case.hil_lock, run_case.hil_flash) self.halt_rc = 0 self.halt_raises = None self.halt_raises_after = None # raised after the halt landed, like a broken pipe @@ -137,8 +132,6 @@ def inject(*a, **kw): (run_case, 'enumerated', lambda uid: True), (run_case, 'battery', battery), (run_case, 'live_peers', lambda: ([], True)), - (run_case.hil_lock, 'acquire_board_lock', lambda name, reason: self.lock), - (run_case.hil_lock, 'clear_record', lambda fh: None), (wedge_drill, 'halt_openocd', halt), (wedge_drill, 'halt_held', lambda board, timeout: halt(board, timeout, 'halt-held')), (run_case.hil_flash, 'reset_primitive', lambda name: reset), @@ -604,6 +597,63 @@ def test_a_good_reset_carries_no_log(self): self.assertNotIn('log', wedge_drill.recovery_from(RECOVERED)) +class TaskVerdicts(unittest.TestCase): + """The board task ends restored once parked, failed otherwise; a probe process that may still + hold the probe is unrecheckable evidence, so no later park closes that failure.""" + + def test_a_parked_drill_restores_and_resolves_an_earlier_failure(self): + rig = Rig(self) + earlier = run_case.hil_lock.log_cleanup_failure('ok', 'earlier', detail='killed drill') + rc, r = rig.run('--board', 'ok', '--delay', '0') + self.assertEqual((rc, r['boardState']), (0, 'parked on board_test')) + self.assertEqual([e['failure'] for e in rig.lock.events('restored')], [earlier['id']]) + + def test_an_unparked_board_fails_the_cleanup(self): + rig = Rig(self) + rig.case27 = (None, RECOVERED, 'usbtest.py killed') + rig.live_children = [] + rig.left_testusb = 4242 + rc, r = rig.run('--board', 'ok', '--delay', '0') + self.assertEqual(rc, 1) + self.assertTrue(r['boardState'].startswith('unknown, not parked'), r) + failed, = rig.lock.events('failed') + self.assertIn(r['boardState'], failed['detail']) + self.assertEqual(failed['receipts'], []) + + def test_an_interrupt_replayed_at_the_task_end_aborts_a_passed_drill(self): + rig = Rig(self) + with mock.patch.object(run_case.hil_lock, 'resolve_restored', side_effect=run_case.Terminated()): + rc, r = rig.run('--board', 'ok', '--delay', '0') + self.assertEqual((rc, r['drill'], r['boardState']), (1, 'pass', 'parked on board_test')) + self.assertEqual(r['error'], 'terminated (signal) as the task ended') + self.assertEqual(rig.lock.events('failed'), []) # the restored cleanup stands + self.assertTrue(rig.lock.cleared and rig.lock.closed) + + def test_a_held_probe_is_unrecheckable_evidence(self): + rig = Rig(self) + rig.live_children = [999] + rig.halt_rc = 1 + rig.run('--board', 'ok', '--delay', '0') + failed, = rig.lock.events('failed') + self.assertEqual(failed['receipts'], [{'unrecheckable': 'probe process 999 may still hold the probe'}]) + self.assertTrue(run_case.hil_lock.resolve_restored('ok', [failed], evidence='parked')) # stays open + + def test_a_peer_under_the_lock_ends_clean(self): + rig = Rig(self) + with mock.patch.object(run_case, 'live_peers', side_effect=[([], True), ([(1, 'hil_test.py')], True)]): + rc, r = rig.run('--board', 'ok', '--delay', '0') + self.assertEqual((rc, r['boardState']), (2, 'untouched')) + self.assertEqual(run_case.hil_lock.cleanup_events('ok'), []) + self.assertTrue(rig.lock.cleared and rig.lock.closed) + + def test_the_busy_check_runs_under_allow_concurrent(self): + rig = Rig(self) + rig.lock.users = [{'pid': 7, 'cmd': 'JLinkExe -USB P1'}] + rc, r = rig.run('--board', 'ok', '--delay', '0', '--allow-concurrent') + self.assertEqual((rc, r['boardState']), (2, 'untouched')) + self.assertIn('ok: probe in use by pid 7', r['error']) + self.assertEqual([c for c in rig.calls if c[0] in ('flash', 'battery')], []) + class LockName(unittest.TestCase): def test_a_registered_board_is_locked_by_its_registry_name(self): """A probe board the drill admits, named apart from its registered board.""" @@ -620,15 +670,11 @@ def test_a_registered_board_is_locked_by_its_registry_name(self): rig = Rig(self) rig.config.write_text(json.dumps({'boards': [{'name': 'aliased', 'uid': 'UIDP', 'probe': probe, 'tests': {'device': True}}]})) - locked = [] - - def acquire(name, reason): - locked.append(name) - raise RuntimeError('board locked') - with mock.patch.object(run_case.hil_lock, 'acquire_board_lock', acquire): - rc, r = rig.run('--board', 'aliased', '--delay', '0') + rig.lock.users = [{'pid': 7, 'cmd': 'openocd'}] + rc, r = rig.run('--board', 'aliased', '--delay', '0') self.assertEqual(rc, 2, r) - self.assertEqual(locked, [reg['name']]) + self.assertEqual(rig.lock.name, reg['name']) + self.assertIn('probe in use by pid 7 (openocd)', r['error']) if __name__ == '__main__': diff --git a/.claude/test/usbtest_rig_lock.py b/.claude/test/usbtest_rig_lock.py new file mode 100644 index 0000000000..b70fcddf2c --- /dev/null +++ b/.claude/test/usbtest_rig_lock.py @@ -0,0 +1,56 @@ +"""The real board lock of a stubbed usbtest rig: run_case.py's hil_lock in a temp lock dir and its +busy check stubbed, read back by the tests: released, cleared, the cleanup log's events.""" +import os +import tempfile +from unittest import mock + + +class RigLock: + def __init__(self, test, hil_lock, hil_flash, on_take=lambda name: None): + td = tempfile.TemporaryDirectory() + test.addCleanup(td.cleanup) + self.hil_lock, self.on_take = hil_lock, on_take + self.users = [] # what the busy check names; an exception raises from it + self.error = None # raised by the take instead: an exception, or the message of a RuntimeError + self.name = None # the lock name of the last take + real_take = self.real_take = hil_lock.take_board_lock + + def take(board, reason, **kw): + if isinstance(self.error, BaseException): + raise self.error + if self.error: + raise RuntimeError(self.error) + self.name = board + self.on_take(board) + return real_take(board, reason, **kw) + for obj, name, value in ((hil_lock, 'BOARD_LOCK_DIR', td.name), (hil_lock, 'take_board_lock', take), + (hil_flash, 'probe_busy', self.probe_busy)): + patcher = mock.patch.object(obj, name, value) + patcher.start() + test.addCleanup(patcher.stop) + env = mock.patch.dict(os.environ) + env.start() + test.addCleanup(env.stop) + os.environ.pop('HIL_NO_BOARD_LOCK', None) + + def probe_busy(self, board): + if isinstance(self.users, BaseException): + raise self.users + return list(self.users) + + @property + def cleared(self): + return self.name is not None and self.hil_lock.record_state(self.name)[0] != 'record' + + @property + def closed(self): + """A peer can take the lock (read after `cleared`: a peer's take logs a record left behind).""" + try: + fh = self.real_take(self.name, 'peer') + except self.hil_lock.BoardLocked: + return False + self.hil_lock.release_board_lock(fh) + return True + + def events(self, kind): + return [e for e in self.hil_lock.cleanup_events(self.name) if e['event'] == kind] diff --git a/test/hil/helper/farm_profile.py b/test/hil/helper/farm_profile.py index df42e0bcd5..d08db8ace8 100644 --- a/test/hil/helper/farm_profile.py +++ b/test/hil/helper/farm_profile.py @@ -60,6 +60,12 @@ def probe_candidates(board: dict) -> list: # --- inside the engine's reservation ---------------------------------------------------------- +def busy(board: dict) -> list: + """The live users of the board's probe, hil_test.py's own busy check (hil_flash.probe_busy): + raises when inconclusive. An engine that predates the hook never calls it.""" + return hil_flash.probe_busy(board) + + def _retain(ctx, board: dict) -> None: """An openocd_esp session the provider left running (hil_flash.cleanup_pending) goes to the engine's ctx.retain, its detail naming the receipts (its receipt path, or its native record diff --git a/test/hil/helper/hil_report.py b/test/hil/helper/hil_report.py index cdcc8b6496..7d3a8f172e 100644 --- a/test/hil/helper/hil_report.py +++ b/test/hil/helper/hil_report.py @@ -44,8 +44,12 @@ # a live cleanup holder from an older helper: refused before any flash, never waited out. # Its value is '❌ '. RECOVERY_BLOCKER_CELL = 'recovery-blocker' -# the cells of a board refused its lock, one per row -_REFUSAL_CELLS = (LOCKED_CELL, LOCK_UNAVAILABLE_CELL, RECOVERY_BLOCKER_CELL) +# the busy check under the taken lock named live users of the board's probe, or could not rule +# them out: refused before any flash, the lock released with nothing logged. Its value is +# '❌ probe in use by ' or '❌ probe check: '. +PROBE_BUSY_CELL = 'probe-busy' +# the cells of a board refused admission, one per row +_REFUSAL_CELLS = (LOCKED_CELL, LOCK_UNAVAILABLE_CELL, RECOVERY_BLOCKER_CELL, PROBE_BUSY_CELL) # 'fail' when the board's usbtest battery reported the device wedged (a HUNG case its # recovery could not clear, or a device it could no longer identify), so the rest of the # board was skipped @@ -691,11 +695,13 @@ def _results(cfg: dict, boards: list, report: dict) -> list: # failure, not a first-try pass earlier = {n: history[n] for n in sorted(set(mine) | {board}) if n in history} kept = {'history': earlier} if earlier else {} - unusable = next((cells[LOCK_UNAVAILABLE_CELL] for cells in mine.values() - if LOCK_UNAVAILABLE_CELL in cells), None) + unusable = next((cells[k] for cells in mine.values() for k in (LOCK_UNAVAILABLE_CELL, PROBE_BUSY_CELL) + if k in cells), None) + previous = [c[PREVIOUS_CLEANUP_CELL] for c in mine.values() if PREVIOUS_CLEANUP_CELL in c] + found = '; previous cleanup failure: ' + '; '.join(previous) if previous else '' if unusable is not None and not aborted and not board_wedged: results.append(({'board': board, 'ran': False, 'pass': False, 'locked': False, - 'wedged': False, 'skipped': [], **kept, 'detail': unusable}, mine, False)) + 'wedged': False, 'skipped': [], **kept, 'detail': unusable + found}, mine, False)) continue blocked = next((cells[RECOVERY_BLOCKER_CELL] for cells in mine.values() if RECOVERY_BLOCKER_CELL in cells), None) @@ -727,9 +733,7 @@ def _results(cfg: dict, boards: list, report: dict) -> list: detail = f'{len(mine)} variant(s), {cells_ok} cell(s) ok' if skipped: detail += f', {len(skipped)} skipped: {", ".join(skipped)}' - previous = [c[PREVIOUS_CLEANUP_CELL] for c in mine.values() if PREVIOUS_CLEANUP_CELL in c] - if previous: - detail += '; previous cleanup failure: ' + '; '.join(previous) + detail += found # a build refusal never flashed this attempt, whatever test history an --accumulate # re-run kept in the row results.append(({'board': board, 'ran': not unbuilt, 'pass': ok, diff --git a/test/hil/hil_flash.py b/test/hil/hil_flash.py index 2084ac6431..4d52f8c0b6 100755 --- a/test/hil/hil_flash.py +++ b/test/hil/hil_flash.py @@ -137,6 +137,30 @@ def convoy_safe(flasher: dict) -> bool: return hil_util.provider().convoy_safe(flasher) +class ProbeCheckFailed(RuntimeError): + """probe_busy could not rule out a user of the board's probe.""" + + +def probe_busy(board: dict) -> list: + """The board_task busy check of every HIL entry point and the farm check: the provider's + probe_users for the board's flasher and, when it differs, its recovery flasher (same probe, + another tool); [{'pid', 'cmd'}]. ProbeCheckFailed, naming the cause, when the provider is + inconclusive or has no lookup for the flasher (wch_uart_loader). Probe users only: a DUT-side + process (a stray testusb) is the run's recovery, never a refusal.""" + users = {} + try: + for f in {(f['name'], f.get('uid')): f for f in (board['flasher'], recover_flasher(board))}.values(): + users.update((u['pid'], u) for u in hil_util.provider().probe_users(f)) + except Exception as e: + raise ProbeCheckFailed(f'{type(e).__name__}: {e}') from e + return sorted(users.values(), key=lambda u: u['pid']) + + +def users_text(users) -> str: + """probe_busy's users for a refusal.""" + return ', '.join(f'pid {u["pid"]} ({u["cmd"]:.120})' for u in users) + + def _idf_target(fw_dir: Path) -> str: with (fw_dir / 'config.env').open() as f: return json.load(f)['IDF_TARGET'] diff --git a/test/hil/hil_test.py b/test/hil/hil_test.py index 7288a7c948..25e71bc849 100755 --- a/test/hil/hil_test.py +++ b/test/hil/hil_test.py @@ -2015,233 +2015,303 @@ def cleanup_pending(name: str) -> str: f'openocd_esp cleanup pending, receipt {", ".join(map(hil_flash.receipt_text, receipts))}' -def end_failed_cleanup(name: str, lock: str, fh, pending: str) -> str: - """Log the unproven cleanup and end this task's lock, naming the log and any write error.""" +def pending_evidence(name: str, pending: str) -> dict: + """The failed verdict's evidence for an unproven cleanup: run_tracked child receipts, which a + recheck can end, apart from the provider sessions it retained; with neither, `pending` as + unrecheckable evidence, so no later park closes the failure.""" receipts = hil_flash.cleanup_pending.get(name, ()) tracked = [r for r in receipts if hil_flash.tracked_receipt(r)] retained = [r for r in receipts if not hil_flash.tracked_receipt(r)] - if not receipts: - tracked = [{'unrecheckable': pending}] - errors = hil_lock.end_failed({lock: fh}, hil_lock.CI_REASON, detail=pending, receipts=tracked, - retained=retained) - log = Path(hil_lock.BOARD_LOCK_DIR) / f'{lock}{hil_lock.CLEANUP_LOG}' - detail = f'{pending}; board lock released; cleanup failure log: {log}' - if errors.get(lock): - detail += '; ' + '; '.join(errors[lock]) - return detail + return {'receipts': tracked if receipts else [{'unrecheckable': pending}], 'retained': retained} + + +def task_ending(task, lock: str) -> str: + """How a board task ended, for display: its lock, whether its failure was logged, its errors.""" + parts = ['board lock bypassed (HIL_NO_BOARD_LOCK=1)' if task.bypassed else + 'board lock released' if task.released else 'board lock NOT released'] + if task.failure_logged is not None: + log = Path(hil_lock.BOARD_LOCK_DIR) / f'{lock}{hil_lock.CLEANUP_LOG}' + parts.append(f'cleanup failure {"logged" if task.failure_logged else "NOT logged"}: {log}') + return '; '.join(parts + task.errors) + + +def previous_cleanup_text(name: str, failures: list) -> str: + """The open failures the take found, logged before any hardware access, as the + previous-cleanup-failure cell names them ('' for none).""" + found = hil_lock.failure_report(failures) + if not found: + return '' + log_line(f'{name:25} {len(failures)} open cleanup failure(s): ' + + '; '.join(hil_lock.failure_text(f) for f in failures)) + text = hil_lock.failure_text(found['previousCleanupFailure']) + if found.get('openCleanupFailures', 1) > 1: + text += f' (+{found["openCleanupFailures"] - 1} more open)' + return text + + +def admission_refused(name: str, task, e: Exception) -> tuple: + """test_board's result for a board refused before any hardware access: one refusal cell, + failed-tests empty so a re-run repeats the whole board (no bogus -bt filter).""" + log_line(f'{name:25} {STATUS_FAILED}: {e}') + fail = hil_report.REPORT_CELL['fail'] # icon-prefixed, so the table tallies it as a failure + if isinstance(e, hil_lock.BoardBusy): + cells = {hil_report.PROBE_BUSY_CELL: f'{fail} probe in use by {hil_flash.users_text(e.users)}'} + elif isinstance(e, hil_flash.ProbeCheckFailed): + cells = {hil_report.PROBE_BUSY_CELL: f'{fail} probe check: {e}'} + elif isinstance(e, hil_lock.RecoveryBlocked): # a live cleanup holder from an older helper + cells = {hil_report.RECOVERY_BLOCKER_CELL: f'{fail} {e}'} + elif isinstance(e, hil_lock.LockUnavailable): + cells = {hil_report.LOCK_UNAVAILABLE_CELL: f'{fail} {e}'} + elif isinstance(e, RuntimeError): + cells = {hil_report.LOCKED_CELL: 'fail'} + else: + raise e + if previous := previous_cleanup_text(name, task.cleanup_failures): + cells[hil_report.PREVIOUS_CLEANUP_CELL] = previous + return name, 1, [], [(name, cells, None)], None def test_board(board: Board) -> tuple: # (name, err_count, failed_tests, rows, pci) name = board['name'] lock = hil_util.lock_name(board) - flasher = board['flasher'] global board_wedged, board_pci board_wedged = '' board_pci = None + # protected for every flasher: a worker killed mid-task leaves its record for the next take to log + task = hil_lock.board_task(lock, hil_lock.CI_REASON, busy=lambda: hil_flash.probe_busy(board), + allow_bypass=True) + entered = False try: - # cleanupOwed records a killed openocd_esp task for the next taker to log. - protected = flasher['name'].lower() == 'openocd_esp' - _lock_fh = hil_lock.acquire_board_lock(lock, protected=protected) - except hil_lock.LockUnavailable as e: - log_line(f'{name:25} {STATUS_FAILED}: {e}') - # icon-prefixed like every failing metric cell, so the table tallies it as a failure - cell = f'{hil_report.REPORT_CELL["fail"]} {e}' - return name, 1, [], [(name, {hil_report.LOCK_UNAVAILABLE_CELL: cell}, None)], None - except RuntimeError as e: - log_line(f'{name:25} {STATUS_FAILED}: {e}') - if isinstance(e, hil_lock.RecoveryBlocked): # a live cleanup holder from an older helper - cell = f'{hil_report.REPORT_CELL["fail"]} {e}' - return name, 1, [], [(name, {hil_report.RECOVERY_BLOCKER_CELL: cell}, None)], None - # visible report row so the ❌ matches the exit code; failed-tests stays empty so a - # re-run repeats the whole board (no bogus -bt filter) - return name, 1, [], [(name, {hil_report.LOCKED_CELL: 'fail'}, None)], None - try: - failures = _lock_fh.cleanup_failures if _lock_fh else [] - previous_cleanup = '' - if found := hil_lock.failure_report(failures): - previous_cleanup = hil_lock.failure_text(found['previousCleanupFailure']) - if found.get('openCleanupFailures', 1) > 1: - previous_cleanup += f' (+{found["openCleanupFailures"] - 1} more open)' - log_line(f'{name:25} {len(failures)} open cleanup failure(s): ' + - '; '.join(hil_lock.failure_text(f) for f in failures)) - test_list, skipped = _tests_for(board) - for skip in skipped: - log_line(f'{name:25} {skip:30} ... Skip') - - err_count = 0 - failed_tests = [] - board_wide_fail = False # re-run the whole board, not a subset of its tests - rows = [] # list of (row_label, {example: status}, duration) — one per build variant - # a -t/-bt filtered run times only a subset; report no duration so an accumulate - # re-run keeps the previous full-run value - partial = bool(test_only) or name in board_test - variants = hil_report.board_variants(board) - - if not skip_flash: - # board_wedged does not outlive a cancelled or SIGKILLed run, but its D-state - # testusb does, and the first flash would block on it (#4126) - strays = usbtest.strays_on(board['uid']) - if strays: - sweep_out = io.StringIO() - with redirect_stdout(sweep_out): - board_wedged = usbtest.recover_strays(board, strays) - log_line(f'{name:25} stray testusb: {compact_output(sweep_out.getvalue())}') - if board_wedged: - # no test runs to charge it, unlike a wedge test_device_usbtest latches - err_count += 1 + with task: + entered = True + previous_cleanup = previous_cleanup_text(name, task.cleanup_failures) + parked = [] # the final park's success, kept for a battery that raises after it + try: + err_count, failed_tests, board_wide_fail, rows, unrestored = _board_battery(board, parked) + except BaseException as e: + _unwinding_verdict(task, board, e, parked) + raise + _verdict(task, board, unrestored) + except BaseException as e: + if not entered and isinstance(e, Exception): + return admission_refused(name, task, e) + if entered: + log_line(f'{name:25} ended by {type(e).__name__}: {task_ending(task, lock)}') + raise - prev_last = None # last test of the previous variant: the variant boundary is an adjacency too - for v in variants: - vname = v['name'] - # Shuffle each (board, variant)'s run order: spreads batteries and flash churn - # across the timeline instead of convoying, and surfaces order-dependent bugs. - # Seeded for replay (HIL_SHUFFLE_SEED). Unique per-example PIDs re-enumerate - # between examples; only the variant boundary can repeat one. - run_list = list(test_list) - if shuffle_seed is not None and len(run_list) > 1: - random.Random(f'{shuffle_seed}:{name}:{vname}').shuffle(run_list) - if run_list[0] == prev_last: - run_list[0], run_list[-1] = run_list[-1], run_list[0] - cells = {} - # beside a pending cleanup no park may flash; the loop below skips every test instead - if run_list and run_list[0] == prev_last and not skip_flash and not cleanup_pending(name): - # Same example (same PID) still repeats across the boundary (a one-test - # -bt run has nothing to swap with). Park on board_test first: it disables - # the board's USB, so the next flash must re-enumerate to be seen. - park_ec, park_status, _ = ( - test_example(board, vname, 'device/board_test') if _should_park(skip_flash) - else (0, 'skip', None)) - if park_ec or park_status == 'skip': - # Boundary not cleared: the previous variant may still be enumerated - # under the same PID, so this variant's tests could pass against ITS - # firmware. Skip them and record the boundary as the failure, so the - # report matches the exit code instead of rendering all-green. - # A 'skip' here has two very different causes: no board_test build, or - # _should_park refusing to flash a WEDGED board. Reporting the latter as - # a missing binary sends the operator hunting a build that exists. - wedge_skip = park_status == 'skip' and bool(board_wedged) - why = ('the board is wedged' if wedge_skip else - 'no board_test binary' if park_status == 'skip' else - 'park flash failed') - log_line(f'{vname:40} {"same-PID boundary":30} {STATUS_FAILED}: not cleared ({why}); ' - f'skipping {len(run_list)} test(s) on this variant') - # the wedge already charged its own error through test_device_usbtest; - # charging again would double-count one incident in the exit code - if not wedge_skip: - err_count += 1 - cells[hil_report.BOUNDARY_CELL] = 'fail' - # blaming run_list[0] would re-run an innocent test that then passes, - # leaving the boundary unretested; re-run the whole board instead - board_wide_fail = True - # leave prev_last alone: the board still holds the previous variant's - # firmware, so the next variant must attempt the park again - run_list = [] - if run_list: - prev_last = run_list[-1] - t_variant = time.monotonic() - for test in run_list: - if cleanup_pending(name): - cells[test] = f'{hil_report.REPORT_CELL["skip"]} cleanup pending' - board_wide_fail = True - continue - if board_wedged: - # Do NOT flash through a poisoned node: each attempt enumerates into - # it, blocks uninterruptibly and leaves another stray behind. Report - # the skip so the cell is not mistaken for a pass. - cells[test] = f'{hil_report.REPORT_CELL["skip"]} board wedged' - # ...and re-run the WHOLE board, like the boundary-failure path above: - # these tests never executed, so naming them individually in the .failed - # spec is not enough -- an --accumulate re-run that fixes only the wedged - # test would merge a green cell over it and leave these skips standing - # from the earlier attempt, forever, under a green job. - board_wide_fail = True - continue - ec, status, metric = test_example(board, vname, test) - err_count += ec - cells[test] = metric if metric else status - if ec > 0: - failed_tests.append(test) + if task.restore_notes: + log_line(f'{name:25} ' + '; '.join(task.restore_notes)) + previous_cleanup += ('; ' + '; '.join(task.restore_notes) if task.bypassed else + f'; {len(task.restore_notes)} still open') + unclean = task.taken and not task.ended_cleanly + if task.errors and not unclean and previous_cleanup: + previous_cleanup += '; board task notes: ' + '; '.join(task.errors) # advisory, e.g. a restoration + ending = task_ending(task, lock) + if pending := cleanup_pending(name): + log_line(f'{name:25} BLOCKER: {pending}; {ending}') + rows.append((name, {hil_report.CLEANUP_PENDING_CELL: f'{hil_report.REPORT_CELL["fail"]} {pending}; {ending}'}, + None)) + err_count += 1 + board_wide_fail = True + elif unclean: + # the lock did not end as its verdict asked: never a passing board + log_line(f'{name:25} BLOCKER: board task ended with errors: {ending}') + rows.append((name, {hil_report.CLEANUP_PENDING_CELL: + f'{hil_report.REPORT_CELL["fail"]} board task ended with errors: {ending}'}, None)) + err_count += 1 + board_wide_fail = True + elif unrestored: + log_line(f'{name:25} board not restored ({unrestored}): failed cleanup logged; {ending}') + if previous_cleanup and rows: + rows[0][1][hil_report.PREVIOUS_CLEANUP_CELL] = previous_cleanup + return (name, err_count, [] if board_wide_fail else sorted(set(failed_tests)), + rows, board_pci) + + +def _unwinding_verdict(task, board: Board, e: BaseException, parked: list) -> None: + """The verdict of a battery that raised: a pending cleanup's evidence; restored when its final + park still ran and succeeded (the run itself stays aborted by `e`); for openocd_esp an + interrupt that may have landed after the provider returned a pending session but before + hil_flash stored its receipt; otherwise none, and the task ends failed naming `e`.""" + name = board['name'] + if pending := cleanup_pending(name): + task.failed(detail=pending, **pending_evidence(name, pending)) + elif parked: + task.restored(evidence='device/board_test park succeeded') + elif board['flasher']['name'].lower() == 'openocd_esp' and not isinstance(e, Exception): + missing = 'openocd_esp interrupted; cleanup unproven, receipt missing' + task.failed(detail=missing, receipts=[{'unrecheckable': missing}]) + + +def _verdict(task, board: Board, unrestored: str) -> None: + """The battery's cleanup verdict, its last act under the lock (the HIL contract's Reservation).""" + name = board['name'] + if pending := cleanup_pending(name): + task.failed(detail=pending, **pending_evidence(name, pending)) + elif unrestored: + task.failed(detail=f'board not restored: {unrestored}') + elif skip_flash: + task.clean() # flashed nothing, so every operation ended leaves the board as found + else: + task.restored(evidence='device/board_test park succeeded') + + +def _board_battery(board: Board, parked: list) -> tuple: + """The board's tests and its final park, under its task: (err_count, failed_tests, + board_wide_fail, rows, why the board is not restored or ''). A successful park also appends to + `parked`, which outlives an exception raised past it.""" + name = board['name'] + global board_wedged + test_list, skipped = _tests_for(board) + for skip in skipped: + log_line(f'{name:25} {skip:30} ... Skip') + + err_count = 0 + failed_tests = [] + board_wide_fail = False # re-run the whole board, not a subset of its tests + rows = [] # list of (row_label, {example: status}, duration) — one per build variant + # a -t/-bt filtered run times only a subset; report no duration so an accumulate + # re-run keeps the previous full-run value + partial = bool(test_only) or name in board_test + variants = hil_report.board_variants(board) + + if not skip_flash: + # board_wedged does not outlive a cancelled or SIGKILLed run, but its D-state + # testusb does, and the first flash would block on it (#4126) + strays = usbtest.strays_on(board['uid']) + if strays: + sweep_out = io.StringIO() + with redirect_stdout(sweep_out): + board_wedged = usbtest.recover_strays(board, strays) + log_line(f'{name:25} stray testusb: {compact_output(sweep_out.getvalue())}') if board_wedged: - log_line(f'{vname:40} SKIPPING the rest of this board: {board_wedged}; ' - f'flashing through the poisoned node would add a stray per test') - cells[hil_report.WEDGED_CELL] = 'fail' - dur = f'{time.monotonic() - t_variant:.0f}s' if run_list and not partial else None - rows.append((vname, cells, dur)) - - restored = False - sv_capture = None # (capture, error, flashed) - try: - if sysview_out and 'sysview' in board and \ - any(t.startswith(('device/', 'dual/')) for t in test_list): - try: - sv_capture = _sysview_capture(board, variants[0]['name']) - except Exception as e: - # optional: the board's tests, its park and its blocker check go on - log_line(f'{name:25} SystemView capture raised {type(e).__name__}: {e}') - sv_capture = None, f'{type(e).__name__}: {e}', True - finally: - # park: flash board_test last to disable the board's usb, after the capture too and when - # it is interrupted; teardown, not a test, so it is not recorded in the report. - park_error = None - if _should_park(skip_flash): - park_ec, park_status, _ = test_example(board, variants[0]['name'], 'device/board_test') - restored = park_ec == 0 and park_status == 'pass' - park_error = ('park flash failed' if park_ec else - 'no park (device/board_test) firmware' if park_status == 'skip' else None) - elif sv_capture and sv_capture[2]: - # the capture left the board wedged or a provider cleanup pending - park_error = f'not parked: {_park_refusal()}' - if sv_capture: - capture, error, flashed = sv_capture - try: - # a capture that never flashed left the board as the tests did: its park is the run's own business - sysview_ci.write_result(sysview_out, sysview_ci.capture_result( - board, sysview_commit, capture, error, park_error=park_error if flashed else None, - identity=sysview_identity)) - except Exception as e: - log_line(f'{name:25} SystemView capture record not written: {type(e).__name__}: {e}') - - pending = cleanup_pending(name) - if pending: - log_line(f'{name:25} BLOCKER: {pending}') - fh, _lock_fh = _lock_fh, None # end_failed releases even when interrupted - detail = end_failed_cleanup(name, lock, fh, pending) if fh else f'{pending}; no board lock held' - log_line(f'{name:25} {detail}') - rows.append((name, {hil_report.CLEANUP_PENDING_CELL: f'{hil_report.REPORT_CELL["fail"]} {detail}'}, None)) - err_count += 1 - board_wide_fail = True - elif restored and failures: + # no test runs to charge it, unlike a wedge test_device_usbtest latches + err_count += 1 + + prev_last = None # last test of the previous variant: the variant boundary is an adjacency too + for v in variants: + vname = v['name'] + # Shuffle each (board, variant)'s run order: spreads batteries and flash churn + # across the timeline instead of convoying, and surfaces order-dependent bugs. + # Seeded for replay (HIL_SHUFFLE_SEED). Unique per-example PIDs re-enumerate + # between examples; only the variant boundary can repeat one. + run_list = list(test_list) + if shuffle_seed is not None and len(run_list) > 1: + random.Random(f'{shuffle_seed}:{name}:{vname}').shuffle(run_list) + if run_list[0] == prev_last: + run_list[0], run_list[-1] = run_list[-1], run_list[0] + cells = {} + # beside a pending cleanup no park may flash; the loop below skips every test instead + if run_list and run_list[0] == prev_last and not skip_flash and not cleanup_pending(name): + # Same example (same PID) still repeats across the boundary (a one-test + # -bt run has nothing to swap with). Park on board_test first: it disables + # the board's USB, so the next flash must re-enumerate to be seen. + park_ec, park_status, _ = ( + test_example(board, vname, 'device/board_test') if _should_park(skip_flash) + else (0, 'skip', None)) + if park_ec or park_status == 'skip': + # Boundary not cleared: the previous variant may still be enumerated + # under the same PID, so this variant's tests could pass against ITS + # firmware. Skip them and record the boundary as the failure, so the + # report matches the exit code instead of rendering all-green. + # A 'skip' here has two very different causes: no board_test build, or + # _should_park refusing to flash a WEDGED board. Reporting the latter as + # a missing binary sends the operator hunting a build that exists. + wedge_skip = park_status == 'skip' and bool(board_wedged) + why = ('the board is wedged' if wedge_skip else + 'no board_test binary' if park_status == 'skip' else + 'park flash failed') + log_line(f'{vname:40} {"same-PID boundary":30} {STATUS_FAILED}: not cleared ({why}); ' + f'skipping {len(run_list)} test(s) on this variant') + # the wedge already charged its own error through test_device_usbtest; + # charging again would double-count one incident in the exit code + if not wedge_skip: + err_count += 1 + cells[hil_report.BOUNDARY_CELL] = 'fail' + # blaming run_list[0] would re-run an innocent test that then passes, + # leaving the boundary unretested; re-run the whole board instead + board_wide_fail = True + # leave prev_last alone: the board still holds the previous variant's + # firmware, so the next variant must attempt the park again + run_list = [] + if run_list: + prev_last = run_list[-1] + t_variant = time.monotonic() + for test in run_list: + if cleanup_pending(name): + cells[test] = f'{hil_report.REPORT_CELL["skip"]} cleanup pending' + board_wide_fail = True + continue + if board_wedged: + # Do NOT flash through a poisoned node: each attempt enumerates into + # it, blocks uninterruptibly and leaves another stray behind. Report + # the skip so the cell is not mistaken for a pass. + cells[test] = f'{hil_report.REPORT_CELL["skip"]} board wedged' + # ...and re-run the WHOLE board, like the boundary-failure path above: + # these tests never executed, so naming them individually in the .failed + # spec is not enough -- an --accumulate re-run that fixes only the wedged + # test would merge a green cell over it and leave these skips standing + # from the earlier attempt, forever, under a green job. + board_wide_fail = True + continue + ec, status, metric = test_example(board, vname, test) + err_count += ec + cells[test] = metric if metric else status + if ec > 0: + failed_tests.append(test) + if board_wedged: + log_line(f'{vname:40} SKIPPING the rest of this board: {board_wedged}; ' + f'flashing through the poisoned node would add a stray per test') + cells[hil_report.WEDGED_CELL] = 'fail' + dur = f'{time.monotonic() - t_variant:.0f}s' if run_list and not partial else None + rows.append((vname, cells, dur)) + + restored = False + sv_capture = None # (capture, error, flashed) + try: + if sysview_out and 'sysview' in board and \ + any(t.startswith(('device/', 'dual/')) for t in test_list): try: - notes = hil_lock.resolve_restored(lock, failures, evidence='device/board_test park succeeded') + sv_capture = _sysview_capture(board, variants[0]['name']) except Exception as e: - previous_cleanup += f'; restorations not logged: {e}' - else: - if notes: - previous_cleanup += f'; {len(notes)} still open' - log_line(f'{name:25} ' + '; '.join(notes)) - if previous_cleanup and rows: - rows[0][1][hil_report.PREVIOUS_CLEANUP_CELL] = previous_cleanup - - return (name, err_count, [] if board_wide_fail else sorted(set(failed_tests)), - rows, board_pci) + # optional: the board's tests, its park and its blocker check go on + log_line(f'{name:25} SystemView capture raised {type(e).__name__}: {e}') + sv_capture = None, f'{type(e).__name__}: {e}', True finally: - unwinding = sys.exc_info()[1] - if _lock_fh and (pending := cleanup_pending(name)): - log_line(f'{name:25} {end_failed_cleanup(name, lock, _lock_fh, pending)}') - elif _lock_fh and protected and unwinding is not None and not isinstance(unwinding, Exception): - # an interrupt may land after the provider returned a pending session but before - # hil_flash stored its receipt: log the missing evidence rather than claim cleanup. - detail = end_failed_cleanup(name, lock, _lock_fh, - 'openocd_esp interrupted; cleanup unproven, receipt missing') - log_line(f'{name:25} {detail}') - elif _lock_fh: - # clear our pid record before dropping the flock: this worker process - # lives on (pool reuse), so a stale record would make hil_lock's - # pid-liveness checks report a freed board as locked for the rest of the run - hil_lock.clear_record(_lock_fh) - _lock_fh.close() + # park: flash board_test last to disable the board's usb, after the capture too and when + # it is interrupted; teardown, not a test, so it is not recorded in the report. + park_error = None + if _should_park(skip_flash): + park_ec, park_status, _ = test_example(board, variants[0]['name'], 'device/board_test') + restored = park_ec == 0 and park_status == 'pass' + if restored: + parked.append(True) + park_error = ('park flash failed' if park_ec else + 'no park (device/board_test) firmware' if park_status == 'skip' else None) + elif sv_capture and sv_capture[2]: + # the capture left the board wedged or a provider cleanup pending + park_error = f'not parked: {_park_refusal()}' + if sv_capture: + capture, error, flashed = sv_capture + try: + # a capture that never flashed left the board as the tests did: its park is the run's own business + sysview_ci.write_result(sysview_out, sysview_ci.capture_result( + board, sysview_commit, capture, error, park_error=park_error if flashed else None, + identity=sysview_identity)) + except Exception as e: + log_line(f'{name:25} SystemView capture record not written: {type(e).__name__}: {e}') + + if restored: + unrestored = '' + elif board_wedged: # failed whether or not this run flashed + unrestored = park_error or f'not parked: the board is wedged: {board_wedged}' + elif skip_flash and not park_error: + unrestored = '' # nothing flashed: no park owed + else: + unrestored = park_error or f'not parked: {_park_refusal()}' + return err_count, failed_tests, board_wide_fail, rows, unrestored # controller hints from previous runs: uid -> {'name', 'pci'}; 'pci' sets the dispatch order. diff --git a/test/hil/test/test_hil_bounded.py b/test/hil/test/test_hil_bounded.py index 8fb4a767e5..d9712e281c 100644 --- a/test/hil/test/test_hil_bounded.py +++ b/test/hil/test/test_hil_bounded.py @@ -1416,8 +1416,9 @@ def test_example(board, variant, example): with mock.patch.object(hil_test, 'skip_flash', False), \ mock.patch.object(hil_test, 'shuffle_seed', None), \ mock.patch.object(hil_flash, 'cleanup_pending', {}), \ - mock.patch.object(hil_test.hil_lock, 'acquire_board_lock', return_value=mock.Mock(cleanup_failures=[])), \ - mock.patch.object(hil_test, 'end_failed_cleanup', return_value='logged'), \ + TemporaryDirectory() as locks, \ + mock.patch.object(hil_test.hil_lock, 'BOARD_LOCK_DIR', locks), \ + mock.patch.object(hil_flash, 'probe_busy', return_value=[]), \ mock.patch.object(hil_test.usbtest, 'strays_on', return_value=[]), \ mock.patch.object(hil_test, '_tests_for', return_value=(['device/cdc_msc'], [])), \ mock.patch.object(hil_test, 'test_example', test_example), \ diff --git a/test/hil/test/test_hil_farm_check.py b/test/hil/test/test_hil_farm_check.py index cf9c6b4d3e..4d8d8df3df 100644 --- a/test/hil/test/test_hil_farm_check.py +++ b/test/hil/test/test_hil_farm_check.py @@ -93,6 +93,21 @@ def runpy_helper(): run_name='helper._hil_lock_cli')) +class Busy(unittest.TestCase): + def test_the_hook_is_the_batterys_own_busy_check(self): + users = [{'pid': 7, 'cmd': 'openocd -c "adapter serial P"'}] + seen = [] + patch(self, hil_flash, 'probe_busy', lambda board: seen.append(board) or users) + self.assertIs(farm_profile.busy(BOARD), users) + self.assertEqual(seen, [BOARD]) + + def test_an_inconclusive_check_raises_through_the_hook(self): + def inconclusive(board): + raise RuntimeError('/proc may hide other users') + patch(self, hil_flash, 'probe_busy', inconclusive) + with self.assertRaisesRegex(RuntimeError, 'hide'): + farm_profile.busy(BOARD) + class Roster(unittest.TestCase): def test_a_rig_host_gets_its_roster(self): got = farm_profile.roster('ci', None, args()) diff --git a/test/hil/test/test_hil_flash.py b/test/hil/test/test_hil_flash.py index d1267df90b..df699305c6 100644 --- a/test/hil/test/test_hil_flash.py +++ b/test/hil/test/test_hil_flash.py @@ -114,6 +114,29 @@ def test_each_flasher_routes_to_its_provider_operation_with_the_callers_bound_an self.assertEqual((called, pargs[0]), (f'{verb}_{name}', BOARDS[name])) self.assertEqual((kw['timeout'], kw['run']), (7, hil_util.run_cmd)) + def test_probe_busy_asks_for_each_entry_of_the_probe_once(self): + asked = [] + users = {'jlink': [{'pid': 9, 'cmd': 'JLinkExe -USB S1'}, {'pid': 3, 'cmd': 'gdb'}], + 'openocd': [{'pid': 9, 'cmd': 'JLinkExe -USB S1'}]} + self.provider.probe_users = lambda f: asked.append(f) or users[f['name']] + board = {'name': 'b', 'flasher': dict(BOARDS['jlink']), 'flasher_recover': {'name': 'openocd', 'args': ''}} + got = hil_flash.probe_busy(board) + self.assertEqual(asked, [BOARDS['jlink'], {'name': 'openocd', 'args': '', 'uid': 'S1'}]) + self.assertEqual(got, [{'pid': 3, 'cmd': 'gdb'}, {'pid': 9, 'cmd': 'JLinkExe -USB S1'}]) + self.assertEqual(hil_flash.users_text(got), 'pid 3 (gdb), pid 9 (JLinkExe -USB S1)') + asked.clear() + hil_flash.probe_busy({'name': 'b', 'flasher': dict(BOARDS['jlink'])}) + self.assertEqual(asked, [BOARDS['jlink']], 'no recovery entry: the primary alone, once') + + def test_every_rostered_flasher_has_a_probe_lookup(self): + # the busy check refuses a board whose flasher it cannot look up, so a roster must not name one + for name in flasher_names(): + with self.subTest(name=name): + try: + hil_util.provider().probe_users(BOARDS[name]) + except hil_util.provider().ProbeCheckInconclusive: + pass # no such probe on this host + def test_without_a_bound_cmd_timeout_is_read_at_call_time(self): self.addCleanup(setattr, hil_util, 'CMD_TIMEOUT', hil_util.CMD_TIMEOUT) hil_util.CMD_TIMEOUT = 33 diff --git a/test/hil/test/test_hil_lock.py b/test/hil/test/test_hil_lock.py index 8e9eb17d05..117267de1e 100644 --- a/test/hil/test/test_hil_lock.py +++ b/test/hil/test/test_hil_lock.py @@ -1,10 +1,10 @@ #!/usr/bin/env python3 # SPDX-License-Identifier: MIT # The hil_lock adapter: callers get agentrc's board-lock primitive from the agentrc helper/agentrc.py -# selects (agentrc's tests/test_hil_lock.py covers the primitive itself), hil_test refuses a board -# whose lock is unavailable before flashing, a recovery blocker refuses the board as a blocker -# rather than contention (RecoveryBlockerIsNotContention), an openocd_esp session left running is -# logged before the board's lock is released (FailedCleanup), `hold --all` takes this host's roster, and an +# selects (agentrc's tests/test_hil_lock.py covers the primitive and board_task itself), hil_test refuses a +# board whose lock is unavailable or whose probe is busy before flashing, a recovery blocker refuses the board +# as a blocker rather than contention (RecoveryBlockerIsNotContention), each board task ends on its +# cleanup verdict (FailedCleanup, Verdicts), `hold --all` takes this host's roster, and an # incomplete agentrc refuses at import (test_hil_agentrc.py covers the loader). Every lock lives in a # temp dir under a name no rig uses. Run directly: # python3 test/hil/test/test_hil_lock.py @@ -48,6 +48,13 @@ def setUp(self): env.start() self.addCleanup(env.stop) os.environ.pop('HIL_NO_BOARD_LOCK', None) + self.users = [] # what the busy check names; an exception raises from it + patch(self, hil_flash, 'probe_busy', self.probe_busy) + + def probe_busy(self, board): + if isinstance(self.users, BaseException): + raise self.users + return self.users def lock_dir_is_a_file(self): path = os.path.join(self.dir, 'not-a-dir') @@ -81,7 +88,7 @@ def test_lock_unavailable_fails_the_board_unflashed(self): self.assertIn(f'{hil_test.STATUS_FAILED}: board lock unavailable: ', self.log[0]) def test_contention_keeps_its_own_cell(self): - def held(name, **kw): + def held(name, *a, **kw): raise RuntimeError('board locked: {"pid": 1}') patch(self, hil_lock, 'acquire_board_lock', held) _, err, _, rows, _ = hil_test.test_board(self.board) @@ -94,7 +101,7 @@ def test_a_registered_board_is_locked_by_its_registry_name(self): 'tests': {'only': ['device/cdc_msc']}}) locked = [] - def held(name, **kw): + def held(name, *a, **kw): locked.append(name) raise RuntimeError('board locked: {"pid": 1}') patch(self, hil_lock, 'acquire_board_lock', held) @@ -429,9 +436,10 @@ def test_tracked_and_retained_receipts_are_logged_separately(self): native = {'pid': 4242, 'startTime': '99', 'argv': ['openocd'], 'ports': [None, None, 6666], 'token': 'x', 'log': '/w/openocd.log', 'closed': False, 'tool': 'hil_openocd_esp', 'init': 'ok', 'submitted': 3} hil_flash.cleanup_pending[BOARD] = (native, self.TRACKED, self.RECEIPT) - fh = hil_lock.take_board_lock(LOCK, 'hil_test.py', protected=True) - cell = hil_test.end_failed_cleanup(BOARD, LOCK, fh, hil_test.cleanup_pending(BOARD)) - self.assertTrue(fh.closed) + cell = hil_test.cleanup_pending(BOARD) + with hil_lock.board_task(LOCK, 'hil_test.py', busy=list) as task: + task.failed(detail=cell, **hil_test.pending_evidence(BOARD, cell)) + self.assertTrue(task.released) failure = self.assert_released(LOCK) self.assertEqual(failure['task']['locks'], [LOCK]) self.assertEqual(failure['receipts'], [self.TRACKED]) @@ -521,6 +529,7 @@ def test_a_log_write_failure_still_releases_and_reports_the_error(self): _, err, _, rows, _ = hil_test.test_board(self.board) self.assertEqual(err, 2) cell = rows[-1][1][hil_test.hil_report.CLEANUP_PENDING_CELL] + self.assertIn('cleanup failure NOT logged', cell) self.assertIn('cleanup log not written', cell) self.assertIn('log is read-only', cell) self.assertEqual(hil_lock.record_state(BOARD)[0], 'empty') @@ -570,7 +579,7 @@ def test_a_restoration_exception_keeps_its_diagnostic_in_the_notice(self): _, err, _, rows, _ = hil_test.test_board(self.board) self.assertEqual(err, 0) self.assertEqual(rows[0][1][hil_test.hil_report.PREVIOUS_CLEANUP_CELL], - hil_lock.failure_text(failure) + '; restorations not logged: log inaccessible') + hil_lock.failure_text(failure) + "; board task notes: restoration: OSError('log inaccessible')") def test_skip_flash_does_not_claim_an_earlier_cleanup_restored(self): self.end_session() @@ -580,16 +589,21 @@ def test_skip_flash_does_not_claim_an_earlier_cleanup_restored(self): self.assertEqual(hil_test.test_board(self.board)[1], 0) self.assertEqual(hil_lock.open_cleanup_failures(BOARD), [failure]) - def test_an_unproven_park_does_not_resolve_an_earlier_failure(self): + def test_an_unproven_park_does_not_resolve_an_earlier_failure_and_fails_its_own_cleanup(self): self.end_session() failure = hil_lock.log_cleanup_failure(BOARD, 'earlier', detail='old session', retained=[self.RECEIPT]) - for outcome in ((1, 'fail', None), (0, 'skip', None)): + for outcome, why in (((1, 'fail', None), 'park flash failed'), + ((0, 'skip', None), 'no park (device/board_test) firmware')): with self.subTest(outcome=outcome): def example(board, variant, test): return outcome if test == 'device/board_test' else (0, 'pass', None) with mock.patch.object(hil_test, 'test_example', example): - hil_test.test_board(self.board) - self.assertEqual(hil_lock.open_cleanup_failures(BOARD), [failure]) + _, err, _, rows, _ = hil_test.test_board(self.board) + self.assertEqual(err, 0) # the park is teardown: its failure is the next take's notice + opened = hil_lock.open_cleanup_failures(BOARD) + self.assertEqual(opened[0], failure) + self.assertEqual((opened[-1]['detail'], opened[-1]['receipts']), (f'board not restored: {why}', [])) + self.assertIn('board not restored', self.log[-1]) def test_previous_failures_do_not_erase_a_current_wedge_on_the_same_row(self): hil_lock.log_cleanup_failure(BOARD, 'earlier', detail='old session', retained=[self.RECEIPT]) @@ -628,5 +642,194 @@ def test_a_free_takeover_journal_is_logged_and_admitted(self): self.assertEqual(failure['journal'], journal) +_HELD = [] + + +def _gap_in_worker(lock): + """A task whose interrupt landed as __exit__ was entered: its flock still held, and its handle + still referenced (as by a traceback), when the task returns.""" + task = hil_lock.board_task(lock, 'hil_test.py', busy=list) + task.__enter__() + _HELD.append(task) + return os.getpid() + + +class Admission(LockDir): + """The busy check runs under the taken lock before any hardware access: a named user or an + inconclusive check refuses the board with a probe-busy cell, releases the lock and logs nothing.""" + + def setUp(self): + super().setUp() + self.log = [] + patch(self, hil_test, 'log_line', self.log.append) + patch(self, hil_flash, 'flash_primitive', lambda *a: self.fail('flashed')) + patch(self, hil_test.usbtest, 'strays_on', lambda uid: self.fail('swept')) + self.board = {'name': BOARD, 'uid': 'ABC123', 'flasher': {'name': 'jlink', 'uid': 'P'}, + 'tests': {'only': ['device/cdc_msc']}} + + def refusal(self): + events = hil_lock.cleanup_events(BOARD) + name, err, failed, rows, _ = hil_test.test_board(self.board) + self.assertEqual((name, err, failed, len(rows)), (BOARD, 1, [], 1)) + self.assertEqual(hil_lock.record_state(BOARD)[0], 'empty') + self.assertEqual(hil_lock.cleanup_events(BOARD), events, 'a refusal logged an event') + hil_lock.release_board_lock(hil_lock.take_board_lock(BOARD, 'peer')) # free + return rows[0][1] + + def test_a_live_probe_user_refuses_the_board(self): + self.users = [{'pid': 4242, 'cmd': 'JLinkExe -USB 000000123'}] + cells = self.refusal() + cell = cells[hil_test.hil_report.PROBE_BUSY_CELL] + self.assertEqual(cell, f'{hil_test.hil_report.REPORT_CELL["fail"]} probe in use by pid 4242 ' + f'(JLinkExe -USB 000000123)') + self.assertEqual(hil_test.hil_report.cell_state(cell), 'fail') + + def test_an_inconclusive_check_refuses_too(self): + self.users = hil_flash.ProbeCheckFailed('RuntimeError: /proc may hide other users\' processes') + cell = self.refusal()[hil_test.hil_report.PROBE_BUSY_CELL] + self.assertIn('probe check: RuntimeError: /proc may hide', cell) + + def test_a_refusal_still_reports_the_failures_the_take_found(self): + failure = hil_lock.log_cleanup_failure(BOARD, 'earlier', detail='old session') + self.users = [{'pid': 1, 'cmd': 'openocd'}] + cells = self.refusal() + self.assertEqual(cells[hil_test.hil_report.PREVIOUS_CLEANUP_CELL], hil_lock.failure_text(failure)) + self.assertEqual(hil_lock.open_cleanup_failures(BOARD), [failure]) + + def test_the_bypass_still_runs_the_busy_check(self): + os.environ['HIL_NO_BOARD_LOCK'] = '1' + self.users = [{'pid': 1, 'cmd': 'openocd'}] + _, err, _, rows, _ = hil_test.test_board(self.board) + self.assertEqual(err, 1) + self.assertIn(hil_test.hil_report.PROBE_BUSY_CELL, rows[0][1]) + self.assertEqual(hil_lock.record_state(BOARD)[0], 'absent') + + def test_a_refused_board_is_not_run_in_the_report(self): + self.users = [{'pid': 1, 'cmd': 'openocd'}] + _, err, _, rows, _ = hil_test.test_board(self.board) + report = hil_test.hil_report + with tempfile.TemporaryDirectory() as tmp: + report.accumulate_report([(BOARD, err, [], rows, None)], Path(tmp), True) + doc, _ = report._load(Path(tmp)) + result = report.normalised_rows({'boards': [self.board]}, [BOARD], doc)[0] + self.assertEqual(result['verdict'], 'not-run') + self.assertIn('probe in use by pid 1', result['detail']) + + +class Verdicts(LockDir): + """test_board's cleanup verdict on a board with no provider session: a successful park + restores, --skip-flash ends clean, an unproven park or an interrupt fails the cleanup, and a + later park resolves that failure.""" + + def setUp(self): + super().setUp() + self.log = [] + patch(self, hil_test, 'log_line', self.log.append) + patch(self, hil_test, 'skip_flash', False) + patch(self, hil_flash, 'cleanup_pending', {}) + patch(self, hil_test.usbtest, 'strays_on', lambda uid: []) + self.park = (0, 'pass', None) + self.test = (1, 'fail', None) + patch(self, hil_test, 'test_example', + lambda board, variant, test: self.park if test == 'device/board_test' else self.result(test)) + self.board = {'name': BOARD, 'uid': 'ABC123', 'flasher': {'name': 'jlink', 'uid': 'P'}, + 'tests': {'only': ['device/cdc_msc']}} + + def result(self, test): + if isinstance(self.test, BaseException): + raise self.test + return self.test + + def events(self, kind): + return [e for e in hil_lock.cleanup_events(BOARD) if e['event'] == kind] + + def test_a_failed_test_with_a_successful_park_restores(self): + earlier = hil_lock.log_cleanup_failure(BOARD, 'earlier', detail='killed worker') + _, err, failed, _, _ = hil_test.test_board(self.board) + self.assertEqual((err, failed), (1, ['device/cdc_msc'])) + self.assertEqual(self.events('failed'), [earlier]) + self.assertEqual([e['failure'] for e in self.events('restored')], [earlier['id']]) + self.assertEqual(self.events('restored')[0]['evidence'], 'device/board_test park succeeded') + self.assertEqual(hil_lock.record_state(BOARD)[0], 'empty') + + def test_a_wedge_fails_the_cleanup_under_skip_flash_too(self): + patch(self, hil_test, 'skip_flash', True) + self.park = None # never parked + + def wedging(test): + hil_test.board_wedged = 'usbtest HUNG' + return 1, 'fail', None + patch(self, self, 'result', wedging) + self.addCleanup(setattr, hil_test, 'board_wedged', '') + self.assertEqual(hil_test.test_board(self.board)[1], 1) + failed, = self.events('failed') + self.assertEqual(failed['detail'], 'board not restored: not parked: the board is wedged: usbtest HUNG') + + def test_skip_flash_ends_clean(self): + patch(self, hil_test, 'skip_flash', True) + self.test = (0, 'pass', None) + self.park = None # never parked + self.assertEqual(hil_test.test_board(self.board)[1], 0) + self.assertEqual(hil_lock.cleanup_events(BOARD), []) + + def test_an_interrupt_fails_the_cleanup_and_a_later_park_resolves_it(self): + self.test = KeyboardInterrupt() + with self.assertRaises(KeyboardInterrupt): + hil_test.test_board(self.board) + failure, = self.events('failed') + self.assertEqual((failure['how'], failure['receipts']), ('ended-failed', [])) + self.assertIn('ended without a cleanup verdict: KeyboardInterrupt', failure['detail']) + self.assertIn('board lock released', self.log[-1]) + self.test = (0, 'pass', None) + _, err, _, rows, _ = hil_test.test_board(self.board) + self.assertEqual(err, 0) + self.assertIn(failure['id'], rows[0][1][hil_test.hil_report.PREVIOUS_CLEANUP_CELL]) + self.assertEqual(hil_lock.open_cleanup_failures(BOARD), []) + + def test_an_exception_fails_the_cleanup_and_propagates(self): + self.test = RuntimeError('harness bug') + with self.assertRaisesRegex(RuntimeError, 'harness bug'): + hil_test.test_board(self.board) + failure, = self.events('failed') + self.assertIn('RuntimeError: harness bug', failure['detail']) + + def test_a_finalization_error_fails_the_board(self): + self.test = (0, 'pass', None) + with mock.patch.object(hil_lock, 'clear_record', return_value=False): + _, err, failed, rows, _ = hil_test.test_board(self.board) + self.assertEqual((err, failed), (1, [])) + cell = rows[-1][1][hil_test.hil_report.CLEANUP_PENDING_CELL] + self.assertIn('board task ended with errors: board lock released; cleanup failure logged', cell) + self.assertIn('record not cleared', cell) + + def test_advisory_task_errors_never_fail_the_board(self): + self.test = (0, 'pass', None) + broken = types.SimpleNamespace(InterruptHold=mock.Mock(side_effect=OSError('no signal mask'))) + with mock.patch.object(hil_lock, '_process', return_value=broken): + _, err, _, rows, _ = hil_test.test_board(self.board) + self.assertEqual(err, 0) + self.assertNotIn(hil_test.hil_report.CLEANUP_PENDING_CELL, rows[-1][1]) + + def test_a_worker_releases_its_board_when_it_exits(self): + # maxtasksperchild=1: a task left holding its flock (the __exit__-entry gap) frees it when its + # worker ends after that one task; the record it left is logged found-left by the next take + pool = hil_test._start_pool('seed') + self.addCleanup(pool.terminate) + worker = pool.apply_async(_gap_in_worker, (BOARD,)).get(timeout=30) + self.assertNotEqual(worker, os.getpid()) + deadline = time.monotonic() + 20 + while True: + try: + fh = hil_lock.take_board_lock(BOARD, 'peer') + break + except hil_lock.BoardLocked: + self.assertLess(time.monotonic(), deadline, 'the worker kept the flock') + time.sleep(0.1) + try: + self.assertEqual([f['how'] for f in fh.cleanup_failures], ['found-left']) + finally: + hil_lock.release_board_lock(fh) + + if __name__ == '__main__': unittest.main() diff --git a/test/hil/test/test_hil_report.py b/test/hil/test/test_hil_report.py index 8389ccfdff..f0941ec52b 100644 --- a/test/hil/test/test_hil_report.py +++ b/test/hil/test/test_hil_report.py @@ -468,6 +468,14 @@ def test_an_unusable_lock_dir_is_not_contention(self): self.assertEqual(got[0], {'board': 'alpha', 'ran': False, 'pass': False, 'locked': False, 'wedged': False, 'skipped': [], 'detail': cell}) + def test_a_busy_probe_is_not_run_not_contention(self): + cell = '❌ probe in use by pid 4242 (JLinkExe -USB 123)' + previous = 'last failed cleanup x (ended-failed, hil_test.py pid 1, id abc): killed' + got = self._sum(['alpha'], [('alpha', {hil_report.PROBE_BUSY_CELL: cell, + hil_report.PREVIOUS_CLEANUP_CELL: previous})]) + self.assertEqual(got[0], {'board': 'alpha', 'ran': False, 'pass': False, 'locked': False, 'wedged': False, + 'skipped': [], 'detail': f'{cell}; previous cleanup failure: {previous}'}) + def test_a_recovery_blocker_is_neither_contention_nor_a_fail(self): cell = '❌ board locked: {"pid": 7, "role": "cleanup-holder"} (recovery blocker: ...)' got = self._sum(['alpha'], [('alpha', {hil_report.RECOVERY_BLOCKER_CELL: cell})]) @@ -981,7 +989,7 @@ def test_a_cleared_boundary_drops_the_previous_attempts_mark(self): self.assertNotIn(hil_report.BOUNDARY_CELL, cells) def test_a_board_that_really_ran_drops_its_stale_lock_cell(self): - for key in (hil_report.LOCKED_CELL, hil_report.LOCK_UNAVAILABLE_CELL, hil_report.RECOVERY_BLOCKER_CELL): + for key in hil_report._REFUSAL_CELLS: with self.subTest(key=key): td = TemporaryDirectory() self.addCleanup(td.cleanup) diff --git a/test/hil/test/test_hil_sysview_capture.py b/test/hil/test/test_hil_sysview_capture.py index ed787fb536..3664503667 100644 --- a/test/hil/test/test_hil_sysview_capture.py +++ b/test/hil/test/test_hil_sysview_capture.py @@ -38,6 +38,7 @@ def setUp(self): ('log_line', lambda line: None)): patch(self, hil_test, name, value) patch(self, hil_test.usbtest, 'strays_on', lambda uid: []) + patch(self, hil_flash, 'probe_busy', lambda board: []) patch(self, hil_flash, 'find_firmware', lambda variant, example, flasher=None: f'{variant}/{example}.elf') self.events = [] self.park = (0, 'pass', None) @@ -153,7 +154,8 @@ def test_a_missing_image_or_a_failed_capture_leaves_the_verdict_alone(self): with self.subTest(name), ctx: self.events.clear() err, rows = self.run_board() - self.assertEqual((err, rows[0][1]), (0, {'device/cdc_msc': 'pass'})) + # the failed park is logged as this task's failed cleanup, the next one's notice + self.assertEqual((err, rows[0][1]['device/cdc_msc']), (0, 'pass')) self.assertEqual(self.events[-1], 'device/board_test') r = self.result() # a capture that never flashed leaves the park to the run @@ -184,10 +186,15 @@ def test_an_interrupted_capture_still_parks_then_propagates(self): def interrupted(): raise KeyboardInterrupt self.capture(interrupted) + earlier = hil_lock.log_cleanup_failure(BOARD, 'earlier', detail='killed run') with self.assertRaises(KeyboardInterrupt): hil_test.test_board(self.board) self.assertEqual(self.events, ['device/cdc_msc', 'capture', 'device/board_test']) self.assert_no_result() + # the park proved restoration: restored, the run still aborted by the interrupt + events = hil_lock.cleanup_events(BOARD) + self.assertEqual([e['event'] for e in events], ['failed', 'restored']) + self.assertEqual(events[1]['failure'], earlier['id']) hil_lock.take_board_lock(BOARD, 'after').close() # the lock was released def test_a_capture_that_wedges_the_board_is_not_parked(self): diff --git a/test/hil/test/test_hil_wedge_sweep.py b/test/hil/test/test_hil_wedge_sweep.py index ffaecfe9ca..e12d8a20a7 100644 --- a/test/hil/test/test_hil_wedge_sweep.py +++ b/test/hil/test/test_hil_wedge_sweep.py @@ -142,13 +142,10 @@ def setUp(self): p(hil_test, 'test_only', []) p(hil_test, 'board_test', {}) p(hil_test, 'log_line', lambda msg: None) - - def acquire(name, **kw): - fh = open(os.devnull) - fh.cleanup_failures = [] - return fh - p(hil_lock, 'acquire_board_lock', acquire) - p(hil_lock, 'clear_record', lambda fh: None) + locks = tempfile.TemporaryDirectory() + self.addCleanup(locks.cleanup) + p(hil_lock, 'BOARD_LOCK_DIR', locks.name) + p(hil_flash, 'probe_busy', lambda board: []) self.ran = [] p(hil_test, 'test_example', lambda board, v, ex: self.ran.append(ex) or (0, 'pass', None)) p(usbtest, 'strays_on', lambda serial: [{'pid': 1, 'start': '1', 'node': NODE}]) From cc319478c4740960abcb6edd48e483207d64170d Mon Sep 17 00:00:00 2001 From: hathach Date: Thu, 12 Nov 2026 01:44:17 +0700 Subject: [PATCH 02/16] Decide and report the board task's end through ended_cleanly and describe() --- .claude/skills/hil-contract/SKILL.md | 2 +- .claude/skills/usbtest/scripts/run_case.py | 8 +++----- .claude/test/test_usbtest_run_case.py | 7 ++++--- test/hil/hil_test.py | 19 ++++--------------- test/hil/test/test_hil_lock.py | 12 ++++++------ 5 files changed, 18 insertions(+), 30 deletions(-) diff --git a/.claude/skills/hil-contract/SKILL.md b/.claude/skills/hil-contract/SKILL.md index 26fe486917..64cc60256d 100644 --- a/.claude/skills/hil-contract/SKILL.md +++ b/.claude/skills/hil-contract/SKILL.md @@ -194,7 +194,7 @@ The `ci` rig also hosts a GitHub Actions runner that flashes boards and runs HIL - `run_case.py`: restored when `--after park` parked; clean for `--after leave` with a complete, unwedged verdict, or a peer found under the lock; failed for a failed flash or park, no enumeration, an incomplete verdict, a wedge, an exception or a SIGTERM. - `wedge_drill.py`: restored when parked, clean while untouched, failed otherwise; a probe process that may still hold the probe goes in as unrecheckable evidence. -A failed verdict appends a `failed` event, with its tracked child receipts and retained sessions, to `/tmp/tinyusb-hil-locks/.cleanup.jsonl`, clears the record and releases the flock; a restored one first resolves the open failures its take found whose own evidence is ended. A task that took the lock and did not end as its verdict asked (`BoardTask.ended_cleanly` false: a record not cleared, a failure not logged, a handle not closed) fails the board as a `cleanup-pending` cell `board task ended with errors: ...`, and `run_case.py` and `wedge_drill.py` exit 1 with it in `error` (`run_case.py`'s `pass` false); an interrupt replayed as a task ends aborts it the same way, exit 1, whatever verdict it gave; each publishes its result only after the task ended, deciding on the task's outcome attributes (`taken`, `failure_logged`, `ended_cleanly`), never on its error text. Advisory errors of a clean end (an interrupt hold not installed, a restoration not logged) are only shown: in `previous-cleanup-failure` as `board task notes`, or on the scripts' stderr. A failed park is the next take's notice, not a test failure of its own run. Limit (`hil_lock.BoardTask`'s): a signal that lands as the task's `__exit__` is entered leaves the flock held while the process lives. No entry point goes on after one: `hil_test.py` runs each board in a pool worker of its own (`maxtasksperchild=1`) that ends with its task or its interrupt, and `run_case.py` and `wedge_drill.py` exit after their one task, so the flock goes with the process and the next take logs the record. +A failed verdict appends a `failed` event, with its tracked child receipts and retained sessions, to `/tmp/tinyusb-hil-locks/.cleanup.jsonl`, clears the record and releases the flock; a restored one first resolves the open failures its take found whose own evidence is ended. A task that did not end as its verdict asked (`BoardTask.ended_cleanly` false: a record not cleared, a failure not logged, under the bypass too, a handle not closed) fails the board as a `cleanup-pending` cell `board task ended with errors: ...`, and `run_case.py` and `wedge_drill.py` exit 1 with it in `error` (`run_case.py`'s `pass` false); an interrupt replayed as a task ends aborts it the same way, exit 1, whatever verdict it gave; each publishes its result only after the task ended, deciding on `ended_cleanly`, never on its error text, and naming how the lock ended with `BoardTask.describe()`. Advisory errors of a clean end (an interrupt hold not installed, a restoration not logged) are only shown: in `previous-cleanup-failure` as `board task notes`, or on the scripts' stderr. A failed park is the next take's notice, not a test failure of its own run. Limit (`hil_lock.BoardTask`'s): a signal that lands as the task's `__exit__` is entered leaves the flock held while the process lives. No entry point goes on after one: `hil_test.py` runs each board in a pool worker of its own (`maxtasksperchild=1`) that ends with its task or its interrupt, and `run_case.py` and `wedge_drill.py` exit after their one task, so the flock goes with the process and the next take logs the record. The provider's `openocd_esp` flasher (`hil` Flashers) is supported by `hil_test.py` and the farm check; `run_case.py` refuses it, its docstring says why. It is unrostered on ci.lan and refused under a CI job (`RUNNER_TRACKING_ID` or `GITHUB_ACTIONS` set). Whatever an `openocd_esp` operation leaves not proven ended stops that board's run, with no retry or park, and ends its task failed with the tracked child receipts and the retained sessions, or with the pending detail as unrecheckable evidence when it names neither. The `cleanup-pending` cell names the receipts, log and any logging error; the farm row's cleanup records the release and retained sessions. An interrupt before a receipt is stored is logged with unrecheckable evidence, never as a proven cleanup. A bench board with an open `openocd_esp` cleanup failure must be recovered before another run or farm check accesses it; the free flock does not gate access. diff --git a/.claude/skills/usbtest/scripts/run_case.py b/.claude/skills/usbtest/scripts/run_case.py index cb219f64d3..083f8c8551 100644 --- a/.claude/skills/usbtest/scripts/run_case.py +++ b/.claude/skills/usbtest/scripts/run_case.py @@ -388,13 +388,11 @@ def lock_and_run(args, tests, report, finish): def ended(task, code, error): """(code, error) once the task ended: a lock that did not end as its verdict asked fails the run, its state and errors in `error`; advisory errors of a clean end only go to stderr.""" - if not task.taken or task.ended_cleanly: + if task.ended_cleanly: if task.errors: - print(f'board task notes: {"; ".join(task.errors)}', file=sys.stderr) + print(f'board task notes: {task.describe()}', file=sys.stderr) return code, error - logged = {None: '', True: ', failure logged', False: ', failure NOT logged'}[task.failure_logged] - problem = (f'board task did not end as its verdict asked (lock {"released" if task.released else "NOT released"}' - f'{logged}): {"; ".join(task.errors)}') + problem = f'board task did not end as its verdict asked: {task.describe()}' return code or 1, f'{error}; {problem}' if error else problem diff --git a/.claude/test/test_usbtest_run_case.py b/.claude/test/test_usbtest_run_case.py index 8652c492d5..bf98363970 100644 --- a/.claude/test/test_usbtest_run_case.py +++ b/.claude/test/test_usbtest_run_case.py @@ -435,8 +435,9 @@ def clear(fh): rc, report, _ = rig.run('--board', 'solo', '--tests', '29', '--after', 'park') self.assertNotIn('"pass"', printed[0]) self.assertEqual((rc, report['pass']), (1, False)) # the battery passed; its lock did not end - self.assertIn('board task did not end as its verdict asked (lock released, failure logged): ' - 'record not cleared', report['error']) + self.assertIn('board task did not end as its verdict asked: solo: lock released, failure logged in', + report['error']) + self.assertIn('record not cleared', report['error']) def test_advisory_task_errors_never_fail_the_run(self): rig = Rig(self) @@ -444,7 +445,7 @@ def test_advisory_task_errors_never_fail_the_run(self): with mock.patch.object(run_case.hil_lock, '_process', return_value=broken): rc, report, err = rig.run('--board', 'solo', '--tests', '29', '--after', 'park') self.assertEqual((rc, report['error']), (0, '')) - self.assertIn('board task notes: interrupt hold', err) + self.assertIn('board task notes: solo: lock released, errors: interrupt hold', err) class Sigterm(unittest.TestCase): """What `hil_lock.py release` sends the lock holder, raised in-process as on_sigterm would.""" diff --git a/test/hil/hil_test.py b/test/hil/hil_test.py index 25e71bc849..ec73cdf654 100755 --- a/test/hil/hil_test.py +++ b/test/hil/hil_test.py @@ -2025,16 +2025,6 @@ def pending_evidence(name: str, pending: str) -> dict: return {'receipts': tracked if receipts else [{'unrecheckable': pending}], 'retained': retained} -def task_ending(task, lock: str) -> str: - """How a board task ended, for display: its lock, whether its failure was logged, its errors.""" - parts = ['board lock bypassed (HIL_NO_BOARD_LOCK=1)' if task.bypassed else - 'board lock released' if task.released else 'board lock NOT released'] - if task.failure_logged is not None: - log = Path(hil_lock.BOARD_LOCK_DIR) / f'{lock}{hil_lock.CLEANUP_LOG}' - parts.append(f'cleanup failure {"logged" if task.failure_logged else "NOT logged"}: {log}') - return '; '.join(parts + task.errors) - - def previous_cleanup_text(name: str, failures: list) -> str: """The open failures the take found, logged before any hardware access, as the previous-cleanup-failure cell names them ('' for none).""" @@ -2098,24 +2088,23 @@ def test_board(board: Board) -> tuple: if not entered and isinstance(e, Exception): return admission_refused(name, task, e) if entered: - log_line(f'{name:25} ended by {type(e).__name__}: {task_ending(task, lock)}') + log_line(f'{name:25} ended by {type(e).__name__}: {task.describe()}') raise if task.restore_notes: log_line(f'{name:25} ' + '; '.join(task.restore_notes)) previous_cleanup += ('; ' + '; '.join(task.restore_notes) if task.bypassed else f'; {len(task.restore_notes)} still open') - unclean = task.taken and not task.ended_cleanly - if task.errors and not unclean and previous_cleanup: + if task.errors and task.ended_cleanly and previous_cleanup: previous_cleanup += '; board task notes: ' + '; '.join(task.errors) # advisory, e.g. a restoration - ending = task_ending(task, lock) + ending = task.describe() if pending := cleanup_pending(name): log_line(f'{name:25} BLOCKER: {pending}; {ending}') rows.append((name, {hil_report.CLEANUP_PENDING_CELL: f'{hil_report.REPORT_CELL["fail"]} {pending}; {ending}'}, None)) err_count += 1 board_wide_fail = True - elif unclean: + elif not task.ended_cleanly: # the lock did not end as its verdict asked: never a passing board log_line(f'{name:25} BLOCKER: board task ended with errors: {ending}') rows.append((name, {hil_report.CLEANUP_PENDING_CELL: diff --git a/test/hil/test/test_hil_lock.py b/test/hil/test/test_hil_lock.py index 117267de1e..d68e157279 100644 --- a/test/hil/test/test_hil_lock.py +++ b/test/hil/test/test_hil_lock.py @@ -373,7 +373,7 @@ def run_board(self): cell = rows[-1][1][hil_test.hil_report.CLEANUP_PENDING_CELL] self.assertEqual(hil_test.hil_report.cell_state(cell), 'fail') self.assertIn(self.RECEIPT, cell) - self.assertIn('board lock released', cell) + self.assertIn('lock released', cell) self.assertIn(str(Path(self.dir) / f'{self.lock}.cleanup.jsonl'), cell) return rows @@ -423,7 +423,7 @@ def test_a_security_read_left_running_stops_before_the_flash_and_logs_its_receip self.assertEqual((failure['receipts'], failure['retained']), ([self.TRACKED], [])) cell = rows[-1][1][hil_test.hil_report.CLEANUP_PENDING_CELL] self.assertIn('esptool child, record /s/hil_op_t0k.json', cell) - self.assertIn('board lock released', cell) + self.assertIn('lock released', cell) def test_a_security_read_of_unknown_cleanup_is_read_once_latched_and_logged(self): self.provider(self.op('done', rc=0), security_cleanup='unknown', security_receipts=(self.TRACKED,)) @@ -472,7 +472,7 @@ def test_pending_on_an_interrupt_is_logged_and_released_on_the_way_out(self): with self.assertRaises(KeyboardInterrupt): hil_test.test_board(self.board) self.assert_logged() - self.assertIn('board lock released', self.log[-1]) + self.assertIn('lock released', self.log[-1]) def test_an_interrupt_before_the_receipt_is_stored_logs_unrecheckable_evidence(self): # the provider returned its pending operation, then the interrupt lands before the store @@ -529,7 +529,7 @@ def test_a_log_write_failure_still_releases_and_reports_the_error(self): _, err, _, rows, _ = hil_test.test_board(self.board) self.assertEqual(err, 2) cell = rows[-1][1][hil_test.hil_report.CLEANUP_PENDING_CELL] - self.assertIn('cleanup failure NOT logged', cell) + self.assertIn('failure NOT logged', cell) self.assertIn('cleanup log not written', cell) self.assertIn('log is read-only', cell) self.assertEqual(hil_lock.record_state(BOARD)[0], 'empty') @@ -779,7 +779,7 @@ def test_an_interrupt_fails_the_cleanup_and_a_later_park_resolves_it(self): failure, = self.events('failed') self.assertEqual((failure['how'], failure['receipts']), ('ended-failed', [])) self.assertIn('ended without a cleanup verdict: KeyboardInterrupt', failure['detail']) - self.assertIn('board lock released', self.log[-1]) + self.assertIn('lock released', self.log[-1]) self.test = (0, 'pass', None) _, err, _, rows, _ = hil_test.test_board(self.board) self.assertEqual(err, 0) @@ -799,7 +799,7 @@ def test_a_finalization_error_fails_the_board(self): _, err, failed, rows, _ = hil_test.test_board(self.board) self.assertEqual((err, failed), (1, [])) cell = rows[-1][1][hil_test.hil_report.CLEANUP_PENDING_CELL] - self.assertIn('board task ended with errors: board lock released; cleanup failure logged', cell) + self.assertIn(f'board task ended with errors: {BOARD}: lock released, failure logged in', cell) self.assertIn('record not cleared', cell) def test_advisory_task_errors_never_fail_the_board(self): From 2e93df1761a0a471f2f6b28d2eabcb67411400c4 Mon Sep 17 00:00:00 2001 From: hathach Date: Thu, 12 Nov 2026 02:04:25 +0700 Subject: [PATCH 03/16] Keep interrupted cleanup evidence and admit only BoardLocked as contention --- .claude/skills/hil-contract/SKILL.md | 2 +- .claude/skills/usbtest/scripts/run_case.py | 6 +- .claude/skills/usbtest/scripts/wedge_drill.py | 79 +++++++++++-------- .claude/test/test_usbtest_wedge_drill.py | 28 +++++++ test/hil/hil_flash.py | 22 ++++-- test/hil/hil_test.py | 73 +++++++---------- test/hil/test/test_hil_farm_check.py | 7 -- test/hil/test/test_hil_flash.py | 30 +++++-- test/hil/test/test_hil_lock.py | 17 +++- 9 files changed, 157 insertions(+), 107 deletions(-) diff --git a/.claude/skills/hil-contract/SKILL.md b/.claude/skills/hil-contract/SKILL.md index 64cc60256d..edf538ffec 100644 --- a/.claude/skills/hil-contract/SKILL.md +++ b/.claude/skills/hil-contract/SKILL.md @@ -194,7 +194,7 @@ The `ci` rig also hosts a GitHub Actions runner that flashes boards and runs HIL - `run_case.py`: restored when `--after park` parked; clean for `--after leave` with a complete, unwedged verdict, or a peer found under the lock; failed for a failed flash or park, no enumeration, an incomplete verdict, a wedge, an exception or a SIGTERM. - `wedge_drill.py`: restored when parked, clean while untouched, failed otherwise; a probe process that may still hold the probe goes in as unrecheckable evidence. -A failed verdict appends a `failed` event, with its tracked child receipts and retained sessions, to `/tmp/tinyusb-hil-locks/.cleanup.jsonl`, clears the record and releases the flock; a restored one first resolves the open failures its take found whose own evidence is ended. A task that did not end as its verdict asked (`BoardTask.ended_cleanly` false: a record not cleared, a failure not logged, under the bypass too, a handle not closed) fails the board as a `cleanup-pending` cell `board task ended with errors: ...`, and `run_case.py` and `wedge_drill.py` exit 1 with it in `error` (`run_case.py`'s `pass` false); an interrupt replayed as a task ends aborts it the same way, exit 1, whatever verdict it gave; each publishes its result only after the task ended, deciding on `ended_cleanly`, never on its error text, and naming how the lock ended with `BoardTask.describe()`. Advisory errors of a clean end (an interrupt hold not installed, a restoration not logged) are only shown: in `previous-cleanup-failure` as `board task notes`, or on the scripts' stderr. A failed park is the next take's notice, not a test failure of its own run. Limit (`hil_lock.BoardTask`'s): a signal that lands as the task's `__exit__` is entered leaves the flock held while the process lives. No entry point goes on after one: `hil_test.py` runs each board in a pool worker of its own (`maxtasksperchild=1`) that ends with its task or its interrupt, and `run_case.py` and `wedge_drill.py` exit after their one task, so the flock goes with the process and the next take logs the record. +A failed verdict appends a `failed` event, with its tracked child receipts and retained sessions, to `/tmp/tinyusb-hil-locks/.cleanup.jsonl`, clears the record and releases the flock; a restored one first resolves the open failures its take found whose own evidence is ended. A task that did not end as its verdict asked (`BoardTask.ended_cleanly` false: a record not cleared, a failure not logged, under the bypass too, a handle not closed) fails the board as a `cleanup-pending` cell `board task ended with errors; : ...`, and `run_case.py` and `wedge_drill.py` exit 1 with it in `error` (`run_case.py`'s `pass` false); an interrupt replayed as a task ends aborts it the same way, exit 1, whatever verdict it gave; each publishes its result only after the task ended, deciding on `ended_cleanly`, never on its error text, and naming how the lock ended with `BoardTask.describe()`. Advisory errors of a clean end (an interrupt hold not installed, a restoration not logged) are only shown: in the run's log and `previous-cleanup-failure` as `board task notes`, or on the scripts' stderr. A failed park is the next take's notice, not a test failure of its own run. Limit (`hil_lock.BoardTask`'s): a signal that lands as the task's `__exit__` is entered leaves the flock held while the process lives. No entry point goes on after one: `hil_test.py` runs each board in a pool worker of its own (`maxtasksperchild=1`) that ends with its task or its interrupt, and `run_case.py` and `wedge_drill.py` exit after their one task, so the flock goes with the process and the next take logs the record. The provider's `openocd_esp` flasher (`hil` Flashers) is supported by `hil_test.py` and the farm check; `run_case.py` refuses it, its docstring says why. It is unrostered on ci.lan and refused under a CI job (`RUNNER_TRACKING_ID` or `GITHUB_ACTIONS` set). Whatever an `openocd_esp` operation leaves not proven ended stops that board's run, with no retry or park, and ends its task failed with the tracked child receipts and the retained sessions, or with the pending detail as unrecheckable evidence when it names neither. The `cleanup-pending` cell names the receipts, log and any logging error; the farm row's cleanup records the release and retained sessions. An interrupt before a receipt is stored is logged with unrecheckable evidence, never as a proven cleanup. A bench board with an open `openocd_esp` cleanup failure must be recovered before another run or farm check accesses it; the free flock does not gate access. diff --git a/.claude/skills/usbtest/scripts/run_case.py b/.claude/skills/usbtest/scripts/run_case.py index 083f8c8551..ffaf316f6e 100644 --- a/.claude/skills/usbtest/scripts/run_case.py +++ b/.claude/skills/usbtest/scripts/run_case.py @@ -338,11 +338,7 @@ def finish(code, error=''): def refusal(e) -> str: """Why a board task refused the board before any hardware action: the lock's refusal, or the busy check under it naming a probe user or unable to rule one out.""" - if isinstance(e, hil_lock.BoardBusy): - return f'probe in use by {hil_flash.users_text(e.users)}' - if isinstance(e, hil_flash.ProbeCheckFailed): - return f'probe check: {e}' - return str(e) if isinstance(e, RuntimeError) else f'{type(e).__name__}: {e}' + return hil_flash.busy_refusal(e) or (str(e) if isinstance(e, RuntimeError) else f'{type(e).__name__}: {e}') def lock_and_run(args, tests, report, finish): diff --git a/.claude/skills/usbtest/scripts/wedge_drill.py b/.claude/skills/usbtest/scripts/wedge_drill.py index 663d941bc5..2e1aafe9c2 100755 --- a/.claude/skills/usbtest/scripts/wedge_drill.py +++ b/.claude/skills/usbtest/scripts/wedge_drill.py @@ -34,8 +34,8 @@ The lock is a board_task as in run_case.py (its busy check runs under --allow-concurrent too), ended restored once parked, clean while untouched, failed otherwise: a halt process that may still hold the probe goes in as unrecheckable evidence, which only its recovery ends. The JSON line follows the lock's -release; a lock that did not end as its verdict asked, or a signal replayed as the task ended, exits 1, -its errors in "error". +release; a lock that did not end as its verdict asked, or a signal or exception raised as the task +ended, exits 1, its errors in "error". """ import argparse import json @@ -414,19 +414,32 @@ def live_children(grace): time.sleep(0.1) -def finish_locked(board, rec_board, park_fw, report): - """Cleanup and parking under the lock, on every path out of the drill.""" +def probe_evidence(report) -> dict: + """A probe process that may still hold the probe, as unrecheckable evidence: only its recovery + ends it, never a later park.""" + held = report['halt'].get('probeHeld') + return {'receipts': [{'unrecheckable': f'probe process {held} may still hold the probe'}]} if held else {} + + +def finish_locked(task, board, rec_board, park_fw, report, given): + """Cleanup and parking under the lock, on every path out of the drill, ending on the task's + verdict: restored once parked (True), else failed with probe_evidence. `given` gets an entry + once a verdict call returned.""" + def failed(**evidence): + task.failed(detail='; '.join(filter(None, (report['boardState'], report['error']))), **evidence) + given.append('failed') + return False + if report['boardState'] == 'flash failed': - return + return failed() if not report['halt'].get('probeHeld'): # whatever path got here, signals included: no probe access past a live child stuck = live_children(hil_util.REAP_GRACE) if stuck: report['halt']['probeHeld'] = stuck[0] - if report['halt'].get('probeHeld'): - report['boardState'] = (f'unknown, not parked: probe process {report["halt"]["probeHeld"]} may ' - f'still hold the probe (usb-kernel-recover)') - return + if held := report['halt'].get('probeHeld'): + report['boardState'] = f'unknown, not parked: probe process {held} may still hold the probe (usb-kernel-recover)' + return failed(**probe_evidence(report)) if report['drill'] == 'pass': safe = True elif report['halt'].get('issued'): @@ -440,19 +453,25 @@ def finish_locked(board, rec_board, park_fw, report): and not report['error']) if not safe: report['boardState'] = 'unknown, not parked: check it (usb-kernel-recover)' - return + return failed() if report['error'].startswith('terminated'): report['boardState'] = 'not parked: terminated' # whoever signalled wants the board - return + return failed() err = run_case.flash(board, park_fw) report['boardState'] = f'park failed: {err}' if err else 'parked on board_test' - if err and not report['error']: - report['error'] = f'park failed: {err}' + if err: + report['error'] = report['error'] or f'park failed: {err}' + return failed() + task.restored(evidence='wedge_drill.py: parked on board_test') + given.append('restored') + return True def drill_locked(task, board, rec_board, halt_with, fw, park_fw, args, report): - """The drill and its cleanup under the board's task, then the task's verdict; 2 when a peer - refused it under the lock, else None.""" + """The drill and its cleanup under the board's task: its exit code, 2 when a peer refused it + under the lock. An interrupted cleanup ends the task failed, with probe_evidence and the + interruption in its detail, then propagates.""" + parked, given = False, [] with tempfile.TemporaryDirectory(prefix='wedge_drill-', ignore_cleanup_errors=True) as workdir: os.chdir(workdir) try: @@ -468,28 +487,19 @@ def drill_locked(task, board, rec_board, halt_with, fw, park_fw, args, report): except Exception as e: report['error'] = f'{type(e).__name__}: {e}' try: - finish_locked(board, rec_board, park_fw, report) - except (Terminated, KeyboardInterrupt): + parked = finish_locked(task, board, rec_board, park_fw, report, given) + except (Terminated, KeyboardInterrupt) as e: report['error'] = report['error'] or 'terminated (signal) during cleanup' report['boardState'] = 'unknown, not parked: cleanup interrupted' - drill_verdict(task, report) - return None + if not given: + try: + task.failed(detail=f'{report["boardState"]}: {type(e).__name__}', **probe_evidence(report)) + except RuntimeError: + pass # its verdict was stored as the interrupt landed: board_task merged them, failed + raise + return 0 if report['drill'] == 'pass' and parked else 1 -def drill_verdict(task, report): - """restored once parked, clean while untouched, failed otherwise: a probe process that may still - hold the probe as unrecheckable evidence (only its recovery ends it), any other state for a - later restore to resolve.""" - state = report['boardState'] - if state == 'parked on board_test': - task.restored(evidence='wedge_drill.py: parked on board_test') - elif state == 'untouched': - task.clean() - elif held := report['halt'].get('probeHeld'): - task.failed(detail=state, receipts=[{'unrecheckable': f'probe process {held} may still hold the probe'}]) - else: - task.failed(detail=f'{state}; {report["error"]}' if report['error'] else state) - def main(): args = build_parser().parse_args() report = new_report(args) @@ -545,10 +555,9 @@ def finish(code): report['error'] = f'{board["name"]}: {run_case.refusal(e)}' return finish(2) report['error'] = report['error'] or f'{type(e).__name__}: {e}' + code = code or 1 finally: os.chdir(cwd) - if code is None: - code = 0 if report['drill'] == 'pass' and report['boardState'] == 'parked on board_test' else 1 # published once the task ended, so its finalization counts code, report['error'] = run_case.ended(task, code, report['error']) return finish(code) diff --git a/.claude/test/test_usbtest_wedge_drill.py b/.claude/test/test_usbtest_wedge_drill.py index ef4b1d4695..f5c8f2c5be 100644 --- a/.claude/test/test_usbtest_wedge_drill.py +++ b/.claude/test/test_usbtest_wedge_drill.py @@ -346,6 +346,34 @@ def test_a_signal_during_the_cleanup_reset(self): rc, r = rig.run('--board', 'ok', '--delay', '0') self.assert_unknown_with_one_verdict(rig, r, rc) + def test_an_interrupted_cleanup_logs_its_cause(self): + rig = Rig(self) + rig.case27 = ({**HUNG, 'cases': [{'num': 27, 'status': 'FAIL'}]}, '', '') + rig.reset_raises = run_case.Terminated() + rig.run('--board', 'ok', '--delay', '0') + failed, = rig.lock.events('failed') + self.assertIn('unknown, not parked: cleanup interrupted: Terminated', failed['detail']) + self.assertEqual(failed['receipts'], []) + + def test_a_known_probe_holder_survives_an_interrupted_verdict(self): + rig = Rig(self) + rig.halt_raises = wedge_drill.ProbeHeld(777) + real, calls = run_case.hil_lock.BoardTask.failed, [] + + def failed(task, **kw): # the interrupt lands as finish_locked gives its verdict + calls.append(kw) + if len(calls) == 1: + raise run_case.Terminated() + return real(task, **kw) + with mock.patch.object(run_case.hil_lock.BoardTask, 'failed', failed), \ + mock.patch.object(run_case, 'kill_children'): + rc, r = rig.run('--board', 'wch', '--delay', '0') + self.assertEqual((rc, r['boardState']), (1, 'unknown, not parked: cleanup interrupted')) + event, = rig.lock.events('failed') + self.assertIn('cleanup interrupted: Terminated', event['detail']) + self.assertEqual(event['receipts'], [{'unrecheckable': 'probe process 777 may still hold the probe'}]) + self.assertTrue(run_case.hil_lock.resolve_restored('wch', [event], evidence='parked')) # stays open + def test_a_signal_during_parking(self): rig = Rig(self) rig.flash_raises['/fw/device/board_test'] = KeyboardInterrupt() diff --git a/test/hil/hil_flash.py b/test/hil/hil_flash.py index 4d52f8c0b6..4c8f394945 100755 --- a/test/hil/hil_flash.py +++ b/test/hil/hil_flash.py @@ -145,13 +145,14 @@ def probe_busy(board: dict) -> list: """The board_task busy check of every HIL entry point and the farm check: the provider's probe_users for the board's flasher and, when it differs, its recovery flasher (same probe, another tool); [{'pid', 'cmd'}]. ProbeCheckFailed, naming the cause, when the provider is - inconclusive or has no lookup for the flasher (wch_uart_loader). Probe users only: a DUT-side - process (a stray testusb) is the run's recovery, never a refusal.""" - users = {} + inconclusive (ProbeCheckInconclusive) or has no lookup for the flasher (ValueError, + wch_uart_loader); any other exception propagates. Probe users only: a DUT-side process (a + stray testusb) is the run's recovery, never a refusal.""" + provider, users = hil_util.provider(), {} try: for f in {(f['name'], f.get('uid')): f for f in (board['flasher'], recover_flasher(board))}.values(): - users.update((u['pid'], u) for u in hil_util.provider().probe_users(f)) - except Exception as e: + users.update((u['pid'], u) for u in provider.probe_users(f)) + except (provider.ProbeCheckInconclusive, ValueError) as e: raise ProbeCheckFailed(f'{type(e).__name__}: {e}') from e return sorted(users.values(), key=lambda u: u['pid']) @@ -161,6 +162,17 @@ def users_text(users) -> str: return ', '.join(f'pid {u["pid"]} ({u["cmd"]:.120})' for u in users) +def busy_refusal(e) -> str | None: + """Why a board task's busy check refused admission (hil_lock.BoardBusy or ProbeCheckFailed), + or None for any other refusal.""" + from helper import hil_lock # agentrc's, loaded on first use like the provider + if isinstance(e, hil_lock.BoardBusy): + return f'probe in use by {users_text(e.users)}' + if isinstance(e, ProbeCheckFailed): + return f'probe check: {e}' + return None + + def _idf_target(fw_dir: Path) -> str: with (fw_dir / 'config.env').open() as f: return json.load(f)['IDF_TARGET'] diff --git a/test/hil/hil_test.py b/test/hil/hil_test.py index ec73cdf654..edc89ccb52 100755 --- a/test/hil/hil_test.py +++ b/test/hil/hil_test.py @@ -2044,17 +2044,15 @@ def admission_refused(name: str, task, e: Exception) -> tuple: failed-tests empty so a re-run repeats the whole board (no bogus -bt filter).""" log_line(f'{name:25} {STATUS_FAILED}: {e}') fail = hil_report.REPORT_CELL['fail'] # icon-prefixed, so the table tallies it as a failure - if isinstance(e, hil_lock.BoardBusy): - cells = {hil_report.PROBE_BUSY_CELL: f'{fail} probe in use by {hil_flash.users_text(e.users)}'} - elif isinstance(e, hil_flash.ProbeCheckFailed): - cells = {hil_report.PROBE_BUSY_CELL: f'{fail} probe check: {e}'} + if busy := hil_flash.busy_refusal(e): + cells = {hil_report.PROBE_BUSY_CELL: f'{fail} {busy}'} elif isinstance(e, hil_lock.RecoveryBlocked): # a live cleanup holder from an older helper cells = {hil_report.RECOVERY_BLOCKER_CELL: f'{fail} {e}'} elif isinstance(e, hil_lock.LockUnavailable): cells = {hil_report.LOCK_UNAVAILABLE_CELL: f'{fail} {e}'} - elif isinstance(e, RuntimeError): + elif isinstance(e, hil_lock.BoardLocked): cells = {hil_report.LOCKED_CELL: 'fail'} - else: + else: # no refusal: an error of the take or the check, which aborts the run raise e if previous := previous_cleanup_text(name, task.cleanup_failures): cells[hil_report.PREVIOUS_CLEANUP_CELL] = previous @@ -2081,9 +2079,9 @@ def test_board(board: Board) -> tuple: try: err_count, failed_tests, board_wide_fail, rows, unrestored = _board_battery(board, parked) except BaseException as e: - _unwinding_verdict(task, board, e, parked) + _verdict(task, board, parked, exc=e) raise - _verdict(task, board, unrestored) + _verdict(task, board, parked, unrestored) except BaseException as e: if not entered and isinstance(e, Exception): return admission_refused(name, task, e) @@ -2095,22 +2093,18 @@ def test_board(board: Board) -> tuple: log_line(f'{name:25} ' + '; '.join(task.restore_notes)) previous_cleanup += ('; ' + '; '.join(task.restore_notes) if task.bypassed else f'; {len(task.restore_notes)} still open') - if task.errors and task.ended_cleanly and previous_cleanup: - previous_cleanup += '; board task notes: ' + '; '.join(task.errors) # advisory, e.g. a restoration ending = task.describe() - if pending := cleanup_pending(name): - log_line(f'{name:25} BLOCKER: {pending}; {ending}') - rows.append((name, {hil_report.CLEANUP_PENDING_CELL: f'{hil_report.REPORT_CELL["fail"]} {pending}; {ending}'}, + if task.errors and task.ended_cleanly: # advisory, e.g. a restoration not logged + log_line(f'{name:25} board task notes: {ending}') + if previous_cleanup: + previous_cleanup += '; board task notes: ' + '; '.join(task.errors) + # a lock that did not end as its verdict asked is never a passing board either + if blocker := cleanup_pending(name) or ('' if task.ended_cleanly else 'board task ended with errors'): + log_line(f'{name:25} BLOCKER: {blocker}; {ending}') + rows.append((name, {hil_report.CLEANUP_PENDING_CELL: f'{hil_report.REPORT_CELL["fail"]} {blocker}; {ending}'}, None)) err_count += 1 board_wide_fail = True - elif not task.ended_cleanly: - # the lock did not end as its verdict asked: never a passing board - log_line(f'{name:25} BLOCKER: board task ended with errors: {ending}') - rows.append((name, {hil_report.CLEANUP_PENDING_CELL: - f'{hil_report.REPORT_CELL["fail"]} board task ended with errors: {ending}'}, None)) - err_count += 1 - board_wide_fail = True elif unrestored: log_line(f'{name:25} board not restored ({unrestored}): failed cleanup logged; {ending}') if previous_cleanup and rows: @@ -2119,26 +2113,21 @@ def test_board(board: Board) -> tuple: rows, board_pci) -def _unwinding_verdict(task, board: Board, e: BaseException, parked: list) -> None: - """The verdict of a battery that raised: a pending cleanup's evidence; restored when its final - park still ran and succeeded (the run itself stays aborted by `e`); for openocd_esp an - interrupt that may have landed after the provider returned a pending session but before - hil_flash stored its receipt; otherwise none, and the task ends failed naming `e`.""" - name = board['name'] - if pending := cleanup_pending(name): - task.failed(detail=pending, **pending_evidence(name, pending)) - elif parked: - task.restored(evidence='device/board_test park succeeded') - elif board['flasher']['name'].lower() == 'openocd_esp' and not isinstance(e, Exception): - missing = 'openocd_esp interrupted; cleanup unproven, receipt missing' - task.failed(detail=missing, receipts=[{'unrecheckable': missing}]) - - -def _verdict(task, board: Board, unrestored: str) -> None: - """The battery's cleanup verdict, its last act under the lock (the HIL contract's Reservation).""" +def _verdict(task, board: Board, parked: list, unrestored: str = '', exc: BaseException | None = None) -> None: + """The battery's cleanup verdict, its last act under the lock (the HIL contract's Reservation). + A battery that raised `exc` is restored when its final park still succeeded (the run itself + stays aborted by `exc`), failed with unrecheckable evidence for an openocd_esp interrupt that + may have landed after the provider returned a pending session but before hil_flash stored its + receipt, and otherwise given none, so the task ends failed naming `exc`.""" name = board['name'] if pending := cleanup_pending(name): task.failed(detail=pending, **pending_evidence(name, pending)) + elif exc is not None: + if parked: + task.restored(evidence='device/board_test park succeeded') + elif board['flasher']['name'].lower() == 'openocd_esp' and not isinstance(exc, Exception): + missing = 'openocd_esp interrupted; cleanup unproven, receipt missing' + task.failed(detail=missing, receipts=[{'unrecheckable': missing}]) elif unrestored: task.failed(detail=f'board not restored: {unrestored}') elif skip_flash: @@ -2149,8 +2138,8 @@ def _verdict(task, board: Board, unrestored: str) -> None: def _board_battery(board: Board, parked: list) -> tuple: """The board's tests and its final park, under its task: (err_count, failed_tests, - board_wide_fail, rows, why the board is not restored or ''). A successful park also appends to - `parked`, which outlives an exception raised past it.""" + board_wide_fail, rows, why the board is not restored or ''). A successful park appends to + `parked`, the one record of it, which outlives an exception raised past it.""" name = board['name'] global board_wedged test_list, skipped = _tests_for(board) @@ -2257,7 +2246,6 @@ def _board_battery(board: Board, parked: list) -> tuple: dur = f'{time.monotonic() - t_variant:.0f}s' if run_list and not partial else None rows.append((vname, cells, dur)) - restored = False sv_capture = None # (capture, error, flashed) try: if sysview_out and 'sysview' in board and \ @@ -2274,8 +2262,7 @@ def _board_battery(board: Board, parked: list) -> tuple: park_error = None if _should_park(skip_flash): park_ec, park_status, _ = test_example(board, variants[0]['name'], 'device/board_test') - restored = park_ec == 0 and park_status == 'pass' - if restored: + if park_ec == 0 and park_status == 'pass': parked.append(True) park_error = ('park flash failed' if park_ec else 'no park (device/board_test) firmware' if park_status == 'skip' else None) @@ -2292,7 +2279,7 @@ def _board_battery(board: Board, parked: list) -> tuple: except Exception as e: log_line(f'{name:25} SystemView capture record not written: {type(e).__name__}: {e}') - if restored: + if parked: unrestored = '' elif board_wedged: # failed whether or not this run flashed unrestored = park_error or f'not parked: the board is wedged: {board_wedged}' diff --git a/test/hil/test/test_hil_farm_check.py b/test/hil/test/test_hil_farm_check.py index 4d8d8df3df..f6768cd0c9 100644 --- a/test/hil/test/test_hil_farm_check.py +++ b/test/hil/test/test_hil_farm_check.py @@ -101,13 +101,6 @@ def test_the_hook_is_the_batterys_own_busy_check(self): self.assertIs(farm_profile.busy(BOARD), users) self.assertEqual(seen, [BOARD]) - def test_an_inconclusive_check_raises_through_the_hook(self): - def inconclusive(board): - raise RuntimeError('/proc may hide other users') - patch(self, hil_flash, 'probe_busy', inconclusive) - with self.assertRaisesRegex(RuntimeError, 'hide'): - farm_profile.busy(BOARD) - class Roster(unittest.TestCase): def test_a_rig_host_gets_its_roster(self): got = farm_profile.roster('ci', None, args()) diff --git a/test/hil/test/test_hil_flash.py b/test/hil/test/test_hil_flash.py index df699305c6..09c0f883ca 100644 --- a/test/hil/test/test_hil_flash.py +++ b/test/hil/test/test_hil_flash.py @@ -128,14 +128,30 @@ def test_probe_busy_asks_for_each_entry_of_the_probe_once(self): hil_flash.probe_busy({'name': 'b', 'flasher': dict(BOARDS['jlink'])}) self.assertEqual(asked, [BOARDS['jlink']], 'no recovery entry: the primary alone, once') + def test_probe_busy_refuses_only_what_the_provider_cannot_decide(self): + board = {'name': 'b', 'flasher': dict(BOARDS['jlink'])} + for raised in (self.provider.real.ProbeCheckInconclusive('/proc may hide'), ValueError('no probe lookup')): + with self.subTest(raised=raised): + self.provider.probe_users = mock.Mock(side_effect=raised) + with self.assertRaisesRegex(hil_flash.ProbeCheckFailed, f'{type(raised).__name__}: {raised}'): + hil_flash.probe_busy(board) + self.provider.probe_users = mock.Mock(side_effect=TypeError('a harness bug')) + with self.assertRaisesRegex(TypeError, 'a harness bug'): # never a refusal + hil_flash.probe_busy(board) + def test_every_rostered_flasher_has_a_probe_lookup(self): - # the busy check refuses a board whose flasher it cannot look up, so a roster must not name one - for name in flasher_names(): - with self.subTest(name=name): - try: - hil_util.provider().probe_users(BOARDS[name]) - except hil_util.provider().ProbeCheckInconclusive: - pass # no such probe on this host + # the busy check refuses a board whose flasher it cannot look up, so a roster must not name one; + # the provider's device lookup and /proc walk are stubbed: no host I/O + real = self.provider.real + usj = types.SimpleNamespace(load_file=lambda path: types.SimpleNamespace(usj_node=lambda uid: '/dev/null')) + with mock.patch.object(real, '_probe_nodes', return_value=set()), \ + mock.patch.object(real, 'esptool_port', return_value='/dev/null'), \ + mock.patch.object(real, 'hil_load', usj), \ + mock.patch.object(real.hil_process, '_proc_hides_others', return_value=False), \ + mock.patch.object(real, '_walk', return_value=[]): + for name in flasher_names(): + with self.subTest(name=name): + self.assertEqual(real.probe_users(BOARDS[name]), []) def test_without_a_bound_cmd_timeout_is_read_at_call_time(self): self.addCleanup(setattr, hil_util, 'CMD_TIMEOUT', hil_util.CMD_TIMEOUT) diff --git a/test/hil/test/test_hil_lock.py b/test/hil/test/test_hil_lock.py index d68e157279..32d1e2563c 100644 --- a/test/hil/test/test_hil_lock.py +++ b/test/hil/test/test_hil_lock.py @@ -89,7 +89,7 @@ def test_lock_unavailable_fails_the_board_unflashed(self): def test_contention_keeps_its_own_cell(self): def held(name, *a, **kw): - raise RuntimeError('board locked: {"pid": 1}') + raise hil_lock.BoardLocked('board locked: {"pid": 1}') patch(self, hil_lock, 'acquire_board_lock', held) _, err, _, rows, _ = hil_test.test_board(self.board) self.assertEqual(err, 1) @@ -103,7 +103,7 @@ def test_a_registered_board_is_locked_by_its_registry_name(self): def held(name, *a, **kw): locked.append(name) - raise RuntimeError('board locked: {"pid": 1}') + raise hil_lock.BoardLocked('board locked: {"pid": 1}') patch(self, hil_lock, 'acquire_board_lock', held) self.assertEqual(hil_test.test_board(board)[0], BOARD) self.assertEqual(locked, [reg['name']]) @@ -704,6 +704,14 @@ def test_the_bypass_still_runs_the_busy_check(self): self.assertIn(hil_test.hil_report.PROBE_BUSY_CELL, rows[0][1]) self.assertEqual(hil_lock.record_state(BOARD)[0], 'absent') + def test_an_unrelated_error_is_no_refusal(self): + # e.g. the provider's bounded /proc walk failing to start its thread: the run aborts on it + self.users = RuntimeError("can't start new thread") + with self.assertRaisesRegex(RuntimeError, "can't start new thread"): + hil_test.test_board(self.board) + self.assertEqual(hil_lock.record_state(BOARD)[0], 'empty') + self.assertEqual(hil_lock.cleanup_events(BOARD), []) + def test_a_refused_board_is_not_run_in_the_report(self): self.users = [{'pid': 1, 'cmd': 'openocd'}] _, err, _, rows, _ = hil_test.test_board(self.board) @@ -799,7 +807,7 @@ def test_a_finalization_error_fails_the_board(self): _, err, failed, rows, _ = hil_test.test_board(self.board) self.assertEqual((err, failed), (1, [])) cell = rows[-1][1][hil_test.hil_report.CLEANUP_PENDING_CELL] - self.assertIn(f'board task ended with errors: {BOARD}: lock released, failure logged in', cell) + self.assertIn(f'board task ended with errors; {BOARD}: lock released, failure logged in', cell) self.assertIn('record not cleared', cell) def test_advisory_task_errors_never_fail_the_board(self): @@ -813,7 +821,8 @@ def test_advisory_task_errors_never_fail_the_board(self): def test_a_worker_releases_its_board_when_it_exits(self): # maxtasksperchild=1: a task left holding its flock (the __exit__-entry gap) frees it when its # worker ends after that one task; the record it left is logged found-left by the next take - pool = hil_test._start_pool('seed') + with mock.patch.object(os, 'cpu_count', return_value=1): + pool = hil_test._start_pool('seed') self.addCleanup(pool.terminate) worker = pool.apply_async(_gap_in_worker, (BOARD,)).get(timeout=30) self.assertNotEqual(worker, os.getpid()) From 7294ebc649bd99883c975f30095cb4625f406bd6 Mon Sep 17 00:00:00 2001 From: hathach Date: Thu, 12 Nov 2026 05:16:45 +0700 Subject: [PATCH 04/16] Pin agentrc to the board_task merge --- test/hil/agentrc.json | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/hil/agentrc.json b/test/hil/agentrc.json index 0b36107339..150df6648f 100644 --- a/test/hil/agentrc.json +++ b/test/hil/agentrc.json @@ -1 +1 @@ -{"url": "https://github.com/hathach/agentrc.git", "commit": "d8c1e65ed0638e6c44c0655b22b288d357e36718"} +{"url": "https://github.com/hathach/agentrc.git", "commit": "0919dcfb9ae97fbcc7c69d4b51685013f26f83f6"} From d910c741d6b6f4d8b53179f760dd23174bcddcb3 Mon Sep 17 00:00:00 2001 From: hathach Date: Thu, 12 Nov 2026 06:22:15 +0700 Subject: [PATCH 05/16] Ignore other ST-LINKs' programmer sessions in the busy check The provider's probe_users counts every running STM32_Programmer_CLI as a user of every stlink probe, so a board was refused while a sibling ST-LINK board was flashing in the same run (stm32g0b1nucleo busy during stm32h743nucleo's flash). --- test/hil/hil_flash.py | 21 +++++++++++++++++++-- test/hil/test/test_hil_flash.py | 15 +++++++++++++++ 2 files changed, 34 insertions(+), 2 deletions(-) diff --git a/test/hil/hil_flash.py b/test/hil/hil_flash.py index 4c8f394945..2680b0f4b9 100755 --- a/test/hil/hil_flash.py +++ b/test/hil/hil_flash.py @@ -15,6 +15,7 @@ import copy import functools import json +import shlex import shutil import subprocess import tempfile @@ -141,17 +142,33 @@ class ProbeCheckFailed(RuntimeError): """probe_busy could not rule out a user of the board's probe.""" +def other_stlink_session(cmd: str, uid: str) -> bool: + """Whether a probe user's command line is an STM32_Programmer_CLI selecting only ST-LINKs + other than `uid` by `sn=`, with no `-script` (whose file may name any probe) and no word + naming `uid`. The provider counts every running STM32_Programmer_CLI as a user of every + `stlink` probe, which refuses a board while the same run flashes a sibling's ST-LINK; the + rig has always flashed ST-LINK boards concurrently.""" + argv, uid = shlex.split(cmd), uid.casefold() + if not argv or os.path.basename(argv[0]) != 'STM32_Programmer_CLI': + return False + words = [w.casefold() for w in argv[1:]] + return (any(w.startswith('sn=') for w in words) and '-script' not in words + and not any(uid in w for w in words)) + + def probe_busy(board: dict) -> list: """The board_task busy check of every HIL entry point and the farm check: the provider's probe_users for the board's flasher and, when it differs, its recovery flasher (same probe, another tool); [{'pid', 'cmd'}]. ProbeCheckFailed, naming the cause, when the provider is inconclusive (ProbeCheckInconclusive) or has no lookup for the flasher (ValueError, wch_uart_loader); any other exception propagates. Probe users only: a DUT-side process (a - stray testusb) is the run's recovery, never a refusal.""" + stray testusb) is the run's recovery, never a refusal, and for an `stlink` entry neither is + another ST-LINK's STM32_Programmer_CLI session (other_stlink_session).""" provider, users = hil_util.provider(), {} try: for f in {(f['name'], f.get('uid')): f for f in (board['flasher'], recover_flasher(board))}.values(): - users.update((u['pid'], u) for u in provider.probe_users(f)) + users.update((u['pid'], u) for u in provider.probe_users(f) + if not (f['name'] == 'stlink' and other_stlink_session(u['cmd'], f.get('uid') or ''))) except (provider.ProbeCheckInconclusive, ValueError) as e: raise ProbeCheckFailed(f'{type(e).__name__}: {e}') from e return sorted(users.values(), key=lambda u: u['pid']) diff --git a/test/hil/test/test_hil_flash.py b/test/hil/test/test_hil_flash.py index 09c0f883ca..4a5fab9f5f 100644 --- a/test/hil/test/test_hil_flash.py +++ b/test/hil/test/test_hil_flash.py @@ -128,6 +128,21 @@ def test_probe_busy_asks_for_each_entry_of_the_probe_once(self): hil_flash.probe_busy({'name': 'b', 'flasher': dict(BOARDS['jlink'])}) self.assertEqual(asked, [BOARDS['jlink']], 'no recovery entry: the primary alone, once') + def test_probe_busy_ignores_another_st_links_programmer_session(self): + # the provider counts every STM32_Programmer_CLI as a user of every stlink probe + cli = 'STM32_Programmer_CLI --connect port=swd ' + users = [{'pid': 1, 'cmd': cli + 'sn=OTHER --write fw.elf --go'}, + {'pid': 2, 'cmd': cli + 'SN=s1 --rst'}, + {'pid': 3, 'cmd': 'STM32_Programmer_CLI -script /tmp/s1.prg'}, + {'pid': 4, 'cmd': cli + 'sn=OTHER -script /tmp/x.prg'}, + {'pid': 5, 'cmd': cli + '--write fw.elf'}, + {'pid': 6, 'cmd': cli + 'sn=OTHER --write cmake-build-S1/fw.elf'}, + {'pid': 7, 'cmd': 'timeout 9 ' + cli + 'sn=OTHER'}] + self.provider.probe_users = lambda f: users + self.assertEqual([u['pid'] for u in hil_flash.probe_busy(self.board('stlink'))], [2, 3, 4, 5, 6, 7]) + board = {'name': 'b', 'flasher': {'name': 'openocd', 'uid': 'S1', 'args': '-f interface/stlink.cfg'}} + self.assertEqual(len(hil_flash.probe_busy(board)), len(users), 'only the stlink entry is filtered') + def test_probe_busy_refuses_only_what_the_provider_cannot_decide(self): board = {'name': 'b', 'flasher': dict(BOARDS['jlink'])} for raised in (self.provider.real.ProbeCheckInconclusive('/proc may hide'), ValueError('no probe lookup')): From 7f7dd4b79b4b814fb54f2b7826ea298928e4d5ba Mon Sep 17 00:00:00 2001 From: hathach Date: Thu, 12 Nov 2026 06:35:34 +0700 Subject: [PATCH 06/16] Report a refused board's unended lock as a cleanup blocker --- test/hil/hil_test.py | 9 +++++++-- test/hil/test/test_hil_lock.py | 12 ++++++++++++ 2 files changed, 19 insertions(+), 2 deletions(-) diff --git a/test/hil/hil_test.py b/test/hil/hil_test.py index edc89ccb52..102ec690cd 100755 --- a/test/hil/hil_test.py +++ b/test/hil/hil_test.py @@ -2040,8 +2040,9 @@ def previous_cleanup_text(name: str, failures: list) -> str: def admission_refused(name: str, task, e: Exception) -> tuple: - """test_board's result for a board refused before any hardware access: one refusal cell, - failed-tests empty so a re-run repeats the whole board (no bogus -bt filter).""" + """test_board's result for a board refused before any hardware access: one refusal cell, beside + the cleanup blocker when its lock did not end as asked, failed-tests empty so a re-run repeats the + whole board (no bogus -bt filter).""" log_line(f'{name:25} {STATUS_FAILED}: {e}') fail = hil_report.REPORT_CELL['fail'] # icon-prefixed, so the table tallies it as a failure if busy := hil_flash.busy_refusal(e): @@ -2054,6 +2055,10 @@ def admission_refused(name: str, task, e: Exception) -> tuple: cells = {hil_report.LOCKED_CELL: 'fail'} else: # no refusal: an error of the take or the check, which aborts the run raise e + if not task.ended_cleanly: # the admitted path's blocker: the refusal's lock did not end as asked + blocker = f'board task ended with errors; {task.describe()}' + log_line(f'{name:25} BLOCKER: {blocker}') + cells[hil_report.CLEANUP_PENDING_CELL] = f'{fail} {blocker}' if previous := previous_cleanup_text(name, task.cleanup_failures): cells[hil_report.PREVIOUS_CLEANUP_CELL] = previous return name, 1, [], [(name, cells, None)], None diff --git a/test/hil/test/test_hil_lock.py b/test/hil/test/test_hil_lock.py index 32d1e2563c..1668725da7 100644 --- a/test/hil/test/test_hil_lock.py +++ b/test/hil/test/test_hil_lock.py @@ -696,6 +696,18 @@ def test_a_refusal_still_reports_the_failures_the_take_found(self): self.assertEqual(cells[hil_test.hil_report.PREVIOUS_CLEANUP_CELL], hil_lock.failure_text(failure)) self.assertEqual(hil_lock.open_cleanup_failures(BOARD), [failure]) + def test_a_refusal_whose_lock_did_not_end_is_a_blocker(self): + self.users = [{'pid': 1, 'cmd': 'openocd'}] + with mock.patch.object(hil_lock, 'clear_record', return_value=False): + _, err, failed, rows, _ = hil_test.test_board(self.board) + self.assertEqual((err, failed), (1, [])) + cells = rows[0][1] + self.assertIn(hil_test.hil_report.PROBE_BUSY_CELL, cells) + cell = cells[hil_test.hil_report.CLEANUP_PENDING_CELL] + self.assertIn(f'board task ended with errors; {BOARD}: lock released', cell) + self.assertIn('record not cleared', cell) + self.assertTrue(any('BLOCKER: board task ended with errors' in line for line in self.log), self.log) + def test_the_bypass_still_runs_the_busy_check(self): os.environ['HIL_NO_BOARD_LOCK'] = '1' self.users = [{'pid': 1, 'cmd': 'openocd'}] From fdd8d91fdbb0010f8e8a90fccc0c4c5d54384349 Mon Sep 17 00:00:00 2001 From: hathach Date: Thu, 12 Nov 2026 06:36:51 +0700 Subject: [PATCH 07/16] Report usbtest tools' unended refusal locks and open cleanup failures --- .claude/skills/usbtest/scripts/run_case.py | 40 +++++++++++++------ .claude/skills/usbtest/scripts/wedge_drill.py | 20 +++++----- .claude/test/test_usbtest_run_case.py | 34 ++++++++++++++++ .claude/test/test_usbtest_wedge_drill.py | 27 +++++++++++++ 4 files changed, 100 insertions(+), 21 deletions(-) diff --git a/.claude/skills/usbtest/scripts/run_case.py b/.claude/skills/usbtest/scripts/run_case.py index ffaf316f6e..0284a3660c 100644 --- a/.claude/skills/usbtest/scripts/run_case.py +++ b/.claude/skills/usbtest/scripts/run_case.py @@ -32,10 +32,12 @@ stdout ends with one JSON line: {"pass", "board", "variant", "tests", "cases", "wedged", "boardState", "error"}, each case with usbtest.py's num, name, status, detail and, when it captured -them, stderr and dmesg. Exit 0 every case passed, 1 a case failed or the run failed after the -lock was taken or the task's lock did not end as its verdict asked (its errors in "error"), 2 refused before any -hardware action; a command line argparse rejects exits 2 with its usage on stderr and no JSON line. The JSON line -follows the lock's release. A SIGTERM kills the running flasher or usbtest.py, ends the task failed and reports +them, stderr and dmesg; with "previousCleanupFailure" and "openCleanupFailures" (hil_lock.failure_report) when +the take found open failed cleanups, which go to stderr before any hardware action too, and "restoreNotes" for +those a park left open. Exit 0 every case passed, 1 a case failed or the run failed after the +lock was taken or the task's lock did not end as its verdict asked (its errors in "error"), a refusal's too, 2 refused +before any hardware action; a command line argparse rejects exits 2 with its usage on stderr and no JSON line. The +JSON line follows the lock's release. A SIGTERM kills the running flasher or usbtest.py, ends the task failed and reports boardState unknown. A signal that lands as the task's __exit__ is entered leaves the lock held until this process exits (hil_lock.BoardTask's limit), which follows at once. """ @@ -362,6 +364,7 @@ def lock_and_run(args, tests, report, finish): try: with task: entered = True + found(task) code, error = run_task(task, board, fw, park_fw, tests, args, report) except Terminated: if not entered: @@ -370,26 +373,39 @@ def lock_and_run(args, tests, report, finish): report['boardState'] = 'unknown: terminated (SIGTERM) mid-run' code, error = 1, 'terminated (SIGTERM)' except Exception as e: - if not entered: # admission: the lock, or the busy check under it, refused the board - return finish(2, f'{board["name"]}: {refusal(e)}') - code, error = 1, f'{type(e).__name__}: {e}' # any failure after the lock still ends with a verdict line + if entered: # any failure after the lock still ends with a verdict line + code, error = 1, f'{type(e).__name__}: {e}' + else: # admission: the lock, or the busy check under it, refused the board + code, error = 2, f'{board["name"]}: {refusal(e)}' finally: os.chdir(cwd) # published once the task ended, so its finalization counts - code, error = ended(task, code, error) + code, error = ended(task, code, error, report) report['pass'] = report['pass'] and code == 0 return finish(code, error) -def ended(task, code, error): - """(code, error) once the task ended: a lock that did not end as its verdict asked fails the run, - its state and errors in `error`; advisory errors of a clean end only go to stderr.""" +def found(task): + """The open failed cleanups the take found, reported before any hardware access.""" + if task.cleanup_failures: + print(f'{len(task.cleanup_failures)} open cleanup failure(s): ' + + '; '.join(map(hil_lock.failure_text, task.cleanup_failures)), file=sys.stderr) + + +def ended(task, code, error, report): + """(code, error) once the task ended, the open failed cleanups its take found and why a restore left + any open in `report`: a lock that did not end as its verdict asked fails the run (1), its state and + errors in `error`; advisory errors of a clean end only go to stderr.""" + report.update(hil_lock.failure_report(task.cleanup_failures)) + if task.restore_notes: + report['restoreNotes'] = list(task.restore_notes) + print(f'board task notes: {"; ".join(task.restore_notes)}', file=sys.stderr) if task.ended_cleanly: if task.errors: print(f'board task notes: {task.describe()}', file=sys.stderr) return code, error problem = f'board task did not end as its verdict asked: {task.describe()}' - return code or 1, f'{error}; {problem}' if error else problem + return 1, f'{error}; {problem}' if error else problem def run_task(task, board, fw, park_fw, tests, args, report): diff --git a/.claude/skills/usbtest/scripts/wedge_drill.py b/.claude/skills/usbtest/scripts/wedge_drill.py index 2e1aafe9c2..357d76acb5 100755 --- a/.claude/skills/usbtest/scripts/wedge_drill.py +++ b/.claude/skills/usbtest/scripts/wedge_drill.py @@ -27,15 +27,16 @@ rc 0, testusb reaped, the serial back as one device on a new devnum, smoke case passed), "fail" (the harness did not recover a wedge it was given), or "inconclusive" (no wedge was produced: the case ended before the halt landed, the halt failed, or no case hung). `cleanup` is the drill's -own reset after a non-pass and never counts as harness recovery. Exit 0 only for a pass with the +own reset after a non-pass and never counts as harness recovery. The open failed cleanups the take +found and a park's restoreNotes are reported as in run_case.py. Exit 0 only for a pass with the board parked; 1 otherwise; 2 refused (a command line argparse rejects: its usage on stderr, no JSON line). The lock is a board_task as in run_case.py (its busy check runs under --allow-concurrent too), ended restored once parked, clean while untouched, failed otherwise: a halt process that may still hold the probe goes in as unrecheckable evidence, which only its recovery ends. The JSON line follows the lock's -release; a lock that did not end as its verdict asked, or a signal or exception raised as the task -ended, exits 1, its errors in "error". +release; a lock that did not end as its verdict asked, a refusal's too, or a signal or exception raised as +the task ended, exits 1, its errors in "error". """ import argparse import json @@ -543,6 +544,7 @@ def finish(code): try: with task: entered = True + run_case.found(task) code = drill_locked(task, board, rec_board, halt_with, fw, park_fw, args, report) except (Terminated, KeyboardInterrupt): if not entered: @@ -551,15 +553,15 @@ def finish(code): report['error'] = report['error'] or 'terminated (signal) as the task ended' code = code or 1 # aborted, whatever the drill and its cleanup did except Exception as e: - if not entered: # admission: the lock, or the busy check under it, refused the board - report['error'] = f'{board["name"]}: {run_case.refusal(e)}' - return finish(2) - report['error'] = report['error'] or f'{type(e).__name__}: {e}' - code = code or 1 + if entered: + report['error'] = report['error'] or f'{type(e).__name__}: {e}' + code = code or 1 + else: # admission: the lock, or the busy check under it, refused the board + report['error'], code = f'{board["name"]}: {run_case.refusal(e)}', 2 finally: os.chdir(cwd) # published once the task ended, so its finalization counts - code, report['error'] = run_case.ended(task, code, report['error']) + code, report['error'] = run_case.ended(task, code, report['error'], report) return finish(code) finally: for s, h in previous.items(): diff --git a/.claude/test/test_usbtest_run_case.py b/.claude/test/test_usbtest_run_case.py index bf98363970..29aa144c86 100644 --- a/.claude/test/test_usbtest_run_case.py +++ b/.claude/test/test_usbtest_run_case.py @@ -439,6 +439,40 @@ def clear(fh): report['error']) self.assertIn('record not cleared', report['error']) + def test_a_refusal_whose_lock_did_not_end_fails_the_run(self): + rig = Rig(self) + rig.lock.users = [{'pid': 7, 'cmd': 'JLinkExe -USB P1'}] + with mock.patch.object(run_case.hil_lock, 'clear_record', return_value=False): + rc, report, _ = rig.run('--board', 'solo', '--tests', '29', '--after', 'park') + self.assertEqual((rc, report['pass'], report['boardState']), (1, False, 'untouched')) + self.assertEqual(rig.calls, [('lock', 'solo')]) + self.assertIn('solo: probe in use by pid 7', report['error']) + self.assertIn('board task did not end as its verdict asked: solo: lock released, errors: record not cleared', + report['error']) + + def test_open_failures_are_reported_before_hardware_and_beside_the_result(self): + rig = Rig(self) + earlier = run_case.hil_lock.log_cleanup_failure('solo', 'earlier', detail='probe left', + receipts=[{'unrecheckable': 'probe left'}]) + text, seen, primitive = run_case.hil_lock.failure_text(earlier), [], run_case.hil_flash.flash_primitive + + def flash_primitive(name): + return lambda board, fw: seen.append(sys.stderr.getvalue()) or primitive(name)(board, fw) + with mock.patch.object(run_case.hil_flash, 'flash_primitive', flash_primitive): + rc, report, err = rig.run('--board', 'solo', '--tests', '29', '--after', 'park') + self.assertEqual((rc, report['pass']), (0, True)) + self.assertIn(text, seen[0]) # before the first flash + self.assertEqual(report['previousCleanupFailure'], earlier) + note, = report['restoreNotes'] # unrecheckable: the park leaves it open + self.assertIn(f'{earlier["id"]} stays open', note) + self.assertIn(note, err) + self.assertEqual(run_case.hil_lock.open_cleanup_failures('solo'), [earlier]) + rig = Rig(self) # a refusal reports them too + earlier = run_case.hil_lock.log_cleanup_failure('solo', 'earlier', detail='killed run') + rig.lock.users = [{'pid': 7, 'cmd': 'openocd'}] + rc, report, _ = rig.run('--board', 'solo', '--tests', '29', '--after', 'park') + self.assertEqual((rc, report['previousCleanupFailure']), (2, earlier)) + def test_advisory_task_errors_never_fail_the_run(self): rig = Rig(self) broken = types.SimpleNamespace(InterruptHold=mock.Mock(side_effect=OSError('no signal mask'))) diff --git a/.claude/test/test_usbtest_wedge_drill.py b/.claude/test/test_usbtest_wedge_drill.py index f5c8f2c5be..18b25073db 100644 --- a/.claude/test/test_usbtest_wedge_drill.py +++ b/.claude/test/test_usbtest_wedge_drill.py @@ -152,6 +152,7 @@ def run(self, *argv): with mock.patch.object(sys, 'argv', ['wedge_drill.py', '--config', str(self.config), *argv]), \ redirect_stdout(out), redirect_stderr(err): rc = wedge_drill.main() + self.stderr = err.getvalue() lines = out.getvalue().splitlines() self.verdicts = [l for l in lines if l.startswith('{')] return rc, json.loads(lines[-1]) @@ -682,6 +683,32 @@ def test_the_busy_check_runs_under_allow_concurrent(self): self.assertIn('ok: probe in use by pid 7', r['error']) self.assertEqual([c for c in rig.calls if c[0] in ('flash', 'battery')], []) + def test_a_refusal_whose_lock_did_not_end_exits_1(self): + rig = Rig(self) + rig.lock.users = [{'pid': 7, 'cmd': 'JLinkExe -USB P1'}] + with mock.patch.object(run_case.hil_lock, 'clear_record', return_value=False): + rc, r = rig.run('--board', 'ok', '--delay', '0') + self.assertEqual((rc, r['boardState']), (1, 'untouched')) + self.assertEqual(rig.calls, []) + self.assertIn('ok: probe in use by pid 7', r['error']) + self.assertIn('board task did not end as its verdict asked: ok: lock released, errors: record not cleared', + r['error']) + + def test_open_failures_are_reported_before_hardware_and_beside_the_result(self): + rig = Rig(self) + earlier = run_case.hil_lock.log_cleanup_failure('ok', 'earlier', detail='probe left', + receipts=[{'unrecheckable': 'probe left'}]) + seen, flash = [], run_case.flash + with mock.patch.object(run_case, 'flash', lambda board, fw: seen.append(sys.stderr.getvalue()) or flash(board, fw)): + rc, r = rig.run('--board', 'ok', '--delay', '0') + self.assertEqual((rc, r['boardState']), (0, 'parked on board_test')) + self.assertIn(run_case.hil_lock.failure_text(earlier), seen[0]) # before the first flash + self.assertEqual(r['previousCleanupFailure'], earlier) + note, = r['restoreNotes'] # unrecheckable: the park leaves it open + self.assertIn(f'{earlier["id"]} stays open', note) + self.assertIn(note, rig.stderr) + + class LockName(unittest.TestCase): def test_a_registered_board_is_locked_by_its_registry_name(self): """A probe board the drill admits, named apart from its registered board.""" From be463fcc74a9d387593cb26456bd1024f93e25e5 Mon Sep 17 00:00:00 2001 From: hathach Date: Thu, 12 Nov 2026 06:52:32 +0700 Subject: [PATCH 08/16] Name a refusal's cleanup blocker in its report detail --- test/hil/helper/hil_report.py | 9 ++++++--- test/hil/test/test_hil_report.py | 9 +++++++++ 2 files changed, 15 insertions(+), 3 deletions(-) diff --git a/test/hil/helper/hil_report.py b/test/hil/helper/hil_report.py index 7d3a8f172e..48f7b1edb7 100644 --- a/test/hil/helper/hil_report.py +++ b/test/hil/helper/hil_report.py @@ -699,15 +699,18 @@ def _results(cfg: dict, boards: list, report: dict) -> list: if k in cells), None) previous = [c[PREVIOUS_CLEANUP_CELL] for c in mine.values() if PREVIOUS_CLEANUP_CELL in c] found = '; previous cleanup failure: ' + '; '.join(previous) if previous else '' + # a refusal whose lock did not end as asked: the admitted path lists this cell among `bad` + pending = ''.join(f'; {CLEANUP_PENDING_CELL}: {c[CLEANUP_PENDING_CELL]}' + for c in mine.values() if CLEANUP_PENDING_CELL in c) if unusable is not None and not aborted and not board_wedged: - results.append(({'board': board, 'ran': False, 'pass': False, 'locked': False, - 'wedged': False, 'skipped': [], **kept, 'detail': unusable + found}, mine, False)) + results.append(({'board': board, 'ran': False, 'pass': False, 'locked': False, 'wedged': False, + 'skipped': [], **kept, 'detail': unusable + pending + found}, mine, False)) continue blocked = next((cells[RECOVERY_BLOCKER_CELL] for cells in mine.values() if RECOVERY_BLOCKER_CELL in cells), None) if blocked is not None and not aborted and not board_wedged: results.append(({'board': board, 'ran': False, 'pass': False, 'locked': False, 'wedged': False, - 'skipped': [], **kept, 'detail': f'recovery blocker; not flashed: {blocked}'}, + 'skipped': [], **kept, 'detail': f'recovery blocker; not flashed: {blocked}{pending}'}, mine, False)) continue locked = not aborted and not board_wedged and any(LOCKED_CELL in cells for cells in mine.values()) diff --git a/test/hil/test/test_hil_report.py b/test/hil/test/test_hil_report.py index f0941ec52b..4097a903c7 100644 --- a/test/hil/test/test_hil_report.py +++ b/test/hil/test/test_hil_report.py @@ -476,6 +476,15 @@ def test_a_busy_probe_is_not_run_not_contention(self): self.assertEqual(got[0], {'board': 'alpha', 'ran': False, 'pass': False, 'locked': False, 'wedged': False, 'skipped': [], 'detail': f'{cell}; previous cleanup failure: {previous}'}) + def test_a_refusal_names_its_cleanup_blocker(self): + pending = '❌ board task ended with errors; alpha: lock released, errors: record not cleared' + for refusal, says in ((hil_report.PROBE_BUSY_CELL, '❌ probe in use by pid 7 (openocd)'), + (hil_report.RECOVERY_BLOCKER_CELL, 'recovery blocker; not flashed: ❌ board locked')): + with self.subTest(refusal=refusal): + cell = says.removeprefix('recovery blocker; not flashed: ') + got = self._sum(['alpha'], [('alpha', {refusal: cell, hil_report.CLEANUP_PENDING_CELL: pending})]) + self.assertEqual(got[0]['detail'], f'{says}; cleanup-pending: {pending}') + def test_a_recovery_blocker_is_neither_contention_nor_a_fail(self): cell = '❌ board locked: {"pid": 7, "role": "cleanup-holder"} (recovery blocker: ...)' got = self._sum(['alpha'], [('alpha', {hil_report.RECOVERY_BLOCKER_CELL: cell})]) From 05d93dab10173a848f01b09eeb0238b276c92899 Mon Sep 17 00:00:00 2001 From: hathach Date: Thu, 12 Nov 2026 06:53:49 +0700 Subject: [PATCH 09/16] Report the take and lock end of a SIGTERM inside the board task's admission --- .claude/skills/usbtest/scripts/run_case.py | 11 +++++++---- .claude/skills/usbtest/scripts/wedge_drill.py | 9 ++++++--- .claude/test/test_usbtest_run_case.py | 13 +++++++++++++ .claude/test/test_usbtest_wedge_drill.py | 13 +++++++++++++ 4 files changed, 39 insertions(+), 7 deletions(-) diff --git a/.claude/skills/usbtest/scripts/run_case.py b/.claude/skills/usbtest/scripts/run_case.py index 0284a3660c..1f90120905 100644 --- a/.claude/skills/usbtest/scripts/run_case.py +++ b/.claude/skills/usbtest/scripts/run_case.py @@ -367,11 +367,14 @@ def lock_and_run(args, tests, report, finish): found(task) code, error = run_task(task, board, fw, park_fw, tests, args, report) except Terminated: - if not entered: + if entered: + report['pass'] = False + report['boardState'] = 'unknown: terminated (SIGTERM) mid-run' + code, error = 1, 'terminated (SIGTERM)' + elif task.taken or task.ended: # inside the admission: its take's failures and end still count + code, error = 2, 'terminated (SIGTERM) before any hardware action' + else: return finish(2, 'terminated (SIGTERM) before any hardware action') - report['pass'] = False - report['boardState'] = 'unknown: terminated (SIGTERM) mid-run' - code, error = 1, 'terminated (SIGTERM)' except Exception as e: if entered: # any failure after the lock still ends with a verdict line code, error = 1, f'{type(e).__name__}: {e}' diff --git a/.claude/skills/usbtest/scripts/wedge_drill.py b/.claude/skills/usbtest/scripts/wedge_drill.py index 357d76acb5..2866e263aa 100755 --- a/.claude/skills/usbtest/scripts/wedge_drill.py +++ b/.claude/skills/usbtest/scripts/wedge_drill.py @@ -547,11 +547,14 @@ def finish(code): run_case.found(task) code = drill_locked(task, board, rec_board, halt_with, fw, park_fw, args, report) except (Terminated, KeyboardInterrupt): - if not entered: + if entered: + report['error'] = report['error'] or 'terminated (signal) as the task ended' + code = code or 1 # aborted, whatever the drill and its cleanup did + elif task.taken or task.ended: # inside the admission: its take's failures and end still count + report['error'], code = 'terminated before any hardware action', 2 + else: report['error'] = 'terminated before any hardware action' return finish(2) - report['error'] = report['error'] or 'terminated (signal) as the task ended' - code = code or 1 # aborted, whatever the drill and its cleanup did except Exception as e: if entered: report['error'] = report['error'] or f'{type(e).__name__}: {e}' diff --git a/.claude/test/test_usbtest_run_case.py b/.claude/test/test_usbtest_run_case.py index 29aa144c86..72f1cd23c2 100644 --- a/.claude/test/test_usbtest_run_case.py +++ b/.claude/test/test_usbtest_run_case.py @@ -523,6 +523,19 @@ def test_before_the_lock_is_a_refusal(self): self.assertEqual(rig.calls, []) self.assertIs(signal.getsignal(signal.SIGTERM), self.previous) + def test_in_the_busy_check_reports_the_take_and_its_end(self): + rig = Rig(self) + earlier = run_case.hil_lock.log_cleanup_failure('solo', 'earlier', detail='probe left', + receipts=[{'unrecheckable': 'probe left'}]) + rig.lock.users = run_case.Terminated() + with mock.patch.object(run_case.hil_lock, 'clear_record', return_value=False): + rc, report, _ = rig.run('--board', 'solo', '--tests', '29', '--after', 'park') + self.assertEqual((rc, report['pass'], report['boardState']), (1, False, 'untouched')) + self.assertEqual(rig.calls, [('lock', 'solo')]) + self.assertEqual(report['previousCleanupFailure'], earlier) + self.assertIn('terminated (SIGTERM) before any hardware action; board task did not end as its verdict asked: ' + 'solo: lock released', report['error']) + def test_handler_installed_for_the_run_then_restored(self): rig = Rig(self) during = [] diff --git a/.claude/test/test_usbtest_wedge_drill.py b/.claude/test/test_usbtest_wedge_drill.py index 18b25073db..4cbf7f5534 100644 --- a/.claude/test/test_usbtest_wedge_drill.py +++ b/.claude/test/test_usbtest_wedge_drill.py @@ -694,6 +694,19 @@ def test_a_refusal_whose_lock_did_not_end_exits_1(self): self.assertIn('board task did not end as its verdict asked: ok: lock released, errors: record not cleared', r['error']) + def test_a_signal_in_the_busy_check_reports_the_take_and_its_end(self): + rig = Rig(self) + earlier = run_case.hil_lock.log_cleanup_failure('ok', 'earlier', detail='probe left', + receipts=[{'unrecheckable': 'probe left'}]) + rig.lock.users = run_case.Terminated() + with mock.patch.object(run_case.hil_lock, 'clear_record', return_value=False): + rc, r = rig.run('--board', 'ok', '--delay', '0') + self.assertEqual((rc, r['boardState']), (1, 'untouched')) + self.assertEqual(rig.calls, []) + self.assertEqual(r['previousCleanupFailure'], earlier) + self.assertIn('terminated before any hardware action; board task did not end as its verdict asked: ' + 'ok: lock released', r['error']) + def test_open_failures_are_reported_before_hardware_and_beside_the_result(self): rig = Rig(self) earlier = run_case.hil_lock.log_cleanup_failure('ok', 'earlier', detail='probe left', From b00992e3d4502dfde8f3487d6acbd320df4acfa4 Mon Sep 17 00:00:00 2001 From: hathach Date: Thu, 12 Nov 2026 07:29:25 +0700 Subject: [PATCH 10/16] Replay an interrupt that lands as the board verdict starts --- test/hil/hil_test.py | 23 +++++++++++++++++ test/hil/test/test_hil_lock.py | 47 ++++++++++++++++++++++++++++++++++ 2 files changed, 70 insertions(+) diff --git a/test/hil/hil_test.py b/test/hil/hil_test.py index 102ec690cd..69ca0caee4 100755 --- a/test/hil/hil_test.py +++ b/test/hil/hil_test.py @@ -2119,6 +2119,29 @@ def test_board(board: Board) -> tuple: def _verdict(task, board: Board, parked: list, unrestored: str = '', exc: BaseException | None = None) -> None: + """_give_verdict under the provider's InterruptHold, so a SIGINT landing before the verdict is + stored is replayed after it, never leaving the task to end evidence-free. One landing before the + hold went in gave nothing yet: it is raised once the verdict has been given.""" + interrupted = None + while True: + try: + hold = hil_util.provider().hil_process.InterruptHold() + except Exception: + hold = None # no hold to be had: the verdict is still given, unprotected + except BaseException as e: + interrupted = interrupted or e + continue + break + try: + _give_verdict(task, board, parked, unrestored, exc) + finally: + if hold is not None: + hold.release() + if interrupted is not None: + raise interrupted + + +def _give_verdict(task, board: Board, parked: list, unrestored: str, exc: BaseException | None) -> None: """The battery's cleanup verdict, its last act under the lock (the HIL contract's Reservation). A battery that raised `exc` is restored when its final park still succeeded (the run itself stays aborted by `exc`), failed with unrecheckable evidence for an openocd_esp interrupt that diff --git a/test/hil/test/test_hil_lock.py b/test/hil/test/test_hil_lock.py index 1668725da7..9c788239e1 100644 --- a/test/hil/test/test_hil_lock.py +++ b/test/hil/test/test_hil_lock.py @@ -12,6 +12,7 @@ import json import os import shutil +import signal import subprocess import sys import tempfile @@ -488,6 +489,52 @@ def __setitem__(self, key, value): self.assertIn('receipt missing', failure['receipts'][0]['unrecheckable']) self.assertTrue(hil_lock.resolve_restored(BOARD, [failure], evidence='parked')) + def run_interrupted_verdict(self): + """run_failing_test's board under a real SIGINT raised as the verdict gathers its evidence, + before task.failed stores it: the pending receipts are still logged, then the interrupt raised.""" + old = signal.signal(signal.SIGINT, signal.default_int_handler) + self.addCleanup(signal.signal, signal.SIGINT, old) + evidence, raised = hil_test.pending_evidence, [] + + def interrupted(name, pending): + if not raised: + raised.append(name) + signal.raise_signal(signal.SIGINT) + return evidence(name, pending) + patch(self, hil_test, 'pending_evidence', interrupted) + + def failing_test(board): + hil_flash.cleanup_pending[BOARD] = (self.RECEIPT,) + raise RuntimeError('no enumeration') + patch(self, hil_test, 'test_device_cdc_msc', failing_test) + self.provider(self.op('done', rc=0)) + with self.assertRaises(KeyboardInterrupt): + hil_test.test_board(self.board) + self.assertEqual(raised, [BOARD]) + failure = self.assert_logged() + self.assertNotIn('without a cleanup verdict', failure['detail']) + self.assertIn('lock released', self.log[-1]) + + def test_an_interrupt_as_the_verdict_starts_still_logs_the_pending_receipts(self): + self.run_interrupted_verdict() + + def test_an_interrupt_before_the_verdicts_hold_still_logs_the_pending_receipts(self): + process = hil_util.provider().hil_process + hold, verdict, calls = process.InterruptHold, hil_test._verdict, [] + + def late_hold(): + calls.append(1) + if len(calls) == 1: + raise KeyboardInterrupt + return hold() + + def verdict_with_late_hold(*args, **kwargs): # the task's own holds stay real + with mock.patch.object(process, 'InterruptHold', late_hold): + return verdict(*args, **kwargs) + patch(self, hil_test, '_verdict', verdict_with_late_hold) + self.run_interrupted_verdict() + self.assertEqual(len(calls), 2) + def test_no_later_session_starts_on_the_board(self): self.provider(self.op('pending')) with redirect_stdout(io.StringIO()): From ba8f5653c0aa87bd2c33376f4f0fa2c1c3b923dc Mon Sep 17 00:00:00 2001 From: hathach Date: Thu, 12 Nov 2026 07:58:08 +0700 Subject: [PATCH 11/16] Keep a replayed signal and surviving probe holders in wedge_drill verdicts --- .claude/skills/usbtest/scripts/wedge_drill.py | 26 ++++++++----- .claude/test/test_usbtest_wedge_drill.py | 38 +++++++++++++++++++ 2 files changed, 55 insertions(+), 9 deletions(-) diff --git a/.claude/skills/usbtest/scripts/wedge_drill.py b/.claude/skills/usbtest/scripts/wedge_drill.py index 2866e263aa..9d91cd92cd 100755 --- a/.claude/skills/usbtest/scripts/wedge_drill.py +++ b/.claude/skills/usbtest/scripts/wedge_drill.py @@ -415,6 +415,14 @@ def live_children(grace): time.sleep(0.1) +def note_probe_holder(report): + """A live child as `probeHeld` when none is known yet: no probe access past it.""" + if not report['halt'].get('probeHeld'): + stuck = live_children(hil_util.REAP_GRACE) + if stuck: + report['halt']['probeHeld'] = stuck[0] + + def probe_evidence(report) -> dict: """A probe process that may still hold the probe, as unrecheckable evidence: only its recovery ends it, never a later park.""" @@ -431,16 +439,12 @@ def failed(**evidence): given.append('failed') return False - if report['boardState'] == 'flash failed': - return failed() - if not report['halt'].get('probeHeld'): - # whatever path got here, signals included: no probe access past a live child - stuck = live_children(hil_util.REAP_GRACE) - if stuck: - report['halt']['probeHeld'] = stuck[0] + note_probe_holder(report) # whatever path got here, signals and a failed flash included if held := report['halt'].get('probeHeld'): report['boardState'] = f'unknown, not parked: probe process {held} may still hold the probe (usb-kernel-recover)' return failed(**probe_evidence(report)) + if report['boardState'] == 'flash failed': + return failed() if report['drill'] == 'pass': safe = True elif report['halt'].get('issued'): @@ -493,6 +497,7 @@ def drill_locked(task, board, rec_board, halt_with, fw, park_fw, args, report): report['error'] = report['error'] or 'terminated (signal) during cleanup' report['boardState'] = 'unknown, not parked: cleanup interrupted' if not given: + note_probe_holder(report) # e.g. the cleanup reset's child, past its reap try: task.failed(detail=f'{report["boardState"]}: {type(e).__name__}', **probe_evidence(report)) except RuntimeError: @@ -548,8 +553,11 @@ def finish(code): code = drill_locked(task, board, rec_board, halt_with, fw, park_fw, args, report) except (Terminated, KeyboardInterrupt): if entered: - report['error'] = report['error'] or 'terminated (signal) as the task ended' - code = code or 1 # aborted, whatever the drill and its cleanup did + landed = 'terminated (signal) as the task ended' + # drill_locked's own interruption is in error already; one its task end replayed is added + report['error'] = (f'{report["error"]}; {landed}' if report['error'] and code is not None + else report['error'] or landed) + code = 1 # aborted, whatever the drill and its cleanup did elif task.taken or task.ended: # inside the admission: its take's failures and end still count report['error'], code = 'terminated before any hardware action', 2 else: diff --git a/.claude/test/test_usbtest_wedge_drill.py b/.claude/test/test_usbtest_wedge_drill.py index 4cbf7f5534..0b15f778ca 100644 --- a/.claude/test/test_usbtest_wedge_drill.py +++ b/.claude/test/test_usbtest_wedge_drill.py @@ -658,6 +658,44 @@ def test_an_interrupt_replayed_at_the_task_end_aborts_a_passed_drill(self): self.assertEqual(rig.lock.events('failed'), []) # the restored cleanup stands self.assertTrue(rig.lock.cleared and rig.lock.closed) + def test_an_interrupt_replayed_at_the_task_end_aborts_a_refused_drill(self): + rig = Rig(self) + real_exit = run_case.hil_lock.BoardTask.__exit__ + + def exit_(task, *a): # the task ended clean, then its hold replays the signal + real_exit(task, *a) + raise run_case.Terminated() + with mock.patch.object(run_case, 'live_peers', side_effect=[([], True), ([(1, 'hil_test.py')], True)]), \ + mock.patch.object(run_case.hil_lock.BoardTask, '__exit__', exit_): + rc, r = rig.run('--board', 'ok', '--delay', '0') + self.assertEqual((rc, r['boardState']), (1, 'untouched')) + self.assertEqual(r['error'], 'a battery may be running on this host: hil_test.py (pid 1); ' + 'terminated (signal) as the task ended') + self.assertTrue(rig.lock.cleared and rig.lock.closed) + + def test_a_flasher_left_by_a_failed_flash_is_unrecheckable_evidence(self): + rig = Rig(self) + rig.flash_errors['/fw/device/usbtest'] = 'flash timed out' + rig.live_children = [999] + rc, r = rig.run('--board', 'ok', '--delay', '0') + self.assertEqual(rc, 1) + self.assertIn('probe process 999', r['boardState']) + self.assertNotIn('battery', [c[0] for c in rig.calls]) + failed, = rig.lock.events('failed') + self.assertEqual(failed['receipts'], [{'unrecheckable': 'probe process 999 may still hold the probe'}]) + + def test_a_child_left_by_an_interrupted_cleanup_reset_is_unrecheckable_evidence(self): + rig = Rig(self) + rig.case27 = ({**HUNG, 'cases': [{'num': 27, 'status': 'FAIL'}]}, '', '') + rig.reset_raises = run_case.Terminated() + with mock.patch.object(wedge_drill, 'live_children', + lambda grace: [999] if ('cleanup-reset', 'openocd') in rig.calls else []): + rc, r = rig.run('--board', 'ok', '--delay', '0') + self.assertEqual((rc, r['boardState']), (1, 'unknown, not parked: cleanup interrupted')) + self.assertEqual(r['halt']['probeHeld'], 999) + failed, = rig.lock.events('failed') + self.assertEqual(failed['receipts'], [{'unrecheckable': 'probe process 999 may still hold the probe'}]) + def test_a_held_probe_is_unrecheckable_evidence(self): rig = Rig(self) rig.live_children = [999] From 353695378fcc42d48cc8450a60ea4488958de02d Mon Sep 17 00:00:00 2001 From: hathach Date: Thu, 12 Nov 2026 08:52:04 +0700 Subject: [PATCH 12/16] Keep an earlier error when a signal interrupts the wedge_drill verdict When a flash failure already set report['error'], a signal during finish_locked's verdict was dropped from the JSON error, so the interrupted cleanup went unreported. --- .claude/skills/usbtest/scripts/wedge_drill.py | 5 ++++- .claude/test/test_usbtest_wedge_drill.py | 16 ++++++++++++++++ 2 files changed, 20 insertions(+), 1 deletion(-) diff --git a/.claude/skills/usbtest/scripts/wedge_drill.py b/.claude/skills/usbtest/scripts/wedge_drill.py index 9d91cd92cd..7e22e4bc27 100755 --- a/.claude/skills/usbtest/scripts/wedge_drill.py +++ b/.claude/skills/usbtest/scripts/wedge_drill.py @@ -494,7 +494,10 @@ def drill_locked(task, board, rec_board, halt_with, fw, park_fw, args, report): try: parked = finish_locked(task, board, rec_board, park_fw, report, given) except (Terminated, KeyboardInterrupt) as e: - report['error'] = report['error'] or 'terminated (signal) during cleanup' + interrupted = 'terminated (signal) during cleanup' + report['error'] = (f'{report["error"]}; {interrupted}' + if report['error'] and not report['error'].startswith('terminated') + else report['error'] or interrupted) report['boardState'] = 'unknown, not parked: cleanup interrupted' if not given: note_probe_holder(report) # e.g. the cleanup reset's child, past its reap diff --git a/.claude/test/test_usbtest_wedge_drill.py b/.claude/test/test_usbtest_wedge_drill.py index 0b15f778ca..97ed9e6936 100644 --- a/.claude/test/test_usbtest_wedge_drill.py +++ b/.claude/test/test_usbtest_wedge_drill.py @@ -375,6 +375,22 @@ def failed(task, **kw): # the interrupt lands as finish_locked gives its ver self.assertEqual(event['receipts'], [{'unrecheckable': 'probe process 777 may still hold the probe'}]) self.assertTrue(run_case.hil_lock.resolve_restored('wch', [event], evidence='parked')) # stays open + def test_a_signal_in_the_verdict_after_a_failed_flash_keeps_both_errors(self): + rig = Rig(self) + rig.flash_errors['/fw/device/usbtest'] = 'flash timed out' + real, calls = run_case.hil_lock.BoardTask.failed, [] + + def failed(task, **kw): # the interrupt lands as finish_locked gives its verdict + calls.append(kw) + if len(calls) == 1: + raise run_case.Terminated() + return real(task, **kw) + with mock.patch.object(run_case.hil_lock.BoardTask, 'failed', failed): + rc, r = rig.run('--board', 'ok', '--delay', '0') + self.assertEqual(rc, 1) + self.assertIn('flash timed out', r['error']) + self.assertEqual(r['error'].count('terminated (signal) during cleanup'), 1, r['error']) + def test_a_signal_during_parking(self): rig = Rig(self) rig.flash_raises['/fw/device/board_test'] = KeyboardInterrupt() From 71907c0c08aa123eaa8e26b7bbba9b1e5cd54d7f Mon Sep 17 00:00:00 2001 From: hathach Date: Thu, 12 Nov 2026 11:19:33 +0700 Subject: [PATCH 13/16] hil: give board verdicts through BoardTask's collector and drop the ST-LINK filter --- .claude/skills/hil-contract/SKILL.md | 4 +- .claude/skills/usbtest/scripts/wedge_drill.py | 67 +++++++++---------- .claude/test/test_usbtest_wedge_drill.py | 56 +++++++++------- test/hil/agentrc.json | 2 +- test/hil/hil_flash.py | 28 +------- test/hil/hil_test.py | 47 +++---------- test/hil/test/test_hil_farm_check.py | 1 + test/hil/test/test_hil_flash.py | 16 ----- test/hil/test/test_hil_lock.py | 33 +++++---- 9 files changed, 98 insertions(+), 156 deletions(-) diff --git a/.claude/skills/hil-contract/SKILL.md b/.claude/skills/hil-contract/SKILL.md index edf538ffec..dfcfea4afd 100644 --- a/.claude/skills/hil-contract/SKILL.md +++ b/.claude/skills/hil-contract/SKILL.md @@ -188,13 +188,13 @@ A local `hil_test.py` run has no done record; wait for its completion notificati The `ci` rig also hosts a GitHub Actions runner that flashes boards and runs HIL as part of CI, never stopped (`hil` Board locks). Each board's lock is taken through `test/hil/helper/hil_lock.py`, under its lock name: agentrc's registry `name` for a board with `probe`, whatever this roster calls it, else its roster `name` (`hil_util.lock_name`). `python3 "${AGENTRC_DIR:-$HOME/.claude}"/skills/hil/scripts/hil_boards.py lock ` prints it; the helper's named `hold` and `release` take lock names, never roster names. The harness's shared scripts (the lock mechanics, the bounded sysfs reads and bus scan of `test/hil/helper/usb_observe.py`, the RTT console, and the `hil` skill's Flashers: the bounded command runner behind `test/hil/helper/hil_util.py` and the per-flasher commands and pyOCD launcher behind `test/hil/hil_flash.py`) are loaded by `test/hil/helper/agentrc.py` through agentrc's `hil_load` (one module per file per process) from the agentrc it selects: a `.agentrc/` that `hil_remote.py` staged at the tree's root, else in CI (`CI` or `GITHUB_ACTIONS` true) the commit `test/hil/agentrc.json` pins, fetched into `lib/agentrc` by `python3 test/hil/helper/agentrc.py fetch`, else the installed agentrc, `"${AGENTRC_DIR:-$HOME/.claude}"`, never fetched; `python3 test/hil/helper/agentrc.py check` prints which. Missing, off the pin, of another `agentrc_source.py` API, unlike its staged manifest or lacking a file of its scripts' closure, every HIL entry point refuses before any board access. -`hil_test.py`, `run_case.py` and `wedge_drill.py` take each board through agentrc's `hil_lock.board_task` (`hil` Board locks), protected for every flasher: the record is marked `cleanupOwed`, its group the board alone, so a task killed before its end leaves it for the next take to log found-left. Under the taken lock, before any hardware access, the busy check (`probe_busy` in `test/hil/hil_flash.py`: agentrc's `hil_flash.probe_users` for the board's flasher and its recovery flasher) refuses the board when it names a live process using the probe, or when it cannot rule one out (`/proc` may hide other users' processes, a read failed, or the flasher has no probe lookup, as `wch_uart_loader`); the lock is then released with nothing logged. The check is a snapshot of probe users, never proof the probe is idle: it misses an `STM32_Programmer_CLI -script` session, a GDB client attached to its server, a process that opens the probe after it, and every DUT-side process; a stray `testusb` on the DUT never refuses admission (Recovery sweeps it inside the run). The farm check's profile exposes the same check as its `busy(board)` hook, which engines older than that hook ignore. Each task ends on one cleanup verdict, its last act under the lock: +`hil_test.py`, `run_case.py` and `wedge_drill.py` take each board through agentrc's `hil_lock.board_task` (`hil` Board locks), protected for every flasher: the record is marked `cleanupOwed`, its group the board alone, so a task killed before its end leaves it for the next take to log found-left. Under the taken lock, before any hardware access, the busy check (`probe_busy` in `test/hil/hil_flash.py`: agentrc's `hil_flash.probe_users` for the board's flasher and its recovery flasher) refuses the board when it names a live process using the probe, or when it cannot rule one out (`/proc` may hide other users' processes, a read failed, or the flasher has no probe lookup, as `wch_uart_loader`); the lock is then released with nothing logged. The check is a snapshot of probe users, never proof the probe is idle: it misses an `STM32_Programmer_CLI -script` session, counts none that selects another ST-LINK by `sn=` (whose discovery opens this one too), and misses a GDB client attached to its server, a process that opens the probe after it, and every DUT-side process; a stray `testusb` on the DUT never refuses admission (Recovery sweeps it inside the run). The farm check's profile exposes the same check as its `busy(board)` hook, which engines older than that hook ignore. Each task ends on one cleanup verdict: `hil_test.py`'s and `wedge_drill.py`'s come from their verdict collector (`board_task(..., verdict=)`), which the task calls at its end under its own interrupt hold, and `run_case.py`'s is its last act under the lock: - `hil_test.py`: restored when the final `device/board_test` park succeeded, a failed test included, and also when an interrupt or exception follows that park (the run still aborts); clean under `--skip-flash` once every operation ended; failed for a pending provider cleanup (below), a wedged board with or without `--skip-flash`, a park that failed or had no firmware, a SystemView capture flash left unparked, or an exception or interrupt before the park. - `run_case.py`: restored when `--after park` parked; clean for `--after leave` with a complete, unwedged verdict, or a peer found under the lock; failed for a failed flash or park, no enumeration, an incomplete verdict, a wedge, an exception or a SIGTERM. - `wedge_drill.py`: restored when parked, clean while untouched, failed otherwise; a probe process that may still hold the probe goes in as unrecheckable evidence. -A failed verdict appends a `failed` event, with its tracked child receipts and retained sessions, to `/tmp/tinyusb-hil-locks/.cleanup.jsonl`, clears the record and releases the flock; a restored one first resolves the open failures its take found whose own evidence is ended. A task that did not end as its verdict asked (`BoardTask.ended_cleanly` false: a record not cleared, a failure not logged, under the bypass too, a handle not closed) fails the board as a `cleanup-pending` cell `board task ended with errors; : ...`, and `run_case.py` and `wedge_drill.py` exit 1 with it in `error` (`run_case.py`'s `pass` false); an interrupt replayed as a task ends aborts it the same way, exit 1, whatever verdict it gave; each publishes its result only after the task ended, deciding on `ended_cleanly`, never on its error text, and naming how the lock ended with `BoardTask.describe()`. Advisory errors of a clean end (an interrupt hold not installed, a restoration not logged) are only shown: in the run's log and `previous-cleanup-failure` as `board task notes`, or on the scripts' stderr. A failed park is the next take's notice, not a test failure of its own run. Limit (`hil_lock.BoardTask`'s): a signal that lands as the task's `__exit__` is entered leaves the flock held while the process lives. No entry point goes on after one: `hil_test.py` runs each board in a pool worker of its own (`maxtasksperchild=1`) that ends with its task or its interrupt, and `run_case.py` and `wedge_drill.py` exit after their one task, so the flock goes with the process and the next take logs the record. +A failed verdict appends a `failed` event, with its tracked child receipts and retained sessions, to `/tmp/tinyusb-hil-locks/.cleanup.jsonl`, clears the record once that event is logged (one it could not log keeps the record for the next take to log found-left) and releases the flock; a restored one first resolves the open failures its take found whose own evidence is ended. A task that did not end as its verdict asked (`BoardTask.ended_cleanly` false: a record not cleared, a failure not logged, under the bypass too, a handle not closed) fails the board as a `cleanup-pending` cell `board task ended with errors; : ...`, and `run_case.py` and `wedge_drill.py` exit 1 with it in `error` (`run_case.py`'s `pass` false); an interrupt replayed as a task ends aborts it the same way, exit 1, whatever verdict it gave; each publishes its result only after the task ended, deciding on `ended_cleanly`, never on its error text, and naming how the lock ended with `BoardTask.describe()`. Advisory errors of a clean end (an interrupt hold not installed, a restoration not logged) are only shown: in the run's log and `previous-cleanup-failure` as `board task notes`, or on the scripts' stderr. A failed park is the next take's notice, not a test failure of its own run. Limit (`hil_lock.BoardTask`'s): a signal that lands as the task's `__exit__` is entered leaves the flock held while the process lives. No entry point goes on after one: `hil_test.py` runs each board in a pool worker of its own (`maxtasksperchild=1`) that ends with its task or its interrupt, and `run_case.py` and `wedge_drill.py` exit after their one task, so the flock goes with the process and the next take logs the record. The provider's `openocd_esp` flasher (`hil` Flashers) is supported by `hil_test.py` and the farm check; `run_case.py` refuses it, its docstring says why. It is unrostered on ci.lan and refused under a CI job (`RUNNER_TRACKING_ID` or `GITHUB_ACTIONS` set). Whatever an `openocd_esp` operation leaves not proven ended stops that board's run, with no retry or park, and ends its task failed with the tracked child receipts and the retained sessions, or with the pending detail as unrecheckable evidence when it names neither. The `cleanup-pending` cell names the receipts, log and any logging error; the farm row's cleanup records the release and retained sessions. An interrupt before a receipt is stored is logged with unrecheckable evidence, never as a proven cleanup. A bench board with an open `openocd_esp` cleanup failure must be recovered before another run or farm check accesses it; the free flock does not gate access. diff --git a/.claude/skills/usbtest/scripts/wedge_drill.py b/.claude/skills/usbtest/scripts/wedge_drill.py index 7e22e4bc27..d0de66aa78 100755 --- a/.claude/skills/usbtest/scripts/wedge_drill.py +++ b/.claude/skills/usbtest/scripts/wedge_drill.py @@ -430,21 +430,15 @@ def probe_evidence(report) -> dict: return {'receipts': [{'unrecheckable': f'probe process {held} may still hold the probe'}]} if held else {} -def finish_locked(task, board, rec_board, park_fw, report, given): - """Cleanup and parking under the lock, on every path out of the drill, ending on the task's - verdict: restored once parked (True), else failed with probe_evidence. `given` gets an entry - once a verdict call returned.""" - def failed(**evidence): - task.failed(detail='; '.join(filter(None, (report['boardState'], report['error']))), **evidence) - given.append('failed') - return False - +def finish_locked(board, rec_board, park_fw, report) -> bool: + """Cleanup and parking under the lock, on every path out of the drill: whether the board was + parked, its state in report['boardState'] for drill_verdict.""" note_probe_holder(report) # whatever path got here, signals and a failed flash included if held := report['halt'].get('probeHeld'): report['boardState'] = f'unknown, not parked: probe process {held} may still hold the probe (usb-kernel-recover)' - return failed(**probe_evidence(report)) + return False if report['boardState'] == 'flash failed': - return failed() + return False if report['drill'] == 'pass': safe = True elif report['halt'].get('issued'): @@ -458,25 +452,32 @@ def failed(**evidence): and not report['error']) if not safe: report['boardState'] = 'unknown, not parked: check it (usb-kernel-recover)' - return failed() + return False if report['error'].startswith('terminated'): report['boardState'] = 'not parked: terminated' # whoever signalled wants the board - return failed() + return False err = run_case.flash(board, park_fw) report['boardState'] = f'park failed: {err}' if err else 'parked on board_test' if err: report['error'] = report['error'] or f'park failed: {err}' - return failed() - task.restored(evidence='wedge_drill.py: parked on board_test') - given.append('restored') - return True + return not err -def drill_locked(task, board, rec_board, halt_with, fw, park_fw, args, report): - """The drill and its cleanup under the board's task: its exit code, 2 when a peer refused it - under the lock. An interrupted cleanup ends the task failed, with probe_evidence and the - interruption in its detail, then propagates.""" - parked, given = False, [] +def drill_verdict(task, report, ledger): + """The drill's board task's verdict collector: clean when a peer refused it under the lock, + restored once parked, else failed with probe_evidence.""" + if ledger.get('refused'): + task.clean() + elif ledger.get('parked'): + task.restored(evidence='wedge_drill.py: parked on board_test') + else: + task.failed(detail='; '.join(filter(None, (report['boardState'], report['error']))), **probe_evidence(report)) + + +def drill_locked(board, rec_board, halt_with, fw, park_fw, args, report, ledger): + """The drill and its cleanup under the board's task, recording in `ledger` what drill_verdict + decides on: its exit code, 2 when a peer refused it under the lock. An interrupted cleanup + propagates once a probe holder it left is noted.""" with tempfile.TemporaryDirectory(prefix='wedge_drill-', ignore_cleanup_errors=True) as workdir: os.chdir(workdir) try: @@ -484,29 +485,23 @@ def drill_locked(task, board, rec_board, halt_with, fw, park_fw, args, report): run_case.check_peers() # again: a peer may have started before the lock report['drill'] = drill(board, halt_with, fw, args.delay, args.timeout, report) except Refused as e: - report['error'] = str(e) - task.clean() + report['error'], ledger['refused'] = str(e), True return 2 except (Terminated, KeyboardInterrupt): report['error'] = 'terminated (signal)' except Exception as e: report['error'] = f'{type(e).__name__}: {e}' try: - parked = finish_locked(task, board, rec_board, park_fw, report, given) - except (Terminated, KeyboardInterrupt) as e: + ledger['parked'] = finish_locked(board, rec_board, park_fw, report) + except (Terminated, KeyboardInterrupt): interrupted = 'terminated (signal) during cleanup' report['error'] = (f'{report["error"]}; {interrupted}' if report['error'] and not report['error'].startswith('terminated') else report['error'] or interrupted) report['boardState'] = 'unknown, not parked: cleanup interrupted' - if not given: - note_probe_holder(report) # e.g. the cleanup reset's child, past its reap - try: - task.failed(detail=f'{report["boardState"]}: {type(e).__name__}', **probe_evidence(report)) - except RuntimeError: - pass # its verdict was stored as the interrupt landed: board_task merged them, failed + note_probe_holder(report) # e.g. the cleanup reset's child, past its reap raise - return 0 if report['drill'] == 'pass' and parked else 1 + return 0 if report['drill'] == 'pass' and ledger.get('parked') else 1 def main(): @@ -546,14 +541,16 @@ def finish(code): except Terminated: report['error'] = 'terminated before any hardware action' return finish(2) + ledger = {} task = hil_lock.board_task(hil_util.lock_name(board), 'wedge_drill.py', - busy=lambda: hil_flash.probe_busy(board)) + busy=lambda: hil_flash.probe_busy(board), + verdict=lambda task, exc: drill_verdict(task, report, ledger)) entered, code = False, None try: with task: entered = True run_case.found(task) - code = drill_locked(task, board, rec_board, halt_with, fw, park_fw, args, report) + code = drill_locked(board, rec_board, halt_with, fw, park_fw, args, report, ledger) except (Terminated, KeyboardInterrupt): if entered: landed = 'terminated (signal) as the task ended' diff --git a/.claude/test/test_usbtest_wedge_drill.py b/.claude/test/test_usbtest_wedge_drill.py index 97ed9e6936..0b691c8591 100644 --- a/.claude/test/test_usbtest_wedge_drill.py +++ b/.claude/test/test_usbtest_wedge_drill.py @@ -6,6 +6,7 @@ import io import json import os +import signal import subprocess import sys import tempfile @@ -353,43 +354,50 @@ def test_an_interrupted_cleanup_logs_its_cause(self): rig.reset_raises = run_case.Terminated() rig.run('--board', 'ok', '--delay', '0') failed, = rig.lock.events('failed') - self.assertIn('unknown, not parked: cleanup interrupted: Terminated', failed['detail']) + self.assertIn('unknown, not parked: cleanup interrupted; ', failed['detail']) + self.assertTrue(failed['detail'].endswith('; then Terminated'), failed['detail']) self.assertEqual(failed['receipts'], []) - def test_a_known_probe_holder_survives_an_interrupted_verdict(self): + def signal_at_the_verdict(self): + """A real SIGTERM, once, as BoardTask calls drill_verdict, its collector: deferred by the + task's hold, replayed once the task ended.""" + fired = [] + + def tracer(frame, event, arg): + if not fired and event == 'call' and frame.f_code is wedge_drill.drill_verdict.__code__: + fired.append(1) + signal.raise_signal(signal.SIGTERM) + prev = sys.gettrace() + sys.settrace(tracer) + self.addCleanup(sys.settrace, prev) + return fired + + def test_a_known_probe_holder_survives_a_signal_as_the_verdict_is_given(self): rig = Rig(self) rig.halt_raises = wedge_drill.ProbeHeld(777) - real, calls = run_case.hil_lock.BoardTask.failed, [] - - def failed(task, **kw): # the interrupt lands as finish_locked gives its verdict - calls.append(kw) - if len(calls) == 1: - raise run_case.Terminated() - return real(task, **kw) - with mock.patch.object(run_case.hil_lock.BoardTask, 'failed', failed), \ - mock.patch.object(run_case, 'kill_children'): + fired = self.signal_at_the_verdict() + with mock.patch.object(run_case, 'kill_children'): rc, r = rig.run('--board', 'wch', '--delay', '0') - self.assertEqual((rc, r['boardState']), (1, 'unknown, not parked: cleanup interrupted')) + sys.settrace(None) + self.assertEqual((fired, rc), ([1], 1)) + self.assertIn('probe process 777 may still hold the probe', r['boardState']) + self.assertIn('terminated (signal) as the task ended', r['error']) event, = rig.lock.events('failed') - self.assertIn('cleanup interrupted: Terminated', event['detail']) self.assertEqual(event['receipts'], [{'unrecheckable': 'probe process 777 may still hold the probe'}]) self.assertTrue(run_case.hil_lock.resolve_restored('wch', [event], evidence='parked')) # stays open - def test_a_signal_in_the_verdict_after_a_failed_flash_keeps_both_errors(self): + def test_a_signal_as_the_verdict_is_given_after_a_failed_flash_keeps_both_errors(self): rig = Rig(self) rig.flash_errors['/fw/device/usbtest'] = 'flash timed out' - real, calls = run_case.hil_lock.BoardTask.failed, [] - - def failed(task, **kw): # the interrupt lands as finish_locked gives its verdict - calls.append(kw) - if len(calls) == 1: - raise run_case.Terminated() - return real(task, **kw) - with mock.patch.object(run_case.hil_lock.BoardTask, 'failed', failed): + fired = self.signal_at_the_verdict() + with mock.patch.object(run_case, 'kill_children'): rc, r = rig.run('--board', 'ok', '--delay', '0') - self.assertEqual(rc, 1) + sys.settrace(None) + self.assertEqual((fired, rc), ([1], 1)) self.assertIn('flash timed out', r['error']) - self.assertEqual(r['error'].count('terminated (signal) during cleanup'), 1, r['error']) + self.assertEqual(r['error'].count('terminated (signal) as the task ended'), 1, r['error']) + event, = rig.lock.events('failed') + self.assertIn('flash failed', event['detail']) def test_a_signal_during_parking(self): rig = Rig(self) diff --git a/test/hil/agentrc.json b/test/hil/agentrc.json index 150df6648f..a77a2d50c1 100644 --- a/test/hil/agentrc.json +++ b/test/hil/agentrc.json @@ -1 +1 @@ -{"url": "https://github.com/hathach/agentrc.git", "commit": "0919dcfb9ae97fbcc7c69d4b51685013f26f83f6"} +{"url": "https://github.com/hathach/agentrc.git", "commit": "f53909b61cbdfe9bcb2d7edd10bda968533f04fc"} diff --git a/test/hil/hil_flash.py b/test/hil/hil_flash.py index 2680b0f4b9..3db538f5d6 100755 --- a/test/hil/hil_flash.py +++ b/test/hil/hil_flash.py @@ -15,7 +15,6 @@ import copy import functools import json -import shlex import shutil import subprocess import tempfile @@ -142,49 +141,28 @@ class ProbeCheckFailed(RuntimeError): """probe_busy could not rule out a user of the board's probe.""" -def other_stlink_session(cmd: str, uid: str) -> bool: - """Whether a probe user's command line is an STM32_Programmer_CLI selecting only ST-LINKs - other than `uid` by `sn=`, with no `-script` (whose file may name any probe) and no word - naming `uid`. The provider counts every running STM32_Programmer_CLI as a user of every - `stlink` probe, which refuses a board while the same run flashes a sibling's ST-LINK; the - rig has always flashed ST-LINK boards concurrently.""" - argv, uid = shlex.split(cmd), uid.casefold() - if not argv or os.path.basename(argv[0]) != 'STM32_Programmer_CLI': - return False - words = [w.casefold() for w in argv[1:]] - return (any(w.startswith('sn=') for w in words) and '-script' not in words - and not any(uid in w for w in words)) - - def probe_busy(board: dict) -> list: """The board_task busy check of every HIL entry point and the farm check: the provider's probe_users for the board's flasher and, when it differs, its recovery flasher (same probe, another tool); [{'pid', 'cmd'}]. ProbeCheckFailed, naming the cause, when the provider is inconclusive (ProbeCheckInconclusive) or has no lookup for the flasher (ValueError, wch_uart_loader); any other exception propagates. Probe users only: a DUT-side process (a - stray testusb) is the run's recovery, never a refusal, and for an `stlink` entry neither is - another ST-LINK's STM32_Programmer_CLI session (other_stlink_session).""" + stray testusb) is the run's recovery, never a refusal.""" provider, users = hil_util.provider(), {} try: for f in {(f['name'], f.get('uid')): f for f in (board['flasher'], recover_flasher(board))}.values(): - users.update((u['pid'], u) for u in provider.probe_users(f) - if not (f['name'] == 'stlink' and other_stlink_session(u['cmd'], f.get('uid') or ''))) + users.update((u['pid'], u) for u in provider.probe_users(f)) except (provider.ProbeCheckInconclusive, ValueError) as e: raise ProbeCheckFailed(f'{type(e).__name__}: {e}') from e return sorted(users.values(), key=lambda u: u['pid']) -def users_text(users) -> str: - """probe_busy's users for a refusal.""" - return ', '.join(f'pid {u["pid"]} ({u["cmd"]:.120})' for u in users) - - def busy_refusal(e) -> str | None: """Why a board task's busy check refused admission (hil_lock.BoardBusy or ProbeCheckFailed), or None for any other refusal.""" from helper import hil_lock # agentrc's, loaded on first use like the provider if isinstance(e, hil_lock.BoardBusy): - return f'probe in use by {users_text(e.users)}' + return f'probe in use by {hil_lock.users_text(e.users)}' if isinstance(e, ProbeCheckFailed): return f'probe check: {e}' return None diff --git a/test/hil/hil_test.py b/test/hil/hil_test.py index 69ca0caee4..9dab11df3f 100755 --- a/test/hil/hil_test.py +++ b/test/hil/hil_test.py @@ -2073,20 +2073,16 @@ def test_board(board: Board) -> tuple: board_wedged = '' board_pci = None # protected for every flasher: a worker killed mid-task leaves its record for the next take to log - task = hil_lock.board_task(lock, hil_lock.CI_REASON, busy=lambda: hil_flash.probe_busy(board), - allow_bypass=True) + parked, unrestored = [], {} # the verdict's ledger: the final park's success, why the board is not restored + task = hil_lock.board_task(lock, hil_lock.CI_REASON, busy=lambda: hil_flash.probe_busy(board), allow_bypass=True, + verdict=lambda task, exc: _give_verdict(task, board, parked, unrestored.get('why', ''), + exc)) entered = False try: with task: entered = True previous_cleanup = previous_cleanup_text(name, task.cleanup_failures) - parked = [] # the final park's success, kept for a battery that raises after it - try: - err_count, failed_tests, board_wide_fail, rows, unrestored = _board_battery(board, parked) - except BaseException as e: - _verdict(task, board, parked, exc=e) - raise - _verdict(task, board, parked, unrestored) + err_count, failed_tests, board_wide_fail, rows, unrestored['why'] = _board_battery(board, parked) except BaseException as e: if not entered and isinstance(e, Exception): return admission_refused(name, task, e) @@ -2110,43 +2106,20 @@ def test_board(board: Board) -> tuple: None)) err_count += 1 board_wide_fail = True - elif unrestored: - log_line(f'{name:25} board not restored ({unrestored}): failed cleanup logged; {ending}') + elif unrestored['why']: + log_line(f'{name:25} board not restored ({unrestored["why"]}): failed cleanup logged; {ending}') if previous_cleanup and rows: rows[0][1][hil_report.PREVIOUS_CLEANUP_CELL] = previous_cleanup return (name, err_count, [] if board_wide_fail else sorted(set(failed_tests)), rows, board_pci) -def _verdict(task, board: Board, parked: list, unrestored: str = '', exc: BaseException | None = None) -> None: - """_give_verdict under the provider's InterruptHold, so a SIGINT landing before the verdict is - stored is replayed after it, never leaving the task to end evidence-free. One landing before the - hold went in gave nothing yet: it is raised once the verdict has been given.""" - interrupted = None - while True: - try: - hold = hil_util.provider().hil_process.InterruptHold() - except Exception: - hold = None # no hold to be had: the verdict is still given, unprotected - except BaseException as e: - interrupted = interrupted or e - continue - break - try: - _give_verdict(task, board, parked, unrestored, exc) - finally: - if hold is not None: - hold.release() - if interrupted is not None: - raise interrupted - - def _give_verdict(task, board: Board, parked: list, unrestored: str, exc: BaseException | None) -> None: - """The battery's cleanup verdict, its last act under the lock (the HIL contract's Reservation). + """The battery's cleanup verdict, the board task's collector (the HIL contract's Reservation). A battery that raised `exc` is restored when its final park still succeeded (the run itself stays aborted by `exc`), failed with unrecheckable evidence for an openocd_esp interrupt that may have landed after the provider returned a pending session but before hil_flash stored its - receipt, and otherwise given none, so the task ends failed naming `exc`.""" + receipt, and otherwise failed, the task naming `exc` after its detail.""" name = board['name'] if pending := cleanup_pending(name): task.failed(detail=pending, **pending_evidence(name, pending)) @@ -2156,6 +2129,8 @@ def _give_verdict(task, board: Board, parked: list, unrestored: str, exc: BaseEx elif board['flasher']['name'].lower() == 'openocd_esp' and not isinstance(exc, Exception): missing = 'openocd_esp interrupted; cleanup unproven, receipt missing' task.failed(detail=missing, receipts=[{'unrecheckable': missing}]) + else: + task.failed(detail='board battery aborted') # board_task names `exc` after it elif unrestored: task.failed(detail=f'board not restored: {unrestored}') elif skip_flash: diff --git a/test/hil/test/test_hil_farm_check.py b/test/hil/test/test_hil_farm_check.py index f6768cd0c9..1ee5df3e5a 100644 --- a/test/hil/test/test_hil_farm_check.py +++ b/test/hil/test/test_hil_farm_check.py @@ -298,6 +298,7 @@ def setUp(self): patch(self, hil_lock, 'BOARD_LOCK_DIR', str(self.d / 'locks')) patch(self, eng, 'RECHECK_WAIT', 0) patch(self, farm_profile, 'scan_usb', lambda: {'1-1': {'serial': 'p', 'vidpid': '0483:374b'}}) + patch(self, hil_flash, 'probe_busy', lambda board: []) # the engine's busy check: never this host's /proc def roster(self, board): self.cfg.write_text(json.dumps({'boards': [board]})) diff --git a/test/hil/test/test_hil_flash.py b/test/hil/test/test_hil_flash.py index 4a5fab9f5f..edefae74cd 100644 --- a/test/hil/test/test_hil_flash.py +++ b/test/hil/test/test_hil_flash.py @@ -123,26 +123,10 @@ def test_probe_busy_asks_for_each_entry_of_the_probe_once(self): got = hil_flash.probe_busy(board) self.assertEqual(asked, [BOARDS['jlink'], {'name': 'openocd', 'args': '', 'uid': 'S1'}]) self.assertEqual(got, [{'pid': 3, 'cmd': 'gdb'}, {'pid': 9, 'cmd': 'JLinkExe -USB S1'}]) - self.assertEqual(hil_flash.users_text(got), 'pid 3 (gdb), pid 9 (JLinkExe -USB S1)') asked.clear() hil_flash.probe_busy({'name': 'b', 'flasher': dict(BOARDS['jlink'])}) self.assertEqual(asked, [BOARDS['jlink']], 'no recovery entry: the primary alone, once') - def test_probe_busy_ignores_another_st_links_programmer_session(self): - # the provider counts every STM32_Programmer_CLI as a user of every stlink probe - cli = 'STM32_Programmer_CLI --connect port=swd ' - users = [{'pid': 1, 'cmd': cli + 'sn=OTHER --write fw.elf --go'}, - {'pid': 2, 'cmd': cli + 'SN=s1 --rst'}, - {'pid': 3, 'cmd': 'STM32_Programmer_CLI -script /tmp/s1.prg'}, - {'pid': 4, 'cmd': cli + 'sn=OTHER -script /tmp/x.prg'}, - {'pid': 5, 'cmd': cli + '--write fw.elf'}, - {'pid': 6, 'cmd': cli + 'sn=OTHER --write cmake-build-S1/fw.elf'}, - {'pid': 7, 'cmd': 'timeout 9 ' + cli + 'sn=OTHER'}] - self.provider.probe_users = lambda f: users - self.assertEqual([u['pid'] for u in hil_flash.probe_busy(self.board('stlink'))], [2, 3, 4, 5, 6, 7]) - board = {'name': 'b', 'flasher': {'name': 'openocd', 'uid': 'S1', 'args': '-f interface/stlink.cfg'}} - self.assertEqual(len(hil_flash.probe_busy(board)), len(users), 'only the stlink entry is filtered') - def test_probe_busy_refuses_only_what_the_provider_cannot_decide(self): board = {'name': 'b', 'flasher': dict(BOARDS['jlink'])} for raised in (self.provider.real.ProbeCheckInconclusive('/proc may hide'), ValueError('no probe lookup')): diff --git a/test/hil/test/test_hil_lock.py b/test/hil/test/test_hil_lock.py index 9c788239e1..7652715a2c 100644 --- a/test/hil/test/test_hil_lock.py +++ b/test/hil/test/test_hil_lock.py @@ -518,22 +518,19 @@ def failing_test(board): def test_an_interrupt_as_the_verdict_starts_still_logs_the_pending_receipts(self): self.run_interrupted_verdict() - def test_an_interrupt_before_the_verdicts_hold_still_logs_the_pending_receipts(self): - process = hil_util.provider().hil_process - hold, verdict, calls = process.InterruptHold, hil_test._verdict, [] + def test_an_interrupt_as_the_collector_is_called_still_logs_the_pending_receipts(self): + fired = [] - def late_hold(): - calls.append(1) - if len(calls) == 1: - raise KeyboardInterrupt - return hold() - - def verdict_with_late_hold(*args, **kwargs): # the task's own holds stay real - with mock.patch.object(process, 'InterruptHold', late_hold): - return verdict(*args, **kwargs) - patch(self, hil_test, '_verdict', verdict_with_late_hold) + def tracer(frame, event, arg): # a real SIGINT as BoardTask calls _give_verdict, its collector + if not fired and event == 'call' and frame.f_code is hil_test._give_verdict.__code__: + fired.append(1) + signal.raise_signal(signal.SIGINT) + prev = sys.gettrace() + sys.settrace(tracer) + self.addCleanup(sys.settrace, prev) self.run_interrupted_verdict() - self.assertEqual(len(calls), 2) + sys.settrace(prev) + self.assertEqual(fired, [1]) def test_no_later_session_starts_on_the_board(self): self.provider(self.op('pending')) @@ -579,8 +576,10 @@ def test_a_log_write_failure_still_releases_and_reports_the_error(self): self.assertIn('failure NOT logged', cell) self.assertIn('cleanup log not written', cell) self.assertIn('log is read-only', cell) - self.assertEqual(hil_lock.record_state(BOARD)[0], 'empty') - hil_lock.release_board_lock(hil_lock.take_board_lock(BOARD, 'peer')) + self.assertEqual(hil_lock.record_state(BOARD)[0], 'record') # kept, its only evidence: the next take logs it + fh = hil_lock.take_board_lock(BOARD, 'peer') + self.assertEqual(fh.cleanup_failures[-1]['how'], 'found-left') + hil_lock.release_board_lock(fh) def test_a_later_run_reports_the_latest_failure_and_counts_other_open_ones(self): first = hil_lock.log_cleanup_failure(BOARD, 'earlier', detail='old session', retained=[self.RECEIPT]) @@ -845,7 +844,7 @@ def test_an_interrupt_fails_the_cleanup_and_a_later_park_resolves_it(self): hil_test.test_board(self.board) failure, = self.events('failed') self.assertEqual((failure['how'], failure['receipts']), ('ended-failed', [])) - self.assertIn('ended without a cleanup verdict: KeyboardInterrupt', failure['detail']) + self.assertEqual(failure['detail'], 'board battery aborted; then KeyboardInterrupt') self.assertIn('lock released', self.log[-1]) self.test = (0, 'pass', None) _, err, _, rows, _ = hil_test.test_board(self.board) From 9a9294181311e0e3cebf748329bffb56847e84fa Mon Sep 17 00:00:00 2001 From: hathach Date: Thu, 12 Nov 2026 11:34:14 +0700 Subject: [PATCH 14/16] hil: bound the busy refusal's user list and keep test_board's unrestored a plain string --- test/hil/hil_flash.py | 2 +- test/hil/hil_test.py | 11 +++++------ test/hil/test/test_hil_lock.py | 5 +++++ 3 files changed, 11 insertions(+), 7 deletions(-) diff --git a/test/hil/hil_flash.py b/test/hil/hil_flash.py index 3db538f5d6..cffd5ea7ff 100755 --- a/test/hil/hil_flash.py +++ b/test/hil/hil_flash.py @@ -162,7 +162,7 @@ def busy_refusal(e) -> str | None: or None for any other refusal.""" from helper import hil_lock # agentrc's, loaded on first use like the provider if isinstance(e, hil_lock.BoardBusy): - return f'probe in use by {hil_lock.users_text(e.users)}' + return f'probe in use by {hil_lock.users_text(e.users):.500}' if isinstance(e, ProbeCheckFailed): return f'probe check: {e}' return None diff --git a/test/hil/hil_test.py b/test/hil/hil_test.py index 9dab11df3f..306be5fab2 100755 --- a/test/hil/hil_test.py +++ b/test/hil/hil_test.py @@ -2073,16 +2073,15 @@ def test_board(board: Board) -> tuple: board_wedged = '' board_pci = None # protected for every flasher: a worker killed mid-task leaves its record for the next take to log - parked, unrestored = [], {} # the verdict's ledger: the final park's success, why the board is not restored + parked, unrestored = [], '' # the verdict's ledger: the final park's success, why the board is not restored task = hil_lock.board_task(lock, hil_lock.CI_REASON, busy=lambda: hil_flash.probe_busy(board), allow_bypass=True, - verdict=lambda task, exc: _give_verdict(task, board, parked, unrestored.get('why', ''), - exc)) + verdict=lambda task, exc: _give_verdict(task, board, parked, unrestored, exc)) entered = False try: with task: entered = True previous_cleanup = previous_cleanup_text(name, task.cleanup_failures) - err_count, failed_tests, board_wide_fail, rows, unrestored['why'] = _board_battery(board, parked) + err_count, failed_tests, board_wide_fail, rows, unrestored = _board_battery(board, parked) except BaseException as e: if not entered and isinstance(e, Exception): return admission_refused(name, task, e) @@ -2106,8 +2105,8 @@ def test_board(board: Board) -> tuple: None)) err_count += 1 board_wide_fail = True - elif unrestored['why']: - log_line(f'{name:25} board not restored ({unrestored["why"]}): failed cleanup logged; {ending}') + elif unrestored: + log_line(f'{name:25} board not restored ({unrestored}): failed cleanup logged; {ending}') if previous_cleanup and rows: rows[0][1][hil_report.PREVIOUS_CLEANUP_CELL] = previous_cleanup return (name, err_count, [] if board_wide_fail else sorted(set(failed_tests)), diff --git a/test/hil/test/test_hil_lock.py b/test/hil/test/test_hil_lock.py index 7652715a2c..6c62c6dadd 100644 --- a/test/hil/test/test_hil_lock.py +++ b/test/hil/test/test_hil_lock.py @@ -730,6 +730,11 @@ def test_a_live_probe_user_refuses_the_board(self): f'(JLinkExe -USB 000000123)') self.assertEqual(hil_test.hil_report.cell_state(cell), 'fail') + def test_a_long_probe_user_list_is_bounded(self): + self.users = [{'pid': p, 'cmd': 'STM32_Programmer_CLI ' + 'x' * 300} for p in (1, 2, 3)] + cell = self.refusal()[hil_test.hil_report.PROBE_BUSY_CELL] + self.assertEqual(len(cell), len(f'{hil_test.hil_report.REPORT_CELL["fail"]} probe in use by ') + 500) + def test_an_inconclusive_check_refuses_too(self): self.users = hil_flash.ProbeCheckFailed('RuntimeError: /proc may hide other users\' processes') cell = self.refusal()[hil_test.hil_report.PROBE_BUSY_CELL] From c3a3f6272a4412d1392b4ed33f3ca46bb535c40b Mon Sep 17 00:00:00 2001 From: hathach Date: Thu, 12 Nov 2026 11:41:55 +0700 Subject: [PATCH 15/16] hil: pin agentrc ac8a8f65, whose ST-LINK exemption covers the recovery entry --- .claude/skills/hil-contract/SKILL.md | 2 +- test/hil/agentrc.json | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/.claude/skills/hil-contract/SKILL.md b/.claude/skills/hil-contract/SKILL.md index dfcfea4afd..e8d3c61452 100644 --- a/.claude/skills/hil-contract/SKILL.md +++ b/.claude/skills/hil-contract/SKILL.md @@ -188,7 +188,7 @@ A local `hil_test.py` run has no done record; wait for its completion notificati The `ci` rig also hosts a GitHub Actions runner that flashes boards and runs HIL as part of CI, never stopped (`hil` Board locks). Each board's lock is taken through `test/hil/helper/hil_lock.py`, under its lock name: agentrc's registry `name` for a board with `probe`, whatever this roster calls it, else its roster `name` (`hil_util.lock_name`). `python3 "${AGENTRC_DIR:-$HOME/.claude}"/skills/hil/scripts/hil_boards.py lock ` prints it; the helper's named `hold` and `release` take lock names, never roster names. The harness's shared scripts (the lock mechanics, the bounded sysfs reads and bus scan of `test/hil/helper/usb_observe.py`, the RTT console, and the `hil` skill's Flashers: the bounded command runner behind `test/hil/helper/hil_util.py` and the per-flasher commands and pyOCD launcher behind `test/hil/hil_flash.py`) are loaded by `test/hil/helper/agentrc.py` through agentrc's `hil_load` (one module per file per process) from the agentrc it selects: a `.agentrc/` that `hil_remote.py` staged at the tree's root, else in CI (`CI` or `GITHUB_ACTIONS` true) the commit `test/hil/agentrc.json` pins, fetched into `lib/agentrc` by `python3 test/hil/helper/agentrc.py fetch`, else the installed agentrc, `"${AGENTRC_DIR:-$HOME/.claude}"`, never fetched; `python3 test/hil/helper/agentrc.py check` prints which. Missing, off the pin, of another `agentrc_source.py` API, unlike its staged manifest or lacking a file of its scripts' closure, every HIL entry point refuses before any board access. -`hil_test.py`, `run_case.py` and `wedge_drill.py` take each board through agentrc's `hil_lock.board_task` (`hil` Board locks), protected for every flasher: the record is marked `cleanupOwed`, its group the board alone, so a task killed before its end leaves it for the next take to log found-left. Under the taken lock, before any hardware access, the busy check (`probe_busy` in `test/hil/hil_flash.py`: agentrc's `hil_flash.probe_users` for the board's flasher and its recovery flasher) refuses the board when it names a live process using the probe, or when it cannot rule one out (`/proc` may hide other users' processes, a read failed, or the flasher has no probe lookup, as `wch_uart_loader`); the lock is then released with nothing logged. The check is a snapshot of probe users, never proof the probe is idle: it misses an `STM32_Programmer_CLI -script` session, counts none that selects another ST-LINK by `sn=` (whose discovery opens this one too), and misses a GDB client attached to its server, a process that opens the probe after it, and every DUT-side process; a stray `testusb` on the DUT never refuses admission (Recovery sweeps it inside the run). The farm check's profile exposes the same check as its `busy(board)` hook, which engines older than that hook ignore. Each task ends on one cleanup verdict: `hil_test.py`'s and `wedge_drill.py`'s come from their verdict collector (`board_task(..., verdict=)`), which the task calls at its end under its own interrupt hold, and `run_case.py`'s is its last act under the lock: +`hil_test.py`, `run_case.py` and `wedge_drill.py` take each board through agentrc's `hil_lock.board_task` (`hil` Board locks), protected for every flasher: the record is marked `cleanupOwed`, its group the board alone, so a task killed before its end leaves it for the next take to log found-left. Under the taken lock, before any hardware access, the busy check (`probe_busy` in `test/hil/hil_flash.py`: agentrc's `hil_flash.probe_users` for the board's flasher and its recovery flasher) refuses the board when it names a live process using the probe, or when it cannot rule one out (`/proc` may hide other users' processes, a read failed, or the flasher has no probe lookup, as `wch_uart_loader`); the lock is then released with nothing logged. The check is a snapshot of probe users, never proof the probe is idle: on an ST-LINK board (either entry) it counts every `STM32_Programmer_CLI` but one selecting only another ST-LINK by `sn=` (whose discovery opens this one too), and it misses a GDB client attached to its server, a process that opens the probe after it, and every DUT-side process; a stray `testusb` on the DUT never refuses admission (Recovery sweeps it inside the run). The farm check's profile exposes the same check as its `busy(board)` hook, which engines older than that hook ignore. Each task ends on one cleanup verdict: `hil_test.py`'s and `wedge_drill.py`'s come from their verdict collector (`board_task(..., verdict=)`), which the task calls at its end under its own interrupt hold, and `run_case.py`'s is its last act under the lock: - `hil_test.py`: restored when the final `device/board_test` park succeeded, a failed test included, and also when an interrupt or exception follows that park (the run still aborts); clean under `--skip-flash` once every operation ended; failed for a pending provider cleanup (below), a wedged board with or without `--skip-flash`, a park that failed or had no firmware, a SystemView capture flash left unparked, or an exception or interrupt before the park. - `run_case.py`: restored when `--after park` parked; clean for `--after leave` with a complete, unwedged verdict, or a peer found under the lock; failed for a failed flash or park, no enumeration, an incomplete verdict, a wedge, an exception or a SIGTERM. diff --git a/test/hil/agentrc.json b/test/hil/agentrc.json index a77a2d50c1..8403652e2b 100644 --- a/test/hil/agentrc.json +++ b/test/hil/agentrc.json @@ -1 +1 @@ -{"url": "https://github.com/hathach/agentrc.git", "commit": "f53909b61cbdfe9bcb2d7edd10bda968533f04fc"} +{"url": "https://github.com/hathach/agentrc.git", "commit": "ac8a8f6503bd10fda96a49b44cd9bbaa8d5a1452"} From 3330b956939c96dfac46ab94e6f5698da9a5e050 Mon Sep 17 00:00:00 2001 From: hathach Date: Thu, 12 Nov 2026 14:16:14 +0700 Subject: [PATCH 16/16] hil: pin agentrc #543's merge commit --- test/hil/agentrc.json | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/hil/agentrc.json b/test/hil/agentrc.json index 8403652e2b..7be8a50b92 100644 --- a/test/hil/agentrc.json +++ b/test/hil/agentrc.json @@ -1 +1 @@ -{"url": "https://github.com/hathach/agentrc.git", "commit": "ac8a8f6503bd10fda96a49b44cd9bbaa8d5a1452"} +{"url": "https://github.com/hathach/agentrc.git", "commit": "3304c248e86d4c925a3649c547987982b2801b52"}