[Bug] [pybricksdev] connecting to hub more than once and running program produces error

[Novakasa]

Describe the bug
When trying to connect to a PybricksHub more than once (and running a program each time), I get the exception:

RuntimeError: disconnected during operation

To reproduce
PC-side:

import asyncio
from pybricksdev.ble import find_device
from pybricksdev.connections.pybricks import PybricksHub

async def main():

    dev = await find_device()
    print(dev)

    hub = PybricksHub()
    for _ in range(3):
        await hub.connect(dev)
        try:
            print("starting program...")
            await hub.run("brickrail-gui/ble-server/hub_programs/test_noop.py")
            print("program stopped!")
        finally:
            await hub.disconnect()

asyncio.run(main())

Hub program:

import usys
from pybricks.tools import wait

print(usys.version)
print("[hub] program start")
wait(30)
print("[hub] program end")

Output:

1B:BC:1B:A5:81:86: city-green
starting program...
100%|█████████████████████████████████████████████████████████████████████████████████████████████| 213/213 [00:00<00:00, 926B/s]
3.4.0; Pybricks MicroPython v3.2.3 on 2023-02-17
[hub] program start
[hub] program end
program stopped!
starting program...
100%|█████████████████████████████████████████████████████████████████████████████████████████████| 213/213 [00:00<00:00, 887B/s]
Exception has occurred: RuntimeError
disconnected during operation
  File "E:\repos\brickrail\brickrail-gui\ble-server\test_connection_pybricksdev.py", line 16, in main
    await hub.run("brickrail-gui/ble-server/hub_programs/test_noop.py")
  File "E:\repos\brickrail\brickrail-gui\ble-server\test_connection_pybricksdev.py", line 21, in <module>
    asyncio.run(main())
RuntimeError: disconnected during operation

The traceback from vscode doesn't track it to the source, here's a traceback from my project that points to the actual point of origin:

Task exception was never retrieved
future: <Task finished name='Task-49' coro=<BLEHub.run.<locals>.run_coroutine() done, defined at E:\repos\brickrail\brickrail-gui\ble-server\ble_hub.py:244> exception=RuntimeError('disconnected during operation')>
Traceback (most recent call last):
  File "E:\repos\brickrail\brickrail-gui\ble-server\ble_hub.py", line 247, in run_coroutine
    await self.hub.run(program, print_output=False, wait=True)
  File "E:\repos\brickrail\brickrail-gui\ble-server\.env\lib\site-packages\pybricksdev\connections\pybricks.py", line 374, in run
    await self._wait_for_user_program_stop()
  File "E:\repos\brickrail\brickrail-gui\ble-server\.env\lib\site-packages\pybricksdev\connections\pybricks.py", line 454, in _wait_for_user_program_stop
    await asyncio.wait_for(
  File "E:\repos\brickrail\brickrail-gui\ble-server\.env\lib\asyncio\tasks.py", line 445, in wait_for
    return fut.result()
  File "E:\repos\brickrail\brickrail-gui\ble-server\.env\lib\site-packages\pybricksdev\connections\pybricks.py", line 286, in race_disconnect
    raise RuntimeError("disconnected during operation")

I am using the most recent version of pybricksdev from pip, 1.0.0a37, and the most recent version of the firmware installed from beta pybricks code, 3.4.0; Pybricks MicroPython v3.2.3 on 2023-02-17

After the exception, the program continues running without problems, and in my project I don't handle the exception, so the hub actually never disconnects ( the light stays on constantly)

When moving the line

hub = PybricksHub()

into the loop, the problem goes away. So I'm guessing the issue must be with some bad state inside PybricksHub

Sometimes, a bit of the output of the program is actually printed the second time the program is run, but I can't reproduce that consistently.

Expected behavior
I would expect multiple connections in serial to work without any issues.

[Novakasa]

I reproduced this also with a version of the firmware very close to stable (frozen module added), and pybricksdev 1.0.0a33

[dlech]

The problem is that PybricksHub.disconnect_observable is currently implemented using an AsyncSubject which is basically a oneshot that can't be reset. So it makes PybricksHub only good for one connection. We should probably replace it with a connection_state_observable that uses a BehaviorSubject to provide the current connection state (disconnected, connecting, connected, disconnecting).

[Novakasa]

Thanks @dlech for the quick fix! Running the program twice works now, however the disconnect after that still seems to have a problem that seems quite related. Even without running a program, I am getting stuck after trying to disconnect the second time.

With the cityhub and same firmware as above:

import asyncio
from pybricksdev.ble import find_device
from pybricksdev.connections.pybricks import PybricksHub

async def main():

    dev = await find_device()
    print(dev)

    hub = PybricksHub()
    for _ in range(2):
        print("connecting...")
        await hub.connect(dev)
        print("connected!")
        await asyncio.sleep(1)
        print("disconnecting...")
        await hub.disconnect()
        print("disconnected!")

    print("OK!")

asyncio.run(main())

1B:BC:1B:A5:81:86: city-green
connecting...
connected!
disconnecting...
disconnected!
connecting...
connected!
disconnecting...
Exception ignored in: <function BleakClientWinRT.connect.<locals>.session_status_changed_event_handler at 0x0000017CF4EB08B0>
  File "E:\repos\brickrail\brickrail-gui\ble-server\.env\lib\site-packages\bleak\backends\winrt\client.py", line 330, in session_status_changed_event_handler
    loop.call_soon_threadsafe(handle_session_status_changed, args)
  File "E:\repos\brickrail\brickrail-gui\ble-server\.env\lib\asyncio\base_events.py", line 795, in call_soon_threadsafe
    self._check_closed()
  File "E:\repos\brickrail\brickrail-gui\ble-server\.env\lib\asyncio\base_events.py", line 515, in _check_closed
    raise RuntimeError('Event loop is closed')
RuntimeError: Event loop is closed

On the second loop, when disconnect() is run, the program is stuck for ~2 minutes until finally I get a TimeoutError. When I interrupt the program before the timeout it seems that the hub does disconnect quite quickly (compared to usually when my pybricksdev program crashes without disconnecting the hub), so it seems "most" of the disconnect is indeed getting "to the hub".

I have actually seen similar behavior in my project when just connecting once and never running a program, then disconnecting, but never could reproduce it just using pybricksdev, so it might just be a problem on my side.

[dlech]

Disconnecting Bluetooth devices on Windows seems problematic in general, e.g. hbldh/bleak#1223. Not sure what we can do about other than log everything and try to understand what is going on behind the scenes.

I would add a much longer delay than one second and also add another delay before reconnecting and see if it makes a difference too.

[Novakasa]

Moving dev = await find_device() into the loop doesn't help, I thought that might have been my issue.

Edit: Oh didn't see your response, I'll check if the delays help

[Novakasa]

I've tested up to a delay of 60 seconds before and after disconnecting, without any success. I also downgraded pybricksdev to 1.0.0a33 because I was surprised I didn't see this problem like this before but it still happens the same. It seems disconnecting always works the first time after I restart the python script though, so it still seems there must be some runtime state somewhere that gets bad. I'll see if I can get some logs over the weekend (will follow your guide about that in discussions).

[dlech]

Running the example from #971 (comment) on two different Windows computers here, I'm getting:

(.venv) PS C:\Users\david\work\pybricks-issue-971> python .\test.py
1E:FE:CF:EF:58:2B: prime_hub
connecting...
connected!
disconnecting...
disconnected!
connecting...
Traceback (most recent call last):
  File "C:\Users\david\work\pybricks-issue-971\test.py", line 22, in <module>
    asyncio.run(main())
  File "C:\Users\david\AppData\Local\Programs\Python\Python311\Lib\asyncio\runners.py", line 190, in run
    return runner.run(main)
           ^^^^^^^^^^^^^^^^
  File "C:\Users\david\AppData\Local\Programs\Python\Python311\Lib\asyncio\runners.py", line 118, in run
    return self._loop.run_until_complete(task)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\david\AppData\Local\Programs\Python\Python311\Lib\asyncio\base_events.py", line 650, in run_until_complete        
    return future.result()
           ^^^^^^^^^^^^^^^
  File "C:\Users\david\work\pybricks-issue-971\test.py", line 13, in main
    await hub.connect(dev)
  File "C:\Users\david\work\pybricks-issue-971\.venv\Lib\site-packages\pybricksdev\connections\pybricks.py", line 208, in connect  
    await self.client.connect()
  File "C:\Users\david\work\pybricks-issue-971\.venv\Lib\site-packages\bleak\__init__.py", line 471, in connect
    return await self._backend.connect(**kwargs)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\david\work\pybricks-issue-971\.venv\Lib\site-packages\bleak\backends\winrt\client.py", line 413, in connect       
    self.services = get_services_task.result()
                    ^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "C:\Users\david\work\pybricks-issue-971\.venv\Lib\site-packages\bleak\backends\winrt\client.py", line 643, in get_services  
    services: Sequence[GattDeviceService] = _ensure_success(
                                            ^^^^^^^^^^^^^^^^
  File "C:\Users\david\work\pybricks-issue-971\.venv\Lib\site-packages\bleak\backends\winrt\client.py", line 120, in _ensure_success
    raise BleakError(f"{fail_msg}: Unreachable")
bleak.exc.BleakError: Could not get GATT services: Unreachable

Which points to a Windows Bluetooth stack issue (the "Unreachable" error has been reported in Bleak occasionally as well).

[dlech]

bleak.exc.BleakError: Could not get GATT services: Unreachable

Moving the scan inside of the loop fixed the issue for me. I forget that the address of the hub changes after each disconnect, so doing this is essential on any OS.

[Novakasa]

I am familiar with the Unreachable Error, but for me it only shows up if I interfere with the state somehow, e.g. I start the script while the hub is still connected from a previous crashed script. Or just now I tried to start the script too early after booting the system.

Moving find_device into the loop doesn't fix it for me, so this might be something on my end.

[Novakasa]

For completeness here are the wireshark logs and full output of running this script:

import asyncio
from pybricksdev.ble import find_device
from pybricksdev.connections.pybricks import PybricksHub

async def main():

    for _ in range(2):
        dev = await find_device()
        print(dev)
        print("connecting...")
        hub = PybricksHub()
        await hub.connect(dev)
        print("connected!")
        await asyncio.sleep(5)
        print("disconnecting...")
        await hub.disconnect()
        print("disconnected!")
        await asyncio.sleep(5)

    print("OK!")

asyncio.run(main())

pybricks_disconnect_ble_log.pcapng.gz
pybricks_disconnect_output.txt

For me (complete noob about ble details) it seems interesting (naively) that after the timeout in the end there are some "Disconnect complete" events, so for some reason the disconnect seems to work in the "cleanup" phase?