feat: add an opt-in structured access log to FastAPI - #241
Merged
Merged
Conversation
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Closes #180.
FastAPI was the only supported framework whose logging instrument bound nothing framework-specific:
instruments_typeslisted the baseLoggingInstrument, while Litestar, FastStream and FastMCP eachship a subclass. This fills that cell with
FastAPILoggingInstrument, which installs an access-logmiddleware when asked.
fastapi_logging_middleware_enableddefaults toFalse, matchinglitestar_logging_middleware_enabled.FastMCP is currently the outlier and is being brought into line in #240.
Why off by default
The issue says "a FastAPI service gets structlog configured process-wide and no structured access
log, while a Litestar service gets both". A Litestar service gets an access log only if it sets
litestar_logging_middleware_enabled=True, so parity means shipping an opt-in one.Two reasons beyond parity:
logging_unset_handlersdefaults toempty. On by default would hand every FastAPI service two lines per request, one structured and one
not. The docs show
logging_unset_handlers=["uvicorn.access"]for anyone who wants only ours.LoggingInstrumentmeasures at+0.1 µs/request while nothing logs; an always-on access log makes every request log. A default that
multiplies log volume and per-request cost on upgrade is not one a bootstrapper should pick.
What it logs
One
http_requestline to thehttp.accesslogger:method,path,content_type,path_paramsand
status_codeunderhttp, plusdurationin nanoseconds. Litestar's hardened field set plus theduration FastMCP logs. A request that raises logs at exception level and re-raises unchanged, with
status_code: None, because the middleware sits insideServerErrorMiddlewareand sees the raisebefore anything turns it into a 500.
Bodies are never read. That is the defect Litestar's own middleware shipped (
54c8ad9), and #180 asksfor it to be pinned rather than asserted in prose, so the invariant test pins the field set: adding
headers,cookiesor a body later fails the test rather than passing a secret-absence check.Pure ASGI, and a correction
The middleware is pure ASGI rather than
BaseHTTPMiddleware. My first draft justified that with theusual claim that
BaseHTTPMiddlewarebreaks streaming responses and background tasks. That isfalse on the declared starlette range: I checked at the 0.37.2 floor and at 1.6.0, and both work.
The real reason is cost.
BaseHTTPMiddlewarebuilds a task group and a pair of memory object streamsper request, measured at over +150 µs per request in the benchmarks' own in-process harness,
against a pure-ASGI wrapper that stays within noise of no middleware at all. That is more than the
entire OpenTelemetry instrument, for a middleware that needs only the status code and the scope.
(Run-to-run variance was wide, +154 to +303 µs, so that is a floor rather than a figure.)
Shared path policy
_build_excluded_pathsis hoisted ontoLoggingInstrumentrather than copied. My first version wasline-for-line identical to Litestar's; ADR-0002's warning is against spreading policy across sibling
configs, while hoisting into the base instrument is what it prescribes ("base instruments own the
hoisted logic"). The base reads sibling paths through
getattr, the defensive read that ADR alreadyblesses for
_build_excluded_urls, and Litestar keeps only itsre.escapeanchoring. A test pinsevery sibling path in the built set, which is the rename guard ADR-0002 asks for.
Testing
Ten tests. Reverting only
fastapi_bootstrapper.pytomainbreaks nine of them.They assert against a patched
fastapi_access_loggerrather than captured stdout orlogging_extra_processors. Neither of those is sound here:_configure_foreign_loggers(
logging_instrument.py:181) registerslogging_extra_processorsa second time inside the roothandler's
ProcessorFormatter, so a capture sees either the event dict or the already-rendered JSONstring depending on what an earlier bootstrap left in structlog's global configuration. Three tests
passed alone and failed in a group until that was understood; the reason is in a docstring so it is
not rediscovered.
Covered: off by default, the full field set when enabled, the no-bodies invariant, all four excluded
paths, a lookalike path (
/custom-healthy) that must still be logged, every sibling path reaching theexclusion set, and the raising request.
319 tests,
ruff,ty,mkdocs build --strictand lychee all clean.Beyond the issue text
The config and integration docs are required by a new public field. The paragraph added to the
Performance page is the most arguable: that page exists to say what each instrument costs, and this
adds an opt-in per-request cost, so leaving it out would make the page incomplete.
No ADR: one was drafted and dropped on review. The reasoning for the default and for the pure-ASGI
choice lives here instead.