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

Powered Up Hub disconnects before leaving "run"? #6

Open
justxi opened this issue Jan 4, 2021 · 49 comments
Open

Powered Up Hub disconnects before leaving "run"? #6

justxi opened this issue Jan 4, 2021 · 49 comments

Comments

@justxi
Copy link

justxi commented Jan 4, 2021

@janvrany

Hi,

while your implementation works fine for the "Powered Up Technic Hub", I have a problem with the "Powered Up Hub".

Using this program:

#!/usr/bin/env python3

import logging

from asyncio import sleep

from bricknil import attach, start
from bricknil.hub import PoweredUpHub
from bricknil.sensor import TrainMotor

@attach(TrainMotor, name='motor', port=0)
class Train(PoweredUpHub):

    async def run(self):

        self.message_info('run')

        self.message_info('set_speed 50')
        await self.motor.set_speed(50)

        self.message_info('wait 5s')
        await sleep(5)

        self.message_info('set_speed 0')
        await self.motor.set_speed(0)

        self.message_info('wait 5s')
        await sleep(5)


async def system():
    train = Train('My train')

if __name__ == '__main__':
    logging.basicConfig(level=logging.INFO)
    start(system)

I get:

INFO:BLE Event Q.0:Starting scan for UART 00001623-1212-efde-1623-785feabcd123
INFO:BLE Event Q.0:Looking for first matching hub
Awaiting on bleak discover
INFO:bleak.backends.bluezdbus.discovery:dev_64_38_13_D0_D4_3E, 64:38:13:D0:D4:3E (? dBm), Object Path: /org/bluez/hci0/dev_64_38_13_D0_D4_3E
Done Awaiting on bleak discover
INFO:BLE Event Q.0:Rescanning for 00001623-1212-efde-1623-785feabcd123 (60 tries left)
Awaiting on bleak discover
Done Awaiting on bleak discover
INFO:BLE Event Q.0:Rescanning for 00001623-1212-efde-1623-785feabcd123 (59 tries left)
Awaiting on bleak discover
INFO:bleak.backends.bluezdbus.discovery:dev_64_38_13_D0_D4_3E, 64:38:13:D0:D4:3E (-95 dBm), Object Path: /org/bluez/hci0/dev_64_38_13_D0_D4_3E
INFO:bleak.backends.bluezdbus.discovery:dev_90_84_2B_1B_05_E7, 90:84:2B:1B:05:E7 (-60 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
INFO:bleak.backends.bluezdbus.discovery:dev_90_84_2B_1B_05_E7, 90:84:2B:1B:05:E7 (-60 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
INFO:bleak.backends.bluezdbus.discovery:dev_64_38_13_D0_D4_3E, 64:38:13:D0:D4:3E (-95 dBm), Object Path: /org/bluez/hci0/dev_64_38_13_D0_D4_3E
INFO:bleak.backends.bluezdbus.discovery:dev_90_84_2B_1B_05_E7, 90:84:2B:1B:05:E7 (-60 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
Done Awaiting on bleak discover
INFO:BLE Event Q.0:Rescanning for 00001623-1212-efde-1623-785feabcd123 (58 tries left)
Awaiting on bleak discover
INFO:bleak.backends.bluezdbus.discovery:Smart Hub, 90:84:2B:1B:05:E7 (-60 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
INFO:bleak.backends.bluezdbus.discovery:Smart Hub, 90:84:2B:1B:05:E7 (-59 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
INFO:bleak.backends.bluezdbus.discovery:Smart Hub, 90:84:2B:1B:05:E7 (-61 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
INFO:bleak.backends.bluezdbus.discovery:Smart Hub, 90:84:2B:1B:05:E7 (-59 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
INFO:bleak.backends.bluezdbus.discovery:dev_64_38_13_D0_D4_3E, 64:38:13:D0:D4:3E (? dBm), Object Path: /org/bluez/hci0/dev_64_38_13_D0_D4_3E
INFO:bleak.backends.bluezdbus.discovery:Smart Hub, 90:84:2B:1B:05:E7 (-59 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
Done Awaiting on bleak discover
INFO:BLE Event Q.0:checking manufacturer ID for device named Smart Hub for HUB NO.4
INFO:BLE Event Q.0:found device Smart Hub
INFO:bleak.backends.bluezdbus.discovery:Smart Hub, 90:84:2B:1B:05:E7 (-60 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
INFO:bleak.backends.bluezdbus.discovery:Smart Hub, 90:84:2B:1B:05:E7 (-61 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
INFO:bleak.backends.bluezdbus.discovery:Smart Hub, 90:84:2B:1B:05:E7 (-60 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
INFO:bleak.backends.bluezdbus.discovery:Smart Hub, 90:84:2B:1B:05:E7 (-60 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
INFO:bleak.backends.bluezdbus.discovery:Smart Hub, 90:84:2B:1B:05:E7 (-59 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
INFO:bleak.backends.bluezdbus.discovery:Smart Hub, 90:84:2B:1B:05:E7 (-61 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
INFO:bleak.backends.bluezdbus.discovery:Smart Hub, 90:84:2B:1B:05:E7 (-59 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
INFO:bleak.backends.bluezdbus.discovery:dev_64_38_13_D0_D4_3E, 64:38:13:D0:D4:3E (? dBm), Object Path: /org/bluez/hci0/dev_64_38_13_D0_D4_3E
INFO:bleak.backends.bluezdbus.discovery:Smart Hub, 90:84:2B:1B:05:E7 (-59 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
DEBUG:bleak.backends.bluezdbus.client:Connecting to BLE device @ 90:84:2B:1B:05:E7 with hci0
DEBUG:bleak.backends.bluezdbus.client:Connection successful.
DEBUG:bleak.backends.bluezdbus.client:Get Services...
DEBUG:bleak.backends.bluezdbus.client:
Primary Service
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c
	00001623-1212-efde-1623-785feabcd123
	Unknown
DEBUG:bleak.backends.bluezdbus.client:
Characteristic
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d
	00001624-1212-efde-1623-785feabcd123
	Unknown
DEBUG:bleak.backends.bluezdbus.client:
Descriptor
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d/desc000f
	00002902-0000-1000-8000-00805f9b34fb
	Client Characteristic Configuration
DEBUG:bleak.backends.bluezdbus.client:
Primary Service
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service0001
	00001801-0000-1000-8000-00805f9b34fb
	Generic Attribute Profile
DEBUG:bleak.backends.bluezdbus.client:
Characteristic
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service0001/char0002
	00002a05-0000-1000-8000-00805f9b34fb
	Service Changed
DEBUG:bleak.backends.bluezdbus.client:
Descriptor
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service0001/char0002/desc0004
	00002902-0000-1000-8000-00805f9b34fb
	Client Characteristic Configuration
INFO:BLE Event Q.0:Device advertised: {'00001624-1212-efde-1623-785feabcd123': <bleak.backends.bluezdbus.characteristic.BleakGATTCharacteristicBlueZDBus object at 0x7fd8fe17dcd0>, '00002a05-0000-1000-8000-00805f9b34fb': <bleak.backends.bluezdbus.characteristic.BleakGATTCharacteristicBlueZDBus object at 0x7fd8fe17dfd0>}
INFO:BLE Event Q.0:Connected to device Smart Hub:90:84:2B:1B:05:E7
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7, domain: org.bluez.Device1, body: {'Appearance': 6144}
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Notifying': True}
INFO:BLE Event Q.0:Waiting for hubs to end
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Value': [15, 0, 4, 0, 1, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0]}
INFO:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Value': [15, 0, 4, 0, 1, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0]}, []]
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Value': [15, 0, 4, 50, 1, 23, 0, 0, 0, 0, 16, 0, 0, 0, 16]}
INFO:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Value': [15, 0, 4, 50, 1, 23, 0, 0, 0, 0, 16, 0, 0, 0, 16]}, []]
INFO:My train.2:run
INFO:My train.2:set_speed 50
INFO:motor.1:Setting speed to 50
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Value': [15, 0, 4, 59, 1, 21, 0, 2, 0, 0, 0, 2, 0, 0, 0]}
INFO:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Value': [15, 0, 4, 59, 1, 21, 0, 2, 0, 0, 0, 2, 0, 0, 0]}, []]
DEBUG:bleak.backends.bluezdbus.client:Write Characteristic 00001624-1212-efde-1623-785feabcd123 | /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d: bytearray(b'\x08\x00\x81\x00\x11Q\x002')
INFO:My train.2:wait 5s
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Value': [15, 0, 4, 60, 1, 20, 0, 2, 0, 0, 0, 2, 0, 0, 0]}
INFO:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Value': [15, 0, 4, 60, 1, 20, 0, 2, 0, 0, 0, 2, 0, 0, 0]}, []]
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7, domain: org.bluez.Device1, body: {'ServicesResolved': False, 'Connected': False}
DEBUG:bleak.backends.bluezdbus.client:Device 90:84:2B:1B:05:E7 disconnected.
DEBUG:bleak.backends.bluezdbus.client:Removing rule PropChanged, ID: 1
INFO:My train.2:set_speed 0
INFO:motor.1:Setting speed to 0
DEBUG:bleak.backends.bluezdbus.client:Disconnecting from BLE device...
INFO:My train.2:Terminating peripheral
DEBUG:bleak.backends.bluezdbus.client:Attempt to stop Twisted reactor failed: Can't stop reactor that isn't running.
Traceback (most recent call last):
  File "citytrain_2.py", line 36, in <module>
    start(system)
  File "/usr/lib/python3.7/site-packages/bricknil/bricknil.py", line 156, in start
    __loop.run_until_complete(main(user_system_setup_func))
  File "/usr/lib/python3.7/asyncio/base_events.py", line 587, in run_until_complete
    return future.result()
  File "/usr/lib/python3.7/site-packages/bricknil/bricknil.py", line 126, in main
    await task
  File "citytrain_2.py", line 25, in run
    await self.motor.set_speed(0)
  File "/usr/lib/python3.7/site-packages/bricknil/sensor/motor.py", line 46, in set_speed
    await self.set_output(0, self._convert_speed_to_val(speed))
  File "/usr/lib/python3.7/site-packages/bricknil/sensor/peripheral.py", line 273, in set_output
    await self.send_message(f'set output port:{self.port} mode: {mode} = {value}', b)
  File "/usr/lib/python3.7/site-packages/bricknil/sensor/peripheral.py", line 240, in send_message
    await self.message_handler(msg, msg_bytes, peripheral=self)
  File "/usr/lib/python3.7/site-packages/bricknil/hub.py", line 110, in send_message
    await self.ble_handler.send_message(self.tx, msg_bytes)
  File "/usr/lib/python3.7/site-packages/bricknil/ble_queue.py", line 63, in send_message
    await device.write_gatt_char(char_uuid, values)
  File "/usr/lib/python3.7/site-packages/bleak/backends/bluezdbus/client.py", line 475, in write_gatt_char
    ).asFuture(self.loop)
txdbus.error.RemoteError: org.bluez.Error.Failed: Not connected

I tried to change the LED color and I can only change the color once.
It seems that the hub disconnects or is disconnected before "run" leaves.
Do you have an idea why this happens?
Or do you have/had a similiar problem?

@janvrany
Copy link
Owner

janvrany commented Jan 4, 2021

This looks like an unsolicited disconnect. This is something I see occasionally (but quite often) with my technic hub too, usually when hub gets too far from my laptop.

Unfortunately, technic hub is the only hub I have so I cannot try.

These days I'm working on providing support for unsolicited disconnects, once finished, will push (I have to do it before I return to day-to-day work process)

This should solve a number of odd things I've seen with technic hub. I'd be rather interested if you can try...

@justxi
Copy link
Author

justxi commented Jan 4, 2021

This looks like an unsolicited disconnect. This is something I see occasionally (but quite often) with my technic hub too, usually > when hub gets too far from my laptop.

The train was around 50 cm away from the Laptop with USB dongle for bluetooth.
On the other hand, my Technic hubs (42100) are around 1-1,5 m away.

This should solve a number of odd things I've seen with technic hub. I'd be rather interested if you can try...

Yes, of course =).
Let me know when and where you have pushed it, once you have finished it.

Which other things have you fixed?

@justxi
Copy link
Author

justxi commented Jan 8, 2021

@janvrany Do you have a preview of your current work?

@janvrany
Copy link
Owner

janvrany commented Jan 8, 2021

@justxi Pushed it to https://github.com/janvrany/bricknil/tree/wip/devel (branch wip/devel).
Please note, that:

  1. some APIs has changed - see the changes and commit log
  2. you need patched bleak: https://github.com/janvrany/bleak/tree/bricknil (branch bricknil)
  3. this is work in progress :-)

@justxi
Copy link
Author

justxi commented Jan 9, 2021

@janvrany Thanks. I have successfully set up a chroot, created ebuilds for Gentoo (https://github.com/justxi/bricks/) and all compiles fine with python 3.8. Next step is to test the train with your changes.

@janvrany
Copy link
Owner

janvrany commented Jan 9, 2021

@justxi Cool, let me know if you need any help!

@justxi
Copy link
Author

justxi commented Jan 10, 2021

@janvrany The deprecation warning says to use "run" instead of "start", but maybe you want to fix that:

Traceback (most recent call last):
  File "citytrain_2.py", line 36, in <module>
    start(system)
  File "/usr/lib/python3.8/site-packages/bricknil/bricknil.py", line 186, in start
    loop.run_until_complete(main(program))
NameError: name 'program' is not defined

@justxi
Copy link
Author

justxi commented Jan 10, 2021

Is it correct that you moved the "run" method out of the class? So the above program should look like this:

#!/usr/bin/env python3

import logging

from asyncio import sleep

import bricknil
from bricknil import attach, run
from bricknil.hub import PoweredUpHub
from bricknil.sensor import TrainMotor


@attach(TrainMotor, name='motor', port=0)
class Train(PoweredUpHub):
    pass
#    async def run(self):
#
#        self.message_info('run')
#
#        self.message_info('set_speed 50')
#        await self.motor.set_speed(50) 
#
#        self.message_info('wait 5s')
#        await sleep(5)
#
#        self.message_info('set_speed 0')
#        await self.motor.set_speed(0)
#
#        self.message_info('wait 5s')
#        await sleep(5)

train = Train('My Train')
async def program_train():
        self.message_info('Run...')
        await self.motor.set_speed(50)

        await sleep(5)

        await self.motor.set_speed(0)

        await sleep(5)
        self.message_info('Shutting down...')


if __name__ == '__main__':
    logging.basicConfig(level=logging.DEBUG)
    bricknil.run(program_train())

But know I get the the following eror:

Traceback (most recent call last):
  File "citytrain_2.py", line 48, in <module>
    bricknil.run(program_train())
  File "/usr/lib/python3.8/site-packages/bricknil/bricknil.py", line 153, in run
    loop.run_until_complete(main(program))
TypeError: main() takes 0 positional arguments but 1 was given
sys:1: RuntimeWarning: coroutine 'program_train' was never awaited

Which python version are you using?
Should "program" only execute once or in the event loop "run_until_complete"?

Another question, is it with your changes still possible to connect to more than one hub?

@justxi
Copy link
Author

justxi commented Jan 10, 2021

Maybe this is also interesting: https://docs.python.org/3/whatsnew/3.8.html#asyncio

@janvrany
Copy link
Owner

janvrany commented Jan 10, 2021

@justxi

But know I get the the following eror:

Okay, I tried to build a simple example like yours and run into all sorts of issues. I messed it up and will need more time to fix it. Thanks for spotting this! Good catch!

Which python version are you using?

3.9.1

Another question, is it with your changes still possible to connect to more than one hub?

Yeah, should be, though I cannot try as I have only one. Moreover, it should be possible to control both (all) hubs using a single program (that was one of the motivations for this refactoring)

@justxi
Copy link
Author

justxi commented Jan 11, 2021

@janvrany

But know I get the the following eror:

Okay, I tried to build a simple example like yours and run into all sorts of issues. I messed it up and will need more time to fix it.

Do you have the problems with python 3.9.1 also?
Do you have a working example?

Thanks for spotting this! Good catch!

Never mind, I´m interested in getting my train running =).

@janvrany
Copy link
Owner

@justxi
Yeah, I have it with 3.9.1 too. This is flaw in my code. I did not noticed since I use it differently
using GTK based GUI and controlling it via Playstation DualShock gamepad...

@janvrany
Copy link
Owner

@justxi
Will try to have a look tonight, if time allows.

@justxi
Copy link
Author

justxi commented Jan 18, 2021

@janvrany

it seems that this patch https://github.com/justxi/bricks/blob/master/dev-python/bricknil-janvrany/files/bricknil-run.patch fixes the problem above, but now I get:

INFO:BLE Event Q.0:Starting scan for UART 00001623-1212-efde-1623-785feabcd123
INFO:BLE Event Q.0:Looking for first matching hub
Awaiting on bleak discover
DEBUG:bleak.backends.bluezdbus.scanner:Smart Hub, 90:84:2B:1B:05:E7 (-62 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
DEBUG:bleak.backends.bluezdbus.scanner:5D-83-CC-B4-F1-39, 5D:83:CC:B4:F1:39 (-96 dBm), Object Path: /org/bluez/hci0/dev_5D_83_CC_B4_F1_39
DEBUG:bleak.backends.bluezdbus.scanner:InterfacesRemoved, org.freedesktop.DBus.ObjectManager (/): ['/org/bluez/hci0/dev_5D_83_CC_B4_F1_39', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
DEBUG:bleak.backends.bluezdbus.scanner:None, None (None dBm), Object Path: None
Done Awaiting on bleak discover
INFO:BLE Event Q.0:checking manufacturer ID for device named Smart Hub for HUB NO.4
INFO:BLE Event Q.0:found device Smart Hub
Traceback (most recent call last):
  File "citytrain_3.py", line 48, in <module>
    bricknil.run(program_train())
  File "/usr/lib/python3.8/site-packages/bricknil/bricknil.py", line 153, in run
    loop.run_until_complete(main(program))
  File "/usr/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
    return future.result()
  File "/usr/lib/python3.8/site-packages/bricknil/bricknil.py", line 147, in main
    await initialize()
  File "/usr/lib/python3.8/site-packages/bricknil/bricknil.py", line 103, in initialize
    await hub._connect()
  File "/usr/lib/python3.8/site-packages/bricknil/hub.py", line 85, in _connect
    await self.ble_handler.connect(self)
  File "/usr/lib/python3.8/site-packages/bricknil/ble_queue.py", line 170, in connect
    device = bleak.BleakClient(address=self.device.address)
TypeError: __init__() missing 1 required positional argument: 'address_or_ble_device'
sys:1: RuntimeWarning: coroutine 'program_train' was never awaited

Any idea?

@justxi
Copy link
Author

justxi commented Jan 19, 2021

I had a look on bleak and that is fixed also ...

https://github.com/justxi/bricks/blob/master/dev-python/bricknil-janvrany/files/bricknil-run.patch

But now I get:

Traceback (most recent call last):
  File "citytrain_3.py", line 48, in <module>
    bricknil.run(program_train())
  File "/usr/lib/python3.8/site-packages/bricknil/bricknil.py", line 153, in run
    loop.run_until_complete(main(program))
  File "/usr/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
    return future.result()
  File "/usr/lib/python3.8/site-packages/bricknil/bricknil.py", line 149, in main
    await program()
TypeError: 'coroutine' object is not callable
sys:1: RuntimeWarning: coroutine 'program_train' was never awaited

@justxi
Copy link
Author

justxi commented Jan 19, 2021

Sorry, this was a mistake on my site...

But it seems that the hub disconnects again ...

INFO:BLE Event Q.0:Starting scan for UART 00001623-1212-efde-1623-785feabcd123
INFO:BLE Event Q.0:Looking for first matching hub
Awaiting on bleak discover
DEBUG:bleak.backends.bluezdbus.scanner:Smart Hub, 90:84:2B:1B:05:E7 (-59 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
Done Awaiting on bleak discover
INFO:BLE Event Q.0:checking manufacturer ID for device named Smart Hub for HUB NO.4
INFO:BLE Event Q.0:found device Smart Hub
DEBUG:bleak.backends.bluezdbus.scanner:Smart Hub, 90:84:2B:1B:05:E7 (-59 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
DEBUG:bleak.backends.bluezdbus.scanner:Smart Hub, 90:84:2B:1B:05:E7 (-59 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
DEBUG:bleak.backends.bluezdbus.client:Connecting to BLE device @ 90:84:2B:1B:05:E7 with hci0
DEBUG:bleak.backends.bluezdbus.client:Connection successful.
DEBUG:bleak.backends.bluezdbus.client:Get Services...
DEBUG:bleak.backends.bluezdbus.client:
Primary Service
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c
	00001623-1212-efde-1623-785feabcd123
	Unknown
DEBUG:bleak.backends.bluezdbus.client:
Characteristic
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d
	00001624-1212-efde-1623-785feabcd123
	Unknown
DEBUG:bleak.backends.bluezdbus.client:
Descriptor
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d/desc000f
	00002902-0000-1000-8000-00805f9b34fb
	Client Characteristic Configuration
DEBUG:bleak.backends.bluezdbus.client:
Primary Service
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service0001
	00001801-0000-1000-8000-00805f9b34fb
	Generic Attribute Profile
DEBUG:bleak.backends.bluezdbus.client:
Characteristic
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service0001/char0002
	00002a05-0000-1000-8000-00805f9b34fb
	Service Changed
DEBUG:bleak.backends.bluezdbus.client:
Descriptor
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service0001/char0002/desc0004
	00002902-0000-1000-8000-00805f9b34fb
	Client Characteristic Configuration
INFO:BLE Event Q.0:Device advertised: {13: <bleak.backends.bluezdbus.characteristic.BleakGATTCharacteristicBlueZDBus object at 0x7f8941c1e5e0>, 2: <bleak.backends.bluezdbus.characteristic.BleakGATTCharacteristicBlueZDBus object at 0x7f8941c1e790>}
INFO:BLE Event Q.0:Connected to device Smart Hub:90:84:2B:1B:05:E7
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7, domain: org.bluez.Device1, body: {'Appearance': 6144}
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Notifying': True}
DEBUG:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Notifying': True}, []]
INFO:My Train.2:set_speed 50
INFO:motor.1:Setting speed to 50
DEBUG:bleak.backends.bluezdbus.client:Disconnecting from BLE device...
DEBUG:bleak.backends.bluezdbus.client:Removing rule PropChanged, ID: 1
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Value': [15, 0, 4, 0, 1, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0]}
DEBUG:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Value': [15, 0, 4, 0, 1, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0]}, []]
DEBUG:BLE Event Q.0:Bleak Raw data received: bytearray(b'\x0f\x00\x04\x00\x01\x02\x00\x00\x00\x00\x00\x00\x00\x00\x00')
DEBUG:BLE Event Q.0:My Train Received: Attached IO Port:0 System Train Motor HW:0x0.0x0.0x00x0 SW:0x0.0x0.0x00x0
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Value': [15, 0, 4, 50, 1, 23, 0, 0, 0, 0, 16, 0, 0, 0, 16]}
DEBUG:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Value': [15, 0, 4, 50, 1, 23, 0, 0, 0, 0, 16, 0, 0, 0, 16]}, []]
DEBUG:BLE Event Q.0:Bleak Raw data received: bytearray(b'\x0f\x00\x042\x01\x17\x00\x00\x00\x00\x10\x00\x00\x00\x10')
DEBUG:BLE Event Q.0:My Train Received: Attached IO Port:50 RGB Light HW:0x10.0x0.0x00x0 SW:0x10.0x0.0x00x0
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Value': [15, 0, 4, 59, 1, 21, 0, 2, 0, 0, 0, 2, 0, 0, 0]}
DEBUG:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Value': [15, 0, 4, 59, 1, 21, 0, 2, 0, 0, 0, 2, 0, 0, 0]}, []]
DEBUG:BLE Event Q.0:Bleak Raw data received: bytearray(b'\x0f\x00\x04;\x01\x15\x00\x02\x00\x00\x00\x02\x00\x00\x00')
DEBUG:BLE Event Q.0:My Train Received: Attached IO Port:59 Current HW:0x0.0x0.0x00x2 SW:0x0.0x0.0x00x2
Traceback (most recent call last):
  File "citytrain_3.py", line 48, in <module>
    bricknil.run(program_train)
  File "/usr/lib/python3.8/site-packages/bricknil/bricknil.py", line 153, in run
    loop.run_until_complete(main(program))
  File "/usr/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
    return future.result()
  File "/usr/lib/python3.8/site-packages/bricknil/bricknil.py", line 149, in main
    await program()
  File "citytrain_3.py", line 36, in program_train
    await train.motor.set_speed(50)
  File "/usr/lib/python3.8/site-packages/bricknil/sensor/motor.py", line 46, in set_speed
    await self.set_output(0, self._convert_speed_to_val(speed))
  File "/usr/lib/python3.8/site-packages/bricknil/sensor/peripheral.py", line 281, in set_output
    await self.send_message(f'set output port:{self.port} mode: {mode} = {value}', b)
  File "/usr/lib/python3.8/site-packages/bricknil/sensor/peripheral.py", line 247, in send_message
    raise NotAttachedException("Peripheral %s not yet attached!" % self)
bricknil.sensor.peripheral.NotAttachedException: Peripheral motor.1 not yet attached!

Any idea?

@janvrany
Copy link
Owner

janvrany commented Jan 19, 2021

@justxi : Yes, that is exactly what I see here (on my system). No idea so far, I'm sorry.

@justxi
Copy link
Author

justxi commented Jan 19, 2021

@janvrany It seems that the hub disconnects always after one command, but this is just a guess... The "good" thing is, that it seems to be reproduceble... as well as on your and my system...

@justxi
Copy link
Author

justxi commented Jan 19, 2021

@janvrany Interestingly the hub does not disconnect if no command is send to it. Instead of changing the speed of the motor, I "await" only a "sleep(1)" or repeated "sleep(1)" in a for-loop. I tested this for up to 100 seconds.

@janvrany
Copy link
Owner

I think this is a fault in my code, see:

INFO:BLE Event Q.0:Connected to device Technic Hub:90:84:2B:4D:D4:75
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_4D_D4_75, domain: org.bluez.Device1, body: {'Appearance': 6144}
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_4D_D4_75/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Notifying': True}
DEBUG:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_4D_D4_75/service000c/char000d | [{'Notifying': True}, []]
DEBUG:bricknil.bricknil:bricknil.initialize() exited
DEBUG:__main__:program entered
INFO:front_drive.1:Setting speed to 10
DEBUG:bleak.backends.bluezdbus.client:Disconnecting from BLE device...
DEBUG:bleak.backends.bluezdbus.client:Removing rule PropChanged, ID: 1
INFO:4x4 X-treme Off Roader.3:Terminating peripheral
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_4D_D4_75/service000c/char000d, domain: org.bluez.GattCharacterist

This shows that bricknil.initialize() leaves before attach events from peripherals are received and processed. Not sure whether this is the problem, but this is not supposed to happen. Digging deeper...

@justxi
Copy link
Author

justxi commented Jan 19, 2021

@janvrany In one test I thought that adding an "await sleep(5)" at the beginning of "program" seems to make it better... but this was not reproducable.

@justxi
Copy link
Author

justxi commented Jan 19, 2021

@janvrany Another question is, why do we see:

DEBUG:bleak.backends.bluezdbus.client:Disconnecting from BLE device...

As far as I understand it, it should be called in the "finally" block when the block "try: await program()" leaves.

@janvrany
Copy link
Owner

@justxi: looks like I have fixed it, will push to wip/devel branch shortly.

janvrany added a commit that referenced this issue Jan 19, 2021
Due to a slip in hub connection logic it could happen a peripheral
was deemed as attached even before an 'attach' message has been sent
and received. If in that case hub has been sent a command, it disconnects
(apparrently).

The problem was that peripheral's port not being `None` was used as an
indication whether or not a peripheral is attached (or not). But this is
WRONG, since when peripheral is attached like:

    @Attach(CPlusXLMotor, name='front_drive', port=0)
    @Attach(CPlusXLMotor, name='rear_drive', port=1)
    class XtremeOffRoader(CPlusHub):

(that is, specifying port explicitly), the port is indeed not `None`!

This commit fixes this by encapsluating the query into new `_is_attached()`
method.

This should fix issue #6.
@janvrany
Copy link
Owner

@justxi: Pushed, see https://github.com/janvrany/bricknil/tree/wip/devel
In particular, commit 086ce26 fixes the real issue.

Could you please checkout https://github.com/janvrany/bricknil/tree/wip/devel and try again? Thanks for the patience!

@justxi
Copy link
Author

justxi commented Jan 19, 2021

Hmm, maybe it is too late... but with this program

import logging

from asyncio import sleep

import bricknil
from bricknil import attach, run
from bricknil.hub import PoweredUpHub
from bricknil.sensor import TrainMotor

@attach(TrainMotor, name='motor', port=0)
class Train(PoweredUpHub):
    pass

train = Train('My Train')
async def program_train():
        train.message_info('program_train')

        for idx in range(5):
             train.message_info('0: wait '+str(idx))
             await sleep(1)

        train.message_info('set_speed 50')
        await train.motor.set_speed(50)

        for idx in range(10):
             train.message_info('1: wait '+str(idx))
             await sleep(1)

if __name__ == '__main__':
    logging.basicConfig(level=logging.DEBUG)
    bricknil.run(program_train())

I get this:

INFO:BLE Event Q.0:Starting scan for UART 00001623-1212-efde-1623-785feabcd123
INFO:BLE Event Q.0:Looking for first matching hub
Awaiting on bleak discover
DEBUG:My Train.2:starting peripheral message loop
DEBUG:bleak.backends.bluezdbus.scanner:68-D7-3F-37-D9-48, 68:D7:3F:37:D9:48 (-95 dBm), Object Path: /org/bluez/hci0/dev_68_D7_3F_37_D9_48
DEBUG:bleak.backends.bluezdbus.scanner:InterfacesRemoved, org.freedesktop.DBus.ObjectManager (/): ['/org/bluez/hci0/dev_68_D7_3F_37_D9_48', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
DEBUG:bleak.backends.bluezdbus.scanner:None, None (None dBm), Object Path: None
Done Awaiting on bleak discover
INFO:BLE Event Q.0:Rescanning for 00001623-1212-efde-1623-785feabcd123 (60 tries left)
Awaiting on bleak discover
DEBUG:bleak.backends.bluezdbus.scanner:Smart Hub, 90:84:2B:1B:05:E7 (-68 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
DEBUG:bleak.backends.bluezdbus.scanner:68-D7-3F-37-D9-48, 68:D7:3F:37:D9:48 (-93 dBm), Object Path: /org/bluez/hci0/dev_68_D7_3F_37_D9_48
DEBUG:bleak.backends.bluezdbus.scanner:InterfacesRemoved, org.freedesktop.DBus.ObjectManager (/): ['/org/bluez/hci0/dev_68_D7_3F_37_D9_48', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
DEBUG:bleak.backends.bluezdbus.scanner:None, None (None dBm), Object Path: None
Done Awaiting on bleak discover
INFO:BLE Event Q.0:checking manufacturer ID for device named Smart Hub for HUB NO.4
INFO:BLE Event Q.0:found device Smart Hub
DEBUG:bleak.backends.bluezdbus.scanner:68-D7-3F-37-D9-48, 68:D7:3F:37:D9:48 (-95 dBm), Object Path: /org/bluez/hci0/dev_68_D7_3F_37_D9_48
DEBUG:bleak.backends.bluezdbus.scanner:Smart Hub, 90:84:2B:1B:05:E7 (-61 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
DEBUG:bleak.backends.bluezdbus.scanner:68-D7-3F-37-D9-48, 68:D7:3F:37:D9:48 (-95 dBm), Object Path: /org/bluez/hci0/dev_68_D7_3F_37_D9_48
DEBUG:bleak.backends.bluezdbus.scanner:InterfacesRemoved, org.freedesktop.DBus.ObjectManager (/): ['/org/bluez/hci0/dev_68_D7_3F_37_D9_48', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
DEBUG:bleak.backends.bluezdbus.scanner:None, None (None dBm), Object Path: None
DEBUG:bleak.backends.bluezdbus.scanner:Smart Hub, 90:84:2B:1B:05:E7 (-61 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
DEBUG:bleak.backends.bluezdbus.client:Connecting to BLE device @ 90:84:2B:1B:05:E7 with hci0
DEBUG:bleak.backends.bluezdbus.client:Connection successful.
DEBUG:bleak.backends.bluezdbus.client:Get Services...
DEBUG:bleak.backends.bluezdbus.client:
Primary Service
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c
	00001623-1212-efde-1623-785feabcd123
	Unknown
DEBUG:bleak.backends.bluezdbus.client:
Characteristic
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d
	00001624-1212-efde-1623-785feabcd123
	Unknown
DEBUG:bleak.backends.bluezdbus.client:
Descriptor
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d/desc000f
	00002902-0000-1000-8000-00805f9b34fb
	Client Characteristic Configuration
DEBUG:bleak.backends.bluezdbus.client:
Primary Service
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service0001
	00001801-0000-1000-8000-00805f9b34fb
	Generic Attribute Profile
DEBUG:bleak.backends.bluezdbus.client:
Characteristic
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service0001/char0002
	00002a05-0000-1000-8000-00805f9b34fb
	Service Changed
DEBUG:bleak.backends.bluezdbus.client:
Descriptor
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service0001/char0002/desc0004
	00002902-0000-1000-8000-00805f9b34fb
	Client Characteristic Configuration
INFO:BLE Event Q.0:Device advertised: {13: <bleak.backends.bluezdbus.characteristic.BleakGATTCharacteristicBlueZDBus object at 0x7f3014015a30>, 2: <bleak.backends.bluezdbus.characteristic.BleakGATTCharacteristicBlueZDBus object at 0x7f30140158e0>}
INFO:BLE Event Q.0:Connected to device Smart Hub:90:84:2B:1B:05:E7
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7, domain: org.bluez.Device1, body: {'Appearance': 6144}
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Notifying': True}
DEBUG:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Notifying': True}, []]
INFO:My Train.2:Waiting for peripheral motor to attach to a port
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Value': [15, 0, 4, 0, 1, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0]}
DEBUG:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Value': [15, 0, 4, 0, 1, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0]}, []]
DEBUG:BLE Event Q.0:Bleak Raw data received: bytearray(b'\x0f\x00\x04\x00\x01\x02\x00\x00\x00\x00\x00\x00\x00\x00\x00')
DEBUG:BLE Event Q.0:My Train Received: Attached IO Port:0 System Train Motor HW:0x0.0x0.0x00x0 SW:0x0.0x0.0x00x0
INFO:motor.1:motor.1 attached to My Train.2, port 0
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Value': [15, 0, 4, 50, 1, 23, 0, 0, 0, 0, 16, 0, 0, 0, 16]}
DEBUG:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Value': [15, 0, 4, 50, 1, 23, 0, 0, 0, 0, 16, 0, 0, 0, 16]}, []]
DEBUG:BLE Event Q.0:Bleak Raw data received: bytearray(b'\x0f\x00\x042\x01\x17\x00\x00\x00\x00\x10\x00\x00\x00\x10')
DEBUG:BLE Event Q.0:My Train Received: Attached IO Port:50 RGB Light HW:0x10.0x0.0x00x0 SW:0x10.0x0.0x00x0
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Value': [15, 0, 4, 59, 1, 21, 0, 2, 0, 0, 0, 2, 0, 0, 0]}
DEBUG:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Value': [15, 0, 4, 59, 1, 21, 0, 2, 0, 0, 0, 2, 0, 0, 0]}, []]
DEBUG:BLE Event Q.0:Bleak Raw data received: bytearray(b'\x0f\x00\x04;\x01\x15\x00\x02\x00\x00\x00\x02\x00\x00\x00')
DEBUG:BLE Event Q.0:My Train Received: Attached IO Port:59 Current HW:0x0.0x0.0x00x2 SW:0x0.0x0.0x00x2
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Value': [15, 0, 4, 60, 1, 20, 0, 2, 0, 0, 0, 2, 0, 0, 0]}
DEBUG:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Value': [15, 0, 4, 60, 1, 20, 0, 2, 0, 0, 0, 2, 0, 0, 0]}, []]
DEBUG:BLE Event Q.0:Bleak Raw data received: bytearray(b'\x0f\x00\x04<\x01\x14\x00\x02\x00\x00\x00\x02\x00\x00\x00')
DEBUG:BLE Event Q.0:My Train Received: Attached IO Port:60 Voltage HW:0x0.0x0.0x00x2 SW:0x0.0x0.0x00x2
INFO:My Train.2:program_train
INFO:My Train.2:0: wait 0
INFO:My Train.2:0: wait 1
INFO:My Train.2:0: wait 2
INFO:My Train.2:0: wait 3
INFO:My Train.2:0: wait 4
INFO:My Train.2:set_speed 50
INFO:motor.1:Setting speed to 50
DEBUG:bleak.backends.bluezdbus.client:Write Characteristic 00001624-1212-efde-1623-785feabcd123 | /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d: bytearray(b'\x08\x00\x81\x00\x11Q\x002')
INFO:My Train.2:1: wait 0
INFO:My Train.2:1: wait 1
INFO:My Train.2:1: wait 2
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7, domain: org.bluez.Device1, body: {'ServicesResolved': False, 'Connected': False}
DEBUG:bleak.backends.bluezdbus.client:Device 90:84:2B:1B:05:E7 disconnected.
DEBUG:bleak.backends.bluezdbus.client:Removing rule PropChanged, ID: 1
INFO:My Train.2:1: wait 3
INFO:My Train.2:1: wait 4
INFO:My Train.2:1: wait 5
INFO:My Train.2:1: wait 6
INFO:My Train.2:1: wait 7
INFO:My Train.2:1: wait 8
INFO:My Train.2:1: wait 9
DEBUG:bleak.backends.bluezdbus.client:Disconnecting from BLE device...
INFO:My Train.2:Terminating peripheral

It seems that the hub still disconnects.

@justxi
Copy link
Author

justxi commented Jan 19, 2021

btw... I will go to C3 now and continue in the evening =).

@janvrany
Copy link
Owner

Given that changes in wip/devel work for me and given the time limitations, I merged these changes to devel branch. Let me know if it fixes your problem, thanks!

@justxi
Copy link
Author

justxi commented Jan 21, 2021

@janvrany
Yes, I will try your current devel branch with the Lego train.

@justxi
Copy link
Author

justxi commented Jan 21, 2021

@janvrany
Good: I adapted your 4x4 example for the rallycar and latest devel branch works for the technic hub, execept the button change seems not to be recognized.

Bad: The PoweredUpHub still disconnects after 2-3 seconds and only one command is possible.
So my guess is, that my problem is not related to what you have fixed :(.

@janvrany
Copy link
Owner

Hmm...disappointing.

Can you please post again complete log with new version, the script and perhaps what exactly you call "PoweredUpHub" (the LEGO number - I'm not very familiar with LEGO - I only have the technic hub from 4x4).

@justxi
Copy link
Author

justxi commented Jan 23, 2021

In the Lego City trains (e.g. 60197) https://www.lego.com/en-gb/product/hub-88009 is used.

I will add the script and the output later.

Thanks for your support.

@justxi
Copy link
Author

justxi commented Jan 23, 2021

This is the script:

import logging

from asyncio import sleep

import bricknil
from bricknil import attach, run
from bricknil.hub import PoweredUpHub
from bricknil.sensor import TrainMotor

@attach(TrainMotor, name='motor', port=0)
class Train(PoweredUpHub):
    pass

train = Train('My Train')
async def program_train():
        train.message_info('program_train')

        for idx in range(5):
             train.message_info('0: wait '+str(idx))
             await sleep(1)

        train.message_info('set_speed 50')
        await train.motor.set_speed(50)

#	await sleep(3)
#        await train.motor.set_speed(0)

        for idx in range(10):
             train.message_info('1: wait '+str(idx))
             await sleep(1)

if __name__ == '__main__':
    logging.basicConfig(level=logging.DEBUG)
    bricknil.run(program_train())

@justxi
Copy link
Author

justxi commented Jan 23, 2021

And the output:

INFO:BLE Event Q.0:Starting scan for UART 00001623-1212-efde-1623-785feabcd123
INFO:BLE Event Q.0:Looking for first matching hub
Awaiting on bleak discover
DEBUG:My Train.2:starting peripheral message loop
DEBUG:bleak.backends.bluezdbus.scanner:Smart Hub, 90:84:2B:1B:05:E7 (-59 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
DEBUG:bleak.backends.bluezdbus.scanner:66-1F-75-1B-7E-69, 66:1F:75:1B:7E:69 (-86 dBm), Object Path: /org/bluez/hci0/dev_66_1F_75_1B_7E_69
DEBUG:bleak.backends.bluezdbus.scanner:InterfacesRemoved, org.freedesktop.DBus.ObjectManager (/): ['/org/bluez/hci0/dev_66_1F_75_1B_7E_69', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
DEBUG:bleak.backends.bluezdbus.scanner:None, None (None dBm), Object Path: None
Done Awaiting on bleak discover
INFO:BLE Event Q.0:checking manufacturer ID for device named Smart Hub for HUB NO.4
INFO:BLE Event Q.0:found device Smart Hub
DEBUG:bleak.backends.bluezdbus.scanner:Smart Hub, 90:84:2B:1B:05:E7 (-59 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
DEBUG:bleak.backends.bluezdbus.scanner:Smart Hub, 90:84:2B:1B:05:E7 (-59 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
DEBUG:bleak.backends.bluezdbus.client:Connecting to BLE device @ 90:84:2B:1B:05:E7 with hci0
DEBUG:bleak.backends.bluezdbus.client:Connection successful.
DEBUG:bleak.backends.bluezdbus.client:Get Services...
DEBUG:bleak.backends.bluezdbus.client:
Primary Service
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c
	00001623-1212-efde-1623-785feabcd123
	Unknown
DEBUG:bleak.backends.bluezdbus.client:
Characteristic
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d
	00001624-1212-efde-1623-785feabcd123
	Unknown
DEBUG:bleak.backends.bluezdbus.client:
Descriptor
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d/desc000f
	00002902-0000-1000-8000-00805f9b34fb
	Client Characteristic Configuration
DEBUG:bleak.backends.bluezdbus.client:
Primary Service
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service0001
	00001801-0000-1000-8000-00805f9b34fb
	Generic Attribute Profile
DEBUG:bleak.backends.bluezdbus.client:
Characteristic
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service0001/char0002
	00002a05-0000-1000-8000-00805f9b34fb
	Service Changed
DEBUG:bleak.backends.bluezdbus.client:
Descriptor
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service0001/char0002/desc0004
	00002902-0000-1000-8000-00805f9b34fb
	Client Characteristic Configuration
INFO:BLE Event Q.0:Device advertised: {13: <bleak.backends.bluezdbus.characteristic.BleakGATTCharacteristicBlueZDBus object at 0x7f9c11565580>, 2: <bleak.backends.bluezdbus.characteristic.BleakGATTCharacteristicBlueZDBus object at 0x7f9c114fa4c0>}
INFO:BLE Event Q.0:Connected to device Smart Hub:90:84:2B:1B:05:E7
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7, domain: org.bluez.Device1, body: {'Appearance': 6144}
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Notifying': True}
DEBUG:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Notifying': True}, []]
INFO:My Train.2:Waiting for peripheral motor to attach to a port
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Value': [15, 0, 4, 0, 1, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0]}
DEBUG:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Value': [15, 0, 4, 0, 1, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0]}, []]
DEBUG:BLE Event Q.0:Bleak Raw data received: bytearray(b'\x0f\x00\x04\x00\x01\x02\x00\x00\x00\x00\x00\x00\x00\x00\x00')
DEBUG:BLE Event Q.0:My Train Received: Attached IO Port:0 System Train Motor HW:0x0.0x0.0x00x0 SW:0x0.0x0.0x00x0
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Value': [15, 0, 4, 50, 1, 23, 0, 0, 0, 0, 16, 0, 0, 0, 16]}
DEBUG:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Value': [15, 0, 4, 50, 1, 23, 0, 0, 0, 0, 16, 0, 0, 0, 16]}, []]
DEBUG:BLE Event Q.0:Bleak Raw data received: bytearray(b'\x0f\x00\x042\x01\x17\x00\x00\x00\x00\x10\x00\x00\x00\x10')
DEBUG:BLE Event Q.0:My Train Received: Attached IO Port:50 RGB Light HW:0x10.0x0.0x00x0 SW:0x10.0x0.0x00x0
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Value': [15, 0, 4, 59, 1, 21, 0, 2, 0, 0, 0, 2, 0, 0, 0]}
DEBUG:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Value': [15, 0, 4, 59, 1, 21, 0, 2, 0, 0, 0, 2, 0, 0, 0]}, []]
DEBUG:BLE Event Q.0:Bleak Raw data received: bytearray(b'\x0f\x00\x04;\x01\x15\x00\x02\x00\x00\x00\x02\x00\x00\x00')
DEBUG:BLE Event Q.0:My Train Received: Attached IO Port:59 Current HW:0x0.0x0.0x00x2 SW:0x0.0x0.0x00x2
INFO:motor.1:motor.1 attached to My Train.2, port 0
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Value': [15, 0, 4, 60, 1, 20, 0, 2, 0, 0, 0, 2, 0, 0, 0]}
DEBUG:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Value': [15, 0, 4, 60, 1, 20, 0, 2, 0, 0, 0, 2, 0, 0, 0]}, []]
DEBUG:BLE Event Q.0:Bleak Raw data received: bytearray(b'\x0f\x00\x04<\x01\x14\x00\x02\x00\x00\x00\x02\x00\x00\x00')
DEBUG:BLE Event Q.0:My Train Received: Attached IO Port:60 Voltage HW:0x0.0x0.0x00x2 SW:0x0.0x0.0x00x2
INFO:My Train.2:program_train
INFO:My Train.2:0: wait 0
INFO:My Train.2:0: wait 1
INFO:My Train.2:0: wait 2
INFO:My Train.2:0: wait 3
INFO:My Train.2:0: wait 4
INFO:My Train.2:set_speed 50
INFO:motor.1:Setting speed to 50
DEBUG:bleak.backends.bluezdbus.client:Write Characteristic 00001624-1212-efde-1623-785feabcd123 | /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d: bytearray(b'\x08\x00\x81\x00\x11Q\x002')
INFO:My Train.2:1: wait 0
INFO:My Train.2:1: wait 1
INFO:My Train.2:1: wait 2
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7, domain: org.bluez.Device1, body: {'ServicesResolved': False, 'Connected': False}
DEBUG:bleak.backends.bluezdbus.client:Device 90:84:2B:1B:05:E7 disconnected.
DEBUG:bleak.backends.bluezdbus.client:Removing rule PropChanged, ID: 1
INFO:My Train.2:1: wait 3
INFO:My Train.2:1: wait 4
INFO:My Train.2:1: wait 5
INFO:My Train.2:1: wait 6
INFO:My Train.2:1: wait 7
INFO:My Train.2:1: wait 8
INFO:My Train.2:1: wait 9
DEBUG:bleak.backends.bluezdbus.client:Disconnecting from BLE device...
INFO:My Train.2:Terminating peripheral

@justxi
Copy link
Author

justxi commented Jan 23, 2021

If the second set_speed command is executed (uncommented), this is the result:

INFO:BLE Event Q.0:Looking for first matching hub
Awaiting on bleak discover
DEBUG:My Train.2:starting peripheral message loop
DEBUG:bleak.backends.bluezdbus.scanner:66-1F-75-1B-7E-69, 66:1F:75:1B:7E:69 (-84 dBm), Object Path: /org/bluez/hci0/dev_66_1F_75_1B_7E_69
DEBUG:bleak.backends.bluezdbus.scanner:InterfacesRemoved, org.freedesktop.DBus.ObjectManager (/): ['/org/bluez/hci0/dev_66_1F_75_1B_7E_69', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
DEBUG:bleak.backends.bluezdbus.scanner:None, None (None dBm), Object Path: None
Done Awaiting on bleak discover
INFO:BLE Event Q.0:checking manufacturer ID for device named Smart Hub for HUB NO.4
INFO:BLE Event Q.0:found device Smart Hub
DEBUG:bleak.backends.bluezdbus.scanner:66-1F-75-1B-7E-69, 66:1F:75:1B:7E:69 (-85 dBm), Object Path: /org/bluez/hci0/dev_66_1F_75_1B_7E_69
DEBUG:bleak.backends.bluezdbus.scanner:Smart Hub, 90:84:2B:1B:05:E7 (-59 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
DEBUG:bleak.backends.bluezdbus.scanner:66-1F-75-1B-7E-69, 66:1F:75:1B:7E:69 (-85 dBm), Object Path: /org/bluez/hci0/dev_66_1F_75_1B_7E_69
DEBUG:bleak.backends.bluezdbus.scanner:InterfacesRemoved, org.freedesktop.DBus.ObjectManager (/): ['/org/bluez/hci0/dev_66_1F_75_1B_7E_69', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
DEBUG:bleak.backends.bluezdbus.scanner:None, None (None dBm), Object Path: None
DEBUG:bleak.backends.bluezdbus.scanner:Smart Hub, 90:84:2B:1B:05:E7 (-59 dBm), Object Path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7
DEBUG:bleak.backends.bluezdbus.client:Connecting to BLE device @ 90:84:2B:1B:05:E7 with hci0
DEBUG:bleak.backends.bluezdbus.client:Connection successful.
DEBUG:bleak.backends.bluezdbus.client:Get Services...
DEBUG:bleak.backends.bluezdbus.client:
Primary Service
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c
	00001623-1212-efde-1623-785feabcd123
	Unknown
DEBUG:bleak.backends.bluezdbus.client:
Characteristic
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d
	00001624-1212-efde-1623-785feabcd123
	Unknown
DEBUG:bleak.backends.bluezdbus.client:
Descriptor
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d/desc000f
	00002902-0000-1000-8000-00805f9b34fb
	Client Characteristic Configuration
DEBUG:bleak.backends.bluezdbus.client:
Primary Service
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service0001
	00001801-0000-1000-8000-00805f9b34fb
	Generic Attribute Profile
DEBUG:bleak.backends.bluezdbus.client:
Characteristic
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service0001/char0002
	00002a05-0000-1000-8000-00805f9b34fb
	Service Changed
DEBUG:bleak.backends.bluezdbus.client:
Descriptor
	/org/bluez/hci0/dev_90_84_2B_1B_05_E7/service0001/char0002/desc0004
	00002902-0000-1000-8000-00805f9b34fb
	Client Characteristic Configuration
INFO:BLE Event Q.0:Device advertised: {13: <bleak.backends.bluezdbus.characteristic.BleakGATTCharacteristicBlueZDBus object at 0x7fcccafa00d0>, 2: <bleak.backends.bluezdbus.characteristic.BleakGATTCharacteristicBlueZDBus object at 0x7fcccafa0190>}
INFO:BLE Event Q.0:Connected to device Smart Hub:90:84:2B:1B:05:E7
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Notifying': True}
DEBUG:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Notifying': True}, []]
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Value': [15, 0, 4, 0, 1, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0]}
DEBUG:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Value': [15, 0, 4, 0, 1, 2, 0, 0, 0, 0, 0, 0, 0, 0, 0]}, []]
DEBUG:BLE Event Q.0:Bleak Raw data received: bytearray(b'\x0f\x00\x04\x00\x01\x02\x00\x00\x00\x00\x00\x00\x00\x00\x00')
DEBUG:BLE Event Q.0:My Train Received: Attached IO Port:0 System Train Motor HW:0x0.0x0.0x00x0 SW:0x0.0x0.0x00x0
INFO:My Train.2:Waiting for peripheral motor to attach to a port
INFO:motor.1:motor.1 attached to My Train.2, port 0
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Value': [15, 0, 4, 50, 1, 23, 0, 0, 0, 0, 16, 0, 0, 0, 16]}
DEBUG:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Value': [15, 0, 4, 50, 1, 23, 0, 0, 0, 0, 16, 0, 0, 0, 16]}, []]
DEBUG:BLE Event Q.0:Bleak Raw data received: bytearray(b'\x0f\x00\x042\x01\x17\x00\x00\x00\x00\x10\x00\x00\x00\x10')
DEBUG:BLE Event Q.0:My Train Received: Attached IO Port:50 RGB Light HW:0x10.0x0.0x00x0 SW:0x10.0x0.0x00x0
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Value': [15, 0, 4, 59, 1, 21, 0, 2, 0, 0, 0, 2, 0, 0, 0]}
DEBUG:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Value': [15, 0, 4, 59, 1, 21, 0, 2, 0, 0, 0, 2, 0, 0, 0]}, []]
DEBUG:BLE Event Q.0:Bleak Raw data received: bytearray(b'\x0f\x00\x04;\x01\x15\x00\x02\x00\x00\x00\x02\x00\x00\x00')
DEBUG:BLE Event Q.0:My Train Received: Attached IO Port:59 Current HW:0x0.0x0.0x00x2 SW:0x0.0x0.0x00x2
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d, domain: org.bluez.GattCharacteristic1, body: {'Value': [15, 0, 4, 60, 1, 20, 0, 2, 0, 0, 0, 2, 0, 0, 0]}
DEBUG:bleak.backends.bluezdbus.client:GATT Char Properties Changed: /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d | [{'Value': [15, 0, 4, 60, 1, 20, 0, 2, 0, 0, 0, 2, 0, 0, 0]}, []]
DEBUG:BLE Event Q.0:Bleak Raw data received: bytearray(b'\x0f\x00\x04<\x01\x14\x00\x02\x00\x00\x00\x02\x00\x00\x00')
DEBUG:BLE Event Q.0:My Train Received: Attached IO Port:60 Voltage HW:0x0.0x0.0x00x2 SW:0x0.0x0.0x00x2
INFO:My Train.2:program_train
INFO:My Train.2:0: wait 0
INFO:My Train.2:0: wait 1
INFO:My Train.2:0: wait 2
INFO:My Train.2:0: wait 3
INFO:My Train.2:0: wait 4
INFO:My Train.2:set_speed 50
INFO:motor.1:Setting speed to 50
DEBUG:bleak.backends.bluezdbus.client:Write Characteristic 00001624-1212-efde-1623-785feabcd123 | /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d: bytearray(b'\x08\x00\x81\x00\x11Q\x002')
DEBUG:bleak.backends.bluezdbus.client:DBUS: path: /org/bluez/hci0/dev_90_84_2B_1B_05_E7, domain: org.bluez.Device1, body: {'ServicesResolved': False, 'Connected': False}
DEBUG:bleak.backends.bluezdbus.client:Device 90:84:2B:1B:05:E7 disconnected.
DEBUG:bleak.backends.bluezdbus.client:Removing rule PropChanged, ID: 1
INFO:motor.1:Setting speed to 0
DEBUG:bleak.backends.bluezdbus.client:Disconnecting from BLE device...
INFO:My Train.2:Terminating peripheral
Traceback (most recent call last):
  File "citytrain_4_dis.py", line 36, in <module>
    bricknil.run(program_train())
  File "/usr/lib/python3.8/site-packages/bricknil/bricknil.py", line 153, in run
    loop.run_until_complete(main())
  File "/usr/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
    return future.result()
  File "/usr/lib/python3.8/site-packages/bricknil/bricknil.py", line 149, in main
    await program
  File "citytrain_4_dis.py", line 28, in program_train
    await train.motor.set_speed(0)
  File "/usr/lib/python3.8/site-packages/bricknil/sensor/motor.py", line 46, in set_speed
    await self.set_output(0, self._convert_speed_to_val(speed))
  File "/usr/lib/python3.8/site-packages/bricknil/sensor/peripheral.py", line 281, in set_output
    await self.send_message(f'set output port:{self.port} mode: {mode} = {value}', b)
  File "/usr/lib/python3.8/site-packages/bricknil/sensor/peripheral.py", line 248, in send_message
    await self.message_handler(msg, msg_bytes, peripheral=self)
  File "/usr/lib/python3.8/site-packages/bricknil/hub.py", line 140, in send_message
    await self.ble_handler.send_message(self.tx, msg_bytes)
  File "/usr/lib/python3.8/site-packages/bricknil/ble_queue.py", line 63, in send_message
    await device.write_gatt_char(char_uuid, values)
  File "/usr/lib/python3.8/site-packages/bleak/backends/bluezdbus/client.py", line 629, in write_gatt_char
    await self._bus.callRemote(
AttributeError: 'NoneType' object has no attribute 'callRemote'


@justxi
Copy link
Author

justxi commented Jan 23, 2021

It is very strange, the "Technic hub" and the "move hub" (Boost) seem to work; all starts, executes and terminates as expected.

I tested the train hub with the Android app and it works as expected also.
Firmware must be the newest version, because the app does not update it on startup.

I use Gentoo Linux, Kernel 5.10.4, bluez 5.55 and python 3.7.9.
In my changeroot I use python 3.8.6.
I use an usb bluetooth stick from Asus.

There must be something different.... but what?
I would assume that the hubs should behave the same way.
Only the ports and internal devices should be different.

@justxi
Copy link
Author

justxi commented Jan 24, 2021

@janvrany
Good or bad news depending on how you want to see it ...

I installed the latest version of bricknil from virantha (0.9.3) and its dependencies using python 3.7.
And the "train_ramp.py" example works.

So there must be something broken regarding the "PoweredUpHub" aka. "TwoPortHub" in your current version or a dependency.
I will try to find the difference.

@janvrany
Copy link
Owner

@justxi
That's very good! Thanks!
I believe my code is based on 0.9.3 so you can bisect to find the offending commit.

@justxi
Copy link
Author

justxi commented Jan 24, 2021

I think thats a good idea.
Besides this, curio was replaced by asyncio and bleak as well as txdbus were updated.
What a challenge =)...

@justxi
Copy link
Author

justxi commented Jan 25, 2021

Do you remember which version of bleak you have used at this point: f433a4c ?

@Novakasa
Copy link

Novakasa commented Feb 5, 2021

I also have the Train hub, and I just tested the code from @justxi above ( #6 (comment) ), it seems to be working for me, also when uncommenting the second set_speed line. I am running on windows 10, python 3.9.1.
I tested it with both of my Train hubs, I think all of them have a pretty recent firmware since I connected them to the PoweredUp App about 2 weeks ago.

@Novakasa
Copy link

Novakasa commented Feb 5, 2021

However, if I add a VisionSensor:

import logging

from asyncio import sleep

import bricknil
from bricknil import attach, run
from bricknil.hub import PoweredUpHub
from bricknil.sensor import TrainMotor, VisionSensor

@attach(TrainMotor, name='motor', port=0)
@attach(VisionSensor, name='train_sensor', capabilities=['sense_color'], port=1)
class Train(PoweredUpHub):
	
	async def train_sensor_change(self):
		print(self.train_sensor.sense_color)

train = Train('My Train')
async def program_train():
		train.message_info('program_train')

		for idx in range(5):
			 train.message_info('0: wait '+str(idx))
			 await sleep(1)

		train.message_info('set_speed 50')
		await train.motor.set_speed(50)

		await sleep(3)
		await train.motor.set_speed(0)

		for idx in range(10):
			 train.message_info('1: wait '+str(idx))
			 await sleep(1)

if __name__ == '__main__':
	logging.basicConfig(level=logging.DEBUG)
	bricknil.run(program_train())

I get the following exception:

Exception has occurred: BleakDotNetTaskError
System.ObjectDisposedException: The object has been closed. (Exception from HRESULT: 0x80000013)
  File "E:\repos\auto-rail\tests\test_github_issue.py", line 26, in program_train
    await train.motor.set_speed(50)
  File "E:\repos\auto-rail\tests\test_github_issue.py", line 37, in <module>
    bricknil.run(program_train())

And the log:

INFO:BLE Event Q.0:Starting scan for UART 00001623-1212-efde-1623-785feabcd123
INFO:BLE Event Q.0:Looking for first matching hub
Awaiting on bleak discover
DEBUG:My Train.3:starting peripheral message loop
DEBUG:bleak.backends.dotnet.scanner:Received 90:84:2B:BE:1E:40: Unknown.
DEBUG:bleak.backends.dotnet.scanner:Received 90:84:2B:BE:1E:40: HUB NO.4.
DEBUG:bleak.backends.dotnet.scanner:Received 40:CB:C0:E2:D9:6A: Unknown.
DEBUG:bleak.backends.dotnet.scanner:Received 21:C7:F6:2B:BB:54: Unknown.
DEBUG:bleak.backends.dotnet.scanner:Received F4:FE:FB:65:41:09: Unknown.
DEBUG:bleak.backends.dotnet.scanner:Received 90:84:2B:BE:1E:40: Unknown.
DEBUG:bleak.backends.dotnet.scanner:Received 90:84:2B:BE:1E:40: HUB NO.4.
DEBUG:bleak.backends.dotnet.scanner:Received AC:37:43:F7:38:82: HTC BS 827BB1.
DEBUG:bleak.backends.dotnet.scanner:Received AC:37:43:F7:38:82: Unknown.
DEBUG:bleak.backends.dotnet.scanner:Received 90:84:2B:BE:1E:40: Unknown.
DEBUG:bleak.backends.dotnet.scanner:Received 90:84:2B:BE:1E:40: HUB NO.4.
DEBUG:bleak.backends.dotnet.scanner:Received 90:84:2B:BE:1E:40: Unknown.
DEBUG:bleak.backends.dotnet.scanner:Received 90:84:2B:BE:1E:40: HUB NO.4.
DEBUG:bleak.backends.dotnet.scanner:Received AC:37:43:F7:3C:B3: HTC BS B3DFFC.
DEBUG:bleak.backends.dotnet.scanner:Received AC:37:43:F7:3C:B3: Unknown.
DEBUG:bleak.backends.dotnet.scanner:Received 90:84:2B:BE:1E:40: Unknown.
DEBUG:bleak.backends.dotnet.scanner:Received 90:84:2B:BE:1E:40: HUB NO.4.
DEBUG:bleak.backends.dotnet.scanner:Received AC:37:43:F7:38:82: HTC BS 827BB1.
DEBUG:bleak.backends.dotnet.scanner:Received AC:37:43:F7:38:82: Unknown.
Done Awaiting on bleak discover
INFO:BLE Event Q.0:checking manufacturer ID for device named Unknown for HUB NO.4
INFO:BLE Event Q.0:found device Unknown
DEBUG:bleak.backends.dotnet.scanner:Received 40:CB:C0:E2:D9:6A: Unknown.
DEBUG:bleak.backends.dotnet.scanner:Received F4:FE:FB:65:41:09: Unknown.
DEBUG:bleak.backends.dotnet.scanner:Received AC:37:43:F7:3C:B3: HTC BS B3DFFC.
DEBUG:bleak.backends.dotnet.scanner:Received AC:37:43:F7:3C:B3: Unknown.
DEBUG:bleak.backends.dotnet.scanner:Received AC:37:43:F7:3C:B3: HTC BS B3DFFC.
DEBUG:bleak.backends.dotnet.scanner:Received F4:FE:FB:65:41:09: Unknown.
DEBUG:bleak.backends.dotnet.scanner:Received 90:84:2B:BE:1E:40: Unknown.
DEBUG:bleak.backends.dotnet.client:Connecting to BLE device @ 90:84:2B:BE:1E:40
DEBUG:bleak.backends.dotnet.client:_ConnectionStatusChanged_Handler: 1
DEBUG:bleak.backends.dotnet.client:Get Services...
INFO:bleak.backends.dotnet.client:Services resolved for BleakClientDotNet (90:84:2B:BE:1E:40)
INFO:BLE Event Q.0:Device advertised: {2: <bleak.backends.dotnet.characteristic.BleakGATTCharacteristicDotNet object at 0x000002B6EEBB1640>, 6: <bleak.backends.dotnet.characteristic.BleakGATTCharacteristicDotNet object at 0x000002B6EEBB63D0>, 8: <bleak.backends.dotnet.characteristic.BleakGATTCharacteristicDotNet object at 0x000002B6EEBB6940>, 10: <bleak.backends.dotnet.characteristic.BleakGATTCharacteristicDotNet object at 0x000002B6EEBB6A90>, 13: <bleak.backends.dotnet.characteristic.BleakGATTCharacteristicDotNet object at 0x000002B6EEBB6BE0>}
INFO:BLE Event Q.0:Connected to device HUB NO.4:90:84:2B:BE:1E:40
INFO:My Train.3:Waiting for peripheral train_sensor to attach to a port
DEBUG:BLE Event Q.0:Bleak Raw data received: bytearray(b'\x0f\x00\x04\x00\x01\x02\x00\x00\x00\x00\x00\x00\x00\x00\x00')
DEBUG:BLE Event Q.0:My Train Received: Attached IO Port:0 System Train Motor HW:0x0.0x0.0x00x0 SW:0x0.0x0.0x00x0
DEBUG:BLE Event Q.0:Bleak Raw data received: bytearray(b'\x0f\x00\x042\x01\x17\x00\x00\x00\x00\x10\x00\x00\x00\x10')
DEBUG:BLE Event Q.0:My Train Received: Attached IO Port:50 RGB Light HW:0x10.0x0.0x00x0 SW:0x10.0x0.0x00x0
DEBUG:BLE Event Q.0:Bleak Raw data received: bytearray(b'\x0f\x00\x04;\x01\x15\x00\x02\x00\x00\x00\x02\x00\x00\x00')
DEBUG:BLE Event Q.0:My Train Received: Attached IO Port:59 Current HW:0x0.0x0.0x00x2 SW:0x0.0x0.0x00x2
INFO:motor.1:motor.1 attached to My Train.3, port 0
DEBUG:BLE Event Q.0:Bleak Raw data received: bytearray(b'\x0f\x00\x04<\x01\x14\x00\x02\x00\x00\x00\x02\x00\x00\x00')
DEBUG:BLE Event Q.0:My Train Received: Attached IO Port:60 Voltage HW:0x0.0x0.0x00x2 SW:0x0.0x0.0x00x2
INFO:My Train.3:Waiting for peripheral train_sensor to attach to a port
DEBUG:BLE Event Q.0:Bleak Raw data received: bytearray(b'\x0f\x00\x04\x01\x01%\x00\x00\x00\x00\x10\x00\x00\x00\x10')
DEBUG:BLE Event Q.0:My Train Received: Attached IO Port:1 Vision Sensor HW:0x10.0x0.0x00x0 SW:0x10.0x0.0x00x0
INFO:train_sensor.2:train_sensor.2 attached to My Train.3, port 1
DEBUG:bleak.backends.dotnet.client:Write Characteristic 00001624-1212-efde-1623-785feabcd123 : bytearray(b'\n\x00A\x01\x00\x01\x00\x00\x00\x01')
DEBUG:bleak.backends.dotnet.client:_ConnectionStatusChanged_Handler: 0
INFO:My Train.3:program_train
INFO:My Train.3:0: wait 0
INFO:My Train.3:0: wait 1
INFO:My Train.3:0: wait 2
INFO:My Train.3:0: wait 3
INFO:My Train.3:0: wait 4
INFO:My Train.3:set_speed 50
INFO:motor.1:Setting speed to 50
DEBUG:bleak.backends.dotnet.client:Disconnecting from BLE device...
INFO:My Train.3:Terminating peripheral

@Novakasa
Copy link

Novakasa commented Feb 5, 2021

Attaching a sensor works as expected with the Control+ hub, using as a basis the example from #7

@Novakasa
Copy link

Novakasa commented Feb 6, 2021

I did the test with 6ed897e (slightly modified, due to bleak API change), without the sensor it works, but with the sensor I still get:

Exception has occurred: BleakDotNetTaskError
System.ObjectDisposedException: The object has been closed. (Exception from HRESULT: 0x80000013)
  File "E:\repos\bricknil\bricknil\ble_queue.py", line 61, in send_message
    await device.write_gatt_char(char_uuid, values)
  File "E:\repos\bricknil\bricknil\hub.py", line 84, in send_message
    await self.ble_handler.send_message(self.tx, msg_bytes)
  File "E:\repos\bricknil\bricknil\sensor\peripheral.py", line 189, in send_message
    await self.message_handler(msg, msg_bytes, peripheral=self)
  File "E:\repos\bricknil\bricknil\sensor\peripheral.py", line 222, in set_output
    await self.send_message(f'set output port:{self.port} mode: {mode} = {value}', b)
  File "E:\repos\bricknil\bricknil\sensor\motor.py", line 46, in set_speed
    await self.set_output(0, self._convert_speed_to_val(speed))
  File "E:\repos\auto-rail\tests\test_github_issue_v_early.py", line 26, in run
    await train.motor.set_speed(50)
  File "E:\repos\bricknil\bricknil\bricknil.py", line 158, in main
    await task
  File "E:\repos\bricknil\bricknil\bricknil.py", line 180, in start
    loop.run_until_complete(main(user_system_setup_func))
  File "E:\repos\auto-rail\tests\test_github_issue_v_early.py", line 40, in <module>
    bricknil.start(init_train)

With dd752e4, It works without the sensor, with sensor no motor is ever started but also no exception is raised.
For the earliest 2 commits of this fork, I can't get the program to work with the train hub at all, with or without sensor.

@justxi
Copy link
Author

justxi commented Feb 6, 2021

That means that the change from curio to asyncio still works (b9e5e37)?

@Novakasa
Copy link

Novakasa commented Feb 6, 2021

No, with that commit I couldn't get it to work at all, with or without sensor. Same with the one before that, where adafruit was removed. I didn't try trouble shooting for too long though.

@justxi
Copy link
Author

justxi commented Feb 7, 2021

@janvrany
@lolligerjoj

I installed bricknil from this repository (devel branch) with commit id f433a4c using bleak-0.6.1.

Running the train_ramp.py example, I get this error:

INFO:My train.2:Running
INFO:My train.2:Increasing speed
DEBUG:motor.1:ramp_speed steps: 50.0, speed_diff: 80, speed_step: 1.6
DEBUG:motor.1:Starting ramp of speed: 0 -> 80 (5.0s)
DEBUG:motor.1:Setting next_speed: 0
INFO:motor.1:Setting speed to 0
DEBUG:bricknil.sockets:{"hub": "My train", "peripheral_type": "TrainMotor", "peripheral_name": "motor", "peripheral_port": 0, "message": "set output port:0 mode: 0 = 0"}
DEBUG:BLE Event Q.0:Got msg: set output port:0 mode: 0 = 0 = [0, 129, 0, 1, 81, 0, 0]
DEBUG:bleak.backends.bluezdbus.client:Write Characteristic 00001624-1212-efde-1623-785feabcd123 | /org/bluez/hci0/dev_90_84_2B_1B_05_E7/service000c/char000d: bytearray(b'\x08\x00\x81\x00\x01Q\x00\x00')
DEBUG:motor.1:Setting next_speed: 1
INFO:motor.1:Setting speed to 1
DEBUG:bricknil.sockets:{"hub": "My train", "peripheral_type": "TrainMotor", "peripheral_name": "motor", "peripheral_port": 0, "message": "set output port:0 mode: 0 = 1"}
DEBUG:BLE Event Q.0:Got msg: set output port:0 mode: 0 = 1 = [0, 129, 0, 1, 81, 0, 1]
Traceback (most recent call last):
  File "train_ramp.py", line 27, in <module>
    start(system)
  File "/usr/lib/python3.7/site-packages/bricknil/bricknil.py", line 207, in start
    ble.run()
  File "/usr/lib/python3.7/site-packages/bricknil/bleak_interface.py", line 52, in run
    self.loop.run_until_complete(self.asyncio_loop())
  File "/usr/lib/python3.7/asyncio/base_events.py", line 587, in run_until_complete
    return future.result()
  File "/usr/lib/python3.7/site-packages/bricknil/bleak_interface.py", line 75, in asyncio_loop
    await device.write_gatt_char(char_uuid, msg_bytes)
  File "/usr/lib/python3.7/site-packages/bleak/backends/bluezdbus/client.py", line 475, in write_gatt_char
    ).asFuture(self.loop)
txdbus.error.RemoteError: org.bluez.Error.Failed: Not connected

So the first commit after forking from virantha seems to introduce something which let the "train" hub fail.

@Novakasa
Copy link

Novakasa commented Feb 8, 2021

I have been going back to testing this:
I got f433a4c to work coming from 0.9.3 (while not updating bleak) with small modifications to the bleak API. I do not remember the full details though, I'll probably have to go back on this.

And actually I now realized that sometimes even the most recent commit works, even with the sensor, using most recent bleak. However, it is not at all consistent, sometimes I get streaks of it working 3-4 times in a row but then it stops working for another 4 times. If it works, I've tested it for >1 minute, so it seems to be stable if it works. I've tested many factors, but so far I got only circumstantial correlation with some things, nothing yet guaranteed it working. I've tested 2 hubs. At one point it seemed like new batteries made it better, and letting a previous program finish normally without forcing it to quit while still connected seemed to have increased the chances, but like I said, nothing guaranteed it working.

@justxi
Copy link
Author

justxi commented Feb 8, 2021

I have been going back to testing this:
I got f433a4c to work coming from 0.9.3 (while not updating bleak) with small modifications to the bleak API. I do not remember the full details though, I'll probably have to go back on this.

Which version of bleak are you using?

@Novakasa
Copy link

Novakasa commented Feb 8, 2021

It must've been bricknil-bleak 0.3.1, since I was approaching this from 0.9.3

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