1 Hz OW_CAMERA_GET_TELEMETRY polling during HISTO streaming wedges the histogram stream (4-cam, fw 1.8.2-dev.1-3-g7f8fe08)

[boringethan]

Summary

Host polling of OW_CAMERA_GET_TELEMETRY (0x54) at 1 Hz during HISTO streaming wedges the histogram stream: all cameras stop delivering HISTO frames after a variable few seconds-to-a-minute, while FSIN keeps counting and the cameras keep running. The telemetry channel itself stays healthy throughout — only HISTO dies.

Without host polling, the same firmware streams cleanly — the firmware's own 125 ms round-robin background telemetry sweep is not the trigger. The sustained 1 Hz COMM query (604-byte response on IF 0) while IF 1 streams is.

• Firmware: 1.8.2-dev.1-3-g7f8fe08 (next @ PR feat: continuous camera-sensor telemetry (#94) — background sweep + OW_CAMERA_GET_TELEMETRY #95 merge)
• Hardware: right sensor module, serial 3386357A3333, 4-camera mask 0xC3 (cams 1,2,7,8), 40 fps external FSIN
• Host: SDK CameraTelemetryCsvLogger (SDK PR #163), 1 Hz get_camera_telemetry() polling started pre-scan and running through the scan

Evidence (three runs, same rig, same day)

Data on the bench PC under openmotion-sdk\.claude\worktrees\camera-scan-off-cycle-e49e7e\bench\telem_dip_out\:

Run	Duration	1 Hz host polling	Result
TELDIP_01	30 min	yes	All 4 cameras stopped at t = 4.6 s (abs_id 185); terminal FSYNC count 72004 (cameras ran the full 30 min). Telemetry stayed healthy the whole scan: 1789/1789 valid rows, 0 I2C errors, sweeps fresh ~7.6 s/cam.
TELSMOKE	90 s	yes	Frames stopped at t = 59.2 s — variable onset, race-like.
WEDGETEST_NOPOLL	150 s	no (fw background sweep still active)	Streamed clean to the full 150 s, 6007 frames/camera.

Firmware-side log evidence (from the SDK pipeline): terminal fsync count 72004 names abs_id 72004 but side=right cam_id=N last delivered abs_id=185 — camera stopped delivering 71819 frames before scan end.

Why this matters

The SDK-side docstring for get_camera_telemetry() says it is "safe to poll during scans" because the query does no camera I2C at request time. That's true for camera I2C — but in practice sustained polling still kills the HISTO endpoint, so the flagship use case of the telemetry (watching camera condition during an acquisition) currently sacrifices the acquisition.

Prior related observation: on fw 1.8.1-rc.3, 8-camera streaming + concurrent host I2C passthrough killed HISTO in ~2 s (the known wedge hazard). This looks like the 4-camera variant of the same underlying contention, now reachable through the supported telemetry query alone. Suspected area: USB/main-loop contention servicing the large IF 0 TX while IF 1 has data pending.

Suggested angles

• Reproduce with dwell on response size: does a small COMM query at 1 Hz also wedge, or is the 604-B response the differentiator?
• Inspect the IF 0 TX path for blocking/starvation while IF 1 streaming has data pending.
• Consider a firmware-side gate (defer/queue telemetry responses while HISTO is enabled) or a documented safe polling cadence.

Refs: #94, PR #95, SDK PR OpenwaterHealth/openmotion-sdk#163.

[boringethan]

Follow-up: response size is NOT the differentiator — any sustained 1 Hz COMM polling wedges

Ran the suggested discriminator on the same rig/firmware (WEDGETEST_SMALLQ, 150-s 0xC3 scan):

• Polled OW_CTRL_FAN_CTL status (tiny response, no data payload) at 1 Hz during streaming → HISTO wedged at t = 32.8 s (all 4 cameras stopped at abs_id 1312; polling itself kept succeeding, 150/150 responses OK).
• Same harness, no polling (WEDGETEST_NOPOLL, previous comment/issue body) → clean 150 s.

So the 604-B telemetry response is off the hook as the specific cause: any sustained ~1 Hz command/response traffic on IF 0 during IF 1 streaming wedges the HISTO endpoint. The telemetry query is just the first API that encourages sustained polling. (Single/occasional COMM commands mid-stream have been fine historically — e.g. a one-shot fan toggle during a 4-cam stream on fw 1.8.1-rc.3 streamed clean through.)

Additional observation: after the wedge, a subsequent scan in the same boot delivered no HISTO frames at all (start accepted, zero frames materialized) — the wedged state appears to persist until a power cycle, consistent with the previously-known behavior of this failure mode.

Caveat: we have not run the sustained-1 Hz-polling test on 1.8.1-rc.3, so this may be a long-standing IF0/IF1 contention rather than a PR #95 regression — the new telemetry just makes it easy to hit. Updated suggested angle: instrument the IF 0 TX path / main-loop service ordering under sustained command load while IF 1 has data pending, independent of response size.

[boringethan]

A/B on the response-size hypothesis: size is not the differentiator

This issue asks: "does a small COMM query at 1 Hz also wedge, or is the 604-B response the differentiator?" #103 grows the telemetry response to 892 B (+48 %), so I ran the experiment before merging it.

Result: any 1 Hz COMM query wedges HISTO. Payload size does not predict it — the smallest response wedged fastest and most often.

Setup

Left sensor, 8-camera mask 0xFF, 90 s cap, one power cycle before every trial (clean endpoint each time). Frames driven by the sensor's own aggregator FSIN (~16 fps) rather than the console trigger — deliberately, so nothing lases. Wedge = no HISTO bytes for >4 s with FSIN still running; in every wedged trial the host also saw [Errno 32] Pipe error.

Arm	Response size	Wedged	Onsets / survival (s)
no polling (control)	—	0/3	survived 89.9, 89.9, 89.9
1 Hz get_camera_telemetry, fw v1	604 B	1/3	wedged 10.9; survived 89.9, 88.8
1 Hz get_camera_telemetry, fw v2 (#103)	892 B	1/2	wedged 16.9; survived 83.9
1 Hz get_debug_flags, fw v2	a few bytes	2/2	wedged 4.4, 14.9

Reading

1. Polling is the trigger, and the control is clean — 0/3 wedged over 90 s with no host polling, confirming this issue's core finding on 8 cameras as well as 4.
2. Size is not the mechanism. A tiny get_debug_flags response wedged 2/2, faster than either telemetry arm. If the 604-B payload were the differentiator, the small arm should have been the safe one.
3. Camera telemetry v2: log the full OB / black-level block (z_avg dark-row means + BLC window/fault context) #103 does not make this worse. 892 B is not worse than 604 B in this data; if anything both telemetry arms outlasted the small-query arm, which is what you'd expect if the driver is the number of IF 0 transactions interleaved with IF 1 streaming rather than their size.

So the suspected area named in the issue — "USB/main-loop contention servicing the large IF 0 TX while IF 1 has data pending" — looks right about the contention and wrong about the large. Any IF 0 transaction during streaming is enough.

Limits of this data

Small N (2–3 per arm) against a highly variable onset (this issue already saw 4.6 s vs 59.2 s on identical config), ~16 fps internal FSIN rather than 40 fps console-driven, and the left module rather than the right. It is enough to rule size out as the dominant factor; it is not enough to quantify a rate.

Also seen, possibly a second symptom of the same contention: in two surviving trials the polls themselves degraded badly while streaming continued — 45 of 62 telemetry queries failed on one v1 trial, 7 of 89 on a v2 4-camera trial — so the COMM channel and the HISTO endpoint appear to starve each other in both directions.

Raw per-trial records: wedge_ab_results.jsonl, harness wedge_ab.py (bench scratchpad).

[boringethan]

Root cause: a shared, non-atomic register between COMM and HISTO transfer arming

Not USB bandwidth and not the telemetry response size — a two-instruction race on a device-wide register.

The OTG core runs in slave mode (usbd_conf.c, Init.dma_enable = DISABLE), so packet data only reaches an endpoint FIFO because that endpoint's TX-FIFO-empty interrupt is enabled. Every IN endpoint's enable bit lives in one register, and USB_EPStartXfer sets its bit with a plain read-modify-write:

/* Drivers/STM32H7xx_HAL_Driver/Src/stm32h7xx_ll_usb.c  USB_EPStartXfer() */
USBx_DEVICE->DIEPEMPMSK |= 1UL << (ep->num & EP_ADDR_MSK);

Three contexts arm transfers:

Context	Path	NVIC priority
Main loop	comms_host_check_received → process_if_command → USBD_COMMS_SetTxBuffer	thread
Frame ISR	USBD_HISTO_SendData → USBD_HISTO_SetTxBuffer	2
USB ISR	USBD_Histo_DataIn (multi-packet chaining)	0

The USB ISR preempts the other two. If it lands between the load and the store, the preempted caller writes back a stale mask and clears the HISTO endpoint's enable bit. HISTO's packet is never copied into the FIFO, DataIn never fires, histo_ep_data stays 1, and every later frame gets BUSY.

This accounts for each of the observations in the report:

• only HISTO dies, telemetry stays healthy — the clobbering writer keeps its own bit;
• the firmware's 125 ms background sweep is not the trigger — it is I2C only and arms no USB transfer, exactly as WEDGETEST_NOPOLL showed;
• variable onset (4.6 s vs 59.2 s) — the ISR has to land inside a specific two-instruction window, which is the "race-like" behaviour noted;
• cameras keep running, FSYNC reaches 72004 — nothing camera-side is involved.

It also explains the prior observation quoted at the bottom of this issue — 8-camera streaming + concurrent host I2C passthrough killing HISTO in ~2 s. Same collision, different COMM traffic. This bug predates telemetry; telemetry polling just made a supported workflow hit it continuously.

On the SDK docstring

get_camera_telemetry()'s "safe to poll during scans" claim was right about what it checked (the handler does no camera I2C) and wrong about the outcome, because the hazard was never in the handler — it was in transmitting the response at all. Any COMM response concurrent with streaming carries the same risk.

Fix

PR #118 masks interrupts across the arm in USBD_LL_Transmit so the read-modify-write cannot be split. The clear side (PCD_WriteEmptyTxFifo) needs no guard — it runs in the USB ISR at priority 0, which nothing touching this register can preempt.

Note on #105

The stuck-TX watchdog merged in #106 already changed this from a permanent wedge into a ~500 ms recovery, which is why next no longer dies outright. That is mitigation, not a fix: the stream still drops ~20 frames per event. This issue was filed against 1.8.2-dev.1-3-g7f8fe08, before the watchdog, which is why the original runs show delivery stopping dead and never returning.

Still owed: bench verification

Builds clean in all four configs; not yet hardware-verified. tests/test_histo_telemetry_contention_hil.py in the PR reproduces the reported scenario (stream + 1 Hz polling) and keys on arrival-gap timing rather than byte totals, since totals can't tell "clean" from "stalled and recovered repeatedly". Worth confirming it fails on current next first, so we know it discriminates.

[boringethan]

Board triage 2026-08-19: moved back to Backlog to clear the review queue. Note the merged PR #104 in this thread was the telemetry-v2 feature (shipped in 1.8.2); the actual wedge fix is PR #118 (branch fix/96-88-telemetry-wedge-deploy-bootmode), closed unmerged — reopen #118 when this is picked back up rather than redoing the work. It was written as a stack with #117 (issue #115) and #119 (issue #116); plan to review the trio together.