signal-bot/tests/test_dispatcher_outcomes.py
Krzysztof kuhy Rudnicki 405541be9b
Some checks are pending
CI / check (push) Waiting to run
CI / web (push) Waiting to run
release: 0.2.6 «Stephanus I» — dodano !analityka
One row per command attempt, not two aggregates written only on success.

command_uses holds last-use only and daily_uses counts successes; both are
rate-limiter state and both are written by store.record_use, which the
dispatcher calls only when a handler returns cleanly. A gate refusal and a
crash returned before it, so a command that failed every time looked exactly
like one nobody ran, and nothing knew which command a counted message was.

command_events now takes every attempt with its outcome, its duration and
the item it served; upstream_calls takes every outbound request made while
serving one. The two writes stay separate on purpose -- recording a refusal
as a use is what slid the cooldown window forward every time somebody was
told to wait -- and test_dispatcher_outcomes asserts last_used does not move.

Backfilled from journald joined against message_events, with daily_uses
filling the residual so the two sources cannot double-count. Two things were
wrong on the first attempt and both were found by measuring rather than by
reasoning: the window has to be symmetric, because sent_at_ms comes from the
sender's phone and the journal stamp from this host (194 of 299 lines landed
*before* their own message, by up to 3.2 s); and matching has to be a global
closest-pair assignment, because per-row greedy cannot separate two commands
seconds apart. Together those took the dropped rows from 137 to zero, and
recovered 418 invocations back to 29 August.

Also: !analityka in the group, twelve Polish lines, naming at most three
people and only ones whose display name has been seen; an Analytics tab with
Nivo charts; and continuous latency measurement, which answers the open
question in DOCS-latency.md -- a text send is 235 ms and an image send about
2.2 s, so the upload really is where the time goes.

EPHEMERAL_TABLES was doing two unrelated jobs and is now two tuples: what a
schema bump rebuilds, and what leaving a group clears. daily_uses left the
first (it is a backfill source now) and stayed in the second, and
_drop_reshaped took over the repair a bump used to do for it.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01T4QTp3h5Q3MvfrwGV8xqPf
2026-08-31 23:19:51 +02:00

172 lines
5.5 KiB
Python

# Copyright (c) 2026 Krzysztof Rudnicki. MIT licence.
"""The outcomes that had no data at all before command_events.
Split out of ``test_dispatcher_recording`` so both stay under the 250-line
cap. This half is the one that matters most: a refusal and a crash are rows
now, and the *use* -- the write that feeds the cooldown -- must still not
move for either of them.
"""
from __future__ import annotations
import datetime as dt
from typing import TYPE_CHECKING
import pytest
from signal_bot.analytics import probe
from signal_bot.decorators import cooldown, daily_limit
from signal_bot.registry import CommandRegistry
from tests.conftest import WATCHED_GROUP, envelope
from tests.test_dispatcher_recording import SENDER, build, calls, history
if TYPE_CHECKING:
from signal_bot.config import Config
from signal_bot.context import CommandContext
from signal_bot.discovery import GroupDirectory
from signal_bot.store import Store
from signal_bot.transport_fake import FakeTransport
NOW = dt.datetime(2026, 8, 29, 12, 0, tzinfo=dt.UTC)
@pytest.fixture
def ok_registry() -> CommandRegistry:
"""One command that succeeds and reports what it did on the way."""
async def handler(_ctx: CommandContext) -> None:
probe.note_upstream("api.example.test", 200, 40)
probe.note_send(120)
probe.note_item("Q42")
reg = CommandRegistry()
reg.register("cat", ["!cat"], handler, "kot")
return reg
async def test_a_refusal_does_not_move_the_cooldown(
config: Config,
directory: GroupDirectory,
store: Store,
transport: FakeTransport,
) -> None:
"""The invariant. A refused attempt is history, never a use.
If these two writes are ever merged, this fails and the bug it names
comes back: every "wait N seconds" reply would push the wait N seconds
further away, and waiting would never end.
"""
async def handler(_ctx: CommandContext) -> None:
pass
reg = CommandRegistry()
reg.register(
"cat",
["!cat"],
cooldown(3600.0, "poczekaj {seconds} {unit}")(handler),
"kot",
)
dispatcher = build(config, directory, reg, store, transport)
await dispatcher.handle(envelope(text="!cat", timestamp=1000))
first_use = store.last_used(WATCHED_GROUP, SENDER, "cat")
await dispatcher.handle(envelope(text="!cat", timestamp=2000))
outcomes = [row["outcome"] for row in history(store)]
assert outcomes == ["ok", "refused_cooldown"]
# The whole point: the second attempt is a row, and it moved nothing.
assert store.last_used(WATCHED_GROUP, SENDER, "cat") == first_use
assert store.uses_today(WATCHED_GROUP, SENDER, "cat", "2026-08-29") == 1
async def test_a_daily_refusal_names_its_own_gate(
config: Config,
directory: GroupDirectory,
store: Store,
transport: FakeTransport,
) -> None:
"""Which gate bit is the difference between "popular" and "mis-tuned"."""
async def handler(_ctx: CommandContext) -> None:
pass
reg = CommandRegistry()
reg.register(
"cat",
["!cat"],
daily_limit(1, "dosc na dzis")(handler),
"kot",
)
dispatcher = build(config, directory, reg, store, transport)
await dispatcher.handle(envelope(text="!cat", timestamp=1000))
await dispatcher.handle(envelope(text="!cat", timestamp=2000))
assert [row["outcome"] for row in history(store)] == ["ok", "refused_daily"]
async def test_a_crash_is_recorded_and_the_bot_survives_it(
config: Config,
directory: GroupDirectory,
store: Store,
transport: FakeTransport,
) -> None:
"""A command that fails every time used to look like one nobody ran."""
async def handler(_ctx: CommandContext) -> None:
raise ValueError
reg = CommandRegistry()
reg.register("cat", ["!cat"], handler, "kot")
dispatcher = build(config, directory, reg, store, transport)
await dispatcher.handle(envelope(text="!cat"))
(row,) = history(store)
assert row["outcome"] == "error"
# The class name, never the message: an exception's str() carries
# whatever it was processing, and here that is somebody's message.
assert row["error_class"] == "ValueError"
assert store.last_used(WATCHED_GROUP, SENDER, "cat") is None
async def test_recording_can_fail_without_taking_the_bot_down(
config: Config,
directory: GroupDirectory,
ok_registry: CommandRegistry,
store: Store,
transport: FakeTransport,
monkeypatch: pytest.MonkeyPatch,
) -> None:
"""A raise here would end the receive loop and the bot would go deaf.
Analytics are worth a great deal less than answering at all, so the
storage failure is logged and the use is still recorded.
"""
def explode(_event: object) -> None:
raise RuntimeError
monkeypatch.setattr(store.commands, "record", explode)
dispatcher = build(config, directory, ok_registry, store, transport)
await dispatcher.handle(envelope(text="!cat"))
assert store.last_used(WATCHED_GROUP, SENDER, "cat") == NOW.timestamp()
async def test_a_replayed_frame_is_recorded_once(
config: Config,
directory: GroupDirectory,
ok_registry: CommandRegistry,
store: Store,
transport: FakeTransport,
) -> None:
"""signal-cli replays undelivered frames when the bot reconnects."""
dispatcher = build(config, directory, ok_registry, store, transport)
for _ in range(3):
await dispatcher.handle(envelope(text="!cat", timestamp=5000))
assert len(history(store)) == 1
assert len(calls(store)) == 1