From f0d6be3533e795f93f1816e212dcc2b60a96067a Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 18 Sep 2026 15:37:29 +0000 Subject: [PATCH 1/4] Let the 30-pin ESP32 start the radio for an audio recording MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit A field report on 0.30.4 had every record_audio command fail on a classic ESP32 hub, while the same firmware and the same hive recorded fine on a C6: [HEAP] audio-start: free=91296 largest=63476 min_ever=28084 E NimBLEDevice: esp_nimble_hci_init() failed; err=257 [HI-AUD] BLE stack would not start ... (free heap 16284, largest 13812) err=257 is ESP_ERR_NO_MEM. Three things are wrong here, and the failed recording is the least of them. The relay asked for the radio LAST. Three large allocations have to coexist for a recording — the BT controller, the TLS session and the staging ring — and only the controller can neither shrink to fit nor be retried. It was bidding behind an open TLS session and the 4 kB upload buffer, on whatever they left: 75 kB of the 91 kB had gone before it was asked. It now goes first, via a new gattaudio::acquireRadio() split out of begin(), and the two that can bend take what is left (the ring already halves itself to 8 KiB). Only the STACK moves. The scan and the connect stay below the socket because HiveInside disconnects a connection that has not claimed a service within HIVE_LINK_ARM_TIMEOUT_MS (10 s, link.c), and only the START write cancels that timer; hoisting the connect as well would have spent that window on a TLS handshake whose own budget is 15 s, trading an out-of-memory failure for a mysterious disconnect. Connect-to-START is as tight as it always was. A failed init also stranded its memory. NimBLEDevice::init() brings the IDF controller up before it reaches the host, so a host-layer failure returns false with the controller still holding its allocation, and nothing unwound it: NimBLEDevice::deinit() guards on a flag the failed init never set, and blestack::release() early-returns on s_up. In the log above that cost ~20 kB for the rest of the cycle (91 kB at audio-start, 71 kB at cycle-end with everything torn down) and took the cycle's minimum free heap to 1456 bytes — the command-result POST and the OTA check that follow each open a fresh TLS session on that. acquire() now unwinds the controller by hand, guarded on its actual state. Not mem_release(): that would take BLE away for good and the next cycle's measurement scan would find no radio. The mic's I2S channel was held all cycle. shutdownMicsI2s() ran only in the deep-sleep prep, which is why "[INMP441] I2S uninstalled" prints after "[SLEEP]" in the report. That is 8 kB of DMA-capable internal RAM — the memory the BT controller wants — resident through the TLS handshake and the BLE init, on top of a heap the 2048-point double-precision FFT has just fragmented (91 kB free but only 63 kB in one piece). It is released as soon as the samples are read; the call in storage_power.cpp stays as a no-op. Why the C6 never showed it: config.h forces ENABLE_INMP441_MICS off there, so it pays for neither the DMA buffers nor the FFT's fragmentation; it takes 24 NimBLE msys blocks from its own sdkconfig where platformio.ini asks esp32dev for 48; and it has more, less divided DRAM and a BLE-only rather than dual-mode controller. MSYS1_BLOCK_COUNT is left at 48 deliberately — lowering it would reintroduce the 0.30.2 seams, and it should only be traded if the three fixes above turn out not to buy enough headroom. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01Jj45DVh6TKdwJ5LyYawqQx --- docs/audio-recording.md | 58 +++++++++++++++++++++++++++++- firmware/include/gatt_audio.h | 19 ++++++++-- firmware/src/ble_stack.cpp | 46 ++++++++++++++++++++++-- firmware/src/gatt_audio.cpp | 60 +++++++++++++++++++++----------- firmware/src/globals.cpp | 2 +- firmware/src/hivehub_network.cpp | 36 +++++++++++++++++++ firmware/src/sensors.cpp | 17 +++++++++ 7 files changed, 211 insertions(+), 27 deletions(-) diff --git a/docs/audio-recording.md b/docs/audio-recording.md index 5b43c7e..9ebb96f 100644 --- a/docs/audio-recording.md +++ b/docs/audio-recording.md @@ -311,6 +311,62 @@ If you see a reset on 0.30.1 or later, the serial log is the place to look: `platformio.ini`, so a panic prints a decoded backtrace rather than raw hex. +## Why this is a 30-pin ESP32 problem + +A field report on 0.30.4 had a hub fail every recording with + +``` +[HEAP] audio-start: free=91296 largest=63476 min_ever=28084 +E NimBLEDevice: esp_nimble_hci_init() failed; err=257 +[HI-AUD] BLE stack would not start ... (free heap 16284, largest block 13812) +``` + +`err=257` is `ESP_ERR_NO_MEM`. The same firmware and the same hive worked on an +ESP32-C6. Four things differ, and only the last is about the silicon: + +* **The classic board compiles a sensor path the C6 does not.** `config.h` + forces `ENABLE_INMP441_MICS` off on the C6. On `esp32dev` every cycle runs a + 2048-point FFT in double precision — `vReal` and `vImag` are 16 kB each — plus + two 8 kB sample buffers. They are all freed, so they cost no *space*; what + they leave behind is **fragmentation**, which is why `audio-start` above shows + 91 kB free but only 63 kB in one piece. The BT controller cannot use the rest. +* **The mic's I2S channel used to stay resident all cycle.** It was released in + the deep-sleep prep, which is why `[INMP441] I2S uninstalled` printed *after* + `[SLEEP]`. That is 8 kB of DMA-capable internal RAM — the exact memory the BT + controller wants — held through the TLS handshake and the BLE init. Since + 0.30.6 it is released as soon as the samples are read. +* **`esp32dev` asks for a bigger NimBLE mbuf pool.** `platformio.ini` sets + `CONFIG_BT_NIMBLE_MSYS1_BLOCK_COUNT=48` there and the C6 takes 24 from its own + sdkconfig. The irony is in the reason: the pool was raised *because* the + classic ESP32 is dual-core and its NimBLE host task competes with the WiFi + driver for core 0 (see [When a recording comes back with + seams](#when-a-recording-comes-back-with-seams)). The property that forced the + larger pool onto that board is the one that makes it hardest to afford. +* **Less usable DRAM, and a bigger controller.** The classic ESP32's SRAM is + split with a fixed IRAM/DRAM boundary, and its controller is dual-mode + Classic BT + BLE — larger than the C6's BLE-only one even with the Classic BT + memory released at init. + +0.30.6 changes two more things beyond the I2S release: + +* **The radio is asked for before the TLS socket, not after.** Three large + allocations have to coexist: the BT controller, the TLS session and the + staging ring. Only the controller can neither shrink nor be retried, so it now + goes first and the other two take what is left — the ring already halves + itself down to 8 KiB to fit. Only the *stack* moved; the scan and connect stay + below the socket, because the node disconnects a connection that has not + claimed a service within ten seconds and only START cancels that timer. +* **A failed BLE init no longer strands its memory.** `NimBLEDevice::init()` + brings the IDF controller up before it reaches the host, so a failure at the + host layer returned false with the controller still holding its allocation — + and nothing unwound it, because `NimBLEDevice::deinit()` guards on a flag the + failed init never set. In the log above that cost ~20 kB for the rest of the + cycle (91 kB at `audio-start`, 71 kB at `cycle-end` with everything torn + down), and the minimum free heap for the cycle was **1456 bytes** — the + command-result POST and the OTA check that follow each open a fresh TLS + session on that. The failed recording was the harmless half of this. + + ## When a recording comes back with seams A hub on 0.30.1 recorded 27.3 s of a 30 s request with `Dropped: 0 B` and @@ -369,5 +425,5 @@ one-second ring; it is a cheap `logDiag()` now. | Recording marked incomplete | See the quality flags above | | Gaps, with `Dropped` at 0 | The link kept up but audio was lost after it left the node. Fixed in 0.30.2 — see [When a recording comes back with seams](#when-a-recording-comes-back-with-seams) | | "hub reset during relay (panic/exception)" | A crash mid-session. Fixed in hub firmware 0.30.1 — see [When the hub resets mid-recording](#when-the-hub-resets-mid-recording) | -| "BLE stack would not start" | The hub could not bring the radio up with WiFi and TLS already open. Almost always a 30-pin ESP32 with an unusually full heap; the serial log prints the free heap and the largest free block next to it | +| "BLE stack would not start" | The hub could not bring the radio up at all. Almost always a 30-pin ESP32 with an unusually full heap; the serial log prints the free heap and the largest free block next to it. Hub firmware 0.30.6 makes this much less likely — see [Why this is a 30-pin ESP32 problem](#why-this-is-a-30-pin-esp32-problem) | | "audio buffer trimmed to N B" (serial log, not an error) | The hub could not get the full 32 KiB staging buffer and took a smaller one. The recording still happens; a slow upload will show up as gaps sooner | diff --git a/firmware/include/gatt_audio.h b/firmware/include/gatt_audio.h index 74bf1d8..9d27df8 100644 --- a/firmware/include/gatt_audio.h +++ b/firmware/include/gatt_audio.h @@ -30,10 +30,10 @@ // 60 s, so a lost STOP costs one minute of audio, never an open microphone. // // Lifecycle: -// begin(mac, durationDs, gainDb) → read(buf,n)… while streaming() → stop() -// → finish(&stats) → cleanup() +// [acquireRadio()] → begin(mac, durationDs, gainDb) → read(buf,n)… while +// streaming() → stop() → finish(&stats) → cleanup() // cleanup() releases the NimBLE stack and the ring, and is safe to call at any -// point after begin() — including after a failed begin(). +// point after acquireRadio() or begin() — including after either has failed. #pragma once #include @@ -73,9 +73,22 @@ struct Stats { // Plain-English name for a STATUS error byte. const char* errorText(uint8_t error); +// Bring the BLE stack up, and nothing else. Optional: begin() calls it itself, +// and it is idempotent. A caller that has other large allocations to make — +// the relay opens a TLS session and an upload buffer — should call this FIRST, +// because the BT controller is the only allocation on this path that can +// neither shrink to fit nor be retried. Returns false with lastError() set; the +// caller must still call cleanup(). See the note on the implementation for why +// this stops at the stack and does not also connect. +bool acquireRadio(); + // Connect, authenticate and start capture. `durationDs` is deciseconds, 0 for // open-ended. `gainDb` is clamped by the node to -20..+20. Returns false with // lastError() set; the caller must still call cleanup(). +// +// The node arms a 10-second window at connect and cancels it only when START +// claims the link, so everything between those two points is on a clock: do +// not put unrelated work inside this call. bool begin(const String& mac, uint16_t durationDs, int8_t gainDb); // Drain up to `max` PCM bytes. Returns 0 when nothing has arrived yet — that is diff --git a/firmware/src/ble_stack.cpp b/firmware/src/ble_stack.cpp index 63f13f9..3f71a00 100644 --- a/firmware/src/ble_stack.cpp +++ b/firmware/src/ble_stack.cpp @@ -5,6 +5,7 @@ GATT_OTA_ENABLED #include +#include namespace blestack { namespace { @@ -12,6 +13,40 @@ bool s_up = false; uint32_t s_generation = 0; // Port lifetime in which a scan last ran. 0 = no scan yet this boot. uint32_t s_scanGeneration = 0; + +// Give back what a FAILED NimBLEDevice::init() left behind. +// +// init() brings the ESP-IDF controller up — esp_bt_controller_init() then +// esp_bt_controller_enable() — before it reaches the NimBLE host, so a failure +// at the host layer returns false with the controller still holding its +// allocation. Nothing unwinds it on its own: NimBLEDevice::deinit() guards on +// the library's own m_initialized flag, which a failed init never set, so it is +// a no-op here; and release() below never runs because s_up was never set +// either. The memory is stranded until the next reset. +// +// A field log from a 30-pin hub shows exactly what that costs. The audio relay +// asked for the radio with WiFi and a TLS session resident, got +// +// E NimBLEDevice: esp_nimble_hci_init() failed; err=257 (ESP_ERR_NO_MEM) +// +// and the cycle went on: free heap 91 kB at the start of the attempt, 71 kB at +// the end of the cycle with everything else torn down, and a minimum free heap +// for the cycle of 1456 bytes. The failed recording was the harmless half of +// that. The command-result POST and the OTA check that follow it each open a +// fresh TLS session, and they ran on ~1.4 kB of headroom. +// +// Deliberately NOT esp_bt_controller_mem_release(): that hands the BLE memory +// back permanently and the next cycle's measurement scan would find no radio. +// Disable + deinit returns the controller to IDLE, where a later acquire() — +// this cycle's or the next one's — can try again. +void unwindFailedInit() { + if (esp_bt_controller_get_status() == ESP_BT_CONTROLLER_STATUS_ENABLED) { + esp_bt_controller_disable(); + } + if (esp_bt_controller_get_status() == ESP_BT_CONTROLLER_STATUS_INITED) { + esp_bt_controller_deinit(); + } +} } // namespace bool acquire() { @@ -21,14 +56,21 @@ bool acquire() { // could not get the memory they need — which is a real possibility on the // classic ESP32, whose BT controller wants tens of kilobytes and which has // far less DRAM than the C6 to begin with. The audio relay in particular asks - // for the stack with WiFi connected AND a TLS session already open, so this - // is the tightest moment in the whole firmware. + // for the stack with WiFi already connected — which is why it now asks BEFORE + // opening its TLS session rather than after (gatt_audio::acquireRadio), so + // the one allocation here that cannot shrink is not also the last in line. // // Returning here rather than pressing on is the point: none of NimBLE's host // API is usable after a failed init, and calling getScan() or createClient() // against an uninitialised host is a fault, not an error code. if (!NimBLEDevice::init("")) { Serial.println("[BLE] stack failed to start (no memory for the controller?)"); + // s_up false means no lifetime of ours is running, so there is nothing live + // to pull out from under: whatever init() got as far as allocating is + // unreachable and ours to give back. (A stack that WAS already up makes + // init() return true, so this branch cannot be reached with s_up set -- + // the guard is there so a future caller cannot make it so.) + if (!s_up) unwindFailedInit(); return false; } if (!s_up) { diff --git a/firmware/src/gatt_audio.cpp b/firmware/src/gatt_audio.cpp index 27114c3..f27e802 100644 --- a/firmware/src/gatt_audio.cpp +++ b/firmware/src/gatt_audio.cpp @@ -211,6 +211,33 @@ void cleanup() { blestack::release(); } +// Bring the BLE stack up on its own, ahead of everything else this file does. +// +// Split out of begin() because it is the one allocation on this path that +// cannot be made smaller and cannot be retried. The BT controller wants tens of +// kilobytes, some of it DMA-capable and in particular regions; the staging ring +// below halves itself to fit, and mbedtls takes ordinary heap. So the radio +// goes first, and the two that can bend take what is left. +// +// Only the STACK is brought up here — no scan, no connect. That matters: the +// node disconnects a connection that has not claimed a service within +// HIVE_LINK_ARM_TIMEOUT_MS (10 s, HiveInside link.c), and the timer is only +// cancelled by the START write. Hoisting the connect as well would spend that +// window on the caller's TLS handshake, whose own budget is 15 s, and turn an +// out-of-memory failure into a mysterious disconnect. Connect-to-START stays as +// tight as it has always been; it is the controller's allocation that moves. +bool acquireRadio() { + if (!blestack::acquire()) { + s_lastError = "BLE stack would not start (not enough memory for the BT controller)"; + Serial.printf("[HI-AUD] %s (free heap %u, largest block %u)\n", + s_lastError.c_str(), (unsigned)ESP.getFreeHeap(), + (unsigned)ESP.getMaxAllocHeap()); + return false; + } + NimBLEDevice::setMTU(247); // 240 PCM bytes per notification once granted + return true; +} + bool begin(const String& mac, uint16_t durationDs, int8_t gainDb) { s_lastError = ""; resetSession(); @@ -234,28 +261,21 @@ bool begin(const String& mac, uint16_t durationDs, int8_t gainDb) { return false; } - // Bring BLE up BEFORE the ring, not after. Both want memory from a heap that - // already holds WiFi and an open TLS session, and on the classic ESP32 there - // is far less of it than on the C6 — the BT controller alone wants tens of - // kilobytes. Of the two, the ring is the one that can be made smaller and - // still produce a recording, so it gets what is left rather than first - // refusal. Ordered the other way, a hub that could have recorded with a - // half-size buffer instead failed to start the radio at all. - if (!blestack::acquire()) { - s_lastError = "BLE stack would not start (out of memory with WiFi and TLS up?)"; - Serial.printf("[HI-AUD] %s (free heap %u, largest block %u)\n", - s_lastError.c_str(), (unsigned)ESP.getFreeHeap(), - (unsigned)ESP.getMaxAllocHeap()); - return false; - } - NimBLEDevice::setMTU(247); // 240 PCM bytes per notification once granted + // Idempotent when the caller already ran acquireRadio(), which the relay does + // precisely so this cannot be the thing that fails — see the contract note in + // gatt_audio.h. A caller that goes straight to begin() still gets a working + // session, just with the radio bidding last. + if (!acquireRadio()) return false; // Size the ring against what the heap can actually give, not against what the - // config asks for. HIVEINSIDE_AUDIO_RING_BYTES is a cushion — how long a TLS - // write may stall before audio is lost — so halving it costs gaps under load, - // while insisting on the full figure costs the whole recording. Never take - // more than half the largest contiguous block: mbedtls still has to allocate - // record buffers underneath this for every chunk of the upload. + // config asks for. This runs last of the three big allocations on this path — + // controller, TLS session, ring — which is the right way round: it is the + // only one of them that can shrink and still produce a recording. + // HIVEINSIDE_AUDIO_RING_BYTES is a cushion — how long a TLS write may stall + // before audio is lost — so halving it costs gaps under load, while insisting + // on the full figure costs the whole recording. Never take more than half the + // largest contiguous block: mbedtls still has to allocate record buffers + // underneath this for every chunk of the upload. size_t want = HIVEINSIDE_AUDIO_RING_BYTES; const size_t largest = ESP.getMaxAllocHeap(); while (want > HIVEINSIDE_AUDIO_RING_MIN_BYTES && want > largest / 2) { diff --git a/firmware/src/globals.cpp b/firmware/src/globals.cpp index 506f971..d292342 100644 --- a/firmware/src/globals.cpp +++ b/firmware/src/globals.cpp @@ -3,7 +3,7 @@ #include -const char* const FIRMWARE_VERSION = "0.30.5"; +const char* const FIRMWARE_VERSION = "0.30.6"; #if ENABLE_HX711 HX711 scale1; diff --git a/firmware/src/hivehub_network.cpp b/firmware/src/hivehub_network.cpp index 2499939..8b03332 100644 --- a/firmware/src/hivehub_network.cpp +++ b/firmware/src/hivehub_network.cpp @@ -1172,6 +1172,37 @@ static bool relayAudioSession(const String& mac, long recordingId, heapdiag::probe("audio-start"); + // Bring the radio up BEFORE the socket, not after. + // + // Three big allocations have to coexist for a recording: the BT controller, + // the TLS session, and the staging ring. Only one of them can neither shrink + // nor be retried — the controller wants tens of kilobytes, some of it + // DMA-capable and in particular regions, and when it cannot have them the + // recording is simply over. Asking for it last, behind an open TLS session, + // is asking the one inflexible allocation to take whatever the flexible ones + // left. A field log from a 30-pin hub shows the result: 91 kB free at + // audio-start, and by the time the radio was asked for, + // + // E NimBLEDevice: esp_nimble_hci_init() failed; err=257 (ESP_ERR_NO_MEM) + // [HI-AUD] ... (free heap 16284, largest block 13812) + // + // The C6 never shows this: it has more heap to begin with, and it does not + // compile the INMP441 path whose FFT fragments what is there (config.h forces + // ENABLE_INMP441_MICS off on that board). + // + // Only the STACK moves up here. The scan and the connect stay inside begin(), + // below the socket, because the node disconnects a connection that has not + // claimed a service within ten seconds and only the START write cancels that + // timer — see gatt_audio.cpp. Hoisting the connect too would spend that + // window on the TLS handshake, whose own budget is fifteen. + if (!gattaudio::acquireRadio()) { + setMsg(gattaudio::lastError().length() + ? gattaudio::lastError() + : String("BLE stack would not start")); + gattaudio::cleanup(); // hands the controller back for the rest of the cycle + return false; + } + WiFiClientSecure secureClient; WiFiClient plainClient; WiFiClient* sock = nullptr; @@ -1201,6 +1232,7 @@ static bool relayAudioSession(const String& mac, long recordingId, secureClient.setTimeout(HTTP_REQUEST_TIMEOUT_MS); if (!secureClient.connect(host.c_str(), port)) { setMsg("TLS connect to the backend failed"); + gattaudio::cleanup(); return false; } sock = &secureClient; @@ -1209,6 +1241,7 @@ static bool relayAudioSession(const String& mac, long recordingId, plainClient.setTimeout(HTTP_REQUEST_TIMEOUT_MS); if (!plainClient.connect(host.c_str(), port)) { setMsg("connect to the backend failed"); + gattaudio::cleanup(); return false; } sock = &plainClient; @@ -1253,9 +1286,12 @@ static bool relayAudioSession(const String& mac, long recordingId, (unsigned)ESP.getFreeHeap(), (unsigned)ESP.getMaxAllocHeap()); sock->print("0\r\n\r\n"); sock->stop(); + gattaudio::cleanup(); return false; } + // The stack is already up from acquireRadio() above; this is the scan, + // connect, subscribe, ring and START. bool bleOk = gattaudio::begin(mac, durationDs, gainDb); if (!bleOk) { setMsg(gattaudio::lastError().length() ? gattaudio::lastError() diff --git a/firmware/src/sensors.cpp b/firmware/src/sensors.cpp index 534e38a..a634af4 100644 --- a/firmware/src/sensors.cpp +++ b/firmware/src/sensors.cpp @@ -602,6 +602,23 @@ void buildMeasurementDoc(JsonDocument& doc) { #endif MicMeasurement micResult; if (wiredMicUsed) micResult = readMicSamples(); + // Release the I2S channel the moment the samples are in hand, rather than + // leaving it to the deep-sleep prep in storage_power.cpp. + // + // The channel holds dma_desc_num * dma_frame_num * slots * 4 B — 8 kB with + // the settings in mics.cpp — of DMA-capable internal RAM, which is exactly + // the memory the BT controller needs when the audio relay asks for the radio + // later in the same cycle. Held to deep sleep it was resident through the + // whole of that, and on the classic ESP32 it is resident on top of a heap the + // 2048-point double-precision FFT above has just finished fragmenting. The + // C6 pays neither cost: config.h forces ENABLE_INMP441_MICS off there, which + // is a large part of why the same relay starts on one board and not the other. + // + // Unconditional and idempotent: shutdownMicsI2s() returns immediately when + // nothing is installed, which covers the BLE-override path above. The next + // cycle is a fresh boot out of deep sleep, and readMicSamples() installs the + // channel itself, so nothing here needs to put it back. + shutdownMicsI2s(); #endif // ── BeeCounter (entrance gates) — BLE/GATT only ──────────────────────────── From 8504b40e1c819aa78cffaab03e9943d5bd30145b Mon Sep 17 00:00:00 2001 From: Claude Date: Sun, 20 Sep 2026 19:07:04 +0000 Subject: [PATCH 2/4] Put the TLS socket back in front of the radio, and lower the peak instead MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 0.30.6 reordered the audio relay to ask for the BLE stack BEFORE opening its upload socket, on the reasoning that the BT controller is the one allocation on that path which can neither shrink to fit nor be retried, so it should get first refusal. A 30-pin hub in the field disproved that in one cycle: id | relay_duration | message 76 | 00:00:01.281127 | TLS connect to the backend failed 1.28 s from claimed_at to completed_at, against a 15 s connect timeout — and that window also contains a SUCCESSFUL TLS handshake to the same host, the one that reported the failure after cleanup() released the radio. So the failed connect consumed essentially no time at all: an allocation that gave up before it reached the network, not a slow link, not coexistence, not DNS. The radio fix worked. It just moved the failure to the other side. The mis-ranking was about WHICH constraint binds. The controller needs a large total in many pieces. mbedtls needs CONTIGUITY, and this framework asks for a lot of it: CONFIG_MBEDTLS_SSL_MAX_CONTENT_LEN is 16384 with CONFIG_MBEDTLS_ASYMMETRIC_CONTENT_LEN unset, so a session wants two 16 kB contiguous record buffers and neither may be the small one. Contiguity is the first thing fragmentation destroys, so whichever of the two goes second, mbedtls suffers far worse for it. The original 0.30.4 log had already said so and nobody read it that way: once the controller took its share, `largest` had collapsed to 13812 — under one record buffer. So the socket goes first again, the controller takes what is left, and the ring stays last as the only one of the three that can shrink and still produce a recording. relayAudioSession() and begin() are back to their pre-0.30.6 control flow; the long comments at both sites record the evidence so this is not rediscovered by reordering it a third time. Both allocations still have to fit, which is a matter of lowering the peak rather than reordering it. Two things do that, and the first was already right in 0.30.6: * the mic I2S channel is freed at the measurement instead of at deep sleep (~8 kB of DMA-capable internal RAM, esp32dev only) — unchanged here; * CONFIG_BT_NIMBLE_MSYS1_BLOCK_COUNT on esp32dev goes 48 -> 24, giving back ~6 kB. That reverses part of 0.30.2, whose note read "costs 12 kB of heap while the stack is up, on a board with ~260 kB free" — true at boot, and badly wrong at the moment that matters, where the same hub is at ~91 kB with a 63 kB largest block. Seams in a recording beat no recording. 24 is still twice NimBLE's own default and matches what the C6 takes from its sdkconfig, and the other two causes of the 0.30.2 seams (three TLS records per chunk, a ring that could not absorb a stalled write) were fixed in code and are untouched. The 0.30.6 failure had to be diagnosed from backend command timestamps because the firmware printed no number anywhere on that path. Fixed: * "[HEAP] audio-radio-up" logs free/largest/min_ever with BOTH the TLS session and the controller resident — the reading every question here turns out to need; * the "TLS connect to the backend failed" line now carries free heap and largest block, so a repeat is legible from a serial log alone. Kept from 0.30.6 unchanged: the failed-init unwind in blestack::acquire(), which is what stopped ~20 kB stranding for the rest of the cycle and the minimum free heap reaching 1456 bytes. Built clean on esp32dev (default and with ENABLE_INMP441_MICS=1) and on xiao_esp32c6. Co-Authored-By: Claude Opus 5 Claude-Session: https://claude.ai/code/session_01Jj45DVh6TKdwJ5LyYawqQx --- docs/audio-recording.md | 128 ++++++++++++++++++++++--------- firmware/include/gatt_audio.h | 19 ++--- firmware/platformio.ini | 21 ++++- firmware/src/ble_stack.cpp | 8 +- firmware/src/gatt_audio.cpp | 57 ++++++-------- firmware/src/globals.cpp | 2 +- firmware/src/hivehub_network.cpp | 64 ++++++++-------- 7 files changed, 181 insertions(+), 118 deletions(-) diff --git a/docs/audio-recording.md b/docs/audio-recording.md index 9ebb96f..28c02f0 100644 --- a/docs/audio-recording.md +++ b/docs/audio-recording.md @@ -329,43 +329,94 @@ ESP32-C6. Four things differ, and only the last is about the silicon: 2048-point FFT in double precision — `vReal` and `vImag` are 16 kB each — plus two 8 kB sample buffers. They are all freed, so they cost no *space*; what they leave behind is **fragmentation**, which is why `audio-start` above shows - 91 kB free but only 63 kB in one piece. The BT controller cannot use the rest. + 91 kB free but only 63 kB in one piece. * **The mic's I2S channel used to stay resident all cycle.** It was released in the deep-sleep prep, which is why `[INMP441] I2S uninstalled` printed *after* - `[SLEEP]`. That is 8 kB of DMA-capable internal RAM — the exact memory the BT - controller wants — held through the TLS handshake and the BLE init. Since - 0.30.6 it is released as soon as the samples are read. -* **`esp32dev` asks for a bigger NimBLE mbuf pool.** `platformio.ini` sets - `CONFIG_BT_NIMBLE_MSYS1_BLOCK_COUNT=48` there and the C6 takes 24 from its own - sdkconfig. The irony is in the reason: the pool was raised *because* the + `[SLEEP]`. That is 8 kB of DMA-capable internal RAM held through the TLS + handshake and the BLE init. Since 0.30.6 it is released as soon as the + samples are read. +* **`esp32dev` asked for a bigger NimBLE mbuf pool.** `platformio.ini` set + `CONFIG_BT_NIMBLE_MSYS1_BLOCK_COUNT=48` there where the C6 takes 24 from its + own sdkconfig. The irony was in the reason: the pool was raised *because* the classic ESP32 is dual-core and its NimBLE host task competes with the WiFi - driver for core 0 (see [When a recording comes back with - seams](#when-a-recording-comes-back-with-seams)). The property that forced the - larger pool onto that board is the one that makes it hardest to afford. + driver for core 0. The property that forced the larger pool onto that board is + the one that made it hardest to afford. 0.30.7 lowers it to 24. * **Less usable DRAM, and a bigger controller.** The classic ESP32's SRAM is - split with a fixed IRAM/DRAM boundary, and its controller is dual-mode - Classic BT + BLE — larger than the C6's BLE-only one even with the Classic BT - memory released at init. - -0.30.6 changes two more things beyond the I2S release: - -* **The radio is asked for before the TLS socket, not after.** Three large - allocations have to coexist: the BT controller, the TLS session and the - staging ring. Only the controller can neither shrink nor be retried, so it now - goes first and the other two take what is left — the ring already halves - itself down to 8 KiB to fit. Only the *stack* moved; the scan and connect stay - below the socket, because the node disconnects a connection that has not - claimed a service within ten seconds and only START cancels that timer. -* **A failed BLE init no longer strands its memory.** `NimBLEDevice::init()` - brings the IDF controller up before it reaches the host, so a failure at the - host layer returned false with the controller still holding its allocation — - and nothing unwound it, because `NimBLEDevice::deinit()` guards on a flag the - failed init never set. In the log above that cost ~20 kB for the rest of the - cycle (91 kB at `audio-start`, 71 kB at `cycle-end` with everything torn - down), and the minimum free heap for the cycle was **1456 bytes** — the - command-result POST and the OTA check that follow each open a fresh TLS - session on that. The failed recording was the harmless half of this. + split with a fixed IRAM/DRAM boundary, and the shipped framework builds its + controller in dual mode (`CONFIG_BTDM_CTRL_MODE_BTDM=y`) rather than BLE-only, + so it is the larger variant even though NimBLE releases the Classic BT static + memory at init. +### The ordering trap, and why the socket goes first + +0.30.6 also reordered the relay to ask for the radio *before* opening the TLS +socket, reasoning that the BT controller is the one allocation here that can +neither shrink nor be retried, so it should get first refusal. **That was +wrong, and the field disproved it in a single cycle.** The radio started and +the handshake underneath it did not: + +``` +TLS connect to the backend failed 1.28 s from claimed_at to completed_at +``` + +against a 15-second connect timeout. An allocation had failed before anything +touched the network — and the same cycle went on to complete a TLS handshake to +the same host, to report that very failure, once the radio had been released. + +The mis-ranking was about *which* constraint binds. The controller needs a large +total in many pieces. mbedtls needs **contiguity**, and a lot of it: this +framework ships `CONFIG_MBEDTLS_SSL_MAX_CONTENT_LEN=16384` with +`CONFIG_MBEDTLS_ASYMMETRIC_CONTENT_LEN` unset, so a session wants **two 16 kB +contiguous record buffers** and neither may be the small one. Contiguity is the +first thing fragmentation destroys, so whichever of the two runs second, +mbedtls suffers far worse for it. The 0.30.4 log had already said so: once the +controller took its share, `largest` collapsed to 13812 — under one record +buffer. + +So the fragile allocation goes first, the robust one takes what is left, and +the ring — the only one of the three that can shrink and still produce a +recording — goes last. Getting all three to fit is a matter of lowering the +peak, not of reordering it. **Do not re-reorder this without a field log +showing the handshake surviving underneath a live controller.** + +That log is now possible: 0.30.7 prints + +``` +[HEAP] audio-radio-up: free=… largest=… min_ever=… +``` + +with both the TLS session and the controller resident, and puts the free and +largest-block figures on the `TLS connect to the backend failed` line too. The +0.30.6 failure had to be diagnosed from `device_commands` timestamps in the +backend, because neither number was printed anywhere. + +If you need to diagnose one of these without a serial cable, that query is +worth keeping: + +```sql +SELECT id, claimed_at, completed_at, + completed_at - claimed_at AS relay_duration, + result->>'message' AS message +FROM device_commands +WHERE command_type = 'record_audio' +ORDER BY id DESC LIMIT 5; +``` + +A sub-second duration on a connect failure means an allocation that never +reached the network. Something near the 15-second timeout means a link or a +handshake problem instead. The two want completely different fixes. + +### A failed BLE init no longer strands its memory + +`NimBLEDevice::init()` brings the IDF controller up before it reaches the host, +so a failure at the host layer returned false with the controller still holding +its allocation — and nothing unwound it, because `NimBLEDevice::deinit()` guards +on a flag the failed init never set. In the 0.30.4 log that cost ~20 kB for the +rest of the cycle (91 kB at `audio-start`, 71 kB at `cycle-end` with everything +torn down), and the minimum free heap for the cycle was **1456 bytes** — the +command-result POST and the OTA check that follow each open a fresh TLS session +on that. The failed recording was the harmless half of it. Since 0.30.6 +`blestack::acquire()` unwinds the controller by hand when init fails. ## When a recording comes back with seams @@ -393,9 +444,13 @@ Two things on the hub can do that, and 0.30.2 addresses both: NimBLE host task shares core 0 with the WiFi driver, which is busy precisely because the same session is uploading over TLS. Whenever the host task was held off longer than that, the pool emptied and the controller dropped the - next packet before any HiveHub code saw it. `platformio.ini` now asks for 48 - blocks (~370 ms) on `esp32dev`. The C6 already gets 24 from the IDF and is - single-core, so its host task is not competing the same way. + next packet before any HiveHub code saw it. `platformio.ini` raised this to 48 + blocks (~370 ms) on `esp32dev` in 0.30.2, and **0.30.7 lowered it again to 24 + (~185 ms)** to buy back ~6 kB for the memory problem above — seams beat no + recording. 24 is still twice NimBLE's own default, and the other two causes of + the 0.30.2 seams (below) were fixed in code, not by buffering. The C6 gets 24 + from the IDF and is single-core, so its host task is not competing the same + way. * **Each HTTP chunk cost three TLS records.** Every `NetworkClientSecure::write()` is one `mbedtls_ssl_write()`, so writing the hex length line, the payload and the trailing CRLF separately spent three records — three lots of framing and @@ -425,5 +480,6 @@ one-second ring; it is a cheap `logDiag()` now. | Recording marked incomplete | See the quality flags above | | Gaps, with `Dropped` at 0 | The link kept up but audio was lost after it left the node. Fixed in 0.30.2 — see [When a recording comes back with seams](#when-a-recording-comes-back-with-seams) | | "hub reset during relay (panic/exception)" | A crash mid-session. Fixed in hub firmware 0.30.1 — see [When the hub resets mid-recording](#when-the-hub-resets-mid-recording) | -| "BLE stack would not start" | The hub could not bring the radio up at all. Almost always a 30-pin ESP32 with an unusually full heap; the serial log prints the free heap and the largest free block next to it. Hub firmware 0.30.6 makes this much less likely — see [Why this is a 30-pin ESP32 problem](#why-this-is-a-30-pin-esp32-problem) | +| "BLE stack would not start" | The hub could not bring the radio up at all. Almost always a 30-pin ESP32 with an unusually full heap; the serial log prints the free heap and the largest free block next to it. Hub firmware 0.30.7 makes this much less likely — see [Why this is a 30-pin ESP32 problem](#why-this-is-a-30-pin-esp32-problem) | +| "TLS connect to the backend failed" | The hub could not open the upload socket. Since 0.30.7 the serial log prints free heap and largest block beside it; a sub-second `relay_duration` in `device_commands` means an allocation failure rather than a network one. This was the 0.30.6 symptom of asking for the radio before the socket | | "audio buffer trimmed to N B" (serial log, not an error) | The hub could not get the full 32 KiB staging buffer and took a smaller one. The recording still happens; a slow upload will show up as gaps sooner | diff --git a/firmware/include/gatt_audio.h b/firmware/include/gatt_audio.h index 9d27df8..4ed89c1 100644 --- a/firmware/include/gatt_audio.h +++ b/firmware/include/gatt_audio.h @@ -30,10 +30,14 @@ // 60 s, so a lost STOP costs one minute of audio, never an open microphone. // // Lifecycle: -// [acquireRadio()] → begin(mac, durationDs, gainDb) → read(buf,n)… while -// streaming() → stop() → finish(&stats) → cleanup() +// begin(mac, durationDs, gainDb) → read(buf,n)… while streaming() → stop() +// → finish(&stats) → cleanup() // cleanup() releases the NimBLE stack and the ring, and is safe to call at any -// point after acquireRadio() or begin() — including after either has failed. +// point after begin() — including after a failed begin(). +// +// begin() brings the radio up itself, and the caller should already have its +// TLS session open when it does. 0.30.6 inverted that and the handshake failed +// underneath the controller; hivehub_network.cpp carries the field evidence. #pragma once #include @@ -73,15 +77,6 @@ struct Stats { // Plain-English name for a STATUS error byte. const char* errorText(uint8_t error); -// Bring the BLE stack up, and nothing else. Optional: begin() calls it itself, -// and it is idempotent. A caller that has other large allocations to make — -// the relay opens a TLS session and an upload buffer — should call this FIRST, -// because the BT controller is the only allocation on this path that can -// neither shrink to fit nor be retried. Returns false with lastError() set; the -// caller must still call cleanup(). See the note on the implementation for why -// this stops at the stack and does not also connect. -bool acquireRadio(); - // Connect, authenticate and start capture. `durationDs` is deciseconds, 0 for // open-ended. `gainDb` is clamped by the node to -20..+20. Returns false with // lastError() set; the caller must still call cleanup(). diff --git a/firmware/platformio.ini b/firmware/platformio.ini index 89fd048..0bce9c0 100644 --- a/firmware/platformio.ini +++ b/firmware/platformio.ini @@ -66,11 +66,28 @@ build_flags = ; gone before any HiveHub code sees it. It arrives as a sequence jump, which the ; hub counts as a gap and the dashboard reports as a seam in the recording. ; 48 blocks is ~370 ms, which covers the scheduling jitter a hub actually sees. -; Costs 12 kB of heap while the stack is up, on a board with ~260 kB free. +; +; 0.30.7 lowered this to 24 (~185 ms), and the reason is worth stating because +; it reverses part of the trade above. "Costs 12 kB of heap while the stack is +; up, on a board with ~260 kB free" was true at BOOT and badly wrong at the +; moment that matters: by the time the audio relay asks for the radio, a 30-pin +; hub is down to ~91 kB with its largest free block at ~63 kB, and every +; recording on that hub failed for want of memory — first the controller +; refusing to start, then, when 0.30.6 let the controller go first, mbedtls +; refusing to hand out a TLS session underneath it. Seams in a recording beat +; no recording, so the pool gives back its ~6 kB. +; +; 24 blocks is still twice NimBLE's own default of 12 and the same figure the +; C6 takes from its sdkconfig, and the two OTHER causes of the 0.30.2 seams — +; three TLS records per HTTP chunk, and a staging ring that could not absorb a +; stalled write — were fixed in the code and are unaffected. If seams come back +; on a hub that has heap to spare, this is the first knob to raise again, and +; the "[HEAP] audio-radio-up" line added in 0.30.7 is how to tell whether that +; hub does. ; esp32dev ONLY: this target has no CONFIG_BT_NIMBLE_MSYS1_BLOCK_COUNT in its ; sdkconfig.h, so NimBLE-Arduino's nimconfig.h default of 12 is what applies ; and this -D is what changes it. See the note in [env:xiao_esp32c6]. - -DCONFIG_BT_NIMBLE_MSYS1_BLOCK_COUNT=48 + -DCONFIG_BT_NIMBLE_MSYS1_BLOCK_COUNT=24 lib_deps = ; HX711 load-cell amp (classic 30-pin board only; force-disabled on the C6). bogde/HX711@0.7.5 diff --git a/firmware/src/ble_stack.cpp b/firmware/src/ble_stack.cpp index 3f71a00..94a6404 100644 --- a/firmware/src/ble_stack.cpp +++ b/firmware/src/ble_stack.cpp @@ -56,9 +56,11 @@ bool acquire() { // could not get the memory they need — which is a real possibility on the // classic ESP32, whose BT controller wants tens of kilobytes and which has // far less DRAM than the C6 to begin with. The audio relay in particular asks - // for the stack with WiFi already connected — which is why it now asks BEFORE - // opening its TLS session rather than after (gatt_audio::acquireRadio), so - // the one allocation here that cannot shrink is not also the last in line. + // for the stack with WiFi connected AND a TLS session already open, so this + // is the tightest moment in the whole firmware. That order is deliberate and + // was tested the other way round in 0.30.6: see gatt_audio.cpp: mbedtls needs + // contiguous 16 kB record buffers and loses that race to a resident + // controller, so the controller is the one that bids last. // // Returning here rather than pressing on is the point: none of NimBLE's host // API is usable after a failed init, and calling getScan() or createClient() diff --git a/firmware/src/gatt_audio.cpp b/firmware/src/gatt_audio.cpp index f27e802..678b64b 100644 --- a/firmware/src/gatt_audio.cpp +++ b/firmware/src/gatt_audio.cpp @@ -12,6 +12,7 @@ #include "audio_ring.h" #include "ble_stack.h" +#include "heap_diag.h" #include "hivehub_network.h" // crc32Update #if ENABLE_BLE_SCAN @@ -211,33 +212,6 @@ void cleanup() { blestack::release(); } -// Bring the BLE stack up on its own, ahead of everything else this file does. -// -// Split out of begin() because it is the one allocation on this path that -// cannot be made smaller and cannot be retried. The BT controller wants tens of -// kilobytes, some of it DMA-capable and in particular regions; the staging ring -// below halves itself to fit, and mbedtls takes ordinary heap. So the radio -// goes first, and the two that can bend take what is left. -// -// Only the STACK is brought up here — no scan, no connect. That matters: the -// node disconnects a connection that has not claimed a service within -// HIVE_LINK_ARM_TIMEOUT_MS (10 s, HiveInside link.c), and the timer is only -// cancelled by the START write. Hoisting the connect as well would spend that -// window on the caller's TLS handshake, whose own budget is 15 s, and turn an -// out-of-memory failure into a mysterious disconnect. Connect-to-START stays as -// tight as it has always been; it is the controller's allocation that moves. -bool acquireRadio() { - if (!blestack::acquire()) { - s_lastError = "BLE stack would not start (not enough memory for the BT controller)"; - Serial.printf("[HI-AUD] %s (free heap %u, largest block %u)\n", - s_lastError.c_str(), (unsigned)ESP.getFreeHeap(), - (unsigned)ESP.getMaxAllocHeap()); - return false; - } - NimBLEDevice::setMTU(247); // 240 PCM bytes per notification once granted - return true; -} - bool begin(const String& mac, uint16_t durationDs, int8_t gainDb) { s_lastError = ""; resetSession(); @@ -261,11 +235,30 @@ bool begin(const String& mac, uint16_t durationDs, int8_t gainDb) { return false; } - // Idempotent when the caller already ran acquireRadio(), which the relay does - // precisely so this cannot be the thing that fails — see the contract note in - // gatt_audio.h. A caller that goes straight to begin() still gets a working - // session, just with the radio bidding last. - if (!acquireRadio()) return false; + // Bring BLE up here, with the caller's TLS session already open, and NOT + // ahead of it. 0.30.6 hoisted this above the socket on the theory that the + // controller is the least flexible allocation and should bid first; the + // field answered in one cycle with "TLS connect to the backend failed" 1.28 s + // after the command was claimed, against a 15 s connect timeout — mbedtls + // failing to allocate, before it reached the network. See the long note in + // hivehub_network.cpp: mbedtls needs two 16 kB CONTIGUOUS record buffers on + // this framework, and contiguity is what a resident BT controller destroys. + // The fragile allocation goes first; this one is the robust one. + if (!blestack::acquire()) { + s_lastError = "BLE stack would not start (out of memory with WiFi and TLS up?)"; + Serial.printf("[HI-AUD] %s (free heap %u, largest block %u)\n", + s_lastError.c_str(), (unsigned)ESP.getFreeHeap(), + (unsigned)ESP.getMaxAllocHeap()); + return false; + } + NimBLEDevice::setMTU(247); // 240 PCM bytes per notification once granted + + // What the heap looks like with BOTH the TLS session and the controller + // resident — the number every question on this path turns out to need, and + // the one 0.30.6 had no way to print. logDiag(), not probe(): nothing is + // streaming yet, but checkIntegrity() walks every block and this runs inside + // the node's ten-second arm window once the connect below happens. + heapdiag::logDiag("audio-radio-up"); // Size the ring against what the heap can actually give, not against what the // config asks for. This runs last of the three big allocations on this path — diff --git a/firmware/src/globals.cpp b/firmware/src/globals.cpp index d292342..c71ca6e 100644 --- a/firmware/src/globals.cpp +++ b/firmware/src/globals.cpp @@ -3,7 +3,7 @@ #include -const char* const FIRMWARE_VERSION = "0.30.6"; +const char* const FIRMWARE_VERSION = "0.30.7"; #if ENABLE_HX711 HX711 scale1; diff --git a/firmware/src/hivehub_network.cpp b/firmware/src/hivehub_network.cpp index 8b03332..f80e967 100644 --- a/firmware/src/hivehub_network.cpp +++ b/firmware/src/hivehub_network.cpp @@ -1172,37 +1172,36 @@ static bool relayAudioSession(const String& mac, long recordingId, heapdiag::probe("audio-start"); - // Bring the radio up BEFORE the socket, not after. + // The SOCKET goes up before the radio, and that order is load-bearing. // - // Three big allocations have to coexist for a recording: the BT controller, - // the TLS session, and the staging ring. Only one of them can neither shrink - // nor be retried — the controller wants tens of kilobytes, some of it - // DMA-capable and in particular regions, and when it cannot have them the - // recording is simply over. Asking for it last, behind an open TLS session, - // is asking the one inflexible allocation to take whatever the flexible ones - // left. A field log from a 30-pin hub shows the result: 91 kB free at - // audio-start, and by the time the radio was asked for, + // 0.30.6 tried it the other way, reasoning that the BT controller is the one + // allocation here that can neither shrink nor be retried, so it should get + // first refusal. The field disproved it in one cycle: the radio started and + // the handshake underneath it did not, with // - // E NimBLEDevice: esp_nimble_hci_init() failed; err=257 (ESP_ERR_NO_MEM) - // [HI-AUD] ... (free heap 16284, largest block 13812) + // "TLS connect to the backend failed" 1.28 s from claim to result // - // The C6 never shows this: it has more heap to begin with, and it does not - // compile the INMP441 path whose FFT fragments what is there (config.h forces - // ENABLE_INMP441_MICS off on that board). + // against a 15 s connect timeout — an allocation that failed before anything + // touched the network, not a slow or degraded link. (The same cycle then + // completed a TLS handshake to the same host to REPORT that failure, once + // the radio had been released again.) // - // Only the STACK moves up here. The scan and the connect stay inside begin(), - // below the socket, because the node disconnects a connection that has not - // claimed a service within ten seconds and only the START write cancels that - // timer — see gatt_audio.cpp. Hoisting the connect too would spend that - // window on the TLS handshake, whose own budget is fifteen. - if (!gattaudio::acquireRadio()) { - setMsg(gattaudio::lastError().length() - ? gattaudio::lastError() - : String("BLE stack would not start")); - gattaudio::cleanup(); // hands the controller back for the rest of the cycle - return false; - } - + // The reasoning was wrong about which constraint binds. The controller needs + // a large total in many pieces; mbedtls needs CONTIGUITY, and on this + // framework it needs a lot of it: CONFIG_MBEDTLS_SSL_MAX_CONTENT_LEN is + // 16384 with CONFIG_MBEDTLS_ASYMMETRIC_CONTENT_LEN unset, so a session wants + // TWO 16 kB contiguous record buffers and neither of them may be the small + // one. Contiguity is what fragmentation destroys first, so whichever of the + // two runs second, mbedtls suffers far worse for it. The 0.30.4 log said as + // much before anyone read it that way: once the controller had taken its + // share, `largest` had collapsed to 13812 — under one record buffer. + // + // So the fragile allocation goes first and the robust one takes what is + // left. Getting both to fit at all is a separate problem, addressed by + // lowering the peak rather than by reordering it: the mic I2S channel is + // freed at the measurement now (sensors.cpp) and esp32dev asks for a smaller + // NimBLE mbuf pool (platformio.ini). Do not re-reorder this without a field + // log showing the handshake surviving underneath a live controller. WiFiClientSecure secureClient; WiFiClient plainClient; WiFiClient* sock = nullptr; @@ -1231,8 +1230,13 @@ static bool relayAudioSession(const String& mac, long recordingId, secureClient.setConnectionTimeout(HTTP_REQUEST_TIMEOUT_MS); secureClient.setTimeout(HTTP_REQUEST_TIMEOUT_MS); if (!secureClient.connect(host.c_str(), port)) { + // Say what the heap looked like. This is the failure 0.30.6 produced in + // the field, and it was diagnosed from command timestamps in the backend + // rather than from this line, because this line did not carry a number. setMsg("TLS connect to the backend failed"); - gattaudio::cleanup(); + Serial.printf("[HI-AUD] TLS connect to the backend failed " + "(free heap %u, largest block %u)\n", + (unsigned)ESP.getFreeHeap(), (unsigned)ESP.getMaxAllocHeap()); return false; } sock = &secureClient; @@ -1241,7 +1245,6 @@ static bool relayAudioSession(const String& mac, long recordingId, plainClient.setTimeout(HTTP_REQUEST_TIMEOUT_MS); if (!plainClient.connect(host.c_str(), port)) { setMsg("connect to the backend failed"); - gattaudio::cleanup(); return false; } sock = &plainClient; @@ -1286,12 +1289,9 @@ static bool relayAudioSession(const String& mac, long recordingId, (unsigned)ESP.getFreeHeap(), (unsigned)ESP.getMaxAllocHeap()); sock->print("0\r\n\r\n"); sock->stop(); - gattaudio::cleanup(); return false; } - // The stack is already up from acquireRadio() above; this is the scan, - // connect, subscribe, ring and START. bool bleOk = gattaudio::begin(mac, durationDs, gainDb); if (!bleOk) { setMsg(gattaudio::lastError().length() ? gattaudio::lastError() From e85e9db923ff4ac6d3319d002db1eeea136c14ff Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 25 Sep 2026 20:01:36 +0000 Subject: [PATCH 3/4] Report why an audio session failed instead of timing out into a guess Field test of 0.30.7 on a 30-pin ESP32: the recording ended as "the hub started uploading but no audio arrived", and the backend logged an unhandled ClientDisconnect traceback. Traefik shows the upload POST closed by the hub after 207 ms (499): the BLE session failed to start straight after the socket opened, the hub closed the body and left, and its single command-result POST evidently failed on the exhausted heap too. With no result, the five-minute sweep wrote its generic message and the real reason was lost. This does not make audio work on that board; it makes the failure visible so the memory problem can be fixed from real numbers. Server: - stream_recording catches ClientDisconnect, still stores the bytes that arrived, and logs one warning. Behind Traefik even a complete body arrives this way when the hub does not wait for the response. The row's error is left for the hub's own result to fill. - A late failed command result replaces the stale-sweep message (only a sweep message, never a /finalize verdict). Firmware (0.30.8): - postCommandResult returns whether it got a 2xx. - The audio relay's result is retried once after 1.5 s; if that fails it is held in RTC memory and delivered at the top of the next cycle (at most three tries). - A session that fails to start carries free heap, largest block and minimum-ever heap in its message, so the dashboard shows the numbers without a serial cable. Tests: regression checks for the disconnect (fail without the fix) and the late-result replacement. esp32dev and xiao_esp32c6 build; host tests and the server suite pass. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01AQa7TMjkrHCnKhfkWnN4GK --- docs/audio-recording.md | 1 + firmware/include/globals.h | 10 ++ firmware/include/hivehub_network.h | 3 +- firmware/src/globals.cpp | 11 ++- firmware/src/hivehub_network.cpp | 96 ++++++++++++++++++-- server/recordings.py | 92 ++++++++++++++----- test-data/test_recordings.py | 141 +++++++++++++++++++++++++++++ 7 files changed, 321 insertions(+), 33 deletions(-) diff --git a/docs/audio-recording.md b/docs/audio-recording.md index 28c02f0..f294bd3 100644 --- a/docs/audio-recording.md +++ b/docs/audio-recording.md @@ -482,4 +482,5 @@ one-second ring; it is a cheap `logDiag()` now. | "hub reset during relay (panic/exception)" | A crash mid-session. Fixed in hub firmware 0.30.1 — see [When the hub resets mid-recording](#when-the-hub-resets-mid-recording) | | "BLE stack would not start" | The hub could not bring the radio up at all. Almost always a 30-pin ESP32 with an unusually full heap; the serial log prints the free heap and the largest free block next to it. Hub firmware 0.30.7 makes this much less likely — see [Why this is a 30-pin ESP32 problem](#why-this-is-a-30-pin-esp32-problem) | | "TLS connect to the backend failed" | The hub could not open the upload socket. Since 0.30.7 the serial log prints free heap and largest block beside it; a sub-second `relay_duration` in `device_commands` means an allocation failure rather than a network one. This was the 0.30.6 symptom of asking for the radio before the socket | +| "the hub started uploading but no audio arrived" | The hub opened the upload and closed it before sending audio — almost always because the BLE session failed to start straight after the socket opened (Traefik logs this as a `499` a few hundred ms in) — and then its command result did not arrive either. From hub firmware 0.30.8 on the hub retries that result and, failing that, holds it in RTC memory and delivers it on its next cycle; the server then replaces this message with the hub's real reason, which carries `[heap free …, largest …, min …]` for any start failure. Before 0.30.8 the backend also logged a `ClientDisconnect` traceback here; that is now a one-line warning | | "audio buffer trimmed to N B" (serial log, not an error) | The hub could not get the full 32 KiB staging buffer and took a smaller one. The recording still happens; a slow upload will show up as gaps sooner | diff --git a/firmware/include/globals.h b/firmware/include/globals.h index b2b1aa8..24eafe1 100644 --- a/firmware/include/globals.h +++ b/firmware/include/globals.h @@ -205,6 +205,16 @@ extern uint32_t rtcRelayMagic; // rather than "firmware transfer" for a recording. See RelayKind in // hivehub_network.cpp. extern uint32_t rtcRelayKind; +// A relay's command result that failed to POST — typically because the relay +// left the heap too low for another TLS session — held for the next cycle so +// the dashboard learns the real reason instead of a backend timeout's guess. +// See postRelayResult() in hivehub_network.cpp. +#define RTC_PENDING_RESULT_MSG_LEN 192 +extern uint32_t rtcPendingResultMagic; +extern uint32_t rtcPendingResultCommandId; +extern uint32_t rtcPendingResultSuccess; +extern uint32_t rtcPendingResultTries; +extern char rtcPendingResultMsg[RTC_PENDING_RESULT_MSG_LEN]; // Set when a `start_provisioning` command has to reboot the hub to open the // portal, so the BLE discovery scan gets a NimBLE port lifetime it is allowed // to scan in. Consumed once, at the top of setup(). RTC_NOINIT_ATTR, for the diff --git a/firmware/include/hivehub_network.h b/firmware/include/hivehub_network.h index 47d6f8a..57ce154 100644 --- a/firmware/include/hivehub_network.h +++ b/firmware/include/hivehub_network.h @@ -93,5 +93,6 @@ bool updateHiveInside(const String& mac, const String& firmwareUrl, bool updateBeeCounter(const String& mac, const String& firmwareUrl, uint32_t expectedCrc32 = 0, String* outMsg = nullptr); void checkForOtaUpdate(); -void postCommandResult(int commandId, bool success, const String& message); +// Returns false when the POST did not get a 2xx; most callers can ignore it. +bool postCommandResult(int commandId, bool success, const String& message); void checkCommands(); diff --git a/firmware/src/globals.cpp b/firmware/src/globals.cpp index c71ca6e..1568410 100644 --- a/firmware/src/globals.cpp +++ b/firmware/src/globals.cpp @@ -3,7 +3,7 @@ #include -const char* const FIRMWARE_VERSION = "0.30.7"; +const char* const FIRMWARE_VERSION = "0.30.8"; #if ENABLE_HX711 HX711 scale1; @@ -134,6 +134,15 @@ RTC_NOINIT_ATTR uint32_t rtcRelayMagic; // power-on leaves here is never believed. RTC_NOINIT_ATTR uint32_t rtcRelayKind; +// A relay result that could not be POSTed, carried to the next cycle instead of +// being lost. See postRelayResult() in hivehub_network.cpp. Same rules as the +// relay marker: magic written last, checked first. +RTC_NOINIT_ATTR uint32_t rtcPendingResultMagic; +RTC_NOINIT_ATTR uint32_t rtcPendingResultCommandId; +RTC_NOINIT_ATTR uint32_t rtcPendingResultSuccess; +RTC_NOINIT_ATTR uint32_t rtcPendingResultTries; +RTC_NOINIT_ATTR char rtcPendingResultMsg[RTC_PENDING_RESULT_MSG_LEN]; + // A `start_provisioning` request that had to reboot to get a NimBLE port // lifetime its BLE scan is allowed to run in. See portal.cpp. RTC_NOINIT_ATTR uint32_t rtcPortalBootMagic; diff --git a/firmware/src/hivehub_network.cpp b/firmware/src/hivehub_network.cpp index f80e967..7bb23ec 100644 --- a/firmware/src/hivehub_network.cpp +++ b/firmware/src/hivehub_network.cpp @@ -1294,8 +1294,14 @@ static bool relayAudioSession(const String& mac, long recordingId, bool bleOk = gattaudio::begin(mac, durationDs, gainDb); if (!bleOk) { - setMsg(gattaudio::lastError().length() ? gattaudio::lastError() - : String("audio session failed to start")); + // Carry the heap numbers into the command result, not just onto serial. + // Every start failure on the 30-pin ESP32 so far has been a memory + // question, and the dashboard is the only place a field tester sees. + const String why = gattaudio::lastError().length() + ? gattaudio::lastError() + : String("audio session failed to start"); + setMsg(why + " [heap free " + ESP.getFreeHeap() + ", largest " + + ESP.getMaxAllocHeap() + ", min " + ESP.getMinFreeHeap() + "]"); // Close the body cleanly anyway: the backend then sees a zero-byte // recording it can mark failed, instead of a half-open socket it has to // time out. @@ -1607,7 +1613,7 @@ static void reportInterruptedRelay() { postCommandResult(commandId, false, msg); } -void postCommandResult(int commandId, bool success, const String& message) { +bool postCommandResult(int commandId, bool success, const String& message) { JsonDocument result; result["success"] = success; result["message"] = message; @@ -1615,7 +1621,77 @@ void postCommandResult(int commandId, bool success, const String& message) { String payload; serializeJson(result, payload); - httpPostJson(apiUrl(String("/api/v1/devices/") + deviceId + "/commands/" + commandId + "/result"), payload); + return httpPostJson(apiUrl(String("/api/v1/devices/") + deviceId + "/commands/" + + commandId + "/result"), + payload); +} + +// ---- Relay results that must not be lost ---------------------------------- +// +// A relay's command result is the only report the backend reliably acts on +// (see finalize_from_command_result() on the server), and it is posted at the +// worst moment of the cycle: straight after a BLE session, with the heap at its +// most fragmented. PR 198's field test on a 30-pin ESP32 showed the cost — the +// session failed, its one result POST evidently failed too, and the dashboard +// got the backend's five-minute guess ("the hub started uploading but no audio +// arrived") instead of the hub's actual reason. +// +// So retry once after a pause (the BLE host has fully released by then, and the +// TLS session from the upload has been torn down), and if that fails as well, +// keep the result in RTC memory and deliver it at the top of the next cycle, +// before anything new is claimed. Bounded, so a backend that keeps rejecting it +// cannot pin the slot forever. +static const uint32_t PENDING_RESULT_MAGIC = 0x48505253UL; // "HPRS" +static const uint32_t PENDING_RESULT_MAX_TRIES = 3; +static const uint32_t RELAY_RESULT_RETRY_DELAY_MS = 1500; + +static void clearPendingResult() { + rtcPendingResultMagic = 0; + rtcPendingResultCommandId = 0; + rtcPendingResultTries = 0; + rtcPendingResultMsg[0] = '\0'; +} + +static void stashPendingResult(int commandId, bool success, const String& message) { + rtcPendingResultCommandId = (uint32_t)commandId; + rtcPendingResultSuccess = success ? 1 : 0; + rtcPendingResultTries = 0; + strlcpy(rtcPendingResultMsg, message.c_str(), sizeof(rtcPendingResultMsg)); + rtcPendingResultMagic = PENDING_RESULT_MAGIC; // last: makes the record valid +} + +static void postRelayResult(int commandId, bool success, const String& message) { + if (postCommandResult(commandId, success, message)) return; + + Serial.printf("[CMD] result for command %d did not post (free heap %u, largest " + "block %u); retrying in %u ms\n", + commandId, (unsigned)ESP.getFreeHeap(), + (unsigned)ESP.getMaxAllocHeap(), + (unsigned)RELAY_RESULT_RETRY_DELAY_MS); + delay(RELAY_RESULT_RETRY_DELAY_MS); + if (postCommandResult(commandId, success, message)) return; + + Serial.printf("[CMD] result for command %d kept for the next cycle\n", commandId); + stashPendingResult(commandId, success, message); +} + +// Deliver a result an earlier cycle could not. Called once per cycle, before +// the next command is fetched. +static void reportPendingResult() { + if (rtcPendingResultMagic != PENDING_RESULT_MAGIC || rtcPendingResultCommandId == 0) + return; + rtcPendingResultMsg[sizeof(rtcPendingResultMsg) - 1] = '\0'; + const int commandId = (int)rtcPendingResultCommandId; + Serial.printf("[CMD] Delivering held result for command %d\n", commandId); + if (postCommandResult(commandId, rtcPendingResultSuccess != 0, + String(rtcPendingResultMsg))) { + clearPendingResult(); + return; + } + if (++rtcPendingResultTries >= PENDING_RESULT_MAX_TRIES) { + Serial.printf("[CMD] giving up on the held result for command %d\n", commandId); + clearPendingResult(); + } } // Claim and run at most one queued command. Returns true when one ran, and @@ -1741,10 +1817,10 @@ static bool runOneCommand(bool* wasAudio) { bool ok = recordHiveInsideAudio(mac, recordingId, durationDs, gainDb, &resultMsg); clearRelayInFlight(); if (wasAudio) *wasAudio = ok; - postCommandResult(commandId, ok, - resultMsg.length() ? resultMsg - : (ok ? "audio session completed" - : "audio session failed")); + postRelayResult(commandId, ok, + resultMsg.length() ? resultMsg + : (ok ? "audio session completed" + : "audio session failed")); } } #else @@ -1838,8 +1914,10 @@ static bool runOneCommand(bool* wasAudio) { void checkCommands() { if (!connectNetwork()) return; - // Close out a relay that a reset interrupted before claiming anything new. + // Close out a relay that a reset interrupted, and deliver a result an + // earlier cycle could not post, before claiming anything new. reportInterruptedRelay(); + reportPendingResult(); bool wasAudio = false; if (!runOneCommand(&wasAudio)) return; diff --git a/server/recordings.py b/server/recordings.py index 3b783d6..3af18d9 100644 --- a/server/recordings.py +++ b/server/recordings.py @@ -32,6 +32,7 @@ from fastapi import APIRouter, Depends, HTTPException, Query, Request from fastapi.responses import Response, StreamingResponse +from starlette.requests import ClientDisconnect from auth import require_api_key, require_device_key from commands import create_command @@ -75,6 +76,14 @@ RECORDING_REQUESTED_TIMEOUT_MIN = 45 RECORDING_STREAMING_TIMEOUT_MIN = 5 +# What expire_stale_recordings() writes when the hub never reported. These are +# guesses, and finalize_from_command_result() lets the hub's own verdict replace +# them when it turns up late — a hub that could not post its result straight +# after a session holds it and delivers it on its next cycle. +SWEEP_NO_AUDIO_MSG = "the hub started uploading but no audio arrived" +SWEEP_NEVER_PICKED_UP_MSG = ("the hub never picked this request up \u2014 offline, " + "or the command was dropped") + def _path_for(device_id: str, recording_id: int) -> Path: """Where a recording's audio lives. @@ -215,26 +224,23 @@ def expire_stale_recordings() -> None: UPDATE hive_recordings SET status = 'failed', completed_at = now(), - error = COALESCE(error, - 'the hub started uploading but no audio arrived') + error = COALESCE(error, %s) WHERE status = 'streaming' AND bytes = 0 AND requested_at < now() - (%s || ' minutes')::interval; """, - (RECORDING_STREAMING_TIMEOUT_MIN,), + (SWEEP_NO_AUDIO_MSG, RECORDING_STREAMING_TIMEOUT_MIN), ) cur.execute( """ UPDATE hive_recordings SET status = 'failed', completed_at = now(), - error = COALESCE(error, - 'the hub never picked this request up \u2014 offline, or the ' - 'command was dropped') + error = COALESCE(error, %s) WHERE status = 'requested' AND requested_at < now() - (%s || ' minutes')::interval; """, - (RECORDING_REQUESTED_TIMEOUT_MIN,), + (SWEEP_NEVER_PICKED_UP_MSG, RECORDING_REQUESTED_TIMEOUT_MIN), ) conn.commit() @@ -283,6 +289,24 @@ def finalize_from_command_result(device_id: str, command_id: int, if cur.rowcount: logger.info("recording for command %s closed by command result " "(success=%s)", command_id, success) + elif not success: + # Late: the sweep already failed the row with a guess. The hub's + # reason is better than the guess, so it replaces it — but only + # a sweep message, never a verdict /finalize wrote. + cur.execute( + """ + UPDATE hive_recordings + SET error = %s + WHERE command_id = %s AND device_id = %s + AND status = 'failed' + AND error IN (%s, %s); + """, + (failed_msg, command_id, device_id, + SWEEP_NO_AUDIO_MSG, SWEEP_NEVER_PICKED_UP_MSG), + ) + if cur.rowcount: + logger.info("recording for command %s: late command result " + "replaced the stale-sweep message", command_id) conn.commit() @@ -465,22 +489,41 @@ async def stream_recording(device_id: str, recording_id: int, request: Request): written = 0 truncated = False + disconnected = False with open(path, "wb") as fh: - async for chunk in request.stream(): - if not chunk: - continue - if written + len(chunk) > MAX_RECORDING_BYTES: - # Keep what fits and stop reading. The node bounds itself at 60 s, - # so this only fires for a hub that has gone wrong — and half a - # recording plus an explicit note beats an unbounded write. - chunk = chunk[: max(0, MAX_RECORDING_BYTES - written)] - truncated = True - if chunk: - fh.write(chunk) - fh.flush() - written += len(chunk) - if truncated: - break + try: + async for chunk in request.stream(): + if not chunk: + continue + if written + len(chunk) > MAX_RECORDING_BYTES: + # Keep what fits and stop reading. The node bounds itself at + # 60 s, so this only fires for a hub that has gone wrong — + # and half a recording plus an explicit note beats an + # unbounded write. + chunk = chunk[: max(0, MAX_RECORDING_BYTES - written)] + truncated = True + if chunk: + fh.write(chunk) + fh.flush() + written += len(chunk) + if truncated: + break + except ClientDisconnect: + # The hub hung up before the body ended — or, behind a reverse + # proxy, simply did not wait for this response: Traefik cancels the + # upstream request (logging a 499) the moment its client goes, even + # after a complete body. A hub whose BLE session fails to start + # sends the terminating chunk and closes at once, so this is the + # ordinary shape of that failure, not a server fault. + # + # Letting it propagate cost twice: a traceback in the log for every + # failed session, and the byte count below never written, so audio + # that DID land before a mid-session drop was recorded as 0 bytes + # and later swept as "no audio arrived". Keep what arrived. The + # row's error is deliberately left alone: the hub's command result + # carries the real reason, and finalize_from_command_result only + # fills an error that is still empty. + disconnected = True with get_conn() as conn: with conn.cursor() as cur: @@ -495,6 +538,11 @@ async def stream_recording(device_id: str, recording_id: int, request: Request): recording_id), ) conn.commit() + if disconnected: + logger.warning("recording %s: hub disconnected after %s bytes", + recording_id, written) + # Nobody is left to read this; it is returned for symmetry and tests. + return {"status": "disconnected", "bytes": written} logger.info("recording %s: received %s bytes%s", recording_id, written, " (truncated)" if truncated else "") return {"status": "ok", "bytes": written} diff --git a/test-data/test_recordings.py b/test-data/test_recordings.py index cb76423..553fb16 100644 --- a/test-data/test_recordings.py +++ b/test-data/test_recordings.py @@ -274,6 +274,147 @@ def row(**over): not _unapplied) + +# ── The hub hanging up mid-upload ────────────────────────────────────────── +# +# A hub whose BLE session fails to start closes the upload ~200 ms in, and +# behind Traefik even a complete body arrives as a disconnect because the hub +# does not wait for the response. That used to escape stream_recording as an +# unhandled ClientDisconnect: a traceback per failed session, and the byte +# count never written, so audio that had landed was recorded as 0 bytes. +import asyncio # noqa: E402 +from contextlib import contextmanager # noqa: E402 + +from starlette.requests import ClientDisconnect # noqa: E402 + + +class _FakeCursor: + def __init__(self, log): + self.log = log + self.rowcount = 1 + + def __enter__(self): + return self + + def __exit__(self, *exc): + return False + + def execute(self, sql, params=None): + self.log.append((" ".join(sql.split()), params)) + + def fetchone(self): + return ("requested",) + + +class _FakeConn: + def __init__(self, log): + self.log = log + + def cursor(self): + return _FakeCursor(self.log) + + def commit(self): + pass + + +class _DisconnectingRequest: + def __init__(self, chunks): + self.chunks = chunks + + async def stream(self): + for c in self.chunks: + yield c + raise ClientDisconnect() + + +def _run_stream(chunks, recording_id): + log = [] + + @contextmanager + def fake_get_conn(): + yield _FakeConn(log) + + real = recordings.get_conn + recordings.get_conn = fake_get_conn + try: + out = asyncio.run(recordings.stream_recording( + "hive-test", recording_id, _DisconnectingRequest(chunks))) + finally: + recordings.get_conn = real + return out, log + + +for _label, _chunks in (("before any audio", []), + ("mid-session", [b"\x01\x02" * 100, b"\x03" * 56])): + _expect = sum(len(c) for c in _chunks) + try: + _out, _log = _run_stream(_chunks, 9001) + _raised = None + except Exception as exc: # noqa: BLE001 - the regression IS an escape + _out, _log, _raised = None, [], exc + check(f"a hub disconnecting {_label} does not escape stream_recording " + f"({type(_raised).__name__ if _raised else 'handled'})", + _raised is None) + _bytes_updates = [p for sql, p in _log if sql.startswith( + "UPDATE hive_recordings SET bytes")] + check(f"a hub disconnecting {_label} still records the {_expect} bytes " + f"that arrived", + bool(_bytes_updates) and _bytes_updates[-1][0] == _expect + and _out == {"status": "disconnected", "bytes": _expect}) + check(f"a hub disconnecting {_label} leaves the error for the hub's own " + f"command result to fill", + not any(sql.startswith("UPDATE hive_recordings SET error") + for sql, _ in _log)) + try: + _path_for("hive-test", 9001).unlink() + except OSError: + pass + + +# ── A command result that arrives after the stale sweep ──────────────────── +# +# A hub that could not post its result right after a failed session holds it +# for the next cycle, by which time the sweep has failed the row with a guess. +# The hub's own reason must replace the guess — and only the guess. +class _LateCursor(_FakeCursor): + def execute(self, sql, params=None): + super().execute(sql, params) + # The in-flight UPDATE finds nothing: the sweep already closed the row. + self.rowcount = 0 if "status IN ('requested', 'streaming')" in sql else 1 + + +class _LateConn(_FakeConn): + def cursor(self): + return _LateCursor(self.log) + + +def _run_late(success, message): + log = [] + + @contextmanager + def fake_get_conn(): + yield _LateConn(log) + + real = recordings.get_conn + recordings.get_conn = fake_get_conn + try: + recordings.finalize_from_command_result("hive-test", 77, success, message) + finally: + recordings.get_conn = real + return log + + +_reason = "BLE stack would not start [heap free 16284, largest 13812, min 1456]" +_late = [(sql, p) for sql, p in _run_late(False, _reason) + if sql.startswith("UPDATE hive_recordings SET error")] +check("a late failed command result replaces the stale-sweep message", + len(_late) == 1 and _late[0][1][0] == _reason + and recordings.SWEEP_NO_AUDIO_MSG in _late[0][1] + and "status = 'failed'" in _late[0][0]) +check("a late successful command result does not rewrite a failed row", + not any(sql.startswith("UPDATE hive_recordings SET error") + for sql, _ in _run_late(True, "recorded 1 B"))) + if _failures: raise SystemExit(f"{_failures} check(s) failed") print("\nAll recording checks passed.") From 088f7bbb08a52f35a64b5238e00097db8425dbd9 Mon Sep 17 00:00:00 2001 From: Claude Date: Fri, 2 Oct 2026 07:47:39 +0000 Subject: [PATCH 4/4] Free the measurement document before commands run (0.30.9) Field test of 0.30.8 on a 30-pin ESP32: the BLE stack and the TLS socket both came up this time, and the session failed one step later: out of memory for the audio buffer (needed at least 8 kB) [heap free 9608, largest 6900, min 4324] runUploadCycle() kept the measurement JsonDocument and its serialised String alive until the function returned, so both were resident through checkCommands() and therefore through the audio relay. Scope them to the measurement/upload block so they are freed before any command runs. This returns their memory and closes the holes they leave in the heap, at the point where the relay is short of a few kilobytes. Not built here: the PlatformIO registry is blocked from this environment. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01LtgySqvo41PbZ4N5GkVPgf --- firmware/src/globals.cpp | 2 +- firmware/src/main.cpp | 99 ++++++++++++++++++++++------------------ 2 files changed, 55 insertions(+), 46 deletions(-) diff --git a/firmware/src/globals.cpp b/firmware/src/globals.cpp index 1568410..e51b304 100644 --- a/firmware/src/globals.cpp +++ b/firmware/src/globals.cpp @@ -3,7 +3,7 @@ #include -const char* const FIRMWARE_VERSION = "0.30.8"; +const char* const FIRMWARE_VERSION = "0.30.9"; #if ENABLE_HX711 HX711 scale1; diff --git a/firmware/src/main.cpp b/firmware/src/main.cpp index 5804517..d83abb1 100644 --- a/firmware/src/main.cpp +++ b/firmware/src/main.cpp @@ -42,52 +42,61 @@ void runUploadCycle() { heapdiag::probe("after-network"); pollSetupButton(); - JsonDocument doc; - // Assembly runs the BLE scan, which inits and deinits the NimBLE stack. That - // teardown is deliberately incomplete (deinit(false) — deinit(true) panics on - // the C6 once a scan has run this boot, see ble_sensor.cpp), so it is the - // stage most worth watching. - buildMeasurementDoc(doc); - heapdiag::probe("after-measure"); - pollSetupButton(); - - // SD.begin() is the reproducible boundary after which ESP32-C6 I2C-NG may - // reject later transfers. Capture the timestamp before bringing SPI/SD up. - initSdCard(); - heapdiag::probe("after-sd"); - - // Stamp sd_ok only now. sdOk is a plain global that starts false on every boot - // and prepareSdForSleep() clears it before each deep sleep, so it is always - // false while the document above is assembled — stamping it there reported an - // SD card fault on every cycle even though the card mounted and the backup - // line was written moments later. - doc["sd_ok"] = sdOk; - - String json = finalizeMeasurementJson(doc); - - if (sdOk) appendBackupLine(json); - - // Track the claim in both directions: latch it once the server confirms the - // device is claimed, and un-latch it when the server explicitly says it is - // not. The second half is what makes "remove the device in the app" a - // recoverable action — the device notices the pairing is gone and starts - // offering its claim code again, so it can simply be re-claimed. A server - // that reports nothing (older build, or a failed upload) changes neither. - ClaimStatus claimStatus = ClaimStatus::Unknown; - bool currentUploaded = uploadLine(json, &claimStatus); - if (claimStatus == ClaimStatus::Claimed) markClaimRegistered(); - else if (claimStatus == ClaimStatus::Unclaimed) clearClaimRegistered(); - - if (!currentUploaded) { - if (sdOk) { - Serial.println("[CYCLE] Live upload failed; adding measurement to retry cache"); - appendCacheLine(json); - } else { - Serial.println("[CYCLE] Live upload failed and no SD card is available; measurement not cached"); + // The measurement document and its serialised form are scoped to this block + // so they are freed BEFORE checkCommands(). They used to live to the end of + // the function, which kept them resident through the audio relay — the + // tightest moment for heap in the whole firmware on the 30-pin ESP32, where + // the staging ring was refused with under 10 kB left and every kilobyte (and + // every hole these leave in the heap) counts. + { + JsonDocument doc; + // Assembly runs the BLE scan, which inits and deinits the NimBLE stack. That + // teardown is deliberately incomplete (deinit(false) — deinit(true) panics on + // the C6 once a scan has run this boot, see ble_sensor.cpp), so it is the + // stage most worth watching. + buildMeasurementDoc(doc); + heapdiag::probe("after-measure"); + pollSetupButton(); + + // SD.begin() is the reproducible boundary after which ESP32-C6 I2C-NG may + // reject later transfers. Capture the timestamp before bringing SPI/SD up. + initSdCard(); + heapdiag::probe("after-sd"); + + // Stamp sd_ok only now. sdOk is a plain global that starts false on every boot + // and prepareSdForSleep() clears it before each deep sleep, so it is always + // false while the document above is assembled — stamping it there reported an + // SD card fault on every cycle even though the card mounted and the backup + // line was written moments later. + doc["sd_ok"] = sdOk; + + String json = finalizeMeasurementJson(doc); + + if (sdOk) appendBackupLine(json); + + // Track the claim in both directions: latch it once the server confirms the + // device is claimed, and un-latch it when the server explicitly says it is + // not. The second half is what makes "remove the device in the app" a + // recoverable action — the device notices the pairing is gone and starts + // offering its claim code again, so it can simply be re-claimed. A server + // that reports nothing (older build, or a failed upload) changes neither. + ClaimStatus claimStatus = ClaimStatus::Unknown; + bool currentUploaded = uploadLine(json, &claimStatus); + if (claimStatus == ClaimStatus::Claimed) markClaimRegistered(); + else if (claimStatus == ClaimStatus::Unclaimed) clearClaimRegistered(); + + if (!currentUploaded) { + if (sdOk) { + Serial.println("[CYCLE] Live upload failed; adding measurement to retry cache"); + appendCacheLine(json); + } else { + Serial.println("[CYCLE] Live upload failed and no SD card is available; measurement not cached"); + } + } else if (sdOk) { + uploadCachedLines(); } - } else if (sdOk) { - uploadCachedLines(); - } + + } // doc and json are released here, before any command runs. if (scaleCalibrationReportPending()) reportScaleCalibration();