feat: Implement user context propagation and enhance error logging with unique IDs and user details.

.env

@@ -1,5 +1,5 @@
 ENV=development
-LOG_LEVEL=ERROR
+LOG_LEVEL=INFO
 PORT=3020
 HOST=0.0.0.0
 

src/auth/service.py

@@ -31,6 +31,17 @@ class JWTBearer(HTTPBearer):
                 )
 
             request.state.user = user_info
+            
+            from src.context import set_user_id, set_username, set_role
+            if hasattr(user_info, "user_id"):
+                set_user_id(str(user_info.user_id))
+            if hasattr(user_info, "username"):
+                set_username(user_info.username)
+            elif hasattr(user_info, "name"):
+                set_username(user_info.name)
+            if hasattr(user_info, "role"):
+                set_role(user_info.role)
+
             return user_info
         else:
             raise HTTPException(status_code=403, detail="Invalid authorization code.")

src/config.py

@@ -45,7 +45,7 @@ def get_config():
 config = get_config()
 
 
-LOG_LEVEL = config("LOG_LEVEL", default=logging.INFO)
+LOG_LEVEL = config("LOG_LEVEL", default="INFO")
 ENV = config("ENV", default="local")
 PORT = config("PORT", cast=int, default=8000)
 HOST = config("HOST", default="localhost")

src/context.py

@@ -2,8 +2,14 @@ from contextvars import ContextVar
 from typing import Optional, Final
 
 REQUEST_ID_CTX_KEY: Final[str] = "request_id"
-_request_id_ctx_var: ContextVar[Optional[str]] = ContextVar(
+USER_ID_CTX_KEY: Final[str] = "user_id"
-    REQUEST_ID_CTX_KEY, default=None)
+USERNAME_CTX_KEY: Final[str] = "username"
+ROLE_CTX_KEY: Final[str] = "role"
+
+_request_id_ctx_var: ContextVar[Optional[str]] = ContextVar(REQUEST_ID_CTX_KEY, default=None)
+_user_id_ctx_var: ContextVar[Optional[str]] = ContextVar(USER_ID_CTX_KEY, default=None)
+_username_ctx_var: ContextVar[Optional[str]] = ContextVar(USERNAME_CTX_KEY, default=None)
+_role_ctx_var: ContextVar[Optional[str]] = ContextVar(ROLE_CTX_KEY, default=None)
 
 
 def get_request_id() -> Optional[str]:
@@ -16,3 +22,21 @@ def set_request_id(request_id: str):
 
 def reset_request_id(token):
     _request_id_ctx_var.reset(token)
+
+def get_user_id() -> Optional[str]:
+    return _user_id_ctx_var.get()
+
+def set_user_id(user_id: str):
+    return _user_id_ctx_var.set(user_id)
+
+def get_username() -> Optional[str]:
+    return _username_ctx_var.get()
+
+def set_username(username: str):
+    return _username_ctx_var.set(username)
+
+def get_role() -> Optional[str]:
+    return _role_ctx_var.get()
+
+def set_role(role: str):
+    return _role_ctx_var.set(role)

src/exceptions.py

@@ -103,15 +103,38 @@ def handle_exception(request: Request, exc: Exception):
     """
     Global exception handler for Fastapi application.
     """
+    import uuid
+    error_id = str(uuid.uuid1())
     request_info = get_request_context(request)
     
+    # In FastAPI, we don't have a global 'g', but we can pass info in request.state
+    request.state.error_id = error_id
 
     if isinstance(exc, RateLimitExceeded):
-        return _rate_limit_exceeded_handler(request, exc)
+        log.warning(
+            f"Rate limit exceeded | Error ID: {error_id}",
+            extra={
+                "error_id": error_id,
+                "error_category": "rate_limit",
+                "request": request_info,
+                "detail": str(exc.description) if hasattr(exc, "description") else str(exc),
+            },
+        )
+        return JSONResponse(
+            status_code=429,
+            content={
+                "data": None,
+                "message": "Rate limit exceeded",
+                "status": ResponseStatus.ERROR,
+                "error_id": error_id
+            }
+        )
+
     if isinstance(exc, RequestValidationError):
-        log.error(
+        log.warning(
-            "Validation error occurred",
+            f"Validation error occurred | Error ID: {error_id}",
             extra={
+                "error_id": error_id,
                 "error_category": "validation",
                 "errors": exc.errors(),
                 "request": request_info,
@@ -120,16 +143,18 @@ def handle_exception(request: Request, exc: Exception):
         return JSONResponse(
             status_code=422,
             content={
-                "data": None,
+                "data": exc.errors(),
                 "message": "Validation Error",
                 "status": ResponseStatus.ERROR,
-                "errors": exc.errors(),
+                "error_id": error_id
             },
         )
+
     if isinstance(exc, (HTTPException, StarletteHTTPException)):
         log.error(
-            "HTTP exception occurred",
+            f"HTTP exception occurred | Error ID: {error_id}",
             extra={
+                "error_id": error_id,
                 "error_category": "http",
                 "status_code": exc.status_code,
                 "detail": exc.detail if hasattr(exc, "detail") else str(exc),
@@ -143,19 +168,16 @@ def handle_exception(request: Request, exc: Exception):
                 "data": None,
                 "message": str(exc.detail) if hasattr(exc, "detail") else str(exc),
                 "status": ResponseStatus.ERROR,
-                "errors": [
+                "error_id": error_id
-                    ErrorDetail(
-                        message=str(exc.detail) if hasattr(exc, "detail") else str(exc)
-                    ).model_dump()
-                ],
             },
         )
 
     if isinstance(exc, SQLAlchemyError):
         error_message, status_code = handle_sqlalchemy_error(exc)
         log.error(
-            "Database error occurred",
+            f"Database error occurred | Error ID: {error_id}",
             extra={
+                "error_id": error_id,
                 "error_category": "database",
                 "error_message": error_message,
                 "request": request_info,
@@ -169,14 +191,15 @@ def handle_exception(request: Request, exc: Exception):
                 "data": None,
                 "message": error_message,
                 "status": ResponseStatus.ERROR,
-                "errors": [ErrorDetail(message=error_message).model_dump()],
+                "error_id": error_id
             },
         )
 
     # Log unexpected errors
     log.error(
-        "Unexpected error occurred",
+        f"Unexpected error occurred | Error ID: {error_id}",
         extra={
+            "error_id": error_id,
             "error_category": "unexpected",
             "error_message": str(exc),
             "request": request_info,
@@ -188,10 +211,8 @@ def handle_exception(request: Request, exc: Exception):
         status_code=500,
         content={
             "data": None,
-            "message": str(exc),
+            "message": "An unexpected error occurred",
             "status": ResponseStatus.ERROR,
-            "errors": [
+            "error_id": error_id
-                ErrorDetail(message="An unexpected error occurred.").model_dump()
-            ],
         },
     )

src/logging.py

@@ -35,28 +35,44 @@ class JSONFormatter(logging.Formatter):
     Custom formatter to output logs in JSON format.
     """
     def format(self, record):
-        from src.context import get_request_id
+        from src.context import get_request_id, get_user_id, get_username, get_role
-
         
         request_id = None
+        user_id = None
+        username = None
+        role = None
+
         try:
             request_id = get_request_id()
+            user_id = get_user_id()
+            username = get_username()
+            role = get_role()
         except Exception:
             pass
 
+        # Standard fields from requirements
         log_record = {
-            "timestamp": datetime.datetime.fromtimestamp(record.created).astimezone().isoformat(),
+            "timestamp": datetime.datetime.fromtimestamp(record.created).strftime("%Y-%m-%d %H:%M:%S"),
             "level": record.levelname,
+            "name": record.name,
             "message": record.getMessage(),
-            "logger_name": record.name,
-            "location": f"{record.module}:{record.funcName}:{record.lineno}",
-            "module": record.module,
-            "funcName": record.funcName,
-            "lineno": record.lineno,
-            "pid": os.getpid(),
-            "request_id": request_id,
         }
 
+        # Add Context information if available
+        if user_id:
+            log_record["user_id"] = user_id
+        if username:
+            log_record["username"] = username
+        if role:
+            log_record["role"] = role
+        if request_id:
+            log_record["request_id"] = request_id
+
+        # Add Error context if available
+        if hasattr(record, "error_id"):
+            log_record["error_id"] = record.error_id
+        elif "error_id" in record.__dict__:
+             log_record["error_id"] = record.error_id
 
         # Capture exception info if available
         if record.exc_info:
@@ -67,15 +83,14 @@ class JSONFormatter(logging.Formatter):
             log_record["stack_trace"] = self.formatStack(record.stack_info)
 
         # Add any extra attributes passed to the log call
-        # We skip standard attributes to avoid duplication
         standard_attrs = {
             "args", "asctime", "created", "exc_info", "exc_text", "filename",
             "funcName", "levelname", "levelno", "lineno", "module", "msecs",
             "message", "msg", "name", "pathname", "process", "processName",
-            "relativeCreated", "stack_info", "thread", "threadName"
+            "relativeCreated", "stack_info", "thread", "threadName", "error_id"
         }
         for key, value in record.__dict__.items():
-            if key not in standard_attrs:
+            if key not in standard_attrs and not key.startswith("_"):
                 log_record[key] = value
                 
         log_json = json.dumps(log_record)
@@ -87,7 +102,6 @@ class JSONFormatter(logging.Formatter):
 
         return log_json
 
-
 def configure_logging():
     log_level = str(LOG_LEVEL).upper()  # cast to string
     log_levels = list(LogLevels)

src/main.py

@@ -52,7 +52,7 @@ app.add_exception_handler(Exception, handle_exception)
 app.add_exception_handler(HTTPException, handle_exception)
 app.add_exception_handler(StarletteHTTPException, handle_exception)
 app.add_exception_handler(RequestValidationError, handle_exception)
-app.add_exception_handler(RateLimitExceeded, _rate_limit_exceeded_handler)
+app.add_exception_handler(RateLimitExceeded, handle_exception)
 app.add_exception_handler(SQLAlchemyError, handle_exception)
 
 app.state.limiter = limiter
@@ -80,23 +80,58 @@ async def db_session_middleware(request: Request, call_next):
         response = await call_next(request)
         process_time = (time.time() - start_time) * 1000
         
+        from src.context import get_username, get_role, get_user_id, set_user_id, set_username, set_role
+        
+        # Pull from context or fallback to request.state
+        username = get_username()
+        role = get_role()
+        user_id = get_user_id()
+        
+        user_obj = getattr(request.state, "user", None)
+        if user_obj:
+            if not user_id and hasattr(user_obj, "user_id"):
+                user_id = str(user_obj.user_id)
+                set_user_id(user_id)
+            if not username and hasattr(user_obj, "name"):
+                username = user_obj.name
+                set_username(username)
+            if not role and hasattr(user_obj, "role"):
+                role = user_obj.role
+                set_role(role)
+
+        user_info_str = ""
+        if username:
+            user_info_str = f" | User: {username}"
+        if role:
+            user_info_str += f" ({role})"
+
         log.info(
-            "Request finished",
+            f"HTTP {request.method} {request.url.path} completed in {round(process_time, 2)}ms{user_info_str}",
             extra={
                 "method": request.method,
                 "path": request.url.path,
                 "status_code": response.status_code,
                 "duration_ms": round(process_time, 2),
+                "user_id": user_id,
+                "role": role,
             },
         )
 
     except Exception as e:
+        # Generate an error_id here if it hasn't been generated yet (e.g., if it failed before the handler)
+        error_id = getattr(request.state, "error_id", None)
+        if not error_id:
+            import uuid
+            error_id = str(uuid.uuid1())
+            request.state.error_id = error_id
+
         log.error(
-            "Request failed",
+            f"Request failed | Error ID: {error_id}",
             extra={
                 "method": request.method,
                 "path": request.url.path,
                 "error": str(e),
+                "error_id": error_id,
             },
             exc_info=True,
         )

src/middleware.py

@@ -37,7 +37,7 @@ SQLI_PATTERN = re.compile(
 )
 
 RCE_PATTERN = re.compile(
-    r"(\$\(|.*|[;&|]\s*(cat|ls|id|whoami|pwd|ifconfig|ip|netstat|nc|netcat|nmap|curl|wget|python|php|perl|ruby|bash|sh|cmd|powershell|pwsh|sc\s+|tasklist|taskkill|base64|sudo|crontab|ssh|ftp|tftp)|"
+    r"(\$\(|`.*`|[;&|]\s*(cat|ls|id|whoami|pwd|ifconfig|ip|netstat|nc|netcat|nmap|curl|wget|python|php|perl|ruby|bash|sh|cmd|powershell|pwsh|sc\s+|tasklist|taskkill|base64|sudo|crontab|ssh|ftp|tftp)|"
     r"\b(cat|ls|id|whoami|pwd|ifconfig|ip|netstat|nc|netcat|nmap|curl|wget|python|php|perl|ruby|bash|sh|cmd|powershell|pwsh|base64|sudo|crontab)\b|"
     r"/etc/passwd|/etc/shadow|/etc/group|/etc/issue|/proc/self/|/windows/system32/|C:\\Windows\\)",
     re.IGNORECASE,