signal-bot/signal_bot/analytics/probe.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

131 lines
4.5 KiB
Python

# Copyright (c) 2026 Krzysztof Rudnicki. MIT licence.
"""What one running command did, collected without changing any signature.
Timing a command means knowing things the handler learns and the dispatcher
records: how long the upstream fetch took, how long the send took, which
item was served. Threading that back would mean a return value or an extra
argument on every handler, every fetcher method and every reply helper.
A ``ContextVar`` avoids all of it. The dispatcher opens a probe around the
handler call; anything running underneath finds it and notes what it did.
``contextvars`` is stdlib, so the runtime stays at exactly six dependencies.
``Bot.listen`` awaits ``dispatcher.handle`` directly rather than spawning a
task per frame, so set/reset in a ``try/finally`` cannot interleave. A
handler that does spawn a task gets a *copy* of the context, which is the
behaviour wanted: the copy's notes land in the probe, and the reset in the
parent cannot be undone by the child.
Every ``note_*`` is a no-op when nothing is probing. That branch lives here,
once, so no caller needs to ask whether it is being measured -- which is
what keeps ``http_client`` and ``context`` free of analytics conditionals.
"""
from __future__ import annotations
import contextlib
import time
from contextvars import ContextVar
from dataclasses import dataclass, field
from typing import TYPE_CHECKING, Final
if TYPE_CHECKING:
from collections.abc import AsyncIterator, Iterator
# No default sentinel object: None is the whole vocabulary, and the helpers
# below are the only readers.
CURRENT: ContextVar[Probe | None] = ContextVar("command_probe", default=None)
# A request that never got an answer at all -- DNS, connect, timeout. Kept
# distinct from a 5xx, which is upstream answering and answering badly; the
# two mean different things when a command starts failing.
NO_RESPONSE: Final = 0
MS_PER_SECOND: Final = 1000
@dataclass(frozen=True, slots=True)
class UpstreamCall:
"""One outbound HTTP request made while serving a command."""
host: str
status: int
ms: int
@dataclass(slots=True)
class Probe:
"""The mutable notes one invocation accumulates.
Upstream calls are *buffered* rather than written as they happen: they
belong to a ``command_events`` row that does not exist yet, because the
outcome and the duration are only known once the handler has returned.
"""
send_ms: int = 0
item_id: str | None = None
calls: list[UpstreamCall] = field(default_factory=list)
@contextlib.contextmanager
def probing() -> Iterator[Probe]:
"""Open a probe for the duration of one command, and always close it."""
active = Probe()
token = CURRENT.set(active)
try:
yield active
finally:
CURRENT.reset(token)
def note_send(ms: int) -> None:
"""Add the cost of one outbound Signal send.
Accumulated rather than assigned: a handler may send twice, and
``!pułapka`` does -- a picture and then its description.
"""
active = CURRENT.get()
if active is not None:
active.send_ms += ms
@contextlib.asynccontextmanager
async def timed_send() -> AsyncIterator[None]:
"""Time one outbound send and note it, whether or not it succeeds.
``DOCS-latency.md`` measured ``POST /v2/send`` at 2.65 s of a 3.7 s
reply -- 72% of the wall clock, none of it this repository's code -- by
reading three log lines by hand, once. This makes that measurement
continuous, which is what the document's own rule asks for: an upstream
latency claim gets measured before it gets designed around.
"""
started = time.perf_counter()
try:
yield
finally:
note_send(round((time.perf_counter() - started) * MS_PER_SECOND))
def note_upstream(host: str, status: int, ms: int) -> None:
"""Add one upstream request. Host only -- never the URL.
A URL carries identifiers, and some of them are the ones ``item_id``
exists to govern. A hostname cannot carry anything.
"""
active = CURRENT.get()
if active is not None:
active.calls.append(UpstreamCall(host=host, status=status, ms=ms))
def note_item(item_id: str) -> None:
"""Record which item was served, as a public identifier.
A Wikidata QID, a Commons page id, a Wolne Lektury slug, a pseudonym
key, a content-addressed filename. Never a title, a caption or a name:
this is what makes "the pope pool feels repetitive" a number instead of
an impression, and an identifier cannot carry a person.
"""
active = CURRENT.get()
if active is not None:
active.item_id = item_id