import json import logging import time import traceback import uuid from contextvars import ContextVar from datetime import datetime, timezone from typing import Any from fastapi import Request from fastapi.exceptions import RequestValidationError from fastapi.responses import JSONResponse from starlette.exceptions import HTTPException as StarletteHTTPException from app.config import settings from app.database import async_session from app.services.log_service import LogService request_id_ctx: ContextVar[str] = ContextVar("request_id", default="-") request_user_ctx: ContextVar[str] = ContextVar("request_user", default="anonymous") request_path_ctx: ContextVar[str] = ContextVar("request_path", default="-") request_method_ctx: ContextVar[str] = ContextVar("request_method", default="-") logger = logging.getLogger("jarvis.request") SENSITIVE_KEYS = {"api_key", "authorization", "password", "current_password", "token", "access_token"} DB_LOG_EXCLUDED_PATH_PREFIXES = ("/api/logs",) class RequestContextFilter(logging.Filter): def filter(self, record: logging.LogRecord) -> bool: record.request_id = request_id_ctx.get() record.user_id = request_user_ctx.get() record.path = request_path_ctx.get() record.method = request_method_ctx.get() return True class JsonFormatter(logging.Formatter): def format(self, record: logging.LogRecord) -> str: payload = { "time": datetime.now(timezone.utc).isoformat(), "level": record.levelname, "logger": record.name, "message": record.getMessage(), "request_id": getattr(record, "request_id", request_id_ctx.get()), "user_id": getattr(record, "user_id", request_user_ctx.get()), "method": getattr(record, "method", request_method_ctx.get()), "path": getattr(record, "path", request_path_ctx.get()), } status_code = getattr(record, "status_code", None) duration_ms = getattr(record, "duration_ms", None) extra_details = getattr(record, "details", None) if status_code is not None: payload["status_code"] = status_code if duration_ms is not None: payload["duration_ms"] = duration_ms if extra_details is not None: payload["details"] = extra_details if record.exc_info: payload["exception"] = self.formatException(record.exc_info) return json.dumps(payload, ensure_ascii=False) class TextFormatter(logging.Formatter): def format(self, record: logging.LogRecord) -> str: record.request_id = getattr(record, "request_id", request_id_ctx.get()) record.user_id = getattr(record, "user_id", request_user_ctx.get()) record.path = getattr(record, "path", request_path_ctx.get()) record.method = getattr(record, "method", request_method_ctx.get()) if not hasattr(record, "status_code"): record.status_code = "-" if not hasattr(record, "duration_ms"): record.duration_ms = "-" return super().format(record) def setup_logging(debug: bool = False) -> None: root_logger = logging.getLogger() if getattr(root_logger, "_jarvis_configured", False): return handler = logging.StreamHandler() handler.addFilter(RequestContextFilter()) if debug: formatter = TextFormatter( "%(asctime)s | %(levelname)s | %(name)s | request_id=%(request_id)s | user=%(user_id)s | %(method)s %(path)s | status=%(status_code)s | duration=%(duration_ms)s | %(message)s" ) else: formatter = JsonFormatter() handler.setFormatter(formatter) root_logger.handlers.clear() root_logger.addHandler(handler) root_logger.setLevel(logging.DEBUG if debug else logging.INFO) logging.getLogger("uvicorn.access").setLevel(logging.WARNING) logging.getLogger("sqlalchemy.engine").setLevel(logging.INFO if debug else logging.WARNING) root_logger._jarvis_configured = True def mask_sensitive(value: Any) -> Any: if isinstance(value, dict): return {k: ("[masked]" if k.lower() in SENSITIVE_KEYS else mask_sensitive(v)) for k, v in value.items()} if isinstance(value, list): return [mask_sensitive(item) for item in value] return value def summarize_llm_config(config: dict | None) -> dict: if not config: return {} summary: dict[str, Any] = {} for key, value in config.items(): if isinstance(value, list): summary[key] = { "count": len(value), "items": [ { "name": item.get("name", ""), "provider": item.get("provider", ""), "model": item.get("model", ""), "has_base_url": bool(item.get("base_url")), "has_api_key": bool(item.get("api_key")), "enabled": item.get("enabled"), } for item in value ], } else: summary[key] = mask_sensitive(value) return summary def should_persist_request_log(path: str) -> bool: return not any(path.startswith(prefix) for prefix in DB_LOG_EXCLUDED_PATH_PREFIXES) async def persist_system_log(**kwargs) -> None: try: async with async_session() as session: await LogService(session).system_log(**kwargs) except Exception: logger.exception("persist_system_log_failed") def build_cors_headers(request: Request) -> dict[str, str]: origin = request.headers.get("origin") if not origin: return {} if "*" in settings.CORS_ORIGINS or origin in settings.CORS_ORIGINS: return { "Access-Control-Allow-Origin": origin, "Access-Control-Allow-Credentials": "true", "Vary": "Origin", } return {} async def request_logging_middleware(request: Request, call_next): request_id = request.headers.get("X-Request-ID") or str(uuid.uuid4()) request.state.request_id = request_id request_id_token = request_id_ctx.set(request_id) path_token = request_path_ctx.set(request.url.path) method_token = request_method_ctx.set(request.method) start = time.perf_counter() response = None logger.info( "request_started", extra={ "details": { "query": dict(request.query_params), "client": request.client.host if request.client else None, } }, ) try: response = await call_next(request) duration_ms = int((time.perf_counter() - start) * 1000) user_id = getattr(request.state, "user_id", "anonymous") request_user_ctx.set(user_id) response.headers["X-Request-ID"] = request_id logger.info( "request_completed", extra={ "status_code": response.status_code, "duration_ms": duration_ms, }, ) if should_persist_request_log(request.url.path): await persist_system_log( message="request_completed", source="http", user_id=user_id if user_id != "anonymous" else None, request_id=request_id, route=request.url.path, method=request.method, status_code=response.status_code, operation="http.request", duration_ms=duration_ms, details={ "query": dict(request.query_params), "client": request.client.host if request.client else None, }, ) return response finally: request_id_ctx.reset(request_id_token) request_path_ctx.reset(path_token) request_method_ctx.reset(method_token) request_user_ctx.set("anonymous") async def log_http_exception(request: Request, exc: StarletteHTTPException): request_id = getattr(request.state, "request_id", request_id_ctx.get()) logger.warning( "http_exception", extra={ "status_code": exc.status_code, "details": {"detail": exc.detail}, }, ) headers = {"X-Request-ID": request_id, **build_cors_headers(request)} return JSONResponse( status_code=exc.status_code, content={"detail": exc.detail, "request_id": request_id}, headers=headers, ) async def log_validation_exception(request: Request, exc: RequestValidationError): request_id = getattr(request.state, "request_id", request_id_ctx.get()) logger.warning( "validation_exception", extra={ "status_code": 422, "details": {"errors": exc.errors()}, }, ) headers = {"X-Request-ID": request_id, **build_cors_headers(request)} return JSONResponse( status_code=422, content={"detail": exc.errors(), "request_id": request_id}, headers=headers, ) async def log_unhandled_exception(request: Request, exc: Exception): request_id = getattr(request.state, "request_id", request_id_ctx.get()) user_id = getattr(request.state, "user_id", None) details = { "error_type": exc.__class__.__name__, "error": str(exc), "traceback": traceback.format_exc(), } logger.error( "unhandled_exception", extra={ "status_code": 500, "details": details, }, ) if should_persist_request_log(request.url.path): await persist_system_log( message="unhandled_exception", source="http", user_id=user_id if user_id not in (None, "anonymous") else None, request_id=request_id, route=request.url.path, method=request.method, status_code=500, error_type=exc.__class__.__name__, operation="http.request", details=details, ) headers = {"X-Request-ID": request_id, **build_cors_headers(request)} return JSONResponse( status_code=500, content={"detail": "服务器内部错误", "request_id": request_id}, headers=headers, )