search

hbldh / bleak

A cross platform Bluetooth Low Energy Client for Python using asyncio
MIT License
1.56k stars 275 forks source link

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

Open baudneo opened 3 months ago

baudneo commented 3 months ago

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 commented 3 months ago

timeout error pcap, btmon and bluetoothctl logs ->

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

baudneo commented 3 months ago

write not permitted logs ->

btmon.writenotpermitted.log btctl.writenotpermitted.log write-not-permitted.pcapng.txt

dlech commented 3 months ago

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.