Fix logging middleware

Signed-off-by: jamshale <[email protected]>

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,23 +1,31 @@
-# import api.core.logconfig
+
+import traceback
+import structlog
 import os
 import time
 import uuid
 from pathlib import Path
+from fastapi import status as http_status
 
-import structlog
 import uvicorn
 from api.core.config import settings
-from api.core.oidc.provider import init_provider
 from fastapi import FastAPI
-from fastapi.middleware.cors import CORSMiddleware
 from starlette.requests import Request
 from starlette.responses import Response
+from fastapi.responses import JSONResponse
+from fastapi.middleware.cors import CORSMiddleware
 
 from .clientConfigurations.router import router as client_config_router
 from .db.session import get_db, init_db
 from .routers import acapy_handler, oidc, presentation_request, well_known_oid_config
-from .routers.socketio import sio_app
 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
 
 logger: structlog.typing.FilteringBoundLogger = structlog.getLogger(__name__)
 
@@ -73,9 +81,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()),
@@ -86,14 +92,25 @@ 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)
+
+            # Need to explicitly log the traceback as json here. Not clear as to why.
+            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")
@@ -118,4 +135,4 @@ def main():
 
 if __name__ == "__main__":
     logger.info("main.")
-    uvicorn.run(app, host="0.0.0.0", port=5100)
+    uvicorn.run(app, host="0.0.0.0", port=5100)