Bluetooth fails at malloc and crashes the badge

>>> import bluetooth
>>> ble = bluetooth.BLE()
>>> ble.active(True)
E (1077027) BLE_INIT: Malloc failed
Guru Meditation Error: Core  1 panic'ed (StoreProhibited). Exception was unhandled.

Core  1 register dump:
PC      : 0x421226d5  PS      : 0x00060530  A0      : 0x82044aa9  A1      : 0x3fcdd140
A2      : 0x00000001  A3      : 0x00000c03  A4      : 0x00000000  A5      : 0xb33fffff
A6      : 0x3fca1b48  A7      : 0xb33fffff  A8      : 0x0000000c  A9      : 0x3fcdd120
A10     : 0x00000000  A11     : 0x00000000  A12     : 0x3fca4c24  A13     : 0x00000001
A14     : 0x00000001  A15     : 0x00000000  SAR     : 0x00000018  EXCCAUSE: 0x0000001d
EXCVADDR: 0x00000001  LBEG    : 0x400570e8  LEND    : 0x400570f3  LCOUNT  : 0x00000000


Backtrace: 0x421226d2:0x3fcdd140 0x42044aa6:0x3fcdd160 0x42042561:0x3fcdd180 0x4203d04e:0x3fcdd1c0 0x42039b28:0x3fcdd1f0 0x42039dda:0x3fcdd210 0x42039de3:0x3fcdd230 0x42042dd2:0x3fcdd250 0x42026c9b:0x3fcdd270 

added bug label

Decoding the backtrace with idf.py monitor:

>>> ble.active(True)
E (42997) BLE_INIT: Malloc failed
assert emi.c 164, param 00000000 00001000
Guru Meditation Error: Core  0 panic'ed (Interrupt wdt timeout on CPU0). 

Core  0 register dump:
PC      : 0x40006fcb  PS      : 0x00060b34  A0      : 0x8000a3d8  A1      : 0x3fceea70  
A2      : 0x00000000  A3      : 0x00001000  A4      : 0x3ff196ce  A5      : 0x000000a4  
A6      : 0x0dd28132  A7      : 0x000fffff  A8      : 0x00000001  A9      : 0x3fcef9e4  
A10     : 0x3fcef9e4  A11     : 0x00000001  A12     : 0x00000000  A13     : 0x00001000  
A14     : 0x00000001  A15     : 0x00000000  SAR     : 0x00000005  EXCCAUSE: 0x00000005  
EXCVADDR: 0x00000000  LBEG    : 0x40006fc4  LEND    : 0x40006fcb  LCOUNT  : 0x00000000  


Backtrace: 0x40006fc8:0x3fceea70 0x4000a3d5:0x3fceea90 0x42050c0b:0x3fceeab0 0x4205100b:0x3fceeaf0 0x4205544f:0x3fceeb30 0x420559c9:0x3fceeb60 0x4204ec74:0x3fceeb80 0x4037ed30:0x3fceeba0
0x42050c0b: r_lld_core_init at ??:?

0x4205100b: r_lld_init at ??:?

0x4205544f: r_rwble_init at ??:?

0x420559c9: r_rwip_reset at ??:?

0x4204ec74: btdm_controller_on_reset at ??:?

0x4037ed30: btdm_controller_task at ??:?



Core  1 register dump:
PC      : 0x403874ba  PS      : 0x00060c34  A0      : 0x82003b9c  A1      : 0x3fcb3180  
0x403874ba: esp_cpu_wait_for_intr at /nix/store/p9f8w7mc4bdga44xp6kh9rk57skkbx83-esp-idf-v5.1/components/esp_hw_support/cpu.c:121

A2      : 0x00000000  A3      : 0x3fcaa570  A4      : 0x8038d154  A5      : 0x3fce2c80  
A6      : 0x00060023  A7      : 0x00000003  A8      : 0x00000000  A9      : 0x3fcb2bbc  
A10     : 0x80000001  A11     : 0x3fcaa570  A12     : 0x8038d154  A13     : 0x3fce2c80  
A14     : 0x00060023  A15     : 0x00000003  SAR     : 0x00000000  EXCCAUSE: 0x00000005  
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000  


Backtrace: 0x403874b7:0x3fcb3180 0x42003b99:0x3fcb31a0 0x4038b31d:0x3fcb31c0
0x403874b7: xt_utils_wait_for_intr at /nix/store/p9f8w7mc4bdga44xp6kh9rk57skkbx83-esp-idf-v5.1/components/xtensa/include/xt_utils.h:81
 (inlined by) esp_cpu_wait_for_intr at /nix/store/p9f8w7mc4bdga44xp6kh9rk57skkbx83-esp-idf-v5.1/components/esp_hw_support/cpu.c:111

0x42003b99: esp_vApplicationIdleHook at /nix/store/p9f8w7mc4bdga44xp6kh9rk57skkbx83-esp-idf-v5.1/components/esp_system/freertos_hooks.c:59

0x4038b31d: prvIdleTask at /nix/store/p9f8w7mc4bdga44xp6kh9rk57skkbx83-esp-idf-v5.1/components/freertos/FreeRTOS-Kernel/tasks.c:4327





ELF file SHA256: b258e19ca1ed0679

That stacktrace is a red herring. Here's something more useful, a dump of all malloc() calls from the BLE stack:

>>> import bluetooth
>>> ble = bluetooth.BLE()
>>> ble.active(True)
I (17251) BLE_INIT: malloc(208)
I (17251) BLE_INIT: BT controller compile version [85b425c]
I (17251) phy_init: phy_version 601,fe52df4,May 10 2023,17:26:54
I (17291) BLE_INIT: malloc(280)
I (17291) BLE_INIT: malloc(976)
I (17291) BLE_INIT: malloc(2344)
I (17291) BLE_INIT: malloc(284)
I (17291) BLE_INIT: malloc(220)
I (17291) BLE_INIT: malloc(408)
I (17291) BLE_INIT: malloc(608)
I (17301) BLE_INIT: malloc(444)
I (17301) BLE_INIT: malloc(260)
I (17301) BLE_INIT: malloc(2088)
I (17311) BLE_INIT: malloc(9356)
I (17311) BLE_INIT: malloc(1868)
I (17311) BLE_INIT: malloc(12)
I (17321) BLE_INIT: Bluetooth MAC: 34:85:18:90:88:8e

I (17331) BLE_INIT: malloc(328)
I (17331) BLE_INIT: malloc(1080)
I (17341) BLE_INIT: malloc(616)
I (17341) BLE_INIT: malloc(200)
I (17341) BLE_INIT: malloc(1260)
E (17351) BLE_INIT: Malloc(1260) failed

components/bt/controller/esp32c3/bt.c is where this malloc call is wrapped:

static void *malloc_internal_wrapper(size_t size)
{
    void *p = heap_caps_malloc(size, MALLOC_CAP_DEFAULT|MALLOC_CAP_INTERNAL|MALLOC_CAP_DMA);
    if(p == NULL) {
        ESP_LOGE(BT_LOG_TAG, "Malloc failed");
    }
    return p;
}

It's worth noting the aggressive flags to heap_caps_malloc: MALLOC_CAP_INTERNAL|MALLOC_CAP_DMA. Perhaps it's just memory fragmentation/OOM?

Here's DMA memory stats from right before when we attempt to start BLE:

6.751 st3m.event (INFO): Heap: DMA: 80943B free, 243460B allocated, 57344B largest free block

I've added a heap_caps_print_heap_info(MALLOC_CAP_DEFAULT|MALLOC_CAP_INTERNAL|MALLOC_CAP_DMA); before every malloc and here's what I get for the failing call:

I (32411) BLE_INIT: malloc(750)
Heap summary for capabilities 0x00001808:
  At 0x3fcad790 len 245632 free 164 allocated 243628 min_free 68
    largest_free_block 96 alloc_blocks 225 free_blocks 3 total_blocks 228
  At 0x3fce9710 len 22308 free 100 allocated 21432 min_free 100
    largest_free_block 92 alloc_blocks 10 free_blocks 1 total_blocks 11
  Totals:
    free 264 allocated 265060 min_free 168 largest_free_block 96
E (32451) BLE_INIT: Malloc(750) failed

So it does indeed just seem like an OOM for DMA & Internal memory?

closed with commit f6ffcc2c

mentioned in commit f6ffcc2c

mentioned in issue #131 (closed)