feat: Add Status Code and Request and Response Bodies to Logs

helm/blueapi/README.md

@@ -47,9 +47,10 @@ A Helm chart deploying a worker pod that runs Bluesky plans
 | tracing | object | `{"otlp":{"enabled":false,"protocol":"http/protobuf","server":{"host":"http://opentelemetry-collector.tracing","port":4318}}}` | Configure tracing: opentelemetry-collector.tracing should be available in all Diamond clusters |
 | volumeMounts | list | `[{"mountPath":"/config","name":"worker-config","readOnly":true}]` | Additional volumeMounts on the output StatefulSet definition. Define how volumes are mounted to the container referenced by using the same name. |
 | volumes | list | `[]` | Additional volumes on the output StatefulSet definition. Define volumes from e.g. Secrets, ConfigMaps or the Filesystem |
-| worker | object | `{"api":{"url":"http://0.0.0.0:8000/"},"env":{"sources":[{"kind":"planFunctions","module":"dodal.plans"},{"kind":"planFunctions","module":"dodal.plan_stubs.wrapped"}]},"logging":{"graylog":{"enabled":false,"url":"tcp://graylog-log-target.diamond.ac.uk:12231/"},"level":"INFO"},"scratch":{"repositories":[],"root":"/workspace"},"stomp":{"auth":{"password":"guest","username":"guest"},"enabled":false,"url":"tcp://rabbitmq:61613/"}}` | Config for the worker goes here, will be mounted into a config file |
+| worker | object | `{"api":{"url":"http://0.0.0.0:8000/"},"env":{"sources":[{"kind":"planFunctions","module":"dodal.plans"},{"kind":"planFunctions","module":"dodal.plan_stubs.wrapped"}]},"logging":{"graylog":{"enabled":false,"url":"tcp://graylog-log-target.diamond.ac.uk:12231/"},"level":"INFO","truncateBodies":true},"scratch":{"repositories":[],"root":"/workspace"},"stomp":{"auth":{"password":"guest","username":"guest"},"enabled":false,"url":"tcp://rabbitmq:61613/"}}` | Config for the worker goes here, will be mounted into a config file |
 | worker.api.url | string | `"http://0.0.0.0:8000/"` | 0.0.0.0 required to allow non-loopback traffic If using hostNetwork, the port must be free on the host |
 | worker.env.sources | list | `[{"kind":"planFunctions","module":"dodal.plans"},{"kind":"planFunctions","module":"dodal.plan_stubs.wrapped"}]` | modules (must be installed in the venv) to fetch devices/plans from |
-| worker.logging | object | `{"graylog":{"enabled":false,"url":"tcp://graylog-log-target.diamond.ac.uk:12231/"},"level":"INFO"}` | Configures logging. Port 12231 is the `dodal` input on graylog which will be renamed `blueapi` |
+| worker.logging | object | `{"graylog":{"enabled":false,"url":"tcp://graylog-log-target.diamond.ac.uk:12231/"},"level":"INFO","truncateBodies":true}` | Configures logging. Port 12231 is the `dodal` input on graylog which will be renamed `blueapi` |
+| worker.logging.truncateBodies | bool | `true` | Whether to truncate request and response bodies, which can be arbitrarily large |
 | worker.scratch | object | `{"repositories":[],"root":"/workspace"}` | If initContainer is enabled the default branch of python projects in this section are installed into the venv *without their dependencies* |
 | worker.stomp | object | `{"auth":{"password":"guest","username":"guest"},"enabled":false,"url":"tcp://rabbitmq:61613/"}` | Message bus configuration for returning status to GDA/forwarding documents downstream Password may be in the form ${ENV_VAR} to be fetched from an environment variable e.g. mounted from a SealedSecret |

helm/blueapi/values.schema.json

@@ -393,6 +393,10 @@
                         },
                         "level": {
                             "type": "string"
+                        },
+                        "truncateBodies": {
+                            "description": "Whether to truncate request and response bodies, which can be arbitrarily large",
+                            "type": "boolean"
                         }
                     }
                 },

helm/blueapi/values.yaml

@@ -205,6 +205,8 @@ worker:
   # -- Configures logging. Port 12231 is the `dodal` input on graylog which will be renamed `blueapi`
   logging:
     level: "INFO"
+    # -- Whether to truncate request and response bodies, which can be arbitrarily large
+    truncateBodies: True
     graylog:
       enabled: False
       url: tcp://graylog-log-target.diamond.ac.uk:12231/

src/blueapi/config.py

@@ -152,6 +152,7 @@ class GraylogConfig(BlueapiBaseModel):
 
 class LoggingConfig(BlueapiBaseModel):
     level: LogLevel = "INFO"
+    truncate_bodies: bool = True
     graylog: GraylogConfig = GraylogConfig()
 
 

src/blueapi/service/main.py

@@ -17,8 +17,9 @@
     Response,
     status,
 )
+from fastapi.concurrency import iterate_in_threadpool
 from fastapi.middleware.cors import CORSMiddleware
-from fastapi.responses import RedirectResponse
+from fastapi.responses import RedirectResponse, StreamingResponse
 from fastapi.security import OAuth2AuthorizationCodeBearer
 from observability_utils.tracing import (
     add_span_attributes,
@@ -154,7 +155,7 @@ def get_app(config: ApplicationConfig):
     app.add_exception_handler(jwt.PyJWTError, on_token_error_401)
     app.middleware("http")(add_api_version_header)
     app.middleware("http")(inject_propagated_observability_context)
-    app.middleware("http")(log_request_details)
+    app.middleware("http")(log_request_details(config.logging.truncate_bodies))
     if config.api.cors:
         app.add_middleware(
             CORSMiddleware,
@@ -594,16 +595,50 @@ async def add_api_version_header(
     return response
 
 
-async def log_request_details(
-    request: Request, call_next: Callable[[Request], Awaitable[Response]]
-) -> Response:
-    msg = f"method: {request.method} url: {request.url} body: {await request.body()}"
-    if request.url.path == "/healthz":
-        LOGGER.debug(msg)
-    else:
-        LOGGER.info(msg)
-    response = await call_next(request)
-    return response
+def log_request_details(truncate_bodies: bool):
+    async def inner(
+        request: Request, call_next: Callable[[Request], Awaitable[StreamingResponse]]
+    ) -> Response:
+        """Middleware to log all request's host, method, path, status and request and
+        response bodies"""
+        request_body = await request.body()
+
+        response = await call_next(request)
+
+        # https://github.com/Kludex/starlette/issues/874#issuecomment-1027743996
+        response_body_list = [section async for section in response.body_iterator]
+        response.body_iterator = iterate_in_threadpool(iter(response_body_list))
+
+        response_body = b""
+        for r in response_body_list:
+            if type(r) is bytes:
+                response_body += r
+            elif type(r) is str:
+                response_body += r.encode("utf-8")
+            elif type(r) is memoryview[int]:
+                response_body += bytes(r)
+
+        log_message = (
+            f"{getattr(request.client, 'host', 'NO_ADDRESS')} {request.method}"
+            f" {request.url.path} {response.status_code}"
+        )
+
+        if truncate_bodies:
+            request_body = request_body[:1024]
+            response_body = response_body[:1024]
+
+        extra = {
+            "request_body": request_body,
+            "response_body": response_body,
+        }
+        if request.url.path == "/healthz":
+            LOGGER.debug(log_message, extra=extra)
+        else:
+            LOGGER.info(log_message, extra=extra)
+
+        return response
+
+    return inner
 
 
 async def inject_propagated_observability_context(

tests/unit_tests/service/test_main.py

@@ -13,16 +13,20 @@ async def test_log_request_details():
         app = FastAPI()
         app.middleware("http")(log_request_details)
 
-        @app.get("/")
+        @app.post("/")
         async def root():
             return {"message": "Hello World"}
 
         client = TestClient(app)
-        response = client.get("/")
+        response = client.post("/", content="foo")
 
         assert response.status_code == 200
         logger.info.assert_called_once_with(
-            "method: GET url: http://testserver/ body: b''"
+            "testclient POST / 200",
+            extra={
+                "request_body": b"foo",
+                "response_body": [b'{"message":"Hello World"}'],
+            },
         )