a2dp media start event not happening with some SINKs in some times (IDFGH-9843)

[espradio]

Answers checklist.

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

General issue report

a2dp media start event not happening with some SINKs in some times. It works sometimes.
Issue is reproducible with ad2p_source app in the tree.(Just changing the SRC name)

working log:

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:6628
load:0x40078000,len:15060
load:0x40080400,len:3816
0x40080400: _init at ??:?

entry 0x40080698
I (27) boot: ESP-IDF v4.4.4-368-ga9c36f277f-dirty 2nd stage bootloader
I (27) boot: compile time 00:41:17
I (28) boot: chip revision: v3.0
I (32) boot.esp32: SPI Speed      : 40MHz
I (37) boot.esp32: SPI Mode       : DIO
I (41) boot.esp32: SPI Flash Size : 2MB
I (46) boot: Enabling RNG early entropy source...
I (51) boot: Partition Table:
I (55) boot: ## Label            Usage          Type ST Offset   Length
I (62) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (70) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (77) boot:  2 factory          factory app      00 00 00010000 00100000
I (85) boot: End of partition table
I (89) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=27e20h (163360) map
I (157) esp_image: segment 1: paddr=00037e48 vaddr=3ffbdb60 size=03f94h ( 16276) load
I (163) esp_image: segment 2: paddr=0003bde4 vaddr=40080000 size=04234h ( 16948) load
I (170) esp_image: segment 3: paddr=00040020 vaddr=400d0020 size=a4d7ch (675196) map
I (415) esp_image: segment 4: paddr=000e4da4 vaddr=40084234 size=13934h ( 80180) load
I (460) boot: Loaded app from partition at offset 0x10000
I (460) boot: Disabling RNG early entropy source...
I (472) cpu_start: Pro cpu up.
I (472) cpu_start: Starting app cpu, entry point is 0x40081200
0x40081200: call_start_cpu1 at /export/iradio/esp-idf/components/esp_system/port/cpu_start.c:148

I (0) cpu_start: App cpu up.
I (488) cpu_start: Pro cpu start user code
I (488) cpu_start: cpu freq: 160000000
I (488) cpu_start: Application information:
I (492) cpu_start: Project name:     a2dp_source
I (498) cpu_start: App version:      2e44d1b
I (503) cpu_start: Compile time:     Apr 11 2023 00:39:55
I (509) cpu_start: ELF file SHA256:  de307f73913015ec...
I (515) cpu_start: ESP-IDF:          v4.4.4-368-ga9c36f277f-dirty
I (522) cpu_start: Min chip rev:     v0.0
I (526) cpu_start: Max chip rev:     v3.99 
I (531) cpu_start: Chip rev:         v3.0
I (536) heap_init: Initializing. RAM available for dynamic allocation:
I (543) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (549) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (555) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (561) heap_init: At 3FFCB320 len 00014CE0 (83 KiB): DRAM
I (567) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (574) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (580) heap_init: At 40097B68 len 00008498 (33 KiB): IRAM
I (588) spi_flash: detected chip: gd
I (591) spi_flash: flash io: dio
W (595) spi_flash: Detected size(16384k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (609) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (655) BTDM_INIT: BT controller compile version [bb77498]
I (655) system_api: Base MAC address is not set
I (655) system_api: read default base MAC address from EFUSE
I (665) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (1345) BT_AV: Starting device discovery...
W (1355) BT_BTC: btc_avrc_tg_set_rn_supported_evt failed: AVRC TG not yet initialized

W (1355) BT_BTC: A2DP Enable with AVRC
I (1365) BT_AV: bt_app_av_sm_hdlr state: 1, event: 0x4
I (1375) BT_AV: event: 10
I (1375) BT_AV: event: 10
I (1385) BT_AV: event: 10
I (1385) BT_AV: event: 10
I (1385) BT_AV: Discovery started.
I (13165) BT_AV: Scanned device: e8:84:0e:10:ce:28
I (13165) BT_AV: --Class of Device: 0x340404
I (13165) BT_AV: --RSSI: -55
I (13165) BT_AV: Found a target device, address e8:84:0e:10:ce:28, name LIVE TECH MELODY
I (13175) BT_AV: Cancel device discovery ...
I (13185) BT_AV: Device discovery stopped.
I (13185) BT_AV: a2dp connecting to peer: LIVE TECH MELODY
W (13195) BT_APPL: reset flags
I (13195) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0x0
W (14575) BT_HCI: hcif conn complete: hdl 0x81, st 0x0
I (14575) BT_AV: event: 16
E (14695) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
W (14755) BT_APPL: new conn_srvc id:18, app_id:0
I (14755) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0x0
I (14755) BT_AV: a2dp connected
I (21345) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0xff00
I (21345) BT_AV: a2dp media ready checking ...
I (21345) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0x3
I (21345) BT_AV: a2dp media ready, starting ...
W (21355) BT_APPL: new conn_srvc id:18, app_id:1
I (21365) BT_LOG: bta_av_link_role_ok hndl:x41 role:0 conn_audio:x1 bits:1 features:x824b

I (21365) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0x3
I (21375) BT_AV: a2dp media start successfully.
I (21375) BT_AV: bt_app_av_sm_hdlr state: 5, event: 0x1

non working log:

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:6628
load:0x40078000,len:15060
load:0x40080400,len:3816
0x40080400: _init at ??:?

entry 0x40080698
I (27) boot: ESP-IDF v4.4.4-368-ga9c36f277f-dirty 2nd stage bootloader
I (27) boot: compile time 00:41:17
I (28) boot: chip revision: v3.0
I (32) boot.esp32: SPI Speed      : 40MHz
I (37) boot.esp32: SPI Mode       : DIO
I (41) boot.esp32: SPI Flash Size : 2MB
I (46) boot: Enabling RNG early entropy source...
I (51) boot: Partition Table:
I (55) boot: ## Label            Usage          Type ST Offset   Length
I (62) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (70) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (77) boot:  2 factory          factory app      00 00 00010000 00100000
I (85) boot: End of partition table
I (89) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=27e20h (163360) map
I (157) esp_image: segment 1: paddr=00037e48 vaddr=3ffbdb60 size=03f94h ( 16276) load
I (163) esp_image: segment 2: paddr=0003bde4 vaddr=40080000 size=04234h ( 16948) load
I (170) esp_image: segment 3: paddr=00040020 vaddr=400d0020 size=a4d7ch (675196) map
I (415) esp_image: segment 4: paddr=000e4da4 vaddr=40084234 size=13934h ( 80180) load
I (460) boot: Loaded app from partition at offset 0x10000
I (460) boot: Disabling RNG early entropy source...
I (472) cpu_start: Pro cpu up.
I (472) cpu_start: Starting app cpu, entry point is 0x40081200
0x40081200: call_start_cpu1 at /export/iradio/esp-idf/components/esp_system/port/cpu_start.c:148

I (0) cpu_start: App cpu up.
I (488) cpu_start: Pro cpu start user code
I (488) cpu_start: cpu freq: 160000000
I (488) cpu_start: Application information:
I (493) cpu_start: Project name:     a2dp_source
I (498) cpu_start: App version:      2e44d1b
I (503) cpu_start: Compile time:     Apr 11 2023 00:39:55
I (509) cpu_start: ELF file SHA256:  de307f73913015ec...
I (515) cpu_start: ESP-IDF:          v4.4.4-368-ga9c36f277f-dirty
I (522) cpu_start: Min chip rev:     v0.0
I (526) cpu_start: Max chip rev:     v3.99 
I (531) cpu_start: Chip rev:         v3.0
I (536) heap_init: Initializing. RAM available for dynamic allocation:
I (543) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (549) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (555) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (561) heap_init: At 3FFCB320 len 00014CE0 (83 KiB): DRAM
I (568) heap_init: At 3FFE0440 len 00003AE0 (14 KiB): D/IRAM
I (574) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (580) heap_init: At 40097B68 len 00008498 (33 KiB): IRAM
I (588) spi_flash: detected chip: gd
I (591) spi_flash: flash io: dio
W (595) spi_flash: Detected size(16384k) larger than the size in the binary image header(2048k). Using the size in the binary image header.
I (609) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (655) BTDM_INIT: BT controller compile version [bb77498]
I (655) system_api: Base MAC address is not set
I (655) system_api: read default base MAC address from EFUSE
I (665) phy_init: phy_version 4670,719f9f6,Feb 18 2021,17:07:07
I (1335) BT_AV: Starting device discovery...
W (1345) BT_BTC: btc_avrc_tg_set_rn_supported_evt failed: AVRC TG not yet initialized

W (1345) BT_BTC: A2DP Enable with AVRC
I (1355) BT_AV: bt_app_av_sm_hdlr state: 1, event: 0x4
I (1365) BT_AV: event: 10
I (1375) BT_AV: event: 10
I (1375) BT_AV: event: 10
I (1375) BT_AV: event: 10
I (1375) BT_AV: Discovery started.
I (11335) BT_AV: bt_app_av_sm_hdlr state: 1, event: 0xff00
I (14035) BT_AV: --RSSI: -80
I (14185) BT_AV: Device discovery failed, continue to discover...
I (16785) BT_AV: Scanned device: e8:84:0e:10:ce:28
I (16785) BT_AV: --Class of Device: 0x340404
I (16785) BT_AV: --RSSI: -52
I (16795) BT_AV: Found a target device, address e8:84:0e:10:ce:28, name LIVE TECH MELODY
I (16795) BT_AV: Cancel device discovery ...
I (16805) BT_AV: Device discovery stopped.
I (16805) BT_AV: a2dp connecting to peer: LIVE TECH MELODY
W (16815) BT_APPL: reset flags
I (16825) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0x0
I (21335) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0xff00
I (31335) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0xff00
W (38135) BT_SDP: SDP - Rcvd conn cnf with error: 0x8  CID 0x40

W (38135) BT_HCI: hcif conn complete: hdl 0x81, st 0x8
I (38135) BT_AV: event: 16
W (38145) BT_BTC: BTA_AV_OPEN_EVT::FAILED status: 2

I (38145) BT_AV: bt_app_av_sm_hdlr state: 3, event: 0x0
I (41335) BT_AV: bt_app_av_sm_hdlr state: 3, event: 0xff00
I (41335) BT_AV: a2dp connecting to peer: e8:84:0e:10:ce:28
I (41335) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0x0
W (46455) BT_SDP: SDP - Rcvd conn cnf with error: 0x4  CID 0x41

W (46465) BT_HCI: hcif conn complete: hdl 0xfff, st 0x4
I (46465) BT_AV: event: 16
W (46465) BT_BTC: BTA_AV_OPEN_EVT::FAILED status: 2

I (46475) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0x0
W (47825) BT_HCI: hcif conn complete: hdl 0x80, st 0x0
I (47835) BT_AV: event: 16
W (47835) BT_HCI: hcif link supv_to changed: hdl 0x80, supv_to 12800
E (47985) BT_BTM: tBTM_SEC_DEV:0x3ffd331c rs_disc_pending=0

E (48125) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (48135) BT_AV: bt_app_av_sm_hdlr state: 3, event: 0x0
W (48215) BT_APPL: new conn_srvc id:18, app_id:0
I (48215) BT_AV: bt_app_av_sm_hdlr state: 3, event: 0x0
I (51335) BT_AV: bt_app_av_sm_hdlr state: 3, event: 0xff00
I (51335) BT_AV: a2dp connecting to peer: e8:84:0e:10:ce:28
W (55415) BT_HCI: hci cmd send: sniff: hdl 0x80, intv(400 800)
W (55415) BT_HCI: hcif mode change: hdl 0x80, mode 0, intv 0, status 0x11
E (55415) BT_APPL: bta_dm_pm_btm_status hci_status=17
I (55425) BT_AV: ESP_BT_GAP_MODE_CHG_EVT mode: 0
I (61335) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0xff00
I (71335) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0xff00
I (81335) BT_AV: bt_app_av_sm_hdlr state: 3, event: 0xff00
I (81335) BT_AV: a2dp connecting to peer: e8:84:0e:10:ce:28
I (91335) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0xff00
I (101335) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0xff00
I (111335) BT_AV: bt_app_av_sm_hdlr state: 3, event: 0xff00
I (111335) BT_AV: a2dp connecting to peer: e8:84:0e:10:ce:28
I (121335) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0xff00
I (131335) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0xff00
I (141335) BT_AV: bt_app_av_sm_hdlr state: 3, event: 0xff00
I (141335) BT_AV: a2dp connecting to peer: e8:84:0e:10:ce:28
I (151335) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0xff00
I (161335) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0xff00
I (171335) BT_AV: bt_app_av_sm_hdlr state: 3, event: 0xff00
I (171335) BT_AV: a2dp connecting to peer: e8:84:0e:10:ce:28
I (181335) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0xff00
I (191335) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0xff00

[xiongweichao]

Hi @espradio ,

Can you help me to print the connection status here?

Thanks

[espradio]

Hi @xiongweichao
See patch and log

 /* AVRCP used transaction label */
@@ -400,6 +400,8 @@ static void bt_app_av_state_unconnected_hdlr(uint16_t event, void *param)
     /* handle the events of intrest in unconnected state */
     switch (event) {
     case ESP_A2D_CONNECTION_STATE_EVT:
+       a2d = (esp_a2d_cb_param_t *)(param);
+        ESP_LOGI(BT_AV_TAG, "########### %s state: %d, event: 0x%x connect_state=%d", __func__, s_a2d_state, event, a2d->conn_stat.state);
     case ESP_A2D_AUDIO_STATE_EVT:
     case ESP_A2D_AUDIO_CFG_EVT:
     case ESP_A2D_MEDIA_CTRL_ACK_EVT:
@@ -413,11 +415,6 @@ static void bt_app_av_state_unconnected_hdlr(uint16_t event, void *param)
         s_connecting_intv = 0;
         break;
     }
@@ -433,6 +430,7 @@ static void bt_app_av_state_connecting_hdlr(uint16_t event, void *param)
     switch (event) {
     case ESP_A2D_CONNECTION_STATE_EVT: {
         a2d = (esp_a2d_cb_param_t *)(param);
+        ESP_LOGI(BT_AV_TAG, "### connect state=%d", a2d->conn_stat.state);
         if (a2d->conn_stat.state == ESP_A2D_CONNECTION_STATE_CONNECTED) {

I (16847) BT_AV: a2dp connecting to peer: LIVE TECH MELODY
W (16857) BT_APPL: reset flags
I (16857) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0x0
I (16857) BT_AV: ### connect state=1
I (21367) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0xff00
W (21987) BT_SDP: SDP - Rcvd conn cnf with error: 0x4  CID 0x40
W (21987) BT_HCI: hcif conn complete: hdl 0xfff, st 0x4
I (21987) BT_AV: event: 16
W (21997) BT_BTC: BTA_AV_OPEN_EVT::FAILED status: 2
I (21997) BT_AV: bt_app_av_sm_hdlr state: 4, event: 0x0
I (22007) BT_AV: ### connect state=0
W (23367) BT_HCI: hcif conn complete: hdl 0x80, st 0x0
I (23367) BT_AV: event: 16
W (23377) BT_HCI: hcif link supv_to changed: hdl 0x80, supv_to 12800
E (23517) BT_BTM: tBTM_SEC_DEV:0x3ffd48f8 rs_disc_pending=0

E (23677) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (23677) BT_AV: bt_app_av_sm_hdlr state: 3, event: 0x0
I (23677) BT_AV: ########### bt_app_av_state_unconnected_hdlr state: 3, event: 0x0 connect_state=1
W (23737) BT_APPL: new conn_srvc id:18, app_id:0
I (23737) BT_AV: bt_app_av_sm_hdlr state: 3, event: 0x0
I (23737) BT_AV: ########### bt_app_av_state_unconnected_hdlr state: 3, event: 0x0 connect_state=2
W (30937) BT_HCI: hci cmd send: sniff: hdl 0x80, intv(400 800)
W (30947) BT_HCI: hcif mode change: hdl 0x80, mode 0, intv 0, status 0x11
E (30947) BT_APPL: bta_dm_pm_btm_status hci_status=17
I (30947) BT_AV: ESP_BT_GAP_MODE_CHG_EVT mode: 0
I (31367) BT_AV: bt_app_av_sm_hdlr state: 3, event: 0xff00

[xiongweichao]

Hi @espradio ,

I think you can add this code too.

        a2d = (esp_a2d_cb_param_t *)(param);
        if (a2d->conn_stat.state == ESP_A2D_CONNECTION_STATE_CONNECTED) {
            ESP_LOGI(BT_AV_TAG, "a2dp connected");
            s_a2d_state =  APP_AV_STATE_CONNECTED;
            s_media_state = APP_AV_MEDIA_STATE_IDLE;
            esp_bt_gap_set_scan_mode(ESP_BT_NON_CONNECTABLE, ESP_BT_NON_DISCOVERABLE);
        }

Thanks

[espradio]

Yes. That works.

[espradio]

Will you be merging this example update?