diff --git a/.claude/skills/hil-contract/SKILL.md b/.claude/skills/hil-contract/SKILL.md index b63dbcd88e..e8d3c61452 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: 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: -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 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. + +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..1f90120905 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 @@ -25,11 +32,14 @@ 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. +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. """ import argparse import json @@ -327,6 +337,12 @@ 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.""" + 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): cwd = os.getcwd() # before the lock: nothing after it may fail outside the cleanup try: @@ -337,60 +353,100 @@ 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 + found(task) + code, error = run_task(task, board, fw, park_fw, tests, args, report) except Terminated: - 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}') + 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') + 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}' + 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, report) + report['pass'] = report['pass'] and code == 0 + return finish(code, error) + + +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 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 +459,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..d0de66aa78 100755 --- a/.claude/skills/usbtest/scripts/wedge_drill.py +++ b/.claude/skills/usbtest/scripts/wedge_drill.py @@ -27,9 +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, a refusal's too, or a signal or exception raised as +the task ended, exits 1, its errors in "error". """ import argparse import json @@ -408,19 +415,30 @@ 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.""" - if report['boardState'] == 'flash failed': - return +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'): - # 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 + + +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(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 False + if report['boardState'] == 'flash failed': + return False if report['drill'] == 'pass': safe = True elif report['halt'].get('issued'): @@ -434,14 +452,56 @@ 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 False if report['error'].startswith('terminated'): report['boardState'] = 'not parked: terminated' # whoever signalled wants the board - return + return False 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 not err + + +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: + 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'], 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: + 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' + note_probe_holder(report) # e.g. the cleanup reset's child, past its reap + raise + return 0 if report['drill'] == 'pass' and ledger.get('parked') else 1 def main(): @@ -475,42 +535,45 @@ 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) + ledger = {} + task = hil_lock.board_task(hil_util.lock_name(board), 'wedge_drill.py', + busy=lambda: hil_flash.probe_busy(board), + verdict=lambda task, exc: drill_verdict(task, report, ledger)) + 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 + run_case.found(task) + 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' + # 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: + report['error'] = 'terminated before any hardware action' + return finish(2) + except Exception as e: + 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) - run_case.release(lock) - parked = report['boardState'] == 'parked on board_test' - return finish(0 if report['drill'] == 'pass' and parked else 1) + # published once the task ended, so its finalization counts + code, report['error'] = run_case.ended(task, code, report['error'], report) + 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..72f1cd23c2 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,126 @@ 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: solo: lock released, failure logged in', + 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'))) + 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: 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.""" @@ -404,13 +516,26 @@ 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')) 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 = [] @@ -419,7 +544,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..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 @@ -26,6 +27,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 +52,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 +133,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), @@ -159,6 +153,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]) @@ -353,6 +348,57 @@ 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; ', failed['detail']) + self.assertTrue(failed['detail'].endswith('; then Terminated'), failed['detail']) + self.assertEqual(failed['receipts'], []) + + 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) + fired = self.signal_at_the_verdict() + with mock.patch.object(run_case, 'kill_children'): + rc, r = rig.run('--board', 'wch', '--delay', '0') + 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.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_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' + fired = self.signal_at_the_verdict() + with mock.patch.object(run_case, 'kill_children'): + rc, r = rig.run('--board', 'ok', '--delay', '0') + sys.settrace(None) + self.assertEqual((fired, rc), ([1], 1)) + self.assertIn('flash timed out', 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) rig.flash_raises['/fw/device/board_test'] = KeyboardInterrupt() @@ -604,6 +650,140 @@ 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_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] + 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')], []) + + 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_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', + 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.""" @@ -620,15 +800,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/agentrc.json b/test/hil/agentrc.json index 0b36107339..7be8a50b92 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": "3304c248e86d4c925a3649c547987982b2801b52"} 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..48f7b1edb7 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,17 +695,22 @@ 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 '' + # 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}, 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()) @@ -727,9 +736,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..cffd5ea7ff 100755 --- a/test/hil/hil_flash.py +++ b/test/hil/hil_flash.py @@ -137,6 +137,37 @@ 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 (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 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 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 {hil_lock.users_text(e.users):.500}' + 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 7288a7c948..306be5fab2 100755 --- a/test/hil/hil_test.py +++ b/test/hil/hil_test.py @@ -2015,233 +2015,281 @@ 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 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, 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): + 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, hil_lock.BoardLocked): + 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 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 + 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, exc)) + 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) + 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) + if entered: + log_line(f'{name:25} ended by {type(e).__name__}: {task.describe()}') + 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') + ending = task.describe() + 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 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 _give_verdict(task, board: Board, parked: list, unrestored: str, exc: BaseException | None) -> None: + """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 failed, the task naming `exc` after its detail.""" + 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}]) + 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: + 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 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) + 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)) + + 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') + 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) + 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 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}' + 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..1ee5df3e5a 100644 --- a/test/hil/test/test_hil_farm_check.py +++ b/test/hil/test/test_hil_farm_check.py @@ -93,6 +93,14 @@ 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]) + class Roster(unittest.TestCase): def test_a_rig_host_gets_its_roster(self): got = farm_profile.roster('ci', None, args()) @@ -290,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 d1267df90b..edefae74cd 100644 --- a/test/hil/test/test_hil_flash.py +++ b/test/hil/test/test_hil_flash.py @@ -114,6 +114,44 @@ 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'}]) + 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_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; + # 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) 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..6c62c6dadd 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 @@ -12,6 +12,7 @@ import json import os import shutil +import signal import subprocess import sys import tempfile @@ -48,6 +49,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,8 +89,8 @@ 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): - raise RuntimeError('board locked: {"pid": 1}') + def held(name, *a, **kw): + 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) @@ -94,9 +102,9 @@ 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}') + 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']]) @@ -366,7 +374,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 @@ -416,7 +424,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,)) @@ -429,9 +437,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]) @@ -464,7 +473,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 @@ -480,6 +489,49 @@ 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_as_the_collector_is_called_still_logs_the_pending_receipts(self): + fired = [] + + 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() + sys.settrace(prev) + self.assertEqual(fired, [1]) + def test_no_later_session_starts_on_the_board(self): self.provider(self.op('pending')) with redirect_stdout(io.StringIO()): @@ -521,10 +573,13 @@ 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('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]) @@ -570,7 +625,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 +635,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 +688,220 @@ 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_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] + 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_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'}] + _, 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_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) + 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.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) + 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(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): + 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 + 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()) + 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..4097a903c7 100644 --- a/test/hil/test/test_hil_report.py +++ b/test/hil/test/test_hil_report.py @@ -468,6 +468,23 @@ 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_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})]) @@ -981,7 +998,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}])