BUG: Log error details to user_session_log.json (#311)

GibranAlfa · web-flow · commit f3798568c28d · 2026-03-03T07:55:55.000+01:00
diff --git a/src/fmu_settings_api/__main__.py b/src/fmu_settings_api/__main__.py
@@ -2,17 +2,27 @@
 
 import asyncio
 import sys
+import time
 from collections.abc import AsyncIterator
 from contextlib import asynccontextmanager, suppress
 
 import uvicorn
 from fastapi import FastAPI
+from fastapi.exception_handlers import (
+    http_exception_handler,
+    request_validation_exception_handler,
+)
+from fastapi.exceptions import RequestValidationError
 from fastapi.routing import APIRoute
 from fmu.settings._fmu_dir import UserFMUDirectory
 from fmu.settings._init import init_user_fmu_directory
 from fmu.settings._resources.user_session_log_manager import UserSessionLogManager
 from fmu.settings.models.event_info import EventInfo
+from starlette.exceptions import HTTPException as StarletteHTTPException
 from starlette.middleware.cors import CORSMiddleware
+from starlette.requests import Request
+from starlette.responses import Response
+from starlette.status import HTTP_422_UNPROCESSABLE_CONTENT
 
 from .config import HttpHeader, settings
 from .logging import get_logger, setup_logging
@@ -30,6 +40,56 @@ def custom_generate_unique_id(route: APIRoute) -> str:
 logger = get_logger(__name__)
 
 
+async def logging_http_exception_handler(
+    request: Request,
+    exc: Exception,
+) -> Response:
+    """Log a structured ``request_failed`` event for HTTP exceptions, then delegate."""
+    if not isinstance(exc, StarletteHTTPException):
+        raise exc
+
+    started_at = getattr(request.state, "request_started_at", None)
+    logger.warning(
+        "request_failed",
+        method=request.method,
+        path=request.url.path,
+        status_code=exc.status_code,
+        error=exc.detail,
+        error_type=type(exc).__name__,
+        duration_ms=(
+            round((time.perf_counter() - started_at) * 1000, 2)
+            if started_at is not None
+            else None
+        ),
+    )
+    return await http_exception_handler(request, exc)
+
+
+async def logging_request_validation_exception_handler(
+    request: Request,
+    exc: Exception,
+) -> Response:
+    """Log ``request_failed`` for validation errors, then delegate."""
+    if not isinstance(exc, RequestValidationError):
+        raise exc
+
+    started_at = getattr(request.state, "request_started_at", None)
+    logger.warning(
+        "request_failed",
+        method=request.method,
+        path=request.url.path,
+        status_code=HTTP_422_UNPROCESSABLE_CONTENT,
+        error=exc.errors(),
+        error_type=type(exc).__name__,
+        duration_ms=(
+            round((time.perf_counter() - started_at) * 1000, 2)
+            if started_at is not None
+            else None
+        ),
+    )
+    return await request_validation_exception_handler(request, exc)
+
+
 @asynccontextmanager
 async def lifespan(app: FastAPI) -> AsyncIterator[None]:
     """App lifespan for startup/shutdown housekeeping.
@@ -67,6 +127,11 @@ async def lifespan(app: FastAPI) -> AsyncIterator[None]:
     lifespan=lifespan,
 )
 app.add_middleware(LoggingMiddleware)
+app.add_exception_handler(StarletteHTTPException, logging_http_exception_handler)
+app.add_exception_handler(
+    RequestValidationError,
+    logging_request_validation_exception_handler,
+)
 app.include_router(api_v1_router, prefix=settings.API_V1_PREFIX)
 
 
diff --git a/src/fmu_settings_api/middleware/logging.py b/src/fmu_settings_api/middleware/logging.py
@@ -5,9 +5,9 @@
 import time
 from typing import TYPE_CHECKING
 
-from fastapi import HTTPException
 from starlette.middleware.base import BaseHTTPMiddleware
 from starlette.responses import JSONResponse
+from starlette.status import HTTP_400_BAD_REQUEST
 
 from fmu_settings_api.logging import get_logger
 
@@ -29,7 +29,8 @@ async def dispatch(
         call_next: Callable[[Request], Awaitable[Response]],
     ) -> Response:
         """Log request and response details."""
-        start_time = time.time()
+        start_time = time.perf_counter()
+        request.state.request_started_at = start_time
 
         logger.info(
             "request_started",
@@ -41,30 +42,19 @@ async def dispatch(
 
         try:
             response = await call_next(request)
-            duration = time.time() - start_time
+            duration = time.perf_counter() - start_time
 
-            logger.info(
-                "request_completed",
-                method=request.method,
-                path=request.url.path,
-                status_code=response.status_code,
-                duration_ms=round(duration * 1000, 2),
-            )
+            if response.status_code < HTTP_400_BAD_REQUEST:
+                logger.info(
+                    "request_completed",
+                    method=request.method,
+                    path=request.url.path,
+                    status_code=response.status_code,
+                    duration_ms=round(duration * 1000, 2),
+                )
             return response
-        except HTTPException as e:
-            duration = time.time() - start_time
-            logger.warning(
-                "request_failed",
-                method=request.method,
-                path=request.url.path,
-                status_code=e.status_code,
-                error=e.detail,
-                error_type=type(e).__name__,
-                duration_ms=round(duration * 1000, 2),
-            )
-            raise
         except Exception as e:
-            duration = time.time() - start_time
+            duration = time.perf_counter() - start_time
             logger.exception(
                 "request_failed",
                 method=request.method,
diff --git a/tests/test_main.py b/tests/test_main.py
@@ -3,12 +3,19 @@
 from datetime import UTC, datetime
 from types import SimpleNamespace
 from typing import Any, cast
-from unittest.mock import MagicMock
+from unittest.mock import MagicMock, patch
 
-from fastapi import status
+from fastapi import FastAPI, HTTPException, status
+from fastapi.exceptions import RequestValidationError
 from fastapi.testclient import TestClient
+from starlette.exceptions import HTTPException as StarletteHTTPException
 
-from fmu_settings_api.__main__ import app
+from fmu_settings_api.__main__ import (
+    app,
+    logging_http_exception_handler,
+    logging_request_validation_exception_handler,
+)
+from fmu_settings_api.middleware.logging import LoggingMiddleware
 from fmu_settings_api.models import Ok
 from fmu_settings_api.session import (
     AccessTokens,
@@ -67,3 +74,78 @@ def test_shutdown_releases_project_lock() -> None:
         lock.release.assert_called_once()
     finally:
         session_manager.storage = original_storage
+
+
+def test_http_exception_logs_request_failed_details() -> None:
+    """Ensure HTTPException emits a detailed request_failed log entry."""
+    test_app = FastAPI()
+    test_app.add_middleware(LoggingMiddleware)
+    test_app.add_exception_handler(
+        StarletteHTTPException,
+        logging_http_exception_handler,
+    )
+    test_app.add_exception_handler(
+        RequestValidationError,
+        logging_request_validation_exception_handler,
+    )
+
+    @test_app.get("/test")
+    async def failing_route() -> None:
+        raise HTTPException(status_code=401, detail="Not authorized")
+
+    with patch("fmu_settings_api.__main__.logger") as mock_logger:
+        with TestClient(test_app) as local_client:
+            response = local_client.get("/test")
+
+        assert response.status_code == status.HTTP_401_UNAUTHORIZED
+
+        warning_calls = [
+            call
+            for call in mock_logger.warning.call_args_list
+            if call[0][0] == "request_failed"
+        ]
+        assert len(warning_calls) > 0
+        log_data = warning_calls[0][1]
+        assert log_data["status_code"] == status.HTTP_401_UNAUTHORIZED
+        assert log_data["error"] == "Not authorized"
+        assert log_data["error_type"] == "HTTPException"
+        assert "duration_ms" in log_data
+        assert log_data["duration_ms"] >= 0
+
+
+def test_validation_exception_logs_request_failed_details() -> None:
+    """Ensure validation errors emit a detailed request_failed log entry."""
+    test_app = FastAPI()
+    test_app.add_middleware(LoggingMiddleware)
+    test_app.add_exception_handler(
+        StarletteHTTPException,
+        logging_http_exception_handler,
+    )
+    test_app.add_exception_handler(
+        RequestValidationError,
+        logging_request_validation_exception_handler,
+    )
+
+    @test_app.get("/test")
+    async def validation_route(limit: int) -> dict[str, int]:
+        return {"limit": limit}
+
+    with patch("fmu_settings_api.__main__.logger") as mock_logger:
+        with TestClient(test_app) as local_client:
+            response = local_client.get("/test?limit=bad")
+
+        assert response.status_code == status.HTTP_422_UNPROCESSABLE_CONTENT
+
+        warning_calls = [
+            call
+            for call in mock_logger.warning.call_args_list
+            if call[0][0] == "request_failed"
+        ]
+        assert len(warning_calls) > 0
+        log_data = warning_calls[0][1]
+        assert log_data["status_code"] == status.HTTP_422_UNPROCESSABLE_CONTENT
+        assert isinstance(log_data["error"], list)
+        assert len(log_data["error"]) > 0
+        assert log_data["error_type"] == "RequestValidationError"
+        assert "duration_ms" in log_data
+        assert log_data["duration_ms"] >= 0
diff --git a/tests/test_middleware_logging.py b/tests/test_middleware_logging.py
@@ -3,7 +3,7 @@
 import contextlib
 from unittest.mock import patch
 
-from fastapi import FastAPI, status
+from fastapi import FastAPI, HTTPException, status
 from fastapi.testclient import TestClient
 from starlette.responses import JSONResponse
 
@@ -163,6 +163,38 @@ async def test_route() -> JSONResponse:
         assert request_completed_call[0][1]["status_code"] == status.HTTP_201_CREATED
 
 
+def test_logging_middleware_skips_request_completed_for_http_errors() -> None:
+    """Test middleware only logs request_completed for responses with status < 400."""
+    app = FastAPI()
+    app.add_middleware(LoggingMiddleware)
+
+    @app.get("/test")
+    async def test_route() -> None:
+        raise HTTPException(status_code=422, detail="Invalid configuration")
+
+    with patch("fmu_settings_api.middleware.logging.logger") as mock_logger:
+        with TestClient(app) as client:
+            response = client.get("/test")
+
+        assert response.status_code == status.HTTP_422_UNPROCESSABLE_CONTENT
+
+        completed_calls = [
+            call
+            for call in mock_logger.info.call_args_list
+            if call[0][0] == "request_completed"
+        ]
+        assert len(completed_calls) == 0
+
+        # HTTPException handling is owned by app-level exception handlers.
+        # Middleware should not emit request_failed here, to avoid duplicate logs.
+        failed_calls = [
+            call
+            for call in mock_logger.warning.call_args_list
+            if call[0][0] == "request_failed"
+        ]
+        assert len(failed_calls) == 0
+
+
 def test_logging_middleware_logs_error_details() -> None:
     """Test middleware logs error type and message on failure."""
     app = FastAPI()
