Fix: Log request body (#6404)

scripts/generate_environment_boot.py

@@ -1,8 +1,8 @@
+import logging
 import os
 
 from azul import (
     config,
-    logging,
 )
 from azul.docker import (
     resolve_docker_image_for_pull,

src/azul/__init__.py

@@ -13,7 +13,7 @@
 from itertools import (
     chain,
 )
-import logging
+import logging as _logging
 import os
 from pathlib import (
     Path,
@@ -66,7 +66,7 @@
     frozendict,
 )
 
-log = logging.getLogger(__name__)
+log = _logging.getLogger(__name__)
 
 Netloc = tuple[str, int]
 

src/azul/chalice.py

@@ -17,6 +17,7 @@
     Callable,
     Iterator,
     Literal,
+    Mapping,
     Self,
     Sequence,
     TypeVar,
@@ -66,7 +67,10 @@
 )
 from azul.json import (
     copy_json,
-    json_head,
+)
+from azul.logging import (
+    BodyType,
+    http_body_log_message,
 )
 from azul.openapi import (
     format_description,
@@ -463,34 +467,34 @@
             log.info('Authenticated request as %r', auth)
 
     def _log_request(self):
-        if log.isEnabledFor(logging.INFO):
-            assert self.current_request is not None
-            context = self.current_request.context
-            request_info = {
-                'query': self.current_request.query_params,
-                'headers': self.current_request.headers
-            }
-            log.info('Received %s request for %r, with %s.',
-                     context['httpMethod'],
-                     context['path'],
-                     json.dumps(request_info, cls=self._LogJSONEncoder))
+        assert self.current_request is not None
+        context = self.current_request.context
+        request_info = {
+            'query': self.current_request.query_params,
+            'headers': self.current_request.headers
+        }
+        log.info('Received %s request for %r, with %s.',
+                 context['httpMethod'],
+                 context['path'],
+                 json.dumps(request_info, cls=self._LogJSONEncoder))
+        self._log_body('request', self.current_request.json_body)
 
     def _log_response(self, response):
-        if log.isEnabledFor(logging.DEBUG):
-            n = 1024
-            if isinstance(response.body, str):
-                body = response.body[:n]
-            else:
-                body = json_head(n, response.body)
-            log.debug('Returning %i response with headers %s. '
-                      'See next line for the first %i characters of the body.\n%s',
-                      response.status_code,
-                      json.dumps(response.headers, cls=self._LogJSONEncoder),
-                      n, body)
+        log.info('Returning %i response with headers %s.',
+                 response.status_code, json.dumps(response.headers, cls=self._LogJSONEncoder))
+        self._log_body('response', response.body)
+
+    def _log_body(self, body_type: BodyType, body: str | JSON | None):
+        if body is None:
+            log.info(http_body_log_message(body_type, None))
         else:
-            log.info('Returning %i response. '
-                     'To log headers and body, set AZUL_DEBUG to 1.',
-                     response.status_code)
+            if isinstance(body, Mapping):
+                body = json.dumps(body)
+            if log.isEnabledFor(logging.DEBUG):
+                message = http_body_log_message(body_type, body, verbatim=config.debug > 1)
+                log.debug(message)
+            else:
+                log.info('… with %s body size of %i bytes', body_type, len(body))
 
     absent = object()
 

src/azul/logging.py

@@ -4,7 +4,9 @@
 import logging
 from typing import (
     IO,
+    Literal,
     Optional,
+    TYPE_CHECKING,
 )
 
 import attr
@@ -13,17 +15,19 @@
 )
 
 import azul
-from azul.chalice import (
-    AzulChaliceApp,
-)
 from azul.strings import (
     trunc_ellipses,
 )
 
+if TYPE_CHECKING:
+    from azul.chalice import (
+        AzulChaliceApp,
+    )
+
 
 @attr.s(frozen=False, kw_only=False, auto_attribs=True)
 class LambdaLogFilter(logging.Filter):
-    app: Optional[AzulChaliceApp] = None
+    app: Optional['AzulChaliceApp'] = None
 
     def filter(self, record):
         if self.app is None or self.app.lambda_context is None:
@@ -43,7 +47,7 @@
 lambda_log_date_format = '%Y-%m-%dT%H:%M:%S'
 
 
-def configure_app_logging(app: AzulChaliceApp, *loggers):
+def configure_app_logging(app: 'AzulChaliceApp', *loggers):
     _configure_log_levels(app.log, *loggers)
     if not app.unit_test:
         # Environment is not unit test
@@ -163,20 +167,28 @@
             assert es_log.level == original_log_level
 
 
-def http_body_log_message(body_type: str,
+type BodyType = Literal['request', 'response']
+
+http_body_log_prefix_len = 1024
+
+
+def http_body_log_message(body_type: BodyType,
                           body: bytes | bytearray | str | IO[bytes] | IO[str] | None,
                           *,
                           verbatim: bool = False,
                           ) -> str:
     if body is None:
         return f'… without {body_type} body'
     elif isinstance(body, (bytes, bytearray, str)):
+        body_len = len(body)
         if verbatim:
             if isinstance(body, (bytes, bytearray)):
                 body = body.decode(errors='ignore')
+            qualify_log = 'all '
         else:
             # https://github.com/python/typing/discussions/1911
-            body = trunc_ellipses(body, max_len=128)  # type: ignore[type-var]
-        return f'… with {body_type} body {body!r}'
+            body = trunc_ellipses(body, max_len=http_body_log_prefix_len)  # type: ignore[type-var]
+            qualify_log = f'first {http_body_log_prefix_len}/'
+        return f'… with {qualify_log}{body_len} bytes of the {body_type} body {body!r}'
     else:
         return f'… with nonprintable body ({type(body)!r})'

test/service/test_app_logging.py

@@ -3,11 +3,16 @@
     DEBUG,
     INFO,
 )
+from unittest.mock import (
+    PropertyMock,
+    patch,
+)
 
 import requests
 
-from app_test_case import (
-    LocalAppTestCase,
+from azul import (
+    Config,
+    logging,
 )
 from azul.chalice import (
     AzulChaliceApp,
@@ -16,67 +21,136 @@
 from azul.logging import (
     configure_test_logging,
 )
+from azul.strings import (
+    trunc_ellipses,
+)
 from indexer import (
     DCP1CannedBundleTestCase,
 )
+from service import (
+    WebServiceTestCase,
+)
 
 
 # noinspection PyPep8Naming
 def setUpModule():
     configure_test_logging()
 
 
-class TestServiceAppLogging(DCP1CannedBundleTestCase, LocalAppTestCase):
+class TestServiceAppLogging(DCP1CannedBundleTestCase, WebServiceTestCase):
+
+    @classmethod
+    def setUpClass(cls):
+        super().setUpClass()
+        cls._setup_indices()
+
+    @classmethod
+    def tearDownClass(cls):
+        cls._teardown_indices()
+        super().tearDownClass()
 
     @classmethod
     def lambda_name(cls) -> str:
         return 'service'
 
     def test_request_logs(self):
-        for level in INFO, DEBUG:
+        for azul_debug in (0, 1, 2):
+            level = [INFO, DEBUG, DEBUG][azul_debug]
             for authenticated in False, True:
-                with self.subTest(level=level, authenticated=authenticated):
-                    url = self.base_url.set(path='/health/basic')
+                for request_body in False, True:
+                    url = self.base_url.set(path='/index/projects')
                     request_headers = {'authorization': 'Bearer foo_token'} if authenticated else {}
-                    with self.assertLogs(logger=log, level=level) as logs:
-                        requests.get(str(url), headers=request_headers)
-                    logs = [(r.levelno, r.getMessage()) for r in logs.records]
-                    request_headers = {
-                        'host': url.netloc,
-                        'user-agent': 'python-requests/2.32.3',
-                        'accept-encoding': 'gzip, deflate, br',
-                        'accept': '*/*',
-                        'connection': 'keep-alive',
-                        **request_headers,
-                    }
-                    response_headers = {
-                        'Access-Control-Allow-Origin': '*',
-                        'Access-Control-Allow-Headers': 'Authorization,'
-                                                        'Content-Type,'
-                                                        'X-Amz-Date,'
-                                                        'X-Amz-Security-Token,'
-                                                        'X-Api-Key',
-                        **AzulChaliceApp.security_headers(),
-                        'Cache-Control': 'no-store'
-                    }
-                    self.assertEqual(logs, [
-                        (
-                            INFO,
-                            "Received GET request for '/health/basic', "
-                            f'with {json.dumps(dict(query=None, headers=request_headers))}.'),
-                        (
-                            INFO,
-                            "Authenticated request as OAuth2(access_token='foo_token')"
-                            if authenticated else
-                            'Did not authenticate request.'
-                        ),
-                        (
-                            level,
-                            'Returning 200 response. To log headers and body, set AZUL_DEBUG to 1.'
-                            if level == INFO else
-                            'Returning 200 response with headers ' +
-                            json.dumps(response_headers) + '. ' +
-                            'See next line for the first 1024 characters of the body.\n' +
-                            '{"up": true}'
+                    if request_body:
+                        request_body = json.dumps({'filters': json.dumps({'organ': {'is': ['foo']}})})
+                        request_headers = {
+                            'content-length': str(len(request_body)),
+                            'content-type': 'application/json',
+                            **request_headers,
+                        }
+                    with self.subTest(azul_debug=azul_debug,
+                                      authenticated=authenticated,
+                                      request_body=request_body):
+                        with self.assertLogs(logger=log, level=level) as logs:
+                            debug = PropertyMock(return_value=azul_debug)
+                            with patch.object(Config, 'debug', new=debug):
+                                with patch.object(logging, 'http_body_log_prefix_len', 128):
+                                    json_body = json.loads(request_body) if request_body else None
+                                    response = requests.get(str(url), headers=request_headers, json=json_body)
+                        logs = [(r.levelno, r.getMessage()) for r in logs.records]
+                        last_log_level, last_log = logs.pop()  # … to validate separately
+                        request_headers = {
+                            'host': url.netloc,
+                            'user-agent': 'python-requests/2.32.3',
+                            'accept-encoding': 'gzip, deflate, br',
+                            'accept': '*/*',
+                            'connection': 'keep-alive',
+                            **request_headers,
+                        }
+                        response_headers = {
+                            'Access-Control-Allow-Origin': '*',
+                            'Access-Control-Allow-Headers': 'Authorization,'
+                                                            'Content-Type,'
+                                                            'X-Amz-Date,'
+                                                            'X-Amz-Security-Token,'
+                                                            'X-Api-Key',
+                            **AzulChaliceApp.security_headers(),
+                            'Cache-Control': 'no-store'
+                        }
+                        self.assertEqual(logs, [
+                            (
+                                INFO,
+                                f"Received GET request for '/index/projects', "
+                                f'with {json.dumps(dict(query=None, headers=request_headers))}.'
+                            ),
+                            (
+                                INFO,
+                                '… without request body'
+                            ) if not request_body else
+                            (
+                                INFO,
+                                '… with request body size of 47 bytes'
+                            ) if azul_debug == 0 else
+                            (
+                                DEBUG,
+                                f'… with {"first 128/" if azul_debug == 1 else "all "}47 bytes of the request '
+                                f'body {request_body!r}'
+                            ),
+                            (
+                                INFO,
+                                "Authenticated request as OAuth2(access_token='foo_token')"
+                                if authenticated else
+                                'Did not authenticate request.'
+                            ),
+                            (
+                                INFO,
+                                f'Returning 200 response with headers {json.dumps(response_headers)}.'
+                            ),
+                        ])
+                        expected_body = json.dumps(
+                            {
+                                'pagination': {
+                                    'count': 1,
+                                    'total': 1,
+                                    'size': 10,
+                                    'next': None,
+                                    'previous': None,
+                                    'pages': 1,
+                                    'sort': 'projectTitle',
+                                    'order': 'asc'
+                                }
+                            }
                         )
-                    ])
+                        if azul_debug == 0:
+                            self.assertEqual(last_log,
+                                             '… with response body size of 9102 bytes')
+                        elif azul_debug == 1:
+                            self.assertEqual(last_log,
+                                             f'… with first 128/9102 bytes of the response body '
+                                             f'{trunc_ellipses(expected_body, max_len=128)!r}')
+                        elif azul_debug > 1:
+                            self.assertTrue(last_log.startswith(
+                                f"… with all 9102 bytes of the response body \'{expected_body[:130]}"))
+                        else:
+                            assert False
+                        self.assertEqual(level, last_log_level)
+                        self.assertEqual(200, response.status_code)