audit_log_middleware зарегистрирован через app.middleware("http") (main.py:92)
→ async dispatch на event loop. После `await call_next(...)` response уже
отдан, но БЛОКИРУЕТ event loop пока идёт sync DB round-trip (SessionLocal/
execute/commit). Это останавливает ВСЕ другие запросы на loop'е до завершения
INSERT'а. При исчерпании connection pool (default 5+10, sync analyze держит
сессию ~15с inline-wait) checkout ждёт pool_timeout=30с НА loop'е → весь API,
включая /health, замирает.
Каждый аудируемый запрос: analyze, КАЖДЫЙ 2с-poll GET /forecast, export,
insight-write. На активной демо-сессии — десятки таких в минуту.
Fix: write_audit_row выполняется через fastapi.concurrency.run_in_threadpool
— sync IO в worker-потоке, event loop свободен для других запросов. Никаких
изменений в самой write_audit_row — она остаётся sync def с собственным
try/except + rollback.
16/16 audit-middleware тестов зелёные (поведение для caller'а не изменилось).
Closes #1202
195 lines
9.1 KiB
Python
195 lines
9.1 KiB
Python
"""§19 audit log middleware (#962, EPIC18).
|
||
|
||
Best-effort аудит ключевых/чувствительных действий через FastAPI HTTP-middleware.
|
||
Регистрируется в ``app/main.py`` ПОСЛЕ ``rbac_guard`` (Starlette applies middleware
|
||
в обратном порядке регистрации, поэтому rbac_guard должен оставаться внешним —
|
||
аудитим только запросы, которые RBAC уже пропустил).
|
||
|
||
Аудируем sensitive actions из ТЗ §19:
|
||
|
||
* ``POST /api/v1/parcels/{cad}/analyze`` → action='analyze'
|
||
* ``GET /api/v1/parcels/{cad}/forecast`` → action='forecast'
|
||
* ``GET /api/v1/parcels/{cad}/forecast/export`` → action='export'
|
||
* ``POST|PUT|DELETE /api/v1/insights[/{id}]`` → action='insight_write' (#948)
|
||
|
||
Insight WRITES (POST/PUT/DELETE) — чувствительные ручные записи (§19); их
|
||
аудируем. GET-чтения insight'ов НЕ аудируются (read-only, не мутируют).
|
||
``/health``, статика, любые non-matched пути НЕ аудируются.
|
||
|
||
Гарантии:
|
||
* Сбой записи в ``audit_log`` НИКОГДА не ломает и не замедляет-фейлит реальный
|
||
запрос — write обёрнут в try/except, ошибка логируется, отдаётся настоящий
|
||
response.
|
||
* Запись делается ПОСЛЕ ``call_next`` (когда response уже готов и status_code
|
||
известен) — off the critical latency path.
|
||
* В ``settings.testing`` middleware пропускает аудит (как rbac_guard) — юнит-тесты
|
||
бьют по app мимо Caddy; аудит-логика покрыта напрямую через
|
||
``classify_path`` / ``write_audit_row`` в tests/test_audit_middleware.py.
|
||
|
||
DB-write использует свежий ``SessionLocal()`` (сессия запроса в middleware
|
||
недоступна), commit + close — всё в try/except.
|
||
"""
|
||
|
||
from __future__ import annotations
|
||
|
||
import logging
|
||
import re
|
||
from collections.abc import Awaitable, Callable
|
||
|
||
from fastapi import Request
|
||
from fastapi.concurrency import run_in_threadpool
|
||
from fastapi.responses import Response
|
||
from sqlalchemy import text
|
||
|
||
from app.core.auth import get_role
|
||
from app.core.config import settings
|
||
from app.core.db import SessionLocal
|
||
|
||
logger = logging.getLogger(__name__)
|
||
|
||
# Кадастровый номер в пути: 66:41:0204016:10 (цифры/двоеточия). Берём «жадный»
|
||
# сегмент между /parcels/ и следующим действием — не парсим формат строго,
|
||
# чтобы не ломаться на нестандартных кад. номерах.
|
||
_CAD = r"(?P<cad>[^/]+)"
|
||
|
||
# Порядок ВАЖЕН: forecast/export проверяем раньше forecast, иначе export
|
||
# заматчится как forecast. Каждый паттерн якорный ($) → точное совпадение пути.
|
||
# Эти пути аудируются НЕЗАВИСИМО от HTTP-метода (parcels-действия из §19).
|
||
_AUDIT_PATTERNS: tuple[tuple[str, re.Pattern[str]], ...] = (
|
||
("export", re.compile(rf"^/api/v1/parcels/{_CAD}/forecast/export$")),
|
||
("analyze", re.compile(rf"^/api/v1/parcels/{_CAD}/analyze$")),
|
||
("forecast", re.compile(rf"^/api/v1/parcels/{_CAD}/forecast$")),
|
||
)
|
||
|
||
# Insight WRITES (#948, §7.13/§8.9): /api/v1/insights и /api/v1/insights/{id}.
|
||
# Аудируем ТОЛЬКО мутации (POST/PUT/DELETE) — GET-чтения insight'ов пропускаем.
|
||
_INSIGHT_PATH = re.compile(r"^/api/v1/insights(?:/[^/]+)?$")
|
||
_INSIGHT_WRITE_METHODS = frozenset({"POST", "PUT", "DELETE"})
|
||
|
||
|
||
def classify_path(path: str, method: str | None = None) -> tuple[str, str | None] | None:
|
||
"""Сопоставить *path* (+ опционально *method*) с аудируемым действием.
|
||
|
||
Returns ``(action, cad_num)`` если путь — sensitive endpoint, иначе ``None``.
|
||
``cad_num`` извлекается из parcels-путей (для insight'ов — ``None``).
|
||
|
||
*method* нужен только для insight-эндпоинтов (аудируем POST/PUT/DELETE, но
|
||
не GET). Parcels-паттерны от метода не зависят. Если *method* не передан
|
||
(``None``), insight-ветка пропускается — обратная совместимость со старыми
|
||
вызовами ``classify_path(path)``.
|
||
"""
|
||
for action, pattern in _AUDIT_PATTERNS:
|
||
m = pattern.match(path)
|
||
if m:
|
||
return action, m.group("cad")
|
||
if method is not None and method in _INSIGHT_WRITE_METHODS and _INSIGHT_PATH.match(path):
|
||
return "insight_write", None
|
||
return None
|
||
|
||
|
||
def write_audit_row(
|
||
*,
|
||
username: str,
|
||
action: str,
|
||
method: str,
|
||
path: str,
|
||
status_code: int,
|
||
cad_num: str | None,
|
||
) -> None:
|
||
"""Best-effort вставка одной строки в ``audit_log``.
|
||
|
||
Открывает свежий ``SessionLocal()``, commit, close — всё в try/except.
|
||
Любая ошибка логируется и ГЛОТАЕТСЯ (re-raise здесь сломал бы основной
|
||
запрос) — это намеренное исключение из «no silent except»: аудит вторичен
|
||
по отношению к запросу пользователя.
|
||
"""
|
||
role: str | None
|
||
try:
|
||
role = get_role(username)
|
||
except KeyError:
|
||
# Юзер прошёл сюда через rbac_guard, так что обычно известен; но
|
||
# на гонке reload roles.yaml / прямом вызове — пишем role=None, не падаем.
|
||
role = None
|
||
|
||
db = SessionLocal()
|
||
try:
|
||
db.execute(
|
||
text(
|
||
"INSERT INTO audit_log "
|
||
"(username, role, action, method, path, cad_num, status_code) "
|
||
"VALUES (:username, :role, :action, :method, :path, :cad_num, "
|
||
":status_code)"
|
||
),
|
||
{
|
||
"username": username,
|
||
"role": role,
|
||
"action": action,
|
||
"method": method,
|
||
"path": path,
|
||
"cad_num": cad_num,
|
||
"status_code": status_code,
|
||
},
|
||
)
|
||
db.commit()
|
||
except Exception:
|
||
# Best-effort: НЕ re-raise — аудит не должен ломать запрос.
|
||
logger.exception(
|
||
"audit_log write failed (user=%s action=%s path=%s) — request unaffected",
|
||
username,
|
||
action,
|
||
path,
|
||
)
|
||
try:
|
||
db.rollback()
|
||
except Exception:
|
||
logger.exception("audit_log rollback failed")
|
||
finally:
|
||
db.close()
|
||
|
||
|
||
async def audit_log_middleware(
|
||
request: Request,
|
||
call_next: Callable[[Request], Awaitable[Response]],
|
||
) -> Response:
|
||
"""Аудируем sensitive actions ПОСЛЕ выполнения запроса (best-effort)."""
|
||
# Test-mode bypass (как rbac_guard). Аудит-логика покрыта напрямую в
|
||
# tests/test_audit_middleware.py через classify_path / write_audit_row.
|
||
if settings.testing:
|
||
return await call_next(request)
|
||
|
||
matched = classify_path(request.url.path, request.method)
|
||
|
||
# Выполняем сам запрос ВСЕГДА (даже non-matched) — сначала получаем response.
|
||
response = await call_next(request)
|
||
|
||
if matched is None:
|
||
return response
|
||
|
||
action, cad_num = matched
|
||
username = request.headers.get("X-Authenticated-User")
|
||
if not username:
|
||
# Без auth-header (локальный curl мимо Caddy) rbac_guard уже отдал бы 401,
|
||
# но если мы тут — нечего атрибутировать, аудит пропускаем.
|
||
return response
|
||
|
||
# Write после готового response — off the critical path для САМОГО клиента
|
||
# (response уже отдан выше), но БЛОКИРУЕТ event loop пока идёт sync DB
|
||
# round-trip (SessionLocal/execute/commit). Это останавливает ВСЕ другие
|
||
# запросы на loop'е до завершения insert'а — а при исчерпании connection
|
||
# pool checkout ждёт `pool_timeout=30s` НА loop'е, замораживая весь API
|
||
# включая /health (#1202). Выполняем write в threadpool через
|
||
# `run_in_threadpool` — sync IO в worker-потоке, event loop свободен.
|
||
try:
|
||
await run_in_threadpool(
|
||
write_audit_row,
|
||
username=username,
|
||
action=action,
|
||
method=request.method,
|
||
path=request.url.path,
|
||
status_code=response.status_code,
|
||
cad_num=cad_num,
|
||
)
|
||
except Exception:
|
||
logger.exception("audit middleware unexpected error — request unaffected")
|
||
|
||
return response
|