Bug 1177850 - When moving out of Bluetooth range, fails to reconnect, until after rebooting system
Summary: When moving out of Bluetooth range, fails to reconnect, until after rebooting...
Status: NEW
Alias: None
Product: openSUSE Tumbleweed
Classification: openSUSE
Component: Basesystem (show other bugs)
Version: Current
Hardware: x86-64 openSUSE Tumbleweed
: P5 - None : Normal (vote)
Target Milestone: ---
Assignee: Vasilis Liaskovitis
QA Contact: E-mail List
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2020-10-18 21:26 UTC by John Langham-Service
Modified: 2021-03-10 10:30 UTC (History)
1 user (show)

See Also:
Found By: ---
Services Priority:
Business Priority:
Blocker: ---
Marketing QA Status: ---
IT Deployment: ---


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description John Langham-Service 2020-10-18 21:26:49 UTC
Random occurance with different headsets.
I move out of range and the headset disconnects as expected 75%ish of the time it reconnects with no issues.
The rest of the time it disconnects but fails to reconnect, turning headset on and off doesnt reconnect. 
Clicking Connect for the headset in the plasma widget doesnt do anything.
Turning bluetooth off via widget and can't turn back on.
Only way to get Bluetooth back working is to reboot the system.

Systemd journal filtered for bluetooth


src/profile.c:ext_io_disconnected() Unable to get io data for Headset Voice gateway: getpeername: Transport endpoint is not connected (107)

[system] Rejected send message, 0 matched rules; type="method_return", sender=":1.45" (uid=1000 pid=1860 comm="/usr/bin/pulseaudio --daemonize=no ") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.2" (uid=0 pid=1099 comm="/usr/libexec/bluetooth/bluetoothd ")

Bluetooth: hci0: command 0x0405 tx timeout

src/profile.c:record_cb() Unable to get Headset Voice gateway SDP record: Connection timed out

Bluetooth: hci0: command 0x0408 tx timeout

profiles/audio/avdtp.c:avdtp_connect_cb() connect to B8:AD:3E:0A:09:25: Connection refused (111)

Bluetooth: hci0: command 0x0408 tx timeout

Bluetooth: hci0: command 0x0405 tx timeout

profiles/audio/avdtp.c:avdtp_connect_cb() connect to B8:AD:3E:0A:09:25: Connection refused (111)

src/profile.c:record_cb() Unable to get Headset Voice gateway SDP record: Connection timed out

Bluetooth: hci0: No way to reset. Ignoring and continuing

src/profile.c:record_cb() Unable to get Headset Voice gateway SDP record: Connection timed out

Bluetooth: hci0: command 0x0408 tx timeout

Bluetooth: hci0: No way to reset. Ignoring and continuing

kf.bluezqt: PendingCall Error: "Did not receive a reply. Possible causes include: the remote application did not send a reply, the message bus security policy blocked the reply, the reply timeout expired, or the network connection was broken."


Bluetooth: hci0: command 0x0408 tx timeout
Bluetooth: hci0: No way to reset. Ignoring and continuing
Comment 1 Vasilis Liaskovitis 2021-03-09 11:43:43 UTC
I can reproduce the dbus error by turning Bluetooth off while a headset is connected. Using "dbus-monitor --system" I can observe a few more relevant messages. 

When we disconnect the device, bluez calls the ClearConfiguration method on pulseaudio's MediaEndpoint (a useful diagram can be found here http://www.lightofdawn.org/wiki/wiki.cgi/BluezA2DP). This "method_call" message is seen in the dbus logs:

method call time=1615053161.594648 sender=:1.2 -> destination=:1.58 serial=50625 path=/MediaEndpoint/A2DPSource/sbc; interface=org.bluez.MediaEndpoint1; member=ClearConfiguration
   object path "/org/bluez/hci0/dev_00_00_AB_CD_A8_81/sep1/fd14"

pulseaudio sends a reply/ack back to bluez (a "method_return" message). However bluez has not requested a reply for CLearConfiguration(), see requested_reply="0" below. The bus posts an error for this unexpected method_return message. 

method return time=1615053161.596494 sender=:1.58 -> destination=:1.2 serial=110 reply_serial=50625
error time=1615053161.596499 sender=org.freedesktop.DBus -> destination=:1.58 error_name=org.freedesktop.DBus.Error.AccessDenied reply_serial=110
   string "Rejected send message, 0 matched rules; type="method_return", sender=":1.58" (uid=1000 pid=2490 comm="/usr/bin/pulseaudio --daemonize=no ") interface="(unset)" member="(unset)" error name="(unset)" requested_reply="0" destination=":1.2" (uid=0 pid=1009 comm="/usr/libexec/bluetooth/bluetoothd ")"

Sending replies when not requested on the system bus causes such errors, as the bus does not let unexpected replies through.

There is already a recent pulseaudio commit that makes pulseaudio not reply to CLearConfiguration (or more specifically reply only if the sender requested a reply):

From ac8f0c2070d04fb2b4a53bc642129b026bf139a7 Mon Sep 17 00:00:00 2001
From: Marijn Suijten <marijns95@gmail.com>
Date: Wed, 13 Jan 2021 14:23:54 +0100
Subject: [PATCH] bluetooth/bluez5-util: Do not reply to ClearConfiguration

Applying this patch, makes the dbus rejected error go away. It also makes my Bluetooth more reliable. Turning off and on again before applying the patch didn't always reconnect; now it has reconnected in all tests. Perhaps there is some logic in bluez or pulseaudio affected by the rejected error.
 
However, I am not sure this issue is the actual root cause for your problem. I have not tested the "out-of-range" scenario, and I have not seen the "tx timeout" and "connection refused" bluez messages. I will post a patched pulseaudio package for you to try.

In any case, I will make a merge request for the above patch to be included, as it is good to remove this error message.
Comment 2 Vasilis Liaskovitis 2021-03-10 10:30:10 UTC
pulseaudio package with the patch can be found here:

https://download.opensuse.org/repositories/home:/vliaskovitis:/branches:/multimedia:/libs/openSUSE_Tumbleweed/x86_64/