search

espressif / esp-idf

Espressif IoT Development Framework. Official development framework for Espressif SoCs.
Apache License 2.0
13.46k stars 7.25k forks source link

ASSERT_PARAM(-218959118 0), in arch_main.c at line 365 while using BLE (IDFGH-12768) #13747

Closed Koxx3 closed 4 months ago

Koxx3 commented 5 months ago

Answers checklist.

General issue report

Environment

Development Kit: none (this is a custom board, but could reproduce the issue with a ESP32-WROOM-based board too)
Module or chip used: ESP32-D0WD
IDF version: v4.4.4 from Tasmota 2023.06.02
Build System: Platformio/Make
Compiler version: xtensa-esp32-elf-gcc (crosstool-NG esp-2021r2-patch5) 8.4.0
Operating System: Windows
Power Supply: external 5V or USB

Problem Description

My software uses BLE, Wifi (disabled during this test, but enable in sdkconfig), TWAI, UART, SPI, U2C and UART...

It scans for BLE beacons every second while it is connected in BLE to a 1 smartphone, and it reports the detected devices belonging to a custom filtered list with custom BLE characteristics.

Advertising is enabled while the smartphone is connected. It uses NimBLE.

I crash after 5 to 8h if a smartphone remains connected. I don't see any crash if the smartphone isn't connected.

I've tried many many configurations following similar previous BLE stack errors reported on this github :

Without success ...

Monitoring memory every 1h, I don't see any leak over time.

My sdkconfig : https://pastebin.com/2TzT7sTC

I can't move to higher IDF without a large impact on my software... which is not possible considering we are launching the production soon. I tried IDF 4.4.5, but it crashes too (I didn't note the exception/backtrace)

Any help please ?

Expected Behaviour

The BLE stack should not panic when scanning.

Actual Behaviour

The application will panic after seemingly non-deterministic intervals, generally during BLE scans.

Steps to reproduce

N/A considering the complexity of the application.

Debug Logs

ASSERT_PARAM(-218959118 0), in arch_main.c at line 365
Guru Meditation Error: Core  0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x40090b88: 000000f0 00004136 f01d0000
Core  0 register dump:
PC      : 0x40090b8f  PS      : 0x00060734  A0      : 0x80086505  A1      : 0x3ffb6020  
A2      : 0x00000000  A3      : 0xf2f2f2f2  A4      : 0x00000000  A5      : 0x3f43627e  
A6      : 0x0000016d  A7      : 0xfffffffc  A8      : 0x8000814b  A9      : 0x3ffb5f90  
A10     : 0x00000000  A11     : 0x3ffb5fb3  A12     : 0x3ffb5f5f  A13     : 0x00000035  
A14     : 0x00000000  A15     : 0x3ffb5f64  SAR     : 0x00000004  EXCCAUSE: 0x00000000  
EXCVADDR: 0x00000000  LBEG    : 0x4008640d  LEND    : 0x40086415  LCOUNT  : 0x00000000  

Backtrace: 0x40090b8c:0x3ffb6020 0x40086502:0x3ffb6040 0x401a1691:0x3ffb6060 0x40019fb5:0x3ffb6080 0x4001a1f2:0x3ffb60b0 0x401afe5a:0x3ffb60d0 0x401b15e1:0x3ffb6140 0x401ae5ff:0x3ffb6190 0x401ab7d2:0x3ffb61e0 0x40019d11:0x3ffb6220 0x40055b4d:0x3ffb6240 0x401a1a83:0x3ffb6260 0x401a20e5:0x3ffb6280 0x40096cad:0x3ffb62b0

Decoded stack trace :

r_assert at C:\Users\koxx3\.platformio\packages\framework-espidf\components\bt\controller\esp32/bt.c:1862
r_assert_param at ??:?
r_platform_reset at ??:?
?? ??:0
?? ??:0
r_llm_le_adv_report_ind at ??:?
r_llm_pdu_defer at ??:?
r_lld_pdu_check at ??:?
r_lld_evt_deffered_elt_handler at ??:?
?? ??:0
?? ??:0
r_rw_schedule at ??:?
btdm_controller_task at ??:?
vPortTaskWrapper at C:\Users\koxx3\.platformio\packages\framework-espidf\components\freertos\port\xtensa/port.c:142

Memory left after boot :

MEM left = 75468    
idle = 5064 
tft = 2188  
wifi = 4492 
btn = 2440  
canrx = 1572    
cantx = 1760    
sound = 188 
serial = 4488   
btCntr = 1580       
btHost = 4932   
CAN_WD_BI = 1536    
CAN_LORX = 3524 
Tmr = 1384  
esp_timer = 3140    
loopTask = 4200 
ipc0 = 860  
ipc1 = 992  
sys_evt = 4200  
arduino_events = 4200

CPU usage : 

loopTask         94881202                9%
taskButtons      12519417                1%
taskWifi         7381082         <1%
taskSerial       7324840         <1%
taskCanRx        28419565                2%
IDLE             976617190               94%
IDLE             806747117               77%
taskSound        4433369         <1%
taskTFT          100563690               9%
CAN_WD_BI        83969           <1%
Tmr Svc          103468          <1%
taskCanTx        4063407         <1%
CAN_RX           36              <1%
ipc1             105205          <1%
CAN_LORX         4447391         <1%
nimble_host      6326191         <1%
btController     18189015                1%
ipc0             4655381         <1%
esp_timer        23              <1%

Tasks informations: 

taskCanTx | Core ID: 0 | Priority: 0 | Stack High Water Mark: 1760
taskCanRx | Core ID: 0 | Priority: 0 | Stack High Water Mark: 1652
Tmr Svc | Core ID: 0 | Priority: 1 | Stack High Water Mark: 1384
nimble_host | Core ID: 0 | Priority: 21 | Stack High Water Mark: 4932
btController | Core ID: 0 | Priority: 23 | Stack High Water Mark: 1580
esp_timer | Core ID: 0 | Priority: 22 | Stack High Water Mark: 3140
ipc0 | Core ID: 0 | Priority: 1 | Stack High Water Mark: 764
IDLE | Core ID: 0 | Priority: 0 | Stack High Water Mark: 1116

loopTask | Core ID: 1 | Priority: 1 | Stack High Water Mark: 4488
taskSound | Core ID: 1 | Priority: 0 | Stack High Water Mark: 220
taskButtons | Core ID: 1 | Priority: 0 | Stack High Water Mark: 2440
taskWifi | Core ID: 1 | Priority: 0 | Stack High Water Mark: 4492
taskSerial | Core ID: 1 | Priority: 0 | Stack High Water Mark: 4488
taskTFT | Core ID: 1 | Priority: 0 | Stack High Water Mark: 2188
CAN_WD_BI | Core ID: 1 | Priority: 10 | Stack High Water Mark: 1536
CAN_LORX | Core ID: 1 | Priority: 19 | Stack High Water Mark: 3524
CAN_RX | Core ID: 2147483647 | Priority: 15 | Stack High Water Mark: 7704
ipc1 | Core ID: 1 | Priority: 1 | Stack High Water Mark: 992
IDLE | Core ID: 1 | Priority: 0 | Stack High Water Mark: 1104
esp-zhp commented 5 months ago

Thank you for reporting the issue. It seems to be related to the BLE controller's memory. The reason for this issue is that the controller failed to allocate memory. We will attempt to replicate the problem. Could you provide a demo that reproduces this issue? This would be helpful in resolving the problem.

esp-zhp commented 5 months ago

The BLE controller allocates a block of memory during initialization, which is exclusively for the controller's use. There's no way to determine from the outside whether there has been a memory leak in the memory allocated for the controller.

Koxx3 commented 5 months ago

thanks a lot for the answer. I've spent a lot of time tracking this issue...

I switch to IDF 4.4.5, but no improvement.

I'll try to patch IDF-4.4.5 BT controller with 4.4.7 BT controller to ensure this issue isn't already fixed in the latest version.

Some questions : 1/ is it possible to observe the memory leak from outside of the BT controller ? 2/ do you think disconnecting the client can release the memory ? 3/ would is possible to allocate more memory to this module by any mean ? 4/ considering it seems to be "r_llm_le_adv_report_ind" the issue, is there any way to prevent it ? with advertising configuration, scan configuration, reducing MTU (255 bytes negociated by the IOS client in my case), sdk configuration or anything else ?

A said in the first post, it will be very complicated to release a test module if other software parts are involved, but I'll try during next weeks.

esp-zhp commented 5 months ago

1-Is it possible to observe memory leaks from outside of the BT controller? Answer: Currently, it's not possible to detect memory leaks externally. The memory allocation for the controller is predetermined, and there's no API available for external monitoring of its memory usage. However, for debugging purposes, I can provide you with a new library and internal interfaces to access the controller's memory usage.Do you require access to this interface? 2-Do you think disconnecting the client can release the memory? Answer: When there are no connections, a portion of the memory is indeed released. This is because the memory size is fixed after the controller's initialization. 3-Is it possible to allocate more memory to this module by any means? Answer: The memory size allocated during controller initialization is calculated based on factors such as duplicate list size and maximum connection count. In theory, there should not be any assertion errors as sufficient memory is already allocated. Currently, there's no external interface to adjust memory allocation size, but internal adjustments can be made. 4-Considering "r_llm_le_adv_report_ind" seems to be the issue, is there any way to prevent it? Whether through advertising configuration, scan configuration, reducing MTU (255 bytes negotiated by the iOS client in my case), SDK configuration, or anything else? Answer: The consumption of memory decreases when there are no established connections, and it also reduces when there are fewer devices in the air (due to duplicate list reasons). Other scenarios require further assessment. 5-As mentioned in the first post, it might be challenging to release a test module if other software components are involved, but I'll attempt it in the next few weeks. Answer: Currently, it seems that this issue is solely related to BLE and not connected to other components. I'm still attempting to replicate the problem here. If you can replicate the issue using BLE, it would greatly aid in resolving the problem.

Koxx3 commented 5 months ago

ok, thanks again. I'll keep you updated of the 4.4.5/4.4.7 patch tests. if it fails, yes, it would be really interesting to have few APIs to monitor the memory and debug.

esp-zhp commented 5 months ago

d166426.zip（based on e8bdaf91986a41678adc6be13888fc037b1acb68 tag: v4.4.4） Please replace the esp-idf/components/bt/controller/lib_esp32/esp32/libbtdm_app.a file. In the new lib file, I've added a new API that can retrieve the memory usage of the controller. Below is an example and the printed log. When the BT controller compile version is printed as [d166426], it indicates successful application.

I (586) BTDM_INIT: BT controller compile version [d166426]

code：

extern uint16_t ke_get_heap_free_size(void);
uint16_t free_size;
while (1) {
free_size = ke_get_heap_free_size();
printf("free size %d byte\n",free_size);
vTaskDelay(10000 / portTICK_PERIOD_MS);
}

log：

I (29) boot: ESP-IDF v4.4.4-dirty 2nd stage bootloader
I (29) boot: compile time 20:28:41
I (29) boot: chip revision: v3.1
I (33) boot_comm: chip revision: 3, min. bootloader chip revision: 0
I (40) boot.esp32: SPI Speed      : 40MHz
I (44) boot.esp32: SPI Mode       : DIO
I (49) boot.esp32: SPI Flash Size : 2MB
I (53) boot: Enabling RNG early entropy source...
I (59) boot: Partition Table:
I (62) boot: ## Label            Usage          Type ST Offset   Length
I (70) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (77) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (85) boot:  2 factory          factory app      00 00 00010000 00100000
I (92) boot: End of partition table
I (96) boot_comm: chip revision: 3, min. application chip revision: 0
I (103) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=1d050h (118864) map
I (155) esp_image: segment 1: paddr=0002d078 vaddr=3ffbdb60 size=02fa0h ( 12192) load
I (160) esp_image: segment 2: paddr=00030020 vaddr=400d0020 size=7ca74h (510580) map
I (346) esp_image: segment 3: paddr=000aca9c vaddr=3ffc0b00 size=017f8h (  6136) load
I (348) esp_image: segment 4: paddr=000ae29c vaddr=40080000 size=17658h ( 95832) load
I (402) boot: Loaded app from partition at offset 0x10000
I (402) boot: Disabling RNG early entropy source...
I (414) cpu_start: Pro cpu up.
I (414) cpu_start: Starting app cpu, entry point is 0x400811d8
0x400811d8: call_start_cpu1 at /home/zhanghaipeng/esp_v4/esp-idf/components/esp_system/port/cpu_start.c:148

I (0) cpu_start: App cpu up.
I (430) cpu_start: Pro cpu start user code
I (430) cpu_start: cpu freq: 160000000
I (431) cpu_start: Application information:
I (435) cpu_start: Project name:     gatt_client_demo
I (441) cpu_start: App version:      v4.4.4-dirty
I (446) cpu_start: Compile time:     May  7 2024 20:28:36
I (452) cpu_start: ELF file SHA256:  c3c24db549fa719a...
I (458) cpu_start: ESP-IDF:          v4.4.4-dirty
I (464) heap_init: Initializing. RAM available for dynamic allocation:
I (471) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (477) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (483) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (489) heap_init: At 3FFC8AC8 len 00017538 (93 KiB): DRAM
I (495) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (502) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (508) heap_init: At 40097658 len 000089A8 (34 KiB): IRAM
I (516) spi_flash: detected chip: generic
I (519) spi_flash: flash io: dio
W (523) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (537) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (586) BTDM_INIT: BT controller compile version [d166426]
I (586) system_api: Base MAC address is not set
I (586) system_api: read default base MAC address from EFUSE
I (596) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (1016) GATTC_DEMO: REG_EVT
free size 9556 byte
I (1016) GATTC_DEMO: scan start success
free size 9364 byte
free size 9364 byte
free size 9364 byte
free size 9540 byte
Koxx3 commented 5 months ago

ok. I am currently trying with IDF 4.4.7 version. I'll be out of the office for few days, I'll be back in few days to continue tests. If it's not too much to ask, can you generate it for IDF 4.4.5 and 4.4.7 please ?

Koxx3 commented 5 months ago

ok, let's go for a test in IDF 4.4.4 + libbtdm_app.a patch before the long weekend.

compilation test : 

15:29:32.558 > I (216) BTDM_INIT: BT controller compile version [d166426]
15:29:32.558 > ESP_ERROR_CHECK failed: esp_err_t 0x101 (ESP_ERR_NO_MEM) at 0x40092ab0
15:29:32.559 > file: ".pio/libdeps/smartdisplay_vesc_35v2_pcb210/nimble/src/NimBLEDevice.cpp" line 879
15:29:32.560 > func: static void NimBLEDevice::init(const string&)
15:29:32.560 > expression: esp_bt_controller_init(&bt_cfg)
15:29:32.561 >
15:29:32.561 > abort() was called at PC 0x40092ab3 on core 1
15:29:32.561 >
15:29:32.561 >
15:29:32.561 > Backtrace: 0x40083842:0x3ffd93c0 0x40092abd:0x3ffd93e0 0x400991da:0x3ffd9400 0x40092ab3:0x3ffd9470 0x40115622:0x3ffd9490 0x400d8517:0x3ffd94e0 0x4010726f:0x3ffd96c0 0x401471da:0x3ffd97c0 0x40096a69:0x3ffd97e0
15:29:32.564 > 
15:29:32.564 >
15:29:32.564 >
15:29:32.564 >
15:29:32.564 > ELF file SHA256: 22f76682b73e94f5
15:29:32.564 >
15:29:32.564 > Rebooting...

NimBle function at this line : 

void NimBLEDevice::init(const std::string &deviceName) {
    if(!initialized){
        int rc=0;
#ifdef ESP_PLATFORM
        esp_err_t errRc = ESP_OK;

#ifdef CONFIG_ENABLE_ARDUINO_DEPENDS
        // make sure the linker includes esp32-hal-bt.c so Arduino init doesn't release BLE memory.
        btStarted();
#endif

        errRc = nvs_flash_init();

        if (errRc == ESP_ERR_NVS_NO_FREE_PAGES || errRc == ESP_ERR_NVS_NEW_VERSION_FOUND) {
            ESP_ERROR_CHECK(nvs_flash_erase());
            errRc = nvs_flash_init();
        }

        ESP_ERROR_CHECK(errRc);

        esp_bt_controller_mem_release(ESP_BT_MODE_CLASSIC_BT);

        esp_bt_controller_config_t bt_cfg = BT_CONTROLLER_INIT_CONFIG_DEFAULT();
#if  defined (CONFIG_IDF_TARGET_ESP32C3) || defined(CONFIG_IDF_TARGET_ESP32S3)
        bt_cfg.bluetooth_mode = ESP_BT_MODE_BLE;
#else
        bt_cfg.mode = ESP_BT_MODE_BLE;
        bt_cfg.ble_max_conn = CONFIG_BT_NIMBLE_MAX_CONNECTIONS;
#endif
        bt_cfg.normal_adv_size = m_scanDuplicateSize;
        bt_cfg.scan_duplicate_type = m_scanFilterMode;

        ESP_ERROR_CHECK(esp_bt_controller_init(&bt_cfg));
        ESP_ERROR_CHECK(esp_bt_controller_enable(ESP_BT_MODE_BLE));
        ESP_ERROR_CHECK(esp_nimble_hci_init());
#endif
        nimble_port_init();

        // Setup callbacks for host events
        ble_hs_cfg.reset_cb = NimBLEDevice::onReset;
        ble_hs_cfg.sync_cb = NimBLEDevice::onSync;

        // Set initial security capabilities
        ble_hs_cfg.sm_io_cap = BLE_HS_IO_NO_INPUT_OUTPUT;
        ble_hs_cfg.sm_bonding = 0;
        ble_hs_cfg.sm_mitm = 0;
        ble_hs_cfg.sm_sc = 1;
        ble_hs_cfg.sm_our_key_dist = 1;
        ble_hs_cfg.sm_their_key_dist = 3;

        ble_hs_cfg.store_status_cb = ble_store_util_status_rr; /*TODO: Implement handler for this*/

        // Set the device name.
        rc = ble_svc_gap_device_name_set(deviceName.c_str());
        assert(rc == 0);

        ble_store_config_init();

        nimble_port_freertos_init(NimBLEDevice::host_task);
    }

    // Wait for host and controller to sync before returning and accepting new tasks
    while(!m_synced){
        taskYIELD();
    }

    initialized = true; // Set the initialization flag to ensure we are only initialized once.
} // init

esp_err_t esp_bt_controller_init(esp_bt_controller_config_t *cfg)
{
    esp_err_t err;
    uint32_t btdm_cfg_mask = 0;

#if CONFIG_BTDM_CTRL_HLI
    hli_queue_setup_pinned_to_core(CONFIG_BTDM_CTRL_PINNED_TO_CORE);
#endif /* CONFIG_BTDM_CTRL_HLI */

    //if all the bt available memory was already released, cannot initialize bluetooth controller
    if (btdm_dram_available_region[0].mode == ESP_BT_MODE_IDLE) {
        return ESP_ERR_INVALID_STATE;
    }

    osi_funcs_p = (struct osi_funcs_t *)malloc_internal_wrapper(sizeof(struct osi_funcs_t));
    if (osi_funcs_p == NULL) {
        return ESP_ERR_NO_MEM;
    }

    memcpy(osi_funcs_p, &osi_funcs_ro, sizeof(struct osi_funcs_t));
    if (btdm_osi_funcs_register(osi_funcs_p) != 0) {
        return ESP_ERR_INVALID_ARG;
    }

    if (btdm_controller_status != ESP_BT_CONTROLLER_STATUS_IDLE) {
        return ESP_ERR_INVALID_STATE;
    }

    if (cfg == NULL) {
        return ESP_ERR_INVALID_ARG;
    }

    if (cfg->controller_task_prio != ESP_TASK_BT_CONTROLLER_PRIO
            || cfg->controller_task_stack_size < ESP_TASK_BT_CONTROLLER_STACK) {
        return ESP_ERR_INVALID_ARG;
    }

    //overwrite some parameters
    cfg->bt_max_sync_conn = CONFIG_BTDM_CTRL_BR_EDR_MAX_SYNC_CONN_EFF;
    cfg->magic  = ESP_BT_CONTROLLER_CONFIG_MAGIC_VAL;

    if (((cfg->mode & ESP_BT_MODE_BLE) && (cfg->ble_max_conn <= 0 || cfg->ble_max_conn > BTDM_CONTROLLER_BLE_MAX_CONN_LIMIT))
            || ((cfg->mode & ESP_BT_MODE_CLASSIC_BT) && (cfg->bt_max_acl_conn <= 0 || cfg->bt_max_acl_conn > BTDM_CONTROLLER_BR_EDR_MAX_ACL_CONN_LIMIT))
            || ((cfg->mode & ESP_BT_MODE_CLASSIC_BT) && (cfg->bt_max_sync_conn > BTDM_CONTROLLER_BR_EDR_MAX_SYNC_CONN_LIMIT))) {
        return ESP_ERR_INVALID_ARG;
    }

    ESP_LOGI(BTDM_LOG_TAG, "BT controller compile version [%s]", btdm_controller_get_compile_version());

    s_wakeup_req_sem = semphr_create_wrapper(1, 0);
    if (s_wakeup_req_sem == NULL) {
        err = ESP_ERR_NO_MEM;
        goto error;
    }

    esp_phy_modem_init();

    esp_bt_power_domain_on();

    btdm_controller_mem_init();

    periph_module_enable(PERIPH_BT_MODULE);

#ifdef CONFIG_PM_ENABLE
    s_btdm_allow_light_sleep = false;
#endif

    // set default sleep clock cycle and its fractional bits
    btdm_lpcycle_us_frac = RTC_CLK_CAL_FRACT;
    btdm_lpcycle_us = 2 << (btdm_lpcycle_us_frac);

#if CONFIG_BTDM_CTRL_MODEM_SLEEP_MODE_ORIG

    btdm_lpclk_sel = BTDM_LPCLK_SEL_XTAL; // set default value
#if CONFIG_BTDM_CTRL_LPCLK_SEL_EXT_32K_XTAL
    // check whether or not EXT_CRYS is working
    if (rtc_clk_slow_freq_get() == RTC_SLOW_FREQ_32K_XTAL) {
        btdm_lpclk_sel = BTDM_LPCLK_SEL_XTAL32K; // External 32kHz XTAL
#ifdef CONFIG_PM_ENABLE
        s_btdm_allow_light_sleep = true;
#endif
    } else {
        ESP_LOGW(BTDM_LOG_TAG, "32.768kHz XTAL not detected, fall back to main XTAL as Bluetooth sleep clock\n"
                 "light sleep mode will not be able to apply when bluetooth is enabled");
        btdm_lpclk_sel = BTDM_LPCLK_SEL_XTAL; // set default value
    }
#else
    btdm_lpclk_sel = BTDM_LPCLK_SEL_XTAL; // set default value
#endif

    bool select_src_ret __attribute__((unused));
    bool set_div_ret __attribute__((unused));
    if (btdm_lpclk_sel == BTDM_LPCLK_SEL_XTAL) {
        select_src_ret = btdm_lpclk_select_src(BTDM_LPCLK_SEL_XTAL);
        set_div_ret = btdm_lpclk_set_div(rtc_clk_xtal_freq_get() * 2 - 1);
        assert(select_src_ret && set_div_ret);
        btdm_lpcycle_us_frac = RTC_CLK_CAL_FRACT;
        btdm_lpcycle_us = 2 << (btdm_lpcycle_us_frac);
    } else { // btdm_lpclk_sel == BTDM_LPCLK_SEL_XTAL32K
        select_src_ret = btdm_lpclk_select_src(BTDM_LPCLK_SEL_XTAL32K);
        set_div_ret = btdm_lpclk_set_div(0);
        assert(select_src_ret && set_div_ret);
        btdm_lpcycle_us_frac = RTC_CLK_CAL_FRACT;
        btdm_lpcycle_us = (RTC_CLK_CAL_FRACT > 15) ? (1000000 << (RTC_CLK_CAL_FRACT - 15)) :
            (1000000 >> (15 - RTC_CLK_CAL_FRACT));
        assert(btdm_lpcycle_us != 0);
    }
    btdm_controller_set_sleep_mode(BTDM_MODEM_SLEEP_MODE_ORIG);

#elif CONFIG_BTDM_CTRL_MODEM_SLEEP_MODE_EVED
    btdm_controller_set_sleep_mode(BTDM_MODEM_SLEEP_MODE_EVED);
#else
    btdm_controller_set_sleep_mode(BTDM_MODEM_SLEEP_MODE_NONE);
#endif

#ifdef CONFIG_PM_ENABLE
    if (!s_btdm_allow_light_sleep) {
        if ((err = esp_pm_lock_create(ESP_PM_NO_LIGHT_SLEEP, 0, "btLS", &s_light_sleep_pm_lock)) != ESP_OK) {
            goto error;
        }
    }
    if ((err = esp_pm_lock_create(ESP_PM_APB_FREQ_MAX, 0, "bt", &s_pm_lock)) != ESP_OK) {
        goto error;
    }
    esp_timer_create_args_t create_args = {
        .callback = btdm_slp_tmr_callback,
        .arg = NULL,
        .name = "btSlp"
    };
    if ((err = esp_timer_create(&create_args, &s_btdm_slp_tmr)) != ESP_OK) {
        goto error;
    }

    s_pm_lock_acquired = true;
#endif

#if CONFIG_SW_COEXIST_ENABLE
    coex_init();
#endif

    btdm_cfg_mask = btdm_config_mask_load();

    if (btdm_controller_init(btdm_cfg_mask, cfg) != 0) {
        err = ESP_ERR_NO_MEM;
        goto error;
    }

    btdm_controller_status = ESP_BT_CONTROLLER_STATUS_INITED;

    return ESP_OK;

error:

    bt_controller_deinit_internal();

    return err;
}

esp_err_t esp_bt_controller_deinit(void)
{
    if (btdm_controller_status != ESP_BT_CONTROLLER_STATUS_INITED) {
        return ESP_ERR_INVALID_STATE;
    }

    btdm_controller_deinit();

    bt_controller_deinit_internal();

    return ESP_OK;
}

static void bt_controller_deinit_internal(void)
{
    periph_module_disable(PERIPH_BT_MODULE);

#ifdef CONFIG_PM_ENABLE
    if (!s_btdm_allow_light_sleep) {
        esp_pm_lock_delete(s_light_sleep_pm_lock);
        s_light_sleep_pm_lock = NULL;
    }

    if (s_pm_lock != NULL) {
        esp_pm_lock_delete(s_pm_lock);
        s_pm_lock = NULL;
    }

    if (s_btdm_slp_tmr != NULL) {
        esp_timer_stop(s_btdm_slp_tmr);
        esp_timer_delete(s_btdm_slp_tmr);
        s_btdm_slp_tmr = NULL;
    }

    s_pm_lock_acquired = false;
#endif

    if (s_wakeup_req_sem) {
        semphr_delete_wrapper(s_wakeup_req_sem);
        s_wakeup_req_sem = NULL;
    }

    if (osi_funcs_p) {
        free(osi_funcs_p);
        osi_funcs_p = NULL;
    }

    btdm_controller_status = ESP_BT_CONTROLLER_STATUS_IDLE;

    btdm_lpcycle_us = 0;
    btdm_controller_set_sleep_mode(BTDM_MODEM_SLEEP_MODE_NONE);

    esp_bt_power_domain_off();

    esp_phy_modem_deinit();
}

build test with ke_get_heap_free_size : 

Linking .pio\build\smartdisplay_vesc_35v2_pcb210\firmware.elf
c:/users/koxx3/.platformio/packages/toolchain-xtensa-esp32/bin/../lib/gcc/xtensa-esp32-elf/8.4.0/../../../../xtensa-esp32-elf/bin/ld.exe: .pio/build/smartdisplay_vesc_35v2_pcb210/src/main.o:(.literal._Z4loopv+0x2c): undefined reference to `ke_get_heap_free_size()'
c:/users/koxx3/.platformio/packages/toolchain-xtensa-esp32/bin/../lib/gcc/xtensa-esp32-elf/8.4.0/../../../../xtensa-esp32-elf/bin/ld.exe: .pio/build/smartdisplay_vesc_35v2_pcb210/src/main.o: in function `loop()':
C:\Users\koxx3\Documents\Coding\SmartController_SmartDisplay_ESP32_priv3/src/main.cpp:1075: undefined reference to `ke_get_heap_free_size()'
collect2.exe: error: ld returned 1 exit status
*** [.pio\build\smartdisplay_vesc_35v2_pcb210\firmware.elf] Error 1
Koxx3 commented 5 months ago

in debug level : 

D (1299) BTDM_INIT: Release DRAM [0x3ffb2730] - [0x3ffb6388]
D (1300) intr_alloc: Connected src -5 to int 29 (cpu 1)
I (1300) BTDM_INIT: BT controller compile version [d166426]
D (1301) BTDM_INIT: .data initialise [0x3ffae6e0] <== [0x4000d890]
D (1301) BTDM_INIT: .bss initialise [0x3ffb0000] - [0x3ffb09a8]
D (1302) BTDM_INIT: .bss initialise [0x3ffb09a8] - [0x3ffb1ddc]
D (1303) BTDM_INIT: .bss initialise [0x3ffb1ddc] - [0x3ffb2730]
D (1304) BTDM_INIT: .bss initialise [0x3ffb8000] - [0x3ffb9a20]
D (1304) BTDM_INIT: .bss initialise [0x3ffbdb28] - [0x3ffbdb5c]
ESP_ERROR_CHECK failed: esp_err_t 0x101 (ESP_ERR_NO_MEM) at 0x40092ad4
file: ".pio/libdeps/smartdisplay_vesc_35v2_pcb210/nimble/src/NimBLEDevice.cpp" line 879
func: static void NimBLEDevice::init(const string&)
expression: esp_bt_controller_init(&bt_cfg)

abort() was called at PC 0x40092ad7 on core 1
esp-zhp commented 5 months ago

The reason for this issue is the mismatch between the "magic value" externally and internally in the controller. The external controller value is configured by ESP_BT_CONTROLLER_CONFIG_MAGIC_VAL and needs to be consistent internally.

It's worth noting that in version v4.4.4, the internal "magic value" is 0x20200622. If you encounter this problem, you need to verify whether you are using version v4.4.4. image

esp-zhp commented 5 months ago

replace esp-idf/components/bt/controller/lib_esp32/esp32/libbtdm_app.a and extern uint16_t ke_get_heap_free_size(void);

make sure：BT controller compile version [d166426] image

Koxx3 commented 4 months ago

I managed to remove Tasmota dependencies and work with "pure" packages now (thanks to Jason2866): 

PACKAGES:
 - framework-arduinoespressif32 @ 3.20016.0 (2.0.16)
 - framework-espidf @ 3.40407.0 (4.4.7)
 - tool-cmake @ 3.16.4
 - tool-esptoolpy @ 1.40501.0 (4.5.1)
 - tool-idf @ 1.0.1
 - tool-mconf @ 1.4060000.20190628 (406.0.0)
 - tool-mkspiffs @ 2.230.0 (2.30)
 - tool-ninja @ 1.9.0
 - toolchain-esp32ulp @ 1.23500.220830 (2.35.0)
 - toolchain-xtensa-esp32 @ 8.4.0+2021r2-patch5

here are the IDF 4.4.7 results with stock "libbtdm_app.a" : 

r_assert at C:\Users\koxx3\.platformio\packages\framework-espidf\components\bt\controller\esp32/bt.c:1902
r_assert_param at ??:?
r_platform_reset at ??:?
?? ??:0
?? ??:0
r_llm_le_adv_report_ind at ??:?
r_llm_pdu_defer at ??:?
r_lld_pdu_check at ??:?
r_lld_evt_deffered_elt_handler at ??:?
?? ??:0
?? ??:0
r_rw_schedule at ??:?
btdm_controller_task at ??:?
vPortTaskWrapper at C:\Users\koxx3\.platformio\packages\framework-espidf\components\freertos\port\xtensa/port.c:142

board 1 crashed after 52 min, then 11h43m board 2 crashed after 12h10m

I tried you patched "libbtdm_app.a" with IDF 4.4.7, but it doesn't work ;)

esp-zhp commented 4 months ago

@Koxx3 can you use ke_get_heap_free_size now?

Koxx3 commented 4 months ago

ok, I'll try to switch back to officiel 4.4.4 and use ke_get_heap_free_size

esp-zhp commented 4 months ago

I guess there might be a subtle memory leak in the controller. Perhaps some patterns could be discovered by using ke_get_heap_free_size... thanks for your testing.

Koxx3 commented 4 months ago

argh. I cleaned everything (build folder & cache). I made sure only 1 framework-espidf remained, then patched ... but it still doesn't link.

image

Linking .pio\build\smartdisplay_vesc_35v2_pcb210\firmware.elf
c:/users/koxx3/.platformio/packages/toolchain-xtensa-esp32/bin/../lib/gcc/xtensa-esp32-elf/8.4.0/../../../../xtensa-esp32-elf/bin/ld.exe: .pio/build/smartdisplay_vesc_35v2_pcb210/src/main.o:(.literal._Z4loopv+0x30): undefined reference to `ke_get_heap_free_size()'
c:/users/koxx3/.platformio/packages/toolchain-xtensa-esp32/bin/../lib/gcc/xtensa-esp32-elf/8.4.0/../../../../xtensa-esp32-elf/bin/ld.exe: .pio/build/smartdisplay_vesc_35v2_pcb210/src/main.o: in function `loop()':
C:\Users\koxx3\Documents\Coding\SmartController_SmartDisplay_ESP32_priv3/src/main.cpp:1075: undefined reference to `ke_get_heap_free_size()'
collect2.exe: error: ld returned 1 exit status
*** [.pio\build\smartdisplay_vesc_35v2_pcb210\firmware.elf] Error 1

then in main.cpp : 

...
extern uint16_t ke_get_heap_free_size(void);
...

void loop()
{

  if (i_loopIdle % 1000 == 0)
  {
    uint16_t free_size = ke_get_heap_free_size();
    Serial.printf("main : free size = %d bytes\n", free_size);
  }
}

At execution (without using ke_get_heap_free_size), it clearly state I am using d166426 : I (1553) BTDM_INIT: BT controller compile version [d166426]

esp-zhp commented 4 months ago

Can you provide me with your current commit ID? I'd like to perform some local testing.

Koxx3 commented 4 months ago

sorry updated too late : At execution (without using ke_get_heap_free_size), it clearly state I am using d166426 : I (1553) BTDM_INIT: BT controller compile version [d166426]

Koxx3 commented 4 months ago

Can you provide me with your current commit ID? I'd like to perform some local testing.

how do I do that ?

Koxx3 commented 4 months ago 
; IDF 4.4.4 / arduino 2.0.16 / building fine
platform = espressif32 @ ^6.6.0
platform_packages = 
    tool-mkspiffs @ 2.230.0
    platformio/framework-espidf @ ~3.40404.0
    platformio/framework-arduinoespressif32 @ ~3.20016.0

framework = arduino, espidf
board = esp32dev
esp-zhp commented 4 months ago

If you don't call ke_get_heap_free_size, the compilation should still proceed without issues, right?

Koxx3 commented 4 months ago

If you don't call ke_get_heap_free_size, the compilation should still proceed without issues, right?

yes. and the app runs perfectly with BT

Koxx3 commented 4 months ago

running logs in debug level : https://koxx3.fr.eu.org:8086/device-monitor-240511-095738.zip

Koxx3 commented 4 months ago

oh !!! you gave me an idea ! I forced the declaration in esp_bt.h.

and it works now !

image

10:54:16.786 > main : free size = 6760 bytes
10:54:22.126 > main : free size = 6760 bytes
10:54:27.461 > main : free size = 6760 bytes
10:54:32.778 > main : free size = 6748 bytes
Koxx3 commented 4 months ago

yes, it really seems to leak :

10:54:16.786 > main : free size = 6760 bytes
10:54:22.126 > main : free size = 6760 bytes
10:54:27.461 > main : free size = 6760 bytes
10:54:32.778 > main : free size = 6748 bytes
10:54:38.107 > main : free size = 6768 bytes
10:54:43.449 > main : free size = 6744 bytes
10:54:48.793 > main : free size = 6760 bytes
10:54:54.135 > main : free size = 6944 bytes
10:54:59.476 > main : free size = 6760 bytes
10:55:04.818 > main : free size = 6760 bytes
10:55:10.156 > main : free size = 6748 bytes
10:55:15.527 > main : free size = 6760 bytes
10:55:20.861 > main : free size = 6760 bytes
10:55:26.196 > main : free size = 6764 bytes
10:55:31.523 > main : free size = 6744 bytes
10:55:36.860 > main : free size = 6760 bytes
10:55:42.191 > main : free size = 6768 bytes
10:55:47.530 > main : free size = 6748 bytes
10:55:52.854 > main : free size = 6748 bytes
10:55:58.180 > main : free size = 6768 bytes
10:56:03.504 > main : free size = 6760 bytes
10:56:08.836 > main : free size = 6744 bytes
10:56:14.177 > main : free size = 6744 bytes
10:56:19.519 > main : free size = 6760 bytes
10:56:24.847 > main : free size = 6768 bytes
10:56:30.171 > main : free size = 6760 bytes
10:56:35.532 > main : free size = 6944 bytes
10:56:40.872 > main : free size = 6740 bytes
10:56:46.223 > main : free size = 6748 bytes
10:56:51.581 > main : free size = 6760 bytes
10:56:56.925 > main : free size = 6760 bytes
10:57:02.262 > main : free size = 6760 bytes
10:57:07.604 > main : free size = 6744 bytes
10:57:12.935 > main : free size = 6744 bytes
10:57:18.281 > main : free size = 6744 bytes
10:57:23.634 > main : free size = 6744 bytes
10:57:28.973 > main : free size = 6732 bytes
10:57:34.309 > main : free size = 6744 bytes
10:57:39.651 > main : free size = 6744 bytes
10:57:45.000 > main : free size = 6736 bytes
10:57:50.340 > main : free size = 6732 bytes
10:57:55.664 > main : free size = 6744 bytes
10:58:01.005 > main : free size = 6728 bytes
10:58:06.342 > main : free size = 6744 bytes
10:58:11.688 > main : free size = 6728 bytes
10:58:17.031 > main : free size = 6928 bytes
10:58:22.377 > main : free size = 6744 bytes
10:58:27.711 > main : free size = 6744 bytes
10:58:33.060 > main : free size = 6744 bytes
10:58:38.405 > main : free size = 6764 bytes
10:58:43.738 > main : free size = 6744 bytes
10:58:49.068 > main : free size = 6744 bytes
10:58:54.401 > main : free size = 6728 bytes
10:58:59.731 > main : free size = 6744 bytes
10:59:05.089 > main : free size = 6744 bytes
10:59:10.424 > main : free size = 6728 bytes
10:59:15.767 > main : free size = 6724 bytes
10:59:21.146 > main : free size = 6724 bytes
10:59:26.511 > main : free size = 6724 bytes
10:59:31.861 > main : free size = 6712 bytes
Koxx3 commented 4 months ago

also, disconnecting and reconnecting BLE doesn't release the memory.

11:01:46.296 > main : free size = 6736 bytes
11:01:51.729 > main : free size = 6724 bytes
11:01:57.162 > main : free size = 6692 bytes
11:02:02.586 > main : free size = 6704 bytes
11:02:08.002 > main : free size = 6676 bytes
11:02:13.441 > main : free size = 6692 bytes
11:02:18.865 > main : free size = 6692 bytes
11:02:21.880 > BLH : onDisconnect - BEGIN
11:02:21.880 > BLH : onDisconnect - getConnectedCount = 0
11:02:21.881 > BLH : onDisconnect - END
11:02:21.881 > W NimBLEAdvertising: Advertising already active
11:02:24.226 > main : free size = 6964 bytes
11:02:25.223 > BLH : onConnect1 - getConnectedCount() : 1
11:02:25.224 > BLH : onConnect1 - nbFailure : 0
11:02:25.224 > BLH : onConnect2 - getPeerMTU() : 23
11:02:25.224 > BLH : onConnect2 - mtuReal - 3 : 20
11:02:25.438 > BLH : onAuthenticationComplete - BEGIN
11:02:25.438 > BLH : onAuthenticationComplete : success
11:02:25.454 > BLH : onAuthenticationComplete - END
11:02:25.620 > BLH : onMTUChange : 255
11:02:27.901 > BLH : onRead : beb5483e-36e1-4688-b7f5-ea07361b26a3
11:02:27.990 > BLH : onWrite : beb5483e-36e1-4688-b7f5-ea07361b26b7
11:02:27.990 > BLH : dateBle = 1715418148
11:02:27.993 > Saturday, May 11 2024 11:02:28
11:02:28.530 > BLH : onRead : beb5483e-36e1-4688-b7f5-ea07361b26a2
11:02:28.530 > BLH : setEbFirmwaresDataPacket
11:02:28.620 > BLH : onRead : beb5483e-36e1-4688-b7f5-ea07361b26a5
11:02:29.429 > BLH : onRead : beb5483e-36e1-4688-b7f5-ea07361b26a7
11:02:29.429 > ErrorLogger - getHistoryBytes ind = 0
11:02:29.520 > BLH : onRead : beb5483e-36e1-4688-b7f5-ea07361b26a8
11:02:29.610 > BLH : onRead : beb5483e-36e1-4688-b7f5-ea07361b26fc
11:02:29.643 > main : free size = 6672 bytes
11:02:29.730 > BLH : onWrite : beb5483e-36e1-4688-b7f5-ea07361b26fe
11:02:29.734 > W NimBLECharacteristic: Sending indication to client subscribed to notification, sending notification instead
11:02:29.757 > W NimBLECharacteristic: Sending indication to client subscribed to notification, sending notification instead
11:02:29.777 > W NimBLECharacteristic: Sending indication to client subscribed to notification, sending notification instead
11:02:30.240 > BLH : onWrite : beb5483e-36e1-4688-b7f5-ea07361b26a5
11:02:35.155 > main : free size = 6692 bytes
11:02:40.610 > main : free size = 6692 bytes
11:02:46.045 > main : free size = 6676 bytes
11:02:51.475 > main : free size = 6692 bytes
esp-zhp commented 4 months ago

If you can analyze the scenarios of memory leaks (broadcasting, scanning, connecting, etc.), it would be very helpful in resolving the issue. What operations trigger memory leaks?

esp-zhp commented 4 months ago

I recently discovered an issue with bidirectional frequent initiation of connection parameter updates leading to memory leaks. Are both ends frequently initiating updates of connection parameters over there? It seems like it might not be the same issue as yours ...

Koxx3 commented 4 months ago

If you can analyze the scenarios of memory leaks (broadcasting, scanning, connecting, etc.), it would be very helpful in resolving the issue.

yes, I'll try.

during this basic test, my IDLE loop call processBLE : 


void BluetoothHandler::processBLE()
{

    // notify changed value
    if (deviceStatus == BLE_STATUS_CONNECTED_AND_AUTHENTIFIED)
    {
        uint16_t period = 250;
        if ((shrd->fastUpdate) && (shrd->navMode == 0))
            period = 100;

        /*
        Serial.print(millis());
        Serial.print("BLH :  / ");
        Serial.print(shrd->timeLastNotifyBle);
        Serial.print("BLH :  / ");
        Serial.print(period);
        Serial.println(" / ");
        */

        if (millis() > shrd->timeLastNotifyBle + period)
        {

            notifyMeasurements();

            notifyBleLockAndErrors();

            shrd->timeLastNotifyBle = millis();
        }

        if (millis() > shrd->timeLastNotifyBleBms + 500)
        {
            notifyMeasurementsBms();

            shrd->timeLastNotifyBleBms = millis();
        }
    }

    // reset BLE stack if impossible to connect to BLE anymore
    if (bleNbFailure > 2)
    {
        deinit();
        delay(100);

        init();
        delay(100);

        bleScanEnabled = 1;

        bleNbFailure = 0;
    }

    // fail-safe restart for scan
    if ((!pBLEScan->isScanning()) && (bleScanEnabled >= 0) /*&& (bleScanStartFailedInMillis != 0) && (millis() - bleScanStartFailedInMillis > BEACON_SCAN_PERIOD_IN_SECONDS * 1000)*/)
    {
        // Serial.println("BLH : millis() - bleScanStartFailedInMillis = " + (String)(millis() - bleScanStartFailedInMillis));

/*
        char print_buffer[200];
        sprintf(print_buffer, "BLH : backup scan restart / isScanning = %d / bleScanEnabled = %d", pBLEScan->isScanning(), bleScanEnabled);
        Serial.println(print_buffer);
        // notifyBleLogs(print_buffer);
*/
        startBleScan();
    }

    oldDeviceStatus = deviceStatus;
}

void BluetoothHandler::startBleScan()
{

/*
    Serial.println("BLH : startBleScan / beacon scan : enabled = " + (String)bleScanEnabled +
                   " / vescToolMode = " + (String)shrd->vescToolMode +
                   " / bleScanMode = " + (String)shrd->bleScanMode +
                   " / beacon1 = " + (String)settings->get_Ble_beacon_mac_address1() +
                   " / beacon2 = " + (String)settings->get_Ble_beacon_mac_address2() +
                   " / tpms1 = " + (String)settings->get_Tpms_mac_address1() +
                   " / tpms2 = " + (String)settings->get_Tpms_mac_address2());
*/

    // start scan only if different from dummy mac address
    if ((bleScanEnabled >= 0) && (shrd->vescToolMode == 0) &&
        (((settings->get_Ble_beacon_mac_address1() != "aa:bb:cc:dd:ee:ff") || //
          (settings->get_Ble_beacon_mac_address2() != "aa:bb:cc:dd:ee:ff") || //
          (settings->get_Tpms_mac_address1() != "aa:bb:cc:dd:ee:ff") ||       //
          (settings->get_Tpms_mac_address2() != "aa:bb:cc:dd:ee:ff")) ||      //
         (shrd->bleScanMode != 0)))
    {
        // Serial.println("BLH : startBleScan / trying to start scan");

        if ((pBLEScan != NULL) && (pBLEScan->isScanning()))
            pBLEScan->stop();

        // Start scanning
        pBLEScan = BLEDevice::getScan(); // create new scan

        /*
        pBLEScan->setActiveScan(true);   // active scan uses more power, but get results faster
        pBLEScan->setInterval(100);
        pBLEScan->setWindow(98); // less or equal setInterval value
        */

#if SCAN_USE_WHITELIST
        if (shrd->bleScanMode == 0)
        {
            // Serial.println("BLH : startBleScan / set white list");
            pBLEScan->setFilterPolicy(BLE_HCI_SCAN_FILT_USE_WL);
            for (auto i = 0; i < NimBLEDevice::getWhiteListCount(); ++i)
                NimBLEDevice::whiteListRemove(NimBLEDevice::getWhiteListAddress(i));
            NimBLEDevice::whiteListAdd(NimBLEAddress(settings->get_Ble_beacon_mac_address1().c_str()));
            NimBLEDevice::whiteListAdd(NimBLEAddress(settings->get_Ble_beacon_mac_address2().c_str()));
            NimBLEDevice::whiteListAdd(NimBLEAddress(settings->get_Tpms_mac_address1().c_str()));
            NimBLEDevice::whiteListAdd(NimBLEAddress(settings->get_Tpms_mac_address2().c_str()));
        }
        else
        {
            // Serial.println("BLH : startBleScan / clear white list");
            pBLEScan->setFilterPolicy(BLE_HCI_SCAN_FILT_NO_WL);
        }
#endif

        // NEW TEST - no improvement
        // pBLEScan->clearResults();

        bool bleScanStarted = pBLEScan->start(BEACON_SCAN_PERIOD_IN_SECONDS, &bleOnScanResults, false);
        if (!bleScanStarted)
        {
            Serial.println("BLH : startBleScan / scan start failed");
            notifyBleLogs("BLH : scan start failed");
            bleScanStartFailedInMillis = millis();
        }
        else
        {
            bleScanStartFailedInMillis = 0;
        }
        // Serial.println("BLH : startBleScan / Beacon scan start res = " + (String)bleScanStarted);
    }
    else
    {
        Serial.println("BLH : startBleScan / Beacon scan disabled - conditions not ok - addresses or bleScanMode or vesctool");
    }
}
Koxx3 commented 4 months ago

I recently discovered an issue with bidirectional frequent initiation of connection parameter updates leading to memory leaks. Are both ends frequently initiating updates of connection parameters over there? It seems like it might not be the same issue as yours ...

hum ... no, the connection is stable in my test.

here is the nimble serverCallbacks class :

    class BLEServerCallback : public NimBLEServerCallbacks
    {

        void onConnect(NimBLEServer *pServer)
        {

            deviceStatus = BLE_STATUS_CONNECTED_AND_AUTHENTIFYING;

...

            /*
            // TODO : add again
            // ble_svc_gatt_changed(0x0000, 0xFFFF);
            */

            // TODO : add again
            // NimBLEDevice::startAdvertising();

            Serial.println("BLH : onConnect1 - getConnectedCount() : " + (String)pServer->getConnectedCount());

            Serial.println("BLH : onConnect1 - nbFailure : " + (String)bleNbFailure);
            bleNbFailure++;
        };

        void onConnect(NimBLEServer *pServer, ble_gap_conn_desc *desc)
        {
            Serial.println("BLH : onConnect2 - getPeerMTU() : " + (String)pServer->getPeerMTU(desc->conn_handle));

            mtuReal = pServer->getPeerMTU(desc->conn_handle) - 3;
            Serial.println("BLH : onConnect2 - mtuReal - 3 : " + (String)mtuReal);
        }

        void onAuthenticationComplete(ble_gap_conn_desc *desc)
        {

            Serial.println(F("BLH : onAuthenticationComplete - BEGIN"));
            if (!desc->sec_state.encrypted)
            {

                Serial.println(F("BLH : onAuthenticationComplete : Encrypt connection failed - disconnecting"));
                NimBLEDevice::getServer()->disconnect(desc->conn_handle);
                deviceStatus = BLE_STATUS_DISCONNECTED;
                deviceStatusConnectedStartTime = 0;
            }
            else
            {
                Serial.println(F("BLH : onAuthenticationComplete : success"));
                deviceStatus = BLE_STATUS_CONNECTED_AND_AUTHENTIFIED;
                deviceStatusConnectedStartTime = millis();
            }

            ble_svc_gatt_changed(0x0000, 0xFFFF);

            if (bleNbFailure > 0)
                bleNbFailure--;

            Serial.println(F("BLH : onAuthenticationComplete - END"));
        }

        bool onConfirmPIN(uint32_t pin)
        {
            Serial.println(F("BLH : onConfirmPIN - BEGIN"));

            uint32_t pinCode = std::stoi(settings->get_Ble_pin_code2().c_str());
            Serial.println(pinCode);
            Serial.print(F("BLH : onConfirmPIN - END"));
            Serial.println(pinCode == pin);

            return pinCode == pin;
        }

        void onDisconnect(NimBLEServer *pServer)
        {
            Serial.println(F("BLH : onDisconnect - BEGIN"));
            deviceStatus = BLE_STATUS_DISCONNECTED;

            // shrd->isRecording = 1;

            if (shrd->bleLockForced == 0)
            {
                if (settings->get_Bluetooth_lock_mode() == settings->LIST_Bluetooth_lock_mode_Smartphone_connected)
                {
                    shrd->isLocked = 1;
                    Serial.println(F("BLH :  ==> device disconnected ==> LOCK decision"));
                    Serial.println(F("BLH : -------------------------------------"));
                }
                if (settings->get_Bluetooth_lock_mode() == settings->LIST_Bluetooth_lock_mode_Smartphone_connected_or_beacon_visible)
                {
                    if ((!shrd->bleBeaconVisible1) && (!shrd->bleBeaconVisible2))
                    {
                        shrd->isLocked = 1;
                        Serial.println(F(" ==> device disconnected / Beacon not visible ==> LOCK decision"));
                        Serial.println(F("-------------------------------------"));
                    }
                }
            }

            shrd->dateIsSyncedInBle = false;

            NimBLEDevice::startAdvertising();

            Serial.println("BLH : onDisconnect - getConnectedCount = " + (String)pServer->getConnectedCount());

            Serial.println(F("BLH : onDisconnect - END"));
        }

        void onMTUChange(uint16_t mtu, ble_gap_conn_desc *desc)
        {
            Serial.println("BLH : onMTUChange : " + (String)mtu);
            mtuReal = mtu - 3;
        }
    };
Koxx3 commented 4 months ago

it seems it leaks with periodic scan...

test 1 : only notifyMeasurements (3 notifications every 100ms) 6436 lowest available mem after beginning 12:02-12:07 => perfectly stable at 6964

test 2 : notifyMeasurements/notifyBleLockAndErrors (4 notifications every 100ms) + notifyMeasurementsBms (1 notification every 500ms) 6832 lowest available mem after beginning 12:08-12:13 => stable at 6964-6980

test 3 : test 2 + start scan every 1s from idle loop WITHOUT whitelist and scan results are sent in a dummy callback max during scan : 6864 12:18-12:48 => seems to leak, I never see memory above 6800 after 20min.

test 3 logs : 

12:18:46.460 > main : btContrl / free size = 6752 bytes  / new low !
12:18:46.460 > main : btContrl / free size = 6744 bytes  / new low !
12:18:46.460 > main : btContrl / free size = 6644 bytes  / new low !
12:18:46.460 > main : btContrl / free size = 6636 bytes  / new low !
12:18:46.460 > BLH : onAuthenticationComplete - BEGIN
12:18:46.460 > BLH : onAuthenticationComplete : success
12:18:46.460 > BLH : onAuthenticationComplete - END
12:18:46.460 > main : btContrl / free size = 6624 bytes  / new low !
12:18:46.460 > main : btContrl / free size = 6564 bytes  / new low !
12:18:46.460 > main : btContrl / free size = 6560 bytes  / new low !
12:18:46.460 > main : btContrl / free size = 6528 bytes  / new low !
12:18:46.460 > BLH : onMTUChange : 255
12:18:46.460 > main : btContrl / free size = 6484 bytes  / new low !
12:18:46.460 > BLH : onRead : beb5483e-36e1-4688-b7f5-ea07361b26a3
12:18:46.460 > BLH : onWrite : beb5483e-36e1-4688-b7f5-ea07361b26b7
12:18:46.460 > BLH : onRead : beb5483e-36e1-4688-b7f5-ea07361b26a2
12:18:46.460 > BLH : setEbFirmwaresDataPacket
12:18:46.460 > BLH : onRead : beb5483e-36e1-4688-b7f5-ea07361b26a5
12:18:47.023 > BLH : onRead : beb5483e-36e1-4688-b7f5-ea07361b26a7
12:18:47.114 > BLH : onRead : beb5483e-36e1-4688-b7f5-ea07361b26a8
12:18:47.204 > BLH : onRead : beb5483e-36e1-4688-b7f5-ea07361b26fc
12:18:47.325 > BLH : onWrite : beb5483e-36e1-4688-b7f5-ea07361b26fe
12:18:47.329 > W NimBLECharacteristic: Sending indication to client subscribed to notification, sending notification instead
12:18:47.351 > W NimBLECharacteristic: Sending indication to client subscribed to notification, sending notification instead
12:18:47.372 > W NimBLECharacteristic: Sending indication to client subscribed to notification, sending notification instead
12:18:47.744 > BLH : onWrite : beb5483e-36e1-4688-b7f5-ea07361b26a5
12:18:48.321 > main : btContrl / free size = 6480 bytes  / new low !
12:18:48.333 > main : btContrl / free size = 6468 bytes  / new low !
12:18:49.978 > main : btContrl / free size = 6608 bytes
12:18:50.587 > main : btContrl / free size = 6464 bytes  / new low !
12:18:55.366 > main : btContrl / free size = 6600 bytes
12:19:00.759 > main : btContrl / free size = 6596 bytes
12:19:03.641 > main : btContrl / free size = 6456 bytes  / new low !
12:19:03.751 > main : btContrl / free size = 6444 bytes  / new low !
12:19:06.172 > main : btContrl / free size = 6668 bytes
12:19:11.566 > main : btContrl / free size = 6596 bytes
12:19:12.175 > main : btContrl / free size = 6436 bytes  / new low !
12:19:16.968 > main : btContrl / free size = 6644 bytes
12:19:18.331 > main : btContrl / free size = 6424 bytes  / new low !
12:19:22.343 > main : btContrl / free size = 6572 bytes
12:19:27.723 > main : btContrl / free size = 6700 bytes
12:19:30.594 > main : btContrl / free size = 6408 bytes  / new low !
12:19:33.115 > main : btContrl / free size = 6688 bytes
12:19:38.510 > main : btContrl / free size = 6584 bytes
12:19:43.912 > main : btContrl / free size = 6584 bytes
12:19:47.975 > main : btContrl / free size = 6404 bytes  / new low !
12:19:49.307 > main : btContrl / free size = 6668 bytes
12:19:52.087 > main : btContrl / free size = 6396 bytes  / new low !
12:19:54.708 > main : btContrl / free size = 6596 bytes
12:20:00.109 > main : btContrl / free size = 6584 bytes
12:20:05.509 > main : btContrl / free size = 6952 bytes
12:20:07.524 > main : btContrl / free size = 6388 bytes  / new low !
12:20:10.907 > main : btContrl / free size = 6660 bytes
12:20:16.310 > main : btContrl / free size = 6552 bytes
12:20:21.727 > main : btContrl / free size = 6536 bytes
12:20:26.019 > main : btContrl / free size = 6372 bytes  / new low !
12:20:27.139 > main : btContrl / free size = 6756 bytes
12:20:31.868 > main : btContrl / free size = 6364 bytes  / new low !
12:20:32.073 > main : btContrl / free size = 6340 bytes  / new low !
12:20:32.180 > main : btContrl / free size = 6320 bytes  / new low !
12:20:32.544 > main : btContrl / free size = 6596 bytes
12:20:35.970 > main : btContrl / free size = 6308 bytes  / new low !
12:20:36.295 > main : btContrl / free size = 6296 bytes  / new low !
12:20:37.949 > main : btContrl / free size = 6484 bytes
12:20:43.347 > main : btContrl / free size = 6528 bytes
12:20:48.738 > main : btContrl / free size = 6732 bytes
12:20:54.127 > main : btContrl / free size = 6564 bytes
12:20:59.533 > main : btContrl / free size = 6568 bytes
12:21:04.922 > main : btContrl / free size = 6700 bytes
12:21:10.315 > main : btContrl / free size = 6656 bytes
12:21:15.693 > main : btContrl / free size = 6652 bytes
12:21:21.083 > main : btContrl / free size = 6600 bytes
12:21:26.467 > main : btContrl / free size = 6548 bytes
12:21:31.858 > main : btContrl / free size = 6652 bytes
12:21:37.272 > main : btContrl / free size = 6584 bytes
12:21:42.660 > main : btContrl / free size = 6552 bytes
12:21:48.065 > main : btContrl / free size = 6952 bytes
12:21:53.468 > main : btContrl / free size = 6592 bytes
12:21:58.867 > main : btContrl / free size = 6604 bytes
12:22:04.263 > main : btContrl / free size = 6580 bytes
12:22:09.644 > main : btContrl / free size = 6748 bytes
12:22:15.015 > main : btContrl / free size = 6640 bytes
12:22:20.398 > main : btContrl / free size = 6640 bytes
12:22:25.776 > main : btContrl / free size = 6564 bytes
12:22:31.179 > main : btContrl / free size = 6692 bytes
12:22:36.558 > main : btContrl / free size = 6620 bytes
12:22:41.931 > main : btContrl / free size = 6564 bytes
12:22:47.302 > main : btContrl / free size = 6600 bytes
12:22:52.692 > main : btContrl / free size = 6656 bytes
12:22:58.067 > main : btContrl / free size = 6592 bytes
12:23:03.457 > main : btContrl / free size = 6556 bytes
12:23:08.835 > main : btContrl / free size = 6632 bytes
12:23:14.210 > main : btContrl / free size = 6692 bytes
12:23:19.611 > main : btContrl / free size = 6668 bytes
12:23:25.013 > main : btContrl / free size = 6572 bytes
12:23:30.412 > main : btContrl / free size = 6920 bytes
12:23:35.800 > main : btContrl / free size = 6620 bytes
12:23:41.180 > main : btContrl / free size = 6520 bytes
12:23:46.573 > main : btContrl / free size = 6580 bytes
12:23:51.967 > main : btContrl / free size = 6656 bytes
12:23:57.356 > main : btContrl / free size = 6596 bytes
12:24:02.737 > main : btContrl / free size = 6500 bytes
12:24:08.112 > main : btContrl / free size = 6580 bytes
12:24:13.504 > main : btContrl / free size = 6680 bytes
12:24:18.889 > main : btContrl / free size = 6560 bytes
12:24:24.269 > main : btContrl / free size = 6568 bytes
12:24:29.660 > main : btContrl / free size = 6484 bytes
12:24:35.071 > main : btContrl / free size = 6692 bytes
12:24:40.474 > main : btContrl / free size = 6600 bytes
12:24:45.874 > main : btContrl / free size = 6596 bytes
12:24:51.279 > main : btContrl / free size = 6544 bytes
12:24:56.685 > main : btContrl / free size = 6612 bytes
12:25:02.077 > main : btContrl / free size = 6628 bytes
12:25:07.464 > main : btContrl / free size = 6624 bytes
12:25:12.856 > main : btContrl / free size = 6920 bytes
12:25:18.238 > main : btContrl / free size = 6560 bytes
12:25:23.621 > main : btContrl / free size = 6648 bytes
12:25:28.977 > main : btContrl / free size = 6572 bytes
12:25:34.347 > main : btContrl / free size = 6680 bytes
12:25:39.714 > main : btContrl / free size = 6604 bytes
12:25:45.098 > main : btContrl / free size = 6564 bytes
12:25:50.498 > main : btContrl / free size = 6576 bytes
12:25:55.899 > main : btContrl / free size = 6680 bytes
12:26:01.297 > main : btContrl / free size = 6544 bytes
12:26:06.688 > main : btContrl / free size = 6552 bytes
12:26:12.088 > main : btContrl / free size = 6500 bytes
12:26:17.469 > main : btContrl / free size = 6688 bytes
12:26:22.862 > main : btContrl / free size = 6572 bytes
12:26:28.248 > main : btContrl / free size = 6556 bytes
12:26:33.644 > main : btContrl / free size = 6460 bytes
12:26:39.033 > main : btContrl / free size = 6556 bytes
12:26:44.414 > main : btContrl / free size = 6544 bytes
12:26:49.790 > main : btContrl / free size = 6516 bytes
12:26:55.168 > main : btContrl / free size = 6900 bytes
12:27:00.543 > main : btContrl / free size = 6584 bytes
12:27:05.946 > main : btContrl / free size = 6552 bytes
12:27:11.352 > main : btContrl / free size = 6576 bytes
12:27:16.743 > main : btContrl / free size = 6676 bytes
12:27:22.125 > main : btContrl / free size = 6528 bytes
12:27:27.532 > main : btContrl / free size = 6492 bytes
12:27:32.922 > main : btContrl / free size = 6504 bytes
12:27:38.326 > main : btContrl / free size = 6668 bytes
12:27:43.721 > main : btContrl / free size = 6644 bytes
12:27:49.122 > main : btContrl / free size = 6508 bytes
12:27:54.517 > main : btContrl / free size = 6456 bytes
12:27:59.917 > main : btContrl / free size = 6608 bytes
12:28:05.299 > main : btContrl / free size = 6556 bytes
12:28:10.689 > main : btContrl / free size = 6504 bytes
12:28:16.069 > main : btContrl / free size = 6532 bytes
12:28:21.450 > main : btContrl / free size = 6568 bytes
12:28:26.834 > main : btContrl / free size = 6524 bytes
12:28:32.224 > main : btContrl / free size = 6492 bytes
12:28:37.593 > main : btContrl / free size = 6880 bytes
12:28:42.980 > main : btContrl / free size = 6540 bytes
12:28:48.360 > main : btContrl / free size = 6552 bytes
12:28:53.744 > main : btContrl / free size = 6536 bytes
12:28:59.136 > main : btContrl / free size = 6660 bytes
12:29:04.532 > main : btContrl / free size = 6524 bytes
12:29:09.930 > main : btContrl / free size = 6524 bytes
12:29:15.330 > main : btContrl / free size = 6520 bytes
12:29:20.739 > main : btContrl / free size = 6632 bytes
12:29:26.149 > main : btContrl / free size = 6508 bytes
12:29:31.544 > main : btContrl / free size = 6560 bytes
12:29:36.935 > main : btContrl / free size = 6432 bytes
12:29:42.332 > main : btContrl / free size = 6592 bytes
12:29:47.716 > main : btContrl / free size = 6536 bytes
12:29:53.109 > main : btContrl / free size = 6468 bytes
12:29:58.489 > main : btContrl / free size = 6460 bytes
12:30:03.850 > main : btContrl / free size = 6572 bytes
12:30:09.252 > main : btContrl / free size = 6512 bytes
12:30:14.639 > main : btContrl / free size = 6452 bytes
12:30:16.913 > main : btContrl / free size = 6292 bytes  / new low !
12:30:20.016 > main : btContrl / free size = 6864 bytes
12:30:25.392 > main : btContrl / free size = 6556 bytes
12:30:30.765 > main : btContrl / free size = 6576 bytes
12:30:36.169 > main : btContrl / free size = 6436 bytes
12:30:41.562 > main : btContrl / free size = 6664 bytes
12:30:46.961 > main : btContrl / free size = 6588 bytes
12:30:52.336 > main : btContrl / free size = 6528 bytes
12:30:57.721 > main : btContrl / free size = 6504 bytes
12:31:03.119 > main : btContrl / free size = 6624 bytes
12:31:08.503 > main : btContrl / free size = 6504 bytes
12:31:13.883 > main : btContrl / free size = 6504 bytes
12:31:19.257 > main : btContrl / free size = 6476 bytes
12:31:24.641 > main : btContrl / free size = 6568 bytes
12:31:30.021 > main : btContrl / free size = 6596 bytes
12:31:35.406 > main : btContrl / free size = 6460 bytes
12:31:40.783 > main : btContrl / free size = 6492 bytes
12:31:46.168 > main : btContrl / free size = 6632 bytes
12:31:51.553 > main : btContrl / free size = 6488 bytes
12:31:56.930 > main : btContrl / free size = 6464 bytes
12:32:02.320 > main : btContrl / free size = 6864 bytes
12:32:07.715 > main : btContrl / free size = 6560 bytes
12:32:13.116 > main : btContrl / free size = 6544 bytes
12:32:18.511 > main : btContrl / free size = 6504 bytes
12:32:23.929 > main : btContrl / free size = 6616 bytes
12:32:29.331 > main : btContrl / free size = 6548 bytes
12:32:34.745 > main : btContrl / free size = 6492 bytes
12:32:40.138 > main : btContrl / free size = 6416 bytes
12:32:45.545 > main : btContrl / free size = 6620 bytes
12:32:50.931 > main : btContrl / free size = 6504 bytes
12:32:56.319 > main : btContrl / free size = 6432 bytes
12:33:01.711 > main : btContrl / free size = 6500 bytes
12:33:07.101 > main : btContrl / free size = 6576 bytes
12:33:12.475 > main : btContrl / free size = 6564 bytes
12:33:17.858 > main : btContrl / free size = 6524 bytes
12:33:23.233 > main : btContrl / free size = 6468 bytes
12:33:28.622 > main : btContrl / free size = 6572 bytes
12:33:34.003 > main : btContrl / free size = 6536 bytes
12:33:39.382 > main : btContrl / free size = 6412 bytes
12:33:39.616 > main : btContrl / free size = 6288 bytes  / new low !
12:33:44.769 > main : btContrl / free size = 6844 bytes
12:33:47.814 > main : btContrl / free size = 6276 bytes  / new low !
12:33:50.169 > main : btContrl / free size = 6540 bytes
12:33:54.827 > main : btContrl / free size = 6272 bytes  / new low !
12:33:54.833 > main : btContrl / free size = 6260 bytes  / new low !
12:33:55.571 > main : btContrl / free size = 6496 bytes
12:34:00.976 > main : btContrl / free size = 6392 bytes
12:34:06.363 > main : btContrl / free size = 6632 bytes
12:34:07.119 > BLH : onWrite : beb5483e-36e1-4688-b7f5-ea07361b26a5
12:34:11.760 > main : btContrl / free size = 6544 bytes
12:34:17.129 > main : btContrl / free size = 6476 bytes
12:34:22.519 > main : btContrl / free size = 6484 bytes
12:34:27.902 > main : btContrl / free size = 6616 bytes
12:34:33.292 > main : btContrl / free size = 6524 bytes
12:34:38.692 > main : btContrl / free size = 6452 bytes
12:34:44.066 > main : btContrl / free size = 6460 bytes
12:34:49.448 > main : btContrl / free size = 6592 bytes
12:34:54.827 > main : btContrl / free size = 6524 bytes
12:35:00.210 > main : btContrl / free size = 6460 bytes
12:35:05.598 > main : btContrl / free size = 6432 bytes
12:35:10.997 > main : btContrl / free size = 6572 bytes
12:35:16.400 > main : btContrl / free size = 6468 bytes
12:35:21.790 > main : btContrl / free size = 6448 bytes
12:35:27.177 > main : btContrl / free size = 6828 bytes
12:35:32.573 > main : btContrl / free size = 6512 bytes
12:35:37.972 > main : btContrl / free size = 6472 bytes
12:35:43.359 > main : btContrl / free size = 6480 bytes
12:35:48.764 > main : btContrl / free size = 6616 bytes
12:35:54.161 > main : btContrl / free size = 6516 bytes
12:35:59.562 > main : btContrl / free size = 6456 bytes
12:36:04.950 > main : btContrl / free size = 6480 bytes
12:36:10.344 > main : btContrl / free size = 6584 bytes
12:36:15.731 > main : btContrl / free size = 6468 bytes
12:36:21.127 > main : btContrl / free size = 6460 bytes
12:36:26.504 > main : btContrl / free size = 6396 bytes
12:36:31.879 > main : btContrl / free size = 6596 bytes
12:36:37.272 > main : btContrl / free size = 6460 bytes
12:36:42.636 > main : btContrl / free size = 6476 bytes
12:36:48.017 > main : btContrl / free size = 6456 bytes
12:36:53.418 > main : btContrl / free size = 6536 bytes
12:36:58.820 > main : btContrl / free size = 6476 bytes
12:37:04.218 > main : btContrl / free size = 6428 bytes
12:37:09.614 > main : btContrl / free size = 6804 bytes
12:37:15.028 > main : btContrl / free size = 6432 bytes
12:37:20.433 > main : btContrl / free size = 6404 bytes
12:37:25.837 > main : btContrl / free size = 6432 bytes
12:37:31.235 > main : btContrl / free size = 6604 bytes
12:37:36.615 > main : btContrl / free size = 6444 bytes
12:37:42.002 > main : btContrl / free size = 6492 bytes
12:37:47.404 > main : btContrl / free size = 6428 bytes
12:37:52.796 > main : btContrl / free size = 6548 bytes
12:37:58.186 > main : btContrl / free size = 6492 bytes
12:38:03.563 > main : btContrl / free size = 6484 bytes
12:38:08.924 > main : btContrl / free size = 6440 bytes
12:38:14.295 > main : btContrl / free size = 6564 bytes
12:38:19.680 > main : btContrl / free size = 6456 bytes
12:38:25.075 > main : btContrl / free size = 6484 bytes
12:38:30.454 > main : btContrl / free size = 6392 bytes
12:38:35.836 > main : btContrl / free size = 6552 bytes
12:38:41.216 > main : btContrl / free size = 6456 bytes
12:38:46.613 > main : btContrl / free size = 6368 bytes
12:38:46.736 > main : btContrl / free size = 6248 bytes  / new low !
12:38:51.996 > main : btContrl / free size = 6816 bytes
12:38:57.087 > main : btContrl / free size = 6220 bytes  / new low !
12:38:57.397 > main : btContrl / free size = 6484 bytes
12:39:02.779 > main : btContrl / free size = 6496 bytes
12:39:08.163 > main : btContrl / free size = 6472 bytes
12:39:13.553 > main : btContrl / free size = 6576 bytes
12:39:18.930 > main : btContrl / free size = 6500 bytes
12:39:23.691 > main : btContrl / free size = 6184 bytes  / new low !
12:39:24.322 > main : btContrl / free size = 6448 bytes
12:39:29.720 > main : btContrl / free size = 6360 bytes
12:39:35.104 > main : btContrl / free size = 6568 bytes
12:39:40.492 > main : btContrl / free size = 6504 bytes
12:39:51.246 > main : btContrl / free size = 6368 bytes
12:39:56.613 > main : btContrl / free size = 6532 bytes
12:40:02.012 > main : btContrl / free size = 6504 bytes
12:40:07.403 > main : btContrl / free size = 6424 bytes
12:40:12.808 > main : btContrl / free size = 6388 bytes
12:40:18.227 > main : btContrl / free size = 6540 bytes
12:40:23.645 > main : btContrl / free size = 6432 bytes
12:40:29.036 > main : btContrl / free size = 6324 bytes
12:40:34.440 > main : btContrl / free size = 6804 bytes
12:40:39.854 > main : btContrl / free size = 6464 bytes
12:40:45.259 > main : btContrl / free size = 6420 bytes
12:40:50.667 > main : btContrl / free size = 6392 bytes
12:40:56.073 > main : btContrl / free size = 6604 bytes
12:41:01.473 > main : btContrl / free size = 6496 bytes
12:41:06.877 > main : btContrl / free size = 6408 bytes
12:41:12.260 > main : btContrl / free size = 6416 bytes
12:41:17.645 > main : btContrl / free size = 6580 bytes
12:41:23.023 > main : btContrl / free size = 6456 bytes
12:41:28.400 > main : btContrl / free size = 6400 bytes
12:41:33.797 > main : btContrl / free size = 6392 bytes
12:41:39.176 > main : btContrl / free size = 6588 bytes
12:41:44.564 > main : btContrl / free size = 6448 bytes
12:41:49.973 > main : btContrl / free size = 6432 bytes
12:41:55.372 > main : btContrl / free size = 6396 bytes
12:42:00.774 > main : btContrl / free size = 6452 bytes
12:42:06.170 > main : btContrl / free size = 6444 bytes
12:42:11.539 > main : btContrl / free size = 6428 bytes
12:42:16.945 > main : btContrl / free size = 6788 bytes
12:42:22.327 > main : btContrl / free size = 6488 bytes
12:42:27.729 > main : btContrl / free size = 6440 bytes
12:42:33.104 > main : btContrl / free size = 6404 bytes
12:42:38.517 > main : btContrl / free size = 6532 bytes
12:42:43.892 > main : btContrl / free size = 6468 bytes
12:42:49.275 > main : btContrl / free size = 6400 bytes
12:42:54.656 > main : btContrl / free size = 6360 bytes
12:43:00.072 > main : btContrl / free size = 6560 bytes
12:43:05.448 > main : btContrl / free size = 6400 bytes
12:43:10.840 > main : btContrl / free size = 6412 bytes
12:43:16.243 > main : btContrl / free size = 6376 bytes
12:43:21.651 > main : btContrl / free size = 6516 bytes
12:43:27.057 > main : btContrl / free size = 6432 bytes
12:43:32.463 > main : btContrl / free size = 6412 bytes
12:43:37.879 > main : btContrl / free size = 6376 bytes
12:43:43.278 > main : btContrl / free size = 6536 bytes
12:43:48.690 > main : btContrl / free size = 6384 bytes
12:43:54.092 > main : btContrl / free size = 6360 bytes
12:43:59.507 > main : btContrl / free size = 6772 bytes
12:44:04.898 > main : btContrl / free size = 6444 bytes
12:44:10.300 > main : btContrl / free size = 6456 bytes
12:44:15.692 > main : btContrl / free size = 6436 bytes
12:44:21.081 > main : btContrl / free size = 6532 bytes
12:44:26.468 > main : btContrl / free size = 6460 bytes
12:44:31.849 > main : btContrl / free size = 6384 bytes
12:44:37.228 > main : btContrl / free size = 6400 bytes
12:44:42.616 > main : btContrl / free size = 6532 bytes
12:44:47.993 > main : btContrl / free size = 6448 bytes
12:44:53.399 > main : btContrl / free size = 6416 bytes
12:44:58.802 > main : btContrl / free size = 6416 bytes
12:45:04.212 > main : btContrl / free size = 6512 bytes
12:45:09.616 > main : btContrl / free size = 6468 bytes
12:45:15.009 > main : btContrl / free size = 6392 bytes
12:45:20.406 > main : btContrl / free size = 6372 bytes
12:45:25.804 > main : btContrl / free size = 6504 bytes
12:45:31.200 > main : btContrl / free size = 6372 bytes
12:45:36.583 > main : btContrl / free size = 6448 bytes
12:45:41.962 > main : btContrl / free size = 6588 bytes
12:45:47.351 > main : btContrl / free size = 6472 bytes
12:45:52.741 > main : btContrl / free size = 6424 bytes
12:45:58.108 > main : btContrl / free size = 6416 bytes
12:46:03.493 > main : btContrl / free size = 6540 bytes
12:46:08.874 > main : btContrl / free size = 6504 bytes
12:46:14.251 > main : btContrl / free size = 6448 bytes
12:46:19.643 > main : btContrl / free size = 6412 bytes
12:46:25.024 > main : btContrl / free size = 6560 bytes
12:46:30.415 > main : btContrl / free size = 6444 bytes
12:46:35.817 > main : btContrl / free size = 6452 bytes
12:46:41.218 > main : btContrl / free size = 6332 bytes
12:46:46.618 > main : btContrl / free size = 6512 bytes
12:46:52.006 > main : btContrl / free size = 6480 bytes
12:46:57.392 > main : btContrl / free size = 6356 bytes
12:47:02.767 > main : btContrl / free size = 6420 bytes
12:47:08.142 > main : btContrl / free size = 6480 bytes
12:47:13.528 > main : btContrl / free size = 6396 bytes
12:47:18.901 > main : btContrl / free size = 6440 bytes
12:47:24.276 > main : btContrl / free size = 6772 bytes
12:47:29.670 > main : btContrl / free size = 6472 bytes
12:47:35.050 > main : btContrl / free size = 6452 bytes
12:47:39.481 > main : btContrl / free size = 6180 bytes  / new low !
12:47:39.588 > main : btContrl / free size = 6156 bytes  / new low !
12:47:40.435 > main : btContrl / free size = 6328 bytes
12:47:45.850 > main : btContrl / free size = 6528 bytes
12:47:51.278 > main : btContrl / free size = 6496 bytes
12:47:56.673 > main : btContrl / free size = 6364 bytes
12:48:02.086 > main : btContrl / free size = 6408 bytes
12:48:07.482 > main : btContrl / free size = 6472 bytes
12:48:12.874 > main : btContrl / free size = 6332 bytes
12:48:14.296 > main : btContrl / free size = 6144 bytes  / new low !
12:48:18.285 > main : btContrl / free size = 6248 bytes
12:48:18.624 > main : btContrl / free size = 6136 bytes  / new low !
12:48:23.691 > main : btContrl / free size = 6344 bytes
12:48:29.097 > main : btContrl / free size = 6452 bytes
12:48:34.495 > main : btContrl / free size = 6320 bytes

FYI, I use the h2zero Nimble version : nimble=https://github.com/h2zero/NimBLE-Arduino.git@1.4.1+sha.e46123a

esp-zhp commented 4 months ago

1-When issues arise, are there many devices advertising around you (for example, more than 20 devices broadcasting simultaneously)? 2-is duplicate scan being utilized?

esp-zhp commented 4 months ago

Based on your description, is it possible for this issue to occur when performing notify and scan simultaneously? image

esp-zhp commented 4 months ago

1-I will provide more debugging methods to pinpoint the location of the memory leak (by supply you with a new controller library) This will involve logging the memory allocated and deallocated, and checking the malloc positions of any memory that hasn't been deallocated. 2-Additionally, I will locally reproduce the scenarios causing the issue. If you make any new discoveries, please let me know."

Koxx3 commented 4 months ago

duplicate

1/ with a BLE scanner, I detect ~25 devices after 1 min.

2/

CONFIG_BTDM_BLE_SCAN_DUPL=y
CONFIG_BTDM_SCAN_DUPL_TYPE_DEVICE=y
# CONFIG_BTDM_SCAN_DUPL_TYPE_DATA is not set
# CONFIG_BTDM_SCAN_DUPL_TYPE_DATA_DEVICE is not set
CONFIG_BTDM_SCAN_DUPL_TYPE=0
CONFIG_BTDM_SCAN_DUPL_CACHE_SIZE=100

1-When issues arise, are there many devices advertising around you (for example, more than 20 devices broadcasting simultaneously)? 2-is duplicate scan being utilized?

Koxx3 commented 4 months ago

Based on your description, is it possible for this issue to occur when performing notify and scan simultaneously? image

yes, I send notifications while it scans.

Koxx3 commented 4 months ago

1-I will provide more debugging methods to pinpoint the location of the memory leak (by supply you with a new controller library) This will involve logging the memory allocated and deallocated, and checking the malloc positions of any memory that hasn't been deallocated. 2-Additionally, I will locally reproduce the scenarios causing the issue. If you make any new discoveries, please let me know."

1/ ok, thanks a lot 2/ yes, I'll let it run during few hours to see how fast it decrease

question : can nimble version have any impact ? (even if the bt controller should be bullet proof...)

esp-zhp commented 4 months ago

The issue appears to be related to the controller at the moment, not the host.

Koxx3 commented 4 months ago

If it can help, I noticed when I have a "new low", it's often by 8 bytes : 

14:38:40.110 > main : btContrl / free size = 6564 bytes  / new low !
...
14:39:56.245 > main : btContrl / free size = 6556 bytes  / new low !
14:39:56.508 > main : btContrl / free size = 6548 bytes  / new low !
...
14:40:02.035 > main : btContrl / free size = 6540 bytes  / new low !
...
14:41:27.760 > main : btContrl / free size = 6528 bytes  / new low !
14:41:28.822 > main : btContrl / free size = 6520 bytes  / new low !
14:41:28.828 > main : btContrl / free size = 6512 bytes  / new low !
Koxx3 commented 4 months ago

another interesting thing. If I scan but do not send any notification, the free memory seems to remain stable.

test 6 : scan without any notification, using nimble whitelist (1 device registered in the whitelist), and still dummy scan processing callback. the remote BLE device is connected. 14:45-15:10 => stabilized at 6776 during 15 minutes

test 8 : scan, nimble whitelist (1 device registered), 1 device connected, 4 notifications with 1ms delay between notification sending 15:25-15:35 => no real change but sometimes, I have a very close group (in time) of memory leaks (look at 15:29:28.377)

FIY, I use one notification with a payload of 30 bytes (the MTU has been negociated greater than that). but it doesn't seems to have a real impact.

15:25:29.943 > main : btContrl / free size = 6788 bytes
15:25:30.320 > BLH : onWrite : beb5483e-36e1-4688-b7f5-ea07361b26a5
15:25:35.308 > main : btContrl / free size = 6792 bytes
15:25:40.700 > main : btContrl / free size = 6772 bytes
15:25:46.081 > main : btContrl / free size = 6772 bytes
15:25:51.441 > main : btContrl / free size = 6788 bytes
15:25:56.836 > main : btContrl / free size = 6800 bytes
15:26:02.216 > main : btContrl / free size = 6768 bytes
15:26:07.588 > main : btContrl / free size = 6752 bytes
15:26:12.974 > main : btContrl / free size = 6768 bytes
15:26:18.345 > main : btContrl / free size = 6752 bytes
15:26:23.741 > main : btContrl / free size = 6752 bytes
15:26:29.130 > main : btContrl / free size = 6764 bytes
15:26:33.991 > main : btContrl / free size = 6656 bytes  / new low !
15:26:34.512 > main : btContrl / free size = 6752 bytes
15:26:39.876 > main : btContrl / free size = 6768 bytes
15:26:46.124 > main : btContrl / free size = 6636 bytes  / new low !
15:26:50.702 > main : btContrl / free size = 6752 bytes
15:26:56.085 > main : btContrl / free size = 6764 bytes
15:27:01.471 > main : btContrl / free size = 6736 bytes
15:27:06.844 > main : btContrl / free size = 6740 bytes
15:27:12.215 > main : btContrl / free size = 6752 bytes
15:27:17.579 > main : btContrl / free size = 6752 bytes
15:27:22.965 > main : btContrl / free size = 6748 bytes
15:27:28.348 > main : btContrl / free size = 6736 bytes
15:27:33.729 > main : btContrl / free size = 6752 bytes
15:27:39.120 > main : btContrl / free size = 6752 bytes
15:27:44.475 > main : btContrl / free size = 6768 bytes
15:27:49.860 > main : btContrl / free size = 6932 bytes  / recover !!!
15:27:55.232 > main : btContrl / free size = 6752 bytes
15:28:00.602 > main : btContrl / free size = 6752 bytes
15:28:05.977 > main : btContrl / free size = 6736 bytes
15:28:11.357 > main : btContrl / free size = 6724 bytes
15:28:13.357 > main : btContrl / free size = 6616 bytes  / new low !
15:28:16.720 > main : btContrl / free size = 6732 bytes
15:28:22.111 > main : btContrl / free size = 6716 bytes
15:28:27.491 > main : btContrl / free size = 6716 bytes
15:28:32.878 > main : btContrl / free size = 6732 bytes
15:28:38.266 > main : btContrl / free size = 6732 bytes
15:28:43.641 > main : btContrl / free size = 6720 bytes
15:28:45.932 > main : btContrl / free size = 6604 bytes  / new low !
15:28:49.045 > main : btContrl / free size = 6708 bytes
15:28:54.447 > main : btContrl / free size = 6716 bytes
15:28:59.832 > main : btContrl / free size = 6708 bytes
15:29:03.302 > main : btContrl / free size = 6596 bytes  / new low !
15:29:05.219 > main : btContrl / free size = 6708 bytes
15:29:10.593 > main : btContrl / free size = 6708 bytes
15:29:15.977 > main : btContrl / free size = 6700 bytes
15:29:21.355 > main : btContrl / free size = 6712 bytes
15:29:26.740 > main : btContrl / free size = 6692 bytes
15:29:28.377 > main : btContrl / free size = 6588 bytes  / new low !
15:29:28.808 > main : btContrl / free size = 6580 bytes  / new low !
15:29:31.176 > main : btContrl / free size = 6556 bytes  / new low !
15:29:31.654 > main : btContrl / free size = 6552 bytes  / new low !
15:29:31.660 > main : btContrl / free size = 6540 bytes  / new low !
15:29:32.122 > main : btContrl / free size = 6832 bytes  / recover !!!
15:29:32.676 > main : btContrl / free size = 6524 bytes  / new low !
15:29:32.893 > main : btContrl / free size = 6516 bytes  / new low !
15:29:36.659 > main : btContrl / free size = 6500 bytes  / new low !
15:29:37.502 > main : btContrl / free size = 6604 bytes
15:29:42.882 > main : btContrl / free size = 6604 bytes
15:29:48.257 > main : btContrl / free size = 6588 bytes
15:29:52.862 > main : btContrl / free size = 6492 bytes  / new low !
15:29:53.658 > main : btContrl / free size = 6604 bytes
15:29:59.046 > main : btContrl / free size = 6604 bytes
15:30:04.417 > main : btContrl / free size = 6588 bytes
15:30:09.784 > main : btContrl / free size = 6616 bytes
15:30:15.162 > main : btContrl / free size = 6604 bytes
15:30:20.545 > main : btContrl / free size = 6604 bytes
15:30:25.920 > main : btContrl / free size = 6588 bytes
15:30:31.293 > main : btContrl / free size = 6600 bytes
15:30:36.674 > main : btContrl / free size = 6628 bytes
15:30:42.046 > main : btContrl / free size = 6588 bytes
15:30:47.443 > main : btContrl / free size = 6608 bytes
15:30:52.818 > main : btContrl / free size = 6612 bytes
15:30:58.190 > main : btContrl / free size = 6612 bytes
15:31:03.568 > main : btContrl / free size = 6588 bytes
15:31:08.944 > main : btContrl / free size = 6588 bytes
15:31:14.316 > main : btContrl / free size = 6792 bytes
15:31:19.676 > main : btContrl / free size = 6588 bytes
15:31:25.062 > main : btContrl / free size = 6600 bytes
15:31:30.442 > main : btContrl / free size = 6596 bytes
15:31:33.848 > main : btContrl / free size = 6484 bytes  / new low !
15:31:35.824 > main : btContrl / free size = 6572 bytes
15:31:41.194 > main : btContrl / free size = 6588 bytes
15:31:46.554 > main : btContrl / free size = 6588 bytes
15:31:50.817 > main : btContrl / free size = 6476 bytes  / new low !
15:31:51.935 > main : btContrl / free size = 6572 bytes
15:31:57.320 > main : btContrl / free size = 6588 bytes
15:31:58.793 > main : btContrl / free size = 6464 bytes  / new low !
15:32:02.710 > main : btContrl / free size = 6580 bytes
15:32:08.097 > main : btContrl / free size = 6580 bytes
15:32:13.481 > main : btContrl / free size = 6580 bytes
15:32:18.866 > main : btContrl / free size = 6592 bytes
15:32:24.236 > main : btContrl / free size = 6596 bytes
15:32:29.620 > main : btContrl / free size = 6552 bytes
15:32:30.444 > main : btContrl / free size = 6448 bytes  / new low !
15:32:34.992 > main : btContrl / free size = 6536 bytes
15:32:37.049 > main : btContrl / free size = 6440 bytes  / new low !
15:32:40.377 > main : btContrl / free size = 6552 bytes
15:32:45.749 > main : btContrl / free size = 6536 bytes
15:32:51.127 > main : btContrl / free size = 6536 bytes
15:32:56.497 > main : btContrl / free size = 6736 bytes
15:33:01.874 > main : btContrl / free size = 6556 bytes
15:33:07.257 > main : btContrl / free size = 6536 bytes
15:33:12.632 > main : btContrl / free size = 6536 bytes
15:33:18.013 > main : btContrl / free size = 6572 bytes
15:33:22.384 > main : btContrl / free size = 6424 bytes  / new low !
15:33:23.380 > main : btContrl / free size = 6512 bytes
15:33:23.829 > main : btContrl / free size = 6416 bytes  / new low !
15:33:28.754 > main : btContrl / free size = 6528 bytes
15:33:34.130 > main : btContrl / free size = 6512 bytes
15:33:39.516 > main : btContrl / free size = 6528 bytes
15:33:44.905 > main : btContrl / free size = 6528 bytes
15:33:50.277 > main : btContrl / free size = 6520 bytes
15:33:55.637 > main : btContrl / free size = 6512 bytes
15:34:01.013 > main : btContrl / free size = 6528 bytes
15:34:06.411 > main : btContrl / free size = 6512 bytes
15:34:11.800 > main : btContrl / free size = 6540 bytes
15:34:17.185 > main : btContrl / free size = 6516 bytes
15:34:22.573 > main : btContrl / free size = 6512 bytes
15:34:27.973 > main : btContrl / free size = 6528 bytes
15:34:33.354 > main : btContrl / free size = 6512 bytes
15:34:35.098 > main : btContrl / free size = 6404 bytes  / new low !
15:34:36.606 > main : btContrl / free size = 6384 bytes  / new low !
15:34:38.744 > main : btContrl / free size = 6692 bytes
15:34:44.123 > main : btContrl / free size = 6492 bytes
15:34:49.507 > main : btContrl / free size = 6492 bytes
15:34:49.740 > main : btContrl / free size = 6380 bytes  / new low !
15:34:54.869 > main : btContrl / free size = 6476 bytes
15:35:00.250 > main : btContrl / free size = 6504 bytes
15:35:05.640 > main : btContrl / free size = 6492 bytes
15:35:11.017 > main : btContrl / free size = 6492 bytes
15:35:16.390 > main : btContrl / free size = 6476 bytes
15:35:21.770 > main : btContrl / free size = 6492 bytes
15:35:27.161 > main : btContrl / free size = 6492 bytes
15:35:32.554 > main : btContrl / free size = 6480 bytes
15:35:37.938 > main : btContrl / free size = 6476 bytes
15:35:43.324 > main : btContrl / free size = 6492 bytes
15:35:48.709 > main : btContrl / free size = 6492 bytes
Koxx3 commented 4 months ago

I confrm the assert is due to memory issue : 

main : btContrl / free size = 400 bytes
main : btContrl / free size = 296 bytes  / new low !
main : btContrl / free size = 384 bytes
main : btContrl / free size = 384 bytes
main : btContrl / free size = 400 bytes
main : btContrl / free size = 384 bytes
main : btContrl / free size = 384 bytes
main : btContrl / free size = 384 bytes
main : btContrl / free size = 384 bytes
main : btContrl / free size = 384 bytes
main : btContrl / free size = 376 bytes
main : btContrl / free size = 288 bytes  / new low !
main : btContrl / free size = 560 bytes
main : btContrl / free size = 380 bytes
main : btContrl / free size = 380 bytes
main : btContrl / free size = 380 bytes
main : btContrl / free size = 380 bytes
main : btContrl / free size = 380 bytes
main : btContrl / free size = 380 bytes
main : btContrl / free size = 380 bytes
main : btContrl / free size = 380 bytes
main : btContrl / free size = 396 bytes
main : btContrl / free size = 380 bytes
main : btContrl / free size = 380 bytes
main : btContrl / free size = 380 bytes
main : btContrl / free size = 384 bytes
main : btContrl / free size = 380 bytes
main : btContrl / free size = 380 bytes
main : btContrl / free size = 380 bytes
main : btContrl / free size = 392 bytes
main : btContrl / free size = 380 bytes
main : btContrl / free size = 560 bytes
main : btContrl / free size = 380 bytes
main : btContrl / free size = 380 bytes
main : btContrl / free size = 280 bytes  / new low !
main : btContrl / free size = 264 bytes  / new low !
main : btContrl / free size = 376 bytes
ASSERT_PARAM(-218959118 0), in arch_main.c at line 364

Guru Meditation Error: Core  1 panic'ed (IllegalInstruction). Exception was unhandled.

Memory dump at 0x4009090c: f01d020c 00004136 f01d0000

Core  1 register dump:

PC      : 0x40090913  PS      : 0x00060b34  A0      : 0x8008655d  A1      : 0x3ffc4c64  

A2      : 0x00000000  A3      : 0xf2f2f2f2  A4      : 0x00000000  A5      : 0x3f434dce  

A6      : 0x0000016c  A7      : 0xfffffffc  A8      : 0x8000814b  A9      : 0x3ffc4bd4  

A10     : 0x00000000  A11     : 0x3ffc4bf7  A12     : 0x3ffc4ba3  A13     : 0x00000034  

A14     : 0x00000000  A15     : 0x3ffc4ba8  SAR     : 0x00000004  EXCCAUSE: 0x00000000  

EXCVADDR: 0x00000000  LBEG    : 0x40086465  LEND    : 0x4008646d  LCOUNT  : 0x00000000  

Backtrace: 0x40090910:0x3ffc4c64 |<-CORRUPTED
Koxx3 commented 4 months ago

I have build a "kinda minimal" app, but it still contains some sensitive code. How can I send you the code privatly ?

To reproduce the issue with "NRF connect" android app :

Another thing: the issue seems to occur more often is there is BLE trafic in the area (another phone exchanging with another device or a device establishing another connection).

esp-zhp commented 4 months ago

sent me by email: zhanghaipeng@espressif.com

esp-zhp commented 4 months ago

If you've created your program using a platform other than ESP-IDF, such as Arduino or PlatformIO, please explain the process required for building and flashing.

Koxx3 commented 4 months ago

at the same time, if you want to me test another lib, let me know.

esp-zhp commented 4 months ago

Where can I configure the path for the IDF and replace the controller lib? image

Koxx3 commented 4 months ago

ok ! almost good !

on windows : C:\Users\USERNAME\.platformio\packages\framework-espidf (replace USERNAME)

on Linux, I think it's the same /home/USERNAME/.platformio/packages/framework-espidf

I don't know if you can configure a custom path. I personally keep the official path.

Koxx3 commented 4 months ago

hello, any news ?

esp-zhp commented 4 months ago

Currently, I can build and flash your application onto the ESP32, but replacing the controller library doesn't seem to take effect. I will try to set up the environment on a Windows platform.

After flashing, I noticed that the ESP32 continuously sends notifications at a high frequency. Additionally, based on your description, the ESP32 is still scanning. I suspect the issue might be that the ESP32 is unable to send data quickly enough, causing the internal queues to grow and eventually leading to memory exhaustion. To verify this hypothesis, you can disconnect the connections before the memory is exhausted and then check if the memory has been freed.

esp-zhp commented 4 months ago

extern void ke_mem_dbg_dump(); eb32dbe.zip I have provided a new library for you to test. Please ensure that the BT controller compiles with version [eb32dbe].

In this new library, I have implemented tracking for memory allocation and release. However, since some of the code resides in ROM, I have temporarily omitted tracking the exact locations of memory allocations (I will add this functionality later using other methods).

Additionally, the new library tracks the usage of queues. Detailed information can be printed using ke_mem_dbg_dump.

P.S.: If the memory leak occurs at the same location each time, I have set up an internal pointer, void *ptr_rec. If the address of the allocated memory matches ptr_rec, an assert will be triggered, allowing you to determine the assert location via backtrace. However, since the memory allocation location might vary, this method might not always be effective.