fix: check more often for a device to reappear after the adapter runs…

… out of slots (#100)

src/bleak_retry_connector/__init__.py

@@ -22,6 +22,7 @@
     get_connected_devices,
     get_device,
     get_device_by_adapter,
+    wait_for_device_to_reappear,
     wait_for_disconnect,
 )
 from .const import IS_LINUX, NO_RSSI_VALUE, RSSI_SWITCH_THRESHOLD
@@ -227,7 +228,7 @@ def calculate_backoff_time(exc: Exception) -> float:
     # the adapters document how many connection slots they have so we cannot
     # know if we are out of slots or not. We can only guess based on the
     # error message and backoff.
-    if isinstance(exc, BleakDeviceNotFoundError):
+    if isinstance(exc, (BleakDeviceNotFoundError, BleakNotFoundError)):
         return BLEAK_OUT_OF_SLOTS_BACKOFF_TIME
     if isinstance(exc, BleakError):
         bleak_error = str(exc)
@@ -304,10 +305,15 @@ def _raise_if_needed(name: str, description: str, exc: Exception) -> None:
             and transient_errors < MAX_TRANSIENT_ERRORS
         ):
             return
-        msg = f"{name} - {description}: Failed to connect: {exc}"
+        msg = (
+            f"{name} - {description}: Failed to connect after "
+            f"{attempt} attempt(s): {str(exc) or type(exc).__name__}"
+        )
         # Sure would be nice if bleak gave us typed exceptions
-        if isinstance(exc, asyncio.TimeoutError) or "not found" in str(exc):
+        if isinstance(exc, asyncio.TimeoutError):
             raise BleakNotFoundError(msg) from exc
+        if isinstance(exc, BleakDeviceNotFoundError) or "not found" in str(exc):
+            raise BleakNotFoundError(f"{msg}: {DEVICE_MISSING_ADVICE}") from exc
         if isinstance(exc, BleakError):
             if any(error in str(exc) for error in OUT_OF_SLOTS_ERRORS):
                 raise BleakOutOfConnectionSlotsError(
@@ -346,6 +352,13 @@ def _raise_if_needed(name: str, description: str, exc: Exception) -> None:
                     dangerous_use_bleak_cache=use_services_cache
                     or bool(cached_services),
                 )
+                if debug_enabled:
+                    _LOGGER.debug(
+                        "%s - %s: Connected after %s attempts",
+                        name,
+                        device.address,
+                        attempt,
+                    )
         except asyncio.TimeoutError as exc:
             timeouts += 1
             if debug_enabled:
@@ -400,7 +413,10 @@ def _raise_if_needed(name: str, description: str, exc: Exception) -> None:
             bleak_error = str(exc)
             # BleakDeviceNotFoundError can mean that the adapter has run out of
             # connection slots.
-            if isinstance(exc, BleakDeviceNotFoundError) or any(
+            device_missing = isinstance(
+                exc, (BleakNotFoundError, BleakDeviceNotFoundError)
+            )
+            if device_missing or any(
                 error in bleak_error for error in TRANSIENT_ERRORS
             ):
                 transient_errors += 1
@@ -409,10 +425,11 @@ def _raise_if_needed(name: str, description: str, exc: Exception) -> None:
             backoff_time = calculate_backoff_time(exc)
             if debug_enabled:
                 _LOGGER.debug(
-                    "%s - %s: Failed to connect: %s, backing off: %s (attempt: %s, last rssi: %s)",
+                    "%s - %s: Failed to connect: %s, device_missing: %s, backing off: %s (attempt: %s, last rssi: %s)",
                     name,
                     device.address,
                     bleak_error,
+                    device_missing,
                     backoff_time,
                     attempt,
                     rssi,

src/bleak_retry_connector/bluez.py

@@ -9,17 +9,20 @@
 
 import async_timeout
 from bleak.backends.device import BLEDevice
+from bleak.exc import BleakError
 
 from .const import IS_LINUX, NO_RSSI_VALUE, RSSI_SWITCH_THRESHOLD
 
 DISCONNECT_TIMEOUT = 5
 DBUS_CONNECT_TIMEOUT = 8.5
 
-_LOGGER = logging.getLogger(__name__)
+REAPPEAR_WAIT_INTERVAL = 0.5
 
 
 DEFAULT_ATTEMPTS = 2
 
+_LOGGER = logging.getLogger(__name__)
+
 
 if IS_LINUX:
     with contextlib.suppress(ImportError):  # pragma: no cover
@@ -237,6 +240,51 @@ async def clear_cache(address: str) -> bool:
     return bool(caches_cleared)
 
 
+async def wait_for_device_to_reappear(device: BLEDevice, wait_timeout: float) -> bool:
+    """Wait for a device to reappear on the bus."""
+    await asyncio.sleep(0)
+    if (
+        not IS_LINUX
+        or not isinstance(device.details, dict)
+        or "path" not in device.details
+        or not (properties := await _get_properties())
+    ):
+        await asyncio.sleep(wait_timeout)
+        return False
+
+    debug = _LOGGER.isEnabledFor(logging.DEBUG)
+    device_path = address_to_bluez_path(device.address)
+    for i in range(int(wait_timeout / REAPPEAR_WAIT_INTERVAL)):
+        for path in _get_possible_paths(device_path):
+            if path in properties and properties[path].get(defs.DEVICE_INTERFACE):
+                if debug:
+                    _LOGGER.debug(
+                        "%s - %s: Device re-appeared on bus after %s seconds as %s",
+                        device.name,
+                        device.address,
+                        i * REAPPEAR_WAIT_INTERVAL,
+                        path,
+                    )
+                return True
+        if debug:
+            _LOGGER.debug(
+                "%s - %s: Waiting %s/%s for device to re-appear on bus",
+                device.name,
+                device.address,
+                (i + 1) * REAPPEAR_WAIT_INTERVAL,
+                wait_timeout,
+            )
+        await asyncio.sleep(REAPPEAR_WAIT_INTERVAL)
+    if debug:
+        _LOGGER.debug(
+            "%s - %s: Device did not re-appear on bus after %s seconds",
+            device.name,
+            device.address,
+            wait_timeout,
+        )
+    return False
+
+
 async def wait_for_disconnect(device: BLEDevice, min_wait_time: float) -> None:
     """Wait for the device to disconnect.
 
@@ -268,7 +316,7 @@ async def wait_for_disconnect(device: BLEDevice, min_wait_time: float) -> None:
         )
         if min_wait_time and waited < min_wait_time:
             await asyncio.sleep(min_wait_time - waited)
-    except KeyError as ex:
+    except (BleakError, KeyError) as ex:
         # Device was removed from bus
         #
         # In testing it was found that most of the CSR adapters
@@ -283,7 +331,7 @@ async def wait_for_disconnect(device: BLEDevice, min_wait_time: float) -> None:
             min_wait_time,
             ex,
         )
-        await asyncio.sleep(min_wait_time)
+        await wait_for_device_to_reappear(device, min_wait_time)
     except Exception:  # pylint: disable=broad-except
         _LOGGER.debug(
             "%s - %s: Failed waiting for disconnect",

tests/test_bluez.py

@@ -1,5 +1,5 @@
 from typing import Any
-from unittest.mock import AsyncMock
+from unittest.mock import AsyncMock, patch
 
 import pytest
 from bleak.backends.bluezdbus import defs
@@ -8,7 +8,11 @@
 
 import bleak_retry_connector
 from bleak_retry_connector import BleakSlotManager, device_source
-from bleak_retry_connector.bluez import ble_device_from_properties, path_from_ble_device
+from bleak_retry_connector.bluez import (
+    ble_device_from_properties,
+    path_from_ble_device,
+    wait_for_device_to_reappear,
+)
 
 pytestmark = pytest.mark.asyncio
 
@@ -264,3 +268,75 @@ def test_path_from_ble_device():
         path_from_ble_device(ble_device_hci0_2)
         == "/org/bluez/hci0/dev_FA_23_9D_AA_45_47"
     )
+
+
+@patch.object(bleak_retry_connector.bluez, "IS_LINUX", True)
+async def test_wait_for_device_to_reappear():
+    class FakeBluezManager:
+        def __init__(self):
+            self.watchers: set[DeviceWatcher] = set()
+            self._properties = {
+                "/org/bluez/hci0/dev_FA_23_9D_AA_45_46": {
+                    "UUID": "service",
+                    "Primary": True,
+                    "Characteristics": [],
+                    defs.DEVICE_INTERFACE: {
+                        "Address": "FA:23:9D:AA:45:46",
+                        "Alias": "FA:23:9D:AA:45:46",
+                        "RSSI": -30,
+                    },
+                    defs.GATT_SERVICE_INTERFACE: True,
+                },
+                "/org/bluez/hci1/dev_FA_23_9D_AA_45_46": {
+                    "UUID": "service",
+                    "Primary": True,
+                    "Characteristics": [],
+                    defs.DEVICE_INTERFACE: {
+                        "Connected": True,
+                        "Address": "FA:23:9D:AA:45:46",
+                        "Alias": "FA:23:9D:AA:45:46",
+                        "RSSI": -79,
+                    },
+                    defs.GATT_SERVICE_INTERFACE: True,
+                },
+            }
+
+        def add_device_watcher(self, path: str, **kwargs: Any) -> DeviceWatcher:
+            """Add a watcher for device changes."""
+            watcher = DeviceWatcher(path, **kwargs)
+            self.watchers.add(watcher)
+            return watcher
+
+        def remove_device_watcher(self, watcher: DeviceWatcher) -> None:
+            """Remove a watcher for device changes."""
+            self.watchers.remove(watcher)
+
+        def is_connected(self, path: str) -> bool:
+            """Check if device is connected."""
+            return False
+
+    bluez_manager = FakeBluezManager()
+    bleak_retry_connector.bluez.get_global_bluez_manager = AsyncMock(
+        return_value=bluez_manager
+    )
+    bleak_retry_connector.bluez.defs = defs
+
+    ble_device_hci0 = BLEDevice(
+        "FA:23:9D:AA:45:46",
+        "FA:23:9D:AA:45:46",
+        {
+            "source": "aa:bb:cc:dd:ee:ff",
+            "path": "/org/bluez/hci0/dev_FA_23_9D_AA_45_46",
+            "props": {},
+        },
+        -127,
+        uuids=[],
+        manufacturer_data={},
+    )
+
+    assert await wait_for_device_to_reappear(ble_device_hci0, 1) is True
+    del bluez_manager._properties["/org/bluez/hci0/dev_FA_23_9D_AA_45_46"]
+    assert await wait_for_device_to_reappear(ble_device_hci0, 1) is True
+    del bluez_manager._properties["/org/bluez/hci1/dev_FA_23_9D_AA_45_46"]
+    with patch.object(bleak_retry_connector.bluez, "REAPPEAR_WAIT_INTERVAL", 0.025):
+        assert await wait_for_device_to_reappear(ble_device_hci0, 0.1) is False