intermittent commit

src/govoplan_core/server/fastapi.py

@@ -1,5 +1,8 @@
 from __future__ import annotations
 
+import logging
+import os
+import time
 from collections.abc import AsyncIterator, Callable, Iterable
 from contextlib import AbstractAsyncContextManager
 from typing import Any
@@ -9,9 +12,19 @@ from fastapi.middleware.cors import CORSMiddleware
 
 from govoplan_core.core.events import event_context, new_event_id, normalize_trace_id
 from govoplan_core.core.registry import PlatformRegistry
+from govoplan_core.db.query_metrics import collect_query_metrics
 from govoplan_core.server.conditional_requests import conditional_json_get_middleware
 
 LifespanFactory = Callable[[FastAPI], AbstractAsyncContextManager[None] | AsyncIterator[None]]
+logger = logging.getLogger("govoplan.request")
+
+
+def _slow_request_threshold_ms() -> float:
+    raw = os.getenv("GOVOPLAN_SLOW_REQUEST_MS", "500").strip()
+    try:
+        return float(raw)
+    except ValueError:
+        return 500.0
 
 
 def create_govoplan_app(
@@ -26,6 +39,7 @@ def create_govoplan_app(
 ) -> FastAPI:
     app = FastAPI(title=title, version=version, lifespan=lifespan)
     app.state.govoplan_registry = registry
+    slow_request_threshold_ms = _slow_request_threshold_ms()
 
     @app.middleware("http")
     async def request_correlation_context(request: Request, call_next):
@@ -39,6 +53,42 @@ def create_govoplan_app(
         response.headers["X-Correlation-ID"] = correlation_id
         return response
 
+    @app.middleware("http")
+    async def slow_request_logging(request: Request, call_next):
+        started_at = time.perf_counter()
+        with collect_query_metrics() as db_metrics:
+            try:
+                response = await call_next(request)
+            except Exception:
+                elapsed_ms = (time.perf_counter() - started_at) * 1000
+                if slow_request_threshold_ms > 0 and elapsed_ms >= slow_request_threshold_ms:
+                    logger.warning(
+                        "slow request failed method=%s path=%s duration_ms=%.1f db_query_count=%s db_time_ms=%.1f db_slowest_ms=%.1f db_error_count=%s",
+                        request.method,
+                        request.url.path,
+                        elapsed_ms,
+                        db_metrics.query_count,
+                        db_metrics.total_ms,
+                        db_metrics.slowest_ms,
+                        db_metrics.error_count,
+                        exc_info=True,
+                    )
+                raise
+            elapsed_ms = (time.perf_counter() - started_at) * 1000
+            if slow_request_threshold_ms > 0 and elapsed_ms >= slow_request_threshold_ms:
+                logger.warning(
+                    "slow request method=%s path=%s status=%s duration_ms=%.1f db_query_count=%s db_time_ms=%.1f db_slowest_ms=%.1f db_error_count=%s",
+                    request.method,
+                    request.url.path,
+                    response.status_code,
+                    elapsed_ms,
+                    db_metrics.query_count,
+                    db_metrics.total_ms,
+                    db_metrics.slowest_ms,
+                    db_metrics.error_count,
+                )
+            return response
+
     app.middleware("http")(conditional_json_get_middleware)
 
     origins = [item.strip() for item in cors_origins if item.strip()]