Add Request ID Logging to a FastAPI App

The agent starts by reading how the app is assembled and how it logs today, because a request ID is only useful if every log line carries it. In an app like testdrivenio/fastapi-tdd-docker, project/app/main.py builds the app in create_application(), includes the ping router and the summaries router under /summaries, and calls init_db; app/config.py and app/db.py each take logging.getLogger("uvicorn") and log through it, so the app has no logger of its own and no log configuration. requirements.txt pins fastapi 0.115.12, uvicorn 0.34.1, gunicorn 22.0.0 and tortoise-orm 0.25.0. docker-compose.yml runs uvicorn app.main:app --reload --workers 1, and Dockerfile.prod runs gunicorn with uvicorn.workers.UvicornWorker, which means the uvicorn access log is what prints each request in both setups.

It also reads the parts that run outside a request handler. app/api/summaries.py queues generate_summary on BackgroundTasks after POST /summaries/, and that function in app/summarizer.py downloads an article and may fetch NLTK data, which is exactly the work a support engineer wants to tie to the request that started it. tests/conftest.py builds the app with TestClient and overrides get_settings, tests/test_summaries.py monkeypatches generate_summary, and Dockerfile.prod and .github/workflows/main.yml run flake8 with the 119-column limit from setup.cfg, black and isort, so any new module has to pass all three.

From that the agent adds project/app/request_id.py: a ContextVar holding the current ID, a pure ASGI middleware that reads X-Request-ID from the incoming request, accepts it when it is short and made of safe characters and otherwise generates a uuid4, sets the variable for the rest of the call, and adds the same X-Request-ID header to the response. Because the middleware wraps the whole ASGI call, the variable is still set while Starlette runs the background task after the response, so generate_summary logs with the right ID. A logging.Filter copies the variable into every record as request_id, with - when no request is active, and a dictConfig applied in create_application() gives the uvicorn, uvicorn.error and a new app logger one format that includes it. The uvicorn access line cannot carry the field, so the middleware logs its own line with method, path, status, duration and ID, and the compose command and the gunicorn command gain the flag that turns the uvicorn access log off.

Then it proves it. tests/test_request_id.py uses the existing test_app fixture: a request without the header gets a UUID back, a request with a valid header gets the same value back, an oversized or unsafe header is replaced, and with caplog a record logged inside a handler carries the ID while one logged before any request carries -. A test on POST /summaries/ with the monkeypatched generate_summary replaced by one that logs confirms the background task sees the ID. It runs pytest with the coverage flags from .coveragerc, flake8 ., black --check . and isort --check-only . the way Dockerfile.prod does, and fixes anything until all four pass.

What comes back is a pull request on its own branch with app/request_id.py, the middleware and logging setup in main.py, the two command changes in docker-compose.yml and Dockerfile.prod, and tests/test_request_id.py. The description documents the X-Request-ID contract, the validation rule for an incoming value, the log format with an example line, the - placeholder outside requests, and the fact that background tasks inherit the ID.

The transcript on the session keeps every command with its output: the pytest run with the new tests and the coverage summary, flake8, black --check, isort --check-only, and a docker compose up followed by curl calls showing the response header and the matching log lines, including one from the background task. The repository's own workflow runs on the pull request too, building the production image and running the same four checks inside the container.

Before merging, a reviewer checks that the log format is what the team's log pipeline parses, that the header name matches what the load balancer already injects so one ID spans the proxy and the app, that the access line does not duplicate anything the proxy logs, and that nothing sensitive from the URL lands in the line. One follow-up message to the same session switches the format to JSON if the pipeline prefers it.

A team that tracks operational work in Linear starts one run per issue from an automation with a linear trigger on the observability label. The automation adds the issue after this prompt, so the agent reads the header name and log format the issue asks for and starts in the repository the automation names.

Each run opens its own pull request from its own sandbox, and an automation run has its own max_runs_per_hour cap. The pull request links back to the issue, and the transcript holds the test run and the sample log lines for that change.

The subtle part of this job is the context: a request ID set in a middleware has to survive into the background task that runs after the response, show up in records from loggers the app did not create, and disappear cleanly when the request ends. Getting that wrong is invisible until someone reads logs in production. In a Rush sandbox the agent runs the real stack from the compose file, sends requests and reads the lines back, and the sandbox parks when the turn ends.

The pull request carries its own proof. The response header, the log lines with the same ID including the one from the background task, and the green lint and test runs are in the transcript beside the commands that produced them, so a reviewer can see the ID propagate rather than take a diagram's word for it.

Why a pure ASGI middleware instead of @app.middleware("http")?

Will it accept any X-Request-ID a client sends?

What happens to the uvicorn access log?

Does the background summary job log with the request's ID?