Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[TW#24578] A2DP SINK example not working with notebook, but with phone #2191

Closed
pad52 opened this issue Jul 13, 2018 · 8 comments
Closed

[TW#24578] A2DP SINK example not working with notebook, but with phone #2191

pad52 opened this issue Jul 13, 2018 · 8 comments

Comments

@pad52
Copy link

pad52 commented Jul 13, 2018

Environment

  • Core: [ESP-WROOM32|ESP32]
  • IDF version: 1e40891c
  • Development Env: [Eclipse]
  • Operating System: [MacOS]
  • Power Supply: [external 3.3V]

Problem Description

In last esp-idf the sink example works with (some) phone but not with (some) notebooks.
If I try to connect some notebook (I tried with two) to play sound with Bluetooth A2DP the connection happens but no sound, after a little I get Disconnected.
My notebook is using OSX, the other notebook that I tried was Windows, and got the same problem.

With an Android Phone everything works as expected.

Expected Behavior

In esp-idf c1c49b6 I got no problems regardless of the device I was using, everything just works.

Actual Behavior

This is the log, turning on the A2DP and AVRCP debug asserts in menuconfig:

USING A NOTEBOOK:

I (12039) BT_AV: Audio player configured, sample rate=44100
W (12069) BT_APPL: new conn_srvc id:19, app_id:0
I (12069) BT_AV: A2DP connection state: Connected, [f0:b4:79:0c:fc:b5]
I (12069) BT_AVRC: AVRC_FindService uuid: 110e
I (12119) BT_AVRC: avrc_sdp_cback status: 0
D (12119) BT_AVRC: AVRC_Open role: 0, control:3 status:0, handle:1
I (12219) BT_AV: AVRC conn_state evt: state 1, [f0:b4:79:0c:fc:b5]
I (12219) BT_AV: AVRC remote features 249
I (12219) BT_AVRC: AVRC_BldCommand: pdu=20 status=4
I (12229) BT_AVRC: avrc_bld_init_cmd_buffer: pdu=20, opcode=0
I (12229) BT_AVRC: avrc_bld_get_element_attr_cmd num_attr: 4
I (12239) BT_AVRC: avrc_bld_get_element_attr_cmd attr_id: 1
I (12239) BT_AVRC: avrc_bld_get_element_attr_cmd attr_id: 2
I (12249) BT_AVRC: avrc_bld_get_element_attr_cmd attr_id: 3
I (12259) BT_AVRC: avrc_bld_get_element_attr_cmd attr_id: 6
I (12259) BT_AVRC: AVRC_BldCommand: returning 4
D (12269) BT_AVRC: AVRC_MsgReq handle = 1 label = 0 ctype = 1 len = 29
I (12279) BT_AVRC: AVRC_BldCommand: pdu=31 status=4
I (12279) BT_AVRC: avrc_bld_init_cmd_buffer: pdu=31, opcode=0
D (12289) BT_AVRC: avrc_msg_cback handle:1, ctype:9, offset:12, len: 50
D (12289) BT_AVRC: pkt_type 0
I (12299) BT_AVRC: avrc_bld_vol_change
I (12299) BT_AVRC: AVRC_BldCommand: returning 4
D (12309) BT_AVRC: AVRC_MsgReq handle = 1 label = 1 ctype = 3 len = 9
D (12319) BT_AVRC: avrc_msg_cback handle:1, ctype:15, offset:12, len: 19
D (12319) BT_AVRC: pkt_type 0
D (35089) BT_AVRC: AVRC_Close handle:1
W (35089) BT_AVCT: ccb 1 not allocated
I (35089) BT_AV: A2DP connection state: Disconnected, [f0:b4:79:0c:fc:b5]
I (35099) BT_AV: AVRC conn_state evt: state 0, [f0:b4:79:0c:fc:b5]

USING A PHONE:

I (94139) BT_AV: Audio player configured, sample rate=44100
W (94179) BT_APPL: new conn_srvc id:19, app_id:0
I (94179) BT_AV: A2DP connection state: Connected, [f8:32:e4:d1:b5:b4]
I (94179) BT_AVRC: AVRC_FindService uuid: 110e
I (94229) BT_AVRC: avrc_sdp_cback status: 0
D (94229) BT_AVRC: AVRC_Open role: 0, control:3 status:0, handle:1
I (94289) BT_AV: AVRC conn_state evt: state 1, [f8:32:e4:d1:b5:b4]
I (94289) BT_AV: AVRC remote features 4b
I (94289) BT_AVRC: AVRC_BldCommand: pdu=20 status=4
I (94299) BT_AVRC: avrc_bld_init_cmd_buffer: pdu=20, opcode=0
I (94309) BT_AVRC: avrc_bld_get_element_attr_cmd num_attr: 4
I (94309) BT_AVRC: avrc_bld_get_element_attr_cmd attr_id: 1
I (94319) BT_AVRC: avrc_bld_get_element_attr_cmd attr_id: 2
I (94329) BT_AVRC: avrc_bld_get_element_attr_cmd attr_id: 3
I (94329) BT_AVRC: avrc_bld_get_element_attr_cmd attr_id: 6
I (94339) BT_AVRC: AVRC_BldCommand: returning 4
D (94349) BT_AVRC: AVRC_MsgReq handle = 1 label = 0 ctype = 1 len = 29
I (94349) BT_AVRC: AVRC_BldCommand: pdu=31 status=4
I (94359) BT_AVRC: avrc_bld_init_cmd_buffer: pdu=31, opcode=0
I (94359) BT_AVRC: avrc_bld_vol_change
I (94369) BT_AVRC: AVRC_BldCommand: returning 4
D (94369) BT_AVRC: AVRC_MsgReq handle = 1 label = 1 ctype = 3 len = 9
D (94389) BT_AVRC: avrc_msg_cback handle:1, ctype:12, offset:12, len: 75
D (94389) BT_AVRC: pkt_type 0
I (94389) BT_AV: AVRC metadata rsp: attribute id 0x1, Esodo
D (94399) BT_AVRC: avrc_msg_cback handle:1, ctype:15, offset:12, len: 19
D (94399) BT_AVRC: pkt_type 0
I (94409) BT_AV: AVRC metadata rsp: attribute id 0x2, 99 Posse
I (94409) BT_AV: AVRC metadata rsp: attribute id 0x4, Curre Curre Guaglio
I (94419) BT_AV: AVRC metadata rsp: attribute id 0x20,
I (145099) BT_LOG: bta_av_link_role_ok hndl:x41 role:1 conn_audio:x1 bits:1 features:x824b

W (145099) BT_APPL: new conn_srvc id:19, app_id:1
I (145109) BT_AV: A2DP audio state: Started
I (147199) BT_AV: Audio packet count 100
I (149209) BT_AV: Audio packet count 200
I (151169) BT_AV: Audio packet count 300

Steps to repropduce

Update to esp-idf 1e40891c
make & flash a2dp sink example

I'm using an external audio i2s codec.

@pufstudio
Copy link
Contributor

A new Secure Simple Pairing module was recently added to idf and it's enabled by default in A2DP example.
Try turning SSP in Bluetooth settings with menuconfig.

If I understood you correctly it was working properly with notebook some time ago...
I have a different experience however, it's never working on Windows or macOS, only on phones.

@FayeY FayeY changed the title A2DP SINK example not working with notebook, but with phone [TW#24578] A2DP SINK example not working with notebook, but with phone Jul 26, 2018
@pc-coholic
Copy link

pc-coholic commented Aug 4, 2018

I am facing the exact same issue - only that in my case it's a Amazon FireTV Stick that is disconnecting.

For the record, disabling SSP with menuconfig is unfortunately not yielding any difference for me.

Update: Apparently I made a mistake running menuselect - or there was something else wrong... With the current master (1c7a8b3) now both version (with and without SSP) work for me...

@pad52
Copy link
Author

pad52 commented Aug 29, 2018

Upgraded esp-idf to cc8ad72:

Now with Notebook (OSX and Win7) I have no problem,
with Android based phone (6.0.1 and 8.0), no problem but with IPhone ESP32 Crashed during Pairing.
I suppose is SSP Related Bug.

Here is the trace:

I (184) boot: compile time 16:33:26
I (189) boot: Enabling RNG early entropy source...
I (206) boot: SPI Speed      : 40MHz
I (219) boot: SPI Mode       : DIO
I (231) boot: SPI Flash Size : 4MB
I (244) boot: Partition Table:
I (255) boot: ## Label            Usage          Type ST Offset   Length
I (278) boot:  0 nvs              WiFi data        01 02 00009000 00006000
I (301) boot:  1 phy_init         RF data          01 01 0000f000 00001000
I (325) boot:  2 factory          factory app      00 00 00010000 00100000
I (348) boot: End of partition table
I (361) esp_image: segment 0: paddr=0x00010020 vaddr=0x3f400020 size=0x284d4 (165076) map
I (745) esp_image: segment 1: paddr=0x000384fc vaddr=0x3ffbdb60 size=0x02f18 ( 12056) load
I (776) esp_image: segment 2: paddr=0x0003b41c vaddr=0x3ffc0a78 size=0x00000 (     0) load
I (778) esp_image: segment 3: paddr=0x0003b424 vaddr=0x40080000 size=0x00400 (  1024) load
0x40080000: _WindowOverflow4 at /Users/pad/micro/esp32/esp-idf-dev/components/freertos/xtensa_vectors.S:1685

I (803) esp_image: segment 4: paddr=0x0003b82c vaddr=0x40080400 size=0x047e4 ( 18404) load
I (875) esp_image: segment 5: paddr=0x00040018 vaddr=0x400d0018 size=0x8c9f4 (575988) map
0x400d0018: _flash_cache_start at ??:?

I (2118) esp_image: segment 6: paddr=0x000cca14 vaddr=0x40084be4 size=0x0d2a4 ( 53924) load
0x40084be4: huart_flow_on at ??:?

I (2258) esp_image: segment 7: paddr=0x000d9cc0 vaddr=0x400c0000 size=0x00000 (     0) load
I (2260) esp_image: segment 8: paddr=0x000d9cc8 vaddr=0x50000000 size=0x00000 (     0) load
I (2344) boot: Loaded app from partition at offset 0x10000
I (2344) boot: Disabling RNG early entropy source...
I (2348) cpu_start: Pro cpu up.
I (2357) cpu_start: Starting app cpu, entry point is 0x40081024
0x40081024: call_start_cpu1 at /Users/pad/micro/esp32/esp-idf-dev/components/esp32/cpu_start.c:226

I (1) cpu_start: App cpu up.
I (2391) heap_init: Initializing. RAM available for dynamic allocation:
I (2411) heap_init: At 3FFAFF10 len 000000F0 (0 KiB): DRAM
I (2430) heap_init: At 3FFB6388 len 00001C78 (7 KiB): DRAM
I (2449) heap_init: At 3FFB9A20 len 00004108 (16 KiB): DRAM
I (2468) heap_init: At 3FFBDB5C len 00000004 (0 KiB): DRAM
I (2487) heap_init: At 3FFCF348 len 00010CB8 (67 KiB): DRAM
I (2506) heap_init: At 3FFE0440 len 00003BC0 (14 KiB): D/IRAM
I (2526) heap_init: At 3FFE4350 len 0001BCB0 (111 KiB): D/IRAM
I (2546) heap_init: At 40091E88 len 0000E178 (56 KiB): IRAM
I (2566) cpu_start: Pro cpu start user code
I (181) cpu_start: Starting scheduler on PRO CPU.
I (0) cpu_start: Starting scheduler on APP CPU.
I (224) I2S: DMA Malloc info, datalen=blocksize=240, dma_buf_count=6
I (224) I2S: PLL_D2: Req RATE: 44100, real rate: 44642.000, BITS: 16, CLKM: 14, BCK: 8, MCLK: 11289966.924, SCLK: 1428544.000000, diva: 64, divb: 11
I (234) BTDM_INIT: BT controller compile version [b2b2ea8]

I (244) system_api: Base MAC address is not set, read default base MAC address from BLK0 of EFUSE
I (314) phy: phy_version: 3960, 5211945, Jul 18 2018, 10:40:07, 0, 0
I (12414) BT_AV: authentication success: iPhone di Eugenia
I (12424) BT_AV: c0 f2 fb cc f6 2e
I (12864) BT_AV: ESP_BT_GAP_CFM_REQ_EVT Please compare the numeric value: 346430
Task watchdog got triggered. The following tasks did not reset the watchdog in time:
 - IDLE (CPU 0)
Tasks currently running:
CPU 0: btuT
CPU 1: IDLE ```

@Elektrik1
Copy link

I do have same issues on BT disconnecting occasionally with such log:

I (16727) BTDM_INIT: BT controller compile version [46a064b]
I (16727) system_api: Base MAC address is not set, read default base MAC address
from BLK0 of EFUSE
I (16877) phy: phy_version: 3960, 5211945, Jul 18 2018, 10:40:07, 0, 2
CMD: 53 2c e4 1b (OK)
E (28367) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (28367) BT_AV: A2DP connection state: Connecting, [08:21:ef:a4:97:eb]
I (28387) BT_AV: A2DP audio stream configuration, codec type 0
I (28387) I2S: PLL_D2: Req RATE: 44100, real rate: 44642.000, BITS: 16, CLKM: 14
, BCK: 8, MCLK: 11289966.924, SCLK: 1428544.000000, diva: 64, divb: 11
I (28397) BT_AV: Configure audio player 21-15-2-35
I (28407) BT_AV: Audio player configured, sample rate=44100
W (28437) BT_APPL: new conn_srvc id:19, app_id:0
I (28437) BT_AV: A2DP connection state: Connected, [08:21:ef:a4:97:eb]
I (28517) BT_AV: AVRC conn_state evt: state 1, [08:21:ef:a4:97:eb]
I (28517) BT_AV: AVRC remote features 24b
W (36247) BT_AVCT: ccb 1 not allocated
I (36247) BT_AV: A2DP connection state: Disconnected, [08:21:ef:a4:97:eb]

tried reconnecting

I (36247) BT_AV: AVRC conn_state evt: state 0, [08:21:ef:a4:97:eb]
E (55237) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (55237) BT_AV: A2DP connection state: Connecting, [08:21:ef:a4:97:eb]
I (55307) BT_AV: A2DP audio stream configuration, codec type 0
I (55307) I2S: PLL_D2: Req RATE: 44100, real rate: 44642.000, BITS: 16, CLKM: 14
, BCK: 8, MCLK: 11289966.924, SCLK: 1428544.000000, diva: 64, divb: 11
I (55317) BT_AV: Configure audio player 21-15-2-35
I (55317) BT_AV: Audio player configured, sample rate=44100
W (55427) BT_APPL: new conn_srvc id:19, app_id:0
I (55427) BT_AV: A2DP connection state: Connected, [08:21:ef:a4:97:eb]
I (55667) BT_AV: AVRC conn_state evt: state 1, [08:21:ef:a4:97:eb]
I (55667) BT_AV: AVRC remote features 24b
I (56887) BT_LOG: bta_av_link_role_ok hndl:x41 role:1 conn_audio:x1 bits:1 featu
res:x824b
W (56887) BT_APPL: new conn_srvc id:19, app_id:1
I (56897) BT_AV: A2DP audio state: Started
I (219007) BT_AV: AVRC event notification: 2, param: 0

Happens occasionally in random order, tired most configuration combinations, (core0/1, BTDM, BR/EDR only, BT stack sizes and priority combinations), with no effect. Unfortunately can't describe how to reproduce this random situation

@blueMoodBHD
Copy link
Collaborator

Hi @pad52 @pufstudio @pc-coholic @Elektrik1

  1. About the problem that disconnect after connected. We find it Will only appear on specific versions of Apple devices(mac: 10.12.5, iphone: 11.4). Update the system of Apple devices will fix it.
  2. About the problem of watchdog timeout of BTU task, it is a bug of ESP-IDF, I will fixed it, soon.
    Thanks

igrr pushed a commit that referenced this issue Sep 30, 2018
…ackport 3.1)

A cherry-pick of MR !3366

Create a new pending queue, then re-submit pending requests in old pending queue,preventing new events being inserted into it.

Closes #2191
@igrr igrr closed this as completed in 15fae99 Oct 4, 2018
@Elektrik1
Copy link

@blueMoodBHD, this is happening for me on Android device (galaxy S7, 8.0 Oreo), and latest checkout does not solve this issue.

I (7796) BT_AV: A2DP connection state: Connecting, [08:21:ef:a4:97:eb]
E (8426) BT_APPL: bta_av_rc_create ACP handle exist for shdl:0
I (8466) BT_AV: A2DP audio stream configuration, codec type 0
I (8466) I2S: PLL_D2: Req RATE: 44100, real rate: 44642.000, BITS: 16, CLKM: 14,
BCK: 8, MCLK: 11289966.924, SCLK: 1428544.000000, diva: 64, divb: 11
I (8476) BT_AV: Configure audio player 21-15-2-35
I (8486) BT_AV: Audio player configured, sample rate=44100
W (8566) BT_APPL: new conn_srvc id:19, app_id:0
I (8566) BT_AV: A2DP connection state: Connected, [08:21:ef:a4:97:eb]
I (8576) I2S: PLL_D2: Req RATE: 44100, real rate: 44642.000, BITS: 16, CLKM: 14,
BCK: 8, MCLK: 11289966.924, SCLK: 1428544.000000, diva: 64, divb: 11
I (8646) BT_AV: AVRC conn_state evt: state 1, [08:21:ef:a4:97:eb]
I (8646) BT_AV: AVRC remote features 24b
I (8676) I2S: PLL_D2: Req RATE: 44100, real rate: 44642.000, BITS: 16, CLKM: 14,
BCK: 8, MCLK: 11289966.924, SCLK: 1428544.000000, diva: 64, divb: 11
E (11676) BT_APPL: bta_dm_pm_btm_status hci_status=12
W (41736) BT_AVCT: ccb 1 not allocated
I (41736) BT_AV: A2DP connection state: Disconnected, [08:21:ef:a4:97:eb]

@blueMoodBHD
Copy link
Collaborator

@Elektrik1 We find a bug in sniff mode, it will disconnect after enter sniff mode. we will fix it, soon.

For now, if it is a Android device, turn off and turn on the Bluetooth will fix it. And if it is a iphone device, restart your phone will fix it.

catalinio pushed a commit to catalinio/pycom-esp-idf that referenced this issue Jun 28, 2019
Create a new pending queue, then re-submit pending requests in old pending queue,preventing new events being inserted into it.

Closes espressif/esp-idf#2191
catalinio pushed a commit to catalinio/pycom-esp-idf that referenced this issue Jun 28, 2019
…ackport 3.1)

A cherry-pick of MR !3366

Create a new pending queue, then re-submit pending requests in old pending queue,preventing new events being inserted into it.

Closes espressif/esp-idf#2191
@crespum
Copy link
Contributor

crespum commented Jul 17, 2019

I'm still experiencing this issue with IDF 3.2. Has it really been fixed?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

6 participants