search

espressif / esp-idf

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

esp_a2d_sink_connect takes a long time to fail out sometimes if HCI_ERR_CONNECTION_EXISTS (IDFGH-12096) #13154

Open ftab opened 5 months ago

ftab commented 5 months ago

Answers checklist.

IDF version.

v5.1.2-691-g7380f96017

Espressif SoC revision.

ESP32-D0WD rev 1

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.

ESP32-LyraT v4.3

Power Supply used.

USB

What is the expected behavior?

Connect to my device or give an error message right away

What is the actual behavior?

Takes a minute to fail out sometimes

Steps to reproduce.

I tested with LyraT v4.3 board and an iPhone 15 Pro

I modified the pipeline_a2dp_sink_and_hfp example in esp-adf to have a connect loop that calls esp_a2d_sink_connect

From scratch without any existing copy of esp-adf:

  1. cd ~/esp
  2. git clone https://github.com/radiosound-com/esp-adf -b esp-bt-connect-bug --recursive
  3. esp-adf/esp-idf/install.sh
  4. export ADF_PATH=~/esp/esp-adf
  5. source esp-adf/esp-idf/export.sh
  6. cd esp-adf/examples/get-started/pipeline_a2dp_sink_and_hfp
  7. Modify line 369 of main/pipeline_a2dp_sink_and_hfp_example.c so that your device's address is set in the array (otherwise this will not connect to anything). Make sure your phone is in Bluetooth settings to get the pair prompt, if this device is not already paired to the LyraT.
  8. idf.py menuconfig and set flash size to 4 MB or larger, set Bluetooth debug logs on
  9. idf.py build flash monitor
  10. After the device is connected, hit the Reset button on LyraT. Repeat step 10

If you have esp-adf and esp-idf already set up:

  1. cd esp-adf/examples/get-started/pipeline_a2dp_sink_and_hfp
  2. Use this copy of pipeline_a2dp_sink_and_hfp_example.c but modify line 369 so that your device's address is set in the array (otherwise this will not connect to anything). Make sure your phone is in Bluetooth settings to get the pair prompt, if this device is not already paired to the LyraT.
  3. idf.py menuconfig and set flash size to 4 MB or larger, set Bluetooth debug logs on
  4. idf.py build flash monitor
  5. After the device is connected, hit the Reset button on LyraT. Repeat step 5

Debug Logs.

I (0) cpu_start: App cpu up.
I (416) cpu_start: Pro cpu start user code
I (416) cpu_start: cpu freq: 240000000 Hz
I (416) cpu_start: Application information:
I (416) cpu_start: Project name:     a2dp_sink_and_hfp_example
I (416) cpu_start: App version:      v2.6-91-g2f6d0460
I (417) cpu_start: Compile time:     Feb  9 2024 15:45:07
I (417) cpu_start: ELF file SHA256:  a2c20f2a489e39b1...
I (417) cpu_start: ESP-IDF:          v5.1.2-691-g7380f96017
I (418) cpu_start: Min chip rev:     v0.0
I (418) cpu_start: Max chip rev:     v3.99 
I (418) cpu_start: Chip rev:         v1.0
I (419) heap_init: Initializing. RAM available for dynamic allocation:
I (419) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (419) heap_init: At 3FFB7468 len 00000B98 (2 KiB): DRAM
I (420) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (420) heap_init: At 3FFCF220 len 00010DE0 (67 KiB): DRAM
I (420) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (421) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (421) heap_init: At 4009B0E8 len 00004F18 (19 KiB): IRAM
I (422) spi_flash: detected chip: generic
I (422) spi_flash: flash io: dio
I (423) coexist: coex firmware version: 77cd7f8
I (424) app_start: Starting scheduler on CPU0
I (424) main_task: Started on CPU0
I (424) app_start: Starting scheduler on CPU1
I (424) main_task: Calling app_main()
I (434) BLUETOOTH_EXAMPLE: [ 1 ] Create Bluetooth service
I (434) BTDM_INIT: BT controller compile version [a38dc5c]
I (434) BTDM_INIT: Bluetooth MAC: bc:dd:c2:d1:c6:6a
I (434) phy_init: phy_version 4791,2c4672b,Dec 20 2023,16:06:06
W (854) BT_BTC: btc_avrc_tg_set_rn_supported_evt failed: AVRC TG not yet initialized

W (854) BT_BTC: A2DP Enable with AVRC
I (864) BLUETOOTH_EXAMPLE: [ 2 ] Start codec chip
I (864) gpio: GPIO[19]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 
I (884) gpio: GPIO[21]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (884) ES8388_DRIVER: init,out:02, in:00
I (884) AUDIO_HAL: Codec mode is 2, Ctrl:1
I (894) BLUETOOTH_EXAMPLE: [ 3 ] Create audio pipeline for playback
I (894) BLUETOOTH_EXAMPLE: [3.1] Create i2s stream to write data to codec chip and read data from codec chip
I (894) BLUETOOTH_EXAMPLE: [3.2] Create Bluetooth stream
I (894) BLUETOOTH_EXAMPLE: [3.3] Register all elements to audio pipeline
I (894) BLUETOOTH_EXAMPLE: [3.4] Link it together [Bluetooth]-->bt_stream_reader-->i2s_stream_writer-->[codec_chip]
I (894) AUDIO_PIPELINE: link el->rb, el:0x3ffdf3bc, tag:bt, rb:0x3ffdf750
I (894) AUDIO_PIPELINE: link el->rb, el:0x3ffddc1c, tag:i2s_r, rb:0x3ffdf89c
I (894) BLUETOOTH_EXAMPLE: [ 4 ] Initialize peripherals
E (894) gpio: gpio_install_isr_service(500): GPIO isr service already installed
I (894) BLUETOOTH_EXAMPLE: [4.1] Initialize Touch peripheral
I (894) gpio: GPIO[36]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 
I (894) gpio: GPIO[39]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 
I (904) AUDIO_THREAD: The esp_periph task allocate stack on internal memory
I (904) BLUETOOTH_EXAMPLE: [4.2] Create Bluetooth peripheral
I (904) BLUETOOTH_EXAMPLE: [4.2] Start all peripherals
I (904) BLUETOOTH_EXAMPLE: [ 5 ] Set up  event listener
I (904) BLUETOOTH_EXAMPLE: [5.1] Listening event from all elements of pipeline
I (904) BLUETOOTH_EXAMPLE: [5.2] Listening event from peripherals
I (904) BLUETOOTH_EXAMPLE: [ 6 ] Start audio_pipeline
I (904) AUDIO_ELEMENT: [bt-0x3ffdf3bc] Element task created
I (904) AUDIO_THREAD: The i2s_w task allocate stack on internal memory
I (904) AUDIO_ELEMENT: [i2s_w-0x3ffdc6b4] Element task created
I (904) AUDIO_PIPELINE: Func:audio_pipeline_run, Line:359, MEM Total:99120 Bytes

I (904) AUDIO_ELEMENT: [i2s_w] AEL_MSG_CMD_RESUME,state:1
I (904) AUDIO_PIPELINE: Pipeline started
I (904) AUDIO_THREAD: The i2s_r task allocate stack on internal memory
I (904) AUDIO_ELEMENT: [i2s_r-0x3ffddc1c] Element task created
I (904) AUDIO_ELEMENT: [raw-0x3ffdd84c] Element task created
I (904) AUDIO_PIPELINE: Func:audio_pipeline_run, Line:359, MEM Total:91584 Bytes

I (904) AUDIO_ELEMENT: [i2s_r] AEL_MSG_CMD_RESUME,state:1
I (904) AUDIO_PIPELINE: Pipeline started
I (904) BLUETOOTH_EXAMPLE: [ 7 ] Listen for all pipeline events
I (914) BLUETOOTH_EXAMPLE: [ * ] Connect to my device
W (914) BT_APPL: reset flags
W (924) PERIPH_TOUCH: _touch_init
W (1814) BT_HCI: hcif conn complete: hdl 0x81, st 0xb
W (5654) BT_HCI: hcif conn complete: hdl 0x80, st 0x0
W (5754) BT_HCI: hcif link supv_to changed: hdl 0x80, supv_to 8000
I (5924) BLUETOOTH_EXAMPLE: [ * ] Connect to my device
E (5954) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (6044) BLUETOOTH_EXAMPLE: [ * ] Receive music info from Bluetooth, sample_rates=44100, bits=16, ch=2
I (6064) AUDIO_ELEMENT: [i2s_w] AEL_MSG_CMD_PAUSE
I (6074) AUDIO_ELEMENT: [i2s_w] AEL_MSG_CMD_RESUME,state:4
W (6164) BT_APPL: new conn_srvc id:19, app_id:0
W (6174) BLUETOOTH_EXAMPLE: [*] A2DP connected
I (29) boot: ESP-IDF v5.1.2-691-g7380f96017 2nd stage bootloader
I (29) boot: compile time Feb  9 2024 15:45:21
I (29) boot: Multicore bootloader
I (29) boot: chip revision: v1.0
I (30) boot.esp32: SPI Speed      : 80MHz
I (30) boot.esp32: SPI Mode       : DIO
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 00006000
I (32) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (32) boot:  2 factory          factory app      00 00 00010000 002dc6c0
I (33) boot: End of partition table
I (33) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=35344h (217924) map
I (99) esp_image: segment 1: paddr=0004536c vaddr=3ffbdb60 size=04ba8h ( 19368) load
I (106) esp_image: segment 2: paddr=00049f1c vaddr=40080000 size=060fch ( 24828) load
I (115) esp_image: segment 3: paddr=00050020 vaddr=400d0020 size=c7d84h (818564) map
I (362) esp_image: segment 4: paddr=00117dac vaddr=400860fc size=14fech ( 85996) load
I (406) boot: Loaded app from partition at offset 0x10000
I (406) boot: Disabling RNG early entropy source...
I (407) cpu_start: Multicore app
I (407) cpu_start: Pro cpu up.
I (407) cpu_start: Starting app cpu, entry point is 0x40081608
0x40081608: call_start_cpu1 at /Users/dennis/esp/esp-adf/esp-idf/components/esp_system/port/cpu_start.c:159

I (0) cpu_start: App cpu up.
I (416) cpu_start: Pro cpu start user code
I (416) cpu_start: cpu freq: 240000000 Hz
I (416) cpu_start: Application information:
I (416) cpu_start: Project name:     a2dp_sink_and_hfp_example
I (416) cpu_start: App version:      v2.6-91-g2f6d0460
I (417) cpu_start: Compile time:     Feb  9 2024 15:45:07
I (417) cpu_start: ELF file SHA256:  a2c20f2a489e39b1...
I (417) cpu_start: ESP-IDF:          v5.1.2-691-g7380f96017
I (418) cpu_start: Min chip rev:     v0.0
I (418) cpu_start: Max chip rev:     v3.99 
I (418) cpu_start: Chip rev:         v1.0
I (419) heap_init: Initializing. RAM available for dynamic allocation:
I (419) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (419) heap_init: At 3FFB7468 len 00000B98 (2 KiB): DRAM
I (420) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (420) heap_init: At 3FFCF220 len 00010DE0 (67 KiB): DRAM
I (420) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (421) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (421) heap_init: At 4009B0E8 len 00004F18 (19 KiB): IRAM
I (422) spi_flash: detected chip: generic
I (422) spi_flash: flash io: dio
I (423) coexist: coex firmware version: 77cd7f8
I (424) app_start: Starting scheduler on CPU0
I (424) main_task: Started on CPU0
I (424) app_start: Starting scheduler on CPU1
I (424) main_task: Calling app_main()
I (434) BLUETOOTH_EXAMPLE: [ 1 ] Create Bluetooth service
I (434) BTDM_INIT: BT controller compile version [a38dc5c]
I (434) BTDM_INIT: Bluetooth MAC: bc:dd:c2:d1:c6:6a
I (434) phy_init: phy_version 4791,2c4672b,Dec 20 2023,16:06:06
W (854) BT_BTC: btc_avrc_tg_set_rn_supported_evt failed: AVRC TG not yet initialized

W (854) BT_BTC: A2DP Enable with AVRC
I (874) BLUETOOTH_EXAMPLE: [ 2 ] Start codec chip
I (874) gpio: GPIO[19]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 
I (884) gpio: GPIO[21]| InputEn: 0| OutputEn: 1| OpenDrain: 0| Pullup: 0| Pulldown: 0| Intr:0 
I (884) ES8388_DRIVER: init,out:02, in:00
I (894) AUDIO_HAL: Codec mode is 2, Ctrl:1
I (894) BLUETOOTH_EXAMPLE: [ 3 ] Create audio pipeline for playback
I (894) BLUETOOTH_EXAMPLE: [3.1] Create i2s stream to write data to codec chip and read data from codec chip
I (894) BLUETOOTH_EXAMPLE: [3.2] Create Bluetooth stream
I (894) BLUETOOTH_EXAMPLE: [3.3] Register all elements to audio pipeline
I (894) BLUETOOTH_EXAMPLE: [3.4] Link it together [Bluetooth]-->bt_stream_reader-->i2s_stream_writer-->[codec_chip]
I (894) AUDIO_PIPELINE: link el->rb, el:0x3ffdf3bc, tag:bt, rb:0x3ffdf750
I (904) AUDIO_PIPELINE: link el->rb, el:0x3ffddc1c, tag:i2s_r, rb:0x3ffdf89c
I (904) BLUETOOTH_EXAMPLE: [ 4 ] Initialize peripherals
E (904) gpio: gpio_install_isr_service(500): GPIO isr service already installed
I (904) BLUETOOTH_EXAMPLE: [4.1] Initialize Touch peripheral
I (904) gpio: GPIO[36]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 
I (904) gpio: GPIO[39]| InputEn: 1| OutputEn: 0| OpenDrain: 0| Pullup: 1| Pulldown: 0| Intr:3 
I (904) AUDIO_THREAD: The esp_periph task allocate stack on internal memory
I (904) BLUETOOTH_EXAMPLE: [4.2] Create Bluetooth peripheral
I (904) BLUETOOTH_EXAMPLE: [4.2] Start all peripherals
I (904) BLUETOOTH_EXAMPLE: [ 5 ] Set up  event listener
I (904) BLUETOOTH_EXAMPLE: [5.1] Listening event from all elements of pipeline
I (904) BLUETOOTH_EXAMPLE: [5.2] Listening event from peripherals
I (904) BLUETOOTH_EXAMPLE: [ 6 ] Start audio_pipeline
I (904) AUDIO_ELEMENT: [bt-0x3ffdf3bc] Element task created
I (904) AUDIO_THREAD: The i2s_w task allocate stack on internal memory
I (904) AUDIO_ELEMENT: [i2s_w-0x3ffdc6b4] Element task created
I (904) AUDIO_PIPELINE: Func:audio_pipeline_run, Line:359, MEM Total:99120 Bytes

I (904) AUDIO_ELEMENT: [i2s_w] AEL_MSG_CMD_RESUME,state:1
I (904) AUDIO_PIPELINE: Pipeline started
I (904) AUDIO_THREAD: The i2s_r task allocate stack on internal memory
I (904) AUDIO_ELEMENT: [i2s_r-0x3ffddc1c] Element task created
I (904) AUDIO_ELEMENT: [raw-0x3ffdd84c] Element task created
I (904) AUDIO_PIPELINE: Func:audio_pipeline_run, Line:359, MEM Total:91584 Bytes

I (904) AUDIO_ELEMENT: [i2s_r] AEL_MSG_CMD_RESUME,state:1
I (904) AUDIO_PIPELINE: Pipeline started
I (904) BLUETOOTH_EXAMPLE: [ 7 ] Listen for all pipeline events
I (914) BLUETOOTH_EXAMPLE: [ * ] Connect to my device
W (914) BT_APPL: reset flags
W (924) PERIPH_TOUCH: _touch_init
W (2354) BT_HCI: hcif conn complete: hdl 0x81, st 0xb
I (5924) BLUETOOTH_EXAMPLE: [ * ] Connect to my device
I (10934) BLUETOOTH_EXAMPLE: [ * ] Connect to my device
I (15944) BLUETOOTH_EXAMPLE: [ * ] Connect to my device
I (20954) BLUETOOTH_EXAMPLE: [ * ] Connect to my device
I (25964) BLUETOOTH_EXAMPLE: [ * ] Connect to my device
I (30974) BLUETOOTH_EXAMPLE: [ * ] Connect to my device
I (35984) BLUETOOTH_EXAMPLE: [ * ] Connect to my device
I (40994) BLUETOOTH_EXAMPLE: [ * ] Connect to my device
I (46004) BLUETOOTH_EXAMPLE: [ * ] Connect to my device
I (51014) BLUETOOTH_EXAMPLE: [ * ] Connect to my device
I (56024) BLUETOOTH_EXAMPLE: [ * ] Connect to my device
W (60914) BT_BTC: BTA_AV_OPEN_EVT::FAILED status: 2

More Information.

Some resets it will reconnect after a few seconds, sometimes it will take a minute before reporting BTA_AV_OPEN_EVT::FAILED status: 2 and allowing another attempt to connect. The latter is the problem. It is annoying to the end user if the device resets and then takes more than a minute to reconnect. This happens up to 50% of the time in our tests so far (on our custom board, but with the same connection attempt method I added to this example)

shangke1112 commented 5 months ago

W (2354) BT_HCI: hcif conn complete: hdl 0x81, st 0xb

The reason for this problem is that the mobile phone rejected the connection of esp32 through LMP_NOT_ACCEPT. The error code is 0xb (connection already exists). It is speculated that the restart speed of esp32 is too fast, and the mobile phone has not yet disconnected; Then ESP32 initiated the connection again and was rejected by the phone. There is no good solution, I think you can try delaying a period of time before connecting.

ftab commented 5 months ago

try delaying a period of time before connecting.

@shangke1112 I added a five second delay before trying to connect initially, and it seems to be connecting more often, but then that means there's a longer wait at startup before it's connected in all cases, not just when restarting. This may be an acceptable workaround for now. But if I can avoid that 5 second delay I'd prefer to. It seems like the status response HCI_ERR_CONNECTION_EXISTS should cause the esp_a2d_sink_connect to fail right away, instead it takes 60 seconds. Is there no way to cancel that?

shangke1112 commented 5 months ago

I suggest that you can add a reset flag to control whether there is a delay .

It seems like the status response HCI_ERR_CONNECTION_EXISTS should cause the esp_a2d_sink_connect to fail right away, instead it takes 60 seconds. Is there no way to cancel that?

We will confirm how to solve this problem later.