fix(nrf): stop a stalled USB host and stuck transfers from wedging loop() - #133
Merged
Merged
Conversation
A connect or disconnect raised while loop() is parked in idleDelay() is not serviced until the wait elapses. On nRF that wait is idleDelay(sleep_timeout_ms) -- ~40 s on the units under test -- so a client that drops mid-transfer leaves the pipe session open and the panel powered for the rest of it, and a client that connects without immediately writing waits that long for requestFastLink(). Captured on hardware: the disconnect callback logs at t+0, "Disconnect reason: 19" lands 39.9 s later, and nothing runs in between. The cause is that serviceBleEvents() is the only consumer and it runs at the top of loop(), while idleDelay()'s sole early exit was bleRxQueuePending(). A flag raised after that point in the pass is invisible until the next pass, and the next pass cannot start until the wait finishes. eventPending() is a peek, not a take, and that is the point: idleDelay() returns to loop() and serviceBleEvents() still consumes the event, so event ordering, the disconnect RX-boundary capture (bleRxQueueDiscardTo) and the deferred-cleanup flags all keep working exactly as before. Consuming here would have moved the single consumer out of loop() and broken that ordering. The break set is deliberately not the workInFlight expression. The two answer different questions -- "did work appear while we were parked?" versus "is there work?" -- and a term belongs in this one only if it can go false->true asynchronously on a task other than loop() AND idleDelay cannot service it itself. TX fails the second test (serviceBleTx() already runs every chunk); epdRefreshInProgress, the transfer-state flags, s_advertisingRestartPending and wifiLanSession fail the first (only loop() raises them, so none can change while loop() is inside this function). RX and transport events are the only two left. The wait itself is unchanged: still 100 ms chunks, so nRF still reaches sd_app_evt_wait() between them and idle current is unaffected. Interruptible, not shorter. Out of scope, deliberately: the workInFlight gate still cannot see an unconsumed event or a live transfer, so a mid-transfer disconnect still costs up to one 100 ms chunk rather than one pass. Adding transferActive() there needs care -- sendPipeNack() leaves pipeState.active set on purpose so the reported ACK position stays consistent, and there is no full-pipe watchdog to clear it, so the term must exclude pipeState.error or a fatally NACKed session would keep the device awake forever. Also unfixed: the take/clear protocol coalesces a second same-type event arriving inside its check-then-clear window. Both are pre-existing and neither is on the critical path for the park. Builds: nrf52840custom, esp32-s3-N16R8.
A stalled full PIPE transfer survives the direct-write watchdog in a split state. cleanupDirectWriteState(true) releases the panel and clears the directWrite fields, but leaves pipeState active and non-errored. The 0x0081 DATA handler gates on pipeState alone, so later frames keep being processed into a session whose hardware is gone. For an uncompressed transfer the cleared byte counters make the auto-complete test read 0 >= 0, so the very next DATA frame enters directWriteFinishAndRefresh(), calls bbepRefresh() and can sit in waitforrefresh() for up to 60 s against an unpowered panel -- a loop() stall of exactly the kind this branch exists to remove. The guard immediately above that test already warns about the same zeroed-directWrite* hazard for partial transfers; the watchdog manufactures it for full ones, where !pipeState.partial does not protect. A compressed transfer instead accepts and ACKs every frame with its payload discarded, and the eventual END runs the same invalid refresh -- reporting success for an image that was never written. The pipe-partial watchdog already resets pipeState when it tears down the shared partialCtx, and says why: "a zombie pipeState.active can't misroute later 0x0081 frames into the dead partialCtx". This applies that existing rule to the full-PIPE hardware half. It is parity with established timeout behaviour, not a new teardown rule. Both watchdogs now sit together in display_service.cpp behind checkTransferTimeouts(), and share a named TRANSFER_WATCHDOG_MS. That is cohesion, not necessity -- pipeState is reachable from main.cpp through resetPipeWriteState(), which loop() already calls on disconnect, so the fix could have stayed where it was. But keeping the two apart is how one of them came to forget the other half of an enclosing transfer, and that is worth not repeating. Deliberately unchanged: the watchdog still measures duration from START rather than idle time, so it still bounds the whole transfer rather than a stall; timeout still does not NACK the client; transferActive() and the workInFlight gate are untouched. The accompanying plan records all three as follow-ups, with the reasoning for each. Builds: nrf52840custom, esp32-s3-N16R8.
…n instead Third draft, and the second time review changed the conclusion rather than the wording. Recorded as revision history in the plan because the reasoning is the part worth keeping. Draft 2 proposed adding transferActive() to workInFlight so a half-finished transfer with the panel powered would count as work. That framing does not survive the state space. A transfer whose transport is gone cannot progress -- frames arrive only over BLE or LAN -- so the term is redundant in both states where the transfer can still advance (owner connected: ble.isConnected() / wifiLanSession already hold the gate; owner disconnecting: serviceBleDisconnectCleanup() runs before the gate and resets everything), and in the one state where it is not redundant it is a regression. That state is the orphan, and there the term holds workInFlight true until the 15-minute watchdog. workInFlight true takes delay(1), which on nRF is one tick, below configEXPECTED_IDLE_TIME_BEFORE_SLEEP, with an empty idle hook -- so it does not sleep, it spins at 64 MHz. Roughly 0.9-1.5 mAh per event on nRF52840, 6-12 mAh on an ESP32-S3 tag. It also removes an existing recovery: on battery ESP32 an orphan is self-healing today, because deep sleep is a reboot and all transfer state is plain RAM. The term would convert a self-healing state into a fifteen-minute awake one. The right response to "this state should not exist" is to remove the state, not to refuse to sleep while it exists. So the gate keeps only ble.eventPending(), and the invariant 77c2226 established becomes a runtime assertion in checkTransferTimeouts() that logs once and resets, rather than a proof obligation the gate defends by burning power. Two further corrections from the same review. The transferActive() amendment is now split: touch and WiFi-roam want "is live work in flight", but the log-quieting predicates want "would logging this frame spam", and a dead pipe still receiving frames answers those differently -- unsplit, a fatal NACK un-suppresses every remaining in-flight 0x0081 frame at ~90 fps and evicts the NACK itself from the log ring. And the >0 timestamp guards move in scope from "prerequisite for the gate term" to "backstop for the orphan assertion"; the justification changes even though the diff does not. The proof-obligations table is nearly empty as a result, which is the clearest signal the design improved: no transfer flag reaches the gate, so no transfer flag can veto sleep.
Four changes, all from docs/PLAN_WORK_GATE_TRANSFER_TERMS_2026-07-29.md. 1. workInFlight gains ble.eventPending(). A connect or disconnect can be raised by a stack callback after serviceBleEvents() has already run in this pass, and the pass is then about to park -- so the event waits for the next one. 4d37d43 made the wait itself interruptible; this stops the gate from entering it. The term is transient like every other: take*Event() clears the peeked flag at the next loop top. 2. workInFlight does NOT gain transferActive(), and the comment says so, because two earlier drafts of the plan proposed exactly that and a future reader should not "complete" the change. A viable transfer already has its connected BLE or LAN owner holding the gate; a transfer whose transport is gone cannot progress, since frames only arrive over BLE or LAN. So the term would be redundant in every state where it could matter and harmful in the one where it applies: it holds the gate until the 15-minute watchdog, and workInFlight true takes delay(1), which on nRF is a single tick -- below configEXPECTED_IDLE_TIME_BEFORE_SLEEP with an empty idle hook -- so it spins at 64 MHz rather than sleeping. Of order 0.9-1.5 mAh per event on nRF52840, 6-12 mAh on an ESP32-S3 tag. It would also remove an existing recovery: on battery ESP32 that state self-heals today, because deep sleep is a reboot and all transfer state is plain RAM. 3. checkTransferTimeouts() heals the orphan instead. 77c2226 proved a live, non-errored pipe session always has a hardware half and closed the one path that broke it; this asserts that at runtime and resets rather than resting on the proof. Placed after both watchdog branches so it is a postcondition over the whole routine: run first it would only see entry state. If the orphan ever recurs, the 0x0081 handler gates on pipeState alone and accepts frames into torn-down state, where the cleanup-zeroed byte counters make the uncompressed auto-complete read 0 >= 0 and drive a refresh at an unpowered panel. 4. Both watchdogs lose their "&& startTime > 0" sentinel. Each START sets the active flag and its millis() stamp in straight-line setup with no return between, so the flag already implies a valid stamp -- and zero is a legitimate stamp, so the sentinel would permanently disable the watchdog for a transfer beginning in the ~1 ms window where millis() wraps through zero. Of order one in 10^9 transfers: a special case removed from the invariant, not a live risk fixed. It matters here because the watchdog now backstops the assertion above. 5. transferActive() splits in two. Touch polling and the WiFi roam gate ask "is viable work in flight" and should resume once sendPipeNack() has released the panel; the log-quieting predicates ask "would logging this frame spam" and must keep the errored pipe, because frames keep arriving after a fatal NACK -- a full window from a compliant client, until END from one that ignores it. At ~90 frames/s and two lines each, un-suppressing those would evict the NACK itself from the log ring. The split also keeps the new pipeState.error read off the logging path, which bleRxQueuePush() reaches on the stack callback task. Deliberately not included: making take*Event() an atomic read-and-clear. It is a real hardening, but the exchange alone does not atomically capture the disconnect reason and RX boundary alongside the flag, so it would close less than its comment would claim. Left as residual 3 with the rest of the event protocol. Builds: nrf52840custom, esp32-s3-N16R8.
…e loop()
Adafruit_USBD_CDC::write() bounds its send loop only by tud_cdc_n_connected(),
which is literally "DTR is high". A host that keeps the port open but stops
draining the IN endpoint therefore spins it forever. On nRF that is fatal: no
watchdog, and every fault handler in the linked image is `b .`, so loop() stops,
epdSessionTick() never runs, the keep-alive never expires, and the tag goes
silent while the link stays up. Two field captures end exactly that way.
Rather than guard that loop, leave it unreachable. od_log now writes through
tud_cdc_write() -- a bare tu_fifo_write_n that takes what fits and returns the
count -- so blocking is impossible by construction instead of prevented by a
correct check. Verifiable without hardware:
arm-none-eabi-nm -C .pio/build/nrf52840custom/src/od_log.cpp.o
U tud_cdc_n_write / _available / _flush <- and no Print:: symbol at all
That reordering of what is load-bearing is the point. An earlier draft of this
change kept Stream::write and made the capacity check the thing standing between
the user and a bricked tag; six review rounds then found three defects in the
scaffolding that check needed. Here the same pieces survive for output quality,
so a bug in them costs a mangled line, not a freeze:
- capacity reservation -> line integrity, not survival
- mutex -> serialises reservation-plus-writes (TinyUSB's own FIFO is already
multi-writer safe, so a single tud_cdc_write is atomic; the span is not)
- single-writer invariant -> an integrity property, no longer a safety proof
A record that will not fit waits up to 20 ms, then is discarded and counted; the
count is spliced into the next record after its level as "[DROP: n] " -- one
line, never an extra one, absent at zero. Logging from any task other than
loop() waits zero: Bluefruit's Callback task runs at priority 2 and escalates to
3 when ada_callback()'s queue fills, and waiting above loop() is priority
inversion. Three consecutive loop-task drops presume a stall and zero the budget,
so a stalled port costs ~3 x 20 ms rather than ~300 x 20 ms across a push --
~6 s of loop() latency that would otherwise time out BLE transfers.
ESP32 is deliberately untouched: neither of its log ports can block on host
backpressure (HWCDC caps at max_consec_timeouts x tx_timeout_ms; the log UART
has flow control hardwired off), so od_port_wait_ready() short-circuits to true,
it never counts a drop, and its object references no tud_cdc at all.
Zero-drop output is byte-identical on both targets: println(buf) was already
write(buf,len) + write("\r\n",2), which is exactly what the new path issues.
All 15 environments build. tests/serial_stall_test.py reproduces the failure on
hardware -- hold DTR, stop reading -- and its phase logic is verified in both
directions against a pty.
Design record: docs/PLAN_NONBLOCKING_LOG_2026-07-29.md
Contributor
Author
|
Series of bugfixes to patch up edge cases that leave the Display stuck. Wait to merge until the next PR lands with a couple additional fixes and I have done a "burn-in" test. |
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Three related fixes to paths that can leave
loop()wedged or spinning on nRF52840, plus the shared plumbing they need. Rebased ontomainat 987c6d9 (post-#132), so the diff is purely additive: 5 commits, +524/-47 across 9 files undersrc/.nRF has no watchdog and every fault handler is
b ., so anything that can blockloop()indefinitely is unrecoverable without a power cycle. Each change below closes one such path.1. The logger can no longer be blocked by a stalled USB host
Adafruit_USBD_CDC::write()'s send loop is bounded only bytud_cdc_n_connected()— literally "DTR is high" — so it spins forever when a host holds the port open but stops draining the IN endpoint. A blocked log write blocksloop().nRF now writes through
tud_cdc_write()directly, which is a baretu_fifo_write_nthat takes what fits and returns the count, making a stalled host structurally incapable of blocking. The delivery contract becomes best-effort and is documented inod_log.h:[DROP: n]— one line, never an extra one, absent when zero.loop()get a zero wait budget: waiting there would invert priority aboveloop().loop()latency, enough to starve BLE ACK draining and time out a transfer that would otherwise complete. It resets on any successful write, so recovery needs no detection of its own.ESP32 output is unchanged. It keeps
Stream::writeand never drops or counts: neither of its log ports can block on host backpressure (HWCDC is bounded bymax_consec_timeouts × tx_timeout_ms; the log UART has flow control hardwired off, so its FIFO always drains at the baud rate). Short writes there are deliberately ignored rather than counted, so ESP32 can never take the tagged path.Two implementation details worth review attention, both load-bearing in non-obvious ways:
od_budget_ms(), thes_loopTask != NULLtest must come first.xTaskGetCurrentTaskHandle()never returns NULL under a running scheduler, so without it an uncaptured handle would make the inequality true for every caller and silently put the whole firmware into try-once-then-drop.od_port_wait_ready(), the room test must precede the expiry test, or a zero budget degenerates from "try once, then discard" into "discard without trying".vTaskDelay(1)is used rather thandelay(): the nRF core'sdelay()flushes CDC and returns early without ever callingvTaskDelaywhen that flush spans a tick, which would busy-spin at priority 2 and never yield toloop()(time slicing is disabled).A static mutex covers the span from the capacity reservation to the last write of a record. It is not a hang guard — TinyUSB's FIFO is already multi-writer safe via
CFG_FIFO_MUTEX— it prevents another producer consuming the reserved space mid-record and truncating the line.2. A direct-write timeout no longer leaves its PIPE session running
A full PIPE transfer owns a direct-write session as its hardware half. The direct-write watchdog tore down the panel but left
pipeState.activeset, so the0x0081handler kept accepting frames into a torn-down session — and because cleanup zeroes the byte counters, the uncompressed auto-complete test read0 >= 0and drove a full refresh at an unpowered panel.Both transfer watchdogs now live in
display_service.cppbeside the state they terminate, sharing oneTRANSFER_WATCHDOG_MS, and the direct-write branch resets the pipe half with it. A closing postcondition check ("a live, non-errored pipe session always has a hardware half") heals an orphan rather than only reporting it; it runs last so it also sees state either watchdog just created.The
&& startTime > 0sentinels are removed. This is invariant cleanup, not a live fix: zero is a legitimatemillis()stamp, and treating it as "unset" would permanently disable the watchdog for a transfer beginning in the ~1 ms window wheremillis()wraps through zero — order 1 in 10^9 transfers.3. A transport event interrupts the cooperative idle wait
An event raised after
serviceBleEvents()ran in a pass was invisible until the next pass — and that pass may be about to park. A new non-destructiveeventPending()peek joinsworkInFlightandidleDelay()'s early return, whileserviceBleEvents()remains the single consumer, so event ordering, the disconnect RX-boundary capture and the deferred-cleanup flags are unaffected.idleDelay()gains the membership rule for its break set: a term qualifies only if it can go false→true asynchronously on a task other thanloop()andidleDelaycannot service that work itself. RX and transport events are the only two that qualify; the comment walks each excluded term against the rule.Also:
transferActive()splits in twoCallers were asking two different questions of the same flags.
transferActive()— "is viable work in flight?" Now excludes a fatally NACKed pipe, whose panelsendPipeNack()has already released, so touch I2C polling and full-channel WiFi scans resume immediately rather than waiting for the client to speak.imageWriteFramesMayStillArrive()— "would logging this frame spam?" Keeps the errored pipe, because frames keep arriving after a fatal NACK: a client may already have a full window in flight. At ~90 frames/s and two lines each, un-suppressing them would evict the NACK itself from the log ring.The split also keeps the new
pipeState.errorread off the logging path, whichimageWriteLogQuietFrame()reaches cross-task frombleRxQueuePush().Deliberately not changed
workInFlight. A live transfer already has its connected BLE or LAN owner holding the gate, and one whose transport is gone cannot progress — holding the loop awake for it burns power for work that will never happen (on nRF adelay(1)gate is below the tickless threshold and spins rather than sleeping). That state is healed incheckTransferTimeouts()instead.Validation
tests/serial_stall_test.pyis included as a hardware-in-the-loop repro for the USB CDC stall (it holds the port open without draining and checks that the tag keeps responding);tests/README.mddocuments running it.src/command_queue.cppis comment-only — it retracts a cost claim ("blocking ~9 ms serial write") the rewrite invalidates.Notes for reviewers
Design rationale for both halves is in the two plan docs added here:
docs/PLAN_NONBLOCKING_LOG_2026-07-29.mdanddocs/PLAN_WORK_GATE_TRANSFER_TERMS_2026-07-29.md.