Improve log messages

Author: brefra

plugwise_usb/connection/manager.py

@@ -184,6 +184,7 @@ async def setup_connection_to_stick(
 
     async def write_to_stick(self, request: PlugwiseRequest) -> None:
         """Write message to USB stick."""
+        _LOGGER.debug("Write to USB-stick: %s", request)
         if not request.resend:
             raise StickError(
                 f"Failed to send {request.__class__.__name__} " +

plugwise_usb/connection/queue.py

@@ -82,7 +82,7 @@ async def submit(
         self, request: PlugwiseRequest
     ) -> PlugwiseResponse:
         """Add request to queue and return the response of node. Raises an error when something fails."""
-        _LOGGER.debug("Queueing %s", request)
+        _LOGGER.debug("Submit %s", request)
         while request.resend:
             if not self._running or self._stick is None:
                 raise StickError(
@@ -93,13 +93,13 @@ async def submit(
             try:
                 response: PlugwiseResponse = await request.response_future()
             except (NodeTimeout, StickTimeout) as e:
-                if request.resend:
-                    _LOGGER.debug("%s, retrying", e)
-                elif isinstance(request, NodePingRequest):
+                if isinstance(request, NodePingRequest):
                     # For ping requests it is expected to receive timeouts, so lower log level
-                    _LOGGER.debug("%s after %s attempts. Cancel request", e, request.max_retries)
+                    _LOGGER.debug("%s, cancel because timeout is expected for NodePingRequests", e)
+                elif request.resend:
+                    _LOGGER.info("%s, retrying", e)
                 else:
-                    _LOGGER.info("%s after %s attempts, cancel request", e, request.max_retries)
+                    _LOGGER.warning("%s, cancel request", e)
             except StickError as exception:
                 _LOGGER.error(exception)
                 raise StickError(
@@ -122,6 +122,7 @@ async def submit(
 
     async def _add_request_to_queue(self, request: PlugwiseRequest) -> None:
         """Add request to send queue."""
+        _LOGGER.debug("Add request to queue: %s", request)
         await self._submit_queue.put(request)
         if self._submit_worker_task is None or self._submit_worker_task.done():
             self._submit_worker_task = self._loop.create_task(
@@ -131,10 +132,14 @@ async def _add_request_to_queue(self, request: PlugwiseRequest) -> None:
 
     async def _send_queue_worker(self) -> None:
         """Send messages from queue at the order of priority."""
+        _LOGGER.debug("Send_queue_worker started")
         while self._running:
             request = await self._submit_queue.get()
+            _LOGGER.debug("Send from queue %s", request)
             if request.priority == Priority.CANCEL:
                 self._submit_queue.task_done()
                 return
             await self._stick.write_to_stick(request)
             self._submit_queue.task_done()
+            _LOGGER.debug("Sent from queue %s", request)
+        _LOGGER.debug("Send_queue_worker finished")

plugwise_usb/connection/receiver.py

@@ -104,9 +104,9 @@ def __init__(
 
     def connection_lost(self, exc: Exception | None = None) -> None:
         """Call when port was closed expectedly or unexpectedly."""
-        _LOGGER.debug("Connection lost")
+        _LOGGER.info("Connection lost")
         if exc is not None:
-            _LOGGER.warning("Connection lost %s", exc)
+            _LOGGER.warning("Connection to Plugwise USB-stick lost %s", exc)
         self._loop.create_task(self.close())
         if len(self._stick_event_subscribers) > 0:
             self._loop.create_task(
@@ -132,7 +132,7 @@ def reduce_logging(self, reduce_logging: bool) -> None:
 
     def connection_made(self, transport: SerialTransport) -> None:
         """Call when the serial connection to USB-Stick is established."""
-        _LOGGER.debug("Connection made")
+        _LOGGER.info("Connection made")
         self._transport = transport
         if (
             self._connected_future is not None
@@ -168,6 +168,7 @@ def data_received(self, data: bytes) -> None:
 
         This function is called by inherited asyncio.Protocol class
         """
+        _LOGGER.debug("Received data from USB-Stick: %s", data)
         self._buffer += data
         if MESSAGE_FOOTER in self._buffer:
             msgs = self._buffer.split(MESSAGE_FOOTER)
@@ -182,6 +183,7 @@ def data_received(self, data: bytes) -> None:
 
     def _put_message_in_receiver_queue(self, response: PlugwiseResponse) -> None:
         """Put message in queue."""
+        _LOGGER.debug("Add response to queue: %s", response)
         self._receive_queue.put_nowait(response)
         if self._msg_processing_task is None or self._msg_processing_task.done():
             self._msg_processing_task = self._loop.create_task(
@@ -194,6 +196,7 @@ def extract_message_from_line_buffer(self, msg: bytes) -> PlugwiseResponse:
         # Lookup header of message, there are stray \x83
         if (_header_index := msg.find(MESSAGE_HEADER)) == -1:
             return False
+        _LOGGER.debug("Extract message from data: %s", msg)
         msg = msg[_header_index:]
         # Detect response message type
         identifier = msg[4:8]
@@ -211,23 +214,25 @@ def extract_message_from_line_buffer(self, msg: bytes) -> PlugwiseResponse:
             _LOGGER.warning(err)
             return None
 
-        _LOGGER.debug("Reading '%s' from USB-Stick", response)
+        _LOGGER.debug("Data %s converted into %s", msg, response)
         return response
 
     async def _receive_queue_worker(self):
         """Process queue items."""
+        _LOGGER.debug("Receive_queue_worker started")
         while self.is_connected:
             response: PlugwiseResponse | None = await self._receive_queue.get()
-            _LOGGER.debug("Processing started for %s", response)
+            _LOGGER.debug("Process from queue: %s", response)
             if isinstance(response, StickResponse):
+                _LOGGER.debug("Received %s", response)
                 await self._notify_stick_response_subscribers(response)
             elif response is None:
                 self._receive_queue.task_done()
                 return
             else:
                 await self._notify_node_response_subscribers(response)
-            _LOGGER.debug("Processing finished for %s", response)
             self._receive_queue.task_done()
+        _LOGGER.debug("Receive_queue_worker finished")
 
     def _reset_buffer(self, new_buffer: bytes) -> None:
         if new_buffer[:2] == MESSAGE_FOOTER:
@@ -295,6 +300,7 @@ async def _notify_stick_response_subscribers(
                     continue
             if response_type is not None and response_type != stick_response.response_type:
                 continue
+            _LOGGER.debug("Notify stick response subscriber for %s", stick_response)
             await callback(stick_response)
 
     def subscribe_to_node_responses(
@@ -320,7 +326,7 @@ def remove_listener() -> None:
     async def _notify_node_response_subscribers(self, node_response: PlugwiseResponse) -> None:
         """Call callback for all node response message subscribers."""
         if node_response.seq_id in self._last_processed_messages:
-            _LOGGER.debug("Drop duplicate already processed %s", node_response)
+            _LOGGER.debug("Drop previously processed duplicate %s", node_response)
             return
 
         notify_tasks: list[Callable] = []
@@ -336,6 +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)
             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:

plugwise_usb/connection/sender.py

@@ -56,6 +56,7 @@ 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()
 
@@ -65,9 +66,9 @@ async def write_request_to_port(self, request: PlugwiseRequest) -> None:
             self._receiver.subscribe_to_node_responses,
         )
 
-        _LOGGER.debug("Writing '%s' to USB-Stick", request)
         # Write message to serial port buffer
         serialized_data = request.serialize()
+        _LOGGER.debug("Write %s to port: %s", request, serialized_data)
         self._transport.write(serialized_data)
         request.start_response_timeout()
 
@@ -85,12 +86,14 @@ async def write_request_to_port(self, request: PlugwiseRequest) -> None:
                 )
             )
         except BaseException as exc:  # pylint: disable=broad-exception-caught
+            _LOGGER.warning("Exception for %s: %s", request, exc)
             request.assign_error(exc)
         else:
-            _LOGGER.debug("Request '%s' was accepted by USB-stick with seq_id %s", request, str(request.seq_id))
             if response.response_type == StickResponseType.ACCEPT:
                 request.seq_id = response.seq_id
+                _LOGGER.info("Sent %s", request)
             elif response.response_type == StickResponseType.TIMEOUT:
+                _LOGGER.warning("USB-Stick responded with communication timeout for %s", request)
                 request.assign_error(
                     BaseException(
                         StickError(
@@ -99,6 +102,7 @@ async def write_request_to_port(self, request: PlugwiseRequest) -> None:
                     )
                 )
             elif response.response_type == StickResponseType.FAILED:
+                _LOGGER.warning("USB-Stick failed communication for %s", request)
                 request.assign_error(
                     BaseException(
                         StickError(

plugwise_usb/helpers/cache.py

@@ -96,8 +96,8 @@ async def write_cache(self, data: dict[str, str], rewrite: bool = False) -> None
             encoding=UTF8,
         ) as file_data:
             await file_data.writelines(data_to_write)
-        _LOGGER.info(
-            "Saved %s lines to network cache file %s",
+        _LOGGER.debug(
+            "Saved %s lines to cache file %s",
             str(len(data)),
             self._cache_file
         )

plugwise_usb/messages/requests.py

@@ -102,6 +102,7 @@ def seq_id(self) -> bytes | None:
     def seq_id(self, seq_id: bytes) -> None:
         """Assign sequence id."""
         if self._seq_id is not None:
+            _LOGGER.warning("Unable to change seq_id into %s for request %s", seq_id, self)
             raise MessageError(f"Unable to set seq_id to {seq_id}. Already set to {self._seq_id}")
         self._seq_id = seq_id
         # Subscribe to receive the response messages
@@ -159,12 +160,14 @@ def _response_timeout_expired(self, stick_timeout: bool = False) -> 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, self._response, NODE_TIME_OUT)
             self._response_future.set_exception(
                 NodeTimeout(
                     f"No response to {self} within {NODE_TIME_OUT} seconds"

plugwise_usb/network/registry.py

@@ -232,7 +232,7 @@ async def update_missing_registrations(
                 _LOGGER.debug("Full network registration finished, pre")
                 await self.save_registry_to_cache()
                 _LOGGER.debug("Full network registration finished, post")
-            _LOGGER.info("Full network registration discovery completed")
+            _LOGGER.info("Full network discovery completed")
             if self._full_scan_finished is not None:
                 await self._full_scan_finished()
                 self._full_scan_finished = None