diff --git a/src/azul/chalice.py b/src/azul/chalice.py index 0405133ff..2dbd1ea23 100644 --- a/src/azul/chalice.py +++ b/src/azul/chalice.py @@ -61,6 +61,9 @@ copy_json, json_head, ) +from azul.logging import ( + http_body_log_message, +) from azul.strings import ( join_words as jw, single_quote as sq, @@ -404,11 +407,23 @@ def _log_request(self): 'query': self.current_request.query_params, 'headers': self.current_request.headers } - log.info('Received %s request for %r, with %s.', + log.info('Received %s request for %r, with %s', context['httpMethod'], context['path'], json.dumps(request_info, cls=self._LogJSONEncoder)) + body = self.current_request.json_body + if not body: + msg = '' + elif config.debug == 2: + body = json.dumps(body, cls=self._LogJSONEncoder) + msg = f' ({len(body)} characters)' + else: + n = 1024 + msg = f' (first {str(n)} characters)' + body = json_head(n, body) if not isinstance(body, str | bytes) else body[:n] + log.info('%s%s', http_body_log_message('request', body, verbatim=True), msg) + def _log_response(self, response): if log.isEnabledFor(logging.DEBUG): n = 1024 diff --git a/src/azul/logging.py b/src/azul/logging.py index f5a24bb37..d0b480f67 100644 --- a/src/azul/logging.py +++ b/src/azul/logging.py @@ -4,6 +4,7 @@ import logging from typing import ( Optional, + TYPE_CHECKING, ) import attr @@ -15,13 +16,18 @@ from azul import ( config, ) -from azul.chalice import ( - AzulChaliceApp, -) from azul.strings import ( trunc_ellipses, ) +if TYPE_CHECKING: + from azul.chalice import ( + AzulChaliceApp, + ) +else: + class AzulChaliceApp: + pass + @attr.s(frozen=False, kw_only=False, auto_attribs=True) class LambdaLogFilter(logging.Filter): diff --git a/test/test_app_logging.py b/test/test_app_logging.py index 237270757..25fc96dec 100644 --- a/test/test_app_logging.py +++ b/test/test_app_logging.py @@ -78,7 +78,7 @@ def fail(): self.assertEqual(response.status_code, 500) # The request is always logged - self.assertEqual(len(azul_log.output), 3) + self.assertEqual(len(azul_log.output), 4) headers = { 'host': f'{host}:{port}', 'user-agent': 'python-requests/2.32.2', @@ -88,8 +88,10 @@ def fail(): } self.assertEqual(azul_log.output[0], f'INFO:azul.chalice:Received GET request for {path!r}, ' - f"with {json.dumps({'query': None, 'headers': headers})}.") + f"with {json.dumps({'query': None, 'headers': headers})}") self.assertEqual(azul_log.output[1], + 'INFO:azul.chalice:… without request body') + self.assertEqual(azul_log.output[2], 'INFO:azul.chalice:Did not authenticate request.') # The exception is always logged @@ -106,7 +108,7 @@ def fail(): self.assertIn(magic_message, response) # … and the response is logged. self.assertEqual( - azul_log.output[2], + azul_log.output[3], 'DEBUG:azul.chalice:Returning 500 response with headers {"Content-Type": "text/plain", ' f'"Content-Security-Policy": "default-src {sq("self")}", ' '"Referrer-Policy": "strict-origin-when-cross-origin", ' @@ -124,7 +126,7 @@ def fail(): }) # … and a generic error message is logged. self.assertEqual( - azul_log.output[2], + azul_log.output[3], 'INFO:azul.chalice:Returning 500 response. To log headers and body, set AZUL_DEBUG to 1.' )