All checks were successful
Deploy Trade-In / changes (push) Successful in 11s
Deploy Trade-In / build-browser (push) Has been skipped
Deploy Trade-In / build-frontend (push) Has been skipped
Deploy Trade-In / test (push) Successful in 48s
Deploy Trade-In / build-backend (push) Successful in 1m0s
Deploy Trade-In / deploy (push) Successful in 51s
RequestAuditMiddleware logs api_request + deduped login per authenticated /api/* request; estimate() logs estimate_request with address. Fire-and-forget, never blocks/breaks the request. Writes to user_events (Feature 2/3 capture).
146 lines
6.4 KiB
Python
146 lines
6.4 KiB
Python
"""Сервис записи в `user_events` — Feature 2 (login/IP audit) + база для Feature 3
|
||
(behavior analytics).
|
||
|
||
`user_events` (migration `184_user_events.sql`) — unified append-only event log,
|
||
admin-read-only. Запись события НИКОГДА не должна ронять реальный HTTP-запрос:
|
||
любая ошибка (БД недоступна, сетевой сбой, схема разъехалась) ловится и логируется
|
||
через `logger.warning`, без re-raise — вызывающий код (middleware / handler)
|
||
продолжает работать так, как если бы аудит был выключен.
|
||
"""
|
||
|
||
from __future__ import annotations
|
||
|
||
import asyncio
|
||
import json
|
||
import logging
|
||
import threading
|
||
from datetime import UTC, datetime
|
||
from typing import Any
|
||
|
||
from sqlalchemy import text
|
||
|
||
from app.core.db import SessionLocal
|
||
|
||
logger = logging.getLogger(__name__)
|
||
|
||
|
||
def record_event(
|
||
*,
|
||
event_type: str,
|
||
username: str,
|
||
ip: str | None = None,
|
||
user_agent: str | None = None,
|
||
path: str | None = None,
|
||
method: str | None = None,
|
||
estimate_id: str | None = None,
|
||
payload: dict[str, Any] | None = None,
|
||
) -> None:
|
||
"""Синхронно вставляет одну строку в `user_events`.
|
||
|
||
Открывает СОБСТВЕННУЮ сессию (`SessionLocal()`), декаплённую от транзакции
|
||
вызывающего запроса — событие коммитится независимо и переживает rollback
|
||
основного хендлера (и наоборот: сбой записи события не трогает основную tx,
|
||
т.к. она уже закоммичена/не связана с этой сессией).
|
||
|
||
Никогда не поднимает исключение — вызывающий код (middleware / endpoint)
|
||
не должен падать из-за проблем с аудит-логом.
|
||
"""
|
||
try:
|
||
with SessionLocal() as db:
|
||
db.execute(
|
||
text(
|
||
"""
|
||
INSERT INTO user_events
|
||
(event_type, username, ip_address, user_agent, path, method,
|
||
estimate_id, payload)
|
||
VALUES
|
||
(:event_type, :username, CAST(:ip AS inet), :user_agent, :path,
|
||
:method, CAST(:estimate_id AS uuid), CAST(:payload AS jsonb))
|
||
"""
|
||
),
|
||
{
|
||
"event_type": event_type,
|
||
"username": username,
|
||
"ip": ip,
|
||
"user_agent": user_agent,
|
||
"path": path,
|
||
"method": method,
|
||
"estimate_id": estimate_id,
|
||
"payload": json.dumps(payload or {}, ensure_ascii=False),
|
||
},
|
||
)
|
||
db.commit()
|
||
except Exception:
|
||
logger.warning(
|
||
"user_events: failed to record event_type=%r username=%r path=%r",
|
||
event_type,
|
||
username,
|
||
path,
|
||
exc_info=True,
|
||
)
|
||
|
||
|
||
def schedule_event(**kwargs: Any) -> None:
|
||
"""Fire-and-forget обёртка над `record_event` — никогда не блокирует запрос и
|
||
никогда не поднимает исключение наружу.
|
||
|
||
- Есть running event loop (обычный async FastAPI handler / middleware) →
|
||
INSERT уводится в отдельный поток через `asyncio.to_thread`, вызывающая
|
||
корутина не ждёт результата. Ошибки ловятся done-callback'ом и просто
|
||
логируются (иначе asyncio ругался бы "Task exception was never retrieved").
|
||
- Нет running loop (sync-контекст: тесты, Celery task, скрипт) → вызывает
|
||
`record_event(**kwargs)` синхронно inline (она сама никогда не raises).
|
||
"""
|
||
try:
|
||
loop = asyncio.get_running_loop()
|
||
except RuntimeError:
|
||
record_event(**kwargs)
|
||
return
|
||
|
||
try:
|
||
task = loop.create_task(asyncio.to_thread(record_event, **kwargs))
|
||
except Exception:
|
||
logger.warning("user_events: failed to schedule background event", exc_info=True)
|
||
return
|
||
|
||
def _log_task_exception(t: asyncio.Task[None]) -> None:
|
||
if t.cancelled():
|
||
return
|
||
exc = t.exception()
|
||
if exc is not None:
|
||
logger.warning("user_events: background record_event failed: %s", exc)
|
||
|
||
task.add_done_callback(_log_task_exception)
|
||
|
||
|
||
# ---------------------------------------------------------------------------
|
||
# In-process best-effort dedup для login-события.
|
||
# ---------------------------------------------------------------------------
|
||
|
||
_LOGIN_DEDUP_LOCK = threading.Lock()
|
||
_LOGIN_DEDUP_SEEN: set[str] = set()
|
||
_LOGIN_DEDUP_MAX = 50_000
|
||
|
||
|
||
def should_log_login(username: str, ip: str | None, user_agent: str | None) -> bool:
|
||
"""True максимум один раз в сутки на комбинацию (username, ip, user_agent) в
|
||
рамках жизни процесса — держит объём `event_type='login'` строк на уровне
|
||
~одной записи на аккаунт+устройство в день, а не одной на каждый API-запрос.
|
||
|
||
Best-effort/не персистентно: рестарт процесса (деплой, worker respawn)
|
||
сбрасывает in-memory set, так что после рестарта первая комбинация дня
|
||
залогируется заново — недо-дедуп, не потеря данных (для отчётов по
|
||
user_events всё равно используется `DISTINCT (username, ip_address,
|
||
user_agent, date_trunc('day', created_at))`, так что дубликаты не искажают
|
||
метрики, лишь чуть увеличивают объём записи).
|
||
"""
|
||
day = datetime.now(UTC).strftime("%Y-%m-%d")
|
||
key = f"{username}|{ip or ''}|{user_agent or ''}|{day}"
|
||
|
||
with _LOGIN_DEDUP_LOCK:
|
||
if key in _LOGIN_DEDUP_SEEN:
|
||
return False
|
||
if len(_LOGIN_DEDUP_SEEN) >= _LOGIN_DEDUP_MAX:
|
||
_LOGIN_DEDUP_SEEN.clear()
|
||
_LOGIN_DEDUP_SEEN.add(key)
|
||
return True
|