IllegalInstruction when connecting to Bluetooth (IDFGH-9159)

Answers checklist.

[X] I have read the documentation ESP-IDF Programming Guide and the issue is not addressed there.
[X] I have updated my IDF branch (master or release) to the latest version and checked that the issue is present there.
[X] I have searched the issue tracker for a similar issue and not found a similar issue.

IDF version.

v5.0-494-g490216a2ac

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?

Connect to Bluetooth reliably without crashing

What is the actual behavior?

Occasionally crashes with IllegalInstruction

btdm_sleep_check_duration seems to be involved, despite having disabled Bluetooth modem sleep in the config.

Steps to reproduce.

Select our fork of ESP-ADF which has commented out blufi (not working with the latest IDF) - https://github.com/radiosound-com/esp-adf - branch: idf-v5.0-494-g490216a2ac - export ADF_PATH=~/esp/esp-adf or wherever you installed it
cd ~/esp/esp-adf/examples/advanced_examples/wifi_bt_ble_coex
See attached sdkconfig.txt, save as sdkconfig in this folder
idf.py menuconfig
Put a valid SSID and password in example configuration
Build, flash, monitor (in this case I used ESP32-LyraT; issue also occurs on our custom boards with custom firmware)
In the phone's Bluetooth settings, connect and disconnect from ESP_ADF_COEX_EXAMPLE until the ESP32 crashes. (In the attached log, it took about 2.5 minutes. In some cases it happens more quickly)

sdkconfig.txt

Debug Logs.

[1277/1278] Generating binary image from built executableesptool.py v4.4
Creating esp32 image...
Merged 25 ELF sections
Successfully created esp32 image.
Generated /Users/dennis/esp/esp-adf/examples/advanced_examples/wifi_bt_ble_coex/build/wifi_bt_ble_coex.bin
[1278/1278] cd /Users/dennis/esp/esp-adf/examples/advanced_examples/wifi...f/examples/advanced_examples/wifi_bt_ble_coex/build/wifi_bt_ble_coex.binwifi_bt_ble_coex.bin binary size 0x1d5e60 bytes. Smallest app partition is 0x300000 bytes. 0x12a1a0 bytes (39%) free.
Executing action: flash
Serial port /dev/cu.wlan-debug
/dev/cu.wlan-debug failed to connect: Could not open /dev/cu.wlan-debug, the port doesn't exist
Serial port /dev/cu.usbserial-1120
Connecting....
Detecting chip type... Unsupported detection protocol, switching and trying again...
Connecting.........
Detecting chip type... ESP32
Running ninja in directory /Users/dennis/esp/esp-adf/examples/advanced_examples/wifi_bt_ble_coex/build
Executing "ninja flash"...
[1/5] cd /Users/dennis/esp/esp-adf/examples/advanced_examples/wifi_bt_ble_coex/build/esp-idf/esptool_py && /Users/dennis/.espressif/python_env/idf5.0_py3.9_env/bin/python /Users/dennis/esp/esp-adf/esp-idf/components/partition_table/check_sizes.py --offset 0x8000 partition --type app /Users/dennis/esp/esp-adf/examples/advanced_examples/wifi_bt_ble_coex/build/partition_table/partition-table.bin /Users/dennis/esp/esp-adf/examples/advanced_examples/wifi_bt_ble_coex/build/wifi_bt_ble_coex.bin
wifi_bt_ble_coex.bin binary size 0x1d5e60 bytes. Smallest app partition is 0x300000 bytes. 0x12a1a0 bytes (39%) free.
[2/5] Performing build step for 'bootloader'
[1/1] cd /Users/dennis/esp/esp-adf/examples/advanced_examples/wifi_bt_ble_coex/build/bootloader/esp-idf/esptool_py && /Users/dennis/.espressif/python_env/idf5.0_py3.9_env/bin/python /Users/dennis/esp/esp-adf/esp-idf/components/partition_table/check_sizes.py --offset 0x8000 bootloader 0x1000 /Users/dennis/esp/esp-adf/examples/advanced_examples/wifi_bt_ble_coex/build/bootloader/bootloader.bin
Bootloader binary size 0x6700 bytes. 0x900 bytes (8%) free.
[2/3] cd /Users/dennis/esp/esp-adf/esp-idf/components/esptool_py && /Users/dennis/.espressif/tools/cmake/3.24.0/CMake.app/Contents/bin/cmake -D IDF_PATH=/Users/dennis/esp/esp-adf/esp-idf -D "SERIAL_TOOL=/Users/dennis/.espressif/python_env/idf5.0_py3.9_env/bin/python;;/Users/dennis/esp/esp-adf/esp-idf/components/esptool_py/esptool/esptool.py;--chip;esp32" -D "SERIAL_TOOL_ARGS=--before=default_reset;--after=hard_reset;write_flash;@flash_args" -D WORKING_DIRECTORY=/Users/dennis/esp/esp-adf/examples/advanced_examples/wifi_bt_ble_coex/build -P /Users/dennis/esp/esp-adf/esp-idf/components/esptool_py/run_serial_tool.cmake
esptool esp32 -p /dev/cu.usbserial-1120 -b 2000000 --before=default_reset --after=hard_reset write_flash --flash_mode dio --flash_freq 80m --flash_size 4MB 0x1000 bootloader/bootloader.bin 0x10000 wifi_bt_ble_coex.bin 0x8000 partition_table/partition-table.bin
esptool.py v4.4
Serial port /dev/cu.usbserial-1120
Connecting..............
Chip is ESP32-D0WD (revision v1.0)
Features: WiFi, BT, Dual Core, 240MHz, VRef calibration in efuse, Coding Scheme None
Crystal is 40MHz
MAC: bc:dd:c2:d1:c8:68
Uploading stub...
Running stub...
Stub running...
Changing baud rate to 2000000
Changed.
Configuring flash size...
Flash will be erased from 0x00001000 to 0x00007fff...
Flash will be erased from 0x00010000 to 0x001e5fff...
Flash will be erased from 0x00008000 to 0x00008fff...
Compressed 26368 bytes to 16396...
Writing at 0x00001000... (50 %)
Writing at 0x000076fa... (100 %)
Wrote 26368 bytes (16396 compressed) at 0x00001000 in 0.5 seconds (effective 418.8 kbit/s)...
Hash of data verified.
Compressed 1924704 bytes to 1225461...
Writing at 0x00010000... (1 %)
Writing at 0x0001d3b8... (2 %)
Writing at 0x0002c928... (4 %)
Writing at 0x0003958e... (5 %)
Writing at 0x00042ae6... (6 %)
Writing at 0x0004e3fd... (8 %)
Writing at 0x00057757... (9 %)
Writing at 0x0005ce11... (10 %)
Writing at 0x000696b5... (12 %)
Writing at 0x0006f3d5... (13 %)
Writing at 0x00074fae... (14 %)
Writing at 0x0007a70c... (16 %)
Writing at 0x0008014c... (17 %)
Writing at 0x00085c83... (18 %)
Writing at 0x0008babf... (20 %)
Writing at 0x00091474... (21 %)
Writing at 0x0009717a... (22 %)
Writing at 0x0009cbec... (24 %)
Writing at 0x000a257c... (25 %)
Writing at 0x000a7b2f... (26 %)
Writing at 0x000ad3fc... (28 %)
Writing at 0x000b2eba... (29 %)
Writing at 0x000b9561... (30 %)
Writing at 0x000bed0c... (32 %)
Writing at 0x000c4811... (33 %)
Writing at 0x000ca2c2... (34 %)
Writing at 0x000d021c... (36 %)
Writing at 0x000d5df4... (37 %)
Writing at 0x000dbd79... (38 %)
Writing at 0x000e1083... (40 %)
Writing at 0x000e70c3... (41 %)
Writing at 0x000ec908... (42 %)
Writing at 0x000f258f... (44 %)
Writing at 0x000f7e4d... (45 %)
Writing at 0x000fda3a... (46 %)
Writing at 0x00103931... (48 %)
Writing at 0x001095d3... (49 %)
Writing at 0x0010f885... (50 %)
Writing at 0x0011544e... (52 %)
Writing at 0x0011b016... (53 %)
Writing at 0x001203aa... (54 %)
Writing at 0x00125e31... (56 %)
Writing at 0x0012c3e5... (57 %)
Writing at 0x00131ff2... (58 %)
Writing at 0x00137bf2... (60 %)
Writing at 0x0013d42c... (61 %)
Writing at 0x001429c7... (62 %)
Writing at 0x00148303... (64 %)
Writing at 0x0014d5f3... (65 %)
Writing at 0x001529d8... (66 %)
Writing at 0x00157cc7... (68 %)
Writing at 0x0015d35b... (69 %)
Writing at 0x00162978... (70 %)
Writing at 0x00168048... (72 %)
Writing at 0x0016dd42... (73 %)
Writing at 0x00172f56... (74 %)
Writing at 0x00178275... (76 %)
Writing at 0x0017d4a0... (77 %)
Writing at 0x0018289a... (78 %)
Writing at 0x00187ca5... (80 %)
Writing at 0x0018cef4... (81 %)
Writing at 0x00191f51... (82 %)
Writing at 0x00197769... (84 %)
Writing at 0x0019cb16... (85 %)
Writing at 0x001a23a0... (86 %)
Writing at 0x001a7f46... (88 %)
Writing at 0x001aeda9... (89 %)
Writing at 0x001b780c... (90 %)
Writing at 0x001bff95... (92 %)
Writing at 0x001c5d4c... (93 %)
Writing at 0x001caf87... (94 %)
Writing at 0x001d07ed... (96 %)
Writing at 0x001d63f9... (97 %)
Writing at 0x001dbcd5... (98 %)
Writing at 0x001e12fe... (100 %)
Wrote 1924704 bytes (1225461 compressed) at 0x00010000 in 15.4 seconds (effective 1003.0 kbit/s)...
Hash of data verified.
Compressed 3072 bytes to 104...
Writing at 0x00008000... (100 %)
Wrote 3072 bytes (104 compressed) at 0x00008000 in 0.1 seconds (effective 366.8 kbit/s)...
Hash of data verified.

Leaving...
Hard resetting via RTS pin...
Executing action: monitor
Serial port /dev/cu.wlan-debug
/dev/cu.wlan-debug failed to connect: Could not open /dev/cu.wlan-debug, the port doesn't exist
Serial port /dev/cu.usbserial-1120
Connecting....
Detecting chip type... Unsupported detection protocol, switching and trying again...
Connecting....
Detecting chip type... ESP32
Running idf_monitor in directory /Users/dennis/esp/esp-adf/examples/advanced_examples/wifi_bt_ble_coex
Executing "/Users/dennis/.espressif/python_env/idf5.0_py3.9_env/bin/python /Users/dennis/esp/esp-adf/esp-idf/tools/idf_monitor.py -p /dev/cu.usbserial-1120 -b 2000000 --toolchain-prefix xtensa-esp32-elf- --target esp32 --revision 1 /Users/dennis/esp/esp-adf/examples/advanced_examples/wifi_bt_ble_coex/build/wifi_bt_ble_coex.elf -m '/Users/dennis/.espressif/python_env/idf5.0_py3.9_env/bin/python' '/Users/dennis/esp/esp-adf/esp-idf/tools/idf.py'"...
--- idf_monitor on /dev/cu.usbserial-1120 2000000 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
I (29) boot: ESP-IDF v5.0-494-g490216a2ac 2nd stage bootloader
I (29) boot: compile time 14:37:19
I (29) boot: chip revision: v1.0
I (29) boot.esp32: SPI Speed      : 80MHz
I (29) boot.esp32: SPI Mode       : DIO
I (30) boot.esp32: SPI Flash Size : 4MB
I (30) boot: Enabling RNG early entropy source...
I (30) boot: Partition Table:
I (30) boot: ## Label            Usage          Type ST Offset   Length
I (31) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (31) boot:  1 phy_init         RF data          01 01 0000d000 00001000
I (32) boot:  2 factory          factory app      00 00 00010000 00300000
I (32) boot: End of partition table
I (32) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=542cch (344780) map
I (137) esp_image: segment 1: paddr=000642f4 vaddr=3ffbdb60 size=05788h ( 22408) load
I (145) esp_image: segment 2: paddr=00069a84 vaddr=40080000 size=06594h ( 26004) load
I (154) esp_image: segment 3: paddr=00070020 vaddr=400d0020 size=15d240h (1430080) map
I (585) esp_image: segment 4: paddr=001cd268 vaddr=40086594 size=18bd4h (101332) load
I (637) boot: Loaded app from partition at offset 0x10000
I (637) boot: Disabling RNG early entropy source...
I (638) quad_psram: This chip is ESP32-D0WD
I (638) esp_psram: Found 8MB PSRAM device
I (638) esp_psram: Speed: 80MHz
I (638) esp_psram: PSRAM initialized, cache is in low/high (2-core) mode.
W (638) esp_psram: Virtual address not enough for PSRAM, map as much as we can. 4MB is mapped
I (639) cpu_start: Pro cpu up.
I (639) cpu_start: Starting app cpu, entry point is 0x4008182c
0x4008182c: call_start_cpu1 at /Users/dennis/esp/esp-adf/esp-idf/components/esp_system/port/cpu_start.c:142

I (0) cpu_start: App cpu up.
I (1104) esp_psram: SPI SRAM memory test OK
I (1112) cpu_start: Pro cpu start user code
I (1112) cpu_start: cpu freq: 240000000 Hz
I (1113) cpu_start: Application information:
I (1113) cpu_start: Project name:     wifi_bt_ble_coex
I (1113) cpu_start: App version:      v2.3-193-gea3b09a-dirty
I (1113) cpu_start: Compile time:     Jan 16 2023 14:39:34
I (1114) cpu_start: ELF file SHA256:  edd385a32e9b55a0...
I (1114) cpu_start: ESP-IDF:          v5.0-494-g490216a2ac
I (1115) heap_init: Initializing. RAM available for dynamic allocation:
I (1115) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (1115) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (1116) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1116) heap_init: At 3FFC53A0 len 0001AC60 (107 KiB): DRAM
I (1116) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1117) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1117) heap_init: At 4009F168 len 00000E98 (3 KiB): IRAM
I (1400) esp_psram: Adding pool of 4082K of PSRAM memory to heap allocator
I (1402) spi_flash: detected chip: generic
I (1402) spi_flash: flash io: dio
W (1403) ADC: legacy driver is deprecated, please migrate to `esp_adc/adc_oneshot.h`
W (1403) i2s(legacy): legacy i2s driver is deprecated, please migrate to use driver/i2s_std.h, driver/i2s_pdm.h or driver/i2s_tdm.h
I (1404) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1446) COEX_EXAMPLE: [ 1 ] Create coex handle for a2dp-gatt-wifi
I (1446) COEX_EXAMPLE: [ 2 ] Initialize peripherals
I (1447) COEX_EXAMPLE: [ 3 ] create and start input key service
I (1448) COEX_EXAMPLE: [ 4 ] Start a2dp and blufi network
I (1448) COEX_EXAMPLE: [4.1] Init Bluetooth
W (1474) PERIPH_TOUCH: _touch_init
I (1983) COEX_EXAMPLE: [4.2] init gatts
I (1983) COEX_EXAMPLE: Blufi module init
E (1984) DISPATCHER: exe first list: 0x0
I (2007) COEX_EXAMPLE: [4.3] Create Bluetooth peripheral
I (2007) COEX_EXAMPLE: [4.4] Start peripherals
I (2042) COEX_EXAMPLE: [4.5] init hfp_stream
E (2066) gpio: gpio_install_isr_service(465): GPIO isr service already installed
W (2647) WIFI_SERV: WiFi Event cb, Unhandle event_base:WIFI_EVENT, event_id:4

----------------------------- ESP Audio Platform -----------------------------
|                                                                            |
|                 ESP_AUDIO-v1.7.0-31-g5b8f999-3072767-09be8fe               |
|                     Compile date: Oct 14 2021-11:00:34                     |
------------------------------------------------------------------------------
W (2713) BT_BTC: A2DP Enable with AVRC
I (2721) COEX_EXAMPLE: A2DP sink user cb
I (2721) COEX_EXAMPLE: User cb A2DP event: 4
W (2745) WIFI_SERV: STATE type:2, pdata:0x0, len:0
I (2796) COEX_EXAMPLE: WIFI_CONNECTED
I (2798) COEX_EXAMPLE: Func:setup_player, Line:298, MEM Total:4195604 Bytes, Inter:124304 Bytes, Dram:120968 Bytes

I (2798) COEX_EXAMPLE: esp_audio instance is:0x3f8197b4

I (2799) COEX_EXAMPLE: [ 5 ] Create audio pipeline for playback
I (2799) COEX_EXAMPLE: [5.1] Create i2s stream to read data from codec chip
E (2799) i2s(legacy): i2s_check_cfg_validity(920): this i2s port is in use
E (2800) i2s(legacy): i2s_driver_install(1575): I2S configuration is invalid
I (2801) COEX_EXAMPLE: [5.2] Create hfp stream
I (2801) COEX_EXAMPLE: [5.3] Register i2s reader and hfp outgoing to audio pipeline
I (2802) COEX_EXAMPLE: [5.4] Link it together [codec_chip]-->i2s_stream_reader-->filter-->hfp_out_stream-->[Bluetooth]
I (2803) COEX_EXAMPLE: [5.5] Start audio_pipeline out
W (41643) BT_HCI: hcif conn complete: hdl 0x80, st 0x0
W (41824) BT_HCI: hcif link supv_to changed: hdl 0x80, supv_to 8000
W (42733) BT_APPL: new conn_srvc id:27, app_id:1
W (43241) BT_APPL: bta_hf_client_send_at: No service, skipping 11 command
E (43274) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (43275) COEX_EXAMPLE: A2DP sink user cb
I (43438) COEX_EXAMPLE: A2DP sink user cb
I (43439) COEX_EXAMPLE: User cb A2DP event: 2
I (43439) COEX_EXAMPLE: A2DP sink user cb
I (43439) COEX_EXAMPLE: User cb A2DP event: 5
W (43537) BT_APPL: new conn_srvc id:19, app_id:0
I (43538) COEX_EXAMPLE: A2DP sink user cb
I (43538) COEX_EXAMPLE: A2DP connected
W (43776) A2DP_STREAM: AVRC ct remote features 25b
W (43777) A2DP_STREAM: AVRC tg remote features 25b, CT features 2
W (46744) BT_HCI: hci cmd send: sniff: hdl 0x80, intv(400 800)
W (46830) BT_HCI: hcif mode change: hdl 0x80, mode 2, intv 800, status 0x0
W (47534) WIFI_SERV: WiFi Event cb, Unhandle event_base:WIFI_EVENT, event_id:21
W (50820) BT_HCI: hcif mode change: hdl 0x80, mode 0, intv 0, status 0x0
W (50828) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:1 state 2 closed: Closed (res: 19)
W (50831) BT_HCI: hci cmd send: sniff: hdl 0x80, intv(400 800)
W (50840) BT_APPL: bta_dm_act no entry for connected service cbs
W (50843) BT_HCI: hcif mode change: hdl 0x80, mode 2, intv 800, status 0x0
I (50844) COEX_EXAMPLE: A2DP sink user cb
I (50844) COEX_EXAMPLE: A2DP disconnected
W (53820) BT_HCI: hcif mode change: hdl 0x80, mode 0, intv 0, status 0x0
W (53823) BT_RFCOMM: rfc_find_lcid_mcb LCID reused LCID:0x41 current:0x0
W (53825) BT_RFCOMM: RFCOMM_DisconnectInd LCID:0x41
W (54029) BT_HCI: hcif disc complete: hdl 0x80, rsn 0x13
W (55823) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
W (55835) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 8000
W (56276) BT_APPL: new conn_srvc id:27, app_id:1
W (56956) BT_APPL: bta_hf_client_send_at: No service, skipping 11 command
E (57142) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (57143) COEX_EXAMPLE: A2DP sink user cb
I (57289) COEX_EXAMPLE: A2DP sink user cb
I (57289) COEX_EXAMPLE: User cb A2DP event: 2
I (57290) COEX_EXAMPLE: A2DP sink user cb
I (57290) COEX_EXAMPLE: User cb A2DP event: 5
W (57376) BT_APPL: new conn_srvc id:19, app_id:0
I (57377) COEX_EXAMPLE: A2DP sink user cb
I (57377) COEX_EXAMPLE: A2DP connected
W (57514) A2DP_STREAM: AVRC ct remote features 25b
W (57515) A2DP_STREAM: AVRC tg remote features 25b, CT features 2
W (59705) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:1 state 2 closed: Closed (res: 19)
W (59710) BT_HCI: hci cmd send: sniff: hdl 0x81, intv(400 800)
W (59766) BT_APPL: bta_dm_act no entry for connected service cbs
W (59767) BT_HCI: hcif mode change: hdl 0x81, mode 2, intv 800, status 0x0
I (59767) COEX_EXAMPLE: A2DP sink user cb
I (59767) COEX_EXAMPLE: A2DP disconnected
W (60320) BT_HCI: hcif mode change: hdl 0x81, mode 0, intv 0, status 0x0
W (60322) BT_RFCOMM: rfc_find_lcid_mcb LCID reused LCID:0x41 current:0x0
W (60323) BT_RFCOMM: RFCOMM_DisconnectInd LCID:0x41
W (60398) BT_HCI: hcif disc complete: hdl 0x81, rsn 0x13
W (65691) BT_HCI: hcif conn complete: hdl 0x80, st 0x0
W (65779) BT_HCI: hcif link supv_to changed: hdl 0x80, supv_to 8000
W (66198) BT_APPL: new conn_srvc id:27, app_id:1
W (66545) BT_APPL: bta_hf_client_send_at: No service, skipping 11 command
E (66593) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (66594) COEX_EXAMPLE: A2DP sink user cb
I (66629) COEX_EXAMPLE: A2DP sink user cb
I (66629) COEX_EXAMPLE: User cb A2DP event: 2
I (66630) COEX_EXAMPLE: A2DP sink user cb
I (66630) COEX_EXAMPLE: User cb A2DP event: 5
W (66789) BT_APPL: new conn_srvc id:19, app_id:0
I (66790) COEX_EXAMPLE: A2DP sink user cb
I (66791) COEX_EXAMPLE: A2DP connected
W (66908) A2DP_STREAM: AVRC ct remote features 25b
W (66908) A2DP_STREAM: AVRC tg remote features 25b, CT features 2
W (68214) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:1 state 2 closed: Closed (res: 19)
W (68217) BT_HCI: hci cmd send: sniff: hdl 0x80, intv(400 800)
W (68227) BT_APPL: bta_dm_act no entry for connected service cbs
W (68230) BT_HCI: hcif mode change: hdl 0x80, mode 2, intv 800, status 0x0
I (68231) COEX_EXAMPLE: A2DP sink user cb
I (68231) COEX_EXAMPLE: A2DP disconnected
W (68231) AUDIO_EVT: There is no space in external queue
W (68821) BT_HCI: hci cmd send: unsniff: hdl 0x80
W (68822) BT_RFCOMM: rfc_find_lcid_mcb LCID reused LCID:0x41 current:0x0
W (68823) BT_RFCOMM: RFCOMM_DisconnectInd LCID:0x41
W (69323) BT_HCI: hcif mode change: hdl 0x80, mode 0, intv 0, status 0x0
W (69399) BT_HCI: hcif disc complete: hdl 0x80, rsn 0x13
W (71526) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
W (71619) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 8000
W (72001) BT_APPL: new conn_srvc id:27, app_id:1
W (72238) BT_APPL: bta_hf_client_send_at: No service, skipping 11 command
E (72309) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (72310) COEX_EXAMPLE: A2DP sink user cb
I (72342) COEX_EXAMPLE: A2DP sink user cb
I (72343) COEX_EXAMPLE: User cb A2DP event: 2
W (72343) AUDIO_EVT: There is no space in external queue
I (72343) COEX_EXAMPLE: A2DP sink user cb
I (72343) COEX_EXAMPLE: User cb A2DP event: 5
W (72422) BT_APPL: new conn_srvc id:19, app_id:0
I (72423) COEX_EXAMPLE: A2DP sink user cb
I (72423) COEX_EXAMPLE: A2DP connected
W (72503) A2DP_STREAM: AVRC ct remote features 25b
W (72503) A2DP_STREAM: AVRC tg remote features 25b, CT features 2
W (73780) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:1 state 2 closed: Closed (res: 19)
W (73783) BT_HCI: hci cmd send: sniff: hdl 0x81, intv(400 800)
W (73855) BT_APPL: bta_dm_act no entry for connected service cbs
W (73856) BT_HCI: hcif mode change: hdl 0x81, mode 2, intv 800, status 0x0
I (73857) COEX_EXAMPLE: A2DP sink user cb
I (73857) COEX_EXAMPLE: A2DP disconnected
W (73858) AUDIO_EVT: There is no space in external queue
W (75321) BT_HCI: hcif mode change: hdl 0x81, mode 0, intv 0, status 0x0
W (75323) BT_RFCOMM: rfc_find_lcid_mcb LCID reused LCID:0x41 current:0x0
W (75324) BT_RFCOMM: RFCOMM_DisconnectInd LCID:0x41
W (75459) BT_HCI: hcif disc complete: hdl 0x81, rsn 0x13
W (77425) BT_HCI: hcif conn complete: hdl 0x80, st 0x0
W (77444) BT_HCI: hcif link supv_to changed: hdl 0x80, supv_to 8000
W (77760) BT_APPL: new conn_srvc id:27, app_id:1
W (78157) BT_APPL: bta_hf_client_send_at: No service, skipping 11 command
E (78246) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (78247) COEX_EXAMPLE: A2DP sink user cb
I (78291) COEX_EXAMPLE: A2DP sink user cb
I (78292) COEX_EXAMPLE: User cb A2DP event: 2
W (78292) AUDIO_EVT: There is no space in external queue
I (78292) COEX_EXAMPLE: A2DP sink user cb
I (78292) COEX_EXAMPLE: User cb A2DP event: 5
W (78372) BT_APPL: new conn_srvc id:19, app_id:0
I (78373) COEX_EXAMPLE: A2DP sink user cb
I (78373) COEX_EXAMPLE: A2DP connected
W (78564) A2DP_STREAM: AVRC ct remote features 25b
W (78565) A2DP_STREAM: AVRC tg remote features 25b, CT features 2
W (80907) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:1 state 2 closed: Closed (res: 19)
W (80913) BT_HCI: hci cmd send: sniff: hdl 0x80, intv(400 800)
W (80920) BT_APPL: bta_dm_act no entry for connected service cbs
I (80921) COEX_EXAMPLE: A2DP sink user cb
I (80921) COEX_EXAMPLE: A2DP disconnected
W (80921) AUDIO_EVT: There is no space in external queue
W (80925) BT_HCI: hcif mode change: hdl 0x80, mode 2, intv 800, status 0x0
W (80928) BT_HCI: hci cmd send: unsniff: hdl 0x80
W (80929) BT_RFCOMM: rfc_find_lcid_mcb LCID reused LCID:0x41 current:0x0
W (80930) BT_RFCOMM: RFCOMM_DisconnectInd LCID:0x41
W (83820) BT_HCI: hcif mode change: hdl 0x80, mode 0, intv 0, status 0x0
W (83948) BT_HCI: hcif disc complete: hdl 0x80, rsn 0x13
W (88450) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
W (88512) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 8000
W (88887) BT_APPL: new conn_srvc id:27, app_id:1
W (89299) BT_APPL: bta_hf_client_send_at: No service, skipping 11 command
E (89320) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (89321) COEX_EXAMPLE: A2DP sink user cb
I (89348) COEX_EXAMPLE: A2DP sink user cb
I (89349) COEX_EXAMPLE: User cb A2DP event: 2
W (89349) AUDIO_EVT: There is no space in external queue
I (89349) COEX_EXAMPLE: A2DP sink user cb
I (89349) COEX_EXAMPLE: User cb A2DP event: 5
W (89427) BT_APPL: new conn_srvc id:19, app_id:0
I (89428) COEX_EXAMPLE: A2DP sink user cb
I (89428) COEX_EXAMPLE: A2DP connected
W (89562) A2DP_STREAM: AVRC ct remote features 25b
W (89563) A2DP_STREAM: AVRC tg remote features 25b, CT features 2
W (91399) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:1 state 2 closed: Closed (res: 19)
W (91403) BT_HCI: hci cmd send: sniff: hdl 0x81, intv(400 800)
W (91599) BT_APPL: bta_dm_act no entry for connected service cbs
W (91601) BT_HCI: hcif mode change: hdl 0x81, mode 2, intv 800, status 0x0
I (91602) COEX_EXAMPLE: A2DP sink user cb
I (91602) COEX_EXAMPLE: A2DP disconnected
W (91602) AUDIO_EVT: There is no space in external queue
W (92820) BT_HCI: hcif mode change: hdl 0x81, mode 0, intv 0, status 0x0
W (92822) BT_RFCOMM: rfc_find_lcid_mcb LCID reused LCID:0x41 current:0x0
W (92823) BT_RFCOMM: RFCOMM_DisconnectInd LCID:0x41
W (92990) BT_HCI: hcif disc complete: hdl 0x81, rsn 0x13
W (95603) BT_HCI: hcif conn complete: hdl 0x80, st 0x0
W (95667) BT_HCI: hcif link supv_to changed: hdl 0x80, supv_to 8000
W (95895) BT_APPL: new conn_srvc id:27, app_id:1
W (96303) BT_APPL: bta_hf_client_send_at: No service, skipping 11 command
E (96388) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (96389) COEX_EXAMPLE: A2DP sink user cb
I (96521) COEX_EXAMPLE: A2DP sink user cb
I (96522) COEX_EXAMPLE: User cb A2DP event: 2
W (96522) AUDIO_EVT: There is no space in external queue
I (96522) COEX_EXAMPLE: A2DP sink user cb
I (96522) COEX_EXAMPLE: User cb A2DP event: 5
W (96563) BT_APPL: new conn_srvc id:19, app_id:0
I (96564) COEX_EXAMPLE: A2DP sink user cb
I (96564) COEX_EXAMPLE: A2DP connected
W (96682) A2DP_STREAM: AVRC ct remote features 25b
W (96682) A2DP_STREAM: AVRC tg remote features 25b, CT features 2
W (98327) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:1 state 2 closed: Closed (res: 19)
W (98331) BT_HCI: hci cmd send: sniff: hdl 0x80, intv(400 800)
W (98359) BT_APPL: bta_dm_act no entry for connected service cbs
I (98360) COEX_EXAMPLE: A2DP sink user cb
I (98361) COEX_EXAMPLE: A2DP disconnected
W (98361) AUDIO_EVT: There is no space in external queue
W (100404) BT_HCI: hcif mode change: hdl 0x80, mode 2, intv 800, status 0x0
W (100405) BT_HCI: hcif mode change: hdl 0x80, mode 0, intv 0, status 0x0
W (100408) BT_RFCOMM: rfc_find_lcid_mcb LCID reused LCID:0x41 current:0x0
W (100411) BT_RFCOMM: RFCOMM_DisconnectInd LCID:0x41
W (100560) BT_HCI: hcif disc complete: hdl 0x80, rsn 0x13
W (104109) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
W (104168) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 8000
W (104475) BT_APPL: new conn_srvc id:27, app_id:1
W (104892) BT_APPL: bta_hf_client_send_at: No service, skipping 11 command
E (104911) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (104912) COEX_EXAMPLE: A2DP sink user cb
I (105005) COEX_EXAMPLE: A2DP sink user cb
I (105005) COEX_EXAMPLE: User cb A2DP event: 2
W (105005) AUDIO_EVT: There is no space in external queue
I (105005) COEX_EXAMPLE: A2DP sink user cb
I (105006) COEX_EXAMPLE: User cb A2DP event: 5
W (105082) BT_APPL: new conn_srvc id:19, app_id:0
I (105083) COEX_EXAMPLE: A2DP sink user cb
I (105083) COEX_EXAMPLE: A2DP connected
W (105214) A2DP_STREAM: AVRC ct remote features 25b
W (105215) A2DP_STREAM: AVRC tg remote features 25b, CT features 2
W (106943) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:1 state 2 closed: Closed (res: 19)
W (106946) BT_HCI: hci cmd send: sniff: hdl 0x81, intv(400 800)
W (107024) BT_APPL: bta_dm_act no entry for connected service cbs
W (107026) BT_HCI: hcif mode change: hdl 0x81, mode 2, intv 800, status 0x0
I (107027) COEX_EXAMPLE: A2DP sink user cb
I (107027) COEX_EXAMPLE: A2DP disconnected
W (107027) AUDIO_EVT: There is no space in external queue
W (109821) BT_HCI: hci cmd send: unsniff: hdl 0x81
W (109822) BT_RFCOMM: rfc_find_lcid_mcb LCID reused LCID:0x40 current:0x0
W (109823) BT_RFCOMM: RFCOMM_DisconnectInd LCID:0x40
W (110820) BT_HCI: hcif mode change: hdl 0x81, mode 0, intv 0, status 0x0
W (110970) BT_HCI: hcif disc complete: hdl 0x81, rsn 0x13
W (114027) BT_HCI: hcif conn complete: hdl 0x80, st 0x0
W (114080) BT_HCI: hcif link supv_to changed: hdl 0x80, supv_to 8000
W (114407) BT_APPL: new conn_srvc id:27, app_id:1
W (114747) BT_APPL: bta_hf_client_send_at: No service, skipping 11 command
E (114841) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (114842) COEX_EXAMPLE: A2DP sink user cb
I (114926) COEX_EXAMPLE: A2DP sink user cb
I (114926) COEX_EXAMPLE: User cb A2DP event: 2
W (114927) AUDIO_EVT: There is no space in external queue
I (114927) COEX_EXAMPLE: A2DP sink user cb
I (114927) COEX_EXAMPLE: User cb A2DP event: 5
W (114965) BT_APPL: new conn_srvc id:19, app_id:0
I (114966) COEX_EXAMPLE: A2DP sink user cb
I (114967) COEX_EXAMPLE: A2DP connected
W (115159) A2DP_STREAM: AVRC ct remote features 25b
W (115160) A2DP_STREAM: AVRC tg remote features 25b, CT features 2
W (116861) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:1 state 2 closed: Closed (res: 19)
W (116864) BT_HCI: hci cmd send: sniff: hdl 0x80, intv(400 800)
W (116901) BT_APPL: bta_dm_act no entry for connected service cbs
W (116904) BT_HCI: hci cmd send: unsniff: hdl 0x80
W (116904) BT_HCI: hcif mode change: hdl 0x80, mode 2, intv 800, status 0x0
I (116905) COEX_EXAMPLE: A2DP sink user cb
I (116905) COEX_EXAMPLE: A2DP disconnected
W (116905) AUDIO_EVT: There is no space in external queue
W (117873) BT_RFCOMM: rfc_find_lcid_mcb LCID reused LCID:0x40 current:0x0
W (117875) BT_RFCOMM: RFCOMM_DisconnectInd LCID:0x40
W (117876) BT_HCI: hcif mode change: hdl 0x80, mode 0, intv 0, status 0x0
W (117950) BT_HCI: hcif disc complete: hdl 0x80, rsn 0x13
W (119861) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
W (119881) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 8000
W (120290) BT_APPL: new conn_srvc id:27, app_id:1
W (120581) BT_APPL: bta_hf_client_send_at: No service, skipping 11 command
E (120655) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (120656) COEX_EXAMPLE: A2DP sink user cb
I (120727) COEX_EXAMPLE: A2DP sink user cb
I (120727) COEX_EXAMPLE: User cb A2DP event: 2
W (120728) AUDIO_EVT: There is no space in external queue
I (120728) COEX_EXAMPLE: A2DP sink user cb
I (120728) COEX_EXAMPLE: User cb A2DP event: 5
W (120772) BT_APPL: new conn_srvc id:19, app_id:0
I (120773) COEX_EXAMPLE: A2DP sink user cb
I (120773) COEX_EXAMPLE: A2DP connected
W (120892) A2DP_STREAM: AVRC ct remote features 25b
W (120893) A2DP_STREAM: AVRC tg remote features 25b, CT features 2
W (123972) BT_HCI: hci cmd send: sniff: hdl 0x81, intv(400 800)
W (124039) BT_HCI: hcif mode change: hdl 0x81, mode 2, intv 800, status 0x0
W (126320) BT_HCI: hcif mode change: hdl 0x81, mode 0, intv 0, status 0x0
W (126390) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:1 state 2 closed: Closed (res: 19)
W (126395) BT_HCI: hci cmd send: sniff: hdl 0x81, intv(400 800)
W (126402) BT_APPL: bta_dm_act no entry for connected service cbs
I (126403) COEX_EXAMPLE: A2DP sink user cb
I (126403) COEX_EXAMPLE: A2DP disconnected
W (126404) AUDIO_EVT: There is no space in external queue
W (126416) BT_HCI: hcif mode change: hdl 0x81, mode 2, intv 800, status 0x0
W (127319) BT_HCI: hcif mode change: hdl 0x81, mode 0, intv 0, status 0x0
W (127321) BT_RFCOMM: rfc_find_lcid_mcb LCID reused LCID:0x40 current:0x0
W (127323) BT_RFCOMM: RFCOMM_DisconnectInd LCID:0x40
W (127410) BT_HCI: hcif disc complete: hdl 0x81, rsn 0x13
W (131015) BT_HCI: hcif conn complete: hdl 0x80, st 0x0
W (131034) BT_HCI: hcif link supv_to changed: hdl 0x80, supv_to 8000
W (131419) BT_APPL: new conn_srvc id:27, app_id:1
W (131812) BT_APPL: bta_hf_client_send_at: No service, skipping 11 command
E (131840) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (131841) COEX_EXAMPLE: A2DP sink user cb
I (131933) COEX_EXAMPLE: A2DP sink user cb
I (131934) COEX_EXAMPLE: User cb A2DP event: 2
W (131934) AUDIO_EVT: There is no space in external queue
I (131934) COEX_EXAMPLE: A2DP sink user cb
I (131934) COEX_EXAMPLE: User cb A2DP event: 5
W (132052) BT_APPL: new conn_srvc id:19, app_id:0
I (132053) COEX_EXAMPLE: A2DP sink user cb
I (132053) COEX_EXAMPLE: A2DP connected
W (132218) A2DP_STREAM: AVRC ct remote features 25b
W (132219) A2DP_STREAM: AVRC tg remote features 25b, CT features 2
W (134472) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:1 state 2 closed: Closed (res: 19)
W (134477) BT_HCI: hci cmd send: sniff: hdl 0x80, intv(400 800)
W (134507) BT_APPL: bta_dm_act no entry for connected service cbs
W (134510) BT_HCI: hci cmd send: unsniff: hdl 0x80
W (134510) BT_HCI: hcif mode change: hdl 0x80, mode 2, intv 800, status 0x0
I (134511) COEX_EXAMPLE: A2DP sink user cb
I (134511) COEX_EXAMPLE: A2DP disconnected
W (134511) AUDIO_EVT: There is no space in external queue
W (135319) BT_HCI: hcif mode change: hdl 0x80, mode 0, intv 0, status 0x0
W (135321) BT_RFCOMM: rfc_find_lcid_mcb LCID reused LCID:0x40 current:0x0
W (135323) BT_RFCOMM: RFCOMM_DisconnectInd LCID:0x40
W (135470) BT_HCI: hcif disc complete: hdl 0x80, rsn 0x13
W (139511) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
W (139532) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 8000
W (139930) BT_APPL: new conn_srvc id:27, app_id:1
W (140322) BT_APPL: bta_hf_client_send_at: No service, skipping 11 command
E (140426) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (140427) COEX_EXAMPLE: A2DP sink user cb
I (140510) COEX_EXAMPLE: A2DP sink user cb
I (140511) COEX_EXAMPLE: User cb A2DP event: 2
W (140511) AUDIO_EVT: There is no space in external queue
I (140511) COEX_EXAMPLE: A2DP sink user cb
I (140511) COEX_EXAMPLE: User cb A2DP event: 5
W (140542) BT_APPL: new conn_srvc id:19, app_id:0
I (140543) COEX_EXAMPLE: A2DP sink user cb
I (140544) COEX_EXAMPLE: A2DP connected
W (140746) A2DP_STREAM: AVRC ct remote features 25b
W (140746) A2DP_STREAM: AVRC tg remote features 25b, CT features 2
W (142572) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:1 state 2 closed: Closed (res: 19)
W (142576) BT_HCI: hci cmd send: sniff: hdl 0x81, intv(400 800)
W (142605) BT_APPL: bta_dm_act no entry for connected service cbs
I (142607) COEX_EXAMPLE: A2DP sink user cb
I (142607) COEX_EXAMPLE: A2DP disconnected
W (142607) AUDIO_EVT: There is no space in external queue
W (142658) BT_HCI: hci cmd send: unsniff: hdl 0x81
W (142658) BT_HCI: hcif mode change: hdl 0x81, mode 2, intv 800, status 0x0
W (144319) BT_HCI: hcif mode change: hdl 0x81, mode 0, intv 0, status 0x0
W (144321) BT_RFCOMM: rfc_find_lcid_mcb LCID reused LCID:0x40 current:0x0
W (144323) BT_RFCOMM: RFCOMM_DisconnectInd LCID:0x40
W (144400) BT_HCI: hcif disc complete: hdl 0x81, rsn 0x13
W (145354) BT_HCI: hcif conn complete: hdl 0x80, st 0x0
W (145414) BT_HCI: hcif link supv_to changed: hdl 0x80, supv_to 8000
W (145677) BT_APPL: new conn_srvc id:27, app_id:1
W (145963) BT_APPL: bta_hf_client_send_at: No service, skipping 11 command
E (146069) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (146070) COEX_EXAMPLE: A2DP sink user cb
I (146160) COEX_EXAMPLE: A2DP sink user cb
I (146161) COEX_EXAMPLE: User cb A2DP event: 2
W (146161) AUDIO_EVT: There is no space in external queue
I (146161) COEX_EXAMPLE: A2DP sink user cb
I (146161) COEX_EXAMPLE: User cb A2DP event: 5
W (146193) BT_APPL: new conn_srvc id:19, app_id:0
I (146194) COEX_EXAMPLE: A2DP sink user cb
I (146194) COEX_EXAMPLE: A2DP connected
W (146389) A2DP_STREAM: AVRC ct remote features 25b
W (146389) A2DP_STREAM: AVRC tg remote features 25b, CT features 2
W (149404) BT_HCI: hci cmd send: sniff: hdl 0x80, intv(400 800)
W (149434) BT_HCI: hcif mode change: hdl 0x80, mode 2, intv 800, status 0x0
W (149824) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:1 state 2 closed: Closed (res: 19)
W (149826) BT_HCI: hci cmd send: unsniff: hdl 0x80
W (152323) BT_APPL: bta_dm_act no entry for connected service cbs
I (152323) COEX_EXAMPLE: A2DP sink user cb
I (152324) COEX_EXAMPLE: A2DP disconnected
W (152324) AUDIO_EVT: There is no space in external queue
W (153319) BT_HCI: hcif mode change: hdl 0x80, mode 0, intv 0, status 0x0
W (153409) BT_HCI: hcif disc complete: hdl 0x80, rsn 0x13
W (153842) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
W (153862) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 8000
W (154247) BT_APPL: new conn_srvc id:27, app_id:1
W (154555) BT_APPL: bta_hf_client_send_at: No service, skipping 11 command
E (154581) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (154582) COEX_EXAMPLE: A2DP sink user cb
I (154659) COEX_EXAMPLE: A2DP sink user cb
I (154660) COEX_EXAMPLE: User cb A2DP event: 2
W (154660) AUDIO_EVT: There is no space in external queue
I (154660) COEX_EXAMPLE: A2DP sink user cb
I (154660) COEX_EXAMPLE: User cb A2DP event: 5
W (154749) BT_APPL: new conn_srvc id:19, app_id:0
I (154750) COEX_EXAMPLE: A2DP sink user cb
I (154750) COEX_EXAMPLE: A2DP connected
W (154892) A2DP_STREAM: AVRC ct remote features 25b
W (154892) A2DP_STREAM: AVRC tg remote features 25b, CT features 2
W (157954) BT_HCI: hci cmd send: sniff: hdl 0x81, intv(400 800)
W (158009) BT_HCI: hcif mode change: hdl 0x81, mode 2, intv 800, status 0x0
ASSERT_ERR(0), in ld_fm.c at line 559
Guru Meditation Error: Core  1 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x400927bc: 00f01d00 00004136 f01d0000
0x400927bc: btdm_sleep_check_duration at /Users/dennis/esp/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:952

Core  1 register dump:
PC      : 0x400927c3  PS      : 0x00060034  A0      : 0x80085aad  A1      : 0x3ffc2028  
0x400927c3: r_assert at /Users/dennis/esp/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:1863

A2      : 0x3f429a54  A3      : 0x00000000  A4      : 0x00000000  A5      : 0x3f42a19c  
A6      : 0x0000022f  A7      : 0xfffffffc  A8      : 0x8000814b  A9      : 0x3ffc1f98  
A10     : 0x00000000  A11     : 0x3ffc1fbb  A12     : 0x3ffc1f67  A13     : 0x00000039  
A14     : 0x00000000  A15     : 0x3ffc1f6c  SAR     : 0x00000004  EXCCAUSE: 0x00000000  
EXCVADDR: 0x00000000  LBEG    : 0x40085a21  LEND    : 0x40085a29  LCOUNT  : 0x00000000  
0x40085a21: r_assert_err at ??:?

0x40085a29: r_assert_err at ??:?

Backtrace: 0x400927c0:0x3ffc2028 |<-CORRUPTED
0x400927c0: r_assert at /Users/dennis/esp/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:1862

ELF file SHA256: edd385a32e9b55a0

CPU halted.

More Information.

No response

Here is another log from another crash (this time built on Linux)

ASSERT_PARAM(131072 0), in rwbt.c at line 381
Guru Meditation Error: Core  0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x40092500: f01d092d 00004136 f01d0000
0x40092500: btdm_sleep_check_duration at /home/build/esp/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:951

Core  0 register dump:
PC      : 0x40092507  PS      : 0x00060834  A0      : 0x80085a29  A1      : 0x3ffc20e0  
0x40092507: r_assert at /home/build/esp/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:1869

A2      : 0x00000000  A3      : 0x00020000  A4      : 0x00000000  A5      : 0x3f42406c  
A6      : 0x0000017d  A7      : 0xfffffffc  A8      : 0x8000814b  A9      : 0x3ffc2050  
A10     : 0x00000000  A11     : 0x3ffc2073  A12     : 0x3ffc201f  A13     : 0x00000031  
A14     : 0x00000000  A15     : 0x3ffc2024  SAR     : 0x00000004  EXCCAUSE: 0x00000000  
EXCVADDR: 0x00000000  LBEG    : 0x40085931  LEND    : 0x40085939  LCOUNT  : 0x00000000  
0x40085931: r_assert_param at ??:?

0x40085939: r_assert_param at ??:?

Backtrace: 0x40092504:0x3ffc20e0 0x40085a26:0x3ffc2100 0x4008be85:0x3ffc2120 0x4008c3eb:0x3ffc2140 0x40084511:0x3ffc2160 0x40084351:0x3ffc2180 0x40084333:0x00000000 |<-CORRUPTED
0x40092504: r_assert at /home/build/esp/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:1868

0x40085a26: r_assert_param at ??:?

0x4008be85: r_rwbt_isr at ??:?

0x4008c3eb: r_rwbtdm_isr_wrapper at intc.c:?

0x40084511: hli_c_handler at /home/build/esp/esp-adf/esp-idf/components/bt/controller/esp32/hli_api.c:92

0x40084351: _highint4_stack_switch at /home/build/esp/esp-adf/esp-idf/components/bt/controller/esp32/hli_vectors.S:177

0x40084333: xt_highint4 at /home/build/esp/esp-adf/esp-idf/components/bt/controller/esp32/hli_vectors.S:161

ELF file SHA256: f1a0aff6678ee7ba

Rebooting...

Hi @ftab ,

Sorry, I didn't reproduce the issue. Please use the attached library(replace $IDF_PATH/components/bt/controller/lib_esp32/esp32/libbtdm_app.a) to reproduce the problem.

Thanks libbtdm_app.a.txt

I didn't see any new kinds of logs with this version of the library. Do I need to enable verbose logging?

It did take me some time to reproduce this time. Not sure if that's because of the updated library or just my luck.

Using a Galaxy A13 (SM-A135U1/DS).

W (3768917) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
W (3769578) BT_APPL: new conn_srvc id:27, app_id:1
W (3769580) BT_HCI: hci cmd send: sniff: hdl 0x81, intv(30 54)
I (3769583) HFP_STREAM: APP HFP event: CONNECTION_STATE_EVT
I (3769584) HFP_STREAM: --Connection state connected, peer feats 0x0, chld_feats 0x0
W (3769587) BT_HCI: hcif mode change: hdl 0x81, mode 2, intv 54, status 0x0
W (3769888) BT_HCI: hci cmd send: unsniff: hdl 0x81
W (3769973) BT_HCI: hcif mode change: hdl 0x81, mode 0, intv 0, status 0x0
I (3770105) HFP_STREAM: APP HFP event: CALL_IND_EVT
I (3770106) HFP_STREAM: --Call indicator NO call in progress
I (3770106) HFP_STREAM: APP HFP event: CALL_SEP_ND_EVT[0m
I (3770106) HFP_STREAM: --Call setup idicator NONE
I (3770107) HFP_STREAM: AP HFP vent: ETWRK_STATE_EVT
I (3770107) HFP_STREAM: --NETWORK state unaailable
I (3770107) HFP_STREAM: APP HFP event: SIGNAL_STRENGTH_IND_EVT
I (3770111) HFP_STREAM: --Signal strength: 0
I (3770111) HFP_STREAM: APP HFP event: ROAMING_STATUS_IND_EVT
I (3770111) HFP_STREAM: --ROAMING: inactive
I (3770111) HFP_STREAM: APP HFP event: BATTERY_LEVEL_IND_EVT
I (3770112) HFP_STREAM: --Battery level 4
I (3770112) HFP_STREAM: APP HFP event: CALL_HELD_IND_EVT
I (3770112) HFP_STREAM: --Call held indicator NONE held
I (3770385) HFP_STREAM: APP HFP event: CONNECTION_STATE_EVT
I (3770385) HFP_STREAM: --Connection state slc_connected, peer feats 0xfef, chld_feats 0x3f
I (3770385) HFP_STREAM: APP HFP event: INBAND_RING_TONE_EVT
I (3770386) HFP_STREAM: --Inband ring state Provided
W (3770508) BT_APPL: bta_hf_client_send_at: No service, skipping 11 command
E (3770594) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (3770595) COEX_EXAMPLE: A2DP sink user cb
I (3770595) COEX_EXAMPLE: A2DP connecting
I (3770595) A2DP_STREAM: A2DP bd address:, [9c:25:95:5c:66:4e]
W (3770623) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:1 state 2 closed: Peer connection failed (res: 16)
W (3770627) BT_HCI: hci cmd send: sniff: hdl 0x81, intv(30 54)
I (3770630) HFP_STREAM: APP HFP event: CONNECTION_STATE_EVT
I (3770630) HFP_STREAM: --Connection state disconnected, peer feats 0x0, chld_feats 0x0
W (3770694) BT_HCI: hcif mode change: hdl 0x81, mode 2, intv 54, status 0x0
W (3770697) BT_HCI: hci cmd send: unsniff: hdl 0x81
W (3770698) BT_RFCOMM: rfc_find_lcid_mcb LCID reused LCID:0x40 current:0x0
W (3770699) BT_RFCOMM: RFCOMM_DisconnectInd LCID:0x40
I (3770730) COEX_EXAMPLE: A2DP sink user cb
I (3770730) COEX_EXAMPLE: User cb A2DP event: 2
I (3770730) A2DP_STREAM: A2DP audio stream configuration, codec type 0
I (3770731) A2DP_STREAM: Bluetooth configured, sample rate=44100
D (3770731) AUDIO_ELEMENT: REPORT_INFO,[IN_aadp]evt out cmd:9,
W (3770731) AUDIO_EVT: Thereis no spae in external queue
I (3770732) COEX_EXAMPLE A2DP sik user cb
I (3770732) COEXEXAMPLE: Usercb A2D event: 5
I (3770732) A2DP_STREAM: Unhandled A2DP event: 5
W (3770748) BT_HCI: hcif mode change: hdl 0x81, mode 0, intv 0, status 0x0
ASSERT_PARAM(131072 0), in rwbt.c at line 381
Guru Meditation Error: Core  1 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x40092558: 00f01d00 00004136 f01d0000
0x40092558: btdm_sleep_check_duration at /Users/dennis/esp/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:951

Core  1 register dump:
PC      : 0x4009255f  PS      : 0x00060234  A0      : 0x80085dc5  A1      : 0x3ffc2000  
0x4009255f: r_assert at /Users/dennis/esp/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:1869

A2      : 0x00000000  A3      : 0x00020000  A4      : 0x00000000  A5      : 0x3f442638  
A6      : 0x0000017d  A7      : 0xfffffffc  A8      : 0x8000814b  A9      : 0x3ffc1f70  
A10     : 0x00000000  A11     : 0x3ffc1f93  A12     : 0x3ffc1f3f  A13     : 0x00000031  
A14     : 0x00000000  A15     : 0x3ffc1f44  SAR     : 0x00000004  EXCCAUSE: 0x00000000  
EXCVADDR: 0x00000000  LBEG    : 0x40085ccd  LEND    : 0x40085cd5  LCOUNT  : 0x00000000  
0x40085ccd: r_assert_param at ??:?

0x40085cd5: r_assert_param at ??:?

Backtrace: 0x4009255c:0x3ffc2000 0x40085dc2:0x3ffc2020 0x4008c211:0x3ffc2040 0x4008c777:0x3ffc2060 0x40084796:0x3ffc2080 0x400845d1:0x3ffc20a0 0x400845b3:0x00000000 |<-CORRUPTED
0x4009255c: r_assert at /Users/dennis/esp/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:1868

0x40085dc2: r_assert_param at ??:?

0x4008c211: r_rwbt_isr at ??:?

0x4008c777: r_rwbtdm_isr_wrapper at intc.c:?

0x40084796: hli_c_handler at /Users/dennis/esp/esp-adf/esp-idf/components/bt/controller/esp32/hli_api.c:92

0x400845d1: _highint4_stack_switch at /Users/dennis/esp/esp-adf/esp-idf/components/bt/controller/esp32/hli_vectors.S:177

0x400845b3: xt_highint4 at /Users/dennis/esp/esp-adf/esp-idf/components/bt/controller/esp32/hli_vectors.S:161

ELF file SHA256: 9e0a528ab9cf11d7

CPU halted.

Additionally, I observed this crash while I was not connected. Possibly unrelated.

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

Core  1 register dump:
PC      : 0x40015788  PS      : 0x00060930  A0      : 0x8017d93d  A1      : 0x3ffcf320  
A2      : 0x3ffcf350  A3      : 0x3ffcf368  A4      : 0x000000ff  A5      : 0x00000001  
A6      : 0x00000003  A7      : 0x00000001  A8      : 0x00148338  A9      : 0x3ff98cc4  
A10     : 0x00000000  A11     : 0x00000000  A12     : 0x3ffcddb0  A13     : 0x00000048  
A14     : 0x3ffcc5b0  A15     : 0x3ffb8360  SAR     : 0x00000016  EXCCAUSE: 0x0000001c  
EXCVADDR: 0x0014833c  LBEG    : 0x4000c46c  LEND    : 0x4000c477  LCOUNT  : 0x00000000  

Backtrace: 0x40015785:0x3ffcf320 0x4017d93a:0x3ffcf350 0x401803b3:0x3ffcf3c0 0x401835e1:0x3ffcf3f0 0x40183c3a:0x3ffcf450 0x40180cc3:0x3ffcf4a0 0x4017dee2:0x3ffcf4f0 0x40019d11:0x3ffcf530 0x40055b4d:0x3ffcf550 0x4017404f:0x3ffcf570 0x401746c1:0x3ffcf590
0x4017d93a: r_lld_evt_move_to_slave at ??:?

0x401803b3: r_lld_move_to_slave_hack at ??:?

0x401835e1: r_llm_con_req_ind at ??:?

0x40183c3a: r_llm_pdu_defer at ??:?

0x40180cc3: r_lld_pdu_check at ??:?

0x4017dee2: r_lld_evt_deffered_elt_handler at ??:?

0x4017404f: r_rw_schedule at ??:?

0x401746c1: btdm_controller_task at ??:?

ELF file SHA256: 9e0a528ab9cf11d7

CPU halted.

Hi @ftab ,

Since the log is incomplete, I can't be sure whether you are using the library I provided. I have added some logs to this version.

I (9663) COEX_EXAMPLE: User cb A2DP event: 2
I (9663) COEX_EXAMPLE: A2DP sink user cb
I (9664) COEX_EXAMPLE: User cb A2DP event: 5
W (9691) BT_APPL: new conn_srvc id:19, app_id:0
I (9692) COEX_EXAMPLE: A2DP sink user cb
I (9692) COEX_EXAMPLE: A2DP connected
SniffAttempt = 4
SniffTimeout = 1
W (12896) BT_HCI: hci cmd send: sniff: hdl 0x80, intv(400 800)
lc_env_ptr->sniff.SniffAttempt = 4
W (12900) BT_HCI: hcif mode change: hdl 0x80, mode 2, intv 800, status 0x0

lib_d9a1785.zip

Thanks

Sorry about that. My terminal had lost its scrollback buffer due to the length of the log. I've increased my scrollback buffer size and captured the full log this time.

2023-02-03-esp-idf-gh-issue-10555-crash-log.txt

Here is a crash log with all Bluetooth logs set to verbose

2023-02-03-esp-idf-gh-issue-10555-crash-log-verbose.txt

Hi @ftab ,

I added some logs to this library, please help reproduce the problem. BTW, can all mobile phones reproduce the problem?

Thanks

libbtdm_4967a98.zip

Here's the latest log

2023-02-06-esp-idf-gh-issue-10555-btdm-4967a98-crash-log-verbose.txt.zip

The issue has occurred on at least 2 out of the 3 phones I've tried so far: Galaxy A13 LTE (SM-A135U1), iPhone 11 Pro Max. The third phone I've been trying, Google Pixel 4a 5g, I may've just not tried for long enough yet.

It has even happened while idle (connected but not doing anything). (This was captured with an older version of the library. I am trying to capture it again with the latest version)

2023-02-03-esp-idf-gh-issue-10555-btdm-d9a1785-idle-crash.txt

Hi @ftab ,

Please verify that this library can solve the problem.

Thanks libbtdm_0e3d793.zip

Unfortunately it still crashes. This time it looked a little weird, disconnecting from the device and then spitting out some cryptic FEX statements.. The phone was attempting to connect to it but failed, and then the esp32 crashed

2023-02-07-esp-idf-gh-issue-10555-btdm-0e3d793-crash.txt

edit: an additional log, this one captured with an iPhone 6 plus

2023-02-07-esp-idf-gh-issue-10555-btdm-0e3d793-iphone-crash.txt

Hi @ftab ,

Sorry, I still can't reproduce the problem. Do you have other modifications locally?

Please help to verify whether this library can solve the problem. libbtdm_75939d3.zip

Thanks

These are my only diffs:

build@build-ThinkPad-W530:~/esp/esp-adf/examples/advanced_examples/wifi_bt_ble_coex$ git diff
diff --git a/esp-idf b/esp-idf
--- a/esp-idf
+++ b/esp-idf
@@ -1 +1 @@
-Subproject commit 490216a2ace6dc3e1b9a3f50d265a80481b32f6d
+Subproject commit 490216a2ace6dc3e1b9a3f50d265a80481b32f6d-dirty
diff --git a/examples/advanced_examples/wifi_bt_ble_coex/main/wifi_bt_ble_coex_example.c b/examples/advanced_examples/wifi_bt_ble_coex/main/wifi_bt_ble_coex_example.c
index dfe446f..2d407c7 100644
--- a/examples/advanced_examples/wifi_bt_ble_coex/main/wifi_bt_ble_coex_example.c
+++ b/examples/advanced_examples/wifi_bt_ble_coex/main/wifi_bt_ble_coex_example.c
@@ -354,8 +354,8 @@ void app_main(void)
     tcpip_adapter_init();
 #endif

-    esp_log_level_set("*", ESP_LOG_WARN);
-    esp_log_level_set(TAG, ESP_LOG_DEBUG);
+    //esp_log_level_set("*", ESP_LOG_WARN);
+    //esp_log_level_set(TAG, ESP_LOG_DEBUG);

     ESP_LOGI(TAG, "[ 1 ] Create coex handle for a2dp-gatt-wifi");
     g_coex_handle = (coex_handle_t *)audio_malloc(sizeof(coex_handle_t));
build@build-ThinkPad-W530:~/esp/esp-adf/examples/advanced_examples/wifi_bt_ble_coex$ cd ~/esp/esp-adf/esp-idf
build@build-ThinkPad-W530:~/esp/esp-adf/esp-idf$ git diff
diff --git a/components/bt/controller/lib_esp32 b/components/bt/controller/lib_esp32
--- a/components/bt/controller/lib_esp32
+++ b/components/bt/controller/lib_esp32
@@ -1 +1 @@
-Subproject commit d4a224c5d682d6b5a76542c6918b6a59dd0b2f8c
+Subproject commit d4a224c5d682d6b5a76542c6918b6a59dd0b2f8c-dirty

I can't imagine that would cause it, though.

Here is the crash with the latest library:

2023-02-08-esp-idf-gh-issue-10555-btdm-75939d3-crash.txt

(Scroll to line 10,000 - my terminal buffer was cut short on this machine so I included the startup logs from the next reboot)

2023-02-08-esp-idf-gh-issue-10555-btdm-75939d3-iphone-crash.txt

Interesting. This crash seems different.

I wish I could take a look at the code so I could help better. My "shot in the dark" theory is it has something to do with the WiFi coexistence code, because it seems to be exclusively when connected to WiFi, or at least, I haven't tried for long enough to reproduce without being connected to WiFi.

Sometimes it took quite a while, half an hour or an hour of repeated disconnects and reconnects to crash. Even when crashing at idle (just staying connected to wifi and bluetooth, not streaming), it feels like a random amount of time. The phone could remain connected to the board for days with no issue, but then some other time crash within minutes.

I was wrong. This time I was not connected to WiFi, and it crashed while idle (though I had tried earlier in the log to crash it with repeated disconnects & reconnects)

2023-02-16-esp-idf-gh-issue-10555-btdm-75939d3-idle-crash-no-wifi.txt

@ftab Sorry to reply you so late.

This commit fixes the connection failure due to memory leaks.
Please try this new lib again. esp32_20230414.zip

Thanks for the update. I have pulled the latest release/v5.0 branch of esp-idf and installed the attached library. Beginning my tests now. I will follow up with my findings.

This is probably a different crash (heap corruption). I am still trying to reproduce the original crash (I will leave it streaming over the weekend) but figured I'd go ahead and give you this log:

I (27) boot: ESP-IDF v5.0.1-464-gef4b1b7704-dirty 2nd stage bootloader
I (27) boot: compile time 09:10:16
I (27) boot: chip revision: v1.0
I (27) boot.esp32: SPI Speed      : 80MHz
I (28) boot.esp32: SPI Mode       : DIO
I (28) boot.esp32: SPI Flash Size : 4MB
I (28) boot: Enabling RNG early entropy source...
I (29) boot: Partition Table:
I (29) boot: ## Label            Usage          Type ST Offset   Length
I (29) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (30) boot:  1 phy_init         RF data          01 01 0000d000 00001000
I (30) boot:  2 factory          factory app      00 00 00010000 00300000
I (30) boot: End of partition table
I (31) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=71bd8h (465880) map
I (172) esp_image: segment 1: paddr=00081c00 vaddr=3ffbdb60 size=05978h ( 22904) load
I (180) esp_image: segment 2: paddr=00087580 vaddr=40080000 size=08a98h ( 35480) load
I (192) esp_image: segment 3: paddr=00090020 vaddr=400d0020 size=177e70h (1539696) map
I (656) esp_image: segment 4: paddr=00207e98 vaddr=40088a98 size=16b08h ( 92936) load
I (705) boot: Loaded app from partition at offset 0x10000
I (705) boot: Disabling RNG early entropy source...
I (706) quad_psram: This chip is ESP32-D0WD
I (706) esp_psram: Found 8MB PSRAM device
I (706) esp_psram: Speed: 80MHz
I (706) esp_psram: PSRAM initialized, cache is in low/high (2-core) mode.
W (707) esp_psram: Virtual address not enough for PSRAM, map as much as we can. 4MB is mapped
I (707) cpu_start: Pro cpu up.
I (707) cpu_start: Starting app cpu, entry point is 0x4008184c
0x4008184c: call_start_cpu1 at /Users/dennis/esp/esp-adf/esp-idf/components/esp_system/port/cpu_start.c:141

I (0) cpu_start: App cpu up.
I (1172) esp_psram: SPI SRAM memory test OK
I (1181) cpu_start: Pro cpu start user code
I (1181) cpu_start: cpu freq: 240000000 Hz
I (1181) cpu_start: Application information:
I (1181) cpu_start: Project name:     wifi_bt_ble_coex
I (1181) cpu_start: App version:      v2.3-194-g0eafda3-dirty
I (1182) cpu_start: Compile time:     Apr 14 2023 09:10:04
I (1182) cpu_start: ELF file SHA256:  ef618c263c5ccbe4...
I (1182) cpu_start: ESP-IDF:          v5.0.1-464-gef4b1b7704-dirty
I (1183) cpu_start: Min chip rev:     v1.0
I (1183) cpu_start: Max chip rev:     v3.99 
I (1183) cpu_start: Chip rev:         v1.0
I (1184) heap_init: Initializing. RAM available for dynamic allocation:
I (1184) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (1184) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (1185) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1185) heap_init: At 3FFC5578 len 0001AA88 (106 KiB): DRAM
I (1185) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1186) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1186) heap_init: At 4009F5A0 len 00000A60 (2 KiB): IRAM
I (1469) esp_psram: Adding pool of 4082K of PSRAM memory to heap allocator
I (1471) spi_flash: detected chip: generic
I (1471) spi_flash: flash io: dio
W (1472) ADC: legacy driver is deprecated, please migrate to `esp_adc/adc_oneshot.h`
W (1472) i2s(legacy): legacy i2s driver is deprecated, please migrate to use driver/i2s_std.h, driver/i2s_pdm.h or driver/i2s_tdm.h
I (1473) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1490) COEX_EXAMPLE: [ 1 ] Create coex handle for a2dp-gatt-wifi
I (1490) COEX_EXAMPLE: [ 2 ] Initialize peripherals
I (1491) COEX_EXAMPLE: [ 3 ] create and start input key service
I (1492) gpio: GPIO[36]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 
I (1492) gpio: GPIO[39]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 
I (1493) COEX_EXAMPLE: [ 4 ] Start a2dp and blufi network
I (1493) COEX_EXAMPLE: [4.1] Init Bluetooth
I (1493) BTDM_INIT: BT controller compile version [ed98430]
I (1495) system_api: Base MAC address is not set
I (1495) system_api: read default base MAC address from EFUSE
I (1497) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
W (1497) phy_init: failed to load RF calibration data (0x1102), falling back to full calibration
W (1518) PERIPH_TOUCH: _touch_init
I (2225) COEX_EXAMPLE: [4.2] init gatts
I (2225) BLE_GATTS: ble gatts module init
I (2225) COEX_EXAMPLE: Blufi module init
E (2226) DISPATCHER: exe first list: 0x0
I (2226) DISPATCHER: dispatcher_event_task is running...
E (2232) WIFI_SSID_MANAGER: Fail to get configuration from nvs flash
I (2250) BLE_GATTS: create attribute table successfully, the number handle = 8

I (2256) BLE_GATTS: SERVICE_START_EVT, status 0, service_handle 40
I (2256) BLE_GATTS: advertising start successfully
I (2259) wifi:wifi driver task: 3ffd9d94, prio:23, stack:3584, core=0
I (2263) wifi:wifi firmware version: 57982fe
I (2264) wifi:wifi certification version: v7.0
I (2264) wifi:config NVS flash: enabled
I (2264) wifi:config nano formating: disabled
I (2264) wifi:Init data frame dynamic rx buffer num: 128
I (2264) wifi:Init management frame dynamic rx buffer num: 128
I (2264) wifi:Init management short buffer num: 32
I (2265) wifi:Init dynamic tx buffer num: 32
I (2269) wifi:Init tx cache buffer num: 32
I (2270) wifi:Init static rx buffer size: 1600
I (2270) wifi:Init static rx buffer num: 2
I (2271) wifi:Init dynamic rx buffer num: 128
I (2288) wifi_init: tcpip mbox: 32
I (2289) wifi_init: udp mbox: 6
I (2289) wifi_init: tcp mbox: 6
I (2289) wifi_init: tcp tx win: 5744
I (2289) wifi_init: tcp rx win: 5744
I (2289) wifi_init: tcp mss: 1440
I (2289) wifi_init: WiFi/LWIP prefer SPIRAM
I (2293) wifi:mode : sta (bc:dd:c2:d1:c8:68)
I (2293) wifi:enable tsf
W (2297) WIFI_SSID_MANAGER: There is no ssid stored in flash, please save ssids to flash first
W (2297) WIFI_SERV: No ssid stored in flash, try to connect to wifi set by wifi_service_set_sta_info()
W (2297) WIFI_SERV: There is no preset ssid, please set the wifi first
I (2258) COEX_EXAMPLE: [4.3] Create Bluetooth peripheral
I (2298) COEX_EXAMPLE: [4.4] Start peripherals
I (2315) COEX_EXAMPLE: [4.5] init hfp_stream
I (2315) gpio: GPIO[19]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 
E (2316) gpio: gpio_install_isr_service(465): GPIO isr service already installed
I (2348) gpio: GPIO[21]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (2349) ES8388_DRIVER: init,out:02, in:00
I (2356) ESP_AUDIO_TASK: media_ctrl_task running...,0x3f819634

----------------------------- ESP Audio Platform -----------------------------
|                                                                            |
|                 ESP_AUDIO-v1.7.0-31-g5b8f999-3072767-09be8fe               |
|                     Compile date: Oct 14 2021-11:00:34                     |
------------------------------------------------------------------------------
I (2358) ESP_AUDIO_CTRL: Func:media_ctrl_create, Line:350, MEM Total:4228996 Bytes, Inter:141312 Bytes, Dram:139056 Bytes

I (2375) AUDIO_HAL: Codec mode is 3, Ctrl:1
I (2381) HFP_STREAM: incoming stream init
W (2381) BT_BTC: A2DP Enable with AVRC
I (2382) MP3_DECODER: MP3 init
I (2390) COEX_EXAMPLE: A2DP sink user cb
I (2390) COEX_EXAMPLE: User cb A2DP event: 4
I (2391) A2DP_STREAM: Unhandled A2DP event: 4
I (2406) COEX_EXAMPLE: Func:setup_player, Line:298, MEM Total:4197784 Bytes, Inter:124540 Bytes, Dram:122284 Bytes

I (2406) COEX_EXAMPLE: esp_audio instance is:0x3f819634

I (2407) COEX_EXAMPLE: [ 5 ] Create audio pipeline for playback
I (2407) COEX_EXAMPLE: [5.1] Create i2s stream to read data from codec chip
E (2408) i2s(legacy): i2s_check_cfg_validity(920): this i2s port is in use
E (2408) i2s(legacy): i2s_driver_install(1576): I2S configuration is invalid
I (2409) COEX_EXAMPLE: [5.2] Create hfp stream
I (2409) HFP_STREAM: outgoing stream init
I (2410) COEX_EXAMPLE: [5.3] Register i2s reader and hfp outgoing to audio pipeline
I (2410) COEX_EXAMPLE: [5.4] Link it together [codec_chip]-->i2s_stream_reader-->filter-->hfp_out_stream-->[Bluetooth]
I (2411) AUDIO_PIPELINE: link el->rb, el:0x3f81c9a8, tag:i2s_reader, rb:0x3f81d61c
I (2411) AUDIO_PIPELINE: link el->rb, el:0x3f81d394, tag:filter, rb:0x3f81f68c
I (2412) COEX_EXAMPLE: [5.5] Start audio_pipeline out
I (2412) AUDIO_ELEMENT: [i2s_reader-0x3f81c9a8] Element task created
I (2413) AUDIO_ELEMENT: [filter-0x3f81d394] Element task created
I (2413) AUDIO_ELEMENT: [outgoing-0x3f81d480] Element task created
I (2413) AUDIO_PIPELINE: Func:audio_pipeline_run, Line:359, MEM Total:4172624 Bytes, Inter:113376 Bytes, Dram:111120 Bytes

I (2414) AUDIO_ELEMENT: [i2s_reader] AEL_MSG_CMD_RESUME,state:1
I (2414) I2S_STREAM: AUDIO_STREAM_READER,Rate:44100,ch:2
I (2416) AUDIO_ELEMENT: [filter] AEL_MSG_CMD_RESUME,state:1
I (2654) RSP_FILTER: sample rate of source data : 44100, channel of source data : 2, sample rate of destination data : 16000, channel of destination data : 1
I (2677) AUDIO_PIPELINE: Pipeline started
W (46379) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
W (48339) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 8000
W (48802) BT_APPL: new conn_srvc id:27, app_id:1
W (48802) BT_APPL: bta_dm_pm_ssr conn_srvc id:27, app_id:1
W (48803) BT_APPL: bta_dm_pm_ssr:2, lat:1200
I (48807) HFP_STREAM: APP HFP event: CONNECTION_STATE_EVT
I (48808) HFP_STREAM: --Connection state connected, peer feats 0x0, chld_feats 0x0
I (48892) HFP_STREAM: APP HFP event: CALL_IND_EVT
I (48892) HFP_STREAM: --Call indicator NO call in progress
I (48892) HFP_STREAM: APP HFP event: CALL_SETUP_IND_EVT
I (48892) HFP_STREAM: --Call setup indicator NONE
I (48893) HFP_STREAM: --NETWK state unavailableT
I (48893) HFP_STREAM:AP HFP event SGNL_TRENGTH_IND_EV
I (48894) HFP_STREAM: --Signal strength: 
I (48894) HFP_STREAM: --ROAMING: inactivemTATUS_IND_EV
I (48894) HFP_TRAM AP HP eent: BATTERY_LEVEL_IND_EVT
I (48895) HFP_STREAM: --Battry level 3
I (48895) HFP_STREAM: APP HFP event: CALL_HLDIND_EVT
I (48895) HF_STREAM: --Call held indiatr NONE held
I (48925) HFP_STREAM: APP HFP event: CONNECTION_STATE_EVT
I (48925) HFP_STREAM: --Connection state slc_connected, peer feats 0xfef, chld_feats 0x3f
I (48925) HFP_STREAM: APP HFP event: INBAND_RING_TONE_EVT
I (48926) HFP_STRM: --Inan rin sate Prvided[0m
W (48985) BT_APPL: bta_hf_client_send_at: No service, skipping 11 command
E (49024) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (49026) COEX_EXAMPLE: A2DP sink user cb
I (49027) A2DP_STREAM: A2DP bd address:, [9c:25:95:5c:66:4e]
I (49063) COEX_EXAMPLE: A2DP sink user cb
I (49063) COEX_EXAMPLE: User cb A2DP event: 2
I (49063) A2DP_STREAM: A2DP audio stream configuration, codec type 0
I (49063) A2DP_STREAM: Bluetooth configured, sample rate=44100
I (49064) COEX_EXAMPLE: A2DP sink user cb
I (49064) COEX_EXAMPLE: User cb A2DP event: 5
I (49064) A2DP_STREAM: Unhandled A2DP event: 5
W (49106) BT_APPL: new conn_srvc id:19, app_id:0
W (49106) BT_APPL: bta_dm_pm_ssr conn_srvc id:27, app_id:1
W (49106) BT_APPL: bta_dm_pm_ssr conn_srvc id:19, app_id:0
W (49107) BT_APPL: bta_dm_pm_ssr:2, lat:1200
I (49108) COEX_EXAMPLE: A2DP sink user cb
I (49109) COEX_EXAMPLE: A2DP connected
I (49109) A2DP_STREAM: A2DP bd address:, [9c:25:95:5c:66:4e]
I (49109) A2DP_STREAM: A2DP connection state =  CONNECTED
I (49193) A2DP_STREAM: AVRC conn_state evt: state 1, [9c:25:95:5c:66:4e]
W (49194) A2DP_STREAM: AVRC ct remote features 25b
W (49194) A2DP_STREAM: AVRC tg remote features 25b, CT features 2
I (49297) A2DP_STREAM: AVRC register event notification: 13, param: 0x0
I (49298) A2DP_STREAM: rn_param.volume:50
SniffAttempt = 4
SniffTimeout = 1
W (52307) BT_HCI: hci cmd send: sniff: hdl 0x81, intv(400 800)
SniffAttempt = 4
SniffTimeout = 1
lc_env_ptr->sniff.SniffAttempt = 4
W (52582) BT_HCI: hcif mode change: hdl 0x81, mode 2, intv 800, status 0x0
W (57083) BT_HCI: hcif ssr evt: st 0x0, hdl 0x81, tx_lat 800 rx_lat 800
W (70079) BT_HCI: hcif mode change: hdl 0x81, mode 0, intv 0, status 0x0
I (70083) BT_LOG: bta_av_link_role_ok hndl:x41 role:1 conn_audio:x1 bits:1 features:x864b

W (70084) BT_APPL: new conn_srvc id:19, app_id:1
I (70086) COEX_EXAMPLE: A2DP sink user cb
I (70087) COEX_EXAMPLE: User cb A2DP event: 1
CORRUPT HEAP: Bad tail at 0x3f821a83. Expected 0xbaad5678 got 0xbaad5600

assert failed: multi_heap_free multi_heap_poisoning.c:276 (head != NULL)

Backtrace: 0x40082749:0x3ffd2a70 0x400974a1:0x3ffd2a90 0x4009d4d1:0x3ffd2ab0 0x4009c7bd:0x3ffd2be0 0x40082be1:0x3ffd2c00 0x4009d525:0x3ffd2c20 0x40169e0b:0x3ffd2c40 0x401572bd:0x3ffd2c70 0x40157b64:0x3ffd2cb0 0x40156e11:0x3ffd2cd0 0x4017446d:0x3ffd2cf0 0x401556df:0x3ffd2d20 0x40124699:0x3ffd2d40 0x4012958a:0x3ffd2d90 0x40113c2a:0x3ffd2f30 0x4013d317:0x3ffd2f50
0x40082749: panic_abort at /Users/dennis/esp/esp-adf/esp-idf/components/esp_system/panic.c:423

0x400974a1: esp_system_abort at /Users/dennis/esp/esp-adf/esp-idf/components/esp_system/esp_system.c:153

0x4009d4d1: __assert_func at /Users/dennis/esp/esp-adf/esp-idf/components/newlib/assert.c:78

0x4009c7bd: multi_heap_free at /Users/dennis/esp/esp-adf/esp-idf/components/heap/multi_heap_poisoning.c:276 (discriminator 1)

0x40082be1: heap_caps_free at /Users/dennis/esp/esp-adf/esp-idf/components/heap/heap_caps.c:374

0x4009d525: free at /Users/dennis/esp/esp-adf/esp-idf/components/newlib/heap.c:39

0x40169e0b: bta_av_stream_data_cback at /Users/dennis/esp/esp-adf/esp-idf/components/bt/host/bluedroid/bta/av/bta_av_aact.c:586

0x401572bd: avdt_scb_hdl_pkt_no_frag at /Users/dennis/esp/esp-adf/esp-idf/components/bt/host/bluedroid/stack/avdt/avdt_scb_act.c:300

0x40157b64: avdt_scb_hdl_pkt at /Users/dennis/esp/esp-adf/esp-idf/components/bt/host/bluedroid/stack/avdt/avdt_scb_act.c:642

0x40156e11: avdt_scb_event at /Users/dennis/esp/esp-adf/esp-idf/components/bt/host/bluedroid/stack/avdt/avdt_scb.c:561

0x4017446d: avdt_ad_tc_data_ind at /Users/dennis/esp/esp-adf/esp-idf/components/bt/host/bluedroid/stack/avdt/avdt_ad.c:451

0x401556df: avdt_l2c_data_ind_cback at /Users/dennis/esp/esp-adf/esp-idf/components/bt/host/bluedroid/stack/avdt/avdt_l2c.c:495

0x40124699: l2c_csm_open at /Users/dennis/esp/esp-adf/esp-idf/components/bt/host/bluedroid/stack/l2cap/l2c_csm.c:972
 (inlined by) l2c_csm_execute at /Users/dennis/esp/esp-adf/esp-idf/components/bt/host/bluedroid/stack/l2cap/l2c_csm.c:94

0x4012958a: l2c_rcv_acl_data at /Users/dennis/esp/esp-adf/esp-idf/components/bt/host/bluedroid/stack/l2cap/l2c_main.c:309

0x40113c2a: btu_hci_msg_process at /Users/dennis/esp/esp-adf/esp-idf/components/bt/host/bluedroid/stack/btu/btu_task.c:144

0x4013d317: osi_thread_run at /Users/dennis/esp/esp-adf/esp-idf/components/bt/common/osi/thread.c:165

ELF file SHA256: ef618c263c5ccbe4

CPU halted.

Hi @ftab ,

Sorry, I still can't reproduce your problem. Could you please help enable this log?

Thanks

I have enabled BT_APPL debug logs, but I have not had the heap corruption issue aside from that one time on Friday. I must've gotten (un)lucky. I also have not been able to reproduce the IllegalInstruction crash at all with your latest library. I've been streaming for days, and hammering on the repeated disconnect/reconnect scenario for a while, and it hasn't crashed.

Hi @ftab ,

Could you please provide a test log? Because I added some printing in the new lib. For example fifo empty.

Thanks

Here is the full log from my last test. It was almost a full day of streaming, followed by repeated disconnect/reconnect attempts, and has been sitting idle (but connected) for almost another full day since my last attempt (the last log entry). However, I don't see any prints of fifo empty

full-log.txt

@ftab Maybe you can use this lib for the time being. Please let me know when the print of fifo empty appears. thanks.

I regret to report that there was an IllegalInstruction crash. All I got was the backtrace because I did it on a machine with a short (10,000 lines) scrollback buffer and the initial boot was scrolled out by noisy WiFi warnings over a period of about a day and a half.

2023-04-26 01:25:41.349533 ASSERT_PARAM(1024 0), in rwbt.c at line 381
2023-04-26 01:25:42.740425 Guru Meditation Error: Core  1 panic'ed (IllegalInstruction). Exception was unhandled.
2023-04-26 01:25:42.741095 Memory dump at 0x40093078: f01d092d 00004136 f01d0000
2023-04-26 01:25:42.741173 0x40093078: btdm_sleep_check_duration at /home/build/esp/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:952
2023-04-26 01:25:42.808939 
Core  1 register dump:
2023-04-26 01:25:42.811064 PC      : 0x4009307f  PS      : 0x00060634  A0      : 0x80085c9a  A1      : 0x3ffc2304  
2023-04-26 01:25:42.811290 0x4009307f: r_assert at /home/build/esp/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:1863
2023-04-26 01:25:42.832693 
A2      : 0x00000000  A3      : 0x00000400  A4      : 0x00000000  A5      : 0x3f4e8f6c  
2023-04-26 01:25:42.833405 A6      : 0x0000017d  A7      : 0xfffffffc  A8      : 0x8000814b  A9      : 0x3ffc2274  
2023-04-26 01:25:42.833494 A10     : 0x00000000  A11     : 0x3ffc2297  A12     : 0x3ffc2243  A13     : 0x00000031  
2023-04-26 01:25:42.833538 A14     : 0x00000000  A15     : 0x3ffc2248  SAR     : 0x00000004  EXCCAUSE: 0x00000000  
2023-04-26 01:25:42.833568 EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000  
2023-04-26 01:25:42.833599 
2023-04-26 01:25:42.833735 
2023-04-26 01:25:42.833775 Backtrace: 0x4009307c:0x3ffc2304 |<-CORRUPTED
2023-04-26 01:25:42.833801 0x4009307c: r_assert at /home/build/esp/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:1862
2023-04-26 01:25:42.853804 
2023-04-26 01:25:42.853932 
2023-04-26 01:25:42.853987 
2023-04-26 01:25:42.854015 
2023-04-26 01:25:42.854039 ELF file SHA256: 27c2ac0dc717a31d
2023-04-26 01:25:42.854062 
2023-04-26 01:25:42.889841 Rebooting...

I still have not seen fifo empty

I will be on vacation through May 8, so I will resume testing around May 9

@ftab or @xiongweichao I'm curious if there has been any more progress on this issue?

We are seeing something very similar using the latest esp-idf release/v5.0 head ( v5.0.2-279-ga6a962d5f8 ) on a DevkitC-ESP32-WROVER-E.

The panic occurs sometimes during BLE connection or disconnection with a Windows 11 laptop (ThinkPad T14). And sometimes occurs randomly during a long-established BLE connection with the laptop.

In particular, we see the same IllegalInstruction panic occurring inside btdm_sleep_check_duration even though CONFIG_BTDM_CTRL_MODEM_SLEEP is disabled. The only difference we know of with the results earlier in this ticket is that we are using the nimBLE host not bluedroid.

Here's a log snippet showing that the panic looks very similar to earlier reports above:

ASSERT_PARAM(-218959118 0), in arch_main.c at line 369
Guru Meditation Error: Core  0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x40092a60: f01d020c 00004136 f01d0000
0x40092a60: btdm_sleep_check_duration at C:/Espressif/frameworks/esp-idf-v5.0/components/bt/controller/esp32/bt.c:950

Core  0 register dump:
PC      : 0x40092a67  PS      : 0x00060634  A0      : 0x80086561  A1      : 0x3ffdd4e0
0x40092a67: r_assert at C:/Espressif/frameworks/esp-idf-v5.0/components/bt/controller/esp32/bt.c:1890

A2      : 0x00000000  A3      : 0xf2f2f2f2  A4      : 0x00000000  A5      : 0x3f41099e
A6      : 0x00000171  A7      : 0xfffffffc  A8      : 0x8000814b  A9      : 0x3ffdd450
A10     : 0x00000000  A11     : 0x3ffdd473  A12     : 0x3ffdd41f  A13     : 0x00000039
A14     : 0x00000000  A15     : 0x3ffdd424  SAR     : 0x00000004  EXCCAUSE: 0x00000000
EXCVADDR: 0x00000000  LBEG    : 0x40086469  LEND    : 0x40086471  LCOUNT  : 0x00000000
0x40086469: r_assert_param at ??:?

0x40086471: r_assert_param at ??:?

Backtrace: 0x40092a64:0x3ffdd4e0 0x4008655e:0x3ffdd500 0x400ffb81:0x3ffdd520 0x40019fb5:0x3ffdd540 0x4001a1f2:0x3ffdd570 0x40019471:0x3ffdd590 0x400175a7:0x3ffdd5d0 0x40019d11:0x3ffdd5f0 0x40055b4d:0x3ffdd610 0x400fff67:0x3ffdd630 0x401005c5:0x3ffdd650 0x40098711:0x3ffdd680
0x40092a64: r_assert at C:/Espressif/frameworks/esp-idf-v5.0/components/bt/controller/esp32/bt.c:1889

0x4008655e: r_assert_param at ??:?

0x400ffb81: r_platform_reset at ??:?

0x400fff67: r_rw_schedule at ??:?

0x401005c5: btdm_controller_task at ??:?

0x40098711: vPortTaskWrapper at C:/Espressif/frameworks/esp-idf-v5.0/components/freertos/FreeRTOS-Kernel/portable/xtensa/port.c:154

No change on our end. The latest library (from https://github.com/espressif/esp-idf/issues/10555#issuecomment-1508326921 ) still exhibits the issue, but doesn't seem to log anything new or interesting along the way. However, it has overall gotten harder to reproduce on demand, albeit still non-zero chance of occurring. (Sometimes I will have several crashes one right after the other, of course this is when I can't have a console attached so I don't know for sure what happened--other times, I will be able to go weeks without a crash, and it doesn't produce any new information)

Hi @rockys-spindance ,

Maybe you can create a new issue.

@ftab and @xiongweichao Thanks so much for the quick response. Per @xiongweichao's suggestion, I will create a new issue with the full details that we are seeing.

Per yesterday's thread, I have created a new issue here https://github.com/espressif/esp-idf/issues/11624

The encouraging news is that we found a way to generate exactly the same failure backtrace in a quickly reproducible way. Fingers crossed that the reproducible proximate failure has the same root cause as the intermittent crash we were all seeing.

I have updated to esp-idf release/v5.0 to bring in the updated Bluetooth library from the fix for #11624, and made a small edit to bring in the fix for #11197 so that I could compile again. So, I am now using this version of esp-adf: https://github.com/radiosound-com/esp-adf/tree/radiosound-modded-v2.5-66-g49e63cd5 (updated to a recent copy of esp-adf master with a few minor changes, instead of my old fork which hacked up a bunch of stuff to work with idf5 and may have had other changes that could have caused an issue)

I was hoping that with the fix to #11624 this issue would be fixed as well, but I just got the same crash in the middle of streaming as I have been getting. So unfortunately this is still happening to us.

I (29) boot: ESP-IDF v5.0.3-147-gdc9a3c43ea 2nd stage bootloader
I (29) boot: compile time 10:13:53
I (29) boot: Multicore bootloader
I (29) boot: chip revision: v3.1
I (29) boot.esp32: SPI Speed      : 80MHz
I (29) boot.esp32: SPI Mode       : DIO
I (30) boot.esp32: SPI Flash Size : 8MB
I (30) boot: Enabling RNG early entropy source...
I (30) boot: Partition Table:
I (30) boot: ## Label            Usage          Type ST Offset   Length
I (31) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (31) boot:  1 otadata          OTA data         01 00 0000d000 00002000
I (32) boot:  2 phy_init         RF data          01 01 0000f000 00001000
I (32) boot:  3 ota_0            OTA app          00 10 00010000 00380000
I (33) boot:  4 ota_1            OTA app          00 11 00390000 00380000
I (33) boot:  5 storage          Unknown data     01 82 00710000 000c0000
I (34) boot: End of partition table
I (34) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=137150h (1274192) map
I (418) esp_image: segment 1: paddr=00147178 vaddr=3ff80063 size=00008h (     8) load
I (419) esp_image: segment 2: paddr=00147188 vaddr=3ffbdb60 size=04858h ( 18520) load
I (425) esp_image: segment 3: paddr=0014b9e8 vaddr=40080000 size=04630h ( 17968) load
I (432) esp_image: segment 4: paddr=00150020 vaddr=400d0020 size=1821f4h (1581556) map
I (908) esp_image: segment 5: paddr=002d221c vaddr=40084630 size=1a390h (107408) load
I (946) esp_image: segment 6: paddr=002ec5b4 vaddr=400c0000 size=00064h (   100) load
I (962) boot: Loaded app from partition at offset 0x10000
I (962) boot: Disabling RNG early entropy source...
I (963) cpu_start: Multicore app
I (963) quad_psram: This chip is ESP32-D0WD
I (963) esp_psram: Found 8MB PSRAM device
I (963) esp_psram: Speed: 80MHz
I (963) esp_psram: PSRAM initialized, cache is in low/high (2-core) mode.
W (964) esp_psram: Virtual address not enough for PSRAM, map as much as we can. 4MB is mapped
I (964) cpu_start: Pro cpu up.
I (964) cpu_start: Starting app cpu, entry point is 0x400818d8
0x400818d8: call_start_cpu1 at /home/build/esp/esp-adf/esp-idf/components/esp_system/port/cpu_start.c:143

I (950) cpu_start: App cpu up.
I (1432) esp_psram: SPI SRAM memory test OK
I (1441) cpu_start: Pro cpu start user code
I (1441) cpu_start: cpu freq: 240000000 Hz
I (1441) cpu_start: Application information:
I (1441) cpu_start: Project name:     ...
I (1441) cpu_start: App version:      008c14f-dirty
I (1442) cpu_start: Compile time:     Jul 20 2023 11:16:35
I (1442) cpu_start: ELF file SHA256:  33756a4c2bbae400...
I (1442) cpu_start: ESP-IDF:          v5.0.3-147-gdc9a3c43ea
I (1443) cpu_start: Min chip rev:     v3.0
I (1443) cpu_start: Max chip rev:     v3.99 
I (1443) cpu_start: Chip rev:         v3.1
I (1444) heap_init: Initializing. RAM available for dynamic allocation:
I (1444) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (1444) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (1445) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1445) heap_init: At 3FFC9AB8 len 00016548 (89 KiB): DRAM
I (1445) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1446) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1446) heap_init: At 4009E9C0 len 00001640 (5 KiB): IRAM
I (1447) esp_psram: Adding pool of 4084K of PSRAM memory to heap allocator
I (1448) spi_flash: detected chip: gd
I (1448) spi_flash: flash io: dio
W (1448) spi_flash: Detected size(16384k) larger than the size in the binary image header(8192k). Using the size in the binary image header.
W (1449) i2s(legacy): legacy i2s driver is deprecated, please migrate to use driver/i2s_std.h, driver/i2s_pdm.h or driver/i2s_tdm.h
W (1449) ADC: legacy driver is deprecated, please migrate to `esp_adc/adc_oneshot.h`
I (1451) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
...
I (1628) Audio_Pipeline_Init: [2.1] Start Bluetooth stack
I (1628) BTDM_INIT: BT controller compile version [946b762]
I (1629) system_api: Base MAC address is not set
I (1630) system_api: read default base MAC address from EFUSE
I (1631) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
...
ASSERT_PARAM(1024 0), in rwbt.c at line 381
Guru Meditation Error: Core  1 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x40092e88: f01d092d 00004136 f01d0000
0x40092e88: btdm_sleep_check_duration at /home/build/esp/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:955

Core  1 register dump:
PC      : 0x40092e8f  PS      : 0x00060031  A0      : 0x80085916  A1      : 0x3ffc05a0  
0x40092e8f: r_assert at /home/build/esp/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:1890

A2      : 0x00000000  A3      : 0x00000400  A4      : 0x00000000  A5      : 0x3f4efdd0  
A6      : 0x0000017d  A7      : 0xfffffffc  A8      : 0x8000814b  A9      : 0x3ffc0510  
A10     : 0x00000000  A11     : 0x3ffc0533  A12     : 0x3ffc04df  A13     : 0x00000031  
A14     : 0x00000000  A15     : 0x3ffc04e4  SAR     : 0x00000004  EXCCAUSE: 0x00000000  
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000  

Backtrace: 0x40092e8c:0x3ffc05a0 0x40085913:0x3ffc05c0 0x4008c52d:0x3ffc05e0 0x4008ca93:0x3ffc0600 0x40083a45:0x3ffc0620 0x40093083:0x3ffbcd50 0x400d4632:0x3ffbcd70 0x4009744f:0x3ffbcd90
0x40092e8c: r_assert at /home/build/esp/esp-adf/esp-idf/components/bt/controller/esp32/bt.c:1889

0x40085913: r_assert_param at ??:?

0x4008c52d: r_rwbt_isr at ??:?

0x4008ca93: r_rwbtdm_isr_wrapper at intc.c:?

0x40083a45: _xt_lowint1 at /home/build/esp/esp-adf/esp-idf/components/freertos/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1118

0x40093083: xt_utils_wait_for_intr at /home/build/esp/esp-adf/esp-idf/components/xtensa/include/xt_utils.h:81
 (inlined by) esp_cpu_wait_for_intr at /home/build/esp/esp-adf/esp-idf/components/esp_hw_support/cpu.c:101

0x400d4632: esp_vApplicationIdleHook at /home/build/esp/esp-adf/esp-idf/components/esp_system/freertos_hooks.c:59

0x4009744f: prvIdleTask at /home/build/esp/esp-adf/esp-idf/components/freertos/FreeRTOS-Kernel/tasks.c:4157

ELF file SHA256: 33756a4c2bbae400

Rebooting...

The full log has stuff about our custom board which isn't relevant here. I will try to find some time to get back to reproducing this on LyraT in the esp-adf example I was using previously.

Hi @ftab ,

Set to non-discoverable non-connectable mode after the connection is complete. Please let me know the test results.

esp_bt_gap_set_scan_mode(ESP_BT_NON_CONNECTABLE, ESP_BT_NON_DISCOVERABLE);

Thanks

I have applied the suggested change, as well as the equivalent change to main/wifi_bt_ble_coex_example.c since that doesn't use bluetooth_service (it uses a2dp_stream). I also had to apply an esp-idf patch from esp-adf in order to get back to using the example (required by audio_thread). To recap, here are my git statuses and diffs:

build@dennis-2021:~/esp/esp-adf$ git status
On branch radiosound-modded-v2.5-66-g49e63cd5
Your branch is up to date with 'radiosound/radiosound-modded-v2.5-66-g49e63cd5'.

Changes not staged for commit:
  (use "git add <file>..." to update what will be committed)
  (use "git restore <file>..." to discard changes in working directory)
  (commit or discard the untracked or modified content in submodules)
    modified:   components/bluetooth_service/bluetooth_service.c
    modified:   esp-idf (modified content)
    modified:   examples/advanced_examples/wifi_bt_ble_coex/main/wifi_bt_ble_coex_example.c

no changes added to commit (use "git add" and/or "git commit -a")
build@dennis-2021:~/esp/esp-adf$ git diff
diff --git a/components/bluetooth_service/bluetooth_service.c b/components/bluetooth_service/bluetooth_service.c
index 594c04c5..2a0999fa 100644
--- a/components/bluetooth_service/bluetooth_service.c
+++ b/components/bluetooth_service/bluetooth_service.c
@@ -178,6 +178,11 @@ static void bt_a2d_sink_cb(esp_a2d_cb_event_t event, esp_a2d_cb_param_t *p_param

             if (g_bt_service->connection_state == ESP_A2D_CONNECTION_STATE_DISCONNECTED
                 && a2d->conn_stat.state == ESP_A2D_CONNECTION_STATE_CONNECTED) {
+#if (ESP_IDF_VERSION >= ESP_IDF_VERSION_VAL(4, 0, 0))
+                esp_bt_gap_set_scan_mode(ESP_BT_NON_CONNECTABLE, ESP_BT_NON_DISCOVERABLE);
+#else
+                esp_bt_gap_set_scan_mode(ESP_BT_SCAN_MODE_NONE);
+#endif
                 memcpy(&g_bt_service->remote_bda, &a2d->conn_stat.remote_bda, sizeof(esp_bd_addr_t));
                 g_bt_service->connection_state = a2d->conn_stat.state;
                 ESP_LOGD(TAG, "A2DP connection state = CONNECTED");
@@ -188,6 +193,11 @@ static void bt_a2d_sink_cb(esp_a2d_cb_event_t event, esp_a2d_cb_param_t *p_param
             if (memcmp(&g_bt_service->remote_bda, &a2d->conn_stat.remote_bda, sizeof(esp_bd_addr_t)) == 0
                 && g_bt_service->connection_state == ESP_A2D_CONNECTION_STATE_CONNECTED
                 && a2d->conn_stat.state == ESP_A2D_CONNECTION_STATE_DISCONNECTED) {
+#if (ESP_IDF_VERSION >= ESP_IDF_VERSION_VAL(4, 0, 0))
+                esp_bt_gap_set_scan_mode(ESP_BT_CONNECTABLE, ESP_BT_GENERAL_DISCOVERABLE);
+#else
+                esp_bt_gap_set_scan_mode(ESP_BT_SCAN_MODE_CONNECTABLE_DISCOVERABLE);
+#endif
                 memset(&g_bt_service->remote_bda, 0, sizeof(esp_bd_addr_t));
                 g_bt_service->connection_state = ESP_A2D_CONNECTION_STATE_DISCONNECTED;
                 ESP_LOGD(TAG, "A2DP connection state =  DISCONNECTED");
diff --git a/esp-idf b/esp-idf
--- a/esp-idf
+++ b/esp-idf
@@ -1 +1 @@
-Subproject commit dc9a3c43ea24007115382f7f194d03882031b091
+Subproject commit dc9a3c43ea24007115382f7f194d03882031b091-dirty
diff --git a/examples/advanced_examples/wifi_bt_ble_coex/main/wifi_bt_ble_coex_example.c b/examples/advanced_examples/wifi_bt_ble_coex/main/wifi_bt_ble_coex_example.c
index 0a90b917..95126756 100644
--- a/examples/advanced_examples/wifi_bt_ble_coex/main/wifi_bt_ble_coex_example.c
+++ b/examples/advanced_examples/wifi_bt_ble_coex/main/wifi_bt_ble_coex_example.c
@@ -237,9 +237,11 @@ static void user_a2dp_sink_cb(esp_a2d_cb_event_t event, esp_a2d_cb_param_t *para
         case ESP_A2D_CONNECTION_STATE_EVT:
             if (param->conn_stat.state == ESP_A2D_CONNECTION_STATE_DISCONNECTED) {
                 ESP_LOGI(TAG, "A2DP disconnected");
+                esp_bt_gap_set_scan_mode(ESP_BT_CONNECTABLE, ESP_BT_GENERAL_DISCOVERABLE);
                 g_a2dp_connect_state = false;
             } else if (param->conn_stat.state == ESP_A2D_CONNECTION_STATE_CONNECTED) {
                 ESP_LOGI(TAG, "A2DP connected");
+                esp_bt_gap_set_scan_mode(ESP_BT_NON_CONNECTABLE, ESP_BT_NON_DISCOVERABLE);
                 g_a2dp_connect_state = true;
             }
             break;
@@ -354,8 +356,8 @@ void app_main(void)
     tcpip_adapter_init();
 #endif

-    esp_log_level_set("*", ESP_LOG_WARN);
-    esp_log_level_set(TAG, ESP_LOG_DEBUG);
+    //esp_log_level_set("*", ESP_LOG_WARN);
+    //esp_log_level_set(TAG, ESP_LOG_DEBUG);

     ESP_LOGI(TAG, "[ 1 ] Create coex handle for a2dp-gatt-wifi");
     g_coex_handle = (coex_handle_t *)audio_malloc(sizeof(coex_handle_t));
build@dennis-2021:~/esp/esp-adf$ cd esp-idf
build@dennis-2021:~/esp/esp-adf/esp-idf$ git status
On branch release/v5.0+0634bb9
Your branch is up to date with 'radiosound/release/v5.0+0634bb9'.

Changes not staged for commit:
  (use "git add <file>..." to update what will be committed)
  (use "git restore <file>..." to discard changes in working directory)
    modified:   components/freertos/FreeRTOS-Kernel/tasks.c

no changes added to commit (use "git add" and/or "git commit -a")
build@dennis-2021:~/esp/esp-adf/esp-idf$ git diff
diff --git a/components/freertos/FreeRTOS-Kernel/tasks.c b/components/freertos/FreeRTOS-Kernel/tasks.c
index 6b2252071e..acca48522f 100644
--- a/components/freertos/FreeRTOS-Kernel/tasks.c
+++ b/components/freertos/FreeRTOS-Kernel/tasks.c
@@ -726,6 +726,46 @@ void taskYIELD_OTHER_CORE( BaseType_t xCoreID, UBaseType_t uxPriority )
 #endif /* SUPPORT_STATIC_ALLOCATION */
 /*-----------------------------------------------------------*/

+       BaseType_t xTaskCreateRestrictedPinnedToCore( const TaskParameters_t * const pxTaskDefinition, TaskHandle_t *pxCreatedTask, const BaseType_t xCoreID)
+       {
+           TCB_t *pxNewTCB;
+           BaseType_t xReturn = errCOULD_NOT_ALLOCATE_REQUIRED_MEMORY;
+
+               configASSERT( pxTaskDefinition->puxStackBuffer );
+
+               if( pxTaskDefinition->puxStackBuffer != NULL )
+               {
+                       /* Allocate space for the TCB.  Where the memory comes from depends
+                       on the implementation of the port malloc function and whether or
+                       not static allocation is being used. */
+                       pxNewTCB = ( TCB_t * ) pvPortMalloc( sizeof( TCB_t ) );
+
+                       if( pxNewTCB != NULL )
+                       {
+                               /* Store the stack location in the TCB. */
+                               pxNewTCB->pxStack = pxTaskDefinition->puxStackBuffer;
+
+                               /* Tasks can be created statically or dynamically, so note
+                               this task had a statically allocated stack in case it is
+                               later deleted.  The TCB was allocated dynamically. */
+                               pxNewTCB->ucStaticallyAllocated = tskDYNAMICALLY_ALLOCATED_STACK_AND_TCB;
+
+                               prvInitialiseNewTask(   pxTaskDefinition->pvTaskCode,
+                                                                               pxTaskDefinition->pcName,
+                                                                               pxTaskDefinition->usStackDepth,
+                                                                               pxTaskDefinition->pvParameters,
+                                                                               pxTaskDefinition->uxPriority,
+                                                                               pxCreatedTask, pxNewTCB,
+                                                                               pxTaskDefinition->xRegions,
+                                                                               xCoreID );
+
+                               prvAddNewTaskToReadyList( pxNewTCB, pxTaskDefinition->pvTaskCode, xCoreID );
+                               xReturn = pdPASS;
+                       }
+           }
+               return xReturn;
+       }
+
 #if ( ( portUSING_MPU_WRAPPERS == 1 ) && ( configSUPPORT_STATIC_ALLOCATION == 1 ) )

     BaseType_t xTaskCreateRestrictedStatic( const TaskParameters_t * const pxTaskDefinition,

While I was setting up one of the test setups, I had an error ELx400 followed by PR that appeared to coincide with Bluetooth ceasing to function. The phone could no longer connect to it, and no additional logs were printed except when I pressed the "Mode" button on the board. Related, or new issue? This is really strange, as it simply "soft locked" without crashing / rebooting...

--- idf_monitor on /dev/ttyUSB1 2000000 ---
--- Quit: Ctrl+] | Menu: Ctrl+T | Help: Ctrl+T followed by Ctrl+H ---
I (29) boot: ESP-IDF v5.0.3-147-gdc9a3c43ea-dirty 2nd stage bootloader
I (29) boot: Multicore bootloader
I (29) boot: chip revision: v1.0
I (29) qio_mode: Enabling default flash chip QIO
I (30) boot.esp32: SPI Speed      : 80MHz
I (30) boot.esp32: SPI Mode       : QIO
I (30) boot.esp32: SPI Flash Size : 4MB
I (30) boot: Enabling RNG early entropy source...
I (31) boot: Partition Table:
I (31) boot: ## Label            Usage          Type ST Offset   Length
I (31) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (32) boot:  1 phy_init         RF data          01 01 0000d000 00001000
I (32) boot:  2 factory          factory app      00 00 00010000 00380000
I (33) boot: End of partition table
I (33) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=55f48h (352072) map
I (130) esp_image: segment 1: paddr=00065f70 vaddr=3ffbdb60 size=05764h ( 22372) load
I (137) esp_image: segment 2: paddr=0006b6dc vaddr=40080000 size=0493ch ( 18748) load
I (144) esp_image: segment 3: paddr=00070020 vaddr=400d0020 size=148a28h (1346088) map
I (514) esp_image: segment 4: paddr=001b8a50 vaddr=4008493c size=174d4h ( 95444) load
I (559) boot: Loaded app from partition at offset 0x10000
I (559) boot: Disabling RNG early entropy source...
I (560) cpu_start: Multicore app
I (560) quad_psram: This chip is ESP32-D0WD
I (560) esp_psram: Found 8MB PSRAM device
I (561) esp_psram: Speed: 80MHz
I (561) esp_psram: PSRAM initialized, cache is in low/high (2-core) mode.
W (561) esp_psram: Virtual address not enough for PSRAM, map as much as we can. 4MB is mapped
I (561) cpu_start: Pro cpu up.
I (562) cpu_start: Starting app cpu, entry point is 0x4008165c
0x4008165c: call_start_cpu1 at /COMPONENT_ESP_SYSTEM_DIR/port/cpu_start.c:143

I (0) cpu_start: App cpu up.
I (1063) esp_psram: SPI SRAM memory test OK
I (1072) cpu_start: Pro cpu start user code
I (1072) cpu_start: cpu freq: 240000000 Hz
I (1072) cpu_start: Application information:
I (1072) cpu_start: Project name:     wifi_bt_ble_coex
I (1072) cpu_start: App version:      v2.5-72-g39642ffc-dirty
I (1073) cpu_start: ELF file SHA256:  57afe451e46aeb8e...
I (1073) cpu_start: ESP-IDF:          v5.0.3-147-gdc9a3c43ea-dirty
I (1073) cpu_start: Min chip rev:     v0.0
I (1074) cpu_start: Max chip rev:     v3.99 
I (1074) cpu_start: Chip rev:         v1.0
I (1074) heap_init: Initializing. RAM available for dynamic allocation:
I (1075) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (1075) heap_init: At 3FFB7468 len 00000B98 (2 KiB): DRAM
I (1075) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1076) heap_init: At 3FFD0078 len 0000FF88 (63 KiB): DRAM
I (1076) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1076) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1077) heap_init: At 4009BE10 len 000041F0 (16 KiB): IRAM
I (1077) esp_psram: Adding pool of 4084K of PSRAM memory to heap allocator
I (1078) spi_flash: detected chip: generic
I (1079) spi_flash: flash io: qio
W (1079) ADC: legacy driver is deprecated, please migrate to `esp_adc/adc_oneshot.h`
W (1079) i2s(legacy): legacy i2s driver is deprecated, please migrate to use driver/i2s_std.h, driver/i2s_pdm.h or driver/i2s_tdm.h
I (1080) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (1081) esp_psram: Reserving pool of 32K of internal memory for DMA/internal allocations
I (1091) COEX_EXAMPLE: [ 1 ] Create coex handle for a2dp-gatt-wifi
I (1091) COEX_EXAMPLE: [ 2 ] Initialize peripherals
I (1091) COEX_EXAMPLE: [ 3 ] create and start input key service
I (1091) COEX_EXAMPLE: [ 4 ] Start a2dp and blufi network
I (1091) COEX_EXAMPLE: [4.1] Init Bluetooth
W (1111) PERIPH_TOUCH: _touch_init
I (1681) COEX_EXAMPLE: [4.2] init gatts
I (1691) COEX_EXAMPLE: Blufi module init
E (1691) DISPATCHER: exe first list: 0x0
I (1711) COEX_EXAMPLE: [4.3] Create Bluetooth peripheral
I (1711) COEX_EXAMPLE: [4.4] Start peripherals
I (1711) COEX_EXAMPLE: [4.5] init hfp_stream
E (1711) gpio: gpio_install_isr_service(465): GPIO isr service already installed
W (1741) WIFI_SSID_MANAGER: There is no ssid stored in flash, please save ssids to flash first
W (1741) WIFI_SERV: No ssid stored in flash, try to connect to wifi set by wifi_service_set_sta_info()
W (2351) WIFI_SERV: WiFi Event cb, Unhandle event_base:WIFI_EVENT, event_id:4

----------------------------- ESP Audio Platform -----------------------------
|                                                                            |
|                 ESP_AUDIO-v1.7.2-48-gd14dfdf-7e1b14a-d08db1d               |
|                     Compile date: Jun  8 2023-08:51:41                     |
------------------------------------------------------------------------------
W (2411) BT_BTC: A2DP Enable with AVRC
I (2411) COEX_EXAMPLE: A2DP sink user cb
I (2411) COEX_EXAMPLE: User cb A2DP event: 4
I (2421) COEX_EXAMPLE: Func:setup_player, Line:298, MEM Total:4158376 Bytes, Inter:74171 Bytes, Dram:58051 Bytes

I (2421) COEX_EXAMPLE: esp_audio instance is:0x3f814a58

I (2421) COEX_EXAMPLE: [ 5 ] Create audio pipeline for playback
I (2431) COEX_EXAMPLE: [5.1] Create i2s stream to read data from codec chip
E (2431) i2s(legacy): i2s_check_cfg_validity(921): this i2s port is in use
E (2431) i2s(legacy): i2s_driver_install(1577): I2S configuration is invalid
I (2431) COEX_EXAMPLE: [5.2] Create hfp stream
I (2441) COEX_EXAMPLE: [5.3] Register i2s reader and hfp outgoing to audio pipeline
I (2441) COEX_EXAMPLE: [5.4] Link it together [codec_chip]-->i2s_stream_reader-->filter-->hfp_out_stream-->[Bluetooth]
I (2441) COEX_EXAMPLE: [5.5] Start audio_pipeline out
W (19341) BT_HCI: hcif conn complete: hdl 0x80, st 0x0
W (19441) BT_HCI: hcif link supv_to changed: hdl 0x80, supv_to 8000
W (20371) BT_APPL: new conn_srvc id:27, app_id:1
W (20371) BT_APPL: bta_dm_pm_ssr conn_srvc id:27, app_id:1
W (20371) BT_APPL: bta_dm_pm_ssr:2, lat:1200
W (20821) BT_APPL: bta_hf_client_send_at: No service, skipping 11 command
E (20951) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (20951) COEX_EXAMPLE: A2DP sink user cb
I (20981) COEX_EXAMPLE: A2DP sink user cb
I (20981) COEX_EXAMPLE: User cb A2DP event: 2
I (20981) COEX_EXAMPLE: A2DP sink user cb
I (20981) COEX_EXAMPLE: User cb A2DP event: 5
W (21171) BT_APPL: new conn_srvc id:19, app_id:0
W (21171) BT_APPL: bta_dm_pm_ssr conn_srvc id:27, app_id:1
W (21171) BT_APPL: bta_dm_pm_ssr conn_srvc id:19, app_id:0
W (21171) BTAPPL: bta_dm_p_ssr:2, lat:1200
I (21171) COEX_EXAMPLE: A2DP sink user cb
I (21171) COEX_EXAMPLE: A2DP connected
W (21481) A2DP_STREAM: AVRC ct remote features 25b
W (21481) A2DP_STREAM: AVRC tg remote features 25b, CT features 2
W (21581) BT_APPL: bta_dm_pm_ssr conn_srvc id:27, app_id:1
W (21581) BT_APPL: bta_dm_pm_ssr conn_srvc id:19, app_id:0
W (21581) BT_APPL: bta_dm_pm_ssr:2, lat:1200
W (21581) BT_APPL: new conn_srvc id:19, app_id:1
I (21581) COEX_EXAMPLE: A2DP sink user cb
I (21581) COEX_EXAMPLE: User cb A2DP event: 1
W (34851) WIFI_SERV: STATE type:2, pdata:0x0, len:0
I (34991) COEX_EXAMPLE: WIFI_CONNECTED
W (53451) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
E (54161) BT_BTM: tBTM_SEC_DEV:0x3ffe3540 rs_disc_pending=1

E (54241) BT_BTM: tBTM_SEC_DEV:0x3ffe3540 rs_disc_pending=1

E (54251) BT_BTM: tBTM_SEC_DEV:0x3ffe3540 rs_disc_pending=1

E (55031) BT_BTM: tBTM_SEC_DEV:0x3fff9b14 rs_disc_pending=0

W (55371) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 8000
E (55391) BT_APPL: rcb[0].lidx=3, lcb.conn_msk=x1
E (55391) BT_BTC: Got RC OPEN in connected state, Connected RC: 1                 and Current RC: 0
W (55391) BT_AVCT: avct_lcb_last_ccb
W (55391) BT_AVCT: 0: aloc:1, lcb:0x3ffce5d4/0x3ffce5d4, ccb:0x3ffce61c/0x3ffce61c
W (55391) BT_AVCT: 1: aloc:1, lcb:0x3ffce5b4/0x3ffce5d4, ccb:0x3ffce634/0x3ffce61c
W (55401) BT_AVCT: 2: aloc:0, lcb:0x0/0x3ffce5d4, ccb:0x3ffce64c/0x3ffce61c
E (55451) BT_APPL: av scb not available for avdt connection
E (55571) BT_BTC: Got disconnect of unknown device
W (56051) A2DP_STREAM: AVRC ct remote features 25b
W (56051) A2DP_STREAM: AVRC tg remote features 25b, CT features 2
W (56201) BT_RFCOMM: rfc_find_lcid_mcb LCID reused LCID:0x43 current:0x0
W (56201) BT_RFCOMM: RFCOMM_DisconnectInd LCID:0x43
W (57071) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 32000
W (60941) BT_HCI: hci cmd send: disconnect: hdl 0x81, rsn:0x13
W (101481) BT_HCI: hcif disc complete: hdl 0x81, rsn 0x13
W (406871) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
E (407511) BT_BTM: tBTM_SEC_DEV:0x3ffe3540 rs_disc_pending=1

E (407531) BT_BTM: tBTM_SEC_DEV:0x3ffe3540 rs_disc_pending=1

E (407531) BT_BTM: tBTM_SEC_DEV:0x3ffe3540 rs_disc_pending=1

E (409561) BT_BTM: tBTM_SEC_DEV:0x3fff9c70 rs_disc_pending=0

W (409701) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 8000
E (409771) BT_APPL: av scb not available for avdt connection
E (409801) BT_APPL: rcb[0].lidx=3, lcb.conn_msk=x1
E (409801) BT_BTC: Got RC OPEN in connected state, Connected RC: 1                 and Current RC: 0
W (409801) BT_AVCT: avct_lcb_last_ccb
W (409801) BT_AVCT: 0: aloc:1, lcb:0x3ffce5d4/0x3ffce5d4, ccb:0x3ffce61c/0x3ffe61
W (409801) BT_AVC: 1: aloc:1, lcb0x3ffc5b4/0xffce54, ccb:0x3ffce63/0x3ffce61c
W (409801) BT_AVCT: 2: aloc:0, lcb:0x0/0x3ffce5d4, ccb:0x3ffce64c/0x3ffce61c
E (409831) BT_BTC: Got disconnect of unknown device
W (409851) BT_RFCOMM: rfc_find_lcid_mcb LCID reused LCID:0x43 current:0x0
W (409851) BT_RFCOMM: RFCOMM_DisconnectInd LCID:0x43
W (410511) BT_HCI: hcif link supv_to changed: hdl 0x81, supv_to 32000
W (411481) BT_HCI: hcif disc complete: hdl 0x81, rsn 0x13
ELx400
PR
I (1456741) COEX_EXAMPLE: [ * ] input key id is 4, key type is 1
I (1456891) COEX_EXAMPLE: [ * ] input key id is 4, key type is 2
I (1456891) COEX_EXAMPLE: [ * ] [mode]
I (1456891) COEX_EXAMPLE: [ * ] Enter BT mode

I have 3 test setups I will leave streaming over the weekend to try to catch a crash. When I get back on Monday I will try the other method I had of reproducing, that is repeatedly disconnecting and reconnecting.

In the hopes of capturing something useful, I had debug logging turned on, but that also includes a lot of noise from i2s as well as BT_APPL for every packet.

The log is too big to attach here (73.4 MB gzipped, 882 MB uncompressed): https://nextcloud.apps.radiosound.com/s/D2iRP2f9tbJpoaT

It appears to have streamed for about 7 hours, then Bluetooth disconnected and it crashed very shortly thereafter.

ASSERT_PARAM(1024 0), in rwbt.c at line 381
Guru Meditation Error: Core  1 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x40092d04: 00f01d00 00004136 f01d0000
Core  1 register dump:
PC      : 0x40092d0b  PS      : 0x00060134  A0      : 0x80085e0a  A1      : 0x3ffc2084  
A2      : 0x00000000  A3      : 0x00000400  A4      : 0x00000000  A5      : 0x3f444c04  
A6      : 0x0000017d  A7      : 0xfffffffc  A8      : 0x8000814b  A9      : 0x3ffc1ff4  
A10     : 0x00000000  A11     : 0x3ffc2017  A12     : 0x3ffc1fc3  A13     : 0x00000031  
A14     : 0x00000000  A15     : 0x3ffc1fc8  SAR     : 0x00000004  EXCCAUSE: 0x00000000  
EXCVADDR: 0x00000000  LBEG    : 0x00000000  LEND    : 0x00000000  LCOUNT  : 0x00000000  

Backtrace: 0x40092d08:0x3ffc2084 |<-CORRUPTED

ELF file SHA256: f4cd83c8699d8ccf

CPU halted.

$ xtensa-esp32-elf-addr2line -pfiaC -e build/wifi_bt_ble_coex.elf 0x40092d04
0x40092d04: btdm_sleep_check_duration at /COMPONENT_BT_DIR/controller/esp32/bt.c:955
$ xtensa-esp32-elf-addr2line -pfiaC -e build/wifi_bt_ble_coex.elf 0x40092d0b
0x40092d0b: r_assert at /COMPONENT_BT_DIR/controller/esp32/bt.c:1890
$ xtensa-esp32-elf-addr2line -pfiaC -e build/wifi_bt_ble_coex.elf 0x40092d08
0x40092d08: r_assert at /COMPONENT_BT_DIR/controller/esp32/bt.c:1889
$ xtensa-esp32-elf-addr2line -pfiaC -e build/wifi_bt_ble_coex.elf 0x3ffc2084
0x3ffc2084: _l4_intr_stack at hli_vectors.S.obj:?

Here is the sdkconfig that was used: sdkconfig.txt

The board in use: LyraT v4.3

The streaming device: iPhone 6 Plus running iOS 12.5.7

Additionally, one more diff, as I had to turn up the stack size for the input key service (otherwise it reaches stack canary watchpoint when the Mode button is pressed)

diff --git a/examples/advanced_examples/wifi_bt_ble_coex/main/wifi_bt_ble_coex_example.c b/examples/advanced_examples/wifi_bt_ble_coex/main/wifi_bt_ble_coex_example.c
index 0a90b917..81af6fd9 100644
--- a/examples/advanced_examples/wifi_bt_ble_coex/main/wifi_bt_ble_coex_example.c
+++ b/examples/advanced_examples/wifi_bt_ble_coex/main/wifi_bt_ble_coex_example.c
@@ -237,9 +237,11 @@ static void user_a2dp_sink_cb(esp_a2d_cb_event_t event, esp_a2d_cb_param_t *para
         case ESP_A2D_CONNECTION_STATE_EVT:
             if (param->conn_stat.state == ESP_A2D_CONNECTION_STATE_DISCONNECTED) {
                 ESP_LOGI(TAG, "A2DP disconnected");
+                esp_bt_gap_set_scan_mode(ESP_BT_CONNECTABLE, ESP_BT_GENERAL_DISCOVERABLE);
                 g_a2dp_connect_state = false;
             } else if (param->conn_stat.state == ESP_A2D_CONNECTION_STATE_CONNECTED) {
                 ESP_LOGI(TAG, "A2DP connected");
+                esp_bt_gap_set_scan_mode(ESP_BT_NON_CONNECTABLE, ESP_BT_NON_DISCOVERABLE);
                 g_a2dp_connect_state = true;
             }
             break;
@@ -354,8 +356,8 @@ void app_main(void)
     tcpip_adapter_init();
 #endif

-    esp_log_level_set("*", ESP_LOG_WARN);
-    esp_log_level_set(TAG, ESP_LOG_DEBUG);
+    //esp_log_level_set("*", ESP_LOG_WARN);
+    //esp_log_level_set(TAG, ESP_LOG_DEBUG);

     ESP_LOGI(TAG, "[ 1 ] Create coex handle for a2dp-gatt-wifi");
     g_coex_handle = (coex_handle_t *)audio_malloc(sizeof(coex_handle_t));
@@ -372,7 +374,7 @@ void app_main(void)
     input_key_service_info_t input_key_info[] = INPUT_KEY_DEFAULT_INFO();
     input_key_service_cfg_t input_cfg = INPUT_KEY_SERVICE_DEFAULT_CONFIG();
     input_cfg.handle = g_coex_handle->set;
-    input_cfg.based_cfg.task_stack = 2048;
+    input_cfg.based_cfg.task_stack = 3072;
     input_cfg.based_cfg.extern_stack = true;
     periph_service_handle_t input_ser = input_key_service_create(&input_cfg);
     input_key_service_add_key(input_ser, input_key_info, INPUT_KEY_NUM);

Again too big to attach directly to GitHub. This time now with a coredump file. Hope that helps.

https://nextcloud.apps.radiosound.com/s/L3JoSorGz4SaKm9

This one was captured with a different LyraT v4.3 board, with a Galaxy A13 phone running Android 12 / OneUI 4.1

I have tried updating to the latest esp-idf to get the latest Bluetooth fixes, but I ran into #12104. I will try with a different example that does not include BLE.

sdkconfig used

@xiongweichao I have devised an alternate reproduction scenario. It still takes time and is random, but it's largely hands-off and uses another ESP32 as the source device instead of the uncontrollable whatever-phone.

I have a branch on my fork of esp-adf with all of the previous diffs applied, as well as a couple of small modifications to make two esp-adf examples into an automated test stressing the sink device out to cause a crash.

https://github.com/radiosound-com/esp-adf branch btdm-crash-testing

Source device: ESP32-LyraT v4.3 running esp-adf/examples/player/pipeline_a2dp_source_stream with a file "test.mp3" on the SD card. (Set dip switches for 1-wire SD card mode) When configuring menuconfig -> example configuration -> remote device name is "ESP-ADF-AUDIO" not "ESP-ADF-SPEAKER" as this is the name used by the other example

Target device: ESP32-LyraT v4.3 running esp-adf/examples/get-started/pipeline_a2dp_sink_and_hfp (specifically in my branch, it is configured not to terminate the program upon Bluetooth disconnect, just continue running ready for the next Bluetooth connection). I also set the panic handler to halt instead of reboot and turned on coredump in my config. The DIP switches can be set for JTAG since this does not use the SD card. I was about ready to start hooking up a JTAG to it myself, but I would be kind of lost as to what to look for.

pipeline_a2dp_source_stream searches for the specified device name from the example configuration, connects to it, streams test.mp3 from the sd card, then disconnects. In my branch it was modified to esp_restart() at the end of the program instead of remaining in an idle state. Therefore, the shorter test.mp3 is, the quicker the connect/disconnect cycle.

(Incidentally, this example seems to crash half the time during its shutdown process--but that's another issue for another day, at least it will reboot itself after the panic)

I have also devised another optional example to serve as a continuous stream from the LyraT source device instead of the repeated connect-stream-disconnect "hammer" test. See esp-adf/examples/recorder/pipeline_raw_a2dp in my branch. This searches for the specified device name from the example configuration, connects to it, records from LyraT's line in, and streams it over A2DP.

Please let me know if these are able to help you reproduce. If you do not have another LyraT handy to act as the source device, let me know--I can whip up another quick example that flashes the mp3 file to a SPIFFS partition for a DevKitC or other ESP32 board.

I used a very very short test.mp3 in my case. My thought was, thus, the quicker we arrive at the crash, but, it still took over a day of running it for me to catch one (which I just caught as of starting to write this reply). I don't know if that log would be useful compared to the other logs I've sent, but here it is. However, the coredump data appears to have been overwritten in this case for some reason, as the subsequent idf.py coredump-info output didn't make any sense (invalid exception cause, not the right PC from the panic backtrace, etc).

I have had a test setup running in a separate location (my home) that has not crashed yet. I wonder if it is something specific to this building, or if I'm just getting lucky again. edit: lots of frequency hopping due to a lot of 2.4ghz traffic at the office maybe? How would we test that theory?

I have captured a crash on my custom board using ESP Insights and the backtrace looks a little different

Exception IllegalInstructionCause has occured in task IDLE.
Register Values
PC:0x40093318
A0:0x800858c6
A1:0x3ffc0a80
A2:0x3f470c90
A3:0x00000000
A4:0x00000000
A5:0x3f471389
A6:0x00000239
A7:0xfffffffc
A8:0x8000814b
A9:0x3ffc09f0
A10:0x00000000
A11:0x3ffc0a13
A12:0x3ffc09bf
A13:0x00000039
A14:0x00000000
A15:0x3ffc09c4
EXCCAUSE:0x00000000
EXCVADDR:0x00000000
Backtrace
0x40093318
/COMPONENT_BT_DIR/controller/esp32/bt.c:955 in btdm_sleep_check_duration
0x400858c3
r_assert_err
0x40087d45
r_ld_fm_rx_isr
0x4008c022
r_rwbt_isr
0x4008cbff
r_rwbtdm_isr_wrapper
0x40083b4d
/COMPONENT_FREERTOS_DIR/FreeRTOS-Kernel/portable/xtensa/xtensa_vectors.S:1118 in _xt_lowint1
0x4009350f
/COMPONENT_ESP_HW_SUPPORT_DIR/cpu.c:101 in esp_cpu_wait_for_intr

The crash occurred shortly after I connected to the device with my phone (iPhone 14 Pro Max)

@ftab I'm very sorry to reply to you so late. Please update to the latest v5.0 branch to verify whether the problem still exists.

@ftab I'm very sorry to reply to you so late. Please update to the latest v5.0 branch to verify whether the problem still exists.

@xiongweichao We are currently on a fork of v5.1.2 to get task stack in SPI RAM. Is that recent enough?

@ftab Yes, this commit should fix the problem.

@xiongweichao thanks, we will hammer on them this week and see if we run into the crash

I haven't seen this crash in a while. Tentatively calling it fixed. 🎉

@xiongweichao I am afraid I spoke too soon 😞

ASSERT_PARAM(1024 0), in rwbt.c at line 393

The full log is too large to post (came from several hours of test, and has some irrelevant logs from our application every 500ms)

This happened a few seconds after the Bluetooth stream suddenly stopped and the device apparently disconnected unexpectedly

I will dust off one of my previous automated tests on a pair of LyraT boards to continue trying to get a reliable reproduction

The LyraT setup ran for a while and didn't crash yet, so this log is from my custom board (implements an SPP server, more complex audio pipeline, etc). I have snipped some repetitive errors/logs out for brevity but this is otherwise the full log

I (31) boot: ESP-IDF v5.1-1279-g4e88327130 2nd stage bootloader
I (31) boot: Multicore bootloader
I (31) boot: chip revision: v3.1
I (31) boot.esp32: SPI Speed      : 80MHz
I (31) boot.esp32: SPI Mode       : DIO
I (31) boot.esp32: SPI Flash Size : 16MB
I (32) boot: Enabling RNG early entropy source...
I (32) boot: Partition Table:
I (32) boot: ## Label            Usage          Type ST Offset   Length
I (33) boot:  0 nvs              WiFi data        01 02 00009000 00004000
I (33) boot:  1 otadata          OTA data         01 00 0000d000 00002000
I (34) boot:  2 phy_init         RF data          01 01 0000f000 00001000
I (34) boot:  3 ota_0            OTA app          00 10 00010000 00380000
I (34) boot:  4 ota_1            OTA app          00 11 00390000 00380000
I (35) boot:  5 storage          Unknown data     01 82 00710000 00800000
I (35) boot:  6 fctry            WiFi data        01 02 00f10000 00006000
I (36) boot:  7 coredump         Unknown data     01 03 00f16000 00013000
I (36) boot: End of partition table
I (72) esp_image: segment 0: paddr=00390020 vaddr=3f400020 size=7a7f0h (501744) map
I (224) esp_image: segment 1: paddr=0040a818 vaddr=3ff80063 size=00008h (     8) load
I (225) esp_image: segment 2: paddr=0040a828 vaddr=3ffbdb60 size=057f0h ( 22512) load
I (232) esp_image: segment 3: paddr=00410020 vaddr=400d0020 size=196f74h (1666932) map
I (736) esp_image: segment 4: paddr=005a6f9c vaddr=3ffc3350 size=00a3ch (  2620) load
I (737) esp_image: segment 5: paddr=005a79e0 vaddr=40080000 size=1bac8h (113352) load
I (777) esp_image: segment 6: paddr=005c34b0 vaddr=400c0000 size=00064h (   100) load
I (792) boot: Loaded app from partition at offset 0x390000
I (792) boot: Disabling RNG early entropy source...
I (793) cpu_start: Multicore app
I (793) quad_psram: This chip is ESP32-D0WD
I (793) esp_psram: Found 8MB PSRAM device
I (793) esp_psram: Speed: 80MHz
I (794) esp_psram: PSRAM initialized, cache is in low/high (2-core) mode.
W (794) esp_psram: Virtual address not enough for PSRAM, map as much as we can. 4MB is mapped
I (794) cpu_start: Pro cpu up.
I (794) cpu_start: Starting app cpu, entry point is 0x400816a8
0x400816a8: call_start_cpu1 at /COMPONENT_ESP_SYSTEM_DIR/port/cpu_start.c:157

I (779) cpu_start: App cpu up.
I (1268) esp_psram: SPI SRAM memory test OK
I (1278) cpu_start: Pro cpu start user code
I (1278) cpu_start: cpu freq: 240000000 Hz
I (1278) cpu_start: Application information:
I (1278) cpu_start: Project name:     Spokane
I (1279) cpu_start: App version:      v0.2.3
I (1279) cpu_start: ELF file SHA256:  fe5ff0de2775a570...
Warning: checksum mismatch between flashed and built applications. Checksum of built application is fa8f887574c19321190a1b76bebf07d48e78b01c6353a2ffa32f21ef80f29895
I (1279) cpu_start: ESP-IDF:          v5.1-1279-g4e88327130
I (1280) cpu_start: Min chip rev:     v3.0
I (1280) cpu_start: Max chip rev:     v3.99 
I (1280) cpu_start: Chip rev:         v3.1
I (1281) heap_init: Initializing. RAM available for dynamic allocation:
I (1281) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (1281) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (1282) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (1282) heap_init: At 3FFC83C8 len 00017C38 (95 KiB): DRAM
I (1282) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (1283) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (1283) heap_init: At 4009BAC8 len 00004538 (17 KiB): IRAM
I (1284) esp_psram: Adding pool of 4062K of PSRAM memory to heap allocator
I (1285) spi_flash: detected chip: gd
I (1285) spi_flash: flash io: dio
W (1286) i2s(legacy): legacy i2s driver is deprecated, please migrate to use driver/i2s_std.h, driver/i2s_pdm.h or driver/i2s_tdm.h
W (1286) ADC: legacy driver is deprecated, please migrate to `esp_adc/adc_oneshot.h`
I (1292) coexist: coex firmware version: b6d5e8c
I (1294) app_start: Starting scheduler on CPU0
I (1294) main_task: Started on CPU0
I (1294) app_start: Starting scheduler on CPU1
I (1294) main_task: Calling app_main()
I (1311) Spokane: Loaded WiFi SSID from NVS: RSI
I (1312) AUDIO_THREAD: The esp_periph task allocate stack on external memory
I (1315) esp_rmaker_work_queue: Work Queue created.
I (1320) wifi_init: rx ba win: 4
I (1320) wifi_init: tcpip mbox: 32
I (1321) wifi_init: udp mbox: 6
I (1321) wifi_init: tcp mbox: 6
I (1321) wifi_init: tcp tx win: 5744
I (1321) wifi_init: tcp rx win: 5744
I (1321) wifi_init: tcp mss: 1440
I (1321) wifi_init: WiFi/LWIP prefer SPIRAM
I (1323) phy_init: phy_version 4780,16b31a7,Sep 22 2023,20:42:16
I (1561) heap_metrics: free:0x35684 lfb:0x1aff0 min_free_ever:0x35218
I (1564) heap_metrics: ext_free:0x3e49c4 ext_lfb:0x3dfff0 ext_min_free_ever:0x3e4900
I (1565) wifi_metrics: Wi-Fi RSSI crossed threshold -51
I (1566) wifi_metrics: rssi:-51 min_rssi_ever:-51
I (1567) esp_insights: =========================================
I (1568) esp_insights: Insights enabled for Node ID 80646FFBD64C
I (1568) esp_insights: =========================================
W (1568) insights_transport: connect callback not set
I (1568) esp_rmaker_work_queue: RainMaker Work Queue task started.
I (1569) esp_insights: Scheduling Insights timer for 60 seconds.
I (1570) esp_insights: Insights metrics metadata changed
E (1572) Spokane: ESP-ADF:  v2.0-beta2-1267-ge7e421e3
I (1573) spiffs: Initializing SPIFFS
E (1575) esp-tls: couldn't get hostname for :client.insights.espressif.com: getaddrinfo() returns 202, addrinfo=0x0
E (1576) esp-tls: Failed to open new connection
E (1576) transport_base: Failed to open a new connection
E (1576) HTTP_CLIENT: Connection failed, sock < 0
E (1577) tport_https: esp_http_client_perform failed err:0x7002
--- snipped, above 5 lines repeat dozens of times ---
I (2685) esp_insights: Insights metrics metadata changed
E (2688) esp-tls: couldn't get hostname for :client.insights.espressif.com: getaddrinfo() returns 202, addrinfo=0x0
E (2690) esp-tls: Failed to open new connection
E (2691) transport_base: Failed to open a new connection
E (2691) HTTP_CLIENT: Connection failed, sock < 0
E (2691) tport_https: esp_http_client_perform failed err:0x7002
I (2705) esp_netif_handlers: sta ip: 192.168.1.108, mask: 255.255.255.0, gw: 192.168.1.6
I (3233) spiffs: Partition size: total: 7703441, used: 8534
E (3313) Spokane: Coming from a fresh OTA update. Starting update verification. WiFi = 0x01, Bluetooth = 0x02, DSP = 0x04
I (3521) dsp: [1fbc2][processConfigFile:147]   Reading config file '/spiffs/update_spokane.dspcfg'
--- snipped, large log from DSP config processing ---
I (3774) dsp: [1fcc0][processConfigFile:375]   DSP is ready to rumble
E (3782) Updater: Self test flag cleared: 0x4
E (3783) Updater: Self test flags still set: 0x3
I (3784) dsp: New target volume: 1
I (3785) AUD: [1.1] Start Bluetooth stack
I (3785) BTDM_INIT: BT controller compile version [ec4ac65]
I (3786) BTDM_INIT: Bluetooth MAC: 80:64:6f:fb:d6:4e
I (4476) AUD: Hello world. I am Spokane FBD64E
I (4477) AUD: [1.2] Create Bluetooth peripheral
I (4477) AUD: [1.3] Create raw stream to pass Bluetooth data into downmixer
I (4479) AUD: [2.1] Initialize ResampleUtil
I (4480) AUD: [2.2] Register resample_element to Bluetooth pipeline
I (4481) AUD: [3.0] Create file stream to read input data
I (4482) AUD: [3.1] Create wav decoder
I (4482) AUD: [3.2] Create raw stream to pass tone data into downmixer
I (4483) AUDIO_PIPELINE: link el->rb, el:0x3f81e038, tag:file, rb:0x3f81f4a4
I (4484) AUDIO_PIPELINE: link el->rb, el:0x3f81f1e8, tag:decoder, rb:0x3f82151c
I (4484) AUD: [4.0] Create pipeline_mix pipeline
I (4485) AUD: [4.1] Create down-mixer element
I (4485) AUD: [5.0] Create dual i2s stream to write data to codec chip
W (4487) i2s(legacy): APLL is occupied already, it is working at 45158386 Hz
I (4489) AUD: [5.1] Register stream_writer to downmix pipeline
I (4489) AUD: [5.2] Start codec chip
I (4500) dsp: New target volume: 70
I (4500) AUDIO_HAL: Codec mode is 2, Ctrl:1
I (4500) AUD: [5.3] Initialize A2DP stream reader
I (4501) AUDIO_THREAD: The audio_a2dp_stream_thread task allocate stack on external memory
I (4502) AUD: [5.4] Register stream_reader to Bluetooth pipeline
W (4502) BT_BTC: A2DP Enable with AVRC
I (4504) AUDIO_PIPELINE: link el->rb, el:0x3f8219fc, tag:bt, rb:0x3f821ba0
I (4511) A2DP_STREAM: Unhandled A2DP event: 4
I (4514) AUDIO_PIPELINE: link el->rb, el:0x3f81f0fc, tag:resample_element, rb:0x3f821fd4
I (4514) AUD: [6.0] Initialize Soft DSP
I (4515) AUD: [6.1] Register Soft DSP to audio pipeline
I (4515) AUD: [7] Link all pipeline elements together
I (4516) AUDIO_PIPELINE: link el->rb, el:0x3f8215d0, tag:mixer, rb:0x3f822148
I (4522) AUDIO_PIPELINE: link el->rb, el:0x3f822014, tag:dsp_x, rb:0x3f8221ac
I (4523) AUD: [8] Set up  event listener
I (4523) AUD: [8.1] Listening event from all elements of pipeline
I (4524) AUD: [8.2] Listening event from peripherals
I (4525) AUD: [8.3] Start audio_pipeline
I (4525) AUDIO_ELEMENT: [bt_raw-0x3f81e150] Element task created
I (4526) AUDIO_THREAD: The resample_element task allocate stack on internal memory
I (4526) AUDIO_ELEMENT: [resample_element-0x3f81f0fc] Element task created
I (4526) AUDIO_ELEMENT: [bt-0x3f8219fc] Element task created
I (4526) AUDIO_PIPELINE: Func:audio_pipeline_run, Line:359, MEM Total:3928552 Bytes, Inter:93176 Bytes, Dram:76248 Bytes

I (4527) AUDIO_ELEMENT: [resample_element] AEL_MSG_CMD_RESUME,state:1
I (4528) AUDIO_PIPELINE: Pipeline started
I (4528) AUDIO_THREAD: The mixer task allocate stack on external memory
I (4529) AUDIO_ELEMENT: [mixer-0x3f8215d0] Element task created
I (4530) AUDIO_THREAD: The i2s_w task allocate stack on internal memory
I (4530) AUDIO_ELEMENT: [i2s_w-0x3f8217bc] Element task created
I (4530) AUDIO_THREAD: The dsp_x task allocate stack on internal memory
I (4530) AUDIO_ELEMENT: [dsp_x-0x3f822014] Element task created
I (4531) AUDIO_PIPELINE: Func:audio_pipeline_run, Line:359, MEM Total:3906720 Bytes, Inter:83672 Bytes, Dram:66744 Bytes

I (4531) AUDIO_ELEMENT: [mixer] AEL_MSG_CMD_RESUME,state:1
I (4543) AUDIO_ELEMENT: [i2s_w] AEL_MSG_CMD_RESUME,state:1
I (4544) DUAL_I2S_STREAM: AUDIO_STREAM_WRITER
I (4544) AUDIO_ELEMENT: [dsp_x] AEL_MSG_CMD_RESUME,state:1
I (4544) AUDIO_PIPELINE: Pipeline started
I (4545) gpio: GPIO[36]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (4545) gpio: GPIO[4]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (4546) gpio: GPIO[27]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (4546) gpio: GPIO[13]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (4547) gpio: GPIO[33]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (4547) gpio: GPIO[2]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (4548) gpio: GPIO[32]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (4716) gpio: GPIO[23]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (4718) gpio: GPIO[34]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (4718) gpio: GPIO[14]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (4740) gpio: GPIO[39]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (5661) esp_insights: Insights metrics metadata changed
E (8439) Updater: Starting post-update file download to get new files I didn't know about before
I (8440) Updater: Using default URL base: https://spokane.apps.radiosound.com/assets/spokane-update/
I (8972) pktcomm_tcp_dsp_control: pktcomm_tcp_server task started
E (8982) Updater: Self test flag cleared: 0x1
I (8985) pktcomm_tcp_dsp_control: ... allocated socket

I (8987) pktcomm_tcp_dsp_control: ... socket bind done 

I (8987) pktcomm_tcp_dsp_control: BLE Adverts updated to include IP address (192.168.1.108)
W (8990) BT_BTM: BTM_BleWriteAdvData, Partial data write into ADV
W (8994) BT_BTM: BTM_BleWriteScanRsp, Partial data write into ADV
E (8986) Updater: Self test flags still set: 0x2
I (9026) SPP: ESP_SPP_INIT_EVT
I (9032) SPP: ESP_SPP_START_EVT
E (9152) BLE_CORE: init_ble_core initialize controller failed: ESP_ERR_INVALID_STATE
This likely indicates that the BT controller was initialized elsewhere.
I (9163) GATTS_GENERIC_HANDLER: REGISTER_APP_EVT, status 0, app_id 0

I (9165) GATTS_GENERIC_HANDLER: CREATE_SERVICE_EVT, status 0,  service_handle 40

I (9171) GATTS_GENERIC_HANDLER: SERVICE_START_EVT, status 0, service_handle 40

I (9174) GATTS_GENERIC_HANDLER: ADD_CHAR_EVT, status 0,  attr_handle 42, service_handle 40

I (9175) GATTS_GENERIC_HANDLER: ADD_DESCR_EVT, status 0, attr_handle 43, service_handle 40

I (9190) esp-x509-crt-bundle: Certificate validated
W (9199) BT_BTM: BTM_BleWriteAdvData, Partial data write into ADV
W (9222) console.repl: light sleep UART wakeup might not work at the configured baud rate
I (9224) uart: ESP_INTR_FLAG_IRAM flag not set while CONFIG_UART_ISR_IN_IRAM is enabled, flag updated
W (9222) BT_BTM: BTM_BleWriteScanRsp, Partial data write into ADV

Type 'help' to get the list of commands.
Use UP/DOWN arrows to navigate through command history.
Press TAB when typing command name to auto-complete.
I (9953) AUD: Checking NVS for last connected device...
                                                                                                                           I (9960) AUD: b8 27 eb 73 33 7a 
I (9978) AUD: Looking for last connected device...
W (9980) BT_APPL: reset flags
I (9988) AUD: b8 27 eb 73 33 7a 
I (9996) A2DP_STREAM: A2DP bd address:, [b8:27:eb:73:33:7a]
cli> W (10007) I2C_BUS: I2C bus has been already created, [port:0]
I (10023) AUD: [9] Listen for all pipeline events
I (10539) Updater: Saving file to /spiffs/update_beep.wav
I (11552) Updater: Writing 38462 bytes
I (12127) Updater: HTTP Status = 200, content_length = 38462
I (13091) esp-x509-crt-bundle: Certificate validated
I (14994) AUD: Looking for last connected device...
I (14997) AUD: b8 27 eb 73 33 7a 
W (15108) BT_SDP: SDP - Rcvd conn cnf with error: 0x4  CID 0x40

W (15110) BT_HCI: hcif conn complete: hdl 0xfff, st 0x4
W (15115) BT_BTC: BTA_AV_OPEN_EVT::FAILED status: 2

I (15119) A2DP_STREAM: A2DP bd address:, [b8:27:eb:73:33:7a]
I (15121) A2DP_STREAM: A2DP connection state =  DISCONNECTED
E (15126) AUD: [*] Bluetooth Audio Disconnected
I (18505) Updater: Saving file to /spiffs/update_error.wav
E (18997) Updater: Self test flags still set: 0x2
I (19481) Updater: Writing 192146 bytes
I (19999) AUD: Looking for last connected device...
I (20017) AUD: b8 27 eb 73 33 7a 
I (20019) A2DP_STREAM: A2DP bd address:, [b8:27:eb:73:33:7a]
W (21776) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
E (21926) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
W (22001) BT_APPL: new conn_srvc id:26, app_id:255
W (22007) BT_APPL: bta_dm_pm_ssr conn_srvc id:26, app_id:255
W (22012) BT_APPL: bta_dm_pm_ssr:2, lat:1200
I (22046) A2DP_STREAM: A2DP audio stream configuration, codec type 0
W (22185) BT_APPL: new conn_srvc id:19, app_id:0
W (22189) BT_APPL: bta_dm_pm_ssr conn_srvc id:26, app_id:255
W (22193) BT_APPL: bta_dm_pm_ssr conn_srvc id:19, app_id:0
W (22197) BT_APPL: bta_dm_pm_ssr:2, lat:1200
I (22223) A2DP_STREAM: Bluetooth configured, sample rate=48000
I (22366) A2DP_STREAM: Unhandled A2DP event: 5
I (22378) SPP: ESP_SPP_SRV_OPEN_EVT
I (22384) A2DP_STREAM: A2DP bd address:, [b8:27:eb:73:33:7a]
I (22394) A2DP_STREAM: A2DP connection state =  CONNECTED
E (22388) AUD: [*] Receive music info from Bluetooth, sample_rates=48000, bits=16, ch=2
I (22467) SPP: cmd = Version
I (22496) A2DP_STREAM: AVRC conn_state evt: state 1, [b8:27:eb:73:33:7a]
W (22528) A2DP_STREAM: AVRC ct remote features 25b
W (22551) A2DP_STREAM: AVRC tg remote features 25b, CT features 4f
I (22565) A2DP_STREAM: AVRC register event notification: 13, param: 0x0
I (22566) A2DP_STREAM: rn_param.volume:63
I (22528) AUD: Saving last connected device...
I (22729) Updater: HTTP Status = 200, content_length = 192146
E (23346) Updater: Self test flag cleared: 0x2
I (23348) Updater: Waiting for post-update task to finish
E (23349) AUD: [*] Bluetooth Audio Connected
I (23362) BT_LOG: bta_av_link_role_ok hndl:x41 role:1 conn_audio:x1 bits:1 features:x864b

W (23366) BT_APPL: bta_dm_pm_ssr conn_srvc id:26, app_id:255
W (23368) BT_APPL: bta_dm_pm_ssr conn_srvc id:19, app_id:0
W (23371) BT_APPL: bta_dm_pm_ssr:2, lat:1200
W (23374) BT_APPL: new conn_srvc id:19, app_id:1
E (23410) AUD: [*] Bluetooth Audio Started
I (23422) Spokane: Unmuting
I (23424) DSP_X: Filling output ring buffer with 35328 bytes
I (23463) AUD: DSP output rb: 69632 / 70560
I (24352) Updater: Waiting for post-update task to finish
I (24425) esp-x509-crt-bundle: Certificate validated
I (25366) Updater: Waiting for post-update task to finish
I (26373) Updater: Waiting for post-update task to finish
I (27387) Updater: Waiting for post-update task to finish
I (27488) adj: History [39424, 39424, 62464]: play faster (remove samples), new offset = 4 hz
I (28404) Updater: Waiting for post-update task to finish
E (28452) AUD: [*] Bluetooth Audio Suspended
I (28455) Spokane: Muting
I (29408) Updater: Waiting for post-update task to finish
I (30410) Updater: Waiting for post-update task to finish
I (31412) Updater: Waiting for post-update task to finish
I (31433) heap_metrics: free:0x5d98 lfb:0x31f0 min_free_ever:0x4f70
I (31440) heap_metrics: ext_free:0x357c00 ext_lfb:0x33fff0 ext_min_free_ever:0x34a244
I (31566) wifi_metrics: Wi-Fi RSSI crossed threshold -52
I (31569) wifi_metrics: rssi:-52 min_rssi_ever:-52
W (31580) BT_HCI: hci cmd send: sniff: hdl 0x81, intv(30 54)
W (31616) BT_HCI: hcif mode change: hdl 0x81, mode 2, intv 54, status 0x0
W (31802) BT_HCI: hcif ssr evt: st 0x0, hdl 0x81, tx_lat 1188 rx_lat 54
I (32422) Updater: Waiting for post-update task to finish
I (32541) Updater: Saving file to /spiffs/update_success.wav
I (33423) Updater: Waiting for post-update task to finish
I (33508) Updater: Writing 279750 bytes
I (34430) Updater: Waiting for post-update task to finish
I (35432) Updater: Waiting for post-update task to finish
I (36436) Updater: Waiting for post-update task to finish
I (37439) Updater: Waiting for post-update task to finish
I (37487) Updater: HTTP Status = 200, content_length = 279750
I (38509) Spokane: unlink status code 0
I (39004) Spokane: rename status code 0
I (39006) Spokane: DSP file saved to final location
I (39495) Spokane: unlink status code -1
I (39981) Spokane: rename status code 0
I (39983) Spokane: Renamed /spiffs/update_beep.wav to /spiffs/beep.wav
I (40474) Spokane: unlink status code -1
I (40958) Spokane: rename status code 0
I (40960) Spokane: Renamed /spiffs/update_error.wav to /spiffs/error.wav
I (41470) Spokane: unlink status code -1
I (41955) Spokane: rename status code 0
I (41957) Spokane: Renamed /spiffs/update_success.wav to /spiffs/success.wav
E (41959) Spokane: Verified and saved update
I (41962) AUD: Playing /spiffs/success.wav
I (41965) Spokane: Unmuting
I (41969) AUDIO_THREAD: The file task allocate stack on internal memory
I (41974) AUDIO_ELEMENT: [file-0x3f81e038] Element task created
I (41979) AUDIO_THREAD: The decoder task allocate stack on external memory
I (41984) AUDIO_ELEMENT: [decoder-0x3f81f1e8] Element task created
I (41989) AUDIO_ELEMENT: [tone_raw-0x3f81f2d4] Element task created
I (41991) AUDIO_PIPELINE: Func:audio_pipeline_run, Line:359, MEM Total:3829188 Bytes, Inter:33768 Bytes, Dram:20956 Bytes

I (42000) AUDIO_ELEMENT: [file] AEL_MSG_CMD_RESUME,state:1
I (42002) FATFS_STREAM: File size: 279750 byte, file position: 0
I (42029) AUDIO_ELEMENT: [decoder] AEL_MSG_CMD_RESUME,state:1
I (42032) CODEC_ELEMENT_HELPER: The element is 0x3f81f1e8. The reserve data 2 is 0x0.
I (42035) WAV_DECODER: a new song playing
I (42055) AUDIO_PIPELINE: Pipeline started
I (42058) AUD: Waiting for pipeline finish event
W (43689) FATFS_STREAM: No more data, ret:0
I (43690) AUDIO_ELEMENT: IN-[file] AEL_IO_DONE,0
I (43735) AUDIO_ELEMENT: IN-[decoder] AEL_IO_DONE,-2
I (43736) DEC_WAV: Closed
I (43737) AUD: Tone finished
I (43743) AUD: Finished
W (43748) AUDIO_ELEMENT: [file] Element already stopped
I (43749) AUD: Tone stopped
W (43754) AUDIO_ELEMENT: [decoder] Element already stopped
I (43783) AUD: Waiting to mute to let tone finish
I (44293) Spokane: Muting
W (53272) BT_HCI: hci cmd send: unsniff: hdl 0x81
W (53279) BT_RFCOMM: port_rfc_closed RFCOMM connection in server:1 state 2 closed: Peer connection failed (res: 16)
W (53287) BT_HCI: hcif disc complete: hdl 0x81, rsn 0x8
E (53289) BT_APPL: bta_dm_pm_sniff BTM_SetPowerMode() returns ERROR status=7
E (53294) BT_APPL: bta_dm_pm_sniff BTM_SetPowerMode() returns ERROR status=7
W (53298) BT_AVCT: ccb 1 not allocated
I (53309) SPP: ESP_SPP_CLOSE_EVT
I (53313) A2DP_STREAM: A2DP bd address:, [b8:27:eb:73:33:7a]
I (53318) A2DP_STREAM: A2DP connection state =  DISCONNECTED
I (53319) A2DP_STREAM: AVRC conn_state evt: state 0, [00:00:00:00:00:00]
E (53319) AUD: [*] Bluetooth Audio Disconnected
FEX 1 8
I (55031) AUD: Looking for last connected device...
W (55036) BT_APPL: reset flags
I (55041) AUD: b8 27 eb 73 33 7a 
I (55047) A2DP_STREAM: A2DP bd address:, [b8:27:eb:73:33:7a]
ASSERT_PARAM(2097152 0), in rwbt.c at line 393
Guru Meditation Error: Core  0 panic'ed (IllegalInstruction). Exception was unhandled.
Memory dump at 0x400936bc: f01d092d 00004136 f01d0000
0x400936bc: btdm_sleep_check_duration at /COMPONENT_BT_DIR/controller/esp32/bt.c:914

Core  0 register dump:
PC      : 0x400936c3  PS      : 0x00060b34  A0      : 0x80085c8a  A1      : 0x3ffbedf4  
0x400936c3: r_assert at /COMPONENT_BT_DIR/controller/esp32/bt.c:1849

A2      : 0x00000000  A3      : 0x00200000  A4      : 0x00000000  A5      : 0x3f43125c  
A6      : 0x00000189  A7      : 0xfffffffc  A8      : 0x8000814b  A9      : 0x3ffbed64  
A10     : 0x00000000  A11     : 0x3ffbed87  A12     : 0x3ffbed33  A13     : 0x00000033  
A14     : 0x00000000  A15     : 0x3ffbed38  SAR     : 0x00000004  EXCCAUSE: 0x00000000  
EXCVADDR: 0x00000000  LBEG    : 0x4000c2e0  LEND    : 0x4000c2f6  LCOUNT  : 0x00000000  
0x4000c2e0: memcpy in ROM

0x4000c2f6: memcpy in ROM

Backtrace: 0x400936c0:0x3ffbedf4 |<-CORRUPTED
0x400936c0: r_assert at /COMPONENT_BT_DIR/controller/esp32/bt.c:1848

ELF file SHA256: fe5ff0de2775a570
Warning: checksum mismatch between flashed and built applications. Checksum of built application is fa8f887574c19321190a1b76bebf07d48e78b01c6353a2ffa32f21ef80f29895

Rebooting...

Here is a very long log with only a small snippet taken out in the middle of the session as I had exited the monitor temporarily. This time the ELF SHA matches.

Of particular note, I observed FEX 1 8 being printed several times just before the crash.

log-esp-idf-issue-10555-long.txt

@ftab Please try if this lib can solve the problem. Please let me know the test results, thanks. libbtdm_app_6511e45.a.txt

Thanks. I have installed the library and am checking with both a LyraT and my custom board. I will report back with my findings.

I have not had the crash in the last couple of weeks, but I also have not had the crash with the production builds either (using the original library in v5.1.2 as per the log a few weeks ago). Continuing to test.

@xiongweichao I am afraid I spoke too soon 😞

ASSERT_PARAM(1024 0), in rwbt.c at line 393

The full log is too large to post (came from several hours of test, and has some irrelevant logs from our application every 500ms)

This happened a few seconds after the Bluetooth stream suddenly stopped and the device apparently disconnected unexpectedly

I will dust off one of my previous automated tests on a pair of LyraT boards to continue trying to get a reliable reproduction

This commit fixes this issue.

espressif / esp-idf