siftlode/backend/tests/test_logsink.py

"""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, func, 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]


def test_an_erased_accounts_late_lines_are_stored_without_it(stored, db, make_user):
    """The DELETE in purge_user cannot reach a row still on its way: one queued before the erasure,
    or the erasing request's own access line, logged after the handler committed."""
    _sink, log, rows = stored
    user = make_user()
    try:
        log.warning("queued before the erasure", extra={"user_id": user.id})
        purge_user(db, user, BackgroundTasks())
        log.info(
            "DELETE /api/me/account 200", extra={**logs.event("http.request"), "user_id": user.id}
        )
        assert [(r.msg, r.user_id) for r in rows()] == [
            ("queued before the erasure", None),
            ("DELETE /api/me/account 200", None),
        ]
    finally:
        logs._erased.clear()


def test_a_nul_character_costs_nothing_but_itself(stored):
    """Postgres refuses NUL in text and JSONB, and a refused row fails its whole batch — every other
    user's rows with it. `GET /assets/%00` logs exactly that."""
    _sink, log, rows = stored
    log.warning("before")
    log.warning("GET /assets/\x00 404", extra=logs.event("http.request", path="/assets/\x00"))
    log.warning("after")
    before, nul, after = rows()
    assert (before.msg, after.msg) == ("before", "after")
    assert nul.msg == "GET /assets/� 404" and nul.attrs["path"] == "/assets/�"


def test_the_writer_drains_what_was_queued_when_it_is_stopped(db):
    sink = logsink.LogSink(engine)
    log = logging.getLogger("siftlode.sinktest.drain")
    log.addHandler(sink)
    try:
        for i in range(logsink.BATCH_MAX + 5):
            log.warning(f"line {i}")  # distinct templates: no flood limiter involved
    finally:
        log.removeHandler(sink)
    sink._stopping.set()
    sink._run()  # stopped before its first wait: everything goes through the drain
    assert (
        db.execute(select(func.count()).select_from(LogEvent)).scalar_one() == logsink.BATCH_MAX + 5
    )


def test_the_running_sink_keeps_the_base_level_for_everyone_the_elevation_is_not_for(
    db, monkeypatch
):
    """`logsink.start()` as production runs it. One user's elevation lowers the ROOT logger, so an
    ordinary request line below the base level reaches every handler — the sink's own level gate is
    what keeps it out of the table, as stdout's keeps it off the terminal."""
    root = logging.getLogger()
    saved = (logs._base_level, dict(logs._elevations), logs._root_applied, root.level)
    monkeypatch.setattr(logsink.settings, "log_db_sink", True)
    logs.set_level("WARNING")
    logs._track_elevation(1, logging.DEBUG, datetime.now(timezone.utc) + timedelta(hours=1))
    log = logging.getLogger("siftlode.sinktest.live")
    try:
        logsink.start()
        log.info("GET /api/feed 200", extra={**logs.event("http.request"), "user_id": 2})
        log.warning("a warning")
    finally:
        logsink.stop()
        logs._base_level, logs._root_applied = saved[0], saved[2]
        logs._elevations.clear()
        logs._elevations.update(saved[1])
        root.setLevel(saved[3])
    assert [r.msg for r in db.execute(select(LogEvent)).scalars()] == ["a warning"]