bleak icon indicating copy to clipboard operation
bleak copied to clipboard
verified publisher icon hbldh

Race resolving services with BlueZ d-bus backend

Open bdraco opened this issue 4 months ago • 10 comments

Some times chars & services appear to be be missing because ServicesResolved comes before the actual services/chars are added to dbus.

To reproduce you must restart dbus as the problem only happens on the first connect before the interfaces are added.

Flow is

PropertiesChanged Connnected: True ... PropertiesChanged ServicesResolved: True ... Than each interface is actually added.

But _wait_for_services_discovery has already started consuming them before they are finished adding. https://github.com/hbldh/bleak/blob/a65eb33845fead04e556afc6e4a7398585ff79c0/bleak/backends/bluezdbus/manager.py#L677C20-L677C48

2025-08-09 00:21:31.061 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2): ['org.bluez.Device1', {'UUIDs': <dbus_fast.signature.Variant ('as', ['0000003e-0000-1000-8000-0026bb765291', '00000043-0000-1000-8000-0026bb765291', '00000055-0000-1000-8000-0026bb765291', '00000096-0000-1000-8000-0026bb765291', '000000a2-0000-1000-8000-0026bb765291', '00000239-0000-1000-8000-0026bb765291', '00000701-0000-1000-8000-0026bb765291', '00001800-0000-1000-8000-00805f9b34fb', '00001801-0000-1000-8000-00805f9b34fb', 'e863f007-079e-48ff-8f27-9c2605a29f52'])>, 'ServicesResolved': <dbus_fast.signature.Variant ('b', True)>}, []]
2025-08-09 00:21:31.062 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000a', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattService1': {'Handle': <dbus_fast.signature.Variant ('q', 10)>, 'UUID': <dbus_fast.signature.Variant ('s', 00001801-0000-1000-8000-00805f9b34fb)>, 'Device': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2)>, 'Primary': <dbus_fast.signature.Variant ('b', True)>, 'Includes': <dbus_fast.signature.Variant ('ao', [])>}, 'org.freedesktop.DBus.Properties': {}}]
2025-08-09 00:21:31.062 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattService1': {'Handle': <dbus_fast.signature.Variant ('q', 11)>, 'UUID': <dbus_fast.signature.Variant ('s', 0000003e-0000-1000-8000-0026bb765291)>, 'Device': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2)>, 'Primary': <dbus_fast.signature.Variant ('b', True)>, 'Includes': <dbus_fast.signature.Variant ('ao', [])>}, 'org.freedesktop.DBus.Properties': {}}]
2025-08-09 00:21:31.065 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b/char000c', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 12)>, 'UUID': <dbus_fast.signature.Variant ('s', e604e95d-a759-4817-87d3-aa005083a0d1)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b)>, 'Value': <dbus_fast.signature.Variant ('ay', b'')>, 'Flags': <dbus_fast.signature.Variant ('as', ['read'])>, 'MTU': <dbus_fast.signature.Variant ('q', 512)>}, 'org.freedesktop.DBus.Properties': {}}]
2025-08-09 00:21:31.066 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b/char000e', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 14)>, 'UUID': <dbus_fast.signature.Variant ('s', 00000014-0000-1000-8000-0026bb765291)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b)>, 'Value': <dbus_fast.signature.Variant ('ay', b'')>, 'Flags': <dbus_fast.signature.Variant ('as', ['read', 'write'])>, 'MTU': <dbus_fast.signature.Variant ('q', 512)>}, 'org.freedesktop.DBus.Properties': {}}]
2025-08-09 00:21:31.066 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b/char000e/desc0010', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattDescriptor1': {'Handle': <dbus_fast.signature.Variant ('q', 45741)>, 'UUID': <dbus_fast.signature.Variant ('s', dc46f0fe-81d2-4616-b5d9-6abdd796939a)>, 'Characteristic': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b/char000e)>, 'Value': <dbus_fast.signature.Variant ('ay', b'')>}, 'org.freedesktop.DBus.Properties': {}}]
2025-08-09 00:21:31.067 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b/char0011', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 17)>, 'UUID': <dbus_fast.signature.Variant ('s', 00000020-0000-1000-8000-0026bb765291)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b)>, 'Value': <dbus_fast.signature.Variant ('ay', b'')>, 'Flags': <dbus_fast.signature.Variant ('as', ['read', 'write'])>, 'MTU': <dbus_fast.signature.Variant ('q', 512)>}, 'org.freedesktop.DBus.Properties': {}}]
2025-08-09 00:21:31.067 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b/char0011/desc0013', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattDescriptor1': {'Handle': <dbus_fast.signature.Variant ('q', 45741)>, 'UUID': <dbus_fast.signature.Variant ('s', dc46f0fe-81d2-4616-b5d9-6abdd796939a)>, 'Characteristic': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b/char0011)>, 'Value': <dbus_fast.signature.Variant ('ay', b'')>}, 'org.freedesktop.DBus.Properties': {}}]
2025-08-09 00:21:31.068 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b/char0014', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 20)>, 'UUID': <dbus_fast.signature.Variant ('s', 00000021-0000-1000-8000-0026bb765291)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b)>, 'Value': <dbus_fast.signature.Variant ('ay', b'')>, 'Flags': <dbus_fast.signature.Variant ('as', ['read', 'write'])>, 'MTU': <dbus_fast.signature.Variant ('q', 512)>}, 'org.freedesktop.DBus.Properties': {}}]
2025-08-09 00:21:31.068 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b/char0014/desc0016', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattDescriptor1': {'Handle': <dbus_fast.signature.Variant ('q', 45741)>, 'UUID': <dbus_fast.signature.Variant ('s', dc46f0fe-81d2-4616-b5d9-6abdd796939a)>, 'Characteristic': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b/char0014)>, 'Value': <dbus_fast.signature.Variant ('ay', b'')>}, 'org.freedesktop.DBus.Properties': {}}]
2025-08-09 00:21:31.068 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b/char0017', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 23)>, 'UUID': <dbus_fast.signature.Variant ('s', 00000023-0000-1000-8000-0026bb765291)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b)>, 'Value': <dbus_fast.signature.Variant ('ay', b'')>, 'Flags': <dbus_fast.signature.Variant ('as', ['read', 'write'])>, 'MTU': <dbus_fast.signature.Variant ('q', 512)>}, 'org.freedesktop.DBus.Properties': {}}]
2025-08-09 00:21:31.069 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b/char0017/desc0019', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattDescriptor1': {'Handle': <dbus_fast.signature.Variant ('q', 45741)>, 'UUID': <dbus_fast.signature.Variant ('s', dc46f0fe-81d2-4616-b5d9-6abdd796939a)>, 'Characteristic': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b/char0017)>, 'Value': <dbus_fast.signature.Variant ('ay', b'')>}, 'org.freedesktop.DBus.Properties': {}}]
2025-08-09 00:21:31.069 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b/char001a', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 26)>, 'UUID': <dbus_fast.signature.Variant ('s', 00000030-0000-1000-8000-0026bb765291)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b)>, 'Value': <dbus_fast.signature.Variant ('ay', b'')>, 'Flags': <dbus_fast.signature.Variant ('as', ['read', 'write'])>, 'MTU': <dbus_fast.signature.Variant ('q', 512)>}, 'org.freedesktop.DBus.Properties': {}}]
2025-08-09 00:21:31.070 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b/char001a/desc001c', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattDescriptor1': {'Handle': <dbus_fast.signature.Variant ('q', 45741)>, 'UUID': <dbus_fast.signature.Variant ('s', dc46f0fe-81d2-4616-b5d9-6abdd796939a)>, 'Characteristic': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000b/char001a)>, 'Value': <dbus_fast.signature.Variant ('ay', b'')>}, 'org.freedesktop.DBus.Properties': {}}]
.... many more added....
2025-08-09 00:21:31.113 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service009e/char00af', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 175)>, 'UUID': <dbus_fast.signature.Variant ('s', 0000008f-0000-1000-8000-0026bb765291)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service009e)>, 'Value': <dbus_fast.signature.Variant ('ay', b'')>, 'Notifying': <dbus_fast.signature.Variant ('b', False)>, 'Flags': <dbus_fast.signature.Variant ('as', ['read', 'write', 'indicate'])>, 'MTU': <dbus_fast.signature.Variant ('q', 512)>}, 'org.freedesktop.DBus.Properties': {}}]
2025-08-09 00:21:31.114 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service009e/char00af/desc00b1', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattDescriptor1': {'Handle': <dbus_fast.signature.Variant ('q', 45742)>, 'UUID': <dbus_fast.signature.Variant ('s', 00002902-0000-1000-8000-00805f9b34fb)>, 'Characteristic': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service009e/char00af)>, 'Value': <dbus_fast.signature.Variant ('ay', b'')>}, 'org.freedesktop.DBus.Properties': {}}]
2025-08-09 00:21:31.114 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service009e/char00af/desc00b2', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattDescriptor1': {'Handle': <dbus_fast.signature.Variant ('q', 45742)>, 'UUID': <dbus_fast.signature.Variant ('s', dc46f0fe-81d2-4616-b5d9-6abdd796939a)>, 'Characteristic': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service009e/char00af)>, 'Value': <dbus_fast.signature.Variant ('ay', b'')>}, 'org.freedesktop.DBus.Properties': {}}]
2025-08-09 00:21:31.115 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_60_55_F9_2B_36_C2): ['org.bluez.Device1', {'RSSI': <dbus_fast.signature.Variant ('n', -55)>}, []]
2025-08-09 00:21:31.119 DEBUG (MainThread) [habluetooth.channels.bluez] Loaded conn params for E1:5D:7E:6A:CF:F2: interval=7-9, latency=0, timeout=800
2025-08-09 00:21:31.119 DEBUG (MainThread) [habluetooth.wrappers] E1:5D:7E:6A:CF:F2 - Eve Flare 17D2 -> /org/bluez/hci0: Loaded ConnectParams.MEDIUM connection parameters
2025-08-09 00:21:31.119 DEBUG (MainThread) [habluetooth.wrappers] E1:5D:7E:6A:CF:F2 - Eve Flare 17D2 -> /org/bluez/hci0: Connected via hci0 (E4:5F:01:D0:EA:29) (last rssi: -88)
2025-08-09 00:21:31.119 DEBUG (MainThread) [bleak_retry_connector] Eve (E1:5D:7E:6A:CF:F2) - E1:5D:7E:6A:CF:F2: Connected after 1 attempts
2025-08-09 00:21:31.131 DEBUG (MainThread) [habluetooth.channels.bluez] hci0: Connection parameters loaded successfully

bdraco avatar Aug 09 '25 05:08 bdraco

And sometimes it comes after

2025-08-09 00:47:46.784 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_DC_0D_15_36_CD_C9): ['org.bluez.Device1', {'ServiceData': <dbus_fast.signature.Variant ('a{sv}', {'0000feaa-0000-1000-8000-00805f9b34fb': <dbus_fast.signature.Variant ('ay', b' \x00\x0b\xe6\x80\x00\x04\x0b\xbdJEn\xd4\xe6')>})>}, []]
2025-08-09 00:47:47.036 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_CC_F4_C4_F9_AC_6C): ['org.bluez.Device1', {'Connected': <dbus_fast.signature.Variant ('b', True)>}, []]
2025-08-09 00:47:47.345 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_CC_F4_C4_F9_AC_6C/service000a', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattService1': {'Handle': <dbus_fast.signature.Variant ('q', 10)>, 'UUID': <dbus_fast.signature.Variant ('s', 00001801-0000-1000-8000-00805f9b34fb)>, 'Device': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_CC_F4_C4_F9_AC_6C)>, 'Primary': <dbus_fast.signature.Variant ('b', True)>, 'Includes': <dbus_fast.signature.Variant ('ao', [])>}, 'org.freedesktop.DBus.Properties': {}}]
2025-08-09 00:47:47.345 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_CC_F4_C4_F9_AC_6C/service000b', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattService1': {'Handle': <dbus_fast.signature.Variant ('q', 11)>, 'UUID': <dbus_fast.signature.Variant ('s', cba20d00-224d-11e6-9fb8-0002a5d5c51b)>, 'Device': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_CC_F4_C4_F9_AC_6C)>, 'Primary': <dbus_fast.signature.Variant ('b', True)>, 'Includes': <dbus_fast.signature.Variant ('ao', [])>}, 'org.freedesktop.DBus.Properties': {}}]
2025-08-09 00:47:47.346 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_CC_F4_C4_F9_AC_6C/service000b/char000c', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 12)>, 'UUID': <dbus_fast.signature.Variant ('s', cba20002-224d-11e6-9fb8-0002a5d5c51b)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_CC_F4_C4_F9_AC_6C/service000b)>, 'Value': <dbus_fast.signature.Variant ('ay', b'')>, 'Flags': <dbus_fast.signature.Variant ('as', ['write-without-response', 'write'])>, 'WriteAcquired': <dbus_fast.signature.Variant ('b', False)>, 'MTU': <dbus_fast.signature.Variant ('q', 247)>}, 'org.freedesktop.DBus.Properties': {}}]
2025-08-09 00:47:47.349 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_CC_F4_C4_F9_AC_6C/service000b/char000e', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 14)>, 'UUID': <dbus_fast.signature.Variant ('s', cba20003-224d-11e6-9fb8-0002a5d5c51b)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_CC_F4_C4_F9_AC_6C/service000b)>, 'Value': <dbus_fast.signature.Variant ('ay', b'')>, 'Notifying': <dbus_fast.signature.Variant ('b', False)>, 'Flags': <dbus_fast.signature.Variant ('as', ['notify'])>, 'NotifyAcquired': <dbus_fast.signature.Variant ('b', False)>, 'MTU': <dbus_fast.signature.Variant ('q', 247)>}, 'org.freedesktop.DBus.Properties': {}}]
2025-08-09 00:47:47.349 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_CC_F4_C4_F9_AC_6C/service000b/char000e/desc0010', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattDescriptor1': {'Handle': <dbus_fast.signature.Variant ('q', 45744)>, 'UUID': <dbus_fast.signature.Variant ('s', 00002902-0000-1000-8000-00805f9b34fb)>, 'Characteristic': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_CC_F4_C4_F9_AC_6C/service000b/char000e)>, 'Value': <dbus_fast.signature.Variant ('ay', b'')>}, 'org.freedesktop.DBus.Properties': {}}]
2025-08-09 00:47:47.350 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_CC_F4_C4_F9_AC_6C): ['org.bluez.Device1', {'UUIDs': <dbus_fast.signature.Variant ('as', ['00001800-0000-1000-8000-00805f9b34fb', '00001801-0000-1000-8000-00805f9b34fb', 'cba20d00-224d-11e6-9fb8-0002a5d5c51b'])>, 'ServicesResolved': <dbus_fast.signature.Variant ('b', True)>}, []]
2025-08-09 00:47:47.351 DEBUG (MainThread) [habluetooth.channels.bluez] Loaded conn params for CC:F4:C4:F9:AC:6C: interval=7-9, latency=0, timeout=800
2025-08-09 00:47:47.352 DEBUG (MainThread) [habluetooth.wrappers] CC:F4:C4:F9:AC:6C - None -> /org/bluez/hci0: Loaded ConnectParams.MEDIUM connection parameters
2025-08-09 00:47:47.352 DEBUG (MainThread) [habluetooth.wrappers] CC:F4:C4:F9:AC:6C - None -> /org/bluez/hci0: Connected via hci0 (E4:5F:01:D0:EA:29) (last rssi: -64)
2025-08-09 00:47:47.352 DEBUG (MainThread) [bleak_retry_connector] None (CC:F4:C4:F9:AC:6C) - CC:F4:C4:F9:AC:6C: Connected after 1 attempts
2025-08-09 00:47:47.353 DEBUG (MainThread) [switchbot.devices.device] None (CC:F4:C4:F9:AC:6C): Connected; RSSI: -70
2025-08-09 00:47:47.353 DEBUG (MainThread) [switchbot.devices.device] None (CC:F4:C4:F9:AC:6C): Starting notify and disconnect timer; RSSI: -70

bdraco avatar Aug 09 '25 05:08 bdraco

Looks like the race only happens when it preceded by retry due to le-connection-abort-by-local

2025-08-09 00:21:27.106 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to BlueZ path /org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2
2025-08-09 00:21:27.465 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2): ['org.bluez.Device1', {'Connected': <dbus_fast.signature.Variant ('b', True)>}, []]
2025-08-09 00:21:27.514 DEBUG (MainThread) [bleak.backends.bluezdbus.client] retry due to le-connection-abort-by-local
2025-08-09 00:21:27.538 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2): ['org.bluez.Device1', {'Connected': <dbus_fast.signature.Variant ('b', False)>}, []]
2025-08-09 00:21:27.539 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Device disconnected (/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2)
2025-08-09 00:21:27.539 DEBUG (MainThread) [bleak.backends.bluezdbus.client] _cleanup_all(/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2)
2025-08-09 00:21:27.540 DEBUG (MainThread) [bleak.backends.bluezdbus.client] _cleanup_all(/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2)
2025-08-09 00:21:27.540 DEBUG (MainThread) [bleak.backends.bluezdbus.client] already disconnected (/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2)
2025-08-09 00:21:27.548 DEBUG (MainThread) [bleak.backends.bluezdbus.client] Connecting to BlueZ path /org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2
00-0026bb765291', '00000043-0000-1000-8000-0026bb765291', '00000055-0000-1000-8000-0026bb765291', '00000096-0000-1000-8000-0026bb765291', '000000a2-0000-1000-8000-0026bb765291', '00000239-0000-1000-8000-0026bb765291', '00000701-0000-1000-8000-0026bb765291', '00001800-0000-1000-8000-00805f9b34fb', '00001801-0000-1000-8000-00805f9b34fb', 'e863f007-079e-48ff-8f27-9c2605a29f52'])>, 'ServicesResolved': <dbus_fast.signature.Variant ('b', True)>}, []]
2025-08-09 00:21:31.062 DEBUG (MainThread) [bleak.backends.bluezdbus.manager] received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2/service000a', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattService1': {'Handle': <dbus_fast.signature.Variant ('q', 10)>, 'UUID': <dbus_fast.signature.Variant ('s', 00001801-0000-1000-8000-00805f9b34fb)>, 'Device': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_E1_5D_7E_6A_CF_F2)>, 'Primary': <dbus_fast.signature.Variant ('b', True)>, 'Includes': <dbus_fast.signature.Variant ('ao', [])>}, 'org.freedesktop.DBus.Properties': {}}]

bdraco avatar Aug 09 '25 05:08 bdraco

Probably a bug in the bluez state machine.

bdraco avatar Aug 09 '25 05:08 bdraco

BlueZ version?

dlech avatar Aug 09 '25 14:08 dlech

5.79

bdraco avatar Aug 09 '25 15:08 bdraco

I didn't see any changes BlueZ that would change this. The order looks right in BlueZ. So might be a race in dbus

bdraco avatar Aug 09 '25 16:08 bdraco

Or a race in glib idle callbacks

bdraco avatar Aug 09 '25 16:08 bdraco

The order looks right in BlueZ.

We should be able to look at debug logs in BlueZ to verify this.

DBG("%s err %d", dev->path, err); is called when "ServicesResolved"

DBG("Exported GATT characteristic: %s", chrc->path); is called when "InterfacesAdded".

dlech avatar Aug 09 '25 16:08 dlech

This is a blueZ problem

More details in https://github.com/bluez/bluez/issues/1489#issuecomment-3212294880

I sent a patch

bdraco avatar Aug 21 '25 22:08 bdraco

Good to know. Thanks for the followup.

dlech avatar Aug 21 '25 22:08 dlech