FastAPI: emit structured RequestHandled event per HTTP request

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",
+]

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

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,
+                )
+            )

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

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")