# Speech downlink diagnostics — 0.5.1, 2026-10-04 Scope: diagnostics, local deterministic tests and physical handoff only. No StopWatch was available. Existing PHYSICAL PASS features are accepted as given. No production restart, deployment, merge, flash, provider request or further TCP/Wi-Fi/I2S tuning was performed. Fake-device transport and historical real TTS provider passes do not prove the ESP32/public-path receive behavior. ## Baseline and historical audit Fetched origin before creating `codex/speech-downlink-diagnostics-0.5.1` in `.cache/speech-downlink-diagnostics-0.5.1`. HEAD and fetched origin/main were both `cdaba7c965e7c04070935d9ce54a7a15d04f9091`; original checkout was clean main. | Commit | What survives in current code | |---|---| | c284360 | `WebSocketTextReceiver` assembles transport events and WS continuation frames before JSON parsing; discontinuities/oversize rejected. Separate 16 KiB PSRAM assembly storage. | | be2ccec | Link-health / slow-text instrumentation survives. Its intermediate 16384-byte TCP window and mailbox 14 do **not**. | | a51e13b | 3000 ms idle timeout measured from current generation start / last accepted frame. New generation cannot inherit an old queue wait's age. | | 512516e | `esp_wifi_set_ps(WIFI_PS_NONE)` was introduced here, then removed. Title is not current behavior. | | 7b5e687 | Window 65535, mailbox 48; explicitly removes the Wi-Fi PS override. | Current effective production build was checked through `firmware/build/project_description.json` → `.cache/sdkconfig/m5stack-stopwatch-1ce73f15a5514c53`. Source defaults and generated config agree: TCP receive window 65535; receive mailbox 48; send buffer 65535; tick rate 100 Hz; separate WebSocket TX lock OFF; dynamic WebSocket allocation OFF. Client RX/TX buffer 16384; app assembly capacity 16384; speech queue 8 × 7056 PCM bytes; speech idle 3000 ms; outgoing send 2000 ms; WebSocket network timeout 10000 ms; PCM 44100/16/mono; chunks 80 ms. I2S DMA and codec configuration remain unchanged, including TX auto-clear. No explicit Wi-Fi PS override; last physical trace reported `ps=1` (MIN_MODEM). ## Real Gateway send chain Read source, not just design notes: ```text SpeechManager.start -> spawn(play) [optional summary] -> speech_text_cleanup await wait_for(provider.synthesize(text, language), 60) CloudflareMeloTTS.synthesize bounded HTTP response (45s outer, 40s HTTP) decode provider audio if JSON -> audio_to_pcm ffmpeg pipe: s16le, mono, 44100 -> complete bounded PCM in memory validate identity / target / blocking state await send_to_device(speech_start) for each 7056-byte slice: validate current stream -> base64 encode await send_to_device(speech_chunk, sequence) await asyncio.sleep(raw_chunk_bytes / 88200) # AFTER send, 80ms for full chunk validate -> await send_to_device(speech_end, chunks) send_to_device offline check async with device.send_lock # no general acquisition deadline await wait_for(websocket.send_json(payload), 3) # timeout starts AFTER acquisition Starlette WebSocket.send_json json.dumps(separators=(',', ':'), ensure_ascii=False) await WebSocket.send -> await self._send (ASGI) Uvicorn WebSocketProtocol.asgi_send -> await self.send(data) websockets.legacy.protocol.WebSocketCommonProtocol.send write_frame -> write_frame_sync -> Frame.write(transport.write) await drain -> transport flow control asyncio._SelectorSocketTransport.write socket.send(data); buffer remainder; pause writer above high-water mark _write_ready -> socket.send(buffer) ``` Entry points: `server/device_gateway/speech.py::{SpeechManager.play,CloudflareMeloTTS.synthesize,audio_to_pcm}`, `server/device_gateway/app.py::send_to_device`. Local installed versions: Starlette 0.47.3 (`websockets.py:171`), Uvicorn 0.35.0 (`protocols/websockets/websockets_impl.py:267,332`), websockets 15.0.1 (`legacy/protocol.py:566,1157,1182`). `uvloop` is not installed; Python 3.11 `/usr/lib64/python3.11/asyncio/selector_events.py::_SelectorSocketTransport.write` reaches the socket. Uvicorn auto selects the installed websockets backend. **Send completion means acceptance/drain at that local transport boundary, not ESP32 delivery, decode, queue acceptance or speaker output.** Kernel buffers, Cloudflare tunnel/proxy buffers, TLS records and downstream queues can hide a slow receiver for a short clip. `--ws-max-size 8192` in run-server is an inbound limit, not an outgoing 9503-byte speech limit. ESP client's handshake does not request permessage-deflate, so do not infer compression from Uvicorn's default option. All `speech_chunk`, `server_snapshot`, `agent_state`, `speech_settings` and `approval_request` sends use `Device.send_lock`. The system monitor sequentially awaits snapshot broadcast, then `push_agent_targets`, then sleeps 2s. Thus these two periodic pushes share one worker, rather than two independent timers. Pi event handlers and approval synchronization can also push agent state. Codex activity uses a separate 150ms coalescing task; that is not the periodic monitor cadence. Approval request delivery additionally wraps the whole send call in `wait_for(...,3)`, which **does** include lock wait. Approval arrival cancels active speech; this is separate from mere lock contention. Snapshot/agent send exceptions can mark the device offline and close 1011; SpeechManager tries cancel/error and cleans its active stream. SDK lock failure alone does not prove which server close/error path occurred. ## Trace contract Gateway: `GATEWAY_SPEECH_TRACE=1`; default OFF. Optional `GATEWAY_SPEECH_TRACE_EVERY=1` captures every send for the short physical test; otherwise samples sequence 0,8,16… and always lifecycle/non-speech sends, exceptions, WebSocket send >150ms, lock wait >100ms or nominal drift >150ms. Every event is `[SPEECH_TRACE] {JSON}`. The test sink receives every record, even unsampled ones. No text, PCM, base64, credentials, tokens, Agent content or exception messages. `scheduled_elapsed_ms` is the ideal PCM offset from the speech-start send attempt; `send_attempt_ms` and `send_complete_ms` use that same monotonic origin. `device_lock_wait_ms` is separate from `websocket_send_ms` (Starlette serialization + ASGI await). `drift_from_nominal_ms = send_attempt_ms - scheduled_elapsed_ms`. Non-speech competitors carry the active speech ID/source, but null schedule/sequence and zero raw bytes. `wire_payload_bytes` is **UTF-8 JSON application bytes**, not WS headers, compressed size, TLS or TCP bytes. A summary records all chunks/bytes, max timings and whether end was successfully sent. A begin marker exists even when start subsequently blocks. Failed/cancelled sends have null completion and safe exception class only; a cancellation during lock acquisition has null send duration. Firmware: `CONFIG_DEVICE_LAB_SPEECH_TRACE=y` in the **independent ignored** local config. Kconfig default OFF. Startup prints `[SPEECH_RX_CONFIG] enabled=1`. - `[SPEECH_RX]`: ID, seq, local frame identity, parts, wire bytes, first-part→complete elapsed, monotonic complete time, previous speech completion delta, queue depths, push result, cumulative successful codec bytes, and completion→board dispatch duration. Chunk 0 / multiples of 8 / final chunk, slow frame/gap >250ms, depth ≥6 or push failure print. Final chunk is explicitly repeated at end/stop; the parser deduplicates it and preserves its original counter/timing snapshot. - `[SPEECH_RX_SLOW]`: all >250ms completions, with first/complete time and largest interval between DATA events. No per-fragment output or payload dump. - `[SPEECH_RX_PARTIAL]`: incomplete message identity/size/timing at error/disconnect; cannot assign a speech seq before valid JSON completion. It may be a non-speech message; the marker alone does not establish stream ownership. - `[SPEECH_RX_SUMMARY]`: all observed/accepted counts, first unmet sequence, max gap / frame time, end seen. End **seen** is distinct from protocol-valid and end **queued**. - `[SPEECH_QUEUE]`: generation, depth, accepted/played/rejected/discarded/dropped frames, bytes and high water. `dropped = rejected + discarded`. End marker is not an accepted PCM frame; rejected counts may include an invalid/end enqueue attempt. High water is a producer enqueue occupancy upper bound (`depth_before+1`, capped at 8), because a consumer can dequeue concurrently. Depths are instantaneous observations. - `[SPEECH_PLAY]`: generation, successful API bytes, write calls, max/total write µs, slow calls >20000µs, errors, first/last write times, in-flight/final and current-task stack high water. 512 bytes represent 5.8ms mono PCM; >20ms is an observation threshold, not proof of an audible stall. No per-512-byte logs. Receive timing starts at the first delivered DATA event, **not** socket header arrival. A delayed first event can give near-zero frame time but a large completion gap. The existing code parses JSON in CLOUD, reserializes it, waits for the display lock, parses again in board, then validates/base64-decodes/enqueues. This work is synchronous in the receive callback. We preserved it; `dispatch_ms` helps distinguish its delay from first-part→complete delay. No additional JSON/base64 decoding was introduced. Queue/playback summaries occur at start, end-received, natural playback end, stop, replacement, timeout or error. A diagnostic metrics object is allocated once per stream, retained by an in-flight writer across stop/replacement. A stop snapshot can have `final=0`; the old writer emits `settled final=1` with its **old generation**. Counters are updated once per audio frame using the existing mutex; codec writes remain outside it. Frame timing totals are local until that update. Callback bytes written can lag by one frame; they are not instantaneous DMA position. `bytes_written` means bytes in calls returning ESP_CODEC_DEV_OK. Actual `esp_codec_dev.c::esp_codec_dev_write` delegates to the I2S data interface; `platform/audio_codec_data_i2s.c::_i2s_data_write` invokes `i2s_channel_write` but returns a status, not the driver's byte count (and has an out_reconfig success path). Thus these metrics do **not** certify DMA drain, codec analog output or audible sound. A full count with silence still leaves codec/amplifier/speaker checks for hardware. ## Deterministic constrained receiver and lock evidence `server/tests/test_speech_trace.py` runs **the actual SpeechManager, send_to_device, asyncio locks/wait_for, and Starlette WebSocket**. A virtual-time SelectorEventLoop advances asyncio timers without real waiting. The ASGI consumer has one queued-message slot and a fixed processing delay. Snapshot and agent_state producers send at 160ms / 240ms intervals for eight sends each, awaiting each send. These are deliberately stressful test cadences, not production configuration. There is no provider or network request. All 16 PCM chunks, all control messages and the final end are checked. Full content-free records: [test trace JSON](speech-downlink-constrained-trace.json). Reproduce from the worktree: ```bash PYTHONPATH=server server/.venv/bin/python server/tests/test_speech_trace.py \ docs/speech-downlink-constrained-trace.json ``` | Consumer delay | Max WS send | Max speech lock wait | Max snapshot lock wait | Last chunk attempt drift | Max speech receive gap | End | |---:|---:|---:|---:|---:|---:|---| | 0ms | 0ms | 0ms | 0ms | 0ms | 80ms | yes | | 100ms | 100ms | 120ms | 40ms | 1880ms | 300ms | yes | | 300ms | 300ms | 520ms | 440ms | 7880ms | 900ms | yes | | 1000ms | 1000ms | 1920ms | 1840ms | 28880ms | 3000ms | yes | | 2000ms | 2000ms | 3920ms | 3840ms | 58880ms | 6000ms | yes | The ≥1000ms tests assert both directions of lock contention. The zero-delay test asserts zero wait. A further test uses the production worker topology (snapshot → agent_state → sleep 2s): at 2s downstream delay, max speech lock wait is 2000ms, agent-state lock wait 2000ms and snapshot send duration 2000ms. Snapshot lock wait happens to be zero in that deterministic phase alignment; this is not a general absence-of-contention claim. Its complete records are `production_cycle_2000` in the JSON. A separate single 2s interruption test asserts that every next chunk attempt is ≥80ms after the preceding completion; the >1.8s drift remains. **No catch-up; each delay adds to the timeline.** The ≤2s ASGI model stays connected and eventually sends end because individual send operations remain below 3s. It intentionally does not implement ESP's 3s idle abort; its 3–6s *speech* gaps show why the real device might terminate before that eventual end. General lock waits can exceed the 3s send timeout. Separate virtual tests verify 3s send timeout, 5s lock-wait cancellation/release, no payload leakage, and the actual snapshot failure handler closing 1011 / marking offline. They do not claim every real slow receiver must disconnect. Expected fingerprint for a receiver consuming one 9.5KB frame per 2s: initial Gateway sends may look normal while buffers absorb data; once pressure propagates, `websocket_send_ms` rises toward downstream service time, nominal drift accumulates, and concurrent sends show lock wait. Multiple queued message types can make speech gaps exceed 3s. A 3–5s clip may fit upstream buffers entirely: normal Gateway send + stalled ESP completion is still compatible with downstream buffering, radio, network, SDK receive or callback scheduling. This test models bounded ASGI backpressure, not kernel/TLS/tunnel capacities or mobile-radio timing. ## ESP-IDF / component source findings Audited local `.cache/esp-idf-v5.5.4`, `firmware/dependencies.lock` and `firmware/managed_components/espressif__esp_websocket_client` version **1.8.0**. References below are to those exact local sources, not web recollection. 1. `esp_websocket_client.c:209`, `esp_websocket_client_dispatch_event`: posts to its private loop then synchronously calls `esp_event_loop_run(...,0)`. Init around 793 sets `task_name=NULL`; no event task is created. DATA handlers therefore run inside `esp_websocket_client_task` during receive. 2. Task receive branch around 1387 takes recursive `client->lock`, calls `esp_websocket_client_recv`, then releases it. `recv` at 1076 loops over `esp_transport_read(buffer_size, network_timeout)` → dispatch DATA → advance payload_offset until full WS frame. The mutex spans those reads and callbacks. 3. `esp_websocket_client_send_text` at 1578 delegates to send-with-opcode. Around 715–721, with separate TX lock OFF, the outgoing task waits on that **same** recursive lock. Recursion helps the same task (hello callback), not other tasks (control/heartbeat). 4. **`Could not lock ws-client within 200 timeout` prints ticks, not milliseconds.** Source prints its `TickType_t timeout` directly. Our caller passes `pdMS_TO_TICKS(VOICE_SEND_TIMEOUT_MS)` where `VOICE_SEND_TIMEOUT_MS=2000` and generated `CONFIG_FREERTOS_HZ=100`; 200 ticks = approximately **2 seconds**. This is a possible symptom of a long receive/dispatch hold, not proof of root cause. The lock-failure branch returns -1; it does not itself abort the connection. A later receive failure follows another path. Do not infer the observed causal ordering. 5. One large WS frame delivered through several transport reads holds this mutex through completion. Multiple WS continuation frames are handled via successive receives; lock release boundaries differ from DATA parts within one WS frame. 6. JSON parse/reserialize, display-lock wait, second parse, base64 and queue work all run before the callback returns and the next read begins. Logging also occupies this task, hence sampling. I2S runs on a separate task but shared queue/locks and CPU scheduling still matter. **What 16KiB means:** init around 891 allocates `rx_buffer` and `tx_buffer` of that size; recv offers it as the maximum bytes for one transport read; outgoing send slices its own payload at that size. It does not configure TCP window, TLS record size, packet boundaries or guarantee full reads. The application separately reassembles up to 16KiB in PSRAM. In IDF `components/tcp_transport/transport_ws.c::ws_read_payload` at 464, requested bytes = min(frame remaining, caller buffer), followed by **one** underlying read; returned bytes can be shorter. `esp_transport_read_internal` at 114 can consume handshake leftovers or delegate. `transport_ssl.c::ssl_read` at 261 polls and calls `esp_tls_conn_read`; `esp-tls/esp_tls_mbedtls.c::esp_mbedtls_read` at 329 calls `mbedtls_ssl_read`. TLS records/available data can split an otherwise small-enough WS frame. Thus **9503 < 16384 does not exclude parts=2**. Parts count DATA deliveries, not necessarily WebSocket protocol fragments or IP packets. ## Future candidates — no implementation or tuning Exact JSON calculation uses a 32-character speech_id, sequence=10 (two digits), compact Starlette JSON, a full PCM chunk; sequence digit count changes size slightly. WS server-to-client header is 4 bytes at these lengths, unmasked, excluding TCP/IP/TLS, ACKs, retransmission and control traffic. | Chunk | Raw PCM | Base64 | JSON bytes | Frames/s | JSON B/s | WS header B/s | JSON+WS B/s | Base64 encode/decode calls/s per side | |---:|---:|---:|---:|---:|---:|---:|---:|---:| | 80ms | 7056 | 9408 | 9503 | 12.5 | 118787.5 | 50 | 118837.5 | 12.5 | | 40ms | 3528 | 4704 | 4799 | 25 | 119975 | 100 | 120075 | 25 | | 20ms | 1764 | 2352 | 2447 | 50 | 122350 | 200 | 122550 | 50 | Raw rate is always 88200 B/s; base64 characters/s always 117600. Smaller frames reduce bytes needed for one complete message and may shorten lock holds / partial-frame exposure, but cannot promise less latency: TCP/TLS boundaries and first-byte delays remain; JSON/callback/base64 call counts double/quadruple and header work increases. With an unchanged 8-frame queue, queued audio capacity would fall from 640ms to 320ms or 160ms. Any future A/B must explicitly account for that confounder. Only consider a physical chunk-size experiment after matched traces show large-frame completion delay. Binary transport: raw 88200 B/s. For illustration, a 24-byte application header plus 7056 raw bytes gives 7080-byte messages, 88500 application B/s, 88550 B/s including WS headers at 12.5Hz (~25.5% less than current JSON+WS). Base64 alone expands raw by 33.3%; removing that expansion saves 25% of the encoded data, not 33% of total traffic. Binary removes base64 conversion and large audio JSON strings, but requires a versioned header, identity/sequence/end semantics, reassembly/bounds checks, capability negotiation, legacy text fallback and cancellation compatibility. **Worth a future experiment**, not demonstrated necessary and not implemented here. ## Hotspot: evidence vs hypothesis Supported: mobile hotspot, RSSI roughly -36…-50 dBm, PS reported 1, incomplete speech, 29 chunks, 3s idle timeout and late >250ms / seconds-long completions. Strong RSSI does not measure retries, airtime, WAN RTT, tunnel buffering or DTIM delay. Plausible: cellular WAN latency/jitter, AP scheduling, DTIM/power-save interaction, TCP/TLS buffering and public Cloudflare tunnel path can add delay. Local IDF header `esp_wifi_types_generic.h` defines MIN_MODEM as waking for each DTIM; `esp_wifi.h` documents it as the default. Neither RSSI nor `ps=1` establishes it as the cause. Speculative without new trace: a particular hotspot defect, TCP-window insufficiency, Cloudflare-specific loss, Wi-Fi PS as root cause or any codec fault. After the first captured run, optional **network-only A/B**: same firmware SHA, Gateway code/config, short displayed text and test-case `read-screen-fixed-01`; hotspot vs a stable 2.4GHz AP. Configure the AP with the same SSID/password and turn off the other radio so the binary and credentials stay identical. If that is not possible, document the config difference; do not claim a strict single-variable test. A new actual speech_id is generated per request: record both IDs under the same test case, never force reuse. Changing networks may also change WAN route, so a better AP result isolates the network condition, not specifically power save. Do not disable PS. Optional future flag *design only*: `CONFIG_DEVICE_LAB_WIFI_PS_NONE_TEST`, default n, with explicit boot marker and separately labeled artifact/config. It is not implemented or enabled here. No timeout increase, mailbox/window change, DMA change or codec tuning. ## Correlation and decision rules Run [correlate-speech-trace.py](../scripts/correlate-speech-trace.py); see the [physical handoff](speech-downlink-next-physical-test.md) for exact capture commands. Tables join Gateway send attempts/completions, ESP complete samples and playback counters by ID/seq; generation maps queue/playback to that stream. `network_gap` is `(ESP_complete(seq)-ESP_complete(anchor)) - (GW_complete(seq)-GW_complete(anchor))`. It is relative progression, **not synchronized one-way latency**. Blank sampled rows are unknown; stream counters / end validation establish prefix completeness. Transparent classifier, observations only (always reports root cause undetermined): - A: Gateway max send >150ms or device-lock wait >100ms; inspect both fields. - B: complete Gateway summary, maxima below those thresholds, nominal drift ≤150ms; device max frame/gap >250ms or a proven incomplete contiguous prefix. - C: Gateway normal, device end valid/queued, all expected chunks accepted, normal completion maxima; a **settled** playback summary has byte deficit, write error or a >250ms individual write. A >20ms slow-write count alone does not trigger C. - D: insufficient evidence for A/B/C, or no measured stall. D is not an audio pass. A takes precedence if multiple symptoms coexist. Missing Gateway summary cannot prove normal send. Missing serial/end logs cannot prove end absent. Earlier disconnects, other speech IDs, duplicate final samples, truncated Gateway JSON and unset/in-flight playback counters are covered by parser tests. Stop and investigate the first observed boundary; do not auto-tune from this classifier.