Skip to content
New issue

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

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

Already on GitHub? Sign in to your account

Underruns without restarting bluez-alsa? #265

Closed
hrc-amilcar opened this issue Nov 13, 2019 · 8 comments
Closed

Underruns without restarting bluez-alsa? #265

hrc-amilcar opened this issue Nov 13, 2019 · 8 comments

Comments

@hrc-amilcar
Copy link

Hello. I'm using bluealsa (master 740886b) to implement a VoIP app for Bluetooth Headsets. I listen for PCMAdded/PCMRemoved signals and display a list of available SCO devices to the user. The user selects a device and opens a call.

Note unrelated to the title of the post: It would be convenient if the PCM properties reported the ALSA Mixer names (SCO, A2DP, Battery) so that I wouldn't have to recreate the naming/numbering scheme programmatically (e.g. Savi 7xx #2 - SCO).

I am testing various brands/models of headsets. Things work fine the first time for any particular headset. But if I switch between headsets without restarting bluealsa, I get underruns for certain models. I'm handling -EPIPE and using snd_pcm_prepare then retrying the snd_pcm_readi/writei as a typical ALSA app would do.

It could very well be something in my ALSA handling code, but the fact that using a particular headset first causes another to fail without restarting, could point to something in bluealsa not releasing or resetting something properly?

Any hints are appreciated...

Here are some logs from bluealsa in DEBUG mode:

  • Connect to PLT_Legend
  • Connect to Savi 7xx
  • Open PCMs for PLT_Legend (audio works fine)
  • Close PCMs for PLT_Legend
  • Open PCMs for Savi 7xx (audio works fine)
  • Close PCMs for Savi 7xx
  • Open PCMs for PLT_Legend (underruns)
  • Close PCMs for PLT_Legend
  • Open PCMs for Savi 7xx (audio works fine)
----- Connect of Plantronics PT_Legend -----

Nov 13 15:22:50 ./bluealsa: D: src/bluez.c:1073: Called: org.bluez.Profile1.NewConnection()
Nov 13 15:22:50 ./bluealsa: D: src/sco.c:201: Created SCO dispatcher [ba-sco-dispatch]: hci0
Nov 13 15:22:50 ./bluealsa: D: src/bluez.c:997: RFCOMM: HFP Audio Gateway configured for device E4:22:A5:8B:35:06
Nov 13 15:22:50 ./bluealsa: D: src/ba-transport.c:635: State transition: 0 -> 2
Nov 13 15:22:50 ./bluealsa: D: src/ba-transport.c:947: Created new thread [ba-rfcomm]: RFCOMM: HFP Audio Gateway
Nov 13 15:22:50 ./bluealsa: D: src/ba-transport.c:635: State transition: 0 -> 2
Nov 13 15:22:50 ./bluealsa: D: src/ba-transport.c:947: Created new thread [ba-sco]: HFP Audio Gateway (CVSD)
Nov 13 15:22:50 ./bluealsa: D: src/sco.c:242: Starting SCO loop: HFP Audio Gateway (CVSD)
Nov 13 15:22:50 ./bluealsa: D: src/rfcomm.c:698: Starting loop: RFCOMM: HFP Audio Gateway
Nov 13 15:22:50 ./bluealsa: D: src/at.c:161: AT message: SET: command:+BRSF, value:25
Nov 13 15:22:50 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:+BRSF, value:2272
Nov 13 15:22:50 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK
Nov 13 15:22:50 ./bluealsa: D: src/rfcomm.c:125: RFCOMM: HFP Audio Gateway state transition: 0 -> 2
Nov 13 15:22:50 ./bluealsa: D: src/sco.c:77: Starting SCO dispatcher loop: hci0
Nov 13 15:22:50 ./bluealsa: D: src/at.c:161: AT message: TEST: command:+CIND, value:(null)
Nov 13 15:22:50 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:+CIND, value:("call",(0,1)),("callsetup",(0-3)),("service",(0-1)),("signal",(0-5)),("roam",(0-1)),("battchg",(0-5)),("callheld",(0-2))
Nov 13 15:22:50 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK
Nov 13 15:22:50 ./bluealsa: D: src/rfcomm.c:125: RFCOMM: HFP Audio Gateway state transition: 2 -> 5
Nov 13 15:22:50 ./bluealsa: D: src/at.c:161: AT message: GET: command:+CIND, value:(null)
Nov 13 15:22:50 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:+CIND, value:0,0,0,0,0,0,0
Nov 13 15:22:50 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK
Nov 13 15:22:50 ./bluealsa: D: src/rfcomm.c:125: RFCOMM: HFP Audio Gateway state transition: 5 -> 7
Nov 13 15:22:50 daemon.err bluetoothd[455]: Unable to get connect data for HSP Audio Gateway: getpeername: Transport endpoint is not connected (107)
Nov 13 15:22:50 ./bluealsa: D: src/at.c:161: AT message: SET: command:+CMER, value:3, 0, 0, 1
Nov 13 15:22:50 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK
Nov 13 15:22:50 ./bluealsa: D: src/rfcomm.c:125: RFCOMM: HFP Audio Gateway state transition: 7 -> 8
Nov 13 15:22:50 ./bluealsa: D: src/rfcomm.c:125: RFCOMM: HFP Audio Gateway state transition: 8 -> 9
Nov 13 15:22:50 ./bluealsa: D: src/at.c:161: AT message: SET: command:+VGS, value:12
Nov 13 15:22:50 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK
Nov 13 15:22:50 ./bluealsa: D: src/at.c:161: AT message: SET: command:+VGM, value:15
Nov 13 15:22:50 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK
Nov 13 15:22:50 ./bluealsa: D: src/at.c:161: AT message: SET: command:+XAPL, value:047F-22-6b,1
Nov 13 15:22:50 ./bluealsa: W: Invalid XAPL value: 047F-22-6b,1
Nov 13 15:22:50 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:ERROR
Nov 13 15:22:50 ./bluealsa: D: src/bluez.c:742: Called: org.bluez.MediaEndpoint1.SelectConfiguration()
Nov 13 15:22:50 ./bluealsa: D: src/at.c:161: AT message: GET: command:+BTRH, value:(null)
Nov 13 15:22:50 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK
Nov 13 15:22:50 ./bluealsa: D: src/bluez.c:1294: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Nov 13 15:22:50 daemon.err bluetoothd[455]: Can't open input device: No such file or directory (2)
Nov 13 15:22:50 daemon.err bluetoothd[455]: AVRCP: failed to init uinput for E4:22:A5:8B:35:06
Nov 13 15:22:50 ./bluealsa: D: src/at.c:161: AT message: SET: command:+XEVENT, value:USER-AGENT,COM.PLANTRONICS,PLT_Legend,113,34.07,65564272dc37614083ffadb4086fbc9d
Nov 13 15:22:50 ./bluealsa: W: Unsupported AT message: SET: command:+XEVENT, value:USER-AGENT,COM.PLANTRONICS,PLT_Legend,113,34.07,65564272dc37614083ffadb4086fbc9d
Nov 13 15:22:50 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:ERROR
Nov 13 15:22:50 ./bluealsa: D: src/bluez.c:742: Called: org.bluez.MediaEndpoint1.SetConfiguration()
Nov 13 15:22:50 ./bluealsa: D: src/bluez.c:663: A2DP Source (SBC) configured for device E4:22:A5:8B:35:06
Nov 13 15:22:50 ./bluealsa: D: src/bluez.c:665: Configuration: channels: 2, sampling: 48000
Nov 13 15:22:50 ./bluealsa: D: src/ba-transport.c:635: State transition: 0 -> 0
Nov 13 15:22:50 ./bluealsa: D: src/bluez.c:787: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/Source/3
Nov 13 15:22:50 ./bluealsa: D: src/bluez.c:818: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/Source/3
Nov 13 15:22:50 ./bluealsa: D: src/at.c:161: AT message: CMD: command:+CLCC, value:(null)
Nov 13 15:22:50 ./bluealsa: W: Unsupported AT message: CMD: command:+CLCC, value:(null)
Nov 13 15:22:50 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:ERROR
Nov 13 15:22:50 daemon.info bluetoothd[455]: Endpoint registered: sender=:1.1638 path=/org/bluez/hci0/A2DP/SBC/Source/3
Nov 13 15:22:50 ./bluealsa: D: src/at.c:161: AT message: SET: command:+BIA, value:1,1,0,0,0,0,1
Nov 13 15:22:50 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK

----- Connect of Plantronics Savi 7xx -----

Nov 13 15:23:53 ./bluealsa: D: src/bluez.c:1073: Called: org.bluez.Profile1.NewConnection()
Nov 13 15:23:53 ./bluealsa: D: src/bluez.c:997: RFCOMM: HFP Audio Gateway configured for device E4:22:A5:53:3D:71
Nov 13 15:23:53 ./bluealsa: D: src/ba-transport.c:635: State transition: 0 -> 2
Nov 13 15:23:53 ./bluealsa: D: src/ba-transport.c:947: Created new thread [ba-rfcomm]: RFCOMM: HFP Audio Gateway
Nov 13 15:23:53 ./bluealsa: D: src/ba-transport.c:635: State transition: 0 -> 2
Nov 13 15:23:53 ./bluealsa: D: src/ba-transport.c:947: Created new thread [ba-sco]: HFP Audio Gateway (CVSD)
Nov 13 15:23:53 ./bluealsa: D: src/sco.c:242: Starting SCO loop: HFP Audio Gateway (CVSD)
Nov 13 15:23:53 ./bluealsa: D: src/rfcomm.c:698: Starting loop: RFCOMM: HFP Audio Gateway
Nov 13 15:23:53 ./bluealsa: D: src/at.c:161: AT message: SET: command:+BRSF, value:126
Nov 13 15:23:53 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:+BRSF, value:2272
Nov 13 15:23:53 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK
Nov 13 15:23:53 ./bluealsa: D: src/rfcomm.c:125: RFCOMM: HFP Audio Gateway state transition: 0 -> 2
Nov 13 15:23:53 ./bluealsa: D: src/at.c:161: AT message: TEST: command:+CIND, value:(null)
Nov 13 15:23:53 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:+CIND, value:("call",(0,1)),("callsetup",(0-3)),("service",(0-1)),("signal",(0-5)),("roam",(0-1)),("battchg",(0-5)),("callheld",(0-2))
Nov 13 15:23:53 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK
Nov 13 15:23:53 ./bluealsa: D: src/rfcomm.c:125: RFCOMM: HFP Audio Gateway state transition: 2 -> 5
Nov 13 15:23:54 ./bluealsa: D: src/at.c:161: AT message: GET: command:+CIND, value:(null)
Nov 13 15:23:54 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:+CIND, value:0,0,0,0,0,0,0
Nov 13 15:23:54 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK
Nov 13 15:23:54 ./bluealsa: D: src/rfcomm.c:125: RFCOMM: HFP Audio Gateway state transition: 5 -> 7
Nov 13 15:23:54 ./bluealsa: D: src/bluez.c:742: Called: org.bluez.MediaEndpoint1.SelectConfiguration()
Nov 13 15:23:54 ./bluealsa: D: src/at.c:161: AT message: SET: command:+CMER, value:3, 0, 0, 1
Nov 13 15:23:54 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK
Nov 13 15:23:54 ./bluealsa: D: src/rfcomm.c:125: RFCOMM: HFP Audio Gateway state transition: 7 -> 8
Nov 13 15:23:54 ./bluealsa: D: src/rfcomm.c:125: RFCOMM: HFP Audio Gateway state transition: 8 -> 9
Nov 13 15:23:54 ./bluealsa: D: src/bluez.c:1294: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Nov 13 15:23:54 ./bluealsa: D: src/bluez.c:742: Called: org.bluez.MediaEndpoint1.SetConfiguration()
Nov 13 15:23:54 ./bluealsa: D: src/bluez.c:663: A2DP Source (SBC) configured for device E4:22:A5:53:3D:71
Nov 13 15:23:54 ./bluealsa: D: src/bluez.c:665: Configuration: channels: 2, sampling: 48000
Nov 13 15:23:54 ./bluealsa: D: src/ba-transport.c:635: State transition: 0 -> 0
Nov 13 15:23:54 ./bluealsa: D: src/bluez.c:787: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/Source/4
Nov 13 15:23:54 ./bluealsa: D: src/bluez.c:818: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/Source/4
Nov 13 15:23:54 ./bluealsa: D: src/at.c:161: AT message: SET: command:+CLIP, value:1
Nov 13 15:23:54 ./bluealsa: W: Unsupported AT message: SET: command:+CLIP, value:1
Nov 13 15:23:54 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:ERROR
Nov 13 15:23:54 daemon.info bluetoothd[455]: Endpoint registered: sender=:1.1638 path=/org/bluez/hci0/A2DP/SBC/Source/4
Nov 13 15:23:54 ./bluealsa: D: src/at.c:161: AT message: SET: command:+NREC, value:0
Nov 13 15:23:54 ./bluealsa: W: Unsupported AT message: SET: command:+NREC, value:0
Nov 13 15:23:54 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:ERROR
Nov 13 15:23:54 ./bluealsa: D: src/at.c:161: AT message: SET: command:+VGS, value:13
Nov 13 15:23:54 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK
Nov 13 15:23:54 ./bluealsa: D: src/at.c:161: AT message: SET: command:+VGM, value:15
Nov 13 15:23:54 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK
Nov 13 15:23:54 daemon.err bluetoothd[455]: Can't open input device: No such file or directory (2)
Nov 13 15:23:54 daemon.err bluetoothd[455]: AVRCP: failed to init uinput for E4:22:A5:53:3D:71

----- Open Playback/Capture PCMs with PLT_Legend -----

Nov 13 15:25:40 ./bluealsa: D: src/bluealsa-dbus.c:139: Called: org.bluealsa.Manager1.GetPCMs()
Nov 13 15:25:40 ./bluealsa: D: src/ba-transport.c:587: Setting volume: 13<>15 [OO]
Nov 13 15:25:40 ./bluealsa: D: src/rfcomm.c:658: Updating speaker gain: 13
Nov 13 15:25:40 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:+VGS=13
Nov 13 15:25:40 ./bluealsa: D: src/bluealsa-dbus.c:139: Called: org.bluealsa.Manager1.GetPCMs()
Nov 13 15:25:40 ./bluealsa: D: src/ba-transport.c:587: Setting volume: 13<>10 [OO]
Nov 13 15:25:40 ./bluealsa: D: src/rfcomm.c:627: Updating microphone gain: 10
Nov 13 15:25:40 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:+VGM=10
Nov 13 15:25:40 Attempting to open ALSA audio device 'bluealsa:SRV=org.bluealsa,DEV=E4:22:A5:8B:35:06,PROFILE=sco'
Nov 13 15:25:40 ./bluealsa: D: src/bluealsa-dbus.c:139: Called: org.bluealsa.Manager1.GetPCMs()
Nov 13 15:25:40 ./bluealsa: D: src/bluealsa-dbus.c:333: Called: org.bluealsa.PCM1.Open()
Nov 13 15:25:40 stream1: 1 channel(s) @ 8000hz without hw_resampling (buffer:1920|240000us, period:80|10000us)
Nov 13 15:25:40 ./bluealsa: D: src/bluealsa-dbus.c:139: Called: org.bluealsa.Manager1.GetPCMs()
Nov 13 15:25:40 ./bluealsa: D: src/bluealsa-dbus.c:333: Called: org.bluealsa.PCM1.Open()
Nov 13 15:25:40 stream0: 1 channel(s) @ 8000hz without hw_resampling (buffer:1920|240000us, period:80|10000us)
Nov 13 15:25:40 ./bluealsa: D: src/ba-transport.c:635: State transition: 2 -> 2
Nov 13 15:25:40 ./bluealsa: D: src/ba-transport.c:635: State transition: 2 -> 2
Nov 13 15:25:41 ./bluealsa: D: src/ba-transport.c:878: New SCO link: E4:22:A5:8B:35:06: 31
Nov 13 15:25:41 ./bluealsa: D: src/hci.c:126: SCO link socket MTU: 31: 180
Nov 13 15:25:41 ./bluealsa: D: src/ba-transport.c:863: Reusing SCO: 31
Nov 13 15:25:41 ./bluealsa: D: src/at.c:161: AT message: SET: command:+VGS, value:14
Nov 13 15:25:41 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK

----- Close PCMs with PLT_Legend -----

Nov 13 15:26:22 ./bluealsa: D: src/a2dp.c:122: PCM read buffer flushed: 0
Nov 13 15:26:22 ./bluealsa: D: src/ba-transport.c:920: Closing PCM: 28
Nov 13 15:26:22 ./bluealsa: D: src/a2dp.c:122: PCM read buffer flushed: 0
Nov 13 15:26:22 ./bluealsa: D: src/ba-transport.c:920: Closing PCM: 27
Nov 13 15:26:22 ./bluealsa: D: src/sco.c:335: Releasing SCO due to PCM inactivity
Nov 13 15:26:22 ./bluealsa: D: src/ba-transport.c:896: Closing SCO: 31

----- Open Playback/Capture PCMs with Savi 7xx -----

Nov 13 15:27:03 ./bluealsa: D: src/bluealsa-dbus.c:139: Called: org.bluealsa.Manager1.GetPCMs()
Nov 13 15:27:03 ./bluealsa: D: src/bluealsa-dbus.c:139: Called: org.bluealsa.Manager1.GetPCMs()
Nov 13 15:27:03 ./bluealsa: D: src/ba-transport.c:587: Setting volume: 13<>10 [OO]
Nov 13 15:27:03 ./bluealsa: D: src/rfcomm.c:627: Updating microphone gain: 10
Nov 13 15:27:03 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:+VGM=10
Nov 13 15:27:03 Attempting to open ALSA audio device 'bluealsa:SRV=org.bluealsa,DEV=E4:22:A5:53:3D:71,PROFILE=sco'
Nov 13 15:27:03 ./bluealsa: D: src/bluealsa-dbus.c:139: Called: org.bluealsa.Manager1.GetPCMs()
Nov 13 15:27:03 ./bluealsa: D: src/bluealsa-dbus.c:333: Called: org.bluealsa.PCM1.Open()
Nov 13 15:27:03 stream1: 1 channel(s) @ 8000hz without hw_resampling (buffer:1920|240000us, period:80|10000us)
Nov 13 15:27:03 ./bluealsa: D: src/bluealsa-dbus.c:139: Called: org.bluealsa.Manager1.GetPCMs()
Nov 13 15:27:03 ./bluealsa: D: src/bluealsa-dbus.c:333: Called: org.bluealsa.PCM1.Open()
Nov 13 15:27:03 stream0: 1 channel(s) @ 8000hz without hw_resampling (buffer:1920|240000us, period:80|10000us)
Nov 13 15:27:03 ./bluealsa: D: src/ba-transport.c:635: State transition: 2 -> 2
Nov 13 15:27:03 ./bluealsa: D: src/ba-transport.c:635: State transition: 2 -> 2
Nov 13 15:27:03 ./bluealsa: D: src/ba-transport.c:878: New SCO link: E4:22:A5:53:3D:71: 31
Nov 13 15:27:03 ./bluealsa: D: src/hci.c:126: SCO link socket MTU: 31: 180
Nov 13 15:27:03 ./bluealsa: D: src/ba-transport.c:863: Reusing SCO: 31

----- Close PCMs with Savi 7xx -----

Nov 13 15:27:35 ./bluealsa: D: src/ba-transport.c:920: Closing PCM: 28
Nov 13 15:27:35 ./bluealsa: D: src/ba-transport.c:920: Closing PCM: 27
Nov 13 15:27:35 ./bluealsa: D: src/a2dp.c:122: PCM read buffer flushed: -1
Nov 13 15:27:35 ./bluealsa: D: src/sco.c:335: Releasing SCO due to PCM inactivity
Nov 13 15:27:35 ./bluealsa: D: src/ba-transport.c:896: Closing SCO: 31
Nov 13 15:27:35 ./bluealsa: D: src/a2dp.c:122: PCM read buffer flushed: -1
Nov 13 15:27:35 ./bluealsa: D: src/sco.c:335: Releasing SCO due to PCM inactivity

----- Open Playback/Capture PCMs with PLT_Legend -----

Nov 13 15:28:13 ./bluealsa: D: src/bluealsa-dbus.c:139: Called: org.bluealsa.Manager1.GetPCMs()
Nov 13 15:28:13 ./bluealsa: D: src/ba-transport.c:587: Setting volume: 13<>10 [OO]
Nov 13 15:28:13 ./bluealsa: D: src/rfcomm.c:658: Updating speaker gain: 13
Nov 13 15:28:13 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:+VGS=13
Nov 13 15:28:13 ./bluealsa: D: src/bluealsa-dbus.c:139: Called: org.bluealsa.Manager1.GetPCMs()
Nov 13 15:28:13 Attempting to open ALSA audio device 'bluealsa:SRV=org.bluealsa,DEV=E4:22:A5:8B:35:06,PROFILE=sco'
Nov 13 15:28:13 ./bluealsa: D: src/bluealsa-dbus.c:139: Called: org.bluealsa.Manager1.GetPCMs()
Nov 13 15:28:13 ./bluealsa: D: src/bluealsa-dbus.c:333: Called: org.bluealsa.PCM1.Open()
Nov 13 15:28:13 stream1: 1 channel(s) @ 8000hz without hw_resampling (buffer:1920|240000us, period:80|10000us)
Nov 13 15:28:13 ./bluealsa: D: src/bluealsa-dbus.c:139: Called: org.bluealsa.Manager1.GetPCMs()
Nov 13 15:28:13 ./bluealsa: D: src/bluealsa-dbus.c:333: Called: org.bluealsa.PCM1.Open()
Nov 13 15:28:13 stream0: 1 channel(s) @ 8000hz without hw_resampling (buffer:1920|240000us, period:80|10000us)
Nov 13 15:28:13 ./bluealsa: D: src/ba-transport.c:635: State transition: 2 -> 2
Nov 13 15:28:13 ./bluealsa: D: src/ba-transport.c:635: State transition: 2 -> 2
Nov 13 15:28:13 ./bluealsa: D: src/at.c:161: AT message: SET: command:+VGS, value:12
Nov 13 15:28:13 ./bluealsa: D: src/rfcomm.c:106: Sending AT message: RESP: command:(null), value:OK
Nov 13 15:28:13 ./bluealsa: D: src/ba-transport.c:878: New SCO link: E4:22:A5:8B:35:06: 31
Nov 13 15:28:13 ./bluealsa: D: src/hci.c:126: SCO link socket MTU: 31: 180
Nov 13 15:28:13 ./bluealsa: D: src/ba-transport.c:863: Reusing SCO: 31
continuos underruns here reported by snd_pcm_writei....
continuos underruns here reported by snd_pcm_writei....
continuos underruns here reported by snd_pcm_writei....
continuos underruns here reported by snd_pcm_writei....

@hrc-amilcar hrc-amilcar changed the title Reusing SCOs cause underrun? Underruns without restarting bluealsa? Nov 13, 2019
@hrc-amilcar hrc-amilcar changed the title Underruns without restarting bluealsa? Underruns without restarting bluez-alsa? Nov 13, 2019
@hrc-amilcar
Copy link
Author

hrc-amilcar commented Nov 25, 2019

I'm continuing to try to debug this issue. I pulled the latest at ec4775d and things are behaving a little differently. The device seems to recover after some time of robotic bleeps and bloops, but it does seem to recover. EDIT: I take that back. It's not recovering.

But now, there is a perpetual RFCOMM poll timeout after connecting a device, even before opening a PCM. Is this a benign debug log?

Nov 25 15:50:04 user.crit ./bluealsa: D: src/bluez.c:750: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/Source/1
Nov 25 15:50:04 user.crit ./bluealsa: D: src/bluez.c:781: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/Source/1
Nov 25 15:50:04 daemon.info bluetoothd[455]: Endpoint registered: sender=:1.468 path=/org/bluez/hci0/A2DP/SBC/Source/1
Nov 25 15:50:04 user.crit ./bluealsa: D: src/bluez.c:750: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/Source/2
Nov 25 15:50:04 user.crit ./bluealsa: D: src/bluez.c:781: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/Source/2
Nov 25 15:50:04 daemon.info bluetoothd[455]: Endpoint registered: sender=:1.468 path=/org/bluez/hci0/A2DP/SBC/Source/2
Nov 25 15:50:04 user.crit ./bluealsa: D: src/ba-adapter.c:151: Freeing adapter: hci0
Nov 25 15:50:04 user.crit ./bluealsa: D: src/bluez.c:1068: Creating hands-free profile object: /org/bluez/HSP/AudioGateway
Nov 25 15:50:04 user.crit ./bluealsa: D: src/bluez.c:1098: Registering hands-free profile: /org/bluez/HSP/AudioGateway
Nov 25 15:50:04 user.crit ./bluealsa: D: src/bluez.c:1068: Creating hands-free profile object: /org/bluez/HFP/AudioGateway
Nov 25 15:50:04 user.crit ./bluealsa: D: src/bluez.c:1098: Registering hands-free profile: /org/bluez/HFP/AudioGateway
Nov 25 15:50:04 user.crit ./bluealsa: D: src/main.c:371: Acquiring D-Bus service name: org.bluealsa
Nov 25 15:50:04 user.crit ./bluealsa: D: src/main.c:376: Starting main dispatching loop
Nov 25 15:50:22 user.crit ./bluealsa: D: src/bluez.c:1257: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Nov 25 15:50:22 user.crit ./bluealsa: D: src/bluez.c:705: Called: org.bluez.MediaEndpoint1.SetConfiguration()
Nov 25 15:50:22 user.crit ./bluealsa: D: src/bluez.c:626: A2DP Source (SBC) configured for device E4:22:A5:53:3D:71
Nov 25 15:50:22 user.crit ./bluealsa: D: src/bluez.c:628: Configuration: channels: 2, sampling: 48000
Nov 25 15:50:22 user.crit ./bluealsa: D: src/ba-transport.c:635: State transition: 0 -> 0
Nov 25 15:50:22 user.crit ./bluealsa: D: src/bluez.c:750: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/Source/3
Nov 25 15:50:22 user.crit ./bluealsa: D: src/bluez.c:781: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/Source/3
Nov 25 15:50:22 daemon.info bluetoothd[455]: Endpoint registered: sender=:1.468 path=/org/bluez/hci0/A2DP/SBC/Source/3
Nov 25 15:50:22 user.crit ./bluealsa: D: src/bluez.c:1036: Called: org.bluez.Profile1.NewConnection()
Nov 25 15:50:22 user.crit ./bluealsa: D: src/sco.c:201: Created SCO dispatcher [ba-sco-dispatch]: hci0
Nov 25 15:50:22 user.crit ./bluealsa: D: src/bluez.c:960: RFCOMM: HFP Audio Gateway configured for device E4:22:A5:53:3D:71
Nov 25 15:50:22 user.crit ./bluealsa: D: src/ba-transport.c:635: State transition: 0 -> 2
Nov 25 15:50:22 user.crit ./bluealsa: D: src/ba-transport.c:947: Created new thread [ba-rfcomm]: RFCOMM: HFP Audio Gateway
Nov 25 15:50:22 user.crit ./bluealsa: D: src/ba-transport.c:635: State transition: 0 -> 2
Nov 25 15:50:22 user.crit ./bluealsa: D: src/ba-transport.c:947: Created new thread [ba-sco]: HFP Audio Gateway
Nov 25 15:50:22 user.crit ./bluealsa: D: src/sco.c:77: Starting SCO dispatcher loop: hci0
Nov 25 15:50:22 user.crit ./bluealsa: D: src/rfcomm.c:802: Starting loop: RFCOMM: HFP Audio Gateway
Nov 25 15:50:22 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+BRSF, value:126
Nov 25 15:50:22 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:+BRSF, value:2784
Nov 25 15:50:22 user.crit ./bluealsa: D: src/sco.c:242: Starting SCO loop: HFP Audio Gateway
Nov 25 15:50:22 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 15:50:22 user.crit ./bluealsa: D: src/rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 0 -> 2
Nov 25 15:50:22 user.crit ./bluealsa: D: src/at.c:161: AT message: TEST: command:+CIND, value:(null)
Nov 25 15:50:22 user.crit ./bluealsa: D: src/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))
Nov 25 15:50:22 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 15:50:22 user.crit ./bluealsa: D: src/rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 2 -> 5
Nov 25 15:50:22 user.crit ./bluealsa: D: src/at.c:161: AT message: GET: command:+CIND, value:(null)
Nov 25 15:50:22 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:+CIND, value:0,0,0,0,0,0,5
Nov 25 15:50:22 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 15:50:22 user.crit ./bluealsa: D: src/rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 5 -> 7
Nov 25 15:50:22 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+CMER, value:3, 0, 0, 1
Nov 25 15:50:22 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 15:50:22 user.crit ./bluealsa: D: src/rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 7 -> 8
Nov 25 15:50:22 user.crit ./bluealsa: D: src/rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 8 -> 9
Nov 25 15:50:22 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+CLIP, value:1
Nov 25 15:50:22 user.crit ./bluealsa: W: Unsupported AT message: SET: command:+CLIP, value:1
Nov 25 15:50:22 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:ERROR
Nov 25 15:50:22 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+NREC, value:0
Nov 25 15:50:22 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:ERROR
Nov 25 15:50:24 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+VGS, value:13
Nov 25 15:50:24 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 15:50:24 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+VGM, value:15
Nov 25 15:50:24 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 15:50:26 user.crit ./bluealsa: D: src/rfcomm.c:996: RFCOMM poll timeout
Nov 25 15:50:29 user.crit ./bluealsa: D: src/rfcomm.c:996: RFCOMM poll timeout
Nov 25 15:50:31 user.crit ./bluealsa: D: src/rfcomm.c:996: RFCOMM poll timeout
Nov 25 15:50:34 user.crit ./bluealsa: D: src/rfcomm.c:996: RFCOMM poll timeout
Nov 25 15:50:36 user.crit ./bluealsa: D: src/rfcomm.c:996: RFCOMM poll timeout
Nov 25 15:50:39 user.crit ./bluealsa: D: src/rfcomm.c:996: RFCOMM poll timeout

@arkq
Copy link
Owner

arkq commented Nov 25, 2019

Hi, I've just fixed two issues found in the logs you've provided, but I think that these were not essential (Invalid XAPL value: 047F-22-6b,1 warning from first comment and rolling RFCOMM poll timeout logs from this comment). The poll timeout message does not harm (it just busy waiting with sleep 2s, right now it will block until RFCOMM message appears).

Regarding original issue, unfortunately, I don't know what might cause such problem. I see that you are using SCO connection, so you might try to look at this (search for "MTU"): #258

@arkq
Copy link
Owner

arkq commented Nov 25, 2019

Please try branch: https://github.com/Arkq/bluez-alsa/tree/hsp-fix and tell whether it will help. The crucial part is the top commit: b1ab34e

@hrc-amilcar
Copy link
Author

hrc-amilcar commented Nov 25, 2019

Thank you for that. I pulled b1ab34e . The RFCOMM poll timeout logs are no longer happening, but I continue to get the same phenomenon. As soon as I connect a second Bluetooth device while there's a currently open stream, the open stream goes into perpetual underrun. It's as if something is corrupting the active stream, or the CPU usage for adding the new device causes something to get out of sync.

EDIT: I'll look into #258 as well.

Perhaps there are more clues from these logs:

--- Startup ---

Nov 25 19:32:43 user.crit ./bluealsa: D: src/ofono.c:628: Checking oFono service presence
Nov 25 19:32:43 user.crit ./bluealsa: D: src/bluez.c:750: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/Source/1
Nov 25 19:32:43 user.crit ./bluealsa: D: src/bluez.c:781: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/Source/1
Nov 25 19:32:43 daemon.info bluetoothd[455]: Endpoint registered: sender=:1.502 path=/org/bluez/hci0/A2DP/SBC/Source/1
Nov 25 19:32:43 user.crit ./bluealsa: D: src/bluez.c:750: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/Source/2
Nov 25 19:32:43 user.crit ./bluealsa: D: src/bluez.c:781: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/Source/2
Nov 25 19:32:43 daemon.info bluetoothd[455]: Endpoint registered: sender=:1.502 path=/org/bluez/hci0/A2DP/SBC/Source/2
Nov 25 19:32:43 user.crit ./bluealsa: D: src/ba-adapter.c:151: Freeing adapter: hci0
Nov 25 19:32:43 user.crit ./bluealsa: D: src/bluez.c:1068: Creating hands-free profile object: /org/bluez/HSP/AudioGateway
Nov 25 19:32:43 user.crit ./bluealsa: D: src/bluez.c:1098: Registering hands-free profile: /org/bluez/HSP/AudioGateway
Nov 25 19:32:43 user.crit ./bluealsa: D: src/bluez.c:1068: Creating hands-free profile object: /org/bluez/HFP/AudioGateway
Nov 25 19:32:43 user.crit ./bluealsa: D: src/bluez.c:1098: Registering hands-free profile: /org/bluez/HFP/AudioGateway
Nov 25 19:32:43 user.crit ./bluealsa: D: src/main.c:371: Acquiring D-Bus service name: org.bluealsa
Nov 25 19:32:43 user.crit ./bluealsa: D: src/main.c:376: Starting main dispatching loop

--- Power on Plantronics Legend (auto connects to Bluealsa) ---

Nov 25 19:32:52 user.crit ./bluealsa: D: src/bluez.c:1036: Called: org.bluez.Profile1.NewConnection()
Nov 25 19:32:52 user.crit ./bluealsa: D: src/sco.c:201: Created SCO dispatcher [ba-sco-dispatch]: hci0
Nov 25 19:32:52 user.crit ./bluealsa: D: src/bluez.c:960: RFCOMM: HFP Audio Gateway configured for device E4:22:A5:8B:35:06
Nov 25 19:32:52 user.crit ./bluealsa: D: src/ba-transport.c:635: State transition: 0 -> 2
Nov 25 19:32:52 user.crit ./bluealsa: D: src/ba-transport.c:947: Created new thread [ba-rfcomm]: RFCOMM: HFP Audio Gateway
Nov 25 19:32:52 user.crit ./bluealsa: D: src/ba-transport.c:635: State transition: 0 -> 2
Nov 25 19:32:52 user.crit ./bluealsa: D: src/ba-transport.c:947: Created new thread [ba-sco]: HFP Audio Gateway
Nov 25 19:32:52 user.crit ./bluealsa: D: src/sco.c:242: Starting SCO loop: HFP Audio Gateway
Nov 25 19:32:52 user.crit ./bluealsa: D: src/sco.c:77: Starting SCO dispatcher loop: hci0
Nov 25 19:32:52 user.crit ./bluealsa: D: src/rfcomm.c:808: Starting loop: RFCOMM: HFP Audio Gateway
Nov 25 19:32:52 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+BRSF, value:25
Nov 25 19:32:52 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:+BRSF, value:2784
Nov 25 19:32:52 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 19:32:52 user.crit ./bluealsa: D: src/rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 0 -> 2
Nov 25 19:32:52 user.crit ./bluealsa: D: src/at.c:161: AT message: TEST: command:+CIND, value:(null)
Nov 25 19:32:52 user.crit ./bluealsa: D: src/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))
Nov 25 19:32:52 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 19:32:52 user.crit ./bluealsa: D: src/rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 2 -> 5
Nov 25 19:32:52 user.crit ./bluealsa: D: src/at.c:161: AT message: GET: command:+CIND, value:(null)
Nov 25 19:32:52 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:+CIND, value:0,0,0,0,0,0,5
Nov 25 19:32:52 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 19:32:52 user.crit ./bluealsa: D: src/rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 5 -> 7
Nov 25 19:32:52 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+CMER, value:3, 0, 0, 1
Nov 25 19:32:52 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 19:32:52 user.crit ./bluealsa: D: src/rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 7 -> 8
Nov 25 19:32:52 user.crit ./bluealsa: D: src/rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 8 -> 9
Nov 25 19:32:52 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+VGS, value:14
Nov 25 19:32:52 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 19:32:52 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+VGM, value:15
Nov 25 19:32:52 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 19:32:52 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+XAPL, value:047F-22-6b,1
Nov 25 19:32:52 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:+XAPL=BlueALSA,6
Nov 25 19:32:52 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 19:32:52 user.crit ./bluealsa: D: src/at.c:161: AT message: GET: command:+BTRH, value:(null)
Nov 25 19:32:52 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 19:32:52 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+XEVENT, value:USER-AGENT,COM.PLANTRONICS,PLT_Legend,113,34.07,65564272dc37614083ffadb4086fbc9d
Nov 25 19:32:52 user.crit ./bluealsa: W: Unsupported AT message: SET: command:+XEVENT, value:USER-AGENT,COM.PLANTRONICS,PLT_Legend,113,34.07,65564272dc37614083ffadb4086fbc9d
Nov 25 19:32:52 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:ERROR
Nov 25 19:32:52 user.crit ./bluealsa: D: src/at.c:161: AT message: CMD: command:+CLCC, value:(null)
Nov 25 19:32:52 user.crit ./bluealsa: W: Unsupported AT message: CMD: command:+CLCC, value:(null)
Nov 25 19:32:52 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:ERROR
Nov 25 19:32:52 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+BIA, value:0,1,1,1,0,0,0
Nov 25 19:32:52 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 19:32:52 daemon.err bluetoothd[455]: Can't open input device: No such file or directory (2)
Nov 25 19:32:52 daemon.err bluetoothd[455]: AVRCP: failed to init uinput for E4:22:A5:8B:35:06
Nov 25 19:32:53 user.crit ./bluealsa: D: src/bluez.c:705: Called: org.bluez.MediaEndpoint1.SelectConfiguration()
Nov 25 19:32:53 user.crit ./bluealsa: D: src/bluez.c:1254: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Nov 25 19:32:53 user.crit ./bluealsa: D: src/bluez.c:705: Called: org.bluez.MediaEndpoint1.SetConfiguration()
Nov 25 19:32:53 user.crit ./bluealsa: D: src/bluez.c:626: A2DP Source (SBC) configured for device E4:22:A5:8B:35:06
Nov 25 19:32:53 user.crit ./bluealsa: D: src/bluez.c:628: Configuration: channels: 2, sampling: 48000
Nov 25 19:32:53 user.crit ./bluealsa: D: src/ba-transport.c:635: State transition: 0 -> 0
Nov 25 19:32:53 user.crit ./bluealsa: D: src/bluez.c:750: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/Source/3
Nov 25 19:32:53 user.crit ./bluealsa: D: src/bluez.c:781: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/Source/3
Nov 25 19:32:53 daemon.info bluetoothd[455]: Endpoint registered: sender=:1.502 path=/org/bluez/hci0/A2DP/SBC/Source/3

--- Open Playback/Capture PCMs on Plantronics Legend ---

Nov 25 19:33:00 user.crit ./bluealsa: D: src/bluealsa-dbus.c:139: Called: org.bluealsa.Manager1.GetPCMs()
Nov 25 19:33:00 user.crit ./bluealsa: D: src/ba-transport.c:587: Setting volume: 13<>15 [OO]
Nov 25 19:33:00 user.crit ./bluealsa: D: src/rfcomm.c:770: Updating speaker gain: 13
Nov 25 19:33:00 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:+VGS=13
Nov 25 19:33:00 user.crit ./bluealsa: D: src/bluealsa-dbus.c:139: Called: org.bluealsa.Manager1.GetPCMs()
Nov 25 19:33:00 user.crit ./bluealsa: D: src/ba-transport.c:587: Setting volume: 13<>10 [OO]
Nov 25 19:33:00 user.crit ./bluealsa: D: src/rfcomm.c:741: Updating microphone gain: 10
Nov 25 19:33:00 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:+VGM=10
Nov 25 19:33:00 user.debug Attempting to open ALSA audio device 'bluealsa:SRV=org.bluealsa,DEV=E4:22:A5:8B:35:06,PROFILE=sco'
Nov 25 19:33:00 user.crit ./bluealsa: D: src/bluealsa-dbus.c:139: Called: org.bluealsa.Manager1.GetPCMs()
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:625: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Setting constraints
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:344: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Initializing HW
Nov 25 19:33:00 user.crit ./bluealsa: D: src/bluealsa-dbus.c:333: Called: org.bluealsa.PCM1.Open()
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:377: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Selected HW buffer: 24 periods x 160 bytes == 3840 bytes
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Initializing SW
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Initializing SW
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:414: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Nov 25 19:33:00 user.debug stream1: 1 channel(s) @ 8000hz without hw_resampling (buffer:1920|240000us, period:80|10000us)
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Initializing SW
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:414: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Nov 25 19:33:00 user.crit ./bluealsa: D: src/bluealsa-dbus.c:139: Called: org.bluealsa.Manager1.GetPCMs()
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:625: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Setting constraints
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:344: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Initializing HW
Nov 25 19:33:00 user.crit ./bluealsa: D: src/bluealsa-dbus.c:333: Called: org.bluealsa.PCM1.Open()
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:371: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: FIFO buffer size: 4096
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:377: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Selected HW buffer: 24 periods x 160 bytes == 3840 bytes
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Initializing SW
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Initializing SW
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:414: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Nov 25 19:33:00 user.debug stream0: 1 channel(s) @ 8000hz without hw_resampling (buffer:1920|240000us, period:80|10000us)
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:392: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Initializing SW
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:414: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:264: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Starting
Nov 25 19:33:00 user.crit ./bluealsa: D: src/ba-transport.c:635: State transition: 2 -> 2
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:264: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Starting
Nov 25 19:33:00 user.crit ./bluealsa: D: src/ba-transport.c:635: State transition: 2 -> 2
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:137: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Starting IO loop: 14
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:137: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Starting IO loop: 19
Nov 25 19:33:00 user.debug D: src/asound/bluealsa-pcm.c:169: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread paused: 4
Nov 25 19:33:01 user.crit ./bluealsa: D: src/ba-transport.c:878: New SCO link: E4:22:A5:8B:35:06: 24
Nov 25 19:33:01 user.crit ./bluealsa: D: src/hci.c:126: SCO link socket MTU: 24: 180
Nov 25 19:33:01 user.crit ./bluealsa: D: src/ba-transport.c:863: Reusing SCO: 24
Nov 25 19:33:01 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+VGS, value:12
Nov 25 19:33:01 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 19:33:01 user.debug D: src/asound/bluealsa-pcm.c:414: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Nov 25 19:33:01 user.debug D: src/asound/bluealsa-pcm.c:264: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Starting
Nov 25 19:33:01 user.debug D: src/asound/bluealsa-pcm.c:172: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread resumed: 3

--- Sounds is fine here for Plantronics Legend ---

--- Power on Plantronics Savi 7xx (auto connects to Bluealsa) ---

Nov 25 19:33:13 daemon.err bluetoothd[455]: Can't open input device: No such file or directory (2)
Nov 25 19:33:13 daemon.err bluetoothd[455]: AVRCP: failed to init uinput for E4:22:A5:53:3D:71
Nov 25 19:33:14 user.crit ./bluealsa: D: src/bluez.c:1254: Signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded()
Nov 25 19:33:14 user.crit ./bluealsa: D: src/bluez.c:705: Called: org.bluez.MediaEndpoint1.SetConfiguration()
Nov 25 19:33:14 user.crit ./bluealsa: D: src/bluez.c:626: A2DP Source (SBC) configured for device E4:22:A5:53:3D:71
Nov 25 19:33:14 user.crit ./bluealsa: D: src/bluez.c:628: Configuration: channels: 2, sampling: 48000
Nov 25 19:33:14 user.crit ./bluealsa: D: src/ba-transport.c:635: State transition: 0 -> 0
Nov 25 19:33:14 user.crit ./bluealsa: D: src/bluez.c:750: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/Source/4
Nov 25 19:33:14 user.crit ./bluealsa: D: src/bluez.c:781: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/Source/4
Nov 25 19:33:14 daemon.info bluetoothd[455]: Endpoint registered: sender=:1.502 path=/org/bluez/hci0/A2DP/SBC/Source/4
Nov 25 19:33:14 user.crit ./bluealsa: D: src/bluez.c:1036: Called: org.bluez.Profile1.NewConnection()
Nov 25 19:33:14 user.crit ./bluealsa: D: src/bluez.c:960: RFCOMM: HFP Audio Gateway configured for device E4:22:A5:53:3D:71
Nov 25 19:33:14 user.crit ./bluealsa: D: src/ba-transport.c:635: State transition: 0 -> 2
Nov 25 19:33:14 user.crit ./bluealsa: D: src/ba-transport.c:947: Created new thread [ba-rfcomm]: RFCOMM: HFP Audio Gateway
Nov 25 19:33:14 user.crit ./bluealsa: D: src/ba-transport.c:635: State transition: 0 -> 2
Nov 25 19:33:14 user.crit ./bluealsa: D: src/ba-transport.c:947: Created new thread [ba-sco]: HFP Audio Gateway
Nov 25 19:33:14 user.crit ./bluealsa: D: src/sco.c:242: Starting SCO loop: HFP Audio Gateway
Nov 25 19:33:14 user.crit ./bluealsa: D: src/rfcomm.c:808: Starting loop: RFCOMM: HFP Audio Gateway
Nov 25 19:33:14 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+BRSF, value:126
Nov 25 19:33:14 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:+BRSF, value:2784
Nov 25 19:33:14 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 19:33:14 user.crit ./bluealsa: D: src/rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 0 -> 2
Nov 25 19:33:14 user.crit ./bluealsa: D: src/at.c:161: AT message: TEST: command:+CIND, value:(null)
Nov 25 19:33:14 user.crit ./bluealsa: D: src/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))
Nov 25 19:33:14 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 19:33:14 user.crit ./bluealsa: D: src/rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 2 -> 5
Nov 25 19:33:16 user.crit ./bluealsa: D: src/rfcomm.c:1010: RFCOMM poll timeout
Nov 25 19:33:18 user.crit ./bluealsa: D: src/at.c:161: AT message: GET: command:+CIND, value:(null)
Nov 25 19:33:18 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:+CIND, value:0,0,0,0,0,0,5
Nov 25 19:33:18 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 19:33:18 user.crit ./bluealsa: D: src/rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 5 -> 7
Nov 25 19:33:19 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+CMER, value:3, 0, 0, 1
Nov 25 19:33:19 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 19:33:19 user.crit ./bluealsa: D: src/rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 7 -> 8
Nov 25 19:33:19 user.crit ./bluealsa: D: src/rfcomm.c:126: RFCOMM: HFP Audio Gateway state transition: 8 -> 9
Nov 25 19:33:19 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+CLIP, value:1
Nov 25 19:33:19 user.crit ./bluealsa: W: Unsupported AT message: SET: command:+CLIP, value:1
Nov 25 19:33:19 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:ERROR
Nov 25 19:33:19 user.debug D: src/asound/bluealsa-pcm.c:169: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread paused: 4
Nov 25 19:33:19 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+NREC, value:0
Nov 25 19:33:19 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:ERROR
Nov 25 19:33:19 user.debug D: src/asound/bluealsa-pcm.c:414: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Nov 25 19:33:19 user.debug D: src/asound/bluealsa-pcm.c:264: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Starting
Nov 25 19:33:19 user.debug D: src/asound/bluealsa-pcm.c:172: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread resumed: 3
Nov 25 19:33:19 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+VGS, value:13
Nov 25 19:33:19 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK
Nov 25 19:33:19 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+VGM, value:15
Nov 25 19:33:19 user.crit ./bluealsa: D: src/rfcomm.c:107: Sending AT message: RESP: command:(null), value:OK

--- Continuous underruns on Plantronics Legend ---

Nov 25 19:33:19 user.debug D: src/asound/bluealsa-pcm.c:169: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread paused: 4
Nov 25 19:33:19 user.debug D: src/asound/bluealsa-pcm.c:414: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Nov 25 19:33:19 user.debug D: src/asound/bluealsa-pcm.c:264: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Starting
Nov 25 19:33:19 user.debug D: src/asound/bluealsa-pcm.c:172: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread resumed: 3
Nov 25 19:33:19 user.debug D: src/asound/bluealsa-pcm.c:169: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread paused: 4
Nov 25 19:33:19 user.debug D: src/asound/bluealsa-pcm.c:414: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Nov 25 19:33:19 user.debug D: src/asound/bluealsa-pcm.c:264: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Starting
Nov 25 19:33:19 user.debug D: src/asound/bluealsa-pcm.c:172: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread resumed: 3
Nov 25 19:33:20 user.debug D: src/asound/bluealsa-pcm.c:169: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread paused: 4
Nov 25 19:33:20 user.debug D: src/asound/bluealsa-pcm.c:414: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Nov 25 19:33:20 user.debug D: src/asound/bluealsa-pcm.c:264: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Starting
Nov 25 19:33:20 user.debug D: src/asound/bluealsa-pcm.c:172: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread resumed: 3
Nov 25 19:33:20 user.debug D: src/asound/bluealsa-pcm.c:169: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread paused: 4
Nov 25 19:33:20 user.debug D: src/asound/bluealsa-pcm.c:414: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Nov 25 19:33:20 user.debug D: src/asound/bluealsa-pcm.c:264: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Starting
Nov 25 19:33:20 user.debug D: src/asound/bluealsa-pcm.c:172: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread resumed: 3
Nov 25 19:33:20 user.debug D: src/asound/bluealsa-pcm.c:169: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread paused: 4
Nov 25 19:33:20 user.debug D: src/asound/bluealsa-pcm.c:414: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Nov 25 19:33:20 user.debug D: src/asound/bluealsa-pcm.c:264: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Starting
Nov 25 19:33:20 user.debug D: src/asound/bluealsa-pcm.c:172: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread resumed: 3
Nov 25 19:33:21 user.debug D: src/asound/bluealsa-pcm.c:169: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread paused: 4
Nov 25 19:33:21 user.debug D: src/asound/bluealsa-pcm.c:414: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Nov 25 19:33:21 user.debug D: src/asound/bluealsa-pcm.c:264: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Starting
Nov 25 19:33:21 user.debug D: src/asound/bluealsa-pcm.c:172: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread resumed: 3
Nov 25 19:33:21 user.debug D: src/asound/bluealsa-pcm.c:169: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread paused: 4
Nov 25 19:33:21 user.debug D: src/asound/bluealsa-pcm.c:414: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Nov 25 19:33:21 user.debug D: src/asound/bluealsa-pcm.c:264: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Starting
Nov 25 19:33:21 user.debug D: src/asound/bluealsa-pcm.c:172: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread resumed: 3
Nov 25 19:33:21 user.debug D: src/asound/bluealsa-pcm.c:169: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread paused: 4
Nov 25 19:33:21 user.debug D: src/asound/bluealsa-pcm.c:414: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Nov 25 19:33:21 user.debug D: src/asound/bluealsa-pcm.c:264: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Starting
Nov 25 19:33:21 user.debug D: src/asound/bluealsa-pcm.c:172: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread resumed: 3

@hrc-amilcar
Copy link
Author

It seems I'm able to get into a state where a particular headset (Zebra HS3100) gets SCO underruns all the time. I see a new error in the logs, but from bluetoothd this time. Any clues as to what 'sdp_extract_arr' error could mean in the context of BlueAlsa?

This is upon connection, before opening playback/capture streams:

Dec  8 20:12:55 user.crit ./bluealsa: D: src/bluez.c:1047: Called: org.bluez.Profile1.NewConnection()
Dec  8 20:12:55 user.crit ./bluealsa: D: src/sco.c:200: Created SCO dispatcher [ba-sco-dispatch]: hci0
Dec  8 20:12:55 user.crit ./bluealsa: D: src/bluez.c:971: RFCOMM: HFP Audio Gateway configured for device 00:1B:41:B2:86:9B
Dec  8 20:12:55 user.crit ./bluealsa: D: src/ba-transport.c:715: State transition: 0 -> 2
Dec  8 20:12:55 user.crit ./bluealsa: D: src/ba-transport.c:1027: Created new thread [ba-rfcomm]: RFCOMM: HFP Audio Gateway
Dec  8 20:12:55 user.crit ./bluealsa: D: src/ba-transport.c:715: State transition: 0 -> 2
Dec  8 20:12:55 user.crit ./bluealsa: D: src/ba-transport.c:1027: Created new thread [ba-sco]: HFP Audio Gateway (CVSD)
Dec  8 20:12:55 user.crit ./bluealsa: D: src/rfcomm.c:849: Starting loop: RFCOMM: HFP Audio Gateway
Dec  8 20:12:55 user.crit ./bluealsa: D: src/sco.c:241: Starting SCO loop: HFP Audio Gateway (CVSD)
Dec  8 20:12:55 user.crit ./bluealsa: D: src/sco.c:76: Starting SCO dispatcher loop: hci0
Dec  8 20:12:55 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+BRSF, value:191
Dec  8 20:12:55 user.crit ./bluealsa: D: src/rfcomm.c:105: Sending AT message: RESP: command:+BRSF, value:2272
Dec  8 20:12:55 user.crit ./bluealsa: D: src/rfcomm.c:105: Sending AT message: RESP: command:(null), value:OK
Dec  8 20:12:55 user.crit ./bluealsa: D: src/rfcomm.c:124: RFCOMM: HFP Audio Gateway state transition: 0 -> 2
Dec  8 20:12:55 user.crit ./bluealsa: D: src/at.c:161: AT message: TEST: command:+CIND, value:(null)
Dec  8 20:12:55 user.crit ./bluealsa: D: src/rfcomm.c:105: 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))
Dec  8 20:12:55 user.crit ./bluealsa: D: src/rfcomm.c:105: Sending AT message: RESP: command:(null), value:OK
Dec  8 20:12:55 user.crit ./bluealsa: D: src/rfcomm.c:124: RFCOMM: HFP Audio Gateway state transition: 2 -> 5
Dec  8 20:12:55 user.crit ./bluealsa: D: src/at.c:161: AT message: GET: command:+CIND, value:(null)
Dec  8 20:12:55 user.crit ./bluealsa: D: src/rfcomm.c:105: Sending AT message: RESP: command:+CIND, value:0,0,0,0,0,0,5
Dec  8 20:12:55 user.crit ./bluealsa: D: src/rfcomm.c:105: Sending AT message: RESP: command:(null), value:OK
Dec  8 20:12:55 user.crit ./bluealsa: D: src/rfcomm.c:124: RFCOMM: HFP Audio Gateway state transition: 5 -> 7
Dec  8 20:12:55 daemon.err bluetoothd[455]: Unable to get connect data for HSP Audio Gateway: getpeername: Transport endpoint is not connected (107)
Dec  8 20:12:56 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+CMER, value:3, 0, 0, 1
Dec  8 20:12:56 user.crit ./bluealsa: D: src/rfcomm.c:105: Sending AT message: RESP: command:(null), value:OK
Dec  8 20:12:56 user.crit ./bluealsa: D: src/rfcomm.c:124: RFCOMM: HFP Audio Gateway state transition: 7 -> 8
Dec  8 20:12:56 user.crit ./bluealsa: D: src/rfcomm.c:124: RFCOMM: HFP Audio Gateway state transition: 8 -> 9
Dec  8 20:12:56 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+VGS, value:13
Dec  8 20:12:56 user.crit ./bluealsa: D: src/rfcomm.c:105: Sending AT message: RESP: command:(null), value:OK
Dec  8 20:12:56 user.crit ./bluealsa: D: src/at.c:161: AT message: GET: command:+BTRH, value:(null)
Dec  8 20:12:56 user.crit ./bluealsa: D: src/rfcomm.c:105: Sending AT message: RESP: command:(null), value:OK
Dec  8 20:12:56 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+ANDROID, value:XHSTCAP,3.8,3.10,2819M0250,^_
Dec  8 20:12:56 user.crit ./bluealsa: W: Unsupported AT message: SET: command:+ANDROID, value:XHSTCAP,3.8,3.10,2819M0250,^_
Dec  8 20:12:56 user.crit ./bluealsa: D: src/rfcomm.c:105: Sending AT message: RESP: command:(null), value:ERROR
Dec  8 20:12:56 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+ANDROID, value:XHSMICMUTE,0
Dec  8 20:12:56 user.crit ./bluealsa: W: Unsupported AT message: SET: command:+ANDROID, value:XHSMICMUTE,0
Dec  8 20:12:56 user.crit ./bluealsa: D: src/rfcomm.c:105: Sending AT message: RESP: command:(null), value:ERROR
Dec  8 20:12:56 daemon.err bluetoothd[455]: sdp_extract_attr: Unknown data descriptor : 0x5 terminating
Dec  8 20:12:56 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+ANDROID, value:XHSTPOWER,0
Dec  8 20:12:56 user.crit ./bluealsa: W: Unsupported AT message: SET: command:+ANDROID, value:XHSTPOWER,0
Dec  8 20:12:56 user.crit ./bluealsa: D: src/rfcomm.c:105: Sending AT message: RESP: command:(null), value:ERROR
Dec  8 20:12:56 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+ANDROID, value:XHSTBATSOC,24,T1468,00042019
Dec  8 20:12:56 user.crit ./bluealsa: W: Unsupported AT message: SET: command:+ANDROID, value:XHSTBATSOC,24,T1468,00042019
Dec  8 20:12:56 user.crit ./bluealsa: D: src/rfcomm.c:105: Sending AT message: RESP: command:(null), value:ERROR
Dec  8 20:12:56 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+ANDROID, value:XHSTBATSOH,100,T1468,00042019
Dec  8 20:12:56 user.crit ./bluealsa: W: Unsupported AT message: SET: command:+ANDROID, value:XHSTBATSOH,100,T1468,00042019
Dec  8 20:12:56 user.crit ./bluealsa: D: src/rfcomm.c:105: Sending AT message: RESP: command:(null), value:ERROR
Dec  8 20:12:56 user.crit ./bluealsa: D: src/at.c:161: AT message: CMD: command:+CLCC, value:(null)
Dec  8 20:12:56 user.crit ./bluealsa: W: Unsupported AT message: CMD: command:+CLCC, value:(null)
Dec  8 20:12:56 user.crit ./bluealsa: D: src/rfcomm.c:105: Sending AT message: RESP: command:(null), value:ERROR
Dec  8 20:12:56 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+BIA, value:0,1,1,1,0,0,0
Dec  8 20:12:56 user.crit ./bluealsa: D: src/rfcomm.c:105: Sending AT message: RESP: command:(null), value:OK
Dec  8 20:12:56 user.crit ./bluealsa: D: src/at.c:161: AT message: SET: command:+CSRSF, value:0,0,0,1,0,0,0
Dec  8 20:12:56 user.crit ./bluealsa: W: Unsupported AT message: SET: command:+CSRSF, value:0,0,0,1,0,0,0
Dec  8 20:12:56 user.crit ./bluealsa: D: src/rfcomm.c:105: Sending AT message: RESP: command:(null), value:ERROR

@hrc-amilcar
Copy link
Author

hrc-amilcar commented Dec 10, 2019

In attempting to debug this issue, I've added some logs to the PCM plugin to see why it's getting into a perpetual underrun condition. The first letter of the log is either 'R' or 'W' for read or write.

I noticed that the shadow copy of hw_ptr is merrily moving along, while the actual io->hw_ptr is stalling. This only happens after I've connected a different headset (A) before opening the PCM with headset (B).

Do you have any clues as to why io->appl_ptr starts off at 1088 and stays there after multiple writes of 160 bytes? Or whyio->appl_ptr and io->hw_ptr are falling behind the local copies of those pointers, even though the reads/writes to the ba_pcm_fd are succeeding?

Dec 10 20:37:05 Attempting to open ALSA audio device 'bluealsa:SRV=org.bluealsa,DEV=E4:22:A5:8B:35:06,PROFILE=sco'
Dec 10 20:37:05 ./bluealsa: D: src/bluealsa-dbus.c:139: Called: org.bluealsa.Manager1.GetPCMs()
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:643: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Setting constraints
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:362: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Initializing HW
Dec 10 20:37:05 ./bluealsa: D: src/bluealsa-dbus.c:371: Called: org.bluealsa.PCM1.Open()
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:395: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Selected HW buffer: 20 periods x 160 bytes == 3200 bytes
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:410: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Initializing SW
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:410: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Initializing SW
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:432: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Dec 10 20:37:05 stream1: 1 channel(s) @ 8000hz without hw_resampling (buffer:1600|200000us, period:80|10000us)
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:410: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Initializing SW
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:432: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Dec 10 20:37:05 ./bluealsa: D: src/bluealsa-dbus.c:139: Called: org.bluealsa.Manager1.GetPCMs()
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:643: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Setting constraints
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:362: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Initializing HW
Dec 10 20:37:05 ./bluealsa: D: src/bluealsa-dbus.c:371: Called: org.bluealsa.PCM1.Open()
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:389: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: FIFO buffer size: 4096
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:395: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Selected HW buffer: 20 periods x 160 bytes == 3200 bytes
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:410: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Initializing SW
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:410: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Initializing SW
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:432: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Dec 10 20:37:05 stream0: 1 channel(s) @ 8000hz without hw_resampling (buffer:1600|200000us, period:80|10000us)
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:410: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Initializing SW
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:432: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:293: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Starting
Dec 10 20:37:05 ./bluealsa: D: src/ba-transport.c:715: State transition: 2 -> 2
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:291: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Starting
Dec 10 20:37:05 ./bluealsa: D: src/ba-transport.c:715: State transition: 2 -> 2
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:137: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Starting IO loop: 14
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:209: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: R: io_ptr [   80] io_hw_ptr [   80] io->appl_ptr [    0] io->hw_ptr [    0]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:137: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Starting IO loop: 19
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [   80] io_hw_ptr [   80] io->appl_ptr [ 1088] io->hw_ptr [    0]: bytes [160]
Dec 10 20:37:05 ./bluealsa: D: src/ba-transport.c:958: New SCO link: E4:22:A5:8B:35:06: 29
Dec 10 20:37:05 ./bluealsa: D: src/hci.c:126: SCO link socket MTU: 29: 180
Dec 10 20:37:05 ./bluealsa: D: src/ba-transport.c:943: Reusing SCO: 29
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  160] io_hw_ptr [  160] io->appl_ptr [ 1088] io->hw_ptr [    0]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  240] io_hw_ptr [  240] io->appl_ptr [ 1088] io->hw_ptr [    0]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  320] io_hw_ptr [  320] io->appl_ptr [ 1088] io->hw_ptr [    0]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  400] io_hw_ptr [  400] io->appl_ptr [ 1088] io->hw_ptr [    0]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  480] io_hw_ptr [  480] io->appl_ptr [ 1088] io->hw_ptr [    0]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  560] io_hw_ptr [  560] io->appl_ptr [ 1088] io->hw_ptr [    0]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  640] io_hw_ptr [  640] io->appl_ptr [ 1088] io->hw_ptr [    0]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  720] io_hw_ptr [  720] io->appl_ptr [ 1088] io->hw_ptr [    0]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  800] io_hw_ptr [  800] io->appl_ptr [ 1088] io->hw_ptr [    0]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:209: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: R: io_ptr [  160] io_hw_ptr [  160] io->appl_ptr [    0] io->hw_ptr [    0]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  880] io_hw_ptr [  880] io->appl_ptr [ 1792] io->hw_ptr [  720]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  960] io_hw_ptr [  960] io->appl_ptr [ 1792] io->hw_ptr [  720]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [ 1040] io_hw_ptr [ 1040] io->appl_ptr [ 1792] io->hw_ptr [  720]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [ 1120] io_hw_ptr [ 1120] io->appl_ptr [ 1792] io->hw_ptr [  720]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:209: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: R: io_ptr [  240] io_hw_ptr [  240] io->appl_ptr [   80] io->hw_ptr [   80]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [ 1200] io_hw_ptr [ 1200] io->appl_ptr [ 1856] io->hw_ptr [ 1040]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [ 1280] io_hw_ptr [ 1280] io->appl_ptr [ 1856] io->hw_ptr [ 1040]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [ 1360] io_hw_ptr [ 1360] io->appl_ptr [ 1856] io->hw_ptr [ 1040]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [ 1440] io_hw_ptr [ 1440] io->appl_ptr [ 1856] io->hw_ptr [ 1040]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:209: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: R: io_ptr [  320] io_hw_ptr [  320] io->appl_ptr [  160] io->hw_ptr [  160]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [ 1520] io_hw_ptr [ 1520] io->appl_ptr [ 1920] io->hw_ptr [ 1360]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [    0] io_hw_ptr [ 1600] io->appl_ptr [ 1920] io->hw_ptr [ 1360]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [   80] io_hw_ptr [ 1680] io->appl_ptr [ 1920] io->hw_ptr [ 1360]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  160] io_hw_ptr [ 1760] io->appl_ptr [ 1920] io->hw_ptr [ 1360]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  240] io_hw_ptr [ 1840] io->appl_ptr [ 1920] io->hw_ptr [ 1360]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  320] io_hw_ptr [ 1920] io->appl_ptr [ 1920] io->hw_ptr [ 1360]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  400] io_hw_ptr [ 2000] io->appl_ptr [ 1920] io->hw_ptr [ 1360]: bytes [160] ** UNDERRUN **
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:169: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread paused: 4
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:209: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: R: io_ptr [  400] io_hw_ptr [  400] io->appl_ptr [  240] io->hw_ptr [  240]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:432: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:283: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Started
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:172: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread resumed: 3
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [   80] io_hw_ptr [   80] io->appl_ptr [ 1152] io->hw_ptr [    0]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  160] io_hw_ptr [  160] io->appl_ptr [ 1152] io->hw_ptr [    0]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  240] io_hw_ptr [  240] io->appl_ptr [ 1152] io->hw_ptr [    0]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  320] io_hw_ptr [  320] io->appl_ptr [ 1152] io->hw_ptr [    0]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  400] io_hw_ptr [  400] io->appl_ptr [ 1152] io->hw_ptr [    0]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:209: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: R: io_ptr [  480] io_hw_ptr [  480] io->appl_ptr [  320] io->hw_ptr [  320]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  480] io_hw_ptr [  480] io->appl_ptr [ 1216] io->hw_ptr [  320]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  560] io_hw_ptr [  560] io->appl_ptr [ 1216] io->hw_ptr [  320]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  640] io_hw_ptr [  640] io->appl_ptr [ 1216] io->hw_ptr [  320]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  720] io_hw_ptr [  720] io->appl_ptr [ 1216] io->hw_ptr [  320]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  800] io_hw_ptr [  800] io->appl_ptr [ 1216] io->hw_ptr [  320]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  880] io_hw_ptr [  880] io->appl_ptr [ 1216] io->hw_ptr [  320]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  960] io_hw_ptr [  960] io->appl_ptr [ 1216] io->hw_ptr [  320]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:209: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: R: io_ptr [  560] io_hw_ptr [  560] io->appl_ptr [  400] io->hw_ptr [  400]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [ 1040] io_hw_ptr [ 1040] io->appl_ptr [ 1216] io->hw_ptr [  320]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [ 1120] io_hw_ptr [ 1120] io->appl_ptr [ 2048] io->hw_ptr [  960]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [ 1200] io_hw_ptr [ 1200] io->appl_ptr [ 2048] io->hw_ptr [  960]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [ 1280] io_hw_ptr [ 1280] io->appl_ptr [ 2048] io->hw_ptr [  960]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [ 1360] io_hw_ptr [ 1360] io->appl_ptr [ 2048] io->hw_ptr [  960]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [ 1440] io_hw_ptr [ 1440] io->appl_ptr [ 2048] io->hw_ptr [  960]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [ 1520] io_hw_ptr [ 1520] io->appl_ptr [ 2048] io->hw_ptr [  960]: bytes [160]
Dec 10 20:37:05 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [    0] io_hw_ptr [ 1600] io->appl_ptr [ 2048] io->hw_ptr [  960]: bytes [160]
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [   80] io_hw_ptr [ 1680] io->appl_ptr [ 2048] io->hw_ptr [  960]: bytes [160]
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  160] io_hw_ptr [ 1760] io->appl_ptr [ 2048] io->hw_ptr [  960]: bytes [160]
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  240] io_hw_ptr [ 1840] io->appl_ptr [ 2048] io->hw_ptr [  960]: bytes [160]
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  320] io_hw_ptr [ 1920] io->appl_ptr [ 2048] io->hw_ptr [  960]: bytes [160]
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  400] io_hw_ptr [ 2000] io->appl_ptr [ 2048] io->hw_ptr [  960]: bytes [160]
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [  480] io_hw_ptr [ 2080] io->appl_ptr [ 2048] io->hw_ptr [  960]: bytes [160] ** UNDERRUN **
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:169: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread paused: 4
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:209: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: R: io_ptr [  640] io_hw_ptr [  640] io->appl_ptr [  480] io->hw_ptr [  480]: bytes [160]
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:432: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:283: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Started
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:172: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread resumed: 3
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [   80] io_hw_ptr [   80] io->appl_ptr [   64] io->hw_ptr [    0]: bytes [160] ** UNDERRUN **
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:169: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread paused: 4
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:432: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:283: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Started
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:172: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread resumed: 3
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [   80] io_hw_ptr [   80] io->appl_ptr [   64] io->hw_ptr [    0]: bytes [160] ** UNDERRUN **
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:169: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread paused: 4
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:432: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:283: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Started
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:172: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread resumed: 3
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [   80] io_hw_ptr [   80] io->appl_ptr [   64] io->hw_ptr [    0]: bytes [160] ** UNDERRUN **
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:169: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread paused: 4
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:209: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: R: io_ptr [  720] io_hw_ptr [  720] io->appl_ptr [  560] io->hw_ptr [  560]: bytes [160]
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:432: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:283: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Started
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:172: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread resumed: 3
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [   80] io_hw_ptr [   80] io->appl_ptr [   64] io->hw_ptr [    0]: bytes [160] ** UNDERRUN **
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:169: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread paused: 4
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:432: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Prepared
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:283: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: Started
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:172: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: IO thread resumed: 3
Dec 10 20:37:06 D: src/asound/bluealsa-pcm.c:233: /org/bluealsa/hci0/dev_E4_22_A5_8B_35_06/sco: W: io_ptr [   80] io_hw_ptr [   80] io->appl_ptr [   64] io->hw_ptr [    0]: bytes [160] ** UNDERRUN **

@hrc-amilcar
Copy link
Author

hrc-amilcar commented Dec 18, 2019

An update to whom it may concern.

It seems that something in the HCI controller is affecting audio performance when there is simultaneous communication between multiple devices, even when simply connecting a second device while streaming to/from the first.

I found this bug post that talks about a similar issue, which may point to a bug in bluez or elsewhere in the bluetooth stack but not related to BlueAlsa. The bug was reported in 2009 but some people are still having issues even 10 years later.

The suggested mitigation is this:

hciconfig hci0 lm ACCEPT,MASTER
hciconfig hci0 lp HOLD,SNIFF,PARK

Audio still stutters sometimes, but there are rarely any underruns now. I'm still trying to understand why changing those modes helps.

@arkq
Copy link
Owner

arkq commented Mar 15, 2020

I'm closing this issue, since it seems, that it's not related to bluez-alsa.

@arkq arkq closed this as completed Mar 15, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants