Bluetooth HFP AG over HCI, outgoing SCO link drops data

craig9yzz
Posts: 5
Joined: Thu May 26, 2022 2:11 pm

Bluetooth HFP AG over HCI, outgoing SCO link drops data

Postby craig9yzz » Fri May 27, 2022 8:02 pm

IDF v4.3.2 - v4.4.1
Hardware: ESP32-WROOM-32E module (ESP32-D0WD-V3 + 16MB flash)
https://espressif.com/sites/default/fil ... eet_en.pdf

I'm using the Bluetooth HFP AG profile in IDF v4.3.2 to connect a headset with WBS audio. In my application I'm getting very choppy outgoing audio which appears to be caused by the SCO link missing data. The logs show excessive SCO errors in the ag read callback:
BT_APPL: bta_ag_sco_read_cback: status(2)
BT_APPL: bta_ag_sco_read_cback: status(1)

Note: incoming data works flawlessly. Audio from the headset microphone has no problems.

I suspect the SCO link has timing issues or is just dropping the data. Is this a know problem with the ESP Bluetooth stack or HFP profile? Are there any settings or workarounds to fix audio data loss here?

Note, this is NOT the same issue as BT-776. In that case, the bt_app_hf_outgoing_cb was not being triggered. I have verified that my hf outgoing callback is being called and that I am delivering audio consistently from the application. Once delivered to the SCO layer it is just getting dropped.
viewtopic.php?f=13&t=15288&hilit=bta_ag_sco_read_cback

Additional Notes and testing to isolate the problem:
Project: examples\bluetooth\bluedroid\classic_bt\hfp_ag

To rule out my application code, I'm using the example hfp_ag project. I have tried IDF versions 4.3.2 + 4.4.1, and both still show many bta_ag_sco_read_cback errors with minor but noticeable popping and glitching in the audio. I have tested using multiple headsets from different manufacturers and all show the same behavior.

My target application also uses WiFi and has moderate CPU load for additional audio processing, which exacerbates the problem. In my application I typically see >20% data loss resulting in very poor audio quality.

SDK Config is set to enable 1 Sync SCO connection and enables HCI data path in controller and bluedroid:
CONFIG_BTDM_CTRL_BR_EDR_MAX_SYNC_CONN=1
CONFIG_BTDM_CTRL_BR_EDR_SCO_DATA_PATH_HCI=y
CONFIG_BTDM_CTRL_HCI_MODE_VHCI=y
CONFIG_BTDM_CONTROLLER_BR_EDR_MAX_SYNC_CONN=1
CONFIG_BTDM_CONTROLLER_HCI_MODE_VHCI=y
CONFIG_BT_HFP_AUDIO_DATA_PATH_HCI=y
CONFIG_BT_HFP_WBS_ENABLE=y
CONFIG_HFP_AUDIO_DATA_PATH_HCI=y

Log from running esp-idf-v4.4.1\examples\bluetooth\bluedroid\classic_bt\hfp_ag, with HCI path enabled.

Code: Select all

I (20683) BT_APP_HF: APP HFP event: AUDIO_STATE_EVT
I (20683) BT_APP_HF: --Audio State connected_msbc
W (20723) BT_APPL: bta_ag_sco_read_cback: status(2)
W (20723) BT_APPL: bta_ag_sco_read_cback: status(2)
W (20733) BT_APPL: bta_ag_sco_read_cback: status(2)
W (20743) BT_APPL: bta_ag_sco_read_cback: status(2)
W (20753) BT_APPL: bta_ag_sco_read_cback: status(2)
W (20753) BT_APPL: bta_ag_sco_read_cback: status(2)
W (20763) BT_APPL: bta_ag_sco_read_cback: status(2)
W (22163) BT_APPL: bta_ag_sco_read_cback: status(1)
W (22703) BT_APPL: bta_ag_sco_read_cback: status(1)
W (22813) BT_APPL: bta_ag_sco_read_cback: status(2)
W (23683) BT_APPL: bta_ag_sco_read_cback: status(1)
I (23703) BT_APP_HF: speed(20.176652s ~ 23.177224s): 250.192291 kbit/s
W (24243) BT_APPL: bta_ag_sco_read_cback: status(1)
I (26703) BT_APP_HF: speed(23.177224s ~ 26.177318s): 255.991989 kbit/s
W (27523) BT_APPL: bta_ag_sco_read_cback: status(1)
W (28263) BT_APPL: bta_ag_sco_read_cback: status(2)
W (28643) BT_APPL: bta_ag_sco_read_cback: status(2)
W (29013) BT_APPL: bta_ag_sco_read_cback: status(2)
W (29393) BT_APPL: bta_ag_sco_read_cback: status(2)
I (29703) BT_APP_HF: speed(26.177318s ~ 29.177335s): 255.998566 kbit/s
W (29763) BT_APPL: bta_ag_sco_read_cback: status(2)
W (30143) BT_APPL: bta_ag_sco_read_cback: status(2)
W (30513) BT_APPL: bta_ag_sco_read_cback: status(2)
W (30893) BT_APPL: bta_ag_sco_read_cback: status(2)
W (31263) BT_APPL: bta_ag_sco_read_cback: status(2)

esp-jc
Posts: 4
Joined: Tue Jun 14, 2022 6:20 am

Re: Bluetooth HFP AG over HCI, outgoing SCO link drops data

Postby esp-jc » Tue Jun 14, 2022 6:27 am

BT_APPL: bta_ag_sco_read_cback: status(2)
This is a known issue which caused by that our hardware is not able to receive retransmitted sco packets from the peer device.

craig9yzz
Posts: 5
Joined: Thu May 26, 2022 2:11 pm

Re: Bluetooth HFP AG over HCI, outgoing SCO link drops data

Postby craig9yzz » Fri Jun 17, 2022 9:25 pm

Thanks for the note on hardware limitation esp-jc. A few follow-up questions:
  1. Is there a workaround to the HW limitation that can improve audio quality?
  2. Will there be a future update to the BT controller lib that will help?
I have some additional observations from testing that may be useful for improvements. These notes match the first log below:
  • log time 12708-19008: It seems that the audio link is more stable while the connection is in ACTIVE mode. The audio link is much better (still not perfect) for the first few seconds after enabling audio.
  • log time 19908: A few seconds after starting audio, the connection enters SNIFF mode with interval=150. From this point, the audio drops much more frequently with regular audible distortion. Sniff mode, ideally, would not affect the SCO link, however it does seem to have a noticeable impact here, perhaps due to controller timing?
  • log time 42808: On only one of my test headsets (I test with several), the controller updates the link interval to 160. After this change, audio is much* better! *Note that I this log is taken while the headset is very close to the ESP32 module. If I move it further away, I do start seeing many more dropped packets (sco_read_cback errors) - possibly due to the HW limitation with retransmits.

Code: Select all

I (12608) BT_APP_HF: APP HFP event: AUDIO_STATE_EVT
I (12608) BT_APP_HF: --Audio State connecting
I (12618) BT_RFCOMM: PORT_ReadData() handle:3 max_len:512
I (12628) BT_BTM: BTM_SetPowerMode: pm_id 0 BDA: f3211306 mode:0x0
I (12638) BT_RFCOMM: PORT_WriteData() max_len:6
I (12638) BT_BTM: BTM_SetEScoMode -> mode 2
I (12638) BT_APPL: Setting retry_with_sco_only to FALSE
I (12658) BT_BTM: BTM_CreateSco -> (e)SCO Link for ACL handle 0x0080, Desired Type 2
I (12658) BT_BTM: txbw 0x1f40, rxbw 0x1f40, lat 0xd, voice 0x43, retrans 0x02, pkt 0x0388
I (12668) BT_APPL: ag create sco: orig 1, inx 0x0000, status 0x1, pkt types 0x0388
I (12668) BT_APP_HF: APP HFP event: BCS_EVT
I (12688) BT_APP_HF: --Consequence of codec negotiation: Use MSBC
E (12698) BT_BTM: btm_sco_connected, handle 180
I (12708) BT_BTM: BTM_ReadEScoLinkParms -> sco_inx 0x0000
I (12708) BT_APP_HF: APP HFP event: AUDIO_STATE_EVT
I (12708) BT_APP_HF: --Audio State connected_msbc
W (12728) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12738) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12748) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12748) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12758) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12768) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12778) BT_APPL: bta_ag_sco_read_cback: status(2)
W (13068) BT_APPL: bta_ag_sco_read_cback: status(1)
W (14128) BT_APPL: bta_ag_sco_read_cback: status(2)
I (15728) BT_APP_HF: speed(12.164186s ~ 15.168058s): 251.195801 kbit/s
W (16348) BT_APPL: bta_ag_sco_read_cback: status(1)
W (16398) BT_APPL: bta_ag_sco_read_cback: status(1)
I (18728) BT_APP_HF: speed(15.168058s ~ 18.168116s): 255.995056 kbit/s
W (19008) BT_APPL: bta_ag_sco_read_cback: status(1)
I (19908) BT_BTM: BTM_SetPowerMode: pm_id 0 BDA: f3211306 mode:0x2
E (19908) BT_BTM: btm_pm_snd_md_req switching from ACTIVE to SNIFF.
W (19908) BT_HCI: hci cmd send: sniff: hdl 0x80, intv(50 150)
W (19928) BT_HCI: hcif mode change: hdl 0x80, mode 2, intv 150, status 0x0
W (20278) BT_APPL: bta_ag_sco_read_cback: status(2)
W (20648) BT_APPL: bta_ag_sco_read_cback: status(2)
W (21028) BT_APPL: bta_ag_sco_read_cback: status(2)
W (21398) BT_APPL: bta_ag_sco_read_cback: status(2)
I (21728) BT_APP_HF: speed(18.168116s ~ 21.174369s): 256.106201 kbit/s
W (21778) BT_APPL: bta_ag_sco_read_cback: status(2)
W (22148) BT_APPL: bta_ag_sco_read_cback: status(2)
W (22528) BT_APPL: bta_ag_sco_read_cback: status(2)
W (22898) BT_APPL: bta_ag_sco_read_cback: status(2)
W (23278) BT_APPL: bta_ag_sco_read_cback: status(2)
W (23648) BT_APPL: bta_ag_sco_read_cback: status(2)
W (24028) BT_APPL: bta_ag_sco_read_cback: status(2)
W (24398) BT_APPL: bta_ag_sco_read_cback: status(2)
I (24728) BT_APP_HF: speed(21.174369s ~ 24.174375s): 255.999481 kbit/s
W (24778) BT_APPL: bta_ag_sco_read_cback: status(2)
W (25148) BT_APPL: bta_ag_sco_read_cback: status(2)
W (25528) BT_APPL: bta_ag_sco_read_cback: status(2)
W (25898) BT_APPL: bta_ag_sco_read_cback: status(2)
W (26278) BT_APPL: bta_ag_sco_read_cback: status(2)
W (26648) BT_APPL: bta_ag_sco_read_cback: status(2)
W (27028) BT_APPL: bta_ag_sco_read_cback: status(2)
W (27398) BT_APPL: bta_ag_sco_read_cback: status(2)
I (27728) BT_APP_HF: speed(24.174375s ~ 27.174586s): 255.981995 kbit/s
W (27778) BT_APPL: bta_ag_sco_read_cback: status(2)
W (28148) BT_APPL: bta_ag_sco_read_cback: status(2)
W (28528) BT_APPL: bta_ag_sco_read_cback: status(2)
W (28898) BT_APPL: bta_ag_sco_read_cback: status(2)
W (29278) BT_APPL: bta_ag_sco_read_cback: status(2)
W (29648) BT_APPL: bta_ag_sco_read_cback: status(2)
W (30028) BT_APPL: bta_ag_sco_read_cback: status(2)
W (30278) BT_APPL: bta_ag_sco_read_cback: status(1)
W (30398) BT_APPL: bta_ag_sco_read_cback: status(2)
I (30738) BT_APP_HF: speed(27.174586s ~ 30.181888s): 256.016846 kbit/s
W (30778) BT_APPL: bta_ag_sco_read_cback: status(2)
W (31148) BT_APPL: bta_ag_sco_read_cback: status(2)
W (31528) BT_APPL: bta_ag_sco_read_cback: status(2)
W (31758) BT_APPL: bta_ag_sco_read_cback: status(1)
W (31898) BT_APPL: bta_ag_sco_read_cback: status(2)
W (32278) BT_APPL: bta_ag_sco_read_cback: status(2)
W (32648) BT_APPL: bta_ag_sco_read_cback: status(2)
W (33028) BT_APPL: bta_ag_sco_read_cback: status(2)
W (33398) BT_APPL: bta_ag_sco_read_cback: status(2)
I (33738) BT_APP_HF: speed(30.181888s ~ 33.181892s): 255.999649 kbit/s
W (33778) BT_APPL: bta_ag_sco_read_cback: status(2)
W (34148) BT_APPL: bta_ag_sco_read_cback: status(2)
W (34528) BT_APPL: bta_ag_sco_read_cback: status(2)
W (34898) BT_APPL: bta_ag_sco_read_cback: status(2)
W (35278) BT_APPL: bta_ag_sco_read_cback: status(2)
W (35648) BT_APPL: bta_ag_sco_read_cback: status(2)
W (36028) BT_APPL: bta_ag_sco_read_cback: status(2)
W (36398) BT_APPL: bta_ag_sco_read_cback: status(2)
I (36738) BT_APP_HF: speed(33.181892s ~ 36.181892s): 256.000000 kbit/s
W (36778) BT_APPL: bta_ag_sco_read_cback: status(2)
W (37028) BT_APPL: bta_ag_sco_read_cback: status(1)
W (37148) BT_APPL: bta_ag_sco_read_cback: status(2)
W (37528) BT_APPL: bta_ag_sco_read_cback: status(2)
W (37898) BT_APPL: bta_ag_sco_read_cback: status(2)
W (38278) BT_APPL: bta_ag_sco_read_cback: status(2)
W (38648) BT_APPL: bta_ag_sco_read_cback: status(2)
W (39028) BT_APPL: bta_ag_sco_read_cback: status(2)
W (39398) BT_APPL: bta_ag_sco_read_cback: status(2)
I (39738) BT_APP_HF: speed(36.181892s ~ 39.181905s): 255.998871 kbit/s
W (39778) BT_APPL: bta_ag_sco_read_cback: status(2)
W (40148) BT_APPL: bta_ag_sco_read_cback: status(2)
W (40528) BT_APPL: bta_ag_sco_read_cback: status(2)
W (40568) BT_APPL: bta_ag_sco_read_cback: status(1)
W (40898) BT_APPL: bta_ag_sco_read_cback: status(2)
W (41278) BT_APPL: bta_ag_sco_read_cback: status(2)
W (41648) BT_APPL: bta_ag_sco_read_cback: status(2)
W (42028) BT_APPL: bta_ag_sco_read_cback: status(2)
W (42398) BT_APPL: bta_ag_sco_read_cback: status(2)
I (42748) BT_APP_HF: speed(39.181905s ~ 42.189416s): 255.999084 kbit/s
W (42768) BT_HCI: hcif mode change: hdl 0x80, mode 0, intv 0, status 0x0
W (42808) BT_HCI: hcif mode change: hdl 0x80, mode 2, intv 160, status 0x0
I (45748) BT_APP_HF: speed(42.189416s ~ 45.189564s): 255.987366 kbit/s
I (48748) BT_APP_HF: speed(45.189564s ~ 48.189656s): 255.992142 kbit/s
I (51748) BT_APP_HF: speed(48.189656s ~ 51.197071s): 256.007233 kbit/s
W (51778) BT_APPL: bta_ag_sco_read_cback: status(1)
I (54758) BT_APP_HF: speed(51.197071s ~ 54.204054s): 256.044006 kbit/s
I (57758) BT_APP_HF: speed(54.204054s ~ 57.204076s): 255.998123 kbit/s
I (60768) BT_APP_HF: speed(57.204076s ~ 60.211544s): 256.002716 kbit/s
I (63768) BT_APP_HF: speed(60.211544s ~ 63.211557s): 255.998871 kbit/s
I (66778) BT_APP_HF: speed(63.211557s ~ 66.219056s): 256.000092 kbit/s
I (69778) BT_APP_HF: speed(66.219056s ~ 69.219076s): 255.998291 kbit/s
I (72788) BT_APP_HF: speed(69.219076s ~ 72.228092s): 255.871017 kbit/s
W (72988) BT_APPL: bta_ag_sco_read_cback: status(1)
I (75788) BT_APP_HF: speed(72.228092s ~ 75.234374s): 256.103729 kbit/s
To further verify, I disabled SNIFF mode in the BTA link policy. This is not a permanent fix, but does demonstrate that sniff mode introduces more instability into the audio link. With sniff disabled, I see many fewer errors, and the audio is much cleaner (at close range).

Code: Select all

bta_dm_cfg.c
#define BTA_DM_LINK_POLICY_SETTINGS    (HCI_ENABLE_MASTER_SLAVE_SWITCH | HCI_ENABLE_HOLD_MODE | /*HCI_ENABLE_SNIFF_MODE |*/ HCI_ENABLE_PARK_MODE)

Code: Select all

I (12388) BT_APP_HF: APP HFP event: AUDIO_STATE_EVT
I (12388) BT_APP_HF: --Audio State connecting
I (12398) BT_RFCOMM: PORT_ReadData() handle:3 max_len:512
I (12398) BT_BTM: BTM_SetPowerMode: pm_id 0 BDA: f3211306 mode:0x0
I (12418) BT_RFCOMM: PORT_WriteData() max_len:6
I (12418) BT_BTM: BTM_SetEScoMode -> mode 2
I (12418) BT_APPL: Setting retry_with_sco_only to FALSE
I (12428) BT_BTM: BTM_CreateSco -> (e)SCO Link for ACL handle 0x0080, Desired Type 2
I (12438) BT_BTM: txbw 0x1f40, rxbw 0x1f40, lat 0xd, voice 0x43, retrans 0x02, pkt 0x0388
I (12448) BT_APPL: ag create sco: orig 1, inx 0x0000, status 0x1, pkt types 0x0388
I (12448) BT_APP_HF: APP HFP event: BCS_EVT
I (12458) BT_APP_HF: --Consequence of codec negotiation: Use MSBC
E (12478) BT_BTM: btm_sco_connected, handle 180
I (12478) BT_BTM: BTM_ReadEScoLinkParms -> sco_inx 0x0000
I (12488) BT_APP_HF: APP HFP event: AUDIO_STATE_EVT
I (12488) BT_APP_HF: --Audio State connected_msbc
W (12508) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12518) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12518) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12528) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12538) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12548) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12548) BT_APPL: bta_ag_sco_read_cback: status(2)
W (13738) BT_APPL: bta_ag_sco_read_cback: status(2)
W (14558) BT_APPL: bta_ag_sco_read_cback: status(2)
I (15498) BT_APP_HF: speed(11.942853s ~ 14.943845s): 251.436859 kbit/s
I (18508) BT_APP_HF: speed(14.943845s ~ 17.950979s): 256.031158 kbit/s
I (21508) BT_APP_HF: speed(17.950979s ~ 20.951144s): 255.985916 kbit/s
W (21668) BT_APPL: bta_ag_sco_read_cback: status(2)
W (23408) BT_APPL: bta_ag_sco_read_cback: status(2)
I (24518) BT_APP_HF: speed(20.951144s ~ 23.958479s): 256.014038 kbit/s
I (27518) BT_APP_HF: speed(23.958479s ~ 26.965974s): 256.000427 kbit/s
I (30528) BT_APP_HF: speed(26.965974s ~ 29.973422s): 256.004425 kbit/s
W (31708) BT_APPL: bta_ag_sco_read_cback: status(1)
I (33528) BT_APP_HF: speed(29.973422s ~ 32.973455s): 255.997192 kbit/s
I (36528) BT_APP_HF: speed(32.973455s ~ 35.973459s): 255.999649 kbit/s
W (37338) BT_APPL: bta_ag_sco_read_cback: status(2)
W (39438) BT_APPL: bta_ag_sco_read_cback: status(2)
I (39528) BT_APP_HF: speed(35.973459s ~ 38.973467s): 255.999313 kbit/s
I (42528) BT_APP_HF: speed(38.973467s ~ 41.973493s): 255.997787 kbit/s
W (43278) BT_APPL: bta_ag_sco_read_cback: status(2)
I (45538) BT_APP_HF: speed(41.973493s ~ 44.981047s): 255.995407 kbit/s
W (45998) BT_APPL: bta_ag_sco_read_cback: status(1)
W (47588) BT_APPL: bta_ag_sco_read_cback: status(1)
I (48538) BT_APP_HF: speed(44.981047s ~ 47.981087s): 255.996582 kbit/s
I (51538) BT_APP_HF: speed(47.981087s ~ 50.981264s): 255.984909 kbit/s
I (54548) BT_APP_HF: speed(50.981264s ~ 53.988577s): 256.015930 kbit/s
I (57548) BT_APP_HF: speed(53.988577s ~ 56.996047s): 256.002563 kbit/s
I (60548) BT_APP_HF: speed(56.996047s ~ 59.996265s): 255.981400 kbit/s
I (63558) BT_APP_HF: speed(59.996265s ~ 63.003839s): 255.993683 kbit/s
I (66558) BT_APP_HF: speed(63.003839s ~ 66.004012s): 255.985229 kbit/s
W (68618) BT_APPL: bta_ag_sco_read_cback: status(2)
I (69568) BT_APP_HF: speed(66.004012s ~ 69.010955s): 256.047424 kbit/s
I (72568) BT_APP_HF: speed(69.010955s ~ 72.010971s): 255.998642 kbit/s
W (73078) BT_APPL: bta_ag_sco_read_cback: status(2)
W (74428) BT_APPL: bta_ag_sco_read_cback: status(2)
I (75568) BT_APP_HF: speed(72.010971s ~ 75.011052s): 255.993073 kbit/s
I (78578) BT_APP_HF: speed(75.011052s ~ 78.018491s): 256.005188 kbit/s
I (81578) BT_APP_HF: speed(78.018491s ~ 81.025959s): 256.002716 kbit/s

esp-jc
Posts: 4
Joined: Tue Jun 14, 2022 6:20 am

Re: Bluetooth HFP AG over HCI, outgoing SCO link drops data

Postby esp-jc » Fri Aug 19, 2022 2:40 am

craig9yzz wrote:
Fri Jun 17, 2022 9:25 pm
Thanks for the note on hardware limitation esp-jc. A few follow-up questions:
  1. Is there a workaround to the HW limitation that can improve audio quality?
  2. Will there be a future update to the BT controller lib that will help?
I have some additional observations from testing that may be useful for improvements. These notes match the first log below:
  • log time 12708-19008: It seems that the audio link is more stable while the connection is in ACTIVE mode. The audio link is much better (still not perfect) for the first few seconds after enabling audio.
  • log time 19908: A few seconds after starting audio, the connection enters SNIFF mode with interval=150. From this point, the audio drops much more frequently with regular audible distortion. Sniff mode, ideally, would not affect the SCO link, however it does seem to have a noticeable impact here, perhaps due to controller timing?
  • log time 42808: On only one of my test headsets (I test with several), the controller updates the link interval to 160. After this change, audio is much* better! *Note that I this log is taken while the headset is very close to the ESP32 module. If I move it further away, I do start seeing many more dropped packets (sco_read_cback errors) - possibly due to the HW limitation with retransmits.

Code: Select all

I (12608) BT_APP_HF: APP HFP event: AUDIO_STATE_EVT
I (12608) BT_APP_HF: --Audio State connecting
I (12618) BT_RFCOMM: PORT_ReadData() handle:3 max_len:512
I (12628) BT_BTM: BTM_SetPowerMode: pm_id 0 BDA: f3211306 mode:0x0
I (12638) BT_RFCOMM: PORT_WriteData() max_len:6
I (12638) BT_BTM: BTM_SetEScoMode -> mode 2
I (12638) BT_APPL: Setting retry_with_sco_only to FALSE
I (12658) BT_BTM: BTM_CreateSco -> (e)SCO Link for ACL handle 0x0080, Desired Type 2
I (12658) BT_BTM: txbw 0x1f40, rxbw 0x1f40, lat 0xd, voice 0x43, retrans 0x02, pkt 0x0388
I (12668) BT_APPL: ag create sco: orig 1, inx 0x0000, status 0x1, pkt types 0x0388
I (12668) BT_APP_HF: APP HFP event: BCS_EVT
I (12688) BT_APP_HF: --Consequence of codec negotiation: Use MSBC
E (12698) BT_BTM: btm_sco_connected, handle 180
I (12708) BT_BTM: BTM_ReadEScoLinkParms -> sco_inx 0x0000
I (12708) BT_APP_HF: APP HFP event: AUDIO_STATE_EVT
I (12708) BT_APP_HF: --Audio State connected_msbc
W (12728) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12738) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12748) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12748) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12758) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12768) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12778) BT_APPL: bta_ag_sco_read_cback: status(2)
W (13068) BT_APPL: bta_ag_sco_read_cback: status(1)
W (14128) BT_APPL: bta_ag_sco_read_cback: status(2)
I (15728) BT_APP_HF: speed(12.164186s ~ 15.168058s): 251.195801 kbit/s
W (16348) BT_APPL: bta_ag_sco_read_cback: status(1)
W (16398) BT_APPL: bta_ag_sco_read_cback: status(1)
I (18728) BT_APP_HF: speed(15.168058s ~ 18.168116s): 255.995056 kbit/s
W (19008) BT_APPL: bta_ag_sco_read_cback: status(1)
I (19908) BT_BTM: BTM_SetPowerMode: pm_id 0 BDA: f3211306 mode:0x2
E (19908) BT_BTM: btm_pm_snd_md_req switching from ACTIVE to SNIFF.
W (19908) BT_HCI: hci cmd send: sniff: hdl 0x80, intv(50 150)
W (19928) BT_HCI: hcif mode change: hdl 0x80, mode 2, intv 150, status 0x0
W (20278) BT_APPL: bta_ag_sco_read_cback: status(2)
W (20648) BT_APPL: bta_ag_sco_read_cback: status(2)
W (21028) BT_APPL: bta_ag_sco_read_cback: status(2)
W (21398) BT_APPL: bta_ag_sco_read_cback: status(2)
I (21728) BT_APP_HF: speed(18.168116s ~ 21.174369s): 256.106201 kbit/s
W (21778) BT_APPL: bta_ag_sco_read_cback: status(2)
W (22148) BT_APPL: bta_ag_sco_read_cback: status(2)
W (22528) BT_APPL: bta_ag_sco_read_cback: status(2)
W (22898) BT_APPL: bta_ag_sco_read_cback: status(2)
W (23278) BT_APPL: bta_ag_sco_read_cback: status(2)
W (23648) BT_APPL: bta_ag_sco_read_cback: status(2)
W (24028) BT_APPL: bta_ag_sco_read_cback: status(2)
W (24398) BT_APPL: bta_ag_sco_read_cback: status(2)
I (24728) BT_APP_HF: speed(21.174369s ~ 24.174375s): 255.999481 kbit/s
W (24778) BT_APPL: bta_ag_sco_read_cback: status(2)
W (25148) BT_APPL: bta_ag_sco_read_cback: status(2)
W (25528) BT_APPL: bta_ag_sco_read_cback: status(2)
W (25898) BT_APPL: bta_ag_sco_read_cback: status(2)
W (26278) BT_APPL: bta_ag_sco_read_cback: status(2)
W (26648) BT_APPL: bta_ag_sco_read_cback: status(2)
W (27028) BT_APPL: bta_ag_sco_read_cback: status(2)
W (27398) BT_APPL: bta_ag_sco_read_cback: status(2)
I (27728) BT_APP_HF: speed(24.174375s ~ 27.174586s): 255.981995 kbit/s
W (27778) BT_APPL: bta_ag_sco_read_cback: status(2)
W (28148) BT_APPL: bta_ag_sco_read_cback: status(2)
W (28528) BT_APPL: bta_ag_sco_read_cback: status(2)
W (28898) BT_APPL: bta_ag_sco_read_cback: status(2)
W (29278) BT_APPL: bta_ag_sco_read_cback: status(2)
W (29648) BT_APPL: bta_ag_sco_read_cback: status(2)
W (30028) BT_APPL: bta_ag_sco_read_cback: status(2)
W (30278) BT_APPL: bta_ag_sco_read_cback: status(1)
W (30398) BT_APPL: bta_ag_sco_read_cback: status(2)
I (30738) BT_APP_HF: speed(27.174586s ~ 30.181888s): 256.016846 kbit/s
W (30778) BT_APPL: bta_ag_sco_read_cback: status(2)
W (31148) BT_APPL: bta_ag_sco_read_cback: status(2)
W (31528) BT_APPL: bta_ag_sco_read_cback: status(2)
W (31758) BT_APPL: bta_ag_sco_read_cback: status(1)
W (31898) BT_APPL: bta_ag_sco_read_cback: status(2)
W (32278) BT_APPL: bta_ag_sco_read_cback: status(2)
W (32648) BT_APPL: bta_ag_sco_read_cback: status(2)
W (33028) BT_APPL: bta_ag_sco_read_cback: status(2)
W (33398) BT_APPL: bta_ag_sco_read_cback: status(2)
I (33738) BT_APP_HF: speed(30.181888s ~ 33.181892s): 255.999649 kbit/s
W (33778) BT_APPL: bta_ag_sco_read_cback: status(2)
W (34148) BT_APPL: bta_ag_sco_read_cback: status(2)
W (34528) BT_APPL: bta_ag_sco_read_cback: status(2)
W (34898) BT_APPL: bta_ag_sco_read_cback: status(2)
W (35278) BT_APPL: bta_ag_sco_read_cback: status(2)
W (35648) BT_APPL: bta_ag_sco_read_cback: status(2)
W (36028) BT_APPL: bta_ag_sco_read_cback: status(2)
W (36398) BT_APPL: bta_ag_sco_read_cback: status(2)
I (36738) BT_APP_HF: speed(33.181892s ~ 36.181892s): 256.000000 kbit/s
W (36778) BT_APPL: bta_ag_sco_read_cback: status(2)
W (37028) BT_APPL: bta_ag_sco_read_cback: status(1)
W (37148) BT_APPL: bta_ag_sco_read_cback: status(2)
W (37528) BT_APPL: bta_ag_sco_read_cback: status(2)
W (37898) BT_APPL: bta_ag_sco_read_cback: status(2)
W (38278) BT_APPL: bta_ag_sco_read_cback: status(2)
W (38648) BT_APPL: bta_ag_sco_read_cback: status(2)
W (39028) BT_APPL: bta_ag_sco_read_cback: status(2)
W (39398) BT_APPL: bta_ag_sco_read_cback: status(2)
I (39738) BT_APP_HF: speed(36.181892s ~ 39.181905s): 255.998871 kbit/s
W (39778) BT_APPL: bta_ag_sco_read_cback: status(2)
W (40148) BT_APPL: bta_ag_sco_read_cback: status(2)
W (40528) BT_APPL: bta_ag_sco_read_cback: status(2)
W (40568) BT_APPL: bta_ag_sco_read_cback: status(1)
W (40898) BT_APPL: bta_ag_sco_read_cback: status(2)
W (41278) BT_APPL: bta_ag_sco_read_cback: status(2)
W (41648) BT_APPL: bta_ag_sco_read_cback: status(2)
W (42028) BT_APPL: bta_ag_sco_read_cback: status(2)
W (42398) BT_APPL: bta_ag_sco_read_cback: status(2)
I (42748) BT_APP_HF: speed(39.181905s ~ 42.189416s): 255.999084 kbit/s
W (42768) BT_HCI: hcif mode change: hdl 0x80, mode 0, intv 0, status 0x0
W (42808) BT_HCI: hcif mode change: hdl 0x80, mode 2, intv 160, status 0x0
I (45748) BT_APP_HF: speed(42.189416s ~ 45.189564s): 255.987366 kbit/s
I (48748) BT_APP_HF: speed(45.189564s ~ 48.189656s): 255.992142 kbit/s
I (51748) BT_APP_HF: speed(48.189656s ~ 51.197071s): 256.007233 kbit/s
W (51778) BT_APPL: bta_ag_sco_read_cback: status(1)
I (54758) BT_APP_HF: speed(51.197071s ~ 54.204054s): 256.044006 kbit/s
I (57758) BT_APP_HF: speed(54.204054s ~ 57.204076s): 255.998123 kbit/s
I (60768) BT_APP_HF: speed(57.204076s ~ 60.211544s): 256.002716 kbit/s
I (63768) BT_APP_HF: speed(60.211544s ~ 63.211557s): 255.998871 kbit/s
I (66778) BT_APP_HF: speed(63.211557s ~ 66.219056s): 256.000092 kbit/s
I (69778) BT_APP_HF: speed(66.219056s ~ 69.219076s): 255.998291 kbit/s
I (72788) BT_APP_HF: speed(69.219076s ~ 72.228092s): 255.871017 kbit/s
W (72988) BT_APPL: bta_ag_sco_read_cback: status(1)
I (75788) BT_APP_HF: speed(72.228092s ~ 75.234374s): 256.103729 kbit/s
To further verify, I disabled SNIFF mode in the BTA link policy. This is not a permanent fix, but does demonstrate that sniff mode introduces more instability into the audio link. With sniff disabled, I see many fewer errors, and the audio is much cleaner (at close range).

Code: Select all

bta_dm_cfg.c
#define BTA_DM_LINK_POLICY_SETTINGS    (HCI_ENABLE_MASTER_SLAVE_SWITCH | HCI_ENABLE_HOLD_MODE | /*HCI_ENABLE_SNIFF_MODE |*/ HCI_ENABLE_PARK_MODE)

Code: Select all

I (12388) BT_APP_HF: APP HFP event: AUDIO_STATE_EVT
I (12388) BT_APP_HF: --Audio State connecting
I (12398) BT_RFCOMM: PORT_ReadData() handle:3 max_len:512
I (12398) BT_BTM: BTM_SetPowerMode: pm_id 0 BDA: f3211306 mode:0x0
I (12418) BT_RFCOMM: PORT_WriteData() max_len:6
I (12418) BT_BTM: BTM_SetEScoMode -> mode 2
I (12418) BT_APPL: Setting retry_with_sco_only to FALSE
I (12428) BT_BTM: BTM_CreateSco -> (e)SCO Link for ACL handle 0x0080, Desired Type 2
I (12438) BT_BTM: txbw 0x1f40, rxbw 0x1f40, lat 0xd, voice 0x43, retrans 0x02, pkt 0x0388
I (12448) BT_APPL: ag create sco: orig 1, inx 0x0000, status 0x1, pkt types 0x0388
I (12448) BT_APP_HF: APP HFP event: BCS_EVT
I (12458) BT_APP_HF: --Consequence of codec negotiation: Use MSBC
E (12478) BT_BTM: btm_sco_connected, handle 180
I (12478) BT_BTM: BTM_ReadEScoLinkParms -> sco_inx 0x0000
I (12488) BT_APP_HF: APP HFP event: AUDIO_STATE_EVT
I (12488) BT_APP_HF: --Audio State connected_msbc
W (12508) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12518) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12518) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12528) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12538) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12548) BT_APPL: bta_ag_sco_read_cback: status(2)
W (12548) BT_APPL: bta_ag_sco_read_cback: status(2)
W (13738) BT_APPL: bta_ag_sco_read_cback: status(2)
W (14558) BT_APPL: bta_ag_sco_read_cback: status(2)
I (15498) BT_APP_HF: speed(11.942853s ~ 14.943845s): 251.436859 kbit/s
I (18508) BT_APP_HF: speed(14.943845s ~ 17.950979s): 256.031158 kbit/s
I (21508) BT_APP_HF: speed(17.950979s ~ 20.951144s): 255.985916 kbit/s
W (21668) BT_APPL: bta_ag_sco_read_cback: status(2)
W (23408) BT_APPL: bta_ag_sco_read_cback: status(2)
I (24518) BT_APP_HF: speed(20.951144s ~ 23.958479s): 256.014038 kbit/s
I (27518) BT_APP_HF: speed(23.958479s ~ 26.965974s): 256.000427 kbit/s
I (30528) BT_APP_HF: speed(26.965974s ~ 29.973422s): 256.004425 kbit/s
W (31708) BT_APPL: bta_ag_sco_read_cback: status(1)
I (33528) BT_APP_HF: speed(29.973422s ~ 32.973455s): 255.997192 kbit/s
I (36528) BT_APP_HF: speed(32.973455s ~ 35.973459s): 255.999649 kbit/s
W (37338) BT_APPL: bta_ag_sco_read_cback: status(2)
W (39438) BT_APPL: bta_ag_sco_read_cback: status(2)
I (39528) BT_APP_HF: speed(35.973459s ~ 38.973467s): 255.999313 kbit/s
I (42528) BT_APP_HF: speed(38.973467s ~ 41.973493s): 255.997787 kbit/s
W (43278) BT_APPL: bta_ag_sco_read_cback: status(2)
I (45538) BT_APP_HF: speed(41.973493s ~ 44.981047s): 255.995407 kbit/s
W (45998) BT_APPL: bta_ag_sco_read_cback: status(1)
W (47588) BT_APPL: bta_ag_sco_read_cback: status(1)
I (48538) BT_APP_HF: speed(44.981047s ~ 47.981087s): 255.996582 kbit/s
I (51538) BT_APP_HF: speed(47.981087s ~ 50.981264s): 255.984909 kbit/s
I (54548) BT_APP_HF: speed(50.981264s ~ 53.988577s): 256.015930 kbit/s
I (57548) BT_APP_HF: speed(53.988577s ~ 56.996047s): 256.002563 kbit/s
I (60548) BT_APP_HF: speed(56.996047s ~ 59.996265s): 255.981400 kbit/s
I (63558) BT_APP_HF: speed(59.996265s ~ 63.003839s): 255.993683 kbit/s
I (66558) BT_APP_HF: speed(63.003839s ~ 66.004012s): 255.985229 kbit/s
W (68618) BT_APPL: bta_ag_sco_read_cback: status(2)
I (69568) BT_APP_HF: speed(66.004012s ~ 69.010955s): 256.047424 kbit/s
I (72568) BT_APP_HF: speed(69.010955s ~ 72.010971s): 255.998642 kbit/s
W (73078) BT_APPL: bta_ag_sco_read_cback: status(2)
W (74428) BT_APPL: bta_ag_sco_read_cback: status(2)
I (75568) BT_APP_HF: speed(72.010971s ~ 75.011052s): 255.993073 kbit/s
I (78578) BT_APP_HF: speed(75.011052s ~ 78.018491s): 256.005188 kbit/s
I (81578) BT_APP_HF: speed(78.018491s ~ 81.025959s): 256.002716 kbit/s
Sorry for the late reply. We checked the sniff interval and found it did seemed to have a noticeable impact on the sco connection. Now we have raised the priority of this issue. I will let you know as soon as there is a fix. Thanks!

craig9yzz
Posts: 5
Joined: Thu May 26, 2022 2:11 pm

Re: Bluetooth HFP AG over HCI, outgoing SCO link drops data

Postby craig9yzz » Mon Aug 22, 2022 10:12 pm

Thanks for confirming issue with sniff mode!

Regarding the original issue, SCO packet loss:
This is a known issue which caused by that our hardware is not able to receive retransmitted sco packets from the peer device.
1. Will there also be a fix for SCO packet retries in the next IDF release?
2. Is there a workaround we can use with the current IDF? The SCO data loss causes very poor HFP audio when interference is present.

esp-jc
Posts: 4
Joined: Tue Jun 14, 2022 6:20 am

Re: Bluetooth HFP AG over HCI, outgoing SCO link drops data

Postby esp-jc » Tue Aug 23, 2022 2:42 am

You can change

Code: Select all

#define BTA_DM_PM_SNIFF3_MAX     150
to

Code: Select all

#define BTA_DM_PM_SNIFF3_MAX     180
and test again. Please provide feedback on your test results, thank you very much!

craig9yzz
Posts: 5
Joined: Thu May 26, 2022 2:11 pm

Re: Bluetooth HFP AG over HCI, outgoing SCO link drops data

Postby craig9yzz » Tue Aug 23, 2022 9:20 pm

I will try some testing with this sniff change. However, I think this sniff mode bug is a separate issue from the original SCO link problem... is that correct?

Regarding SCO link quality and retries:
This is a known issue which caused by that our hardware is not able to receive retransmitted sco packets from the peer device.

Is there a workaround for the SCO packet loss?
Will there be a future update to the BT controller that will improve?

esp-jc
Posts: 4
Joined: Tue Jun 14, 2022 6:20 am

Re: Bluetooth HFP AG over HCI, outgoing SCO link drops data

Postby esp-jc » Thu Sep 01, 2022 8:20 am

craig9yzz wrote:
Tue Aug 23, 2022 9:20 pm
I will try some testing with this sniff change. However, I think this sniff mode bug is a separate issue from the original SCO link problem... is that correct?

Regarding SCO link quality and retries:
This is a known issue which caused by that our hardware is not able to receive retransmitted sco packets from the peer device.

Is there a workaround for the SCO packet loss?
Will there be a future update to the BT controller that will improve?

We have focused on this issue recently and found some information.
With sniff enabled, the ACL connection will wake up and communicate with peer device at a specific instant. If the instant is coincided with SCO transmission, then SCO can be interrupted which result in a packet loss. We will improve the algorithm of calculating wake-up instatnt to avoid the above situation. I'm sure this won't take too long. Thanks!

craig9yzz
Posts: 5
Joined: Thu May 26, 2022 2:11 pm

Re: Bluetooth HFP AG over HCI, outgoing SCO link drops data

Postby craig9yzz » Thu Oct 06, 2022 9:00 pm

You can change
CODE: SELECT ALL

#define BTA_DM_PM_SNIFF3_MAX 150
to
CODE: SELECT ALL

#define BTA_DM_PM_SNIFF3_MAX 180
and test again. Please provide feedback on your test results, thank you very much!
I've completed additional testing with the above change to SNIFF3_MAX. There was no improvement in the HFP_AG audio loss or quality issues.

I also tested (separately) with with Sniff/Hold modes disabled by changing the BTA_DM_LINK_POLICY_SETTINGS define. In most cases this does not improve audio quality. It does prevent quality from worsening when the device would previously enter sniff mode.
We have focused on this issue recently and found some information.
With sniff enabled, the ACL connection will wake up and communicate with peer device at a specific instant. If the instant is coincided with SCO transmission, then SCO can be interrupted which result in a packet loss. We will improve the algorithm of calculating wake-up instatnt to avoid the above situation. I'm sure this won't take too long. Thanks!
Have you been able to fix this issue with ACL/SCO instant collisions? Is it included in any newer IDF releases? I can test this too, when available.

Who is online

Users browsing this forum: Bing [Bot] and 124 guests