Skip to content

Commit a18f6f0

Browse files
authored
feat: add an opt-in structured access log to FastAPI (#241)
* feat: add an opt-in structured access log to FastAPI Closes #180 * review: hoist the path policy, correct the ASGI rationale, pin the log shape * docs: drop the access-log ADR
1 parent 75b31b8 commit a18f6f0

7 files changed

Lines changed: 324 additions & 15 deletions

File tree

‎docs/integrations/fastapi.md‎

Lines changed: 39 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -46,3 +46,42 @@ application = bootstrapper.bootstrap()
4646
```
4747

4848
Read more about available configuration options [here](../introduction/configuration.md).
49+
50+
## Logging
51+
52+
Structlog is configured process-wide, so `structlog.get_logger()` works in any route handler.
53+
54+
FastAPI has no access log of its own, so lite-bootstrap provides one. It is **off by default**,
55+
because uvicorn already writes an access line per request and an HTTP service is the highest-volume
56+
place to add a log record. Turn it on explicitly:
57+
58+
```python
59+
FastAPIConfig(
60+
service_name="microservice",
61+
fastapi_logging_middleware_enabled=True,
62+
)
63+
```
64+
65+
Enabled, it writes one `http_request` line per request to the `http.access` logger, carrying `method`,
66+
`path`, `content_type`, `path_params` and `status_code` under `http`, plus `duration` in nanoseconds.
67+
A request that raises is logged at exception level and the exception is re-raised unchanged.
68+
69+
Request and response **bodies are never read or logged**. `path` and `path_params` are, so a secret
70+
embedded in the URL itself (e.g. `/reset-password/{token}`) is recorded. Keep secrets in the request
71+
body.
72+
73+
These paths are skipped, whether or not the corresponding instrument is configured: `swagger_path`,
74+
`swagger_static_path` (when `swagger_offline_docs` is on), `health_checks_path` and
75+
`prometheus_metrics_path`. So if you disable health checks but still serve your own route at
76+
`health_checks_path`, that route is not access-logged either.
77+
78+
If you keep uvicorn's own access log as well, you will get two lines per request. To leave only the
79+
structured one, clear uvicorn's handlers:
80+
81+
```python
82+
FastAPIConfig(
83+
service_name="microservice",
84+
fastapi_logging_middleware_enabled=True,
85+
logging_unset_handlers=["uvicorn.access"],
86+
)
87+
```

‎docs/introduction/configuration.md‎

Lines changed: 9 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -246,6 +246,15 @@ Additional parameters for Litestar's access-log middleware:
246246

247247
See [the Litestar integration guide](../integrations/litestar.md#logging) for what gets logged and why access logging defaults to off.
248248

249+
### Structlog FastAPI
250+
251+
FastAPI ships no access log of its own, so lite-bootstrap provides one. It is **off by default**:
252+
253+
- `fastapi_logging_middleware_enabled` - turn on the structured access log (default: `False`).
254+
255+
See [the FastAPI integration guide](../integrations/fastapi.md#logging) for what gets logged and why
256+
it defaults to off.
257+
249258
### Structlog FastStream
250259

251260
When using FastStream, the structlog logger is automatically injected into the broker so that all broker

‎docs/introduction/performance.md‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -56,6 +56,11 @@ so there is nothing else material hiding in it. That configuration is:
5656

5757
--8<-- "benchmarks/README.md:tuned"
5858

59+
One thing to leave off rather than turn on: the FastAPI access log
60+
([`fastapi_logging_middleware_enabled`](../integrations/fastapi.md#logging)) is off by default, and
61+
turning it on makes every request emit a log record. On a service that otherwise logs nothing per
62+
request, that is the difference between the first row of the logging table above and the rest of it.
63+
5964
lite-bootstrap already applies one saving for you: it passes `sentry_logs_level=None` by default,
6065
because it never enables Sentry Logs and the handler formats every record before checking whether
6166
they are enabled. That one costs nothing, which is why it is a default rather than a knob.

‎lite_bootstrap/bootstrappers/fastapi_bootstrapper.py‎

Lines changed: 81 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,6 @@
11
import contextlib
22
import dataclasses
3+
import time
34
import typing
45

56
from lite_bootstrap import import_checker
@@ -22,11 +23,19 @@
2223
from lite_bootstrap.types import UNSET, UnsetType
2324

2425

26+
if typing.TYPE_CHECKING:
27+
from starlette.types import ASGIApp, Message, Receive, Scope, Send
28+
2529
if import_checker.is_fastapi_installed:
2630
import fastapi
2731
from fastapi.middleware.cors import CORSMiddleware
2832
from fastapi.routing import _merge_lifespan_context
2933

34+
if import_checker.is_structlog_installed:
35+
import structlog
36+
37+
fastapi_access_logger: typing.Final = structlog.get_logger("http.access")
38+
3039
if import_checker.is_opentelemetry_installed:
3140
from opentelemetry.trace import get_tracer_provider
3241

@@ -55,6 +64,7 @@ class FastAPIConfig(
5564
prometheus_instrumentator_params: dict[str, typing.Any] = dataclasses.field(default_factory=dict)
5665
prometheus_instrument_params: dict[str, typing.Any] = dataclasses.field(default_factory=dict)
5766
prometheus_expose_params: dict[str, typing.Any] = dataclasses.field(default_factory=dict)
67+
fastapi_logging_middleware_enabled: bool = False
5868

5969
def __post_init__(self) -> None:
6070
# @dataclass(slots=True) replaces the class object, breaking bare super().
@@ -83,6 +93,76 @@ def app(self) -> "fastapi.FastAPI":
8393
return self.application
8494

8595

96+
class _AccessLogMiddleware:
97+
"""One structured line per request, pure ASGI."""
98+
99+
def __init__(self, app: "ASGIApp", *, excluded_paths: tuple[str, ...]) -> None:
100+
self.app = app
101+
self.excluded_paths = excluded_paths
102+
103+
def _is_excluded(self, path: str) -> bool:
104+
normalized_path = path.rstrip("/")
105+
return any(
106+
normalized_path == excluded_path or normalized_path.startswith(f"{excluded_path}/")
107+
for excluded_path in self.excluded_paths
108+
)
109+
110+
@staticmethod
111+
def _http_fields(scope: "Scope", status_code: int | None) -> dict[str, typing.Any]:
112+
content_type = ""
113+
for header_name, header_value in scope.get("headers", ()):
114+
if header_name == b"content-type":
115+
content_type = header_value.decode("latin-1")
116+
break
117+
return {
118+
"method": scope.get("method", ""),
119+
"path": scope.get("path", ""),
120+
"content_type": content_type,
121+
"path_params": scope.get("path_params", {}),
122+
"status_code": status_code,
123+
}
124+
125+
async def __call__(self, scope: "Scope", receive: "Receive", send: "Send") -> None:
126+
if scope["type"] != "http" or self._is_excluded(scope["path"]):
127+
await self.app(scope, receive, send)
128+
return
129+
130+
status_code: int | None = None
131+
132+
async def send_wrapper(message: "Message") -> None:
133+
nonlocal status_code
134+
if message["type"] == "http.response.start":
135+
status_code = message["status"]
136+
await send(message)
137+
138+
started_at = time.perf_counter_ns()
139+
try:
140+
await self.app(scope, receive, send_wrapper)
141+
except Exception:
142+
fastapi_access_logger.exception(
143+
"http_request",
144+
http=self._http_fields(scope, status_code),
145+
duration=time.perf_counter_ns() - started_at,
146+
)
147+
raise
148+
fastapi_access_logger.info(
149+
"http_request",
150+
http=self._http_fields(scope, status_code),
151+
duration=time.perf_counter_ns() - started_at,
152+
)
153+
154+
155+
@dataclasses.dataclass(kw_only=True)
156+
class FastAPILoggingInstrument(LoggingInstrument):
157+
bootstrap_config: FastAPIConfig
158+
159+
def bootstrap(self) -> None:
160+
super().bootstrap()
161+
if not self.bootstrap_config.fastapi_logging_middleware_enabled:
162+
return
163+
self.bootstrap_config.app.add_middleware(_AccessLogMiddleware, excluded_paths=self._build_excluded_paths())
164+
165+
86166
@dataclasses.dataclass(kw_only=True, slots=True)
87167
class FastAPICorsInstrument(CorsInstrument):
88168
bootstrap_config: FastAPIConfig
@@ -174,7 +254,7 @@ class FastAPIBootstrapper(BaseBootstrapper["fastapi.FastAPI"]):
174254
PyroscopeInstrument,
175255
SentryInstrument,
176256
FastAPIHealthChecksInstrument,
177-
LoggingInstrument,
257+
FastAPILoggingInstrument,
178258
FastAPIPrometheusInstrument,
179259
FastAPISwaggerInstrument,
180260
]

‎lite_bootstrap/bootstrappers/litestar_bootstrapper.py‎

Lines changed: 1 addition & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -190,22 +190,9 @@ class LitestarLoggingInstrument(LoggingInstrument):
190190

191191
def _build_logging_middleware_excluded_paths(self) -> list[str]:
192192
"""Regex-escaped path prefixes for infrastructure routes not worth an access log line."""
193-
config = self.bootstrap_config
194-
candidate_paths: typing.Final = (
195-
config.swagger_path,
196-
config.swagger_static_path if config.swagger_offline_docs else "",
197-
config.health_checks_path,
198-
config.prometheus_metrics_path,
199-
)
200-
excluded_paths: list[str] = []
201-
for candidate_path in candidate_paths:
202-
# A bare "/" would exclude every route, so it is dropped along with empty values.
203-
normalized_path = candidate_path.rstrip("/")
204-
if normalized_path and normalized_path not in excluded_paths:
205-
excluded_paths.append(normalized_path)
206193
# Litestar matches exclude patterns with an unanchored search, so anchor each one to the
207194
# path itself or a sub-path; a bare prefix would also suppress an unrelated /custom-healthy.
208-
return [rf"^{re.escape(excluded_path)}(?:/|$)" for excluded_path in excluded_paths]
195+
return [rf"^{re.escape(excluded_path)}(?:/|$)" for excluded_path in self._build_excluded_paths()]
209196

210197
def _build_logging_middleware_config(self) -> "LoggingMiddlewareConfig":
211198
# A caller-supplied config replaces the hardened defaults wholesale, no merging.

‎lite_bootstrap/instruments/logging_instrument.py‎

Lines changed: 22 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -115,6 +115,28 @@ def _unset_handlers(self) -> None:
115115
for unset_handlers_logger in self.bootstrap_config.logging_unset_handlers:
116116
logging.getLogger(unset_handlers_logger).handlers = []
117117

118+
def _build_excluded_paths(self) -> tuple[str, ...]:
119+
"""Infrastructure routes not worth an access log line, normalized and deduplicated.
120+
121+
Sibling paths are read with ``getattr`` because they live on the Swagger, HealthChecks and
122+
Prometheus configs, which a given framework's config need not mix in (see ADR-0002).
123+
"""
124+
config = self.bootstrap_config
125+
offline_docs: typing.Final = getattr(config, "swagger_offline_docs", False)
126+
candidate_paths: typing.Final = (
127+
getattr(config, "swagger_path", ""),
128+
getattr(config, "swagger_static_path", "") if offline_docs else "",
129+
getattr(config, "health_checks_path", ""),
130+
getattr(config, "prometheus_metrics_path", ""),
131+
)
132+
excluded_paths: list[str] = []
133+
for candidate_path in candidate_paths:
134+
# A bare "/" would exclude every route, so it is dropped along with empty values.
135+
normalized_path = candidate_path.rstrip("/")
136+
if normalized_path and normalized_path not in excluded_paths:
137+
excluded_paths.append(normalized_path)
138+
return tuple(excluded_paths)
139+
118140
@property
119141
def structlog_processors(self) -> list[typing.Any]:
120142
return [

0 commit comments

Comments
 (0)