arkq
E: Invalid BT socket & W: Couldn't register oFono
- Are these warning relevant?
- Why are they always arising?
I have still very long delay for sent out audio on Raspberry zero W (buster) and Raspberry zero 2 (bullseye) with ofono see also #385 Could this be the reason?
raspberry zero 2 W:
root@rpi:/home/pi# bluealsa -p hfp-ofono
bluealsa: I: main.c:479: Disabling native HFP support due to enabled oFono profile
bluealsa: D: main.c:534: Starting main dispatching loop
bluealsa: D: main.c:111: Acquired D-Bus service name: org.bluealsa
bluealsa: D: bluealsa-dbus.c:426: Registering D-Bus manager: /org/bluealsa
bluealsa: D: bluez.c:669: Registering battery provider: /org/bluez/hci0/battery
bluealsa: D: bluez.c:689: BlueZ battery provider support not available
bluealsa: D: bluez.c:483: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/source/1
bluealsa: D: bluez.c:392: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/source/1
bluealsa: D: bluez.c:483: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/source/2
bluealsa: D: bluez.c:392: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/source/2
bluealsa: D: bluez.c:918: Creating hands-free profile object: /org/bluez/HSP/AudioGateway
bluealsa: D: bluez.c:842: Registering hands-free profile: /org/bluez/HSP/AudioGateway
bluealsa: D: ofono.c:466: Registering oFono audio agent: /org/bluez/HFP/oFono
bluealsa: D: ofono.c:247: Adding new oFono card: /card_1
bluealsa: D: ba-transport.c:1151: Starting transport: HFP Hands-Free (CVSD)
bluealsa: E: ba-transport.c:278: Invalid BT socket: -1
bluealsa: E: ba-transport.c:278: Invalid BT socket: -1
bluealsa: D: ofono.c:466: Registering oFono audio agent: /org/bluez/HFP/oFono
bluealsa: W: ofono.c:521: Couldn't register oFono: GDBus.Error:org.ofono.Error.InUse: The resource is currently in use
raspberry zero w:
root@pilot1:/home/pilot/bluez-alsa# export LIBASOUND_THREAD_SAFE=0
root@pilot1:/home/pilot/bluez-alsa# bluealsa -p hfp-ofono
bluealsa: I: main.c:479: Disabling native HFP support due to enabled oFono profile
bluealsa: D: main.c:534: Starting main dispatching loop
bluealsa: D: main.c:111: Acquired D-Bus service name: org.bluealsa
bluealsa: D: bluealsa-dbus.c:426: Registering D-Bus manager: /org/bluealsa
bluealsa: D: bluez.c:669: Registering battery provider: /org/bluez/hci0/battery
bluealsa: D: bluez.c:689: BlueZ battery provider support not available
bluealsa: D: bluez.c:483: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/source/1
bluealsa: D: bluez.c:392: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/source/1
bluealsa: D: bluez.c:483: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/source/2
bluealsa: D: bluez.c:392: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/source/2
bluealsa: D: bluez.c:918: Creating hands-free profile object: /org/bluez/HSP/AudioGateway
bluealsa: D: bluez.c:842: Registering hands-free profile: /org/bluez/HSP/AudioGateway
bluealsa: D: ofono.c:466: Registering oFono audio agent: /org/bluez/HFP/oFono
bluealsa: D: ofono.c:466: Registering oFono audio agent: /org/bluez/HFP/oFono
bluealsa: W: ofono.c:521: Couldn't register oFono: GDBus.Error:org.ofono.Error.InUse: The resource is currently in use
raspberry zero 2 W:
root@rpi:/home/pi# hciconfig -a
hci0: Type: Primary Bus: UART
BD Address: xx:xx:xx:xx:xx:xx ACL MTU: 1021:7 SCO MTU: 64:1
UP RUNNING
RX bytes:4890 acl:56 sco:0 events:160 errors:0
TX bytes:5069 acl:48 sco:0 commands:124 errors:0
Features: 0xbf 0xfe 0xcf 0xfe 0xdb 0xff 0x7b 0x87
Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3
Link policy: RSWITCH SNIFF
Link mode: SLAVE ACCEPT
Name: 'rpi'
Class: 0x200000
Service Classes: Audio
Device Class: Miscellaneous,
HCI Version: 4.2 (0x8) Revision: 0x5c
LMP Version: 4.2 (0x8) Subversion: 0x410c
Manufacturer: Broadcom Corporation (15)
raspberry zero W:
root@rpil:/home/pilot/bluez-alsa# hciconfig -a
hci0: Type: Primary Bus: UART
BD Address: xx:xx:xx:xx:xx:xx ACL MTU: 1021:8 SCO MTU: 64:1
UP RUNNING PSCAN
RX bytes:28102 acl:603 sco:0 events:869 errors:0
TX bytes:11546 acl:249 sco:0 commands:363 errors:0
Features: 0xbf 0xfe 0xcf 0xfe 0xdb 0xff 0x7b 0x87
Packet type: DM1 DM3 DM5 DH1 DH3 DH5 HV1 HV2 HV3
Link policy: RSWITCH SNIFF
Link mode: SLAVE ACCEPT
Name: 'rpi'
Class: 0x200000
Service Classes: Audio
Device Class: Miscellaneous,
HCI Version: 4.1 (0x7) Revision: 0x1fc
LMP Version: 4.1 (0x7) Subversion: 0x2209
Manufacturer: Broadcom Corporation (15)
bluealsa-aplay -l
**** List of PLAYBACK Bluetooth Devices ****
hci0: xx:xx:xx:xx:xx:xx [Galaxy Tab S2], trusted phone
SCO (CVSD): S16_LE 1 channel 8000 Hz
**** List of CAPTURE Bluetooth Devices ****
hci0: xx:xx:xx:xx:xx:xx [Galaxy Tab S2], trusted phone
SCO (CVSD): S16_LE 1 channel 8000 Hz
Are these warning relevant? Why are they always arising?
It was a bug in the master which was introduced some time ago. I've just pushed a fix for that, so you should not see this error message any more. However, I'm not sure (honestly I doubt) that it was a cause of a delay you are seeing...
ok, the warning is now fixed but still these two errors?
root@pilot:/home/pilot/bluez-alsa# LIBASOUND_THREAD_SAFE=0 bluealsa -p hfp-ofono
bluealsa: I: main.c:474: Disabling native HFP support due to enabled oFono profile
bluealsa: D: main.c:529: Starting main dispatching loop
bluealsa: D: main.c:111: Acquired D-Bus service name: org.bluealsa
bluealsa: D: bluealsa-dbus.c:426: Registering D-Bus manager: /org/bluealsa
bluealsa: D: bluez.c:669: Registering battery provider: /org/bluez/hci0/battery
bluealsa: D: bluez.c:689: BlueZ battery provider support not available
bluealsa: D: bluez.c:483: Creating media endpoint object: /org/bluez/hci0/A2DP/AAC/source/1
bluealsa: D: bluez.c:392: Registering media endpoint: /org/bluez/hci0/A2DP/AAC/source/1
bluealsa: D: bluez.c:483: Creating media endpoint object: /org/bluez/hci0/A2DP/AAC/source/2
bluealsa: D: bluez.c:392: Registering media endpoint: /org/bluez/hci0/A2DP/AAC/source/2
bluealsa: D: bluez.c:483: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/source/1
bluealsa: D: bluez.c:392: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/source/1
bluealsa: D: bluez.c:483: Creating media endpoint object: /org/bluez/hci0/A2DP/SBC/source/2
bluealsa: D: bluez.c:392: Registering media endpoint: /org/bluez/hci0/A2DP/SBC/source/2
bluealsa: D: bluez.c:918: Creating hands-free profile object: /org/bluez/HSP/AudioGateway
bluealsa: D: bluez.c:842: Registering hands-free profile: /org/bluez/HSP/AudioGateway
bluealsa: D: ofono.c:466: Registering oFono audio agent: /org/bluez/HFP/oFono
bluealsa: D: ofono.c:247: Adding new oFono card: /card_1
bluealsa: D: ba-transport.c:1151: Starting transport: HFP Hands-Free (CVSD)
bluealsa: E: ba-transport.c:278: Invalid BT socket: -1
bluealsa: E: ba-transport.c:278: Invalid BT socket: -1
Ok, that might be an another issues then. I'll try to check that today, or during a weekend (currently I'm busy with some other work).
I've made a small test with oFono and it seems that there is one unnecessary line in the code :D Please, remove that and see whether it will help:
https://github.com/Arkq/bluez-alsa/blob/master/src/ofono.c#L277
Ok, that has now solved the issue. I have to check if the delay is now also better. It is sometimes working good (<=1s) - but almost around 10s. I do not know the reasons for that. Maybe some problems with the raspberry UARTs?
I do not know the reasons for that. Maybe some problems with the raspberry UARTs?
I have never experienced such a delay... So, I'm afraid I will be no help for you in this area.
@dr-ni This issue has been idle for a long time, so if is no longer of interest please let us know and then it will be closed.
In the meantime I've been experimenting with HSP-HS and HFP-HF profiles (I don't use ofono though) and at last I can understand how such a long delay can be created.
When the AG device "connects" to the HF/HS, a the profile configuration is negotiated and BlueALSA creates the PCM objects on the HF/HS. However at this stage no audio connection exists and any ALSA application that opens one of these PCMS will be blocked. After some indeterminate time the AG will open the audio connection at which point the application is unblocked and audio flows in and out of the bluetooth adapter.
Now when the client is a pipeline such as record -f s16_le -c 1 -r 8000 -D mic | aplay -D bluealsa the aplay process is blocked once it has filled the BlueALSA pipe to the daemon, while the arecord process starts capture immediately and runs until all buffers in the total pipeline are filled, at which point it too becomes blocked. So using CVSD with default buffer definitions we can have up to 500ms buffered in arecord, 4096ms buffered in the first pipe, 500ms in aplay and 256ms in the second pipe; giving a total of 5352ms buffered, which translates into a delay of that amount once the audio connection is opened. I see exactly this is my experiments. If arecord is run in its default config it captures in format U8, not S16_LE, and that doubles the number of samples that can be stored in the first pipe giving a total delay of 9448ms. I suspect that is what you are seeing.
The only workaround is to avoid starting the ALSA client before the audio connection has been opened by the AG (i.e. when the SCO transport is "acquired"). Unfortunately so far I have not been able to identify any system events that an application can listen for to know when acquisition has occcured, so I have no idea how to start arecord/aplay at the right time. Perhaps ofono emits some D-Bus event? I don't know.
Hi borine,
here is an ofono dial example (should be working with your mobile):
dial:
#!/usr/bin/python3
import sys
import dbus
if (len(sys.argv) < 2):
print("Usage: %s [modem] <number> [hide_callerid]" % (sys.argv[0]))
sys.exit(1)
bus = dbus.SystemBus()
manager = dbus.Interface(bus.get_object('org.ofono', '/'),
'org.ofono.Manager')
modems = manager.GetModems()
modem = modems[0][0]
hide_callerid = "default"
if (len(sys.argv) == 2):
number = sys.argv[1]
elif (len(sys.argv) == 3):
if (sys.argv[2] == "default") or (sys.argv[2] == "enabled") or \
(sys.argv[2] == "disabled"):
number = sys.argv[1]
hide_callerid = sys.argv[2]
else:
modem = sys.argv[1]
number = sys.argv[2]
else:
modem = sys.argv[1]
number = sys.argv[2]
hide_callerid = sys.argv[3]
print("Using modem %s" % modem)
vcm = dbus.Interface(bus.get_object('org.ofono', modem),
'org.ofono.VoiceCallManager')
path = vcm.Dial(number, hide_callerid)
print(path)
hangup:
import sys
import dbus
bus = dbus.SystemBus()
manager = dbus.Interface(bus.get_object('org.ofono', '/'),
'org.ofono.Manager')
modems = manager.GetModems()
modem = modems[0][0]
if (len(sys.argv) == 2):
modem = sys.argv[1]
manager = dbus.Interface(bus.get_object('org.ofono', modem),
'org.ofono.VoiceCallManager')
manager.HangupAll()
@borine +1 for nice investigation of this issue!
Unfortunately so far I have not been able to identify any system events that an application can listen for to know when acquisition has occcured
Maybe we should add a property to the PCM D-Bus interface which will determine the "state" (I don't know how to name it yet) of the acquirability of the PCM? Not all PCMs are able to transmit/receive data immediately. The issue might be with HSP-HS/HFP-HF (currently there is no implementation for requesting SCO connection from HS/HF). Moreover, the issue is more problematic for HSP and HFP without mSBC support - with mSBC support PCM is "invalid" if audio was not acquired by AG (no sampling frequency, because codec is not known). And of course A2DP source PCM will output samples only when source BT device starts playback.
Maybe we should add a property to the PCM D-Bus interface
I was thinking just the same thing ... boolean TransportAcquired [readonly] is my current thinking. bluealsa-cli monitor could be extended to print this PropertyChanged event to make a simple trigger for shell scripts. I haven't thought through any implementation details, its just an abstract idea. Incidentally I am also planning to modify the HSP/HFP wiki page to make this issue more visible to users (and many thanks to @dr-ni for raising it in the first place).
Does this always require a check of the property before calling arecord and aplay pipe combinations?
Its just an idea at present, exactly how it could be used wll depend on how it is implemented, (if it ever is implemented). My thinking is that it should be possible to listen for the D-Bus PropertiesChanged signal from the org.freedesktop.DBus.Properties interface, and launch the ALSA client in response. From a shell script this could be done using dbus-monitor or similar tools, or bluealsa-cli monitor may be changed to also support this signal. From a python script the dbus add_signal_receiver() method could be used. I'm sure that examples would be added to the wiki if this ever were implemented.
Perhaps ofono emits some D-Bus event?
A liitle research later ...
The D-Bus interface org.ofono.VoiceCall (https://git.kernel.org/pub/scm/network/ofono/ofono.git/tree/doc/voicecall-api.txt) has a string property called "State", and monitoring changes to this property may be sufficient know when audio connection is available.
HFP spec requires that the audio connection must be established before a call enters the "active" state, so you can be certain that your ALSA client will not be blocked once this state has been achieved. That is fine for outgoing audio.
The HFP spec permits the AG to establish the audio connection much earlier than that, for support of in-band ringtone alerts of incoming calls. That is optional, so not all AG devices support it. For incoming audio, client setups such as arecord -D bluealsa | aplay -D plughw or bluealsa-cli open | aplay -D plughw or bluealsa-aplay --profile-sco will be OK when blocked (however clients such as alsaloop will not), so for incoming audio it may be best to start the client as soon as the blusealsa PCM appears so that the ringtone can be heard.
@dr-ni
I've raised a draft PR (#601) to add a new boolean property to the BlueALSA PCM1 interface. If you are able to test this to see if it can fix your ofono delay issues that would be very helpful (I don't use, and have no plans to use, ofono so I can't test that use-case myself). As a simple test, I've modified your "dial" python script so that it waits for the SCO audio connection, by using this new PCM property, before it terminates. So if you start your aplay/arecord pipeline after the "dial" script has returned then the delay should be much reduced. The script assumes that you only have 1 bluetooth audio device connected as it does not filter by device address, and it does not have any error handling, but hopefully it will suffice for testing purposes:
#!/usr/bin/python3
import sys
import dbus
# we need glib mainloop to wait for DBus signals
import dbus.mainloop.glib
from gi.repository import GLib as glib
if (len(sys.argv) < 2):
print("Usage: %s [modem] <number> [hide_callerid]" % (sys.argv[0]))
sys.exit(1)
bus = dbus.SystemBus()
manager = dbus.Interface(bus.get_object('org.ofono', '/'),
'org.ofono.Manager')
modems = manager.GetModems()
modem = modems[0][0]
hide_callerid = "default"
if (len(sys.argv) == 2):
number = sys.argv[1]
elif (len(sys.argv) == 3):
if (sys.argv[2] == "default") or (sys.argv[2] == "enabled") or \
(sys.argv[2] == "disabled"):
number = sys.argv[1]
hide_callerid = sys.argv[2]
else:
modem = sys.argv[1]
number = sys.argv[2]
else:
modem = sys.argv[1]
number = sys.argv[2]
hide_callerid = sys.argv[3]
print("Using modem %s" % modem)
vcm = dbus.Interface(bus.get_object('org.ofono', modem),
'org.ofono.VoiceCallManager')
path = vcm.Dial(number, hide_callerid)
print(path)
# New code to wait for org.bluealsa.PCM1 "Running" property to become True
def signal_handler(*args, **kwargs):
running = args[1].get('Running')
if (bool(running)) :
mainloop.quit()
dbus.mainloop.glib.DBusGMainLoop(set_as_default=True)
mainloop = glib.MainLoop()
bus.add_signal_receiver(signal_handler,
bus_name='org.bluealsa',
signal_name='PropertiesChanged',
dbus_interface='org.freedesktop.DBus.Properties',
arg0='org.bluealsa.PCM1')
mainloop.run()
print('Audio connection started')
hi again, after recompiling I have now this:
sudo su
root@pi:/home/pi/bluez-alsa# bluealsa -p hfp-ofono
pi@pi:# ./ndial.py mynumber
Using modem /hfp/org/bluez/hci0/dev_xx_xx_xx_xx_xx_xx
/hfp/org/bluez/hci0/dev_xx_xx_xx_xx_xx_xx/voicecall01
Traceback (most recent call last):
File "/home/pi/./ndial.py", line 57, in <module>
bus.add_signal_receiver(signal_handler,
File "/usr/lib/python3/dist-packages/dbus/bus.py", line 148, in add_signal_receiver
match = super(BusConnection, self).add_signal_receiver(
File "/usr/lib/python3/dist-packages/dbus/connection.py", line 402, in add_signal_receiver
self._require_main_loop()
RuntimeError: To make asynchronous calls, receive signals or export objects, D-Bus connections must be attached to a main loop by passing mainloop=... to the constructor or calling dbus.set_default_main_loop(...)
Ahh, sorry, it seems the lines
dbus.mainloop.glib.DBusGMainLoop(set_as_default=True)
mainloop = glib.MainLoop()
must be placed before the call to
bus = dbus.SystemBus()
So just moving those 2 lines earlier in the file should fix it.
it's waiting now without any message although connected
root@pi:/home/pilot/bluez-alsa# bluealsa -p hfp-ofono
pi@pi:# ./ndial.py mynumber
Using modem /hfp/org/bluez/hci0/dev_xx_xx_xx_xx_xx_xx
/hfp/org/bluez/hci0/dev_xx_xx_xx_xx_xx_xx/voicecall01
and
arecord -D bluealsa | aplay
ALSA lib bluealsa-pcm.c:1305:(_snd_pcm_bluealsa_open) Couldn't get BlueALSA PCM: PCM not found
arecord: main:830: Fehler beim Öffnen des Gerätes: Kein passendes Gerät gefunden
aplay: read_header:2839: Lesefehler
Hmm, that error indicates that bluealsa has not been informed by ofono that the call exists. I can't imagine how my patch could have caused that, so I'm hoping that this is just an error with the bluealsa command line or perhaps bluealsa build options. Are there any debug messages from the bluealsa daemon?
only after hangup:
bluealsa: E: BT socket disconnected: Connection reset by peer
do I have to enable debug while configure?
bluealsa: E: BT socket disconnected: Connection reset by peer
OK, so that tells us that that the bluealsa PCM was created, and that the audio connection had been opened (because otherwise there would have been no BT socket to disconnect). So perhaps this is an issue with the aplay command line. Does this make any difference?
arecord -D bluealsa:PROFILE=sco |aplay
[BTW, not related to this error, you really should tell arecord what audio parameters to use, otherwise the sound quality will be really bad. It uses 8-bit samples at 8000Hz unless you tell it otherwise. For best results, use that parameters of the bluetooth stream, so for CVSD
arecord -c 1 -f s16_le -r 8000 -D bluealsa:PROFILE=sco | aplay
For mSBC use -r 16000
You can also reduce delay further by setting explicit period and buffer sizes, but lets fix this connection issue first]
PS your log file just arrived while I am typing this. The bluealsa configure version number near the top of the file suggests you have the wrong branch - you need the pcm-running-property branch from my repository, not the main branch. The main branch is experimental and may well have lots of issues with ofono, it is completely untested with ofono.
ok now with pcm-running-property branch:
root@pi:/home/pilot/bluez-alsa# bluealsa -p hfp-ofono
pi@pi:# ./ndial.py mynumber
Using modem /hfp/org/bluez/hci0/dev_xx_xx_xx_xx_xx_xx
/hfp/org/bluez/hci0/dev_xx_xx_xx_xx_xx_xx/voicecall01
Audio connection started
but still
pi@pi:~/bluez-alsa $ arecord -D bluealsa | aplay
ALSA lib bluealsa-pcm.c:1327:(_snd_pcm_bluealsa_open) Couldn't get BlueALSA PCM: PCM not found
arecord: main:830: Fehler beim Öffnen des Gerätes: Kein passendes Gerät gefunden
aplay: read_header:2839: Lesefehler
pi@pi:~/bluez-alsa $ arecord -D bluealsa:PROFILE=sco | aplay
ALSA lib bluealsa-pcm.c:1327:(_snd_pcm_bluealsa_open) Couldn't get BlueALSA PCM: PCM not found
arecord: main:830: Fehler beim Öffnen des Gerätes: Kein passendes Gerät gefunden
aplay: read_header:2839: Lesefehler
pi@pi:~/bluez-alsa $ arecord -c 1 -f s16_le -r 8000 -D bluealsa:PROFILE=sco | aplay
ALSA lib bluealsa-pcm.c:1327:(_snd_pcm_bluealsa_open) Couldn't get BlueALSA PCM: PCM not found
arecord: main:830: Fehler beim Öffnen des Gerätes: Kein passendes Gerät gefunden
aplay: read_header:2839: Lesefehler
Quite a mystery here ! I don't have an explanation why arecord can't find the PCM at present. When the "Audio connection started" message appears, can you post the output of
bluealsa-aplay -L
and perhaps also try
bluealsa-aplay --profile-sco
to see if that can produce any audio?
Thanks for taking time with this, it really is very helpful to have "real world" testing early in the development of new features. It's getting late here now, and I may not have time to work on it this weekend, but I will get back to it next week.
late update: please can you modify the dial script to print the bluealsa pcm object path. Change the signal handler definition to:
def signal_handler(*args, **kwargs):
running = args[1].get('Running')
if (bool(running)) :
print(kwargs['path'])
mainloop.quit()
And the add_signal_receiver call to:
bus.add_signal_receiver(signal_handler,
bus_name='org.bluealsa',
signal_name='PropertiesChanged',
dbus_interface='org.freedesktop.DBus.Properties',
arg0='org.bluealsa.PCM1',
path_keyword='path')
bluealsa-aplay -L
bluealsa:DEV=xx:xx:xx:xx:xx:xx,PROFILE=sco,SRV=org.bluealsa
Tab S5e von Uwe, trusted phone, playback
SCO (CVSD): S16_LE 1 channel 8000 Hz
bluealsa:DEV=xx:xx:xx:xx:xx:xx,PROFILE=sco,SRV=org.bluealsa
Tab S5e von Uwe, trusted phone, capture
SCO (CVSD): S16_LE 1 channel 8000 Hz
pi@pi:# ./ndial.py mynumber
Using modem /hfp/org/bluez/hci0/dev_xx_xx_xx_xx_xx_xx
/hfp/org/bluez/hci0/dev_xx_xx_xx_xx_xx_xx/voicecall01
/org/bluealsa/hci0/dev_xx_xx_xx_xx_xx_xx/hfphf/sink
Audio connection started
cat .asoundrc
defaults.bluealsa.service "org.bluealsa"
defaults.bluealsa.device "xx:xx:xx:xx:xx:xx"
defaults.bluealsa.profile "sco"
defaults.bluealsa.delay 10000
good news:
bluealsa-aplay --profile-sco
bluealsa-aplay: W: Couldn't open mixer: Mixer element not found
and audio was playing
now compiled with debug:
root@pi:/home/pi# bluealsa -p hfp-ofono
bluealsa: [24401] D: main.c:590: Starting main dispatching loop
bluealsa: [24401] D: main.c:114: Acquired D-Bus service name: org.bluealsa
bluealsa: [24401] D: bluealsa-dbus.c:374: Registering D-Bus manager: /org/bluealsa
bluealsa: [24401] D: bluez.c:679: Registering battery provider: /org/bluez/hci0/battery
bluealsa: [24401] D: bluez.c:699: BlueZ battery provider support not available
bluealsa: [24401] D: ofono.c:464: Registering oFono audio agent: /org/bluez/HFP/oFono
bluealsa: [24401] D: ofono.c:247: Adding new oFono card: /card_1
bluealsa: [24401] D: storage.c:102: Loading storage: /var/lib/bluealsa/xx:xx:xx:xx:xx:xx
bluealsa: [24401] D: dbus.c:66: Called: org.ofono.HandsfreeAudioAgent.NewConnection() on /org/bluez/HFP/oFono
bluealsa: [24401] D: ofono.c:405: New oFono SCO connection (codec: 0x1): 17
bluealsa: [24401] D: hci.c:133: SCO link socket MTU: 17: 64
bluealsa: [24401] D: ba-transport.c:1246: Starting transport: HFP Hands-Free (CVSD)
bluealsa: [24401] D: ba-transport.c:323: Created BT socket duplicate: [17]: 18
bluealsa: [24401] D: ba-transport.c:1586: Created new IO thread [ba-sco-enc]: HFP Hands-Free (CVSD)
bluealsa: [24401] D: ba-transport.c:323: Created BT socket duplicate: [17]: 19
bluealsa: [24401] D: ba-transport.c:1586: Created new IO thread [ba-sco-dec]: HFP Hands-Free (CVSD)
bluealsa: [24507] D: sco.c:232: IO loop: START: sco_cvsd_enc_thread: HFP Hands-Free (CVSD)
bluealsa: [24508] D: sco.c:303: IO loop: START: sco_cvsd_dec_thread: HFP Hands-Free (CVSD)
bluealsa: [24508] E: io.c:47: BT socket disconnected: Connection reset by peer
bluealsa: [24508] D: ba-transport.c:335: Closing BT socket duplicate [17]: 19
bluealsa: [24508] D: sco.c:332: IO loop: EXIT: sco_cvsd_dec_thread: HFP Hands-Free (CVSD)
bluealsa: [24508] D: ofono.c:136: Closing oFono SCO link: 17
bluealsa: [24508] D: ba-transport.c:1615: Exiting IO thread [ba-sco-dec]: HFP Hands-Free (CVSD)
The debug log, plus the bluealsa-aplay results, prove that the bluealsa daemon is working correctly and the ndial script shows that the new "Running" PCM property is also working as expected. The only explanation I can think of is that arecord is simply using the wrong bluetooth device address. The only bluetooth address that should be used by any part of this system is the phone's address. So all the "xx_xx_xx_xx_xx_xx" values should be the same for both the ofono object path and the bluealsa PCM path. Also defaults.bluealsa.device xx:xx:xx:xx:xx:xx in your ALSA config should be the same address.
If you installed a debug build of bluealsa then arecord should also print out debug info, and we should be able to see the actual address it is looking for in that output.