From 34e233bdb46caf5e89ac6657d3008868ff34d69e Mon Sep 17 00:00:00 2001 From: Daniel Fernandes Date: Wed, 28 Jan 2026 13:37:51 +0000 Subject: [PATCH 01/20] Add log_response_details middleware --- src/blueapi/service/main.py | 21 ++++++++++++++++++++- 1 file changed, 20 insertions(+), 1 deletion(-) diff --git a/src/blueapi/service/main.py b/src/blueapi/service/main.py index 9711f2005..ed1b70388 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,6 +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_response_details) app.middleware("http")(log_request_details) if config.api.cors: app.add_middleware( @@ -607,6 +609,23 @@ async def log_request_details( return response +async def log_response_details( + request: Request, call_next: Callable[[Request], Awaitable[StreamingResponse]] +) -> Response: + response = await call_next(request) + + response_body = [section async for section in response.body_iterator] + response.body_iterator = iterate_in_threadpool(iter(response_body)) + + msg = f"Response body: {response_body}" + if request.url.path == "/healthz": + LOGGER.debug(msg) + else: + LOGGER.info(msg) + + return response + + async def inject_propagated_observability_context( request: Request, call_next: Callable[[Request], Awaitable[Response]] ) -> Response: From 25b4f8a2724a7d299f6dd9ae713ad7de35190119 Mon Sep 17 00:00:00 2001 From: Daniel Fernandes Date: Wed, 28 Jan 2026 13:43:20 +0000 Subject: [PATCH 02/20] Fix log statement, add comment --- src/blueapi/service/main.py | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/blueapi/service/main.py b/src/blueapi/service/main.py index ed1b70388..9dfcc12c0 100644 --- a/src/blueapi/service/main.py +++ b/src/blueapi/service/main.py @@ -600,7 +600,8 @@ async def add_api_version_header( 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()}" + msg = f"Request method: {request.method} url: {request.url} \ + body: {await request.body()}" if request.url.path == "/healthz": LOGGER.debug(msg) else: @@ -614,6 +615,7 @@ async def log_response_details( ) -> Response: response = await call_next(request) + # https://github.com/Kludex/starlette/issues/874#issuecomment-1027743996 response_body = [section async for section in response.body_iterator] response.body_iterator = iterate_in_threadpool(iter(response_body)) From b51e5352d79c7d42fd5c128a2b504b3c656f353e Mon Sep 17 00:00:00 2001 From: Daniel Fernandes Date: Wed, 28 Jan 2026 14:40:27 +0000 Subject: [PATCH 03/20] Aggregate response and request logs into single log --- src/blueapi/service/main.py | 28 +++++++++++----------------- 1 file changed, 11 insertions(+), 17 deletions(-) diff --git a/src/blueapi/service/main.py b/src/blueapi/service/main.py index 9dfcc12c0..f125c56b6 100644 --- a/src/blueapi/service/main.py +++ b/src/blueapi/service/main.py @@ -155,7 +155,6 @@ 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_response_details) app.middleware("http")(log_request_details) if config.api.cors: app.add_middleware( @@ -598,19 +597,6 @@ async def add_api_version_header( async def log_request_details( - request: Request, call_next: Callable[[Request], Awaitable[Response]] -) -> Response: - msg = f"Request 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 - - -async def log_response_details( request: Request, call_next: Callable[[Request], Awaitable[StreamingResponse]] ) -> Response: response = await call_next(request) @@ -619,11 +605,19 @@ async def log_response_details( response_body = [section async for section in response.body_iterator] response.body_iterator = iterate_in_threadpool(iter(response_body)) - msg = f"Response body: {response_body}" + msg = ( + f"{getattr(request.client, 'host', 'NO_ADDRESS')} {request.method}" + f" {request.url.path} {response.status_code}" + ) + + extra = { + "request_body": request.body, + "response_body": response_body, + } if request.url.path == "/healthz": - LOGGER.debug(msg) + LOGGER.debug(msg, extra=extra) else: - LOGGER.info(msg) + LOGGER.info(msg, extra=extra) return response From 128a1f89954af26c2ab17986e4443bc5c12dfe59 Mon Sep 17 00:00:00 2001 From: Daniel Fernandes Date: Wed, 28 Jan 2026 15:10:25 +0000 Subject: [PATCH 04/20] Fix placement of request body consumption --- src/blueapi/service/main.py | 10 ++++++---- 1 file changed, 6 insertions(+), 4 deletions(-) diff --git a/src/blueapi/service/main.py b/src/blueapi/service/main.py index f125c56b6..c3f6dff2d 100644 --- a/src/blueapi/service/main.py +++ b/src/blueapi/service/main.py @@ -599,25 +599,27 @@ async def add_api_version_header( async def log_request_details( request: Request, call_next: Callable[[Request], Awaitable[StreamingResponse]] ) -> Response: + request_body = await request.body() + response = await call_next(request) # https://github.com/Kludex/starlette/issues/874#issuecomment-1027743996 response_body = [section async for section in response.body_iterator] response.body_iterator = iterate_in_threadpool(iter(response_body)) - msg = ( + log_message = ( f"{getattr(request.client, 'host', 'NO_ADDRESS')} {request.method}" f" {request.url.path} {response.status_code}" ) extra = { - "request_body": request.body, + "request_body": request_body, "response_body": response_body, } if request.url.path == "/healthz": - LOGGER.debug(msg, extra=extra) + LOGGER.debug(log_message, extra=extra) else: - LOGGER.info(msg, extra=extra) + LOGGER.info(log_message, extra=extra) return response From 659381017f122488e36cb5d98aa9730a400951d9 Mon Sep 17 00:00:00 2001 From: Daniel Fernandes Date: Wed, 28 Jan 2026 15:10:37 +0000 Subject: [PATCH 05/20] Fix logging test --- tests/unit_tests/service/test_main.py | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/tests/unit_tests/service/test_main.py b/tests/unit_tests/service/test_main.py index 92d7cd414..d31ae3b66 100644 --- a/tests/unit_tests/service/test_main.py +++ b/tests/unit_tests/service/test_main.py @@ -22,7 +22,11 @@ async def root(): assert response.status_code == 200 logger.info.assert_called_once_with( - "method: GET url: http://testserver/ body: b''" + "testclient GET / 200", + extra={ + "request_body": b"", + "response_body": [b'{"message":"Hello World"}'], + }, ) From 46738e18bd4c5bed002817f029ec63d58db98052 Mon Sep 17 00:00:00 2001 From: Daniel Fernandes Date: Wed, 28 Jan 2026 15:21:30 +0000 Subject: [PATCH 06/20] Add docstring --- src/blueapi/service/main.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/src/blueapi/service/main.py b/src/blueapi/service/main.py index c3f6dff2d..90dd0a950 100644 --- a/src/blueapi/service/main.py +++ b/src/blueapi/service/main.py @@ -599,6 +599,8 @@ async def add_api_version_header( async def log_request_details( 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) From 610f0a108486770021dc1629eda98a3dbbd5f4d5 Mon Sep 17 00:00:00 2001 From: Daniel Fernandes Date: Wed, 28 Jan 2026 15:29:50 +0000 Subject: [PATCH 07/20] Make log test endpoint a POST --- tests/unit_tests/service/test_main.py | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/tests/unit_tests/service/test_main.py b/tests/unit_tests/service/test_main.py index d31ae3b66..2a7e8cb65 100644 --- a/tests/unit_tests/service/test_main.py +++ b/tests/unit_tests/service/test_main.py @@ -13,18 +13,18 @@ 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( - "testclient GET / 200", + "testclient POST / 200", extra={ - "request_body": b"", + "request_body": b"foo", "response_body": [b'{"message":"Hello World"}'], }, ) From 5d10315ef984db4f75664a17890164c574bc1028 Mon Sep 17 00:00:00 2001 From: Daniel Fernandes Date: Fri, 13 Feb 2026 15:11:49 +0000 Subject: [PATCH 08/20] Make request and reponse bodies truncateable --- helm/blueapi/README.md | 5 ++- helm/blueapi/values.schema.json | 4 ++ helm/blueapi/values.yaml | 2 + src/blueapi/config.py | 1 + src/blueapi/service/main.py | 66 ++++++++++++++++++++------------- 5 files changed, 51 insertions(+), 27 deletions(-) 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 6b653e693..1cbcd38ad 100644 --- a/src/blueapi/service/main.py +++ b/src/blueapi/service/main.py @@ -155,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, @@ -595,34 +595,50 @@ async def add_api_version_header( return response -async def log_request_details( - 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) +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}" + ) - # https://github.com/Kludex/starlette/issues/874#issuecomment-1027743996 - response_body = [section async for section in response.body_iterator] - response.body_iterator = iterate_in_threadpool(iter(response_body)) + if truncate_bodies: + request_body = request_body[:1024] + response_body = response_body[:1024] - log_message = ( - f"{getattr(request.client, 'host', 'NO_ADDRESS')} {request.method}" - f" {request.url.path} {response.status_code}" - ) + 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) - 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 response + return inner async def inject_propagated_observability_context( From 32b5587971f0b4121ac6c00b89b7e05de460ec76 Mon Sep 17 00:00:00 2001 From: Daniel Fernandes Date: Tue, 17 Feb 2026 11:00:03 +0000 Subject: [PATCH 09/20] Update config schema --- helm/blueapi/config_schema.json | 5 +++++ helm/blueapi/values.schema.json | 5 +++++ 2 files changed, 10 insertions(+) diff --git a/helm/blueapi/config_schema.json b/helm/blueapi/config_schema.json index d54bc5357..cb151e550 100644 --- a/helm/blueapi/config_schema.json +++ b/helm/blueapi/config_schema.json @@ -248,6 +248,11 @@ "title": "Level", "type": "string" }, + "truncate_bodies": { + "default": true, + "title": "Truncate Bodies", + "type": "boolean" + }, "graylog": { "$ref": "GraylogConfig", "default": { diff --git a/helm/blueapi/values.schema.json b/helm/blueapi/values.schema.json index 16d77fae1..3049dd9d9 100644 --- a/helm/blueapi/values.schema.json +++ b/helm/blueapi/values.schema.json @@ -683,6 +683,11 @@ "ERROR", "CRITICAL" ] + }, + "truncate_bodies": { + "title": "Truncate Bodies", + "default": true, + "type": "boolean" } }, "additionalProperties": false From 216eb86e7af57dc763b01ba4cbabd045ed88c823 Mon Sep 17 00:00:00 2001 From: Daniel Fernandes Date: Tue, 17 Feb 2026 14:49:32 +0000 Subject: [PATCH 10/20] Add alias to LoggingConfig.truncate_bodies --- src/blueapi/config.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/blueapi/config.py b/src/blueapi/config.py index 629591434..80169c480 100644 --- a/src/blueapi/config.py +++ b/src/blueapi/config.py @@ -152,7 +152,7 @@ class GraylogConfig(BlueapiBaseModel): class LoggingConfig(BlueapiBaseModel): level: LogLevel = "INFO" - truncate_bodies: bool = True + truncate_bodies: bool = Field(default=True, alias="truncateBodies") graylog: GraylogConfig = GraylogConfig() From cb00ae2ef8d501ad172cc60f294e0d527bc4c9cd Mon Sep 17 00:00:00 2001 From: Daniel Fernandes Date: Tue, 17 Feb 2026 14:50:13 +0000 Subject: [PATCH 11/20] Update helm and config schemas --- helm/blueapi/config_schema.json | 4 ++-- helm/blueapi/values.schema.json | 4 ++-- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/helm/blueapi/config_schema.json b/helm/blueapi/config_schema.json index cb151e550..09dc4e15d 100644 --- a/helm/blueapi/config_schema.json +++ b/helm/blueapi/config_schema.json @@ -248,9 +248,9 @@ "title": "Level", "type": "string" }, - "truncate_bodies": { + "truncateBodies": { "default": true, - "title": "Truncate Bodies", + "title": "Truncatebodies", "type": "boolean" }, "graylog": { diff --git a/helm/blueapi/values.schema.json b/helm/blueapi/values.schema.json index 3049dd9d9..ba785f30f 100644 --- a/helm/blueapi/values.schema.json +++ b/helm/blueapi/values.schema.json @@ -684,8 +684,8 @@ "CRITICAL" ] }, - "truncate_bodies": { - "title": "Truncate Bodies", + "truncateBodies": { + "title": "Truncatebodies", "default": true, "type": "boolean" } From 1ce51310714edfba1ca25a2909dddba3d31b96a2 Mon Sep 17 00:00:00 2001 From: Daniel Fernandes Date: Fri, 20 Feb 2026 10:46:07 +0000 Subject: [PATCH 12/20] Remove log body truncation --- helm/blueapi/config_schema.json | 5 ----- helm/blueapi/values.schema.json | 5 ----- src/blueapi/config.py | 1 - src/blueapi/service/main.py | 9 ++------- 4 files changed, 2 insertions(+), 18 deletions(-) diff --git a/helm/blueapi/config_schema.json b/helm/blueapi/config_schema.json index 09dc4e15d..d54bc5357 100644 --- a/helm/blueapi/config_schema.json +++ b/helm/blueapi/config_schema.json @@ -248,11 +248,6 @@ "title": "Level", "type": "string" }, - "truncateBodies": { - "default": true, - "title": "Truncatebodies", - "type": "boolean" - }, "graylog": { "$ref": "GraylogConfig", "default": { diff --git a/helm/blueapi/values.schema.json b/helm/blueapi/values.schema.json index 93ff00d0a..ef6ff8f96 100644 --- a/helm/blueapi/values.schema.json +++ b/helm/blueapi/values.schema.json @@ -687,11 +687,6 @@ "ERROR", "CRITICAL" ] - }, - "truncateBodies": { - "title": "Truncatebodies", - "default": true, - "type": "boolean" } }, "additionalProperties": false diff --git a/src/blueapi/config.py b/src/blueapi/config.py index 2104f8d8e..6f0ca4ae7 100644 --- a/src/blueapi/config.py +++ b/src/blueapi/config.py @@ -152,7 +152,6 @@ class GraylogConfig(BlueapiBaseModel): class LoggingConfig(BlueapiBaseModel): level: LogLevel = "INFO" - truncate_bodies: bool = Field(default=True, alias="truncateBodies") graylog: GraylogConfig = GraylogConfig() diff --git a/src/blueapi/service/main.py b/src/blueapi/service/main.py index 0a0d91295..e2ca27812 100644 --- a/src/blueapi/service/main.py +++ b/src/blueapi/service/main.py @@ -125,7 +125,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(config.logging.truncate_bodies)) + app.middleware("http")(log_request_details()) if config.api.cors: app.add_middleware( CORSMiddleware, @@ -576,7 +576,7 @@ async def add_api_version_header( return response -def log_request_details(truncate_bodies: bool): +def log_request_details(): async def inner( request: Request, call_next: Callable[[Request], Awaitable[StreamingResponse]] ) -> Response: @@ -603,11 +603,6 @@ async def inner( 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, From d031fc5a30f60ed9b14968e30d9ce6df553f5126 Mon Sep 17 00:00:00 2001 From: Daniel Fernandes Date: Fri, 20 Feb 2026 10:49:45 +0000 Subject: [PATCH 13/20] Remove truncateBodies frm values --- helm/blueapi/README.md | 6 +++--- helm/blueapi/values.schema.json | 5 +---- helm/blueapi/values.yaml | 1 - 3 files changed, 4 insertions(+), 8 deletions(-) diff --git a/helm/blueapi/README.md b/helm/blueapi/README.md index 651c72ba6..068dbdbfe 100644 --- a/helm/blueapi/README.md +++ b/helm/blueapi/README.md @@ -48,10 +48,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","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 | 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.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","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.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.graylog | object | `{"enabled":false,"url":"tcp://graylog-log-target.diamond.ac.uk:12231/"}` | 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 ef6ff8f96..9e247124a 100644 --- a/helm/blueapi/values.schema.json +++ b/helm/blueapi/values.schema.json @@ -385,6 +385,7 @@ "type": "object", "properties": { "graylog": { + "description": "Whether to truncate request and response bodies, which can be arbitrarily large", "type": "object", "properties": { "enabled": { @@ -397,10 +398,6 @@ }, "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 d3d82348a..474db676f 100644 --- a/helm/blueapi/values.yaml +++ b/helm/blueapi/values.yaml @@ -206,7 +206,6 @@ worker: 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/ From 00472178add7322c2559fa4b060517cfc2234f8d Mon Sep 17 00:00:00 2001 From: Daniel Fernandes Date: Fri, 20 Feb 2026 10:51:40 +0000 Subject: [PATCH 14/20] Make log_request_details its own middleware, rather than factory --- src/blueapi/service/main.py | 73 ++++++++++++++++++------------------- 1 file changed, 35 insertions(+), 38 deletions(-) diff --git a/src/blueapi/service/main.py b/src/blueapi/service/main.py index e2ca27812..3f40e9861 100644 --- a/src/blueapi/service/main.py +++ b/src/blueapi/service/main.py @@ -125,7 +125,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) if config.api.cors: app.add_middleware( CORSMiddleware, @@ -576,45 +576,42 @@ async def add_api_version_header( return response -def log_request_details(): - 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}" - ) - 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) +async def log_request_details( + 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() - return response + response = await call_next(request) - return inner + # 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}" + ) + 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 async def inject_propagated_observability_context( From bd87cd0b7a978b6223887e9471e8ca4e3b3661eb Mon Sep 17 00:00:00 2001 From: Daniel Fernandes Date: Fri, 20 Feb 2026 10:53:16 +0000 Subject: [PATCH 15/20] No longer log response body --- src/blueapi/service/main.py | 17 +---------------- tests/unit_tests/service/test_main.py | 1 - 2 files changed, 1 insertion(+), 17 deletions(-) diff --git a/src/blueapi/service/main.py b/src/blueapi/service/main.py index 3f40e9861..e30966d0a 100644 --- a/src/blueapi/service/main.py +++ b/src/blueapi/service/main.py @@ -16,7 +16,6 @@ Response, status, ) -from fastapi.concurrency import iterate_in_threadpool from fastapi.middleware.cors import CORSMiddleware from fastapi.responses import RedirectResponse, StreamingResponse from fastapi.security import OAuth2AuthorizationCodeBearer @@ -580,31 +579,17 @@ async def log_request_details( request: Request, call_next: Callable[[Request], Awaitable[StreamingResponse]] ) -> Response: """Middleware to log all request's host, method, path, status and request and - response bodies""" + body""" 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}" ) extra = { "request_body": request_body, - "response_body": response_body, } if request.url.path == "/healthz": LOGGER.debug(log_message, extra=extra) diff --git a/tests/unit_tests/service/test_main.py b/tests/unit_tests/service/test_main.py index 2a7e8cb65..43a072b55 100644 --- a/tests/unit_tests/service/test_main.py +++ b/tests/unit_tests/service/test_main.py @@ -25,7 +25,6 @@ async def root(): "testclient POST / 200", extra={ "request_body": b"foo", - "response_body": [b'{"message":"Hello World"}'], }, ) From 4e045986a2397daa8a4b45824ad56f5615abd2c3 Mon Sep 17 00:00:00 2001 From: Daniel Fernandes Date: Fri, 20 Feb 2026 10:54:15 +0000 Subject: [PATCH 16/20] Remove old comment --- helm/blueapi/README.md | 1 - helm/blueapi/values.schema.json | 1 - helm/blueapi/values.yaml | 1 - 3 files changed, 3 deletions(-) diff --git a/helm/blueapi/README.md b/helm/blueapi/README.md index 068dbdbfe..fed02cfd4 100644 --- a/helm/blueapi/README.md +++ b/helm/blueapi/README.md @@ -52,6 +52,5 @@ A Helm chart deploying a worker pod that runs Bluesky plans | 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.graylog | object | `{"enabled":false,"url":"tcp://graylog-log-target.diamond.ac.uk:12231/"}` | 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 9e247124a..e439f285d 100644 --- a/helm/blueapi/values.schema.json +++ b/helm/blueapi/values.schema.json @@ -385,7 +385,6 @@ "type": "object", "properties": { "graylog": { - "description": "Whether to truncate request and response bodies, which can be arbitrarily large", "type": "object", "properties": { "enabled": { diff --git a/helm/blueapi/values.yaml b/helm/blueapi/values.yaml index 474db676f..6784f5847 100644 --- a/helm/blueapi/values.yaml +++ b/helm/blueapi/values.yaml @@ -205,7 +205,6 @@ 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 graylog: enabled: False url: tcp://graylog-log-target.diamond.ac.uk:12231/ From c34816205883ad506bfb3aff579c1a360070eda2 Mon Sep 17 00:00:00 2001 From: Daniel Fernandes Date: Fri, 20 Feb 2026 11:27:40 +0000 Subject: [PATCH 17/20] Add port to request log --- src/blueapi/service/main.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/blueapi/service/main.py b/src/blueapi/service/main.py index e30966d0a..de32461bb 100644 --- a/src/blueapi/service/main.py +++ b/src/blueapi/service/main.py @@ -16,6 +16,7 @@ Response, status, ) +from fastapi.datastructures import Address from fastapi.middleware.cors import CORSMiddleware from fastapi.responses import RedirectResponse, StreamingResponse from fastapi.security import OAuth2AuthorizationCodeBearer @@ -584,8 +585,10 @@ async def log_request_details( response = await call_next(request) + client = request.client or Address("Unknown", -1) + log_message = ( - f"{getattr(request.client, 'host', 'NO_ADDRESS')} {request.method}" + f"{client.host}:{client.port} {request.method}" f" {request.url.path} {response.status_code}" ) extra = { From 3a09940a8a6c0bb81fc8e8cfc5aba2dc66f8f398 Mon Sep 17 00:00:00 2001 From: Daniel Fernandes Date: Fri, 20 Feb 2026 11:30:37 +0000 Subject: [PATCH 18/20] Add request debug log in receive --- src/blueapi/service/main.py | 11 ++++------- 1 file changed, 4 insertions(+), 7 deletions(-) diff --git a/src/blueapi/service/main.py b/src/blueapi/service/main.py index de32461bb..243588f07 100644 --- a/src/blueapi/service/main.py +++ b/src/blueapi/service/main.py @@ -582,15 +582,12 @@ async def log_request_details( """Middleware to log all request's host, method, path, status and request and body""" request_body = await request.body() - - response = await call_next(request) - client = request.client or Address("Unknown", -1) + log_message = f"{client.host}:{client.port} {request.method}" + LOGGER.debug(log_message) - log_message = ( - f"{client.host}:{client.port} {request.method}" - f" {request.url.path} {response.status_code}" - ) + response = await call_next(request) + log_message += f" {request.url.path} {response.status_code}" extra = { "request_body": request_body, } From ade3d01f528f7420484fcda830e1d9e1a06dd292 Mon Sep 17 00:00:00 2001 From: Daniel Fernandes Date: Fri, 20 Feb 2026 11:34:04 +0000 Subject: [PATCH 19/20] Reformat debug log in request --- src/blueapi/service/main.py | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/blueapi/service/main.py b/src/blueapi/service/main.py index 243588f07..c79dd3df3 100644 --- a/src/blueapi/service/main.py +++ b/src/blueapi/service/main.py @@ -583,14 +583,14 @@ async def log_request_details( body""" request_body = await request.body() client = request.client or Address("Unknown", -1) - log_message = f"{client.host}:{client.port} {request.method}" - LOGGER.debug(log_message) - - response = await call_next(request) - log_message += f" {request.url.path} {response.status_code}" + log_message = f"{client.host}:{client.port} {request.method} {request.url.path}" extra = { "request_body": request_body, } + LOGGER.debug(log_message, extra=extra) + + response = await call_next(request) + log_message += f" {response.status_code}" if request.url.path == "/healthz": LOGGER.debug(log_message, extra=extra) else: From de2a5ee92c20b50cae23d8465c20a079fb2bcfcb Mon Sep 17 00:00:00 2001 From: Daniel Fernandes Date: Fri, 20 Feb 2026 11:34:11 +0000 Subject: [PATCH 20/20] Fix tests --- tests/unit_tests/service/test_main.py | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/tests/unit_tests/service/test_main.py b/tests/unit_tests/service/test_main.py index 43a072b55..2e109d38c 100644 --- a/tests/unit_tests/service/test_main.py +++ b/tests/unit_tests/service/test_main.py @@ -21,8 +21,15 @@ async def root(): response = client.post("/", content="foo") assert response.status_code == 200 + logger.debug.assert_called_once_with( + "testclient:50000 POST /", + extra={ + "request_body": b"foo", + }, + ) + logger.info.assert_called_once_with( - "testclient POST / 200", + "testclient:50000 POST / 200", extra={ "request_body": b"foo", },