diff --git a/docs/releases/1.6.0.md b/docs/releases/1.6.0.md index 2f8f817..df90771 100644 --- a/docs/releases/1.6.0.md +++ b/docs/releases/1.6.0.md @@ -51,6 +51,20 @@ 8-slot queue halves whatever is configured). This removes the audible mid-sentence dropouts on long speeches; hosts without the audio modules fall back to the host `tts-remote` automatically. +- `/api/status` reports live XS heap usage under `instruments` when the host + bundles the instrumentation module (instrumented build). The matchday host + branch fixes recurring `memory full` reboots: the CoreS3 XS chunk heap was + configured with `incremental: 0`, which hard-caps it at its 256KB initial + size — `fxGrowChunks` aborts with "Chunk allocation … failed in fixed size + heap" the moment the working set needs more, regardless of the 8MB of free + PSRAM (serial signature: 20–40 byte allocation failures, then reset). The + chunk heap is now `{ initial: 393216, incremental: 32768 }`; verified on an + instrumented build that chunk usage sails past the old 256KB cap to ~385KB + under heavy load with healthy GC and zero aborts. (An earlier attempt bumped + a `static` arena on the wrong platform block — `m5stack_core2`, not this + device — and did nothing; that is reverted.) The abort hook also falls back + to persisting the bare status when heap exhaustion makes the full reason + string unallocatable. The mod runs unchanged on older or stock hosts. ### Upgrade boundary @@ -99,6 +113,15 @@ - 远程 TTS 内置进 mod（`matchday/tts-remote-safe`），流缓冲提高到 1500ms、音频 队列 16 槽（host 固定 600ms，且默认 8 槽队列会把实际深度再腰斩）。长句中间 的可听断音由此消除；host 缺音频模块时自动回落到原 `tts-remote`。 +- host 带 instrumentation 模块（仪表化构建）时，`/api/status` 在 `instruments` + 字段实时报告 XS 堆用量。matchday host 分支修掉反复 `memory full` 重启：CoreS3 + 的 XS chunk 堆配了 `incremental: 0`，把它硬锁在 256KB 初始大小——工作集一超， + `fxGrowChunks` 立即 abort "Chunk allocation … failed in fixed size heap"，哪怕 + PSRAM 还空着 8MB（串口签名：20–40 字节小分配失败后复位）。chunk 堆改为 + `{ initial: 393216, incremental: 32768 }`；仪表化构建实测重负载下 chunk 冲到 + ~385KB（远超旧的 256KB 上限）、GC 正常、零 abort。（此前一次尝试改的是 + `m5stack_core2`——另一块板子——的 `static`，纯空操作，已撤销。）abort 钩子在 + 堆耗尽导致完整原因串无法分配时退而保存裸状态。mod 在旧 host / 官方 host 照常运行。 ### 升级边界 diff --git a/host/sdk-patches/0001-esp32-tcp-clear-callbacks-safe.patch b/host/sdk-patches/0001-esp32-tcp-clear-callbacks-safe.patch index 2e45d6e..04df45b 100644 --- a/host/sdk-patches/0001-esp32-tcp-clear-callbacks-safe.patch +++ b/host/sdk-patches/0001-esp32-tcp-clear-callbacks-safe.patch @@ -1,8 +1,39 @@ diff --git a/modules/io/socket/lwip/tcp.c b/modules/io/socket/lwip/tcp.c -index 0f90023..63a2820 100644 +index 0f90023..95030f1 100644 --- a/modules/io/socket/lwip/tcp.c +++ b/modules/io/socket/lwip/tcp.c -@@ -262,6 +262,11 @@ void xs_tcp_destructor(void *data) +@@ -242,14 +242,26 @@ void xs_tcp_destructor(void *data) + if (!tcp) return; + + if (tcp->skt) { +- removeTCPCallbacks(tcp); ++ // Marshaled: when this returns, no callback for this pcb is running ++ // or can start, so an in-flight tcpReceive that already loaded this ++ // record cannot race the frees below. ++ tcp_clear_callbacks_safe(tcp->skt); ++ tcp->triggerable &= ~kTCPWritable; + + tcp_close_safe(tcp->skt); + } + +- while (tcp->buffers) { +- TCPBuffer buffer = tcp->buffers; +- tcp->buffers = buffer->next; ++ for (;;) { ++ TCPBuffer buffer; ++ ++ // Detach under the append guard; free outside it. ++ builtinCriticalSectionBegin(); ++ buffer = tcp->buffers; ++ if (buffer) ++ tcp->buffers = buffer->next; ++ builtinCriticalSectionEnd(); ++ if (!buffer) ++ break; + pbuf_free_safe(buffer->pb); + c_free(buffer); + } +@@ -262,6 +274,11 @@ void xs_tcp_destructor(void *data) void removeTCPCallbacks(TCP tcp) { if (tcp->skt) { @@ -14,7 +45,21 @@ index 0f90023..63a2820 100644 tcp_recv(tcp->skt, NULL); tcp_sent(tcp->skt, NULL); tcp_err(tcp->skt, NULL); -@@ -358,7 +363,11 @@ void xs_tcp_read(xsMachine *the) +@@ -313,8 +330,13 @@ void xs_tcp_read(xsMachine *the) + uint8_t allocate = 1; + xsUnsignedValue byteLength; + ++ // Walk under the same guard tcpReceive appends under: an unlocked ++ // traversal on the other core has no acquire ordering against the ++ // appender's initializing stores. ++ builtinCriticalSectionBegin(); + for (buffer = tcp->buffers; NULL != buffer; buffer = buffer->next) + available += buffer->bytes; ++ builtinCriticalSectionEnd(); + + if (0 == xsmcArgc) + requested = available; +@@ -358,7 +380,11 @@ void xs_tcp_read(xsMachine *the) buffer->fragment = fragment->next; buffer->fragmentOffset = 0; if (NULL == buffer->fragment) { @@ -26,7 +71,7 @@ index 0f90023..63a2820 100644 tcp_recved_safe(tcp->skt, buffer->pb->tot_len); pbuf_free_safe(buffer->pb); c_free(buffer); -@@ -535,6 +544,9 @@ void tcpError(void *arg, err_t err) +@@ -535,6 +561,9 @@ void tcpError(void *arg, err_t err) { TCP tcp = arg; @@ -36,7 +81,7 @@ index 0f90023..63a2820 100644 removeTCPCallbacks(tcp); tcp->skt = NULL; // "pcb is already freed when this callback is called" if (kTCPError & tcp->triggerable) -@@ -546,6 +558,12 @@ err_t tcpReceive(void *arg, struct tcp_pcb *pcb, struct pbuf *pb, err_t err) +@@ -546,6 +575,12 @@ err_t tcpReceive(void *arg, struct tcp_pcb *pcb, struct pbuf *pb, err_t err) TCP tcp = arg; TCPBuffer buffer; @@ -49,7 +94,7 @@ index 0f90023..63a2820 100644 if ((NULL == pb) || (ERR_OK != err)) { //@@ when is err set here? removeTCPCallbacks(tcp); #if ESP32 -@@ -572,6 +590,10 @@ err_t tcpReceive(void *arg, struct tcp_pcb *pcb, struct pbuf *pb, err_t err) +@@ -572,6 +607,10 @@ err_t tcpReceive(void *arg, struct tcp_pcb *pcb, struct pbuf *pb, err_t err) modInstrumentationAdjust(NetworkBytesRead, buffer->bytes); @@ -60,7 +105,7 @@ index 0f90023..63a2820 100644 if (tcp->buffers) { TCPBuffer walker; -@@ -581,6 +603,7 @@ err_t tcpReceive(void *arg, struct tcp_pcb *pcb, struct pbuf *pb, err_t err) +@@ -581,6 +620,7 @@ err_t tcpReceive(void *arg, struct tcp_pcb *pcb, struct pbuf *pb, err_t err) } else tcp->buffers = buffer; @@ -68,7 +113,7 @@ index 0f90023..63a2820 100644 if (tcp->triggerable & kTCPReadable) tcpTrigger(tcp, kTCPReadable); -@@ -590,6 +613,9 @@ err_t tcpReceive(void *arg, struct tcp_pcb *pcb, struct pbuf *pb, err_t err) +@@ -590,6 +630,9 @@ err_t tcpReceive(void *arg, struct tcp_pcb *pcb, struct pbuf *pb, err_t err) err_t tcpSent(void *arg, struct tcp_pcb *pcb, u16_t len) { @@ -78,48 +123,3 @@ index 0f90023..63a2820 100644 tcpTrigger((TCP)arg, kTCPWritable); return ERR_OK; } -diff --git a/modules/network/socket/lwip/modLwipSafe.c b/modules/network/socket/lwip/modLwipSafe.c -index a4cc7fb..dc699dd 100644 ---- a/modules/network/socket/lwip/modLwipSafe.c -+++ b/modules/network/socket/lwip/modLwipSafe.c -@@ -169,6 +169,28 @@ void tcp_recved_safe(struct tcp_pcb *tcpPCB, u16_t len) - tcpip_callback_with_block(tcp_recved_INLWIP, msg, 1); - } - -+static err_t tcp_clear_callbacks_INLWIP(struct tcpip_api_call_data *tcpMsg) -+{ -+ LwipMsg msg = (LwipMsg)tcpMsg; -+ if (msg->tcpPCB) { -+ tcp_arg(msg->tcpPCB, NULL); -+ tcp_recv(msg->tcpPCB, NULL); -+ tcp_sent(msg->tcpPCB, NULL); -+ tcp_err(msg->tcpPCB, NULL); -+ } -+ return ERR_OK; -+} -+ -+// Synchronous: when this returns, no lwIP callback for this pcb is running -+// or can run again, so the caller may safely free its callback argument. -+void tcp_clear_callbacks_safe(struct tcp_pcb *tcpPCB) -+{ -+ LwipMsgRecord msg = { -+ .tcpPCB = tcpPCB, -+ }; -+ tcpip_api_call(tcp_clear_callbacks_INLWIP, &msg.call); -+} -+ - static err_t tcp_listen_INLWIP(struct tcpip_api_call_data *tcpMsg) - { - LwipMsg msg = (LwipMsg)tcpMsg; -diff --git a/modules/network/socket/lwip/modLwipSafe.h b/modules/network/socket/lwip/modLwipSafe.h -index 717808d..0f5c94f 100644 ---- a/modules/network/socket/lwip/modLwipSafe.h -+++ b/modules/network/socket/lwip/modLwipSafe.h -@@ -52,6 +52,7 @@ - #include "lwip/raw.h" - - struct tcp_pcb *tcp_new_safe(void); -+ void tcp_clear_callbacks_safe(struct tcp_pcb *tcpPCB); - err_t tcp_connect_safe(struct tcp_pcb *tcpPCB, const ip_addr_t *ipaddr, u16_t port, tcp_connected_fn connected); - u8_t pbuf_free_safe(struct pbuf *p); - err_t tcp_bind_safe(struct tcp_pcb *tcpPCB, const ip_addr_t *ipaddr, u16_t port); diff --git a/host/sdk-patches/README.md b/host/sdk-patches/README.md index d513837..b6ee98a 100644 --- a/host/sdk-patches/README.md +++ b/host/sdk-patches/README.md @@ -26,29 +26,59 @@ The patch fixes two independent races behind the same panic signature (discussed with the maintainer in [moddable#1655](https://github.com/Moddable-OpenSource/moddable/issues/1655)): -1. **Teardown use-after-free.** `removeTCPCallbacks()` now clears the lwIP - callback argument first (`tcp_arg(pcb, NULL)`) and then the callbacks — - plain pointer stores, per maintainer guidance; no tcpip-thread marshaling - needed. `tcpReceive`/`tcpSent`/`tcpError` gain NULL-argument guards so any - late delivery observes NULL and bails. (An earlier revision marshaled the - clear via `tcpip_api_call`; soak testing showed the simpler arg-first - variant is sufficient. The unused `tcp_clear_callbacks_safe` helper may - remain in modLwipSafe from that revision.) +1. **Teardown use-after-free.** `removeTCPCallbacks()` clears the lwIP callback + argument first (`tcp_arg(pcb, NULL)`) and then the callbacks; + `tcpReceive`/`tcpSent`/`tcpError` gain NULL-argument guards so any *late* + delivery observes NULL and bails. 2. **Receive-buffer list race.** `tcp->buffers` was appended to by the lwIP task (`tcpReceive` walks to the tail) while the XS task pops and frees head nodes in `xs_tcp_read` — with no synchronization, the tail walk can traverse a node mid-free. Both sides now do their pointer surgery inside `builtinCriticalSection` (heap operations stay outside the critical - section). This was the direct cause of the `LoadProhibited` panics at the - `walker->next` walk and kept crashing hosts that had only fix 1. + section). `xs_tcp_read`'s length pre-scan and the destructor's buffer drain + are guarded too. +3. **In-flight `tcpReceive` vs destructor (added 2026-07-15).** The arg-first + NULL guard only protects callbacks that *start* after the clear. It does + nothing for a `tcpReceive` already past the guard and mid-tail-walk when the + XS task runs `xs_tcp_destructor` and frees `tcp->buffers`/`tcp`. Under the + 1.6.0 mod's *concurrent* HTTP handling, connection teardowns overlap inbound + data far more often than the old serialized handler did, and a + `tcpReceive` `LoadProhibited` (reached via `tcp_input`) began recurring at + ~25 min under only light polling. The destructor was changed to clear + callbacks through the marshaled `tcp_clear_callbacks_safe`. -Soak evidence: the device previously crashed every 15–25 minutes under -ordinary watcher traffic; with both fixes it has run clean for hours -(instrumented via the abort hook so app-level restarts are separable). + **⚠️ Fix 3 is NOT sufficient — the crash still recurs (2026-07-15).** After + deploying it, the device crashed again at 27 min under real load with a + healthy heap. Same `tcpReceive` backtrace, but the fault address is a + *poison* value (`EXCVADDR=0xe2f61b44`) and `tcp` itself is valid: the fault + is a *buffer-list node* freed while still linked (`tcp->buffers` walking a + poisoned node), not the `tcp` record. The receive-buffer node lifetime is + shared across `tcpReceive` (append, tcpip thread), `xs_tcp_read` (consume + + free, XS thread), and the destructor drain, on two cores; the + `builtinCriticalSection` guards on the pointer surgery do not cover the + whole node lifetime. **This is an unresolved SDK-level race that needs the + maintainer.** The marshaled destructor change is kept as a partial + hardening but is not claimed to fix the crash. + +Soak evidence: the device previously crashed every 15–25 minutes; fixes 1+2 +ran clean for 2.1 hours *before* 1.6.0's concurrent HTTP handling, which raised +teardown/receive overlap and reopened the receive-path race. Fix 3 did not +close it. Escalation with the poison-UAF evidence is pending on #1655. + +**Known remaining gap (not fixed here).** Listener accept path: a pending +socket (accepted by lwIP, not yet consumed by `xs_listener_read`) has no error +callback — see the `//@@ also install error handler` comment in `listenerAccept`. +If the peer RSTs a pending connection before the XS task consumes it, lwIP frees +the pcb and `pending->skt` dangles; `xs_listener_read` then calls `tcp_err()` on +it and trips `LWIP_ASSERT(... pcb->state != LISTEN)`. Only reproduced under a +pathological burst (10 simultaneous connections RST together), not under match +load. A correct fix installs an error handler on pending sockets and removes +them from the pending list under lock; it needs its own soak and a separate +upstream discussion. Reported and fixed upstream: issue [moddable#1655](https://github.com/Moddable-OpenSource/moddable/issues/1655), -PR [moddable#1656](https://github.com/Moddable-OpenSource/moddable/pull/1656) -(same two changes). Once the PR lands, drop this patch and update the SDK -instead. `mcconfig` rebuilds pick the change up automatically; the mod does -not need to be rebuilt. +PR [moddable#1656](https://github.com/Moddable-OpenSource/moddable/pull/1656). +Once the PR lands (with fix 3), drop this patch and update the SDK instead. +`mcconfig` rebuilds pick the change up automatically; the mod does not need to +be rebuilt. diff --git a/mod/commands.js b/mod/commands.js index 1adf7c4..09e07f7 100644 --- a/mod/commands.js +++ b/mod/commands.js @@ -1,6 +1,28 @@ // Text command dispatcher shared by HTTP /api/command and /api/control. // The stable command strings let watcher and device tooling evolve separately. +import Modules from 'modules' import Timer from 'timer' + +// Optional: only present when the host bundles modules/base/instrumentation. +// Exposes XS heap usage in /api/status so heap exhaustion (the 2026-07-15 +// "Chunk allocation failed" reboot signature) can be graphed from outside. +let Instrumentation +try { + Instrumentation = Modules.importNow('instrumentation') +} catch (_error) {} + +function instrumentsPayload() { + if (!Instrumentation) return undefined + const values = {} + try { + for (let index = 1; index < 40; index++) { + const name = Instrumentation.name(index) + if (!name) break + values[name] = Instrumentation.get(index) + } + } catch (_error) {} + return values +} import { EMOTIONS, MOD_NAME, @@ -208,6 +230,7 @@ export function statusPayload() { lastCommand: state.lastCommand, lastError: state.lastError, lastAbort: state.diagnostics.lastAbort ?? '', + instruments: instrumentsPayload(), } } diff --git a/mod/mod.js b/mod/mod.js index 4444885..d4404bb 100644 --- a/mod/mod.js +++ b/mod/mod.js @@ -49,7 +49,15 @@ globalThis.abort = function (status, exception) { const reason = `${status ?? 'abort'}: ${exception ?? ''}`.slice(0, 160) savePreference('lastAbort', reason) } catch (_error) { - // never throw from the abort hook + // Building the reason string allocates; when the abort IS heap + // exhaustion that fails (observed 2026-07-15: 20-byte chunk allocations + // failing right before "XS abort"). Fall back to persisting the status + // string as-is — a plain host string with far better odds. + try { + savePreference('lastAbort', status) + } catch (_error2) { + // never throw from the abort hook + } } return false } diff --git a/mod/tts-remote-safe.js b/mod/tts-remote-safe.js index 5b6e640..37a063d 100644 --- a/mod/tts-remote-safe.js +++ b/mod/tts-remote-safe.js @@ -10,10 +10,19 @@ // Host audio modules are resolved lazily; on a host without them the // constructor throws and the caller falls back to the host's own tts-remote. import Modules from 'modules' +import Timer from 'timer' const DEFAULT_SAMPLE_RATE = 24000 const DEFAULT_VOLUME = 0.5 const DEFAULT_BUFFER_MS = 1500 +// If the stream makes no forward progress — no audio block played, no ready +// transition — for this long, treat it as wedged: tear it down and reject so +// the caller's `finally` clears its busy flag instead of blocking every future +// utterance (observed 2026-07-15: a stalled stream left tts.busy stuck true and +// silenced all commentary until a reboot). The timer is reset on every sign of +// progress, so a long but healthy utterance is never cut off; it only has to be +// generous enough to cover the TTS server's synthesis latency before first byte. +const STALL_TIMEOUT_MS = 15000 class RemoteTTS { #AudioOut @@ -51,6 +60,42 @@ class RemoteTTS { this.audio.enqueue(0, this.#AudioOut.Volume, Math.round((volume ?? this.volume) * 256)) const audio = this.audio let streamer + let settled = false + let watchdog + + // Settle exactly once, always releasing the streamer, audio, and busy + // state first so a wedged stream can never leave `streaming` stuck. + const settle = (error) => { + if (settled) return + settled = true + if (watchdog !== undefined) { + Timer.clear(watchdog) + watchdog = undefined + } + this.streaming = false + try { + streamer?.close() + } catch (_closeError) {} + try { + this.audio?.close() + } catch (_closeError) {} + this.audio = undefined + if (error) reject(error) + else { + onDone?.() + resolve() + } + } + const kick = () => { + if (settled) return + if (watchdog !== undefined) Timer.clear(watchdog) + watchdog = Timer.set(() => { + trace('[matchday] tts stream stalled; aborting\n') + settle(new Error('tts stream stalled')) + }, STALL_TIMEOUT_MS) + } + kick() // arm before the first byte so a dead TTS host is caught too + streamer = new this.#WavStreamer({ http: device.network.http, host: this.host, @@ -62,9 +107,11 @@ class RemoteTTS { stream: 0, }, onPlayed(buffer) { + kick() if (onPlayed && calculatePower) onPlayed(calculatePower(buffer)) }, onReady(state) { + kick() trace(`Ready: ${state}\n`) if (state) { audio.start() @@ -74,20 +121,11 @@ class RemoteTTS { }, onError: (e) => { trace('ERROR: ', e, '\n') - this.streaming = false - streamer?.close() - this.audio?.close() - this.audio = undefined - reject(e) + settle(e instanceof Error ? e : new Error(String(e))) }, onDone: () => { trace('DONE\n') - this.streaming = false - streamer?.close() - this.audio?.close() - this.audio = undefined - onDone?.() - resolve() + settle() }, }) }) diff --git a/tools/test_stackchan_mod_layout.py b/tools/test_stackchan_mod_layout.py index 978ce92..ee82b5e 100644 --- a/tools/test_stackchan_mod_layout.py +++ b/tools/test_stackchan_mod_layout.py @@ -210,6 +210,15 @@ def test_http_service_uses_rejection_safe_listener(self): manifest = (ROOT / "mod" / "manifest.json").read_text(encoding="utf-8") self.assertIn('"matchday/listen-safe": "./listen-safe"', manifest) + def test_status_exposes_heap_instruments_and_abort_hook_survives_oom(self): + # Heap-exhaustion reboots (2026-07-15) are diagnosable from outside: + # /api/status carries XS heap usage when the host has instrumentation. + self.assertIn("Modules.importNow('instrumentation')", COMMANDS_SOURCE) + self.assertIn("instruments: instrumentsPayload()", COMMANDS_SOURCE) + # When the abort IS heap exhaustion, building the reason string fails; + # the hook must still persist something. + self.assertIn("savePreference('lastAbort', status)", MOD_SOURCE) + def test_tts_uses_deep_buffer_with_host_fallback(self): # The host pins WavStreamer to 600ms; XS busy bursts while speaking # overrun that and every overrun is an audible mid-sentence dropout. @@ -219,6 +228,13 @@ def test_tts_uses_deep_buffer_with_host_fallback(self): self.assertIn("Modules.importNow('tts-remote')", AUDIO_SOURCE) tts_source = (ROOT / "mod" / "tts-remote-safe.js").read_text(encoding="utf-8") self.assertIn("bufferDuration: this.bufferDuration", tts_source) + # A stalled stream must not leave the caller's busy flag stuck (observed + # 2026-07-15: silenced all commentary until reboot). A progress-reset + # watchdog settles the promise so speakRemote's finally clears busy. + self.assertIn("STALL_TIMEOUT_MS", tts_source) + self.assertIn("tts stream stalled", tts_source) + # progress resets the watchdog from both onReady and onPlayed + self.assertGreaterEqual(tts_source.count("kick()"), 3) manifest = (ROOT / "mod" / "manifest.json").read_text(encoding="utf-8") self.assertIn('"matchday/tts-remote-safe": "./tts-remote-safe"', manifest)