Let the 30-pin ESP32 start the radio for an audio recording

docs/audio-recording.md

@@ -311,6 +311,113 @@ 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 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 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. 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 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
 
 A hub on 0.30.1 recorded 27.3 s of a 30 s request with `Dropped: 0 B` and
@@ -337,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
@@ -369,5 +480,7 @@ 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.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 |

firmware/include/gatt_audio.h

@@ -34,6 +34,10 @@
 //   → 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().
+//
+// 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 <Arduino.h>
@@ -76,6 +80,10 @@ const char* errorText(uint8_t error);
 // 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

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

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();

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

firmware/src/ble_stack.cpp

@@ -5,13 +5,48 @@
     GATT_OTA_ENABLED
 
 #include <NimBLEDevice.h>
+#include <esp_bt.h>
 
 namespace blestack {
 namespace {
 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() {
@@ -22,13 +57,22 @@ bool acquire() {
   // 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.
+  // 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()
   // 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) {