diff options
| author | hathach <[email protected]> | 2026-08-14 01:08:50 +0700 |
|---|---|---|
| committer | hathach <[email protected]> | 2026-08-18 12:19:09 +0700 |
| commit | f822f69a9871b2115c5213889d70411da66ca1b1 (patch) | |
| tree | e8d1ddba4dbed71112af7f216aa2e677321a8c1c /docs | |
| parent | 3963a1b70a572132aced1c1a0033e1c8249a0c7e (diff) | |
skills, docs: rewrite USB recovery from the live incidents
Two things the rig taught us that the old guidance got wrong.
A usbfs ioctl wedged in D state cannot be freed on a running kernel. It holds
the device lock, so usb_disconnect() blocks behind it; reboot(2) walks
device_shutdown() and takes the same lock, so every userspace reboot stalls too.
Only sysrq b (emergency_restart, which skips device_shutdown) or hypervisor
action clears it -- all cited to the kernel source. The recovery ladder is
generic across rigs now (ci.lan, hifiphile, a bench PC) and ends at hypervisor
escalation only where host access exists. Two claims are corrected outright:
JLinkExe is NOT convoy-safe, and a park-flash cannot free a device-lock owner.
The hil skill's banner list is what an operator agent matches a report against,
so it enumerates the banners that actually exist, including the D-state note --
which is explicitly NOT a wedge, since a healthy in-flight testusb is
uninterruptible for most of every case and a concurrent CI battery would
otherwise turn a clean run red.
Diffstat (limited to 'docs')
| -rw-r--r-- | docs/superpowers/specs/2026-07-30-hil-usbtest-fleet-wedge-design.md | 236 |
1 files changed, 236 insertions, 0 deletions
diff --git a/docs/superpowers/specs/2026-07-30-hil-usbtest-fleet-wedge-design.md b/docs/superpowers/specs/2026-07-30-hil-usbtest-fleet-wedge-design.md new file mode 100644 index 000000000..3ed0c1519 --- /dev/null +++ b/docs/superpowers/specs/2026-07-30-hil-usbtest-fleet-wedge-design.md @@ -0,0 +1,236 @@ +# HIL fleet-wedge containment + +Date: 2026-07-30 +Status: implemented, then superseded in part — addendum last checked 2026-08-12 +against the shipped code; where they disagree the CODE and the usb-kernel-recover +skill win, never this document. + +- **Pool guard.** A single constant, not the flat 4200s below and not a derivation: + `POOL_TIMEOUT = pos_int_env('HIL_POOL_TIMEOUT', 3600)`. A per-controller model briefly + lived here and was removed -- it under-modelled the flash phase and could INVERT + (adding a usbtest board lowered the guard, because the derived value fell below the + baseline it was meant to raise). The guard's only job is to stop a wedged pool short + of the job ceiling so the report still gets written; predicting a healthy run's + duration is a different problem. `pos_int_env` warns only on a non-integer or a value + <= 0: there is NO upper clamp and no warning above any threshold, so a pin larger than + a job ceiling silently restores the inversion this work removed. +- **Job ceilings.** 90/90/120 min (build.yml), not 60/60/90 and not the 85/115 below. + They must clear the 3600s guard plus the pre-pool checkout/artifact merge and the + post-guard sweep and report upload. No job pins `HIL_POOL_TIMEOUT`. +- **Battery budgets.** `USBTEST_BATTERY_BUDGET` 260s, `USBTEST_RECOVERY_BUDGET` 250s. + The 200s-with-a-197s-floor derivation recorded here was never shipped; the floor + assertion was removed with it. +- **HUNG recovery.** Reflash of the DUT through its roster flasher + (`usbtest.py --recover-board/--recover-fw`), not the root-cycle-first recovery in + section 1d — replaced after the 2026-08-11 ppps measurement (uhubctl never cuts + VBUS; root-cycle is probe-only). Since 2026-08-12 the reflash is SKIPPED + when `hil_flash.convoy_safe(board['flasher'])` is false (usbtest.py:675): the flasher + would enumerate by opening usbfs nodes, block on the same convoy, and become a second + stray rather than clear the first. A holder that owns the device lock inside a driver + ioctl is terminal either way -- a reflash only produces a disconnect, and + `usb_disconnect()` needs that same lock -- and that state needs a reboot. + +Step 0 done — the host was rebooted 2026-07-30 14:11 and the rig +came back clean. The device that triggered this incident was removed from the rig, so +only the containment work remains relevant. +Rig: `ci.lan` (Proxmox guest on `pve.lan`) + +## Problem + +On 2026-07-29/30 every board in the `ci.lan` usbtest fleet failed, `openocd` processes +landed in uninterruptible sleep, and no subsequent HIL run could start. Two GitHub +Actions runs were stranded: `30484641269` sat `in_progress` for over eight hours +(past GitHub's own 360-minute default), and `30485082274` sat `queued` behind it from +2026-07-29 19:35 UTC onward. Both report directories were written empty. + +A reboot of the `ci` guest at 10:48 did not clear the condition: the same kernel state +re-formed at 10:52:23. + +## Root cause + +Five layers, each independently observable. + +### 1. A permanently wedged hub worker holds a root-hub device lock + +A device that repeatedly re-asserts connect while failing to enumerate keeps +`hub_event()` busy, and `hub_event()` holds `usb_lock_device(hdev)` on its hub for its +whole run (hub.c:5896/5989). The `usb_hub_wq` worker sits in `hub_port_reset`, so that +hub's `device_lock` is effectively never released: + +``` +kworker/14:6+usb_hub_wq (state D, 400+ s) + msleep+0x2b + hub_port_reset+0x1a4 [usbcore] + hub_event+0x727 [usbcore] +``` + +`usb usbN-portM: Cannot enable. Maybe the USB cable is bad?` is logged every four seconds +for as long as it lasts. + +Verified against hub.c v6.12.96 rather than inferred: the kernel does **not** retry +without bound, and root and downstream ports are bounded identically — +`hub_port_reset()` tries `PORT_RESET_TRIES` then logs that message (hub.c:3149), +`hub_port_connect()` wraps it in `PORT_INIT_TRIES` = 4 and disables the port on give-up +(hub.c:5455/5619). A count in the thousands is therefore that many separate connect +events, not one runaway loop, and it indicts the device rather than the port. + +### 2. A parked board storms the second controller + +`ra6m5_ek` (`test/hil/tinyusb.json`, uid `8419032D32363657364EF4622D294B4E`, at +`13-3.3`) runs dfu firmware (`cafe:400b`) and re-enumerates every 1-2 seconds +continuously, wrapping the entire bus-13 devnum space (`...120 -> 127 -> 4 -> 6 -> 10`). +This is standing `hub_event` and Address-Device pressure on controller `03:00.0`, +concurrent with parallel usbtest batteries on the same silicon. + +The board is already listed in `boards-skip`, which is precisely why it storms: +`boards-skip` stops testing a board but never parks it, so it keeps running whatever +firmware it last received. Park-flash only runs as teardown of a board that actually +executed tests. + +### 3. The kernel `usbtest` control-queue case waits without a timeout + +`test_ctrl_queue` blocks on an untimed `wait_for_completion()` while `usbdev_ioctl` +holds the DUT's `device_lock`: + +``` +wait_for_completion+0x8a <- no _timeout variant +test_ctrl_queue+0x4ab [usbtest] +usbtest_do_ioctl+0x501 [usbtest] +usbdev_ioctl+0x6b8 [usbcore] +``` + +`--timeout 60` in `test/hil/usbtest.py` is a subprocess timeout only. `SIGKILL` is not +delivered to a task in uninterruptible sleep. `usbtest.py` already recognises this and +reports `HUNG`, then calls `usb_recover.sh root-cycle`. + +### 4. openocd inherits the convoy and the whole fleet dies + +Once a device lock is stuck, `port_event()` takes a child device's lock to warm-reset +it and blocks while still holding its hub's lock. Any later +`open("/dev/bus/usb/BBB/DDD")` against such a device blocks uninterruptibly: + +``` +usbdev_open+0xdc [usbcore] -> __mutex_lock +chrdev_open -> do_sys_openat2 -> __x64_sys_openat +``` + +That is the state of the three `openocd` processes at 04:16:51 (pids 207921, 207987, +208034) — the flasher, unkillable. Because one controller carries two buses, a single +convoy takes out every board on both, which is why the failure presents as the entire +fleet. + +The existing `HUNG` recovery cannot help here. A root-port VBUS cycle frees a +*device-lock* holder; it cannot free a lock held by a stuck *hub worker*, and on this +rig the cycle lands on the controller that is already wedged. + +### 5. Nothing bounds the damage, so one bad run becomes a CI outage + +- `hil-tinyusb` and `hil-tinyusb-esp` in `.github/workflows/build.yml` carry no + `timeout-minutes`. Only `hil-hfp-iar` does. +- `ci.lan` runs a single runner service, so there is one job slot. +- `test/hil/hil_test.py` bounds the pool with `POOL_TIMEOUT` (4200 s), and that guard + fires correctly — but the recovery path does not survive a D-state worker: + +```python +with Pool(processes=os.cpu_count() or 1, initializer=init_worker, initargs=initargs) as pool: + async_ret = pool.map_async(test_board, config_boards) + try: + mret = async_ret.get(timeout=POOL_TIMEOUT) + except MpTimeoutError: + pool.terminate() + pool.join() # blocks forever: a D-state worker never reaps + raise RuntimeError(f'HIL worker pool timed out after {POOL_TIMEOUT}s') +``` + +`multiprocessing` joins workers unbounded, so both `pool.terminate()` and +`pool.join()` hang, as does the `with Pool(...)` exit on the success path. Normal +`hil-tinyusb (tinyusb.json)` runs take 10-20 minutes; one recent run took 71.3 +minutes, which is the 70-minute guard firing and succeeding. The eight-hour run is the +pathological case. + +## Design + +### Step 0 — recovery (manual prerequisite) + +Power-cycle the PVE **host**, not the `ci` guest. A guest reboot is not sufficient; +hubs latch up across the PCIe reset, which the 10:48 reboot demonstrated. Nothing +below can be verified until the rig is clean. + +### Section 1 — CI containment + +**1a. Two layered timers.** An inner guard inside `hil_test.py` (`POOL_TIMEOUT`, 70 min) +that fails gracefully -- it writes a report naming the timeout and the dispatched boards, +shuts the pool down and exits -- and an outer `timeout-minutes` per rig job (85 for the +hil-tinyusb jobs; 115 for hil-hfp-iar, which also builds four boards with IAR in the same +job) as the backstop for when even exiting cannot free the runner. The ceiling must stay +ABOVE the inner guard, or GitHub kills the job before the report is written. + +> **Corrected after measurement.** An earlier revision cut the guard to 30 min on the +> reading that real runs take 9-17 min and everything longer was the old guard firing. +> That was wrong. `hil_lock.py` records 22.2/14.3/12.5/10.8 min at usbtest width 1/2/3/4, +> and raising the per-battery budget to 380s made hung boards cost more again. The 30 min +> guard then fired on 5 of the last 8 HIL job executions across both rigs, and because +> `map_async` is all-or-nothing each of those runs published a banner instead of any +> per-board result. Restored to 4200s, the value whose original rationale -- usbtest +> batteries are serialized fleet-wide, lengthening the tail -- was correct. + +**1b. Bound the pool shutdown.** Add a helper to `test/hil/hil_test.py`: + +```python +def _shutdown_pool(pool, grace=30): + """terminate() a Pool without ever blocking forever: multiprocessing joins its + workers unbounded, and a worker in uninterruptible sleep (wedged usbfs) never + reaps -- which would hold the runner's only job slot indefinitely.""" + t = threading.Thread(target=pool.terminate, daemon=True) + t.start() + t.join(grace) + return not t.is_alive() +``` + +On the `MpTimeoutError` path: write the report first, recording the boards that never +reported so the run stops producing an empty report directory; then `_shutdown_pool`; +then `os._exit(1)` if it did not return. The hard exit is the point — it is the only +way past a kernel-side unkillable child. Use the same helper for the `with Pool(...)` +exit path. + +**1c. Pre-flight rig health check.** `check_rig_health()` runs before the build and +**never aborts**. It probes `/proc` unprivileged (dmesg is restricted on the rig) for a +wedged `usb_hub_wq` worker, and reports a `/proc` too restricted to trust as its own +distinct cause rather than as a diagnosed fault. + +It is deliberately non-fatal: the rig is unattended and every remedy for a real wedge is +manual, so aborting would not fix anything -- it would discard the per-board results the +run can still collect and leave CI red until a human noticed. It emits a GitHub +`::error::` annotation and continues. The automatic containment is 1a and 1b, which bound +a stuck run and explain it without anyone touching the rig. + +**1d. Order the recovery correctly.** In `test/hil/usbtest.py`, attempt +`usb_recover.sh root-cycle` FIRST on a `HUNG` case, and only check for a wedged hub worker +*afterwards*. + +> **Corrected during implementation.** This section originally said to check for a wedged +> worker *before* the cycle and skip it on a hit. That is backwards. Our own stuck +> `testusb` holds the DUT's device lock, so any port event drives a hub worker into +> `usb_lock_device()` on it -- uninterruptible, so it reads `D` in ~100% of samples and the +> confirmation window makes the wrong verdict *more* confident, not less. Cutting VBUS is +> precisely what completes the in-flight URB, returns the ioctl and frees that worker, so +> gating on that signature would suppress the recovery in the exact ordering it exists for. +> A worker still wedged after the cycle is the genuinely unrecoverable case, and that is +> what the code now reports. + +## Verification + +- Unit-test `shutdown_pool` and the `hil_health` detectors against a synthetic `/proc`. + A real wedge cannot be manufactured on demand, so they are tested against fabricated + inputs rather than live hardware. +- Confirm the detectors flag a genuinely wedged rig, and return clean on a healthy one. +- One clean full-fleet `hil_test.py` run to prove `check_rig_health` does not + false-abort. + +## Out of scope + +- **`ra6m5_ek` park and its dfu reset loop.** Dropped by decision. Consequence: the + layer-2 devnum storm remains as standing pressure on controller `03:00.0`. Unplugging + the board or flashing `board_test` by hand resolves it without any code change. +- **An unattended PVE watchdog** that detects the wedge and power-cycles the host. + Declined: more moving parts, and it can cut a running CI job. |
