search

arkq / bluez-alsa

Bluetooth Audio ALSA Backend
MIT License
856 stars 188 forks source link

Output only works from SCO. A2DP profile returns PCM error. #554

Closed reitermiller closed 1 year ago

reitermiller commented 2 years ago

Hi, I'm experiencing problems outputting to Airpods Pro(s) over bluez-alsa v. v3.1.0-106-g177e163. I am able to output over SCO aplay -D ass2 example.wav, but A2DP output, aplay -D ass example.wav returns the following:

eros@lycia /tmp                                                                                                                                                                    [10:20:04]
> $ aplay -D ass example.wav                                                                                                                                                            
D: ../../../src/asound/bluealsa-pcm.c:1309: Getting BlueALSA PCM: PLAYBACK 74:65:0C:8E:5B:9D a2dp
ALSA lib ../../../src/asound/bluealsa-pcm.c:1313:(_snd_pcm_bluealsa_open) Couldn't get BlueALSA PCM: PCM not found
aplay: main:852: audio open error: No such device

(working) output of sco playback

eros@lycia /tmp                                                                                                                                                                    [10:23:48]
> $ aplay -D ass2 example.wav                                                                                                                                                                
D: ../../../src/asound/bluealsa-pcm.c:1309: Getting BlueALSA PCM: PLAYBACK 74:65:0C:8E:5B:9D sco
D: ../../../src/asound/bluealsa-pcm.c:1062: /org/bluealsa/hci0/dev_74_65_0C_8E_5B_9D/hfpag/sink: Setting constraints
Playing WAVE 'example.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
D: ../../../src/asound/bluealsa-pcm.c:532: /org/bluealsa/hci0/dev_74_65_0C_8E_5B_9D/hfpag/sink: Initializing HW
D: ../../../src/asound/bluealsa-pcm.c:567: /org/bluealsa/hci0/dev_74_65_0C_8E_5B_9D/hfpag/sink: FIFO buffer size: 2048 frames
D: ../../../src/asound/bluealsa-pcm.c:573: /org/bluealsa/hci0/dev_74_65_0C_8E_5B_9D/hfpag/sink: Selected HW buffer: 4 periods x 2000 bytes == 8000 bytes
D: ../../../src/asound/bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_74_65_0C_8E_5B_9D/hfpag/sink: Initializing SW
D: ../../../src/asound/bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_74_65_0C_8E_5B_9D/hfpag/sink: Initializing SW
D: ../../../src/asound/bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_74_65_0C_8E_5B_9D/hfpag/sink: Initializing SW
D: ../../../src/asound/bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_74_65_0C_8E_5B_9D/hfpag/sink: Initializing SW
D: ../../../src/asound/bluealsa-pcm.c:639: /org/bluealsa/hci0/dev_74_65_0C_8E_5B_9D/hfpag/sink: Prepared
D: ../../../src/asound/bluealsa-pcm.c:600: /org/bluealsa/hci0/dev_74_65_0C_8E_5B_9D/hfpag/sink: Initializing SW
D: ../../../src/asound/bluealsa-pcm.c:356: /org/bluealsa/hci0/dev_74_65_0C_8E_5B_9D/hfpag/sink: Starting
D: ../../../src/asound/bluealsa-pcm.c:226: /org/bluealsa/hci0/dev_74_65_0C_8E_5B_9D/hfpag/sink: Starting IO loop: 8

Hardware config:

XPS 15 7590 Pop_OS! 20.04 Focal Airpods Pro

bluetoothctl info 74:65:0C:8E:5B:9D 

Device 74:65:0C:8E:5B:9D (public)
    Name: milfpods
    Alias: milfpods
    Class: 0x00240418
    Icon: audio-card
    Paired: yes
    Trusted: yes
    Blocked: no
    Connected: yes
    LegacyPairing: no
    UUID: Service Discovery Serve.. (00001000-0000-1000-8000-00805f9b34fb)
    UUID: Audio Sink                (0000110b-0000-1000-8000-00805f9b34fb)
    UUID: A/V Remote Control Target (0000110c-0000-1000-8000-00805f9b34fb)
    UUID: A/V Remote Control        (0000110e-0000-1000-8000-00805f9b34fb)
    UUID: Handsfree                 (0000111e-0000-1000-8000-00805f9b34fb)
    UUID: PnP Information           (00001200-0000-1000-8000-00805f9b34fb)
    UUID: Vendor specific           (74ec2172-0bad-4d01-8f77-997b2be0722a)
    Modalias: bluetooth:v004Cp200Ed88A5

cat ~/.asoundrc

pcm.!default {
    type plug
    slave { pcm "jack" }
}

pcm.jack {
    type jack
    playback_ports {
        0 system:playback_1
        1 system:playback_2
    }
    capture_ports {
        0 system:capture_1
        1 system:capture_2
    }
}

ctl.mixer0 {
    type hw
    card 0
}

defaults.bluealsa.interface "org.bluealsa"
defaults.bluealsa.device "74:65:0C:8E:5B:9D"
defaults.bluealsa.profile "a2dp"
defaults.bluealsa.delay 10000

pcm.ass {
    type plug
    slave.pcm {
        type bluealsa
        device "74:65:0C:8E:5B:9D"
        profile "a2dp"
    }
}

pcm.ass2 {
    type plug
    slave.pcm {
        type bluealsa
        device "74:65:0C:8E:5B:9D"
        profile "sco"
    }
}

sudo bluealsa -p a2dp-sink -p a2dp-source

eros@lycia /tmp                                                                                                                                                                    [10:18:12]
> $ sudo bluealsa -p a2dp-source -p a2dp-sink                                                                                                                                                
bluealsa: D: ../../src/ofono.c:629: Checking oFono service presence
bluealsa: D: ../../src/main.c:580: Starting main dispatching loop
bluealsa: D: ../../src/main.c:112: Acquired D-Bus service name: org.bluealsa
bluealsa: D: ../../src/bluealsa-dbus.c:426: Registering D-Bus manager: /org/bluealsa
bluealsa: D: ../../src/bluez.c:679: Registering battery provider: /org/bluez/hci0/battery
bluealsa: D: ../../src/bluez.c:699: BlueZ battery provider support not available
bluealsa: D: ../../src/bluez.c:493: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/source/1
bluealsa: D: ../../src/bluez.c:402: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/source/1
bluealsa: D: ../../src/bluez.c:493: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/source/2
bluealsa: D: ../../src/bluez.c:402: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/source/2
bluealsa: D: ../../src/bluez.c:493: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/sink/1
bluealsa: D: ../../src/bluez.c:402: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/sink/1
bluealsa: D: ../../src/bluez.c:493: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/sink/2
bluealsa: D: ../../src/bluez.c:402: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/sink/2
bluealsa: D: ../../src/bluez.c:928: Creating hands-free profile object: /org/bluez/HSP/AudioGateway
bluealsa: D: ../../src/bluez.c:852: Registering hands-free profile: /org/bluez/HSP/AudioGateway
bluealsa: D: ../../src/bluez.c:928: Creating hands-free profile object: /org/bluez/HFP/AudioGateway
bluealsa: D: ../../src/bluez.c:852: Registering hands-free profile: /org/bluez/HFP/AudioGateway
bluealsa: D: ../../src/dbus.c:66: Called: org.bluez.Profile1.NewConnection() on /org/bluez/HFP/AudioGateway
bluealsa: D: ../../src/ba-rfcomm.c:1415: Created new RFCOMM thread [ba-rfcomm]: HFP Audio Gateway
bluealsa: D: ../../src/ba-rfcomm.c:1014: Starting RFCOMM loop: HFP Audio Gateway
bluealsa: D: ../../src/sco.c:206: Created SCO dispatcher [ba-sco-dispatch]: hci0
bluealsa: D: ../../src/bluez.c:767: HFP Audio Gateway (CVSD) configured for device 74:65:0C:8E:5B:9D
bluealsa: D: ../../src/sco.c:80: Starting SCO dispatcher loop: hci0
bluealsa: D: ../../src/at.c:162: AT message: SET: command:+BRSF, value:155
bluealsa: D: ../../src/ba-rfcomm.c:108: Sending AT message: RESP: command:+BRSF, value:2272
bluealsa: D: ../../src/ba-rfcomm.c:108: Sending AT message: RESP: command:(null), value:OK
bluealsa: D: ../../src/ba-rfcomm.c:127: RFCOMM: HFP Audio Gateway (CVSD) state transition: 0 -> 2
bluealsa: D: ../../src/at.c:162: AT message: TEST: command:+CIND, value:(null)
bluealsa: D: ../../src/ba-rfcomm.c:108: Sending AT message: RESP: command:+CIND, value:("service",(0-1)),("call",(0,1)),("callsetup",(0-3)),("callheld",(0-2)),("signal",(0-5)),("roam",(0-1)),("battchg",(0-5))
bluealsa: D: ../../src/ba-rfcomm.c:108: Sending AT message: RESP: command:(null), value:OK
bluealsa: D: ../../src/ba-rfcomm.c:127: RFCOMM: HFP Audio Gateway (CVSD) state transition: 2 -> 5
bluealsa: D: ../../src/bluez.c:1049: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
bluealsa: D: ../../src/bluez.c:1145: Adding new Stream End-Point: 74:65:0C:8E:5B:9D: SBC
bluealsa: D: ../../src/bluez.c:1049: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
bluealsa: D: ../../src/bluez.c:1145: Adding new Stream End-Point: 74:65:0C:8E:5B:9D: AAC
bluealsa: D: ../../src/at.c:162: AT message: GET: command:+CIND, value:(null)
bluealsa: D: ../../src/ba-rfcomm.c:108: Sending AT message: RESP: command:+CIND, value:0,0,0,0,0,0,5
bluealsa: D: ../../src/ba-rfcomm.c:108: Sending AT message: RESP: command:(null), value:OK
bluealsa: D: ../../src/ba-rfcomm.c:127: RFCOMM: HFP Audio Gateway (CVSD) state transition: 5 -> 7
bluealsa: D: ../../src/bluez.c:1049: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
bluealsa: D: ../../src/a2dp.c:262: Unknown vendor codec [len=14]: 4c00000001800080008c0083e800
bluealsa: D: ../../src/bluez.c:1145: Adding new Stream End-Point: 74:65:0C:8E:5B:9D: (null)
bluealsa: D: ../../src/at.c:162: AT message: SET: command:+CMER, value:3,0,0,1
bluealsa: D: ../../src/ba-rfcomm.c:108: Sending AT message: RESP: command:(null), value:OK
bluealsa: D: ../../src/ba-rfcomm.c:127: RFCOMM: HFP Audio Gateway (CVSD) state transition: 7 -> 8
bluealsa: D: ../../src/ba-rfcomm.c:127: RFCOMM: HFP Audio Gateway (CVSD) state transition: 8 -> 9
bluealsa: D: ../../src/at.c:162: AT message: SET: command:+VGS, value:11
bluealsa: D: ../../src/ba-rfcomm.c:108: Sending AT message: RESP: command:(null), value:OK
bluealsa: D: ../../src/bluez.c:1049: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
bluealsa: D: ../../src/at.c:162: AT message: SET: command:+VGM, value:8
bluealsa: D: ../../src/ba-rfcomm.c:108: Sending AT message: RESP: command:(null), value:OK
bluealsa: D: ../../src/at.c:162: AT message: SET: command:+BIA, value:0,1,1,1,0,0,0
bluealsa: D: ../../src/ba-rfcomm.c:108: Sending AT message: RESP: command:(null), value:OK
bluealsa: D: ../../src/at.c:162: AT message: SET: command:+NREC, value:0
bluealsa: D: ../../src/ba-rfcomm.c:108: Sending AT message: RESP: command:(null), value:ERROR
bluealsa: E: ../../src/bluez.c:1241: Transport not available: /org/bluez/hci0/dev_74_65_0C_8E_5B_9D/sep1/fd2
bluealsa: D: ../../src/dbus.c:66: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_74_65_0C_8E_5B_9D/hfpag/sink
bluealsa: E: ../../src/bluez.c:1241: Transport not available: /org/bluez/hci0/dev_74_65_0C_8E_5B_9D/sep1/fd2
bluealsa: D: ../../src/ba-transport.c:715: New SCO link: 74:65:0C:8E:5B:9D: 22
bluealsa: D: ../../src/hci.c:133: SCO link socket MTU: 22: 96
bluealsa: D: ../../src/hci.c:141: USB adjusted SCO MTU: 22: 48
bluealsa: D: ../../src/ba-transport.c:1166: Starting transport: HFP Audio Gateway (CVSD)
bluealsa: D: ../../src/ba-transport.c:297: Created BT socket duplicate: [22]: 23
bluealsa: D: ../../src/ba-transport.c:1487: Created new IO thread [ba-sco-enc]: HFP Audio Gateway (CVSD)
bluealsa: D: ../../src/ba-transport.c:297: Created BT socket duplicate: [22]: 24
bluealsa: D: ../../src/sco.c:232: IO loop: START: sco_cvsd_enc_thread: HFP Audio Gateway (CVSD)
bluealsa: D: ../../src/ba-transport.c:1487: Created new IO thread [ba-sco-dec]: HFP Audio Gateway (CVSD)
bluealsa: D: ../../src/sco.c:303: IO loop: START: sco_cvsd_dec_thread: HFP Audio Gateway (CVSD)
bluealsa: D: ../../src/ba-transport.c:1402: PCM resumed: 8
bluealsa: D: ../../src/ba-transport.c:1434: PCM dropped: 8
bluealsa: D: ../../src/ba-transport.c:1449: Closing PCM: 8
bluealsa: D: ../../src/ba-transport.c:441: PCM clients check keep-alive: 0 ms
bluealsa: D: ../../src/ba-transport.c:441: PCM clients check keep-alive: 0 ms
bluealsa: D: ../../src/ba-transport.c:390: Stopping transport: No PCM clients
bluealsa: D: ../../src/ba-transport.c:309: Closing BT socket duplicate [22]: 23
bluealsa: D: ../../src/ba-transport.c:730: Releasing SCO link: 22
bluealsa: D: ../../src/ba-transport.c:1512: Exiting IO thread [ba-sco-enc]: HFP Audio Gateway (CVSD)
bluealsa: D: ../../src/ba-transport.c:309: Closing BT socket duplicate [-1]: 24
bluealsa: D: ../../src/ba-transport.c:1512: Exiting IO thread [ba-sco-dec]: HFP Audio Gateway (CVSD)
bluealsa: D: ../../src/dbus.c:66: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_74_65_0C_8E_5B_9D/hfpag/sink
bluealsa: D: ../../src/ba-transport.c:715: New SCO link: 74:65:0C:8E:5B:9D: 22
bluealsa: D: ../../src/hci.c:133: SCO link socket MTU: 22: 96
bluealsa: D: ../../src/hci.c:141: USB adjusted SCO MTU: 22: 48
bluealsa: D: ../../src/ba-transport.c:1166: Starting transport: HFP Audio Gateway (CVSD)
bluealsa: D: ../../src/ba-transport.c:297: Created BT socket duplicate: [22]: 23
bluealsa: D: ../../src/ba-transport.c:1487: Created new IO thread [ba-sco-enc]: HFP Audio Gateway (CVSD)
bluealsa: D: ../../src/ba-transport.c:297: Created BT socket duplicate: [22]: 24
bluealsa: D: ../../src/sco.c:232: IO loop: START: sco_cvsd_enc_thread: HFP Audio Gateway (CVSD)
bluealsa: D: ../../src/ba-transport.c:1487: Created new IO thread [ba-sco-dec]: HFP Audio Gateway (CVSD)
bluealsa: D: ../../src/sco.c:303: IO loop: START: sco_cvsd_dec_thread: HFP Audio Gateway (CVSD)
bluealsa: D: ../../src/ba-transport.c:1402: PCM resumed: 8
bluealsa: D: ../../src/ba-transport.c:1434: PCM dropped: 8
bluealsa: D: ../../src/ba-transport.c:1449: Closing PCM: 8
bluealsa: D: ../../src/ba-transport.c:441: PCM clients check keep-alive: 0 ms
bluealsa: D: ../../src/ba-transport.c:390: Stopping transport: No PCM clients
bluealsa: D: ../../src/ba-transport.c:309: Closing BT socket duplicate [22]: 23
bluealsa: D: ../../src/ba-transport.c:730: Releasing SCO link: 22
bluealsa: D: ../../src/ba-transport.c:1512: Exiting IO thread [ba-sco-enc]: HFP Audio Gateway (CVSD)
bluealsa: D: ../../src/ba-transport.c:309: Closing BT socket duplicate [-1]: 24
bluealsa: D: ../../src/ba-transport.c:1512: Exiting IO thread [ba-sco-dec]: HFP Audio Gateway (CVSD)
bluealsa: D: ../../src/bluez.c:1049: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
bluealsa: D: ../../src/bluez.c:1049: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
bluealsa: D: ../../src/bluez.c:1156: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved()
bluealsa: D: ../../src/bluez.c:1156: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved()
bluealsa: D: ../../src/bluez.c:1156: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved()
bluealsa: D: ../../src/bluez.c:1156: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved()
bluealsa: D: ../../src/bluez.c:1156: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved()
bluealsa: D: ../../src/bluez.c:1049: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
bluealsa: D: ../../src/bluez.c:1049: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
borine commented 2 years ago

I suspect this is an issue with the Bluez cache. I've seen similar issues when I changed the codec(s) used by bluealsa after I've already paired the headphones. This may be fixed in very recent bluez code (see for example https://github.com/bluez/bluez/issues/313).

In the meantime, you could try manually deleting the cache; however this is not an officially supported procedure for Bluez!. I fixed my similar issue this way. Suppose your host BT adapter is AA:AA:AA:AA:AA:AA, and your remote headphone device is DD:DD:DD:DD:DD:DD. You need to unpair your headphones first: bluetoothctl remove DD:DD:DD:DD:DD:DD

This is is how I cleared its cache:

# start a root shell
sudo -s

# stop bluealsa
systemctl stop bluealsa

# make absolutely sure bluetoothd is not running:
systemctl mask bluetooth
systemctl stop bluetooth

# navigate to the bluetooth cache
cd /var/lib/bluetooth/AA:AA:AA:AA:AA:AA/cache

# remove the cache file for your headphones
rm DD:DD:DD:DD:DD:DD

# restart bluetoothd
systemctl unmask bluetooth
systemctl start bluetooth

# restart bluealsa
systemctl start bluealsa

# close the root shell
exit

Now re-pair the headphones and hopefully they will now attempt to connect the correct codec.

borine commented 2 years ago

I believe Bluez has now fixed this bug in bluez release 5.65

borine commented 1 year ago

I've been setting up a new device with BlueALSA, and got the symptoms reported here, but now clearing the Bluez cache did not help. It turns out that it is now necessary for both devices to trust each other for A2DP connections to succeed. So I fixed it using bluetoothctl telling Bluez to trust the remote device. Now connecting creates transports for both A2DP and HFP.

borine commented 1 year ago

Seems that the symptoms reported here are all actually faults in Bluez. PopOS! 20.04 uses bluez 5.53 which is known to have problems with pairing and connecting when using the NoInputNoOutput capabililty, and also has the cache management bug. The NoInputNoOutput issue appears to have been fixed in Bluez 5.61 (it is certainly OK in Bluez 5.64) and the cache problem is fixed in Bluez 5.65.

borine commented 1 year ago

As this issue is believed to be caused by Bluez, not BlueALSA, and there have been no further comments to suggest otherwise for nearly a year, I am closing now.