From 2b815cce910300cd24047ee0fff14690194abe93 Mon Sep 17 00:00:00 2001 From: Artur Shiriev Date: Sun, 20 Sep 2026 15:25:57 +0300 Subject: [PATCH 1/3] feat: add an opt-in structured access log to FastAPI Closes #180 --- ...ss-logging-is-opt-in-on-every-framework.md | 24 ++++ docs/integrations/fastapi.md | 39 +++++++ docs/introduction/configuration.md | 9 ++ docs/introduction/performance.md | 5 + .../bootstrappers/fastapi_bootstrapper.py | 103 +++++++++++++++++- tests/test_fastapi_bootstrap.py | 85 +++++++++++++++ 6 files changed, 264 insertions(+), 1 deletion(-) create mode 100644 docs/adr/0009-access-logging-is-opt-in-on-every-framework.md diff --git a/docs/adr/0009-access-logging-is-opt-in-on-every-framework.md b/docs/adr/0009-access-logging-is-opt-in-on-every-framework.md new file mode 100644 index 0000000..f3b2926 --- /dev/null +++ b/docs/adr/0009-access-logging-is-opt-in-on-every-framework.md @@ -0,0 +1,24 @@ +# A structured access log is opt-in on every framework + +`fastapi_logging_middleware_enabled` defaults to `False`, matching +`litestar_logging_middleware_enabled`. FastMCP's `logging_turn_off_middleware` is the outlier and is +being brought into line separately (#240), so the rule is uniform: lite-bootstrap configures structlog +process-wide for every framework, and logs a line per request only when asked. + +Defaulting FastAPI's on was rejected for two reasons FastMCP does not have. uvicorn already writes an +access line per request and `logging_unset_handlers` defaults to empty, so an on-by-default access log +would give every FastAPI service two lines per request, one structured and one not, until it +discovered `logging_unset_handlers=["uvicorn.access"]`. And HTTP request rates are the highest of any +supported framework, so the cost lands where it is largest: `LoggingInstrument` measures at +0.1 +µs/request while nothing logs, and an always-on access log makes every request log, on a path where +Sentry's handlers alone cost ~12 µs per record when Sentry is enabled. A default that silently +multiplies log volume and per-request cost on upgrade is not one a bootstrapper should pick for its +users. + +The middleware is pure ASGI rather than `BaseHTTPMiddleware`, which buffers the response body and so +breaks streaming responses and background tasks. It wraps `send` to capture the status code, reads +`path_params` from the scope after routing has populated it, and logs metadata only: `method`, `path`, +`content_type`, `path_params`, `status_code` and `duration`. Bodies are never read, which is the +defect Litestar's own middleware shipped (`54c8ad9`) and the reason that framework's binding is +hardened rather than passed through; `tests/test_fastapi_bootstrap.py` pins the claim as an invariant +rather than leaving it to prose. diff --git a/docs/integrations/fastapi.md b/docs/integrations/fastapi.md index 44da1b2..5ca4c76 100644 --- a/docs/integrations/fastapi.md +++ b/docs/integrations/fastapi.md @@ -46,3 +46,42 @@ application = bootstrapper.bootstrap() ``` Read more about available configuration options [here](../introduction/configuration.md). + +## Logging + +Structlog is configured process-wide, so `structlog.get_logger()` works in any route handler. + +FastAPI has no access log of its own, so lite-bootstrap provides one. It is **off by default**, +because uvicorn already writes an access line per request and an HTTP service is the highest-volume +place to add a log record. Turn it on explicitly: + +```python +FastAPIConfig( + service_name="microservice", + fastapi_logging_middleware_enabled=True, +) +``` + +Enabled, it writes one `http_request` line per request to the `http.access` logger, carrying `method`, +`path`, `content_type`, `path_params` and `status_code` under `http`, plus `duration` in nanoseconds. +A request that raises is logged at exception level and the exception is re-raised unchanged. + +Request and response **bodies are never read or logged**. `path` and `path_params` are, so a secret +embedded in the URL itself (e.g. `/reset-password/{token}`) is recorded. Keep secrets in the request +body. + +These paths are skipped, whether or not the corresponding instrument is configured: `swagger_path`, +`swagger_static_path` (when `swagger_offline_docs` is on), `health_checks_path` and +`prometheus_metrics_path`. So if you disable health checks but still serve your own route at +`health_checks_path`, that route is not access-logged either. + +If you keep uvicorn's own access log as well, you will get two lines per request. To leave only the +structured one, clear uvicorn's handlers: + +```python +FastAPIConfig( + service_name="microservice", + fastapi_logging_middleware_enabled=True, + logging_unset_handlers=["uvicorn.access"], +) +``` diff --git a/docs/introduction/configuration.md b/docs/introduction/configuration.md index 95e3189..fe74989 100644 --- a/docs/introduction/configuration.md +++ b/docs/introduction/configuration.md @@ -246,6 +246,15 @@ Additional parameters for Litestar's access-log middleware: See [the Litestar integration guide](../integrations/litestar.md#logging) for what gets logged and why access logging defaults to off. +### Structlog FastAPI + +FastAPI ships no access log of its own, so lite-bootstrap provides one. It is **off by default**: + +- `fastapi_logging_middleware_enabled` - turn on the structured access log (default: `False`). + +See [the FastAPI integration guide](../integrations/fastapi.md#logging) for what gets logged and why +it defaults to off. + ### Structlog FastStream When using FastStream, the structlog logger is automatically injected into the broker so that all broker diff --git a/docs/introduction/performance.md b/docs/introduction/performance.md index 56330a7..4784a21 100644 --- a/docs/introduction/performance.md +++ b/docs/introduction/performance.md @@ -56,6 +56,11 @@ so there is nothing else material hiding in it. That configuration is: --8<-- "benchmarks/README.md:tuned" +One thing to leave off rather than turn on: the FastAPI access log +([`fastapi_logging_middleware_enabled`](../integrations/fastapi.md#logging)) is off by default, and +turning it on makes every request emit a log record. On a service that otherwise logs nothing per +request, that is the difference between the first row of the logging table above and the rest of it. + lite-bootstrap already applies one saving for you: it passes `sentry_logs_level=None` by default, because it never enables Sentry Logs and the handler formats every record before checking whether they are enabled. That one costs nothing, which is why it is a default rather than a knob. diff --git a/lite_bootstrap/bootstrappers/fastapi_bootstrapper.py b/lite_bootstrap/bootstrappers/fastapi_bootstrapper.py index f4a27db..7d12b67 100644 --- a/lite_bootstrap/bootstrappers/fastapi_bootstrapper.py +++ b/lite_bootstrap/bootstrappers/fastapi_bootstrapper.py @@ -1,5 +1,6 @@ import contextlib import dataclasses +import time import typing from lite_bootstrap import import_checker @@ -22,11 +23,19 @@ from lite_bootstrap.types import UNSET, UnsetType +if typing.TYPE_CHECKING: + from starlette.types import ASGIApp, Message, Receive, Scope, Send + if import_checker.is_fastapi_installed: import fastapi from fastapi.middleware.cors import CORSMiddleware from fastapi.routing import _merge_lifespan_context +if import_checker.is_structlog_installed: + import structlog + + fastapi_access_logger: typing.Final = structlog.get_logger("http.access") + if import_checker.is_opentelemetry_installed: from opentelemetry.trace import get_tracer_provider @@ -55,6 +64,7 @@ class FastAPIConfig( prometheus_instrumentator_params: dict[str, typing.Any] = dataclasses.field(default_factory=dict) prometheus_instrument_params: dict[str, typing.Any] = dataclasses.field(default_factory=dict) prometheus_expose_params: dict[str, typing.Any] = dataclasses.field(default_factory=dict) + fastapi_logging_middleware_enabled: bool = False def __post_init__(self) -> None: # @dataclass(slots=True) replaces the class object, breaking bare super(). @@ -83,6 +93,97 @@ def app(self) -> "fastapi.FastAPI": return self.application +class _AccessLogMiddleware: + """One structured line per request, pure ASGI. + + Not `BaseHTTPMiddleware`: that one buffers the response, which breaks streaming + responses and background tasks. + """ + + def __init__(self, app: "ASGIApp", *, excluded_paths: tuple[str, ...]) -> None: + self.app = app + self.excluded_paths = excluded_paths + + def _is_excluded(self, path: str) -> bool: + normalized_path = path.rstrip("/") + return any( + normalized_path == excluded_path or normalized_path.startswith(f"{excluded_path}/") + for excluded_path in self.excluded_paths + ) + + @staticmethod + def _http_fields(scope: "Scope", status_code: int) -> dict[str, typing.Any]: + content_type = "" + for header_name, header_value in scope.get("headers", ()): + if header_name == b"content-type": + content_type = header_value.decode("latin-1") + break + return { + "method": scope.get("method", ""), + "path": scope.get("path", ""), + "content_type": content_type, + "path_params": scope.get("path_params", {}), + "status_code": status_code, + } + + async def __call__(self, scope: "Scope", receive: "Receive", send: "Send") -> None: + if scope["type"] != "http" or self._is_excluded(scope["path"]): + await self.app(scope, receive, send) + return + + status_code = 0 + + async def send_wrapper(message: "Message") -> None: + nonlocal status_code + if message["type"] == "http.response.start": + status_code = message["status"] + await send(message) + + started_at = time.perf_counter_ns() + try: + await self.app(scope, receive, send_wrapper) + except Exception: + fastapi_access_logger.exception( + "http_request", + http=self._http_fields(scope, status_code), + duration=time.perf_counter_ns() - started_at, + ) + raise + fastapi_access_logger.info( + "http_request", + http=self._http_fields(scope, status_code), + duration=time.perf_counter_ns() - started_at, + ) + + +@dataclasses.dataclass(kw_only=True) +class FastAPILoggingInstrument(LoggingInstrument): + bootstrap_config: FastAPIConfig + + def _build_excluded_paths(self) -> tuple[str, ...]: + """Infrastructure routes not worth an access log line, normalized and deduplicated.""" + config = self.bootstrap_config + candidate_paths: typing.Final = ( + config.swagger_path, + config.swagger_static_path if config.swagger_offline_docs else "", + config.health_checks_path, + config.prometheus_metrics_path, + ) + excluded_paths: list[str] = [] + for candidate_path in candidate_paths: + # A bare "/" would exclude every route, so it is dropped along with empty values. + normalized_path = candidate_path.rstrip("/") + if normalized_path and normalized_path not in excluded_paths: + excluded_paths.append(normalized_path) + return tuple(excluded_paths) + + def bootstrap(self) -> None: + super().bootstrap() + if not self.bootstrap_config.fastapi_logging_middleware_enabled: + return + self.bootstrap_config.app.add_middleware(_AccessLogMiddleware, excluded_paths=self._build_excluded_paths()) + + @dataclasses.dataclass(kw_only=True, slots=True) class FastAPICorsInstrument(CorsInstrument): bootstrap_config: FastAPIConfig @@ -174,7 +275,7 @@ class FastAPIBootstrapper(BaseBootstrapper["fastapi.FastAPI"]): PyroscopeInstrument, SentryInstrument, FastAPIHealthChecksInstrument, - LoggingInstrument, + FastAPILoggingInstrument, FastAPIPrometheusInstrument, FastAPISwaggerInstrument, ] diff --git a/tests/test_fastapi_bootstrap.py b/tests/test_fastapi_bootstrap.py index cf4c7e9..554bf02 100644 --- a/tests/test_fastapi_bootstrap.py +++ b/tests/test_fastapi_bootstrap.py @@ -1,6 +1,8 @@ import dataclasses +import json import logging import typing +import uuid import warnings from unittest.mock import patch @@ -256,3 +258,86 @@ def test_missing_exporter_warning_points_at_the_bootstrap_call_site(fastapi_conf bootstrapper.teardown() assert warning_source_files(caught, InstrumentDependencyMissingWarning) == [__file__] + + +def _access_log_lines(stdout: str) -> list[dict[str, typing.Any]]: + """Every structlog line emitted by the access logger, parsed.""" + lines: list[dict[str, typing.Any]] = [] + for raw_line in stdout.splitlines(): + if '"logger":"http.access"' not in raw_line.replace(", ", ","): + continue + lines.append(json.loads(raw_line)) + return lines + + +def _bootstrap_with_route(config: FastAPIConfig) -> "fastapi.FastAPI": + bootstrapper = FastAPIBootstrapper(bootstrap_config=config) + application = bootstrapper.bootstrap() + + @application.post("/items/{item_id}") + async def create_item(item_id: str, payload: dict[str, typing.Any]) -> dict[str, typing.Any]: + return {"item_id": item_id, "echo": payload} + + return application + + +def test_fastapi_access_log_is_off_by_default( + fastapi_config: FastAPIConfig, capsys: pytest.CaptureFixture[str] +) -> None: + application = _bootstrap_with_route(fastapi_config) + with TestClient(application) as test_client: + test_client.post("/items/abc", json={"a": 1}) + + assert _access_log_lines(capsys.readouterr().out) == [] + + +def test_fastapi_access_log_records_the_request_when_enabled( + fastapi_config: FastAPIConfig, capsys: pytest.CaptureFixture[str] +) -> None: + config = dataclasses.replace(fastapi_config, fastapi_logging_middleware_enabled=True) + application = _bootstrap_with_route(config) + with TestClient(application) as test_client: + test_client.post("/items/abc", json={"a": 1}) + + lines = _access_log_lines(capsys.readouterr().out) + assert len(lines) == 1 + http_fields = lines[0]["http"] + assert http_fields["method"] == "POST" + assert http_fields["path"] == "/items/abc" + assert http_fields["status_code"] == status.HTTP_200_OK + assert http_fields["path_params"] == {"item_id": "abc"} + assert lines[0]["duration"] > 0 + + +def test_fastapi_access_log_never_records_bodies( + fastapi_config: FastAPIConfig, capsys: pytest.CaptureFixture[str] +) -> None: + """INVARIANT: the access log records request metadata only, never request or response bodies. + + Litestar's middleware shipped this defect (54c8ad9): its defaults logged full bodies, putting + credentials into the log. A new framework cell must not reintroduce it. + """ + config = dataclasses.replace(fastapi_config, fastapi_logging_middleware_enabled=True) + application = _bootstrap_with_route(config) + secret = f"secret-{uuid.uuid4().hex}" + with TestClient(application) as test_client: + response = test_client.post("/items/abc", json={"password": secret}) + assert secret in response.text # the body really did carry it, both ways + + stdout = capsys.readouterr().out + assert secret not in stdout + + +@pytest.mark.parametrize( + "path_attribute", + ["health_checks_path", "prometheus_metrics_path", "swagger_path"], +) +def test_fastapi_access_log_excludes_infrastructure_paths( + fastapi_config: FastAPIConfig, capsys: pytest.CaptureFixture[str], path_attribute: str +) -> None: + config = dataclasses.replace(fastapi_config, fastapi_logging_middleware_enabled=True) + application = _bootstrap_with_route(config) + with TestClient(application) as test_client: + test_client.get(getattr(config, path_attribute)) + + assert _access_log_lines(capsys.readouterr().out) == [] From 200d0628888159dda3a2d18a62c3e06650eea564 Mon Sep 17 00:00:00 2001 From: Artur Shiriev Date: Sun, 20 Sep 2026 15:40:51 +0300 Subject: [PATCH 2/3] review: hoist the path policy, correct the ASGI rationale, pin the log shape --- ...ss-logging-is-opt-in-on-every-framework.md | 9 +- .../bootstrappers/fastapi_bootstrapper.py | 27 +-- .../bootstrappers/litestar_bootstrapper.py | 15 +- .../instruments/logging_instrument.py | 22 +++ tests/test_fastapi_bootstrap.py | 164 +++++++++++++----- 5 files changed, 156 insertions(+), 81 deletions(-) diff --git a/docs/adr/0009-access-logging-is-opt-in-on-every-framework.md b/docs/adr/0009-access-logging-is-opt-in-on-every-framework.md index f3b2926..2109691 100644 --- a/docs/adr/0009-access-logging-is-opt-in-on-every-framework.md +++ b/docs/adr/0009-access-logging-is-opt-in-on-every-framework.md @@ -15,8 +15,13 @@ Sentry's handlers alone cost ~12 µs per record when Sentry is enabled. A defaul multiplies log volume and per-request cost on upgrade is not one a bootstrapper should pick for its users. -The middleware is pure ASGI rather than `BaseHTTPMiddleware`, which buffers the response body and so -breaks streaming responses and background tasks. It wraps `send` to capture the status code, reads +The middleware is pure ASGI rather than `BaseHTTPMiddleware`, for cost rather than correctness. The +usual claim that `BaseHTTPMiddleware` breaks streaming responses and background tasks is stale: both +work on the declared starlette range, checked at the 0.37.2 floor and at 1.6.0. What it still costs is +a task group and a pair of memory object streams per request, measured in the benchmarks' in-process +harness at over +150 µs per request 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. It wraps `send` to capture the status code, reads `path_params` from the scope after routing has populated it, and logs metadata only: `method`, `path`, `content_type`, `path_params`, `status_code` and `duration`. Bodies are never read, which is the defect Litestar's own middleware shipped (`54c8ad9`) and the reason that framework's binding is diff --git a/lite_bootstrap/bootstrappers/fastapi_bootstrapper.py b/lite_bootstrap/bootstrappers/fastapi_bootstrapper.py index 7d12b67..588c237 100644 --- a/lite_bootstrap/bootstrappers/fastapi_bootstrapper.py +++ b/lite_bootstrap/bootstrappers/fastapi_bootstrapper.py @@ -94,11 +94,7 @@ def app(self) -> "fastapi.FastAPI": class _AccessLogMiddleware: - """One structured line per request, pure ASGI. - - Not `BaseHTTPMiddleware`: that one buffers the response, which breaks streaming - responses and background tasks. - """ + """One structured line per request, pure ASGI.""" def __init__(self, app: "ASGIApp", *, excluded_paths: tuple[str, ...]) -> None: self.app = app @@ -112,7 +108,7 @@ def _is_excluded(self, path: str) -> bool: ) @staticmethod - def _http_fields(scope: "Scope", status_code: int) -> dict[str, typing.Any]: + def _http_fields(scope: "Scope", status_code: int | None) -> dict[str, typing.Any]: content_type = "" for header_name, header_value in scope.get("headers", ()): if header_name == b"content-type": @@ -131,7 +127,7 @@ async def __call__(self, scope: "Scope", receive: "Receive", send: "Send") -> No await self.app(scope, receive, send) return - status_code = 0 + status_code: int | None = None async def send_wrapper(message: "Message") -> None: nonlocal status_code @@ -160,23 +156,6 @@ async def send_wrapper(message: "Message") -> None: class FastAPILoggingInstrument(LoggingInstrument): bootstrap_config: FastAPIConfig - def _build_excluded_paths(self) -> tuple[str, ...]: - """Infrastructure routes not worth an access log line, normalized and deduplicated.""" - config = self.bootstrap_config - candidate_paths: typing.Final = ( - config.swagger_path, - config.swagger_static_path if config.swagger_offline_docs else "", - config.health_checks_path, - config.prometheus_metrics_path, - ) - excluded_paths: list[str] = [] - for candidate_path in candidate_paths: - # A bare "/" would exclude every route, so it is dropped along with empty values. - normalized_path = candidate_path.rstrip("/") - if normalized_path and normalized_path not in excluded_paths: - excluded_paths.append(normalized_path) - return tuple(excluded_paths) - def bootstrap(self) -> None: super().bootstrap() if not self.bootstrap_config.fastapi_logging_middleware_enabled: diff --git a/lite_bootstrap/bootstrappers/litestar_bootstrapper.py b/lite_bootstrap/bootstrappers/litestar_bootstrapper.py index 3e31646..e8cefff 100644 --- a/lite_bootstrap/bootstrappers/litestar_bootstrapper.py +++ b/lite_bootstrap/bootstrappers/litestar_bootstrapper.py @@ -190,22 +190,9 @@ class LitestarLoggingInstrument(LoggingInstrument): def _build_logging_middleware_excluded_paths(self) -> list[str]: """Regex-escaped path prefixes for infrastructure routes not worth an access log line.""" - config = self.bootstrap_config - candidate_paths: typing.Final = ( - config.swagger_path, - config.swagger_static_path if config.swagger_offline_docs else "", - config.health_checks_path, - config.prometheus_metrics_path, - ) - excluded_paths: list[str] = [] - for candidate_path in candidate_paths: - # A bare "/" would exclude every route, so it is dropped along with empty values. - normalized_path = candidate_path.rstrip("/") - if normalized_path and normalized_path not in excluded_paths: - excluded_paths.append(normalized_path) # Litestar matches exclude patterns with an unanchored search, so anchor each one to the # path itself or a sub-path; a bare prefix would also suppress an unrelated /custom-healthy. - return [rf"^{re.escape(excluded_path)}(?:/|$)" for excluded_path in excluded_paths] + return [rf"^{re.escape(excluded_path)}(?:/|$)" for excluded_path in self._build_excluded_paths()] def _build_logging_middleware_config(self) -> "LoggingMiddlewareConfig": # A caller-supplied config replaces the hardened defaults wholesale, no merging. diff --git a/lite_bootstrap/instruments/logging_instrument.py b/lite_bootstrap/instruments/logging_instrument.py index 059dcc3..132e124 100644 --- a/lite_bootstrap/instruments/logging_instrument.py +++ b/lite_bootstrap/instruments/logging_instrument.py @@ -115,6 +115,28 @@ def _unset_handlers(self) -> None: for unset_handlers_logger in self.bootstrap_config.logging_unset_handlers: logging.getLogger(unset_handlers_logger).handlers = [] + def _build_excluded_paths(self) -> tuple[str, ...]: + """Infrastructure routes not worth an access log line, normalized and deduplicated. + + Sibling paths are read with ``getattr`` because they live on the Swagger, HealthChecks and + Prometheus configs, which a given framework's config need not mix in (see ADR-0002). + """ + config = self.bootstrap_config + offline_docs: typing.Final = getattr(config, "swagger_offline_docs", False) + candidate_paths: typing.Final = ( + getattr(config, "swagger_path", ""), + getattr(config, "swagger_static_path", "") if offline_docs else "", + getattr(config, "health_checks_path", ""), + getattr(config, "prometheus_metrics_path", ""), + ) + excluded_paths: list[str] = [] + for candidate_path in candidate_paths: + # A bare "/" would exclude every route, so it is dropped along with empty values. + normalized_path = candidate_path.rstrip("/") + if normalized_path and normalized_path not in excluded_paths: + excluded_paths.append(normalized_path) + return tuple(excluded_paths) + @property def structlog_processors(self) -> list[typing.Any]: return [ diff --git a/tests/test_fastapi_bootstrap.py b/tests/test_fastapi_bootstrap.py index 554bf02..6ec171f 100644 --- a/tests/test_fastapi_bootstrap.py +++ b/tests/test_fastapi_bootstrap.py @@ -1,3 +1,4 @@ +import contextlib import dataclasses import json import logging @@ -260,84 +261,165 @@ def test_missing_exporter_warning_points_at_the_bootstrap_call_site(fastapi_conf assert warning_source_files(caught, InstrumentDependencyMissingWarning) == [__file__] -def _access_log_lines(stdout: str) -> list[dict[str, typing.Any]]: - """Every structlog line emitted by the access logger, parsed.""" - lines: list[dict[str, typing.Any]] = [] - for raw_line in stdout.splitlines(): - if '"logger":"http.access"' not in raw_line.replace(", ", ","): - continue - lines.append(json.loads(raw_line)) - return lines +class RecordingAccessLogger: + """Stands in for the module-level access logger. + + Asserting through `logging_extra_processors` is not sound here: `_configure_foreign_loggers` + registers those processors a second time inside the root handler's ProcessorFormatter, so a + capture sees either the event dict or the already-rendered JSON depending on what an earlier + bootstrap left in structlog's global configuration. + """ + + def __init__(self) -> None: + self.calls: list[tuple[str, str, dict[str, typing.Any]]] = [] + + def info(self, event: str, **kwargs: object) -> None: + self.calls.append(("info", event, dict(kwargs))) + + def exception(self, event: str, **kwargs: object) -> None: + self.calls.append(("exception", event, dict(kwargs))) -def _bootstrap_with_route(config: FastAPIConfig) -> "fastapi.FastAPI": +@pytest.fixture +def access_logger() -> typing.Iterator[RecordingAccessLogger]: + recorder = RecordingAccessLogger() + with patch.object(fastapi_bootstrapper, "fastapi_access_logger", recorder): + yield recorder + + +@contextlib.contextmanager +def _bootstrapped(config: FastAPIConfig) -> typing.Iterator["fastapi.FastAPI"]: bootstrapper = FastAPIBootstrapper(bootstrap_config=config) - application = bootstrapper.bootstrap() + try: + yield bootstrapper.bootstrap() + finally: + bootstrapper.teardown() + - @application.post("/items/{item_id}") - async def create_item(item_id: str, payload: dict[str, typing.Any]) -> dict[str, typing.Any]: - return {"item_id": item_id, "echo": payload} +@contextlib.contextmanager +def _bootstrapped_with_route(config: FastAPIConfig) -> typing.Iterator["fastapi.FastAPI"]: + with _bootstrapped(config) as application: - return application + @application.post("/items/{item_id}") + async def create_item(item_id: str, payload: dict[str, typing.Any]) -> dict[str, typing.Any]: + return {"item_id": item_id, "echo": payload} + + yield application def test_fastapi_access_log_is_off_by_default( - fastapi_config: FastAPIConfig, capsys: pytest.CaptureFixture[str] + fastapi_config: FastAPIConfig, access_logger: RecordingAccessLogger ) -> None: - application = _bootstrap_with_route(fastapi_config) - with TestClient(application) as test_client: + with _bootstrapped_with_route(fastapi_config) as application, TestClient(application) as test_client: test_client.post("/items/abc", json={"a": 1}) - assert _access_log_lines(capsys.readouterr().out) == [] + assert access_logger.calls == [] def test_fastapi_access_log_records_the_request_when_enabled( - fastapi_config: FastAPIConfig, capsys: pytest.CaptureFixture[str] + fastapi_config: FastAPIConfig, access_logger: RecordingAccessLogger ) -> None: config = dataclasses.replace(fastapi_config, fastapi_logging_middleware_enabled=True) - application = _bootstrap_with_route(config) - with TestClient(application) as test_client: + with _bootstrapped_with_route(config) as application, TestClient(application) as test_client: test_client.post("/items/abc", json={"a": 1}) - lines = _access_log_lines(capsys.readouterr().out) - assert len(lines) == 1 - http_fields = lines[0]["http"] - assert http_fields["method"] == "POST" - assert http_fields["path"] == "/items/abc" - assert http_fields["status_code"] == status.HTTP_200_OK - assert http_fields["path_params"] == {"item_id": "abc"} - assert lines[0]["duration"] > 0 + assert len(access_logger.calls) == 1 + level, event, fields = access_logger.calls[0] + assert (level, event) == ("info", "http_request") + assert fields["http"] == { + "method": "POST", + "path": "/items/abc", + "content_type": "application/json", + "path_params": {"item_id": "abc"}, + "status_code": status.HTTP_200_OK, + } + assert fields["duration"] > 0 def test_fastapi_access_log_never_records_bodies( - fastapi_config: FastAPIConfig, capsys: pytest.CaptureFixture[str] + fastapi_config: FastAPIConfig, access_logger: RecordingAccessLogger ) -> None: - """INVARIANT: the access log records request metadata only, never request or response bodies. + """INVARIANT: the access log records a fixed set of metadata fields, never bodies. Litestar's middleware shipped this defect (54c8ad9): its defaults logged full bodies, putting - credentials into the log. A new framework cell must not reintroduce it. + credentials into the log. Pinning the field set, not just one secret, is what stops a later + change quietly adding headers, cookies or a body back. """ config = dataclasses.replace(fastapi_config, fastapi_logging_middleware_enabled=True) - application = _bootstrap_with_route(config) secret = f"secret-{uuid.uuid4().hex}" - with TestClient(application) as test_client: + with _bootstrapped_with_route(config) as application, TestClient(application) as test_client: response = test_client.post("/items/abc", json={"password": secret}) assert secret in response.text # the body really did carry it, both ways - stdout = capsys.readouterr().out - assert secret not in stdout + assert len(access_logger.calls) == 1 + fields = access_logger.calls[0][2] + assert set(fields) == {"http", "duration"} + assert set(fields["http"]) == {"method", "path", "content_type", "path_params", "status_code"} + assert secret not in json.dumps(access_logger.calls, default=str) @pytest.mark.parametrize( "path_attribute", - ["health_checks_path", "prometheus_metrics_path", "swagger_path"], + ["health_checks_path", "prometheus_metrics_path", "swagger_path", "swagger_static_path"], ) def test_fastapi_access_log_excludes_infrastructure_paths( - fastapi_config: FastAPIConfig, capsys: pytest.CaptureFixture[str], path_attribute: str + fastapi_config: FastAPIConfig, access_logger: RecordingAccessLogger, path_attribute: str ) -> None: config = dataclasses.replace(fastapi_config, fastapi_logging_middleware_enabled=True) - application = _bootstrap_with_route(config) - with TestClient(application) as test_client: + with _bootstrapped_with_route(config) as application, TestClient(application) as test_client: test_client.get(getattr(config, path_attribute)) - assert _access_log_lines(capsys.readouterr().out) == [] + assert access_logger.calls == [] + + +def test_fastapi_access_log_excluded_paths_cover_every_sibling(fastapi_config: FastAPIConfig) -> None: + """INVARIANT: every sibling path the policy names reaches the built exclusion set. + + ADR-0002 keeps this policy in one method and answers the rename risk with exactly this test: + renaming a sibling field would otherwise stop the exclusion silently. + """ + instrument = fastapi_bootstrapper.FastAPILoggingInstrument(bootstrap_config=fastapi_config) + excluded = instrument._build_excluded_paths() # noqa: SLF001 + + for path_attribute in ("swagger_path", "swagger_static_path", "health_checks_path", "prometheus_metrics_path"): + assert getattr(fastapi_config, path_attribute).rstrip("/") in excluded, path_attribute + + +def test_fastapi_access_log_keeps_lookalike_paths( + fastapi_config: FastAPIConfig, access_logger: RecordingAccessLogger +) -> None: + """A route merely sharing a prefix with an excluded path is still logged.""" + config = dataclasses.replace(fastapi_config, fastapi_logging_middleware_enabled=True) + lookalike_path = f"{config.health_checks_path.rstrip('/')}y" + with _bootstrapped(config) as application: + + @application.get(lookalike_path) + async def lookalike() -> str: + return "not a health check" + + with TestClient(application) as test_client: + assert test_client.get(lookalike_path).status_code == status.HTTP_200_OK + + assert len(access_logger.calls) == 1 + assert access_logger.calls[0][2]["http"]["path"] == lookalike_path + + +def test_fastapi_access_log_records_a_raising_request( + fastapi_config: FastAPIConfig, access_logger: RecordingAccessLogger +) -> None: + config = dataclasses.replace(fastapi_config, fastapi_logging_middleware_enabled=True) + with _bootstrapped(config) as application: + + @application.get("/boom") + async def boom() -> str: + msg = "boom" + raise RuntimeError(msg) + + with TestClient(application) as test_client, pytest.raises(RuntimeError, match="boom"): + test_client.get("/boom") + + assert len(access_logger.calls) == 1 + level, _, fields = access_logger.calls[0] + assert level == "exception" + # No response ever started, so there is no status to report. + assert fields["http"]["status_code"] is None From a13d2b739dfe81b2b950b0b43ccd32ca9472199d Mon Sep 17 00:00:00 2001 From: Artur Shiriev Date: Sun, 20 Sep 2026 15:50:22 +0300 Subject: [PATCH 3/3] docs: drop the access-log ADR --- ...ss-logging-is-opt-in-on-every-framework.md | 29 ------------------- 1 file changed, 29 deletions(-) delete mode 100644 docs/adr/0009-access-logging-is-opt-in-on-every-framework.md diff --git a/docs/adr/0009-access-logging-is-opt-in-on-every-framework.md b/docs/adr/0009-access-logging-is-opt-in-on-every-framework.md deleted file mode 100644 index 2109691..0000000 --- a/docs/adr/0009-access-logging-is-opt-in-on-every-framework.md +++ /dev/null @@ -1,29 +0,0 @@ -# A structured access log is opt-in on every framework - -`fastapi_logging_middleware_enabled` defaults to `False`, matching -`litestar_logging_middleware_enabled`. FastMCP's `logging_turn_off_middleware` is the outlier and is -being brought into line separately (#240), so the rule is uniform: lite-bootstrap configures structlog -process-wide for every framework, and logs a line per request only when asked. - -Defaulting FastAPI's on was rejected for two reasons FastMCP does not have. uvicorn already writes an -access line per request and `logging_unset_handlers` defaults to empty, so an on-by-default access log -would give every FastAPI service two lines per request, one structured and one not, until it -discovered `logging_unset_handlers=["uvicorn.access"]`. And HTTP request rates are the highest of any -supported framework, so the cost lands where it is largest: `LoggingInstrument` measures at +0.1 -µs/request while nothing logs, and an always-on access log makes every request log, on a path where -Sentry's handlers alone cost ~12 µs per record when Sentry is enabled. A default that silently -multiplies log volume and per-request cost on upgrade is not one a bootstrapper should pick for its -users. - -The middleware is pure ASGI rather than `BaseHTTPMiddleware`, for cost rather than correctness. The -usual claim that `BaseHTTPMiddleware` breaks streaming responses and background tasks is stale: both -work on the declared starlette range, checked at the 0.37.2 floor and at 1.6.0. What it still costs is -a task group and a pair of memory object streams per request, measured in the benchmarks' in-process -harness at over +150 µs per request 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. It wraps `send` to capture the status code, reads -`path_params` from the scope after routing has populated it, and logs metadata only: `method`, `path`, -`content_type`, `path_params`, `status_code` and `duration`. Bodies are never read, which is the -defect Litestar's own middleware shipped (`54c8ad9`) and the reason that framework's binding is -hardened rather than passed through; `tests/test_fastapi_bootstrap.py` pins the claim as an invariant -rather than leaving it to prose.