From 740e35bd5ea6f60156e525566ebef848403cb1fd Mon Sep 17 00:00:00 2001
From: Fabio Manganiello <fabio@manganiello.tech>
Date: Sat, 31 Aug 2024 21:47:44 +0200
Subject: [PATCH] Moved full dump of requests+responses+events to log debug
 level.

Messages can be quite big and verbose, and they can anyway be subscribed
over Websockets.

Full dumps are anyway enabled when Platypush is started in verbose mode.

This commit replaces the dumps on INFO level with a quick summary
containing the message ID, request/event type and response time.
---
 platypush/app/_app.py                  |  8 +++++++-
 platypush/message/__init__.py          | 13 +++++++------
 platypush/message/request/__init__.py  | 18 ++++++++++++++++--
 platypush/message/response/__init__.py |  8 ++++++--
 4 files changed, 36 insertions(+), 11 deletions(-)

diff --git a/platypush/app/_app.py b/platypush/app/_app.py
index 9bcffdba03..4f16e69c29 100644
--- a/platypush/app/_app.py
+++ b/platypush/app/_app.py
@@ -365,7 +365,13 @@ class Application:
             elif isinstance(msg, Response):
                 msg.log()
             elif isinstance(msg, Event):
-                msg.log()
+                log.info(
+                    'Received event: %s.%s[id=%s]',
+                    msg.__class__.__module__,
+                    msg.__class__.__name__,
+                    msg.id,
+                )
+                msg.log(level=logging.DEBUG)
                 self.event_processor.process_event(msg)
 
         return _f
diff --git a/platypush/message/__init__.py b/platypush/message/__init__.py
index 65106da2b4..69c9673f71 100644
--- a/platypush/message/__init__.py
+++ b/platypush/message/__init__.py
@@ -8,7 +8,7 @@ import logging
 import inspect
 import json
 import time
-from typing import Union
+from typing import Optional, Union
 from uuid import UUID
 
 _logger = logging.getLogger('platypush')
@@ -114,18 +114,19 @@ class Message:
         self._logger = _logger
         self._default_log_prefix = ''
 
-    def log(self, prefix=''):
+    def log(self, level: Optional[int] = None, prefix=''):
         if self.logging_level is None:
             return  # Skip logging
 
         log_func = self._logger.info
-        if self.logging_level == logging.DEBUG:
+        level = level if level is not None else self.logging_level
+        if level == logging.DEBUG:
             log_func = self._logger.debug
-        elif self.logging_level == logging.WARNING:
+        elif level == logging.WARNING:
             log_func = self._logger.warning
-        elif self.logging_level == logging.ERROR:
+        elif level == logging.ERROR:
             log_func = self._logger.error
-        elif self.logging_level == logging.FATAL:
+        elif level == logging.FATAL:
             log_func = self._logger.fatal
 
         if not prefix:
diff --git a/platypush/message/request/__init__.py b/platypush/message/request/__init__.py
index 9e4c20db25..7a55e65429 100644
--- a/platypush/message/request/__init__.py
+++ b/platypush/message/request/__init__.py
@@ -165,6 +165,11 @@ class Request(Message):
                         context_value = [*context_value]
                     if isinstance(context_value, datetime.date):
                         context_value = context_value.isoformat()
+                except NameError as e:
+                    logger.warning(
+                        'Could not expand expression "%s": %s', inner_expr, e
+                    )
+                    context_value = expr
                 except Exception as e:
                     logger.exception(e)
                     context_value = expr
@@ -188,7 +193,13 @@ class Request(Message):
         response.id = self.id
         response.target = self.origin
         response.origin = Config.get('device_id')
-        response.log()
+        self._logger.info(
+            'Sending response to request[id=%s, action=%s], response_time=%.02fs',
+            self.id,
+            self.action,
+            response.timestamp - self.timestamp,
+        )
+        response.log(level=logging.DEBUG)
 
         if self.backend and self.origin:
             self.backend.send_response(response=response, request=self)
@@ -221,7 +232,10 @@ class Request(Message):
             from platypush.plugins import RunnablePlugin
 
             response = None
-            self.log()
+            self._logger.info(
+                'Executing request[id=%s, action=%s]', self.id, self.action
+            )
+            self.log(level=logging.DEBUG)
 
             try:
                 if self.action.startswith('procedure.'):
diff --git a/platypush/message/response/__init__.py b/platypush/message/response/__init__.py
index f1db626e24..2a16a1cb5d 100644
--- a/platypush/message/response/__init__.py
+++ b/platypush/message/response/__init__.py
@@ -1,6 +1,7 @@
 import json
 import logging
 import time
+from typing import Optional
 
 from platypush.message import Message
 
@@ -99,8 +100,11 @@ class Response(Message):
 
         return json.dumps(response_dict, cls=self.Encoder)
 
-    def log(self, *args, **kwargs):
-        self.logging_level = logging.WARNING if self.is_error() else logging.INFO
+    def log(self, *args, level: Optional[int] = None, **kwargs):
+        if level is None:
+            level = logging.WARNING if self.is_error() else logging.INFO
+
+        kwargs['level'] = level
         super().log(*args, **kwargs)