signal-bot/signal_bot/analytics/recorder.py

# Copyright (c) 2026 Krzysztof Rudnicki. MIT licence.
"""Turning one attempted command into one row of history.

This is where the dispatcher's ``try/except`` around a handler now lives, so
that the dispatcher gains a ``with`` rather than forty lines and stays under
the 250-line cap. It also means the six outcome branches can be tested
directly, without driving a whole websocket frame through to reach an
exception path.

The invariant that must survive every future edit to this file: recording a
*use* and recording an *attempt* are two different writes with two different
rules, and they may never be merged.

* ``store.record_use`` is success-only and feeds the cooldown and the daily
  limit. ``CommandRefusedError``'s own docstring records what happened when
  a refusal reached it: the cooldown window slid forward every time somebody
  was told to wait, so waiting the stated time never helped.
* ``store.commands.record`` takes every attempt, including the refusals and
  the crashes -- which is the entire point, since a command that fails every
  time used to be indistinguishable from one nobody ran.

The temptation this creates is to hoist one call above the other, or to route
both through a single store method. ``test_dispatcher_recording`` fires a
refused invocation and asserts both that the history grew *and* that
``last_used`` did not move, which is the cheapest way to notice.
"""

from __future__ import annotations

import contextlib
import logging
import time
from dataclasses import dataclass
from typing import TYPE_CHECKING, Final

from signal_bot.analytics.uses import (
    ARGS_PRESENT,
    OUTCOME_COOLDOWN,
    OUTCOME_DAILY,
    OUTCOME_ERROR,
    OUTCOME_OFF,
    OUTCOME_OK,
    OUTCOME_VOTE,
    CommandEvent,
)
from signal_bot.decorators import GATE_COOLDOWN, GATE_DAILY, GATE_OFF, GATE_VOTE
from signal_bot.registry import CommandRefusedError
from signal_bot.stats.periods import day_of, hour_of, weekday_of

if TYPE_CHECKING:
    from collections.abc import Iterator

    from signal_bot.analytics import probe
    from signal_bot.analytics.uses import CommandEventStore

logger = logging.getLogger(__name__)

MS_PER_SECOND: Final = 1000

# A gate that did not name itself. Reachable only from a bare
# ``raise CommandRefusedError``, which nothing in this repository does any
# more -- but the constructor still allows it, so the mapping must too.
OUTCOME_REFUSED: Final = "refused_cooldown"

_BY_GATE: Final = {
    GATE_COOLDOWN: OUTCOME_COOLDOWN,
    GATE_DAILY: OUTCOME_DAILY,
    GATE_VOTE: OUTCOME_VOTE,
    GATE_OFF: OUTCOME_OFF,
}


def refusal_outcome(gate: str) -> str:
    """Name the outcome one gate's refusal should be filed under."""
    return _BY_GATE.get(gate, OUTCOME_REFUSED)


def args_token(args: tuple[str, ...]) -> str:
    """Reduce a command's arguments to something that cannot hold a name.

    The registry has already replaced a photo album's arguments with their
    pseudonym keys before the dispatcher sees them -- that is what
    ``arg_resolver`` is for, and why it runs at resolution rather than in a
    handler. Those keys are safe and worth keeping: "which person is asked
    for most" is a real question.

    Anything else becomes a flag. A column of words people typed is exactly
    the shape that put real names in this repository once, and the personal
    data gate learns the names it refuses from the live database -- so it
    would catch a name typed correctly and could never catch a typo.
    """
    if not args:
        return ""
    # One resolved token is a key. Several words are words.
    if len(args) == 1 and args[0].isalnum():
        return args[0]
    return ARGS_PRESENT


@dataclass(slots=True)
class Attempt:
    """What the dispatcher learned by trying to run one command."""

    outcome: str = OUTCOME_OK
    error_class: str = ""
    handler_ms: int = 0

    @property
    def ok(self) -> bool:
        """True when the handler actually ran to completion.

        The dispatcher asks this rather than comparing to a constant, so
        "did it work" has one spelling and the *use* -- the write that feeds
        the cooldown -- cannot accidentally start counting refusals.
        """
        return self.outcome == OUTCOME_OK


@contextlib.contextmanager
def attempting(command: str) -> Iterator[Attempt]:
    """Run one handler, and come out knowing how it went and what it cost.

    Swallows the handler's exception rather than re-raising: the dispatcher
    has always treated a failed command as an answered frame, because a raise
    here ends the receive loop and the bot goes silently deaf until the
    watchdog notices. That behaviour is unchanged -- only now the failure
    leaves a row behind.
    """
    attempt = Attempt()
    started = time.perf_counter()
    try:
        yield attempt
    except CommandRefusedError as refusal:
        attempt.outcome = refusal_outcome(refusal.gate)
        logger.debug("command %s refused by a gate", command)
    except Exception as error:
        # The class name, never str(error): an exception's message carries
        # whatever it was processing, and here that is somebody's message.
        # "17 ImageFetchError" is the whole diagnostic value anyway.
        attempt.outcome = OUTCOME_ERROR
        attempt.error_class = type(error).__name__
        logger.exception("command %s failed", command)
    attempt.handler_ms = round((time.perf_counter() - started) * MS_PER_SECOND)


@dataclass(frozen=True, slots=True)
class Invocation:
    """Who ran what, where, and when the message that asked was sent.

    Grouped rather than passed as five arguments, because these five always
    travel together and none of them means anything without the rest.
    """

    group_id: str
    user_uuid: str
    command: str
    args: tuple[str, ...]
    sent_at_ms: int


def record_attempt(
    store: CommandEventStore,
    invocation: Invocation,
    attempt: Attempt,
    notes: probe.Probe,
) -> None:
    """Append one attempt, and never let doing so break the bot.

    The whole body is guarded for the reason ``_answer_unknown``'s is: this
    runs inside the receive loop, and an exception escaping it stops the bot
    answering anything at all. Analytics are worth a great deal less than
    that, so a storage failure is logged and the frame carries on.
    """
    sent_at_ms = invocation.sent_at_ms
    day = day_of(sent_at_ms)
    try:
        store.record(
            CommandEvent(
                group_id=invocation.group_id,
                user_uuid=invocation.user_uuid,
                command=invocation.command,
                args=args_token(invocation.args),
                item_id=notes.item_id,
                outcome=attempt.outcome,
                error_class=attempt.error_class,
                invoked_at_ms=sent_at_ms,
                day=day,
                local_hour=hour_of(sent_at_ms),
                weekday=weekday_of(day),
                handler_ms=attempt.handler_ms,
                send_ms=notes.send_ms,
                calls=tuple(notes.calls),
            )
        )
    except Exception:
        logger.exception("could not record the use of %s", invocation.command)