Frame classifier locks out a whole module for one 8-bit wrap (6.4 s) after a module-wide frame gap > 8

Summary

When a whole sensor module skips more than 8 frames at once (all 8 cameras jump together), FrameClassificationStage quarantines every subsequent frame from that module until the 8-bit wire frame ID wraps back round to the stale anchor. A sub-second hiccup becomes a fixed 6.4 s (256-frame) data hole, and the side's absolute frame count ends one wrap (256) short for the rest of the scan.

Evidence

Field log open-motion-20260918_085556.log — Open-Motion Research 1.5.2 (portable), SDK 1.11.0, host MotionDemo, console WWW04Q40007 (fw 1.8.1), sensors fw 1.8.2. Scan 20260918_160728 (60 s, both modules, all cameras). The scans immediately before and after it in the same session are clean.

09:08:15,916 quarantining frame: side=0 cam=0 packet=1837 raw_frame_id=62 timestamp=46.326000 reason=gap_too_large (forward frame-id gap +17 exceeds direct acceptance limit 8; no independent camera-outage evidence permits re-anchoring)
09:08:15,960 FrameGapFillAnomaly(side=1, cam_id=0, gap_start_fid=1842, gap_end_fid=1846, n_filled=5, timestamp_s=46.15)
09:08:18,487 quarantining frame: side=0 cam=0 packet=1948 raw_frame_id=173 timestamp=49.101000 reason=non_monotonic
09:08:21,888 Timestamp timeline re-anchored: side=0 cam=0..7 ... accepting device timestamps from frame 1845 (t=52.501s)
09:08:31,354 Scan summary: quarantined 1920 frame(s) by reason: {'gap_too_large': 888, 'non_monotonic': 1032}
09:08:31,356 terminal fsync count 2404 names abs_id 2404 but side=left cam_id=0 last delivered abs_id=2148 — camera stopped delivering 256 frames before scan end (dropout)

Arithmetic, per camera: 17 (real gap) + 111 (gap_too_large) + 129 (non_monotonic) = 257 ≈ 256 = one 8-bit wrap. 1920 quarantined = 8 cameras x 240 frames. 256 frames at 40 Hz = 6.4 s, matching the app's reported data gap of 45.9-52.3 s. Frame 1845 being assigned t=52.5 s (nominal 46.1 s) shows the left abs ids are 256 behind from then on.

Both modules hiccuped at the same instant (t~46 s): the right lost 5 frames (<= 8, gap-filled, carried on); the left lost 17 and locked out. The hardware kept delivering valid left-side frames throughout - the SDK discarded ~6 s of good data.

Mechanism (`omotion/pipeline/stages/classify.py`, unchanged between 1.11.0 and 1.12.0)

_MAX_FORWARD_GAP_FRAMES = 8: a forward step > 8 is rejected as gap_too_large without touching unwrapper state (last_raw stays at the pre-gap value).
Large re-anchoring needs allow_large_resync, which is only granted via _resync_allowed, which is only populated from _note_camera_missing -> CameraStreamGap "resumed" - i.e. when ONE camera disappears from otherwise-flowing source packets.
A whole-module skip has no packets at all during the gap, so _note_camera_missing never fires (no CAMERA STREAM ALERT in the log), so re-anchoring is never permitted.
Every later frame is therefore measured against the stale last_raw: steps +18..+127 -> gap_too_large, then the signed step goes negative -> non_monotonic, until the raw id wraps round to last_raw + 1 and is accepted as a single step. The epoch is never incremented for the wrap that happened during the lockout, so abs ids are permanently 256 low.

Downstream effects

App raises eight "Camera LEFT n dropout detected" toasts and a "Scan data gaps detected" warning that are caused by the quarantine, not by missing frames.
DarkCorrectionStage end-of-scan warning "camera stopped delivering 256 frames before scan end (dropout)" is false - the cameras ran to the end. (The content-based fallback did confirm the terminal dark, so that part degraded gracefully.)
Scheduled-dark position bookkeeping (abs id % 600) is presumably off by 256 for that side after the lockout (in this scan the scheduled dark at true frame 2400 would have been labelled 2144) - not verified from this log, worth checking when fixing.

Expected

A coherent resumed stream after a module-wide gap should re-anchor quickly (the existing two-consecutive-counter/clock-pairs confirmation is a reasonable bar), with the epoch derived from clock elapsed time so abs ids stay correct. Loss should be bounded by the real gap plus a couple of confirmation frames, not pinned at one full wrap.

Fix direction (not decided): treat "all expected cameras of a side absent for > N packets' worth of clock time, then all returning with mutually consistent ids" as outage evidence equivalent to the per-camera CameraStreamGap; or allow the resync-candidate path whenever counter and clock agree on the gap size and packet-mates agree on the id.

Contact quality failed unexpectedly on right sensor module openmotion-bloodflow-app#516 - different unit (console WWW04Q40005), but the same signature was recorded there: a 6.4 s "stall" at t~45 s. That may be this lockout rather than a real 6.4 s stall; worth re-reading that bundle for gap_too_large / non_monotonic quarantine counts.
Etch-a-sketch: corrupted frame_id misread as frame gap — fabricated frames, rewritten timestamps, zigzag live trace #220 / TimestampRepairStage: unvalidated re-anchors turn transient timestamp bursts into false-correction cascades; per-side window churn floods WARNINGs #229 - the hardening that introduced the strict acceptance rules. This is the fail-closed side of that trade going too far for module-wide gaps.
Open question tracked separately from this bug: what caused both modules to skip frames simultaneously at t~46 s in the first place.

Follow-up: what made both modules skip frames at t~46 s (the trigger, not the lockout)

Status: leading hypothesis, not confirmed - the field log has no firmware-side output (sensor debug logging was off), so this is from code reading plus a hardware-free benchmark.

Established

The frames were never sent by the firmware. The frame id comes from the camera FPGA and the packet timestamp is latched in the FSIN ISR (sensor-fw 1.8.2 main.c:2063), so "+17 ids with matching timestamps" means FSIN kept running and the MCU shipped nothing for those periods.
Two independent MCUs skipping at the same instant points at the one thing they share: the host.
The app/SDK send no COMM traffic to the sensors mid-scan in this configuration (the temperature in the dropout toast comes from the histogram stream, not a poll), and debug flags were 0xC0, so DEBUG_FLAG_USB_PRINTF is off and the firmware's diagnostics do not go through the 500 ms COMM TX busy-wait (sensor-fw#115). That leaves HISTO back-pressure: host stops reading the HISTO endpoints -> firmware's 4-deep TX queue (usbd_histo.c:22, ~5 frames incl. the in-flight one) fills -> new frames are dropped (HISTO enqueue fail: queue full), cameras untouched, clean resume. That matches "all 8 cameras, no camera death, clean resume".

Leading hypothesis: dark-interval close stalls the single pipeline thread, which back-pressures BOTH readers

The scheduled dark at abs frame 1801 (t=45.0 s) closes the [1201, 1801] interval for all 8 cameras of a side at once. DarkCorrectionStage batch correction -> shot noise -> BFI/BVI -> dark-frame hold then run as per-frame Python loops over ~4800 frames per side, and ScanDBSink writes them as 24 x executemany + commit (batch_size=200), all synchronously on the one ScanWorkflow-scan thread, left then right back-to-back.
LiveUsbSource._batch_queue is maxsize=4 and shared by both sides, fed with an untimed put (sources.py:228, :395). A batch is 2 frames, so ~0.2 s of runner stall blocks both parser threads; the per-side packet queues (64 x 4096 B, because the bulk read size is HISTOGRAM_BYTES=4096 for a 32837 B packet) absorb another ~0.2 s; then both _stream_loops sit in data_queue.put(timeout=1.0) and stop calling dev.read on both HISTO endpoints at once. Total slack before frames are lost: roughly 0.4 s host + 0.125 s firmware.
Timing fits: stall begins ~45.05-45.3 s, buffers exhaust ~0.5 s later, last delivered left frame was 1837 (t=45.93 s).
It would also explain why app#516 (different unit) saw its glitch at t~45 s.

Benchmark (hardware-free, dev desktop, SDK 1.12.0, real `default_pipeline` + on-disk `ScanDBSink`, synthetic 60 s / 2 sides / 8 cams)

Steady-state batch: median 1.7 ms, p99 9 ms. The six slowest batches in every run are exactly the interval closes at t=15.03 / 30.03 / 45.03 s: 70-95 ms per side (~1/3 pipeline, ~2/3 DB sink), i.e. ~170 ms back-to-back, with nothing else competing for the GIL. No growth across three consecutive scans into the same DB on this machine.

So on a quiet fast desktop the stall is about a third of the available slack. On the field host (Tiger Lake laptop) the same work contends for the GIL with two parser threads (pure-Python RLE decompress), the live-plot sink and the 30 Hz GUI repaint, plus whatever the disk/AV does to 24 commits - reaching 0.5-1 s there is plausible but unproven. It is consistent with the failure being intermittent (1 of 3 scans in this session).

Not explained yet

Why the third close (45 s) rather than 15/30 s, on two units. Candidates: WAL autocheckpoint landing in that commit burst, the 3 s plot autoscale (whose cost grows with scan time) aligning with it, or chance. The benchmark shows no intrinsic growth.
The 17 vs 5 asymmetry between sides (left is processed first, so its reader is unblocked later - direction fits, magnitude unverified).

How to confirm (cheap, no firmware change)

Log wall-clock duration of each interval close + ScanDBSink flush, and the high-water mark of _batch_queue / packet queues, at INFO. One field scan then settles it.
On a bench unit with sensorDebugLogging off but the debug UART attached: look for HISTO enqueue fail: queue full / [CMP] USB FAIL at the gap (back-pressure) vs a mid-scan Scan finished/Scan started pair (main-loop stall > 150 ms).

Independent hardening, if the hypothesis holds

Move interval-close work / DB writes off the runner thread, or chunk them so the runner yields between cameras; one commit per interval instead of 24.
Give each side its own batch queue and size the bulk read to the packet (32837 B) so host-side slack is what the queue depth implies.

Second field unit with this exact signature: OpenwaterHealth/openmotion-bloodflow-app#516 (console WWW04Q40005, app 1.5.1 / SDK 1.11.0), closed as a duplicate of this issue. Simultaneous both-module skip at t≈45.7 s (left 7 frames = filled, right 9 = locked out 6.4 s), then right-side abs numbering 256 low for the remaining ~5.5 min, so every scheduled right dark landed on a light frame (176 DarkIntegrityWarnings, all right) and CQ never recovered. The user-visible damage is the permanent 256-frame offset, not just the 6.4 s hole.

Test of the trigger hypothesis: reproduced in software, end to end

Hardware-free harness (not yet committed), built exactly like ScanWorkflow.start_scan: real StreamInterface read loop, LiveUsbSource, default_pipeline, ScanRunner, on-disk ScanDBSink, DiagnosticsLogSink, CsvSink, ContactQualityMonitor, and the app's real _LivePlotSink + LiveScanSource. Only the sensor is emulated behind dev.read(): 40 Hz frames on both sides, RLE TYPE_HISTO_CMP packets, the real dark schedule, and a 1-in-flight + 4-queued TX queue that drops new frames when full. SDK next 09bdbb8, app next f2ac64e, Core Ultra 7 155H desktop.

Result: once the scan thread spends more than about 0.65 s on a dark-interval close (both sides back to back), the host queues fill, the USB reads stop, and the emulated sensor drops frames on both modules at the same instant. Past about 0.9 s the gap exceeds 8 frames and the full field signature follows.

With +60 ms injected per ScanDBSink final write at the 15 s close (62 s scan):

the close took 0.56 s + 0.63 s back to back;
USB reads paused about 620 ms;
22 left and 20 right frames were dropped at 15.73 / 15.75 s;
the classifier locked out: 3,760 frames quarantined, timeline re-anchored at 22.3 s;
the next closes came at 36.4 s and 51.4 s instead of 30 and 45 s;
32 dark frame brighter than expected warnings followed (u1 199–351 DN vs pedestal 128). The lit frames were still used as the dark reference.

Scenario	Worst close, both sides	Dropped L/R	Outcome
Fresh DB, 60 s	0.16 s	0/0	clean
636 MB real research DB, 60 s	0.33 s	0/0	clean, packet queues peaked 28/64
Same + heavy GUI-like Python load	0.48 s	0/0	clean, packet queues peaked 52/64
+40 ms per DB write	0.79 s	5/4, same instant	gap-filled
+60 ms per DB write	1.11 s	17/18, same instant	lockout, both sides
+60 ms per DB write, larger host queues (512 packet, 64 batch)	1.12 s	0/0	clean, max USB read pause 36 ms

It is back-pressure, not CPU starvation of the USB readers. With bigger queues, the identical stall lost nothing: the readers keep reading as long as there is somewhere to put the data. The shipping sizes give about 0.65 s of total headroom:

shared batch queue, 4 batches, about 100 ms;
per-side packet queue, 64 × 4 KB reads, about 400 ms;
sensor TX queue, 5 frames, 125 ms.

On a fast desktop a normal scan already uses up to about 0.48 s of that headroom at a close.

Still owed: proof that field hosts actually stall that long. Their CPU, disk, antivirus and GUI thread aren't reproduced here. The cheap confirmation from the comment above still applies: log each interval close's duration and the queue high-water marks at INFO, and capture the sensor debug UART at a gap.

WAL checkpoints landed inside the 30 s and 45 s closes. They were cheap on this SSD, but they are a plausible reason slower hosts fail at the later closes.

Related, found in the same trace: DarkCorrectionStage ignores its own DarkIntegrityGuard verdict (dark.py:478-482 appends the lit frame to the dark history and uses it as the interval boundary). That is what turns the 256-frame offset into corrupted output for the rest of the scan.

Starting work (2026-09-24).

Reproduced at unit level (FrameClassificationStage fed packet-shaped batches, 8 cameras, a whole-module gap at frame 1837): any gap of 8+ missing frames locks out.

200-250 captures are quarantined.
Every frame accepted afterwards has the wrong abs id for the rest of the scan, so no post-gap frame is ever labelled dark correctly.
Gaps of 200 and 273 frames end with wrong abs ids as well: the 8-bit id alone can't express gaps of 128 frames or more.
Secondary effect: after the lockout the clock anchor never re-syncs, so any later 2-8 frame gap is also rejected as counter_clock_mismatch until the anchor is ~64 s old.

Planned fix: re-anchor from the clock, confirmed by the next frame. When a frame fails direct acceptance (step > 8, or step <= 0):

Compute the abs id the device clock implies: clock_abs + round(elapsed / 25 ms), allowing ±1 for crystal drift over long gaps.
Take that as a candidate only if its low byte equals the wire id.
Re-anchor only if the next frame continues it (+1 frame, ~25 ms). The epoch comes from the clock, so abs ids stay correct for a gap of any length.

Why this keeps #220's protections. The #220 cases fail at step 2 or 3:

A corrupted frame id with a real timestamp: its low byte won't match the clock.
A single capture with matched counter+timestamp corruption (test_matched_large_counter_and_timestamp_jump_fails_closed): the next clean frame doesn't continue from it.

Simplification. Since that evidence covers one-camera outages too, the separate "camera went missing" permission (_resync_allowed / allow_large_resync) becomes unnecessary and can be removed. The CameraStreamGap alerts stay.

Intentional behaviour change. test_unannounced_large_gap_fails_closed_without_delivery_evidence encodes the current lockout and will change: after this, a coherent resumed stream re-anchors, losing only the first resumed frame.

The end-to-end check is the stall harness: induce a real gap with the old packet queue and expect the next dark-interval closes on schedule and zero dark-integrity warnings.

PR up: #294. After a gap, the frame counter re-anchors from the device clock and needs the next frame to confirm it. The camera-outage permission it replaces is removed. #220's etch-a-sketch suite passes unchanged.

In the stall harness, a forced ~18-frame gap on both modules now loses only the first resumed capture per side:

16 rows quarantined, down from 3,760;
dark-interval closes stay at 15/30/45/60 s, instead of shifting to 36.4/51.4 s;
zero lit frames used as darks.

A 58-frame gap behaves the same, and gaps past 127 frames, including 256·n + 1, get the right epoch from the clock. Not yet run on hardware; #222's sensor-fw fault-injection matrix is the bench check.

Available for verification in app 1.5.4-dev.2 (bbb226e), which installs openmotion-sdk from next (683057d).

Verified on hardware with tests/test_frame_gap_resync.py from the HIL suite (5/5 passed), app 1.5.4-dev.4 (SDK 1.9.0.post1.dev267 from next, contains #294), console fw 1.8.2-dev.5, sensor fw 1.8.2, one module, 8 cameras.

Gap injection: laser-less stream with DEBUG_FLAG_HISTO_STALL armed (sensor-fw#75); the stall tripped at frame 1799 (45.0 s) and the flag was cleared over the command link 0.40 s later. Result: one module-wide gap of +17 frames on all 8 cameras at the same packet boundary, clock +425 ms, no packets during it — the same signature as open-motion-20260918_085556.log.

Same capture through both classifiers:

installed (with fix: re-anchor the frame counter from the device clock after a gap #294): 1 row quarantined per camera (gap_too_large, the held first resumed frame), no non_monotonic, abs ids after the gap match the device clock to the frame (offset 0) through the 10 s tail.
pre-fix: re-anchor the frame counter from the device clock after a gap #294 (next @ 4d4159c): 240 rows quarantined per camera (gap_too_large 111 + non_monotonic 129), final abs ids 256 low — the lockout described above, reproduced to the frame.

Not covered in this run: a two-module laser scan end to end; shown in the stall harness on the PR. Closing.

Navigation Menu

Repository navigation

Frame classifier locks out a whole module for one 8-bit wrap (6.4 s) after a module-wide frame gap > 8 #286

Summary

Evidence

Mechanism (`omotion/pipeline/stages/classify.py`, unchanged between 1.11.0 and 1.12.0)

Downstream effects

Expected

Related

Follow-up: what made both modules skip frames at t~46 s (the trigger, not the lockout)

Established

Leading hypothesis: dark-interval close stalls the single pipeline thread, which back-pressures BOTH readers

Benchmark (hardware-free, dev desktop, SDK 1.12.0, real `default_pipeline` + on-disk `ScanDBSink`, synthetic 60 s / 2 sides / 8 cams)

Not explained yet

How to confirm (cheap, no firmware change)

Independent hardening, if the hypothesis holds

Test of the trigger hypothesis: reproduced in software, end to end

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Frame classifier locks out a whole module for one 8-bit wrap (6.4 s) after a module-wide frame gap > 8 #286

Description

Summary

Evidence

Mechanism (omotion/pipeline/stages/classify.py, unchanged between 1.11.0 and 1.12.0)

Downstream effects

Expected

Related

Activity

boringethan commented on Sep 18, 2026

Follow-up: what made both modules skip frames at t~46 s (the trigger, not the lockout)

Established

Leading hypothesis: dark-interval close stalls the single pipeline thread, which back-pressures BOTH readers

Benchmark (hardware-free, dev desktop, SDK 1.12.0, real default_pipeline + on-disk ScanDBSink, synthetic 60 s / 2 sides / 8 cams)

Not explained yet

How to confirm (cheap, no firmware change)

Independent hardening, if the hypothesis holds

boringethan commented on Sep 24, 2026

boringethan commented on Sep 24, 2026

Test of the trigger hypothesis: reproduced in software, end to end

boringethan commented on Sep 24, 2026

boringethan commented on Sep 24, 2026

boringethan commented on Oct 3, 2026

vpennam commented on Oct 8, 2026

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions

Mechanism (`omotion/pipeline/stages/classify.py`, unchanged between 1.11.0 and 1.12.0)

Benchmark (hardware-free, dev desktop, SDK 1.12.0, real `default_pipeline` + on-disk `ScanDBSink`, synthetic 60 s / 2 sides / 8 cams)