From ff33523867502b1837a6547e6f9e28655457409c Mon Sep 17 00:00:00 2001 From: "tao.chen" <93983997+taochen-ct@users.noreply.github.com> Date: Fri, 21 Aug 2026 13:22:00 +0800 Subject: [PATCH] feat(audit): per-request loguru audit middleware with daily rotation MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 按需为每个 HTTP 接口写一条合规记录到 data/logs/audit/audit-YYYY-MM-DD.log,字段:时间 / 用户 / METHOD path / 状态码。 设计: * 复用全局 loguru logger,文件 sink 由 audit._DailyFileSink 自管:缓存当天文件句柄、跨日重建。不走 loguru 的 rotation=00:00(产物是 audit.log.YYYY-MM-DD_HH-MM-SS, 不符合按天单文件的命名要求)。 * AuditMiddleware 只做 CPU 验签拿 user_id:cookie access_token 优先,Authorization Bearer 兜底,无/坏 JWT 一律记 '-'。 绝不查 DB(RequestContext 在路由解析后才注入)。 * 审计失败不拖死请求:所有异常捕获。 * 与 main.py 现有 access_log 严格分离:access_log 走 stderr 诊断(method/path/status/耗时),audit 走独立文件合规 (时间/用户/接口),并存。 * 启动时按 settings.audit_log_retention_days 清理过期文件 (设 0 关闭)。 * 新增 settings.audit_log_dir(默认 data/logs/audit,相对 cwd) 与 settings.audit_log_retention_days(默认 30)两个配置项; .env.example 同步。 新增 9 个 case:文件创建、行字段、未登录 '-'、坏 JWT、ULID path、retention 清理/关闭、Bearer 头、幂等。 --- .env.example | 7 + backend/src/backend/audit.py | 195 ++++++++++++++++++++++++++ backend/src/backend/main.py | 9 ++ backend/tests/test_audit_logging.py | 203 ++++++++++++++++++++++++++++ common/src/common/config.py | 11 ++ 5 files changed, 425 insertions(+) create mode 100644 backend/src/backend/audit.py create mode 100644 backend/tests/test_audit_logging.py diff --git a/.env.example b/.env.example index 3216d94..d1527b7 100644 --- a/.env.example +++ b/.env.example @@ -30,6 +30,13 @@ INITIAL_ADMIN_PASSWORD=admin12345 # runtime_client._jupyter_request. LOG_LEVEL=INFO +# Audit log (backend HTTP interface compliance log). One line per HTTP +# request, written to data/logs/audit/audit-YYYY-MM-DD.log (one file per +# day). AUDIT_LOG_DIR is relative to the backend process cwd (/app in the +# container). AUDIT_LOG_RETENTION_DAYS=0 disables cleanup of old files. +AUDIT_LOG_DIR= +AUDIT_LOG_RETENTION_DAYS=30 + # Object storage. Two modes are supported: # STORAGE_BACKEND=s3 — connects to an S3-compatible service (MinIO, # RustFS, SeaweedFS, AWS S3, …). Requires the diff --git a/backend/src/backend/audit.py b/backend/src/backend/audit.py new file mode 100644 index 0000000..831ea90 --- /dev/null +++ b/backend/src/backend/audit.py @@ -0,0 +1,195 @@ +"""审计日志中间件:每个 HTTP 请求写一条合规记录到独立的按天滚动文件。 + +设计要点 +-------- +* 复用全局 loguru ``logger``(与 ``common.logging.configure_logging`` + 共用同一套日志框架,不新增依赖)。日志文件 sink 由本模块的 + :func:`configure_audit_logging` 在进程启动时挂上,只此一次(幂等, + 与 ``configure_logging`` 的风格一致)。 +* 每天一个文件 ``audit-YYYY-MM-DD.log``,放在 ``settings.audit_log_dir`` + (默认 ``data/logs/audit``,相对 backend 进程 cwd)。滚动由 + :class:`_DailyFileSink` 自行实现:缓存当天的文件句柄,跨自然日时关闭旧 + fd 再打开新文件。不使用 loguru 自带的 ``rotation="00:00"``,因为它对 + string path 产出的文件名是 ``audit.log.YYYY-MM-DD_HH-MM-SS``,既没有 + ``audit-`` 前缀也不符合每天一个文件的要求。 +* 与 ``main.py`` L108 的 ``access_log`` 是两回事,刻意分离: + ``access_log`` 是诊断日志(method / path / status / 耗时),走 stderr; + 本中间件是合规日志(时间 / 用户 / 接口 / 状态码),写独立文件。两者并存。 + +认证解析 +-------- +中间件在路由解析之前执行,拿不到 ``Depends(request_context)`` 注入的结果, +也绝不为此做 DB 查询。用户身份只通过本进程内 CPU 验签解 JWT 得到: +优先 ``access_token`` cookie,其次 ``Authorization: Bearer`` 头;验签 +失败或缺失一律记 ``-``。审计写入自身失败也不得把请求拖死(全部捕获)。 +""" + +from __future__ import annotations + +import os +import time +from collections.abc import Callable +from datetime import UTC, datetime +from pathlib import Path +from typing import TextIO + +from common.auth.jwt import verify_jwt_token +from loguru import logger +from starlette.middleware.base import BaseHTTPMiddleware +from starlette.requests import Request +from starlette.responses import Response + +# 纯文本一行一条(末尾换行由 loguru 的 terminator 追加): +# 2026-08-21 14:30:00.123 | 01USER... | GET /api/v1/scripts/01ABC... -> 200 +AUDIT_LOG_FORMAT = ( + "{time:YYYY-MM-DD HH:mm:ss.SSS} | {extra[user_id]} | " + "{extra[method]} {extra[path]} -> {extra[status]}" +) + +_CONFIGURED: bool = False +_HANDLER_ID: int | None = None + + +class _DailyFileSink: + """按自然日滚动到 ``audit-YYYY-MM-DD.log`` 的 loguru sink。 + + 缓存当天已打开的 ``Path.open("a")`` 文件句柄;跨日时关闭旧 fd 并打开 + 新文件,不依赖 loguru 自己的 rotation。``write`` 收到的是 loguru 已经 + 按 ``AUDIT_LOG_FORMAT`` 格式化好、以 ``\n`` 结尾的一行文本。 + """ + + def __init__(self, log_dir: str | Path) -> None: + self._log_dir = Path(log_dir) + self._log_dir.mkdir(parents=True, exist_ok=True) + self._fh: TextIO | None = None + self._open_date: str | None = None + + def write(self, message: str) -> None: + day = datetime.now(UTC).astimezone().strftime("%Y-%m-%d") + if self._fh is None or self._open_date != day: + self._close() + self._fh = (self._log_dir / f"audit-{day}.log").open( + "a", encoding="utf-8" + ) + self._open_date = day + self._fh.write(message) + + def flush(self) -> None: + if self._fh is not None: + self._fh.flush() + + def stop(self) -> None: + self._close() + + def _close(self) -> None: + if self._fh is not None: + self._fh.close() + self._fh = None + self._open_date = None + + +def _audit_filter(record: dict) -> bool: + """只放行中间件自己打的审计行,其它 INFO 日志不进审计文件。""" + extra = record["extra"] + return ( + record["message"] == "audit" + and "user_id" in extra + and "method" in extra + and "path" in extra + and "status" in extra + ) + + +def _cleanup_expired_files(log_dir: Path, retention_days: int) -> None: + """启动时删除 ``retention_days`` 天前的 ``audit-*.log``;0 表示关闭清理。""" + if retention_days <= 0: + return + cutoff = time.time() - retention_days * 86_400 + for path in log_dir.glob("audit-*.log"): + try: + if os.path.getmtime(path) < cutoff: + path.unlink() + except OSError: + continue + + +def configure_audit_logging(log_dir: str, retention_days: int) -> None: + """挂上审计日志文件 sink。幂等:多次调用只有首次生效。""" + global _CONFIGURED, _HANDLER_ID + if _CONFIGURED: + return + + dir_path = Path(log_dir) + dir_path.mkdir(parents=True, exist_ok=True) + _cleanup_expired_files(dir_path, retention_days) + + # 注意:loguru 的 ``encoding=`` 只对 file-path sink 生效;对 callable / + # stream sink 传入会直接 TypeError。UTF-8 由 _DailyFileSink 在 + # ``open(..., encoding="utf-8")`` 里保证。 + _HANDLER_ID = logger.add( + _DailyFileSink(dir_path), + level="INFO", + format=AUDIT_LOG_FORMAT, + filter=_audit_filter, + enqueue=True, + serialize=False, + catch=True, + ) + _CONFIGURED = True + + +class AuditMiddleware(BaseHTTPMiddleware): + """对每个 HTTP 请求写一行审计记录。 + + 与 ``access_log``(main.py L108)的关系:``access_log`` 是诊断日志 + (方法/路径/状态码/耗时,走 stderr),本中间件是合规日志(时间/用户/ + 接口),写独立文件。两者并存,互不合并。 + + 关键约束:中间件不做 DB 查询、不碰 ``Depends(request_context)``、 + 不修改 response body;用户身份只靠本进程 CPU 验签 JWT 解析。 + """ + + async def dispatch(self, request: Request, call_next: Callable) -> Response: + try: + response = await call_next(request) + except Exception: + # call_next 抛错(例如 websocket upgrade 或未处理的路由异常): + # 仍然写一行 status=0 的审计,并把原始异常继续往上抛,交给全局 + # unhandled_exception_handler 返回 500 —— 审计逻辑本身不吞错、 + # 也不改写响应。 + self._record(request, 0) + raise + self._record(request, response.status_code) + return response + + @staticmethod + def _record(request: Request, status: int) -> None: + token = request.cookies.get("access_token") or "" + if not token: + token = ( + request.headers.get("authorization", "") + .removeprefix("Bearer ") + .strip() + ) + user_id = "-" + if token: + try: + user_id = verify_jwt_token(token)["sub"] + except Exception: # noqa: BLE001 - 验签/解析失败一律记 "-",审计不能因坏 JWT 抛错 + user_id = "-" + try: + logger.bind( + user_id=user_id, + method=request.method, + path=request.url.path, + status=status, + ).info("audit") + except Exception: # noqa: BLE001, S110 - 审计写入失败静默忽略,不能把请求拖死 + pass + + +__all__ = [ + "AUDIT_LOG_FORMAT", + "AuditMiddleware", + "configure_audit_logging", +] diff --git a/backend/src/backend/main.py b/backend/src/backend/main.py index f9df7ae..451993f 100644 --- a/backend/src/backend/main.py +++ b/backend/src/backend/main.py @@ -32,6 +32,7 @@ from fastapi import Request from fastapi.responses import JSONResponse from loguru import logger +from backend.audit import AuditMiddleware, configure_audit_logging from backend.admin import router as admin_router from backend.auth import router as auth_router from backend.jupyter import router as jupyter_router @@ -45,6 +46,10 @@ from backend.scripts import router as scripts_router from backend.storage_api import router as storage_api_router configure_logging(settings.log_level) +configure_audit_logging( + settings.audit_log_dir, + settings.audit_log_retention_days, +) @asynccontextmanager @@ -104,6 +109,10 @@ app.include_router(platform_router) # 内部存储接口额外加上 /internal 前缀,供后端服务间调用,不作为普通前端 API。 app.include_router(storage_api_router, prefix="/internal") +# 审计中间件必须注册在所有路由之后:这样早期 include_router 注册的路由也 +# 会被审计覆盖;access_log 在它外面,负责诊断日志,两者并存。 +app.add_middleware(AuditMiddleware) + @app.middleware("http") async def access_log(request: Request, call_next): diff --git a/backend/tests/test_audit_logging.py b/backend/tests/test_audit_logging.py new file mode 100644 index 0000000..67a6166 --- /dev/null +++ b/backend/tests/test_audit_logging.py @@ -0,0 +1,203 @@ +"""审计日志中间件测试。 + +覆盖: +* 每天一个 ``audit-YYYY-MM-DD.log`` 文件且写入至少一行; +* 日志行包含 user_id / method / path / status; +* 未登录(无 cookie 无 header)与坏 JWT 时 user_id 记 ``-``; +* 带路径参数的请求原样记录实际 path(不替换为 ``{script_id}``); +* 启动时按 mtime 清理超过保留天数的旧 ``audit-*.log``; +* ``configure_audit_logging`` 幂等。 + +测试只注册空路由,不触达 MySQL / 任何真实业务逻辑;``AuditMiddleware`` +挂在独立的临时 FastAPI app 上,用 ``TestClient`` 发请求。 +""" + +from __future__ import annotations + +import os +from datetime import UTC, datetime +from pathlib import Path + +import pytest +from common.auth.jwt import issue_jwt +from fastapi import FastAPI +from fastapi.testclient import TestClient +from loguru import logger + +from backend import audit + + +@pytest.fixture(autouse=True) +def _reset_audit_logging(): + """每个用例之间重置审计模块的幂等标志并卸掉上次挂上的审计 sink。 + + loguru 的全局 logger 会跨用例留存 sink,若不清理,后面的用例会往已 + 删除的临时目录继续写,且 ``_CONFIGURED`` 会让后续 configure 变空操作。 + """ + audit._CONFIGURED = False + yield + if audit._HANDLER_ID is not None: + logger.remove(audit._HANDLER_ID) + audit._HANDLER_ID = None + audit._CONFIGURED = False + + +def _build_client(log_dir: str) -> TestClient: + """配置审计日志并返回挂上 AuditMiddleware 的测试 app 客户端。 + + 只注册空路由,不碰数据库与业务逻辑;中间件与路由的注册顺序与 + ``main.py`` 保持一致(路由先注册,再挂中间件)。 + """ + audit.configure_audit_logging(log_dir, retention_days=30) + + app = FastAPI() + + @app.get("/x") + def x() -> dict: + return {"ok": True} + + @app.get("/api/v1/scripts/{script_id}") + def script(script_id: str) -> dict: + return {"id": script_id} + + app.add_middleware(audit.AuditMiddleware) + return TestClient(app) + + +def _local_today() -> str: + return datetime.now(UTC).astimezone().strftime("%Y-%m-%d") + + +def _today_file(log_dir: Path) -> Path: + return log_dir / f"audit-{_local_today()}.log" + + +def _audit_lines(log_dir: Path) -> list[str]: + """等 enqueue 队列落盘后返回今天审计文件的全部非空行。""" + logger.complete() + path = _today_file(log_dir) + if not path.exists(): + return [] + return [line for line in path.read_text(encoding="utf-8").splitlines() if line] + + +def test_audit_log_file_is_created_with_date_suffix(tmp_path: Path) -> None: + client = _build_client(str(tmp_path)) + client.get("/x") + + lines = _audit_lines(tmp_path) + assert _today_file(tmp_path).exists() + assert len(lines) >= 1 + + +def test_audit_log_line_contains_user_method_path_status(tmp_path: Path) -> None: + client = _build_client(str(tmp_path)) + user_id = "01USER12345678901234567890" + token = issue_jwt(user_id) + client.cookies.set("access_token", token) + response = client.get("/x") + assert response.status_code == 200 + + lines = _audit_lines(tmp_path) + assert lines + assert f"| {user_id} | GET /x -> 200" in lines[0] + + +def test_audit_log_user_id_dash_when_no_jwt(tmp_path: Path) -> None: + client = _build_client(str(tmp_path)) + response = client.get("/x") + assert response.status_code == 200 + + lines = _audit_lines(tmp_path) + assert lines + assert "| - | GET /x -> 200" in lines[0] + + +def test_audit_log_invalid_jwt_does_not_raise_or_skip(tmp_path: Path) -> None: + client = _build_client(str(tmp_path)) + client.cookies.set("access_token", "not.a.jwt") + response = client.get("/x") + # 坏 JWT 不应拖垮请求:响应依旧正常,审计行照样写,user_id 记 "-"。 + assert response.status_code == 200 + + lines = _audit_lines(tmp_path) + assert lines + assert "| - | GET /x -> 200" in lines[0] + + +def test_audit_log_includes_ulid_path_params(tmp_path: Path) -> None: + client = _build_client(str(tmp_path)) + ulid = "01ABCDEFGHIJKLMNOPQRSTUVWXYZ" + response = client.get(f"/api/v1/scripts/{ulid}") + assert response.status_code == 200 + + lines = _audit_lines(tmp_path) + assert lines + # 记录的是实际请求路径,而不是路由模板里的 {script_id}。 + assert f"GET /api/v1/scripts/{ulid} -> 200" in lines[0] + assert "{script_id}" not in lines[0] + + +def test_audit_log_bearer_header_resolves_user(tmp_path: Path) -> None: + """Authorization: Bearer 头同样能解析出 user_id。""" + client = _build_client(str(tmp_path)) + user_id = "01BEARER000000000000000001" + token = issue_jwt(user_id) + response = client.get("/x", headers={"Authorization": f"Bearer {token}"}) + assert response.status_code == 200 + + lines = _audit_lines(tmp_path) + assert lines + assert f"| {user_id} | GET /x -> 200" in lines[0] + + +def test_retention_cleanup_removes_old_files(tmp_path: Path) -> None: + old = tmp_path / "audit-2024-01-01.log" + recent = tmp_path / "audit-2024-06-01.log" + old.write_text("old\n", encoding="utf-8") + recent.write_text("recent\n", encoding="utf-8") + + old_mtime = datetime.now(UTC).timestamp() - 60 * 86_400 # 60 天前 + recent_mtime = datetime.now(UTC).timestamp() - 5 * 86_400 # 5 天前 + os.utime(old, (old_mtime, old_mtime)) + os.utime(recent, (recent_mtime, recent_mtime)) + + audit.configure_audit_logging(str(tmp_path), retention_days=30) + + assert not old.exists(), "超过保留期的旧审计文件应被启动清理删除" + assert recent.exists(), "保留期内(5 天前)的文件应保留" + + +def test_retention_cleanup_disabled_when_zero(tmp_path: Path) -> None: + """AUDIT_LOG_RETENTION_DAYS=0 关闭清理:任何旧文件都不删除。""" + old = tmp_path / "audit-2024-01-01.log" + old.write_text("old\n", encoding="utf-8") + old_mtime = datetime.now(UTC).timestamp() - 400 * 86_400 # 400 天前 + os.utime(old, (old_mtime, old_mtime)) + + audit.configure_audit_logging(str(tmp_path), retention_days=0) + + assert old.exists(), "retention_days=0 时应跳过清理,保留所有旧文件" + + +def test_configure_audit_logging_is_idempotent(tmp_path: Path) -> None: + """多次调用只有首次生效:日志只写到第一次给的目录。""" + first_dir = tmp_path / "first" + second_dir = tmp_path / "second" + + audit.configure_audit_logging(str(first_dir), retention_days=30) + audit.configure_audit_logging(str(second_dir), retention_days=30) + + app = FastAPI() + + @app.get("/x") + def x() -> dict: + return {"ok": True} + + app.add_middleware(audit.AuditMiddleware) + client = TestClient(app) + client.get("/x") + + logger.complete() + assert (first_dir / f"audit-{_local_today()}.log").exists() + assert not (second_dir / f"audit-{_local_today()}.log").exists() diff --git a/common/src/common/config.py b/common/src/common/config.py index 4d78060..8fc9394 100644 --- a/common/src/common/config.py +++ b/common/src/common/config.py @@ -68,6 +68,17 @@ class Settings(BaseSettings): "anything else falls back to INFO inside configure_logging()." ), ) + audit_log_dir: str = Field( + default="data/logs/audit", + description=( + "审计日志目录。每天一个文件 audit-YYYY-MM-DD.log。" + "路径相对于 backend 进程 cwd(容器内通常为 /app)。" + ), + ) + audit_log_retention_days: int = Field( + default=30, + description="审计日志保留天数;过期文件启动时清理。设 0 关闭清理。", + ) # ── runtime container endpoint ─────────────────────────────── runtime_api_url: str = Field(