Improved logging for requests, responses and events.

- The following logging namespaces are now used, to make it easier to
  filter only log lines related to the logged application message:

  - `platypush:events`
  - `platypush:requests`
  - `platypush:responses`

- Those messages are always logged as JSON, with no prefixes nor
  suffixes.

- Requests are always logged when executed - no more delegation to the
  upstream backend.

- Responses are always logged when fully populated (including `id`,
  `origin`, `target` etc.), instead of being logged when still partially
  populated. This makes it particularly easy to link request/response
  IDs directly from the logs.

platypush/backend/http/app/routes/execute.py

@@ -21,20 +21,18 @@ def execute_route():
     try:
         msg = json.loads(request.data.decode('utf-8'))
     except Exception as e:
-        logger().error(
+        logger().error('Unable to parse JSON from request %s: %s', request.data, e)
-            'Unable to parse JSON from request {}: {}'.format(request.data, str(e))
-        )
         abort(400, str(e))
 
-    logger().info('Received message on the HTTP backend: {}'.format(msg))
+    logger().debug(
+        'Received message on the HTTP backend from %s: %s', request.remote_addr, msg
+    )
 
     try:
         response = send_message(msg)
         return Response(str(response or {}), mimetype='application/json')
     except Exception as e:
-        logger().error(
+        logger().error('Error while running HTTP action: %s. Request: %s', e, msg)
-            'Error while running HTTP action: {}. Request: {}'.format(str(e), msg)
-        )
         abort(500, str(e))
 
 

platypush/message/event/__init__.py

@@ -57,6 +57,7 @@ class Event(Message):
         self.type = f'{self.__class__.__module__}.{self.__class__.__name__}'
         self.args = kwargs
         self.disable_web_clients_notification = disable_web_clients_notification
+        self._logger = logging.getLogger('platypush:events')
 
         for arg, value in self.args.items():
             if arg not in [

platypush/message/request/__init__.py

@@ -57,6 +57,7 @@ class Request(Message):
         self.args = args if args else {}
         self.backend = backend
         self.token = token
+        self._logger = logging.getLogger('platypush:requests')
 
     @classmethod
     def build(cls, msg):
@@ -77,16 +78,11 @@ class Request(Message):
 
     @staticmethod
     def _generate_id():
-        _id = ''
+        return ''.join(f'{random.randint(0, 255):02x}' for _ in range(0, 16))
-        for _ in range(0, 16):
-            _id += '%.2x' % random.randint(0, 255)
-        return _id
 
     def _execute_procedure(self, *args, **kwargs):
-        from platypush.config import Config
         from platypush.procedure import Procedure
 
-        logger.info('Executing procedure request: {}'.format(self.action))
         procedures = Config.get_procedures()
         proc_name = '.'.join(self.action.split('.')[1:])
         if proc_name not in procedures:
@@ -120,7 +116,7 @@ class Request(Message):
 
         constants = Config.get_constants()
         context['constants'] = {}
-        for (name, value) in constants.items():
+        for name, value in constants.items():
             context['constants'][name] = value
 
         keys = []
@@ -143,23 +139,20 @@ class Request(Message):
 
     @classmethod
     def expand_value_from_context(cls, _value, **context):
-        for (k, v) in context.items():
+        for k, v in context.items():
             if isinstance(v, Message):
                 v = json.loads(str(v))
             try:
                 exec('{}={}'.format(k, v))
-            except Exception as e:
+            except Exception:
-                logger.debug(str(e))
                 if isinstance(v, str):
                     try:
                         exec('{}="{}"'.format(k, re.sub(r'(^|[^\\])"', '\1\\"', v)))
-                    except Exception as e:
+                    except Exception as e2:
                         logger.debug(
-                            'Could not set context variable {}={}: {}'.format(
+                            'Could not set context variable %s=%s: %s', k, v, e2
-                                k, v, str(e)
-                            )
                         )
-                        logger.debug('Context: {}'.format(context))
+                        logger.debug('Context: %s', context)
 
         parsed_value = ''
         if not isinstance(_value, str):
@@ -205,6 +198,7 @@ class Request(Message):
         response.id = self.id
         response.target = self.origin
         response.origin = Config.get('device_id')
+        response.log()
 
         if self.backend and self.origin:
             self.backend.send_response(response=response, request=self)
@@ -235,6 +229,7 @@ class Request(Message):
             from platypush.plugins import RunnablePlugin
 
             response = None
+            self.log()
 
             try:
                 if self.action.startswith('procedure.'):
@@ -243,25 +238,20 @@ class Request(Message):
                     if response is not None:
                         self._send_response(response)
                     return response
+
                 # utils.get_context is a special action that simply returns the current context
-                elif self.action == 'utils.get_context':
+                if self.action == 'utils.get_context':
                     response = Response(output=context)
                     self._send_response(response)
                     return response
-                else:
+
-                    action = self.expand_value_from_context(self.action, **context)
+                action = self.expand_value_from_context(self.action, **context)
-                    (module_name, method_name) = get_module_and_method_from_action(
+                (module_name, method_name) = get_module_and_method_from_action(action)
-                        action
+                plugin = get_plugin(module_name)
-                    )
+                assert plugin, f'No such plugin: {module_name}'
-                    plugin = get_plugin(module_name)
-                    assert plugin, f'No such plugin: {module_name}'
             except Exception as e:
                 logger.exception(e)
-                msg = 'Uncaught pre-processing exception from action [{}]: {}'.format(
+                response = Response(output=None, errors=[str(e)])
-                    self.action, str(e)
-                )
-                logger.warning(msg)
-                response = Response(output=None, errors=[msg])
                 self._send_response(response)
                 return response
 
@@ -276,41 +266,23 @@ class Request(Message):
                 else:
                     response = plugin.run(method_name, args)
 
-                if not response:
+                if response is None:
-                    logger.warning(
+                    response = Response()
-                        'Received null response from action {}'.format(action)
-                    )
-                else:
-                    if response.is_error():
-                        logger.warning(
-                            (
-                                'Response processed with errors from ' + 'action {}: {}'
-                            ).format(action, str(response))
-                        )
-                    else:
-                        response.log(action)
             except (AssertionError, TimeoutError) as e:
                 logger.warning(
-                    '%s from action [%s]: %s', e.__class__.__name__, action, str(e)
+                    '%s from action [%s]: %s', e.__class__.__name__, action, e
                 )
                 response = Response(output=None, errors=[str(e)])
             except Exception as e:
                 # Retry mechanism
                 plugin.logger.exception(e)
-                logger.warning(
-                    (
-                        'Uncaught exception while processing response '
-                        + 'from action [{}]: {}'
-                    ).format(action, str(e))
-                )
-
                 errors = errors or []
                 if str(e) not in errors:
                     errors.append(str(e))
 
                 response = Response(output=None, errors=errors)
                 if _n_tries - 1 > 0:
-                    logger.info('Reloading plugin {} and retrying'.format(module_name))
+                    logger.info('Reloading plugin %s and retrying', module_name)
                     plugin = get_plugin(module_name, reload=True)
                     if isinstance(plugin, RunnablePlugin):
                         plugin.bus = get_bus()

platypush/message/response/__init__.py

@@ -37,6 +37,7 @@ class Response(Message):
         self.errors = self._parse_msg(errors or [])
         self.origin = origin
         self.id = id
+        self._logger = logging.getLogger('platypush:responses')
 
     def is_error(self):
         """Returns True if the response has errors"""
@@ -98,14 +99,9 @@ class Response(Message):
 
         return json.dumps(response_dict, cls=self.Encoder)
 
-    def log(self, action=None):
+    def log(self, *args, **kwargs):
-        prefix = (
+        self.logging_level = logging.WARNING if self.is_error() else logging.INFO
-            f'Processed response from action {action}: '
+        super().log(*args, **kwargs)
-            if action
-            else 'Received response: '
-        )
-
-        super().log(prefix)
 
 
 # vim:sw=4:ts=4:et: