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.

Sign up for GitHub

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

Jump to bottom

Calling hub methods from callback functions blocks further operations #127

Open
Yakuza-UA opened this issue Dec 25, 2022 · 6 comments
Open

Calling hub methods from callback functions blocks further operations #127

Yakuza-UA opened this issue Dec 25, 2022 · 6 comments

Comments

@Yakuza-UA
Copy link

So, I tried to implement a simple demo where press of the button controls some other functions of a MoveHub, i.e. changes LED colour, or spins up a motor. The code looks like this:

from pylgbst.hub import MoveHub
from pylgbst import get_connection_bleak

conn = get_connection_bleak()
hub = MoveHub(conn)

def callback_btn(is_pressed):
    global hub
    print("Btn pressed: %s" % is_pressed)

    hub.motor_external.wait_complete()
    if is_pressed == 0:
        hub.motor_external.timed(5, 1.0, wait_complete=False)

try:
    hub.button.subscribe(callback_btn)
    time.sleep(60)
finally:
    hub.button.unsubscribe(callback_btn)
    hub.disconnect()

Once I release the button for the first time, it spins up the motor for 5 seconds exactly as I expect it to do. However, it does seem to ignore any further button presses... callback function is not called at all as I am not even getting any strings printed. Is this an expected behaviour due to threaded execution?

Is there a way to implement this?

Thanks a lot in advance.
@undera
Copy link
Owner

undera commented Dec 25, 2022

Hi
It does not sound as a normal behavior. Is there any communication with hub showing up in debug log when you press button the second time?

I would suspect the wait_complete=False somehow interferes here.

@Yakuza-UA
Copy link
Author

Yakuza-UA commented Dec 26, 2022 •
edited

Hmm, well wait_complete=False was actualy my attempt to resolve it :) I thought maybe it's something blocking it so I've slightly changed the implementation. Original code was simpler, like the following:

from pylgbst.hub import MoveHub
from pylgbst import get_connection_bleak

conn = get_connection_bleak()
hub = MoveHub(conn)

def callback_btn(is_pressed):
    global hub
    print("Btn pressed: %s" % is_pressed)

    if is_pressed == 0:
        hub.motor_external.timed(5, 1.0)

try:
    hub.button.subscribe(callback_btn)
    time.sleep(60)
finally:
    hub.button.unsubscribe(callback_btn)
    hub.disconnect()

Behavior is the same. Here's the debug output.

DEBUG:comms-bleak:Response: 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic ['0x6', '0x0', '0x1', '0x2', '0x6', '0x2']
DEBUG:hub:Notification on 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic: b'060001020600'
DEBUG:hub:Decoded message: MsgHubProperties({'payload': b'00', 'needs_reply': False, 'property': 2, 'operation': 6, 'parameters': b'00'})
DEBUG:hub:Found matching upstream msg: MsgHubProperties({'payload': b'00', 'needs_reply': False, 'property': 2, 'operation': 6, 'parameters': b'00'})
DEBUG:hub:Handling msg with <bound method Button._props_msg of Button on port 0x0>: MsgHubProperties({'payload': b'00', 'needs_reply': False, 'property': 2, 'operation': 6, 'parameters': b'00'})
DEBUG:hub:Fetched sync reply: MsgHubProperties({'payload': b'00', 'needs_reply': False, 'property': 2, 'operation': 6, 'parameters': b'00'})
DEBUG:hub:Notification on 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic: b'060001020601'
DEBUG:hub:Decoded message: MsgHubProperties({'payload': b'01', 'needs_reply': False, 'property': 2, 'operation': 6, 'parameters': b'01'})
DEBUG:hub:Handling msg with <bound method Button._props_msg of Button on port 0x0>: MsgHubProperties({'payload': b'01', 'needs_reply': False, 'property': 2, 'operation': 6, 'parameters': b'01'})
Btn pressed: 1
DEBUG:hub:Notification on 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic: b'060001020602'
DEBUG:hub:Decoded message: MsgHubProperties({'payload': b'02', 'needs_reply': False, 'property': 2, 'operation': 6, 'parameters': b'02'})
DEBUG:hub:Handling msg with <bound method Button._props_msg of Button on port 0x0>: MsgHubProperties({'payload': b'02', 'needs_reply': False, 'property': 2, 'operation': 6, 'parameters': b'02'})
Btn pressed: 2
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_00_16_53_A1_4C_92/service000c/char000d): ['org.bluez.GattCharacteristic1', {'Value': <dbus_fast.signature.Variant ('ay', bytearray(b'\x06\x00\x01\x02\x06\x00'))>}, []]
DEBUG:comms-bleak:Response: 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic ['0x6', '0x0', '0x1', '0x2', '0x6', '0x0']
DEBUG:hub:Notification on 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic: b'060001020600'
DEBUG:hub:Decoded message: MsgHubProperties({'payload': b'00', 'needs_reply': False, 'property': 2, 'operation': 6, 'parameters': b'00'})
DEBUG:hub:Handling msg with <bound method Button._props_msg of Button on port 0x0>: MsgHubProperties({'payload': b'00', 'needs_reply': False, 'property': 2, 'operation': 6, 'parameters': b'00'})
Btn pressed: 0
DEBUG:hub:Send message: MsgPortOutput({'payload': b'', 'needs_reply': False, 'port': 3, 'is_buffered': False, 'do_feedback': True, 'wait_complete': True, 'subcommand': 9, 'params': b'881364647f03'})
DEBUG:hub:Waiting for sync reply to MsgPortOutput({'payload': b'031109881364647f03', 'needs_reply': True, 'port': 3, 'is_buffered': False, 'do_feedback': True, 'wait_complete': True, 'subcommand': 9, 'params': b'881364647f03'})...
DEBUG:comms-bleak:Request: 14 ['0xc', '0x0', '0x81', '0x3', '0x11', '0x9', '0x88', '0x13', '0x64', '0x64', '0x7f', '0x3']
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_00_16_53_A1_4C_92/service000c/char000d): ['org.bluez.GattCharacteristic1', {'Value': <dbus_fast.signature.Variant ('ay', bytearray(b'\x05\x00\x82\x03\x01'))>}, []]
DEBUG:comms-bleak:Response: 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic ['0x5', '0x0', '0x82', '0x3', '0x1']
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_00_16_53_A1_4C_92/service000c/char000d): ['org.bluez.GattCharacteristic1', {'Value': <dbus_fast.signature.Variant ('ay', bytearray(b'\x05\x00\x82\x03\n'))>}, []]
DEBUG:comms-bleak:Response: 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic ['0x5', '0x0', '0x82', '0x3', '0xa']
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_00_16_53_A1_4C_92/service000c/char000d): ['org.bluez.GattCharacteristic1', {'Value': <dbus_fast.signature.Variant ('ay', bytearray(b'\x06\x00\x01\x02\x06\x01'))>}, []]
DEBUG:comms-bleak:Response: 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic ['0x6', '0x0', '0x1', '0x2', '0x6', '0x1']
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_00_16_53_A1_4C_92/service000c/char000d): ['org.bluez.GattCharacteristic1', {'Value': <dbus_fast.signature.Variant ('ay', bytearray(b'\x06\x00\x01\x02\x06\x02'))>}, []]
DEBUG:comms-bleak:Response: 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic ['0x6', '0x0', '0x1', '0x2', '0x6', '0x2']
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_00_16_53_A1_4C_92/service000c/char000d): ['org.bluez.GattCharacteristic1', {'Value': <dbus_fast.signature.Variant ('ay', bytearray(b'\x06\x00\x01\x02\x06\x00'))>}, []]
DEBUG:comms-bleak:Response: 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic ['0x6', '0x0', '0x1', '0x2', '0x6', '0x0']
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_00_16_53_A1_4C_92/service000c/char000d): ['org.bluez.GattCharacteristic1', {'Value': <dbus_fast.signature.Variant ('ay', bytearray(b'\x06\x00\x01\x02\x06\x01'))>}, []]
DEBUG:comms-bleak:Response: 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic ['0x6', '0x0', '0x1', '0x2', '0x6', '0x1']
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_00_16_53_A1_4C_92/service000c/char000d): ['org.bluez.GattCharacteristic1', {'Value': <dbus_fast.signature.Variant ('ay', bytearray(b'\x06\x00\x01\x02\x06\x02'))>}, []]
DEBUG:comms-bleak:Response: 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic ['0x6', '0x0', '0x1', '0x2', '0x6', '0x2']
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_00_16_53_A1_4C_92/service000c/char000d): ['org.bluez.GattCharacteristic1', {'Value': <dbus_fast.signature.Variant ('ay', bytearray(b'\x06\x00\x01\x02\x06\x00'))>}, []]
DEBUG:comms-bleak:Response: 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic ['0x6', '0x0', '0x1', '0x2', '0x6', '0x0']
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_6B_B3_02_CE_1F_F4', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_23_1B_00_00_14_42', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_53_B6_7E_AC_83_0A', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_58_95_D8_AF_B1_72', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_60_22_F3_87_B7_97', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_53_0C_55_7E_83_17', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.ObjectManager.InterfacesRemoved (/): ['/org/bluez/hci0/dev_44_1F_7F_26_00_58', ['org.freedesktop.DBus.Properties', 'org.freedesktop.DBus.Introspectable', 'org.bluez.Device1']]
DEBUG:hub:Send message: MsgHubProperties({'payload': b'', 'needs_reply': False, 'property': 2, 'operation': 3, 'parameters': b''})
DEBUG:hub:Send message: MsgHubAction({'payload': b'', 'needs_reply': False, 'action': 2})
Traceback (most recent call last):
  File "/home/pi/Documents/MoveHub/test.py", line 46, in <module>
    hub.disconnect()
  File "/home/pi/.local/lib/python3.9/site-packages/pylgbst/hub.py", line 206, in disconnect
    self.send(MsgHubAction(MsgHubAction.DISCONNECT))
  File "/home/pi/.local/lib/python3.9/site-packages/pylgbst/hub.py", line 93, in send
    assert not self._sync_request, "Pending request %r while trying to put %r" % (self._sync_request, msg)
AssertionError: Pending request MsgPortOutput({'payload': b'031109881364647f03', 'needs_reply': True, 'port': 3, 'is_buffered': False, 'do_feedback': True, 'wait_complete': True, 'subcommand': 9, 'params': b'881364647f03'}) while trying to put MsgHubAction({'payload': b'02', 'needs_reply': True, 'action': 2})

As you can see, right after Btn pressed: 0 is printed on the console, it waits on DEBUG:hub:Waiting for sync reply to MsgPortOutput. I've tried to press the button two or three more times, and it generated a number of debug messages, such as

DEBUG:bleak.backends.bluezdbus.manager:received D-Bus signal: org.freedesktop.DBus.Properties.PropertiesChanged (/org/bluez/hci0/dev_00_16_53_A1_4C_92/service000c/char000d): ['org.bluez.GattCharacteristic1', {'Value': <dbus_fast.signature.Variant ('ay', bytearray(b'\x05\x00\x82\x03\n'))>}, []]
DEBUG:comms-bleak:Response: 00001624-1212-efde-1623-785feabcd123 (Handle: 13): LEGO Wireless Protocol v3 Hub Characteristic ['0x5', '0x0', '0x82', '0x3', '0xa']

Then exited with exception once 60 seconds timer run out.

@undera
Copy link
Owner

undera commented Dec 27, 2022

This looks like the request for motor movement never gets the corresponding "ended" message. This might be a deadlock, when button click handler waits for command completion. It seems the motor completion message never gets through.

The usual flow of processing info from hub is "DEBUG:comms-bleak:Response" followed by "DEBUG:hub:Notification". You can see it in the beginning of the log, but after "Btn pressed: 0" there's never "Notification" recognized.

The fact that it happens is really strange and unusual. I looked over the code and not sure how can this happen. It would need some debugging to look at where each thread is, and track the problem. Unfortunately, I have no access to my MoveHub anymore, so I can't do that.

If you are python-proficient and have proper IDE, you may try it.

@HotDog702
Copy link

IMHO it is a totally bad idea to send a command in a callback function. You should raise some flag in the callback and look for it in another function with a circle.

@Yakuza-UA
Copy link
Author

IMHO it is a totally bad idea to send a command in a callback function. You should raise some flag in the callback and look for it in another function with a circle.

Hmm... great suggestion. I'll give it a try as soon as I can :) By circle you mean a loop right?

@HotDog702
Copy link

HotDog702 commented Mar 27, 2023 •
edited

By circle you mean a loop right?

Yes, a loop ))
I don't know the internals of the hub, but suspect that a callback function must be as short as possible and do NOT communicate with the hub

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@undera @Yakuza-UA @HotDog702