bluez-alsa crash when testing aplay playback device

moozhub commented 4 years ago

Hello,

I'm not fully sure on what may be going on since I just started playing with this project. My ultimate goal is to get a headset of mine to work with the Mumble voice application through ALSA since I recently ditched Pulseaudio. I'm able to pair the devices like normal and get them recognized with aplay but I seem to be experiencing a crash when attempting to do a simple playback test through the headset. I've pasted my findings below and appreciate any assistance.

.asoundrc:

pcm.!default {
      type plug
      slave.pcm {
              type bluealsa
              device "48:C1:AC:E6:XX:XX"
              profile "a2dp"
      }
      hint {
              show on
              description "BT Headset"
      }
}

BT Pairing:

[CHG] Controller BC:14:EF:68:XX:XX Class: 0x00500104
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000110e-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001200-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001132-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001133-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000112f-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001800-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001105-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001801-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001106-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000110c-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001104-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000110e-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001200-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001132-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001133-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000112f-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001800-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001105-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001801-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001106-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000110c-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000110a-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001104-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX Class: 0x00100104
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000110e-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001200-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001132-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001112-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001133-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000112f-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001800-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001105-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001801-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001106-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000110c-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000110a-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000111f-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001104-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX Class: 0x00180104
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000110e-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001200-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001132-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001112-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001133-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000112f-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001800-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001105-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001801-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001106-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000110c-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000110a-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000111f-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001104-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000110e-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001200-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001132-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001112-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001133-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000112f-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001800-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001105-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001801-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001106-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000110c-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000110a-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000111f-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001104-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX Class: 0x00580104
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000110e-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001200-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001132-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001112-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001133-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000112f-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001800-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001105-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001801-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001106-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000110c-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000110a-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 0000111f-0000-1000-8000-00805f9b34fb
[CHG] Controller BC:14:EF:68:XX:XX UUIDs: 00001104-0000-1000-8000-00805f9b34fb
[CHG] Device 48:C1:AC:E6:XX:XX Connected: yes
Authorize service
[agent] Authorize service 0000111F-0000-1000-8000-00805F9B34FB (yes/no): yes
[PLT_M50]#

bluealsa-aplay devices:

$ bluealsa-aplay -lL
bluealsa:SRV=org.bluealsa,DEV=48:C1:AC:E6:XX:XX,PROFILE=a2dp
    PLT_M50, audio-card, playback
    A2DP (SBC): S16_LE 2 channels 48000 Hz
bluealsa:SRV=org.bluealsa,DEV=48:C1:AC:E6:XX:XX,PROFILE=sco
    PLT_M50, audio-card, playback
    SCO (CVSD): S16_LE 1 channel 8000 Hz
bluealsa:SRV=org.bluealsa,DEV=48:C1:AC:E6:XX:XX,PROFILE=sco
    PLT_M50, audio-card, capture
    SCO (CVSD): S16_LE 1 channel 8000 Hz
**** List of PLAYBACK Bluetooth Devices ****
hci0: 48:C1:AC:E6:XX:XX [PLT_M50], audio-card
  A2DP (SBC): S16_LE 2 channels 48000 Hz
  SCO (CVSD): S16_LE 1 channel 8000 Hz
**** List of CAPTURE Bluetooth Devices ****
hci0: 48:C1:AC:E6:XX:XX [PLT_M50], audio-card
  SCO (CVSD): S16_LE 1 channel 8000 Hz

Execution of aplay:

$ aplay something.wav 
D: ../../../src/asound/bluealsa-pcm.c:761: /org/bluealsa/hci0/dev_48_C1_AC_E6_9D_B1/a2dpsrc/sink: Setting constraints
Playing WAVE 'something.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
D: ../../../src/asound/bluealsa-pcm.c:397: /org/bluealsa/hci0/dev_48_C1_AC_E6_9D_B1/a2dpsrc/sink: Initializing HW
D: ../../../src/asound/bluealsa-pcm.c:404: /org/bluealsa/hci0/dev_48_C1_AC_E6_9D_B1/a2dpsrc/sink: Couldn't open PCM: Remote peer disconnected
aplay: set_params:1407: Unable to install hw params:
ACCESS:  RW_INTERLEAVED
FORMAT:  S16_LE
SUBFORMAT:  STD
SAMPLE_BITS: 16
FRAME_BITS: 32
CHANNELS: 2
RATE: 44100
PERIOD_TIME: [85333 85334)
PERIOD_SIZE: (3763 3764)
PERIOD_BYTES: (15052 15056)
PERIODS: (5 6)
BUFFER_TIME: (511882 511883)
BUFFER_SIZE: 22574
BUFFER_BYTES: 90296
TICK_TIME: 0
D: ../../../src/asound/bluealsa-pcm.c:386: /org/bluealsa/hci0/dev_48_C1_AC_E6_9D_B1/a2dpsrc/sink: Closing

bluealsa.service

Aug 22 21:28:35 computer systemd[1]: Starting Bluealsa daemon...
Aug 22 21:28:35 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ofono.c:628: Checking oFono service presence
Aug 22 21:28:35 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/AAC/Source/1
Aug 22 21:28:35 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/AAC/Source/1
Aug 22 21:28:35 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/AAC/Source/2
Aug 22 21:28:35 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/AAC/Source/2
Aug 22 21:28:35 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/Source/1
Aug 22 21:28:35 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/Source/1
Aug 22 21:28:35 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/Source/2
Aug 22 21:28:35 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/Source/2
Aug 22 21:28:35 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:785: Creating hands-free profile object: /org/bluez/HSP/AudioGateway
Aug 22 21:28:35 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:719: Registering hands-free profile: /org/bluez/HSP/AudioGateway
Aug 22 21:28:35 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:785: Creating hands-free profile object: /org/bluez/HFP/AudioGateway
Aug 22 21:28:35 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:719: Registering hands-free profile: /org/bluez/HFP/AudioGateway
Aug 22 21:28:35 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/main.c:397: Acquiring D-Bus service name: org.bluealsa
Aug 22 21:28:35 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/main.c:402: Starting main dispatching loop
Aug 22 21:28:35 computer systemd[1]: Started Bluealsa daemon.
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluez.Profile1.NewConnection() on /org/bluez/HFP/AudioGateway
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:880: Starting RFCOMM loop: HFP Audio Gateway
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:1262: Created new RFCOMM thread [ba-rfcomm]: HFP Audio Gateway
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/sco.c:166: Checking Broadcom internal SCO routing
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/sco.c:172: Current SCO interface setup: 1 2 0 1 1
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/sco.c:200: Created SCO dispatcher [ba-sco-dispatch]: hci0
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:609: HFP Audio Gateway configured for device 48:C1:AC:E6:XX:XX
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:750: Starting transport: HFP Audio Gateway
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/sco.c:77: Starting SCO dispatcher loop: hci0
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1032: Created new thread [ba-sco]: HFP Audio Gateway
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/sco.c:241: Starting SCO loop: HFP Audio Gateway
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+BRSF, value:25
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:+BRSF, value:2784
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:126: RFCOMM: HFP Audio Gateway (CVSD) state transition: 0 -> 2
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:998: Adding new Stream End-Point: 48:C1:AC:E6:XX:XX: SBC
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: TEST: command:+CIND, value:(null)
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: 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))
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:126: RFCOMM: HFP Audio Gateway (CVSD) state transition: 2 -> 5
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: GET: command:+CIND, value:(null)
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:+CIND, value:0,0,0,0,0,0,5
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:126: RFCOMM: HFP Audio Gateway (CVSD) state transition: 5 -> 7
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluez.MediaEndpoint1.SelectConfiguration() on /org/bluez/hci0/A2DP/SBC/Source/1
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+CMER, value:3,0,0,1
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:126: RFCOMM: HFP Audio Gateway (CVSD) state transition: 7 -> 8
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:126: RFCOMM: HFP Audio Gateway (CVSD) state transition: 8 -> 9
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluez.MediaEndpoint1.SetConfiguration() on /org/bluez/hci0/A2DP/SBC/Source/1
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/a2dp.c:664: Selected A2DP SBC bit-pool range: [2, 89]
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:291: A2DP Source (SBC) configured for device 48:C1:AC:E6:XX:XX
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:294: Configuration: channels: 2, sampling: 48000
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/Source/3
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/Source/3
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+COPS, value:3,0
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: W: Unsupported AT message: SET: command:+COPS, value:3,0
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:ERROR
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+XAPL, value:0A5C-0064-0069,7
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:+XAPL=BlueALSA,6
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+VGS, value:15
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+CMEE, value:1
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: W: Unsupported AT message: SET: command:+CMEE, value:1
Aug 22 21:28:56 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:ERROR
Aug 22 21:29:21 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+XAPL, value:0A5C-0064-0069,7
Aug 22 21:29:21 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:+XAPL=BlueALSA,6
Aug 22 21:29:21 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:29:50 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+XAPL, value:0A5C-0064-0069,7
Aug 22 21:29:50 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:+XAPL=BlueALSA,6
Aug 22 21:29:50 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:30:50 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+XAPL, value:0A5C-0064-0069,7
Aug 22 21:30:50 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:+XAPL=BlueALSA,6
Aug 22 21:30:50 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:30:51 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluealsa.Manager1.GetPCMs() on /org/bluealsa
Aug 22 21:31:19 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+XAPL, value:0A5C-0064-0069,7
Aug 22 21:31:19 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:+XAPL=BlueALSA,6
Aug 22 21:31:19 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:31:49 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+XAPL, value:0A5C-0064-0069,7
Aug 22 21:31:49 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:+XAPL=BlueALSA,6
Aug 22 21:31:49 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:32:20 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+XAPL, value:0A5C-0064-0069,7
Aug 22 21:32:20 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:+XAPL=BlueALSA,6
Aug 22 21:32:20 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:32:49 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+XAPL, value:0A5C-0064-0069,7
Aug 22 21:32:49 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:+XAPL=BlueALSA,6
Aug 22 21:32:49 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:33:19 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+XAPL, value:0A5C-0064-0069,7
Aug 22 21:33:19 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:+XAPL=BlueALSA,6
Aug 22 21:33:19 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:33:38 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluealsa.Manager1.GetPCMs() on /org/bluealsa
Aug 22 21:33:38 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_48_C1_AC_E6_9D_B1/a2dpsrc/sink
Aug 22 21:33:39 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:868: New transport: 20 (MTU: R:672 W:1008)
Aug 22 21:33:39 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:1068: Signal: org.freedesktop.DBus.Properties.PropertiesChanged()
Aug 22 21:33:39 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/bluez.c:1104: Signal: PropertiesChanged: org.bluez.MediaTransport1: State
Aug 22 21:33:39 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:750: Starting transport: A2DP Source (SBC)
Aug 22 21:33:39 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/sbc.c:114: SBC setup: 48000 Hz JointStereo allocation=SNR blocks=16 sub-bands=8 bit-pool=51 => 345000 bps
Aug 22 21:33:39 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/a2dp-audio.c:643: Starting IO loop: A2DP Source (SBC)
Aug 22 21:33:39 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/a2dp-audio.c:143: PCM has been closed: 16
Aug 22 21:33:39 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1006: Closing PCM: 16
Aug 22 21:33:39 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/a2dp-audio.c:313: Keep-alive polling: 0
Aug 22 21:33:39 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:901: Releasing A2DP transport: A2DP Source (SBC)
Aug 22 21:33:39 computer bluealsa[59158]: /usr/bin/bluealsa: E: Couldn't release transport: The connection is closed
Aug 22 21:33:39 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1054: Exiting IO thread: A2DP Source (SBC)
Aug 22 21:33:39 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1032: Created new thread [ba-a2dp-sbc]: A2DP Source (SBC)
Aug 22 21:33:39 computer bluealsa[59158]: /usr/bin/bluealsa: D: ../../src/main.c:406: Exiting main loop
Aug 22 21:33:39 computer systemd[1]: bluealsa.service: Succeeded.

strace of bluealsa process when attempting playback (may not be entirely useful, but whatever):

$ strace -p 59158
strace: attach: ptrace(PTRACE_SEIZE, 59158): Operation not permitted
[gmann@desktop bluez-alsa]$ sudo strace -p 59158
strace: Process 59158 attached
restart_syscall(<... resuming interrupted read ...>) = 1
read(5, "\1\0\0\0\0\0\0\0", 16)         = 8
write(2, "/usr/bin/bluealsa: ", 19)     = 19
write(2, "D: ", 3)                      = 3
write(2, "../../src/dbus.c:57: Called: org"..., 77) = 77
write(2, "\n", 1)                       = 1
write(7, "\1\0\0\0\0\0\0\0", 8)         = 8
futex(0x11c1790, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x11c13b0, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x11b8058, FUTEX_WAKE_PRIVATE, 1) = 1
poll([{fd=5, events=POLLIN}], 1, -1)    = 1 ([{fd=5, revents=POLLIN}])
read(5, "\1\0\0\0\0\0\0\0", 16)         = 8
write(2, "/usr/bin/bluealsa: ", 19)     = 19
write(2, "D: ", 3)                      = 3
write(2, "../../src/dbus.c:57: Called: org"..., 110) = 110
write(2, "\n", 1)                       = 1
mmap(NULL, 8392704, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0x7f7d997fb000
mprotect(0x7f7d997fc000, 8388608, PROT_READ|PROT_WRITE) = 0
clone(child_stack=0x7f7d99ffaeb0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tid=[59866], tls=0x7f7d99ffb700, child_tidptr=0x7f7d99ffb9d0) = 59866
poll([{fd=5, events=POLLIN}], 1, -1)    = 1 ([{fd=5, revents=POLLIN}])
read(5, "\3\0\0\0\0\0\0\0", 16)         = 8
poll([{fd=5, events=POLLIN}, {fd=18, events=POLLIN}], 2, 0) = 0 (Timeout)
write(2, "/usr/bin/bluealsa: ", 19)     = 19
write(2, "D: ", 3)                      = 3
write(2, "../../src/bluez.c:1068: Signal: "..., 83) = 83
write(2, "\n", 1)                       = 1
write(2, "/usr/bin/bluealsa: ", 19)     = 19
write(2, "D: ", 3)                      = 3
write(2, "../../src/bluez.c:1104: Signal: "..., 83) = 83
write(2, "\n", 1)                       = 1
write(2, "/usr/bin/bluealsa: ", 19)     = 19
write(2, "D: ", 3)                      = 3
write(2, "../../src/ba-transport.c:750: St"..., 67) = 67
write(2, "\n", 1)                       = 1
clone(child_stack=0x7f7d99ffaeb0, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tid=[59868], tls=0x7f7d99ffb700, child_tidptr=0x7f7d99ffb9d0) = 59868
openat(AT_FDCWD, "/proc/self/task/59868/comm", O_RDWR) = -1 ENOENT (No such file or directory)
write(2, "/usr/bin/bluealsa: ", 19)     = 19
write(2, "D: ", 3)                      = 3
write(2, "../../src/ba-transport.c:1032: C"..., 82) = 82
write(2, "\n", 1)                       = 1
write(2, "/usr/bin/bluealsa: ", 19)     = 19
write(2, "D: ", 3)                      = 3
write(2, "../../src/main.c:406: Exiting ma"..., 39) = 39
write(2, "\n", 1)                       = 1
exit_group(0)                           = ?
+++ exited with 0 +++

Also tried using the SCO profile:

Aug 22 21:43:19 computer systemd[1]: Started Bluealsa daemon.
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluez.Profile1.NewConnection() on /org/bluez/HFP/AudioGateway
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:880: Starting RFCOMM loop: HFP Audio Gateway
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:1262: Created new RFCOMM thread [ba-rfcomm]: HFP Audio Gateway
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/sco.c:166: Checking Broadcom internal SCO routing
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/sco.c:172: Current SCO interface setup: 1 2 0 1 1
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/sco.c:200: Created SCO dispatcher [ba-sco-dispatch]: hci0
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/bluez.c:609: HFP Audio Gateway configured for device 48:C1:AC:E6:XX:XX
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:750: Starting transport: HFP Audio Gateway
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1032: Created new thread [ba-sco]: HFP Audio Gateway
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/sco.c:77: Starting SCO dispatcher loop: hci0
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/sco.c:241: Starting SCO loop: HFP Audio Gateway
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+BRSF, value:25
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:+BRSF, value:2784
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:126: RFCOMM: HFP Audio Gateway (CVSD) state transition: 0 -> 2
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/bluez.c:998: Adding new Stream End-Point: 48:C1:AC:E6:XX:XX: SBC
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: TEST: command:+CIND, value:(null)
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: 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))
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:126: RFCOMM: HFP Audio Gateway (CVSD) state transition: 2 -> 5
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluez.MediaEndpoint1.SelectConfiguration() on /org/bluez/hci0/A2DP/SBC/Source/1
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: GET: command:+CIND, value:(null)
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:+CIND, value:0,0,0,0,0,0,5
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:126: RFCOMM: HFP Audio Gateway (CVSD) state transition: 5 -> 7
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluez.MediaEndpoint1.SetConfiguration() on /org/bluez/hci0/A2DP/SBC/Source/1
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/a2dp.c:664: Selected A2DP SBC bit-pool range: [2, 89]
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/bluez.c:291: A2DP Source (SBC) configured for device 48:C1:AC:E6:XX:XX
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/bluez.c:294: Configuration: channels: 2, sampling: 48000
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/Source/3
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/Source/3
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+CMER, value:3,0,0,1
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:126: RFCOMM: HFP Audio Gateway (CVSD) state transition: 7 -> 8
Aug 22 21:58:05 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:126: RFCOMM: HFP Audio Gateway (CVSD) state transition: 8 -> 9
Aug 22 21:58:06 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+COPS, value:3,0
Aug 22 21:58:06 computer bluealsa[62169]: /usr/bin/bluealsa: W: Unsupported AT message: SET: command:+COPS, value:3,0
Aug 22 21:58:06 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:ERROR
Aug 22 21:58:06 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+XAPL, value:0A5C-0064-0069,7
Aug 22 21:58:06 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:+XAPL=BlueALSA,6
Aug 22 21:58:06 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:58:06 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+VGS, value:15
Aug 22 21:58:06 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:58:06 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+CMEE, value:1
Aug 22 21:58:06 computer bluealsa[62169]: /usr/bin/bluealsa: W: Unsupported AT message: SET: command:+CMEE, value:1
Aug 22 21:58:06 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:ERROR
Aug 22 21:58:29 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+XAPL, value:0A5C-0064-0069,7
Aug 22 21:58:29 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:+XAPL=BlueALSA,6
Aug 22 21:58:29 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:59:01 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+XAPL, value:0A5C-0064-0069,7
Aug 22 21:59:01 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:+XAPL=BlueALSA,6
Aug 22 21:59:01 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 22 21:59:22 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluealsa.Manager1.GetPCMs() on /org/bluealsa
Aug 22 21:59:22 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_48_C1_AC_E6_9D_B1/hfpag/sink
Aug 22 21:59:24 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:964: New SCO link: 48:C1:AC:E6:XX:XX: 20
Aug 22 21:59:24 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/hci.c:132: SCO link socket MTU: 20: 64
Aug 22 21:59:24 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/sco.c:507: PCM poll error status: 0x10
Aug 22 21:59:24 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1006: Closing PCM: 16
Aug 22 21:59:24 computer bluealsa[62169]: /usr/bin/bluealsa: E: Couldn't acquire D-Bus name: org.bluealsa
Aug 22 21:59:24 computer bluealsa[62169]: /usr/bin/bluealsa: D: ../../src/main.c:406: Exiting main loop
Aug 22 21:59:24 computer systemd[1]: bluealsa.service: Main process exited, code=exited, status=1/FAILURE
Aug 22 21:59:24 computer systemd[1]: bluealsa.service: Failed with result 'exit-code'.
Aug 22 21:59:24 computer systemd[1]: bluealsa.service: Scheduled restart job, restart counter is at 2.
Aug 22 21:59:24 computer systemd[1]: Stopped Bluealsa daemon.

EDIT forgot to mention bluealsa version:

/usr/bin/bluealsa -V
v2.1.0-78-g80db29f

moozhub commented 4 years ago

Just realized this may be a duplicate of #359 ...

arkq commented 4 years ago

No, it seems like a separate issue. It looks like your headset does not like Sending AT message: RESP: command:(null), value:+XAPL=BlueALSA,6 response from bluealsa, and keeps sending AT+XAPL command. Could you try to disable HFP profile and check only with A2DP (bluealsa -p a2dp-source)?

moozhub commented 4 years ago

Hi @Arkq thanks for the reply. I've indeed already tried this method, and at least for this particular device it seems to be worse off because the device itself doesn't ever seem to want to get into it's "phone" method, but I suppose that probably has to do with the profile being used... none the less it does pair but I've also been unable to get aplay to playback a sound file through it..

aplay:

$ aplay something.wav
D: ../../../src/asound/bluealsa-pcm.c:671: /org/bluealsa/hci0/dev_48_C1_AC_E6_XX_XX/a2dpsrc/sink: Setting constraints
Playing WAVE 'something.wav' : Signed 16 bit Little Endian, Rate 22050 Hz, Mono
D: ../../../src/asound/bluealsa-pcm.c:368: /org/bluealsa/hci0/dev_48_C1_AC_E6_XX_XX/a2dpsrc/sink: Initializing HW
D: ../../../src/asound/bluealsa-pcm.c:375: /org/bluealsa/hci0/dev_48_C1_AC_E6_XX_XX/a2dpsrc/sink: Couldn't open PCM: Remote peer disconnected
aplay: set_params:1407: Unable to install hw params:
ACCESS:  RW_INTERLEAVED
FORMAT:  S16_LE
SUBFORMAT:  STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 22050
PERIOD_TIME: [85333 85334)
PERIOD_SIZE: (1881 1882)
PERIOD_BYTES: (3762 3764)
PERIODS: (5 7)
BUFFER_TIME: (511882 511883)
BUFFER_SIZE: NONE
BUFFER_BYTES: 22574
TICK_TIME: 0
D: ../../../src/asound/bluealsa-pcm.c:357: /org/bluealsa/hci0/dev_48_C1_AC_E6_XX_XX/a2dpsrc/sink: Closing

bluealsa.service:

Aug 23 21:28:57 computer systemd[1]: Started Bluealsa daemon.
Aug 23 21:29:23 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Aug 23 21:29:51 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/bluez.c:1009: Signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved()
Aug 23 21:29:58 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Aug 23 21:30:02 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Aug 23 21:30:02 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Aug 23 21:30:02 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/bluez.c:998: Adding new Stream End-Point: 48:C1:AC:E6:XX:XX: SBC
Aug 23 21:30:02 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluez.MediaEndpoint1.SelectConfiguration() on /org/bluez/hci0/A2DP/SBC/Source/1
Aug 23 21:30:02 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Aug 23 21:30:02 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluez.MediaEndpoint1.SetConfiguration() on /org/bluez/hci0/A2DP/SBC/Source/1
Aug 23 21:30:02 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/a2dp.c:664: Selected A2DP SBC bit-pool range: [2, 89]
Aug 23 21:30:02 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/bluez.c:291: A2DP Source (SBC) configured for device 48:C1:AC:E6:XX:XX
Aug 23 21:30:02 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/bluez.c:294: Configuration: channels: 2, sampling: 48000
Aug 23 21:30:02 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/Source/3
Aug 23 21:30:02 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/Source/3
Aug 23 21:30:25 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluealsa.Manager1.GetPCMs() on /org/bluealsa
Aug 23 21:30:42 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluealsa.Manager1.GetPCMs() on /org/bluealsa
Aug 23 21:30:42 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_48_C1_AC_E6_XX_XX/a2dpsrc/sink
Aug 23 21:30:43 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:868: New transport: 14 (MTU: R:672 W:1008)
Aug 23 21:30:43 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/bluez.c:1068: Signal: org.freedesktop.DBus.Properties.PropertiesChanged()
Aug 23 21:30:43 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/bluez.c:1104: Signal: PropertiesChanged: org.bluez.MediaTransport1: State
Aug 23 21:30:43 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:750: Starting transport: A2DP Source (SBC)
Aug 23 21:30:43 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/sbc.c:114: SBC setup: 48000 Hz JointStereo allocation=SNR blocks=16 sub-bands=8 bit-pool=51 => 345000 bps
Aug 23 21:30:43 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/a2dp-audio.c:643: Starting IO loop: A2DP Source (SBC)
Aug 23 21:30:43 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/a2dp-audio.c:143: PCM has been closed: 10
Aug 23 21:30:43 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1006: Closing PCM: 10
Aug 23 21:30:43 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/a2dp-audio.c:313: Keep-alive polling: 0
Aug 23 21:30:43 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:901: Releasing A2DP transport: A2DP Source (SBC)
Aug 23 21:30:43 computer bluealsa[99036]: /usr/bin/bluealsa: E: Couldn't release transport: The connection is closed
Aug 23 21:30:43 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1054: Exiting IO thread: A2DP Source (SBC)
Aug 23 21:30:43 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1032: Created new thread [ba-a2dp-sbc]: A2DP Source (SBC)
Aug 23 21:30:43 computer bluealsa[99036]: /usr/bin/bluealsa: D: ../../src/main.c:406: Exiting main loop

For what it's worth, I also tried pairing and playing back through a different headset the Samsung Galaxy Buds+ using my original settings with somewhat similar results:

Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/bluez.c:998: Adding new Stream End-Point: 24:5A:B5:F8:XX:XX: SBC
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/bluez.c:998: Adding new Stream End-Point: 24:5A:B5:F8:XX:XX: AAC
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/bluez.c:998: Adding new Stream End-Point: 24:5A:B5:F8:XX:XX: samsung-SC
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluez.MediaEndpoint1.SetConfiguration() on /org/bluez/hci0/A2DP/AAC/Source/1
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/bluez.c:291: A2DP Source (AAC) configured for device 24:5A:B5:F8:XX:XX
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/bluez.c:294: Configuration: channels: 2, sampling: 48000
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/AAC/Source/3
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/AAC/Source/3
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluez.Profile1.NewConnection() on /org/bluez/HFP/AudioGateway
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:880: Starting RFCOMM loop: HFP Audio Gateway
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:1262: Created new RFCOMM thread [ba-rfcomm]: HFP Audio Gateway
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/sco.c:166: Checking Broadcom internal SCO routing
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/sco.c:172: Current SCO interface setup: 1 2 0 1 1
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/sco.c:200: Created SCO dispatcher [ba-sco-dispatch]: hci0
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/bluez.c:609: HFP Audio Gateway configured for device 24:5A:B5:F8:XX:XX
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:750: Starting transport: HFP Audio Gateway
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1032: Created new thread [ba-sco]: HFP Audio Gateway
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/sco.c:77: Starting SCO dispatcher loop: hci0
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/sco.c:241: Starting SCO loop: HFP Audio Gateway
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+BRSF, value:923
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:+BRSF, value:2784
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 0 -> 2
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+BAC, value:1,2,16
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 2 -> 3
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: TEST: command:+CIND, value:(null)
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: 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))
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 3 -> 5
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: GET: command:+CIND, value:(null)
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:+CIND, value:0,0,0,0,0,0,5
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 5 -> 7
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+CMER, value:3,0,0,1
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 7 -> 8
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 8 -> 9
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+VGM, value:7
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+VGS, value:8
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+CCWA, value:1
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: W: Unsupported AT message: SET: command:+CCWA, value:1
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:ERROR
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+COPS, value:3,0
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: W: Unsupported AT message: SET: command:+COPS, value:3,0
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:ERROR
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+CMEE, value:1
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: W: Unsupported AT message: SET: command:+CMEE, value:1
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:ERROR
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+BIA, value:0,1,1,1,0,0,0
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+SAMSUNG, value:VID,117,PID,40978,BTVER,R175XXU0ATF2
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: W: Unsupported AT message: SET: command:+SAMSUNG, value:VID,117,PID,40978,BTVER,R175XXU0ATF2
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:ERROR
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+SAMSUNG, value:VR_BTN,0
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: W: Unsupported AT message: SET: command:+SAMSUNG, value:VR_BTN,0
Aug 23 21:44:10 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:ERROR
Aug 23 21:44:13 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:1085: RFCOMM poll timeout
Aug 23 21:44:13 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:724: RFCOMM: HFP Audio Gateway setting codec: mSBC
Aug 23 21:44:13 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:+BCS, value:2
Aug 23 21:44:13 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/at.c:161: AT message: SET: command:+BCS, value:2
Aug 23 21:44:13 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Aug 23 21:45:35 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluealsa.Manager1.GetPCMs() on /org/bluealsa
Aug 23 21:45:35 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_24_5A_B5_F8_XX_XX/a2dpsrc/sink
Aug 23 21:45:38 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:868: New transport: 20 (MTU: R:672 W:679)
Aug 23 21:45:38 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/bluez.c:1068: Signal: org.freedesktop.DBus.Properties.PropertiesChanged()
Aug 23 21:45:38 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/bluez.c:1104: Signal: PropertiesChanged: org.bluez.MediaTransport1: State
Aug 23 21:45:38 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:750: Starting transport: A2DP Source (AAC)
Aug 23 21:45:38 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1032: Created new thread [ba-a2dp-aac]: A2DP Source (AAC)
Aug 23 21:45:38 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/a2dp-audio.c:1437: Starting IO loop: A2DP Source (AAC)
Aug 23 21:45:38 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1006: Closing PCM: 10
Aug 23 21:45:38 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/a2dp-audio.c:143: PCM has been closed: 10
Aug 23 21:45:38 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/a2dp-audio.c:313: Keep-alive polling: 0
Aug 23 21:45:38 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/a2dp-audio.c:313: Keep-alive polling: 0
Aug 23 21:45:38 computer bluealsa[103025]: /usr/bin/bluealsa: E: Couldn't acquire D-Bus name: org.bluealsa
Aug 23 21:45:38 computer bluealsa[103025]: /usr/bin/bluealsa: D: ../../src/main.c:406: Exiting main loop
Aug 23 21:45:38 computer systemd[1]: bluealsa.service: Main process exited, code=exited, status=1/FAILURE
Aug 23 21:45:38 computer systemd[1]: bluealsa.service: Failed with result 'exit-code'.

Here is the same test with the Galaxy Buds with the settings you suggested (only -p a2dp-source)...

aplay:

$ aplay something.wav
D: ../../../src/asound/bluealsa-pcm.c:761: /org/bluealsa/hci0/dev_24_5A_B5_F8_XX_XX/a2dpsrc/sink: Setting constraints
Playing WAVE 'something.wav' : Signed 16 bit Little Endian, Rate 22050 Hz, Mono
D: ../../../src/asound/bluealsa-pcm.c:397: /org/bluealsa/hci0/dev_24_5A_B5_F8_XX_XX/a2dpsrc/sink: Initializing HW
D: ../../../src/asound/bluealsa-pcm.c:404: /org/bluealsa/hci0/dev_24_5A_B5_F8_XX_XX/a2dpsrc/sink: Couldn't open PCM: Remote peer disconnected
aplay: set_params:1407: Unable to install hw params:
ACCESS:  RW_INTERLEAVED
FORMAT:  S16_LE
SUBFORMAT:  STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 22050
PERIOD_TIME: [85333 85334)
PERIOD_SIZE: (1881 1882)
PERIOD_BYTES: (3762 3764)
PERIODS: (5 7)
BUFFER_TIME: (511882 511883)
BUFFER_SIZE: NONE
BUFFER_BYTES: 22574
TICK_TIME: 0
D: ../../../src/asound/bluealsa-pcm.c:386: /org/bluealsa/hci0/dev_24_5A_B5_F8_XX_XX/a2dpsrc/sink: Closing

bluealsa.service

Aug 23 21:51:06 computer systemd[1]: Started Bluealsa daemon.
Aug 23 21:51:24 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Aug 23 21:51:24 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/bluez.c:998: Adding new Stream End-Point: 24:5A:B5:F8:XX:XX: SBC
Aug 23 21:51:24 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Aug 23 21:51:24 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/bluez.c:998: Adding new Stream End-Point: 24:5A:B5:F8:XX:XX: AAC
Aug 23 21:51:24 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Aug 23 21:51:24 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/bluez.c:998: Adding new Stream End-Point: 24:5A:B5:F8:XX:XX: samsung-SC
Aug 23 21:51:24 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Aug 23 21:51:24 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluez.MediaEndpoint1.SetConfiguration() on /org/bluez/hci0/A2DP/AAC/Source/1
Aug 23 21:51:24 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/bluez.c:291: A2DP Source (AAC) configured for device 24:5A:B5:F8:XX:XX
Aug 23 21:51:24 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/bluez.c:294: Configuration: channels: 2, sampling: 48000
Aug 23 21:51:24 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/AAC/Source/3
Aug 23 21:51:24 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/AAC/Source/3
Aug 23 21:51:54 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluealsa.Manager1.GetPCMs() on /org/bluealsa
Aug 23 21:51:54 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_24_5A_B5_F8_XX_XX/a2dpsrc/sink
Aug 23 21:51:55 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:868: New transport: 14 (MTU: R:672 W:679)
Aug 23 21:51:55 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/bluez.c:1068: Signal: org.freedesktop.DBus.Properties.PropertiesChanged()
Aug 23 21:51:55 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/bluez.c:1104: Signal: PropertiesChanged: org.bluez.MediaTransport1: State
Aug 23 21:51:55 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:750: Starting transport: A2DP Source (AAC)
Aug 23 21:51:55 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/a2dp-audio.c:1437: Starting IO loop: A2DP Source (AAC)
Aug 23 21:51:55 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/a2dp-audio.c:143: PCM has been closed: 10
Aug 23 21:51:55 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1006: Closing PCM: 10
Aug 23 21:51:55 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/a2dp-audio.c:313: Keep-alive polling: 0
Aug 23 21:51:55 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:901: Releasing A2DP transport: A2DP Source (AAC)
Aug 23 21:51:55 computer bluealsa[103431]: /usr/bin/bluealsa: E: Couldn't release transport: The connection is closed
Aug 23 21:51:55 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1054: Exiting IO thread: A2DP Source (AAC)
Aug 23 21:51:55 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1032: Created new thread [ba-a2dp-aac]: A2DP Source (AAC)
Aug 23 21:51:55 computer bluealsa[103431]: /usr/bin/bluealsa: E: Couldn't acquire D-Bus name: org.bluealsa
Aug 23 21:51:55 computer bluealsa[103431]: /usr/bin/bluealsa: D: ../../src/main.c:406: Exiting main loop
Aug 23 21:51:55 computer systemd[1]: bluealsa.service: Main process exited, code=exited, status=1/FAILURE
Aug 23 21:51:55 computer systemd[1]: bluealsa.service: Failed with result 'exit-code'.

moozhub commented 4 years ago

Hey @Arkq .. is there any additional information I can provide for this issue? Would really like to take advantage of this project.

borine commented 4 years ago

It looks to me as though it is aplay that is closing the connection, and the only reason I can imagine that happening is because it is not using "plug" to convert the audio parameters. Please can you post the output from aplay when you run it with this extra option:

aplay --dump-hw-params something.wav

[EDIT] ... and also please try:

aplay -D bluealsa:DEV=48:C1:AC:E6:XX:XX,PROFILE=a2dp something.wav

borine commented 4 years ago

@moozhub - sorry, just read through the logs you posted again, and my first thought was completely wrong - it is definitely the bluealsa server that is failing. Please ignore my previous comment.

arkq commented 4 years ago

E: Couldn't release transport: The connection is closed E: Couldn't acquire D-Bus name: org.bluealsa

I think that the second error message is caused by D-Bus issue or bluealsa incorrect usage of D-Bus (probably the latter). Anyway, it seems like a problem with D-Bus communication. You can try to dump D-Bus system bus communication with dbus-monitor --system maybe there will be some clue. If you running desktop with lots of services, this log might contain lots unrelated information (potentially confidential info...) I'm interested only with signals and messages send by BlueZ, BlueALSA and their clients.

moozhub commented 4 years ago

@Arkq @borine apologies for the delay... In effort to reduce dbus chat that you all probably don't care about, I ended up just dropping to the multi-user target, restarting the bluetooth service and going from there... In the dbus log I have everything from restarting the bluealsa service, to connecting to my bluetooth headset, and finally playing the audio file that ultimately causes the bluealsa service to go away.. Will provide any additonal information you need..thanks for the assistance.

dbus-bluealsa.log

aplay:

$ aplay StarWars3.wav 
D: ../../../src/asound/bluealsa-pcm.c:761: /org/bluealsa/hci0/dev_48_C1_AC_E6_XX_XX/a2dpsrc/sink: Setting constraints
Playing WAVE 'StarWars3.wav' : Signed 16 bit Little Endian, Rate 22050 Hz, Mono
D: ../../../src/asound/bluealsa-pcm.c:397: /org/bluealsa/hci0/dev_48_C1_AC_E6_XX_XX/a2dpsrc/sink: Initializing HW
D: ../../../src/asound/bluealsa-pcm.c:404: /org/bluealsa/hci0/dev_48_C1_AC_E6_XX_XX/a2dpsrc/sink: Couldn't open PCM: Remote peer disconnected
aplay: set_params:1407: Unable to install hw params:
ACCESS:  RW_INTERLEAVED
FORMAT:  S16_LE
SUBFORMAT:  STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 22050
PERIOD_TIME: [85333 85334)
PERIOD_SIZE: (1881 1882)
PERIOD_BYTES: (3762 3764)
PERIODS: (5 7)
BUFFER_TIME: (511882 511883)
BUFFER_SIZE: NONE
BUFFER_BYTES: 22574
TICK_TIME: 0
D: ../../../src/asound/bluealsa-pcm.c:386: /org/bluealsa/hci0/dev_48_C1_AC_E6_XX_XX/a2dpsrc/sink: Closing

bluealsa.service:

Sep 05 03:45:24 computer systemd[1]: Starting Bluealsa daemon...
Sep 05 03:45:24 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/AAC/Source/1
Sep 05 03:45:24 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/AAC/Source/1
Sep 05 03:45:24 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/AAC/Source/2
Sep 05 03:45:24 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/AAC/Source/2
Sep 05 03:45:24 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/MPEG/Source/1
Sep 05 03:45:24 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/MPEG/Source/1
Sep 05 03:45:24 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/MPEG/Source/2
Sep 05 03:45:24 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/MPEG/Source/2
Sep 05 03:45:24 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/Source/1
Sep 05 03:45:24 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/Source/1
Sep 05 03:45:24 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/Source/2
Sep 05 03:45:24 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/Source/2
Sep 05 03:45:24 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/main.c:397: Acquiring D-Bus service name: org.bluealsa
Sep 05 03:45:24 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/main.c:402: Starting main dispatching loop
Sep 05 03:45:24 computer systemd[1]: Started Bluealsa daemon.
Sep 05 03:45:30 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Sep 05 03:45:30 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:998: Adding new Stream End-Point: 48:C1:AC:E6:XX:XX: SBC
Sep 05 03:45:30 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluez.MediaEndpoint1.SelectConfiguration() on /org/bluez/hci0/A2DP/SBC/Source/1
Sep 05 03:45:30 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Sep 05 03:45:30 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluez.MediaEndpoint1.SetConfiguration() on /org/bluez/hci0/A2DP/SBC/Source/1
Sep 05 03:45:30 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/a2dp.c:664: Selected A2DP SBC bit-pool range: [2, 89]
Sep 05 03:45:30 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:291: A2DP Source (SBC) configured for device 48:C1:AC:E6:XX:XX
Sep 05 03:45:30 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:294: Configuration: channels: 2, sampling: 48000
Sep 05 03:45:30 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/Source/3
Sep 05 03:45:30 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/Source/3
Sep 05 03:45:38 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluealsa.Manager1.GetPCMs() on /org/bluealsa
Sep 05 03:45:38 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/dbus.c:57: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_48_C1_AC_E6_XX_XX/a2dpsrc/sink
Sep 05 03:45:38 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:868: New transport: 14 (MTU: R:672 W:1008)
Sep 05 03:45:38 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:1068: Signal: org.freedesktop.DBus.Properties.PropertiesChanged()
Sep 05 03:45:38 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/bluez.c:1104: Signal: PropertiesChanged: org.bluez.MediaTransport1: State
Sep 05 03:45:38 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:750: Starting transport: A2DP Source (SBC)
Sep 05 03:45:38 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/sbc.c:114: SBC setup: 48000 Hz JointStereo allocation=SNR blocks=16 sub-bands=8 bit-pool=51 => 345000 bps
Sep 05 03:45:38 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/a2dp-audio.c:643: Starting IO loop: A2DP Source (SBC)
Sep 05 03:45:38 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/a2dp-audio.c:143: PCM has been closed: 10
Sep 05 03:45:38 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1006: Closing PCM: 10
Sep 05 03:45:38 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/a2dp-audio.c:313: Keep-alive polling: 0
Sep 05 03:45:38 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:901: Releasing A2DP transport: A2DP Source (SBC)
Sep 05 03:45:38 computer bluealsa[4078]: /usr/bin/bluealsa: E: Couldn't release transport: The connection is closed
Sep 05 03:45:38 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1054: Exiting IO thread: A2DP Source (SBC)
Sep 05 03:45:38 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1032: Created new thread [ba-a2dp-sbc]: A2DP Source (SBC)
Sep 05 03:45:38 computer bluealsa[4078]: /usr/bin/bluealsa: D: ../../src/main.c:406: Exiting main loop

arkq commented 4 years ago

I think, I've seen something similar by myself - it was caused by invalid D-Bus message. It might be hard to debug...

Anyway, there is something strange in your last log. There is no Couldn't acquire D-Bus name: org.bluealsa message, but bluealsa server quits anyway... Recently I've changed how main event loop is terminated. Could you add here some debug line and check whether it will be printed (might be debug("XXXXXXXXXXX")? Because that's the other place where main event loop might be terminated, but this should happen only in case of SIGTERM or SIGINT signal....

Reprint from the log file of the most important part (bluealsa termination just after method return from Acquire call):

method call time=1599291938.880195 sender=:1.66 -> destination=org.bluealsa serial=3 path=/org/bluealsa/hci0/dev_48_C1_AC_E6_XX_XX/a2dpsrc/sink; interface=org.bluealsa.PCM1; member=Open
method call time=1599291938.880580 sender=:1.65 -> destination=:1.59 serial=19 path=/org/bluez/hci0/dev_48_C1_AC_E6_XX_XX/sep1/fd0; interface=org.bluez.MediaTransport1; member=Acquire
method return time=1599291938.939132 sender=:1.59 -> destination=:1.65 serial=77 reply_serial=19
   file descriptor
         inode: 71753
         type: socket
         address family: bluetooth
   uint16 672
   uint16 1008
signal time=1599291938.939187 sender=:1.59 -> destination=(null destination) serial=78 path=/org/bluez/hci0/dev_48_C1_AC_E6_XX_XX/sep1/fd0; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.bluez.MediaTransport1"
   array [
      dict entry(
         string "State"
         variant             string "active"
      )
   ]
   array [
   ]
signal time=1599291938.940051 sender=org.freedesktop.DBus -> destination=:1.65 serial=4294967295 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
   string "org.bluealsa"
signal time=1599291938.940071 sender=org.freedesktop.DBus -> destination=(null destination) serial=4294967295 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string "org.bluealsa"
   string ":1.65"
   string ""

moozhub commented 4 years ago

@Arkq did you want me to checkout the latest or add the debug messages to the commit I'm currently working with?

moozhub commented 4 years ago

Hi @Arkq apologies for the delay. I ended up just pulling down the latest from trunk, I'm now using 3.0.0 ... I added the debug statement in main.c as you instructed, I'm still experiencing the same issue.. Here's the dbus log that you wanted, I didn't see the debug statement I added in before g_main_loop_quit but I added in the log from the bluealsa service.. For what it's worth, it appears the original "Couldn't acquire D-Bus name" error returned in this test, perhaps the last time it didn't was a error on my part..

aplay:

$ aplay StarWars3.wav
D: ../../../src/asound/bluealsa-pcm.c:895: Getting BlueALSA PCM: PLAYBACK 48:C1:AC:E6:XX:XX a2dp
D: ../../../src/asound/bluealsa-pcm.c:769: /org/bluealsa/hci0/dev_48_C1_AC_E6_XX_XX/a2dpsrc/sink: Setting constraints
Playing WAVE 'StarWars3.wav' : Signed 16 bit Little Endian, Rate 22050 Hz, Mono
D: ../../../src/asound/bluealsa-pcm.c:396: /org/bluealsa/hci0/dev_48_C1_AC_E6_XX_XX/a2dpsrc/sink: Initializing HW
D: ../../../src/asound/bluealsa-pcm.c:403: /org/bluealsa/hci0/dev_48_C1_AC_E6_XX_XX/a2dpsrc/sink: Couldn't open PCM: Remote peer disconnected
aplay: set_params:1407: Unable to install hw params:
ACCESS:  RW_INTERLEAVED
FORMAT:  S16_LE
SUBFORMAT:  STD
SAMPLE_BITS: 16
FRAME_BITS: 16
CHANNELS: 1
RATE: 22050
PERIOD_TIME: [85333 85334)
PERIOD_SIZE: (1881 1882)
PERIOD_BYTES: (3762 3764)
PERIODS: (5 7)
BUFFER_TIME: (511882 511883)
BUFFER_SIZE: NONE
BUFFER_BYTES: 22574
TICK_TIME: 0
D: ../../../src/asound/bluealsa-pcm.c:385: /org/bluealsa/hci0/dev_48_C1_AC_E6_XX_XX/a2dpsrc/sink: Closing

dbus:

method call time=1600752507.685027 sender=:1.169 -> destination=org.bluealsa serial=3 path=/org/bluealsa/hci0/dev_48_C1_AC_E6_XX_XX/a2dpsrc/sink; interface=org.bluealsa.PCM1; member=Open
method call time=1600752507.685980 sender=:1.163 -> destination=:1.12 serial=19 path=/org/bluez/hci0/dev_48_C1_AC_E6_XX_XX/sep1/fd3; interface=org.bluez.MediaTransport1; member=Acquire
method return time=1600752507.764434 sender=:1.12 -> destination=:1.163 serial=251 reply_serial=19
   file descriptor
         inode: 174319
         type: socket
         address family: bluetooth
   uint16 672
   uint16 1008
signal time=1600752507.764512 sender=:1.12 -> destination=(null destination) serial=252 path=/org/bluez/hci0/dev_48_C1_AC_E6_XX_XX/sep1/fd3; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.bluez.MediaTransport1"
   array [
      dict entry(
         string "State"
         variant             string "active"
      )
   ]
   array [
   ]
signal time=1600752507.765128 sender=org.freedesktop.DBus -> destination=:1.163 serial=4294967295 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
   string "org.bluealsa"
signal time=1600752507.765159 sender=org.freedesktop.DBus -> destination=(null destination) serial=4294967295 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string "org.bluealsa"
   string ":1.163"
   string ""
signal time=1600752507.765182 sender=org.freedesktop.DBus -> destination=:1.163 serial=4294967295 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
   string ":1.163"
signal time=1600752507.765196 sender=org.freedesktop.DBus -> destination=(null destination) serial=4294967295 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string ":1.163"
   string ":1.163"
   string ""
error time=1600752507.765224 sender=org.freedesktop.DBus -> destination=:1.169 error_name=org.freedesktop.DBus.Error.NoReply reply_serial=3
   string "Remote peer disconnected"
signal time=1600752507.765401 sender=org.freedesktop.DBus -> destination=:1.169 serial=4294967295 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
   string ":1.169"
signal time=1600752507.765427 sender=org.freedesktop.DBus -> destination=(null destination) serial=4294967295 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameOwnerChanged
   string ":1.169"
   string ":1.169"
   string ""
signal time=1600752507.765587 sender=:1.12 -> destination=(null destination) serial=253 path=/org/bluez/hci0/dev_48_C1_AC_E6_XX_XX/sep1/fd3; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.bluez.MediaTransport1"
   array [
      dict entry(
         string "State"
         variant             string "idle"
      )
   ]
   array [
   ]
signal time=1600752507.765629 sender=:1.12 -> destination=(null destination) serial=254 path=/; interface=org.freedesktop.DBus.ObjectManager; member=InterfacesRemoved
   object path "/org/bluez/hci0/dev_48_C1_AC_E6_XX_XX/sep1/fd3"
   array [
      string "org.freedesktop.DBus.Properties"
      string "org.freedesktop.DBus.Introspectable"
      string "org.bluez.MediaTransport1"
   ]
signal time=1600752507.765679 sender=:1.0 -> destination=(null destination) serial=3648 path=/org/freedesktop/systemd1/unit/bluealsa_2eservice; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.freedesktop.systemd1.Service"
   array [
      dict entry(
         string "MainPID"
         variant             uint32 72126
      )
      dict entry(
         string "ControlPID"
         variant             uint32 0
      )
      dict entry(
         string "StatusText"
         variant             string ""
      )
      dict entry(
         string "StatusErrno"
         variant             int32 0
      )
      dict entry(
         string "Result"
         variant             string "success"
      )
      dict entry(
         string "ReloadResult"
         variant             string "success"
      )
      dict entry(
         string "CleanResult"
         variant             string "success"
      )
      dict entry(
         string "UID"
         variant             uint32 4294967295
      )
      dict entry(
         string "GID"
         variant             uint32 63
      )
      dict entry(
         string "NRestarts"
         variant             uint32 2
      )
      dict entry(
         string "ExecMainStartTimestamp"
         variant             uint64 1600752423036156
      )
      dict entry(
         string "ExecMainStartTimestampMonotonic"
         variant             uint64 1956784142
      )
      dict entry(
         string "ExecMainExitTimestamp"
         variant             uint64 0
      )
      dict entry(
         string "ExecMainExitTimestampMonotonic"
         variant             uint64 0
      )
      dict entry(
         string "ExecMainPID"
         variant             uint32 72126
      )
      dict entry(
         string "ExecMainCode"
         variant             int32 0
      )
      dict entry(
         string "ExecMainStatus"
         variant             int32 0
      )
   ]
   array [
      string "ExecCondition"
      string "ExecConditionEx"
      string "ExecStartPre"
      string "ExecStartPreEx"
      string "ExecStart"
      string "ExecStartEx"
      string "ExecStartPost"
      string "ExecStartPostEx"
      string "ExecReload"
      string "ExecReloadEx"
      string "ExecStop"
      string "ExecStopEx"
      string "ExecStopPost"
      string "ExecStopPostEx"
   ]
signal time=1600752507.765996 sender=:1.0 -> destination=(null destination) serial=3649 path=/org/freedesktop/systemd1/unit/bluealsa_2eservice; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.freedesktop.systemd1.Unit"
   array [
      dict entry(
         string "ActiveState"
         variant             string "deactivating"
      )
      dict entry(
         string "SubState"
         variant             string "stop-sigterm"
      )
      dict entry(
         string "StateChangeTimestamp"
         variant             uint64 1600752507765529
      )
      dict entry(
         string "StateChangeTimestampMonotonic"
         variant             uint64 2041513515
      )
      dict entry(
         string "InactiveExitTimestamp"
         variant             uint64 1600752423036382
      )
      dict entry(
         string "InactiveExitTimestampMonotonic"
         variant             uint64 1956784368
      )
      dict entry(
         string "ActiveEnterTimestamp"
         variant             uint64 1600752423058065
      )
      dict entry(
         string "ActiveEnterTimestampMonotonic"
         variant             uint64 1956806051
      )
      dict entry(
         string "ActiveExitTimestamp"
         variant             uint64 1600752507765529
      )
      dict entry(
         string "ActiveExitTimestampMonotonic"
         variant             uint64 2041513515
      )
      dict entry(
         string "InactiveEnterTimestamp"
         variant             uint64 1600752423034070
      )
      dict entry(
         string "InactiveEnterTimestampMonotonic"
         variant             uint64 1956782056
      )
      dict entry(
         string "Job"
         variant             struct {
               uint32 0
               object path "/"
            }
      )
      dict entry(
         string "ConditionResult"
         variant             boolean true
      )
      dict entry(
         string "AssertResult"
         variant             boolean true
      )
      dict entry(
         string "ConditionTimestamp"
         variant             uint64 1600752423034191
      )
      dict entry(
         string "ConditionTimestampMonotonic"
         variant             uint64 1956782177
      )
      dict entry(
         string "AssertTimestamp"
         variant             uint64 1600752423034192
      )
      dict entry(
         string "AssertTimestampMonotonic"
         variant             uint64 1956782178
      )
      dict entry(
         string "InvocationID"
         variant             array of bytes [
               ad 12 39 61 0e 18 43 44 9a 0b ec 8a d1 2e 15 77
            ]
      )
   ]
   array [
      string "Conditions"
      string "Asserts"
   ]
signal time=1600752507.766465 sender=:1.0 -> destination=(null destination) serial=3650 path=/org/freedesktop/systemd1; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.freedesktop.systemd1.Manager"
   array [
      dict entry(
         string "NFailedUnits"
         variant             uint32 1
      )
   ]
   array [
   ]
signal time=1600752507.766972 sender=:1.0 -> destination=(null destination) serial=3651 path=/org/freedesktop/systemd1/unit/bluealsa_2eservice; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.freedesktop.systemd1.Service"
   array [
      dict entry(
         string "MainPID"
         variant             uint32 0
      )
      dict entry(
         string "ControlPID"
         variant             uint32 0
      )
      dict entry(
         string "StatusText"
         variant             string ""
      )
      dict entry(
         string "StatusErrno"
         variant             int32 0
      )
      dict entry(
         string "Result"
         variant             string "exit-code"
      )
      dict entry(
         string "ReloadResult"
         variant             string "success"
      )
      dict entry(
         string "CleanResult"
         variant             string "success"
      )
      dict entry(
         string "UID"
         variant             uint32 4294967295
      )
      dict entry(
         string "GID"
         variant             uint32 63
      )
      dict entry(
         string "NRestarts"
         variant             uint32 2
      )
      dict entry(
         string "ExecMainStartTimestamp"
         variant             uint64 1600752423036156
      )
      dict entry(
         string "ExecMainStartTimestampMonotonic"
         variant             uint64 1956784142
      )
      dict entry(
         string "ExecMainExitTimestamp"
         variant             uint64 1600752507766176
      )
      dict entry(
         string "ExecMainExitTimestampMonotonic"
         variant             uint64 2041514162
      )
      dict entry(
         string "ExecMainPID"
         variant             uint32 72126
      )
      dict entry(
         string "ExecMainCode"
         variant             int32 1
      )
      dict entry(
         string "ExecMainStatus"
         variant             int32 1
      )
   ]
   array [
      string "ExecCondition"
      string "ExecConditionEx"
      string "ExecStartPre"
      string "ExecStartPreEx"
      string "ExecStart"
      string "ExecStartEx"
      string "ExecStartPost"
      string "ExecStartPostEx"
      string "ExecReload"
      string "ExecReloadEx"
      string "ExecStop"
      string "ExecStopEx"
      string "ExecStopPost"
      string "ExecStopPostEx"
   ]
signal time=1600752507.767242 sender=:1.0 -> destination=(null destination) serial=3652 path=/org/freedesktop/systemd1/unit/bluealsa_2eservice; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.freedesktop.systemd1.Unit"
   array [
      dict entry(
         string "ActiveState"
         variant             string "failed"
      )
      dict entry(
         string "SubState"
         variant             string "failed"
      )
      dict entry(
         string "StateChangeTimestamp"
         variant             uint64 1600752507766403
      )
      dict entry(
         string "StateChangeTimestampMonotonic"
         variant             uint64 2041514389
      )
      dict entry(
         string "InactiveExitTimestamp"
         variant             uint64 1600752423036382
      )
      dict entry(
         string "InactiveExitTimestampMonotonic"
         variant             uint64 1956784368
      )
      dict entry(
         string "ActiveEnterTimestamp"
         variant             uint64 1600752423058065
      )
      dict entry(
         string "ActiveEnterTimestampMonotonic"
         variant             uint64 1956806051
      )
      dict entry(
         string "ActiveExitTimestamp"
         variant             uint64 1600752507765529
      )
      dict entry(
         string "ActiveExitTimestampMonotonic"
         variant             uint64 2041513515
      )
      dict entry(
         string "InactiveEnterTimestamp"
         variant             uint64 1600752507766403
      )
      dict entry(
         string "InactiveEnterTimestampMonotonic"
         variant             uint64 2041514389
      )
      dict entry(
         string "Job"
         variant             struct {
               uint32 0
               object path "/"
            }
      )
      dict entry(
         string "ConditionResult"
         variant             boolean true
      )
      dict entry(
         string "AssertResult"
         variant             boolean true
      )
      dict entry(
         string "ConditionTimestamp"
         variant             uint64 1600752423034191
      )
      dict entry(
         string "ConditionTimestampMonotonic"
         variant             uint64 1956782177
      )
      dict entry(
         string "AssertTimestamp"
         variant             uint64 1600752423034192
      )
      dict entry(
         string "AssertTimestampMonotonic"
         variant             uint64 1956782178
      )
      dict entry(
         string "InvocationID"
         variant             array of bytes [
               ad 12 39 61 0e 18 43 44 9a 0b ec 8a d1 2e 15 77
            ]
      )
   ]
   array [
      string "Conditions"
      string "Asserts"
   ]
signal time=1600752507.767530 sender=:1.0 -> destination=(null destination) serial=3653 path=/org/freedesktop/systemd1; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.freedesktop.systemd1.Manager"
   array [
      dict entry(
         string "NFailedUnits"
         variant             uint32 0
      )
   ]
   array [
   ]

bluealsa.service:

Sep 22 01:27:03 computer systemd[1]: Starting Bluealsa daemon...
Sep 22 01:27:03 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/AAC/Source/1
Sep 22 01:27:03 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/AAC/Source/1
Sep 22 01:27:03 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/AAC/Source/2
Sep 22 01:27:03 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/AAC/Source/2
Sep 22 01:27:03 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/MPEG/Source/1
Sep 22 01:27:03 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/MPEG/Source/1
Sep 22 01:27:03 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/MPEG/Source/2
Sep 22 01:27:03 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/MPEG/Source/2
Sep 22 01:27:03 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/Source/1
Sep 22 01:27:03 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/Source/1
Sep 22 01:27:03 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/Source/2
Sep 22 01:27:03 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/Source/2
Sep 22 01:27:03 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/main.c:391: Acquiring D-Bus service name: org.bluealsa
Sep 22 01:27:03 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/main.c:396: Starting main dispatching loop
Sep 22 01:27:03 computer systemd[1]: Started Bluealsa daemon.
Sep 22 01:28:20 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Sep 22 01:28:20 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:998: Adding new Stream End-Point: 48:C1:AC:E6:XX:XX: SBC
Sep 22 01:28:20 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/dbus.c:59: Called: org.bluez.MediaEndpoint1.SelectConfiguration() on /org/bluez/hci0/A2DP/SBC/Source/1
Sep 22 01:28:20 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:915: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Sep 22 01:28:20 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/dbus.c:59: Called: org.bluez.MediaEndpoint1.SetConfiguration() on /org/bluez/hci0/A2DP/SBC/Source/1
Sep 22 01:28:20 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/a2dp.c:668: Selected A2DP SBC bit-pool range: [2, 89]
Sep 22 01:28:20 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:291: A2DP Source (SBC) configured for device 48:C1:AC:E6:XX:XX
Sep 22 01:28:20 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:294: Configuration: channels: 2, sampling: 48000
Sep 22 01:28:20 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:490: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/Source/3
Sep 22 01:28:20 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:406: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/Source/3
Sep 22 01:28:27 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/dbus.c:59: Called: org.bluealsa.Manager1.GetPCMs() on /org/bluealsa
Sep 22 01:28:27 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/dbus.c:59: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_48_C1_AC_E6_XX_XX/a2dpsrc/sink
Sep 22 01:28:27 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:868: New transport: 14 (MTU: R:672 W:1008)
Sep 22 01:28:27 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:1068: Signal: org.freedesktop.DBus.Properties.PropertiesChanged()
Sep 22 01:28:27 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/bluez.c:1104: Signal: PropertiesChanged: org.bluez.MediaTransport1: State
Sep 22 01:28:27 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:750: Starting transport: A2DP Source (SBC)
Sep 22 01:28:27 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/sbc.c:114: SBC setup: 48000 Hz JointStereo allocation=SNR blocks=16 sub-bands=8 bit-pool=51 => 345000 bps
Sep 22 01:28:27 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/a2dp-audio.c:644: Starting IO loop: A2DP Source (SBC)
Sep 22 01:28:27 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/a2dp-audio.c:144: PCM has been closed: 10
Sep 22 01:28:27 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1006: Closing PCM: 10
Sep 22 01:28:27 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/a2dp-audio.c:314: Keep-alive polling: 0
Sep 22 01:28:27 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:901: Releasing A2DP transport: A2DP Source (SBC)
Sep 22 01:28:27 computer bluealsa[72126]: /usr/bin/bluealsa: E: Couldn't release transport: The connection is closed
Sep 22 01:28:27 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1054: Exiting IO thread: A2DP Source (SBC)
Sep 22 01:28:27 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/ba-transport.c:1032: Created new thread [ba-a2dp-sbc]: A2DP Source (SBC)
Sep 22 01:28:27 computer bluealsa[72126]: /usr/bin/bluealsa: E: Couldn't acquire D-Bus name: org.bluealsa
Sep 22 01:28:27 computer bluealsa[72126]: /usr/bin/bluealsa: D: ../../src/main.c:399: Exiting main loop
Sep 22 01:28:27 computer systemd[1]: bluealsa.service: Main process exited, code=exited, status=1/FAILURE
Sep 22 01:28:27 computer systemd[1]: bluealsa.service: Failed with result 'exit-code'.
Sep 22 01:28:28 computer systemd[1]: bluealsa.service: Scheduled restart job, restart counter is at 3.
Sep 22 01:28:28 computer systemd[1]: Stopped Bluealsa daemon.

arkq commented 4 years ago

@moozhub, if you are still using bluealsa, please check the solution posted by @xyzzy42 in here: https://github.com/Arkq/bluez-alsa/issues/398#issuecomment-735464291

moozhub commented 4 years ago

@moozhub, if you are still using bluealsa, please check the solution posted by @xyzzy42 in here: https://github.com/Arkq/bluez-alsa/issues/398#issuecomment-735464291

Thanks, I always forget about selinux. I'll give it a shot soon and report back if it's corrected.

moozhub commented 4 years ago

@Arkq I can confirm it's related to selinux, the solution provided assuming I wanted to keep selinux enabled didn't work for me however, but I'll try to work through it with the other user.. Thanks for the help

borine commented 3 years ago

This issue was identified as being caused by SELinux config.

arkq / bluez-alsa

bluez-alsa crash when testing aplay playback device #361