bluez-ofono-pulseaudio HFP connection has two problems

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 

Hi everyone,

We would like to develop an bluetooth-media application (A2DP+HFP) using bluez-ofono-pulseaudio. I really would like to get a couple of pointers from the community. I have identified our problems in two categories.
(1)- pulseaudio crashing (2)- ofono getting delays.

(background)
We use iMX8 Quad Max Multisensory Enablement Kit, Yocto-Arch Linux compiled distro, We tried bluez-5.41, ofono-1.18, pulseaudio-12.2; but now we upgraded to bluez-5.50, ofono-1.25, pulseaudio-12.2. We are using CSR v4.0 bluetooth dongle with vendor ID 0a12, which gives Class 0x2c0000 when HFP is connected.
Another important note on our side is that we are unable to use pulseaudio in system mode, because it is giving problems regarding a2dp->hfp switching. Also we have made the following changes to our pulseaudio configuration /etc/pulse/default.pa, having commented ones uncommented did not help us:

#load-module module-switch-on-port-available
#load-module module-switch-on-connect
load-module module-bluetooth-policy ag=true
load-module module-bluetooth-discover headset=auto
set-default-sink alsa_output.platform-sound-hdmi.stereo-fallback

We start our daemons with the following command (because we use wayland, x11 does not work, so pulseaudio complains about not having DBUS_SESSION_BUS_ADDRESS, when in session mode):

export DBUS_SESSION_BUS_ADDRESS=unix:path=/run/dbus/system_bus_socket && export DBUS_SESSION_BUS_PID=$(cat /run/dbus/pid) && {
        /usr/libexec/bluetooth/bluetoothd  -d -n  2>&1 | tee /opt/onyx-a2dp-hfp/bluetooth.log &
        /usr/sbin/ofonod -d -n 2>&1 | tee /opt/onyx-a2dp-hfp/ofono.log &
        /usr/libexec/bluetooth/obexd -d -n 2>&1 | tee /opt/onyx-a2dp-hfp/obex.log &
        pulseaudio --realtime 2>&1 | tee /opt/onyx-a2dp-hfp/pulse.log &
}

We have tried using system.d services, which did not make a difference for us. But there might be something we are missing here.

After switching from bluez-5.41 to 5.50, we started getting following AccessDenied error, but having this error, we were still able to accomplish a proper A2DP+HFP experience until aforementioned errors. I think this is not due to the configuration file, since we basically have every permission dbus needs on /etc/dbus-1/system.conf.

method return time=1539068262.046519 sender=:1.26 -> destination=:1.23 serial=21 reply_serial=114
error time=1539068262.046600 sender=org.freedesktop.DBus -> destination=:1.26 error_name=org.freedesktop.DBus.Error.AccessDenied reply_serial=21
   string "Rejected send message, 1 matched rules; type="method_return", sender=":1.26" (uid=0 pid=30830 comm="pulseaudio --realtime ") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.23" (uid=0 pid=30827 comm="/usr/sbin/ofonod -d -n ")"


 We were able to accomplish A2DP+HFP connection using bluez-ofono-pulseaudio, but we are having the aforementioned two problems.

(1)
Concerning the first one, it randomly happens while using ofono, we get a new card connection (as in org.ofono.HandsfreeAudioAgentNewConnection) after some time, for some reason, and then due to a non-existing file descriptor, connection breaks, sometimes even bluetooth gets disconnected. We get the following on dbus-monitor:

method call time=1539347485.416982 sender=:1.14 -> destination=:1.18 serial=72 path=/HandsfreeAudioAgent; interface=org.ofono.HandsfreeAudioAgent; member=NewConnection
   object path "/card_1"
   file descriptor
         inode: 18312
         type: socket
         address family: bluetooth
   byte 1


followed by

   string "Rejected send message, 1 matched rules; type="error", sender=":1.22" (uid=0 pid=758 comm="/usr/bin/pulseaudio --start --log-target=syslog ") interface="(unset)" member="(unset)" error name="org.ofono.Error.InvalidArguments" requested_reply="0" destination=":1.15" (uid=0 pid=5482 comm="/usr/sbin/ofonod -d -n ")"

On pulseaudio log, we get:

E: [bluetooth] module-bluez5-device.c: Failed to read data from SCO socket: Connection reset by peer
W: [pulseaudio] backend-ofono.c: New audio connection invalid arguments (path=/card_1 fd=18, codec=1)
W: [pulseaudio] backend-ofono.c: New audio connection invalid arguments (path=/card_1 fd=18, codec=1)
W: [pulseaudio] backend-ofono.c: New audio connection invalid arguments (path=/card_1 fd=18, codec=1)


All these results in the following in the kernel (dmesg):

[  444.715333] Bluetooth: hci0 SCO packet for unknown connection handle 65


I have included extra debugging information in backend-ofono.c in pulseaudio in order to trace the problem and found out that,   card->fd >= 0 fails in the following, which is from hf_audio_agent_new_connection function:

if (!card || codec != HFP_AUDIO_CODEC_CVSD || card->fd >= 0) {
pa_log_warn("New audio connection invalid arguments (path=%s fd=%d, codec=%d)", path, fd, codec);
pa_assert_se(r = dbus_message_new_error(m, "org.ofono.Error.InvalidArguments", "Invalid arguments in method call"));
shutdown(fd, SHUT_RDWR);
close(fd);
return r;
}

But I think that this might be due to a configuration problem in my pulseaudio, not able to set up a new connection with ofono. Also there is a question why we suddenly get disconnection and new connection is created. (To this case, I think it might be due to our USB bluetooth dongle CSR v4.0, but this alsa happened to us a few times before on a HP Pavillion laptop with Ubuntu 16.04 -suddenly problem vanished by itself). I dont know if it's related to our specific dongle, but we get the following a lot of times in ofono logs:

ofonod[20146]: ../ofono-1.25/plugins/udevng.c:add_serial_device() Device is missing required OFONO_DRIVER property

We would like to ask if  you could help us regarding how to trace and find the root cause of this problem.

(2)
Concerning our second problem, we have less clues unfortunately. Second problem is ofono slowing down (that is, getting state changes late, sometimes not even receives any state changes). We monitor state changes from `dbus-monitor --system` and we can see that it is not related to our prototype client application at all, rather ofono really gets slow downs. It is not necessarily tied with (1), but usually ofono starts slowing down first, then sometimes issue nr. (1) happens.

The following log is our biggest lead for this particular problem (dbus-monitor --system):

method call time=1539757315.572547 sender=:1.5 -> destination=org.freedesktop.DBus serial=212 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
   string "type='signal',sender='org.bluez',path='/org/bluez/hci0/dev_60_F6_77_FD_C4_23',interface='org.freedesktop.DBus.Properties',member='PropertiesChanged',arg0='org.bluez.Device1'"
method return time=1539757315.572596 sender=org.freedesktop.DBus -> destination=:1.5 serial=138 reply_serial=212
method call time=1539757315.572898 sender=:1.25 -> destination=org.freedesktop.DBus serial=158 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
   string "type='signal',sender='org.bluez',path='/org/bluez/hci0/dev_60_F6_77_FD_C4_23',interface='org.freedesktop.DBus.Properties',member='PropertiesChanged',arg0='org.bluez.Device1'"
method return time=1539757315.572958 sender=org.freedesktop.DBus -> destination=:1.25 serial=47 reply_serial=158
method call time=1539757315.579855 sender=:1.33 -> destination=org.freedesktop.DBus serial=427 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
   string "type='signal',sender='org.bluez',path='/org/bluez/hci0/dev_60_F6_77_FD_C4_23',interface='org.freedesktop.DBus.Properties',member='PropertiesChanged'"
signal time=1539757315.585969 sender=:1.24 -> destination=(null destination) serial=401 path=/; interface=org.freedesktop.DBus.ObjectManager; member=InterfacesRemoved
   object path "/org/bluez/hci0/dev_E4_46_DA_7B_A9_21"
   array [
      string "org.freedesktop.DBus.Properties"
      string "org.freedesktop.DBus.Introspectable"
      string "org.bluez.Device1"
   ]
method call time=1539757315.586967 sender=:1.5 -> destination=org.freedesktop.DBus serial=213 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
   string "type='signal',sender='org.bluez',path='/org/bluez/hci0/dev_E4_46_DA_7B_A9_21',interface='org.freedesktop.DBus.Properties',member='PropertiesChanged',arg0='org.bluez.Device1'"
method return time=1539757315.587040 sender=org.freedesktop.DBus -> destination=:1.5 serial=139 reply_serial=213
method call time=1539757315.587624 sender=:1.25 -> destination=org.freedesktop.DBus serial=159 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
   string "type='signal',sender='org.bluez',path='/org/bluez/hci0/dev_E4_46_DA_7B_A9_21',interface='org.freedesktop.DBus.Properties',member='PropertiesChanged',arg0='org.bluez.Device1'"
method return time=1539757315.587690 sender=org.freedesktop.DBus -> destination=:1.25 serial=48 reply_serial=159
signal time=1539757315.588726 sender=:1.24 -> destination=(null destination) serial=402 path=/; interface=org.freedesktop.DBus.ObjectManager; member=InterfacesRemoved
   object path "/org/bluez/hci0/dev_67_21_84_5A_E0_FF"
   array [
      string "org.freedesktop.DBus.Properties"
      string "org.freedesktop.DBus.Introspectable"
      string "org.bluez.Device1"
   ]
method call time=1539757315.589350 sender=:1.5 -> destination=org.freedesktop.DBus serial=214 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
   string "type='signal',sender='org.bluez',path='/org/bluez/hci0/dev_67_21_84_5A_E0_FF',interface='org.freedesktop.DBus.Properties',member='PropertiesChanged',arg0='org.bluez.Device1'"
method return time=1539757315.589387 sender=org.freedesktop.DBus -> destination=:1.5 serial=140 reply_serial=214
method call time=1539757315.589668 sender=:1.25 -> destination=org.freedesktop.DBus serial=160 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
   string "type='signal',sender='org.bluez',path='/org/bluez/hci0/dev_67_21_84_5A_E0_FF',interface='org.freedesktop.DBus.Properties',member='PropertiesChanged',arg0='org.bluez.Device1'"
method return time=1539757315.589713 sender=org.freedesktop.DBus -> destination=:1.25 serial=49 reply_serial=160
method call time=1539757315.595363 sender=:1.33 -> destination=org.freedesktop.DBus serial=428 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
   string "type='signal',sender='org.bluez',path='/org/bluez/hci0/dev_E4_46_DA_7B_A9_21',interface='org.freedesktop.DBus.Properties',member='PropertiesChanged'"
method call time=1539757315.595561 sender=:1.33 -> destination=org.freedesktop.DBus serial=429 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
   string "type='signal',sender='org.bluez',path='/org/bluez/hci0/dev_67_21_84_5A_E0_FF',interface='org.freedesktop.DBus.Properties',member='PropertiesChanged'"
signal time=1539757315.602966 sender=:1.24 -> destination=(null destination) serial=403 path=/; interface=org.freedesktop.DBus.ObjectManager; member=InterfacesRemoved
   object path "/org/bluez/hci0/dev_EA_E2_9A_7F_BB_76"
   array [
      string "org.freedesktop.DBus.Properties"
      string "org.freedesktop.DBus.Introspectable"
      string "org.bluez.Device1"
   ]
signal time=1539757315.604608 sender=:1.24 -> destination=(null destination) serial=404 path=/; interface=org.freedesktop.DBus.ObjectManager; member=InterfacesRemoved
   object path "/org/bluez/hci0/dev_61_27_A5_DC_DD_C3"
   array [
      string "org.freedesktop.DBus.Properties"
      string "org.freedesktop.DBus.Introspectable"
      string "org.bluez.Device1"
   ]
method call time=1539757315.604995 sender=:1.5 -> destination=org.freedesktop.DBus serial=215 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
   string "type='signal',sender='org.bluez',path='/org/bluez/hci0/dev_EA_E2_9A_7F_BB_76',interface='org.freedesktop.DBus.Properties',member='PropertiesChanged',arg0='org.bluez.Device1'"
method return time=1539757315.605035 sender=org.freedesktop.DBus -> destination=:1.5 serial=141 reply_serial=215
method call time=1539757315.605622 sender=:1.25 -> destination=org.freedesktop.DBus serial=161 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
   string "type='signal',sender='org.bluez',path='/org/bluez/hci0/dev_EA_E2_9A_7F_BB_76',interface='org.freedesktop.DBus.Properties',member='PropertiesChanged',arg0='org.bluez.Device1'"
method return time=1539757315.605674 sender=org.freedesktop.DBus -> destination=:1.25 serial=50 reply_serial=161
method call time=1539757315.605990 sender=:1.25 -> destination=org.freedesktop.DBus serial=162 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
   string "type='signal',sender='org.bluez',path='/org/bluez/hci0/dev_61_27_A5_DC_DD_C3',interface='org.freedesktop.DBus.Properties',member='PropertiesChanged',arg0='org.bluez.Device1'"
method return time=1539757315.606042 sender=org.freedesktop.DBus -> destination=:1.25 serial=51 reply_serial=162
method call time=1539757315.607927 sender=:1.5 -> destination=org.freedesktop.DBus serial=216 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
   string "type='signal',sender='org.bluez',path='/org/bluez/hci0/dev_61_27_A5_DC_DD_C3',interface='org.freedesktop.DBus.Properties',member='PropertiesChanged',arg0='org.bluez.Device1'"
method return time=1539757315.607984 sender=org.freedesktop.DBus -> destination=:1.5 serial=142 reply_serial=216
method call time=1539757315.611658 sender=:1.33 -> destination=org.freedesktop.DBus serial=430 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
   string "type='signal',sender='org.bluez',path='/org/bluez/hci0/dev_EA_E2_9A_7F_BB_76',interface='org.freedesktop.DBus.Properties',member='PropertiesChanged'"
method call time=1539757315.611985 sender=:1.33 -> destination=org.freedesktop.DBus serial=431 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
   string "type='signal',sender='org.bluez',path='/org/bluez/hci0/dev_61_27_A5_DC_DD_C3',interface='org.freedesktop.DBus.Properties',member='PropertiesChanged'"

Bluetooth or ofono somehow starts to change properties of a lot of the modems it finds, which causes a huge delay (I'm guessing), and if you keep sending commands, the connection breaks (maybe this is what triggers issue nr. (1)). Maybe ofono uses org.freedesktop.DBus.Properties a lot, which causes a delay when other applications also use it.

The following is the log, when the ofono starts slowing down leading to a disconnection:
...
ofonod[1006]: ../ofono-1.25/src/voicecall.c:ofono_voicecall_disconnected() Got disconnection event for id: 1, reason: 2
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_remove() Removing device /org/bluez/hci0/dev_51_88_89_85_40_56
bluetoothd[1004]: ../bluez-5.50/src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_51_88_89_85_40_56
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_free() 0x2a82f800
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_remove() Removing device /org/bluez/hci0/dev_43_42_41_9B_8D_B2
bluetoothd[1004]: ../bluez-5.50/src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_43_42_41_9B_8D_B2
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_free() 0x2a837ee0
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_remove() Removing device /org/bluez/hci0/dev_40_A3_CC_A5_61_2A
bluetoothd[1004]: ../bluez-5.50/src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_40_A3_CC_A5_61_2A
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_free() 0x2a832350
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_remove() Removing device /org/bluez/hci0/dev_61_AF_F1_3D_B5_89
bluetoothd[1004]: ../bluez-5.50/src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_61_AF_F1_3D_B5_89
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_free() 0x2a83dc00
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_remove() Removing device /org/bluez/hci0/dev_5C_03_39_B5_1A_60
bluetoothd[1004]: ../bluez-5.50/src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_5C_03_39_B5_1A_60
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_free() 0x2a83f690
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_remove() Removing device /org/bluez/hci0/dev_D8_63_75_A1_3D_14
bluetoothd[1004]: ../bluez-5.50/src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_D8_63_75_A1_3D_14
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_free() 0x2a83a400
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_remove() Removing device /org/bluez/hci0/dev_79_AC_39_07_DE_A7
bluetoothd[1004]: ../bluez-5.50/src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_79_AC_39_07_DE_A7
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_free() 0x2a83f9a0
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_remove() Removing device /org/bluez/hci0/dev_60_F6_77_FD_C4_23
bluetoothd[1004]: ../bluez-5.50/src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_60_F6_77_FD_C4_23
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_free() 0x2a838e40
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_remove() Removing device /org/bluez/hci0/dev_E4_46_DA_7B_A9_21
bluetoothd[1004]: ../bluez-5.50/src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_E4_46_DA_7B_A9_21
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_free() 0x2a83c3a0
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_remove() Removing device /org/bluez/hci0/dev_67_21_84_5A_E0_FF
bluetoothd[1004]: ../bluez-5.50/src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_67_21_84_5A_E0_FF
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_free() 0x2a847650
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_remove() Removing device /org/bluez/hci0/dev_EA_E2_9A_7F_BB_76
bluetoothd[1004]: ../bluez-5.50/src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_EA_E2_9A_7F_BB_76
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_free() 0x2a831e60
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_remove() Removing device /org/bluez/hci0/dev_61_27_A5_DC_DD_C3
bluetoothd[1004]: ../bluez-5.50/src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_61_27_A5_DC_DD_C3
bluetoothd[1004]: ../bluez-5.50/src/device.c:device_free() 0x2a848690
bluetoothd[1004]: ../bluez-5.50/profiles/audio/avctp.c:req_timeout() transaction 8 retry true
bluetoothd[1004]: ../bluez-5.50/profiles/audio/avctp.c:req_timeout() transaction 8 retry false
W: [bluetooth] module-bluez5-device.c: SCO packet received of unaligned size: 9
ofonod[1006]: ../ofono-1.25/src/handsfree-audio.c:sco_accept() SCO connection setup between local: 00:1A:7D:DA:71:15 and remote: D8:5B:2A:5B:7B:E6
ofonod[1006]: ../ofono-1.25/src/handsfree-audio.c:send_new_connection() 0x1d127f70, fd: 10, codec: 1
W: [pulseaudio] backend-ofono.c: debug: (path=/card_1 fd=17, codec=1)
ofonod[1006]: ../ofono-1.25/src/voicecall.c:ofono_voicecall_mpty_hint() ids: 0

followed by the following in the kernel:

[ 3491.850928] Bluetooth: hci0 SCO packet for unknown connection handle 47104
[ 3491.850931] Bluetooth: hci0 SCO packet for unknown connection handle 0
[ 3491.850934] Bluetooth: hci0 SCO packet for unknown connection handle 0
[ 3491.850937] Bluetooth: hci0 SCO packet for unknown connection handle 14336
[ 3491.850941] Bluetooth: hci0 SCO packet for unknown connection handle 3072
[ 3491.850943] Bluetooth: hci0 SCO packet for unknown connection handle 0
[ 3491.850947] Bluetooth: hci0 SCO packet for unknown connection handle 0

 I've asked the question on many different forums, but the question gets clearer every step of the way.  So, I hope I could make it more clear than before.

If you could help us, I'd really appreciate it.

Thank you very much in advance.
_______________________________________________
pulseaudio-discuss mailing list
pulseaudio-discuss@xxxxxxxxxxxxxxxxxxxxx
https://lists.freedesktop.org/mailman/listinfo/pulseaudio-discuss
[Index of Archives]     [Linux Audio Users]     [AMD Graphics]     [Linux USB Devel]     [Linux Audio Users]     [Yosemite News]     [Linux Kernel]     [Linux SCSI]

  Powered by Linux