diff options
Diffstat (limited to 'test/hil/helper')
| -rw-r--r-- | test/hil/helper/hil_health.py | 6 | ||||
| -rwxr-xr-x | test/hil/helper/hil_lock.py | 15 | ||||
| -rw-r--r-- | test/hil/helper/hil_pool_check.py | 93 | ||||
| -rw-r--r-- | test/hil/helper/hil_report.py | 22 | ||||
| -rw-r--r-- | test/hil/helper/hil_util.py | 395 |
5 files changed, 266 insertions, 265 deletions
diff --git a/test/hil/helper/hil_health.py b/test/hil/helper/hil_health.py index b9c05c236..d78d0f220 100644 --- a/test/hil/helper/hil_health.py +++ b/test/hil/helper/hil_health.py @@ -246,10 +246,8 @@ def _kill_kids(kids: dict, seen: set) -> int: if denied: _p(f'warning: could not kill {sorted(denied)}; they still hold whatever they ' f'had open (probe, usbfs node) into the next job', flush=True) - # SURVIVORS, not the signalled-child count: the caller needs to know the rig is dirty - # for the next job, and a count of what we successfully signalled cannot tell it that. - # (They are different units anyway -- a killpg is counted once per child sharing the - # group -- so the old return was never comparable to anything.) + # SURVIVORS, not the count we signalled: the caller needs to know the rig is dirty for + # the next job, and a killpg is counted once per child sharing the group anyway. return len(denied) diff --git a/test/hil/helper/hil_lock.py b/test/hil/helper/hil_lock.py index 7757ef17d..91f05ca86 100755 --- a/test/hil/helper/hil_lock.py +++ b/test/hil/helper/hil_lock.py @@ -175,13 +175,12 @@ def controller_of(uid: str): if cached: return cached # vid='cafe' first: the target is always a TinyUSB DUT, and the VID is a lock-free - # descriptor field. Without it this read every probe's and hub's `serial` -- the - # attribute served under device_lock -- so a HEALTHY peer mid-usbtest would strand a - # reader here and spend one of this worker's four blindness credits. - devs, _ = hil_util.usb_scan(vid='cafe', serial=uid) + # descriptor field. Without it this reads every probe's and hub's `serial` -- the one + # attribute served under device_lock -- so a wedged peer would block us here. + devs = hil_util.usb_scan(vid='cafe', serial=uid) for dev in devs: busnum = hil_util.read_sysfs(os.path.join(dev['dir'], 'busnum')) - if busnum is None or busnum is hil_util.SYSFS_UNKNOWN: + if busnum is None: continue try: root = os.path.realpath(f'/sys/bus/usb/devices/usb{int(busnum)}') @@ -212,7 +211,7 @@ def controller_slot(pci: str) -> int: # Unresolved boards budget in a slot of their OWN, one past the real ones, and that slot # holds exactly ONE permit whatever the per-controller width is. Neither neighbour works: # a permit on every slot (the old fail-closed rule) serialized the whole fleet the moment -# a worker went blind, while a full private budget let unknown boards run a second +# one board could not be resolved, while a full private budget let unknown boards run a second # controller's worth of batteries on top of the resolved ones -- doubling the load on # whichever physical controller they actually sit on, which is the saturation the # uPD720201 deaths above are attributed to. Width 1 caps the over-subscription at +1. @@ -252,8 +251,8 @@ class controller_permit: if pci is None: pci = controller_of(uid) if pci is None and warn_unknown: - log(f'warning: cannot resolve {uid} to a host controller' - f'{hil_util.sysfs_blind_note()}; budgeting it in the unknown bucket') + log(f'warning: cannot resolve {uid} to a host controller; ' + f'budgeting it in the unknown bucket') self.slots = [controller_slot(pci) if pci else UNKNOWN_SLOT] def __enter__(self): diff --git a/test/hil/helper/hil_pool_check.py b/test/hil/helper/hil_pool_check.py index b92f0aee0..d98b92bd4 100644 --- a/test/hil/helper/hil_pool_check.py +++ b/test/hil/helper/hil_pool_check.py @@ -54,7 +54,7 @@ ENUM_WAIT_RETRY = 8 # s, uid wait after a recovery reset/re-flash SERIAL_WAIT = 6 # s, host-board serial-output wait print_mutex = threading.Lock() -_UNKNOWN_WARNED = False # scan_usb's caveat: once per process, not once per poll +_STRANDED_WARNED = False # scan_usb's caveat: once per process, not once per poll t0 = time.monotonic() @@ -72,20 +72,20 @@ def scan_usb() -> dict: USB-Serial-JTAG bridge and the cafe device it flashes both derive it from the same MAC), and one dict slot would silently drop whichever lost the race.""" found = {} - # `unknown` matters BEFORE the blindness latch trips: one wedged device is the normal - # reason this tool is run, and its serial read stranding makes it absent from `devs`. - # Reported as fact, that is "probe MISSING" for hardware that is physically present. - devs, unknown = hil_util.usb_scan() - # ONCE per process: this is called from 0.5s poll loops across 4 worker threads and - # ~26 boards, so warning per call buried the table it exists to qualify under 600+ - # identical lines. The memo in read_sysfs makes the condition sticky, so one line is - # as true as six hundred. - global _UNKNOWN_WARNED - if unknown and not _UNKNOWN_WARNED: - _UNKNOWN_WARNED = True - say('WARNING: at least one device did not answer a bounded read; rows below that ' - 'say a probe or board is missing may be this scan losing sight of healthy ' - 'hardware. Find the wedged device (usb-kernel-recover) and re-run.') + # usb_scan's `serial` read is bounded by default (see hil_util.read_sysfs) -- this tool + # has no pool guard behind it and is run exactly when a device is suspected wedged. A + # device that will not answer is simply absent from the table; the footer says so. + devs = hil_util.usb_scan() + # ONCE per process, at SCAN time, not only in the footer: this tool prints rows as it + # goes over minutes, so a board dropped from the scan says "probe MISSING" within + # seconds while the only qualification would arrive after the final counts -- and an + # operator acting on the streaming output, or a run cut short by ^C, never sees it. + global _STRANDED_WARNED + if hil_util.sysfs_stranded() and not _STRANDED_WARNED: + _STRANDED_WARNED = True + say('WARNING: a bounded sysfs read gave up; rows below that say a probe or board ' + 'is missing may be this scan losing sight of healthy hardware. Find the ' + 'wedged device (usb-kernel-recover) and re-run.') for dev in devs: try: found[dev['busport']] = { @@ -360,7 +360,47 @@ def check_host_serial(board: dict, do_reset: bool = True, want_hello: bool = Fal do_reset=False listens to the firmware as-is: used right after a flash whose own reset already started it — a second openocd/JLink session back-to-back on - the same probe can fail transiently and leave the target halted.""" + the same probe can fail transiently and leave the target halted. + + "logger": "rtt" boards have no VCOM: the same check runs over the probe's RTT + console instead. The reset happens BEFORE the console opens (it owns the probe), + which also zeroes the .bss ring — so pre-reset backlog cannot count as life, and + without a reset Commander delivers the boot burst the preceding flash left.""" + if board.get('logger') == 'rtt': + if do_reset: + # a failed reset leaves the previous run's ring intact: attaching anyway would + # score stale output as life, so bail to host_alive's board_test reflash ladder + rc, err = call_flasher(getattr(hil_flash, f'reset_{board["flasher"]["name"].lower()}'), board) + if rc: + say(f'{board["name"]:26} reset failed: {err}') + return None + try: + ser = hil_util.JlinkRtt(board, timeout=0.3) + except hil_util.RttError as e: + say(f'{board["name"]:26} no RTT console: {e}') + return None + try: + data = b'' + deadline = time.monotonic() + SERIAL_WAIT + while time.monotonic() < deadline: + ser.write(b'U') + data += ser.read(256) + # JLinkExe's banner arrives whether or not the target is alive -- + # judged unfiltered it scores a dead board 'alive'. Same shared filter + # as test_host_device_info; complete_only drops a trailing partial + # line, so a banner FRAGMENT split by this read boundary cannot count + # as target output either. + td = hil_util.strip_banner(data, complete_only=True) + if want_hello: + if b'Hello from TinyUSB' in td: + return td + elif td and not boardtest_output(td): + return td + return hil_util.strip_banner(data) + except hil_util.RttError: + return None # console died mid-poll (server exited, probe dropped) + finally: + ser.close() import serial try: port = hil_util.get_serial_dev(board['flasher']['uid'], None, None, 0) @@ -1005,17 +1045,16 @@ def main() -> None: counts[r.get('status', 'failed')] += 1 print(f'\n{counts["ok"]} ok · {counts["flash-failed"]} flash-failed · {counts["failed"]} failed ' f'· {counts["locked"]} locked · in {time.monotonic() - t0:.0f}s') - if hil_util.sysfs_blind(): - # Without this the table is the worst kind of wrong: once the process latches - # blind, every read answers SYSFS_UNKNOWN, scan_usb() returns {}, and EVERY board - # prints "probe MISSING"/"off bus" -- a clean-looking report declaring the whole - # fleet dead, produced during exactly the incident this tool is run to diagnose, - # and it sends the operator to power-cycle a rig where one device is wedged. - print('WARNING: this scan lost sight of the bus' - f'{hil_util.sysfs_blind_note()}. Rows above that say a probe or board is ' - f'missing may be this tool losing sight of healthy hardware, not absent ' - f'hardware. Find the wedged device (see the usb-kernel-recover skill) and ' - f're-run before acting on the table.') + if hil_util.sysfs_stranded(): + # Without this the table is the worst kind of wrong: a device whose `serial` never + # answered is absent from the scan, which prints as "probe MISSING"/"off bus" for + # hardware that is physically present -- during exactly the incident this tool is + # run to diagnose, and it sends the operator to power-cycle a healthy rig. + print('WARNING: at least one sysfs read did not answer within ' + f'{hil_util.SYSFS_READ_GRACE:.0f}s, so rows above that say a probe or board ' + f'is missing may be this tool losing sight of healthy hardware rather than ' + f'absent hardware. Find the wedged device (see the usb-kernel-recover ' + f'skill) and re-run before acting on the table.') sys.exit(min(counts['flash-failed'] + counts['failed'], 125)) diff --git a/test/hil/helper/hil_report.py b/test/hil/helper/hil_report.py index d059c62c9..c93c8e6a1 100644 --- a/test/hil/helper/hil_report.py +++ b/test/hil/helper/hil_report.py @@ -63,6 +63,10 @@ LOCKED_CELL = 'board-locked' # A pseudo-test column, not a real one: write_timeout_report marks the boards that were # still dispatched when the pool guard fired. accumulate_report clears it on a retry. POOL_TIMEOUT_CELL = 'pool-timeout' +# The other way a board can fail to report: the pool did not expire, a worker RAISED. Same +# shape, different cause, and naming the cause is the whole point of the column -- a board +# marked pool-timeout by an abort that never timed out sends the reader after the guard. +RUN_ABORTED_CELL = 'run-aborted' def _load(report_dir: Path) -> tuple: @@ -352,6 +356,7 @@ def accumulate_report(mret: list, report_dir: Path, fresh: bool, scope: str = '' # never reported, and update() below MERGES, so without this a board that # passed clean on the retry kept a red cell for ever. stale[0].pop(POOL_TIMEOUT_CELL, None) + stale[0].pop(RUN_ABORTED_CELL, None) if not stale[0]: # variant-keyed boards never repopulate the board-name row, so drop it # or it renders as a blank ghost row @@ -360,6 +365,7 @@ def accumulate_report(mret: list, report_dir: Path, fresh: bool, scope: str = '' row = acc.setdefault(row_label, [{}, None]) # a row that ran is no longer pool-timed-out, whatever it is keyed by row[0].pop(POOL_TIMEOUT_CELL, None) + row[0].pop(RUN_ABORTED_CELL, None) # the boundary cell is only ever written on failure, so a re-run of this # variant that cleared the boundary must drop the previous attempt's ❌ if BOUNDARY_CELL not in cells: @@ -409,7 +415,8 @@ def _write_stuck_over_prior_md(report_dir: Path, doc: dict) -> None: def write_timeout_report(report_dir: Path, boards, secs: int, - banner: str = '', prefix: str = '') -> None: + banner: str = '', prefix: str = '', + cell: str = POOL_TIMEOUT_CELL) -> None: """Leave a report behind when the worker pool has to be abandoned. map_async is all-or-nothing, so a timeout loses every per-board result and the report @@ -427,7 +434,7 @@ def write_timeout_report(report_dir: Path, boards, secs: int, caveat = banner or ( f'**HIL run abandoned: worker pool timed out after {secs}s.**\n\n' f'No per-board results could be collected for this attempt. Rows other than ' - f'the {POOL_TIMEOUT_CELL} cells below are from an earlier attempt. Boards ' + f'the {cell} cells below are from an earlier attempt. Boards ' f'dispatched:\n\n' + '\n'.join(f'- {n}' for n in names) + '\n') doc, readable = _load(report_dir) rows = doc['rows'] @@ -435,13 +442,13 @@ def write_timeout_report(report_dir: Path, boards, secs: int, for name in names: row = by_board.get(name) if row is None: - rows.append({'board': name, 'cells': {POOL_TIMEOUT_CELL: 'fail'}, + rows.append({'board': name, 'cells': {cell: 'fail'}, 'duration': None}) else: # _load guarantees `cells` is a dict, so a null-cells row from an uploaded # sidecar can no longer send this down the fallback and publish a board # that ate the whole pool guard as a pass. - row['cells'][POOL_TIMEOUT_CELL] = 'fail' + row['cells'][cell] = 'fail' out = {'rows': rows, 'scope': doc['scope'], 'caveat': caveat, 'banner': ((doc['banner'] + prefix) if prefix not in doc['banner'] else doc['banner'])} @@ -517,8 +524,11 @@ def summarize(cfg: dict, boards: list, report: dict) -> dict: # a wedge outranks lock contention: `locked` short-circuits `detail` below, so a # stale board-locked cell from an earlier attempt used to mask the pool-timeout # cell the retry added -- publishing a board that hung the rig as LOCKED, which - # hil-validate.js then RE-RUNS, paying another pool guard on it. - wedged = any(POOL_TIMEOUT_CELL in cells for cells in mine.values()) + # hil-validate.js then RE-RUNS, paying another pool guard on it. RUN_ABORTED_CELL + # is written by the same _abort_report path for a board the guard never reached, + # and must outrank it for the same reason. + wedged = any(POOL_TIMEOUT_CELL in cells or RUN_ABORTED_CELL in cells + for cells in mine.values()) locked = not wedged and any(LOCKED_CELL in cells for cells in mine.values()) bad = [] for vname, cells in sorted(mine.items()): diff --git a/test/hil/helper/hil_util.py b/test/hil/helper/hil_util.py index 03d01270f..6f84c143d 100644 --- a/test/hil/helper/hil_util.py +++ b/test/hil/helper/hil_util.py @@ -1,7 +1,8 @@ #!/usr/bin/env python3 # SPDX-License-Identifier: MIT # Bottom layer of the HIL harness: the bounded command runner plus the shared helpers and -# data every other module needs. Stays stdlib-only and imports nothing local -- everything +# data every other module needs. Stays stdlib-only; its one local dependency is +# tools/rtt.py (the RTT console, loaded by path below) -- everything # else imports this, including the unit tests on GitHub's bare runner; never import them # from here. Callers set the module global `verbose`. @@ -89,6 +90,10 @@ def pos_float_env(name: str, default: float) -> float: CMD_TIMEOUT = pos_int_env('HIL_CMD_TIMEOUT', 180) +# Post-SIGKILL reap, spent ON TOP of a run_cmd timeout whenever the child has to be killed. +# A caller budgeting several bounded steps must add one of these PER STEP, or its own outer +# bound fires mid-step -- for a flasher, orphaning it on the probe. +REAP_GRACE = 10 TINYUSB_ROOT = Path(__file__).resolve().parents[3] # test/hil/helper/ -> repo root @@ -157,74 +162,119 @@ def _print_banner(title: str, out: Any, err: Any) -> None: print(_banner_body(out, err)) -SYSFS_READ_GRACE = 2.0 # bound on one attribute read of a possibly-wedged device -SYSFS_STUCK_MAX = 4 # stranded readers tolerated before read_sysfs goes blind -_sysfs_stuck = 0 # each costs a thread + an fd for the life of the process -_sysfs_stuck_lock = threading.Lock() -_sysfs_blind_logged = False +SYSFS_READ_GRACE = 2.0 # default bound on one attribute read; see read_sysfs +# path -> the kernfs inode the node had when its bounded read gave up. Keyed by INODE, not +# by path alone: a busport does not change when a board returns to the same physical port, +# so a path-only blacklist outlives the wedge -- hil_pool_check resets or reflashes the +# board, wait_device polls that busport for the new inode, and the scan it polls through +# would never look at the device again. A re-enumeration destroys the kernfs node and makes +# a new one, so a CHANGED inode is the all-clear. os.stat is safe on a wedged device: it +# does not call ->show(), so it cannot block on the lock the reader is stuck behind. +_stranded: dict = {} +_strand_hits: dict = {} # path -> how many times it has stranded, ever +_refused: set = set() # paths answered None WITHOUT reading, once past _STRAND_MAX +_strand_lock = threading.Lock() +_ever_stranded = False -class _SysfsUnknown: - """Sentinel: the read did not answer. NOT "the attribute is absent" -- reading it as - absence turns a healthy board into a firmware regression in the report.""" - __slots__ = () +# Each strand costs a thread AND an fd for the life of the process -- on sysfs the open() +# SUCCEEDS and only the read blocks. Two ceilings, because they bound different things: +# +# _PATH_STRAND_MAX -- a device that FLAPS while still wedged re-enumerates, clears the +# inode memo, and strands again. Per path, so one sick board cannot leak without bound. +# After this many it stays memoised whatever its inode says. +# _STRAND_MAX -- a whole-process backstop against RLIMIT_NOFILE or the thread ceiling, +# which would raise inside a worker and lose every board's result. Counted PER PATH, not +# per reader: hil_pool_check runs four poll threads over one bus, and counting each +# reader let four threads on ONE wedged device spend four credits between them. With +# per-path counting a 27-board rig cannot approach this. +_PATH_STRAND_MAX = 4 +_STRAND_MAX = 64 - def __bool__(self) -> bool: - return False - def __repr__(self) -> str: - return 'SYSFS_UNKNOWN' +def sysfs_stranded() -> bool: + """True once any bounded read has given up, and it STAYS true. + A sticky, process-wide fact, so it answers exactly one question: "could anything in + this process's output be the tool losing sight of healthy hardware?" -- which is what + hil_pool_check's footer needs. It canNOT answer "is THIS device unreadable" for a + caller deciding what a single missing device means; use path_stranded() for that. + """ + return _ever_stranded -SYSFS_UNKNOWN = _SysfsUnknown() +def strand_note() -> str: + """Suffix for an absence claim, so "not found" never reads as proven absence. -def sysfs_blind() -> bool: - """True once this process has stranded SYSFS_STUCK_MAX readers: every later read - answers SYSFS_UNKNOWN, so nothing it reports about a device is a fact any more.""" - return _sysfs_stuck >= SYSFS_STUCK_MAX + Lives here because every caller that can say "not found" needs the same sentence, and + the one that had to re-invent it got missed: a wedged-but-enumerated printer was + reported as an enumeration failure, sending a maintainer after firmware. + """ + return (' (a bounded sysfs read gave up, so "not found" here means "could not tell"' + ' -- see the usb-kernel-recover skill)') if sysfs_stranded() else '' -def sysfs_blind_note() -> str: - """Suffix for a failure message, so a blind worker's verdict never reads as hardware.""" - return (f' (this worker is blind: {SYSFS_STUCK_MAX} sysfs reads stranded on a wedged ' - f'device, so the check could not see the bus)') if sysfs_blind() else '' +def path_stranded(path: str) -> bool: + """Whether THIS attribute is currently memoised as unreadable. + The per-device question sysfs_stranded() cannot answer. usbtest uses it to tell a DUT + whose `serial` is held under device_lock from one that genuinely left the bus, because + the difference decides whether it performs driver-registry writes that take the + UNINTERRUPTIBLE device_lock. + """ + with _strand_lock: + return path in _stranded or path in _refused -def read_sysfs(path: str, grace: float = SYSFS_READ_GRACE) -> str | None | _SysfsUnknown: - """Read a sysfs attribute with a WALL-CLOCK bound. - The value, None when the attribute is genuinely unreadable (OSError), or SYSFS_UNKNOWN - when the read did not answer -- it timed out, or this process is already blind. Callers - MUST keep those apart: absence is a fact, unknown is not. +def read_sysfs(path: str, timeout: float = SYSFS_READ_GRACE) -> str | None: + """A sysfs attribute's value, or None when it did not answer. - usb_string_attr (serial/product/manufacturer) is served under the device lock a wedged - usbfs ioctl holds, so a plain open().read() blocks for as long as the wedge lasts, on - exactly the board an incident is about. The reader sleeps INTERRUPTIBLY (every read - takes usb_lock_device_interruptible, v6.12.96 sysfs.c:124-139 -- uninterruptible is the - ioctl holder, not us), so it dies with a SIGKILLed worker; what it costs meanwhile is a - thread and an fd for this process's life, because on sysfs the open() SUCCEEDS and only - the read blocks. Measured: 20 blocking reads leave 20 live threads. + BOUNDED BY DEFAULT, and it has to be. `serial` is served by usb_string_attr, which + takes usb_lock_device_interruptible (v6.12.96 sysfs.c:141-143) -- the same lock a + wedged usbfs ioctl holds. Every OTHER attribute the harness reads (idVendor, idProduct, + bcdDevice, busnum, devnum, speed) is a lock-free sysfs_emit from a cached field and + cannot block. - Hence the cap: callers rescan (hil_lock's controller_of re-reads every unresolved - device on EVERY permit), and hitting RLIMIT_NOFILE or the thread ceiling raises inside - the worker and loses every board's result -- worse than the hang this prevents. + "Only the wedged board's own worker pays" is FALSE, which is why the bound is not + opt-in: usb_scan reads `serial` on every device matching the VID to find the one it + wants, so resolving MY board touches every peer's locked attribute. hil_lock's + controller_of does that from controller_permit, on essentially every board -- one + wedged DUT would stall every worker, not one. hil_pool_check has no guard at all. + + A give-up reads as None, the same as unreadable: there is no third value and no + per-attribute blindness. The memo is keyed by inode so the cost stays on the device + that is actually wedged; path_stranded() tells a caller which device that was. """ - if sysfs_blind(): - return SYSFS_UNKNOWN - # Known-stranded? Re-reading costs another permanent thread+fd and a blindness credit - # to learn what we already know. Lives HERE, not at the call sites: a call-site memo - # has to be remembered by every new scanner, and twice it was not. - was = _sysfs_stranded.get(path, _STRAND_MISS) - if was is not _STRAND_MISS: - if was is None: - return SYSFS_UNKNOWN # stranded, inode unknown: never re-read it + with _strand_lock: + was = _stranded.get(path) + stuck_for_good = _strand_hits.get(path, 0) >= _PATH_STRAND_MAX + budget_spent = len(_stranded) >= _STRAND_MAX + if was is not None: try: if os.stat(path).st_ino == was: - return SYSFS_UNKNOWN # same node, still wedged + return None # same kernfs node, still wedged except OSError: - pass # gone: fall through, the read reports it - _sysfs_stranded.pop(path, None) # replaced or gone -> re-read it + pass # gone: let the read below report it + if stuck_for_good: + return None # flapped too many times; see _PATH_STRAND_MAX + with _strand_lock: + _stranded.pop(path, None) # a different inode is the all-clear + elif budget_spent: + # see _STRAND_MAX. Recorded, not just returned: usbtest fails CLOSED on + # path_stranded() before the lock-taking cleanup, and a path we declined to read + # is exactly the case it must not be told is readable-and-absent. + with _strand_lock: + _refused.add(path) + return None + + # BEFORE the read, not after: a node that re-enumerates DURING the grace would + # otherwise have its brand-new HEALTHY inode recorded as the wedged one, and only a + # second re-enumeration could ever clear it. If it cannot be stat'd there is no key to + # memoise against, so the path is simply re-read next time -- the open fails fast. + try: + ino = os.stat(path).st_ino + except OSError: + ino = None out: dict = {} def _read(): @@ -232,96 +282,70 @@ def read_sysfs(path: str, grace: float = SYSFS_READ_GRACE) -> str | None | _Sysf with open(path) as f: out['v'] = f.read().strip() except (OSError, ValueError): - pass # no such attribute, or not text: unreadable, and that IS a fact + pass t = threading.Thread(target=_read, daemon=True) t.start() - t.join(grace) - # `out` FIRST, not is_alive() alone: a reader can deposit its value and still be alive - # for a moment afterwards, and counting that as a strand memoises a healthy attribute as - # unreadable and spends one of four blindness credits. bounded_open has always checked - # its box for the same reason. + t.join(timeout) + # `out` FIRST: a reader can deposit its value and still be alive for a moment + # afterwards, and counting that as a strand blacklists a healthy attribute forever + if 'v' in out: + # a path that answered is not refused any more: _refused feeds path_stranded(), + # and a stale entry makes usbtest read a LATER genuine disconnect as "cannot tell" + with _strand_lock: + _refused.discard(path) if t.is_alive() and 'v' not in out: - # Count the PATH once, not once per reader. hil_pool_check runs -j4 by default, - # which equals SYSFS_STUCK_MAX, so four threads hitting ONE wedged device used to - # spend the entire blindness budget between them -- latching blind on the single - # wedge the tool was run to find. The strand is real for each thread, but the - # DEVICE is what the cap is about. - # Under the SAME lock as the counter: check-then-act here is a race, and - # hil_pool_check runs a ThreadPoolExecutor of exactly SYSFS_STUCK_MAX workers in - # ONE process, so four threads on one wedged path could each see `first` before any - # of them recorded it -- spending the whole blindness budget on a single device, - # which is what this memo exists to prevent. note_sysfs_strand takes the lock - # itself, so call it after releasing. - with _sysfs_stuck_lock: - first = path not in _sysfs_stranded - if first: - try: - # stat, never the thread's own open(): stat does not call ->show(), so - # it cannot block on the device lock the reader is stuck behind - _sysfs_stranded[path] = os.stat(path).st_ino - except OSError: - _sysfs_stranded[path] = None # unstattable, but still known-stranded - if first: - note_sysfs_strand() - return SYSFS_UNKNOWN + global _ever_stranded + announce = False + if ino is None: + # the pre-read stat lost a race the open then won -- the node was replaced + # between them. Re-stat now: the reader is blocked on whatever node exists, + # so this is the key it is stuck on. Without a key nothing is memoised and + # every later poll starts another permanent thread and fd for this path. + try: + ino = os.stat(path).st_ino + except OSError: + pass + with _strand_lock: + _ever_stranded = True + if ino is not None: + first = path not in _stranded # count the PATH once, not each reader + _stranded[path] = ino + if first: + _strand_hits[path] = _strand_hits.get(path, 0) + 1 + announce = len(_stranded) == _STRAND_MAX + else: + _refused.add(path) # unkeyable: at least do not vouch for it + if announce: + print(f'warning: {_STRAND_MAX} devices have unreadable sysfs attributes; ' + f'refusing to start more bounded readers, so later reads answer None ' + f'without looking. Find the wedged device (usb-kernel-recover skill).', + file=sys.stderr, flush=True) + return None return out.get('v') -def note_sysfs_strand() -> None: - """Record ONE stranded sysfs reader. Shared by read_sysfs and bounded_open so both - account against a single counter -- the report caveat keys off it.""" - global _sysfs_stuck, _sysfs_blind_logged - with _sysfs_stuck_lock: - _sysfs_stuck += 1 - announce = sysfs_blind() and not _sysfs_blind_logged - _sysfs_blind_logged = _sysfs_blind_logged or announce - if announce: - # once per process, on stderr: a worker's stdout is compacted into one report - # row, where this would be lost among the test output - print(f'warning: {SYSFS_STUCK_MAX} sysfs reads stranded on a wedged device; ' - f'this process is now blind and answers SYSFS_UNKNOWN for every ' - f'attribute -- its verdicts about device presence are not evidence', - file=sys.stderr, flush=True) - - -# path -> the inode it had when its read stranded. A stranded attribute stays -# stranded until the DEVICE is replaced, and a re-enumeration destroys the kernfs -# node and makes a new one -- so a changed inode is the all-clear. Keyed by path -# alone it would outlive the wedge: a busport does not change when a board comes -# back on the same port, so the HUNG reflash this branch performs would recover a -# board the harness could then never see again. -_sysfs_stranded: dict = {} -# A stranded path whose inode could not be read is stored as None, so a plain .get() cannot -# tell 'known stranded, inode unknown' from 'never seen' -- and treating the first as the -# second re-reads it, stranding another permanent thread and fd every call. Distinct miss -# sentinel, so None keeps its own meaning. -_STRAND_MISS = object() - - -def usb_scan(vid_pid=None, serial=None, vid=None) -> tuple[list, bool]: - """Enumerated USB devices matching the filters, and whether anything is unknown. - - Returns ([{busport, dir, vid, pid, serial}], unknown). `unknown` True means a bounded - read did not answer, so absence is NOT proven -- the same contract as read_sysfs. +def usb_scan(vid_pid=None, serial=None, vid=None, timeout=SYSFS_READ_GRACE) -> list: + """Enumerated USB devices matching the filters: [{busport, dir, vid, pid, serial}]. Three rules, one implementation for every caller: * Root hubs excluded (glob `*-*`): no DUT is one, and scans including them measured seconds slower (observation, no mechanism -- the "autosuspend wake" explanation was - wrong; usb_string_attr reads a cached string, sysfs.c:124-139). + wrong; usb_string_attr reads a cached string, sysfs.c:141-143). * idVendor/idProduct first: lock-free `sysfs_emit` from udev->descriptor (sysfs.c:688-705), so they rule out nearly every device for free. - * `serial` last and bounded: it is served under the lock a wedged ioctl holds, and a - path that already stranded is never re-read (each strand costs a thread and an fd - for this process's life). + * `serial` LAST and BOUNDED: it is the only attribute here served under the device + lock, so it is the only one that can block. Filtering on the lock-free pair first + keeps most devices out of it, but a scan for ONE board still reads the serial of + every peer that shares its VID -- so the bound is what stops one wedged DUT from + stalling every caller (see read_sysfs). """ out = [] - unknown = False for d in glob.glob('/sys/bus/usb/devices/*-*'): - # Interfaces are '<busport>:<cfg>.<ifnum>' (e.g. 2-4:1.0) -- they CONTAIN the - # colon, they do not end with it, so the original endswith() never fired and every - # scan opened idVendor/idProduct on all of them (measured: 31 of 44 matches). + # `in`, not endswith: an interface is '<busport>:<cfg>.<ifnum>' (2-4:1.0), which + # CONTAINS the colon rather than ending with it. Screening them out here is worth + # real time -- they were 31 of 44 matches on this rig. if ':' in os.path.basename(d): continue try: @@ -335,106 +359,14 @@ def usb_scan(vid_pid=None, serial=None, vid=None) -> tuple[list, bool]: continue # ruled out for free, without touching the locked attribute if vid is not None and dev_vid != vid: continue # same, for callers that know the VID but not the PID - sn = read_sysfs(os.path.join(d, 'serial')) - if sn is SYSFS_UNKNOWN: - unknown = True # read_sysfs memoises it; a repeat scan costs nothing - continue + sn = read_sysfs(os.path.join(d, 'serial'), timeout) if sn is None: - continue # no serial attribute: a fact + continue # no serial attribute if serial is not None and sn.lower() != serial.lower(): continue out.append({'busport': os.path.basename(d), 'dir': d, 'vid': dev_vid, 'pid': dev_pid, 'serial': sn}) - return out, unknown - - -def bounded_open(path: str, flags: int, timeout: float = SYSFS_READ_GRACE): - """os.open() with a wall-clock bound. - - The fd, None when the open genuinely FAILED (OSError: EBUSY, ENOENT, EACCES), or - SYSFS_UNKNOWN when it did not answer -- the same three-valued contract as read_sysfs, - and for the same reason: folding a fact into an unknown made an ordinary EBUSY read as - a wedged device and sent the operator hunting hardware that is healthy. - - An open CAN block on a wedged device -- not on O_NONBLOCK, which usblp_open never - consults, but on usb_autopm_get_interface(), a runtime-PM resume that does I/O - (v6.12.96 drivers/usb/class/usblp.c). It holds usblp_mutex while it waits, and that - mutex is driver-GLOBAL, so one wedged printer blocks opens of every usblp node. - - Unlike read_sysfs the stranded thread cleans up after itself: if we have given up it - closes the fd it eventually got, so only the thread leaks. Both sides take `handoff` - -- "store or close" and "abandon and drain" are a check-then-act pair that can - interleave into an fd stored after the box was drained, which would leak it into a - node that allows a SINGLE opener (usblp_open returns -EBUSY when usblp->used). - """ - # Same short-circuit as read_sysfs: once blind, another stranded thread buys nothing - # and the cap exists precisely to stop them accumulating. - if sysfs_blind(): - return SYSFS_UNKNOWN - # Known-stranded? Re-opening costs another thread, another fd and another blindness - # credit to learn what we already know -- and the printer test re-opens ONE lp node on - # every retry. Same memo and same inode check as read_sysfs. - was = _sysfs_stranded.get(path, _STRAND_MISS) - if was is not _STRAND_MISS: - if was is None: - return SYSFS_UNKNOWN # stranded, inode unknown: never re-read it - try: - if os.stat(path).st_ino == was: - return SYSFS_UNKNOWN - except OSError: - pass - _sysfs_stranded.pop(path, None) - box: dict = {} - done, abandoned = threading.Event(), threading.Event() - handoff = threading.Lock() - - def _open(): - try: - fd = os.open(path, flags) - except OSError: - done.set() - return - with handoff: - stored = not abandoned.is_set() - if stored: - box['fd'] = fd - if not stored: - try: - os.close(fd) - except OSError: - pass - done.set() - - threading.Thread(target=_open, daemon=True).start() - if not done.wait(timeout): - with handoff: - abandoned.set() - fd = box.pop('fd', None) # completed in the gap between timeout and flag - if fd is not None: - # It DID open, just after our deadline -- the thread finished, so nothing is - # stranded. Report unknown (we already gave up on it) but do not spend a - # blindness credit, and do not call a merely-slow node wedged. - try: - os.close(fd) - except OSError: - pass - return SYSFS_UNKNOWN - # counted like a stranded read_sysfs: the thread and (eventually) its fd are gone - # for the life of the process, and the cap exists to stop that reaching the - # thread/fd ceiling -- an exception there escapes the worker and loses every board. - # Memoised by inode so a retry of the same node does not pay again. - # same lock as read_sysfs, same reason - with _sysfs_stuck_lock: - first = path not in _sysfs_stranded - if first: - try: - _sysfs_stranded[path] = os.stat(path).st_ino - except OSError: - _sysfs_stranded[path] = None - if first: - note_sysfs_strand() - return SYSFS_UNKNOWN - return box.get('fd') + return out def _close_pipes(p: subprocess.Popen) -> None: @@ -477,7 +409,7 @@ def run_alongside(argv: list, work, timeout: int) -> subprocess.CompletedProcess except OSError: p.kill() try: - out, err = p.communicate(timeout=5) + out, err = p.communicate(timeout=REAP_GRACE) except subprocess.TimeoutExpired: # Outlasted SIGKILL: uninterruptible, still holding whatever it opened. # Abandoned like any other stray -- but as a real child in its own @@ -499,6 +431,29 @@ def run_alongside(argv: list, work, timeout: int) -> subprocess.CompletedProcess return _reap() +# The RTT console implementation lives in tools/rtt.py (importable classes + CLI, +# stdlib-only, harness-critical — see its module docstring). Loaded by file path so +# no sys.path entry for tools/ can shadow other imports; re-exported here so the +# harness keeps addressing hil_util.JlinkRtt. +import importlib.util as _ilu + +_rtt_path = TINYUSB_ROOT / 'tools' / 'rtt.py' +if not _rtt_path.exists(): + # name the real cause: a bare FileNotFoundError out of an exec_module here reads + # as a harness bug, when the actual problem is an incompletely staged tree + raise ImportError(f'{_rtt_path} is missing — the RTT console lives there and the ' + f'harness depends on it; stage it alongside test/hil (hil_ci.sh does)') +_rtt_spec = _ilu.spec_from_file_location('tinyusb_tools_rtt', _rtt_path) +_rtt = _ilu.module_from_spec(_rtt_spec) +sys.modules[_rtt_spec.name] = _rtt # registered: RttError must be picklable across the fork Pool +_rtt_spec.loader.exec_module(_rtt) +JlinkRtt = _rtt.JlinkRtt +OpenocdRtt = _rtt.OpenocdRtt +RttError = _rtt.RttError +RTT_BANNER_RE = _rtt.RTT_BANNER_RE +strip_banner = _rtt.strip_banner + + def _cmd_label(cmd) -> str: """A one-line name for a banner. An argv whose payload is a `python3 -c` program would otherwise dump the whole body into the CI log, where run_cmd's banners are already the @@ -551,7 +506,7 @@ def run_cmd(cmd: str | list, cwd: str | None = None, timeout: int | None = None, # close and the rc-124 return this handler exists for. pass try: - out, err = p.communicate(timeout=10) + out, err = p.communicate(timeout=REAP_GRACE) except subprocess.TimeoutExpired: # Something in the group outlived SIGKILL: D state (truly unkillable), or # root-owned because sudo FORKS rather than execs, so the wrapper dies and its |