diff --git a/fastapi_startkit/src/fastapi_startkit/fastapi/__init__.py b/fastapi_startkit/src/fastapi_startkit/fastapi/__init__.py index 254b5130..243a711a 100644 --- a/fastapi_startkit/src/fastapi_startkit/fastapi/__init__.py +++ b/fastapi_startkit/src/fastapi_startkit/fastapi/__init__.py @@ -2,5 +2,14 @@ from .routers.router import Router from .requests.model import RequestModel from .config import FastAPIConfig +from .events import RequestHandled +from .middleware import RequestLifecycleMiddleware -__all__ = ["FastAPIProvider", "Router", "RequestModel", "FastAPIConfig"] +__all__ = [ + "FastAPIProvider", + "Router", + "RequestModel", + "FastAPIConfig", + "RequestHandled", + "RequestLifecycleMiddleware", +] diff --git a/fastapi_startkit/src/fastapi_startkit/fastapi/events.py b/fastapi_startkit/src/fastapi_startkit/fastapi/events.py new file mode 100644 index 00000000..ce625811 --- /dev/null +++ b/fastapi_startkit/src/fastapi_startkit/fastapi/events.py @@ -0,0 +1,29 @@ +"""Structured events emitted by the FastAPI request lifecycle. + +These ride on the framework's Laravel-style event dispatcher (see +``fastapi_startkit.events``) — this module only defines the event payload, +it does not dispatch, log, or persist anything itself. +""" + +from dataclasses import dataclass + + +@dataclass +class RequestHandled: + """Dispatched once per HTTP request by ``RequestLifecycleMiddleware``. + + Register a listener the normal way to observe it:: + + from fastapi_startkit.facades import Event + from fastapi_startkit.fastapi.events import RequestHandled + + Event.listen(RequestHandled, lambda e: logger.info( + "%s %s -> %s (%.1fms) [%s]", e.method, e.path, e.status_code, e.duration_ms, e.request_id + )) + """ + + method: str + path: str + status_code: int + duration_ms: float + request_id: str diff --git a/fastapi_startkit/src/fastapi_startkit/fastapi/middleware.py b/fastapi_startkit/src/fastapi_startkit/fastapi/middleware.py new file mode 100644 index 00000000..8aca198c --- /dev/null +++ b/fastapi_startkit/src/fastapi_startkit/fastapi/middleware.py @@ -0,0 +1,54 @@ +"""ASGI middleware that emits a structured ``RequestHandled`` event per request. + +This is dispatch-only: it fires the event through the framework's existing +Event dispatcher (task #940) and does not persist, log, or render anything +itself. Consumers — a logging listener, tests, future tooling — register +listeners the normal way via ``Event.listen(RequestHandled, ...)``. + +Out of scope for this middleware (left as extension points for follow-up +work): DB query watchers, exception watchers, and any other Telescope-style +watcher, plus storage/UI for the emitted events. +""" + +import time +import uuid + +from starlette.middleware.base import BaseHTTPMiddleware, RequestResponseEndpoint +from starlette.requests import Request +from starlette.responses import Response + +from fastapi_startkit.events.helpers import event + +from .events import RequestHandled + +REQUEST_ID_HEADER = "X-Request-Id" + + +class RequestLifecycleMiddleware(BaseHTTPMiddleware): + """Dispatches ``RequestHandled`` (method, path, status, duration, request id).""" + + async def dispatch(self, request: Request, call_next: RequestResponseEndpoint) -> Response: + request_id = request.headers.get(REQUEST_ID_HEADER) or str(uuid.uuid4()) + request.state.request_id = request_id + + started_at = time.perf_counter() + response = None + try: + response = await call_next(request) + return response + finally: + duration_ms = (time.perf_counter() - started_at) * 1000 + status_code = response.status_code if response is not None else 500 + + if response is not None: + response.headers.setdefault(REQUEST_ID_HEADER, request_id) + + await event( + RequestHandled( + method=request.method, + path=request.url.path, + status_code=status_code, + duration_ms=duration_ms, + request_id=request_id, + ) + ) diff --git a/fastapi_startkit/src/fastapi_startkit/fastapi/providers/fastapi_provider.py b/fastapi_startkit/src/fastapi_startkit/fastapi/providers/fastapi_provider.py index f6e106a7..fc478a2a 100644 --- a/fastapi_startkit/src/fastapi_startkit/fastapi/providers/fastapi_provider.py +++ b/fastapi_startkit/src/fastapi_startkit/fastapi/providers/fastapi_provider.py @@ -3,6 +3,7 @@ from fastapi_startkit.fastapi.commands import ServeCommand from fastapi_startkit.fastapi.config import FastAPIConfig +from fastapi_startkit.fastapi.middleware import REQUEST_ID_HEADER, RequestLifecycleMiddleware from fastapi_startkit.support import Provider @@ -26,6 +27,7 @@ def boot(self): self.commands([ServeCommand]) self._register_exception_handlers() + self.app.add_middleware(RequestLifecycleMiddleware) source = os.path.abspath(os.path.join(os.path.dirname(__file__), "../config/fastapi.py")) self.publishes({source: "config/fastapi.py"}) @@ -41,7 +43,17 @@ def _register_exception_handlers(self): exception_manager.register_handler(RequestValidationError, ValidationExceptionHandler()) async def handler(request, exc): - return await exception_manager.handle(exc, {"request": request}) + response = await exception_manager.handle(exc, {"request": request}) + + # Starlette promotes the bare-Exception handler onto ServerErrorMiddleware, + # which sits outside RequestLifecycleMiddleware — so that middleware never + # sees the response built here and can't stamp the header itself. Stamp it + # here instead, for every exception path this handler covers. + request_id = getattr(request.state, "request_id", None) + if request_id: + response.headers.setdefault(REQUEST_ID_HEADER, request_id) + + return response # FastAPI registers its own handlers for these two types internally, # so they must be overridden explicitly diff --git a/fastapi_startkit/tests/fastapi/test_request_lifecycle_events.py b/fastapi_startkit/tests/fastapi/test_request_lifecycle_events.py new file mode 100644 index 00000000..74ab551b --- /dev/null +++ b/fastapi_startkit/tests/fastapi/test_request_lifecycle_events.py @@ -0,0 +1,132 @@ +"""Tests for RequestLifecycleMiddleware — structured RequestHandled events (task #1324).""" + +import tempfile +import unittest +from pathlib import Path + +from fastapi.responses import JSONResponse +from fastapi.testclient import TestClient + +from fastapi_startkit.application import Application +from fastapi_startkit.container.container import Container +from fastapi_startkit.facades import Event +from fastapi_startkit.fastapi import FastAPIProvider, RequestHandled +from fastapi_startkit.fastapi.middleware import REQUEST_ID_HEADER + + +def make_client(app: Application) -> TestClient: + @app.fastapi.get("/ping") + def ping(): + return {"ok": True} + + @app.fastapi.get("/boom") + def boom(): + return JSONResponse(status_code=404, content={"detail": "not found"}) + + @app.fastapi.get("/crash") + def crash(): + raise RuntimeError("bare exception escaping the route") + + return TestClient(app.fastapi, raise_server_exceptions=False) + + +class RequestLifecycleEventTest(unittest.TestCase): + def setUp(self): + self._tmp_dir = tempfile.TemporaryDirectory() + self.addCleanup(self._tmp_dir.cleanup) + self._original_container_instance = Container._instance + self.addCleanup(self._restore_container) + + self.app = Application(base_path=Path(self._tmp_dir.name), env="testing", providers=[FastAPIProvider]) + self.client = make_client(self.app) + + def _restore_container(self): + Container._instance = self._original_container_instance + + def test_dispatches_request_handled_event(self): + seen = [] + Event.listen(RequestHandled, lambda e: seen.append(e)) + + response = self.client.get("/ping") + + self.assertEqual(response.status_code, 200) + self.assertEqual(len(seen), 1) + event = seen[0] + self.assertEqual(event.method, "GET") + self.assertEqual(event.path, "/ping") + self.assertEqual(event.status_code, 200) + self.assertGreaterEqual(event.duration_ms, 0) + self.assertTrue(event.request_id) + + def test_event_reflects_error_status_code(self): + seen = [] + Event.listen(RequestHandled, lambda e: seen.append(e)) + + response = self.client.get("/boom") + + self.assertEqual(response.status_code, 404) + self.assertEqual(seen[0].status_code, 404) + + def test_response_carries_generated_request_id_header(self): + response = self.client.get("/ping") + + self.assertIn(REQUEST_ID_HEADER, response.headers) + self.assertTrue(response.headers[REQUEST_ID_HEADER]) + + def test_incoming_request_id_is_echoed_back(self): + response = self.client.get("/ping", headers={REQUEST_ID_HEADER: "client-supplied-id"}) + + self.assertEqual(response.headers[REQUEST_ID_HEADER], "client-supplied-id") + + seen = [] + Event.listen(RequestHandled, lambda e: seen.append(e)) + self.client.get("/ping", headers={REQUEST_ID_HEADER: "another-id"}) + self.assertEqual(seen[0].request_id, "another-id") + + def test_event_fake_records_without_invoking_real_listener(self): + called = [] + Event.listen(RequestHandled, lambda e: called.append(e)) + + fake = Event.fake() + self.client.get("/ping") + + self.assertEqual(called, []) + fake.assert_dispatched(RequestHandled, lambda e: e.path == "/ping" and e.status_code == 200) + + # ----------------------------------------------------------------- + # Bare exception escaping the route (task #1329 regression) + # ----------------------------------------------------------------- + # + # A bare (non-HTTPException) exception is handled by Starlette's + # ServerErrorMiddleware, which sits *outside* RequestLifecycleMiddleware — + # unlike HTTPException, which stays inside it via ExceptionMiddleware. + # The event must still log status_code=500, and the response the client + # actually receives must still carry the same X-Request-Id. + + def test_event_reflects_bare_exception_as_500(self): + seen = [] + Event.listen(RequestHandled, lambda e: seen.append(e)) + + response = self.client.get("/crash") + + self.assertEqual(response.status_code, 500) + self.assertEqual(seen[0].status_code, 500) + + def test_response_carries_request_id_when_bare_exception_escapes(self): + response = self.client.get("/crash") + + self.assertIn(REQUEST_ID_HEADER, response.headers) + self.assertTrue(response.headers[REQUEST_ID_HEADER]) + + def test_response_request_id_matches_event_request_id_on_crash(self): + seen = [] + Event.listen(RequestHandled, lambda e: seen.append(e)) + + response = self.client.get("/crash") + + self.assertEqual(response.headers[REQUEST_ID_HEADER], seen[0].request_id) + + def test_incoming_request_id_is_echoed_back_on_crash(self): + response = self.client.get("/crash", headers={REQUEST_ID_HEADER: "crash-request-id"}) + + self.assertEqual(response.headers[REQUEST_ID_HEADER], "crash-request-id")