Add contextual logging where applicable (#124)

* Add contextual logging where applicable

* Compress device id in log output

custom_components/localtuya/binary_sensor.py

@@ -38,7 +38,7 @@ class LocaltuyaBinarySensor(LocalTuyaEntity, BinarySensorEntity):
         **kwargs,
     ):
         """Initialize the Tuya binary sensor."""
-        super().__init__(device, config_entry, sensorid, **kwargs)
+        super().__init__(device, config_entry, sensorid, _LOGGER, **kwargs)
         self._is_on = False
 
     @property
@@ -59,7 +59,7 @@ class LocaltuyaBinarySensor(LocalTuyaEntity, BinarySensorEntity):
         elif state == self._config[CONF_STATE_OFF].lower():
             self._is_on = False
         else:
-            _LOGGER.warning(
+            self.warning(
                 "State for entity %s did not match state patterns", self.entity_id
             )
 

custom_components/localtuya/common.py

@@ -90,7 +90,7 @@ def get_entity_config(config_entry, dp_id):
     raise Exception(f"missing entity config for id {dp_id}")
 
 
-class TuyaDevice(pytuya.TuyaListener):
+class TuyaDevice(pytuya.TuyaListener, pytuya.ContextualLogger):
     """Cache wrapper for pytuya.TuyaInterface."""
 
     def __init__(self, hass, config_entry):
@@ -103,6 +103,7 @@ class TuyaDevice(pytuya.TuyaListener):
         self._is_closing = False
         self._connect_task = None
         self._connection_attempts = 0
+        self.set_logger(_LOGGER, config_entry[CONF_DEVICE_ID])
 
         # This has to be done in case the device type is type_0d
         for entity in config_entry[CONF_ENTITIES]:
@@ -111,14 +112,13 @@ class TuyaDevice(pytuya.TuyaListener):
     def connect(self):
         """Connet to device if not already connected."""
         if not self._is_closing and self._connect_task is None and not self._interface:
-            _LOGGER.debug(
+            self.debug(
-                "Connecting to %s (%s)",
+                "Connecting to %s",
                 self._config_entry[CONF_HOST],
-                self._config_entry[CONF_DEVICE_ID],
             )
             self._connect_task = asyncio.ensure_future(self._make_connection())
         else:
-            _LOGGER.debug(
+            self.debug(
                 "Already connecting to %s (%s) - %s, %s, %s",
                 self._config_entry[CONF_HOST],
                 self._config_entry[CONF_DEVICE_ID],
@@ -132,11 +132,11 @@ class TuyaDevice(pytuya.TuyaListener):
             randrange(2 ** self._connection_attempts), BACKOFF_TIME_UPPER_LIMIT
         )
 
-        _LOGGER.debug("Waiting %d seconds before connecting", backoff)
+        self.debug("Waiting %d seconds before connecting", backoff)
         await asyncio.sleep(backoff)
 
         try:
-            _LOGGER.debug("Connecting to %s", self._config_entry[CONF_HOST])
+            self.debug("Connecting to %s", self._config_entry[CONF_HOST])
             self._interface = await pytuya.connect(
                 self._config_entry[CONF_HOST],
                 self._config_entry[CONF_DEVICE_ID],
@@ -146,7 +146,7 @@ class TuyaDevice(pytuya.TuyaListener):
             )
             self._interface.add_dps_to_request(self._dps_to_request)
 
-            _LOGGER.debug("Retrieving initial state")
+            self.debug("Retrieving initial state")
             status = await self._interface.status()
             if status is None:
                 raise Exception("Failed to retrieve status")
@@ -154,7 +154,7 @@ class TuyaDevice(pytuya.TuyaListener):
             self.status_updated(status)
             self._connection_attempts = 0
         except Exception:
-            _LOGGER.exception(f"Connect to {self._config_entry[CONF_HOST]} failed")
+            self.exception(f"Connect to {self._config_entry[CONF_HOST]} failed")
             self._connection_attempts += 1
             if self._interface is not None:
                 self._interface.close()
@@ -176,9 +176,9 @@ class TuyaDevice(pytuya.TuyaListener):
             try:
                 await self._interface.set_dp(state, dp_index)
             except Exception:
-                _LOGGER.exception("Failed to set DP %d to %d", dp_index, state)
+                self.exception("Failed to set DP %d to %d", dp_index, state)
         else:
-            _LOGGER.error(
+            self.error(
                 "Not connected to device %s", self._config_entry[CONF_FRIENDLY_NAME]
             )
 
@@ -188,9 +188,9 @@ class TuyaDevice(pytuya.TuyaListener):
             try:
                 await self._interface.set_dps(states)
             except Exception:
-                _LOGGER.exception("Failed to set DPs %r", states)
+                self.exception("Failed to set DPs %r", states)
         else:
-            _LOGGER.error(
+            self.error(
                 "Not connected to device %s", self._config_entry[CONF_FRIENDLY_NAME]
             )
 
@@ -205,9 +205,7 @@ class TuyaDevice(pytuya.TuyaListener):
     @callback
     def disconnected(self, exc):
         """Device disconnected."""
-        _LOGGER.debug(
+        self.debug("Disconnected: %s", exc)
-            "Disconnected from %s: %s", self._config_entry[CONF_DEVICE_ID], exc
-        )
 
         signal = f"localtuya_{self._config_entry[CONF_DEVICE_ID]}"
         async_dispatcher_send(self._hass, signal, None)
@@ -216,22 +214,23 @@ class TuyaDevice(pytuya.TuyaListener):
         self.connect()
 
 
-class LocalTuyaEntity(Entity):
+class LocalTuyaEntity(Entity, pytuya.ContextualLogger):
     """Representation of a Tuya entity."""
 
-    def __init__(self, device, config_entry, dp_id, **kwargs):
+    def __init__(self, device, config_entry, dp_id, logger, **kwargs):
         """Initialize the Tuya entity."""
         self._device = device
         self._config_entry = config_entry
         self._config = get_entity_config(config_entry, dp_id)
         self._dp_id = dp_id
         self._status = {}
+        self.set_logger(logger, self._config_entry.data[CONF_DEVICE_ID])
 
     async def async_added_to_hass(self):
         """Subscribe localtuya events."""
         await super().async_added_to_hass()
 
-        _LOGGER.debug("Adding %s with configuration: %s", self.entity_id, self._config)
+        self.debug("Adding %s with configuration: %s", self.entity_id, self._config)
 
         def _update_handler(status):
             """Update entity state when status was updated."""
@@ -291,7 +290,7 @@ class LocalTuyaEntity(Entity):
         """Return cached value for DPS index."""
         value = self._status.get(str(dp_index))
         if value is None:
-            _LOGGER.warning(
+            self.warning(
                 "Entity %s is requesting unknown DPS index %s",
                 self.entity_id,
                 dp_index,
@@ -307,7 +306,7 @@ class LocalTuyaEntity(Entity):
         """
         dp_index = self._config.get(conf_item)
         if dp_index is None:
-            _LOGGER.warning(
+            self.warning(
                 "Entity %s is requesting unset index for option %s",
                 self.entity_id,
                 conf_item,

custom_components/localtuya/cover.py

@@ -68,7 +68,7 @@ class LocaltuyaCover(LocalTuyaEntity, CoverEntity):
         **kwargs,
     ):
         """Initialize a new LocaltuyaCover."""
-        super().__init__(device, config_entry, switchid, **kwargs)
+        super().__init__(device, config_entry, switchid, _LOGGER, **kwargs)
         self._state = None
         self._current_cover_position = None
         commands_set = DEFAULT_COMMANDS_SET
@@ -122,7 +122,7 @@ class LocaltuyaCover(LocalTuyaEntity, CoverEntity):
 
     async def async_set_cover_position(self, **kwargs):
         """Move the cover to a specific position."""
-        _LOGGER.debug("Setting cover position: %r", kwargs[ATTR_POSITION])
+        self.debug("Setting cover position: %r", kwargs[ATTR_POSITION])
         if self._config[CONF_POSITIONING_MODE] == COVER_MODE_FAKE:
             newpos = float(kwargs[ATTR_POSITION])
 
@@ -130,15 +130,15 @@ class LocaltuyaCover(LocalTuyaEntity, CoverEntity):
             posdiff = abs(newpos - currpos)
             mydelay = posdiff / 50.0 * self._config[CONF_SPAN_TIME]
             if newpos > currpos:
-                _LOGGER.debug("Opening to %f: delay %f", newpos, mydelay)
+                self.debug("Opening to %f: delay %f", newpos, mydelay)
                 await self.async_open_cover()
             else:
-                _LOGGER.debug("Closing to %f: delay %f", newpos, mydelay)
+                self.debug("Closing to %f: delay %f", newpos, mydelay)
                 await self.async_close_cover()
             await asyncio.sleep(mydelay)
             await self.async_stop_cover()
             self._current_cover_position = 50
-            _LOGGER.debug("Done")
+            self.debug("Done")
 
         elif self._config[CONF_POSITIONING_MODE] == COVER_MODE_POSITION:
             converted_position = int(kwargs[ATTR_POSITION])
@@ -152,17 +152,17 @@ class LocaltuyaCover(LocalTuyaEntity, CoverEntity):
 
     async def async_open_cover(self, **kwargs):
         """Open the cover."""
-        _LOGGER.debug("Launching command %s to cover ", self._open_cmd)
+        self.debug("Launching command %s to cover ", self._open_cmd)
         await self._device.set_dp(self._open_cmd, self._dp_id)
 
     async def async_close_cover(self, **kwargs):
         """Close cover."""
-        _LOGGER.debug("Launching command %s to cover ", self._close_cmd)
+        self.debug("Launching command %s to cover ", self._close_cmd)
         await self._device.set_dp(self._close_cmd, self._dp_id)
 
     async def async_stop_cover(self, **kwargs):
         """Stop the cover."""
-        _LOGGER.debug("Launching command %s to cover ", self._stop_cmd)
+        self.debug("Launching command %s to cover ", self._stop_cmd)
         await self._device.set_dp(self._stop_cmd, self._dp_id)
 
     def status_updated(self):

custom_components/localtuya/fan.py

@@ -54,7 +54,7 @@ class LocaltuyaFan(LocalTuyaEntity, FanEntity):
         **kwargs,
     ):
         """Initialize the entity."""
-        super().__init__(device, config_entry, fanid, **kwargs)
+        super().__init__(device, config_entry, fanid, _LOGGER, **kwargs)
         self._is_on = False
         self._speed = None
         self._oscillating = None
@@ -141,7 +141,7 @@ class LocaltuyaFan(LocalTuyaEntity, FanEntity):
         if self.has_config(CONF_FAN_SPEED_CONTROL):
             self._speed = mappings.get(self.dps_conf(CONF_FAN_SPEED_CONTROL))
             if self.speed is None:
-                _LOGGER.warning(
+                self.warning(
                     "%s/%s: Ignoring unknown fan controller state: %s",
                     self.name,
                     self.entity_id,

custom_components/localtuya/light.py

@@ -78,7 +78,7 @@ class LocaltuyaLight(LocalTuyaEntity, LightEntity):
         **kwargs,
     ):
         """Initialize the Tuya light."""
-        super().__init__(device, config_entry, lightid, **kwargs)
+        super().__init__(device, config_entry, lightid, _LOGGER, **kwargs)
         self._state = False
         self._brightness = None
         self._color_temp = None

custom_components/localtuya/pytuya/__init__.py

@@ -104,7 +104,40 @@ class TuyaLoggingAdapter(logging.LoggerAdapter):
 
     def process(self, msg, kwargs):
         """Process log point and return output."""
-        return f"[{self.extra['device_id']}] {msg}", kwargs
+        dev_id = self.extra["device_id"]
+        return f"[{dev_id[0:3]}...{dev_id[-3:]}] {msg}", kwargs
+
+
+class ContextualLogger:
+    """Contextual logger adding device id to log points."""
+
+    def __init__(self):
+        """Initialize a new ContextualLogger."""
+        self._logger = None
+
+    def set_logger(self, logger, device_id):
+        """Set base logger to use."""
+        self._logger = TuyaLoggingAdapter(logger, {"device_id": device_id})
+
+    def debug(self, msg, *args):
+        """Debug level log."""
+        return self._logger.log(logging.DEBUG, msg, *args)
+
+    def info(self, msg, *args):
+        """Info level log."""
+        return self._logger.log(logging.INFO, msg, *args)
+
+    def warning(self, msg, *args):
+        """Warning method log."""
+        return self._logger.log(logging.WARNING, msg, *args)
+
+    def error(self, msg, *args):
+        """Error level log."""
+        return self._logger.log(logging.ERROR, msg, *args)
+
+    def exception(self, msg, *args):
+        """Exception level log."""
+        return self._logger.log(logging.EXCEPTION, msg, *args)
 
 
 def pack_message(msg):
@@ -171,19 +204,19 @@ class AESCipher:
         return s[: -ord(s[len(s) - 1 :])]
 
 
-class MessageDispatcher:
+class MessageDispatcher(ContextualLogger):
     """Buffer and dispatcher for Tuya messages."""
 
     # Heartbeats always respond with sequence number 0, so they can't be waited for like
     # other messages. This is a hack to allow waiting for heartbeats.
     HEARTBEAT_SEQNO = -100
 
-    def __init__(self, log, listener):
+    def __init__(self, dev_id, listener):
         """Initialize a new MessageBuffer."""
-        self.log = log
         self.buffer = b""
         self.listeners = {}
         self.listener = listener
+        self.set_logger(_LOGGER, dev_id)
 
     def abort(self):
         """Abort all waiting clients."""
@@ -198,9 +231,9 @@ class MessageDispatcher:
     async def wait_for(self, seqno, timeout=5):
         """Wait for response to a sequence number to be received and return it."""
         if seqno in self.listeners:
-            raise Exception(f"listener exists for {seqno} (id: {self.id})")
+            raise Exception(f"listener exists for {seqno}")
 
-        self.log.debug("Waiting for sequence number %d", seqno)
+        self.debug("Waiting for sequence number %d", seqno)
         self.listeners[seqno] = asyncio.Semaphore(0)
         try:
             await asyncio.wait_for(self.listeners[seqno].acquire(), timeout=timeout)
@@ -246,23 +279,23 @@ class MessageDispatcher:
 
     def _dispatch(self, msg):
         """Dispatch a message to someone that is listening."""
-        _LOGGER.debug("Dispatching message %s", msg)
+        self.debug("Dispatching message %s", msg)
         if msg.seqno in self.listeners:
-            self.log.debug("Dispatching sequence number %d", msg.seqno)
+            self.debug("Dispatching sequence number %d", msg.seqno)
             sem = self.listeners[msg.seqno]
             self.listeners[msg.seqno] = msg
             sem.release()
         elif msg.cmd == 0x09:
-            self.log.debug("Got heartbeat response")
+            self.debug("Got heartbeat response")
             if self.HEARTBEAT_SEQNO in self.listeners:
                 sem = self.listeners[self.HEARTBEAT_SEQNO]
                 self.listeners[self.HEARTBEAT_SEQNO] = msg
                 sem.release()
         elif msg.cmd == 0x08:
-            self.log.debug("Got status update")
+            self.debug("Got status update")
             self.listener(msg)
         else:
-            self.log.debug(
+            self.debug(
                 "Got message type %d for unknown listener %d: %s",
                 msg.cmd,
                 msg.seqno,
@@ -292,7 +325,7 @@ class EmptyListener(TuyaListener):
         """Device disconnected."""
 
 
-class TuyaProtocol(asyncio.Protocol):
+class TuyaProtocol(asyncio.Protocol, ContextualLogger):
     """Implementation of the Tuya protocol."""
 
     def __init__(self, dev_id, local_key, protocol_version, on_connected, listener):
@@ -308,7 +341,7 @@ class TuyaProtocol(asyncio.Protocol):
             port (int): The port to connect to.
         """
         self.loop = asyncio.get_running_loop()
-        self.log = TuyaLoggingAdapter(_LOGGER, {"device_id": dev_id})
+        self.set_logger(_LOGGER, dev_id)
         self.id = dev_id
         self.local_key = local_key.encode("latin1")
         self.version = protocol_version
@@ -333,22 +366,22 @@ class TuyaProtocol(asyncio.Protocol):
             if listener is not None:
                 listener.status_updated(self.dps_cache)
 
-        return MessageDispatcher(self.log, _status_update)
+        return MessageDispatcher(self.id, _status_update)
 
     def connection_made(self, transport):
         """Did connect to the device."""
 
         async def heartbeat_loop():
             """Continuously send heart beat updates."""
-            self.log.debug("Started heartbeat loop")
+            self.debug("Started heartbeat loop")
             while True:
                 try:
                     await self.heartbeat()
                 except Exception as ex:
-                    self.log.exception("Heartbeat failed (%s), disconnecting", ex)
+                    self.exception("Heartbeat failed (%s), disconnecting", ex)
                     break
                 await asyncio.sleep(HEARTBEAT_INTERVAL)
-            self.log.debug("Stopped heartbeat loop")
+            self.debug("Stopped heartbeat loop")
             self.close()
 
         self.transport = transport
@@ -361,22 +394,22 @@ class TuyaProtocol(asyncio.Protocol):
 
     def connection_lost(self, exc):
         """Disconnected from device."""
-        self.log.debug("Connection lost: %s", exc)
+        self.debug("Connection lost: %s", exc)
         try:
             self.close()
         except Exception:
-            self.log.exception("Failed to close connection")
+            self.exception("Failed to close connection")
         finally:
             try:
                 listener = self.listener()
                 if listener is not None:
                     listener.disconnected(exc)
             except Exception:
-                self.log.exception("Failed to call disconnected callback")
+                self.exception("Failed to call disconnected callback")
 
     def close(self):
         """Close connection and abort all outstanding listeners."""
-        self.log.debug("Closing connection")
+        self.debug("Closing connection")
         if self.heartbeater is not None:
             self.heartbeater.cancel()
         if self.dispatcher is not None:
@@ -388,7 +421,7 @@ class TuyaProtocol(asyncio.Protocol):
 
     async def exchange(self, command, dps=None):
         """Send and receive a message, returning response from device."""
-        self.log.debug(
+        self.debug(
             "Sending command %s (device type: %s)",
             command,
             self.dev_type,
@@ -406,7 +439,7 @@ class TuyaProtocol(asyncio.Protocol):
         self.transport.write(payload)
         msg = await self.dispatcher.wait_for(seqno)
         if msg is None:
-            self.log.debug("Wait was aborted for seqno %d", seqno)
+            self.debug("Wait was aborted for seqno %d", seqno)
             return None
 
         # TODO: Verify stuff, e.g. CRC sequence number?
@@ -414,7 +447,7 @@ class TuyaProtocol(asyncio.Protocol):
 
         # Perform a new exchange (once) if we switched device type
         if dev_type != self.dev_type:
-            self.log.debug(
+            self.debug(
                 "Re-send %s due to device type change (%s -> %s)",
                 command,
                 dev_type,
@@ -465,14 +498,14 @@ class TuyaProtocol(asyncio.Protocol):
             try:
                 data = await self.status()
             except Exception as e:
-                self.log.exception("Failed to get status: %s", e)
+                self.exception("Failed to get status: %s", e)
                 raise
             if "dps" in data:
                 self.dps_cache.update(data["dps"])
 
             if self.dev_type == "type_0a":
                 return self.dps_cache
-        self.log.debug("Detected dps: %s", self.dps_cache)
+        self.debug("Detected dps: %s", self.dps_cache)
         return self.dps_cache
 
     def add_dps_to_request(self, dp_indicies):
@@ -501,17 +534,17 @@ class TuyaProtocol(asyncio.Protocol):
 
             if "data unvalid" in payload:
                 self.dev_type = "type_0d"
-                self.log.debug(
+                self.debug(
                     "switching to dev_type %s",
                     self.dev_type,
                 )
                 return None
         else:
-            raise Exception(f"Unexpected payload={payload} (id: {self.id})")
+            raise Exception(f"Unexpected payload={payload}")
 
         if not isinstance(payload, str):
             payload = payload.decode()
-        self.log.debug("Decrypted payload: %s", payload)
+        self.debug("Decrypted payload: %s", payload)
         return json.loads(payload)
 
     def _generate_payload(self, command, data=None):
@@ -543,7 +576,7 @@ class TuyaProtocol(asyncio.Protocol):
             json_data["dps"] = self.dps_to_request
 
         payload = json.dumps(json_data).replace(" ", "").encode("utf-8")
-        self.log.debug("Send payload: %s", payload)
+        self.debug("Send payload: %s", payload)
 
         if self.version == 3.3:
             payload = self.cipher.encrypt(payload, False)

custom_components/localtuya/sensor.py

@@ -40,7 +40,7 @@ class LocaltuyaSensor(LocalTuyaEntity):
         **kwargs,
     ):
         """Initialize the Tuya sensor."""
-        super().__init__(device, config_entry, sensorid, **kwargs)
+        super().__init__(device, config_entry, sensorid, _LOGGER, **kwargs)
         self._state = STATE_UNKNOWN
 
     @property

custom_components/localtuya/switch.py

@@ -38,7 +38,7 @@ class LocaltuyaSwitch(LocalTuyaEntity, SwitchEntity):
         **kwargs,
     ):
         """Initialize the Tuya switch."""
-        super().__init__(device, config_entry, switchid, **kwargs)
+        super().__init__(device, config_entry, switchid, _LOGGER, **kwargs)
         self._state = None
         print("Initialized switch [{}]".format(self.name))