[2/2] Fix: Log request body (#6404)

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,24 @@ 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 body is None:
+                body_len_msg = ''
+            elif config.debug == 2:
+                body = json.dumps(body, cls=self._LogJSONEncoder)
+                body_len_msg = f' ({len(body)} characters)'
+            else:
+                n = 1024
+                body_len_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), body_len_msg)
+
     def _log_response(self, response):
         if log.isEnabledFor(logging.DEBUG):
             n = 1024

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

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