JARVIS/backend/app/logging_utils.py

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,
    )