fix: Add device logger

allenporter · allenporter · commit 11816e4a4247 · 2025-12-13T15:31:10.000-08:00
This prefixes all log lines for the device with a standard log prefix.

Example:
```
DEBUG:roborock.devices.v1_channel:abcdefghblachfdfs Background reconnect task cancelled
DEBUG:roborock.devices.v1_channel:zzyyaaqwwerrefdsa Background reconnect task cancelled
DEBUG:roborock.devices.local_channel:abcdefghblachfdfs Connection lost to 192.168.1.11
DEBUG:roborock.devices.local_channel:zzyyaaqwwerrefdsa Connection lost to 192.168.1.10
```
diff --git a/roborock/callbacks.py b/roborock/callbacks.py
@@ -10,7 +10,9 @@
 V = TypeVar("V")
 
 
-def safe_callback(callback: Callable[[V], None], logger: logging.Logger | None = None) -> Callable[[V], None]:
+def safe_callback(
+    callback: Callable[[V], None], logger: logging.Logger | logging.LoggerAdapter | None = None
+) -> Callable[[V], None]:
     """Wrap a callback to catch and log exceptions.
 
     This is useful for ensuring that errors in callbacks do not propagate
@@ -36,7 +38,7 @@ class CallbackMap(Generic[K, V]):
     when a value is received for a specific key.
     """
 
-    def __init__(self, logger: logging.Logger | None = None) -> None:
+    def __init__(self, logger: logging.Logger | logging.LoggerAdapter | None = None) -> None:
         self._callbacks: dict[K, list[Callable[[V], None]]] = {}
         self._logger = logger or _LOGGER
 
@@ -79,7 +81,7 @@ class CallbackList(Generic[V]):
     additional callbacks to the list at any time.
     """
 
-    def __init__(self, logger: logging.Logger | None = None) -> None:
+    def __init__(self, logger: logging.Logger | logging.LoggerAdapter | None = None) -> None:
         self._callbacks: list[Callable[[V], None]] = []
         self._logger = logger or _LOGGER
 
@@ -101,7 +103,9 @@ def __call__(self, value: V) -> None:
 
 
 def decoder_callback(
-    decoder: Callable[[K], list[V]], callback: Callable[[V], None], logger: logging.Logger | None = None
+    decoder: Callable[[K], list[V]],
+    callback: Callable[[V], None],
+    logger: logging.Logger | logging.LoggerAdapter | None = None,
 ) -> Callable[[K], None]:
     """Create a callback that decodes messages using a decoder and invokes a callback.
 
@@ -120,7 +124,7 @@ def wrapper(data: K) -> None:
             logger.warning("Failed to decode message: %s", data)
             return
         for message in messages:
-            _LOGGER.debug("Decoded message: %s", message)
+            logger.debug("Decoded message: %s", message)
             safe_cb(message)
 
     return wrapper
diff --git a/roborock/devices/device.py b/roborock/devices/device.py
@@ -12,6 +12,7 @@
 from typing import Any, TypeVar, cast
 
 from roborock.data import HomeDataDevice, HomeDataProduct
+from roborock.devices.logger import DeviceLoggerAdapter
 from roborock.exceptions import RoborockException
 from roborock.roborock_message import RoborockMessage
 
@@ -59,6 +60,7 @@ def __init__(
         """
         TraitsMixin.__init__(self, trait)
         self._duid = device_info.duid
+        self._logger = DeviceLoggerAdapter(_LOGGER, self._duid)
         self._name = device_info.name
         self._device_info = device_info
         self._product = product
@@ -134,14 +136,11 @@ async def connect_loop() -> None:
                         return
                     except RoborockException as e:
                         start_attempt.set()
-                        _LOGGER.info("Failed to connect to device %s: %s", self.name, e)
-                        _LOGGER.info(
-                            "Retrying connection to device %s in %s seconds", self.name, backoff.total_seconds()
-                        )
+                        self._logger.info("Failed to connect (retry %s): %s", backoff.total_seconds(), e)
                         await asyncio.sleep(backoff.total_seconds())
                         backoff = min(backoff * BACKOFF_MULTIPLIER, MAX_BACKOFF_INTERVAL)
             except asyncio.CancelledError:
-                _LOGGER.info("connect_loop for device %s was cancelled", self.name)
+                self._logger.debug("connect_loop was cancelled", self.duid)
                 # Clean exit on cancellation
                 return
             finally:
@@ -152,14 +151,14 @@ async def connect_loop() -> None:
         try:
             await asyncio.wait_for(start_attempt.wait(), timeout=START_ATTEMPT_TIMEOUT.total_seconds())
         except TimeoutError:
-            _LOGGER.debug("Initial connection attempt to device %s is taking longer than expected", self.name)
+            self._logger.debug("Initial connection attempt took longer than expected, will keep trying in background")
 
     async def connect(self) -> None:
         """Connect to the device using the appropriate protocol channel."""
         if self._unsub:
             raise ValueError("Already connected to the device")
         unsub = await self._channel.subscribe(self._on_message)
-        _LOGGER.info("Connected to V1 device %s", self.name)
+        self._logger.info("Connecting to device")
         if self.v1_properties is not None:
             try:
                 await self.v1_properties.discover_features()
@@ -182,7 +181,7 @@ async def close(self) -> None:
 
     def _on_message(self, message: RoborockMessage) -> None:
         """Handle incoming messages from the device."""
-        _LOGGER.debug("Received message from device: %s", message)
+        self._logger.debug("Received message from device: %s", message)
 
     def diagnostic_data(self) -> dict[str, Any]:
         """Return diagnostics information about the device."""
diff --git a/roborock/devices/local_channel.py b/roborock/devices/local_channel.py
@@ -13,6 +13,7 @@
 from ..protocols.v1_protocol import LocalProtocolVersion
 from ..util import get_next_int
 from .channel import Channel
+from .logger import DeviceLoggerAdapter
 
 _LOGGER = logging.getLogger(__name__)
 _PORT = 58867
@@ -52,11 +53,12 @@ class LocalChannel(Channel):
     format most parsing to higher-level components.
     """
 
-    def __init__(self, host: str, local_key: str):
+    def __init__(self, host: str, local_key: str, device_uid: str) -> None:
         self._host = host
+        self._logger = DeviceLoggerAdapter(_LOGGER, device_uid)
         self._transport: asyncio.Transport | None = None
         self._protocol: _LocalProtocol | None = None
-        self._subscribers: CallbackList[RoborockMessage] = CallbackList(_LOGGER)
+        self._subscribers: CallbackList[RoborockMessage] = CallbackList(self._logger)
         self._is_connected = False
         self._local_protocol_version: LocalProtocolVersion | None = None
         self._keep_alive_task: asyncio.Task[None] | None = None
@@ -80,11 +82,11 @@ def _update_encoder_decoder(self, params: LocalChannelParams) -> None:
             local_key=params.local_key, connect_nonce=params.connect_nonce, ack_nonce=params.ack_nonce
         )
         # Callback to decode messages and dispatch to subscribers
-        self._dispatch = decoder_callback(self._decoder, self._subscribers, _LOGGER)
+        self._dispatch = decoder_callback(self._decoder, self._subscribers, self._logger)
 
     async def _do_hello(self, local_protocol_version: LocalProtocolVersion) -> LocalChannelParams | None:
         """Perform the initial handshaking and return encoder params if successful."""
-        _LOGGER.debug(
+        self._logger.debug(
             "Attempting to use the %s protocol for client %s...",
             local_protocol_version,
             self._host,
@@ -101,7 +103,7 @@ async def _do_hello(self, local_protocol_version: LocalProtocolVersion) -> Local
                 request_id=request.seq,
                 response_protocol=RoborockMessageProtocol.HELLO_RESPONSE,
             )
-            _LOGGER.debug(
+            self._logger.debug(
                 "Client %s speaks the %s protocol.",
                 self._host,
                 local_protocol_version,
@@ -110,7 +112,7 @@ async def _do_hello(self, local_protocol_version: LocalProtocolVersion) -> Local
                 local_key=self._params.local_key, connect_nonce=self._params.connect_nonce, ack_nonce=response.random
             )
         except RoborockException as e:
-            _LOGGER.debug(
+            self._logger.debug(
                 "Client %s did not respond or does not speak the %s protocol. %s",
                 self._host,
                 local_protocol_version,
@@ -153,7 +155,7 @@ async def _keep_alive_loop(self) -> None:
             except asyncio.CancelledError:
                 break
             except Exception:
-                _LOGGER.debug("Keep-alive ping failed", exc_info=True)
+                self._logger.debug("Keep-alive ping failed", exc_info=True)
                 # Retry next interval
 
     @property
@@ -176,9 +178,9 @@ def is_local_connected(self) -> bool:
     async def connect(self) -> None:
         """Connect to the device and negotiate protocol."""
         if self._is_connected:
-            _LOGGER.debug("Unexpected call to connect when already connected")
+            self._logger.debug("Unexpected call to connect when already connected")
             return
-        _LOGGER.debug("Connecting to %s:%s", self._host, _PORT)
+        self._logger.debug("Connecting to %s:%s", self._host, _PORT)
         loop = asyncio.get_running_loop()
         protocol = _LocalProtocol(self._data_received, self._connection_lost)
         try:
@@ -208,13 +210,13 @@ def close(self) -> None:
         if self._transport:
             self._transport.close()
         else:
-            _LOGGER.warning("Close called but transport is already None")
+            self._logger.warning("Close called but transport is already None")
         self._transport = None
         self._is_connected = False
 
     def _connection_lost(self, exc: Exception | None) -> None:
         """Handle connection loss."""
-        _LOGGER.debug("Connection lost to %s", self._host, exc_info=exc)
+        self._logger.debug("Connection lost to %s", self._host, exc_info=exc)
         if self._keep_alive_task:
             self._keep_alive_task.cancel()
             self._keep_alive_task = None
@@ -236,12 +238,12 @@ async def publish(self, message: RoborockMessage) -> None:
         try:
             encoded_msg = self._encoder(message)
         except Exception as err:
-            _LOGGER.exception("Error encoding MQTT message: %s", err)
+            self._logger.exception("Error encoding MQTT message: %s", err)
             raise RoborockException(f"Failed to encode MQTT message: {err}") from err
         try:
             self._transport.write(encoded_msg)
         except Exception as err:
-            logging.exception("Uncaught error sending command")
+            self._logger.exception("Uncaught error sending command")
             raise RoborockException(f"Failed to send message: {message}") from err
 
     async def _send_message(
@@ -276,7 +278,7 @@ def find_response(response_message: RoborockMessage) -> None:
 LocalSession = Callable[[str], LocalChannel]
 
 
-def create_local_session(local_key: str) -> LocalSession:
+def create_local_session(local_key: str, device_uid: str) -> LocalSession:
     """Creates a local session which can create local channels.
 
     This plays a role similar to the MqttSession but is really just a factory
@@ -285,6 +287,6 @@ def create_local_session(local_key: str) -> LocalSession:
 
     def create_local_channel(host: str) -> LocalChannel:
         """Create a LocalChannel instance for the given host."""
-        return LocalChannel(host, local_key)
+        return LocalChannel(host, local_key, device_uid)
 
     return create_local_channel
diff --git a/roborock/devices/logger.py b/roborock/devices/logger.py
@@ -0,0 +1,18 @@
+"""Logger adapter for device-specific logging."""
+
+import logging
+from collections.abc import MutableMapping
+from typing import Any
+
+
+class DeviceLoggerAdapter(logging.LoggerAdapter):
+    """A LoggerAdapter that prepends a [DUID] prefix to all messages."""
+
+    def __init__(self, logger: logging.Logger, duid: str):
+        # The 'extra' dictionary can hold any custom context you need.
+        # We define a custom 'prefix' key here.
+        super().__init__(logger, {"prefix": duid})
+
+    def process(self, msg: str, kwargs: MutableMapping[str, Any]) -> tuple[str, MutableMapping[str, Any]]:
+        """Format the message by adding the device prefix."""
+        return f"{self.extra['prefix']} {msg}", kwargs  # type: ignore[index]
diff --git a/roborock/devices/mqtt_channel.py b/roborock/devices/mqtt_channel.py
@@ -11,6 +11,7 @@
 from roborock.roborock_message import RoborockMessage
 
 from .channel import Channel
+from .logger import DeviceLoggerAdapter
 
 _LOGGER = logging.getLogger(__name__)
 
@@ -25,6 +26,7 @@ class MqttChannel(Channel):
     def __init__(self, mqtt_session: MqttSession, duid: str, local_key: str, rriot: RRiot, mqtt_params: MqttParams):
         self._mqtt_session = mqtt_session
         self._duid = duid
+        self._logger = DeviceLoggerAdapter(_LOGGER, duid)
         self._local_key = local_key
         self._rriot = rriot
         self._mqtt_params = mqtt_params
@@ -74,12 +76,12 @@ async def publish(self, message: RoborockMessage) -> None:
         try:
             encoded_msg = self._encoder(message)
         except Exception as e:
-            _LOGGER.exception("Error encoding MQTT message: %s", e)
+            self._logger.exception("Error encoding MQTT message: %s", e)
             raise RoborockException(f"Failed to encode MQTT message: {e}") from e
         try:
             return await self._mqtt_session.publish(self._publish_topic, encoded_msg)
         except MqttSessionException as e:
-            _LOGGER.exception("Error publishing MQTT message: %s", e)
+            self._logger.exception("Error publishing MQTT message: %s", e)
             raise RoborockException(f"Failed to publish MQTT message: {e}") from e
 
     async def restart(self) -> None:
diff --git a/roborock/devices/v1_channel.py b/roborock/devices/v1_channel.py
diff --git a/tests/devices/test_local_channel.py b/tests/devices/test_local_channel.py
