diff --git a/helm/blueapi/README.md b/helm/blueapi/README.md index e4fe2c162..91c6b6b78 100644 --- a/helm/blueapi/README.md +++ b/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 | diff --git a/helm/blueapi/values.schema.json b/helm/blueapi/values.schema.json index 1578c0dad..16d77fae1 100644 --- a/helm/blueapi/values.schema.json +++ b/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" } } }, diff --git a/helm/blueapi/values.yaml b/helm/blueapi/values.yaml index ec6515921..22bc296b9 100644 --- a/helm/blueapi/values.yaml +++ b/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/ diff --git a/src/blueapi/config.py b/src/blueapi/config.py index 54baa500a..75aad7ba9 100644 --- a/src/blueapi/config.py +++ b/src/blueapi/config.py @@ -152,6 +152,7 @@ class GraylogConfig(BlueapiBaseModel): class LoggingConfig(BlueapiBaseModel): level: LogLevel = "INFO" + truncate_bodies: bool = True graylog: GraylogConfig = GraylogConfig() diff --git a/src/blueapi/service/main.py b/src/blueapi/service/main.py index 5aa44c533..1cbcd38ad 100644 --- a/src/blueapi/service/main.py +++ b/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( diff --git a/tests/unit_tests/service/test_main.py b/tests/unit_tests/service/test_main.py index 92d7cd414..2a7e8cb65 100644 --- a/tests/unit_tests/service/test_main.py +++ b/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"}'], + }, )