Improve logging

Author: brefra

plugwise_usb/connection/receiver.py

@@ -222,7 +222,7 @@ async def _receive_queue_worker(self):
         _LOGGER.debug("Receive_queue_worker started")
         while self.is_connected:
             response: PlugwiseResponse | None = await self._receive_queue.get()
-            _LOGGER.debug("Process from queue: %s", response)
+            _LOGGER.debug("Process from receive queue: %s", response)
             if isinstance(response, StickResponse):
                 _LOGGER.debug("Received %s", response)
                 await self._notify_stick_response_subscribers(response)
@@ -232,7 +232,7 @@ async def _receive_queue_worker(self):
             else:
                 await self._notify_node_response_subscribers(response)
             self._receive_queue.task_done()
-        _LOGGER.debug("Receive_queue_worker finished")
+        _LOGGER.debug("Receive_queue_worker stopped")
 
     def _reset_buffer(self, new_buffer: bytes) -> None:
         if new_buffer[:2] == MESSAGE_FOOTER:
@@ -342,7 +342,7 @@ async def _notify_node_response_subscribers(self, node_response: PlugwiseRespons
             notify_tasks.append(callback(node_response))
 
         if len(notify_tasks) > 0:
-            _LOGGER.debug("Notify node response subscribers (%s) about %s", len(notify_tasks), node_response)
+            _LOGGER.info("Received %s", node_response)
             if node_response.seq_id not in BROADCAST_IDS:
                 self._last_processed_messages.append(node_response.seq_id)
             if node_response.seq_id in self._delayed_processing_tasks:
@@ -351,6 +351,7 @@ async def _notify_node_response_subscribers(self, node_response: PlugwiseRespons
             self._last_processed_messages = self._last_processed_messages[-CACHED_REQUESTS:]
 
             # execute callbacks
+            _LOGGER.debug("Notify node response subscribers (%s) about %s", len(notify_tasks), node_response)
             task_result = await gather(*notify_tasks)
 
             # Log execution result for special cases

plugwise_usb/connection/sender.py

@@ -56,11 +56,11 @@ async def write_request_to_port(self, request: PlugwiseRequest) -> None:
             raise StickError("USB-Stick transport missing.")
 
         await self._stick_lock.acquire()
-        _LOGGER.debug("Send %s", request)
         self._current_request = request
         self._stick_response: Future[bytes] = self._loop.create_future()
 
         request.add_send_attempt()
+        _LOGGER.debug("Send %s", request)
         request.subscribe_to_responses(
             self._receiver.subscribe_to_stick_responses,
             self._receiver.subscribe_to_node_responses,
@@ -91,7 +91,7 @@ async def write_request_to_port(self, request: PlugwiseRequest) -> None:
         else:
             if response.response_type == StickResponseType.ACCEPT:
                 request.seq_id = response.seq_id
-                _LOGGER.info("Sent %s", request)
+                _LOGGER.debug("USB-Stick accepted %s with seq_id=%s", request, response.seq_id)
             elif response.response_type == StickResponseType.TIMEOUT:
                 _LOGGER.warning("USB-Stick responded with communication timeout for %s", request)
                 request.assign_error(

plugwise_usb/messages/requests.py

@@ -66,8 +66,8 @@ def __init__(
     def __repr__(self) -> str:
         """Convert request into writable str."""
         if self._seq_id is None:
-            return f"{self.__class__.__name__} (mac={self.mac_decoded}, seq_id=UNKNOWN, attempts={self._send_counter})"
-        return f"{self.__class__.__name__} (mac={self.mac_decoded}, seq_id={self._seq_id}, attempts={self._send_counter})"
+            return f"{self.__class__.__name__} (mac={self.mac_decoded}, seq_id=UNKNOWN, attempt={self._send_counter})"
+        return f"{self.__class__.__name__} (mac={self.mac_decoded}, seq_id={self._seq_id}, attempt={self._send_counter})"
 
     def response_future(self) -> Future[PlugwiseResponse]:
         """Return awaitable future with response message."""
@@ -145,18 +145,20 @@ def _response_timeout_expired(self, stick_timeout: bool = False) -> None:
         """Handle response timeout."""
         if self._response_future.done():
             return
+        if stick_timeout:
+            _LOGGER.info("USB-stick responded with time out to %s", self)
+        else:
+            _LOGGER.warning("No response received for %s within timeout (%s seconds)", self, NODE_TIME_OUT)
         self._seq_id = None
         self._unsubscribe_from_stick()
         self._unsubscribe_from_node()
         if stick_timeout:
-            _LOGGER.warning("USB-stick responded with time out to %s", self)
             self._response_future.set_exception(
                 StickTimeout(
                     f"USB-stick responded with time out to {self}"
                 )
             )
         else:
-            _LOGGER.warning("No response received for %s within timeout (%s seconds)", self, NODE_TIME_OUT)
             self._response_future.set_exception(
                 NodeTimeout(
                     f"No device response to {self} within {NODE_TIME_OUT} seconds"