Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Timeout exception connecting to BLE plug - bluetoothctl works. #1505

Closed
baudneo opened this issue Feb 10, 2024 · 3 comments
Closed

Timeout exception connecting to BLE plug - bluetoothctl works. #1505

baudneo opened this issue Feb 10, 2024 · 3 comments
Labels
3rd party issue The issue is with the Bluetooth stack, the BLE device, or other 3rd party code not with Bleak itself Backend: BlueZ Issues and PRs relating to the BlueZ backend

Comments

@baudneo
Copy link

baudneo commented Feb 10, 2024

  • bleak version:
    0.21.1
  • Python version:
    3.10.12 and 3.11.6
  • Operating System:
    Ubuntu Jammy and Arch
  • BlueZ version (bluetoothctl -v) in case of Linux:
    5.66 and 5.72

Description

I have tested this on 2 different machines. Each machine has a different bt adapter and different versions of bluez/kernels.

I can connect to other BT devices using bleak, it is just this specififc device. The device is a bluetooth/wifi telink device; Cync by GE smart plug. I can get a connection using bluetoothctl but I can not get a connection using bleak.
There are a few different errors, I detail 3 of them below in logging.

What I Did

The issue is with BleakClient(mac_addr).connect(), using a context manager and without. I am assuming this is some sort of bad device implementation? I am trying to get good bluetoothctl, btmon and pcaps for each error.

Logs

Here is my script output with BLEAK_LOGGING=1. I will detail a few different errors with this device.

Timeout

The plug connects, throws some errors and disconnects

02/10/24 11:30:40.0603 DEBUG - acync.mesh mesh:408 -> telink mesh:connect: attempt: 1/3 to MAC (4/4): 34:13:43:70:D9:2E [Cync Plug] - Scan Timeout: 10
2024-02-10 11:30:40,603 bleak.backends.bluezdbus.client MainThread DEBUG: Connecting to device @ 34:13:43:70:D9:2E
2024-02-10 11:30:40,646 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', True)>}, []]
2024-02-10 11:30:40,747 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_C0_23_8D_D6_3E_AA', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.Device1': {'Address': <dbus_fast.signature.Variant ('s', C0:23:8D:D6:3E:AA)>, 'AddressType': <dbus_fast.signature.Variant ('s', public)>, 'Name': <dbus_fast.signature.Variant ('s', [TV] Samsung TU7000 50 TV)>, 'Alias': <dbus_fast.signature.Variant ('s', [TV] Samsung TU7000 50 TV)>, 'Paired': <dbus_fast.signature.Variant ('b', False)>, 'Bonded': <dbus_fast.signature.Variant ('b', False)>, 'Trusted': <dbus_fast.signature.Variant ('b', False)>, 'Blocked': <dbus_fast.signature.Variant ('b', False)>, 'LegacyPairing': <dbus_fast.signature.Variant ('b', False)>, 'RSSI': <dbus_fast.signature.Variant ('n', -96)>, 'Connected': <dbus_fast.signature.Variant ('b', False)>, 'UUIDs': <dbus_fast.signature.Variant ('as', [])>, 'Adapter': <dbus_fast.signature.Variant ('o', /org/bluez/hci0)>, 'ManufacturerData': <dbus_fast.signature.Variant ('a{qv}', {117: <dbus_fast.signature.Variant ('ay', bytearray(b'B\x04\x01\x80f\xc0#\x8d\xd6>\xaa\xc2#\x8d\xd6>\xa9\x01\x00\x00\x00\x00\x00\x00'))>})>, 'ServicesResolved': <dbus_fast.signature.Variant ('b', False)>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:30:40,747 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_78_6D_EB_28_EA_A3', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.Device1': {'Address': <dbus_fast.signature.Variant ('s', 78:6D:EB:28:EA:A3)>, 'AddressType': <dbus_fast.signature.Variant ('s', public)>, 'Name': <dbus_fast.signature.Variant ('s', 7B19400144A4D0F4)>, 'Alias': <dbus_fast.signature.Variant ('s', 7B19400144A4D0F4)>, 'Paired': <dbus_fast.signature.Variant ('b', False)>, 'Bonded': <dbus_fast.signature.Variant ('b', False)>, 'Trusted': <dbus_fast.signature.Variant ('b', False)>, 'Blocked': <dbus_fast.signature.Variant ('b', False)>, 'LegacyPairing': <dbus_fast.signature.Variant ('b', False)>, 'RSSI': <dbus_fast.signature.Variant ('n', -58)>, 'Connected': <dbus_fast.signature.Variant ('b', False)>, 'UUIDs': <dbus_fast.signature.Variant ('as', [])>, 'Adapter': <dbus_fast.signature.Variant ('o', /org/bluez/hci0)>, 'ManufacturerData': <dbus_fast.signature.Variant ('a{qv}', {529: <dbus_fast.signature.Variant ('ay', bytearray(b'\x11\x02\xa3\xea(\xeb\x1f\x00\x01\x01\x00\x00\x01\x02\x03\x04\x05\x06\x07\x08\t\n\x0b\x0c\r\x0e\x0f'))>})>, 'ServicesResolved': <dbus_fast.signature.Variant ('b', False)>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:30:40,901 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.Device1': {'Address': <dbus_fast.signature.Variant ('s', 34:13:43:70:D9:2E)>, 'AddressType': <dbus_fast.signature.Variant ('s', public)>, 'Name': <dbus_fast.signature.Variant ('s', 7B19400144A4D0F4)>, 'Alias': <dbus_fast.signature.Variant ('s', 7B19400144A4D0F4)>, 'Paired': <dbus_fast.signature.Variant ('b', False)>, 'Bonded': <dbus_fast.signature.Variant ('b', False)>, 'Trusted': <dbus_fast.signature.Variant ('b', False)>, 'Blocked': <dbus_fast.signature.Variant ('b', False)>, 'LegacyPairing': <dbus_fast.signature.Variant ('b', False)>, 'RSSI': <dbus_fast.signature.Variant ('n', -56)>, 'Connected': <dbus_fast.signature.Variant ('b', False)>, 'UUIDs': <dbus_fast.signature.Variant ('as', [])>, 'Adapter': <dbus_fast.signature.Variant ('o', /org/bluez/hci0)>, 'ManufacturerData': <dbus_fast.signature.Variant ('a{qv}', {529: <dbus_fast.signature.Variant ('ay', bytearray(b'\x11\x02.\xd9pCD\x00\x01\x04\x004\x13Cx\xd9.\x06\x07\x08\t\n\x0b\x0c\r\x0e\x0f'))>})>, 'ServicesResolved': <dbus_fast.signature.Variant ('b', False)>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:30:40,910 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_C0_23_8D_D6_3E_AA): ['org.bluez.Device1', {}, ['RSSI']]
2024-02-10 11:30:40,911 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_C0_23_8D_D6_3E_AA', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
2024-02-10 11:30:40,911 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_34_13_43_70_D9_2E): ['org.bluez.Device1', {}, ['RSSI']]
2024-02-10 11:30:40,911 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_78_6D_EB_28_EA_A3): ['org.bluez.Device1', {}, ['RSSI']]
2024-02-10 11:30:40,911 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
2024-02-10 11:30:40,914 bleak.backends.bluezdbus.client MainThread DEBUG: Connecting to BlueZ path /org/bluez/hci0/dev_34_13_43_70_D9_2E
2024-02-10 11:30:50,915 bleak.backends.bluezdbus.client MainThread DEBUG: _cleanup_all(/org/bluez/hci0/dev_34_13_43_70_D9_2E)
02/10/24 11:30:50.0915 WARNING - acync.mesh mesh:428 -> telink mesh:connect: EXCEPTION! Unable to CONNECT to device: 34:13:43:70:D9:2E [Cync Plug] -->
Traceback (most recent call last):
  File "/home/baudneo/cync2mqtt/venv/lib/python3.11/site-packages/bleak/backends/bluezdbus/client.py", line 209, in connect
    reply = await self._bus.call(
            ^^^^^^^^^^^^^^^^^^^^^
  File "/home/baudneo/cync2mqtt/venv/lib/python3.11/site-packages/dbus_fast/aio/message_bus.py", line 384, in call
    await future
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/home/baudneo/PycharmProjects/cync2mqtt/src/acync/mesh.py", line 422, in connect
    await self.client.connect()
  File "/home/baudneo/PycharmProjects/cync2mqtt/src/acync/mesh.py", line 267, in connect
    status = await self.client.connect(timeout=timeout)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/baudneo/cync2mqtt/venv/lib/python3.11/site-packages/bleak/__init__.py", line 605, in connect
    return await self._backend.connect(**kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/baudneo/cync2mqtt/venv/lib/python3.11/site-packages/bleak/backends/bluezdbus/client.py", line 146, in connect
    async with async_timeout(timeout):
  File "/usr/lib/python3.11/asyncio/timeouts.py", line 111, in __aexit__
    raise TimeoutError from exc_val
TimeoutError
2024-02-10 11:30:50,922 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]

Write Not Permitted

Device connects, throws this specififc error and disconnects.

02/10/24 11:47:30.0887 DEBUG - acync.mesh mesh:408 -> telink mesh:connect: attempt: 2/3 to MAC (4/4): 34:13:43:70:D9:2E [Cync Plug] - Scan Timeout: 10
2024-02-10 11:47:30,887 bleak.backends.bluezdbus.client MainThread DEBUG: Connecting to device @ 34:13:43:70:D9:2E
2024-02-10 11:47:30,897 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', True)>}, []]
2024-02-10 11:47:30,967 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.Device1': {'Address': <dbus_fast.signature.Variant ('s', 34:13:43:70:D9:2E)>, 'AddressType': <dbus_fast.signature.Variant ('s', public)>, 'Name': <dbus_fast.signature.Variant ('s', 7B19400144A4D0F4)>, 'Alias': <dbus_fast.signature.Variant ('s', 7B19400144A4D0F4)>, 'Paired': <dbus_fast.signature.Variant ('b', False)>, 'Bonded': <dbus_fast.signature.Variant ('b', False)>, 'Trusted': <dbus_fast.signature.Variant ('b', False)>, 'Blocked': <dbus_fast.signature.Variant ('b', False)>, 'LegacyPairing': <dbus_fast.signature.Variant ('b', False)>, 'RSSI': <dbus_fast.signature.Variant ('n', -58)>, 'Connected': <dbus_fast.signature.Variant ('b', False)>, 'UUIDs': <dbus_fast.signature.Variant ('as', [])>, 'Adapter': <dbus_fast.signature.Variant ('o', /org/bluez/hci0)>, 'ManufacturerData': <dbus_fast.signature.Variant ('a{qv}', {529: <dbus_fast.signature.Variant ('ay', bytearray(b'\x11\x02.\xd9pCD\x00\x01\x04\x004\x13Cx\xd9.\x06\x07\x08\t\n\x0b\x0c\r\x0e\x0f'))>})>, 'ServicesResolved': <dbus_fast.signature.Variant ('b', False)>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:30,969 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_34_13_43_70_D9_2E): ['org.bluez.Device1', {}, ['RSSI']]
2024-02-10 11:47:30,970 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
2024-02-10 11:47:30,972 bleak.backends.bluezdbus.client MainThread DEBUG: Connecting to BlueZ path /org/bluez/hci0/dev_34_13_43_70_D9_2E
2024-02-10 11:47:31,257 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_34_13_43_70_D9_2E): ['org.bluez.Device1', {'Connected': <dbus_fast.signature.Variant ('b', True)>}, []]
2024-02-10 11:47:34,578 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0007', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattService1': {'Handle': <dbus_fast.signature.Variant ('q', 7)>, 'UUID': <dbus_fast.signature.Variant ('s', 0000180a-0000-1000-8000-00805f9b34fb)>, 'Device': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E)>, 'Primary': <dbus_fast.signature.Variant ('b', True)>, 'Includes': <dbus_fast.signature.Variant ('ao', [])>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,579 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0007/char0008', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 8)>, 'UUID': <dbus_fast.signature.Variant ('s', 00002a26-0000-1000-8000-00805f9b34fb)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E/service0007)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>, 'Flags': <dbus_fast.signature.Variant ('as', ['read'])>, 'MTU': <dbus_fast.signature.Variant ('q', 247)>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,579 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0007/char000a', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 10)>, 'UUID': <dbus_fast.signature.Variant ('s', 00002a29-0000-1000-8000-00805f9b34fb)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E/service0007)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>, 'Flags': <dbus_fast.signature.Variant ('as', ['read'])>, 'MTU': <dbus_fast.signature.Variant ('q', 247)>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,579 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0007/char000c', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 12)>, 'UUID': <dbus_fast.signature.Variant ('s', 00002a24-0000-1000-8000-00805f9b34fb)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E/service0007)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>, 'Flags': <dbus_fast.signature.Variant ('as', ['read'])>, 'MTU': <dbus_fast.signature.Variant ('q', 247)>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,579 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0007/char000e', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 14)>, 'UUID': <dbus_fast.signature.Variant ('s', 00002a27-0000-1000-8000-00805f9b34fb)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E/service0007)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>, 'Flags': <dbus_fast.signature.Variant ('as', ['read'])>, 'MTU': <dbus_fast.signature.Variant ('q', 247)>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,579 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0010', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattService1': {'Handle': <dbus_fast.signature.Variant ('q', 16)>, 'UUID': <dbus_fast.signature.Variant ('s', 00010203-0405-0607-0809-0a0b0c0d1910)>, 'Device': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E)>, 'Primary': <dbus_fast.signature.Variant ('b', True)>, 'Includes': <dbus_fast.signature.Variant ('ao', [])>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,579 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0010/char0011', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 17)>, 'UUID': <dbus_fast.signature.Variant ('s', 00010203-0405-0607-0809-0a0b0c0d1911)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E/service0010)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>, 'Notifying': <dbus_fast.signature.Variant ('b', False)>, 'Flags': <dbus_fast.signature.Variant ('as', ['read', 'write-without-response', 'write', 'notify'])>, 'WriteAcquired': <dbus_fast.signature.Variant ('b', False)>, 'NotifyAcquired': <dbus_fast.signature.Variant ('b', False)>, 'MTU': <dbus_fast.signature.Variant ('q', 247)>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,579 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0010/char0011/desc0013', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattDescriptor1': {'Handle': <dbus_fast.signature.Variant ('q', 823)>, 'UUID': <dbus_fast.signature.Variant ('s', 00002902-0000-1000-8000-00805f9b34fb)>, 'Characteristic': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E/service0010/char0011)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,579 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0010/char0014', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 20)>, 'UUID': <dbus_fast.signature.Variant ('s', 00010203-0405-0607-0809-0a0b0c0d1912)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E/service0010)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>, 'Flags': <dbus_fast.signature.Variant ('as', ['read', 'write-without-response', 'write'])>, 'WriteAcquired': <dbus_fast.signature.Variant ('b', False)>, 'MTU': <dbus_fast.signature.Variant ('q', 247)>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,579 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0010/char0014/desc0016', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattDescriptor1': {'Handle': <dbus_fast.signature.Variant ('q', 822)>, 'UUID': <dbus_fast.signature.Variant ('s', 00002901-0000-1000-8000-00805f9b34fb)>, 'Characteristic': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E/service0010/char0014)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,579 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0010/char0017', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 23)>, 'UUID': <dbus_fast.signature.Variant ('s', 00010203-0405-0607-0809-0a0b0c0d1913)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E/service0010)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>, 'Flags': <dbus_fast.signature.Variant ('as', ['read', 'write-without-response'])>, 'WriteAcquired': <dbus_fast.signature.Variant ('b', False)>, 'MTU': <dbus_fast.signature.Variant ('q', 247)>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,579 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0010/char0017/desc0019', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattDescriptor1': {'Handle': <dbus_fast.signature.Variant ('q', 823)>, 'UUID': <dbus_fast.signature.Variant ('s', 00002901-0000-1000-8000-00805f9b34fb)>, 'Characteristic': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E/service0010/char0017)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,579 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0010/char001a', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 26)>, 'UUID': <dbus_fast.signature.Variant ('s', 00010203-0405-0607-0809-0a0b0c0d1914)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E/service0010)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>, 'Flags': <dbus_fast.signature.Variant ('as', ['read', 'write-without-response', 'write'])>, 'WriteAcquired': <dbus_fast.signature.Variant ('b', False)>, 'MTU': <dbus_fast.signature.Variant ('q', 247)>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,579 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0010/char001a/desc001c', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattDescriptor1': {'Handle': <dbus_fast.signature.Variant ('q', 823)>, 'UUID': <dbus_fast.signature.Variant ('s', 00002901-0000-1000-8000-00805f9b34fb)>, 'Characteristic': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E/service0010/char001a)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,579 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service001d', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattService1': {'Handle': <dbus_fast.signature.Variant ('q', 29)>, 'UUID': <dbus_fast.signature.Variant ('s', 19200d0c-0b0a-0908-0706-050403020100)>, 'Device': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E)>, 'Primary': <dbus_fast.signature.Variant ('b', True)>, 'Includes': <dbus_fast.signature.Variant ('ao', [])>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,581 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service001d/char001e', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 30)>, 'UUID': <dbus_fast.signature.Variant ('s', 00002af0-0000-1000-8000-00805f9b34fb)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E/service001d)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>, 'Flags': <dbus_fast.signature.Variant ('as', ['read'])>, 'MTU': <dbus_fast.signature.Variant ('q', 247)>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,581 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0020', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattService1': {'Handle': <dbus_fast.signature.Variant ('q', 32)>, 'UUID': <dbus_fast.signature.Variant ('s', 00001827-0000-1000-8000-00805f9b34fb)>, 'Device': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E)>, 'Primary': <dbus_fast.signature.Variant ('b', True)>, 'Includes': <dbus_fast.signature.Variant ('ao', [])>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,582 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0020/char0021', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 33)>, 'UUID': <dbus_fast.signature.Variant ('s', 00002adb-0000-1000-8000-00805f9b34fb)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E/service0020)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>, 'Flags': <dbus_fast.signature.Variant ('as', ['write-without-response'])>, 'WriteAcquired': <dbus_fast.signature.Variant ('b', False)>, 'MTU': <dbus_fast.signature.Variant ('q', 247)>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,582 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0020/char0023', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 35)>, 'UUID': <dbus_fast.signature.Variant ('s', 00002adc-0000-1000-8000-00805f9b34fb)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E/service0020)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(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': {}}]
2024-02-10 11:47:34,582 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0020/char0023/desc0025', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattDescriptor1': {'Handle': <dbus_fast.signature.Variant ('q', 823)>, 'UUID': <dbus_fast.signature.Variant ('s', 00002902-0000-1000-8000-00805f9b34fb)>, 'Characteristic': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E/service0020/char0023)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,582 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0026', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattService1': {'Handle': <dbus_fast.signature.Variant ('q', 38)>, 'UUID': <dbus_fast.signature.Variant ('s', 00001828-0000-1000-8000-00805f9b34fb)>, 'Device': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E)>, 'Primary': <dbus_fast.signature.Variant ('b', True)>, 'Includes': <dbus_fast.signature.Variant ('ao', [])>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,582 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0026/char0027', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 39)>, 'UUID': <dbus_fast.signature.Variant ('s', 00002add-0000-1000-8000-00805f9b34fb)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E/service0026)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>, 'Flags': <dbus_fast.signature.Variant ('as', ['write-without-response'])>, 'WriteAcquired': <dbus_fast.signature.Variant ('b', False)>, 'MTU': <dbus_fast.signature.Variant ('q', 247)>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,583 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0026/char0029', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattCharacteristic1': {'Handle': <dbus_fast.signature.Variant ('q', 41)>, 'UUID': <dbus_fast.signature.Variant ('s', 00002ade-0000-1000-8000-00805f9b34fb)>, 'Service': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E/service0026)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(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': {}}]
2024-02-10 11:47:34,583 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0026/char0029/desc002b', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.GattDescriptor1': {'Handle': <dbus_fast.signature.Variant ('q', 822)>, 'UUID': <dbus_fast.signature.Variant ('s', 00002902-0000-1000-8000-00805f9b34fb)>, 'Characteristic': <dbus_fast.signature.Variant ('o', /org/bluez/hci0/dev_34_13_43_70_D9_2E/service0026/char0029)>, 'Value': <dbus_fast.signature.Variant ('ay', bytearray(b''))>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:47:34,583 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_34_13_43_70_D9_2E): ['org.bluez.Device1', {'UUIDs': <dbus_fast.signature.Variant ('as', ['00001800-0000-1000-8000-00805f9b34fb', '0000180a-0000-1000-8000-00805f9b34fb', '00001827-0000-1000-8000-00805f9b34fb', '00001828-0000-1000-8000-00805f9b34fb', '00010203-0405-0607-0809-0a0b0c0d1910', '19200d0c-0b0a-0908-0706-050403020100'])>, 'ServicesResolved': <dbus_fast.signature.Variant ('b', True)>}, []]
2024-02-10 11:47:34,750 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_34_13_43_70_D9_2E): ['org.bluez.Device1', {'Name': <dbus_fast.signature.Variant ('s', C by GE)>, 'Alias': <dbus_fast.signature.Variant ('s', C by GE)>}, []]
2024-02-10 11:47:34,970 bleak.backends.bluezdbus.client MainThread DEBUG: Write Characteristic 00010203-0405-0607-0809-0a0b0c0d1914 | /org/bluez/hci0/dev_34_13_43_70_D9_2E/service0010/char001a: b'\x0c:\x89\xf7-s\xae\xb5\xa2"\xb9\xa3!V\x0e`\x96'
2024-02-10 11:47:35,377 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_34_13_43_70_D9_2E/service0010/char001a): ['org.bluez.GattCharacteristic1', {'Value': <dbus_fast.signature.Variant ('ay', bytearray(b'\r\x8eR<&\x10\xfa\xe4\xce\xcc\x9a\x9e\x19\xba\xa0\xc3\x80'))>}, []]
2024-02-10 11:47:35,377 bleak.backends.bluezdbus.client MainThread DEBUG: Read Characteristic 00010203-0405-0607-0809-0a0b0c0d1914 | /org/bluez/hci0/dev_34_13_43_70_D9_2E/service0010/char001a: bytearray(b'\r\x8eR<&\x10\xfa\xe4\xce\xcc\x9a\x9e\x19\xba\xa0\xc3\x80')
02/10/24 11:47:35.0557 INFO - acync.mesh mesh:499 -> telink mesh:connect: Unable to connect to mesh mac for notify: 34:13:43:70:D9:2E -> [org.bluez.Error.NotPermitted] Write not permitted
2024-02-10 11:47:35,557 bleak.backends.bluezdbus.client MainThread DEBUG: Disconnecting ({/org/bluez/hci0/dev_34_13_43_70_D9_2E})
2024-02-10 11:47:38,117 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_34_13_43_70_D9_2E): ['org.bluez.Device1', {'ServicesResolved': <dbus_fast.signature.Variant ('b', False)>}, []]
2024-02-10 11:47:38,117 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_34_13_43_70_D9_2E): ['org.bluez.Device1', {'Connected': <dbus_fast.signature.Variant ('b', False)>}, []]
2024-02-10 11:47:38,117 bleak.backends.bluezdbus.client MainThread DEBUG: Device disconnected (/org/bluez/hci0/dev_34_13_43_70_D9_2E)
2024-02-10 11:47:38,117 bleak.backends.bluezdbus.client MainThread DEBUG: _cleanup_all(/org/bluez/hci0/dev_34_13_43_70_D9_2E)

It may have been removed from BlueZ when scanning stopped

Device shows up in scans but is removed when scanning is aborted

02/10/24 11:50:32.0925 DEBUG - acync.mesh mesh:408 -> telink mesh:connect: attempt: 3/3 to MAC (4/4): 34:13:43:70:D9:2E [Cync Plug] - Scan Timeout: 10
2024-02-10 11:50:32,925 bleak.backends.bluezdbus.client MainThread DEBUG: Connecting to device @ 34:13:43:70:D9:2E
2024-02-10 11:50:32,934 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', True)>}, []]
2024-02-10 11:50:33,025 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesAdded (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E', {'org.freedesktop.DBus.Introspectable': {}, 'org.bluez.Device1': {'Address': <dbus_fast.signature.Variant ('s', 34:13:43:70:D9:2E)>, 'AddressType': <dbus_fast.signature.Variant ('s', public)>, 'Name': <dbus_fast.signature.Variant ('s', 7B19400144A4D0F4)>, 'Alias': <dbus_fast.signature.Variant ('s', 7B19400144A4D0F4)>, 'Paired': <dbus_fast.signature.Variant ('b', False)>, 'Bonded': <dbus_fast.signature.Variant ('b', False)>, 'Trusted': <dbus_fast.signature.Variant ('b', False)>, 'Blocked': <dbus_fast.signature.Variant ('b', False)>, 'LegacyPairing': <dbus_fast.signature.Variant ('b', False)>, 'RSSI': <dbus_fast.signature.Variant ('n', -56)>, 'Connected': <dbus_fast.signature.Variant ('b', False)>, 'UUIDs': <dbus_fast.signature.Variant ('as', [])>, 'Adapter': <dbus_fast.signature.Variant ('o', /org/bluez/hci0)>, 'ServicesResolved': <dbus_fast.signature.Variant ('b', False)>}, 'org.freedesktop.DBus.Properties': {}}]
2024-02-10 11:50:33,039 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_34_13_43_70_D9_2E): ['org.bluez.Device1', {}, ['RSSI']]
2024-02-10 11:50:33,039 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_34_13_43_70_D9_2E', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
2024-02-10 11:50:33,039 bleak.backends.bluezdbus.manager MainThread DEBUG: received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0): ['org.bluez.Adapter1', {'Discovering': <dbus_fast.signature.Variant ('b', False)>}, []]
2024-02-10 11:50:33,046 bleak.backends.bluezdbus.client MainThread DEBUG: Connecting to BlueZ path /org/bluez/hci0/dev_34_13_43_70_D9_2E
2024-02-10 11:50:33,049 bleak.backends.bluezdbus.client MainThread DEBUG: _cleanup_all(/org/bluez/hci0/dev_34_13_43_70_D9_2E)
02/10/24 11:50:33.0049 WARNING - acync.mesh mesh:428 -> telink mesh:connect: EXCEPTION! Unable to CONNECT to device: 34:13:43:70:D9:2E [Cync Plug] --> Device with address 34:13:43:70:D9:2E was not found. It may have been removed from BlueZ when scanning stopped.
@baudneo
Copy link
Author

baudneo commented Feb 10, 2024

timeout error pcap, btmon and bluetoothctl logs ->

plug-connect_timeout.pcapng.txt
btctl.timeout.log
btmon.timeout.log

@baudneo
Copy link
Author

baudneo commented Feb 10, 2024

@dlech
Copy link
Collaborator

dlech commented Feb 11, 2024

The packet logs for the timeout error also have the write not permitted error, so I'm guessing it is the same problem causing both exceptions.

The write not permitted error is coming from the device you are connecting to when trying to write the Client Characteristic Configuration descriptor for one of the characteristics. So either this needs some sort of authentication or the device is defective. In either case, similar to #972.

@dlech dlech added 3rd party issue The issue is with the Bluetooth stack, the BLE device, or other 3rd party code not with Bleak itself Backend: BlueZ Issues and PRs relating to the BlueZ backend labels Apr 29, 2024
@baudneo baudneo closed this as not planned Won't fix, can't repro, duplicate, stale Jun 15, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
3rd party issue The issue is with the Bluetooth stack, the BLE device, or other 3rd party code not with Bleak itself Backend: BlueZ Issues and PRs relating to the BlueZ backend
Projects
None yet
Development

No branches or pull requests

2 participants