interactive-story/backend/app/accesslog.py

"""The access log: who arrived, when, and from where.

The deliberate opposite of analytics.py. That module counts and stores nothing
that points at a person; this one records addresses, email addresses and
devices, because an access log that cannot identify the access is not an access
log. The two live in separate modules and separate tables on purpose, so that
the anonymity of the counters is a property of the code rather than a convention
someone has to remember.

Owner-only, and never shown to the people it records.

Four kinds of row:

- `session`      A browser that has a session made a request. For a guest, this
                 is their first visit.
- `login`        An existing account signed in.
- `register`     A guest upgraded to an account.
- `login_failed` A password attempt that did not match, with the address tried.

Session rows are the only ones that need thinning. `/auth/me` runs on every page
load, and one row per load would be noise rather than a log. A row is written
when the day or the address changes for that user. That is the granularity a log
is read at, such as seen on the 3rd from 1.2.3.4, and it still records someone
moving networks during a day.
"""

import logging
import threading

from sqlalchemy import desc, or_, select
from sqlalchemy.orm import Session

from . import analytics, models

logger = logging.getLogger(__name__)

SESSION = "session"
LOGIN = "login"
REGISTER = "register"
LOGIN_FAILED = "login_failed"

MAX_UA = 200

# user id -> (day, ip) of the last session row written for them. Process-local
# like the rate limiter's windows, and for the same reason: this is a single
# process, and the worst case after a restart is one redundant row per user.
_last_session: dict[int, tuple[str, str]] = {}
_guard = threading.Lock()
_MAX_TRACKED = 10_000


def _client_ip(request) -> str:
    # This import is deferred. `limits` imports `auth`, which the routers that
    # call this function import, so a module-level import here would create a
    # cycle. The spoof resistance lives in `limits` and must not be
    # reimplemented. A second, looser answer to which address belongs to the
    # client is how one of them ends up trusting a header it should not.
    from . import limits

    return limits.client_ip(request)


def describe(user: models.User) -> str:
    """Returns how a user is named in the log.

    A guest has no email, and their id is the only handle anyone has for them.
    The third case is a local install's implicit single user, who also has no
    email but is the operator rather than a visitor. Naming that user "Guest #1"
    would be wrong in the one row they are certain to read.
    """
    if user.email:
        return user.email
    return f"Guest #{user.id}" if user.is_guest else f"Local user #{user.id}"


def _country(request) -> str:
    """Returns the edge's country header, or "" when there is none.

    The blank differs from the counters' "(unknown)" label. A table column reads
    better as a dash than as a word, and an empty string is the correct value for
    a country that is not known.
    """
    country = analytics.country_of(request.headers)
    return "" if country == analytics.UNKNOWN else country


def record(
    db: Session,
    kind: str,
    request,
    *,
    user: models.User | None = None,
    who: str | None = None,
) -> None:
    """Writes one row.

    This function never raises. The log observes sign-in rather than guarding it,
    and a logging failure must not lock anyone out.
    """
    try:
        event = models.AccessEvent(
            kind=kind,
            user_id=user.id if user is not None else None,
            who=(who if who is not None else describe(user) if user else "")[:320],
            is_guest=bool(user.is_guest) if user is not None else False,
            ip=_client_ip(request)[:45],
            country=_country(request),
            device=analytics.device_of(request.headers.get("user-agent", "")),
            user_agent=(request.headers.get("user-agent") or "")[:MAX_UA],
        )
        db.add(event)
        db.commit()
    except Exception:  # pragma: no cover - defensive
        db.rollback()
        logger.exception("Access log write failed; continuing.")


def note_session(db: Session, user: models.User, request) -> None:
    """Records that a session made a request, at most one row per day per address."""
    try:
        today = analytics._today()
        ip = _client_ip(request)
        with _guard:
            if _last_session.get(user.id) == (today, ip):
                return
            _last_session[user.id] = (today, ip)
            if len(_last_session) > _MAX_TRACKED:
                # Nothing here needs to persist. Clearing the map costs at most
                # one extra row per active user.
                _last_session.clear()
                _last_session[user.id] = (today, ip)
    except Exception:  # pragma: no cover - defensive
        logger.exception("Access log session check failed; continuing.")
        return
    record(db, SESSION, request, user=user)


def recent(
    db: Session,
    *,
    limit: int = 50,
    before_id: int | None = None,
    kind: str | None = None,
    query: str | None = None,
) -> dict:
    """Returns a page of the log, newest first.

    The page is anchored on a row id rather than an offset, as the story pager
    is. Rows keep arriving while the log is read, and an offset would shift the
    page under whoever is reading it.
    """
    statement = select(models.AccessEvent).order_by(desc(models.AccessEvent.id))
    if before_id is not None:
        statement = statement.where(models.AccessEvent.id < before_id)
    if kind:
        statement = statement.where(models.AccessEvent.kind == kind)
    if query:
        like = f"%{query.strip()}%"
        statement = statement.where(or_(
            models.AccessEvent.who.ilike(like),
            models.AccessEvent.ip.ilike(like),
            models.AccessEvent.country.ilike(like),
        ))
    # Requesting one extra row reports whether more rows exist, without a
    # second COUNT over the whole table.
    rows = list(db.scalars(statement.limit(limit + 1)))
    has_more = len(rows) > limit
    return {"events": rows[:limit], "has_more": has_more}