diff --git a/src/blueapi/service/main.py b/src/blueapi/service/main.py index aaaa66503..c79dd3df3 100644 --- a/src/blueapi/service/main.py +++ b/src/blueapi/service/main.py @@ -16,8 +16,9 @@ Response, status, ) +from fastapi.datastructures import Address 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, @@ -576,14 +577,25 @@ async def add_api_version_header( async def log_request_details( - request: Request, call_next: Callable[[Request], Awaitable[Response]] + request: Request, call_next: Callable[[Request], Awaitable[StreamingResponse]] ) -> Response: - msg = f"method: {request.method} url: {request.url} body: {await request.body()}" + """Middleware to log all request's host, method, path, status and request and + body""" + request_body = await request.body() + client = request.client or Address("Unknown", -1) + 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(msg) + LOGGER.debug(log_message, extra=extra) else: - LOGGER.info(msg) - response = await call_next(request) + LOGGER.info(log_message, extra=extra) + return response diff --git a/tests/unit_tests/service/test_main.py b/tests/unit_tests/service/test_main.py index 92d7cd414..2e109d38c 100644 --- a/tests/unit_tests/service/test_main.py +++ b/tests/unit_tests/service/test_main.py @@ -13,16 +13,26 @@ 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.debug.assert_called_once_with( + "testclient:50000 POST /", + extra={ + "request_body": b"foo", + }, + ) + logger.info.assert_called_once_with( - "method: GET url: http://testserver/ body: b''" + "testclient:50000 POST / 200", + extra={ + "request_body": b"foo", + }, )