日志与可观测性基线

更新日期：2025-10-19 · 维护者：Codex
关联任务：P1-BE-006

Phase 1 为 FastAPI/Celery 后端铺设了统一的 JSON 日志基线，便于后续在 Docker / Prometheus / OpenTelemetry 中扩展。本文档介绍配置、上下文约定以及本地查看方式。

1. 技术栈

structlog 24.x：负责 JSON 序列化、上下文绑定（通过 contextvars）。
标准 logging：uvicorn / Celery 等第三方库仍使用 logging；我们通过 structlog.stdlib.LoggerFactory 进行桥接。
RequestContextMiddleware：自动为每个 HTTP 请求生成或透传 X-Request-ID，并写入日志上下文。

所有初始化逻辑位于 backend/src/eval_752/app/logging.py，在 app/main.py 导入模块时自动执行 configure_logging()。

2. 日志格式

{
  "event": "healthz.check",
  "logger": "eval_752.app.main",
  "level": "info",
  "timestamp": "2025-10-19T08:12:34.567Z",
  "request_id": "7f3d3aa7a4b444cfaf3e1f8bdbf8f6ad",
  "run_id": "run-1234",
  "extra": "value"
}

字段说明：

request_id：来自 X-Request-ID 头；若缺省则自动生成。
run_id：通过 bind_run_id("run-1234") 或 with run_context("run-1234"): 显式绑定，用于队列任务串联。
其它业务字段可通过 logger.info("event", key=value) 方式附加。

2026-03-11 起，若浏览器用户在 Settings 中显式开启 onboarding telemetry，后端还会记录 onboarding_telemetry.received 事件。该事件仅包含教程生命周期字段（started / step_viewed / completed / dismissed）、路由、时区、教程版本与匿名 session id；不会记录 prompt、dataset 名称、provider 名称或任何自由输入文本。

3. 使用姿势

3.1 FastAPI 路由

from eval_752.app.logging import get_logger

logger = get_logger(__name__)

@router.get("/healthz")
async def healthz() -> dict[str, str]:
    logger.info("healthz.check")
    return {"status": "ok"}

RequestContextMiddleware 已自动添加到应用中，并透传 X-Request-ID。

3.2 Celery / 后台任务

from eval_752.app.logging import get_logger, run_context

logger = get_logger(__name__)

@celery_app.task
def process_run(run_id: str) -> None:
    with run_context(run_id):
        logger.info("worker.run.start", run_id=run_id)
        ...

run_context 会在 block 内绑定 run_id 并在结束时清理，避免上下文泄漏。

3.3 手动绑定/清理

bind_run_id(value): 持久化绑定直到显式 bind_run_id(None) 或离开请求上下文。
structlog.contextvars.bind_contextvars(...): 仍可直接绑定额外键值（例如 dataset_id）。

4. 请求追踪

所有响应都会包含 X-Request-ID（默认 32 字节 hex）。
自定义请求 ID：在请求头添加 X-Request-ID: <value>，后端将原样透传。
下一阶段计划：在 frontend fetch 封装中自动生成 request id，并在 Celery pipeline 中继续传递。

5. Prometheus 指标

PrometheusMiddleware（backend/src/eval_752/app/metrics.py）负责统计 HTTP 请求计数、延迟与并发数； Prometheus Info 指标记录当前部署版本。
暴露端点：GET /metrics（text/plain; version=0.0.4; charset=utf-8），可供 Prometheus/Grafana Agent/Vector 等采集。
主要指标：
- eval752_http_requests_total{method, path, status_code}
- eval752_http_request_duration_seconds_bucket|sum|count
- eval752_http_requests_in_progress{method, path}
- eval752_build_info{version}

5.1 Worker 指标（取消轮询）

为评估取消轮询带来的数据库开销与延迟，Celery worker 暴露以下指标（见 backend/src/eval_752/workers/metrics.py）：

runs_cancel_poll_count：Worker 检查取消状态的次数。
runs_cancel_poll_db_queries_total：检查取消状态期间执行的数据库查询次数。
runs_cancel_poll_latency_seconds_bucket|sum|count：单次取消状态查询的延迟（直方图）。

配合 Settings 页面里的 cancellation check interval 控制（见配置说明），可在 Grafana 中观察不同间隔设置下的 DB 往返次数与平均延迟，辅助选择默认值。

pytest 使用 reset_metrics_for_testing() 复位计数器，防止测试间串扰。

部署采集建议：

Docker Compose：在 Prometheus 服务中添加 scrape_configs，指向 backend:8000/metrics。
Kubernetes：通过 ServiceMonitor/PodMonitor 或直接配置 Prometheus Operator。

6. 后续扩展

OpenTelemetry：logging.py 保留 OTLP 输出扩展点，可在 Phase 2 接入。
Log shipping：在 Compose/K8s 中接入 Fluent Bit / Vector 进行集中收集与转发。

7. 验证

本地快速验证：

uv run uvicorn eval_752.app.main:app --reload
curl -i http://localhost:8000/healthz
curl -s http://localhost:8000/metrics | head
tail -f backend/uvicorn.log # 或观察终端输出

Vitest/pytest 覆盖：

backend/tests/app/test_logging.py：确保 JSON 序列化与上下文绑定。
backend/tests/test_health.py 与 backend/tests/app/test_metrics.py：验证 X-Request-ID、Prometheus 指标输出及请求统计。

如需对日志字段做额外约束，请在 logging.py 中调整 structlog.configure(processors=...) 并同步更新此文档。

#日志与可观测性基线

#1. 技术栈

#2. 日志格式

#3. 使用姿势

#3.1 FastAPI 路由

#3.2 Celery / 后台任务

#3.3 手动绑定/清理

#4. 请求追踪

#5. Prometheus 指标

#5.1 Worker 指标（取消轮询）

#6. 后续扩展

#7. 验证