Include esphome device name in BLE logs (#81284)

* Include esphome device name in BLE logs

This makes it easier to debug what is going on when there
are multiple esphome proxies

* revert unintended change

homeassistant/components/esphome/__init__.py

@@ -249,6 +249,8 @@ async def async_setup_entry(  # noqa: C901
 
     async def on_disconnect() -> None:
         """Run disconnect callbacks on API disconnect."""
+        name = entry_data.device_info.name if entry_data.device_info else host
+        _LOGGER.debug("%s: %s disconnected, running disconnected callbacks", name, host)
         for disconnect_cb in entry_data.disconnect_callbacks:
             disconnect_cb()
         entry_data.disconnect_callbacks = []

homeassistant/components/esphome/bluetooth/__init__.py

@@ -30,13 +30,15 @@ def _async_can_connect_factory(
     @hass_callback
     def _async_can_connect() -> bool:
         """Check if a given source can make another connection."""
+        can_connect = bool(entry_data.available and entry_data.ble_connections_free)
         _LOGGER.debug(
-            "Checking if %s can connect, available=%s, ble_connections_free=%s",
+            "%s: Checking can connect, available=%s, ble_connections_free=%s result=%s",
             source,
             entry_data.available,
             entry_data.ble_connections_free,
+            can_connect,
         )
-        return bool(entry_data.available and entry_data.ble_connections_free)
+        return can_connect
 
     return _async_can_connect
 
@@ -55,7 +57,7 @@ async def async_connect_scanner(
     version = entry_data.device_info.bluetooth_proxy_version
     connectable = version >= 2
     _LOGGER.debug(
-        "Connecting scanner for %s, version=%s, connectable=%s",
+        "%s: Connecting scanner version=%s, connectable=%s",
         source,
         version,
         connectable,

homeassistant/components/esphome/bluetooth/client.py

@@ -61,7 +61,7 @@ def verify_connected(func: _WrapFuncType) -> _WrapFuncType:
         if disconnected_event.is_set():
             task.cancel()
             raise BleakError(
-                f"{self._ble_device.name} ({self._ble_device.address}): "  # pylint: disable=protected-access
+                f"{self._source}: {self._ble_device.name} - {self._ble_device.address}: "  # pylint: disable=protected-access
                 "Disconnected during operation"
             )
         return next(iter(done)).result()
@@ -120,7 +120,10 @@ class ESPHomeClient(BaseBleakClient):
             self._cancel_connection_state()
         except (AssertionError, ValueError) as ex:
             _LOGGER.debug(
-                "Failed to unsubscribe from connection state (likely connection dropped): %s",
+                "%s: %s - %s: Failed to unsubscribe from connection state (likely connection dropped): %s",
+                self._source,
+                self._ble_device.name,
+                self._ble_device.address,
                 ex,
             )
         self._cancel_connection_state = None
@@ -134,13 +137,23 @@ class ESPHomeClient(BaseBleakClient):
             self._disconnected_event.set()
             self._disconnected_event = None
         if was_connected:
-            _LOGGER.debug("%s: BLE device disconnected", self._source)
+            _LOGGER.debug(
+                "%s: %s - %s: BLE device disconnected",
+                self._source,
+                self._ble_device.name,
+                self._ble_device.address,
+            )
             self._async_call_bleak_disconnected_callback()
         self._unsubscribe_connection_state()
 
     def _async_esp_disconnected(self) -> None:
         """Handle the esp32 client disconnecting from hass."""
-        _LOGGER.debug("%s: ESP device disconnected", self._source)
+        _LOGGER.debug(
+            "%s: %s - %s: ESP device disconnected",
+            self._source,
+            self._ble_device.name,
+            self._ble_device.address,
+        )
         self.entry_data.disconnect_callbacks.remove(self._async_esp_disconnected)
         self._async_ble_device_disconnected()
 
@@ -170,7 +183,10 @@ class ESPHomeClient(BaseBleakClient):
         ) -> None:
             """Handle a connect or disconnect."""
             _LOGGER.debug(
-                "Connection state changed: connected=%s mtu=%s error=%s",
+                "%s: %s - %s: Connection state changed to connected=%s mtu=%s error=%s",
+                self._source,
+                self._ble_device.name,
+                self._ble_device.address,
                 connected,
                 mtu,
                 error,
@@ -203,6 +219,12 @@ class ESPHomeClient(BaseBleakClient):
                 connected_future.set_exception(BleakError("Disconnected"))
                 return
 
+            _LOGGER.debug(
+                "%s: %s - %s: connected, registering for disconnected callbacks",
+                self._source,
+                self._ble_device.name,
+                self._ble_device.address,
+            )
             self.entry_data.disconnect_callbacks.append(self._async_esp_disconnected)
             connected_future.set_result(connected)
 
@@ -230,7 +252,10 @@ class ESPHomeClient(BaseBleakClient):
         if self.entry_data.ble_connections_free:
             return
         _LOGGER.debug(
-            "%s: Out of connection slots, waiting for a free one", self._source
+            "%s: %s - %s: Out of connection slots, waiting for a free one",
+            self._source,
+            self._ble_device.name,
+            self._ble_device.address,
         )
         async with async_timeout.timeout(timeout):
             await self.entry_data.wait_for_ble_connections_free()
@@ -272,20 +297,29 @@ class ESPHomeClient(BaseBleakClient):
             cached_services := entry_data.get_gatt_services_cache(address_as_int)
         ):
             _LOGGER.debug(
-                "Cached services hit for %s - %s",
+                "%s: %s - %s: Cached services hit",
+                self._source,
                 self._ble_device.name,
                 self._ble_device.address,
             )
             self.services = cached_services
             return self.services
         _LOGGER.debug(
-            "Cached services miss for %s - %s",
+            "%s: %s - %s: Cached services miss",
+            self._source,
             self._ble_device.name,
             self._ble_device.address,
         )
         esphome_services = await self._client.bluetooth_gatt_get_services(
             address_as_int
         )
+        _LOGGER.debug(
+            "%s: %s - %s: Got services: %s",
+            self._source,
+            self._ble_device.name,
+            self._ble_device.address,
+            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:
@@ -309,7 +343,8 @@ class ESPHomeClient(BaseBleakClient):
                     )
         self.services = services
         _LOGGER.debug(
-            "Cached services saved for %s - %s",
+            "%s: %s - %s: Cached services saved",
+            self._source,
             self._ble_device.name,
             self._ble_device.address,
         )

homeassistant/components/esphome/entry_data.py

@@ -99,6 +99,11 @@ class RuntimeEntryData:
         default_factory=lambda: LRU(MAX_CACHED_SERVICES)  # type: ignore[no-any-return]
     )
 
+    @property
+    def name(self) -> str:
+        """Return the name of the device."""
+        return self.device_info.name if self.device_info else self.entry_id
+
     def get_gatt_services_cache(
         self, address: int
     ) -> BleakGATTServiceCollection | None:
@@ -114,8 +119,13 @@ class RuntimeEntryData:
     @callback
     def async_update_ble_connection_limits(self, free: int, limit: int) -> None:
         """Update the BLE connection limits."""
-        name = self.device_info.name if self.device_info else self.entry_id
+        _LOGGER.debug(
-        _LOGGER.debug("%s: BLE connection limits: %s/%s", name, free, limit)
+            "%s: BLE connection limits: used=%s free=%s limit=%s",
+            self.name,
+            limit - free,
+            free,
+            limit,
+        )
         self.ble_connections_free = free
         self.ble_connections_limit = limit
         if free:
@@ -186,7 +196,8 @@ class RuntimeEntryData:
         subscription_key = (type(state), state.key)
         self.state[type(state)][state.key] = state
         _LOGGER.debug(
-            "Dispatching update with key %s: %s",
+            "%s: dispatching update with key %s: %s",
+            self.name,
             subscription_key,
             state,
         )