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

@@ -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

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:

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.'):

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)