Fix logging middleware exception handling

Signed-off-by: jamshale <jamiehalebc@gmail.com>

oidc-controller/api/core/logger_util.py

@@ -1,8 +1,9 @@
 import structlog
 import time
+from typing import Callable, Any
 
+logger = structlog.getLogger(__name__)
 
-from typing import Callable, Any
 
 
 def log_debug(func: Callable[..., Any]) -> Callable[..., Any]:
@@ -20,3 +21,11 @@ def wrapper(*args, **kwargs):
         return ret_val
 
     return wrapper
+
+
+def extract_error_msg_from_traceback_exc(format_exc) -> str:
+    try:
+        return format_exc.splitlines()[-1].split(": ")[1:][0]
+    except Exception:
+        logger.error(f"Failed to extract error message from traceback: {format_exc}")
+        return "Unknown error"

oidc-controller/api/main.py

@@ -1,25 +1,27 @@
-# import api.core.logconfig
-import logging
-import logging.config
+
+import traceback
 import structlog
 import os
 import time
 import uuid
 from pathlib import Path
+from fastapi import status as http_status
 
 import uvicorn
 from api.core.config import settings
 from fastapi import FastAPI
 from starlette.requests import Request
 from starlette.responses import Response
-from fastapi.responses import HTMLResponse
+from fastapi.responses import JSONResponse
 from fastapi.middleware.cors import CORSMiddleware
 
 from .routers import acapy_handler, oidc, presentation_request, well_known_oid_config
 from .verificationConfigs.router import router as ver_configs_router
 from .clientConfigurations.router import router as client_config_router
 from .db.session import init_db, get_db
 from .routers.socketio import sio_app
+from api.core.logger_util import extract_error_msg_from_traceback_exc
+from api.core.models import GenericErrorMessage
 
 from api.core.oidc.provider import init_provider
 
@@ -77,9 +79,7 @@ def get_application() -> FastAPI:
 
 @app.middleware("http")
 async def logging_middleware(request: Request, call_next) -> Response:
-    # clear the threadlocal context
     structlog.threadlocal.clear_threadlocal()
-    # bind threadlocal
     structlog.threadlocal.bind_threadlocal(
         logger="uvicorn.access",
         request_id=str(uuid.uuid4()),
@@ -90,14 +90,24 @@ async def logging_middleware(request: Request, call_next) -> Response:
     start_time = time.time()
     try:
         response: Response = await call_next(request)
+        return response
     finally:
         process_time = time.time() - start_time
-        logger.info(
-            "processed a request",
-            status_code=response.status_code,
-            process_time=process_time,
-        )
-    return response
+        # If we have a response object, log the details
+        if 'response' in locals():
+            logger.info("processed a request", status_code=response.status_code, process_time=process_time)
+        # Otherwise, extract the exception from traceback, log and return a 500 response
+        else:
+            logger.info("failed to process a request", status_code=500, process_time=process_time)
+
+            if os.environ.get("LOG_WITH_JSON") is True:
+                logger.error(traceback.format_exc())
+
+            return JSONResponse(
+                status_code=http_status.HTTP_500_INTERNAL_SERVER_ERROR,
+                content=GenericErrorMessage(
+                    detail=extract_error_msg_from_traceback_exc(traceback.format_exc())).dict()
+            )
 
 
 @app.on_event("startup")