blueman-project / blueman

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

Blueman doesn't detect auto-connected devices #2304

Closed gchamon closed 5 months ago

gchamon commented 5 months ago

blueman: 2.3.5 BlueZ: 5.73 Distribution: Archlinux Desktop environment: Hyprland

Running blueman-applet from the terminal, whenever I turn on my headset and it automatically connects, the following error is written to the terminal:

Traceback (most recent call last):
  File "/usr/lib/python3.11/site-packages/blueman/main/BatteryWatcher.py", line 17, in <lambda>
    lambda _manager, obj_path: callback(obj_path, Battery(obj_path=obj_path)["Percentage"])
                               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/blueman/plugins/applet/ConnectionNotifier.py", line 39, in _on_battery_update
    notification = self._notifications[path]
                   ~~~~~~~~~~~~~~~~~~~^^^^^^
KeyError: '/org/bluez/hci0/dev_5C_C6_E9_3A_27_6E'

If I turn on the device in pairing mode, that is without giving it a chance to auto-connect, and then I manually connect it using blueman, then it works without issue. After that, turning the device off and back on doesn't reproduce the issue. However, restarting blueman-applet, the issue crops up again.

I investigated a bit and self._notifications is empty whenever this issue happens. I am not familiar with the structure of the project and couldn't pinpoint where this object is populated to see where the issue might be. I am suspecting, though, that there might be a signaling issue with my current setup, that is, dbus might not be correctly sending the necessary signals for blueman to populate its internal data structures, but that is a long shot guess.

MaxXor commented 5 months ago

I've ran into the same issue today, the error message is a bit spammy, With GNOME 46 it gets thrown every 2 mins.

infirit commented 5 months ago

Notifications are added when the device connect and if battery information becomes available we update the notification with the battery level. It would be nice to get a full debug log (blueman-applet --loglevel debug) when this happens so we can see how we got to this error. Below should fix this but Id like to understand how we got there before I open a PR.

diff --git a/blueman/plugins/applet/ConnectionNotifier.py b/blueman/plugins/applet/ConnectionNotifier.py
index 35c202f1c..8e9ffd9f7 100644
--- a/blueman/plugins/applet/ConnectionNotifier.py
+++ b/blueman/plugins/applet/ConnectionNotifier.py
@@ -53,7 +53,7 @@ class ConnectionNotifier(AppletPlugin):

     def _on_battery_property_changed(self, _battery: Battery, key: str, value: Any, path: str) -> None:
         if key == "Percentage":
-            notification = self._notifications[path]
+            notification = self._notifications.get(path, None)
             if notification:
                 notification.set_message(f"{_('Connected')} {value}%")
                 notification.set_notification_icon("battery")
gchamon commented 5 months ago

@infirit I did something similar, but wrapping self._notifications[path] with a try... except KeyError and yes, although the exception goes away, the device still isn't recognized in blueman-applet. I think your change will have the same result.

I will try to run the experiment again with debug level once I have a little more time.

cschramm commented 5 months ago

That's definitely not 2.3.5 but rather some git snapshot.

The error is expected if the signal that reports the device to be connected arrives after a signal for the battery level ... or not at all. That, however, is totally unexpected.

gchamon commented 5 months ago

@cschramm it's the archlinux package from extra

image

gchamon commented 5 months ago

@infirit here are the complete logs with debug enabled:

$ blueman-applet --loglevel debug
blueman-applet 08.24.18 INFO     PluginManager:86 load_plugin: ['StandardItems', 'DiscvManager', 'KillSwitch', 'Networking', 'DBusService', 'NetUsage', 'ConnectionNotifier', 'Menu', 'AuthAgent', 'PPPSupport', 'AutoConnect', 'ShowConnected', 'ExitItem', 'DhcpClient', 'NMPANSupport', 'PowerManager', 'TransferService', 'DisconnectItems', 'RecentConns', 'GameControllerWakelock', 'StatusNotifierItem', 'PulseAudioProfile', 'NMDUNSupport', 'SerialManager', 'StatusIcon']
blueman-applet 08.24.18 WARNING  PluginManager:93 load_plugin: Failed to start plugin GameControllerWakelock: Only X11 platform is supported
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.DBusService.DBusService'>
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.Menu.Menu'>
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.StandardItems.StandardItems'>
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.StatusIcon.StatusIcon'>
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.PowerManager.PowerManager'>
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.RecentConns.RecentConns'>
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.DiscvManager.DiscvManager'>
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.KillSwitch.KillSwitch'>
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.Networking.Networking'>
blueman-applet 08.24.18 WARNING  PluginManager:150 __load_plugin: Not loading PPPSupport because its conflict has higher priority
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.ConnectionNotifier.ConnectionNotifier'>
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.AuthAgent.AuthAgent'>
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.AutoConnect.AutoConnect'>
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.ShowConnected.ShowConnected'>
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.ExitItem.ExitItem'>
blueman-applet 08.24.18 WARNING  PluginManager:150 __load_plugin: Not loading DhcpClient because its conflict has higher priority
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.NMPANSupport.NMPANSupport'>
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.TransferService.TransferService'>
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.DisconnectItems.DisconnectItems'>
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.StatusNotifierItem.StatusNotifierItem'>
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.PulseAudioProfile.AudioProfiles'>
blueman-applet 08.24.18 INFO     PulseAudioUtils:207 pa_context_event: 1
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.NMDUNSupport.NMDUNSupport'>
blueman-applet 08.24.18 INFO     PluginManager:159 __load_plugin: loading <class 'blueman.plugins.applet.SerialManager.SerialManager'>
blueman-applet 08.24.18 INFO     PulseAudioUtils:207 pa_context_event: 2
blueman-applet 08.24.18 INFO     KillSwitch:106 io_event  : killswitch registered 1
blueman-applet 08.24.18 INFO     KillSwitch:122 io_event  : State: True
blueman-applet 08.24.18 INFO     PowerManager:160 update_power_state: off False | foff False | on True | current state True | new state True
blueman-applet 08.24.18 INFO     KillSwitch:85 _on_connman_vanished: net.connman vanished
blueman-applet 08.24.18 INFO     KillSwitch:106 io_event  : killswitch registered 3
blueman-applet 08.24.18 INFO     KillSwitch:122 io_event  : State: True
blueman-applet 08.24.18 INFO     PowerManager:160 update_power_state: off False | foff False | on True | current state True | new state True
blueman-applet 08.24.18 INFO     TransferService:243 _on_dbus_name_vanished: org.bluez.obex not running or was stopped
blueman-applet 08.24.18 INFO     Applet:76 _on_dbus_name_appeared: org.bluez :1.8
blueman-applet 08.24.18 INFO     Functions:99 launch    : Gtk eventtime is 0, not using LaunchContext
blueman-applet 08.24.18 INFO     Networking:78 set_nap   : set nap False
blueman-applet 08.24.18 INFO     BluezAgent:56 register_agent: Register Agent
blueman-applet 08.24.18 INFO     PulseAudioUtils:207 pa_context_event: 3
blueman-applet 08.24.18 DEBUG    Base:67 _properties_changed: /org/bluez/hci0 {'Pairable': True} [] <Adapter.Adapter object at 0x751b64dcc040 (blueman+bluez+Adapter+Adapter at 0x632a182b5170)>
blueman-applet 08.24.18 DEBUG    DiscvManager:95 on_adapter_property_changed: prop Pairable True
blueman-applet 08.24.18 INFO     ShowConnected:55 enumerate_connections: Found 0 existing connections
blueman-applet 08.24.18 INFO     PulseAudioUtils:207 pa_context_event: 4
blueman-applet 08.24.18 INFO     PulseAudioProfile:133 on_pa_ready: PulseAudio Ready
blueman-applet 08.24.18 INFO     PulseAudioUtils:213 <lambda>  : 1
blueman-applet 08.24.23 INFO     PulseAudioUtils:337 __event_callback: 25 1082
blueman-applet 08.24.23 DEBUG    PulseAudioProfile:109 on_pa_event: 25 1082
blueman-applet 08.24.23 INFO     PulseAudioProfile:122 on_pa_event: card
blueman-applet 08.24.23 INFO     PulseAudioProfile:124 on_pa_event: change
blueman-applet 08.24.23 INFO     PulseAudioUtils:337 __event_callback: 41 1082
blueman-applet 08.24.23 DEBUG    PulseAudioProfile:109 on_pa_event: 41 1082
blueman-applet 08.24.23 INFO     PulseAudioProfile:122 on_pa_event: card
blueman-applet 08.24.23 INFO     PulseAudioProfile:127 on_pa_event: remove
blueman-applet 08.24.26 DEBUG    Manager:86 _on_interface_added: Battery1 added to /org/bluez/hci0/dev_5C_C6_E9_3A_27_6E
Traceback (most recent call last):
  File "/usr/lib/python3.11/site-packages/blueman/main/BatteryWatcher.py", line 17, in <lambda>
    lambda _manager, obj_path: callback(obj_path, Battery(obj_path=obj_path)["Percentage"])
                               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3.11/site-packages/blueman/plugins/applet/ConnectionNotifier.py", line 39, in _on_battery_update
    notification = self._notifications[path]
                   ~~~~~~~~~~~~~~~~~~~^^^^^^
KeyError: '/org/bluez/hci0/dev_5C_C6_E9_3A_27_6E'
blueman-applet 08.24.27 INFO     PulseAudioUtils:337 __event_callback: 9 1136
blueman-applet 08.24.27 DEBUG    PulseAudioProfile:109 on_pa_event: 9 1136
blueman-applet 08.24.27 INFO     PulseAudioProfile:122 on_pa_event: card
blueman-applet 08.24.27 INFO     PulseAudioProfile:129 on_pa_event: add
blueman-applet 08.24.27 INFO     PulseAudioUtils:337 __event_callback: 25 1136
blueman-applet 08.24.27 DEBUG    PulseAudioProfile:109 on_pa_event: 25 1136
blueman-applet 08.24.27 INFO     PulseAudioProfile:122 on_pa_event: card
blueman-applet 08.24.27 INFO     PulseAudioProfile:124 on_pa_event: change
blueman-applet 08.24.27 INFO     PulseAudioUtils:337 __event_callback: 25 1136
blueman-applet 08.24.28 DEBUG    PulseAudioProfile:109 on_pa_event: 25 1136
blueman-applet 08.24.28 INFO     PulseAudioProfile:122 on_pa_event: card
blueman-applet 08.24.28 INFO     PulseAudioProfile:124 on_pa_event: change
blueman-applet 08.24.28 INFO     PulseAudioUtils:337 __event_callback: 25 1136
blueman-applet 08.24.28 DEBUG    PulseAudioProfile:109 on_pa_event: 25 1136
blueman-applet 08.24.28 INFO     PulseAudioProfile:122 on_pa_event: card
blueman-applet 08.24.28 INFO     PulseAudioProfile:124 on_pa_event: change
gchamon commented 5 months ago

Could messing with dbus have something to do with it? Because on Wayland we need to apply extra steps in order for screenshare to work, and although screenshare shouldn't have anything to do with Bluetooth, the signal bus does, maybe?

cschramm commented 5 months ago

@cschramm it's the archlinux package from extra

Cannot have been. 2.4 was released a day after your post and the code hasn't been part of 2.3.5 yet. Anyway, let's assume 2.4 then.

Could messing with dbus have something to do with it? Because on Wayland we need to apply extra steps in order for screenshare to work, and although screenshare shouldn't have anything to do with Bluetooth, the signal bus does, maybe?

Sure. What kind of extra steps do you mean?

Please try sudo dbus-monitor --system sender=org.bluez to see the signals.

infirit commented 5 months ago

There is no entry in the log that shows the device was connected. I must say that bluetooth has been flaky on arch for me. I just connected my DualSense by pressing a button on it but there is no signal whatsoever about it on the bus. It definitely connected as it works on dolphin-emu.

cschramm commented 5 months ago

ABRT logs something like this in Fedora every few months: https://bugzilla.redhat.com/buglist.cgi?quicksearch=connectionnotifier Interestingly I cannot find anything similar on the Ubuntu error tracker.

gchamon commented 5 months ago

@cschramm it's the archlinux package from extra

Cannot have been. 2.4 was released a day after your post and the code hasn't been part of 2.3.5 yet. Anyway, let's assume 2.4 then.

Could messing with dbus have something to do with it? Because on Wayland we need to apply extra steps in order for screenshare to work, and although screenshare shouldn't have anything to do with Bluetooth, the signal bus does, maybe?

Sure. What kind of extra steps do you mean?

Please try sudo dbus-monitor --system sender=org.bluez to see the signals.

Here it is

sudo dbus-monitor --system sender=org.bluez
[sudo] password for gchamon: 
signal time=1712191473.382530 sender=org.freedesktop.DBus -> destination=:1.58 serial=4294967295 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameAcquired
   string ":1.58"
signal time=1712191473.382553 sender=org.freedesktop.DBus -> destination=:1.58 serial=4294967295 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=NameLost
   string ":1.58"
signal time=1712191485.683192 sender=:1.6 -> destination=(null destination) serial=135 path=/org/bluez/hci0/dev_5C_C6_E9_3A_27_6E; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.bluez.MediaControl1"
   array [
      dict entry(
         string "Connected"
         variant             boolean false
      )
   ]
   array [
      string "Player"
   ]
method call time=1712191485.683310 sender=:1.6 -> destination=org.freedesktop.DBus serial=136 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=RemoveMatch
   string "type='signal',sender=':1.33',path='/org/freedesktop/pipewire/battery/org/bluez/hci0/dev_5C_C6_E9_3A_27_6E',interface='org.freedesktop.DBus.Properties',member='PropertiesChanged',arg0='org.bluez.BatteryProvider1'"
signal time=1712191485.683378 sender=:1.6 -> destination=(null destination) serial=137 path=/; interface=org.freedesktop.DBus.ObjectManager; member=InterfacesRemoved
   object path "/org/bluez/hci0/dev_5C_C6_E9_3A_27_6E"
   array [
      string "org.bluez.Battery1"
   ]
method return time=1712191485.683416 sender=:1.6 -> destination=:1.42 serial=138 reply_serial=65
   variant       boolean false
method call time=1712191486.066500 sender=:1.6 -> destination=:1.33 serial=139 path=/MediaEndpoint/A2DPSource/sbc_xq; interface=org.bluez.MediaEndpoint1; member=ClearConfiguration
   object path "/org/bluez/hci0/dev_5C_C6_E9_3A_27_6E/sep1/fd0"
signal time=1712191486.066531 sender=:1.6 -> destination=(null destination) serial=140 path=/; interface=org.freedesktop.DBus.ObjectManager; member=InterfacesRemoved
   object path "/org/bluez/hci0/dev_5C_C6_E9_3A_27_6E/sep1/fd0"
   array [
      string "org.freedesktop.DBus.Properties"
      string "org.freedesktop.DBus.Introspectable"
      string "org.bluez.MediaTransport1"
   ]
signal time=1712191486.079798 sender=:1.6 -> destination=(null destination) serial=141 path=/; interface=org.freedesktop.DBus.ObjectManager; member=InterfacesRemoved
   object path "/org/bluez/hci0/dev_5C_C6_E9_3A_27_6E/sep1"
   array [
      string "org.freedesktop.DBus.Properties"
      string "org.freedesktop.DBus.Introspectable"
      string "org.bluez.MediaEndpoint1"
   ]
method call time=1712191488.747125 sender=:1.6 -> destination=:1.33 serial=142 path=/Profile/HFPAG; interface=org.bluez.Profile1; member=NewConnection
   object path "/org/bluez/hci0/dev_5C_C6_E9_3A_27_6E"
   file descriptor
         inode: 34742
         type: socket
         address family: bluetooth
   array [
      dict entry(
         string "Version"
         variant             uint16 262
      )
      dict entry(
         string "Features"
         variant             uint16 63
      )
   ]
signal time=1712191488.913970 sender=:1.6 -> destination=(null destination) serial=143 path=/; interface=org.freedesktop.DBus.ObjectManager; member=InterfacesAdded
   object path "/org/bluez/hci0/dev_5C_C6_E9_3A_27_6E/sep1"
   array [
      dict entry(
         string "org.freedesktop.DBus.Introspectable"
         array [
         ]
      )
      dict entry(
         string "org.bluez.MediaEndpoint1"
         array [
            dict entry(
               string "UUID"
               variant                   string "0000110b-0000-1000-8000-00805f9b34fb"
            )
            dict entry(
               string "Codec"
               variant                   byte 0
            )
            dict entry(
               string "Capabilities"
               variant                   array of bytes [
                     ff ff 02 35
                  ]
            )
            dict entry(
               string "Device"
               variant                   object path "/org/bluez/hci0/dev_5C_C6_E9_3A_27_6E"
            )
            dict entry(
               string "DelayReporting"
               variant                   boolean false
            )
         ]
      )
      dict entry(
         string "org.freedesktop.DBus.Properties"
         array [
         ]
      )
   ]
method call time=1712191489.033824 sender=:1.6 -> destination=org.freedesktop.DBus serial=144 path=/org/freedesktop/DBus; interface=org.freedesktop.DBus; member=AddMatch
   string "type='signal',sender=':1.33',path='/org/freedesktop/pipewire/battery/org/bluez/hci0/dev_5C_C6_E9_3A_27_6E',interface='org.freedesktop.DBus.Properties',member='PropertiesChanged',arg0='org.bluez.BatteryProvider1'"
signal time=1712191489.034097 sender=:1.6 -> destination=(null destination) serial=145 path=/; interface=org.freedesktop.DBus.ObjectManager; member=InterfacesAdded
   object path "/org/bluez/hci0/dev_5C_C6_E9_3A_27_6E"
   array [
      dict entry(
         string "org.bluez.Battery1"
         array [
            dict entry(
               string "Percentage"
               variant                   byte 80
            )
         ]
      )
   ]
method return time=1712191489.035515 sender=:1.6 -> destination=:1.42 serial=146 reply_serial=66
   variant       byte 80
method return time=1712191489.036391 sender=:1.6 -> destination=:1.42 serial=147 reply_serial=67
   variant       byte 80
method call time=1712191490.052600 sender=:1.6 -> destination=:1.33 serial=148 path=/MediaEndpoint/A2DPSource/sbc_xq; interface=org.bluez.MediaEndpoint1; member=SelectConfiguration
   array of bytes [
      ff ff 02 35
   ]
signal time=1712191490.066862 sender=:1.6 -> destination=(null destination) serial=149 path=/; interface=org.freedesktop.DBus.ObjectManager; member=InterfacesAdded
   object path "/org/bluez/hci0/dev_5C_C6_E9_3A_27_6E/sep1/fd1"
   array [
      dict entry(
         string "org.freedesktop.DBus.Introspectable"
         array [
         ]
      )
      dict entry(
         string "org.bluez.MediaTransport1"
         array [
            dict entry(
               string "Device"
               variant                   object path "/org/bluez/hci0/dev_5C_C6_E9_3A_27_6E"
            )
            dict entry(
               string "UUID"
               variant                   string "0000110a-0000-1000-8000-00805f9b34fb"
            )
            dict entry(
               string "Codec"
               variant                   byte 0
            )
            dict entry(
               string "Configuration"
               variant                   array of bytes [
                     14 15 02 27
                  ]
            )
            dict entry(
               string "State"
               variant                   string "idle"
            )
         ]
      )
      dict entry(
         string "org.freedesktop.DBus.Properties"
         array [
         ]
      )
   ]
method call time=1712191490.067160 sender=:1.6 -> destination=:1.33 serial=150 path=/MediaEndpoint/A2DPSource/sbc_xq; interface=org.bluez.MediaEndpoint1; member=SetConfiguration
   object path "/org/bluez/hci0/dev_5C_C6_E9_3A_27_6E/sep1/fd1"
   array [
      dict entry(
         string "Device"
         variant             object path "/org/bluez/hci0/dev_5C_C6_E9_3A_27_6E"
      )
      dict entry(
         string "UUID"
         variant             string "0000110a-0000-1000-8000-00805f9b34fb"
      )
      dict entry(
         string "Codec"
         variant             byte 0
      )
      dict entry(
         string "Configuration"
         variant             array of bytes [
               14 15 02 27
            ]
      )
      dict entry(
         string "State"
         variant             string "idle"
      )
   ]
method return time=1712191490.075913 sender=:1.6 -> destination=:1.42 serial=151 reply_serial=68
   variant       boolean false
method return time=1712191490.086326 sender=:1.6 -> destination=:1.42 serial=152 reply_serial=69
   variant       boolean false
method return time=1712191490.089435 sender=:1.6 -> destination=:1.42 serial=153 reply_serial=70
   variant       boolean false
method return time=1712191490.095937 sender=:1.6 -> destination=:1.42 serial=154 reply_serial=71
   variant       boolean false
signal time=1712191491.057443 sender=:1.6 -> destination=(null destination) serial=155 path=/org/bluez/hci0/dev_5C_C6_E9_3A_27_6E; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.bluez.MediaControl1"
   array [
      dict entry(
         string "Connected"
         variant             boolean true
      )
   ]
   array [
   ]
signal time=1712191491.080009 sender=:1.6 -> destination=(null destination) serial=156 path=/org/bluez/hci0/dev_5C_C6_E9_3A_27_6E/sep1/fd1; interface=org.freedesktop.DBus.Properties; member=PropertiesChanged
   string "org.bluez.MediaTransport1"
   array [
      dict entry(
         string "Volume"
         variant             uint16 96
      )
   ]
   array [
   ]

It seems that the battery status message is dispatched before the message for setting the Connected property. Could that have something to do with this?

What I had to do for screenshare to work on hyprland was to set the WM to execute on login dbus-update-activation-environment --systemd WAYLAND_DISPLAY XDG_CURRENT_DESKTOP.

cschramm commented 5 months ago

That definitely shouldn't break anything.

I suppose you disconnected the already connected device and re-connected it 2 or 3 seconds later? As expected, Battery1 and MediaEndpoint1 interfaces get removed and added accordingly and there are some PropertiesChanged signals for them. The signals with a "Connected" property are for MediaControl1. Signals for Device1 are completely missing.

Anything in the bluetooth.service logs?

Does the device object even have the interface? You can e.g. check

sudo dbus-send --print-reply --system --dest=org.bluez /org/bluez/hci0/dev_5C_C6_E9_3A_27_6E org.freedesktop.DBus.Introspectable.Introspect

for org.bluez.Device1 or have a look at it with d-feet.

cschramm commented 5 months ago

Also, if you have downgrade at hand, it could make sense to try slightly older bluez to see if that changes anything.

(For reference: https://github.com/bluez/bluez/blob/5.73/src/device.c#L3323-L3324 is where the signal should get emitted and I do not really see a path for that not to happen)

MaxXor commented 5 months ago

There is no entry in the log that shows the device was connected. I must say that bluetooth has been flaky on arch for me. I just connected my DualSense by pressing a button on it but there is no signal whatsoever about it on the bus. It definitely connected as it works on dolphin-emu.

AFAIK kernel 6.8.1 and 6.8.2 contain a bluetooth regression, downgrading to 6.7.9 works fine for me. With blueman 2.4 and 2.3.5. It could be fixed in 6.8.3 but I didn't had the chance to test it yet: https://bbs.archlinux.org/viewtopic.php?id=294310&p=3

cschramm commented 5 months ago

@MaxXor: Thanks for the hint. So you do see the same issue with those kernels? I'm actually running fine on them, but probably the bug has some conditions.

MaxXor commented 5 months ago

Currently back to using 6.8.2 and see the same issue. I'm waiting for Arch to release linux 6.8.3 from testing to stable repos so I can test 6.8.3.

cschramm commented 5 months ago

Looks like the right direction.

ABRT logs something like this in Fedora every few months: https://bugzilla.redhat.com/buglist.cgi?quicksearch=connectionnotifier Interestingly I cannot find anything similar on the Ubuntu error tracker.

I noticed a huge spike of 2 reports there yesterday ( :sweat_smile: ). Those are for kernel 6.7.11 and it actually seems like that has the same regression as 6.8.2 and fixed in 6.7.12.

6.8.1 and 6.7.10 do not seem to be affected.

infirit commented 5 months ago

That kernel issue bug report is exactly what I am seeing with the DualSense. Let's hope 6.8.~2~3 fixes this.

gchamon commented 5 months ago

should it also affect linux-lts?

$ uname -a
Linux anarchy 6.6.23-1-lts #1 SMP PREEMPT_DYNAMIC Wed, 27 Mar 2024 07:47:20 +0000 x86_64 GNU/Linux
cschramm commented 5 months ago

Yes, 6.8.2, 6.7.11, 6.6.23 and 6.1.83 seem to be affected.

MaxXor commented 5 months ago

I tested linux 6.8.4 and it's NOT fixed yet. However a patch has been mentioned in the bugzilla issue: https://bugzilla.kernel.org/show_bug.cgi?id=218680

Hopefully it makes it way to 6.8.5 soon.

cschramm commented 5 months ago

Yes, 6.8.2, 6.7.11, 6.6.23 and 6.1.83 seem to be affected.

Correction: 6.1 should not be affected. The other versions introduced a bug for which https://lore.kernel.org/lkml/20240404185022.1.Ic27505c8f1ca7d4a653b1dcc1b08cdfc862a4622@changeid/T/ seems to be a proper fix that did not make it into 6.8.4 or 6.6.25 (6.7 is doomed anyway).

MaxXor commented 5 months ago

Latest linux kernel in arch linux 6.8.5 includes the patch and it's working again correctly. It should be upstreamed too and I think this issue can be closed here?

https://github.com/archlinux/linux/commits/v6.8.5-arch1/

cschramm commented 5 months ago

I just double checked and unfortunately the fix did not make it into any kernel release yet (it will be in 6.9-rc4, though). Arch Linux now maintains a patch, though, and from what I see I'd expect it in 6.8.7 and 6.6.28.

cschramm commented 5 months ago

6.6.28 and 6.8.7 have the fix.

gchamon commented 4 months ago

@cschramm can confirm that blueman now works as expected. Thanks for the support and patience! You guys do a wonderful job for the community. Hope one day I can give back.