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/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..f3d1d50 --- /dev/null +++ b/docs/PLAN_WORK_GATE_TRANSFER_TERMS_2026-07-29.md @@ -0,0 +1,235 @@ +# Plan — orphaned transfer state: heal it, don't idle on it + +**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 history + +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. + +**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. + +**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. + +**This draft** keeps `ble.eventPending()`, drops `transferActive()` from the gate, +and replaces it with a self-healing assertion in the watchdog. + +--- + +## Commit 1 — landed as `77c2226` + +`fix(pipe): terminate the pipe session when the transfer watchdog fires` + +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. + +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 (revised) — `fix(loop): heal orphaned transfer state; count pending events as work` + +### Why `transferActive()` does not belong in the gate + +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: + +| 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 + +**1. `main.cpp` — one gate term, not two:** + +```diff + const bool workInFlight = bleRxQueuePending() || bleTxQueuePending() || + ble.isConnected() || ++ ble.eventPending() || + s_advertisingRestartPending || + epdRefreshInProgress || + wifiLanSession; +``` + +`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. + +**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 | 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. **`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 — 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. 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 | +|---|---|---| +| 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 | + +Every item reverts independently. None depends on `77c2226` except the orphan +assertion, which asserts the invariant that commit established. 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/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/display_service.cpp b/src/display_service.cpp index c24f7a0..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 @@ -575,15 +576,65 @@ static void directWriteFinishAndRefresh(uint8_t* data, uint16_t len, uint8_t end static PipeWriteState pipeState = {}; static PipeReorderSlot pipeReorder[PIPE_REORDER_SLOTS]; -void checkPartialWriteTimeout(void) { - if (partialCtx.active && partialCtx.start_time > 0 && - (millis() - partialCtx.start_time) > 900000UL) { +// 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) { + // 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); + 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 && + (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 // 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 @@ -1902,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 @@ -2472,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/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 b2842bc..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(); @@ -626,14 +644,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 @@ -666,8 +680,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; @@ -701,14 +727,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; 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 "