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.types import (
     JSON,
     LambdaContext,
@@ -382,11 +385,25 @@ 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.raw_body
+            if not body:
+                body = None
+                msg = ''
+            else:
+                if config.debug == 2:
+                    body = json.dumps(body, cls=self._LogJSONEncoder)
+                    msg = f' ({len(body)} total characters)'
+                else:
+                    n = 1024
+                    body = json_head(n, body) if not isinstance(body, str | bytes) else body[:n]
+                    msg = f' (first {n} characters)'
+            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

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/service/test_app_logging.py

@@ -52,7 +52,12 @@ def test_request_logs(self):
                         (
                             INFO,
                             f"Received GET request for '/health/basic', "
-                            f"with {json.dumps({'query': None, 'headers': headers})}."),
+                            f"with {json.dumps({'query': None, 'headers': headers})}"
+                        ),
+                        (
+                            INFO,
+                            "… without request body"
+                        ),
                         (
                             INFO,
                             "Authenticated request as OAuth2(access_token='foo_token')"

test/test_app_logging.py

@@ -75,7 +75,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',
@@ -85,8 +85,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
@@ -103,7 +105,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", '
                             '"Strict-Transport-Security": "max-age=31536000; includeSubDomains", '
                             '"X-Content-Type-Options": "nosniff", '
@@ -118,7 +120,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.'
                         )