From d3f8967904b0831d02cb98cae5e2d72d73503db8 Mon Sep 17 00:00:00 2001
From: Marcel van der Veldt <marcel.vanderveldt@nabucasa.com>
Date: Tue, 27 Jun 2023 15:59:49 +0200
Subject: [PATCH] Add some additional logging to client (#337)

---
 matter_server/client/client.py     | 23 ++++++++++++++++++++---
 matter_server/client/connection.py | 14 ++++----------
 2 files changed, 24 insertions(+), 13 deletions(-)

diff --git a/matter_server/client/client.py b/matter_server/client/client.py
index bf9edf29..5314ce07 100644
--- a/matter_server/client/client.py
+++ b/matter_server/client/client.py
@@ -386,7 +386,6 @@ def _handle_incoming_message(self, msg: MessageType) -> None:
 
         # handle EventMessage
         if isinstance(msg, EventMessage):
-            self.logger.debug("Received event: %s", msg.event)
             self._handle_event_message(msg)
             return
 
@@ -407,29 +406,41 @@ def _handle_event_message(self, msg: EventMessage) -> None:
                 event = EventType.NODE_ADDED
                 node = MatterNode(node_data)
                 self._nodes[node.node_id] = node
+                self.logger.debug("New node added: %s", node.node_id)
             else:
                 event = EventType.NODE_UPDATED
                 node.update(node_data)
+                self.logger.debug("Node updated: %s", node.node_id)
             self._signal_event(event, data=node, node_id=node.node_id)
             return
         if msg.event == EventType.NODE_REMOVED:
             node_id = msg.data
+            self.logger.debug("Node removed: %s", node_id)
             self._signal_event(EventType.NODE_REMOVED, data=node_id, node_id=node_id)
             # cleanup node only after signalling subscribers
             self._nodes.pop(node_id, None)
             return
         if msg.event == EventType.ENDPOINT_REMOVED:
             node_id = msg.data["node_id"]
+            endpoint_id = msg.data["endpoint_id"]
+            self.logger.debug("Endpoint removed: %s/%s", node_id, endpoint_id)
             self._signal_event(
                 EventType.ENDPOINT_REMOVED, data=msg.data, node_id=node_id
             )
             # cleanup endpoint only after signalling subscribers
             if node := self._nodes.get(node_id):
-                node.endpoints.pop(msg.data["endpoint_id"], None)
+                node.endpoints.pop(endpoint_id, None)
             return
         if msg.event == EventType.ATTRIBUTE_UPDATED:
             # data is tuple[node_id, attribute_path, new_value]
             node_id, attribute_path, new_value = msg.data
+            if self.logger.isEnabledFor(logging.DEBUG):
+                self.logger.debug(
+                    "Attribute updated: Node: %s - Attribute: %s - New value: %s",
+                    node_id,
+                    attribute_path,
+                    new_value,
+                )
             self._nodes[node_id].update_attribute(attribute_path, new_value)
             self._signal_event(
                 EventType.ATTRIBUTE_UPDATED,
@@ -438,7 +449,13 @@ def _handle_event_message(self, msg: EventMessage) -> None:
                 attribute_path=attribute_path,
             )
             return
-        # TODO: handle any other events ?
+        if msg.event == EventType.ENDPOINT_ADDED:
+            node_id = msg.data["node_id"]
+            endpoint_id = msg.data["endpoint_id"]
+            self.logger.debug("Endpoint added: %s/%s", node_id, endpoint_id)
+        # simply forward all other events as-is
+        if self.logger.isEnabledFor(logging.DEBUG):
+            self.logger.debug("Received event: %s", msg)
         self._signal_event(msg.event, msg.data)
 
     def _signal_event(
diff --git a/matter_server/client/connection.py b/matter_server/client/connection.py
index 52101da9..2dcb5a4d 100644
--- a/matter_server/client/connection.py
+++ b/matter_server/client/connection.py
@@ -130,11 +130,8 @@ async def receive_message_or_raise(self) -> MessageType:
         except ValueError as err:
             raise InvalidMessage("Received invalid JSON.") from err
 
-        if LOGGER.isEnabledFor(logging.DEBUG):
-            if VERBOSE_LOGGER:
-                LOGGER.debug("Received message:\n%s\n", pprint.pformat(ws_msg))
-            else:
-                LOGGER.debug("Received message: %s ...", ws_msg.data[:50])
+        if VERBOSE_LOGGER and LOGGER.isEnabledFor(logging.DEBUG):
+            LOGGER.debug("Received message:\n%s\n", pprint.pformat(ws_msg))
 
         return msg
 
@@ -147,11 +144,8 @@ async def send_message(self, message: CommandMessage) -> None:
         if not self.connected:
             raise NotConnected
 
-        if LOGGER.isEnabledFor(logging.DEBUG):
-            if VERBOSE_LOGGER:
-                LOGGER.debug("Publishing message:\n%s\n", pprint.pformat(message))
-            else:
-                LOGGER.debug("Publishing message: %s", message)
+        if VERBOSE_LOGGER and LOGGER.isEnabledFor(logging.DEBUG):
+            LOGGER.debug("Publishing message:\n%s\n", pprint.pformat(message))
 
         assert self._ws_client
         assert isinstance(message, CommandMessage)