feat: store warnings and request lines in log_events
The log now has a stored, queryable copy for the diagnostics console: every WARNING and above plus the request line of every request, kept for log_retention_days (default 7, no "forever") and pruned hourly by the new log_gc job. Rows are built on the logging thread from the same redacted fields as the stdout line, queued without blocking and written in batches by one background thread on its own connection. A full queue or a failed write drops and reports instead of retrying. Flood control keeps 30 of any one message per minute plus a count of the rest; anonymous request lines are capped at 60 a minute per client, and the client address is never stored. Deleting an account deletes its stored events. Measured on prod first: a YouTube RSS outage wrote 11k warnings in four hours, one per channel per poll. The poll now writes one warning with per-reason counts and a few examples, and a failure on our side gets one traceback per poll instead of one per channel.
This commit is contained in:
@@ -57,6 +57,10 @@ def _db_reachable() -> bool:
|
||||
|
||||
_DB_REACHABLE = _db_reachable()
|
||||
|
||||
# No background log writer in tests: every TestClient would otherwise start one on app startup and
|
||||
# write into tables the fixtures truncate between tests. The sink's own tests drive it explicitly.
|
||||
settings.log_db_sink = False
|
||||
|
||||
|
||||
@pytest.fixture(scope="session")
|
||||
def _schema():
|
||||
|
||||
@@ -13,7 +13,7 @@ import json
|
||||
import logging
|
||||
|
||||
import pytest
|
||||
from fastapi import FastAPI
|
||||
from fastapi import FastAPI, Request
|
||||
from fastapi.testclient import TestClient
|
||||
|
||||
from app import logs
|
||||
@@ -27,11 +27,13 @@ class _Sink(logging.Handler):
|
||||
def __init__(self):
|
||||
super().__init__(level=logging.NOTSET)
|
||||
self.lines: list[str] = []
|
||||
self.records: list[logging.LogRecord] = []
|
||||
self.setFormatter(logs.JsonFormatter())
|
||||
self.addFilter(logs.ContextFilter())
|
||||
|
||||
def emit(self, record):
|
||||
self.lines.append(self.format(record))
|
||||
self.records.append(record)
|
||||
|
||||
def objects(self) -> list[dict]:
|
||||
return [json.loads(line) for line in self.lines]
|
||||
@@ -220,6 +222,40 @@ def test_the_request_line_has_the_route_template_and_no_query_string(sink):
|
||||
assert isinstance(payload["attrs"]["duration_ms"], float)
|
||||
|
||||
|
||||
def test_anonymous_request_lines_are_capped_per_client_for_storage_but_still_logged(sink):
|
||||
# A scanner's 404s are WARNINGs, and WARNINGs are stored. Past the cap they stay on stdout but are
|
||||
# marked not-for-storage; a signed-in request is never capped. No address appears in any line.
|
||||
logs._anonymous_lines.reset()
|
||||
client = _client()
|
||||
for _ in range(logs.ANONYMOUS_LINES_PER_MINUTE + 3):
|
||||
client.get("/wp-login.php")
|
||||
lines = sink.objects()[-(logs.ANONYMOUS_LINES_PER_MINUTE + 3) :]
|
||||
assert len(lines) == logs.ANONYMOUS_LINES_PER_MINUTE + 3 # stdout keeps every one
|
||||
records = sink.records[-(logs.ANONYMOUS_LINES_PER_MINUTE + 3) :]
|
||||
stored = [getattr(r, logs.PERSIST, True) for r in records]
|
||||
assert stored.count(False) == 3 and all(stored[: logs.ANONYMOUS_LINES_PER_MINUTE])
|
||||
assert "testclient" not in "".join(sink.lines) # the client key never reaches the line
|
||||
logs._anonymous_lines.reset()
|
||||
|
||||
|
||||
def test_a_signed_in_request_is_never_capped_and_names_its_account(sink):
|
||||
logs._anonymous_lines.reset()
|
||||
app = FastAPI()
|
||||
app.middleware("http")(logs.log_requests)
|
||||
|
||||
@app.get("/api/me")
|
||||
def _me(request: Request):
|
||||
request.state.user_id = 42 # what the auth dependency does
|
||||
return {}
|
||||
|
||||
client = TestClient(app)
|
||||
for _ in range(logs.ANONYMOUS_LINES_PER_MINUTE + 3):
|
||||
client.get("/api/me")
|
||||
records = sink.records[-(logs.ANONYMOUS_LINES_PER_MINUTE + 3) :]
|
||||
assert all(getattr(r, logs.PERSIST, True) for r in records)
|
||||
assert sink.objects()[-1]["user_id"] == 42 and "user_id" not in sink.objects()[-1]["attrs"]
|
||||
|
||||
|
||||
def test_the_request_id_is_echoed_and_shared_by_every_line_of_that_request(sink):
|
||||
client = _client()
|
||||
r = client.get("/api/videos/abc123")
|
||||
|
||||
@@ -0,0 +1,175 @@
|
||||
"""E22 S3 — the `log_events` sink: what reaches the table, in what shape, and what it refuses to do.
|
||||
|
||||
The sink is driven synchronously (`write_pending()` on the test's own thread) so nothing here waits on
|
||||
a timer. It is attached to a private logger rather than the root, for the same reason test_logs.py's
|
||||
capture handler is: a `configure_logging` call elsewhere replaces the root handlers.
|
||||
DB lane (`db` fixture): the rows are read back from a real Postgres.
|
||||
"""
|
||||
|
||||
import logging
|
||||
import threading
|
||||
from datetime import datetime, timedelta, timezone
|
||||
|
||||
import pytest
|
||||
from fastapi import BackgroundTasks
|
||||
from sqlalchemy import create_engine, select
|
||||
|
||||
from app import logs, logsink, scheduler
|
||||
from app.auth import purge_user
|
||||
from app.db import engine
|
||||
from app.models import LogEvent
|
||||
|
||||
|
||||
@pytest.fixture
|
||||
def stored(db):
|
||||
"""A LogSink on the logger `siftlode.sinktest`, and a reader for the rows it wrote."""
|
||||
sink = logsink.LogSink(engine)
|
||||
logger = logging.getLogger("siftlode.sinktest")
|
||||
logger.addHandler(sink)
|
||||
logger.setLevel(logs.TRACE)
|
||||
|
||||
def rows() -> list[LogEvent]:
|
||||
sink.write_pending()
|
||||
db.expire_all()
|
||||
return list(db.execute(select(LogEvent).order_by(LogEvent.id)).scalars())
|
||||
|
||||
try:
|
||||
yield sink, logger, rows
|
||||
finally:
|
||||
logger.removeHandler(sink)
|
||||
|
||||
|
||||
def test_warnings_and_request_lines_are_stored_and_everything_else_is_not(stored):
|
||||
_sink, log, rows = stored
|
||||
log.info("an ordinary info line")
|
||||
log.debug("GET /healthz 200", extra=logs.event("http.request", path="/healthz", status=200))
|
||||
log.info("GET /api/feed 200", extra=logs.event("http.request", path="/api/feed", status=200))
|
||||
log.warning("scanner", extra={**logs.event("http.request", status=404), logs.PERSIST: False})
|
||||
log.warning("disk nearly full")
|
||||
assert [r.msg for r in rows()] == ["GET /api/feed 200", "disk nearly full"]
|
||||
|
||||
|
||||
def test_a_row_is_redacted_exactly_like_the_stdout_line(stored):
|
||||
_sink, log, rows = stored
|
||||
try:
|
||||
raise ValueError("reset link https://x.test/#reset=abc123")
|
||||
except ValueError:
|
||||
log.exception(
|
||||
"sign-in failed for someone@example.com",
|
||||
extra=logs.event("auth.failed", password="hunter2", reason="bad_password"),
|
||||
)
|
||||
(row,) = rows()
|
||||
assert row.level == "ERROR" and row.sev == logs.SEVERITY["ERROR"]
|
||||
assert row.event == "auth.failed"
|
||||
assert "someone@example.com" not in row.msg and logs.REDACTED_EMAIL in row.msg
|
||||
assert row.attrs == {"password": logs.REDACTED, "reason": "bad_password"}
|
||||
assert "abc123" not in row.exc and "ValueError" in row.exc
|
||||
assert row.source == logs.current_source() and row.version
|
||||
|
||||
|
||||
def test_correlation_is_captured_when_the_line_is_logged_not_when_it_is_written(stored):
|
||||
_sink, log, rows = stored
|
||||
with logs.bind(job_id=7, request_id="req-0123456789"):
|
||||
log.warning("inside the job")
|
||||
# The writer runs later, outside the bind — the row still belongs to job 7.
|
||||
(row,) = rows()
|
||||
assert (row.job_id, row.request_id) == (7, "req-0123456789")
|
||||
|
||||
|
||||
def test_a_flood_of_one_message_is_stored_up_to_the_limit_and_then_summarised(stored):
|
||||
sink, log, rows = stored
|
||||
limit = logsink.REPEATS_PER_MINUTE
|
||||
for i in range(limit + 70):
|
||||
log.warning("RSS poll skipped for channel %s: HTTP 404", f"UC{i}")
|
||||
log.warning("a different message")
|
||||
assert len(rows()) == limit + 1 # the flood capped; the other message untouched
|
||||
sink._repeats.started -= logsink.REPEAT_WINDOW_SECONDS # the minute is over
|
||||
notice = rows()[-1]
|
||||
assert notice.event == "log.repeats_suppressed"
|
||||
assert notice.attrs["suppressed"] == 70
|
||||
assert notice.attrs["template"] == "RSS poll skipped for channel %s: HTTP 404"
|
||||
|
||||
|
||||
def test_request_lines_are_never_treated_as_a_flood(stored):
|
||||
_sink, log, rows = stored
|
||||
for _ in range(logsink.REPEATS_PER_MINUTE + 5):
|
||||
log.info("%s %s %s", "GET", "/api/feed", 200, extra=logs.event("http.request"))
|
||||
assert len(rows()) == logsink.REPEATS_PER_MINUTE + 5
|
||||
|
||||
|
||||
def test_a_full_queue_drops_and_says_how_many(db, monkeypatch):
|
||||
monkeypatch.setattr(logsink, "QUEUE_MAX", 3)
|
||||
sink = logsink.LogSink(engine)
|
||||
log = logging.getLogger("siftlode.sinktest.small")
|
||||
log.addHandler(sink)
|
||||
try:
|
||||
for i in range(5):
|
||||
log.warning("message number %d", i)
|
||||
finally:
|
||||
log.removeHandler(sink)
|
||||
assert sink.write_pending() == 4
|
||||
notice = db.execute(select(LogEvent).where(LogEvent.event == "log.sink.dropped")).scalar_one()
|
||||
assert notice.attrs == {"dropped": 2}
|
||||
|
||||
|
||||
def test_an_unreachable_database_costs_the_batch_not_the_caller(capsys):
|
||||
dead = create_engine(
|
||||
"postgresql+psycopg://x:y@127.0.0.1:1/none", connect_args={"connect_timeout": 1}
|
||||
)
|
||||
sink = logsink.LogSink(dead)
|
||||
log = logging.getLogger("siftlode.sinktest.dead")
|
||||
log.addHandler(sink)
|
||||
try:
|
||||
log.error("this has nowhere to go") # must not raise
|
||||
finally:
|
||||
log.removeHandler(sink)
|
||||
assert sink.write_pending() == 0
|
||||
assert "could not store 1 log events" in capsys.readouterr().err
|
||||
|
||||
|
||||
def test_the_writer_thread_does_not_store_its_own_records(stored):
|
||||
sink, log, rows = stored
|
||||
sink._writer = threading.current_thread() # as if this line came from inside the writer
|
||||
log.error("a driver warning raised while inserting")
|
||||
sink._writer = None
|
||||
assert rows() == []
|
||||
|
||||
|
||||
def test_gc_keeps_the_retention_window_and_never_keeps_forever(db):
|
||||
now = datetime.now(timezone.utc)
|
||||
|
||||
def add(age: timedelta) -> None:
|
||||
db.add(
|
||||
LogEvent(ts=now - age, level="WARNING", sev=13, source="api", logger="t", msg=str(age))
|
||||
)
|
||||
|
||||
for age in (timedelta(hours=1), timedelta(days=2), timedelta(days=8)):
|
||||
add(age)
|
||||
db.commit()
|
||||
assert logsink.gc(db, 7) == 1
|
||||
assert logsink.gc(db, 0) == 1 # 0 is not "forever": stored logs always expire (floor: 1 day)
|
||||
db.commit()
|
||||
assert [r.msg for r in db.execute(select(LogEvent)).scalars()] == [str(timedelta(hours=1))]
|
||||
|
||||
|
||||
def test_log_gc_is_a_scheduled_job():
|
||||
assert "log_gc" in scheduler.JOB_FUNCS and scheduler.JOB_INTERVALS["log_gc"] >= 1
|
||||
|
||||
|
||||
def test_deleting_an_account_deletes_its_stored_log_events(db, make_user):
|
||||
gone, kept = make_user(), make_user()
|
||||
for uid in (gone.id, kept.id, gone.id):
|
||||
db.add(
|
||||
LogEvent(
|
||||
ts=datetime.now(timezone.utc),
|
||||
level="INFO",
|
||||
sev=9,
|
||||
source="api",
|
||||
logger="t",
|
||||
msg="x",
|
||||
user_id=uid,
|
||||
)
|
||||
)
|
||||
db.commit()
|
||||
purge_user(db, gone, BackgroundTasks())
|
||||
assert [r.user_id for r in db.execute(select(LogEvent)).scalars()] == [kept.id]
|
||||
@@ -1,6 +1,8 @@
|
||||
"""Guards that stop one bad YouTube answer from cascading: the subscription prune guard, the
|
||||
playlist-push circuit breaker, and RSS telling a failure apart from an empty feed."""
|
||||
|
||||
import logging
|
||||
|
||||
import httpx
|
||||
import pytest
|
||||
|
||||
@@ -120,7 +122,7 @@ class TestRssPollResult:
|
||||
# One dead channel among healthy ones: counted, but the run itself is still a run.
|
||||
def fetch(cid):
|
||||
if cid == "UC_dead":
|
||||
raise rss.RssError("404")
|
||||
raise rss.RssError("404", "http_404")
|
||||
return [{"id": "v"}]
|
||||
|
||||
out = self._run(
|
||||
@@ -143,6 +145,54 @@ class TestRssPollResult:
|
||||
)
|
||||
assert out == {"new": 1, "failed": 1}, "an unstored channel must not read as ok"
|
||||
|
||||
def test_many_failures_write_one_warning_with_counts_not_one_per_channel(
|
||||
self, monkeypatch, caplog
|
||||
):
|
||||
# YouTube's RSS outage of 2026-09-16: ~900 of 979 feeds failed on every 20-minute poll and
|
||||
# each wrote its own WARNING — 11k lines in four hours, which the log_events table would
|
||||
# have stored too. One summary per poll, per-channel detail at DEBUG.
|
||||
channels = [f"UC{i}" for i in range(40)]
|
||||
|
||||
def fetch(cid):
|
||||
n = int(cid[2:])
|
||||
if n < 30:
|
||||
raise rss.RssError(f"RSS fetch for {cid} returned HTTP 404", "http_404")
|
||||
if n < 35:
|
||||
raise rss.RssError(f"RSS fetch failed for {cid}: timed out", "transport")
|
||||
return [{"id": "v"}]
|
||||
|
||||
caplog.set_level(logging.DEBUG, logger="siftlode.sync")
|
||||
out = self._run(monkeypatch, fetch=fetch, apply_=lambda db, ch, e: 1, channels=channels)
|
||||
assert out == {"new": 5, "failed": 35}
|
||||
warnings = [r for r in caplog.records if r.levelno >= logging.WARNING]
|
||||
assert len(warnings) == 1
|
||||
assert warnings[0].event == "sync.rss.failed"
|
||||
assert warnings[0].attrs["reasons"] == {"http_404": 30, "transport": 5}
|
||||
assert len(warnings[0].attrs["examples"]) == runner.RSS_FAILURE_EXAMPLES
|
||||
assert sum(r.levelno == logging.DEBUG for r in caplog.records) == 35
|
||||
|
||||
def test_a_failure_on_our_side_gets_one_traceback_per_poll_not_one_per_channel(
|
||||
self, monkeypatch, caplog
|
||||
):
|
||||
# A read-only database fails every channel's apply identically. The first gets a traceback
|
||||
# at ERROR; repeating it for each of 979 channels would be the RSS flood all over again.
|
||||
def apply_(db, ch, entries):
|
||||
raise RuntimeError("read-only transaction")
|
||||
|
||||
caplog.set_level(logging.DEBUG, logger="siftlode.sync")
|
||||
with pytest.raises(RuntimeError):
|
||||
self._run(
|
||||
monkeypatch,
|
||||
fetch=lambda cid: [{"id": "v"}],
|
||||
apply_=apply_,
|
||||
channels=("A", "B", "C"),
|
||||
)
|
||||
errors = [r for r in caplog.records if r.levelno == logging.ERROR]
|
||||
assert len(errors) == 1 and errors[0].exc_info is not None
|
||||
assert (
|
||||
sum(r.levelno == logging.DEBUG and r.exc_info is not None for r in caplog.records) == 2
|
||||
)
|
||||
|
||||
def test_a_quiet_hour_is_distinguishable_from_an_outage(self, monkeypatch):
|
||||
quiet = self._run(monkeypatch, fetch=lambda cid: [], apply_=lambda db, ch, e: 0)
|
||||
assert quiet == {"new": 0, "failed": 0} # same "new", different "failed" — that's the point
|
||||
@@ -152,7 +202,7 @@ class TestRssPollResult:
|
||||
# here recorded the scheduler run as "ok", with the outage only visible inside the summary
|
||||
# text — a green pill for a run that did nothing at all.
|
||||
def boom(cid):
|
||||
raise rss.RssError("Connection refused")
|
||||
raise rss.RssError("Connection refused", "transport")
|
||||
|
||||
with pytest.raises(RuntimeError, match="all 2 channels"):
|
||||
self._run(monkeypatch, fetch=boom, apply_=lambda db, ch, e: 1)
|
||||
@@ -162,7 +212,7 @@ class TestRssPollResult:
|
||||
# The card has to say which: `HTTP 404` = fix the subscription, `Connection refused` =
|
||||
# the egress is down.
|
||||
def dead(cid):
|
||||
raise rss.RssError(f"RSS fetch for {cid} returned HTTP 404")
|
||||
raise rss.RssError(f"RSS fetch for {cid} returned HTTP 404", "http_404")
|
||||
|
||||
with pytest.raises(RuntimeError, match="HTTP 404"):
|
||||
self._run(monkeypatch, fetch=dead, apply_=lambda db, ch, e: 1, channels=("UC_dead",))
|
||||
|
||||
Reference in New Issue
Block a user