fix: add extra logging

This commit is contained in:
Luke Bonaccorsi 2024-03-03 04:18:14 +00:00
parent c251501aed
commit 3dd4a7b0e0
1 changed files with 27 additions and 22 deletions

View File

@ -527,7 +527,7 @@ class Message:
await self.device._async_send(self) await self.device._async_send(self)
@classmethod @classmethod
def from_bytes(cls, data, cipher=None): def from_bytes(cls, device, data, cipher=None):
try: try:
prefix, sequence, command, payload_size = struct.unpack_from( prefix, sequence, command, payload_size = struct.unpack_from(
MESSAGE_PREFIX_FORMAT, data MESSAGE_PREFIX_FORMAT, data
@ -584,15 +584,15 @@ class Message:
try: try:
payload_text = payload_data.decode("utf8") payload_text = payload_data.decode("utf8")
except UnicodeDecodeError as e: except UnicodeDecodeError as e:
_LOGGER.debug(payload_data.hex()) device._LOGGER.debug(payload_data.hex())
_LOGGER.error(e) device._LOGGER.error(e)
raise MessageDecodeFailed() from e raise MessageDecodeFailed() from e
try: try:
payload = json.loads(payload_text) payload = json.loads(payload_text)
except json.decoder.JSONDecodeError as e: except json.decoder.JSONDecodeError as e:
# data may be encrypted # data may be encrypted
_LOGGER.debug(payload_data.hex()) device._LOGGER.debug(payload_data.hex())
_LOGGER.error(e) device._LOGGER.error(e)
raise MessageDecodeFailed() from e raise MessageDecodeFailed() from e
return cls(command, payload, sequence) return cls(command, payload, sequence)
@ -614,6 +614,7 @@ class TuyaDevice:
version=(3, 3), version=(3, 3),
): ):
"""Initialize the device.""" """Initialize the device."""
self._LOGGER = _LOGGER.getChild(device_id)
self.device_id = device_id self.device_id = device_id
self.host = host self.host = host
self.port = port self.port = port
@ -668,7 +669,7 @@ class TuyaDevice:
self.clean_queue() self.clean_queue()
if len(self._queue) > 0: if len(self._queue) > 0:
_LOGGER.debug( self._LOGGER.debug(
"Processing queue. Current length: {}".format(len(self._queue)) "Processing queue. Current length: {}".format(len(self._queue))
) )
try: try:
@ -679,14 +680,16 @@ class TuyaDevice:
self._backoff = False self._backoff = False
except Exception as e: except Exception as e:
self._failures += 1 self._failures += 1
_LOGGER.debug("{} failures. Most recent: {}".format(self._failures, e)) self._LOGGER.debug(
"{} failures. Most recent: {}".format(self._failures, e)
)
if self._failures > 3: if self._failures > 3:
self._backoff = True self._backoff = True
self._queue_interval = min( self._queue_interval = min(
INITIAL_BACKOFF * (BACKOFF_MULTIPLIER ** (self._failures - 4)), INITIAL_BACKOFF * (BACKOFF_MULTIPLIER ** (self._failures - 4)),
600, 600,
) )
_LOGGER.warn( self._LOGGER.warn(
"{} failures, backing off for {} seconds".format( "{} failures, backing off for {} seconds".format(
self._failures, self._queue_interval self._failures, self._queue_interval
) )
@ -709,7 +712,7 @@ class TuyaDevice:
sock = socket.socket(family=socket.AF_INET, type=socket.SOCK_STREAM) sock = socket.socket(family=socket.AF_INET, type=socket.SOCK_STREAM)
sock.settimeout(self.timeout) sock.settimeout(self.timeout)
_LOGGER.debug("Connecting to {}".format(self)) self._LOGGER.debug("Connecting to {}".format(self))
try: try:
sock.connect((self.host, self.port)) sock.connect((self.host, self.port))
except (socket.timeout, TimeoutError) as e: except (socket.timeout, TimeoutError) as e:
@ -734,7 +737,7 @@ class TuyaDevice:
if self._connected is False: if self._connected is False:
return return
_LOGGER.debug("Disconnected from {}".format(self)) self._LOGGER.debug("Disconnected from {}".format(self))
self._connected = False self._connected = False
self.last_pong = 0 self.last_pong = 0
@ -769,7 +772,7 @@ class TuyaDevice:
return return
if self._backoff is True: if self._backoff is True:
_LOGGER.debug("Currently in backoff, not adding ping to queue") self._LOGGER.debug("Currently in backoff, not adding ping to queue")
else: else:
self.last_ping = time.time() self.last_ping = time.time()
encrypt = False if self.version < (3, 3) else True encrypt = False if self.version < (3, 3) else True
@ -801,7 +804,7 @@ class TuyaDevice:
and state_message.payload["dps"] and state_message.payload["dps"]
): ):
self._dps.update(state_message.payload["dps"]) self._dps.update(state_message.payload["dps"])
_LOGGER.debug("Received updated state {}: {}".format(self, self._dps)) self._LOGGER.debug("Received updated state {}: {}".format(self, self._dps))
@property @property
def state(self): def state(self):
@ -821,21 +824,23 @@ class TuyaDevice:
) )
await self._response_task await self._response_task
response_data = self._response_task.result() response_data = self._response_task.result()
message = Message.from_bytes(response_data, self.cipher) message = Message.from_bytes(self, response_data, self.cipher)
except Exception as e: except Exception as e:
if isinstance(e, InvalidMessage): if isinstance(e, InvalidMessage):
_LOGGER.debug("Invalid message from {}: {}".format(self, e)) self._LOGGER.debug("Invalid message from {}: {}".format(self, e))
elif isinstance(e, MessageDecodeFailed): elif isinstance(e, MessageDecodeFailed):
_LOGGER.debug("Failed to decrypt message from {}".format(self)) self._LOGGER.debug("Failed to decrypt message from {}".format(self))
elif isinstance(e, asyncio.IncompleteReadError): elif isinstance(e, asyncio.IncompleteReadError):
if self._connected: if self._connected:
_LOGGER.debug("Incomplete read") self._LOGGER.debug("Incomplete read")
elif isinstance(e, ConnectionResetError): elif isinstance(e, ConnectionResetError):
_LOGGER.debug("Connection reset: {}".format(e)) self._LOGGER.debug(
"Connection reset: {}\n{}".format(e, e.__traceback__)
)
await self.async_disconnect() await self.async_disconnect()
else: else:
_LOGGER.debug("Received message from {}: {}".format(self, message)) self._LOGGER.debug("Received message from {}: {}".format(self, message))
if message.sequence in self._listeners: if message.sequence in self._listeners:
sem = self._listeners[message.sequence] sem = self._listeners[message.sequence]
if isinstance(sem, asyncio.Semaphore): if isinstance(sem, asyncio.Semaphore):
@ -850,7 +855,7 @@ class TuyaDevice:
asyncio.create_task(self._async_handle_message()) asyncio.create_task(self._async_handle_message())
async def _async_send(self, message, retries=2): async def _async_send(self, message, retries=2):
_LOGGER.debug("Sending to {}: {}".format(self, message)) self._LOGGER.debug("Sending to {}: {}".format(self, message))
try: try:
await self.async_connect() await self.async_connect()
self.writer.write(message.bytes()) self.writer.write(message.bytes())
@ -871,19 +876,19 @@ class TuyaDevice:
raise TuyaException("Failed to send data to {}".format(self)) raise TuyaException("Failed to send data to {}".format(self))
if isinstance(e, socket.error): if isinstance(e, socket.error):
_LOGGER.debug( self._LOGGER.debug(
"Retrying send due to error. Connection to {} failed: {}".format( "Retrying send due to error. Connection to {} failed: {}".format(
self, e self, e
) )
) )
elif isinstance(e, asyncio.IncompleteReadError): elif isinstance(e, asyncio.IncompleteReadError):
_LOGGER.debug( self._LOGGER.debug(
"Retrying send due to error. Incomplete read from: {} : {}. Partial data recieved: {}".format( "Retrying send due to error. Incomplete read from: {} : {}. Partial data recieved: {}".format(
self, e, e.partial self, e, e.partial
) )
) )
else: else:
_LOGGER.debug( self._LOGGER.debug(
"Retrying send due to error. Failed to send data to {}".format(self) "Retrying send due to error. Failed to send data to {}".format(self)
) )
await asyncio.sleep(0.25) await asyncio.sleep(0.25)