feat(audit): per-request loguru audit middleware with daily rotation

按需为每个 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 头、幂等。
This commit is contained in:
tao.chen
2026-08-21 13:22:00 +08:00
parent 2b1f6b5303
commit 97825ca86d
5 changed files with 425 additions and 0 deletions
+195
View File
@@ -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",
]
+9
View File
@@ -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):
+203
View File
@@ -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()