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..588c237 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,76 @@ def app(self) -> "fastapi.FastAPI": return self.application +class _AccessLogMiddleware: + """One structured line per request, pure ASGI.""" + + 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 | None) -> 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: int | None = None + + 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 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 +254,7 @@ class FastAPIBootstrapper(BaseBootstrapper["fastapi.FastAPI"]): PyroscopeInstrument, SentryInstrument, FastAPIHealthChecksInstrument, - LoggingInstrument, + FastAPILoggingInstrument, FastAPIPrometheusInstrument, FastAPISwaggerInstrument, ] 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 cf4c7e9..6ec171f 100644 --- a/tests/test_fastapi_bootstrap.py +++ b/tests/test_fastapi_bootstrap.py @@ -1,6 +1,9 @@ +import contextlib import dataclasses +import json import logging import typing +import uuid import warnings from unittest.mock import patch @@ -256,3 +259,167 @@ def test_missing_exporter_warning_points_at_the_bootstrap_call_site(fastapi_conf bootstrapper.teardown() assert warning_source_files(caught, InstrumentDependencyMissingWarning) == [__file__] + + +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))) + + +@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) + try: + yield bootstrapper.bootstrap() + finally: + bootstrapper.teardown() + + +@contextlib.contextmanager +def _bootstrapped_with_route(config: FastAPIConfig) -> typing.Iterator["fastapi.FastAPI"]: + with _bootstrapped(config) as 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, access_logger: RecordingAccessLogger +) -> None: + with _bootstrapped_with_route(fastapi_config) as application, TestClient(application) as test_client: + test_client.post("/items/abc", json={"a": 1}) + + assert access_logger.calls == [] + + +def test_fastapi_access_log_records_the_request_when_enabled( + fastapi_config: FastAPIConfig, access_logger: RecordingAccessLogger +) -> None: + config = dataclasses.replace(fastapi_config, fastapi_logging_middleware_enabled=True) + with _bootstrapped_with_route(config) as application, TestClient(application) as test_client: + test_client.post("/items/abc", json={"a": 1}) + + 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, access_logger: RecordingAccessLogger +) -> None: + """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. 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) + secret = f"secret-{uuid.uuid4().hex}" + 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 + + 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", "swagger_static_path"], +) +def test_fastapi_access_log_excludes_infrastructure_paths( + fastapi_config: FastAPIConfig, access_logger: RecordingAccessLogger, path_attribute: str +) -> None: + config = dataclasses.replace(fastapi_config, fastapi_logging_middleware_enabled=True) + with _bootstrapped_with_route(config) as application, TestClient(application) as test_client: + test_client.get(getattr(config, path_attribute)) + + 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