feat: implement structured logging

Author: fiqrikm18

.env.example

@@ -16,11 +16,15 @@ ACCESS_TOKEN_EXPIRE_MINUTES=30
 REFRESH_TOKEN_EXPIRE_MINUTES=10080
 
 RATE_LIMIT="100/minute"
+
 CORS_ALLOW_ORIGINS=http://localhost:3000
 CORS_ALLOW_METHODS=*
 CORS_ALLOW_HEADERS=*
+
 SECURITY_CONTENT_SECURITY_POLICY=default-src 'self'; frame-ancestors 'none'
+
 IDEMPOTENCY_TTL_SECONDS=86400
+
 ACCOUNT_LOCKOUT_MAX_ATTEMPTS=5
 ACCOUNT_LOCKOUT_WINDOW_MINUTES=15
 ACCOUNT_LOCKOUT_DURATION_MINUTES=15

src/core/middleware/structured_logging.py

@@ -10,18 +10,48 @@
 class StructuredLoggingMiddleware(BaseHTTPMiddleware):
     async def dispatch(self, request: Request, call_next):
         started_at = time.perf_counter()
-        response = await call_next(request)
-        latency_ms = round((time.perf_counter() - started_at) * 1000, 2)
+        try:
+            response = await call_next(request)
+        except Exception as exc:
+            self._log_request(
+                request=request,
+                started_at=started_at,
+                status_code=500,
+                level=logging.ERROR,
+                message="request failed",
+                error_type=type(exc).__name__,
+            )
+            raise
+
+        self._log_request(
+            request=request,
+            started_at=started_at,
+            status_code=response.status_code,
+            level=logging.INFO,
+            message="request completed",
+        )
+        return response
 
-        logger.info(
-            "request completed",
+    @staticmethod
+    def _log_request(
+        request: Request,
+        started_at: float,
+        status_code: int,
+        level: int,
+        message: str,
+        error_type: str | None = None,
+    ) -> None:
+        latency_ms = round((time.perf_counter() - started_at) * 1000, 2)
+        logger.log(
+            level,
+            message,
             extra={
                 "method": request.method,
                 "path": request.url.path,
-                "status_code": response.status_code,
+                "status_code": status_code,
                 "latency_ms": latency_ms,
                 "request_id": getattr(request.state, "request_id", None),
                 "user_id": getattr(request.state, "user_id", None),
+                "error_type": error_type,
             },
         )
-        return response

tests/core/test_security_not_implemented.py

@@ -107,6 +107,41 @@ async def call_next(_request):
     assert record.user_id == "user-123"
 
 
+def test_structured_logging_middleware_logs_exception_context(caplog):
+    async def run():
+        caplog.set_level(logging.ERROR, logger="src.core.middleware.structured_logging")
+        request = Request(
+            {
+                "type": "http",
+                "method": "POST",
+                "path": "/api/v1/todos/",
+                "headers": [],
+                "query_string": b"",
+                "server": ("testserver", 80),
+                "scheme": "http",
+                "client": ("testclient", 50000),
+            }
+        )
+        request.state.request_id = "request-456"
+        request.state.user_id = "user-456"
+
+        async def call_next(_request):
+            raise RuntimeError("write failed")
+
+        with pytest.raises(RuntimeError, match="write failed"):
+            await StructuredLoggingMiddleware(None).dispatch(request, call_next)
+
+    asyncio.run(run())
+
+    record = caplog.records[0]
+    assert record.method == "POST"
+    assert record.path == "/api/v1/todos/"
+    assert record.status_code == 500
+    assert record.request_id == "request-456"
+    assert record.user_id == "user-456"
+    assert record.error_type == "RuntimeError"
+
+
 def test_admin_router_exposes_liveness_and_readiness():
     app = FastAPI()
     register_admin_router(app)