blueman-project / blueman

Blueman is a GTK+ Bluetooth Manager
GNU General Public License v3.0
1.24k stars 188 forks source link

Blueman shows not devices #1498

Closed WhyNotHugo closed 3 years ago

WhyNotHugo commented 3 years ago

blueman: 2.1.r423.gd50b8a20 (e.g.: master) BlueZ: 5.55 Distribution: ArchLinux Desktop environment: swaywm

blueman-manager takes a long while to start up, and then shows no devices (not even the ones that are currently connected).

$ blueman-manager
Traceback (most recent call last):
  File "/usr/lib/python3.9/site-packages/blueman/main/Manager.py", line 130, in on_dbus_name_appeared
    check_bluetooth_status(_("Bluetooth needs to be turned on for the device manager to function"),
  File "/usr/lib/python3.9/site-packages/blueman/Functions.py", line 65, in check_bluetooth_status
    if "PowerManager" not in applet.QueryPlugins():
  File "/usr/lib/python3.9/site-packages/gi/overrides/Gio.py", line 350, in __call__
    result = self.dbus_proxy.call_sync(self.method_name, arg_variant,
gi.repository.GLib.Error: g-io-error-quark: Timeout was reached (24)

However, bluetooth is running fine -- I'm using both my mouse and headphones via bluetooth without issues.

Here's the output of blueman-applet:

$ blueman-applet --loglevel debug
blueman-applet 10.47.35 INFO     PluginManager:85 load_plugin: ['AppIndicator', 'StatusIcon', 'DBusService', 'ShowConnected', 'NMDUNSupport', 'TransferService', 'PPPSupport', 'PowerManager', 'ConnectionNotifier', 'Menu', 'DhcpClient', 'StandardItems', 'Battery', 'NMPANSupport', 'Networking', 'NetUsage', 'GameControllerWakelock', 'AuthAgent', 'DisconnectItems', 'DiscvManager', 'AutoConnect', 'ExitItem', 'RecentConns', 'SerialManager', 'KillSwitch']
blueman-applet 10.47.35 ERROR    PluginManager:90 load_plugin: Unable to load plugin module GameControllerWakelock
Traceback (most recent call last):
  File "/usr/lib/python3.9/site-packages/blueman/main/PluginManager.py", line 88, in load_plugin
    importlib.import_module(self.module_path.__name__ + f".{plugin}")
  File "/usr/lib/python3.9/importlib/__init__.py", line 127, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
  File "<frozen importlib._bootstrap>", line 1030, in _gcd_import
  File "<frozen importlib._bootstrap>", line 1007, in _find_and_load
  File "<frozen importlib._bootstrap>", line 986, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 680, in _load_unlocked
  File "<frozen importlib._bootstrap_external>", line 790, in exec_module
  File "<frozen importlib._bootstrap>", line 228, in _call_with_frames_removed
  File "/usr/lib/python3.9/site-packages/blueman/plugins/applet/GameControllerWakelock.py", line 15, in <module>
    raise ImportError('This is not an X11 screen')
ImportError: This is not an X11 screen
blueman-applet 10.47.35 INFO     PluginManager:156 __load_plugin: loading <class 'blueman.plugins.applet.Menu.Menu'>
blueman-applet 10.47.35 INFO     PluginManager:156 __load_plugin: loading <class 'blueman.plugins.applet.StatusIcon.StatusIcon'>
blueman-applet 10.47.35 DEBUG    Base:60 do_g_properties_changed: /org/bluez/hci0 {'Address': '64:5D:86:ED:F9:53', 'AddressType': 'public', 'Name': 'victory', 'Alias': 'victory', 'Class': 3932428, 'Powered': True, 'Discoverable': False, 'DiscoverableTimeout': 180, 'Pairable': False, 'PairableTimeout': 0, 'Discovering': False, 'UUIDs': ['00001133-0000-1000-8000-00805f9b34fb', '0000110e-0000-1000-8000-00805f9b34fb', '00001105-0000-1000-8000-00805f9b34fb', '00001132-0000-1000-8000-00805f9b34fb', '00001200-0000-1000-8000-00805f9b34fb', '00001104-0000-1000-8000-00805f9b34fb', '00005005-0000-1000-8000-0002ee000001', '00001108-0000-1000-8000-00805f9b34fb', '00001112-0000-1000-8000-00805f9b34fb', '0000110c-0000-1000-8000-00805f9b34fb', '00001801-0000-1000-8000-00805f9b34fb', '0000112f-0000-1000-8000-00805f9b34fb', '0000110b-0000-1000-8000-00805f9b34fb', '0000180a-0000-1000-8000-00805f9b34fb', '00001800-0000-1000-8000-00805f9b34fb', '0000110a-0000-1000-8000-00805f9b34fb', '00001106-0000-1000-8000-00805f9b34fb'], 'Modalias': 'usb:v1D6Bp0246d0537', 'Roles': ['central', 'peripheral']}
blueman-applet 10.47.35 INFO     PluginManager:156 __load_plugin: loading <class 'blueman.plugins.applet.DBusService.DBusService'>
blueman-applet 10.47.35 INFO     PluginManager:156 __load_plugin: loading <class 'blueman.plugins.applet.NMDUNSupport.NMDUNSupport'>
blueman-applet 10.47.35 INFO     PluginManager:156 __load_plugin: loading <class 'blueman.plugins.applet.TransferService.TransferService'>
blueman-applet 10.47.35 WARNING  PluginManager:147 __load_plugin: Not loading PPPSupport because its conflict has higher priority
blueman-applet 10.47.35 INFO     PluginManager:156 __load_plugin: loading <class 'blueman.plugins.applet.PowerManager.PowerManager'>
blueman-applet 10.47.35 INFO     PluginManager:156 __load_plugin: loading <class 'blueman.plugins.applet.Battery.Battery'>
blueman-applet 10.47.35 INFO     PluginManager:156 __load_plugin: loading <class 'blueman.plugins.applet.ConnectionNotifier.ConnectionNotifier'>
blueman-applet 10.47.35 WARNING  PluginManager:147 __load_plugin: Not loading DhcpClient because its conflict has higher priority
blueman-applet 10.47.35 INFO     PluginManager:156 __load_plugin: loading <class 'blueman.plugins.applet.StandardItems.StandardItems'>
blueman-applet 10.47.35 INFO     PluginManager:156 __load_plugin: loading <class 'blueman.plugins.applet.NMPANSupport.NMPANSupport'>
blueman-applet 10.47.35 INFO     PluginManager:156 __load_plugin: loading <class 'blueman.plugins.applet.Networking.Networking'>
blueman-applet 10.47.35 INFO     Networking:35 load_nap_settings: Loading NAP settings
blueman-applet 10.47.35 INFO     PluginManager:156 __load_plugin: loading <class 'blueman.plugins.applet.AuthAgent.AuthAgent'>
blueman-applet 10.47.35 INFO     PluginManager:156 __load_plugin: loading <class 'blueman.plugins.applet.DisconnectItems.DisconnectItems'>
blueman-applet 10.47.35 INFO     PluginManager:156 __load_plugin: loading <class 'blueman.plugins.applet.DiscvManager.DiscvManager'>
blueman-applet 10.47.35 INFO     PluginManager:156 __load_plugin: loading <class 'blueman.plugins.applet.AutoConnect.AutoConnect'>
blueman-applet 10.47.35 INFO     PluginManager:156 __load_plugin: loading <class 'blueman.plugins.applet.RecentConns.RecentConns'>
blueman-applet 10.47.35 INFO     PluginManager:156 __load_plugin: loading <class 'blueman.plugins.applet.SerialManager.SerialManager'>
blueman-applet 10.47.35 INFO     PluginManager:156 __load_plugin: loading <class 'blueman.plugins.applet.KillSwitch.KillSwitch'>
Failed to register: Timeout was reached
blueman-applet 10.48.00 INFO     KillSwitch:106 io_event  : killswitch registered 0
blueman-applet 10.48.00 INFO     KillSwitch:122 io_event  : State: True
blueman-applet 10.48.00 INFO     PowerManager:178 update_power_state: off False | foff False | on True | current state True | new state True
blueman-applet 10.48.00 INFO     KillSwitch:87 _on_connman_vanished: net.connman vanished

I'm not sure what the initial timeout refers to, but bluez is also running:

image

cschramm commented 3 years ago

blueman-manager fails to reach blueman-applet. blueman-applet fails to register its GApplication. There are a lot of references to "Failed to register: Timeout was reached" on the web for GApplications and it sounds like usually there is another instance, in this case of blueman-applet, that is somehow stuck. Do you see another process?

WhyNotHugo commented 3 years ago

There's no other instance of anything blueman running:

➜ ps aux | grep blueman
hugo      396550  0.0  0.0   6756  2392 pts/13   S+   22:01   0:00 grep --color=auto --exclude-dir=.git blueman

I also tried running blueman-manager menually:

➜ blueman-applet
blueman-applet 22.02.04 ERROR    PluginManager:90 load_plugin: Unable to load plugin module GameControllerWakelock
Traceback (most recent call last):
  File "/usr/lib/python3.9/site-packages/blueman/main/PluginManager.py", line 88, in load_plugin
    importlib.import_module(self.module_path.__name__ + f".{plugin}")
  File "/usr/lib/python3.9/importlib/__init__.py", line 127, in import_module
    return _bootstrap._gcd_import(name[level:], package, level)
  File "<frozen importlib._bootstrap>", line 1030, in _gcd_import
  File "<frozen importlib._bootstrap>", line 1007, in _find_and_load
  File "<frozen importlib._bootstrap>", line 986, in _find_and_load_unlocked
  File "<frozen importlib._bootstrap>", line 680, in _load_unlocked
  File "<frozen importlib._bootstrap_external>", line 790, in exec_module
  File "<frozen importlib._bootstrap>", line 228, in _call_with_frames_removed
  File "/usr/lib/python3.9/site-packages/blueman/plugins/applet/GameControllerWakelock.py", line 15, in <module>
    raise ImportError('This is not an X11 screen')
ImportError: This is not an X11 screen
blueman-applet 22.02.04 WARNING  PluginManager:147 __load_plugin: Not loading PPPSupport because its conflict has higher priority
blueman-applet 22.02.04 WARNING  PluginManager:147 __load_plugin: Not loading DhcpClient because its conflict has higher priority

It does keep running though, but running blueman-manageron another terminal still behaves the same: takes a while to start up, and then shows up with no devices:

➜ blueman-manager
Traceback (most recent call last):
  File "/usr/lib/python3.9/site-packages/blueman/main/Manager.py", line 130, in on_dbus_name_appeared
    check_bluetooth_status(_("Bluetooth needs to be turned on for the device manager to function"),
  File "/usr/lib/python3.9/site-packages/blueman/Functions.py", line 65, in check_bluetooth_status
    if "PowerManager" not in applet.QueryPlugins():
  File "/usr/lib/python3.9/site-packages/gi/overrides/Gio.py", line 350, in __call__
    result = self.dbus_proxy.call_sync(self.method_name, arg_variant,
gi.repository.GLib.Error: g-io-error-quark: Timeout was reached (24)
cschramm commented 3 years ago

No "Failed to register: Timeout was reached" in blueman-applet this time. :+1:

You can try the same D-Bus call from d-feet or dbus-send --session --dest=org.blueman.Applet --print-reply /org/blueman/Applet org.blueman.Applet.QueryPlugins.

WhyNotHugo commented 3 years ago

Seems to work:

➜ dbus-send --session --dest=org.blueman.Applet --print-reply /org/blueman/Applet org.blueman.Applet.QueryPlugins
method return time=1614115551.457825 sender=:1.605 -> destination=:1.604 serial=46 reply_serial=2
   array [
      string "Menu"
      string "StatusIcon"
      string "DBusService"
      string "NMDUNSupport"
      string "TransferService"
      string "PowerManager"
      string "Battery"
      string "ConnectionNotifier"
      string "StandardItems"
      string "NMPANSupport"
      string "Networking"
      string "AuthAgent"
      string "DisconnectItems"
      string "DiscvManager"
      string "AutoConnect"
      string "RecentConns"
      string "SerialManager"
      string "KillSwitch"
   ]
WhyNotHugo commented 3 years ago

Huh, that first call worked, but subsequent calls fail.

Tried restarting blueman-applet. Looks like that single successful call was the only one, after that, there's always a timeout:

➜ dbus-send --session --dest=org.blueman.Applet --print-reply /org/blueman/Applet org.blueman.Applet.QueryPlugins
Error org.freedesktop.DBus.Error.NoReply: 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.
cschramm commented 3 years ago

:thinking: Super weird. It stopped responding even if you completely restart the process? That does not really sound like it can be the applet's fault. Anything showing up in the dbus.service logs?

WhyNotHugo commented 3 years ago

Nope, nothing in either the system or session dbus services.

cschramm commented 3 years ago

I have absolutely no idea what could be happening there. Maybe dbus-monitor could give some direction but I guess you'll just see a working request without response. 🤷 Might be worth comparing with a working request, though (if replicable; first one after reboot?).

infirit commented 3 years ago

I can confirm this is a problem on Arch. But it is apparently not limited to blueman as the forums report the same for other GtkApplications like gnome-terminal.

WhyNotHugo commented 3 years ago

@infirit Can you share some link to these? I'm clearly very bad at using the search in Arch's forums, and can't find any references to this :sweat_smile:

infirit commented 3 years ago

Example, https://bbs.archlinux.org/viewtopic.php?id=264002

infirit commented 3 years ago

2.1.4 from community does work so it is related to my personal build or something in master. The applet actually uses Gio.Application not Gtk.Application so I'll experiment this week and see if the latter makes a difference.

cschramm commented 3 years ago

If it's actually related to GApplication (and that makes some sense, as it interferes with D-Bus), #1304 is relevant and that's not in 2.1.4.

(@infirit! :scream:)

WhyNotHugo commented 3 years ago

I don't think it's #1304 / dce1a6e. I tested dce1a6e~ (0cbbe9f7), and it has a similar issue. The only difference I'm noticing is that blueman-manager does not autostart blueman-applet, but starting it manually has the same timeout.

I'll try bisecting to latest stable and see if anything changes.

WhyNotHugo commented 3 years ago

Huh, journalctl shows dozens of entries of this:

Mar 02 23:58:07 victory blueman-mechanism[3912712]: Unable to init server: Could not connect: Connection refused
Mar 02 23:58:07 victory blueman-mechanism[3912712]: Unable to init server: Could not connect: Connection refused
Mar 02 23:58:07 victory blueman-mechani[3912712]: gtk_icon_theme_get_for_screen: assertion 'GDK_IS_SCREEN (screen)' failed
Mar 02 23:58:07 victory systemd[1]: Started Bluetooth management mechanism.
Mar 02 23:58:37 victory systemd[1]: blueman-mechanism.service: Succeeded.
Mar 02 23:58:39 victory systemd[1]: Starting Bluetooth management mechanism...
Mar 02 23:58:39 victory blueman-mechanism[3913312]: Unable to init server: Could not connect: Connection refused
Mar 02 23:58:39 victory blueman-mechanism[3913312]: Unable to init server: Could not connect: Connection refused
Mar 02 23:58:39 victory blueman-mechani[3913312]: gtk_icon_theme_get_for_screen: assertion 'GDK_IS_SCREEN (screen)' failed
Mar 02 23:58:39 victory systemd[1]: Started Bluetooth management mechanism.
Mar 02 23:59:09 victory systemd[1]: blueman-mechanism.service: Succeeded.

Apparently, blueman-mechanism keeps starting and dying, over and over. What exactly is this daemon?

WhyNotHugo commented 3 years ago

b3eb13835c2eba73349b9ad2101facbab98c1f99 is the last commit that works for me. c0335308d4a341d87fd9ee8d5b81ab91fad0b307 is the first commit that reproduces the timeout issue.

cschramm commented 3 years ago

Surprising. :sweat_smile:

blueman-mechanism is a short-lived daemon for root-level tasks. It's ok that it terminates after some time.

Unfortunately I squashed #1122 back then. Could you bisect https://github.com/blueman-project/blueman/pull/1122/commits (on top of b3eb138) to get closer to the cause?

infirit commented 3 years ago

Strange, I'll make some time this weekend to look into this.

infirit commented 3 years ago

b3eb138 is the last commit that works for me. c033530 is the first commit that reproduces the timeout issue.

Just to be sure I build both and can confirm. Now on to figure out why :confused:

infirit commented 3 years ago

It's 1cbd175f9d28a8af257d8e55a6f882ba1c9e8442

infirit commented 3 years ago

@WhyNotHugo https://github.com/infirit/blueman/commit/a118d326aad9ae691e10bd39df0adbc203889829 reverts that commit which works on master.

infirit commented 3 years ago

Possible solution, https://github.com/blueman-project/blueman/commit/815c3c36da92aa34db17040b71779e2ff3eeb499

That's it for now, will be busy until the weekend.

cschramm commented 3 years ago

🤔 What's required that it blocks? I did not experience any such issues with master builds on two different systems (one's even Arch as well).

infirit commented 3 years ago

It only started recently after a bigish update. It is either a change in the kernel which I think is unlikely. Or the behaviour in glib changed. I'll have look at the pacman logs to see if something stands out.

I see that the iochannel is reading nothing useful the first time. It is strange.

WhyNotHugo commented 3 years ago

815c3c36da92aa34db17040b71779e2ff3eeb499 works for me :tada:

cschramm commented 3 years ago

It's the kernel. I actually pinned it to 5.9.14 in my Arch system as early versions of 5.10 break my mouse (https://bugzilla.kernel.org/show_bug.cgi?id=209745), just tried 5.11 and experienced the same behavior.

WhyNotHugo commented 3 years ago

Odd. I use a bluetooth mouse (MX Vertical) and headphones (QC 35 II). Both connect fine (the mouse at startup, the headphones as soon as I turn them on).

They've also worked during the many weeks when I had a broken blueman, so apparently, that kernel bug never manifested for me...? :crossed_fingers:

cschramm commented 3 years ago

Looks like it happens with 5.11. 5.10 seems fine.

WhyNotHugo commented 3 years ago

815c3c3 + linux-5.11.2.arch1-1 works for me.

Are you also applying that patch? If you're also on Arch, then just apply this to the AUR's PKGBUILD:

diff --git a/PKGBUILD b/PKGBUILD
index 0d9f484..7c88d74 100644
--- a/PKGBUILD
+++ b/PKGBUILD
@@ -17,7 +17,7 @@ optdepends=('dnsmasq: DHCP server for Network Access Point'
 makedepends=('cython' 'git' 'intltool' 'libtool')
 conflicts=('blueman' 'blueman-bzr')
 provides=('blueman')
-source=("${pkgname}"::"git+https://github.com/blueman-project/${_pkgname}.git")
+source=("${pkgname}"::"git+https://github.com/blueman-project/${_pkgname}.git#commit=815c3c36da92aa34db17040b71779e2ff3eeb499")
 sha1sums=('SKIP')
 install=${pkgname}.install
cschramm commented 3 years ago

No, I didn't patch. I just tried to see what causes the problem to show and it's the 5.11 kernel.

infirit commented 3 years ago

That's surprising. Anyway, making it non blocking appears to have no negative effect so you want me to open a PR?

The only thing that changes is that we get a few warning about wrong event size, genuine block/unblock events get handled properly.

cschramm commented 3 years ago

I'd also love to understand what's going on there, but making the channel non-blocking makes sense in any case, yes. PR would be cool. :+1: