search

hbldh / bleak

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

Bleak DBus error on Raspberry Pi #1162

Open larsskj opened 1 year ago

larsskj commented 1 year ago

Description

I'm trying to setup a Raspberry Pi 3+ to connect to a Lego tram from this year's Lego Christmas set. This requires Bluetooth control, and we're trying to set it up using the Python pylgbst library. Trying to run a minimal test as described in this issue, the code first connects and works, then disconnects with the message bleak.exc.BleakDBusError: [org.bluez.Error.Failed] Not connected.

Debug messages can be found in the issue mentioned above, but I'll be happy to provide as much as needed here as well.

What I Did

The test script I use:

#!/usr/bin/env python
# coding=utf-8

import logging

logging.basicConfig(level=logging.DEBUG)

from pylgbst import *
from pylgbst.hub import SmartHub

import pylgbst.peripherals

hub = SmartHub()

# create objects
motor = pylgbst.peripherals.EncodedMotor(hub, 0x0)
led = pylgbst.peripherals.LEDLight(hub, 0x1)

# optionally, assign it into hub class
hub.peripherals[0x0] = motor
hub.peripherals[0x1] = led

# also the shorthand ports
hub.port_A = motor
hub.port_B = led

# use it!
led.brightness = 1.0
motor.timed(1.0, 1.0)

Logs

Wireshark won't run, unfortunately, as this Linux host has no GUI.

But the debug log for the above program shows:

DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_90_84_2B_C6_9A_F8): ['org.bluez.Device1', {'Appearance': <dbus_fast.signature.Variant ('q', 6144)>}, []]
DEBUG:hub:Waiting for builtin devices to appear: (None, None, None)
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_90_84_2B_C6_9A_F8/service000c/char000d): ['org.bluez.GattCharacteristic1', {'Notifying': <dbus_fast.signature.Variant ('b', True)>}, []]
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_90_84_2B_C6_9A_F8/service000c/char000d): ['org.bluez.GattCharacteristic1', {'Value': <dbus_fast.signature.Variant ('ay', bytearray(b'\x0f\x00\x04\x00\x01\x02\x00\x00\x00\x00\x00\x00\x00\x00\x00'))>}, []]
DEBUG:comms-bleak:Response: 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic ['0xf', '0x0', '0x4', '0x0', '0x1', '0x2', '0x0', '0x0', '0x0', '0x0', '0x0', '0x0', '0x0', '0x0', '0x0']
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_90_84_2B_C6_9A_F8/service000c/char000d): ['org.bluez.GattCharacteristic1', {'Value': <dbus_fast.signature.Variant ('ay', bytearray(b'\x0f\x00\x04\x01\x01\x08\x00\x00\x00\x00\x00\x00\x00\x00\x00'))>}, []]
DEBUG:comms-bleak:Response: 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic ['0xf', '0x0', '0x4', '0x1', '0x1', '0x8', '0x0', '0x0', '0x0', '0x0', '0x0', '0x0', '0x0', '0x0', '0x0']
DEBUG:hub:Notification on 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic: b'0f0004000102000000000000000000'
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_90_84_2B_C6_9A_F8/service000c/char000d): ['org.bluez.GattCharacteristic1', {'Value': <dbus_fast.signature.Variant ('ay', bytearray(b'\x0f\x00\x042\x01\x17\x00\x00\x00\x00\x10\x00\x00\x00\x10'))>}, []]
DEBUG:hub:Decoded message: MsgHubAttachedIO({'payload': b'02000000000000000000', 'port': 0, 'event': 1})
DEBUG:comms-bleak:Response: 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic ['0xf', '0x0', '0x4', '0x32', '0x1', '0x17', '0x0', '0x0', '0x0', '0x0', '0x10', '0x0', '0x0', '0x0', '0x10']
DEBUG:hub:Handling msg with <bound method SmartHub._handle_device_change of <pylgbst.hub.SmartHub object at 0x7661bd60>>: MsgHubAttachedIO({'payload': b'02000000000000000000', 'port': 0, 'event': 1})
INFO:hub:Attached peripheral SYSTEM_TRAIN_MOTOR => EncodedMotor on port 0x0
DEBUG:hub:Notification on 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic: b'0f0004010108000000000000000000'
DEBUG:hub:Decoded message: MsgHubAttachedIO({'payload': b'08000000000000000000', 'port': 1, 'event': 1})
DEBUG:hub:Handling msg with <bound method SmartHub._handle_device_change of <pylgbst.hub.SmartHub object at 0x7661bd60>>: MsgHubAttachedIO({'payload': b'08000000000000000000', 'port': 1, 'event': 1})
INFO:hub:Attached peripheral LED_LIGHT => LEDLight on port 0x1
DEBUG:hub:Notification on 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic: b'0f0004320117000000001000000010'
DEBUG:hub:Decoded message: MsgHubAttachedIO({'payload': b'17000000001000000010', 'port': 50, 'event': 1})
DEBUG:hub:Handling msg with <bound method SmartHub._handle_device_change of <pylgbst.hub.SmartHub object at 0x7661bd60>>: MsgHubAttachedIO({'payload': b'17000000001000000010', 'port': 50, 'event': 1})
INFO:hub:Attached peripheral RGB_LIGHT => LEDRGB on port 0x32
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_90_84_2B_C6_9A_F8/service000c/char000d): ['org.bluez.GattCharacteristic1', {'Value': <dbus_fast.signature.Variant ('ay', bytearray(b'\x0f\x00\x04;\x01\x15\x00\x02\x00\x00\x00\x02\x00\x00\x00'))>}, []]
DEBUG:comms-bleak:Response: 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic ['0xf', '0x0', '0x4', '0x3b', '0x1', '0x15', '0x0', '0x2', '0x0', '0x0', '0x0', '0x2', '0x0', '0x0', '0x0']
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_90_84_2B_C6_9A_F8/service000c/char000d): ['org.bluez.GattCharacteristic1', {'Value': <dbus_fast.signature.Variant ('ay', bytearray(b'\x0f\x00\x04<\x01\x14\x00\x02\x00\x00\x00\x02\x00\x00\x00'))>}, []]
DEBUG:comms-bleak:Response: 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic ['0xf', '0x0', '0x4', '0x3c', '0x1', '0x14', '0x0', '0x2', '0x0', '0x0', '0x0', '0x2', '0x0', '0x0', '0x0']
DEBUG:hub:Notification on 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic: b'0f00043b0115000200000002000000'
DEBUG:hub:Decoded message: MsgHubAttachedIO({'payload': b'15000200000002000000', 'port': 59, 'event': 1})
DEBUG:hub:Handling msg with <bound method SmartHub._handle_device_change of <pylgbst.hub.SmartHub object at 0x7661bd60>>: MsgHubAttachedIO({'payload': b'15000200000002000000', 'port': 59, 'event': 1})
INFO:hub:Attached peripheral CURRENT => Current on port 0x3b
DEBUG:hub:Waiting for builtin devices to appear: (LEDRGB on port 0x32, Current on port 0x3b, None)
DEBUG:hub:Notification on 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic: b'0f00043c0114000200000002000000'
DEBUG:hub:Decoded message: MsgHubAttachedIO({'payload': b'14000200000002000000', 'port': 60, 'event': 1})
DEBUG:hub:Handling msg with <bound method SmartHub._handle_device_change of <pylgbst.hub.SmartHub object at 0x7661bd60>>: MsgHubAttachedIO({'payload': b'14000200000002000000', 'port': 60, 'event': 1})
INFO:hub:Attached peripheral VOLTAGE => Voltage on port 0x3c
DEBUG:hub:All devices are present: (LEDRGB on port 0x32, Current on port 0x3b, Voltage on port 0x3c)
DEBUG:peripherals:Implied update is enabled=False
DEBUG:peripherals:Implied update delta=1
DEBUG:hub:Send message: MsgPortInputFmtSetupSingle({'payload': b'01000100000000', 'needs_reply': True, 'port': 1, 'mode': 0, 'updates_enabled': False, 'update_delta': 1})
DEBUG:hub:Waiting for sync reply to MsgPortInputFmtSetupSingle({'payload': b'01000100000000', 'needs_reply': True, 'port': 1, 'mode': 0, 'updates_enabled': False, 'update_delta': 1})...
DEBUG:comms-bleak:Request: 14 ['0xa', '0x0', '0x41', '0x1', '0x0', '0x1', '0x0', '0x0', '0x0', '0x0']
Exception in thread Thread-1:
Traceback (most recent call last):
  File "/usr/lib/python3.9/threading.py", line 954, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.9/threading.py", line 892, in run
    self._target(*self._args, **self._kwargs)
  File "/usr/local/lib/python3.9/dist-packages/pylgbst/comms/cbleak.py", line 51, in <lambda>
    self._connection_thread = threading.Thread(target=lambda: asyncio.run(self._bleak_thread()))
  File "/usr/lib/python3.9/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/usr/lib/python3.9/asyncio/base_events.py", line 642, in run_until_complete
    return future.result()
  File "/usr/local/lib/python3.9/dist-packages/pylgbst/comms/cbleak.py", line 74, in _bleak_thread
    await bleak.write(data[0], data[1])
  File "/usr/local/lib/python3.9/dist-packages/pylgbst/comms/cbleak.py", line 188, in write
    await self._client.write_gatt_char(MOVE_HUB_HW_UUID_CHAR, data)
  File "/usr/local/lib/python3.9/dist-packages/bleak/__init__.py", line 593, in write_gatt_char
    await self._backend.write_gatt_char(char_specifier, data, response)
  File "/usr/local/lib/python3.9/dist-packages/bleak/backends/bluezdbus/client.py", line 801, in write_gatt_char
    assert_reply(reply)
  File "/usr/local/lib/python3.9/dist-packages/bleak/backends/bluezdbus/utils.py", line 20, in assert_reply
    raise BleakDBusError(reply.error_name, reply.body)
bleak.exc.BleakDBusError: [org.bluez.Error.Failed] Not connected
undera commented 1 year ago

I want to add that we know the same pylgbst library with the similar code snippet works fine on other machines, specifically on Linux and Mac.

undera commented 1 year ago

Also from linked issue:

Upgraded dbus-fast from 1.74.0 to 1.75.1 - no change.

lorenzofelletti commented 1 year ago

I don't know if this could be relevant, but in order to be able to successfully write a characteristic (on Windows I think I was) I had to set the flag response=True. So in your case, line 188 of pylgbst/comms/cbleak.py would become:

await self._client.write_gatt_char(MOVE_HUB_HW_UUID_CHAR, data, True)

I don't know if this could be relevant also your scenario, but this solved my problems.

dlech commented 1 year ago

I want to add that we know the same pylgbst library with the similar code snippet works fine on other machines, specifically on Linux and Mac.

If it works on other Linux machines, the problem is probably a bug in BlueZ that has been fixed in more recent versions.

larsskj commented 1 year ago

Sorry for being quite for a long time: I've been ill - and then we've had all the celebrations.

But now I've found the time: I've downloaded BlueZ 5.66 from kernel.org and built it on my Raspberry Pi. According to bluetoothctl version I am running 5.66 - but the problem persists and the result is the same as above.

dlech commented 1 year ago

If the LEGO hub still has the same Bluetooth bug where write without response still sends a response, it causes BlueZ to disconnect due to the unexpected response. You can confirm this by capturing Bluetooth packets with btmon or hcidump. Every call to BleakClient.write_gatt_char() in pylgbst needs to be changed to include the response=True argument, at least on Linux and for this particular hub. You could also have a look at Pybricks to run the train without having to be connected to a computer.