Cannot run example - Future/Bleak error - Got Future attached to a different loop about spherov2.py

[superfashi]

pretty weird, can you try using the tcp adapter and see if the same thing happens?

[LucNies]

With the tcp adapter it seems to work, but as soon it I try using the eduAPI I'm getting a timeout error in the main program and tcp server throws several errors as well. Sphero does move though surprisingly enough. Running this on ubuntu (20.04) by the way. Read in the docs of Bleak that they have a different back-end for windows and linux. Is ubuntu a supported platform?

This is the code i'm running now:

from spherov2.adapter.tcp_adapter import get_tcp_adapter
from spherov2 import scanner
from spherov2.sphero_edu import SpheroEduAPI

with scanner.find_Mini(adapter=get_tcp_adapter('localhost')) as toy:
    print(toy)

    api= SpheroEduAPI(toy)
    api.roll(heading=180, speed=150, duration=2)

Which produces this as output:

SM-3F48 (DA:88:43:AD:3F:48)
Traceback (most recent call last):
  File "/home/luc/code/sphero_test/mini_test TCP.py", line 12, in <module>
    api.roll(heading=180, speed=150, duration=2)
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/spherov2/sphero_edu.py", line 165, in roll
    self.__update_speed()
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/spherov2/sphero_edu.py", line 170, in __update_speed
    ToyUtil.roll_start(self.__toy, self.__heading, self.__speed)
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/spherov2/utils.py", line 47, in roll_start
    toy.drive_control.roll_start(heading, speed)
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/spherov2/controls/v2.py", line 195, in roll_start
    self.__toy.drive_with_heading(speed, heading, flag)
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/spherov2/commands/drive.py", line 79, in drive_with_heading
    toy._execute(Drive._encode(toy, 7, proc, [speed, *to_bytes(heading, 2), drive_flags]))
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/spherov2/toy/__init__.py", line 89, in _execute
    return self._wait_packet(packet.id)
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/spherov2/toy/__init__.py", line 94, in _wait_packet
    packet = future.result(timeout)
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/concurrent/futures/_base.py", line 446, in result
    raise TimeoutError()
concurrent.futures._base.TimeoutError

Stack from the tcp server:
Incoming connection from 127.0.0.1:59908
ERROR:root:A message handler raised an exception: 'BleakGATTCharacteristicBlueZDBus' object has no attribute 'encode'.
Traceback (most recent call last):
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/dbus_fast/message_bus.py", line 737, in _process_message
    result = handler(msg)
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/bleak/backends/bluezdbus/manager.py", line 824, in _parse_msg
    on_value_changed(message.path, self_interface["Value"])
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/bleak/backends/bluezdbus/client.py", line 152, in on_value_changed
    callback(bytearray(value))
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/spherov2/adapter/tcp_server.py", line 18, in callback
    char = char.encode('ascii')
AttributeError: 'BleakGATTCharacteristicBlueZDBus' object has no attribute 'encode'

Message is repeated 8 times.

[superfashi]

Can you install the latest commit a21fee5 and try again?

[LucNies]

Yes, that seems to fix the issues with the tcp server at least! Thanks, even though the default adapter still doesn't work, I now got something I can work with. I'm fine for now, but should this issue stay open for the original issue or would you rather close it?

[superfashi]

It seems to be an environment-specific behavior, cause I haven't seen any other reports similar to this yet. Do you think you can help with investigating further?

[LucNies]

It's definitely environment specific behavior, probably Linux/Ubuntu specific? I tried the same device, same python version, same sphero but different OS (windows) and it worked like a charm.

According to the bleak linux back-end documentation, you get this error if a single bleak object is shared between two event loops. So apparently there is a second loop somewhere.

I'm not great with async and threading and could not find where the second loop was immediately. I delved a bit deeper into it anyway. Apparently the scanner works fine. It finds the toy and creates a Toy object. But as soon as it enters the context manager and executes Toy.enter it breaks when adding adding the adapter. So I started to dissect the BleakAdapter. Simply executing this code seems to work as well:

 device = bleak.BleakClient(address, timeout=5.0)
 asyncio.run(device.connect())

So the BleakClient seems to be fine. When creating a BleakAdapter object directly (and not via Toy.enter), it just keeps running forever with no result (which makes sense? Since the self.__event_loop.run_forever()):

adapter = BleakAdapter(address=address)

I also tried creating the adapter from with in a context object to mimic how Toy creates the adapter, but again it seems to work just fine.

class Context:

    def __enter__(self):
        print("Im in context now!")
        self.adapter = BleakAdapter(address=address)
        return self

    def __exit__(self, exc_type, exc_val, exc_tb):
        self.adapter.close()
        print('Exiting context')
    
if __name__ == "__main__":
    with Context() as c:
        print(c)

So far my guess is that there is a second loop created somewhere either with the toy creation or within the scanner. I'm gonna pick this up later (probably somewhere this weekend). Any suggestions or ideas so far?

[LucNies]

Ah, it's the BleakAdapter.scan_toys.

This running this gives the same error: (same as the last code snippet, but now with toys = BleakAdapter.scan_toys() before entering the context.

class Context:

    def __enter__(self):
        print("Im in context now!")
        self.adapter = BleakAdapter(address=address)
        return self
    def __exit__(self, exc_type, exc_val, exc_tb):
        self.adapter.close()
        print('Exiting context')
    
if __name__ == "__main__":
    toys = BleakAdapter.scan_toys()
    with Context() as c:
        print(c)

Running BleakAdapter.scan_toys() twice gives the same error as well.
Apparently something from asyncio.run stays alive even when completed?

[superfashi]

Thanks for investigation. For your latest code, can you point out which line throws an exception? If possible, can you also post the entire stack trace?

[LucNies]

This is enough to reproduce the error. It breaks on the second scan_toys.

if __name__ == "__main__":
    toys = BleakAdapter.scan_toys()
    toys = BleakAdapter.scan_toys() # Here it breaks

Here is the stack trace:

Traceback (most recent call last):
  File "/home/luc/code/sphero_test/thread_tryout.py", line 41, in <module>
    toys = BleakAdapter.scan_toys()
  File "/home/luc/code/spherov2.py/spherov2/adapter/bleak_adapter.py", line 10, in scan_toys
    return asyncio.run(bleak.BleakScanner.discover(timeout))
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
    return future.result()
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/bleak/__init__.py", line 171, in discover
    async with cls(**kwargs) as scanner:
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/bleak/__init__.py", line 101, in __aenter__
    await self._backend.start()
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/bleak/backends/bluezdbus/scanner.py", line 150, in start
    self._stop = await manager.active_scan(
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/bleak/backends/bluezdbus/manager.py", line 345, in active_scan
    reply = await self._bus.call(
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/dbus_fast/aio/message_bus.py", line 358, in call
    await future
RuntimeError: Task <Task pending name='Task-3' coro=<BleakScanner.discover() running at /home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/bleak/__init__.py:171> cb=[_run_until_complete_cb() at /home/luc/anaconda3/envs/sphero/lib/python3.8/asyncio/base_events.py:184]> got Future <Future pending> attached to a different loop

[superfashi]

I see. I think asyncio.run will probably create a new loop.

Can you try

from bleak import BleakScanner
import asyncio

asyncio.run(BleakScanner.discover())
asyncio.run(BleakScanner.discover())

and see if the same error message shows up?

[LucNies]

Same behavior, it crashed on the second one asyncio.run:

Traceback (most recent call last):
  File "/home/luc/code/sphero_test/discover.py", line 5, in <module>
    asyncio.run(BleakScanner.discover())
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/asyncio/base_events.py", line 616, in run_until_complete
    return future.result()
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/bleak/__init__.py", line 171, in discover
    async with cls(**kwargs) as scanner:
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/bleak/__init__.py", line 101, in __aenter__
    await self._backend.start()
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/bleak/backends/bluezdbus/scanner.py", line 150, in start
    self._stop = await manager.active_scan(
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/bleak/backends/bluezdbus/manager.py", line 345, in active_scan
    reply = await self._bus.call(
  File "/home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/dbus_fast/aio/message_bus.py", line 358, in call
    await future
RuntimeError: Task <Task pending name='Task-3' coro=<BleakScanner.discover() running at /home/luc/anaconda3/envs/sphero/lib/python3.8/site-packages/bleak/__init__.py:171> cb=[_run_until_complete_cb() at /home/luc/anaconda3/envs/sphero/lib/python3.8/asyncio/base_events.py:184]> got Future <Future pending> attached to a different loop

[LucNies]

Apparently this was a known issue in bleak. With the emphasis on WAS. It got fixed 10 days ago with the release of 0.19.0. I've updated to this version and this solved all the issues.

Nonetheless, thanks a lot for your quick replies and thinking along with me!