From ac410e7a5d56e1d37f207fd69eff3a3b59ba7647 Mon Sep 17 00:00:00 2001 From: wangwei Date: Tue, 23 Jun 2026 10:35:00 +0800 Subject: [PATCH] feat: add detailed logging to all API routes and global access log middleware Each API module now logs: - evaluations: trigger (scenario path, task_id), status polls, list - runs: list (count), detail (run_id, metrics, sample counts) - scenarios: list (total, valid, error counts) - pipeline: submit (docs_path, models, max_docs), status polls, list - llm_profiles: CRUD ops (name, model, id), probe/test (model, ok, latency), apply (patched fields) - score: already had per-request logging Global middleware (webapp.access logger): - Every API request: METHOD path -> status (latency_ms) at INFO - Static file requests demoted to DEBUG to reduce noise Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --- webapp/api/evaluations.py | 12 +++- webapp/api/llm_profiles.py | 39 +++++++++-- webapp/api/pipeline.py | 131 +++++++++++++++++++++++++++++++++++++ webapp/api/runs.py | 11 ++++ webapp/api/scenarios.py | 5 ++ webapp/server.py | 20 ++++++ 6 files changed, 213 insertions(+), 5 deletions(-) create mode 100644 webapp/api/pipeline.py diff --git a/webapp/api/evaluations.py b/webapp/api/evaluations.py index 3775b47..8f1034a 100644 --- a/webapp/api/evaluations.py +++ b/webapp/api/evaluations.py @@ -2,6 +2,8 @@ from __future__ import annotations +import logging + from fastapi import APIRouter, HTTPException from webapp.models import ( @@ -13,19 +15,23 @@ from webapp.services import scenario_scanner from webapp.services.task_manager import task_manager router = APIRouter(prefix="/api/evaluations", tags=["evaluations"]) +logger = logging.getLogger("webapp.api.evaluations") @router.post("", response_model=TriggerEvaluationResponse) def trigger_evaluation(request: TriggerEvaluationRequest) -> TriggerEvaluationResponse: """Validate the scenario path and queue a background evaluation task.""" + logger.info("[trigger] scenario=%s", request.scenario_path) resolved = scenario_scanner.resolve_scenario_path(request.scenario_path) if resolved is None: + logger.warning("[trigger] invalid scenario path: %s", request.scenario_path) raise HTTPException( status_code=400, detail=f"无效或不允许的场景路径: {request.scenario_path}", ) task_id = task_manager.submit(request.scenario_path) + logger.info("[trigger] queued task_id=%s scenario=%s", task_id, request.scenario_path) return TriggerEvaluationResponse(task_id=task_id) @@ -34,11 +40,15 @@ def get_task_status(task_id: str) -> TaskStatus: """Return the current status and logs for one evaluation task.""" status = task_manager.get(task_id) if status is None: + logger.warning("[task_status] not found task_id=%s", task_id) raise HTTPException(status_code=404, detail=f"未找到任务: {task_id}") + logger.debug("[task_status] task_id=%s status=%s", task_id, status.status) return status @router.get("", response_model=dict) def list_tasks() -> dict[str, list]: """Return all known evaluation tasks for this server session.""" - return {"tasks": [task.model_dump() for task in task_manager.list_tasks()]} + tasks = task_manager.list_tasks() + logger.info("[list_tasks] count=%d", len(tasks)) + return {"tasks": [task.model_dump() for task in tasks]} diff --git a/webapp/api/llm_profiles.py b/webapp/api/llm_profiles.py index c0c9183..0dfa1a0 100644 --- a/webapp/api/llm_profiles.py +++ b/webapp/api/llm_profiles.py @@ -2,6 +2,7 @@ from __future__ import annotations +import logging import time from fastapi import APIRouter, HTTPException @@ -19,6 +20,7 @@ from webapp.services.profile_manager import profile_manager from webapp.services.yaml_patcher import apply_profiles_to_scenario router = APIRouter(prefix="/api/llm-profiles", tags=["llm-profiles"]) +logger = logging.getLogger("webapp.api.llm_profiles") def _do_connectivity_test( @@ -50,35 +52,44 @@ def _do_connectivity_test( @router.post("/probe", response_model=ProfileTestResponse, tags=["llm-profiles"]) def probe_connectivity(request: ProfileProbeRequest) -> ProfileTestResponse: """Test LLM connectivity with inline credentials (no saved profile required).""" - return _do_connectivity_test( + logger.info("[probe] model=%s base_url=%s", request.model, request.base_url) + result = _do_connectivity_test( model=request.model, base_url=request.base_url, api_key=request.api_key, timeout_seconds=request.timeout_seconds, ) + logger.info("[probe] ok=%s latency=%sms msg=%s", result.ok, result.latency_ms, result.message) + return result @router.get("", response_model=dict) def list_profiles() -> dict: """Return all saved LLM profiles.""" - return {"profiles": [p.model_dump() for p in profile_manager.list_all()]} + profiles = profile_manager.list_all() + logger.info("[list_profiles] count=%d", len(profiles)) + return {"profiles": [p.model_dump() for p in profiles]} @router.post("", status_code=201, response_model=LLMProfile) def create_profile(request: CreateProfileRequest) -> LLMProfile: """Create a new LLM profile.""" - return profile_manager.create( + logger.info("[create_profile] name=%r model=%s base_url=%s", request.name, request.model, request.base_url) + profile = profile_manager.create( name=request.name, model=request.model, base_url=request.base_url, api_key=request.api_key, timeout_seconds=request.timeout_seconds, ) + logger.info("[create_profile] created id=%s", profile.profile_id) + return profile @router.put("/{profile_id}", response_model=LLMProfile) def update_profile(profile_id: str, request: CreateProfileRequest) -> LLMProfile: """Update an existing LLM profile by id.""" + logger.info("[update_profile] id=%s name=%r model=%s", profile_id, request.name, request.model) updated = profile_manager.update( profile_id=profile_id, name=request.name, @@ -88,16 +99,21 @@ def update_profile(profile_id: str, request: CreateProfileRequest) -> LLMProfile timeout_seconds=request.timeout_seconds, ) if updated is None: + logger.warning("[update_profile] not found id=%s", profile_id) raise HTTPException(status_code=404, detail=f"Profile not found: {profile_id}") + logger.info("[update_profile] updated id=%s", profile_id) return updated @router.delete("/{profile_id}", response_model=dict) def delete_profile(profile_id: str) -> dict: """Delete an LLM profile by id.""" + logger.info("[delete_profile] id=%s", profile_id) deleted = profile_manager.delete(profile_id) if not deleted: + logger.warning("[delete_profile] not found id=%s", profile_id) raise HTTPException(status_code=404, detail=f"Profile not found: {profile_id}") + logger.info("[delete_profile] deleted id=%s", profile_id) return {"deleted": True} @@ -106,18 +122,31 @@ def test_profile(profile_id: str) -> ProfileTestResponse: """Test LLM connectivity for a saved profile.""" profile = profile_manager.get(profile_id) if profile is None: + logger.warning("[test_profile] not found id=%s", profile_id) raise HTTPException(status_code=404, detail=f"Profile not found: {profile_id}") - return _do_connectivity_test( + logger.info("[test_profile] id=%s model=%s base_url=%s", profile_id, profile.model, profile.base_url) + result = _do_connectivity_test( model=profile.model, base_url=profile.base_url, api_key=profile.api_key, timeout_seconds=profile.timeout_seconds, ) + logger.info("[test_profile] ok=%s latency=%sms", result.ok, result.latency_ms) + return result @router.post("/apply", response_model=ProfileApplyResponse) def apply_profiles(request: ProfileApplyRequest) -> ProfileApplyResponse: """Patch selected LLM profiles into the target scenario YAML file.""" + logger.info( + "[apply_profiles] scenario=%s judge=%s answer=%s dataset=%s metric_weights=%s doc_weights=%s", + request.scenario_path, + request.judge_profile_id, + request.answer_profile_id, + request.dataset_profile_id, + bool(request.metric_weights), + bool(request.doc_weights), + ) role_profiles: dict[str, LLMProfile | None] = { "judge": profile_manager.get(request.judge_profile_id) if request.judge_profile_id else None, "answer": profile_manager.get(request.answer_profile_id) if request.answer_profile_id else None, @@ -135,6 +164,7 @@ def apply_profiles(request: ProfileApplyRequest) -> ProfileApplyResponse: ] if missing: + logger.warning("[apply_profiles] missing profiles for roles: %s", missing) raise HTTPException( status_code=400, detail=f"Profile(s) not found for roles: {', '.join(missing)}", @@ -148,6 +178,7 @@ def apply_profiles(request: ProfileApplyRequest) -> ProfileApplyResponse: metric_weights=request.metric_weights, doc_weights=request.doc_weights, ) + logger.info("[apply_profiles] patched fields: %s", patched) return ProfileApplyResponse( scenario_path=request.scenario_path, patched_fields=patched, diff --git a/webapp/api/pipeline.py b/webapp/api/pipeline.py new file mode 100644 index 0000000..4115db8 --- /dev/null +++ b/webapp/api/pipeline.py @@ -0,0 +1,131 @@ +"""Routes for the end-to-end pipeline API (document parse → build → eval).""" + +from __future__ import annotations + +import logging + +from fastapi import APIRouter, HTTPException + +from webapp.models import ( + PipelineJobRequest, + PipelineJobResponse, + PipelineJobStatus, +) +from webapp.services.pipeline_task_manager import pipeline_task_manager + +router = APIRouter(prefix="/api/pipeline", tags=["pipeline"]) +logger = logging.getLogger("webapp.api.pipeline") + + +@router.post( + "/jobs", + status_code=202, + response_model=PipelineJobResponse, + summary="提交全链路评估任务", + responses={ + 202: { + "description": "任务已成功排队，立即返回 job_id。", + "content": { + "application/json": { + "example": { + "job_id": "a1b2c3d4e5f6", + "job_name": "siemens-ct-eval-2026", + "status": "queued", + } + } + }, + }, + 422: {"description": "请求参数校验失败（docs_path 等必填字段缺失或格式错误）。"}, + }, +) +def submit_pipeline_job(request: PipelineJobRequest) -> PipelineJobResponse: + """提交一个「解析文档 → 生成题库 → RAGAS 评估 → 输出报告」全链路任务。 + + 任务在后台线程中异步执行，立即返回 `job_id`。 + 通过 `GET /api/pipeline/jobs/{job_id}` 轮询 `status` / `phase` / `logs`。 + + **Pipeline 执行阶段**： + 1. `parsing_documents` — 调用阿里云 DocMind 解析每份 PDF + 2. `generating_questions` — LLM 从文档片段生成草稿题库 + 3. `evaluating` — RAGAS 在线评测打分（answer_model 答题 + judge_model 评分） + 4. `done` — 所有产物写入磁盘，`status` 变为 `completed` + """ + logger.info( + "[submit_pipeline] docs_path=%s job_name=%r gen_model=%s judge=%s max_docs=%s", + request.docs_path, request.job_name, request.generation_model, + request.judge_model, request.max_documents, + ) + task = pipeline_task_manager.submit(request) + logger.info("[submit_pipeline] queued job_id=%s job_name=%s", task.job_id, task.job_name) + return PipelineJobResponse( + job_id=task.job_id, + job_name=task.job_name, + status=task.status, + ) + + +@router.get( + "/jobs/{job_id}", + response_model=PipelineJobStatus, + summary="查询任务状态", + responses={ + 200: {"description": "返回任务当前状态、执行阶段、日志及完成后的产物路径。"}, + 404: {"description": "指定 job_id 的任务不存在。"}, + }, +) +def get_pipeline_job(job_id: str) -> PipelineJobStatus: + """查询一个 Pipeline 任务的当前状态、执行阶段、实时日志和结果。 + + **轮询建议**：每 3–5 秒查询一次，直到 `status` 为 `completed` 或 `failed`。 + + `result` 字段在任务完成后填充，包含： + - `scores_csv` — 每道题目逐项评分 + - `summary_md` — 评估摘要 Markdown + - `dataset_csv` — 生成的题库 CSV + - `source_chunks_jsonl` — 文档片段索引 + """ + status = pipeline_task_manager.get(job_id) + if status is None: + logger.warning("[get_pipeline_job] not found job_id=%s", job_id) + raise HTTPException(status_code=404, detail=f"Pipeline job not found: {job_id}") + logger.debug("[get_pipeline_job] job_id=%s status=%s phase=%s", job_id, status.status, status.phase) + return status + + +@router.get( + "/jobs", + response_model=dict, + summary="列出所有任务", + responses={ + 200: { + "description": "按创建时间倒序返回本次服务器会话中所有的 Pipeline 任务。", + "content": { + "application/json": { + "example": { + "jobs": [ + { + "job_id": "a1b2c3d4e5f6", + "job_name": "siemens-ct-eval", + "status": "completed", + "phase": "done", + "logs": ["[build] 17 documents parsed", "..."], + "result": { + "total_questions": 19, + "eval_run_id": "2026-06-18T...", + "scores_csv": "outputs/pipeline/.../scores.csv", + "summary_md": "outputs/pipeline/.../summary.md", + }, + "error": None, + } + ] + } + } + }, + } + }, +) +def list_pipeline_jobs() -> dict: + """返回本次服务器会话中所有已提交的 Pipeline 任务，按创建时间倒序排列。""" + jobs = pipeline_task_manager.list_jobs() + logger.info("[list_pipeline_jobs] count=%d", len(jobs)) + return {"jobs": [s.model_dump() for s in jobs]} diff --git a/webapp/api/runs.py b/webapp/api/runs.py index da3765d..3af3bcd 100644 --- a/webapp/api/runs.py +++ b/webapp/api/runs.py @@ -2,31 +2,42 @@ from __future__ import annotations +import logging + from fastapi import APIRouter, HTTPException from webapp.models import RunDetail from webapp.services import report_builder, run_reader router = APIRouter(prefix="/api/runs", tags=["runs"]) +logger = logging.getLogger("webapp.api.runs") @router.get("") def get_runs() -> dict[str, list]: """Return summaries for every discoverable evaluation run.""" summaries = run_reader.list_run_summaries() + logger.info("[get_runs] found %d runs", len(summaries)) return {"runs": [summary.model_dump() for summary in summaries]} @router.get("/{run_id}") def get_run_detail(run_id: str) -> RunDetail: """Return the full summary and aggregated report for one run.""" + logger.info("[get_run_detail] run_id=%s", run_id) run_dir = run_reader.find_run_dir(run_id) if run_dir is None: + logger.warning("[get_run_detail] not found run_id=%s", run_id) raise HTTPException(status_code=404, detail=f"未找到运行: {run_id}") summary = run_reader.build_run_summary(run_dir) if summary is None: + logger.warning("[get_run_detail] missing metadata run_id=%s", run_id) raise HTTPException(status_code=404, detail=f"运行元数据缺失: {run_id}") report = report_builder.build_report(run_dir, summary.metrics) + logger.info( + "[get_run_detail] ok run_id=%s metrics=%s valid=%d invalid=%d", + run_id, summary.metrics, summary.valid_samples, summary.invalid_samples, + ) return RunDetail(summary=summary, report=report) diff --git a/webapp/api/scenarios.py b/webapp/api/scenarios.py index 45aa31c..d7ac356 100644 --- a/webapp/api/scenarios.py +++ b/webapp/api/scenarios.py @@ -2,15 +2,20 @@ from __future__ import annotations +import logging + from fastapi import APIRouter from webapp.services import scenario_scanner router = APIRouter(prefix="/api/scenarios", tags=["scenarios"]) +logger = logging.getLogger("webapp.api.scenarios") @router.get("") def get_scenarios() -> dict[str, list]: """Return every scenario file found under the scenarios/ directory.""" scenarios = scenario_scanner.list_scenarios() + valid = sum(1 for s in scenarios if not s.error) + logger.info("[get_scenarios] total=%d valid=%d errors=%d", len(scenarios), valid, len(scenarios) - valid) return {"scenarios": [item.model_dump() for item in scenarios]} diff --git a/webapp/server.py b/webapp/server.py index e941091..d5eff16 100644 --- a/webapp/server.py +++ b/webapp/server.py @@ -8,6 +8,7 @@ the server starts even when the evaluation dependencies are not yet installed. from __future__ import annotations import logging +import time from pathlib import Path from fastapi import FastAPI, Request @@ -20,6 +21,7 @@ from webapp.api import evaluations, llm_profiles, pipeline, runs, scenarios, sco STATIC_DIR = Path(__file__).resolve().parent / "static" logger = logging.getLogger("webapp.server") +access_logger = logging.getLogger("webapp.access") # OpenAPI tag metadata — controls the grouping and descriptions in /docs. OPENAPI_TAGS = [ @@ -107,6 +109,24 @@ def create_app() -> FastAPI: app.include_router(pipeline.router) app.include_router(score.router) + @app.middleware("http") + async def access_log_middleware(request: Request, call_next): + """Log every API request with method, path, status code and latency. + + Static file requests are logged at DEBUG level to keep the console clean. + """ + t0 = time.monotonic() + response = await call_next(request) + latency_ms = int((time.monotonic() - t0) * 1000) + path = request.url.path + is_static = path.startswith("/static/") or path in ("/", "/favicon.ico") + msg = "%s %s → %d (%dms)", request.method, path, response.status_code, latency_ms + if is_static: + access_logger.debug(*msg) + else: + access_logger.info(*msg) + return response + @app.exception_handler(RequestValidationError) async def validation_exception_handler(request: Request, exc: RequestValidationError) -> JSONResponse: """Log full validation error detail to help diagnose 422 responses."""