From fa1364d85462cdbf52d580728c3957020b070562 Mon Sep 17 00:00:00 2001 From: Fabio Manganiello Date: Sat, 15 Jul 2023 01:01:15 +0200 Subject: [PATCH] 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 | 12 ++-- platypush/message/event/__init__.py | 1 + platypush/message/request/__init__.py | 72 ++++++-------------- platypush/message/response/__init__.py | 12 ++-- 4 files changed, 32 insertions(+), 65 deletions(-) diff --git a/platypush/backend/http/app/routes/execute.py b/platypush/backend/http/app/routes/execute.py index 148c6687..8caecce7 100644 --- a/platypush/backend/http/app/routes/execute.py +++ b/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( - 'Unable to parse JSON from request {}: {}'.format(request.data, str(e)) - ) + logger().error('Unable to parse JSON from request %s: %s', request.data, 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( - 'Error while running HTTP action: {}. Request: {}'.format(str(e), msg) - ) + logger().error('Error while running HTTP action: %s. Request: %s', e, msg) abort(500, str(e)) diff --git a/platypush/message/event/__init__.py b/platypush/message/event/__init__.py index 221487a7..1b56553a 100644 --- a/platypush/message/event/__init__.py +++ b/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 [ diff --git a/platypush/message/request/__init__.py b/platypush/message/request/__init__.py index 5ddf2cfb..58e5bbbd 100644 --- a/platypush/message/request/__init__.py +++ b/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 = '' - for _ in range(0, 16): - _id += '%.2x' % random.randint(0, 255) - return _id + return ''.join(f'{random.randint(0, 255):02x}' for _ in range(0, 16)) 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: - logger.debug(str(e)) + except Exception: 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( - k, v, str(e) - ) + 'Could not set context variable %s=%s: %s', k, v, e2 ) - 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) - (module_name, method_name) = get_module_and_method_from_action( - action - ) - plugin = get_plugin(module_name) - assert plugin, f'No such plugin: {module_name}' + + action = self.expand_value_from_context(self.action, **context) + (module_name, method_name) = get_module_and_method_from_action(action) + 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( - self.action, str(e) - ) - logger.warning(msg) - response = Response(output=None, errors=[msg]) + response = Response(output=None, errors=[str(e)]) self._send_response(response) return response @@ -276,41 +266,23 @@ class Request(Message): else: response = plugin.run(method_name, args) - if not response: - logger.warning( - '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) + if response is None: + response = Response() 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() diff --git a/platypush/message/response/__init__.py b/platypush/message/response/__init__.py index e8844e40..f1db626e 100644 --- a/platypush/message/response/__init__.py +++ b/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): - prefix = ( - f'Processed response from action {action}: ' - if action - else 'Received response: ' - ) - - super().log(prefix) + def log(self, *args, **kwargs): + self.logging_level = logging.WARNING if self.is_error() else logging.INFO + super().log(*args, **kwargs) # vim:sw=4:ts=4:et: