[pulseaudio-discuss] bluez-ofono-pulseaudio HFP connection has two problems
Mustafa Özçelikörs
mustafa.ozcelikors at redpine.com.tr
Wed Oct 17 06:53:40 UTC 2018
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.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/pulseaudio-discuss/attachments/20181017/741a3e87/attachment-0001.html>
More information about the pulseaudio-discuss
mailing list