ofono not working anymore
dr-ni opened this issue · 11 comments
after my latest git pull I have now suddenly problems with my previously well working ofono setup:
root@pi:/home/pi# bluealsa -p hfp-ofono
bluealsa: [23060] D: storage.c:84: Initializing persistent storage: /var/lib/bluealsa
bluealsa: [23060] D: main.c:604: Starting main dispatching loop
bluealsa: [23060] D: main.c:114: Acquired D-Bus service name: org.bluealsa
bluealsa: [23060] D: bluealsa-dbus.c:392: Registering D-Bus manager: /org/bluealsa
bluealsa: [23060] D: bluez.c:781: Registering battery provider: /org/bluez/hci0/battery
bluealsa: [23060] D: bluez.c:801: BlueZ battery provider support not available
bluealsa: [23060] D: ofono.c:882: Registering oFono audio agent: /org/bluez/HFP/oFono
bluealsa: [23060] D: ofono.c:620: Adding new oFono card: /card_1
bluealsa: [23060] D: storage.c:117: Loading storage: /var/lib/bluealsa/xx:xx:xx:xx:xx:xx
bluealsa: [23060] D: ofono.c:393: Linking oFono card with modem: /hfp/org/bluez/hci0/dev_xx_xx_xx_xx_xx_xx
bluealsa: [23060] D: ofono.c:457: Updating SCO speaker volume: 7 [-10.99 dB]
bluealsa: [23060] D: ofono.c:477: Updating SCO microphone volume: 7 [-10.99 dB]
bluealsa: [23060] D: ofono.c:437: Updating SCO microphone mute: false
bluealsa: [23060] D: dbus.c:47: Called: org.ofono.HandsfreeAudioAgent.NewConnection() on /org/bluez/HFP/oFono
bluealsa: [23060] D: ofono.c:819: New oFono SCO link (codec: 0x1): 15
bluealsa: [23060] W: hci.c:131: Couldn't get SCO socket options: Transport endpoint is not connected
bluealsa: [23060] D: hci.c:137: SCO link socket MTU: 15: 0
bluealsa: [23060] D: ba-transport.c:1528: Starting transport: HFP Hands-Free (CVSD)
bluealsa: [23060] E: ba-transport.c:438: Invalid BT socket MTU [15]: R:0 W:0
bluealsa: [23060] E: ba-transport.c:438: Invalid BT socket MTU [15]: R:0 W:0
bluealsa: [23060] D: dbus.c:47: Called: org.ofono.HandsfreeAudioAgent.NewConnection() on /org/bluez/HFP/oFono
bluealsa: [23060] D: ofono.c:819: New oFono SCO link (codec: 0x1): 16
bluealsa: [23060] W: hci.c:131: Couldn't get SCO socket options: Transport endpoint is not connected
bluealsa: [23060] D: hci.c:137: SCO link socket MTU: 16: 0
bluealsa: [23060] D: ba-transport.c:1528: Starting transport: HFP Hands-Free (CVSD)
bluealsa: [23060] E: ba-transport.c:438: Invalid BT socket MTU [16]: R:0 W:0
bluealsa: [23060] E: ba-transport.c:438: Invalid BT socket MTU [16]: R:0 W:0
^C
bluealsa: [23060] D: ofono.c:163: Closing oFono SCO link: 16
bluealsa: [23060] D: ba-transport.c:1195: Freeing transport: HFP Hands-Free (CVSD)
bluealsa: [23060] D: storage.c:154: Saving storage: /var/lib/bluealsa/xx:xx:xx:xx:xx:xx
bluealsa: [23060] D: ba-device.c:142: Freeing device: xx:xx:xx:xx:xx:xx
bluealsa: [23060] D: ba-adapter.c:144: Freeing adapter: hci0
root@pi:/home/pi#
are there now minor changes or is this a bug?
Did you configure BlueALSA with --enable-msbc? If so, I think this may be a bug (in one of my patches 😞 ). Comparing ofono SCO connection acceptance with bluealsa native, I see that with --enable-msbc the native code "authorizes" the socket before getting the MTU for both codecs, but the ofono code only does so for mSBC codec. I suspect that would explain the Transport endpoint is not connected error. I'm not able to test this for a few days, but please try changing ofono.c line 805 from:
if (t->profile == BA_TRANSPORT_PROFILE_HFP_HF &&
codec == HFP_CODEC_MSBC) {
to:
if (t->profile == BA_TRANSPORT_PROFILE_HFP_HF) {
no, no --enable-msbc was configured
OK, then there is also some other error in the recent HFP changes. Please can you confirm which BlueALSA commit you were using with your "previously well working ofono setup" and I will try to see what else may have caused this error. If you could possibly do a git bisect to identify the exact commit that introduced this failure that would help speed up the investigation
reflog:
142307d (HEAD -> master, origin/master, origin/HEAD) HEAD@{0}: pull: Fast-forward
6837b54 HEAD@{1}: clone: from https://github.com/arkq/bluez-alsa.git
git show @@{1}..@@{0}
Hmm, it seems that oFono uses BT_DEFER_SETUP on its SCO listen socket, even when mSBC is not supported. That means BlueALSA also has to "authorize" the accepted socket even when mSBC is not supported. That was my mistake - the original code did that, and my patchset removed it. I'll pepare a PR with a fix. In the meantime, please could you try this patch for me:
EDIT
This patch is wrong - see next comment
diff --git a/src/ofono.c b/src/ofono.c
index c5dbb10..3e29f03 100644
--- a/src/ofono.c
+++ b/src/ofono.c
@@ -20,6 +20,7 @@
/* IWYU pragma: no_include "config.h" */
#include <errno.h>
+#include <poll.h>
#include <pthread.h>
#include <stdbool.h>
#include <stdint.h>
@@ -802,11 +803,18 @@ static void ofono_agent_new_connection(GDBusMethodInvocation *inv, void *userdat
}
/* For HF, oFono does not authorize after setting the voice option, so we
- * have to do it ourselves here. */
- if (t->profile == BA_TRANSPORT_PROFILE_HFP_HF &&
- codec == HFP_CODEC_MSBC) {
+ * may have to do it ourselves here. oFono always tries to set the
+ * BT_DEFER_SETUP option, but may not always succeed. So we must first
+ * check if the socket is in defered setup state before authorizing. */
+ if (t->profile == BA_TRANSPORT_PROFILE_HFP_HF) {
+ /* If socket is not writable, it means that it is in the defer setup
+ * state, so it needs to be read to authorize the connection. */
+ struct pollfd pfd = { fd, POLLOUT, 0 };
uint8_t auth;
- if (read(fd, &auth, sizeof(auth)) == -1) {
+
+ if (poll(&pfd, 1, 0) == -1)
+ goto fail;
+ if (!(pfd.revents & POLLOUT) && read(fd, &auth, sizeof(auth)) == -1) {
error("Couldn't authorize oFono SCO link: %s", strerror(errno));
goto fail;
}oops - sorry - I forgot to move that clause out of the #if ENABLE_MSBC block. Try this:
diff --git a/src/ofono.c b/src/ofono.c
index c5dbb10..cc85e9d 100644
--- a/src/ofono.c
+++ b/src/ofono.c
@@ -20,6 +20,7 @@
/* IWYU pragma: no_include "config.h" */
#include <errno.h>
+#include <poll.h>
#include <pthread.h>
#include <stdbool.h>
#include <stdint.h>
@@ -801,17 +802,25 @@ static void ofono_agent_new_connection(GDBusMethodInvocation *inv, void *userdat
return;
}
+#endif
+
/* For HF, oFono does not authorize after setting the voice option, so we
- * have to do it ourselves here. */
- if (t->profile == BA_TRANSPORT_PROFILE_HFP_HF &&
- codec == HFP_CODEC_MSBC) {
+ * may have to do it ourselves here. oFono always tries to set the
+ * BT_DEFER_SETUP option, but may not always succeed. So we must first
+ * check if the socket is in defered setup state before authorizing. */
+ if (t->profile == BA_TRANSPORT_PROFILE_HFP_HF) {
+ /* If socket is not writable, it means that it is in the defer setup
+ * state, so it needs to be read to authorize the connection. */
+ struct pollfd pfd = { fd, POLLOUT, 0 };
uint8_t auth;
- if (read(fd, &auth, sizeof(auth)) == -1) {
+
+ if (poll(&pfd, 1, 0) == -1)
+ goto fail;
+ if (!(pfd.revents & POLLOUT) && read(fd, &auth, sizeof(auth)) == -1) {
error("Couldn't authorize oFono SCO link: %s", strerror(errno));
goto fail;
}
}
-#endif
ba_transport_stop(t);root@pi:/home/pi/bluez-alsa# bluealsa -p hfp-ofono
bluealsa: [91077] D: storage.c:84: Initializing persistent storage: /var/lib/bluealsa
bluealsa: [91077] D: main.c:604: Starting main dispatching loop
bluealsa: [91077] D: main.c:114: Acquired D-Bus service name: org.bluealsa
bluealsa: [91077] D: bluealsa-dbus.c:392: Registering D-Bus manager: /org/bluealsa
bluealsa: [91077] D: bluez.c:781: Registering battery provider: /org/bluez/hci0/battery
bluealsa: [91077] D: bluez.c:801: BlueZ battery provider support not available
bluealsa: [91077] D: ofono.c:891: Registering oFono audio agent: /org/bluez/HFP/oFono
bluealsa: [91077] D: ofono.c:621: Adding new oFono card: /card_1
bluealsa: [91077] D: storage.c:117: Loading storage: /var/lib/bluealsa/xx:xx:xx:xx:xx:xx
bluealsa: [91077] D: ofono.c:394: Linking oFono card with modem: /hfp/org/bluez/hci0/dev_xx_xx_xx_xx_xx_xx
bluealsa: [91077] D: ofono.c:458: Updating SCO speaker volume: 7 [-10.99 dB]
bluealsa: [91077] D: ofono.c:478: Updating SCO microphone volume: 7 [-10.99 dB]
bluealsa: [91077] D: ofono.c:438: Updating SCO microphone mute: false
bluealsa: [91077] D: dbus.c:47: Called: org.ofono.HandsfreeAudioAgent.NewConnection() on /org/bluez/HFP/oFono
bluealsa: [91077] D: ofono.c:828: New oFono SCO link (codec: 0x1): 15
bluealsa: [91077] D: hci.c:137: SCO link socket MTU: 15: 64
bluealsa: [91077] D: ba-transport.c:1528: Starting transport: HFP Hands-Free (CVSD)
bluealsa: [91077] D: ba-transport.c:448: Created BT socket duplicate: [15]: 16
bluealsa: [91077] D: ba-transport.c:1949: Created new IO thread [ba-sco-dec]: HFP Hands-Free (CVSD)
bluealsa: [91077] D: ba-transport.c:448: Created BT socket duplicate: [15]: 17
bluealsa: [91077] D: ba-transport.c:1949: Created new IO thread [ba-sco-enc]: HFP Hands-Free (CVSD)
bluealsa: [91307] D: sco.c:245: IO loop: START: sco_cvsd_enc_thread: HFP Hands-Free (CVSD)
bluealsa: [91306] D: sco.c:319: IO loop: START: sco_cvsd_dec_thread: HFP Hands-Free (CVSD)
bluealsa: [91323] D: dbus.c:47: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_xx_xx_xx_xx_xx_xx/hfphf/source
bluealsa: [91077] D: ba-transport.c:1822: PCM resume: 18
bluealsa: [91323] D: dbus.c:47: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_xx_xx_xx_xx_xx_xx/hfphf/source
bluealsa: [91323] D: dbus.c:47: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_xx_xx_xx_xx_xx_xx/hfphf/sink
bluealsa: [91323] D: dbus.c:47: Called: org.bluealsa.PCM1.Open() on /org/bluealsa/hci0/dev_xx_xx_xx_xx_xx_xx/hfphf/sink
bluealsa: [91077] D: ba-transport.c:1822: PCM resume: 14
bluealsa: [91306] D: io.c:46: BT socket disconnected: Connection reset by peer
bluealsa: [91306] D: ba-transport.c:462: Closing BT socket duplicate [15]: 16
bluealsa: [91306] D: sco.c:356: IO loop: EXIT: sco_cvsd_dec_thread: HFP Hands-Free (CVSD)
bluealsa: [91306] D: ofono.c:164: Closing oFono SCO link: 15
bluealsa: [91306] D: ba-transport.c:1983: Exiting IO thread [ba-sco-dec]: HFP Hands-Free (CVSD)
bluealsa: [91307] E: sco.c:273: BT write error: Broken pipe
bluealsa: [91307] D: sco.c:292: IO loop: EXIT: sco_cvsd_enc_thread: HFP Hands-Free (CVSD)
bluealsa: [91307] D: ba-transport.c:462: Closing BT socket duplicate [-1]: 17
bluealsa: [91307] D: ba-transport.c:1983: Exiting IO thread [ba-sco-enc]: HFP Hands-Free (CVSD)
bluealsa: [91077] D: ba-transport.c:1891: Closing PCM: 18
bluealsa: [91081] D: ba-transport.c:610: PCM clients check keep-alive: 0 ms
bluealsa: [91077] D: ba-transport.c:1866: PCM drop: 14
bluealsa: [91077] D: io.c:171: Flushed PCM samples [14]: 1504
bluealsa: [91077] D: ba-transport.c:1891: Closing PCM: 14
bluealsa: [91081] D: ba-transport.c:610: PCM clients check keep-alive: 0 ms
^Cbluealsa: [91077] D: ba-transport.c:1195: Freeing transport: HFP Hands-Free (CVSD)
bluealsa: [91077] D: storage.c:154: Saving storage: /var/lib/bluealsa/xx:xx:xx:xx:xx:xx
bluealsa: [91077] D: ba-device.c:142: Freeing device: xx:xx:xx:xx:xx:xx
bluealsa: [91077] D: ba-adapter.c:144: Freeing adapter: hci0
I'm not sure how to read the above log. It seems the Transport endpoint is not connected error is now fixed. A 'phone successfully connects and opens a HFP audio connection. Some ALSA client(s) opens the bluealsa SCO device for both playback and capture (twice, but that should not be a problem). Then the 'phone closes the audio connection. and finally the 'phone disconnects. Is that expected (it seems OK), or was there a problem?
yes - it seems to be working again - as you discribed, thank you
That's great. I'll set up my own system to test it later next week, just to be sure, then I'll raise a PR to get this into master branch. Many thanks for taking time with this, and my apologies for not finding this error before raising the original PR.
oh - the duplication is not clear how it occurs I'll check it again later