diff options
Diffstat (limited to 'test/hil/hil_test.py')
| -rwxr-xr-x | test/hil/hil_test.py | 1128 |
1 files changed, 600 insertions, 528 deletions
diff --git a/test/hil/hil_test.py b/test/hil/hil_test.py index 174251343..b2b74b13c 100755 --- a/test/hil/hil_test.py +++ b/test/hil/hil_test.py @@ -44,7 +44,6 @@ import itertools import os import random import re -import select import signal import shlex import sys @@ -64,14 +63,15 @@ from multiprocessing import TimeoutError as MpTimeoutError sys.path.insert(0, os.path.dirname(os.path.abspath(__file__))) # PYTHONSAFEPATH drops it import hil_flash -from helper import hil_health, hil_lock, hil_util +import usbtest # for the recovery bounds only; hil_test runs it as a subprocess +from helper import hil_health, hil_lock, hil_report, hil_util from helper.hil_util import device_tests, dual_tests, host_test # Raw Lock/Semaphore objects in Pool initargs are inheritable only under fork # (spawn/forkserver pickle them and fail at Pool creation), so pin it against an -# interpreter default change. Windows has no fork: fall back so it still IMPORTS there. +# interpreter default change. -_mp = multiprocessing.get_context('fork') if os.name != 'nt' else multiprocessing.get_context() +_mp = multiprocessing.get_context('fork') Pool, Lock, Semaphore, Manager = _mp.Pool, _mp.Lock, _mp.Semaphore, _mp.Manager import string @@ -106,9 +106,6 @@ STATUS_OK = "\033[32mOK\033[0m" STATUS_FAILED = "\033[31mFailed\033[0m" STATUS_SKIPPED = "\033[33mSkipped\033[0m" -# Plain (non-ANSI) cell symbols for hil_report.md; a missing binary counts as skipped. -REPORT_CELL = {'pass': '✅', 'fail': '❌', 'skip': '⚪'} - class TestFail(AssertionError): """Fail a test but still surface a metric string in its report cell (e.g. usbtest's '❌ 29/30' @@ -194,10 +191,6 @@ class TestsCfg(TypedDict, total=False): dev_attached: list[AttachedDevCfg] -class BuildCfg(TypedDict, total=False): - args: list[str] - - class VariantCfg(TypedDict, total=False): name: str # build dir (cmake-build-<name>) and HIL report row flags: str # raw CFLAGS, e.g. "-DCFG_TUD_DWC2_DMA_ENABLE=1" @@ -209,8 +202,11 @@ class Board(TypedDict): uid: str tests: TestsCfg flasher: FlasherCfg - build: NotRequired[BuildCfg] + # every build knob lives here, including a board's always-on defines: a board that + # needs one carries a single variant named after itself (metro_m4_express / + # MAX3421_HOST=1), which is exactly what the `or [...]` default below synthesises variant: NotRequired[list[VariantCfg]] + logger: NotRequired[str] # "rtt": console = the debug probe's RTT channel 0, not a VCOM (rtt skill) toolchain: NotRequired[str] # CI build bucket override, e.g. "riscv-gcc" (consumed by hil_ci_set_matrix.py) @@ -225,13 +221,17 @@ class HilConfig(TypedDict): POOL_TIMEOUT = hil_util.pos_int_env('HIL_POOL_TIMEOUT', 3600) -# Headroom on top of a battery's own budget so ONE HUNG recovery (case timeout, SIGKILL -# wait, bounded reflash, settle) can finish. Only spent when cases actually time out. -USBTEST_RECOVERY_BUDGET = hil_util.pos_int_env('HIL_USBTEST_RECOVERY_BUDGET', 250) +# The post-hang recovery reserve is PER BOARD and lives in usbtest.recovery_reserve(), +# derived from the ladder that file itself declares. Reserved whole, which is what lets the +# child run the ladder straight through instead of asking "does the next step still fit?" +# before each step. It only ELAPSES when cases actually time out; a healthy battery returns +# in ~200s and never touches it. + # How long usbtest.py may keep starting new cases (--budget). The outer run_cmd timeout is -# always this PLUS the recovery headroom, never a separate literal, or lowering one eats -# the reserve the recovery needs. 0 is refused (usbtest.py reads it as "no limit"); the -# margin over a healthy battery (~200s) keeps contention from becoming BUDGET entries. +# always this PLUS the overshoot PLUS the recovery reserve when one can run, never a +# separate literal, or lowering one eats the room the other needs. 0 is refused (usbtest.py +# reads it as "no limit"); the margin over a healthy battery (~200s) keeps contention from +# becoming BUDGET entries. USBTEST_BATTERY_BUDGET = hil_util.pos_int_env('HIL_USBTEST_BATTERY_BUDGET', 260) # The battery checks its budget BEFORE dispatching a case, so it can overshoot by one @@ -239,10 +239,13 @@ USBTEST_BATTERY_BUDGET = hil_util.pos_int_env('HIL_USBTEST_BATTERY_BUDGET', 260) # as it goes to print its JSON, turning ~29 real per-case verdicts into "usbtest did not # run" and re-paying the whole battery on retry. # Worst case, from usbtest.py: --timeout 60 (the case) + 5s post-SIGKILL reap + -# dmesg_tail(), which is bounded by HELPER_TIMEOUT=30 and runs on BOTH the FAIL and HUNG -# timeout paths = 95s. 120 leaves a margin; 75 (my first estimate, taken before checking -# dmesg_tail) was 20s SHORT and would have killed the battery mid-print. +# dmesg_tail(), bounded by HELPER_TIMEOUT=30 and run on BOTH the FAIL and HUNG timeout +# paths = 95s. 120 leaves a margin. Re-derive it if any of those three moves -- dmesg_tail +# is the one easily missed, and without it the estimate lands 20s short. USBTEST_OVERSHOOT = 120 +# Named, not a literal, so the unit tests can zero it: every test that drives +# test_device_usbtest against a fake rig otherwise pays a real 3s (ten of them, 30s a run). +USBTEST_SETTLE = 3 SERIAL_READ_TIMEOUT = hil_util.pos_float_env('HIL_SERIAL_READ_TIMEOUT', 5) SERIAL_WRITE_TIMEOUT = hil_util.pos_float_env('HIL_SERIAL_WRITE_TIMEOUT', 10) @@ -294,6 +297,25 @@ def open_serial_dev(port: str): return ser +def open_board_console(board: Board): + """The board's log console: its probe's VCOM, or RTT when the probe has none. + + Both ends expose the same read/in_waiting/write/close surface, so the tests read one + the same way they read the other.""" + if board.get('logger') == 'rtt': + # JlinkRtt speaks JLinkExe only; an openocd/stlink flasher would yield + # `-device ''` and fail 15 s later with a misleading port error. The OpenOCD + # RTT route is validated manually on native probes but has no harness backend + # yet (rtt skill; followup doc) — and never point it at ea4088's LPC-Link2 + # (measured: knocks that probe off USB; other J-Link-OB probes untested) + assert board['flasher']['name'].lower() == 'jlink', \ + f'{board["name"]}: "logger": "rtt" needs a jlink flasher, not {board["flasher"]["name"]}' + return hil_util.JlinkRtt(board) + ser = open_serial_dev(hil_util.get_serial_dev(board['flasher']["uid"], None, None, 0)) + ser.timeout = 0.1 + return ser + + def serial_write_all(ser: serial.Serial, data: bytes): # write_timeout is a deadline for the whole call. A timeout means the device stopped # draining, and it is fatal: pyserial loses the partial-write count on raise, so @@ -302,8 +324,19 @@ def serial_write_all(ser: serial.Serial, data: bytes): ser.write(data) except serial.SerialTimeoutException: raise AssertionError(f'Serial write timeout after {SERIAL_WRITE_TIMEOUT:.1f}s') + except hil_util.RttError as e: + # the RTT console's failure contract (stall/closed/peer death): same + # drain-stopped meaning as the serial timeout -- a test failure, not a harness + # crash. Deliberately NOT bare RuntimeError: NotImplementedError and CPython's + # own 'dictionary changed size during iteration' are RuntimeErrors too, and a + # harness bug must not be reported as this board misbehaving. + raise AssertionError(f'Console write failed: {e}') +# J-Link Commander's telnet greeting: never target output (defined with the console +# in tools/rtt.py; hil_pool_check strips it through the same object) +RTT_BANNER_RE = hil_util.RTT_BANNER_RE + LP_OPEN_TIMEOUT = 5 # bound on opening the printer lp node; see test_device_printer_to_cdc # Runs under hil_util.run_alongside as `python3 -c`. Inline rather than a file so hil_ci.sh's # staging list does not need another entry to keep the rig working. @@ -322,6 +355,87 @@ LP_READER = ( ' buf += chunk\n' 'sys.stdout.buffer.write(buf)\n' ) +# Runs under hil_util.run_cmd as `python3 -c`, argv so the body needs no shell quoting. +# A PROCESS, not a thread, and not optional: cython-hidapi wraps hid_enumerate in +# `with nogil` but calls hid_open and hid_close BARE (hidapi 0.15.0 hid.pyx), so those hold +# the GIL for their whole blocking call. A daemon thread cannot bound that -- the waiter +# parks off-GIL but must reacquire the GIL to return, which the stuck thread never yields +# -- so an in-process bound is inert exactly where it is needed, and the whole worker +# freezes rather than just the call. killpg reaches a child regardless. +# +# What blocks: hidapi's hidraw backend reads `manufacturer` and `product` via udev for each +# device that reaches create_device_info_for_device, via copy_udev_string(usb_dev, +# "manufacturer"/"product") -- both usb_string_attr, served under the device lock a wedged +# usbfs ioctl holds (v6.12.96 sysfs.c:141-143). +# +# Passing BOTH ids is what keeps a wedged peer out of that path, and it does more than skip +# non-matches: hidapi only runs the cheap pre-check `if (vendor_id != 0 || product_id != 0)` +# (0.15.0 linux/hid.c:962), so an unfiltered walk sends EVERY device straight to the locked +# reads. The pre-check itself is free -- parse_hid_vid_pid_from_sysfs parses +# <sysfs_path>/device/uevent (:532) -- and both `continue`s precede +# create_device_info_for_device (:966-970 before :976). Six examples in this tree expose a +# HID interface under VID cafe, so a VID-only walk would stall on any of them wedged on a +# peer. hid_open passes the same ids through to hid_enumerate internally (:1030), so the +# filter narrows that walk too -- but a peer running THIS example still matches both ids, +# which is why the child process, not the filter, is what bounds this. +HID_ECHO = r""" +import hid, random, sys, time + +uid, budget, want_pid = sys.argv[1], float(sys.argv[2]), int(sys.argv[3], 16) +deadline = time.monotonic() + budget + +dev = None +while dev is None: + for d in hid.enumerate(0xCafe, want_pid): + if d["serial_number"] == uid: + dev = d + break + if dev is not None or time.monotonic() >= deadline: + break + time.sleep(1) +if dev is None: + sys.exit(f"HID device not found for {uid}") + +h = hid.device() +h.open(dev["vendor_id"], dev["product_id"], uid) +try: + for size in (8, 32, 63): + # Report ID (0) + payload, padded to 64 bytes + payload = bytes(random.randint(1, 255) for _ in range(size)) + h.write(bytes([0]) + payload + bytes(64 - size)) + echo = h.read(64, 2000) + if not echo or len(echo) < size: + sys.exit(f"HID echo timeout or short read ({size} bytes)") + if bytes(echo[:size]) != payload: + sys.exit(f"HID echo wrong data ({size} bytes): " + f"sent {payload.hex()} received {bytes(echo[:size]).hex()}") +finally: + h.close() +""" +# The write half, same shape and same reason: usblp_open() ignores O_NONBLOCK and stalls in +# usb_autopm_get_interface() on a wedged device, holding the driver-global usblp_mutex. A +# blocked THREAD cannot be abandoned without keeping the fd, and usblp allows a single opener +# (v6.12.96 usblp.c), so the next open of this node returns -EBUSY for the life of the worker. +# A killed process takes its fd with it. O_NONBLOCK is kept because usblp DOES honour it on +# write, which is what the select()/partial-write loop below relies on. +LP_WRITER = ( + 'import os, random, select, sys\n' + 'lp, payload_path, ready = sys.argv[1], sys.argv[2], sys.argv[3]\n' + 'data = open(payload_path, "rb").read()\n' + 'fd = os.open(lp, os.O_WRONLY | os.O_NONBLOCK)\n' + # readiness marker, as in LP_READER: the parent must not read CDC before the node is open + 'open(ready, "w").close()\n' + 'off = 0\n' + 'while off < len(data):\n' + ' n = min(random.randint(1, 64), len(data) - off)\n' + ' buf, w = data[off:off + n], 0\n' + ' while w < len(buf):\n' + ' _, wr, _ = select.select([], [fd], [], 5.0)\n' + ' if not wr:\n' + ' sys.exit("printer write timeout (firmware not draining OUT endpoint)")\n' + ' w += os.write(fd, buf[w:])\n' + ' off += n\n' +) MTYPE_TIMEOUT = 30 # a README-sized read is <1 s; bounds a D-state hang on a wedged device @@ -360,6 +474,13 @@ def read_disk_file(uid: str, lun: int, fname: str) -> bytes: # ~5 KB of transfers plus libmtp setup takes seconds, not minutes; a larger value makes a # wedged MTP board cost that much on every retry, all charged to the pool guard. MTP_SESSION_MARGIN = 30 # transfer budget after enumeration; past it the session is killed +# room past the child's OWN enumeration budget for the echo exchange (3 x write + a 2000ms +# hidapi read) and interpreter start-up, so the outer kill only fires on a real stall +HID_ECHO_MARGIN = 30 +# hid_generic_inout's own idProduct. Pinned against the example's descriptor by +# HidEchoRunsInAChild.test_the_pid_matches_the_example, because a silent drift here would +# widen the walk back to every cafe: HID device without failing anything. +HID_INOUT_PID = 0x4012 def get_printer_dev(id: str, vendor_str, product_str, ifnum: int): @@ -368,12 +489,8 @@ def get_printer_dev(id: str, vendor_str, product_str, ifnum: int): product_str = product_str.replace(' ', '_') if product_str else '' for lp in glob.glob('/sys/class/usbmisc/lp*'): try: - # bounded: same device_lock() exposure as the sibling reads (see read_sysfs) sn = hil_util.read_sysfs(f'{lp}/device/../serial') - # UNKNOWN is not None: the sentinel has no __eq__, so an unanswered read - # would fall through both tests and read as 'not this board' -- the exact - # absence/unknown conflation read_sysfs exists to prevent. - if sn is None or sn is hil_util.SYSFS_UNKNOWN: + if sn is None: continue if sn == id: return f'/dev/usb/{os.path.basename(lp)}' @@ -390,7 +507,7 @@ def open_printer_dev(id: str, vendor_str, product_str, ifnum: int) -> str: lp_dev = wait_until(try_find) assert lp_dev, (f'Printer device not found for {id} if{ifnum:02d}' - + hil_util.sysfs_blind_note()) + + hil_util.strand_note()) return lp_dev @@ -446,34 +563,53 @@ def test_host_device_info(board): flasher = board['flasher'] declared_devs = [f'{d["vid_pid"]}_{d["serial"]}' for d in board['tests']['dev_attached']] - port = hil_util.get_serial_dev(flasher["uid"], None, None, 0) - ser = open_serial_dev(port) - ser.timeout = 0.1 - - # reset device since we can miss the first line - ret = getattr(hil_flash, f'reset_{flasher["name"].lower()}')(board) - assert ret.returncode == 0, 'Failed to reset device' + if board.get('logger') == 'rtt': + # The RTT console owns the probe, so reset BEFORE opening it (Commander then + # delivers the buffered boot burst). Unconditional, not only under --skip-flash: + # a previous run's console drained the ring, and the enumeration lines print + # only once — without this a re-run on unchanged firmware reads an empty ring. + ret = getattr(hil_flash, f'reset_{flasher["name"].lower()}')(board) + assert ret.returncode == 0, 'Failed to reset device' + ser = open_board_console(board) + try: + if board.get('logger') != 'rtt': + # reset device since we can miss the first line; on the VCOM the console + # survives the reset, so resetting after open catches the boot banner. + ret = getattr(hil_flash, f'reset_{flasher["name"].lower()}')(board) + assert ret.returncode == 0, 'Failed to reset device' - data = b'' - timeout = enum_timeout() - while timeout > 0: - new_data = ser.read(ser.in_waiting or 1) - if new_data: - data += new_data - enum_dev_sn = [] - for l in data.decode('utf-8', errors='ignore').splitlines(): - vid_pid_sn = re.search(r'ID ([0-9a-fA-F]+):([0-9a-fA-F]+) SN (\w+)', l) - if vid_pid_sn: - enum_dev_sn.append(f'{vid_pid_sn.group(1)}_{vid_pid_sn.group(2)}_{vid_pid_sn.group(3)}') - if set(declared_devs).issubset(set(enum_dev_sn)): - break - time.sleep(0.1) - timeout -= 0.1 - ser.close() + data = b'' + timeout = enum_timeout() + while timeout > 0: + # infra death is not a board failure: without this a dead JLinkExe/probe + # would burn the whole timeout and report as 'No data from device' + assert not getattr(ser, 'eof', False), \ + 'RTT console died (its server exited or the probe dropped off USB)' + new_data = ser.read(ser.in_waiting or 1) + if new_data: + data += new_data + enum_dev_sn = [] + for l in data.decode('utf-8', errors='ignore').splitlines(): + vid_pid_sn = re.search(r'ID ([0-9a-fA-F]+):([0-9a-fA-F]+) SN (\w+)', l) + if vid_pid_sn: + enum_dev_sn.append(f'{vid_pid_sn.group(1)}_{vid_pid_sn.group(2)}_{vid_pid_sn.group(3)}') + if set(declared_devs).issubset(set(enum_dev_sn)): + break + time.sleep(0.1) + timeout -= 0.1 + finally: + ser.close() - if len(data) == 0: - assert False, 'No data from device' lines = data.decode('utf-8', errors='ignore').splitlines() + if board.get('logger') == 'rtt': + # JLinkExe's telnet banner is delivered at connect, whether or not it ever + # finds the control block, so len(data) alone cannot tell "board said nothing" + # from "console never attached to the ring" -- drop the banner first + target_lines = hil_util.strip_banner(data).splitlines() + assert target_lines, ('No data from device: the RTT console attached but the target ' + 'produced nothing -- firmware built without LOGGER=rtt, or SWD lost') + elif len(data) == 0: + assert False, 'No data from device' enum_dev_sn = [] for l in lines: @@ -770,9 +906,9 @@ def test_device_cdc_msc_freertos(board): def link_is_fs(speed) -> bool: - """Payload scaling from a `speed` attribute. Anything not positively read as high speed - counts as FS -- including None and SYSFS_UNKNOWN: the FS payload merely tests an HS - board less, while the HS payload hard-fails a healthy FS board.""" + """Payload scaling from a `speed` attribute. Anything not positively read as high + speed counts as FS, None included: the FS payload merely tests an HS board less, while + the HS payload hard-fails a healthy FS board.""" return speed not in ('480', '5000', '10000') @@ -811,16 +947,15 @@ def test_device_cdc_msc_throughput(board): # Detect speed (12 Mbps FS / 480 Mbps HS) for payload scaling; a device we never find # keeps the FS payload (see link_is_fs) - # usb_scan, not a private glob: it skips root hubs and remembers paths that already - # stranded, so one wedged peer cannot spend this worker's blindness budget four reads - # at a time. + # usb_scan, not a private glob: it skips root hubs and filters on the lock-free + # descriptor pair before touching `serial`. is_fs = True speed_known = False - devs, _ = hil_util.usb_scan(vid='cafe', serial=uid) + devs = hil_util.usb_scan(vid='cafe', serial=uid) if devs: speed = hil_util.read_sysfs(os.path.join(devs[0]['dir'], 'speed')) is_fs = link_is_fs(speed) - speed_known = speed not in (None, hil_util.SYSFS_UNKNOWN) + speed_known = speed is not None # Put tty in raw mode so dd sees pure binary throughput. rs = hil_util.run_cmd(f'timeout 30 stty -F {tty} raw -echo') @@ -873,7 +1008,7 @@ def test_device_cdc_msc_throughput(board): # payload, so an HS board reads as suspiciously slow. Say so rather than publish a green # cell whose scale is a guess. scale = '' if speed_known else ' FS?' - return f'{REPORT_CELL["pass"]} C {pair(cdc_r, cdc_w)} M {pair(msc_r, msc_w)}{scale}' + return f'{hil_report.REPORT_CELL["pass"]} C {pair(cdc_r, cdc_w)} M {pair(msc_r, msc_w)}{scale}' def test_device_dfu(board): @@ -993,45 +1128,81 @@ def test_device_printer_to_cdc(board): ser.reset_input_buffer() # Test 1: Printer -> CDC with multiple sizes, write in random 1-64 byte chunks - LP_WRITE_TIMEOUT = 5.0 # seconds; firmware may stall draining the printer OUT endpoint + # The write runs in a PROCESS for the same reason the read below does: see LP_WRITER. for size in sizes: test_data = rand_ascii(size) ser.reset_input_buffer() - rd = b'' - offset = 0 - # bounded: O_NONBLOCK does NOT save us -- usblp_open() takes the device mutex - # first -- and this open runs on the worker itself, with no thread to abandon - lp_fd = hil_util.bounded_open(lp_dev, os.O_WRONLY | os.O_NONBLOCK, 5) - # Three-valued on purpose: an OSError here is a FACT about the node (EBUSY from - # usblp's single-opener rule, ENOENT from a re-enumeration race, EACCES from a - # udev gap) and must not be reported as a wedge -- that sends the operator to - # usb-kernel-recover for hardware that is fine. - assert lp_fd is not hil_util.SYSFS_UNKNOWN, ( - f'printer: opening {lp_dev} for write blocked (device wedged)' - f'{hil_util.sysfs_blind_note()}') - assert lp_fd is not None, f'printer: {lp_dev} could not be opened for write' + rd = bytearray() + + payload = Path(tempfile.gettempdir()) / f'hil-lp-tx-{os.getpid()}-{size}' + ready = Path(tempfile.gettempdir()) / f'hil-lp-ready-{os.getpid()}-{size}' + payload.write_bytes(test_data) + ready.unlink(missing_ok=True) + # +5 like write_cdc's sibling wait below: the bound is on the OPEN, and the child + # must first fork, exec and boot CPython, which on a loaded rig routinely exceeds + # LP_OPEN_TIMEOUT on its own. A tighter wait here reports a slow interpreter start + # as a wedged node. + open_deadline = time.monotonic() + LP_OPEN_TIMEOUT + 5 + saw_ready = False + + def read_cdc(): + # WAIT for the writer to have the node open, as Test 2's write_cdc does: the + # child has to fork, exec and boot CPython, and reading before it starts just + # burns the serial timeout. + # ONE deadline, shared with the child's bound below. Two different ones let + # the writer open after the parent gave up: it writes the whole payload with + # nobody reading, exits 0, and the byte-compare reports FIRMWARE DATA + # CORRUPTION for a board whose only problem was a slow open. + nonlocal saw_ready + while not ready.exists(): + if time.monotonic() > open_deadline: + return # never opened; the assert below reports THAT, not data + time.sleep(0.02) + saw_ready = True + # fullspeed devices may need extra time; ser.read is bounded by + # SERIAL_READ_TIMEOUT, so an empty return means the stream went quiet + while len(rd) < size: + chunk = ser.read(size - len(rd)) + if not chunk: + break + rd.extend(chunk) # in place: `rd +=` would rebind it as a local + try: - while offset < size: - chunk_size = min(random.randint(1, 64), size - offset) - buf = test_data[offset:offset + chunk_size] - written = 0 - while written < len(buf): - _, wr, _ = select.select([], [lp_fd], [], LP_WRITE_TIMEOUT) - assert wr, f'Printer write timeout after {LP_WRITE_TIMEOUT}s (firmware not draining OUT endpoint)' - n = os.write(lp_fd, buf[written:]) - written += n - rd += ser.read(chunk_size) - offset += chunk_size + r = hil_util.run_alongside( + [sys.executable, '-c', LP_WRITER, lp_dev, str(payload), str(ready)], + read_cdc, LP_OPEN_TIMEOUT + 12) finally: - os.close(lp_fd) - # read any remaining bytes (fullspeed devices may need extra time) - while len(rd) < size: - remaining = ser.read(size - len(rd)) - if not remaining: - break - rd += remaining - assert rd == test_data, (f'Printer->CDC wrong data ({size} bytes):\n' - f' expected: {test_data[:64]}\n received: {rd[:64]}') + ready.unlink(missing_ok=True) + payload.unlink(missing_ok=True) + # rc 124 is run_alongside's kill, i.e. the open blocked -- and stderr is EMPTY + # there, so without the fallback the cell reads 'failed (32 bytes, rc 124):' and + # nothing, for the one failure this conversion exists to contain. An OSError is a + # FACT about the node (EBUSY from usblp's single-opener rule, ENOENT from a + # re-enumeration race) and must not send the operator to usb-kernel-recover. + # The bound covers the open AND the whole write, so rc 124 alone does not mean a + # wedged node. `ready` is written on the line after os.open() returns, so its + # ABSENCE is what says the open never completed -- the case that sends an operator + # to usb-kernel-recover. Anything else killed on the bound was a slow drain. + detail = hil_util.cmd_stdout_text(r.stderr).strip()[:200] + # FIRST: a child that exited on its OWN carries the concrete errno, and only one + # we KILLED (rc 124) can be diagnosed as an open that never completed. Asserting + # the marker before this reported EBUSY/ENOENT as a wedged node -- the conflation + # the comment above exists to prevent. rc is in the message because a child killed + # by a signal leaves `detail` empty. + assert r.returncode in (0, 124), ( + f'Printer->CDC writer failed ({size} bytes, rc {r.returncode}): {detail}') + # saw_ready, not ready.exists(): a marker that appeared AFTER read_cdc gave up + # means the child wrote with nobody reading, and the byte-compare below would call + # that firmware data corruption. Report the slow open instead. + assert saw_ready, (f'printer: {lp_dev} was not opened for write within ' + f'{LP_OPEN_TIMEOUT + 5}s (device wedged, or the writer never ' + f'started); rc {r.returncode}') + assert r.returncode == 0, ( + f'Printer->CDC writer killed on its bound after opening {lp_dev} ' + f'(rc {r.returncode}): the firmware stopped draining the OUT endpoint') + assert bytes(rd) == test_data, (f'Printer->CDC wrong data ({size} bytes):\n' + f' expected: {test_data[:64]}\n' + f' received: {bytes(rd)[:64]}') # Test 2: CDC -> Printer with multiple sizes, write in random 1-64 byte chunks. # The lp read runs in a PROCESS, not a thread: /dev/usb/lp* blocks on read, usblp @@ -1071,8 +1242,13 @@ def test_device_printer_to_cdc(board): ready.unlink(missing_ok=True) # stderr, not stdout: run_alongside keeps the payload stream clean, so a traceback # from the reader now arrives on its own pipe - assert r.returncode == 0, (f'CDC->Printer reader failed ({size} bytes, rc ' - f'{r.returncode}): {hil_util.cmd_stdout_text(r.stderr)[:200]}') + # rc 124 is run_alongside's kill -- a blocked usblp_open leaves stderr EMPTY, so + # without the fallback this renders as 'failed (32 bytes, rc 124):' and nothing + rdetail = hil_util.cmd_stdout_text(r.stderr).strip()[:200] + assert r.returncode == 0, ( + f'CDC->Printer reader failed ({size} bytes): {rdetail}' if rdetail else + f'printer: reading {lp_dev} blocked (device wedged): the reader was killed on ' + f'its bound (rc {r.returncode})') assert r.stdout == test_data, (f'CDC->Printer wrong data ({size} bytes):\n' f' expected: {test_data[:64]}\n received: {r.stdout[:64]}') time.sleep(0.2) @@ -1239,9 +1415,6 @@ def test_device_midi_test(board): def test_device_audio_test_freertos(board): uid = board['uid'] - if os.name == 'nt': - return 'skipped' - pcm = None timeout = enum_timeout() while timeout > 0: @@ -1301,38 +1474,19 @@ def test_device_audio_test_freertos(board): def test_device_hid_generic_inout(board): + # The whole exchange runs in a child (see HID_ECHO): hidapi's blocking calls hold the + # GIL, so nothing in-process can bound them. run_cmd's killpg can. uid = board['uid'] - import hid # cython-hidapi (pip: hidapi, apt: python3-hid) - - timeout = enum_timeout() - dev = None - while timeout > 0: - for d in hid.enumerate(0xCafe): - if d['serial_number'] == uid: - dev = d - break - if dev: - break - time.sleep(1) - timeout -= 1 - assert dev is not None, f'HID device not found for {uid}' - - h = hid.device() - h.open(dev['vendor_id'], dev['product_id'], uid) - try: - for size in [8, 32, 63]: - # Report ID (0) + payload, padded to 64 bytes - payload = bytes([random.randint(1, 255) for _ in range(size)]) - report = bytes([0]) + payload + bytes(64 - size) - h.write(report) - echo = h.read(64, 2000) - assert echo and len(echo) >= size, ( - f'HID echo timeout or short read ({size} bytes)') - assert bytes(echo[:size]) == payload, ( - f'HID echo wrong data ({size} bytes):\n' - f' expected: {payload.hex()}\n received: {bytes(echo[:size]).hex()}') - finally: - h.close() + r = hil_util.run_cmd( + [sys.executable, '-c', HID_ECHO, uid, str(enum_timeout()), f'{HID_INOUT_PID:#06x}'], + timeout=enum_timeout() + HID_ECHO_MARGIN, split_stderr=True) + # rc 124 is run_cmd's kill: the child was still inside a hidapi call, which is the + # wedge this runs in a child FOR -- and stderr is empty there, so say so rather than + # render a bare trailing colon + detail = hil_util.cmd_stdout_text(r.stderr).strip()[:300] + assert r.returncode == 0, (f'hid_generic_inout: {detail}' if detail else + f'hid_generic_inout: the child was killed on its bound ' + f'(rc {r.returncode}) -- a hidapi call did not return') def test_device_usbtest(board): @@ -1342,35 +1496,30 @@ def test_device_usbtest(board): uid = board['uid'] def usbtest_enumerated(): - """True, False, or None when a bounded read did not answer -- absence unproven.""" # vid_pid FIRST: right after flashing, the previous example's enumeration (same # serial, different PID) can linger and would fail usbtest.py's lookup -- and # filtering on the two lock-free descriptor fields rules out every other device - # on the bus before the one read that can block. usb_scan memoises paths that - # already stranded, so one wedged peer cannot spend the blindness budget here. - devs, unknown = hil_util.usb_scan(vid_pid=('cafe', '4010'), serial=uid) - if devs: - return True - return None if unknown else False + # on the bus before the one read that can block. + return bool(hil_util.usb_scan(vid_pid=('cafe', '4010'), serial=uid)) end = time.monotonic() + enum_timeout() seen = usbtest_enumerated() - while time.monotonic() < end and seen is not True: + while time.monotonic() < end and not seen: time.sleep(0.2) seen = usbtest_enumerated() # fail before usbtest_permit: an absent device would otherwise queue on the battery # mutex for minutes behind real batteries just to have usbtest.py report "no device" - if seen is not True: + if not seen: # 0/30 rather than a bare cell: the battery never ran (30 = standard case count) - raise TestFail( - f'no cafe:4010 device with serial {uid}' if seen is False else - f'cannot tell whether cafe:4010 {uid} is present: the bounded sysfs reads did ' - f'not answer{hil_util.sysfs_blind_note()}', - metric=f'{REPORT_CELL["fail"]} 0/30') + # maxtasksperchild=1, so this worker only ever handled THIS board: a give-up here + # is about this device. Without the caveat a wedged-but-present DUT reads as a + # positive absence claim -- the conflation this whole path exists to avoid. + raise TestFail(f'no cafe:4010 device with serial {uid}{hil_util.strand_note()}', + metric=f'{hil_report.REPORT_CELL["fail"]} 0/30') # settle: right after flashing the enumeration can bounce once (and on dual-port parts # the other port's stale node — same serial and PID — lingers), and testusb run into # that gap sees the device drop mid-case - time.sleep(3) + time.sleep(USBTEST_SETTLE) # --keep-binding is required for concurrent batteries: usbtest.py's cleanup unbinds # EVERY usbtest-bound interface, killing a peer battery under USBTEST_PARALLEL > 1, and @@ -1386,8 +1535,9 @@ def test_device_usbtest(board): # Post-hang recovery reflashes the DUT through its own probe, NEVER a root-port cycle # (one board reached instead of every fixture under the port; see usb-kernel-recover). # _current_fw is the artifact test_example flashed for THIS test: re-deriving it from - # board['name'] reflashes the wrong build on variant-only boards. --outer-timeout lets - # usbtest skip a reflash it cannot finish before our run_cmd kill, which would orphan + # board['name'] reflashes the wrong build on variant-only boards. Our run_cmd bound + # below RESERVES the whole ladder (usbtest.recovery_reserve), which is what lets the + # child run it straight through without an outer kill landing mid-flash and orphaning # the flasher (own session) on the probe. Never under --skip-flash -- and say so: a # HUNG case then holds the DUT's usbfs lock for the rest of the run, and a probe reset # is no substitute (the DWC2 pullup survives a core halt). @@ -1399,14 +1549,12 @@ def test_device_usbtest(board): # same probe convoy-safely without changing how the board is normally flashed. _rec_flasher = hil_flash.recover_flasher(board) recovery = bool(_current_fw and not skip_flash and hil_flash.convoy_safe(_rec_flasher)) - # ONE bound, computed here and used for BOTH the child's --outer-timeout and our own - # run_cmd kill below. Three separate expressions disagreed: --skip-flash appended no - # --outer-timeout at all (usbtest reads 0 as "no limit"), and the no-recovery branch - # narrowed only the CHILD's view while run_cmd still waited the full reserve -- so a - # board that cannot recover held a pool worker AND its battery permit idle for - # USBTEST_RECOVERY_BUDGET it had no way to spend, under a usbtest width of 2. - outer = USBTEST_BATTERY_BUDGET + (USBTEST_RECOVERY_BUDGET if recovery - else USBTEST_OVERSHOOT) + # ONE bound: run_cmd's kill below. It carries the recovery reserve only when a + # recovery can actually run, and only what THIS flasher's ladder can spend -- a board + # that cannot recover used to hold a pool worker AND its battery permit idle for a + # reserve it had no way to spend, under a usbtest width of 2. + outer = USBTEST_BATTERY_BUDGET + USBTEST_OVERSHOOT + ( + usbtest.recovery_reserve(_rec_flasher) if recovery else 0) if _current_fw and skip_flash: print('note: --skip-flash disables usbtest hang recovery; a HUNG case will leave ' 'the device wedged until it is reflashed', flush=True) @@ -1415,12 +1563,11 @@ def test_device_usbtest(board): f'usbfs node, so usbtest hang recovery is disabled for {board["name"]}; a ' f'HUNG case will leave it wedged for the rest of the run', flush=True) if recovery: - # ship the RECOVERY flasher as `flasher`: usbtest.py, recovery_steps and - # convoy_safe all read board['flasher'], so substituting here keeps the entire - # child side unaware that a second roster entry exists + # ship the RECOVERY flasher as `flasher`: usbtest.py and convoy_safe both read + # board['flasher'], so substituting here keeps the entire child side unaware that + # a second roster entry exists rb = json.dumps({'name': board['name'], 'flasher': _rec_flasher}) cmd += f' --recover-board {shlex.quote(rb)} --recover-fw {shlex.quote(_current_fw)}' - cmd += f' --outer-timeout {outer}' # The reserve above USBTEST_BATTERY_BUDGET exists because the battery can overrun by # one already-started case, and a hang there needs room for the recovery (whose reflash # is bounded by usbtest.RECOVER_FLASH_TIMEOUT, not HIL_CMD_TIMEOUT). Without it run_cmd @@ -1456,8 +1603,22 @@ def test_device_usbtest(board): board_wedged = (f'{board["name"]}: usbtest reported a hang and was killed ' f'before it could report a verdict') raise TestFail(f'usbtest did not run: {detail}', - metric=f'{REPORT_CELL["fail"]} 0/30') + metric=f'{hil_report.REPORT_CELL["fail"]} 0/30') + + return _usbtest_verdict(board, data, out, passed, failed, recovery, + _rec_flasher) + +def _usbtest_verdict(board: Board, data: dict, out: str, passed: int, failed: int, + recovery: bool, rec_flasher: dict) -> str: + """The report cell for a battery that produced JSON, or a TestFail carrying one. + + Also latches board_wedged, which stops the REST of this board's examples: each would + flash THROUGH the poisoned usbfs node, block, survive SIGKILL and add another stray -- + one wedge becoming one stray per remaining example, which is the convoy this whole + containment path exists to prevent. + """ + global board_wedged # A HUNG case that recovery could not clear leaves a D-state holder on this board's # usbfs node. Latch it: the remaining examples would each flash THROUGH that node, # block, survive SIGKILL and add another stray -- turning one wedge into one stray per @@ -1466,30 +1627,30 @@ def test_device_usbtest(board): # the reflash worked, so a convoy-safe board whose recovery failed used to come back # unlatched and flash every remaining example through the poisoned node. if data.get('wedged') or (not recovery and 'HUNG' in out): - # _rec_flasher, NOT board['flasher']: recovery was decided against recover_flasher() - # at the top of this function, and the two diverge as soon as a roster carries the + # rec_flasher, NOT board['flasher']: recovery was decided against recover_flasher() + # in the caller, and the two diverge as soon as a roster carries the # optional `flasher_recover` key -- naming the wrong one sends the operator to the # wrong probe. The wording stays on what usbtest actually reported ("still wedged"), - # because unrecovered_hang is also set by the ambiguous/inconclusive aborts, where + # because unrecovered_hang is also set by the ambiguous abort, where # nothing hung and the old text was false on both clauses. board_wedged = (f'{board["name"]}: usbtest reports the device still wedged ' - + (f'after a recovery reflash via {_rec_flasher["name"]}' if recovery - else f'and {_rec_flasher["name"]} cannot deliver a recovery reflash')) + + (f'after a recovery reflash via {rec_flasher["name"]}' if recovery + else f'and {rec_flasher["name"]} cannot deliver a recovery reflash')) # notrun counts toward the denominator but is NOT a failure: listing cases that never # ran as failures sends a maintainer bisecting one of them. notrun = int(data.get('notrun', 0)) total = passed + failed + notrun if board_wedged and failed == 0 and notrun == 0: - # Every case passed and the device STILL wedged -- usbtest's inconclusive/ambiguous + # Every case passed and the device STILL wedged -- usbtest's ambiguous # abort fires after the last case, so nothing back-fills a BUDGET entry. Reporting # the pass would exit 0 with a D-state holder on the rig and the board absent from # the re-run spec. parsed=True: a retry re-pays the whole battery to re-observe a # wedge, and flashes through the poisoned node to do it. raise TestFail(f'usbtest {passed}/{total} but the device wedged ({board_wedged})', - metric=f'{REPORT_CELL["fail"]} {passed}/{total}', parsed=True) + metric=f'{hil_report.REPORT_CELL["fail"]} {passed}/{total}', parsed=True) if failed == 0 and notrun == 0 and total > 0: - return f'{REPORT_CELL["pass"]} {passed}/{total}' + return f'{hil_report.REPORT_CELL["pass"]} {passed}/{total}' bad = [c.get('num') for c in data.get('cases', []) if c.get('status') not in ('PASS', 'BUDGET')] why = f'usbtest {passed}/{total}' @@ -1505,7 +1666,7 @@ def test_device_usbtest(board): why += f'; {notrun} case(s) never ran ({reason}), so this says nothing about them' # parsed ONLY when every case ran: an aborted battery (budget expiry, kernel hang, bus # drop) leaves BUDGET entries, and those are exactly what a reflash retry can fix. - raise TestFail(why, metric=f'{REPORT_CELL["fail"]} {passed}/{total}', + raise TestFail(why, metric=f'{hil_report.REPORT_CELL["fail"]} {passed}/{total}', parsed=(notrun == 0)) @@ -1670,21 +1831,17 @@ def test_example(board: Board, variant: str, example: str) -> tuple[int, str, st def build_board(board: Board) -> tuple[str, int]: """Build firmware for this board via tools/build.py. - Honors board config's variant list and build.args defines. + Honors board config's variant list. Output goes to cmake-build/cmake-build-<variant>/ (tools/build.py layout). Unbounded on purpose: --build is a local convenience (no CI workflow passes it), so the developer watching the build is the timeout.""" name = board['name'] - bcfg = cast(BuildCfg, board.get('build', {})) - extra_defs = bcfg.get('args', []) variants = board.get('variant') or [{'name': name, 'flags': ''}] failed = 0 for v in variants: cmd = [sys.executable, str(hil_util.TINYUSB_ROOT / 'tools' / 'build.py'), '-b', name] - for d in extra_defs: - cmd += ['-D', d] if v['name'] != name: cmd += ['--build-name', v['name']] for d in v.get('defines', []): @@ -1711,11 +1868,48 @@ def build_board(board: Board) -> tuple[str, int]: return name, failed -# pseudo-test column for a variant boundary the park-flash could not clear (see below) -BOUNDARY_CELL = 'same-PID boundary' +def _tests_for(board: Board) -> list: + """Which examples this board runs, in roster order. + + Three sources, most specific first: an explicit -bt list for this board, a global -t + list filtered against what the board can actually do, or the roster's own capability + flags. The -t filter is not cosmetic -- without it a device-only board runs host/dual + tests whose `dev_attached` roster entry does not exist. + """ + name = board['name'] + if name in board_test: + return list(board_test[name]) + board_tests = board.get('tests', {}) + if test_only: + if 'only' in board_tests: + allowed = set(board_tests['only']) + return [t for t in test_only if t in allowed] + return [t for t in test_only + if board_tests.get(t.split('/', 1)[0]) is True] -def test_board(board: Board) -> tuple[str, int, list[str], list, float]: + if 'tests' not in board: + return [] + test_list: list = [] + if board_tests.get('device') is True: + test_list += list(device_tests) + if board_tests.get('dual') is True: + test_list += dual_tests + if board_tests.get('host') is True: + test_list += host_test + if 'only' in board_tests: + test_list = list(board_tests['only']) + for skip in board_tests.get('skip', []): + if skip in test_list: + test_list.remove(skip) + log_line(f'{name:25} {skip:30} ... Skip') + return test_list + + +def test_board(board: Board) -> tuple: + # (name, err_count, failed_tests, rows, duration[, strays]) -- the board-LOCKED early + # return is 5 wide, the normal one 6. _stray_note reads index 5 behind a len() guard, + # so a field inserted anywhere before it silently reports a duration as a stray count. swept = False name = board['name'] flasher = board['flasher'] @@ -1728,42 +1922,11 @@ def test_board(board: Board) -> tuple[str, int, list[str], list, float]: log_line(f'{name:25} {STATUS_FAILED}: {e}') # 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, {'board-locked': 'fail'}, None)], 0.0 + return name, 1, [], [(name, {hil_report.LOCKED_CELL: 'fail'}, None)], 0.0 # after the lock: flock wait behind a concurrent run is not board cost t_board = time.monotonic() try: - test_list = [] - - if name in board_test: - test_list = board_test[name] - elif len(test_only) > 0: - # Explicit -t: filter against the board's capabilities, or a device-only board - # runs host/dual tests whose `dev_attached` config entry does not exist. - board_tests = board.get('tests', {}) - if 'only' in board_tests: - allowed = set(board_tests['only']) - test_list = [t for t in test_only if t in allowed] - else: - for t in test_only: - category = t.split('/', 1)[0] - if board_tests.get(category) is True: - test_list.append(t) - else: - if 'tests' in board: - board_tests = board['tests'] - if board_tests.get('device') is True: - test_list += list(device_tests) - if board_tests.get('dual') is True: - test_list += dual_tests - if board_tests.get('host') is True: - test_list += host_test - if 'only' in board_tests: - test_list = board_tests['only'] - if 'skip' in board_tests: - for skip in board_tests['skip']: - if skip in test_list: - test_list.remove(skip) - log_line(f'{name:25} {skip:30} ... Skip') + test_list = _tests_for(board) err_count = 0 failed_tests = [] @@ -1815,7 +1978,7 @@ def test_board(board: Board) -> tuple[str, int, list[str], list, float]: # charging again would double-count one incident in the exit code if not wedge_skip: err_count += 1 - cells[BOUNDARY_CELL] = 'fail' + 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 @@ -1831,7 +1994,7 @@ def test_board(board: Board) -> tuple[str, int, list[str], list, float]: # 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'{REPORT_CELL["skip"]} board wedged' + 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 @@ -1872,12 +2035,10 @@ def test_board(board: Board) -> tuple[str, int, list[str], list, float]: stray = hil_health.kill_own_children() swept = True - # LAST fields: whether this worker ran out of bounded-read budget, and what it could - # not kill. Only the worker can answer either -- the blindness latch is - # process-global and this is a separate process -- and the result tuple already - # crosses back, so no Manager round-trip. + # LAST field: what this worker could not kill. Only the worker can answer it, and + # the result tuple already crosses back, so no Manager round-trip. return (name, err_count, [] if board_wide_fail else sorted(set(failed_tests)), - rows, t_total, hil_util.sysfs_blind(), stray) + rows, t_total, stray) finally: # A raise skips the sweep above, and maxtasksperchild=1 retires this process # immediately afterwards -- reparenting its flasher to init and erasing the ppid @@ -1899,8 +2060,6 @@ def test_board(board: Board) -> tuple[str, int, list[str], list, float]: _lock_fh.close() -REPORT_MD = 'hil_report.md' -REPORT_JSON = 'hil_report.json' # controller hints from previous runs: uid -> {'name', 'pci', 'duration'}. Only 'pci' is # consumed (dispatch order and first-flash budgeting, never battery serialization). PCI # addresses are boot-stable, so the cache survives reboots and goes stale on re-cabling. @@ -1918,66 +2077,6 @@ def schedule_boards(boards: list, pci_of_uid: dict) -> list: return [b for grp in itertools.zip_longest(*buckets.values()) for b in grp if b is not None] -def render_matrix(rows_all: list) -> str: - """Render rows (list of (row_label, {example: status}, duration)) as an aligned - markdown matrix: columns = tests (bare names) centered, boards left-aligned, - per-row duration as the trailing column.""" - seen = set() - for _, cells, _ in rows_all: - seen.update(cells) - if not seen: - return 'No tests were run.' - - # metric-bearing columns pinned first, the rest alphabetical: stable regardless of the - # shuffled execution order - pinned = ['usbtest', 'cdc_msc_throughput', 'msc_file_explorer', 'msc_file_explorer_freertos'] - - def col_key(t): - name = t.rsplit('/', 1)[-1] - return (pinned.index(name) if name in pinned else len(pinned), name, t) - - columns = sorted(seen, key=col_key) - headers = [c.rsplit('/', 1)[-1] for c in columns] + ['duration'] # bare example names - - def cell(cells, col): - v = cells.get(col) - if v is None: - return '' - return REPORT_CELL.get(v, v) # status symbol, or a metric string (e.g. speed) verbatim - - rows_vals = [(lbl, [cell(cells, c) for c in columns] + [dur or '']) - for lbl, cells, dur in rows_all] - board_hdr = 'Board' - board_w = max([len(board_hdr)] + [len(lbl) for lbl, _ in rows_vals]) - col_w = [max([len(h)] + [len(vals[i]) for _, vals in rows_vals]) - for i, h in enumerate(headers)] - - def line(label, values): - padded = [label.ljust(board_w)] + [v.center(w) for v, w in zip(values, col_w)] - return '| ' + ' | '.join(padded) + ' |' - - header = line(board_hdr, headers) - sep = '| ' + '-' * board_w + ' | ' + ' | '.join(':' + '-' * (w - 2) + ':' for w in col_w) + ' |' - body = [line(lbl, vals) for lbl, vals in rows_vals] - - # tally run cells (not-run cells are absent from the dicts). A cell is a bare status or - # a metric string carrying its own icon ("❌ 29/30"), so classify by the leading icon. - def cell_kind(v): - if v == 'fail' or (isinstance(v, str) and v.startswith(REPORT_CELL['fail'])): - return 'fail' - if v == 'skip' or (isinstance(v, str) and v.startswith(REPORT_CELL['skip'])): - return 'skip' - return 'pass' - kinds = [cell_kind(v) for _, cells, _ in rows_all for v in cells.values()] - failed = kinds.count('fail') - skipped = kinds.count('skip') - passed = kinds.count('pass') - summary = (f'**{REPORT_CELL["pass"]} {passed} passed · {REPORT_CELL["fail"]} {failed} failed · ' - f'{REPORT_CELL["skip"]} {skipped} skipped · blank not run**') - - return summary + '\n\n' + '\n'.join([header, sep] + body) - - def _write_failed_spec(failed_fname: Path, report_dir: Path, mret: list) -> None: """Re-run spec: only the failed boards (-b), each restricted to its own failed tests (-bt); a board with failures but no test list re-runs entirely. @@ -2058,7 +2157,7 @@ def _stray_note(mret: list) -> str: runs AFTER accumulate_report on both abort paths, so a banner appended there was written to a variable nobody read again. """ - dirty = [(r[0], r[6]) for r in mret if len(r) > 6 and r[6]] + dirty = [(r[0], r[5]) for r in mret if len(r) > 5 and r[5]] if not dirty: return '' total = sum(n for _, n in dirty) @@ -2067,109 +2166,13 @@ def _stray_note(mret: list) -> str: f'{", ".join(f"{b} ({n})" for b, n in dirty)}.\n') -def _blind_note(mret: list) -> str: - """Name the boards whose worker went blind, for the report banner. - - A blind worker answers SYSFS_UNKNOWN for every attribute, so its "device not found" is - "could not tell". That already reaches the log and the per-cell failure text, but the - TABLE is what gets quoted -- and a red cell there is read as a broken board. Seen live - (run 31794359407): four workers blind, several cells red because of it, and a report - that said nothing. - - Per-board, not global: maxtasksperchild=1 gives every board a fresh worker, so a board - that ran on a healthy one is not smeared by a neighbour's wedge. Rows synthesised by - the timeout path are 5 fields wide and have nothing to report. - """ - blind = [r[0] for r in mret if len(r) > 5 and r[5]] - if not blind: - return '' - return (f'> **Not all verdicts are evidence.** {len(blind)} board(s) ran on a worker ' - f'that went blind on sysfs -- too many bounded reads stranded on a wedged ' - f'device -- so "not found" from them means "could not tell": ' - f'{", ".join(blind)}. See the usb-kernel-recover skill.\n') - - -def accumulate_report(mret: list, report_dir: Path, fresh: bool, scope: str = '', - banner: str = '') -> str: - """Merge this run's results into hil_report.json in report_dir, then (re)write - the markdown matrix to hil_report.md. `fresh` (a first run, no --accumulate) - starts a new report; otherwise a re-run accumulates so boards/tests that - already passed are preserved while re-run cells are updated. `scope` names the - board filter, if any, so a scoped table is not mistaken for a full one. - Returns the md.""" - acc = {} # ordered {row_label: [cells dict, duration str|None]} - prior_banner = '' - jpath = report_dir / REPORT_JSON - if not fresh and jpath.is_file(): - try: - saved = json.loads(jpath.read_text()) - # CI keys the report dir by run id, so the sidecar is from an earlier attempt - for entry in saved.get('rows', []): - acc[entry['board']] = [dict(entry['cells']), entry.get('duration')] - # ... and so is the caveat those cells were collected under. A rerun on a rig - # that has since recovered contributes no banner, and the .failed spec reruns - # only FAILURES -- so the earlier attempt's passes are never re-earned and - # would be published as clean results of a rig that was not. - prior_banner = saved.get('banner', '') - except (ValueError, KeyError, TypeError): - pass # corrupt/old sidecar: start fresh - - # current cells override prior for boards/tests that ran; a filtered run reports - # duration None, keeping the previous full-run value - for name, _, _, rows, *_ in mret: - if rows and not any('board-locked' in cells for _, cells, _ in rows): - # board ran for real: clear a stale lock-failure cell (its row is keyed by - # board name; test rows may be variant names) - stale = acc.get(name) - if stale is not None: - stale[0].pop('board-locked', None) - if not stale[0]: - # variant-keyed boards never repopulate the board-name row, so drop it - # or it renders as a blank ghost row - del acc[name] - for row_label, cells, dur in rows: - row = acc.setdefault(row_label, [{}, None]) - # the boundary cell is only ever written on failure, so a re-run of this - # variant that cleared the boundary must drop the previous attempt's ❌ - if BOUNDARY_CELL not in cells: - row[0].pop(BOUNDARY_CELL, None) - row[0].update(cells) - if dur is not None: - row[1] = dur - - report_dir.mkdir(parents=True, exist_ok=True) - # by LINE, deduped: attempts repeat the same caveat far more often than they add a new - # one, and three copies of the D-state note reads as three incidents - seen, merged = set(), [] - for line in (prior_banner + banner).splitlines(): - if line.strip() and line not in seen: - seen.add(line) - merged.append(line) - banner = '\n'.join(merged) + '\n' if merged else '' - jpath.write_text(json.dumps({'rows': [{'board': k, 'cells': c, 'duration': d} - for k, (c, d) in acc.items()], - 'banner': banner}, indent=2) + '\n') - - md = render_matrix([(k, c, d) for k, (c, d) in acc.items()]) - if scope: - # a scoped run's small table is otherwise indistinguishable from a full one, and - # it replaces the previous full table in the sticky PR comment - md = f'_Scoped run: {scope}. Boards/tests not listed were not run._\n\n' + md - # LAST, so it is outermost: a rig-health caveat outranks the table AND the scope note, - # and the top of the report is where hil/SKILL.md tells the agent to look for it. - if banner: - md = banner + '\n' + md - (report_dir / REPORT_MD).write_text(md + '\n', encoding='utf-8') - return md - - # containment paths print through hil_health._p: stdout may already be a dead pipe (a # dropped ssh session), and a BrokenPipeError there would skip os._exit _p = hil_health._p def _abandon_exit(pool, mgr, abandoned: bool, err_count: int, - report: Path | None = None) -> None: + report_dir: Path | None = None) -> None: """Free the runner when the pool could not be shut down. Returns only if not abandoned. Must run even while an exception is propagating: multiprocessing's atexit handler @@ -2205,24 +2208,11 @@ def _abandon_exit(pool, mgr, abandoned: bool, err_count: int, 'stay locked.', flush=True) # A report already written by accumulate_report says nothing about the abandon, and a # green table under a red job is how an agent ends up pasting it as this run's result. - # Prepend the caveat; best-effort, never at the cost of exiting. - if report is not None: - try: - if report.exists(): - # utf-8 explicitly (the cells are ✅/❌/⚪) and catch ValueError too: a torn - # report or a LANG=C locale raises UnicodeDecodeError -- NOT an OSError -- - # straight past os._exit, stranding the runner. - body = report.read_text(encoding='utf-8', errors='replace') - # Only when no banner is there yet, searched anywhere in the head rather - # than at char 0: write_timeout_report's banner must stay FIRST (its table - # is a PREVIOUS attempt's) and it puts the rig-health quote above itself. - if '**HIL run ab' not in body[:2000]: - report.write_text( - '**HIL run abandoned: the worker pool would not shut down.** The ' - 'table below was collected before the abandon; treat board ' - 'results as unverified.\n\n' + body, encoding='utf-8') - except (OSError, ValueError): - pass + # Set the caveat in the DOCUMENT -- prepending to the markdown alone left the sidecar, + # which is all hil_report.summarize() and therefore an agent ever sees, saying nothing. + # Best-effort, never at the cost of exiting. + if report_dir is not None: + hil_report.mark_report_abandoned(report_dir, 'the worker pool would not shut down.') try: sys.stdout.flush() except OSError: @@ -2232,6 +2222,135 @@ def _abandon_exit(pool, mgr, abandoned: bool, err_count: int, os._exit(min(err_count, 125) if err_count else 1) +def _load_controller_hints() -> tuple[dict, dict]: + """The uid -> {name, pci, duration} cache, plus the uid -> pci view scheduling wants. + + Best effort throughout: a missing, hand-edited or torn cache costs dispatch ORDER, + never the run. + """ + hints: dict = {} + try: + with CONTROLLER_CACHE.open() as f: + loaded = json.load(f) + if isinstance(loaded, dict): # keep only the expected uid -> dict shape + hints = {k: v for k, v in loaded.items() if isinstance(v, dict)} + except (OSError, ValueError): + pass + return hints, {uid: h['pci'] for uid, h in hints.items() if h.get('pci')} + + +def _save_controller_hints(hints: dict, mret: list, uid_of: dict, cmap) -> None: + """Fold this run's PCI resolutions and durations back into the cache, atomically. + + Merge-on-write: another HIL job (the esp split) may have finished since our startup + read, so overlay only this run's boards rather than publishing our whole view. + """ + for name, _, _, _, dur, *_ in mret: + uid = uid_of.get(name) + if uid is None: + continue + h = dict(hints.get(uid) or {}) + h['name'] = name # informational: the cache is keyed by uid + h['pci'] = cmap.get(f'uid:{uid}') or h.get('pci') + if dur > 0: # test_board reports 0.0 for filtered (partial) runs + h['duration'] = round(dur, 1) + hints[uid] = h + merged: dict = {} + try: + with CONTROLLER_CACHE.open() as f: + cur = json.load(f) + if isinstance(cur, dict): + merged = {k: v for k, v in cur.items() if isinstance(v, dict)} + except (OSError, ValueError): + pass + # overlay onto what the CACHE now holds, not onto our startup snapshot: another HIL + # job may have written a newer duration/pci for these boards since we read it + for name, *_ in mret: + uid = uid_of.get(name) + if uid is not None and uid in hints: + merged[uid] = {**merged.get(uid, {}), **hints[uid]} + CONTROLLER_CACHE.parent.mkdir(parents=True, exist_ok=True) + tmp = CONTROLLER_CACHE.with_suffix('.json.tmp') + with tmp.open('w') as f: + json.dump(merged, f, indent=1, sort_keys=True) + tmp.replace(CONTROLLER_CACHE) + + +def _abort_report(reason: str, mret: list, config_boards: list, failed_fname: Path, + report_dir: Path, fresh: bool, health_banner: str, + timeout_secs: int | None = None) -> None: + """Keep what finished, name what did not, and get a report on disk. Never raises. + + Both abort paths -- the pool guard expiring and a worker raising -- need exactly this, + and in this order. The re-run spec goes FIRST: a fresh run already unlinked it, and + leaving it unwritten is what made a GitHub re-run repeat the whole fleet. Only the + boards that never reported go in it. + + The report follows, before anything that can block, and the caller raises afterwards + into the one containment path. `timeout_secs` adds the pool-guard fallback: when + accumulate_report itself fails -- an unwritable report dir, a torn JSON -- + _abandon_exit can only stamp a report that EXISTS, so without it the artifact upload + finds nothing and the sticky PR comment keeps the previous push's green table under a + red job. + """ + stuck = [b['name'] for b in config_boards if b['name'] not in {r[0] for r in mret}] + try: + _write_failed_spec(failed_fname, report_dir, + [(n, 1, [], None, 0) for n in stuck] + + [r for r in mret if r[1] > 0]) + except Exception as werr: # noqa: BLE001 - it mkdir()s and open()s the very report dir + # the fallback below is FOR an unwritable/root-owned report dir; letting the spec + # raise here replaces the caller's RuntimeError, so the operator never sees the + # 'pool timed out' line and no report is written at all + print(f'warning: re-run spec failed: {type(werr).__name__}: {werr}', flush=True) + banner = (f"**HIL run {reason}.** {len(mret)} board(s) below finished and are this " + f"run's; {len(stuck)} never reported and are NOT in the table: " + f"{', '.join(stuck)}. The re-run spec covers those.\n") + try: + hil_report.accumulate_report(mret, report_dir, fresh, '', + health_banner + _stray_note(mret), caveat=banner) + return + except Exception as rerr: # noqa: BLE001 - the caller's raise must still happen + print(f'warning: partial report failed: {type(rerr).__name__}: {rerr}' + + '; falling back to the board list', flush=True) + try: + # banner=, or write_timeout_report's default caveat publishes 'No per-board + # results could be collected' onto a report where mret DID hold finished rows + # the CELL names the cause: a board the pool guard never reached did not + # "pool-timeout", and marking it so sends the reader after a guard that did not fire + hil_report.write_timeout_report( + report_dir, [b for b in config_boards if b['name'] in stuck], + timeout_secs or 0, banner=banner, prefix=health_banner, + cell=(hil_report.POOL_TIMEOUT_CELL if timeout_secs + else hil_report.RUN_ABORTED_CELL)) + except Exception as re2: # noqa: BLE001 + print(f'warning: fallback report failed too: {type(re2).__name__}: {re2}', + flush=True) + + +def _start_pool(mgr, seed: str, hints_by_uid: dict): + """(cmap, pool). Split out so main()'s try/finally reads as one shape. + + The Manager is created by the CALLER and passed in: Pool() forks, and after a convoy + that fork is what hits EAGAIN/ENOMEM. Creating the Manager here too would leave main() + with `mgr` still None while a live SyncManager child exists -- os._exit skips its + finalizer and the orphan holds the runner's stdout, so the job step never completes. + + maxtasksperchild=1: a fresh worker per board makes cross-board contamination + structural rather than dependent on every module global being reset by hand + (board_wedged, _current_fw, hil_flash's warn-once sets). The extra fork is noise + against a flash+test cycle. + """ + cmap = mgr.dict() + initargs = (Lock(), seed, + hil_lock.make_permit_sems(Semaphore, hil_lock.USBTEST_PARALLEL), + hil_lock.make_permit_sems(Semaphore, hil_lock.FLASH_PARALLEL), + cmap, Lock(), hints_by_uid) + pool = Pool(processes=os.cpu_count() or 1, initializer=init_worker, + initargs=initargs, maxtasksperchild=1) + return cmap, pool + + def main() -> None: """ Hardware test on specified boards @@ -2303,6 +2422,56 @@ def main() -> None: config_boards = [e for e in config['boards'] if e['name'] in boards] config_boards = [e for e in config_boards if e['flasher']['name'] not in args.exclude_flasher and (not args.flasher or e['flasher']['name'] in args.flasher)] + + # fail rtt misconfigurations before the first flash cycle -- but only for boards + # this run actually touches: one bad roster entry must not abort other runs' subsets + def _rtt_config_abort(msg: str): + # loud AND leaving evidence, like the no-boards branch below: exiting with no + # report at all lets the PR comment keep the previous push's stale table + print(f'ERROR: {msg}', flush=True) + rd = Path(os.environ.get('HIL_REPORT_DIR', '.')) + hil_report.mark_report_no_boards(rd, f'config error: {msg}', fresh=not args.accumulate) + sys.exit(1) + + bad_logger = [e['name'] for e in config_boards if e.get('logger') not in (None, 'rtt')] + if bad_logger: + # only the exact string activates RTT handling; anything else would silently + # mean VCOM and reproduce the misleading 'No serial device found' failure + _rtt_config_abort(f'unknown "logger" value (only "rtt" is supported): {", ".join(bad_logger)}') + bad_rtt = [e['name'] for e in config_boards + if e.get('logger') == 'rtt' and e['flasher']['name'].lower() != 'jlink'] + if bad_rtt: + # JlinkRtt speaks JLinkExe only (the OpenOCD RTT route is manual — rtt skill) + _rtt_config_abort(f'"logger": "rtt" needs a jlink flasher: {", ".join(bad_rtt)}') + rtt_no_logger_def = [e['name'] for e in config_boards + if e.get('logger') == 'rtt' + and any('LOGGER=rtt' not in (v.get('defines') or []) + for v in (e.get('variant') or [{}]))] + if rtt_no_logger_def: + # a prebuilt cmake-build-<board> configured with -DLOGGER=rtt is a legitimate + # build path the roster need not describe, so warn there -- but when this run is + # responsible for the firmware (--build, or CI where the hil-build job compiled + # the artifact from these same defines) the flashed image is UART-logger and every + # test times out as 'the target produced nothing'. An always-on define is + # expressed as a single self-named variant (see the Board comment). + msg = (f'"logger": "rtt" board has a variant without LOGGER=rtt in its defines ' + f'({", ".join(rtt_no_logger_def)})') + if args.build or os.environ.get('GITHUB_ACTIONS'): + _rtt_config_abort(f'{msg} -- the firmware built for this run cannot serve the ' + f'configured RTT console') + print(f'warning: {msg} -- fine for prebuilt example sets, wrong for --build/CI ' + f'builds', flush=True) + rtt_fixture = [e['name'] for e in config_boards + if e.get('logger') == 'rtt' + and any(d.get('is_cdc') or d.get('is_msc') + for d in e.get('tests', {}).get('dev_attached', []))] + if rtt_fixture: + # interim guard, removed when the followup lands: cdc_msc_hid/msc_file_explorer + # still open the flasher VCOM directly and would die mid-run on an rtt board + _rtt_config_abort(f'"logger": "rtt" boards cannot carry is_cdc/is_msc fixtures yet ' + f'(host cdc/msc tests bypass the RTT console — see ' + f'the rtt harness-adoption doc in docs/superpowers/followup/): {", ".join(rtt_fixture)}') + if not config_boards: # same reason the unknown -b board exits 1: 'No tests were run.' with rc 0 reads as # a green HIL leg, so a roster edit emptying a leg's filter stops testing silently @@ -2311,13 +2480,11 @@ def main() -> None: print(msg, flush=True) # loud AND leaving evidence: exiting with no report at all lets the PR comment # keep the previous push's stale table under a red job - try: - rd = Path(os.environ.get('HIL_REPORT_DIR', '.')) - rd.mkdir(parents=True, exist_ok=True) - (rd / REPORT_MD).write_text(f'**HIL run selected no boards.** {msg}\n', - encoding='utf-8') - except OSError: - pass + rd = Path(os.environ.get('HIL_REPORT_DIR', '.')) + # fresh must be threaded through: this runs BEFORE the `if fresh:` wipe below, so + # defaulting it here wiped an --accumulate run's accumulated rows -- the exact + # regression the parameter exists to prevent. + hil_report.mark_report_no_boards(rd, msg, fresh=not args.accumulate) sys.exit(1) @@ -2352,9 +2519,6 @@ def main() -> None: report_dir = Path(os.environ.get('HIL_REPORT_DIR', '.')) failed_fname = report_dir / (config_file.name + '.failed') fresh = not args.accumulate - # The unlink is DEFERRED to inside the pool try/except below: wiping here leaves - # Manager() and Pool() running with the old report gone and no report-writing path - # armed, so an EAGAIN/ENOMEM on fork gives CI an EMPTY report dir with no reason. seed = os.getenv('HIL_SHUFFLE_SEED') or str(int(time.time())) log_line(f'test-order shuffle seed: {seed} (HIL_SHUFFLE_SEED={seed} to replay); ' @@ -2364,16 +2528,7 @@ def main() -> None: # unattributable from the log alone f'pool guard: {POOL_TIMEOUT}s') - hints = {} - try: - with CONTROLLER_CACHE.open() as f: - loaded = json.load(f) - # tolerate a hand-edited/torn cache: keep only the expected uid -> dict shape - if isinstance(loaded, dict): - hints = {k: v for k, v in loaded.items() if isinstance(v, dict)} - except (OSError, ValueError): - pass - hints_by_uid = {uid: h['pci'] for uid, h in hints.items() if h.get('pci')} + hints, hints_by_uid = _load_controller_hints() config_boards = schedule_boards(config_boards, hints_by_uid) log_line('dispatch order: ' + ', '.join(b['name'] for b in config_boards)) @@ -2393,31 +2548,22 @@ def main() -> None: # BEFORE Manager()/Pool(), not inside the try: hil_ci.sh reuses a persistent REMOTE_DIR # and scp's the report back unconditionally, so if a fork failure (OSError/EAGAIN right # after a convoy -- the case this whole block guards) skipped the wipe, the finally's - # _abandon_exit would prepend "HIL run abandoned" to the PREVIOUS run's table and + # _abandon_exit would stamp "HIL run abandoned" onto the PREVIOUS run's report and # publish last night's board results as this run's. Nothing is live yet here, so an # OSError from the wipe itself just exits with its traceback -- it cannot strand the # interpreter in multiprocessing's unbounded atexit join, which is what deferring it # was protecting against. if fresh: report_dir.mkdir(parents=True, exist_ok=True) - for f in (REPORT_JSON, REPORT_MD): + for f in (hil_report.REPORT_JSON, hil_report.REPORT_MD): (report_dir / f).unlink(missing_ok=True) failed_fname.unlink(missing_ok=True) try: + # BOUND FIRST, in main's own scope: a Pool fork failure inside _start_pool must + # still leave a live Manager reachable by the finally below, or its child is + # orphaned holding the runner's stdout. mgr = Manager() - cmap = mgr.dict() - initargs = (Lock(), seed, - hil_lock.make_permit_sems(Semaphore, hil_lock.USBTEST_PARALLEL), - hil_lock.make_permit_sems(Semaphore, hil_lock.FLASH_PARALLEL), - cmap, Lock(), hints_by_uid) - # maxtasksperchild=1: the sysfs blindness latch is process-global and permanent - # (no decrement anywhere -- see hil_util.SYSFS_STUCK_MAX), so a worker that goes - # blind on ONE wedged board would report 0/30 and "probe missing" for the 2-3 - # healthy boards it picked up afterwards. A fresh worker per board confines the - # damage to the board that caused it; the extra fork is noise against a - # flash+test cycle. - pool = Pool(processes=os.cpu_count() or 1, initializer=init_worker, - initargs=initargs, maxtasksperchild=1) + cmap, pool = _start_pool(mgr, seed, hints_by_uid) # OUTER: encloses the pool block too, not just the reporting below. An exception # escaping async_ret.get() (a worker exception, a Ctrl-C) runs the pool finally and # then propagates straight out of main(); with _abandon_exit in a sibling try it @@ -2434,43 +2580,13 @@ def main() -> None: try: mret = drain_pool(it, config_boards, deadline, out=mret) except MpTimeoutError as te: - mret = te.finished - stuck = [b['name'] for b in config_boards - if b['name'] not in {r[0] for r in mret}] - # The re-run spec FIRST and before the raise: a fresh run already unlinked - # it, so leaving it unwritten is what made the GitHub re-run repeat the - # whole fleet. Only the boards that never reported go in it. - _write_failed_spec(failed_fname, report_dir, - [(n, 1, [], None, 0) for n in stuck] - + [r for r in mret if r[1] > 0]) - # Then the report, with the rows that DID finish, before anything that can - # block. Then RAISE into the ONE containment path: the inner finally runs + # RAISE afterwards into the ONE containment path: the inner finally runs # the ordered sweep (kill_worker_children BEFORE terminate, or a reaped # worker's flasher reparents out of reach), the outer one os._exit's. - banner = (f'**HIL run abandoned: worker pool timed out after ' - f'{POOL_TIMEOUT}s.** {len(mret)} board(s) below finished and ' - f'are this run\'s; {len(stuck)} never reported and are NOT in ' - f'the table: {", ".join(stuck)}. Re-run covers those.\n') - try: - accumulate_report(mret, report_dir, fresh, '', - health_banner + _blind_note(mret) - + _stray_note(mret) + banner) - except Exception as rerr: # noqa: BLE001 - the raise below must still happen - # FALL BACK, do not just warn: accumulate_report can raise on an - # unwritable/root-owned report dir or a torn JSON, and _abandon_exit - # only PREPENDS to a report that exists. Without this the artifact - # upload finds nothing (if-no-files-found: ignore) and the sticky PR - # comment keeps the previous push's green table under a red job. - print(f'warning: partial report failed: {type(rerr).__name__}: {rerr}; ' - f'falling back to the board list', flush=True) - try: - hil_health.write_timeout_report( - report_dir, [b for b in config_boards - if b['name'] in stuck], POOL_TIMEOUT, REPORT_MD, - prefix=health_banner) - except Exception as re2: # noqa: BLE001 - print(f'warning: fallback report failed too: ' - f'{type(re2).__name__}: {re2}', flush=True) + mret = te.finished + _abort_report(f'abandoned: worker pool timed out after {POOL_TIMEOUT}s', + mret, config_boards, failed_fname, report_dir, fresh, + health_banner, timeout_secs=POOL_TIMEOUT) _p(f'HIL worker pool timed out after {POOL_TIMEOUT}s; sweeping and ' f'shutting it down (abandoning it if a worker is unkillable)', flush=True) @@ -2478,44 +2594,26 @@ def main() -> None: except Exception as e: # A worker RAISED -- e.g. a flasher adapter dropping off the bus makes # get_serial_dev raise in the worker's flash section, which no per-test - # handler guards. Same treatment as the timeout path: the drain means - # `mret` already holds every board that finished, so keep those rows and - # name only the ones still in flight. (Under map_async they were all lost, - # which is what the old banner here claimed.) - done = {r[0] for r in mret} - stuck = [b['name'] for b in config_boards if b['name'] not in done] - _write_failed_spec(failed_fname, report_dir, - [(n, 1, [], None, 0) for n in stuck] - + [r for r in mret if r[1] > 0]) - banner = (f'**HIL run aborted: a worker raised {type(e).__name__}: {e}.** ' - f'{len(mret)} board(s) below finished and are this run\'s; ' - f'{len(stuck)} did not report: {", ".join(stuck)}.\n') - try: - accumulate_report(mret, report_dir, fresh, '', - health_banner + _blind_note(mret) - + _stray_note(mret) + banner) - except Exception as re2: # noqa: BLE001 - the raise below must still happen - print(f'warning: partial report failed: {type(re2).__name__}: {re2}', - flush=True) + # handler guards. The drain means `mret` already holds every board that + # finished, so keep those rows and name only the ones still in flight. + _abort_report(f'aborted: a worker raised {type(e).__name__}: {e}', + mret, config_boards, failed_fname, report_dir, fresh, + health_banner) raise err_count = build_err + sum(e[1] for e in mret) _write_failed_spec(failed_fname, report_dir, mret) finally: - # Not `with Pool(...)`: its __exit__ joins the workers unbounded, hanging on + # Not `with Pool(...)`: its __exit__ joins the workers unbounded and hangs on # any worker in uninterruptible sleep. shutdown_pool bounds the same terminate() - # by a grace period, so the pool is NOT cleanly closed/joined when it returns - # False. Record the outcome but never exit here: the report below is the only - # record of a run that otherwise passed. + # and returns False when the pool is NOT cleanly closed. # - # Same ordering as the timeout path: what the workers spawned must be - # snapshotted and killed while its parent is alive, or terminate() reparents it - # out of reach. + # Sweep BEFORE shutdown: what the workers spawned must be snapshotted and + # killed while its parent is alive, or terminate() reparents it out of reach. # - # Both calls must stay guarded: a raise here skips accumulate_report(), so a run - # whose boards ALL passed publishes an empty report dir -- and both can raise - # for reasons unrelated to the results. pool_abandoned stays fail-CLOSED, so - # _abandon_exit still arms. + # Both calls stay guarded and neither exits: a raise here would skip + # accumulate_report and publish an empty report dir for a run whose boards all + # passed. pool_abandoned is fail-CLOSED, so _abandon_exit still arms. try: # Still worth running for the TIMEOUT path, where the workers are # genuinely stuck mid-task and their children are still reachable through @@ -2543,33 +2641,8 @@ def main() -> None: report_dir.mkdir(parents=True, exist_ok=True) with (report_dir / 'hil_profile_ctrl.json').open('w') as f: json.dump(dict(cmap), f, indent=1, sort_keys=True) - uid_of = {b['name']: b['uid'] for b in config['boards']} - for name, _, _, _, dur, *_ in mret: - uid = uid_of.get(name) - if uid is None: - continue - h = dict(hints.get(uid) or {}) - h['name'] = name # informational: cache is keyed by uid - h['pci'] = cmap.get(f'uid:{uid}') or h.get('pci') - if dur > 0: # test_board reports 0.0 for filtered (partial) runs - h['duration'] = round(dur, 1) - hints[uid] = h - # merge-on-write: another HIL job (e.g. the esp split) may have finished since - # our startup read, so overlay only this run's boards and replace atomically - merged = {} - try: - with CONTROLLER_CACHE.open() as f: - cur = json.load(f) - if isinstance(cur, dict): - merged = {k: v for k, v in cur.items() if isinstance(v, dict)} - except (OSError, ValueError): - pass - merged.update({uid_of[n]: hints[uid_of[n]] for n, *_ in mret if n in uid_of}) - CONTROLLER_CACHE.parent.mkdir(parents=True, exist_ok=True) - tmp = CONTROLLER_CACHE.with_suffix('.json.tmp') - with tmp.open('w') as f: - json.dump(merged, f, indent=1, sort_keys=True) - tmp.replace(CONTROLLER_CACHE) + _save_controller_hints( + hints, mret, {b['name']: b['uid'] for b in config['boards']}, cmap) except Exception as e: # Deliberately broad, and it must stay that way: this best-effort refresh makes # Manager proxy RPCs that raise EOFError / BrokenPipeError / RemoteError when @@ -2584,12 +2657,11 @@ def main() -> None: # looks exactly like a full run that happened to be small scoped = sorted(set(args.board) | set(board_test)) scope = f'{len(scoped)} board(s) — {", ".join(scoped)}' if scoped else '' - report = accumulate_report(mret, report_dir, fresh, scope, - health_banner + _blind_note(mret) - + _stray_note(mret)) + report = hil_report.accumulate_report(mret, report_dir, fresh, scope, + health_banner + _stray_note(mret)) print() print(report) - print(f'\nReport written to {(report_dir / REPORT_MD).resolve()}') + print(f'\nReport written to {(report_dir / hil_report.REPORT_MD).resolve()}') duration = time.time() - duration print() @@ -2600,7 +2672,7 @@ def main() -> None: # In the finally, not after: any raise above (accumulate_report sits outside the # OSError handler) would skip the abandon path and unwind into multiprocessing's # unbounded atexit join, hanging the runner. - _abandon_exit(pool, mgr, pool_abandoned, err_count, report_dir / REPORT_MD) + _abandon_exit(pool, mgr, pool_abandoned, err_count, report_dir) # Same clamp: exit status is a byte either way, so 256 failures would report green. sys.exit(min(err_count, 125)) |