refactor: device instance log identifier

Improve log messages with friendly device name to easily associate log
messages with multiple device instances.

Author: zehnm

intg-androidtv/driver.py

@@ -122,17 +122,22 @@ async def media_player_cmd_handler(
     :param params: optional command parameters
     :return:
     """
-    _LOG.info("Got %s command request: %s %s", entity.id, cmd_id, params)
-
     # Simple mapping at the moment: one entity per device (with the same id)
     atv_id = entity.id
 
     if atv_id not in _configured_android_tvs:
-        _LOG.warning("No Android TV device found for entity: %s", entity.id)
+        _LOG.warning(
+            "Cannot execute command %s %s: no Android TV device found for entity %s",
+            cmd_id,
+            params if params else "",
+            entity.id,
+        )
         return ucapi.StatusCodes.SERVICE_UNAVAILABLE
 
     android_tv = _configured_android_tvs[atv_id]
 
+    _LOG.info("[%s] command: %s %s", android_tv.log_id, cmd_id, params if params else "")
+
     if cmd_id == media_player.Commands.ON:
         return await android_tv.turn_on()
     if cmd_id == media_player.Commands.OFF:
@@ -174,7 +179,7 @@ async def handle_android_tv_address_change(atv_id: str, address: str) -> None:
     """Update device configuration with changed IP address."""
     device = config.devices.get(atv_id)
     if device and device.address != address:
-        _LOG.info("Updating IP address %s of configured ATV %s", address, atv_id)
+        _LOG.info("Updating IP address %s of configured device %s", address, atv_id)
         device.address = address
         config.devices.update(device)
 
@@ -186,7 +191,7 @@ async def handle_android_tv_update(atv_id: str, update: dict[str, Any]) -> None:
     :param atv_id: AndroidTV identifier
     :param update: dictionary containing the updated properties
     """
-    _LOG.debug("[%s] ATV update: %s", atv_id, update)
+    _LOG.debug("[%s] device update: %s", atv_id, update)
 
     attributes = {}
     # Simple mapping at the moment: one entity per device (with the same id)
@@ -251,7 +256,7 @@ def _add_configured_android_tv(device: config.AtvDevice, connect: bool = True) -
 
         _configured_android_tvs[device.id] = android_tv
         _LOG.info(
-            "Configured Android TV device '%s' (%s) with profile: %s %s",
+            "[%s] Configured Android TV device %s with profile: %s %s",
             device.name,
             device.id,
             profile.manufacturer,

intg-androidtv/tv.py

@@ -26,7 +26,7 @@
 from pyee import AsyncIOEventEmitter
 from ucapi import media_player
 
-LOG = logging.getLogger(__name__)
+_LOG = logging.getLogger(__name__)
 
 BACKOFF_MAX = 30
 MIN_RECONNECT_DELAY: float = 0.5
@@ -111,19 +111,19 @@ async def init(self, max_timeout: int | None = None) -> bool:
         :return: True if connected or connecting, False if timeout occurred.
         """
         if self._connecting:
-            LOG.debug("Skipping init task: connection already running for %s", self._identifier)
+            _LOG.debug("[%s] Skipping init task: connection already running", self.log_id)
             return True
 
         if await self._atv.async_generate_cert_if_missing():
-            LOG.debug("Generated new certificate")
+            _LOG.debug("[%s] Generated new certificate", self.log_id)
 
         request_start = None
         success = False
         start = time.time()
 
         while not success:
             try:
-                LOG.debug("Retrieving device information from '%s' on %s", self._name, self._atv.host)
+                _LOG.debug("[%s] Retrieving device information from %s", self.log_id, self._atv.host)
                 # Limit connection time for async_get_name_and_mac: if a previous pairing screen is still shown,
                 # this would hang for a long time (often minutes)!
                 request_start = time.time()
@@ -134,10 +134,11 @@ async def init(self, max_timeout: int | None = None) -> bool:
                 self._reconnect_delay = MIN_RECONNECT_DELAY
             except (CannotConnect, ConnectionClosed, asyncio.TimeoutError) as ex:
                 if max_timeout and time.time() - start > max_timeout:
-                    LOG.error(
-                        "Abort connecting after %ss: device '%s' not reachable on %s. %s",
+                    _LOG.error(
+                        "[%s] Abort connecting after %ss: device %s not reachable on %s. %s",
+                        self.log_id,
                         max_timeout,
-                        self._name,
+                        self._identifier,
                         self._atv.host,
                         ex,
                     )
@@ -148,7 +149,7 @@ async def init(self, max_timeout: int | None = None) -> bool:
             self._name = name
         self._identifier = mac.replace(":", "")
 
-        LOG.debug("Android TV initialised: %s, %s", self._identifier, self._name)
+        _LOG.debug("[%s] Android TV initialised", self.log_id)
         return True
 
     @property
@@ -162,6 +163,11 @@ def identifier(self) -> str:
             raise ValueError("Instance not initialized, no identifier available")
         return self._identifier
 
+    @property
+    def log_id(self) -> str:
+        """Return a log identifier."""
+        return self._name if self._name else self._identifier
+
     @property
     def name(self) -> str:
         """Return the device name."""
@@ -212,11 +218,11 @@ async def start_pairing(self) -> ucapi.StatusCodes:
             await self._atv.async_start_pairing()
             return ucapi.StatusCodes.OK
         except CannotConnect as ex:
-            LOG.error("Failed to start pairing. Error connecting: %s", ex)
+            _LOG.error("[%s] Failed to start pairing. Error connecting: %s", self.log_id, ex)
             return ucapi.StatusCodes.SERVICE_UNAVAILABLE
         except ConnectionClosed as ex:
             # TODO better error code?
-            LOG.error("Failed to start pairing. Connection closed: %s", ex)
+            _LOG.error("[%s] Failed to start pairing. Connection closed: %s", self.log_id, ex)
             return ucapi.StatusCodes.SERVER_ERROR
 
     async def finish_pairing(self, pin: str) -> ucapi.StatusCodes:
@@ -232,10 +238,10 @@ async def finish_pairing(self, pin: str) -> ucapi.StatusCodes:
             await self._atv.async_finish_pairing(pin)
             return ucapi.StatusCodes.OK
         except InvalidAuth as ex:
-            LOG.error("Invalid pairing code. Error: %s", ex)
+            _LOG.error("[%s] Invalid pairing code. Error: %s", self.log_id, ex)
             return ucapi.StatusCodes.UNAUTHORIZED
         except ConnectionClosed as ex:
-            LOG.error("Initialize pair again. Error: %s", ex)
+            _LOG.error("[%s] Initialize pair again. Error: %s", self.log_id, ex)
             return ucapi.StatusCodes.SERVICE_UNAVAILABLE
 
     async def connect(self, max_timeout: int | None = None) -> bool:
@@ -247,11 +253,11 @@ async def connect(self, max_timeout: int | None = None) -> bool:
         """
         # if we are already connecting, simply ignore further connect calls
         if self._connecting:
-            LOG.debug("Connection task already running for %s", self._identifier)
+            _LOG.debug("[%s] Connection task already running", self.log_id)
             return
 
         if self._atv.is_on is not None:
-            LOG.debug("Android TV is already connected: %s", self._identifier)
+            _LOG.debug("[%s] Android TV is already connected", self.log_id)
             # just to make sure the state is up-to-date
             self.events.emit(Events.CONNECTED, self._identifier)
             return True
@@ -266,7 +272,7 @@ async def connect(self, max_timeout: int | None = None) -> bool:
 
         while not success:
             try:
-                LOG.debug("Connecting Android TV %s on %s", self._identifier, self._atv.host)
+                _LOG.debug("[%s] Connecting Android TV %s on %s", self.log_id, self._identifier, self._atv.host)
                 self.events.emit(Events.CONNECTING, self._identifier)
                 request_start = time.time()
                 async with timeout(5.0):
@@ -277,22 +283,29 @@ async def connect(self, max_timeout: int | None = None) -> bool:
             except InvalidAuth:
                 # TODO: In this case we need to re-authenticate
                 # How to handle this?
-                LOG.error("Invalid authentication for %s", self._identifier)
+                _LOG.error("[%s] Invalid authentication for %s", self.log_id, self._identifier)
                 self.events.emit(Events.AUTH_ERROR, self._identifier)
                 break
             except (CannotConnect, ConnectionClosed, asyncio.TimeoutError) as ex:
                 if max_timeout and time.time() - start > max_timeout:
-                    LOG.error(
-                        "Abort connecting after %ss: device '%s' not reachable on %s. %s",
+                    _LOG.error(
+                        "[%s] Abort connecting after %ss: device %s not reachable on %s. %s",
+                        self.log_id,
                         max_timeout,
-                        self._name,
+                        self._identifier,
                         self._atv.host,
                         ex,
                     )
                     break
                 await self._handle_connection_failure(time.time() - request_start, ex)
             except Exception as ex:  # pylint: disable=broad-exception-caught
-                LOG.error("Fatal error connecting Android TV %s on %s: %s", self._identifier, self._atv.host, ex)
+                _LOG.error(
+                    "[%s] Fatal error connecting Android TV %s on %s: %s",
+                    self.log_id,
+                    self._identifier,
+                    self._atv.host,
+                    ex,
+                )
                 break
 
         if not success:
@@ -302,7 +315,7 @@ async def connect(self, max_timeout: int | None = None) -> bool:
         self._atv.keep_reconnecting()
 
         device_info = self._atv.device_info
-        LOG.info("Device information: %s", device_info)
+        _LOG.info("[%s] Device information: %s", self.log_id, device_info)
 
         self._update_app_list()
         self.events.emit(Events.CONNECTED, self._identifier)
@@ -315,8 +328,9 @@ async def _handle_connection_failure(self, connect_duration: float, ex):
         backoff = self._backoff() - connect_duration
         if backoff <= 0:
             backoff = 0.1
-        LOG.error(
-            "Cannot connect to '%s' on %s, trying again in %.1fs. %s",
+        _LOG.error(
+            "[%s] Cannot connect to %s on %s, trying again in %.1fs. %s",
+            self.log_id,
             self._identifier if self._identifier else self._name,
             self._atv.host,
             backoff,
@@ -325,19 +339,21 @@ async def _handle_connection_failure(self, connect_duration: float, ex):
 
         # try resolving IP address from device name if we keep failing to connect, maybe the IP address changed
         if self._connection_attempts % 10 == 0:
-            LOG.debug("Start resolving IP address for '%s'...", self._name)
+            _LOG.debug("[%s] Start resolving IP address for %s...", self.log_id, self._identifier)
             try:
                 discovered = await discover.android_tvs()
                 for item in discovered:
                     if item["name"] == self._name:
                         if self._atv.host != item["address"]:
-                            LOG.info("IP address of '%s' changed: %s", self._name, item["address"])
+                            _LOG.info(
+                                "[%s] IP address of %s changed: %s", self.log_id, self._identifier, item["address"]
+                            )
                             self._atv.host = item["address"]
                             self.events.emit(Events.IP_ADDRESS_CHANGED, self._identifier, self._atv.host)
                             break
             except Exception as e:  # pylint: disable=broad-exception-caught
                 # extra safety, otherwise reconnection task is dead
-                LOG.error("Discovery failed: %s", e)
+                _LOG.error("[%s] Discovery failed: %s", self.log_id, e)
         else:
             await asyncio.sleep(backoff)
 
@@ -350,7 +366,7 @@ def disconnect(self) -> None:
     # Callbacks
     def _is_on_updated(self, is_on: bool) -> None:
         """Notify that the Android TV power state is updated."""
-        LOG.info("%s is on: %s", self._identifier, is_on)
+        _LOG.info("[%s] is on: %s", self.log_id, is_on)
         update = {}
         if is_on:
             update["state"] = media_player.States.ON.value
@@ -360,7 +376,7 @@ def _is_on_updated(self, is_on: bool) -> None:
 
     def _current_app_updated(self, current_app: str) -> None:
         """Notify that the current app on Android TV is updated."""
-        LOG.info("%s notified that current_app: %s", self._identifier, current_app)
+        _LOG.debug("[%s] current_app: %s", self.log_id, current_app)
         update = {"source": current_app}
 
         if current_app in apps.IdMappings:
@@ -382,13 +398,13 @@ def _current_app_updated(self, current_app: str) -> None:
 
     def _volume_info_updated(self, volume_info: dict[str, str | bool]) -> None:
         """Notify that the Android TV volume information is updated."""
-        LOG.info("%s notified that volume_info: %s", self._identifier, volume_info)
+        _LOG.debug("[%s] volume_info: %s", self.log_id, volume_info)
         update = {"volume": volume_info["level"], "muted": volume_info["muted"]}
         self.events.emit(Events.UPDATE, self._identifier, update)
 
     def _is_available_updated(self, is_available: bool):
         """Notify that the Android TV is ready to receive commands or is unavailable."""
-        LOG.info("%s notified that is_available: %s", self._identifier, is_available)
+        _LOG.info("[%s] is_available: %s", self.log_id, is_available)
         self.events.emit(Events.CONNECTED if is_available else Events.DISCONNECTED, self.identifier)
 
     def _update_app_list(self) -> None:
@@ -445,10 +461,10 @@ async def _send_command(self, keycode: int | str, action: KeyPress = KeyPress.SH
 
             return ucapi.StatusCodes.OK
         except ConnectionClosed:
-            LOG.error("Cannot send command, connection lost: %s", self._identifier)
+            _LOG.error("[%s] Cannot send command, connection lost", self.log_id)
             return ucapi.StatusCodes.SERVICE_UNAVAILABLE
         except ValueError:
-            LOG.error("Cannot send command, invalid key_code: %s", keycode)
+            _LOG.error("[%s] Cannot send command, invalid key_code: %s", self.log_id, keycode)
             return ucapi.StatusCodes.BAD_REQUEST
 
     async def send_media_player_command(self, cmd_id: str) -> ucapi.StatusCodes:
@@ -461,13 +477,13 @@ async def send_media_player_command(self, cmd_id: str) -> ucapi.StatusCodes:
                  BAD_REQUEST if the ``cmd_id`` is unknown or not supported
         """
         if not self._profile:
-            LOG.error("Cannot send command %s: no device profile set", cmd_id)
+            _LOG.error("[%s] Cannot send command %s: no device profile set", self.log_id, cmd_id)
             return ucapi.StatusCodes.SERVER_ERROR
 
         if command := self._profile.command(cmd_id):
             return await self._send_command(command.keycode, command.action)
 
-        LOG.error("Cannot send command, unknown or unsupported command: %s", cmd_id)
+        _LOG.error("[%s] Cannot send command, unknown or unsupported command: %s", self.log_id, cmd_id)
         return ucapi.StatusCodes.BAD_REQUEST
 
     async def turn_on(self) -> ucapi.StatusCodes:
@@ -502,9 +518,9 @@ async def select_source(self, source: str) -> ucapi.StatusCodes:
         if source in inputs.KeyCode:
             return await self._switch_input(source)
 
-        LOG.warning(
+        _LOG.warning(
             "[%s] Unknown source parameter in select_source command: %s",
-            self._identifier,
+            self.log_id,
             source,
         )
         return ucapi.StatusCodes.BAD_REQUEST
@@ -515,7 +531,7 @@ def _launch_app(self, app: str) -> ucapi.StatusCodes:
             self._atv.send_launch_app_command(apps.Apps[app]["url"])
             return ucapi.StatusCodes.OK
         except ConnectionClosed:
-            LOG.error("Cannot launch app, connection lost: %s", self._identifier)
+            _LOG.error("[%s] Cannot launch app, connection lost", self.log_id)
             return ucapi.StatusCodes.SERVICE_UNAVAILABLE
 
     async def _switch_input(self, source: str) -> ucapi.StatusCodes: