FS#72540 - Bluetooth disconnects from dbus after suspend, causing bluetoothd to stop

Attached to Project: Arch Linux
Opened by Gideon Farrell (gtf21) - Monday, 25 October 2021, 13:26 GMT
Last edited by Andreas Radke (AndyRTR) - Saturday, 19 February 2022, 20:03 GMT
Task Type Bug Report
Category Kernel
Status Closed
Assigned To Andreas Radke (AndyRTR)
Jan Alexander Steffens (heftig)
Architecture x86_64
Severity Medium
Priority Normal
Reported Version
Due in Version Undecided
Due Date Undecided
Percent Complete 100%
Votes 2
Private No

Details

Description:

On wake from suspend, bluetoothctl / bluez no longer works. Requires the service to be restarted. See logs, 100% reproducible.


Additional info:

Kernel: 5.14.14
Output of `pacman -Qs bluetooth`:
local/blueman 2.2.2-1
local/bluez 5.62-1
local/bluez-libs 5.62-1
local/bluez-utils 5.62-1
local/hidapi 0.11.0-1
local/libldac 2.0.2.3-1
local/pulseaudio-bluetooth 15.0-1
local/sbc 1.5-2

Log file output:

Oct 23 14:59:01 anaximander systemd[1]: Starting Bluetooth service...
Oct 23 14:59:01 anaximander bluetoothd[639]: Bluetooth daemon 5.62
Oct 23 14:59:01 anaximander systemd[1]: Started Bluetooth service.
Oct 23 14:59:01 anaximander bluetoothd[639]: Starting SDP server
Oct 23 14:59:01 anaximander bluetoothd[639]: Bluetooth management interface 1.21 initialized
Oct 23 15:00:06 anaximander bluetoothd[639]: Endpoint registered: sender=:1.42 path=/MediaEndpoint/A2DPSink/sbc
Oct 23 15:00:06 anaximander bluetoothd[639]: Endpoint registered: sender=:1.42 path=/MediaEndpoint/A2DPSource/sbc
Oct 23 15:00:06 anaximander bluetoothd[639]: Endpoint registered: sender=:1.42 path=/MediaEndpoint/A2DPSink/sbc_xq_>
Oct 23 15:00:06 anaximander bluetoothd[639]: Endpoint registered: sender=:1.42 path=/MediaEndpoint/A2DPSource/sbc_x>
Oct 23 15:00:06 anaximander bluetoothd[639]: Endpoint registered: sender=:1.42 path=/MediaEndpoint/A2DPSink/sbc_xq_>
Oct 23 15:00:06 anaximander bluetoothd[639]: Endpoint registered: sender=:1.42 path=/MediaEndpoint/A2DPSource/sbc_x>
Oct 23 15:00:06 anaximander bluetoothd[639]: Endpoint registered: sender=:1.42 path=/MediaEndpoint/A2DPSink/sbc_xq_>
Oct 23 15:00:06 anaximander bluetoothd[639]: Endpoint registered: sender=:1.42 path=/MediaEndpoint/A2DPSource/sbc_x>
Oct 23 17:26:24 anaximander bluetoothd[639]: Controller resume with wake event 0x0
Oct 23 20:16:19 anaximander bluetoothd[639]: Authentication attempt without agent
Oct 23 20:16:19 anaximander bluetoothd[639]: src/profile.c:ext_auth() Hands-Free Voice gateway rejected 74:5C:4B:C6>
Oct 23 20:16:21 anaximander bluetoothd[639]: Authentication attempt without agent
Oct 23 20:16:21 anaximander bluetoothd[639]: src/profile.c:ext_auth() Hands-Free Voice gateway rejected 74:5C:4B:C6>
Oct 23 20:16:21 anaximander bluetoothd[639]: Authentication attempt without agent
Oct 23 20:16:21 anaximander bluetoothd[639]: profiles/audio/a2dp.c:auth_cb() Access denied: org.bluez.Error.Rejected
Oct 23 20:16:21 anaximander bluetoothd[639]: Authentication attempt without agent
Oct 23 20:16:21 anaximander bluetoothd[639]: profiles/audio/avctp.c:auth_cb() Access denied: org.bluez.Error.Reject>
Oct 23 20:17:20 anaximander bluetoothd[639]: Authentication attempt without agent
Oct 23 20:17:20 anaximander bluetoothd[639]: src/profile.c:ext_auth() Hands-Free Voice gateway rejected 74:5C:4B:C6>
Oct 23 20:17:21 anaximander bluetoothd[639]: Authentication attempt without agent
Oct 23 20:17:21 anaximander bluetoothd[639]: profiles/audio/a2dp.c:auth_cb() Access denied: org.bluez.Error.Rejected
Oct 23 20:17:21 anaximander bluetoothd[639]: Authentication attempt without agent
Oct 23 20:17:21 anaximander bluetoothd[639]: profiles/audio/avctp.c:auth_cb() Access denied: org.bluez.Error.Reject>
Oct 23 23:08:17 anaximander bluetoothd[639]: Authentication attempt without agent
Oct 23 23:08:17 anaximander bluetoothd[639]: src/profile.c:ext_auth() Hands-Free Voice gateway rejected 74:5C:4B:C6>
Oct 23 23:08:17 anaximander bluetoothd[639]: Authentication attempt without agent
Oct 23 23:08:17 anaximander bluetoothd[639]: profiles/audio/a2dp.c:auth_cb() Access denied: org.bluez.Error.Rejected
Oct 23 23:08:17 anaximander bluetoothd[639]: Authentication attempt without agent
Oct 23 23:08:17 anaximander bluetoothd[639]: profiles/audio/avctp.c:auth_cb() Access denied: org.bluez.Error.Reject>
Oct 24 12:52:48 anaximander bluetoothd[639]: Controller resume with wake event 0x0
Oct 24 18:44:59 anaximander bluetoothd[639]: Controller resume with wake event 0x0
Oct 25 09:27:39 anaximander bluetoothd[639]: Controller resume with wake event 0x0
Oct 25 09:27:53 anaximander bluetoothd[639]: Disconnected from D-Bus. Exiting.
Oct 25 09:27:53 anaximander bluetoothd[639]: Endpoint unregistered: sender=:1.42 path=/MediaEndpoint/A2DPSink/sbc
Oct 25 09:27:53 anaximander bluetoothd[639]: Endpoint unregistered: sender=:1.42 path=/MediaEndpoint/A2DPSource/sbc
Oct 25 09:27:53 anaximander bluetoothd[639]: Endpoint unregistered: sender=:1.42 path=/MediaEndpoint/A2DPSink/sbc_x>
Oct 25 09:27:53 anaximander bluetoothd[639]: Endpoint unregistered: sender=:1.42 path=/MediaEndpoint/A2DPSource/sbc>
Oct 25 09:27:53 anaximander bluetoothd[639]: Endpoint unregistered: sender=:1.42 path=/MediaEndpoint/A2DPSink/sbc_x>
Oct 25 09:27:53 anaximander bluetoothd[639]: Endpoint unregistered: sender=:1.42 path=/MediaEndpoint/A2DPSource/sbc>
Oct 25 09:27:53 anaximander bluetoothd[639]: Endpoint unregistered: sender=:1.42 path=/MediaEndpoint/A2DPSink/sbc_x>
Oct 25 09:27:53 anaximander bluetoothd[639]: Endpoint unregistered: sender=:1.42 path=/MediaEndpoint/A2DPSource/sbc>
Oct 25 09:27:53 anaximander bluetoothd[639]: Stopping SDP server
Oct 25 09:27:53 anaximander bluetoothd[639]: Exit
Oct 25 09:27:53 anaximander systemd[1]: bluetooth.service: Deactivated successfully.
Oct 25 09:27:53 anaximander systemd[1]: bluetooth.service: Consumed 30.594s CPU time.

Steps to reproduce:

1. system starts, `systemctl status bluetooth` should show bluetooth is running
2. close laptop lid to trigger suspend
3. wait for a bit to ensure the system has entered suspend
4. wake the machine, try to use bluetoothctl -- it fails
5. restart bluetooth `systemctl restart bluetooth` -- bluetooth now works
This task depends upon

Closed by  Andreas Radke (AndyRTR)
Saturday, 19 February 2022, 20:03 GMT
Reason for closing:  Fixed
Comment by Andreas Radke (AndyRTR) - Tuesday, 02 November 2021, 18:26 GMT
Does it work with a different or older kernel?
Comment by Gideon Farrell (gtf21) - Wednesday, 17 November 2021, 20:38 GMT
It worked fine on previous kernels (this is a new problem) but I couldn't tell you exactly at which version it stopped working (but I'm pretty sure all of 5.09 - 5.13 were fine). Still happening on 5.14.16 and bluetooth performance is generally appalling -- crashes randomly in the same way as in these logs, but not just related to sleep, and audio quality over bluetooth is massively degraded about 50% of the time.
Comment by Andreas Radke (AndyRTR) - Thursday, 18 November 2021, 13:27 GMT
Please get in touch with upsream bluetooth developers #bluez/OFTC or bluetooth mailing list and search
for existing kernel bluetooth bugs or file a new one:
https://bugzilla.kernel.org/query.cgi (linux-bluetooth or driver-bluetooth)
Comment by nya (nya) - Monday, 17 January 2022, 11:19 GMT
I see the same behaviour, I think related to the update to kernel 5.16.
Comment by Emmanuel (manu0600) - Monday, 31 January 2022, 13:24 GMT
Exact same behaviour on my laptop HP spectre x360 since a recent update
The temporary fix to restart bluetooth with `systemctl restart bluetooth` works, but it's not ideal having to do this, as it was not an issue before.
Comment by Andreas Radke (AndyRTR) - Saturday, 19 February 2022, 16:25 GMT
Is this still an issue with recent kernels and bluez 5.63-2 ?
Comment by Gideon Farrell (gtf21) - Saturday, 19 February 2022, 19:23 GMT
I haven't noticed this happening recently. I'm now on 5.16.9.

Loading...