diff --git a/.env b/.env index 7acb2f1..21ec9b5 100644 --- a/.env +++ b/.env @@ -1,5 +1,5 @@ ENV=development -LOG_LEVEL=ERROR +LOG_LEVEL=INFO PORT=3020 HOST=0.0.0.0 diff --git a/src/auth/service.py b/src/auth/service.py index 1fde033..3649975 100644 --- a/src/auth/service.py +++ b/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.") diff --git a/src/config.py b/src/config.py index d30f24a..7a99e3d 100644 --- a/src/config.py +++ b/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") diff --git a/src/context.py b/src/context.py index 4c968a2..779a3e4 100644 --- a/src/context.py +++ b/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( - REQUEST_ID_CTX_KEY, default=None) +USER_ID_CTX_KEY: Final[str] = "user_id" +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) diff --git a/src/exceptions.py b/src/exceptions.py index ca15852..25b345e 100644 --- a/src/exceptions.py +++ b/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( - "Validation error occurred", + log.warning( + 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": [ - ErrorDetail( - message=str(exc.detail) if hasattr(exc, "detail") else str(exc) - ).model_dump() - ], + "error_id": error_id }, ) 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": [ - ErrorDetail(message="An unexpected error occurred.").model_dump() - ], + "error_id": error_id }, ) diff --git a/src/logging.py b/src/logging.py index e815405..412a1c2 100644 --- a/src/logging.py +++ b/src/logging.py @@ -35,29 +35,45 @@ 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: log_record["exception"] = self.formatException(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) diff --git a/src/main.py b/src/main.py index b683894..dcb6524 100644 --- a/src/main.py +++ b/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, ) diff --git a/src/middleware.py b/src/middleware.py index fdb2bb1..d87190c 100644 --- a/src/middleware.py +++ b/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,