peter
b2eaa9e00b
Round 2 of the E22 review, on what round 1 changed. `redact_query` decodes a parameter before the text rules see it, which is what lets `%40` be recognised as an address — but `_SECRET_PARAM_RE` was written for the raw, encoded form, where a value holds no space, `&` or quote. On decoded text its value class stops at the first one, so `?state=a%20b` kept its tail and `?code=%20abc` was not matched at all. The parameter-NAME rule now decides, on the key, before any text rule runs. `forget_user` dropped the account's level elevation without recomputing the root level, so a process whose only elevated account had just deleted itself kept building TRACE records to throw away, until some later request happened to recompute it. Every other path that drops an elevation recomputes. The sink's writer took the erasure lock and THEN waited for a pooled connection, while every request path already holds a connection when it reaches that lock — so under pool pressure the writer held a process-global lock against the very requests that could hand a connection back. Same order on both sides now; the lock still spans the check, the insert and the commit. The storage-budget notice said the rest of the hour was not kept, and then smaller batches kept landing underneath it: the window slides and a refused batch is not charged to it. Says what it does. Tests: the route's half of the erasure rule had no test — only the sink's did — and a source-level contract test now covers the third insert nobody has written yet. `logs._erased` is process-global with an hour's memory while the DB fixture hands serial ids back out from 1, so it is swept before each test like the rate limiters are.
316 lines
13 KiB
Python
316 lines
13 KiB
Python
"""The `log_events` sink (E22 S3): the stored copy of the log the diagnostics console reads.
|
||
|
||
stdout stays the complete log (docker keeps 3×50 MB of it); this table keeps the part worth querying
|
||
for `log_retention_days`:
|
||
|
||
* every WARNING and above,
|
||
* the `http.request` line of every request at INFO or above (not the DEBUG-level health checks and
|
||
static files),
|
||
* every line of a request whose user raised their diagnostics level (E22 S5 — `logs.LevelGate`
|
||
marks them), which is the detail they consented to have kept,
|
||
* nothing a caller marked `extra={logs.PERSIST: False}` — how the request log caps anonymous
|
||
traffic per client.
|
||
|
||
What the table must never do is slow down or break the code that logs. So a line is redacted and
|
||
turned into a row on the CALLER's thread (the same `logs.record_fields` the stdout line is built
|
||
from), put on a bounded queue without blocking, and written in batches by one background thread
|
||
on its own connection — never inside a request's transaction. A full queue drops the row and
|
||
counts it; a failed write drops the batch and says so on stderr. Both are reported rather than
|
||
retried: a log that retries into a sick database is how a small outage becomes a big one.
|
||
|
||
Flood control is the second half. On 2026-09-16 a YouTube RSS outage made prod log 11k near-identical
|
||
warnings in four hours. stdout keeps them all; the table keeps `REPEATS_PER_MINUTE` of each message
|
||
template per minute and one `log.repeats_suppressed` row saying how many more there were.
|
||
|
||
Core layer: imports `logs`, `db`, `models`, `config` — nothing above them.
|
||
"""
|
||
|
||
import atexit
|
||
import json
|
||
import logging
|
||
import queue
|
||
import sys
|
||
import threading
|
||
import time
|
||
from datetime import datetime, timedelta, timezone
|
||
from typing import Any
|
||
|
||
from sqlalchemy import delete, insert
|
||
from sqlalchemy.engine import Engine
|
||
from sqlalchemy.orm import Session
|
||
|
||
from app import logs
|
||
from app.config import settings
|
||
from app.db import engine
|
||
from app.models import LogEvent
|
||
|
||
QUEUE_MAX = 10_000
|
||
BATCH_MAX = 500
|
||
FLUSH_SECONDS = 1.0
|
||
REPEATS_PER_MINUTE = 30
|
||
REPEAT_WINDOW_SECONDS = 60.0
|
||
# Distinct templates tracked per window. Past this many, a new template is stored without counting
|
||
# — the limiter must not become the unbounded thing it exists to prevent.
|
||
_REPEAT_KEYS_MAX = 2_000
|
||
|
||
# Column widths from models.LogEvent. A value past its column would fail the WHOLE batch it rides in.
|
||
_LIMITS = {
|
||
"level": 10,
|
||
"source": 16,
|
||
"logger": 128,
|
||
"event": 64,
|
||
"request_id": 64,
|
||
"debug_session_id": 64,
|
||
"version": 64,
|
||
"msg": 8_000,
|
||
"exc": 32_000,
|
||
}
|
||
|
||
_log = logging.getLogger("siftlode.logsink")
|
||
|
||
|
||
def should_store(record: logging.LogRecord) -> bool:
|
||
"""Whether this record belongs in `log_events` (see the module docstring)."""
|
||
if getattr(record, logs.PERSIST, True) is False:
|
||
return False
|
||
if record.levelno >= logging.WARNING or getattr(record, "elevated", False):
|
||
return True
|
||
return getattr(record, "event", None) == "http.request" and record.levelno >= logging.INFO
|
||
|
||
|
||
def _without_nul(value: Any) -> Any:
|
||
"""`value` with every NUL character replaced, in keys and nested values alike. Postgres refuses
|
||
NUL in text and `\\u0000` in JSONB, and a refused row fails the WHOLE batch it rides in — every
|
||
user's rows with it. Anything logged can carry one (`GET /assets/%00` logs the decoded path)."""
|
||
if isinstance(value, str):
|
||
return value.replace("\x00", "�")
|
||
if isinstance(value, dict):
|
||
return {_without_nul(k): _without_nul(v) for k, v in value.items()}
|
||
if isinstance(value, list):
|
||
return [_without_nul(v) for v in value]
|
||
return value
|
||
|
||
|
||
def to_row(fields: dict[str, Any]) -> dict[str, Any]:
|
||
"""`logs.record_fields` output → a `log_events` row: known columns only, text clipped to its
|
||
column and free of NUL, attrs made JSON-safe (anything exotic becomes its `str`, as on stdout)."""
|
||
row = {
|
||
column: fields.get(column) for column in LogEvent.__table__.columns.keys() if column != "id"
|
||
}
|
||
for column, limit in _LIMITS.items():
|
||
value = row.get(column)
|
||
if isinstance(value, str):
|
||
value = _without_nul(value)
|
||
row[column] = value[: limit - 1] + "…" if len(value) > limit else value
|
||
if row["attrs"] is not None:
|
||
row["attrs"] = _without_nul(
|
||
json.loads(json.dumps(row["attrs"], ensure_ascii=False, default=str))
|
||
)
|
||
return row
|
||
|
||
|
||
def without_erased(rows: list[dict[str, Any]]) -> list[dict[str, Any]]:
|
||
"""The rows, with the account taken off any whose account was erased meanwhile
|
||
(`logs.forget_user`). Checked right before the INSERT, under `logs.erasure_guard()` held until
|
||
the commit: a row built before the erasure can still be waiting for its batch."""
|
||
for row in rows:
|
||
if logs.is_erased(row.get("user_id")):
|
||
row["user_id"] = None
|
||
return rows
|
||
|
||
|
||
def _notice(code: str, msg: str, **attrs: Any) -> dict[str, Any]:
|
||
"""A row the sink writes about ITSELF. Built directly, not logged: logging it would route it back
|
||
through this sink (and the writer thread's own records are deliberately ignored)."""
|
||
return to_row(
|
||
{
|
||
"ts": datetime.now(timezone.utc),
|
||
"level": "WARNING",
|
||
"sev": logs.SEVERITY["WARNING"],
|
||
"source": logs.current_source(),
|
||
"logger": _log.name,
|
||
"event": code,
|
||
"msg": msg,
|
||
"attrs": attrs,
|
||
"version": settings.app_version,
|
||
}
|
||
)
|
||
|
||
|
||
class _Repeats:
|
||
"""Per-template admission for one minute at a time. Used by the writer thread only (unlocked)."""
|
||
|
||
def __init__(self, per_window: int, window_seconds: float):
|
||
self.per_window = per_window
|
||
self.window = window_seconds
|
||
self.started = time.monotonic()
|
||
self.seen: dict[tuple[str, str, int], int] = {}
|
||
|
||
def admit(self, key: tuple[str, str, int] | None) -> bool:
|
||
if key is None:
|
||
return True
|
||
count = self.seen.get(key)
|
||
if count is None and len(self.seen) >= _REPEAT_KEYS_MAX:
|
||
return True
|
||
self.seen[key] = (count or 0) + 1
|
||
return self.seen[key] <= self.per_window
|
||
|
||
def roll(self, now: float) -> list[dict[str, Any]]:
|
||
"""Close the window if it is over: one notice per template that went past the limit."""
|
||
if now - self.started < self.window:
|
||
return []
|
||
notices = [
|
||
_notice(
|
||
"log.repeats_suppressed",
|
||
f"{count - self.per_window} more like this were not stored",
|
||
logger=logger,
|
||
template=logs.redact_text(template),
|
||
suppressed=count - self.per_window,
|
||
window_seconds=int(self.window),
|
||
)
|
||
for (logger, template, _level), count in self.seen.items()
|
||
if count > self.per_window
|
||
]
|
||
self.seen.clear()
|
||
self.started = now
|
||
return notices
|
||
|
||
|
||
class LogSink(logging.Handler):
|
||
"""The handler plus its writer. `start()` runs the writer thread; a test drives `write_pending()`
|
||
directly instead, on its own thread, with no timing involved."""
|
||
|
||
def __init__(self, bind: Engine = engine):
|
||
super().__init__(level=logging.NOTSET)
|
||
# Correlation fields are contextvars: capture them now, on the thread that logged.
|
||
self.addFilter(logs.ContextFilter())
|
||
self._bind = bind
|
||
self._queue: queue.Queue[tuple[tuple[str, str, int] | None, dict[str, Any]]] = queue.Queue(
|
||
QUEUE_MAX
|
||
)
|
||
self._dropped = 0
|
||
self._dropped_lock = threading.Lock()
|
||
self._repeats = _Repeats(REPEATS_PER_MINUTE, REPEAT_WINDOW_SECONDS)
|
||
self._stopping = threading.Event()
|
||
self._writer: threading.Thread | None = None
|
||
|
||
# --- caller side ---------------------------------------------------------------------------
|
||
def emit(self, record: logging.LogRecord) -> None:
|
||
if threading.current_thread() is self._writer:
|
||
return # the writer's own trouble (a driver warning mid-insert) must not feed itself
|
||
if not should_store(record):
|
||
return
|
||
try:
|
||
row = to_row(logs.record_fields(record))
|
||
except Exception: # noqa: BLE001 — a record we cannot turn into a row is reported, not raised
|
||
self.handleError(record)
|
||
return
|
||
# Request lines are one per request by nature; only the repeated SAME message is a flood.
|
||
key = (
|
||
None
|
||
if row["event"] == "http.request"
|
||
else (record.name, str(record.msg), record.levelno)
|
||
)
|
||
try:
|
||
self._queue.put_nowait((key, row))
|
||
except queue.Full:
|
||
with self._dropped_lock:
|
||
self._dropped += 1
|
||
|
||
# --- writer side ---------------------------------------------------------------------------
|
||
def write_pending(self, wait: float = 0.0) -> int:
|
||
"""Write one batch: whatever is queued (up to BATCH_MAX), waiting up to `wait` seconds for the
|
||
first item. Returns the number of rows written, notices included."""
|
||
rows: list[dict[str, Any]] = []
|
||
try:
|
||
item = self._queue.get(timeout=wait) if wait > 0 else self._queue.get_nowait()
|
||
except queue.Empty:
|
||
item = None
|
||
while item is not None:
|
||
key, row = item
|
||
if self._repeats.admit(key):
|
||
rows.append(row)
|
||
if len(rows) >= BATCH_MAX:
|
||
break
|
||
try:
|
||
item = self._queue.get_nowait()
|
||
except queue.Empty:
|
||
item = None
|
||
rows.extend(self._repeats.roll(time.monotonic()))
|
||
with self._dropped_lock:
|
||
dropped, self._dropped = self._dropped, 0
|
||
if dropped:
|
||
rows.append(
|
||
_notice("log.sink.dropped", f"{dropped} log events were dropped", dropped=dropped)
|
||
)
|
||
if not rows:
|
||
return 0
|
||
try:
|
||
# The connection is checked out BEFORE the guard, and every request path takes them in
|
||
# that order too (its session already holds a connection when it reaches the guard). The
|
||
# other way round, this thread would hold a process-global lock while waiting up to
|
||
# `pool_timeout` for a connection, and the requests that could return one are the ones
|
||
# blocked on the lock. The guard still spans the check, the insert and the commit.
|
||
with self._bind.connect() as conn, logs.erasure_guard(), conn.begin():
|
||
conn.execute(insert(LogEvent), without_erased(rows))
|
||
except Exception as exc: # noqa: BLE001 — the database is down or refused the batch
|
||
print(
|
||
f"log sink: could not store {len(rows)} log events: {logs.redact_text(str(exc))[:300]}",
|
||
file=sys.stderr,
|
||
)
|
||
return 0
|
||
return len(rows)
|
||
|
||
def _run(self) -> None:
|
||
while not self._stopping.is_set():
|
||
self.write_pending(wait=FLUSH_SECONDS)
|
||
while self.write_pending(): # drain what arrived before the stop
|
||
pass
|
||
|
||
def start(self) -> None:
|
||
self._writer = threading.Thread(target=self._run, name="log-sink", daemon=True)
|
||
self._writer.start()
|
||
|
||
def stop(self, timeout: float = 5.0) -> None:
|
||
self._stopping.set()
|
||
if self._writer is not None:
|
||
self._writer.join(timeout)
|
||
|
||
|
||
_sink: LogSink | None = None
|
||
|
||
|
||
def start() -> None:
|
||
"""Attach the sink to the root logger and start its writer. Call after `logs.configure_logging`
|
||
(which replaces the root handlers) and once the schema exists. A no-op when `LOG_DB_SINK` is off
|
||
or it is already running."""
|
||
global _sink
|
||
if _sink is not None or not settings.log_db_sink:
|
||
return
|
||
_sink = LogSink()
|
||
# The same level gate as stdout: the root may be lowered for one user's elevated requests, and
|
||
# everyone else's detail must not reach the table through that gap either.
|
||
_sink.addFilter(logs.LevelGate())
|
||
logging.getLogger().addHandler(_sink)
|
||
_sink.start()
|
||
# A short-lived process (the download child) exits without a lifespan: flush on the way out.
|
||
atexit.register(stop)
|
||
|
||
|
||
def stop() -> None:
|
||
"""Detach the sink and write what is still queued."""
|
||
global _sink
|
||
if _sink is None:
|
||
return
|
||
logging.getLogger().removeHandler(_sink)
|
||
_sink.stop()
|
||
_sink = None
|
||
|
||
|
||
def gc(db: Session, retention_days: int) -> int:
|
||
"""Stage the deletion of rows older than `retention_days` (at least one day — stored logs always
|
||
expire). The caller commits. Returns the number of rows removed."""
|
||
cutoff = datetime.now(timezone.utc) - timedelta(days=max(1, retention_days))
|
||
result = db.execute(delete(LogEvent).where(LogEvent.ts < cutoff))
|
||
return result.rowcount or 0
|