test: HIL sweep for how long a host USB-drain stall the firmware tolerates

[boringethan]

What

A HIL harness that answers the question openmotion-sdk#116 has never had a number for: how long can the host stall the USB drain before the sensor firmware gives up?

PipelineRunner consumes sinks inline on the thread draining LiveUsbSource._batch_queue, so a slow sink stops dev.read() from being called. With ~0.2 s of packet queue plus a shared 4-slot batch queue, the host absorbs only a few hundred ms before back-pressure reaches the sensor's deliberately shallow 4-deep (~100 ms) histogram queue. In the field (OpenwaterHealth/openmotion-bloodflow-app#300) a sub-second stall on a 20-minute scan escalated to the RIGHT module dropping off the USB bus — with no host-side warning at any point, because StreamInterface only warns after a full second of blocked put.

How

StallSink blocks the drain for a configurable time every Nth live batch. It goes in through the public ScanRequest.sinks list (all_sinks = default_sinks + list(request.sinks)), so no library code changes — the harness measures shipping behaviour, not a patched variant. Default storage sinks stay in the chain so the number is the real system's tolerance.

A log-signature collector then records which firmware failure stage each stall length reaches:

Stage	Firmware signature
HISTO_QUEUE_FULL	host absorption exhausted
USB_TX_BLOCKED	USBD_HISTO_SendData failed / COMM USB TX Timeout
CAMERA_OVERRUN	Error in USARTn/SPIn: Overrun error, failed to setup receive
FALSE_SCAN_END	firmware abandons the scan → the number OpenwaterHealth/openmotion-sensor-fw#101 needs
ENDPOINT_LOST	host sees EPIPE / device lost
HOST_PUT_WARNED	the >1 s put warning — i.e. the only thing today's code would have told us

Sweep is 0.1 / 0.2 / 0.3 / 0.5 / 1.0 / 2.0 s over 40 s scans, ~5 minutes of bench time. The summary test prints an escalation table.

Assertions

Deliberately minimal — this is characterization. The one hard assertion is STALL_BUDGET_S = 0.3 s: a stall within budget must not reach queue-full. Shipping code is expected to fail that, which is the point; it's the metric #113 has to move.

test_zz_summary is a reporter, and the sweep fails fast if a stall takes a module off the bus, since later sweep points would be untrustworthy without a power-cycle.

Verification

tests/test_usb_drain_stall_unit.py (15 tests, unit marker, no hardware) feeds the classifier verbatim firmware printf from the #300 field log — including the multi-line records that a line-oriented matcher would silently miss, the SPI-not-USART overrun variant that killed L7, and benign traffic that must not be classified. The harness is trusted before it costs bench time.

tests/test_usb_drain_stall_unit.py .............   15 passed
python -m pytest -m unit                            40 passed, 750 deselected
flake8                                              clean

The HIL sweep itself has not been run yet — it needs a console + both sensors. That bench run is the deliverable; this PR is the instrument.

Refs #116, OpenwaterHealth/openmotion-bloodflow-app#300

🤖 Generated with Claude Code

[boringethan]

First HIL run — sweep results + 5 defects found

Ran this harness on hardware for the first time today (console + both sensors,
sensor-fw 1.8.2-rc.4 and 1.8.2-dev.1, 4 cameras/side 0xC3). The PR notes
the bench run was still outstanding, so this is that run.

Results — the deliverable

sensor-fw 1.8.2-rc.4

stall	queue-full	USB TX blocked	frames lost	camera overrun	host warned
0.1–0.5 s	–	–	–	–	–
1.0 s	1310	1321	667	–	–
2.0 s	1946	1955	988	–	38

Tolerance boundary: between 0.5 s and 1.0 s.

The headline number for #116: at a 1.0 s stall the host lost 667 frames and
emitted zero warnings. The coarse >1 s instrumentation only spoke at 2.0 s.
That is the case for #113's counters, measured rather than argued.

Two controls:

• Firmware A/B — 1.8.2-dev.1 gives 1429 / 2210 queue-full and 724 / 1121
  frames lost at 1 s / 2 s. Same boundary, same stage, ~10% worse. Host-stall
  tolerance is effectively unchanged between the two builds.
• Laser A/B — laser off vs on differs by <1% (1438 vs 1429 at 1 s). Expected
  in hindsight: the histo queue is 4 frames deep, so it holds ~100 ms
  regardless of payload size. This sweep is payload-independent.

Defects

1. Never bootstraps the camera hardware. The harness calls start_scan
   directly, but the scan path only calls enable_camera (OW_CAMERA_STREAM),
   which assumes powered rails and programmed camera FPGAs — those come from
   configure_camera_sensors (the app's FlashSensorsTask). Works only when a
   prior GUI session left the rig configured; fails on any cold/power-cycled rig.

2. Never calls apply_laser_power. Laser driver registers are volatile and
   cleared by a power cycle. Without it the laser is dark, frames classify as
   warmup/stale, and Tee("live", emit_if_any=not_warmup_or_stale) never emits —
   so StallSink receives nothing.

3. Vacuous pass when no data flows — most important. Nothing asserts
   stalls_injected > 0, so 1 and 2 present as a clean green characterization
   table, every stage "not reached", exit 0. My first run reported
   7 passed having injected zero stalls and moved zero data. That would let
   someone "verify" feat: decouple storage sinks from USB drain — revised (supersedes #96) #113 against a run that never executed the code path.

   assert result.stalls_injected > 0, (
       f"no stalls injected at {stall_s}s — this point measured nothing")

4. Cannot run under the repo's own pytest timeout. pyproject.toml sets
   timeout = 30; each point scans for 40 s. Died in await_complete on a warm
   rig before any of the above mattered. Needs
   @pytest.mark.timeout(SCAN_SEC + 120).

5. FALSE_SCAN_END counts healthy scans. The regex
   r"Scan finished \((\d+) ms" matches the normal end-of-scan line, so every
   clean row reads x2. The derived summary verdict is correct; only the
   per-point counter cries wolf. Suggest keying the signature off the
   ms-threshold check.

Portability note (not a defect): left/right_camera_mask=0xFF fails the power
step on a partially-populated module. Correct on a full rig; worth deriving from
the bench.

Design findings

• CAMERA_OVERRUN is unreachable by construction. Host stalls exercise queue
  depth, which is frame-count-driven — the laser A/B proves payload doesn't
  enter into it. The overrun path needs per-frame compress+send stress (refactor(scripts): purge dead scripts, port the rest to MotionInterface #70).
  That row will read "not reached" indefinitely while presenting as a reachable
  escalation stage.
• STALL_BUDGET_S = 0.3 needs recalibrating. The PR expects shipping code to
  fail it; it passes with margin on both firmwares (0.5 s is clean too). As
  written the assertion can only pass.

Suite-wide: a wedged rig (both sensors in USB Error) yields 7 skipped and
exit 0. Worth an opt-in --require-hardware so a HIL job can't go green on
hardware that's been unplugged for a month.

Fixes for 1–5 are written and were used to produce the numbers above; happy to
push them to the branch.

[boringethan]

Addendum — correction: the numbers above were taken uncompressed

Correcting my previous comment. Every figure in it (the 0.5–1.0 s tolerance boundary, the
firmware A/B, the laser A/B) was measured with histogram compression OFF, so it
characterises a configuration we don't ship. Cause is defect 7 below.

The bloodflow app pushes 0xC1 (printf | histo_cmp | send_defer) at connect. printf_on
only ORs in DEBUG_FLAG_USB_PRINTF, inheriting whatever the sensor already had — a
freshly-flashed or power-cycled sensor sits at 0x00, so the sweep ran uncompressed:
a different send path (camera_manager.c:1769 vs :2032) that never calls rle_compress
at all. The per-frame budget sensor-fw#70 blames for SPI/USART overruns was never loaded.

Compressed results (rc.4, flags 0xC1)

stall	queue-full	camera overrun	host warned
0.1–0.5 s	–	–	–
1.0 s	1084	2	–
2.0 s	1651	–	36

The 1.0 s point reproduced the field failure exactly — the same chain as the
bloodflow-app scan of 2026-07-24, on both modules simultaneously:

Error in USART2: Overrun error / failed to setup receive for Camera 1 channel
Camera 1 has stopped posting data
Camera 1: rail off for 10000 ms (regulator cool-off)
[DIAG] overruns c1-c8: 1 0 0 0 0 0 0 0

Uncompressed never reached it: 18 scan-points across three sweeps, 3278 USB failures,
zero camera overruns.

Repeat experiment — 15x the 1.0 s point per arm

config	full-load trials	camera deaths	mean queue-full
compressed	24	1 (~4%)	1084
uncompressed	18	0	1324

Not statistically significant (Fisher p≈1.0) — 15 trials cannot separate 4% from 0%.
Reporting it as characterisation, not proof.

The mean-queue-full column is the more informative result: the uncompressed arm sustained
22% more back-pressure and still killed nothing. So the escalation to camera death is
not driven by back-pressure magnitude — if it were, uncompressed should be worse. What
distinguishes the arms is the compressed path's extra per-frame work, i.e. sensor-fw#70.

Three further defects

7. Doesn't pin the firmware debug flags. printf_on does flags | DEBUG_FLAG_USB_PRINTF
   and restores prev on teardown — correct in isolation, but it means the effective
   configuration is inherited from whatever ran before. For a harness whose stated purpose is
   measuring shipping behaviour, the production set should be pinned explicitly. Note flags
   persist across runs, so OR-only logic cannot turn a bit off: my first attempt at an
   uncompressed arm silently stayed compressed because the sensors still held 0xC0.

8. USB_TX_BLOCKED only matches the uncompressed send path. The regex is
   USBD_HISTO_SendData failed|COMM USB TX Timeout, but the compressed path logs
   [CMP] USB FAIL: status=%d. In production config the column read 0 while the log
   carried 14350 [CMP] USB FAIL lines. Needs \[CMP\] USB FAIL added, or the column
   silently reads zero in the only configuration we ship.

9. No per-point recovery — a camera death corrupts every later point. When the overrun
   killed camera 1 at run 9 of 15, it stayed dead for runs 10–15 (sensor-fw#102: rail
   re-powered, FPGA held in reset). Packet census: 4 cams → 9238 packets before,
   3 cams → 4889 after; queue-full stepped 1084 → 770 (≈¾ load). Those six points were
   reported as normal data while running at 75% load. Suggest asserting the active camera
   count against the requested mask per point, and re-configuring (or failing) on mismatch.
   As it stands, the escalation the harness exists to detect silently invalidates the rest
   of the sweep.

Side finding for sensor-fw#102

That camera stayed dead across six complete scan stop/start cycles, not just the
remainder of one scan — a full teardown and restart does not revive it; only
configure_camera_sensors does. Worth weighing against the "not planned" rationale: this is
a channel lost until something reprograms the FPGA, which for back-to-back clinical scans
means until the app is restarted.