Fix ESPHome BLE client raising confusing error when not connected

homeassistant/components/esphome/bluetooth/client.py

@@ -75,15 +75,13 @@ async def _async_wrap_bluetooth_connected_operation(
         self: ESPHomeClient, *args: Any, **kwargs: Any
     ) -> Any:
         # pylint: disable=protected-access
+        if not self._is_connected:
+            raise BleakError(f"{self._description} is not connected")
         loop = self._loop
         disconnected_futures = self._disconnected_futures
         disconnected_future = loop.create_future()
         disconnected_futures.add(disconnected_future)
-        ble_device = self._ble_device
-        disconnect_message = (
-            f"{self._source_name }: {ble_device.name} - {ble_device.address}: "
-            "Disconnected during operation"
-        )
+        disconnect_message = f"{self._description}: Disconnected during operation"
         try:
             async with interrupt(disconnected_future, BleakError, disconnect_message):
                 return await func(self, *args, **kwargs)
@@ -115,10 +113,8 @@ async def _async_wrap_bluetooth_operation(
             if ex.error.error == -1:
                 # pylint: disable=protected-access
                 _LOGGER.debug(
-                    "%s: %s - %s: BLE device disconnected during %s operation",
-                    self._source_name,
-                    self._ble_device.name,
-                    self._ble_device.address,
+                    "%s: BLE device disconnected during %s operation",
+                    self._description,
                     func.__name__,
                 )
                 self._async_ble_device_disconnected()
@@ -159,10 +155,11 @@ def __init__(
         assert isinstance(address_or_ble_device, BLEDevice)
         super().__init__(address_or_ble_device, *args, **kwargs)
         self._loop = asyncio.get_running_loop()
-        self._ble_device = address_or_ble_device
-        self._address_as_int = mac_to_int(self._ble_device.address)
-        assert self._ble_device.details is not None
-        self._source = self._ble_device.details["source"]
+        ble_device = address_or_ble_device
+        self._ble_device = ble_device
+        self._address_as_int = mac_to_int(ble_device.address)
+        assert ble_device.details is not None
+        self._source = ble_device.details["source"]
         self._cache = client_data.cache
         self._bluetooth_device = client_data.bluetooth_device
         self._client = client_data.client
@@ -177,8 +174,11 @@ def __init__(
         self._feature_flags = device_info.bluetooth_proxy_feature_flags_compat(
             client_data.api_version
         )
-        self._address_type = address_or_ble_device.details["address_type"]
+        self._address_type = ble_device.details["address_type"]
         self._source_name = f"{client_data.title} [{self._source}]"
+        self._description = (
+            f"{self._source_name}: {ble_device.name} - {ble_device.address}"
+        )
         scanner = client_data.scanner
         assert scanner is not None
         self._scanner = scanner
@@ -196,12 +196,10 @@ def _unsubscribe_connection_state(self) -> None:
         except (AssertionError, ValueError) as ex:
             _LOGGER.debug(
                 (
-                    "%s: %s - %s: Failed to unsubscribe from connection state (likely"
+                    "%s: Failed to unsubscribe from connection state (likely"
                     " connection dropped): %s"
                 ),
-                self._source_name,
-                self._ble_device.name,
-                self._ble_device.address,
+                self._description,
                 ex,
             )
         self._cancel_connection_state = None
@@ -224,22 +222,12 @@ def _async_ble_device_disconnected(self) -> None:
         was_connected = self._is_connected
         self._async_disconnected_cleanup()
         if was_connected:
-            _LOGGER.debug(
-                "%s: %s - %s: BLE device disconnected",
-                self._source_name,
-                self._ble_device.name,
-                self._ble_device.address,
-            )
+            _LOGGER.debug("%s: BLE device disconnected", self._description)
             self._async_call_bleak_disconnected_callback()
 
     def _async_esp_disconnected(self) -> None:
         """Handle the esp32 client disconnecting from us."""
-        _LOGGER.debug(
-            "%s: %s - %s: ESP device disconnected",
-            self._source_name,
-            self._ble_device.name,
-            self._ble_device.address,
-        )
+        _LOGGER.debug("%s: ESP device disconnected", self._description)
         self._disconnect_callbacks.remove(self._async_esp_disconnected)
         self._async_ble_device_disconnected()
 
@@ -258,10 +246,8 @@ def _on_bluetooth_connection_state(
     ) -> None:
         """Handle a connect or disconnect."""
         _LOGGER.debug(
-            "%s: %s - %s: Connection state changed to connected=%s mtu=%s error=%s",
-            self._source_name,
-            self._ble_device.name,
-            self._ble_device.address,
+            "%s: Connection state changed to connected=%s mtu=%s error=%s",
+            self._description,
             connected,
             mtu,
             error,
@@ -300,10 +286,8 @@ def _on_bluetooth_connection_state(
             return
 
         _LOGGER.debug(
-            "%s: %s - %s: connected, registering for disconnected callbacks",
-            self._source_name,
-            self._ble_device.name,
-            self._ble_device.address,
+            "%s: connected, registering for disconnected callbacks",
+            self._description,
         )
         self._disconnect_callbacks.append(self._async_esp_disconnected)
         connected_future.set_result(connected)
@@ -403,10 +387,8 @@ async def _wait_for_free_connection_slot(self, timeout: float) -> None:
         if bluetooth_device.ble_connections_free:
             return
         _LOGGER.debug(
-            "%s: %s - %s: Out of connection slots, waiting for a free one",
-            self._source_name,
-            self._ble_device.name,
-            self._ble_device.address,
+            "%s: Out of connection slots, waiting for a free one",
+            self._description,
         )
         async with asyncio.timeout(timeout):
             await bluetooth_device.wait_for_ble_connections_free()
@@ -434,7 +416,7 @@ async def pair(self, *args: Any, **kwargs: Any) -> bool:
         if response.paired:
             return True
         _LOGGER.error(
-            "Pairing with %s failed due to error: %s", self.address, response.error
+            "%s: Pairing failed due to error: %s", self._description, response.error
         )
         return False
 
@@ -451,7 +433,7 @@ async def unpair(self) -> bool:
         if response.success:
             return True
         _LOGGER.error(
-            "Unpairing with %s failed due to error: %s", self.address, response.error
+            "%s: Unpairing failed due to error: %s", self._description, response.error
         )
         return False
 
@@ -486,30 +468,14 @@ async def _get_services(
             self._feature_flags & BluetoothProxyFeature.REMOTE_CACHING
             or dangerous_use_bleak_cache
         ) and (cached_services := cache.get_gatt_services_cache(address_as_int)):
-            _LOGGER.debug(
-                "%s: %s - %s: Cached services hit",
-                self._source_name,
-                self._ble_device.name,
-                self._ble_device.address,
-            )
+            _LOGGER.debug("%s: Cached services hit", self._description)
             self.services = cached_services
             return self.services
-        _LOGGER.debug(
-            "%s: %s - %s: Cached services miss",
-            self._source_name,
-            self._ble_device.name,
-            self._ble_device.address,
-        )
+        _LOGGER.debug("%s: Cached services miss", self._description)
         esphome_services = await self._client.bluetooth_gatt_get_services(
             address_as_int
         )
-        _LOGGER.debug(
-            "%s: %s - %s: Got services: %s",
-            self._source_name,
-            self._ble_device.name,
-            self._ble_device.address,
-            esphome_services,
-        )
+        _LOGGER.debug("%s: Got services: %s", self._description, esphome_services)
         max_write_without_response = self.mtu_size - GATT_HEADER_SIZE
         services = BleakGATTServiceCollection()  # type: ignore[no-untyped-call]
         for service in esphome_services.services:
@@ -538,12 +504,7 @@ async def _get_services(
             raise BleakError("Failed to get services from remote esp")
 
         self.services = services
-        _LOGGER.debug(
-            "%s: %s - %s: Cached services saved",
-            self._source_name,
-            self._ble_device.name,
-            self._ble_device.address,
-        )
+        _LOGGER.debug("%s: Cached services saved", self._description)
         cache.set_gatt_services_cache(address_as_int, services)
         return services
 
@@ -552,13 +513,15 @@ def _resolve_characteristic(
     ) -> BleakGATTCharacteristic:
         """Resolve a characteristic specifier to a BleakGATTCharacteristic object."""
         if (services := self.services) is None:
-            raise BleakError("Services have not been resolved")
+            raise BleakError(f"{self._description}: Services have not been resolved")
         if not isinstance(char_specifier, BleakGATTCharacteristic):
             characteristic = services.get_characteristic(char_specifier)
         else:
             characteristic = char_specifier
         if not characteristic:
-            raise BleakError(f"Characteristic {char_specifier} was not found!")
+            raise BleakError(
+                f"{self._description}: Characteristic {char_specifier} was not found!"
+            )
         return characteristic
 
     @verify_connected
@@ -579,8 +542,8 @@ async def clear_cache(self) -> bool:
         if response.success:
             return True
         _LOGGER.error(
-            "Clear cache failed with %s failed due to error: %s",
-            self.address,
+            "%s: Clear cache failed due to error: %s",
+            self._description,
             response.error,
         )
         return False
@@ -692,7 +655,7 @@ def callback(sender: int, data: bytearray):
         ble_handle = characteristic.handle
         if ble_handle in self._notify_cancels:
             raise BleakError(
-                "Notifications are already enabled on "
+                f"{self._description}: Notifications are already enabled on "
                 f"service:{characteristic.service_uuid} "
                 f"characteristic:{characteristic.uuid} "
                 f"handle:{ble_handle}"
@@ -702,8 +665,8 @@ def callback(sender: int, data: bytearray):
             and "indicate" not in characteristic.properties
         ):
             raise BleakError(
-                f"Characteristic {characteristic.uuid} does not have notify or indicate"
-                " property set."
+                f"{self._description}: Characteristic {characteristic.uuid} "
+                "does not have notify or indicate property set."
             )
 
         self._notify_cancels[
@@ -725,18 +688,13 @@ def callback(sender: int, data: bytearray):
         cccd_descriptor = characteristic.get_descriptor(CCCD_UUID)
         if not cccd_descriptor:
             raise BleakError(
-                f"Characteristic {characteristic.uuid} does not have a "
-                "characteristic client config descriptor."
+                f"{self._description}: Characteristic {characteristic.uuid} "
+                "does not have a characteristic client config descriptor."
             )
 
         _LOGGER.debug(
-            (
-                "%s: %s - %s: Writing to CCD descriptor %s for notifications with"
-                " properties=%s"
-            ),
-            self._source_name,
-            self._ble_device.name,
-            self._ble_device.address,
+            "%s: Writing to CCD descriptor %s for notifications with properties=%s",
+            self._description,
             cccd_descriptor.handle,
             characteristic.properties,
         )
@@ -774,12 +732,10 @@ def __del__(self) -> None:
         if self._cancel_connection_state:
             _LOGGER.warning(
                 (
-                    "%s: %s - %s: ESPHomeClient bleak client was not properly"
+                    "%s: ESPHomeClient bleak client was not properly"
                     " disconnected before destruction"
                 ),
-                self._source_name,
-                self._ble_device.name,
-                self._ble_device.address,
+                self._description,
             )
         if not self._loop.is_closed():
             self._loop.call_soon_threadsafe(self._async_disconnected_cleanup)

tests/components/esphome/bluetooth/test_client.py

@@ -0,0 +1,62 @@
+"""Tests for ESPHomeClient."""
+from __future__ import annotations
+
+from aioesphomeapi import APIClient, APIVersion, BluetoothProxyFeature, DeviceInfo
+from bleak.exc import BleakError
+import pytest
+
+from homeassistant.components.bluetooth import HaBluetoothConnector
+from homeassistant.components.esphome.bluetooth.cache import ESPHomeBluetoothCache
+from homeassistant.components.esphome.bluetooth.client import (
+    ESPHomeClient,
+    ESPHomeClientData,
+)
+from homeassistant.components.esphome.bluetooth.device import ESPHomeBluetoothDevice
+from homeassistant.components.esphome.bluetooth.scanner import ESPHomeScanner
+from homeassistant.core import HomeAssistant
+
+from tests.components.bluetooth import generate_ble_device
+
+ESP_MAC_ADDRESS = "AA:BB:CC:DD:EE:FF"
+ESP_NAME = "proxy"
+
+
+@pytest.fixture(name="client_data")
+async def client_data_fixture(
+    hass: HomeAssistant, mock_client: APIClient
+) -> ESPHomeClientData:
+    """Return a client data fixture."""
+    connector = HaBluetoothConnector(ESPHomeClientData, ESP_MAC_ADDRESS, lambda: True)
+    return ESPHomeClientData(
+        bluetooth_device=ESPHomeBluetoothDevice(ESP_NAME, ESP_MAC_ADDRESS),
+        cache=ESPHomeBluetoothCache(),
+        client=mock_client,
+        device_info=DeviceInfo(
+            mac_address=ESP_MAC_ADDRESS,
+            name=ESP_NAME,
+            bluetooth_proxy_feature_flags=BluetoothProxyFeature.PASSIVE_SCAN
+            & BluetoothProxyFeature.ACTIVE_CONNECTIONS
+            & BluetoothProxyFeature.REMOTE_CACHING
+            & BluetoothProxyFeature.PAIRING
+            & BluetoothProxyFeature.CACHE_CLEARING
+            & BluetoothProxyFeature.RAW_ADVERTISEMENTS,
+        ),
+        api_version=APIVersion(1, 9),
+        title=ESP_NAME,
+        scanner=ESPHomeScanner(
+            hass, ESP_MAC_ADDRESS, ESP_NAME, lambda info: None, connector, True
+        ),
+    )
+
+
+async def test_client_usage_while_not_connected(client_data: ESPHomeClientData) -> None:
+    """Test client usage while not connected."""
+    ble_device = generate_ble_device(
+        "CC:BB:AA:DD:EE:FF", details={"source": ESP_MAC_ADDRESS, "address_type": 1}
+    )
+
+    client = ESPHomeClient(ble_device, client_data=client_data)
+    with pytest.raises(
+        BleakError, match=f"{ESP_NAME}.*{ESP_MAC_ADDRESS}.*not connected"
+    ):
+        await client.write_gatt_char("test", b"test") is False