search

espressif / esp-idf

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

ESP-IDF v4.3.7 - BLE Crashes after connection parameter update (IDFGH-12607) #13605

Open expresspotato opened 5 months ago

expresspotato commented 5 months ago

Answers checklist.

IDF version.

v4.3.7

Espressif SoC revision.

ESP32-Pico-V3-02

Operating System used.

macOS

How did you build your project?

Command line with idf.py

If you are using Windows, please specify command line type.

None

Development Kit.

LyraT

Power Supply used.

USB

What is the expected behavior?

Not crash

What is the actual behavior?

Crashes

Steps to reproduce.

  1. Build a co-ex project
  2. Connect via HFP, A2D, AVRC, BLE
  3. Change the connection parameters, relatively often (1-2 times per minute) as needed between an idle / active state
  4. Observe crash

Debug Logs.

Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x40015788  PS      : 0x00060d30  A0      : 0x80049eba  A1      : 0x3ffdc7c0  
A2      : 0x3ffdc7f0  A3      : 0x3ffdc808  A4      : 0x000000ff  A5      : 0x00000001  
A6      : 0x00000003  A7      : 0x00000001  A8      : 0x0014f00f  A9      : 0x00000000  
A10     : 0x000000a6  A11     : 0x000000a6  A12     : 0x00000000  A13     : 0x000000c0  
A14     : 0x3ffd9f04  A15     : 0x00000001  SAR     : 0x0000001d  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x0014f013  LBEG    : 0x4000c46c  LEND    : 0x4000c477  LCOUNT  : 0xffffffff  

Backtrace:0x40015785:0x3ffdc7c0 0x40049eb7:0x3ffdc7f0 0x40164cf6:0x3ffdc840 0x40042386:0x3ffdc870 0x40089766:0x3ffdc890 0x40019d11:0x3ffdc8c0 0x40055b4d:0x3ffdc8e0 0x4015b547:0x3ffdc900 0x4015bbca:0x3ffdc920
0x40164cf6: hci_le_rem_con_param_req_reply_cmd_handler at llc_hci.c:?

0x40089766: ke_task_schedule at ke_task.c:?

0x4015b547: r_rw_schedule at ??:?

0x4015bbca: btdm_controller_task at ??:?

ELF file SHA256: 7f571c4f7e7eff18

I (1469) esp_core_dump_flash: Save core dump to flash...
I (1475) esp_core_dump_flash: Erase flash 36864 bytes @ 0x7e0000
I (1701) esp_core_dump_flash: Write end offset 0x86a4, check sum length 4
I (1701) esp_core_dump_flash: Core dump has been saved to flash.

More Information.

Forum topic: https://esp32.com/viewtopic.php?f=28&t=37739

Edit: I've also noticed this issue without changing the connection params myself...

esp-zhp commented 5 months ago

@expresspotato thanks for reporting the bug,we will check it.

expresspotato commented 4 months ago

@expresspotato thanks for reporting the bug,we will check it.

Hi @zhp0406,

Were you able to determine the root cause and a fix for this issue?

esp-zhp commented 4 months ago

Version 4.3 is no longer under active maintenance, so I've utilized the latest master branch to replicate your issue. I've employed two examples (esp-idf/examples/bluetooth/bluedroid/coex/a2dp_gatts_coex and esp-idf/examples/bluetooth/bluedroid/ble/gatt_client).

In the gatt_client example, I irregularly initiate connection parameter updates. No alterations have been made to a2dp_gatts_coex. However, I haven't been able to reproduce the issue you described.

log in a2dp_gatts_coex:

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:7192
load:0x40078000,len:15564
ho 0 tail 12 room 4
load:0x40080400,len:4
load:0x40080404,len:3904
entry 0x40080640
I (31) boot: ESP-IDF v5.4-dev-120-g1b95af2096-dirty 2nd stage bootloader
I (31) boot: compile time Apr 29 2024 15:59:36
I (33) boot: Multicore bootloader
I (37) boot: chip revision: v3.1
I (41) boot.esp32: SPI Speed      : 40MHz
I (46) boot.esp32: SPI Mode       : DIO
I (50) boot.esp32: SPI Flash Size : 2MB
I (55) boot: Enabling RNG early entropy source...
I (60) boot: Partition Table:
I (64) boot: ## Label            Usage          Type ST Offset   Length
I (71) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (79) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (86) boot:  2 factory          factory app      00 00 00010000 00100000
I (94) boot: End of partition table
I (98) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=2f310h (193296) map
I (173) esp_image: segment 1: paddr=0003f338 vaddr=3ffbdb60 size=00ce0h (  3296) load
I (174) esp_image: segment 2: paddr=00040020 vaddr=400d0020 size=a9564h (693604) map
I (416) esp_image: segment 3: paddr=000e958c vaddr=3ffbe840 size=04274h ( 17012) load
I (423) esp_image: segment 4: paddr=000ed808 vaddr=40080000 size=1aa94h (109204) load
I (479) boot: Loaded app from partition at offset 0x10000
I (479) boot: Disabling RNG early entropy source...
I (491) cpu_start: Multicore app
I (500) cpu_start: Pro cpu start user code
I (500) cpu_start: cpu freq: 160000000 Hz
I (500) app_init: Application information:
I (503) app_init: Project name:     bt_ble_coex
I (508) app_init: App version:      v5.4-dev-120-g1b95af2096-dirty
I (515) app_init: Compile time:     Apr 29 2024 15:59:32
I (521) app_init: ELF file SHA256:  7c4f2dacf...
I (526) app_init: ESP-IDF:          v5.4-dev-120-g1b95af2096-dirty
I (533) efuse_init: Min chip rev:     v0.0
I (538) efuse_init: Max chip rev:     v3.99 
I (542) efuse_init: Chip rev:         v3.1
I (548) heap_init: Initializing. RAM available for dynamic allocation:
I (555) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (561) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (567) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (573) heap_init: At 3FFCC258 len 00013DA8 (79 KiB): DRAM
I (579) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (585) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (592) heap_init: At 4009AA94 len 0000556C (21 KiB): IRAM
I (600) spi_flash: detected chip: generic
I (603) spi_flash: flash io: dio
W (606) spi_flash: Detected size(4096k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (621) coexist: coex firmware version: 7fff68fa5
I (626) main_task: Started on CPU0
I (636) main_task: Calling app_main()
I (646) BTDM_INIT: BT controller compile version [4012cfb]
I (646) BTDM_INIT: Bluetooth MAC: 08:3a:8d:15:0b:5e
I (656) phy_init: phy_version 4791,2c4672b,Dec 20 2023,16:06:06
W (1346) BT_BTC: A2DP Enable with AVRC
I (1356) BT_AV: A2DP PROF STATE: Init Complete
I (1366) BT_BLE_COEX: event: 10
I (1366) BT_BLE_COEX: event: 10
I (1366) BT_BLE_COEX: event: 10
I (1366) BT_AV: Get delay report value: delay_value: 1200 * 1/10 ms
I (1376) BT_BLE_COEX: REGISTER_APP_EVT, status 0, app_id 0
I (1386) BT_AV: Set delay report value: success, delay_value: 1250 * 1/10 ms
I (1386) BT_BLE_COEX: CREATE_SERVICE_EVT, status 0,  service_handle 40
I (1396) main_task: Returned from app_main()
I (1406) BT_BLE_COEX: Start adv successfully
I (1406) BT_BLE_COEX: SERVICE_START_EVT, status 0, service_handle 40
I (1416) BT_BLE_COEX: ADD_CHAR_EVT, status 0,  attr_handle 42, service_handle 40
I (1416) BT_BLE_COEX: REGISTER_APP_EVT, status 0, app_id 1
I (1426) BT_BLE_COEX: ADD_DESCR_EVT, status 0, attr_handle 43, service_handle 40
I (1436) BT_BLE_COEX: CREATE_SERVICE_EVT, status 0,  service_handle 44
I (1446) BT_BLE_COEX: SERVICE_START_EVT, status 0, service_handle 44
I (1446) BT_BLE_COEX: ADD_CHAR_EVT, status 0,  attr_handle 46, service_handle 44
I (1456) BT_BLE_COEX: ADD_DESCR_EVT, status 0, attr_handle 47, service_handle 44
I (22366) BT_BLE_COEX: CONNECT_EVT, conn_id 0, remote 30:ae:a4:80:56:0e:
I (23156) BT_BLE_COEX: ESP_GATTS_MTU_EVT, MTU 500
I (23156) BT_BLE_COEX: ESP_GATTS_MTU_EVT, MTU 500
I (23246) BT_BLE_COEX: GATT_WRITE_EVT, conn_id 0, trans_id 2, handle 43
I (23246) BT_BLE_COEX: GATT_WRITE_EVT, value len 2, value :
I (23246) BT_BLE_COEX: 01 00 
I (23256) BT_BLE_COEX: notify enable
I (23256) BT_BLE_COEX: ESP_GATTS_CONF_EVT, status 0
I (23306) BT_BLE_COEX: GATT_WRITE_EVT, conn_id 0, trans_id 3, handle 42
I (23306) BT_BLE_COEX: GATT_WRITE_EVT, value len 35, value :
I (23306) BT_BLE_COEX: 00 01 02 03 04 05 06 07 08 09 0a 0b 0c 0d 0e 0f 
I (23316) BT_BLE_COEX: 10 11 12 13 14 15 16 17 18 19 1a 1b 1c 1d 1e 1f 
I (23326) BT_BLE_COEX: 20 21 22 
I (32096) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 32,latency = 0, timeout = 400
I (33326) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 33,latency = 0, timeout = 400
I (34276) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 34,latency = 0, timeout = 400
I (35346) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 35,latency = 0, timeout = 400
I (36446) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 36,latency = 0, timeout = 400
I (64226) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 37,latency = 0, timeout = 400
I (65246) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 38,latency = 0, timeout = 400
I (66256) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 39,latency = 0, timeout = 400
I (67336) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 40,latency = 0, timeout = 400
I (68246) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 41,latency = 0, timeout = 400
I (73376) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 42,latency = 0, timeout = 400
I (74376) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 43,latency = 0, timeout = 400
I (75406) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 44,latency = 0, timeout = 400
I (78486) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 45,latency = 0, timeout = 400
I (94586) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 46,latency = 0, timeout = 400
I (95516) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 47,latency = 0, timeout = 400
I (105156) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 48,latency = 0, timeout = 400
I (132046) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 49,latency = 0, timeout = 400
I (133216) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 50,latency = 0, timeout = 400
I (142476) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 51,latency = 0, timeout = 400
I (143436) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 52,latency = 0, timeout = 400
I (173476) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 53,latency = 0, timeout = 400
I (188856) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 54,latency = 0, timeout = 400
I (212896) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 55,latency = 0, timeout = 400
I (213926) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 56,latency = 0, timeout = 400
I (214916) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 57,latency = 0, timeout = 400
I (235446) BT_BLE_COEX: update connection params status = 0, min_int = 0, max_int = 0,conn_int = 58,latency = 0, timeout = 400
esp-zhp commented 4 months ago

Could you test with the latest version to see if the issue persists? If it still exists, could you provide an example that reproduces the problem?

expresspotato commented 4 months ago

Well there are other issues that are unresolved in 4.4.x, namely https://github.com/espressif/esp-idf/issues/11315, and a few others...

Our project is very large, so it's not easy to switch between 4.3.7 and 4.4.x (nor 5.x anything for that matter) without extensive testing. To my knowledge v.4.3.5 didn't have this issue.

I see in your test that A2DP, HFP and AVRC aren't connected yet. Can you try and connect those first?

esp-zhp commented 4 months ago

Do you mean this issue only occurs when A2DP, HFP, and AVRC are connected? I don't have A2DP, HFP, and AVRC connected here, only BLE connections. Can you test whether the issue can be reproduced with only BLE connections?

esp-zhp commented 4 months ago

If you have a demo that reproduces the issue , it would be helpful for me to resolve the problem.”

expresspotato commented 4 months ago

Do you mean this issue only occurs when A2DP, HFP, and AVRC are connected? I don't have A2DP, HFP, and AVRC connected here, only BLE connections. Can you test whether the issue can be reproduced with only BLE connections?

Upon further observation, the crash occurs during an indicate. The parameters are not yet changed, and an indicate is sent from the ESP32 (GATTS) -> to an Android phone (GATTC) during the update process.

One instance:

I (74413) LIBERTY: 8 Bit --> 4077935
I (74418) LIBERTY: Internal --> 82228
I (74423) LIBERTY: SPI RAM --> 3999095
I (74428) LIBERTY: Largest free block in Internal --> 69620
I (74433) LIBERTY: Largest free block in SPI RAM --> 3932148
W (74438) LIBERTY: --> Memory used (After POST connection tasks): 0 / 20
W (74448) LIBERTY: --> BLE connection params set: Idle
E (74453) LIBERTY: --> Finished, sending back item... is threaded (1)
E (74463) LIBERTY: --> Dispatch callback!
E (74468) LIBERTY: --> CBBP Command Response Sent (1)
Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x40015788  PS      : 0x00060830  A0      : 0x80049eba  A1      : 0x3ffdc720  
A2      : 0x3ffdc750  A3      : 0x3ffdc768  A4      : 0x000000ff  A5      : 0x00000001  
A6      : 0x00000003  A7      : 0x00000001  A8      : 0x0014f00f  A9      : 0x00000000  
A10     : 0x0000008f  A11     : 0x0000008f  A12     : 0x00000000  A13     : 0x000000c0  
A14     : 0x3ffd9e18  A15     : 0x00000001  SAR     : 0x0000001d  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x0014f013  LBEG    : 0x4000c46c  LEND    : 0x4000c477  LCOUNT  : 0xffffffff  

Backtrace:0x40015785:0x3ffdc720 0x40049eb7:0x3ffdc750 0x40162492:0x3ffdc7a0 0x40042386:0x3ffdc7d0 0x40087ece:0x3ffdc7f0 0x40019d11:0x3ffdc820 0x40055b4d:0x3ffdc840 0x40158ce7:0x3ffdc860 0x4015936a:0x3ffdc880
0x40162492: hci_le_rem_con_param_req_reply_cmd_handler at llc_hci.c:?

0x40087ece: ke_task_schedule at ke_task.c:?

0x40158ce7: r_rw_schedule at ??:?

0x4015936a: btdm_controller_task at ??:?

ELF file SHA256: 83803e802dc23644

I (2981) esp_core_dump_flash: Save core dump to flash...
I (2987) esp_core_dump_flash: Erase flash 28672 bytes @ 0x7e0000
I (3186) esp_core_dump_flash: Write end offset 0x6b44, check sum length 4
I (3186) esp_core_dump_flash: Core dump has been saved to flash.
Rebooting...
ets Jul 29 2019 12:21:46

rst:0xc (SW_CPU_RESET),boot:0x1f (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0030,len:7592
load:0x40078000,len:15860
load:0x40080400,len:4416
0x40080400: _init at ??:?

Another:

E (307599) LIBERTY: --> BLE request active
W (307599) LIBERTY: --> BLE connection params set: Active
E (307649) LIBERTY: --> CBBP Request over BT (87684 bytes)
Guru Meditation Error: Core  0 panic'ed (LoadProhibited). Exception was unhandled.

Core  0 register dump:
PC      : 0x40015788  PS      : 0x00060a30  A0      : 0x80049eba  A1      : 0x3ffdc720  
A2      : 0x3ffdc750  A3      : 0x3ffdc768  A4      : 0x000000ff  A5      : 0x00000001  
A6      : 0x00000003  A7      : 0x00000001  A8      : 0x0014f00f  A9      : 0x00000000  
A10     : 0x0000000f  A11     : 0x0000000f  A12     : 0x00000000  A13     : 0x00000018  
A14     : 0x3ffd9e18  A15     : 0x00000001  SAR     : 0x0000001d  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x0014f013  LBEG    : 0x4000c46c  LEND    : 0x4000c477  LCOUNT  : 0xffffffff  

Backtrace:0x40015785:0x3ffdc720 0x40049eb7:0x3ffdc750 0x40162492:0x3ffdc7a0 0x40042386:0x3ffdc7d0 0x40087ece:0x3ffdc7f0 0x40019d11:0x3ffdc820 0x40055b4d:0x3ffdc840 0x40158ce7:0x3ffdc860 0x4015936a:0x3ffdc880
0x40162492: hci_le_rem_con_param_req_reply_cmd_handler at llc_hci.c:?

0x40087ece: ke_task_schedule at ke_task.c:?

0x40158ce7: r_rw_schedule at ??:?

0x4015936a: btdm_controller_task at ??:?

ELF file SHA256: 83803e802dc23644

I (4085) esp_core_dump_flash: Save core dump to flash...
I (4091) esp_core_dump_flash: Erase flash 28672 bytes @ 0x7e0000
I (4284) esp_core_dump_flash: Write end offset 0x6ec4, check sum length 4
I (4284) esp_core_dump_flash: Core dump has been saved to flash.
Rebooting...
ets Jul 29 2019 12:21:46

rst:0xc (SW_CPU_RESET),boot:0x1f (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:1
load:0x3fff0030,len:7592
load:0x40078000,len:15860
load:0x40080400,len:4416
0x40080400: _init at ??:?

entry 0x400806a0