signal-bot/tests/test_command_events.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

169 lines
5.3 KiB
Python

# Copyright (c) 2026 Krzysztof Rudnicki. MIT licence.
"""The command history table: what it holds, and what a redelivery does to it."""
from __future__ import annotations
from typing import TYPE_CHECKING
from signal_bot.analytics.probe import NO_RESPONSE, UpstreamCall
from signal_bot.analytics.uses import (
OUTCOME_COOLDOWN,
OUTCOME_OK,
SOURCE_DAILY,
SOURCE_LIVE,
CommandEvent,
)
if TYPE_CHECKING:
from collections.abc import Sequence
from signal_bot.store import Store
GROUP = "group-a=="
# The exact column set, in order. Pinned for the reason message_events' is:
# this table sits in a repository that leaked real names once, and a column
# that could hold free text must be a deliberate, test-visible addition.
EVENT_COLUMNS = (
"group_id",
"user_uuid",
"command",
"args",
"item_id",
"outcome",
"error_class",
"invoked_at_ms",
"day",
"local_hour",
"weekday",
"handler_ms",
"send_ms",
"source",
)
CALL_COLUMNS = (
"group_id",
"invoked_at_ms",
"command",
"host",
"status",
"duration_ms",
"seq",
)
def an_event(
*,
command: str = "cat",
outcome: str = OUTCOME_OK,
invoked_at_ms: int = 1,
local_hour: int = 12,
handler_ms: int | None = None,
source: str = SOURCE_LIVE,
calls: Sequence[UpstreamCall] = (),
) -> CommandEvent:
"""One minimal attempt. ``invoked_at_ms`` also disambiguates the key."""
return CommandEvent(
group_id=GROUP,
user_uuid="u1",
command=command,
outcome=outcome,
invoked_at_ms=invoked_at_ms,
day="2026-08-29",
local_hour=local_hour,
weekday=5,
handler_ms=handler_ms,
source=source,
calls=calls,
)
def rows(store: Store, table: str) -> list[dict[str, object]]:
"""Every row of one of the two tables, as plain dicts."""
queries = {
"command_events": "SELECT * FROM command_events ORDER BY invoked_at_ms, source",
"upstream_calls": "SELECT * FROM upstream_calls ORDER BY invoked_at_ms, seq",
}
return [dict(row) for row in store.commands.connection.execute(queries[table])]
def test_the_column_set_is_exactly_this(store: Store) -> None:
"""A new column here is a deliberate change, never a quiet one."""
store.commands.record(an_event())
assert tuple(rows(store, "command_events")[0]) == EVENT_COLUMNS
def test_the_call_column_set_is_exactly_this(store: Store) -> None:
"""The same pin on the table that records where the time went."""
store.commands.record(an_event(calls=(UpstreamCall("api.example.test", 200, 9),)))
assert tuple(rows(store, "upstream_calls")[0]) == CALL_COLUMNS
def test_a_replayed_frame_does_not_become_a_second_row(store: Store) -> None:
"""signal-cli replays undelivered frames when the bot reconnects.
Keyed on the envelope's own timestamp rather than the wall clock, so the
replay collides with the row it already wrote.
"""
for _ in range(3):
store.commands.record(an_event())
assert len(rows(store, "command_events")) == 1
def test_a_replay_does_not_duplicate_the_upstream_calls(store: Store) -> None:
"""The calls are keyed independently, so they need their own guard.
Without ON CONFLICT on this table too, a redelivered frame would triple
the recorded upstream traffic while the invocation count stayed at one.
"""
for _ in range(3):
store.commands.record(an_event(calls=(UpstreamCall("api.example.test", 200, 9),)))
assert len(rows(store, "upstream_calls")) == 1
def test_the_same_invocation_from_two_sources_is_two_rows(store: Store) -> None:
"""source is in the key: a backfilled row may not overwrite a live one.
The two disagree about the hour by construction, and whichever wrote
last would win silently.
"""
store.commands.record(an_event())
store.commands.record(an_event(source=SOURCE_DAILY, local_hour=-1))
assert [row["source"] for row in rows(store, "command_events")] == ["daily_uses", "live"]
def test_a_refusal_is_recorded_like_any_other_attempt(store: Store) -> None:
"""The rows that did not exist at all before this table did."""
store.commands.record(an_event(outcome=OUTCOME_COOLDOWN, handler_ms=0))
(row,) = rows(store, "command_events")
assert row["outcome"] == "refused_cooldown"
def test_an_invocation_with_no_upstream_calls_records_none(store: Store) -> None:
"""Every stats_* command is this shape, and the loop must not mind."""
store.commands.record(an_event(command="stats_today"))
assert rows(store, "upstream_calls") == []
def test_several_calls_keep_their_order(store: Store) -> None:
"""seq is the enumerate index, so two calls to one host stay distinct."""
store.commands.record(
an_event(
calls=(
UpstreamCall("api.example.test", 200, 40),
UpstreamCall("api.example.test", NO_RESPONSE, 5000),
)
)
)
assert [(row["seq"], row["status"]) for row in rows(store, "upstream_calls")] == [
(0, 200),
(1, 0),
]
def test_a_backfilled_row_has_no_duration(store: Store) -> None:
"""NULL, never 0. Zero milliseconds reads as data and would drag a p50."""
store.commands.record(an_event(source=SOURCE_DAILY, local_hour=-1))
(row,) = rows(store, "command_events")
assert row["handler_ms"] is None
assert row["send_ms"] is None