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

[dan-fernandes]

Logs now have status code. Logs now have request and response bodies as attributes to log record (accessible via Graylog). Logs now look prettier.

Example:

$ blueapi serve
2026-01-28 15:11:32,869     INFO numexpr.utils Note: NumExpr detected 22 cores but "NUMEXPR_MAX_THREADS" not set, so enforcing safe limit of 16.
2026-01-28 15:11:32,869     INFO numexpr.utils NumExpr defaulting to 16 threads.
2026-01-28 15:11:33,325     INFO uvicorn.error Started server process [123565]
2026-01-28 15:11:33,325     INFO uvicorn.error Waiting for application startup.
Authorization required, but no authorization protocol specified

2026-01-28 15:11:35,649     INFO blueapi.worker.task_worker Setting up event loop
2026-01-28 15:11:35,649     INFO blueapi.worker.task_worker Worker starting
2026-01-28 15:11:35,649     INFO blueapi.worker.task_worker Worker starting
2026-01-28 15:11:35,650     INFO blueapi.worker.task_worker Awaiting task
2026-01-28 15:11:35,650     INFO uvicorn.error Application startup complete.
2026-01-28 15:11:35,652     INFO uvicorn.error Uvicorn running on http://localhost:8000 (Press CTRL+C to quit)
2026-01-28 15:11:39,311     INFO blueapi.service.main 127.0.0.1 GET /docs 200
2026-01-28 15:11:39,456     INFO blueapi.service.main 127.0.0.1 GET /openapi.json 200
2026-01-28 15:11:43,824     INFO blueapi.service.main 127.0.0.1 GET /plans 200
2026-01-28 15:11:50,157     INFO blueapi.service.main 127.0.0.1 POST /tasks 422

[keithralphs]

The response body could be massive (in theory), this is why the FastAPI tracing does not set it as an attribute by default, rather they recommend truncating it when manually adding it to the trace, if it is over a certain length. So it could be useful to add this modality, possibly as a selectable option that defaults to truncate=true as there may legitimately be times when you want to see the whole response to a particular request in the log.

[codecov]

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 95.02%. Comparing base (1ed54e1) to head (610f0a1).

Additional details and impacted files

@@           Coverage Diff           @@
##             main    #1358   +/-   ##
=======================================
  Coverage   95.01%   95.02%           
=======================================
  Files          43       43           
  Lines        2768     2773    +5     
=======================================
+ Hits         2630     2635    +5     
  Misses        138      138           

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:

• ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

[tpoliaw]

Could we add some logging (possibly at debug?) when the request is received as well? Running a plan with this logging now gives something like

INFO blueapi.service.main 127.0.0.1 POST /tasks 201
... Load of logging from a plan starting, requests to tiled etc ...
INFO blueapi.service.main 127.0.0.1 PUT /worker/task 200

where the plan appears to start before the request that started it.

Making the client section of the message into host:port could be useful as well. The port isn't guaranteed to be unique but a clash is pretty unlikely for consecutive requests so it'd give some correlation for the two log events. The first one could just be the client/method/endpoint without the body.