tl;dr I’m out of ideas/leads - anyone with more bluetooth experience know what I can try to debug? Or anyone more familiar with the journacltl output below maybe can spot something I’m missing?
symptom/what’s apparently wrong
symptom: sometimes when I reboot and log into gnome, I find bluetooth is off and I’m unable to get it on. Now it’s been the last two reboots, so I’m afraid now it’s a long-lasting bug.
Here's some more specific details about this symptom
-
system tray in the top-right corner of the gnome desktop:
- a. click system tray
- b. note: bluetooth off (strange, but okay - maybe a bug already, as it’s usually on automatically?)
- c. expand “bluetooth off” entry
- d. bug: note “turn off” is the current choice; this clearly conflicts with the state read out (the only option for something that is off should be to turn it on)
- click turn off for funsies to see what happens (eg hoping state gets fixed); nothing
-
gnome settings pane for bluetooth:
- a. open gnome settings, click on the “bluetooth pane”
- b. note it’s off and everything here (unlike the tray) agrees with that:
- i) the toggle in the top-right corner is moved to the left (in state off)
- ii) the the pane itself has a bluetooth logo and says “Bluetooth Turned Off” and has the explainer “Turn on to connect devices…”
- c. click toggle in top-right corner to turn on
- d. bug: note nothing changes; pane contents still match 2.b.ii; strangely the toggle is moved to the right now, but it’s not colored in as is normal for gnome’s default theming for an on-toggle
- e. note if you click another gnome settings tab (eg “Notifications”) and then re-visit Bluetooth tab: toggle has reset itself to off
debugging info
So all the debugging I’ve been doing is to see if I can uncover what’s really happening in step 2.c in the “more specific details” above. The main two tools I’ve found in the arch wiki and forums on bluetooth debugging are:
-
rfkill- ensurerfkillisn’t turning off bluetooth in some way- done; seems to be unblocked, and the gnome settings UI’s toggle seems to be reflected correctly by this tool.
-
bluetooth.servicesystemd unit - restarting from here as well as using the Gnome UI toggle- there’s also
bluetoothCLI, but that has the same behavior as the gnome settings UI outliend in details above (I can get it to say “on” and “off”, but nothing really happens differently than when I use the settings UI to do this).
- there’s also
So I’ve mainly been poking at those two in one terminal and watching journalctl output in another terminal, and looking for any interesting leads. No leads so far. Here’s the journactl command I’m running: journalctl --pager-end --catalog --follow
making sure it’s supposed to be on
I’m not sure how this would help the problem of being able to toggle on/off, but just in case: I followed “Auto power-on after boot” section of the bluetooth wiki (and rebooted) to make sure there’s not some initialization step that’s needed for bluetooth to behave well.
It’s maybe worth noting that it used to be the case that bluetooth was just already on when I rebooted before.
device info - unsure what to do with this, though
$ lspci | grep -i bluetooth
$ lsusb | grep -i bluetooth
Bus 003 Device 003: ID 8087:0032 Intel Corp. AX210 Bluetooth
This is on a Framework laptop.
rfkill poking
$ rfkill list
...
1: hci0: Bluetooth
Soft blocked: no
Hard blocked: no
If I run that^ command repeatedly, even many minutes after toggling to state=on in the gnome UI, the command still seems correct: it’s always on (unless I toggle to state off, in which case the command outputs Soft blocked: yes). But when I toggle to state on, and then the gnome UI eventually reverts (see 2.e in “more specific details” of symptom above), then rfkill list still shows unblocked. In other words: despite gnome UI being confused, rfkill still remembers what I asked gnome UI for.
journalctl output
Here’s what I see when I click the Gnome UI toggle sometimes in my journacltl output…
setting the toggle to off, I see... (tl;dr it seems fine?)
Nov 26 13:23:06 mymachine systemd[1]: Starting Load/Save RF Kill Switch Status...
░░ Subject: A start job for unit systemd-rfkill.service has begun execution
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░
░░ A start job for unit systemd-rfkill.service has begun execution.
░░
░░ The job identifier is 3481.
Nov 26 13:23:06 mymachine systemd[1]: Started Load/Save RF Kill Switch Status.
░░ Subject: A start job for unit systemd-rfkill.service has finished successfully
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░
░░ A start job for unit systemd-rfkill.service has finished successfully.
░░
░░ The job identifier is 3481.
Nov 26 13:23:06 mymachine audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj==unconfined msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 26 13:23:06 mymachine kernel: audit: type=1130 audit(1637954586.687:246): pid=1 uid=0 auid=4294967295 ses=4294967295 subj==unconfined msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 26 13:23:11 mymachine systemd[1]: systemd-rfkill.service: Deactivated successfully.
░░ Subject: Unit succeeded
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░
░░ The unit systemd-rfkill.service has successfully entered the 'dead' state.
Nov 26 13:23:11 mymachine audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj==unconfined msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 26 13:23:11 mymachine kernel: audit: type=1131 audit(1637954591.693:247): pid=1 uid=0 auid=4294967295 ses=4294967295 subj==unconfined msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
setting the toggle to on, I see... (tl;dr seems bad - rfkill auto-disabling right away?)
You can see about 5 seconds after the log output of SERVICE_START prints, a SERVICE_STOP follows up:
Nov 26 13:33:55 mymachine systemd[1]: Starting Load/Save RF Kill Switch Status...
░░ Subject: A start job for unit systemd-rfkill.service has begun execution
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░
░░ A start job for unit systemd-rfkill.service has begun execution.
░░
░░ The job identifier is 3521.
Nov 26 13:33:55 mymachine systemd[1]: Started Load/Save RF Kill Switch Status.
░░ Subject: A start job for unit systemd-rfkill.service has finished successfully
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░
░░ A start job for unit systemd-rfkill.service has finished successfully.
░░
░░ The job identifier is 3521.
Nov 26 13:33:55 mymachine audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj==unconfined msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 26 13:33:55 mymachine kernel: audit: type=1130 audit(1637955235.129:256): pid=1 uid=0 auid=4294967295 ses=4294967295 subj==unconfined msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 26 13:34:00 mymachine systemd[1]: systemd-rfkill.service: Deactivated successfully.
░░ Subject: Unit succeeded
░░ Defined-By: systemd
░░ Support: https://forum.manjaro.org/c/support
░░
░░ The unit systemd-rfkill.service has successfully entered the 'dead' state.
Nov 26 13:34:00 mymachine audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 subj==unconfined msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Nov 26 13:34:00 mymachine kernel: audit: type=1131 audit(1637955240.135:257): pid=1 uid=0 auid=4294967295 ses=4294967295 subj==unconfined msg='unit=systemd-rfkill comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
TLP - systemd-rfkill.service masking advice
I also occasionally see this output:
Nov 26 13:18:24 mymachine tlp[48410]: Warning: systemd-rfkill.service is not masked, radio device switching may not work as configured.
Nov 26 13:18:24 mymachine tlp[48410]: >>> Invoke 'systemctl mask systemd-rfkill.service' to correct this.
Nov 26 13:18:24 mymachine tlp[48410]: Warning: systemd-rfkill.socket is not masked, radio device switching may not work as configured.
Nov 26 13:18:24 mymachine tlp[48410]: >>> Invoke 'systemctl mask systemd-rfkill.socket' to correct this.
I tried running the mask command, and restarting bluetooth services, but nothing changed in behavior. I found a github thread (I’ll find the link if someone wants) about this, but nothing that I could gleam helpful info from. Since I’m not confident what this is really about, I’ve unmasked to bring things back to how they were.
output of `systemctl status systemd-rfkill.{socket,service}`
$ sudo systemctl status systemd-rfkill.socket
○ systemd-rfkill.service - Load/Save RF Kill Switch Status
Loaded: loaded (/usr/lib/systemd/system/systemd-rfkill.service; static)
Active: inactive (dead) since Fri 2021-11-26 13:42:32 CST; 6min ago
TriggeredBy: ● systemd-rfkill.socket
Docs: man:systemd-rfkill.service(8)
Process: 59360 ExecStart=/usr/lib/systemd/systemd-rfkill (code=exited, status=0/SUCCESS)
Main PID: 59360 (code=exited, status=0/SUCCESS)
CPU: 7ms
Nov 26 13:42:27 mymachine systemd[1]: Starting Load/Save RF Kill Switch Status...
Nov 26 13:42:27 mymachine systemd[1]: Started Load/Save RF Kill Switch Status.
$ sudo systemctl status systemd-rfkill.socket
Nov 26 13:42:32 mymachine systemd[1]: systemd-rfkill.service: Deactivated successfully.
● systemd-rfkill.socket - Load/Save RF Kill Switch Status /dev/rfkill Watch
Loaded: loaded (/usr/lib/systemd/system/systemd-rfkill.socket; static)
Active: active (listening) since Fri 2021-11-26 12:17:24 CST; 1h 31min ago
Triggers: ● systemd-rfkill.service
Docs: man:systemd-rfkill.socket(8)
Listen: /dev/rfkill (Special)
CGroup: /system.slice/systemd-rfkill.socket
Nov 26 12:17:24 mymachine systemd[1]: Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch.
Also since this is tlp (software focusing on battery optimization for laptops) I switched the gnome system tray from “balanced” to “performance” (which I believe means “don’t inhibit things”), but I’ve still not seen a change in behavior.
disclaimer on research: I found a lot of posts online of people debugging some bluetooth toggle not doing anything. None quite helped, but I’m sure I need to keep digging, so for now I’m just dumping my notes here in hopes it’s useful to someone when and if I figure out what’s wrong. Another option is none of those other posts is the exact same bug I’m hitting, because bluetooth is probably susceptible to so many parts of the stack having subtle bugs in different places over time, so … that’s okay too, maybe this is a new bug then.
rebooted with