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

ofono not working anymore #640

Closed
dr-ni opened this issue Jun 10, 2023 · 11 comments · Fixed by #642
Closed

ofono not working anymore #640

dr-ni opened this issue Jun 10, 2023 · 11 comments · Fixed by #642

Comments

@dr-ni
Copy link

dr-ni commented Jun 10, 2023

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?

@borine
Copy link
Collaborator

borine commented Jun 10, 2023

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) {

@dr-ni
Copy link
Author

dr-ni commented Jun 10, 2023

no, no --enable-msbc was configured

@borine
Copy link
Collaborator

borine commented Jun 10, 2023

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

@dr-ni
Copy link
Author

dr-ni commented Jun 10, 2023

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}

chg.txt

@borine
Copy link
Collaborator

borine commented Jun 10, 2023

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;
 		}

@borine
Copy link
Collaborator

borine commented Jun 10, 2023

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);

@dr-ni
Copy link
Author

dr-ni commented Jun 10, 2023

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

@borine
Copy link
Collaborator

borine commented Jun 10, 2023

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?

@dr-ni
Copy link
Author

dr-ni commented Jun 10, 2023

yes - it seems to be working again - as you discribed, thank you

@borine
Copy link
Collaborator

borine commented Jun 10, 2023

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.

@dr-ni
Copy link
Author

dr-ni commented Jun 10, 2023

oh - the duplication is not clear how it occurs I'll check it again later

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

Successfully merging a pull request may close this issue.

2 participants