Ubuntu
pulseaudio package

PC streams music over low-quality HFP/SCO connection, instead of A2DP/AVDTP

Bug #1941977 reported by Brian Ejike on 2021-08-29

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	bluez (Ubuntu)	New	Undecided	Unassigned
	pulseaudio (Ubuntu)	New	Undecided	Unassigned

Bug Description

This issue was first discovered when I got this headset 2 years back: https://www.amazon.co.uk/gp/product/B01C2QCPYI.

STEPS
* Enable Bluetooth on the PC
* Have music or some video playing on the PC
* Power on the (already-paired) headset. It automatically connects to the PC.

EXPECTED RESULT
The PC's audio should now be streamed to the headset, over high-quality A2DP

ACTUAL RESULT
The PC's audio gets streamed over the low-quality HFP/SCO connection instead.

Stopping and resuming the stream changes nothing. I have to manually open Blueman and right-click on the device and select "High-quality A2DP profile", for it to switch to the expected high-quality A2DP transport.

HCI snoop logs and verbose bluetoothd-syslogs taken in both headset-initiated and PC-initiated connections are attached.

ProblemType: Bug
DistroRelease: Ubuntu 20.04
Package: bluez 5.53-0ubuntu3.3 [modified: lib/systemd/system/bluetooth.service]
ProcVersionSignature: Ubuntu 5.4.0-74.83-generic 5.4.114
Uname: Linux 5.4.0-74-generic x86_64
ApportVersion: 2.20.11-0ubuntu27.18
Architecture: amd64
CasperMD5CheckResult: skip
CurrentDesktop: ubuntu:GNOME
Date: Sun Aug 29 03:49:08 2021
InstallationDate: Installed on 2019-06-08 (812 days ago)
InstallationMedia: Ubuntu 19.04 "Disco Dingo" - Release amd64 (20190416)
InterestingModules: rfcomm bnep btusb bluetooth
MachineType: Dell Inc. XPS 13 9380
ProcEnviron:
LANGUAGE=en_GB:en
PATH=(custom, no user)
XDG_RUNTIME_DIR=<set>
LANG=en_GB.UTF-8
SHELL=/bin/bash
ProcKernelCmdLine: BOOT_IMAGE=/boot/vmlinuz-5.4.0-74-generic root=UUID=93dae559-0f0d-4e36-9318-ee7154840a9f ro resume=UUID=01c18f00-e0eb-4891-9bf1-3110416d9b39 quiet splash mem_sleep_default=deep vt.handoff=7
SourcePackage: bluez
UpgradeStatus: No upgrade log present (probably fresh install)
dmi.bios.date: 12/14/2020
dmi.bios.vendor: Dell Inc.
dmi.bios.version: 1.12.1
dmi.board.name: 0KTW76
dmi.board.vendor: Dell Inc.
dmi.board.version: A00
dmi.chassis.type: 10
dmi.chassis.vendor: Dell Inc.
dmi.modalias: dmi:bvnDellInc.:bvr1.12.1:bd12/14/2020:svnDellInc.:pnXPS139380:pvr:rvnDellInc.:rn0KTW76:rvrA00:cvnDellInc.:ct10:cvr:
dmi.product.family: XPS
dmi.product.name: XPS 13 9380
dmi.product.sku: 08AF
dmi.sys.vendor: Dell Inc.
hciconfig:
hci0: Type: Primary Bus: USB
  BD Address: 9C:B6:D0:99:1D:20 ACL MTU: 1024:8 SCO MTU: 50:8
  UP RUNNING PSCAN
  RX bytes:3313120 acl:776 sco:26275 events:305102 errors:0
  TX bytes:255208317 acl:298108 sco:22053 commands:6779 errors:0
mtime.conffile..etc.bluetooth.main.conf: 2020-04-27T23:21:52.866445

Tags:

Revision history for this message

Brian Ejike (bejike) wrote on 2021-08-29:

HCI snoop taken when the headset initiates the connection Edit (222.7 KiB, application/octet-stream)
CurrentDmesg.txt Edit (258.4 KiB, text/plain; charset="utf-8")
Dependencies.txt Edit (2.2 KiB, text/plain; charset="utf-8")
Lspci.txt Edit (19.9 KiB, text/plain; charset="utf-8")
Lspci-vt.txt Edit (1.8 KiB, text/plain; charset="utf-8")
Lsusb.txt Edit (454 bytes, text/plain; charset="utf-8")
Lsusb-t.txt Edit (664 bytes, text/plain; charset="utf-8")
Lsusb-v.txt Edit (38.1 KiB, text/plain; charset="utf-8")
ProcCpuinfo.txt Edit (10.2 KiB, text/plain; charset="utf-8")
ProcCpuinfoMinimal.txt Edit (1.3 KiB, text/plain; charset="utf-8")
ProcInterrupts.txt Edit (6.7 KiB, text/plain; charset="utf-8")
ProcModules.txt Edit (11.0 KiB, text/plain; charset="utf-8")
UdevDb.txt Edit (252.6 KiB, text/plain; charset="utf-8")
acpidump.txt Edit (1.6 MiB, text/plain; charset="utf-8")
getfacl.txt Edit (156 bytes, text/plain; charset="utf-8")
modified.conffile..etc.bluetooth.main.conf.txt Edit (4.0 KiB, text/plain; charset="utf-8")
rfkill.txt Edit (114 bytes, text/plain; charset="utf-8")
syslog.txt Edit (766.7 KiB, text/plain; charset="utf-8")

Revision history for this message

Brian Ejike (bejike) wrote on 2021-08-29:

Syslog taken when the headset initiates the connection Edit (270.0 KiB, text/plain)

Revision history for this message

Brian Ejike (bejike) wrote on 2021-08-29:

HCI snoop taken when the PC initiates the connection Edit (243.3 KiB, application/octet-stream)

Revision history for this message

Brian Ejike (bejike) wrote on 2021-08-29:

Syslog taken when the PC initiates the connection Edit (89.0 KiB, text/plain)

Revision history for this message

Brian Ejike (bejike) wrote on 2021-08-29:

I've spent a while studying the snoop/syslogs and Bluez source, and I believe I've narrowed down the issue.

* From the Headset-Initiated snoop, we can see where the headset connected the ACL (23:54:47 UTC), followed shortly by connecting HFP (successfully).

* Very soon after the headset connected HFP, the PC/bluez initiated an AVDTP connection, a bid to connect A2DP -- this is unfriendly behaviour, since the general convention is: whomever created the ACL gets to create the profiles. Or at least is given enough time to connect them, before the other end starts its own attempt.

The result of this behaviour is that the headset, probably getting ready to connect A2DP itself, now gets confused by this incoming PC connection, its firmware apparently not strong or flexible enough to handle this A2DP crossover scenario, manifesting as follows:

That AVDTP channel (for A2DP signalling) does get established, but then strange behaviour is seen while setting up the media-channel -- the headset takes 3s to respond to the AVDTP_DISCOVER command. These 3s end up being costly because...

* The PC creates a SCO connection to the headset around this time -- I believe this is because the PC must route my current audio stream somewhere, and since A2DP media isn't setup yet after all this time, it (PulseAudio?) will settle for HFP/SCO.

(Even this SCO connection takes 5s to complete, headset still not out of the woods.)

Revision history for this message

Brian Ejike (bejike) wrote on 2021-08-29:

So why did Bluez initiate A2DP even when the headset was the one that established the ACL?

The bluetoothd logs help out here:

Aug 29 00:54:47 RhoPC bluetoothd[4046739]: src/adapter.c:connected_callback() hci0 device FC:58:FA:7F:E5:18 connected eir_len 5
Aug 29 00:54:47 RhoPC bluetoothd[4046739]: src/profile.c:ext_confirm() incoming connect from FC:58:FA:7F:E5:18
Aug 29 00:54:47 RhoPC bluetoothd[4046739]: src/service.c:btd_service_ref() 0x562f6441d710: ref=2
Aug 29 00:54:47 RhoPC bluetoothd[4046739]: src/profile.c:ext_confirm() Headset Voice gateway authorizing connection from FC:58:FA:7F:E5:18
Aug 29 00:54:47 RhoPC bluetoothd[4046739]: src/profile.c:ext_auth() FC:58:FA:7F:E5:18 authorized to connect to Headset Voice gateway
Aug 29 00:54:47 RhoPC bluetoothd[4046739]: src/profile.c:ext_connect() Headset Voice gateway connected to FC:58:FA:7F:E5:18
Aug 29 00:54:47 RhoPC bluetoothd[4046739]: src/service.c:change_state() 0x562f6441d710: device FC:58:FA:7F:E5:18 profile Headset Voice gateway state changed: disconnected -> connecting (0)
Aug 29 00:54:47 RhoPC bluetoothd[4046739]: src/service.c:change_state() 0x562f6441d710: device FC:58:FA:7F:E5:18 profile Headset Voice gateway state changed: connecting -> connected (0)
Aug 29 00:54:47 RhoPC bluetoothd[4046739]: src/device.c:device_profile_connected() Headset Voice gateway Success (0)
Aug 29 00:54:47 RhoPC bluetoothd[4046739]: plugins/policy.c:policy_connect() /org/bluez/hci0/dev_FC_58_FA_7F_E5_18 profile a2dp-sink
Aug 29 00:54:47 RhoPC bluetoothd[4046739]: profiles/audio/a2dp.c:a2dp_sink_connect() path /org/bluez/hci0/dev_FC_58_FA_7F_E5_18

One can easily see at the end there, where something in plugins/policy.c kicks off A2DP connection, apparently as soon as it got word that HFP had connected.

Checking that file, the offending code seems to be this in hs_cb():

case BTD_SERVICE_STATE_CONNECTED:
  /* Check if service initiate the connection then proceed
   * immediately otherwise set timer
   */
  if (old_state == BTD_SERVICE_STATE_CONNECTING)
   policy_connect(data, sink);
  else if (btd_service_get_state(sink) !=
      BTD_SERVICE_STATE_CONNECTED)
   policy_set_sink_timer(data);
  break;

The reasoning is sound though -- if the HFP connection was locally initiated i.e. previously in STATE_CONNECTING, then go ahead and connect A2DP right now. Otherwise, respect right-of-way and set a timer to connect it in around 2s, in case the headset somehow fails to do so.

The problem is, this HFP connection was NOT locally initiated. So why was policy.c informed that it is?

So why did Bluez initiate A2DP even when the headset was the one that established the ACL?

The bluetoothd logs help out here:

One can easily see at the end there, where something in plugins/policy.c kicks off A2DP connection, apparently as soon as it got word that HFP had connected.

Checking that file, the offending code seems to be this in hs_cb():

case BTD_SERVICE_STATE_CONNECTED:
		/* Check if service initiate the connection then proceed
		 * immediately otherwise set timer
		 */
		if (old_state == BTD_SERVICE_STATE_CONNECTING)
			policy_connect(data, sink);
		else if (btd_service_get_state(sink) !=
						BTD_SERVICE_STATE_CONNECTED)
			policy_set_sink_timer(data);
		break;

The problem is, this HFP connection was NOT locally initiated. So why was policy.c informed that it is?

Revision history for this message

Brian Ejike (bejike) wrote on 2021-08-29 (last edit on 2021-08-29):

That one's clear enough from the earlier log snippet and source:

Aug 29 00:54:47 RhoPC bluetoothd[4046739]: src/profile.c:ext_connect() Headset Voice gateway connected to FC:58:FA:7F:E5:18
Aug 29 00:54:47 RhoPC bluetoothd[4046739]: src/service.c:change_state() 0x562f6441d710: device FC:58:FA:7F:E5:18 profile Headset Voice gateway state changed: disconnected -> connecting (0)
Aug 29 00:54:47 RhoPC bluetoothd[4046739]: src/service.c:change_state() 0x562f6441d710: device FC:58:FA:7F:E5:18 profile Headset Voice gateway state changed: connecting -> connected (0)

This ext_connect() seems to be called whenever a profile connection is completed, whether successfully or not, whether locally or remotely initiated. Above, we see the state changes it orchestrated -- it first transitions the HFP "service" to CONNECTING and then to CONNECTED pretty quickly:

if (conn->service && service_set_connecting(conn->service) < 0)
  goto drop;
...
if (conn->service)
  btd_service_connecting_complete(conn->service,
      err ? -err->code : -EIO);

Each of these state changes gets propagated to a bunch of listeners -- one of which is policy.c.

=========================
I think that first transition (to CONNECTING) should not have happened, because it takes away the ability of any listeners to judge whether a connection was locally or remotely initiated, and act accordingly. The HFP service should've simply gone from DISCONNECTED to CONNECTED -- that first IF block should be removed entirely.
=========================

If a connection were indeed locally initiated, the service's state would've been set to CONNECTING way back, by btd_service_connect() probably since it looks to be the one that kicks off the connection. ext_connect() only has enough info to make that final jump to CONNECTED.

Revision history for this message

Brian Ejike (bejike) wrote on 2021-08-29 (last edit on 2021-08-29):

I attached snoop/logs where the PC initiated the connection, for comparison. There, the issue doesn't happen, the headset calmly allows the PC to establish all the profiles since the PC connected the ACL.

One can also see the difference in flow:

Aug 29 01:57:02 RhoPC bluetoothd[4053589]: src/device.c:connect_profiles() /org/bluez/hci0/dev_FC_58_FA_7F_E5_18 (all), client :1.160
Aug 29 01:57:02 RhoPC bluetoothd[4053589]: src/service.c:btd_service_ref() 0x556620ba9bb0: ref=2
Aug 29 01:57:02 RhoPC bluetoothd[4053589]: src/service.c:change_state() 0x556620ba9bb0: device FC:58:FA:7F:E5:18 profile Headset Voice gateway state changed: disconnected -> connecting (0)
Aug 29 01:57:05 RhoPC bluetoothd[4053589]: src/adapter.c:connected_callback() hci0 device FC:58:FA:7F:E5:18 connected eir_len 9
Aug 29 01:57:05 RhoPC bluetoothd[4053589]: src/profile.c:ext_connect() Headset Voice gateway connected to FC:58:FA:7F:E5:18
Aug 29 01:57:05 RhoPC bluetoothd[4053589]: src/service.c:change_state() 0x556620ba9bb0: device FC:58:FA:7F:E5:18 profile Headset Voice gateway state changed: connecting -> connected (0)

THe HFP service entered state CONNECTING pretty much as soon as I tapped "Connect" in Blueman, even before the ACL was established. Then 3s later, it entered CONNECTED once the HFP SLC was established, courtesy of ext_connect().

I did a basic search and couldn't find anything that would be hurt by removing that CONNECTING transition -- pretty much every spot that checks for state CONNECTING during transitions, expects it to mean "this service connection was locally initiated". So we just need to make sure it means just that, especially since I see no other indicator accessible to listeners.

Since a bunch of guesswork was done to get here, it would be neat if someone experienced with the stack can confirm how much of this is even correct, and if the proposed solution makes sense :-)

Brian Ejike (bejike) on 2021-08-29

tags:

added: a2dp hfp sco

Revision history for this message

Daniel van Vugt (vanvugt) wrote on 2021-08-30:

Thank you for taking the time to report this bug and helping to make Ubuntu better. This particular bug has already been reported and is a duplicate of bug 1838151, so it is being marked as such. Please look at the other bug report to see if there is any missing information that you can provide, or to see if there is a workaround for the bug. Additionally, any further discussion regarding the bug should occur in the other report. Feel free to continue to report any other bugs you may find.

affects:

bluez (Ubuntu) → pulseaudio (Ubuntu)

Revision history for this message

Brian Ejike (bejike) wrote on 2021-08-30:

#10

Hi Daniel, thanks for responding. This isn't a duplicate of that issue -- that ticket complains of the current NB/8k default which is pretty low-quality, now requesting that the stack support WBS/16k for higher quality voice.

OTOH, this one is about audio getting streamed over a different transport (SCO) entirely than expected (AVDTP), as explained above.

Revision history for this message

Daniel van Vugt (vanvugt) wrote on 2021-08-30:

#11

Please test Ubuntu 21.10 where many of these issues are now fixed and tell us if the issue persists:

http://cdimage.ubuntu.com/daily-live/current/

Changed in pulseaudio (Ubuntu):
status:	New → Incomplete

Revision history for this message

Brian Ejike (bejike) wrote on 2021-09-02 (last edit on 2021-09-02):

#12

Syslog taken when the headset initiates the connection on Impish Indri Edit (469.7 KiB, text/plain)

Nope, if anything, it's even worse. On Indri, the PC audio doesn't even get streamed over SCO at all -- the media channel just gets disconnected when Bluez times out in the middle of an AVDTP SET_CONFIGURATION. Here, as before, both headset and Bluez are jockeying for first to connect/setup A2DP and the headset isn't handling this contest well. At the end of the whole thing, the headset just disconnects and the PC audio plays through the internal speakers.

Bluez needs to wait for the designated 2s already in its code, before attempting to connect any profiles it suspects the other side failed to connect.

I've attached snoop and syslogs taken during the Indri test. There should be more than enough data here already for someone to check this out, especially with the explanation offered in earlier comments.

Revision history for this message

Brian Ejike (bejike) wrote on 2021-09-02:

#13

HCI snoop taken when the headset initiates the connection on Indri Edit (19.9 KiB, application/octet-stream)

Revision history for this message

Brian Ejike (bejike) wrote on 2021-09-02:

#14

HeadsetInitiated_Android10.cfa Edit (439.9 KiB, application/octet-stream)

For comparison, I've attached these Android HCI snoop logs, taken when the same headset initiates a connection to an Android handset this time.

From ~22:00:50 UTC when the ACL was connected between them, one can see that the handset remains chill, allowing the headset to connect any profiles its heart desires. The headset happened to connect only HFP and A2DP signalling here, before going "silent". Then precisely 2s later, the handset accepts the responsibility of connecting the rest -- it connects A2DP media, while the headset then connects AVRCP (probably on some internal timeout).

Within 500ms, everything relevant had been connected and configured, and media streaming was underway, showing none of the issues I found with my PC.

Daniel van Vugt (vanvugt) on 2021-09-03

Changed in pulseaudio (Ubuntu):
status:	Incomplete → New

Revision history for this message

Igor V. Kovalenko (i-garrison) wrote on 2021-09-11:

#15

Hi Brian, would you mind filing an issue on bluez tracker for this analysis here https://github.com/bluez/bluez/issues

To me it looks valid, but still running this through bluez maintainers is a good idea.

Revision history for this message

Brian Ejike (bejike) wrote on 2021-09-12:

#16

Thanks Igor, I didn't know Bluez issues are being tracked on Github, would've probably raised this there first/instead. I've opened it here: https://github.com/bluez/bluez/issues/205, offering a summary, people can always come here if they need to get traces and such.

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Bug attachments

Add attachment

Remote bug watches

auto-github-bluez-bluez #205
[closed] Edit

Bug watches keep track of this bug in other bug trackers.

Ubuntupulseaudio package

PC streams music over low-quality HFP/SCO connection, instead of A2DP/AVDTP

Bug Description

Other bug subscribers

Bug attachments

Remote bug watches

Ubuntu
pulseaudio package