Device remains connected if connection is successful but get_services receives TimeoutError during connect

[bdraco]

2022-08-20 11:12:01.209 DEBUG (MainThread) [yalexs_ble.lock] Front Door (M10CK0F): Disconnected from lock callback
2022-08-20 11:12:01.210 DEBUG (MainThread) [yalexs_ble.lock] Front Door (M10CK0F): Disconnected from lock callback
2022-08-20 11:12:01.211 DEBUG (MainThread) [yalexs_ble.lock] Front Door (M10CK0F): Disconnected from lock callback

I noticed I was getting the callback multiple times and tracked it down to the _remove_device_watcher not being canceled when the connection fails

bleak/bleak/backends/bluezdbus/client.py

Line 152 in 456cea8

self._remove_device_watcher = lambda: manager.remove_device_watcher(watcher)

[dlech]

I don't see how this is possible. Immediately after line 152, there is a try/except block that calls _cleanup_all on any exception. _cleanup_all calls self._remove_device_watcher().

How exactly is the connection failing?

[bdraco]

It happens after the connection timed out. I expect the its raising CanceledError but I would have expected BaseException catching would have caught that and triggered the _cleanup_all

I have not yet been able to replicate it on demand.

[bdraco]

So I think part of what's going on is (and this is a tricky race so I may still be missing something):

Disconnected Monitor is started

bleak/bleak/backends/bluezdbus/client.py

Line 202 in 8515d22

asyncio.ensure_future(self._disconnect_monitor())

await self.get_services() is called and the timeout from the code calling bleak's connect is hit, raising CanceledError

bleak/bleak/backends/bluezdbus/client.py

Line 205 in 8515d22

await self.get_services()

and then trapped by the BaseException so _cleanup_all() is called

bleak/bleak/backends/bluezdbus/client.py

Line 209 in 8515d22

self._cleanup_all()

Device completes connection in the background is is connected but we think it is not connected because the timeout was raised.

The next connection attempt things are in an indeterminate state since the device is actually connected but we don't know that.

[bdraco]

So I think the race is that the cancel happens during get_services

Then _cleanup_all runs it calls self._bus.disconnect()

bleak/bleak/backends/bluezdbus/client.py

Line 257 in 8515d22

self._bus.disconnect()

And set self._bus to None

bleak/bleak/backends/bluezdbus/client.py

Line 269 in 8515d22

self._bus = None

After that the _disconnect_monitor runs and the bus is already disconnected so it leaves the connection open

bleak/bleak/backends/bluezdbus/client.py

Line 223 in 8515d22

await self._disconnect_monitor_event.wait()

[bdraco]

And I just realized why I can't replicate it anymore.

Since I have get_services wrapped to disconnect on Exception it never happens anymore

https://github.com/Bluetooth-Devices/bleak-retry-connector/blob/acbee3824e4200f4acb43851ff90ccfd60ecb575/src/bleak_retry_connector/__init__.py#L160