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

Cannot run a Lego tram #125

Open
larsskj opened this issue Nov 14, 2022 · 25 comments
Open

Cannot run a Lego tram #125

larsskj opened this issue Nov 14, 2022 · 25 comments

Comments

@larsskj
Copy link

larsskj commented Nov 14, 2022

I'm trying to create a working solution for the new Lego Christmas tram. We want to make it run periodically in a shop window.

My plan is to use a Raspberry Pi connecting using Bluetooth, and then write some software to run the tram every now and then. As a start: My family wants me to setup an SMS gateway, so visitors outside the window can start the tram on demand by sending a text message. :-)

But first things first: I need a Python library to control the tram - and I would like to use pylgbst. But unfortunately, I cannot make it work.

Before diving into the details, I want to add that it actually works with another Python library known as BrickNil. However, this library has its own set of challenges, and it seems to be completely unsupported - there hasn't been an update in three years, and PR and issues are unanswered. So I would prefer helping out to make pylgbst work.

Hardware for the tram is determined by Lego: An 88009 SmartHub, an 88011 Train Motor, and an 88005 Light Set.

BrickNil uses Bleak, and I can write a program and connect to the hub, change the colour of the builtin LED, and turn on the light in the external light set.

However, when I try pylgbst on the same RPi and tram, nothing works. If I try using pylgbst with bluepy, it can find the hub, but reports that nothing is connected. If I try using Bleak, it cannot find anything at all.

In issue #124 I found a small debug program. If I modify this to use a specific BT backend, I get these results for bluepy:

lars@lego-sporvogn:~ $ sudo ./test.py 
DEBUG:comms-bluepy:Trying to connect client to MoveHub with MAC: 90:84:2b:c6:9a:f8
INFO:comms-bluepy:Discovering devices...
DEBUG:comms:Checking device: None, MAC: xx:xx:xx:xx:xx:xx
DEBUG:comms:Checking device: Smart Hub, MAC: 90:84:2b:c6:9a:f8
INFO:comms:Found Smart Hub at 90:84:2b:c6:9a:f8
DEBUG:comms-bluepy:Writing to handle 15: b'0100'
lars@lego-sporvogn:~ $ 

and for Bleak:

lars@lego-sporvogn:~ $ ./test.py 
DEBUG:asyncio:Using selector: EpollSelector
DEBUG:asyncio:Using selector: EpollSelector
INFO:comms-bleak:Discovering devices... Press green button on Hub
lars@lego-sporvogn:~ $ 

Nothing more before the test program times out.

The RPi runs the latest Raspbian as of writing and updated to the latest and greatest everything. This means Python version 3.9.2.

I would love to see this work - but we're in a bit of a hurry, our traditional Christmas exhibition in the shop window opens Dec. 1st. :-)

@undera
Copy link
Owner

undera commented Nov 14, 2022

Hello,
I am very excited to hear about your task, would love to help.
With RPi, I saw that there are various behaviors from device to device, probably due to hardware and software differences.

What you should try is to experiment around version of bleak Python library. Which version do you use at the moment? It should be something recent from this list: https://pypi.org/project/bleak/#history

Also, I can see that bricknil uses a patched version of Bleak: https://github.com/virantha/bleak that is installable as bricknil-bleak (https://pypi.org/project/bricknil-bleak/#history). This may be worth trying, to uninstall official bleak library and install bricknil-bleak instead. The author made it to clash with official bleak, so you need to be extra careful with what is installed first and second. THis may also explain why bricknil works and others don't. I'll be happy to help you through the process.

I understand the urgency, let's see if there can be some progress from bleak library variants.

@larsskj
Copy link
Author

larsskj commented Nov 14, 2022

Hm - did some more troubleshooting, and lo and behold, now something works.

I was foolish enough to assume that the bleak library had been installed, but even though BrickNil uses Bleak, apparently it doesn't use the Python library. pip install bleak changed a lot.

But now I wonder: If pylgbst depends on bleak, how come it doesn't complain when the package isn't installed?

@larsskj
Copy link
Author

larsskj commented Nov 14, 2022

Sorry - my last comment was posted just after you posted yours.

I'll try some troubleshooting along the lines you suggest and report back.

@undera
Copy link
Owner

undera commented Nov 14, 2022

Bleak is not installed.by default because pylgbst works with several variants of BLE backends. you need to decide which you use and install it

In your case things are more complex: bricknil has installed its own patched bleak, and pylgbst uses it and fails. You should uninstall bricknil and bricknil-bleak, then install official bleak and then try again.

@larsskj
Copy link
Author

larsskj commented Nov 14, 2022

I've now done it properly and created a virtual environment. Installing pylgbst and bleak and running demo.py I get this debug output:

6109	DEBUG	comms-bleak	Connection status: True
6149	DEBUG	hub	Waiting for builtin devices to appear: (None, None, None)
6250	DEBUG	hub	Waiting for builtin devices to appear: (None, None, None)
6351	DEBUG	hub	Waiting for builtin devices to appear: (None, None, None)
6353	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)>}, []]
6451	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)>}, []]
6452	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'))>}, []]
6453	DEBUG	hub	Waiting for builtin devices to appear: (None, None, None)
6454	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']
6455	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'))>}, []]
6456	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']
6457	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'))>}, []]
6458	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']
6460	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'))>}, []]
6461	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']
6461	DEBUG	hub	Notification on 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic: b'0f0004000102000000000000000000'
6463	DEBUG	hub	Decoded message: MsgHubAttachedIO({'payload': b'02000000000000000000', 'port': 0, 'event': 1})
6465	DEBUG	hub	Handling msg with <bound method SmartHub._handle_device_change of <pylgbst.hub.SmartHub object at 0x7654c5b0>>: MsgHubAttachedIO({'payload': b'02000000000000000000', 'port': 0, 'event': 1})
6468	WARNING	hub	Have no dedicated class for peripheral type 0x2 (SYSTEM_TRAIN_MOTOR) on port 0x0
6472	INFO	hub	Attached peripheral: Peripheral on port 0x0
6484	DEBUG	hub	Notification on 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic: b'0f0004010108000000000000000000'
6484	DEBUG	hub	Decoded message: MsgHubAttachedIO({'payload': b'08000000000000000000', 'port': 1, 'event': 1})
6485	DEBUG	hub	Handling msg with <bound method SmartHub._handle_device_change of <pylgbst.hub.SmartHub object at 0x7654c5b0>>: MsgHubAttachedIO({'payload': b'08000000000000000000', 'port': 1, 'event': 1})
6487	WARNING	hub	Have no dedicated class for peripheral type 0x8 (LED_LIGHT) on port 0x1
6489	INFO	hub	Attached peripheral: Peripheral on port 0x1
6499	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'))>}, []]
6500	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']
6501	DEBUG	hub	Notification on 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic: b'0f0004320117000000001000000010'
6502	DEBUG	hub	Decoded message: MsgHubAttachedIO({'payload': b'17000000001000000010', 'port': 50, 'event': 1})
6503	DEBUG	hub	Handling msg with <bound method SmartHub._handle_device_change of <pylgbst.hub.SmartHub object at 0x7654c5b0>>: MsgHubAttachedIO({'payload': b'17000000001000000010', 'port': 50, 'event': 1})
6506	INFO	hub	Attached peripheral: LEDRGB on port 0x32
6517	DEBUG	hub	Notification on 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic: b'0f00043b0115000200000002000000'
6518	DEBUG	hub	Decoded message: MsgHubAttachedIO({'payload': b'15000200000002000000', 'port': 59, 'event': 1})
6518	DEBUG	hub	Handling msg with <bound method SmartHub._handle_device_change of <pylgbst.hub.SmartHub object at 0x7654c5b0>>: MsgHubAttachedIO({'payload': b'15000200000002000000', 'port': 59, 'event': 1})
6521	INFO	hub	Attached peripheral: Current on port 0x3b
6533	DEBUG	hub	Notification on 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic: b'0f00043c0114000200000002000000'
6533	DEBUG	hub	Decoded message: MsgHubAttachedIO({'payload': b'14000200000002000000', 'port': 60, 'event': 1})
6534	DEBUG	hub	Handling msg with <bound method SmartHub._handle_device_change of <pylgbst.hub.SmartHub object at 0x7654c5b0>>: MsgHubAttachedIO({'payload': b'14000200000002000000', 'port': 60, 'event': 1})
6537	INFO	hub	Attached peripheral: Voltage on port 0x3c
6555	DEBUG	hub	All devices are present: (LEDRGB on port 0x32, Current on port 0x3b, Voltage on port 0x3c)
6556	INFO	demo	Motors movement demo: timed
6557	INFO	demo	Speed level: 0.0%
6558	DEBUG	hub	Send message: MsgHubAction({'payload': b'', 'needs_reply': False, 'action': 2})
6559	DEBUG	hub	Waiting for sync reply to MsgHubAction({'payload': b'02', 'needs_reply': True, 'action': 2})...
6574	DEBUG	comms-bleak	Request: 14 ['0x4', '0x0', '0x2', '0x2']
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 "/home/lars/venv/lib/python3.9/site-packages/pylgbst/comms/cbleak.py", line 50, 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 "/home/lars/venv/lib/python3.9/site-packages/pylgbst/comms/cbleak.py", line 69, in _bleak_thread
    await bleak.write(data[0], data[1])
  File "/home/lars/venv/lib/python3.9/site-packages/pylgbst/comms/cbleak.py", line 180, in write
    await self._client.write_gatt_char(MOVE_HUB_HW_UUID_CHAR, data)
  File "/home/lars/venv/lib/python3.9/site-packages/bleak/__init__.py", line 593, in write_gatt_char
    await self._backend.write_gatt_char(char_specifier, data, response)
  File "/home/lars/venv/lib/python3.9/site-packages/bleak/backends/bluezdbus/client.py", line 801, in write_gatt_char
    assert_reply(reply)
  File "/home/lars/venv/lib/python3.9/site-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

Then pressing Ctrl-C I get:

^CTraceback (most recent call last):
  File "/home/lars/./sporvogn.py", line 265, in <module>
    demo(hub)
  File "/home/lars/./sporvogn.py", line 177, in demo_all
    demo_motors_timed(movehub)
  File "/home/lars/./sporvogn.py", line 33, in demo_motors_timed
    movehub.motor_A.timed(0.2, level)
AttributeError: 'SmartHub' object has no attribute 'motor_A'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/lars/./sporvogn.py", line 267, in <module>
    hub.disconnect()
  File "/home/lars/venv/lib/python3.9/site-packages/pylgbst/hub.py", line 190, in disconnect
    self.send(MsgHubAction(MsgHubAction.DISCONNECT))
  File "/home/lars/venv/lib/python3.9/site-packages/pylgbst/hub.py", line 96, in send
    resp = self._sync_replies.get()
  File "/usr/lib/python3.9/queue.py", line 171, in get
    self.not_empty.wait()
  File "/usr/lib/python3.9/threading.py", line 312, in wait
    waiter.acquire()
KeyboardInterrupt

Interesting to learn that it complains about a motor that it cannot find - but only after i press Ctrl-C.

I have modified demo.py to create a SmartHub object instead of a MoveHub.

@larsskj
Copy link
Author

larsskj commented Nov 14, 2022

Package       Version
------------- -------
async-timeout 4.0.2
bleak         0.19.4
dbus-fast     1.74.0
pip           22.3.1
pkg_resources 0.0.0
pylgbst       1.2.2
setuptools    44.1.1

@undera
Copy link
Owner

undera commented Nov 14, 2022

SmartHub object will have different capabilities, so you can't run demo with that type of hub. Demo script is designed to be used with MoveHub.

"All devices are present" in log is a very good sign, seems your SmartHub is up and ready. Now, you need to work with it properly.

@undera
Copy link
Owner

undera commented Nov 14, 2022

There are couple of important messages in the log:

6468 WARNING hub Have no dedicated class for peripheral type 0x2 (SYSTEM_TRAIN_MOTOR) on port 0x0
6487 WARNING hub Have no dedicated class for peripheral type 0x8 (LED_LIGHT) on port 0x1

Those mean that pylgbst does not have specialized handling for those devices. That's OK, you can still interact with them.

The interaction can happen on lower level, via message sending/receiving, or by optimistic peripheral enablement. We can even figure out the exact device capabilities and write nice peripheral handling for those.

@undera
Copy link
Owner

undera commented Nov 14, 2022

Here's a snippet of initializing your own objects bindings:

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)

After that, your can do commands to those peripherals. The code can be arranged slightly differently. If EncodedMotor class does not work well, try using Motor class instead.

@larsskj
Copy link
Author

larsskj commented Dec 3, 2022

Back again after surgery - and on to the project!

Thank you very much for your example: But whilst it most likely will work with the current code on Github, it doesn't work with the latest release and hence it won't work with the latest package on PyPi. Your latest release is 1.2.2, that's the latest package on PyPi as well - but it doesn't include the peripheral LEDLight.

Perhaps time for a new release?

@larsskj
Copy link
Author

larsskj commented Dec 3, 2022

Having removed the LED and concentrating on the motor for now, I do get a bit further, but your code snippet still fails:

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 0x764a7d00>>: MsgHubAttachedIO({'payload': b'08000000000000000000', 'port': 1, 'event': 1})
WARNING:hub:Have no dedicated class for peripheral type 0x8 (LED_LIGHT) on port 0x1
INFO:hub:Attached peripheral: Peripheral 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 0x764a7d00>>: MsgHubAttachedIO({'payload': b'17000000001000000010', 'port': 50, 'event': 1})
INFO:hub:Attached peripheral: LEDRGB on port 0x32
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 0x764a7d00>>: MsgHubAttachedIO({'payload': b'15000200000002000000', 'port': 59, 'event': 1})
INFO:hub:Attached peripheral: Current on port 0x3b
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 0x764a7d00>>: MsgHubAttachedIO({'payload': b'14000200000002000000', 'port': 60, 'event': 1})
INFO:hub:Attached peripheral: Voltage on port 0x3c
DEBUG:hub:All devices are present: (LEDRGB on port 0x32, Current on port 0x3b, Voltage on port 0x3c)
DEBUG:hub:Send message: MsgPortOutput({'payload': b'', 'needs_reply': False, 'port': 0, 'is_buffered': False, 'do_feedback': True, 'subcommand': 9, 'params': b'e80364647f03'})
DEBUG:hub:Waiting for sync reply to MsgPortOutput({'payload': b'001109e80364647f03', 'needs_reply': True, 'port': 0, 'is_buffered': False, 'do_feedback': True, 'subcommand': 9, 'params': b'e80364647f03'})...
DEBUG:comms-bleak:Request: 14 ['0xc', '0x0', '0x81', '0x0', '0x11', '0x9', '0xe8', '0x3', '0x64', '0x64', '0x7f', '0x3']
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 50, 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 69, in _bleak_thread
    await bleak.write(data[0], data[1])
  File "/usr/local/lib/python3.9/dist-packages/pylgbst/comms/cbleak.py", line 180, 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
Copy link
Owner

undera commented Dec 3, 2022

Hey, welcome back. Hope nothing serious with your surgery.

I would love to validate that the source code works before doing a release. It is easily possible by running pip install https://github.com/undera/pylgbst/archive/refs/heads/master.zip, which will install latest source code from GitHub.

Regarding "Not connected" error - it's something very specific to bluez, not something that we control on the pylgbst level. Their docs (https://bleak.readthedocs.io/en/latest/backends/linux.html?highlight=dbus) mention that https://github.com/Bluetooth-Devices/dbus-fast library is used. I would look if latest version of Bleak is installed and also that dbus-fast library.

From reading the log above, I don't see the motor is attached. It rather reports attaching the LED with INFO:hub:Attached peripheral: Peripheral on port 0x1. I see no corresponding message for the motor on port 0, thus I'd not expect it to function.

Let's continue troubleshooting it.

@larsskj
Copy link
Author

larsskj commented Dec 3, 2022

No, nothing too bad about surgery - just a toe with osteoarthritis. But bad enough when you suffer from it.

Anyway, the motor is there - my snippet was just too short. The lines immediately before the ones above:

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:hub:Notification on 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic: b'0f0004000102000000000000000000'
DEBUG:hub:Decoded message: MsgHubAttachedIO({'payload': b'02000000000000000000', 'port': 0, 'event': 1})
DEBUG:hub:Handling msg with <bound method SmartHub._handle_device_change of <pylgbst.hub.SmartHub object at 0x7656dd00>>: MsgHubAttachedIO({'payload': b'02000000000000000000', 'port': 0, 'event': 1})
WARNING:hub:Have no dedicated class for peripheral type 0x2 (SYSTEM_TRAIN_MOTOR) on port 0x0
INFO:hub:Attached peripheral: Peripheral on port 0x0
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', {'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: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: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: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:hub:Notification on 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic: b'0f0004010108000000000000000000'

Will try to install from Github instead of PyPi.

@larsskj
Copy link
Author

larsskj commented Dec 3, 2022

Unfortunately, same result after installing latest master.

In general, everything should be up to date: The RPi was installed from scratch only three weeks ago, and I've uninstalled all Python packages related to this project for my venv, my personal home, and the overall root account. Sigh. There was a mixture of packages, there isn't anymore.

If everything else fails, we can try wiping out the RPi and start over again with a fresh Raspbian. This RPi will only be used for Lego - at least for now.

@larsskj
Copy link
Author

larsskj commented Dec 3, 2022

But the debug log isn't completely the same after the upgrade:

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: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: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: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:hub:Notification on 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic: b'0f0004000102000000000000000000'
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', '0x3b', '0x1', '0x15', '0x0', '0x2', '0x0', '0x0', '0x0', '0x2', '0x0', '0x0', '0x0']
DEBUG:hub:Handling msg with <bound method SmartHub._handle_device_change of <pylgbst.hub.SmartHub object at 0x765370b8>>: 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 0x765370b8>>: 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 0x765370b8>>: 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\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 0x765370b8>>: MsgHubAttachedIO({'payload': b'15000200000002000000', 'port': 59, 'event': 1})
INFO:hub:Attached peripheral CURRENT => Current on port 0x3b
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 0x765370b8>>: 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

@larsskj
Copy link
Author

larsskj commented Dec 3, 2022

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

@undera
Copy link
Owner

undera commented Dec 3, 2022

What is the exact Bleak version you have? I have no other ideas than asking on Bleak issue tracker for possible help.

The difficult part is the fact that the code works on other machines. It must be something with that specific combination of OS, hardware and software.

@larsskj
Copy link
Author

larsskj commented Dec 3, 2022

I'm using Bleak version 0.19.5 - the latest and greatest just about two weeks old.

I'll try opening a ticket with the Bleak project as well.

@undera
Copy link
Owner

undera commented Dec 5, 2022

@larsskj Can you try patching the library right on RPi, by searching for file like find / -name "cbleak.py" and modifying the line according to @lorenzofelletti advice?

@larsskj
Copy link
Author

larsskj commented Dec 30, 2022

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

But here we go and I've found the time to test some of the suggestions: I first downloaded the latest BlueZ from kernel.org (version 5.66) and compiled it for my Raspberry Pi - a suggestion from the Bleak project. I then patched the Python code according to the suggestion as well - but all of it to no avail: Same disappointing result.

@undera
Copy link
Owner

undera commented Dec 31, 2022

@larsskj Did you try patching cbleak.py ?

@larsskj
Copy link
Author

larsskj commented Dec 31, 2022

@undera Yes, that's what I meant by writing "I then patched the Python code according to the suggestion as well..."

Did you see the comment from dlech in the Bleak issue about a bug in the Lego implementation? And that the simple patch of cbleak.py wouldn't be enough?

@undera
Copy link
Owner

undera commented Dec 31, 2022

So, looks like we are unable to find the solution for this particular problem. Something is broken there in BLE communications.

@cuernodegazpacho
Copy link
Contributor

@larsskj we were able to include support for the train motor. It is available in the latest master.

@larsskj
Copy link
Author

larsskj commented Feb 16, 2023

This sounds amazing: I'll give it a try in the weekend.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants