From 1ca5bf40b9cff0ebf0fd5c74dd31a1df7f641a59 Mon Sep 17 00:00:00 2001 From: David Lee <247393336+davelee98@users.noreply.github.com> Date: Wed, 29 Jul 2026 10:24:53 -0400 Subject: [PATCH 1/5] fix(ble): let a transport event interrupt the cooperative idle wait 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. --- src/ble_transport.h | 13 ++++++++++++- src/ble_transport_esp32.cpp | 4 ++++ src/ble_transport_nrf.cpp | 4 ++++ src/main.cpp | 26 +++++++++++++++++++------- 4 files changed, 39 insertions(+), 8 deletions(-) diff --git a/src/ble_transport.h b/src/ble_transport.h index e324269..c77af49 100644 --- a/src/ble_transport.h +++ b/src/ble_transport.h @@ -58,7 +58,18 @@ class BleTransport { void boostAdvertising(); // nRF: temporary fast advertising interval void tick(); // periodic housekeeping (advertising interval restore) - // --- events: consume-once, polled from loop(). No app-facing callbacks. --- + // --- events: polled from loop(), consumed once by the take*() pair below. + // No app-facing callbacks. --- + // Non-destructive peek. Cooperative waits need to return to loop() on an event + // without taking it away from serviceBleEvents(), which remains the single + // consumer -- so event ordering, the disconnect RX-boundary capture and the + // deferred-cleanup flags are all unaffected by anything that polls this. + // + // The backing flags are plain volatile, and the existing take/clear protocol + // has a known pre-existing coalescing weakness: a second same-type event + // arriving inside the check-then-clear window is lost. This peek neither + // introduces nor worsens that; fixing it is a separate change. + bool eventPending() const; bool takeConnectedEvent(); // Optionally reports the stack's disconnect reason code, which is otherwise // lost now that the callback no longer runs application code inline. diff --git a/src/ble_transport_esp32.cpp b/src/ble_transport_esp32.cpp index 808260e..79348e7 100644 --- a/src/ble_transport_esp32.cpp +++ b/src/ble_transport_esp32.cpp @@ -334,6 +334,10 @@ void BleTransport::tick() { // No-op: nothing periodic to restore, since boostAdvertising() is a no-op. } +bool BleTransport::eventPending() const { + return s_connectedEvent || s_disconnectedEvent; +} + bool BleTransport::takeConnectedEvent() { if (!s_connectedEvent) return false; s_connectedEvent = false; diff --git a/src/ble_transport_nrf.cpp b/src/ble_transport_nrf.cpp index 50ff656..424a55e 100644 --- a/src/ble_transport_nrf.cpp +++ b/src/ble_transport_nrf.cpp @@ -316,6 +316,10 @@ void BleTransport::tick() { Bluefruit.Advertising.start(0); } +bool BleTransport::eventPending() const { + return s_connectedEvent || s_disconnectedEvent; +} + bool BleTransport::takeConnectedEvent() { if (!s_connectedEvent) return false; s_connectedEvent = false; diff --git a/src/main.cpp b/src/main.cpp index b2842bc..d1410e1 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -701,14 +701,26 @@ void idleDelay(uint32_t delayMs) { // idleDelay would otherwise hold queued ACKs for its full duration. // Draining TX is safe here because it only notifies; it dispatches nothing. serviceBleTx(); - // RX is deliberately NOT drained here -- return to loop() and let - // serviceBleRx() dispatch at top level instead. Dispatching inside - // idleDelay would make command handlers reentrant the moment anything - // calls idleDelay from a handler, corrupting multi-frame transfer state. - // Returning early also caps command latency at one CHECK_INTERVAL_MS - // rather than the caller's full delay, which is what makes nRF's move to + // RX and transport events are deliberately NOT serviced here -- return to + // loop() and let serviceBleEvents()/serviceBleRx() handle them at top + // level. Dispatching RX inside idleDelay would make command handlers + // reentrant the moment anything calls idleDelay from a handler, corrupting + // multi-frame transfer state; consuming events here would move the single + // consumer out of loop() and break the ordering serviceBleEvents() relies + // on. Returning early also caps latency at one CHECK_INTERVAL_MS rather + // than the caller's full delay, which is what makes nRF's move to // loop()-side dispatch viable: its idle waits are 500 ms and up. - if (bleRxQueuePending()) return; + // + // This break set answers "did work appear while we were parked?", which is + // NOT the question workInFlight answers ("is there work?"). A term belongs + // here only if (i) it can go false->true asynchronously, on a task other + // than loop(), and (ii) idleDelay cannot service that work itself. RX and + // transport events are the only two that qualify. bleTxQueuePending() is + // excluded because serviceBleTx() already runs every chunk above; + // epdRefreshInProgress, the transfer-state flags, s_advertisingRestartPending + // and wifiLanSession are excluded because only loop() itself raises them, + // so none can change while loop() is sitting inside this function. + if (bleRxQueuePending() || ble.eventPending()) return; uint32_t chunkDelay = (remainingDelay > CHECK_INTERVAL_MS) ? CHECK_INTERVAL_MS : remainingDelay; delay(chunkDelay); remainingDelay -= chunkDelay; From 1135899f58ff6cd753159c524c990dde03b486a9 Mon Sep 17 00:00:00 2001 From: David Lee <247393336+davelee98@users.noreply.github.com> Date: Wed, 29 Jul 2026 12:10:43 -0400 Subject: [PATCH 2/5] fix(pipe): terminate the pipe session when the transfer watchdog fires 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. --- ...LAN_WORK_GATE_TRANSFER_TERMS_2026-07-29.md | 316 ++++++++++++++++++ src/display_service.cpp | 26 +- src/display_service.h | 7 +- src/main.cpp | 12 +- 4 files changed, 350 insertions(+), 11 deletions(-) create mode 100644 docs/PLAN_WORK_GATE_TRANSFER_TERMS_2026-07-29.md diff --git a/docs/PLAN_WORK_GATE_TRANSFER_TERMS_2026-07-29.md b/docs/PLAN_WORK_GATE_TRANSFER_TERMS_2026-07-29.md new file mode 100644 index 0000000..99f1f9d --- /dev/null +++ b/docs/PLAN_WORK_GATE_TRANSFER_TERMS_2026-07-29.md @@ -0,0 +1,316 @@ +# Plan — terminate orphaned transfers, then teach `workInFlight` about them + +**Date:** 2026-07-29 +**Branch:** `fix/loop-hang-3` +**Follows:** `4d37d43` *fix(ble): let a transport event interrupt the cooperative idle wait* + +Part (b) of the three-part fix for the ~40 s post-disconnect park. Parts (a) and +(c) landed in `4d37d43`. + +**Revision note.** The first draft of this plan proposed a single change: amend +`transferActive()` to exclude `pipeState.error` and add it to `workInFlight`. +Review found that unsafe — the 15-minute direct-write watchdog orphans full-PIPE +state in a form the exclusion does not catch, so the amended predicate would +still latch true forever. The work therefore splits into two commits, the first +of which is a real bug fix that stands on its own. + +--- + +## Commit 1 — `fix(pipe): terminate the pipe session when the transfer watchdog fires` + +### The bug (present today, independent of any gate change) + +`main.cpp` runs two transfer watchdogs: + +```cpp +if (directWriteActive && directWriteStartTime > 0) { + if (directWriteDuration > 900000UL) { // 15 min + cleanupDirectWriteState(true); // clears directWriteActive ONLY + } +} +checkPartialWriteTimeout(); // resets pipe only if pipeState.partial +``` + +`cleanupDirectWriteState()` contains no reference to `pipeState`. A **full** +(non-partial) PIPE transfer whose client stalls past 15 minutes therefore lands +in a split state: + +| Flag | After the watchdog | +|---|---| +| `directWriteActive` | `false` — panel torn down, rail cut, touch resumed | +| `partialCtx.active` | `false` | +| `pipeState.active` | **`true`** | +| `pipeState.error` | **`false`** | + +The pipe half survives its own hardware half. The `0x0081` DATA handler gates on +`pipeState`, not on `directWriteActive` (`if (!pipeState.active || pipeState.error) return;`), +so the session keeps accepting frames after its panel is gone. The only exits are +a replacement `0x0080` START, an END, or a disconnect. + +**The consequence is worse than lost frames.** `cleanupDirectWriteState()` zeroes +`directWriteTotalBytes`, `directWriteBytesWritten` and `directWriteCompressed`. +That is precisely the state the auto-complete guard already warns about — the +existing comment at `display_service.cpp:2820-2824` reads: + +> MUST be gated on `!partial`: a partial transfer never touches `directWrite*` +> (both are 0), so `0>=0` would false-fire a FULL refresh on the very first frame + +The watchdog manufactures that same zeroed state for a **full** transfer, where +the `!pipeState.partial` guard does not apply. So on an *uncompressed* full pipe, +the next `0x0081` frame trips `directWriteBytesWritten >= directWriteTotalBytes` +as `0 >= 0` and calls `directWriteFinishAndRefresh()`, which issues +`bbepRefresh()` + `waitforrefresh(60)` **against an unpowered panel with no +`epdSessionAcquire()`**. If the floating BUSY line reads busy, that spins +`delay(10)` for up to **60 seconds inside `loop()`** — the exact class of stall +this branch exists to remove. + +On a *compressed* full pipe, auto-complete is gated off, so every frame is +accepted and ACKed with its payload silently discarded, and the eventual `0x0082` +END runs the same bogus refresh — reporting success for an image that was never +written. + +Scope: this only bites while the owning client stays connected across the 15 +minutes, since `serviceBleDisconnectCleanup()` resets pipe state on disconnect. + +The asymmetry exists because the two watchdogs were written in different files: +the partial one sits in `display_service.cpp` beside the state it must clear, the +direct one in `main.cpp`, where reaching that state means going through an +accessor rather than seeing it inline. Nothing prevented it — see the correction +under *The change* — but nothing prompted it either. + +### The change + +**Correction to an earlier draft:** this plan previously claimed the fix *had* to +move into `display_service.cpp` because `pipeState` is file-static and +unreachable from `main.cpp`. That is wrong. `display_service.h` already declares +both `resetPipeWriteState()` (:64) and `pipeWriteActive()` (:66), and `main.cpp` +already calls the former at :404. The minimal fix is two lines in `loop()`: + +```c +cleanupDirectWriteState(true); +if (pipeWriteActive()) resetPipeWriteState(); +``` + +Moving the block is therefore a **cohesion** choice, not a necessity — the two +watchdogs belong together beside the state they terminate, and their separation +is why one of them forgot the pipe. Recommended, but the commit message must not +claim it was required. + +**`display_service.h`** — replace the `checkPartialWriteTimeout()` declaration: + +```c +// Both transfer watchdogs, together: the direct-write timeout must terminate the +// enclosing pipe session, and keeping the two apart is exactly how it came to +// tear down the panel and leave that session running. +void checkTransferTimeouts(void); +``` + +**`display_service.cpp`** — the direct block moves in, and gains the pipe +teardown: + +```c +void checkTransferTimeouts(void) { + if (directWriteActive && directWriteStartTime > 0 && + (millis() - directWriteStartTime) > TRANSFER_WATCHDOG_MS) { + od_log_error("ERROR: Direct write timeout (%u ms) - cleaning up stuck state", + (unsigned)(millis() - directWriteStartTime)); + cleanupDirectWriteState(true); + // A full PIPE owns this direct-write session as its hardware half. Reset + // the pipe with it: leaving pipeState.active set orphans a transfer with + // no panel, and the 0x0081 handler gates on pipeState, so it would keep + // accepting frames into a torn-down session. Deliberately NOT folded into + // cleanupDirectWriteState(), which normal END also calls and where the + // pipe reset is already sequenced separately. + if (pipeState.active) resetPipeWriteState(); + } + checkPartialWriteTimeout(); // unchanged; already resets pipe when partial +} +``` + +**`main.cpp`** — the two calls collapse to one; the 15-minute literal and the log +line move out with the block. + +### Why reset rather than NACK + +Disconnect cleanup already resets rather than notifies, and after 15 minutes of +silence there is rarely a client to tell. Reset also cannot fail on a dead link, +where `sendPipeNack()` would queue a response that `serviceBleTx()` discards. + +### Test + +- **Full PIPE watchdog, uncompressed.** Start an *uncompressed* full PIPE + transfer, send a few frames, stop, **stay connected**. After 15 minutes assert: + the timeout logs once, the panel powers down, and a subsequent `0x0081` frame is + rejected rather than processed. Before this commit that frame trips the `0>=0` + auto-complete and drives `bbepRefresh()` at a dead panel — run it once against + unfixed code to confirm the test has teeth, and watch for the up-to-60 s + `waitforrefresh()` stall. +- **Full PIPE watchdog, compressed.** Same, but assert the eventual `0x0082` END + does not report success for an image that was never written. +- **Pipe-partial watchdog.** Unchanged behaviour; regression only. +- **Normal END.** Confirm the reordered call site did not disturb the ordinary + completion path. + +### Why it stands alone + +It fixes a live defect — frames processed into a torn-down session — with no +dependency on the gate change. It is also the prerequisite for Commit 2. + +--- + +## Commit 2 — `fix(ble): count unconsumed events and live transfers as work` + +### What is still wrong after `4d37d43` + +```cpp +const bool workInFlight = bleRxQueuePending() || bleTxQueuePending() || + ble.isConnected() || + s_advertisingRestartPending || + epdRefreshInProgress || + wifiLanSession; +``` + +Two blind spots: an event raised after `serviceBleEvents()` ran in this pass, and +a live transfer with the panel powered. Consequence today is bounded — one +`CHECK_INTERVAL_MS` (~100 ms) rather than the original 40 s, because `4d37d43` +makes the wait interruptible — but the gate is still wrong about what constitutes +work, and it governs ESP32 deep sleep. + +### The change + +**`display_service.cpp`** — `transferActive()` stops reporting dead sessions: + +```c +bool transferActive(void) { + // pipeState.error means the session is dead but deliberately remembered: + // sendPipeNack() keeps pipeState so the reported ACK position stays + // consistent for the client, and the panel has already been released. That + // is bookkeeping, not work. A genuinely live transfer always has + // directWriteActive (full pipe/direct START -> directWriteActivatePanel) or + // partialCtx.active (0x76 / pipe-partial START) set, so excluding the errored + // case never under-reports -- given Commit 1, which stops the watchdog + // leaving a non-errored pipe behind with neither hardware flag set. + return directWriteActive || partialCtx.active || + (pipeState.active && !pipeState.error); +} +``` + +**`main.cpp`** — two terms: + +```diff + const bool workInFlight = bleRxQueuePending() || bleTxQueuePending() || + ble.isConnected() || ++ ble.eventPending() || + s_advertisingRestartPending || + epdRefreshInProgress || ++ transferActive() || + wifiLanSession; +``` + +### Why amend `transferActive()` rather than add a gate-only predicate + +It has four other callers — `touch_input.cpp:587`, `wifi_service.cpp:697`, and +two log-quieting predicates at `display_service.cpp:1898-1903`. Each asks "is a +transfer in flight?" and each is currently told "yes" by a session that is dead +and whose panel has already been released: touch polling stays suspended, WiFi +roam scans stay blocked, and frames the session is silently discarding are +suppressed from the log rather than shown. Reviewed individually, none of the +four is protected by the current behaviour. Amending fixes the meaning once; a +separate narrow predicate would fork the concept and leave the misuse in place. + +### Proof obligations + +| Term | Set by | Cleared by | Cannot latch because | +|---|---|---|---| +| `ble.eventPending()` | stack callbacks | `take*Event()` at the next loop top | Survives at most to the next pass; the peek clears nothing, the take always runs | +| `directWriteActive` | `directWriteActivatePanel()` only | `cleanupDirectWriteState()` only — END, NACK, replacement START, refresh completion/failure, disconnect cleanup, watchdog | Single set site, single clear site, watchdog backstop | +| `partialCtx.active` | `0x76` START, pipe-partial START | whole-struct `memset` in `cleanup_partial_write_state()` | Watchdog backstop via `checkPartialWriteTimeout()` | +| `pipeState.active && !pipeState.error` | pipe START only | `resetPipeWriteState()` — END, auto-complete, replacement START, disconnect, **and the watchdog as of Commit 1**; or `pipeState.error` going true | Commit 1 closes the only path that produced a non-errored orphan | + +### ESP32 deep sleep — corrected claim + +The first draft asserted the new terms cannot change sleep *duration* because +neither touches `lastActivityMs`. That was too strong: `workInFlight` bypasses +`platformIdle()` entirely, so any stuck term is an independent sleep veto +regardless of the quiet window. + +The accurate claim: **for normal, fully-observed transport teardown**, sleep +behaviour is unchanged, because a live transfer already held the device awake via +`ble.isConnected()` (BLE-owned) or `wifiLanSession` (LAN-owned), and both go +false at the same point the new term does. What the change does add is a veto on +*stale* transfer state — which is precisely why Commit 1 must land first, and why +the "cleanup is dropped, not deferred" residual below is now a safety +consideration rather than documentation debt. + +### The `workInFlight` comment + +The existing text — *"Every term is transient and most are cleared earlier in +this same pass"* — becomes false and must be rewritten. It must not be replaced +with "`lastActivityMs` is the sole authority on sleep", which is also false while +`workInFlight` short-circuits `platformIdle()`. State instead: every term is +bounded either within the pass or by a terminal transfer path with a watchdog +backstop, and none is a sticky "ever happened" flag. + +### Test + +1. **Mid-transfer disconnect.** `sleep_timeout_ms` ≈ 40 s. Connect, authenticate, + start a PIPE transfer, send enough frames to power the panel, kill the link + before END. Assert `Disconnect reason:` within one pass, transfer state + cleared, panel down, advertising back up, no departed-client frame dispatched + afterwards. Repeat for full PIPE, pipe-partial, legacy partial. + *Timing caveat:* do not assert a hard sub-50 ms bound. A disconnect landing + during a synchronous refresh cannot be serviced until `waitforrefresh()` + returns; the assertion is "one pass after the handler returns", not wall-clock. +2. **The latch, fault-injected.** The obvious test — fatal NACK then disconnect — + is worthless: `serviceBleDisconnectCleanup()` calls `resetPipeWriteState()` + unconditionally before the gate is evaluated, so it passes with or without the + amendment. Reproduce instead via the path that skips cleanup: force the + `ownerStillUp` early return, or inject a lost disconnect event, then evaluate + the gate. Alternatively use the Commit 1 watchdog path, which now terminates + cleanly and can be asserted directly. +3. **ESP32 deep-sleep regression.** Battery config: idle → sleeps; connect and + disconnect with no transfer → sleeps after the re-armed window; mid-transfer + disconnect → prompt cleanup then sleeps; completed transfer → sleeps. +4. **nRF idle current.** Unchanged expected; this touches the gate, not the wait. + Any delta means a term is stuck. +5. **Build matrix.** All 11 environments, both commits. + +--- + +## Residuals — deliberately not in either commit + +0. **The watchdog is a duration timer, not an idle timer.** `directWriteStartTime` + is stamped at START and cleared only on completion or cleanup, so the 15-minute + limit measures the *whole* transfer, not silence. A genuinely healthy but slow + push — a large panel over a poor link, or a client that throttles — is aborted + mid-flight, and after Commit 1 that abort now also resets the pipe, which is + more correct but no less abrupt. Converting it to an idle timer (stamp on each + accepted frame) is a behaviour change worth its own commit and its own + argument; flagged here so the choice is deliberate rather than inherited. +1. **A fatally-NACKed pipe session is still remembered indefinitely.** + `pipeState` has no timestamp field, so there is no watchdog for a session + whose hardware half was already released by `sendPipeNack()`. Harmless after + Commit 2, since nothing reads it as work, and bounded in practice by the next + START/END/disconnect. Adding `start_ms` to `PipeWriteState` would close it. +2. **Event coalescing.** `takeDisconnectedEvent()` does check-then-clear and then + reads `s_disconnectReason`, so a second same-type event inside that window is + lost and its payload can attach to the wrong edge. `serviceBleEvents()` also + processes connect before disconnect regardless of true order. Observed in the + 8.5 h capture as a connect/disconnect/connect burst inside 400 ms. +3. **Cleanup is dropped, not deferred.** `serviceBleDisconnectCleanup()` clears + `s_disconnectCleanupPending` *before* the `ownerStillUp` test and returns, so + when the skip fires that disconnect's teardown never runs at all. Now a safety + consideration, per the deep-sleep correction above. +4. **nRF MSD cadence** is still coupled to the idle duration. + +## Risk and rollback + +| Risk | Likelihood | Mitigation | +|---|---|---| +| Commit 1 reorders the normal END path | Low | Test 1.3; the moved block is the watchdog only | +| A transfer flag latches through a path not in the table | Low after Commit 1 | Fault-injected test 2; watchdog backstops | +| ESP32 stops deep-sleeping | Low | Test 3; residual 3 is the remaining exposure | +| Amending `transferActive()` changes touch/WiFi behaviour | Low, and desirable | Only for errored sessions, where suspension was already wrong | + +Both commits revert independently. Commit 2 depends on Commit 1; Commit 1 depends +on nothing. diff --git a/src/display_service.cpp b/src/display_service.cpp index c24f7a0..fb03c01 100644 --- a/src/display_service.cpp +++ b/src/display_service.cpp @@ -575,9 +575,31 @@ static void directWriteFinishAndRefresh(uint8_t* data, uint16_t len, uint8_t end static PipeWriteState pipeState = {}; static PipeReorderSlot pipeReorder[PIPE_REORDER_SLOTS]; -void checkPartialWriteTimeout(void) { +// Shared by both watchdogs below. Measured from START, not from the last accepted +// frame, so it bounds the whole transfer rather than a stall -- see the residual +// note in docs/PLAN_WORK_GATE_TRANSFER_TERMS_2026-07-29.md before changing that. +static const uint32_t TRANSFER_WATCHDOG_MS = 900000UL; // 15 min (upload + refresh window) + +void checkTransferTimeouts(void) { + if (directWriteActive && directWriteStartTime > 0) { + uint32_t directWriteDuration = millis() - directWriteStartTime; + if (directWriteDuration > TRANSFER_WATCHDOG_MS) { + od_log_error("ERROR: Direct write timeout (%u ms) - cleaning up stuck state", (unsigned)directWriteDuration); + cleanupDirectWriteState(true); + // Parity with the pipe-partial branch below: a full PIPE transfer owns this + // direct-write session as its hardware half, so the pipe half must die with + // it. Left alive, pipeState.active keeps the 0x0081 handler accepting frames + // into a torn-down session -- and because the cleanup above zeroes the byte + // counters, the uncompressed auto-complete test reads 0 >= 0 and drives a + // full refresh at an unpowered panel. Deliberately not folded into + // cleanupDirectWriteState(), which normal END also calls and where the pipe + // reset is already sequenced separately. + if (pipeState.active) resetPipeWriteState(); + } + } + if (partialCtx.active && partialCtx.start_time > 0 && - (millis() - partialCtx.start_time) > 900000UL) { + (millis() - partialCtx.start_time) > TRANSFER_WATCHDOG_MS) { od_log_error("ERROR: Partial write timeout - cleaning up stuck state"); cleanup_partial_write_state(); // A pipe-partial transfer shares partialCtx: also clear pipeState so a zombie diff --git a/src/display_service.h b/src/display_service.h index 35fed84..03303b8 100644 --- a/src/display_service.h +++ b/src/display_service.h @@ -76,7 +76,12 @@ bool imageWriteLogQuietAck(void); bool imageWriteLogQuietFrame(const uint8_t* data, uint16_t len); extern volatile bool epdRefreshInProgress; void handlePartialWriteStart(uint8_t* data, uint16_t len); -void checkPartialWriteTimeout(void); +// Both transfer watchdogs, together. They live beside the state they terminate +// rather than in loop(): pipeState is reachable from main.cpp via +// resetPipeWriteState(), so this is cohesion rather than necessity -- but keeping +// the two apart is exactly how the direct-write timeout came to tear down the +// panel and leave its enclosing PIPE session running. +void checkTransferTimeouts(void); void cleanupPartialWriteOnDisconnect(void); // Origin (see commandOrigin()) of the transport that opened the in-flight transfer. // A disconnect must only tear down a session its own transport owns. diff --git a/src/main.cpp b/src/main.cpp index d1410e1..76ac86f 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -626,14 +626,10 @@ void loop() { // Session watchdogs. Shared as of Phase 4: these are transport-agnostic and // were ESP32-only for no reason other than living in the ESP32 loop arm, so // nRF gains them. A hung transfer there used to sit until disconnect. - if (directWriteActive && directWriteStartTime > 0) { - uint32_t directWriteDuration = millis() - directWriteStartTime; - if (directWriteDuration > 900000UL) { // 15 minute timeout (upload + refresh window) - od_log_error("ERROR: Direct write timeout (%u ms) - cleaning up stuck state", (unsigned)directWriteDuration); - cleanupDirectWriteState(true); - } - } - checkPartialWriteTimeout(); + // Both now live in display_service.cpp, beside the transfer state they tear + // down. Splitting them across files is how the direct-write one came to + // release the panel while leaving its enclosing PIPE session running. + checkTransferTimeouts(); #ifdef OPENDISPLAY_HAS_WIFI // WiFi handling runs after BLE queue processing to avoid blocking From 833643c647c5c8c807fa4890972f589676956201 Mon Sep 17 00:00:00 2001 From: David Lee <247393336+davelee98@users.noreply.github.com> Date: Wed, 29 Jul 2026 13:32:00 -0400 Subject: [PATCH 3/5] docs(plan): drop the transfer term from the work gate; heal the orphan 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. --- ...LAN_WORK_GATE_TRANSFER_TERMS_2026-07-29.md | 439 +++++++----------- 1 file changed, 179 insertions(+), 260 deletions(-) diff --git a/docs/PLAN_WORK_GATE_TRANSFER_TERMS_2026-07-29.md b/docs/PLAN_WORK_GATE_TRANSFER_TERMS_2026-07-29.md index 99f1f9d..f3d1d50 100644 --- a/docs/PLAN_WORK_GATE_TRANSFER_TERMS_2026-07-29.md +++ b/docs/PLAN_WORK_GATE_TRANSFER_TERMS_2026-07-29.md @@ -1,4 +1,4 @@ -# Plan — terminate orphaned transfers, then teach `workInFlight` about them +# Plan — orphaned transfer state: heal it, don't idle on it **Date:** 2026-07-29 **Branch:** `fix/loop-hang-3` @@ -7,195 +7,84 @@ Part (b) of the three-part fix for the ~40 s post-disconnect park. Parts (a) and (c) landed in `4d37d43`. -**Revision note.** The first draft of this plan proposed a single change: amend -`transferActive()` to exclude `pipeState.error` and add it to `workInFlight`. -Review found that unsafe — the 15-minute direct-write watchdog orphans full-PIPE -state in a form the exclusion does not catch, so the amended predicate would -still latch true forever. The work therefore splits into two commits, the first -of which is a real bug fix that stands on its own. +### Revision history ---- - -## Commit 1 — `fix(pipe): terminate the pipe session when the transfer watchdog fires` - -### The bug (present today, independent of any gate change) - -`main.cpp` runs two transfer watchdogs: - -```cpp -if (directWriteActive && directWriteStartTime > 0) { - if (directWriteDuration > 900000UL) { // 15 min - cleanupDirectWriteState(true); // clears directWriteActive ONLY - } -} -checkPartialWriteTimeout(); // resets pipe only if pipeState.partial -``` - -`cleanupDirectWriteState()` contains no reference to `pipeState`. A **full** -(non-partial) PIPE transfer whose client stalls past 15 minutes therefore lands -in a split state: - -| Flag | After the watchdog | -|---|---| -| `directWriteActive` | `false` — panel torn down, rail cut, touch resumed | -| `partialCtx.active` | `false` | -| `pipeState.active` | **`true`** | -| `pipeState.error` | **`false`** | - -The pipe half survives its own hardware half. The `0x0081` DATA handler gates on -`pipeState`, not on `directWriteActive` (`if (!pipeState.active || pipeState.error) return;`), -so the session keeps accepting frames after its panel is gone. The only exits are -a replacement `0x0080` START, an END, or a disconnect. - -**The consequence is worse than lost frames.** `cleanupDirectWriteState()` zeroes -`directWriteTotalBytes`, `directWriteBytesWritten` and `directWriteCompressed`. -That is precisely the state the auto-complete guard already warns about — the -existing comment at `display_service.cpp:2820-2824` reads: - -> MUST be gated on `!partial`: a partial transfer never touches `directWrite*` -> (both are 0), so `0>=0` would false-fire a FULL refresh on the very first frame - -The watchdog manufactures that same zeroed state for a **full** transfer, where -the `!pipeState.partial` guard does not apply. So on an *uncompressed* full pipe, -the next `0x0081` frame trips `directWriteBytesWritten >= directWriteTotalBytes` -as `0 >= 0` and calls `directWriteFinishAndRefresh()`, which issues -`bbepRefresh()` + `waitforrefresh(60)` **against an unpowered panel with no -`epdSessionAcquire()`**. If the floating BUSY line reads busy, that spins -`delay(10)` for up to **60 seconds inside `loop()`** — the exact class of stall -this branch exists to remove. - -On a *compressed* full pipe, auto-complete is gated off, so every frame is -accepted and ACKed with its payload silently discarded, and the eventual `0x0082` -END runs the same bogus refresh — reporting success for an image that was never -written. - -Scope: this only bites while the owning client stays connected across the 15 -minutes, since `serviceBleDisconnectCleanup()` resets pipe state on disconnect. - -The asymmetry exists because the two watchdogs were written in different files: -the partial one sits in `display_service.cpp` beside the state it must clear, the -direct one in `main.cpp`, where reaching that state means going through an -accessor rather than seeing it inline. Nothing prevented it — see the correction -under *The change* — but nothing prompted it either. - -### The change - -**Correction to an earlier draft:** this plan previously claimed the fix *had* to -move into `display_service.cpp` because `pipeState` is file-static and -unreachable from `main.cpp`. That is wrong. `display_service.h` already declares -both `resetPipeWriteState()` (:64) and `pipeWriteActive()` (:66), and `main.cpp` -already calls the former at :404. The minimal fix is two lines in `loop()`: - -```c -cleanupDirectWriteState(true); -if (pipeWriteActive()) resetPipeWriteState(); -``` - -Moving the block is therefore a **cohesion** choice, not a necessity — the two -watchdogs belong together beside the state they terminate, and their separation -is why one of them forgot the pipe. Recommended, but the commit message must not -claim it was required. - -**`display_service.h`** — replace the `checkPartialWriteTimeout()` declaration: - -```c -// Both transfer watchdogs, together: the direct-write timeout must terminate the -// enclosing pipe session, and keeping the two apart is exactly how it came to -// tear down the panel and leave that session running. -void checkTransferTimeouts(void); -``` - -**`display_service.cpp`** — the direct block moves in, and gains the pipe -teardown: +This plan has been rewritten twice under review, and both rewrites changed the +conclusion rather than the wording. Recorded because the reasoning matters more +than the diff. -```c -void checkTransferTimeouts(void) { - if (directWriteActive && directWriteStartTime > 0 && - (millis() - directWriteStartTime) > TRANSFER_WATCHDOG_MS) { - od_log_error("ERROR: Direct write timeout (%u ms) - cleaning up stuck state", - (unsigned)(millis() - directWriteStartTime)); - cleanupDirectWriteState(true); - // A full PIPE owns this direct-write session as its hardware half. Reset - // the pipe with it: leaving pipeState.active set orphans a transfer with - // no panel, and the 0x0081 handler gates on pipeState, so it would keep - // accepting frames into a torn-down session. Deliberately NOT folded into - // cleanupDirectWriteState(), which normal END also calls and where the - // pipe reset is already sequenced separately. - if (pipeState.active) resetPipeWriteState(); - } - checkPartialWriteTimeout(); // unchanged; already resets pipe when partial -} -``` +**Draft 1** — amend `transferActive()` to exclude `pipeState.error`, add it and +`ble.eventPending()` to `workInFlight`. *Refuted:* the 15-minute direct-write +watchdog orphans full-PIPE state in a form the exclusion does not catch, so the +predicate would still latch true forever. Split into two commits, the first a +standalone bug fix. -**`main.cpp`** — the two calls collapse to one; the 15-minute literal and the log -line move out with the block. +**Draft 2** — Commit 1 (the watchdog fix) landed as `77c2226`; Commit 2 kept the +gate terms. *Refuted:* `transferActive()` in the gate is redundant in every state +where the transfer can still progress, and actively harmful in the states where +it cannot — it converts a low-power park into up to fifteen minutes of full-CPU +spinning. The invariant it was meant to enforce is better enforced by healing the +orphan than by refusing to sleep on it. -### Why reset rather than NACK +**This draft** keeps `ble.eventPending()`, drops `transferActive()` from the gate, +and replaces it with a self-healing assertion in the watchdog. -Disconnect cleanup already resets rather than notifies, and after 15 minutes of -silence there is rarely a client to tell. Reset also cannot fail on a dead link, -where `sendPipeNack()` would queue a response that `serviceBleTx()` discards. +--- -### Test +## Commit 1 — landed as `77c2226` -- **Full PIPE watchdog, uncompressed.** Start an *uncompressed* full PIPE - transfer, send a few frames, stop, **stay connected**. After 15 minutes assert: - the timeout logs once, the panel powers down, and a subsequent `0x0081` frame is - rejected rather than processed. Before this commit that frame trips the `0>=0` - auto-complete and drives `bbepRefresh()` at a dead panel — run it once against - unfixed code to confirm the test has teeth, and watch for the up-to-60 s - `waitforrefresh()` stall. -- **Full PIPE watchdog, compressed.** Same, but assert the eventual `0x0082` END - does not report success for an image that was never written. -- **Pipe-partial watchdog.** Unchanged behaviour; regression only. -- **Normal END.** Confirm the reordered call site did not disturb the ordinary - completion path. +`fix(pipe): terminate the pipe session when the transfer watchdog fires` -### Why it stands alone +The direct-write watchdog released the panel but left `pipeState.active` set with +`pipeState.error` false. Because the `0x0081` handler gates on `pipeState` alone, +a timed-out full PIPE kept accepting frames into a torn-down session — and since +the cleanup zeroes the byte counters, the uncompressed auto-complete test read +`0 >= 0` and drove `bbepRefresh()` + `waitforrefresh(60)` at an unpowered panel. -It fixes a live defect — frames processed into a torn-down session — with no -dependency on the gate change. It is also the prerequisite for Commit 2. +Both watchdogs now live in `display_service.cpp` behind `checkTransferTimeouts()` +and share `TRANSFER_WATCHDOG_MS`. Full reasoning is in the commit message; it is +not repeated here. --- -## Commit 2 — `fix(ble): count unconsumed events and live transfers as work` +## Commit 2 (revised) — `fix(loop): heal orphaned transfer state; count pending events as work` -### What is still wrong after `4d37d43` +### Why `transferActive()` does not belong in the gate -```cpp -const bool workInFlight = bleRxQueuePending() || bleTxQueuePending() || - ble.isConnected() || - s_advertisingRestartPending || - epdRefreshInProgress || - wifiLanSession; -``` +Draft 2 argued the gate was "wrong about what constitutes work" because a +half-finished transfer with the panel powered was not counted. That framing does +not survive contact with the state space. **A transfer whose transport is gone +cannot progress** — frames arrive only over BLE or LAN — so enumerate every state +in which `transferActive()` would be true: -Two blind spots: an event raised after `serviceBleEvents()` ran in this pass, and -a live transfer with the panel powered. Consequence today is bounded — one -`CHECK_INTERVAL_MS` (~100 ms) rather than the original 40 s, because `4d37d43` -makes the wait interruptible — but the gate is still wrong about what constitutes -work, and it governs ESP32 deep sleep. +| State | What the gate does today | What the term would add | +|---|---|---| +| Owner connected, transfer live | `ble.isConnected()` / `wifiLanSession` already true | Nothing — redundant | +| Owner disconnecting | `serviceBleDisconnectCleanup()` runs at `main.cpp:619`, **before** the gate at :665, and resets all three flags. Deferral needs `epdRefreshInProgress`, refusal needs `ownerStillUp` — both already gate terms | Nothing — redundant | +| Orphaned: state set, transport gone | Gate false → `platformIdle()` → park (nRF) or deep sleep (ESP32) | Holds the gate until the 15-minute watchdog | + +The third row is the only distinct behaviour, and it is a regression: + +- `workInFlight` true takes the `delay(1)` path. On nRF that is **one tick**, + below `configEXPECTED_IDLE_TIME_BEFORE_SLEEP` (2), and the core's + `vApplicationIdleHook` is an empty weak stub — so it does not sleep. The idle + task spins at 64 MHz and the loop body re-runs ~1000×/s. +- The watchdog measures from START, so the spin lasts *15 minutes minus however + long the transfer already ran*. +- Cost per event: **~0.9–1.5 mAh** on nRF52840 (≈1.5–2 days of CR2450 standby), + **~6–12 mAh** on an ESP32-S3 tag with WiFi+BLE up. +- Worse, it 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 converts a self-healing state into a fifteen-minute awake + one. + +So the term buys invariant-hardening at the price of the only states it applies +to. The right response to "this state should not exist" is to remove the state, +not to refuse to sleep while it exists. ### The change -**`display_service.cpp`** — `transferActive()` stops reporting dead sessions: - -```c -bool transferActive(void) { - // pipeState.error means the session is dead but deliberately remembered: - // sendPipeNack() keeps pipeState so the reported ACK position stays - // consistent for the client, and the panel has already been released. That - // is bookkeeping, not work. A genuinely live transfer always has - // directWriteActive (full pipe/direct START -> directWriteActivatePanel) or - // partialCtx.active (0x76 / pipe-partial START) set, so excluding the errored - // case never under-reports -- given Commit 1, which stops the watchdog - // leaving a non-errored pipe behind with neither hardware flag set. - return directWriteActive || partialCtx.active || - (pipeState.active && !pipeState.error); -} -``` - -**`main.cpp`** — two terms: +**1. `main.cpp` — one gate term, not two:** ```diff const bool workInFlight = bleRxQueuePending() || bleTxQueuePending() || @@ -203,114 +92,144 @@ bool transferActive(void) { + ble.eventPending() || s_advertisingRestartPending || epdRefreshInProgress || -+ transferActive() || wifiLanSession; ``` -### Why amend `transferActive()` rather than add a gate-only predicate +`eventPending()` closes the real gap: an event raised after `serviceBleEvents()` +ran in this pass is otherwise invisible until the next one, and the pass is about +to park. This defers idle by exactly one pass, deliberately. + +**2. `display_service.cpp` — heal the orphan in `checkTransferTimeouts()`:** + +```c +// Commit 77c2226 proved a live pipe session always has a hardware half, and +// closed the one path that broke it. This asserts it at runtime rather than +// resting on the proof: any future path that recreates the orphan gets one log +// line and a reset, instead of a session that silently accepts 0x0081 frames +// into torn-down state. Deliberately not a gate term -- a transfer whose +// transport is gone cannot progress, so refusing to sleep on it burns power for +// work that will never happen. +if (pipeState.active && !pipeState.error && !directWriteActive && !partialCtx.active) { + od_log_error("ERROR: orphaned pipe session (no hardware half) - resetting"); + resetPipeWriteState(); +} +``` + +**3. `display_service.cpp` — drop the `> 0` timestamp guards:** + +```c +if (directWriteActive && directWriteStartTime > 0) // -> drop "&& ... > 0" +if (partialCtx.active && partialCtx.start_time > 0 && ...) // -> drop "&& ... > 0" +``` + +The `active` flag is set in straight-line code eleven lines from the `millis()` +stamp with no return between, so it already implies a valid timestamp. The guard +is not merely redundant: a transfer starting in the ~1 ms window where `millis()` +wraps through zero has its watchdog disabled **permanently**. Odds are of order +1 in 10⁹ transfers — this is a free removal of a reasoning burden, not a live +risk, and it matters because item 2 makes the watchdog the backstop for the +orphan assertion. -It has four other callers — `touch_input.cpp:587`, `wifi_service.cpp:697`, and -two log-quieting predicates at `display_service.cpp:1898-1903`. Each asks "is a -transfer in flight?" and each is currently told "yes" by a session that is dead -and whose panel has already been released: touch polling stays suspended, WiFi -roam scans stay blocked, and frames the session is silently discarding are -suppressed from the log rather than shown. Reviewed individually, none of the -four is protected by the current behaviour. Amending fixes the meaning once; a -separate narrow predicate would fork the concept and leave the misuse in place. +**4. Split the two questions `transferActive()` currently answers.** It has five +callers asking two different things: + +| Caller | Question | Wants | +|---|---|---| +| `workInFlight` (proposed) | is live work in flight? | — *not adding it, see above* | +| `touch_input.cpp:587` | may I poll GT911 over I2C? | live work only | +| `wifi_service.cpp:697` | may I run a full-channel scan? | live work only | +| `display_service.cpp:1921,1925` | would logging this frame spam? | **any** stream, including a dead one still receiving frames | + +Amend `transferActive()` to `directWriteActive || partialCtx.active || +(pipeState.active && !pipeState.error)` for the first three, and give the +log-quieting predicates their own broader test that keeps the errored case quiet. + +Without the split, a fatal NACK un-suppresses every remaining in-flight `0x0081` +frame — up to a full window from a compliant client, unbounded from one that +ignores the NACK until END — at ~90 frames/s, two log lines each +(`bleRxQueuePush()` arrival + dispatch banner), evicting the NACK itself from the +ring. That is the opposite of the diagnostic improvement Draft 2 claimed. + +Note also that `imageWriteLogQuietFrame()` is called from `bleRxQueuePush()`, +which runs on the **callback task** — so `transferActive()` is already read +cross-task. Keeping the logging predicate separate avoids widening that read to +`pipeState.error`. + +**5. Optional, same commit or its own:** make `takeConnectedEvent()` / +`takeDisconnectedEvent()` atomic read-and-clear (`__atomic_exchange_n`). The +current check-then-clear can lose a whole event, not just its payload — and a +lost disconnect means no `s_disconnectCleanupPending` *and* no +`s_advertisingRestartPending`, so the radio never re-arms. Instruction-scale +window, but a one-line fix. ### Proof obligations | Term | Set by | Cleared by | Cannot latch because | |---|---|---|---| -| `ble.eventPending()` | stack callbacks | `take*Event()` at the next loop top | Survives at most to the next pass; the peek clears nothing, the take always runs | -| `directWriteActive` | `directWriteActivatePanel()` only | `cleanupDirectWriteState()` only — END, NACK, replacement START, refresh completion/failure, disconnect cleanup, watchdog | Single set site, single clear site, watchdog backstop | -| `partialCtx.active` | `0x76` START, pipe-partial START | whole-struct `memset` in `cleanup_partial_write_state()` | Watchdog backstop via `checkPartialWriteTimeout()` | -| `pipeState.active && !pipeState.error` | pipe START only | `resetPipeWriteState()` — END, auto-complete, replacement START, disconnect, **and the watchdog as of Commit 1**; or `pipeState.error` going true | Commit 1 closes the only path that produced a non-errored orphan | - -### ESP32 deep sleep — corrected claim - -The first draft asserted the new terms cannot change sleep *duration* because -neither touches `lastActivityMs`. That was too strong: `workInFlight` bypasses -`platformIdle()` entirely, so any stuck term is an independent sleep veto -regardless of the quiet window. - -The accurate claim: **for normal, fully-observed transport teardown**, sleep -behaviour is unchanged, because a live transfer already held the device awake via -`ble.isConnected()` (BLE-owned) or `wifiLanSession` (LAN-owned), and both go -false at the same point the new term does. What the change does add is a veto on -*stale* transfer state — which is precisely why Commit 1 must land first, and why -the "cleanup is dropped, not deferred" residual below is now a safety -consideration rather than documentation debt. - -### The `workInFlight` comment - -The existing text — *"Every term is transient and most are cleared earlier in -this same pass"* — becomes false and must be rewritten. It must not be replaced -with "`lastActivityMs` is the sole authority on sleep", which is also false while -`workInFlight` short-circuits `platformIdle()`. State instead: every term is -bounded either within the pass or by a terminal transfer path with a watchdog -backstop, and none is a sticky "ever happened" flag. +| `ble.eventPending()` | stack callbacks | `take*Event()` at the next loop top | The peek clears nothing; the take always runs. Continuous new events are ongoing work, not a latch | +| orphan assertion | n/a — it is the clear | itself | Runs every pass, unconditionally | + +No transfer flag enters the gate, so no transfer flag can veto sleep. That is the +point of this revision. + +### ESP32 deep sleep + +`ble.eventPending()` defers `platformIdle()` by one pass when an event lands +after `serviceBleEvents()`. That is the term's purpose and its entire effect. +Nothing else changes: no transfer state reaches the gate, `lastActivityMs` still +supplies the quiet window, and a deep-sleep wake is a full reboot, so no state +here survives it. ### Test -1. **Mid-transfer disconnect.** `sleep_timeout_ms` ≈ 40 s. Connect, authenticate, - start a PIPE transfer, send enough frames to power the panel, kill the link - before END. Assert `Disconnect reason:` within one pass, transfer state - cleared, panel down, advertising back up, no departed-client frame dispatched - afterwards. Repeat for full PIPE, pipe-partial, legacy partial. - *Timing caveat:* do not assert a hard sub-50 ms bound. A disconnect landing - during a synchronous refresh cannot be serviced until `waitforrefresh()` - returns; the assertion is "one pass after the handler returns", not wall-clock. -2. **The latch, fault-injected.** The obvious test — fatal NACK then disconnect — - is worthless: `serviceBleDisconnectCleanup()` calls `resetPipeWriteState()` - unconditionally before the gate is evaluated, so it passes with or without the - amendment. Reproduce instead via the path that skips cleanup: force the - `ownerStillUp` early return, or inject a lost disconnect event, then evaluate - the gate. Alternatively use the Commit 1 watchdog path, which now terminates - cleanly and can be asserted directly. -3. **ESP32 deep-sleep regression.** Battery config: idle → sleeps; connect and - disconnect with no transfer → sleeps after the re-armed window; mid-transfer - disconnect → prompt cleanup then sleeps; completed transfer → sleeps. -4. **nRF idle current.** Unchanged expected; this touches the gate, not the wait. - Any delta means a term is stuck. -5. **Build matrix.** All 11 environments, both commits. +1. **`eventPending()`.** Raise a connect or disconnect after `serviceBleEvents()` + has run and before the gate is evaluated; assert the pass takes `delay(1)` and + the next pass consumes the event. On hardware, the observable is a + mid-transfer disconnect being serviced one pass later rather than after a + `CHECK_INTERVAL_MS`. +2. **Orphan assertion.** Fault-inject the orphan (clear `directWriteActive` + without resetting the pipe), then assert: one `ERROR:` line, pipe state + cleared, a subsequent `0x0081` frame rejected, and the device idling/sleeping + normally. Confirm it does *not* fire in ordinary operation — a full transfer, + a partial transfer, a fatal NACK, and a mid-transfer disconnect should each + complete with the assertion silent. +3. **Watchdog guards.** Regression only: both watchdogs still fire at 15 minutes. +4. **Log split.** Force a fatal NACK mid-stream with frames still in flight; + assert the NACK line survives in the ring and the per-frame lines stay + suppressed. +5. **nRF idle current**, disconnected, before and after. Expected unchanged; a + delta means something reaches the gate that should not. +6. **Build matrix**, all 11 environments. --- -## Residuals — deliberately not in either commit - -0. **The watchdog is a duration timer, not an idle timer.** `directWriteStartTime` - is stamped at START and cleared only on completion or cleanup, so the 15-minute - limit measures the *whole* transfer, not silence. A genuinely healthy but slow - push — a large panel over a poor link, or a client that throttles — is aborted - mid-flight, and after Commit 1 that abort now also resets the pipe, which is - more correct but no less abrupt. Converting it to an idle timer (stamp on each - accepted frame) is a behaviour change worth its own commit and its own - argument; flagged here so the choice is deliberate rather than inherited. -1. **A fatally-NACKed pipe session is still remembered indefinitely.** - `pipeState` has no timestamp field, so there is no watchdog for a session - whose hardware half was already released by `sendPipeNack()`. Harmless after - Commit 2, since nothing reads it as work, and bounded in practice by the next - START/END/disconnect. Adding `start_ms` to `PipeWriteState` would close it. -2. **Event coalescing.** `takeDisconnectedEvent()` does check-then-clear and then - reads `s_disconnectReason`, so a second same-type event inside that window is - lost and its payload can attach to the wrong edge. `serviceBleEvents()` also - processes connect before disconnect regardless of true order. Observed in the - 8.5 h capture as a connect/disconnect/connect burst inside 400 ms. +## Residuals — not in this commit + +1. **Duration, not idle.** Both watchdogs measure from START, so a genuinely slow + 15-minute push is aborted mid-flight. Converting to an idle timer (stamp on + each accepted frame) is a behaviour change deserving its own argument. +2. **A fatally-NACKed pipe session is remembered indefinitely.** `PipeWriteState` + has no timestamp, so nothing bounds it; harmless, since it is excluded from + every live-work predicate and bounded in practice by the next + START/END/disconnect. 3. **Cleanup is dropped, not deferred.** `serviceBleDisconnectCleanup()` clears `s_disconnectCleanupPending` *before* the `ownerStillUp` test and returns, so - when the skip fires that disconnect's teardown never runs at all. Now a safety - consideration, per the deep-sleep correction above. -4. **nRF MSD cadence** is still coupled to the idle duration. + when the skip fires that disconnect's teardown never runs. Less severe now + that no transfer flag vetoes sleep, but still a silent drop. +4. **`sessionOrigin` is never cleared** — stamped at every START, so a refusal log + line can cite a transfer that ended long ago. +5. **nRF MSD cadence** is still coupled to the idle duration. +6. **A stale source comment** at `display_service.cpp:2771-2772` still says nRF + dispatches from its callback task; untrue since Phase 3. ## Risk and rollback | Risk | Likelihood | Mitigation | |---|---|---| -| Commit 1 reorders the normal END path | Low | Test 1.3; the moved block is the watchdog only | -| A transfer flag latches through a path not in the table | Low after Commit 1 | Fault-injected test 2; watchdog backstops | -| ESP32 stops deep-sleeping | Low | Test 3; residual 3 is the remaining exposure | -| Amending `transferActive()` changes touch/WiFi behaviour | Low, and desirable | Only for errored sessions, where suspension was already wrong | +| Orphan assertion fires in normal operation | Low | Test 2's negative cases; it logs at ERROR, so a false positive is loud rather than silent | +| Dropping the `> 0` guards changes watchdog timing | None | `active` already implies a valid stamp | +| Log split leaves a case unsuppressed | Low | Test 4 | +| `eventPending()` defers sleep unexpectedly | By design, one pass | Test 5 measures the aggregate | -Both commits revert independently. Commit 2 depends on Commit 1; Commit 1 depends -on nothing. +Every item reverts independently. None depends on `77c2226` except the orphan +assertion, which asserts the invariant that commit established. From 3b8f1161f72b0e1a6b01aa7e9215af767388460e Mon Sep 17 00:00:00 2001 From: David Lee <247393336+davelee98@users.noreply.github.com> Date: Wed, 29 Jul 2026 13:43:09 -0400 Subject: [PATCH 4/5] fix(loop): heal orphaned transfer state; count pending events as work 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. --- src/display_service.cpp | 75 ++++++++++++++++++++++++++++++++++------- src/main.cpp | 12 +++++++ 2 files changed, 75 insertions(+), 12 deletions(-) diff --git a/src/display_service.cpp b/src/display_service.cpp index fb03c01..b3cacfb 100644 --- a/src/display_service.cpp +++ b/src/display_service.cpp @@ -563,6 +563,7 @@ static PartialStreamContext partialCtx = {}; static void directWriteComputeGeometry(bool compressed); static void directWriteActivatePanel(void); static void directWriteFinishAndRefresh(uint8_t* data, uint16_t len, uint8_t endOpcode); +static bool imageWriteFramesMayStillArrive(void); // serviceBleTx() comes from command_queue.h. The response ring's only drainer is // the loop task, which is the same task running these handlers -- so anything @@ -581,7 +582,14 @@ static PipeReorderSlot pipeReorder[PIPE_REORDER_SLOTS]; static const uint32_t TRANSFER_WATCHDOG_MS = 900000UL; // 15 min (upload + refresh window) void checkTransferTimeouts(void) { - if (directWriteActive && directWriteStartTime > 0) { + // No "&& startTime > 0" sentinel on either watchdog: 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. Zero is a legitimate stamp -- treating + // it as "unset" would permanently disable the watchdog for a transfer that began + // in the ~1 ms window where millis() wraps through zero. Of order one in 10^9 + // transfers, so this is removing a special case from the invariant rather than + // fixing a live risk. + if (directWriteActive) { uint32_t directWriteDuration = millis() - directWriteStartTime; if (directWriteDuration > TRANSFER_WATCHDOG_MS) { od_log_error("ERROR: Direct write timeout (%u ms) - cleaning up stuck state", (unsigned)directWriteDuration); @@ -598,7 +606,7 @@ void checkTransferTimeouts(void) { } } - if (partialCtx.active && partialCtx.start_time > 0 && + if (partialCtx.active && (millis() - partialCtx.start_time) > TRANSFER_WATCHDOG_MS) { od_log_error("ERROR: Partial write timeout - cleaning up stuck state"); cleanup_partial_write_state(); @@ -606,6 +614,27 @@ void checkTransferTimeouts(void) { // pipeState.active can't misroute later 0x0081 frames into the dead partialCtx. if (pipeState.partial) resetPipeWriteState(); } + + // Postcondition over both branches above: a live, non-errored pipe session + // always has a hardware half. 77c2226 proved that and closed the one path that + // broke it; this asserts it at runtime rather than resting on the proof, and + // heals it rather than merely reporting it. Placed last deliberately -- run + // first it would only inspect entry state, and could leave an inconsistency + // either watchdog had just created until the next pass. + // + // What a recurrence costs: the 0x0081 handler gates on pipeState alone, so + // frames are accepted into torn-down state, and with the byte counters zeroed by + // cleanup the uncompressed auto-complete reads 0 >= 0 and drives a full refresh + // at an unpowered panel. + // + // Deliberately NOT a workInFlight term. A transfer whose transport is gone + // cannot progress, so holding the loop awake for it burns power for work that + // will never happen -- on nRF a delay(1) gate is below the tickless threshold + // and spins rather than sleeping. Remove the state; do not idle on it. + if (pipeState.active && !pipeState.error && !directWriteActive && !partialCtx.active) { + od_log_error("ERROR: orphaned pipe session (no hardware half) - resetting"); + resetPipeWriteState(); + } } // Disconnect hook: a partial session (0x76 or pipe-partial) powers the panel via @@ -1924,11 +1953,11 @@ static void imageWriteLogFinish(uint32_t written, uint32_t total) { } bool imageWriteLogQuietCmd(void) { - return transferActive() && imgLogChunks >= 1; + return imageWriteFramesMayStillArrive() && imgLogChunks >= 1; } bool imageWriteLogQuietAck(void) { - return transferActive() && imgLogChunks >= 2; + return imageWriteFramesMayStillArrive() && imgLogChunks >= 2; } // True when this raw frame is a mid-stream image-write data chunk (command @@ -2494,18 +2523,40 @@ void resetPipeWriteState(void) { bool pipeWriteActive(void) { return pipeState.active; } -// True while ANY of the three transfer types is streaming. The three flags live in -// three different places (directWriteActive is a global; pipeState/partialCtx are -// file-static here), so every caller that just means "a transfer is in flight" used -// to spell the disjunction out itself -- and drifted: the WiFi roam gate checked -// direct+pipe but not partial, so a BLE-origin partial write with no LAN client -// attached could be interrupted by a full-channel scan. Add a fourth transfer type -// here, not in each caller. +// Two predicates, because the callers ask two different questions of the same three +// flags. The flags live in three different places (directWriteActive is a global; +// pipeState/partialCtx are file-static here), so every caller that just meant "a +// transfer is in flight" used to spell the disjunction out itself -- and drifted: +// the WiFi roam gate checked direct+pipe but not partial, so a BLE-origin partial +// write with no LAN client attached could be interrupted by a full-channel scan. +// Add a fourth transfer type to BOTH of these, not to each caller. // // Callers wanting ONE specific transfer keep testing that flag directly (the // direct-write watchdog and its teardown, the 0x0072 session-ownership check). +// +// transferActive() -- "is viable work in flight?" Excludes a fatally NACKed pipe, +// whose panel sendPipeNack() has already released: touch I2C polling and a +// full-channel WiFi scan are safe again the moment that happens, and suspending +// them until the client next says something is protecting nothing. +// +// imageWriteFramesMayStillArrive() -- "would logging this frame spam?" Keeps the +// errored pipe, because frames keep arriving after a fatal NACK: a compliant client +// may already have a full window in flight, one that ignores the NACK streams until +// END. At ~90 frames/s and two lines each (bleRxQueuePush() arrival plus the +// dispatch banner) un-suppressing those would evict the NACK itself from the log +// ring -- losing exactly the line worth keeping. +// +// The split also keeps the new pipeState.error read off the logging path, which +// imageWriteLogQuietFrame() reaches from bleRxQueuePush() on the stack callback +// task. That predicate is read cross-task; it keeps precisely the field reads it +// has always made. bool transferActive(void) { - return directWriteActive || pipeState.active || partialCtx.active; + return directWriteActive || partialCtx.active || + (pipeState.active && !pipeState.error); +} + +static bool imageWriteFramesMayStillArrive(void) { + return directWriteActive || partialCtx.active || pipeState.active; } // A chunk c is "received" for ACK purposes if it was accepted in-order (lies just diff --git a/src/main.cpp b/src/main.cpp index 76ac86f..58c4255 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -662,8 +662,20 @@ void loop() { // deep sleep — lastActivityMs supplies the quiet window. The terms that only // one target can ever raise (s_advertisingRestartPending, wifiLanSession) // are simply false on the other, so one expression serves both. + // eventPending() closes the callback-timing hole: an event raised after + // serviceBleEvents() ran in this pass is otherwise invisible until the next + // pass -- and this pass is about to park. It is transient like the rest; + // take*Event() clears the peeked flag at the next loop top. + // + // No transfer-state term belongs here, and its absence is deliberate. A live + // transfer already has its connected BLE or LAN owner holding the gate, and + // one whose transport is gone cannot progress, so refusing to sleep on it + // would burn power for work that will never happen. That state is healed in + // checkTransferTimeouts() instead. See + // docs/PLAN_WORK_GATE_TRANSFER_TERMS_2026-07-29.md. const bool workInFlight = bleRxQueuePending() || bleTxQueuePending() || ble.isConnected() || + ble.eventPending() || s_advertisingRestartPending || epdRefreshInProgress || wifiLanSession; From 881487662e7f31f19ee746aa6e7eb7f7d68a8626 Mon Sep 17 00:00:00 2001 From: David Lee <247393336+davelee98@users.noreply.github.com> Date: Wed, 29 Jul 2026 14:27:07 -0400 Subject: [PATCH 5/5] fix(log): write through TinyUSB on nRF so a stalled host cannot freeze 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 --- docs/PLAN_NONBLOCKING_LOG_2026-07-29.md | 425 ++++++++++++++++++++++++ src/command_queue.cpp | 13 +- src/main.cpp | 18 + src/od_log.cpp | 332 +++++++++++++++++- src/od_log.h | 31 ++ tests/README.md | 80 +++++ tests/serial_stall_test.py | 149 +++++++++ 7 files changed, 1031 insertions(+), 17 deletions(-) create mode 100644 docs/PLAN_NONBLOCKING_LOG_2026-07-29.md create mode 100644 tests/README.md create mode 100755 tests/serial_stall_test.py diff --git a/docs/PLAN_NONBLOCKING_LOG_2026-07-29.md b/docs/PLAN_NONBLOCKING_LOG_2026-07-29.md new file mode 100644 index 0000000..ec75784 --- /dev/null +++ b/docs/PLAN_NONBLOCKING_LOG_2026-07-29.md @@ -0,0 +1,425 @@ +# Plan — make `od_log` non-blocking on nRF via TinyUSB, short-circuited on ESP32 + +**Date:** 2026-07-29 +**Branch:** `fix/loop-hang-3` +**Supersedes:** the reverted `a84e512` / `1fc524b`, and the check-guarded draft of this plan +**Related:** [`FINDINGS_NRF_BLOCKING_CALLS_2026-07-29.md`](FINDINGS_NRF_BLOCKING_CALLS_2026-07-29.md) +§C (this path), §D (starvation), §E4 (stack pressure) + +**Architecture note.** An earlier version of this plan kept writing through Arduino +`Stream::write` and *prevented* the hang with a capacity check. That check was load-bearing for +safety, so it needed a mutex to be correct, static allocation for the mutex, a context-aware +budget, a level-aware budget, a drop backoff, tick deadlines, and short-write rules — 521 lines, +six review rounds, and three defects found in the scaffolding itself. + +This version writes through `tud_cdc_write()` instead. **Blocking becomes impossible by +construction rather than prevented by a correct check.** Everything that remains survives for +*output quality*, so a bug in it costs a mangled log line, not a bricked tag. That reordering of +what is load-bearing is the whole point of the rewrite. + +--- + +## The bug + +`Adafruit_USBD_CDC::write()` spins with no timeout and no iteration cap while DTR is asserted and +the host is not draining: + +```c +// Adafruit_TinyUSB_Arduino/src/arduino/Adafruit_USBD_CDC.cpp:218 +size_t Adafruit_USBD_CDC::write(const uint8_t *buffer, size_t size) { + size_t remain = size; + while (remain && tud_cdc_n_connected(_instance)) { + size_t wrcount = tud_cdc_n_write(_instance, buffer, remain); + remain -= wrcount; buffer += wrcount; + if (remain) { yield(); } + } +``` + +`od_log` writes through it ([`src/od_log.cpp:40`](../src/od_log.cpp)), so a terminal that stays +open but stops reading wedges the logging task. On `loop()` that is fatal: nRF has no watchdog +and every fault handler in the linked image is `b .`, so `epdSessionTick()` stops, the keep-alive +never expires, and the tag goes silent while the link stays up. + +**The wrapper is the only blocking layer.** Everything beneath it already reports backpressure +instead of waiting on it: + +```c +// class/cdc/cdc_device.c:168 -- writes what fits, returns the count. No loop. +uint32_t tud_cdc_n_write(uint8_t itf, void const* buffer, uint32_t bufsize) { + uint16_t ret = tu_fifo_write_n(&_cdcd_itf[itf].tx_ff, buffer, bufsize); + if (tu_fifo_count(&p_cdc->tx_ff) >= BULK_PACKET_SIZE) tud_cdc_n_write_flush(itf); + return ret; +} + +// :182 -- endpoint busy? return 0. Never waits. +uint32_t tud_cdc_n_write_flush(uint8_t itf) { + TU_VERIFY(tud_ready(), 0); + TU_VERIFY(usbd_edpt_claim(rhport, p_cdc->ep_in), 0); + ... +} +``` + +The Arduino wrapper takes a non-blocking primitive that already says "I only took 40 of your 210 +bytes" and retries it forever instead of reporting it. + +**Necessary conditions** — only one host state hangs: + +| Host state | `tud_cdc_n_connected()` | Hangs? | +|---|---|---| +| Unplugged / not enumerated | false (`tud_mounted()`) | No | +| Bus suspended | false (`tud_suspended()`) | No | +| Port closed, DTR low | false | No — and the FIFO is *overwritable*, so writes never fill | +| **Enumerated, not suspended, DTR high, app not reading** | true | **Yes** | + +DTR does two independent things: it keeps the loop's continue condition true, *and* `cdcd_init` +flips the TX FIFO from overwritable to strict on it (`cdc_device.c:394`, +`tu_fifo_set_overwritable(&tx_ff, !dtr)`). Both halves come from the same bit, which is why an +unattended tag never hits this. + +This is **not** the freeze presently under investigation — the audit ranks TWIM I²C spins (§A1) +and SoftDevice flash `portMAX_DELAY` (§A2) above it, with a watchdog as the remedy for both. It +removes one confirmed unbounded wait and makes log gaps self-describing. + +--- + +## Design + +### 1. One backend function — the only place the targets differ + +```c +// All-or-nothing. Returns false without writing anything if the port cannot take +// the whole record. NEVER blocks on nRF: tud_cdc_write() is a bare tu_fifo_write_n. +static bool od_port_write(const uint8_t *b, size_t n) { +#ifdef TARGET_ESP32 + return s_port->write(b, n) == n; // Stream, as today; see §6 +#else + return tud_cdc_write(b, n) == n; // caller has already reserved capacity +#endif +} +``` + +Contained in one function rather than spread through `od_log` as conditionals. nRF loses the +`Stream*` abstraction; that is the price of the guarantee, and it is paid in exactly one place. + +`#include ` already compiles in this project +([`src/utilities/nrf52840_reformat/main.cpp:22`](../src/utilities/nrf52840_reformat/main.cpp)), +and `tud_cdc_write` / `tud_cdc_write_available` / `tud_cdc_write_flush` are instance-0 inlines at +`class/cdc/cdc_device.h:219-236`. + +### 2. Capacity reservation — for line integrity, not for safety + +Check `tud_cdc_write_available() >= total` once, then issue the record's writes. Because the +reservation and the writes happen **under our mutex**, no producer of ours can consume the space +in between, so every write is guaranteed to take its bytes in full. Partial records are therefore +impossible on nRF without an assembly buffer. + +| Case | Writes | +|---|---| +| Untagged | `write(text, len)`, `write("\r\n", 2)` | +| Tagged | `write(text, tagAt)`, `write(tag, tagLen)`, `write(text + tagAt, len - tagAt)`, `write("\r\n", 2)` | + +Note what this check is **not** doing any more: it is not what keeps the firmware alive. If it +were wrong, the consequence is a truncated line, because `tud_cdc_write()` returns short rather +than spinning. + +Byte-identity is exact for any record ≤232 bytes. `len = min(strlen(text), 232)`; the longest +current caller is [`command_queue.cpp:82`](../src/command_queue.cpp) `char line[192]` plus a ≤20 +char header = 211. + +### 3. The mutex — line serialisation only + +TinyUSB's FIFO is already multi-writer safe: `CFG_TUSB_OS = OPT_OS_FREERTOS` +(`arduino/ports/nrf/tusb_config_nrf.h:43`) ⇒ `CFG_FIFO_MUTEX` (`common/tusb_fifo.h:48`), and +`cdcd_init` gives `tx_ff` a write mutex (`cdc_device.c:252`). So a **single** `tud_cdc_write()` +is atomic against other writers. + +Our mutex exists because the *reservation-plus-N-writes span* is not. Without it, a producer can +consume the reserved space between our check and our third write, truncating the record. It is a +`xSemaphoreCreateMutexStatic()` with a file-scope `StaticSemaphore_t` +(`configSUPPORT_STATIC_ALLOCATION`, `FreeRTOSConfig.h:72`) — static purely to avoid an +allocation-failure branch, not because failure is now dangerous. + +**On lock timeout: drop and count.** A dropped line reads better than a mangled one. This is +now a quality choice with no safety consequence, which is why it needs no fail-closed reasoning. + +### 4. The 20 ms bounded wait — delivery quality + +```c +const TickType_t start = xTaskGetTickCount(); // ONCE, before xSemaphoreTake +const TickType_t budget = pdMS_TO_TICKS(od_budget_ms()); +#define OD_EXPIRED() ((TickType_t)(xTaskGetTickCount() - start) >= budget) + +for (;;) { + if (tud_cdc_write_available() >= need) break; // ORDER MATTERS -- see below + if (OD_EXPIRED()) { drop(); return; } + vTaskDelay(1); +} +``` + +Without a wait, a single-shot check fails constantly on a *healthy* host: the FIFO is 256 bytes, +the longest line is ~210, and one image push emits ~300 lines back to back. The wait is what +keeps the frame dumps. + +`start` is stamped **once, before the mutex take**, and the take's timeout is the remaining +budget — not a fresh one — or worst case per line is 2× budget. + +**Ticks, not `millis()`.** `millis()` on nRF is `tick2ms(xTaskGetTickCount())` with +`tick2ms(t) = (uint64_t)t * 1000 / configTICK_RATE_HZ` (`cores/nRF5/rtos.h:65`) at 1024 Hz, so it +wraps at **4,194,303,999**, not `2³²`. The `(int32_t)(a - b)` idiom is unsound on it; the tick +counter does wrap modulo `2³²`, so unsigned tick subtraction is correct by construction. + +**The room check must precede the expiry check**, so a 0 ms budget degenerates to "try once, then +discard" rather than "discard without trying". Reversing them makes off-loop logging drop 100%. + +**`vTaskDelay(1)`, not `delay(1)`.** `delay()` returns *without* `vTaskDelay` when the CDC flush +spans a tick (`cores/nRF5/delay.c:33-48`: `if (flush_tick >= ticks) return;`, and `ms2tick(1)` is +1 tick). Under load that degrades into a busy-spin at priority 2 that never yields to `loop()`; +time slicing is disabled (`FreeRTOSConfig.h:68`). + +### 5. Budget: 0 off-loop, backoff on stall + +```c +static uint32_t od_budget_ms(void) { + // NULL-check first: without it an uncaptured handle makes the inequality true + // for every caller and silently puts everything in try-once-then-drop mode. + if (s_loopTask != NULL && xTaskGetCurrentTaskHandle() != s_loopTask) return 0; + if (s_loopConsecutiveDrops >= 3) return 0; + return 20; +} +``` + +**0 ms off-loop.** Waiting above `loop()` is priority inversion even though it is no longer +dangerous. See the inventory below for exactly which sites this covers. + +**Backoff.** Waiting is a bet that pays off on transient fullness (~1 ms drain) and loses on a +real stall. Without it a stalled port costs 20 ms on *every* line — ~300 lines per push ≈ **6 s of +added `loop()` latency**, enough to starve BLE ACK draining and time out a transfer. Three +consecutive drops presumes a stall and zeroes the budget; any successful write resets it. + +Fed by **loop-context drops only** — it only gates the loop budget, and a global counter is +poisoned across contexts on a healthy host: a `-debug` frame burst drops three off-loop hex lines +(budget 0, FIFO draining ~64 B/ms) and a loop-task ERROR 1 ms later then gets budget 0 when +20 ms would have saved it. Loop-only also makes it single-writer, so it needs no atomics. + +Two further rules: a **lock-timeout** drop does not feed the backoff (it says nothing about the +port), and the **ready-hook** early return neither counts nor resets, so a counter ≥3 can survive +a DTR-low period — self-healing on the first success. + +**Cut from the previous design: the level-aware budget** (DEBUG 5 ms vs 20 ms). It existed to +ration a safety-critical resource. With safety structural, and with 0-off-loop plus the backoff +covering the pathological cases, the extra state is not worth it. + +`s_loopTask` is captured via `od_log_set_loop_task(xTaskGetCurrentTaskHandle())` **immediately +after `od_log_init()`** in `setup()`. Both cores run `setup()` and `loop()` on the same task — +nRF's `loop_task` calls `setup()` then loops (`cores/nRF5/main.cpp:47-73`), and the ESP32 +`loopTask` does the same. + +### 6. ESP32 — unchanged, and it never drops + +`od_port_write()` uses `Stream::write` there; `od_budget_ms()` is irrelevant because +`od_port_wait_ready()` short-circuits to true. Neither ESP32 log port can block on host +backpressure: + +| Port | Envs | Bound | +|---|---|---| +| HWCDC | all except `-extuart` | 100 ms lock + 20 × 100 ms ≈ **2.1 s**, then short write | +| UART1 | the three `-extuart` envs | **baud-bounded**, ~18 ms for a 210 B line at 115200 | + +`HWCDC::write()` caps at `max_consec_timeouts` × `tx_timeout_ms` and separates real unplug from +backpressure. `uartBegin()` hardwires `flow_ctrl = UART_HW_FLOWCTRL_DISABLE` +(`esp32-hal-uart.c:1117`) and `begin()` never enables CTS. + +Two caveats: `UART_MUTEX_LOCK()` is `do {} while (xSemaphoreTake(uart->lock, portMAX_DELAY))` +(`esp32-hal-uart.c:108`) — bounded by the invariant that the logger is UART1's only user, not by +construction. And bounded is not fast; "always ready" means "cannot hang", not "cannot stall". + +**ESP32 never counts a drop**, so `[DROP: x]` can never appear there and byte-identity holds +unconditionally. Short writes are consequently *not* counted there — an unqualified "short writes +count" rule would set `s_dropped`, put the next line on a tagged path that is nRF-only, and break +that guarantee. ESP32 keeps today's behaviour exactly: return ignored, loss silent. + +> **Correction to an earlier claim in this investigation.** The bounded `HWCDC::write()` was +> reported as an untracked local patch CI would not have. Wrong — every file in `cores/esp32/` +> carries the package install mtime, so nothing was hand-edited; the cap ships in pioarduino +> `55.03.39`, which every build pins. + +### 7. Drop counter and `[DROP: x]` + +`__atomic_fetch_add` on every increment — producers increment outside the mutex. Wrap accepted, +not saturated (saturation needs a CAS loop; 2³² drops is 49 days of continuous dropping at +1000/s). `reported = load()` before the writes; `fetch_sub(reported)` after they complete. + +Placement is after the level, before the message, so the timestamp stays in column 1: + +``` +[0416.212|C0] I: === [BLE] PIPE WRITE END COMMAND (0x0082) === +[0416.213|C0] I: [DROP: 214] DW complete: 307 chunks, 96000/96000 bytes +[0416.214|C0] I: EPD refresh: FULL (mode=0, end payload 0x00) +``` + +No extra line; zero drops ⇒ no tag. `tagAt` is the `pos` returned by `_od_log`'s header +`snprintf` ([`od_log.cpp:27-30`](../src/od_log.cpp)); the worst-case header is ~29 chars so it +cannot truncate, and `pos < 0` is handled at `:31`. Max tag is 19 bytes +(`"[DROP: 4294967295] "`), so the worst wire line is 232 + 19 + 2 = **253**, inside the 256-byte +`CFG_TUD_CDC_TX_BUFSIZE`. + +`od_log_raw()` passes `tagAt = -1`. It emits partial lines — `waitforrefresh()` progress dots — +so it respects the wait and counts drops but is never spliced; the count surfaces on the next +`_od_log()` line. + +### 8. Dark-port guard — nRF only + +With DTR low the FIFO is overwritable (`cdc_device.c:394`), so `tud_cdc_write_available()` can +read 0 while a write would in fact succeed by discarding old bytes. All-or-nothing gating would +then drop every line on an unattended tag and hand the first attaching terminal +`[DROP: 4102931]` — a true number that says nothing. + +`od_log_set_ready_hook([]() -> bool { return (bool)Serial; })` returns early **without counting**. +`Adafruit_USBD_CDC::operator bool()` is `tud_cdc_n_connected()` — literally the old write loop's +continue condition. + +Not installed on ESP32: `HWCDC::isCDC_Connected()` documents that its SOF watchdog "is known to +flap even on a healthy link" (`HWCDC.cpp:268-275`), so a hook there would discard good output. + +### 9. `od_log_flush()` + +Routes to `tud_cdc_write_flush()` on nRF (non-blocking by construction) and `s_port->flush()` on +ESP32. Takes the mutex to avoid racing a mid-record emitter; the existing unconditional `delay(5)` +([`od_log.cpp:92`](../src/od_log.cpp)) stays **outside** the lock — 16 boot call sites × 5 ms of +hold is not something to add. + +--- + +## Off-loop logging inventory + +Bluefruit defers callbacks to a dedicated task — `xTaskCreate(adafruit_callback_task, "Callback", +..., TASK_PRIO_NORMAL, ...)` (`cores/nRF5/utility/AdaCallback.c:147`), `TASK_PRIO_NORMAL == 2` +(`cores/nRF5/rtos.h:59`). Every site below runs at priority 2, not on `loop()`: + +| Site | Level | Fires on | +|---|---|---| +| [`command_queue.cpp:49`](../src/command_queue.cpp) "Empty BLE frame received" | WARN | every zero-length write | +| [`command_queue.cpp:53`](../src/command_queue.cpp) "Command too large for queue" | WARN | every oversized write | +| [`command_queue.cpp:63`](../src/command_queue.cpp) "Command queue full" | ERROR | ring full | +| [`command_queue.cpp:84`](../src/command_queue.cpp) the `ERX`/`URX` hex line | DEBUG | every accepted frame not suppressed by `imageWriteLogQuietFrame` | +| [`ble_transport_nrf.cpp:126`](../src/ble_transport_nrf.cpp) "BLE CLIENT CONNECTED" | INFO | per connect | +| [`ble_transport_nrf.cpp:133`](../src/ble_transport_nrf.cpp) "BLE CLIENT DISCONNECTED" | INFO | per disconnect | + +The first four are inside `bleRxQueuePush()`, reached from `onWriteCb` +([`ble_transport_nrf.cpp:155`](../src/ble_transport_nrf.cpp)), which deliberately logs nothing +itself. + +Plus the **FreeRTOS timer task** (also priority 2): `linkDiagCallback` +([`ble_transport_nrf.cpp:101`](../src/ble_transport_nrf.cpp)) → `logLinkParams()` → the +`[LINK negotiated]` line at [`:89`](../src/ble_transport_nrf.cpp). `logLinkParams()` is also +called from `requestFastLink()` on `loop()` ([`main.cpp:449`](../src/main.cpp)), so the task check +must be a **runtime** test, not a compile-time split. + +**The write callback can escalate to priority 3.** `setWriteCallback(onWriteCb)` defaults to +`useAdaCallback = true`, but the dispatch has an inline fallback: + +```c +// Bluefruit52Lib/src/BLECharacteristic.cpp:538 +if ( !(_use_ada_cb.write && ada_callback(...)) ) { + _wr_cb(conn_hdl, this, request->data, request->len); // inline: BLE task, priority 3 +} +``` + +`ada_callback()` fails when its queue is full (`xQueueSend(..., CFG_CALLBACK_TIMEOUT)`, 100 ms, +`AdaCallback.h:42`). So under exactly the flood conditions that matter, those four log lines move +to priority **3**. The `xTaskGetCurrentTaskHandle() != s_loopTask` test catches it identically — +recorded because it makes the worst case "priority 3 above everything", which is the strongest +argument for a 0 ms off-loop budget rather than a small non-zero one. + +--- + +## The single-writer invariant — now integrity, not safety + +Under the previous design this proved the firmware could not hang. It no longer does: a foreign +writer consuming our reservation truncates a line, it cannot make `tud_cdc_write()` spin. Still +worth keeping as an integrity check. + +Verified for shipping envs: no nRF env sets `CFG_DEBUG` ([`platformio.ini:43`](../platformio.ini); +platform default 0 in `nordicnrf52/builder/frameworks/arduino/adafruit.py:250`), so Bluefruit +`LOG_LV*` compiles out; SEGGER RTT is a separate buffer; no `tud_cdc_tx_complete_cb` refill writer +is linked. **But the stdio retarget is linked and dormant, not absent** — `_write()` routes stdout +to `Serial.write()` (`cores/nRF5/main.cpp:121`). + +--- + +## Files + +| File | Change | +|---|---| +| [`src/od_log.cpp`](../src/od_log.cpp) | `od_port_write()` backend; `od_emit()`; capacity reservation; tick deadline; static mutex; budget + backoff; atomic drop counter; `od_log_flush()` routing | +| [`src/od_log.h`](../src/od_log.h) | `od_log_set_ready_hook()`, `od_log_set_loop_task()`, drop/tag contract comment | +| [`src/main.cpp`](../src/main.cpp) | nRF-only ready hook after `od_log_init`; `od_log_set_loop_task()` immediately after it | +| [`src/command_queue.cpp`](../src/command_queue.cpp) | correct the now-false "od_log ends in a blocking serial write (~9 ms …)" comment at `:36-41` — load-bearing rationale for logging on the callback task | +| `tests/serial_stall_test.py`, `tests/README.md` | restore from `13fb679`; match string `"[od_log] dropped"` → `"[DROP:"` (4 sites: `DROP_NOTICE`, docstring, `--expect-drop-notice` help, failure messages) | + +Estimated code change: **~100 lines** in `od_log.cpp`, against the previous design's surface. No +`platformio.ini` change. No `diagnostics.*`. No `display_service.cpp` change. + +**Out of scope:** the heap-stats and 5 s heartbeat from the reverted `a84e512`. The audit's +Stage 1 items 5–6 still want a heartbeat; separate commit. + +--- + +## Accepted limitations + +- **Starvation is reduced, not solved.** Off-loop logging becomes non-blocking, removing the + priority-inversion wait — but a flood still costs formatting time on those tasks. Audit §D stays + open; the watchdog is its remedy. +- **The debug build is not diagnostically equivalent to today under load.** The 256-byte FIFO + drains 64 bytes per completed bulk-IN transaction (`cdc_device.c:168-179`, `:465-467`), so a + sustained `-debug` rate above the IN completion rate drops even with a healthy host, and + off-loop lines drop immediately. `imageWriteLogQuietFrame` + ([`display_service.cpp:1910`](../src/display_service.cpp)) already suppresses the highest-rate + source. The trade is completeness for not wedging. +- **Evidence density collapses where the freeze hunt needs it.** The first lines to drop are the + `[hb]` heartbeat and the ERX arrival lines. "No ERX line" becomes ambiguous between *frame never + arrived* and *logger dropped it*; `[DROP: n]` gives the count, not the identity. Worth an + addendum to the §D bracketing methodology in the findings doc. +- **ESP32 loss is silent** — short writes uncounted there, as today. The drop counter is an + nRF-only instrument. +- **nRF loses the `Stream*` abstraction.** Contained to `od_port_write()`, but `od_log` is no + longer backend-agnostic on that target. +- **Two diagnostic envs still write `Serial` directly**: `OPENDISPLAY_BOOT_DIAG` (unbounded + `while (!Serial)` at [`src/main.cpp:70`](../src/main.cpp)) and + [`src/utilities/nrf52840_reformat/main.cpp`](../src/utilities/nrf52840_reformat/main.cpp) + (`:149`). Both excluded from `default_envs`. +- **"Just enlarge the FIFO" is unavailable.** `CFG_TUD_CDC_TX_BUFSIZE` is a bare `#define` with no + `#ifndef` guard (`arduino/ports/nrf/tusb_config_nrf.h:66`). + +--- + +## Verification + +- `pio run` — all 11 CI envs, plus `nrf52840custom-debug`, `nrf52840-reformat`, + `nrf52840-bootdiag`, `esp32-s3-N16R8-extuart-debug`. +- **Zero-drop byte-identity on a quiet link**, normalising the timestamp prefix (every line starts + `[%04lu.%03lu|C%lu]`, [`od_log.cpp:27`](../src/od_log.cpp), and millis differs every boot): + `sed -E 's/^\[[0-9]+\.[0-9]+\|C[0-9]+\] //' before.log > a; …; diff a b`. + Must hold unconditionally on ESP32. +- **Single-writer / integrity regression test**, anchored so it is usable: + ```bash + grep -rnE '\b(printf|puts)\s*\(|\bSerial\.(write|print|println|printf)\b' src/ \ + --exclude=od_log.cpp --exclude-dir=utilities + ``` + Expect **9 hits, all in `src/main.cpp`, all inside `#ifdef OPENDISPLAY_BOOT_DIAG`** (lines + 79-81, 137, 142, 156, 161, 171, 176 — verified 2026-07-29). The unanchored form gives 121 hits + on a clean tree because `printf` substring-matches `snprintf`. +- **Bench, nRF** (`nrf52840custom-debug`): `./tests/serial_stall_test.py --port /dev/ttyACM0 + --stall 45 --expect-drop-notice`, triggering an image push during the stall. Expect the transfer + and refresh to complete and the first complete line on resume to carry `[DROP: n]` after its + level. **Run it on the parent commit first** — a FAIL there is the single result that validates + the whole diagnosis. +- **Callback-task WARN flood**: drive [`command_queue.cpp:47,52,62`](../src/command_queue.cpp) + with malformed/oversized frames and confirm `loop()` keeps being scheduled. +- **Backoff engages and releases**: `loop()` latency must not grow with the number of attempted + lines during a stall (~3 × budget, not ~300 ×), and the first line after the host resumes must + restore full-budget behaviour rather than staying latched. +- **Stall during a refresh's progress dots**: drops counted but untagged; the count appears on the + next `_od_log()` line, not inside the dot run. +- Scope the timing claim correctly: the **waits** are budgeted. Formatting, preemption and the + writes are outside it. diff --git a/src/command_queue.cpp b/src/command_queue.cpp index 0772eb1..bff34a7 100644 --- a/src/command_queue.cpp +++ b/src/command_queue.cpp @@ -34,11 +34,14 @@ static volatile uint8_t s_rxTail = 0; // // Logged at ARRIVAL, on the stack callback task, so the timestamp is when the radio // delivered the frame rather than when loop() got to it -- that ordering is the -// point of the line, and it cannot be had from the consumer side. The cost is real -// and deliberate: od_log ends in a blocking serial write (~9 ms for a full hex line -// at 115200), so this delays the NimBLE host / SoftDevice callback task. It is -// compiled out entirely at the default INFO level; only the -debug envs pay it, and -// only for frames the quiet predicate does not suppress. +// point of the line, and it cannot be had from the consumer side. The cost used to +// be a blocking serial write (~9 ms for a full hex line at 115200) that delayed this +// callback task; as of the od_log rewrite it is a formatting cost plus a +// non-blocking write attempt, because od_log gives any task other than loop() a zero +// wait budget and discards the record rather than waiting above loop()'s priority. +// A frame's line can therefore be dropped under burst -- see the delivery contract +// in od_log.h. It is compiled out entirely at the default INFO level; only the +// -debug envs pay it, and only for frames the quiet predicate does not suppress. // // Depth is the PRE-push count, matching logTxFrame()'s pre-enqueue depth, so a // healthy path reads [BLE][Q:0] and a rising Q means arrivals are outrunning diff --git a/src/main.cpp b/src/main.cpp index 58c4255..6450ee5 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -89,7 +89,25 @@ void setup() { od_log_init(&LogSerialPort); #elif !defined(DISABLE_USB_SERIAL) od_log_init(&Serial); + #ifndef TARGET_ESP32 + // nRF only. With DTR low the CDC TX FIFO is overwritable, so its free-space + // query reads 0 while a write would still succeed -- without this the logger + // would count a drop for every line on an unattended tag and hand the first + // terminal to attach a meaningless six-figure total. operator bool() is + // tud_cdc_n_connected(), i.e. exactly the condition that used to trap + // Adafruit_USBD_CDC::write(). + // + // Deliberately NOT installed on ESP32: HWCDC::isCDC_Connected()'s SOF watchdog + // is documented to flap on a healthy link, so a hook there would silently + // discard good output. + od_log_set_ready_hook([]() -> bool { return (bool)Serial; }); + #endif #endif + // Immediately after od_log_init(), so the boot lines below are not emitted at a + // zero budget. setup() and loop() share a task on both targets (nRF's loop_task + // calls setup() then loops; the ESP32 loopTask does the same), so capturing here + // identifies the right one. + od_log_set_loop_task(xTaskGetCurrentTaskHandle()); od_log_info("=== FIRMWARE INFO ==="); uint8_t fwMajor = getFirmwareMajor(); uint8_t fwMinor = getFirmwareMinor(); diff --git a/src/od_log.cpp b/src/od_log.cpp index 04e78ec..75aa056 100644 --- a/src/od_log.cpp +++ b/src/od_log.cpp @@ -1,21 +1,311 @@ #include "od_log.h" #include #include +#include + +#ifndef TARGET_ESP32 +// The whole point of this file's nRF path: bypass Adafruit_USBD_CDC::write(), whose +// send loop is bounded only by tud_cdc_n_connected() -- literally "DTR is high" -- +// and therefore spins forever when a host holds the port open but stops draining the +// IN endpoint. tud_cdc_write() underneath it is a bare tu_fifo_write_n that takes +// what fits and returns the count, so it cannot block no matter what the host does. +// See docs/PLAN_NONBLOCKING_LOG_2026-07-29.md. +#include +#endif // Implemented in main.cpp: RTC-persisted wake cycle count on ESP32, always 0 on nRF52840. uint32_t getDeepSleepCount(); // Log output destination, set once by od_log_init(). Stays NULL if // od_log_init() is never called (e.g. DISABLE_USB_SERIAL builds), in which -// case all log calls become no-ops. +// case all log calls become no-ops. On nRF this is still used for the readiness +// hook and flush; the record bytes go out through tud_cdc_write(). static Stream *s_port = NULL; +// Optional "is a host actually listening" predicate. With DTR low, TinyUSB flips the +// TX FIFO to overwritable (cdcd_init -> tu_fifo_set_overwritable(&tx_ff, !dtr)), so +// tud_cdc_write_available() can read 0 while a write would in fact succeed by +// discarding old bytes. Without this hook the all-or-nothing gate below would drop +// every line on an unattended tag and hand the first terminal to attach a +// "[DROP: 4102931]" -- a true number that says nothing. NULL means "assume ready". +static bool (*s_readyHook)(void) = NULL; + +// The loop task, captured in setup(). Anything logging from another context -- +// Bluefruit's "Callback" task at priority 2, the FreeRTOS timer task, or the BLE +// task at priority 3 when ada_callback()'s queue is full and the write callback +// runs inline -- gets a zero budget, because waiting above loop() (priority 1) is +// priority inversion. NULL means "not captured yet": everything then gets the full +// budget, which is the safe bring-up default. The NULL test is not optional -- see +// od_budget_ms(). +static TaskHandle_t s_loopTask = NULL; + +// Records discarded for want of TX space, reported on the next line that gets out. +// Written from three tasks, hence the atomics. +static uint32_t s_dropped = 0; +static uint32_t s_droppedTotal = 0; + +// Consecutive drops taken ON THE LOOP TASK ONLY. Deliberately not a global count of +// every drop: this gates the loop budget and nothing else, and a global is poisoned +// across contexts on a perfectly healthy host -- a -debug frame burst drops a few +// off-loop hex lines (they run at budget 0 and the FIFO drains ~64 B per bulk-IN +// completion), and a loop-task ERROR arriving a millisecond later would then find +// the budget already zeroed when 20 ms would certainly have saved it. Loop-only also +// makes this single-writer, so it needs no atomics. +static uint32_t s_loopConsecutiveDrops = 0; + +// Total wait budget per record, shared between the mutex take and the room wait. +// Not a safety bound -- nothing here can block -- but a latency one: without a wait +// at all, a single-shot capacity test fails constantly on a healthy host, because +// the FIFO is 256 bytes, the longest record is ~210, and one image push emits ~300 +// records back to back. The wait is what keeps the frame dumps. +static const uint32_t OD_LOG_BUDGET_MS = 20; + +// After this many consecutive loop-task drops the port is presumed stalled and the +// budget goes to zero until something gets through. Without it a stalled host costs +// the full budget on every record: ~300 records per push x 20 ms is ~6 s of added +// loop() latency, enough to starve BLE ACK draining and time out a transfer that +// would otherwise have completed. Resets on any successful write, so recovery needs +// no detection of its own. +static const uint32_t OD_LOG_STALL_DROPS = 3; + +// Longest record handed to the port. Worst wire line is 232 + 19 ("[DROP: 4294967295] ") +// + 2 (CRLF) = 253, inside the 256-byte CFG_TUD_CDC_TX_BUFSIZE. Nothing currently +// emitted reaches it -- the longest is command_queue.cpp's 192-byte hex body plus a +// ~20-byte header -- so this is a guard, not a routine cost. +static const size_t OD_LOG_MAX_TEXT = 232; + +// Serialises the capacity reservation and the writes that follow it. +// +// NOT a hang guard: TinyUSB's own FIFO is multi-writer safe (CFG_TUSB_OS == +// OPT_OS_FREERTOS enables CFG_FIFO_MUTEX, and cdcd_init gives tx_ff a write mutex), +// so a single tud_cdc_write() is already atomic against other writers. What is not +// atomic is the span from "there is room for the whole record" to the last write of +// that record: without this lock another producer can consume the reserved space in +// between and truncate the line. A failure here costs a mangled or dropped line, not +// a wedged tag -- which is exactly the property the tud_cdc_write() rewrite buys. +// +// Static allocation only to avoid an allocation-failure branch. +static StaticSemaphore_t s_txLockStorage; +static SemaphoreHandle_t s_txLock = NULL; + static const char level_chars[] = "EWID"; void od_log_init(Stream *port) { + if (s_txLock == NULL) { + s_txLock = xSemaphoreCreateMutexStatic(&s_txLockStorage); + } s_port = port; } +void od_log_set_ready_hook(bool (*fn)(void)) { + s_readyHook = fn; +} + +void od_log_set_loop_task(TaskHandle_t task) { + s_loopTask = task; +} + +uint32_t od_log_dropped_total(void) { + return __atomic_load_n(&s_droppedTotal, __ATOMIC_RELAXED); +} + +// How long this record may wait. Zero means "try once, then discard". +static uint32_t od_budget_ms(void) { + // The NULL test comes first and is load-bearing: xTaskGetCurrentTaskHandle() + // never returns NULL under a running scheduler, so without it an uncaptured + // s_loopTask would make the inequality true for every caller and silently put + // the whole firmware into try-once-then-drop -- the exact inverse of the + // intended bring-up default. + if (s_loopTask != NULL && xTaskGetCurrentTaskHandle() != s_loopTask) { + return 0; + } + if (s_loopConsecutiveDrops >= OD_LOG_STALL_DROPS) { + return 0; + } + return OD_LOG_BUDGET_MS; +} + +static bool od_on_loop_task(void) { + return (s_loopTask == NULL) || (xTaskGetCurrentTaskHandle() == s_loopTask); +} + +static void od_count_drop(bool feedBackoff) { + __atomic_fetch_add(&s_dropped, 1u, __ATOMIC_RELAXED); + __atomic_fetch_add(&s_droppedTotal, 1u, __ATOMIC_RELAXED); + // A lock-timeout drop passes feedBackoff=false: losing a record to another + // producer holding the mutex says nothing about the state of the port. + if (feedBackoff && od_on_loop_task()) { + s_loopConsecutiveDrops++; + } +} + +// Free space in the port's TX buffer, without blocking on either target. +static int od_port_room(void) { +#ifdef TARGET_ESP32 + return (s_port != NULL) ? s_port->availableForWrite() : 0; +#else + return (int)tud_cdc_write_available(); +#endif +} + +// The only place the two targets differ. All-or-nothing by contract: the caller has +// already reserved `n` bytes and holds the lock, so on nRF this always takes the lot. +// +// On nRF this CANNOT block -- tud_cdc_write() is tu_fifo_write_n plus a conditional +// flush, and tud_cdc_write_flush() bails through usbd_edpt_claim() rather than +// waiting. On ESP32 it stays on Stream::write, which is bounded (HWCDC caps at +// max_consec_timeouts x tx_timeout_ms; the log UART has flow control hardwired off +// so its FIFO always drains at the baud rate) and whose short-write behaviour is +// deliberately left exactly as it is today -- see od_emit(). +static bool od_port_write(const uint8_t *b, size_t n) { +#ifdef TARGET_ESP32 + return s_port->write(b, n) == n; +#else + return tud_cdc_write(b, n) == n; +#endif +} + +// True once the port can take `need` bytes, false if the budget ran out first. +static bool od_port_wait_ready(int need, TickType_t start, TickType_t budget) { +#ifdef TARGET_ESP32 + // Short-circuit by design. Neither ESP32 log port can block on host + // backpressure, so there is nothing to wait for and nothing to protect + // against: always write. + (void)need; (void)start; (void)budget; + return true; +#else + for (;;) { + // The room test MUST precede the expiry test. With a zero budget this + // degenerates to "try once, then discard"; reversed, it becomes "discard + // without trying" and every off-loop record is lost unconditionally. + if (od_port_room() >= need) { + return true; + } + if ((TickType_t)(xTaskGetTickCount() - start) >= budget) { + return false; + } + // vTaskDelay, NOT delay(): the core's delay() flushes CDC first and returns + // early without ever calling vTaskDelay when that flush spans a tick + // (cores/nRF5/delay.c, `if (flush_tick >= ticks) return;`, and ms2tick(1) is + // one tick at 1024 Hz). That turns this into a busy-spin at priority 2 that + // never yields to loop(), and time slicing is disabled. + vTaskDelay(1); + } +#endif +} + +// The single write choke point. Emits one log record as a run of writes covered by a +// single capacity reservation, so no write in the run can come up short. +// +// `text` is the whole record without its line ending. `tagAt` is the offset at which +// a "[DROP: n] " tag may be spliced (the first byte after "] L: "), or -1 for a +// partial line that must never carry one. +static void od_emit(const char *text, int tagAt, bool newline) { + if (s_port == NULL) { + return; + } + // Dark port: discard without counting. Nobody is listening, so there is no gap + // for a drop report to explain. + if (s_readyHook != NULL && !s_readyHook()) { + return; + } + + const TickType_t start = xTaskGetTickCount(); + const TickType_t budget = pdMS_TO_TICKS(od_budget_ms()); + + if (s_txLock != NULL) { + // Stamped once, before the take, and the take gets only what is left -- + // giving it a fresh full budget would make the worst case per record 2x. + const TickType_t used = (TickType_t)(xTaskGetTickCount() - start); + const TickType_t left = (used >= budget) ? 0 : (TickType_t)(budget - used); + if (xSemaphoreTake(s_txLock, left) != pdTRUE) { + od_count_drop(false); + return; + } + } + + size_t len = strlen(text); + if (len > OD_LOG_MAX_TEXT) { + len = OD_LOG_MAX_TEXT; + } + if (tagAt > (int)len) { + tagAt = -1; // truncation ate the splice point + } + + // Read without clearing: the count is only consumed once the record is out. + uint32_t reported = (tagAt >= 0) ? __atomic_load_n(&s_dropped, __ATOMIC_RELAXED) : 0u; + char tag[24]; + size_t tagLen = 0; + if (reported > 0) { + int n = snprintf(tag, sizeof(tag), "[DROP: %lu] ", (unsigned long)reported); + if (n > 0 && n < (int)sizeof(tag)) { + tagLen = (size_t)n; + } else { + reported = 0; + } + } + + const int need = (int)(len + tagLen + (newline ? 2 : 0)); + if (!od_port_wait_ready(need, start, budget)) { + od_count_drop(true); + if (s_txLock != NULL) { + xSemaphoreGive(s_txLock); + } + return; + } + + // Every write below is covered by the reservation above and runs under the lock, + // so on nRF each one takes its bytes in full and the record cannot be truncated + // or interleaved. On ESP32 the returns are deliberately ignored: a short write + // there would otherwise set s_dropped, which would put the next record on the + // tagged path -- a path this target must never take, and which would break the + // "ESP32 output is byte-identical to before" guarantee. ESP32 loss stays silent, + // exactly as it is today. + bool ok = true; + if (tagLen > 0) { + ok = od_port_write((const uint8_t *)text, (size_t)tagAt) && ok; + ok = od_port_write((const uint8_t *)tag, tagLen) && ok; + ok = od_port_write((const uint8_t *)text + tagAt, len - (size_t)tagAt) && ok; + } else { + ok = od_port_write((const uint8_t *)text, len) && ok; + } + if (newline) { + ok = od_port_write((const uint8_t *)"\r\n", 2) && ok; + } + +#ifdef TARGET_ESP32 + (void)ok; // see the comment above; ESP32 never counts a drop + s_loopConsecutiveDrops = 0; + if (reported > 0) { + __atomic_fetch_sub(&s_dropped, reported, __ATOMIC_RELAXED); + } +#else + // Push whatever is queued at the record boundary rather than waiting for a full + // bulk packet to accumulate, so a lone line is not held back by a quiet link. + tud_cdc_write_flush(); + if (ok) { + s_loopConsecutiveDrops = 0; + if (reported > 0) { + // Subtract what was reported rather than zeroing, so a drop taken by + // another task between the load above and here is not swallowed. + __atomic_fetch_sub(&s_dropped, reported, __ATOMIC_RELAXED); + } + } else { + // Cannot happen while the reservation and the lock both hold; if it ever + // does, the tag bytes reached the host, so consume the report (re-reporting + // would double-count for a reader summing them) and count the lost record. + if (reported > 0) { + __atomic_fetch_sub(&s_dropped, reported, __ATOMIC_RELAXED); + } + od_count_drop(true); + } +#endif + + if (s_txLock != NULL) { + xSemaphoreGive(s_txLock); + } +} + void _od_log(int level, const char *fmt, ...) { if (s_port == NULL) { return; @@ -37,7 +327,10 @@ void _od_log(int level, const char *fmt, ...) { vsnprintf(buf + pos, sizeof(buf) - pos, fmt, args); va_end(args); - s_port->println(buf); + // pos is the offset of the first message byte, i.e. just past "] L: ", which is + // where a drop tag goes so the timestamp keeps column 1. The header is ~29 chars + // at worst, so it can never be the thing snprintf truncates. + od_emit(buf, pos, true); } void od_log_raw(const char *fmt, ...) { @@ -51,7 +344,10 @@ void od_log_raw(const char *fmt, ...) { vsnprintf(buf, sizeof(buf), fmt, args); va_end(args); - s_port->print(buf); + // tagAt = -1: this emits partial lines (waitforrefresh()'s progress dots), and a + // "[DROP: n]" spliced into a run of dots is noise rather than information. Its + // drops are still counted; the total surfaces on the next complete _od_log line. + od_emit(buf, -1, false); } void od_log_hex_line(char *buf, size_t bufSize, const char *label, @@ -79,15 +375,27 @@ void od_log_flush(void) { return; } + // Taken so this cannot land between the writes of a record another task is + // mid-way through emitting. Bounded, and skipping the flush on contention costs + // nothing that the next flush will not fix. + const bool locked = (s_txLock != NULL) && + (xSemaphoreTake(s_txLock, pdMS_TO_TICKS(OD_LOG_BUDGET_MS)) == pdTRUE); +#ifdef TARGET_ESP32 s_port->flush(); - // Settling pause after flush(), unconditional as of 2026-07-27. Stream::flush() - // returns once the driver has accepted the bytes, which is not the same as the - // host having seen them: on a USB CDC port the transfer still has to be polled - // off the device, and both targets log over CDC by default (nRF always -- there - // is no OPENDISPLAY_LOG_UART path there). This was TARGET_ESP32-only for reasons - // never recorded; the mechanism it compensates for is not ESP32-specific, and - // od_log_flush() is called only at boot/wake checkpoints and before a rail cut -- - // the places where losing the last line costs the most and 5 ms costs nothing. - // 16 call sites, so at most ~80 ms across a boot. +#else + tud_cdc_write_flush(); +#endif + if (locked) { + xSemaphoreGive(s_txLock); + } + + // Settling pause after flush(), unconditional as of 2026-07-27. flush() returns + // once the driver has accepted the bytes, which is not the same as the host + // having seen them: on a USB CDC port the transfer still has to be polled off the + // device, and both targets log over CDC by default (nRF always -- there is no + // OPENDISPLAY_LOG_UART path there). od_log_flush() is called only at boot/wake + // checkpoints and before a rail cut -- the places where losing the last line + // costs the most and 5 ms costs nothing. 16 call sites, so at most ~80 ms across + // a boot. Deliberately OUTSIDE the lock: 16 x 5 ms of hold is not worth adding. delay(5); } diff --git a/src/od_log.h b/src/od_log.h index 2e43dc3..030c5f1 100644 --- a/src/od_log.h +++ b/src/od_log.h @@ -31,6 +31,37 @@ void _od_log(int level, const char *fmt, ...) __attribute__((format(printf, 2, 3 void od_log_raw(const char *fmt, ...) __attribute__((format(printf, 1, 2))); void od_log_flush(void); +// Delivery contract: best-effort, bounded, may drop. +// +// On nRF the bytes go out through tud_cdc_write(), NOT Adafruit_USBD_CDC::write(), +// whose send loop is bounded only by "DTR is high" and so spins forever when a host +// holds the port open but stops reading. Writing through TinyUSB directly makes a +// stalled host structurally incapable of blocking loop() -- which matters because +// this chip has no watchdog and every fault handler is `b .`. +// +// A record that will not fit waits up to 20 ms for space and is then discarded and +// counted. The count is reported on the next record that gets out, spliced in after +// the level as "[DROP: n] " -- one line, never an extra one, and absent when the +// count is zero. Records logged from a task other than loop() do not wait at all. +// +// ESP32 keeps Stream::write and never drops or counts: neither of its log ports can +// block on host backpressure, so its output is unchanged. +// See docs/PLAN_NONBLOCKING_LOG_2026-07-29.md. + +// Tells the logger whether a host is listening, so a dark port is not counted as +// dropped records. Optional; NULL (the default) means "assume ready". nRF only -- +// ESP32's HWCDC::isCDC_Connected() flaps on a healthy link and would discard good +// output. +void od_log_set_ready_hook(bool (*fn)(void)); + +// Identifies the loop task, so logging from anywhere else can skip the wait rather +// than invert priority above it. Call once in setup(), immediately after +// od_log_init(); until then everything gets the full budget. +void od_log_set_loop_task(TaskHandle_t task); + +// Records dropped since boot. +uint32_t od_log_dropped_total(void); + // Builds "