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

251 lines
9.2 KiB
Python

# Copyright (c) 2026 Krzysztof Rudnicki. MIT licence.
"""Recovering the command history, without inventing any of it.
Two properties matter more than the rest and each has its own test: the two
sources must not double-count the same invocations, and a second run must
insert nothing.
"""
from __future__ import annotations
from typing import TYPE_CHECKING
from signal_bot.analytics import backfill
from signal_bot.analytics.backfill_join import WINDOW_MS
from signal_bot.analytics.journal import JournalLine
from signal_bot.analytics.uses import SOURCE_DAILY, SOURCE_JOURNAL
from signal_bot.stats.events import MessageEvent
if TYPE_CHECKING:
from signal_bot.store import Store
GROUP = "group-a=="
DAY = "2026-08-29"
# Midday on the day above, so a +/- window cannot cross a date boundary.
NOON_MS = backfill.midnight_ms(DAY) + 12 * 3600 * 1000
def a_message(store: Store, at_ms: int, who: str = "ala", uuid: str = "u1") -> None:
"""One counted command in the message history."""
store.events.record(
MessageEvent(
group_id=GROUP,
uuid=uuid,
display_name=who,
sent_at_ms=at_ms,
day=DAY,
local_hour=12,
is_command=True,
)
)
def a_line(at_ms: int, command: str, who: str = "ala", *, refused: bool = False) -> JournalLine:
"""One line the bot wrote about running a command."""
return JournalLine(at_ms=at_ms, command=command, display_name=who, refused=refused)
def rows(store: Store) -> list[tuple[str, str, int, str]]:
"""Every recorded attempt as (command, outcome, hour, source)."""
return [
(str(r["command"]), str(r["outcome"]), int(r["local_hour"]), str(r["source"]))
for r in store.commands.connection.execute(
"SELECT command, outcome, local_hour, source FROM command_events ORDER BY invoked_at_ms"
)
]
def test_a_message_gets_its_name_from_the_journal(store: Store) -> None:
"""The whole point: the database has the hour, the journal has the name."""
a_message(store, NOON_MS)
report, events = backfill.plan(store, [a_line(NOON_MS + 200, "cat")])
backfill.apply(store, events)
assert report.journal_rows == 1
assert rows(store) == [("cat", "ok", 12, SOURCE_JOURNAL)]
def test_a_journal_line_earlier_than_its_message_still_matches(store: Store) -> None:
"""The window is symmetric, and this is why.
sent_at_ms comes from the sender's phone and the journal stamp from this
host; nothing keeps two clocks in step. On the live database 194 of 299
counted commands had a journal line *earlier* than their own timestamp.
An asymmetric window drops every one of them.
"""
a_message(store, NOON_MS)
_report, events = backfill.plan(store, [a_line(NOON_MS - 3_000, "cat")])
backfill.apply(store, events)
assert rows(store) == [("cat", "ok", 12, SOURCE_JOURNAL)]
def test_a_line_outside_the_window_is_not_used(store: Store) -> None:
"""Far enough away it is somebody else's invocation, or another day's."""
a_message(store, NOON_MS)
report, events = backfill.plan(store, [a_line(NOON_MS + WINDOW_MS + 1, "cat")])
backfill.apply(store, events)
assert report.journal_rows == 0
assert report.unmatched == 1
assert [row for row in rows(store) if row[3] == SOURCE_JOURNAL] == []
def test_two_commands_seconds_apart_are_both_resolved(store: Store) -> None:
"""Global closest-pair assignment, not best-for-each-row in turn.
Both lines sit inside both messages' windows. Per-row greedy cannot tell
them apart and drops both; assignment pairs them by distance, which is
correct because the clock skew is the same for both.
"""
a_message(store, NOON_MS)
a_message(store, NOON_MS + 5_000)
report, events = backfill.plan(
store,
[a_line(NOON_MS + 200, "cat"), a_line(NOON_MS + 5_200, "dog")],
)
backfill.apply(store, events)
assert report.ambiguous == 0
assert [(row[0], row[3]) for row in rows(store)] == [
("cat", SOURCE_JOURNAL),
("dog", SOURCE_JOURNAL),
]
def test_a_message_with_no_line_left_for_it_is_dropped(store: Store) -> None:
"""Two messages, one line: the second is a gap, never a guess."""
a_message(store, NOON_MS)
a_message(store, NOON_MS + 1_000)
report, events = backfill.plan(store, [a_line(NOON_MS + 100, "cat")])
backfill.apply(store, events)
assert report.journal_rows == 1
assert report.ambiguous == 1
def test_a_cooldown_refusal_is_recovered_as_a_refusal(store: Store) -> None:
"""The one gate that already logged. daily_limit and vote_gated did not."""
a_message(store, NOON_MS)
_report, events = backfill.plan(store, [a_line(NOON_MS, "cat", refused=True)])
backfill.apply(store, events)
assert rows(store) == [("cat", "refused_cooldown", 12, SOURCE_JOURNAL)]
def test_the_two_sources_do_not_double_count(store: Store) -> None:
"""The failure that would look exactly like data.
daily_uses says three uses. The journal explains one of them exactly.
The residual must be two, not three -- otherwise every historical count
is inflated and nothing anywhere fails.
"""
a_message(store, NOON_MS)
for _ in range(3):
store.record_use(GROUP, "u1", "cat", 1.0, DAY)
report, events = backfill.plan(store, [a_line(NOON_MS + 100, "cat")])
backfill.apply(store, events)
assert report.journal_rows == 1
assert report.daily_rows == 2
assert len(rows(store)) == 3
def test_a_day_the_message_history_never_saw_arrives_whole(store: Store) -> None:
"""The real shape of 2026-08-29: counts, and no message_events at all.
Those rows carry UNKNOWN_HOUR, so every hour-of-day panel must exclude
them rather than file them under midnight.
"""
for _ in range(4):
store.record_use(GROUP, "u1", "pope", 1.0, DAY)
report, events = backfill.plan(store, [])
backfill.apply(store, events)
assert report.journal_rows == 0
assert report.daily_rows == 4
assert {row[2] for row in rows(store)} == {-1}
assert {row[3] for row in rows(store)} == {SOURCE_DAILY}
def test_running_it_twice_inserts_nothing_the_second_time(store: Store) -> None:
"""Idempotency, and it must come from the key rather than from a wipe.
journald has no retention configuration and will rotate. A
clear-then-reimport pass would delete rows it could no longer replace,
so a second run has to be harmless without one.
"""
a_message(store, NOON_MS)
store.record_use(GROUP, "u1", "cat", 1.0, DAY)
lines = [a_line(NOON_MS + 100, "cat")]
_first, events = backfill.plan(store, lines)
backfill.apply(store, events)
before = rows(store)
for candidate in lines:
assert candidate is not None
_second, again = backfill.plan(store, [a_line(NOON_MS + 100, "cat")])
backfill.apply(store, again)
assert rows(store) == before
def test_live_rows_are_never_re_imported(store: Store) -> None:
"""The cutoff. A live row already describes that invocation exactly.
Without it, a pass run after recording started would import the journal
line for an invocation that already exists -- under a different source,
so the natural key would not stop it.
"""
a_message(store, NOON_MS)
store.commands.connection.execute(
"""
INSERT INTO command_events (
group_id, user_uuid, command, args, item_id, outcome, error_class,
invoked_at_ms, day, local_hour, weekday, handler_ms, send_ms, source
) VALUES (?, ?, 'cat', '', NULL, 'ok', '', ?, ?, 12, 5, 10, 10, 'live')
""",
(GROUP, "u1", NOON_MS, DAY),
)
store.commands.connection.commit()
report, events = backfill.plan(store, [a_line(NOON_MS + 100, "cat")])
backfill.apply(store, events)
assert report.journal_rows == 0
assert [row[3] for row in rows(store)] == ["live"]
def test_a_pass_marks_the_groups_it_touched(store: Store) -> None:
"""The same marker stats/backfill.py writes, for the same reason."""
a_message(store, NOON_MS)
_report, events = backfill.plan(store, [a_line(NOON_MS, "cat")])
backfill.apply(store, events)
assert store.meta(GROUP, backfill.BACKFILL_KEY) == "done"
def test_the_report_counts_everything_and_names_nobody() -> None:
"""It is printed to a terminal and pasted into issues.
The join's only input that could carry a person is a display name, and
it dies inside the joiner -- so the summary has to be countable and
nothing else.
"""
report = backfill.Report(journal_rows=3, daily_rows=2, unmatched=1, ambiguous=4, groups=2)
text = "\n".join(report.lines())
assert "3" in text
assert "ambiguous: 4" in text
assert text.count("\n") == 4
def test_midnight_is_built_from_the_date_not_from_arithmetic() -> None:
"""Warsaw days are not all 24 hours; subtracting 86_400_000 lands wrong.
2026-10-25 is the 25-hour day, so the gap from the 24th is not a day's
worth of milliseconds and any spelling that assumes it is drifts.
"""
short_day = backfill.midnight_ms("2026-10-25") - backfill.midnight_ms("2026-10-24")
assert short_day == 24 * 3600 * 1000
long_day = backfill.midnight_ms("2026-10-26") - backfill.midnight_ms("2026-10-25")
assert long_day == 25 * 3600 * 1000