|
|
""" |
|
|
API middleware for logging, profiling, and error handling. |
|
|
""" |
|
|
|
|
|
import functools |
|
|
import logging |
|
|
import time |
|
|
from typing import Callable |
|
|
from fastapi import HTTPException, Request |
|
|
from fastapi.responses import JSONResponse |
|
|
|
|
|
logger = logging.getLogger(__name__) |
|
|
|
|
|
try: |
|
|
from .profiler import Profiler, profile_context |
|
|
|
|
|
HAS_PROFILER = True |
|
|
except ImportError: |
|
|
HAS_PROFILER = False |
|
|
|
|
|
|
|
|
def api_endpoint_logging( |
|
|
endpoint_name: str, |
|
|
log_request: bool = True, |
|
|
log_response: bool = True, |
|
|
include_profiling: bool = True, |
|
|
): |
|
|
""" |
|
|
Decorator for API endpoints that adds: |
|
|
- Request/response logging |
|
|
- Error handling with structured error responses |
|
|
- Profiling integration |
|
|
- Timing information |
|
|
|
|
|
Args: |
|
|
endpoint_name: Name of the endpoint for logging |
|
|
log_request: Whether to log request details |
|
|
log_response: Whether to log response details |
|
|
include_profiling: Whether to include profiling |
|
|
""" |
|
|
|
|
|
def decorator(func: Callable) -> Callable: |
|
|
@functools.wraps(func) |
|
|
async def wrapper(*args, **kwargs): |
|
|
request = kwargs.get("request") or ( |
|
|
args[0] if args and isinstance(args[0], Request) else None |
|
|
) |
|
|
|
|
|
|
|
|
request_id = None |
|
|
if request: |
|
|
request_id = ( |
|
|
request.headers.get("X-Request-ID") or f"req_{int(time.time() * 1000)}" |
|
|
) |
|
|
client_ip = request.client.host if request.client else "unknown" |
|
|
method = request.method |
|
|
path = request.url.path |
|
|
query_params = dict(request.query_params) |
|
|
else: |
|
|
client_ip = "unknown" |
|
|
method = "UNKNOWN" |
|
|
path = endpoint_name |
|
|
query_params = {} |
|
|
|
|
|
start_time = time.time() |
|
|
|
|
|
|
|
|
if log_request: |
|
|
logger.info( |
|
|
f"[{endpoint_name}] Request started", |
|
|
extra={ |
|
|
"request_id": request_id, |
|
|
"method": method, |
|
|
"path": path, |
|
|
"client_ip": client_ip, |
|
|
"query_params": query_params, |
|
|
"endpoint": endpoint_name, |
|
|
}, |
|
|
) |
|
|
|
|
|
|
|
|
profiler_context = None |
|
|
if include_profiling and HAS_PROFILER: |
|
|
profiler = Profiler.get_instance() |
|
|
if profiler.enabled: |
|
|
profiler_context = profile_context( |
|
|
stage="api_endpoint", operation=endpoint_name |
|
|
) |
|
|
profiler_context.__enter__() |
|
|
|
|
|
try: |
|
|
|
|
|
if profiler_context: |
|
|
with profile_context(stage="api_endpoint", operation=endpoint_name): |
|
|
result = await func(*args, **kwargs) |
|
|
else: |
|
|
result = await func(*args, **kwargs) |
|
|
|
|
|
duration = time.time() - start_time |
|
|
|
|
|
|
|
|
if log_response: |
|
|
status_code = 200 |
|
|
if hasattr(result, "status_code"): |
|
|
status_code = result.status_code |
|
|
elif isinstance(result, dict) and "status_code" in result: |
|
|
status_code = result["status_code"] |
|
|
|
|
|
logger.info( |
|
|
f"[{endpoint_name}] Request completed successfully", |
|
|
extra={ |
|
|
"request_id": request_id, |
|
|
"duration_ms": duration * 1000, |
|
|
"status_code": status_code, |
|
|
"endpoint": endpoint_name, |
|
|
}, |
|
|
) |
|
|
|
|
|
return result |
|
|
|
|
|
except HTTPException as e: |
|
|
duration = time.time() - start_time |
|
|
|
|
|
logger.warning( |
|
|
f"[{endpoint_name}] HTTP error", |
|
|
extra={ |
|
|
"request_id": request_id, |
|
|
"duration_ms": duration * 1000, |
|
|
"status_code": e.status_code, |
|
|
"detail": str(e.detail), |
|
|
"endpoint": endpoint_name, |
|
|
}, |
|
|
exc_info=True, |
|
|
) |
|
|
raise |
|
|
|
|
|
except ValueError as e: |
|
|
duration = time.time() - start_time |
|
|
|
|
|
logger.error( |
|
|
f"[{endpoint_name}] Validation error", |
|
|
extra={ |
|
|
"request_id": request_id, |
|
|
"duration_ms": duration * 1000, |
|
|
"error": str(e), |
|
|
"endpoint": endpoint_name, |
|
|
}, |
|
|
exc_info=True, |
|
|
) |
|
|
|
|
|
return JSONResponse( |
|
|
status_code=400, |
|
|
content={ |
|
|
"error": "ValidationError", |
|
|
"message": str(e), |
|
|
"request_id": request_id, |
|
|
"endpoint": endpoint_name, |
|
|
}, |
|
|
) |
|
|
|
|
|
except FileNotFoundError as e: |
|
|
duration = time.time() - start_time |
|
|
|
|
|
logger.error( |
|
|
f"[{endpoint_name}] File not found", |
|
|
extra={ |
|
|
"request_id": request_id, |
|
|
"duration_ms": duration * 1000, |
|
|
"error": str(e), |
|
|
"endpoint": endpoint_name, |
|
|
}, |
|
|
exc_info=True, |
|
|
) |
|
|
|
|
|
return JSONResponse( |
|
|
status_code=404, |
|
|
content={ |
|
|
"error": "FileNotFoundError", |
|
|
"message": str(e), |
|
|
"request_id": request_id, |
|
|
"endpoint": endpoint_name, |
|
|
}, |
|
|
) |
|
|
|
|
|
except PermissionError as e: |
|
|
duration = time.time() - start_time |
|
|
|
|
|
logger.error( |
|
|
f"[{endpoint_name}] Permission error", |
|
|
extra={ |
|
|
"request_id": request_id, |
|
|
"duration_ms": duration * 1000, |
|
|
"error": str(e), |
|
|
"endpoint": endpoint_name, |
|
|
}, |
|
|
exc_info=True, |
|
|
) |
|
|
|
|
|
return JSONResponse( |
|
|
status_code=403, |
|
|
content={ |
|
|
"error": "PermissionError", |
|
|
"message": str(e), |
|
|
"request_id": request_id, |
|
|
"endpoint": endpoint_name, |
|
|
}, |
|
|
) |
|
|
|
|
|
except Exception as e: |
|
|
duration = time.time() - start_time |
|
|
|
|
|
|
|
|
logger.error( |
|
|
f"[{endpoint_name}] Unexpected error", |
|
|
extra={ |
|
|
"request_id": request_id, |
|
|
"duration_ms": duration * 1000, |
|
|
"error_type": type(e).__name__, |
|
|
"error": str(e), |
|
|
"endpoint": endpoint_name, |
|
|
}, |
|
|
exc_info=True, |
|
|
) |
|
|
|
|
|
|
|
|
return JSONResponse( |
|
|
status_code=500, |
|
|
content={ |
|
|
"error": "InternalServerError", |
|
|
"message": "An unexpected error occurred", |
|
|
"error_type": type(e).__name__, |
|
|
"request_id": request_id, |
|
|
"endpoint": endpoint_name, |
|
|
}, |
|
|
) |
|
|
|
|
|
finally: |
|
|
if profiler_context: |
|
|
try: |
|
|
profiler_context.__exit__(None, None, None) |
|
|
except Exception: |
|
|
pass |
|
|
|
|
|
return wrapper |
|
|
|
|
|
return decorator |
|
|
|
|
|
|
|
|
def log_execution_time(func_name: str): |
|
|
"""Decorator to log execution time of a function.""" |
|
|
|
|
|
def decorator(func: Callable) -> Callable: |
|
|
@functools.wraps(func) |
|
|
def wrapper(*args, **kwargs): |
|
|
start_time = time.time() |
|
|
try: |
|
|
result = func(*args, **kwargs) |
|
|
duration = time.time() - start_time |
|
|
logger.debug(f"{func_name} executed in {duration:.3f}s") |
|
|
return result |
|
|
except Exception as e: |
|
|
duration = time.time() - start_time |
|
|
logger.error(f"{func_name} failed after {duration:.3f}s: {e}", exc_info=True) |
|
|
raise |
|
|
|
|
|
return wrapper |
|
|
|
|
|
return decorator |
|
|
|
