From 72482629d9a33a8130e1bfccadd97201cf899ed2 Mon Sep 17 00:00:00 2001 From: Krzysztof kuhy Rudnicki Date: Sun, 30 Aug 2026 15:23:42 +0200 Subject: [PATCH] fix: a signal-api that is not up yet no longer kills the bot at boot Co-Authored-By: Claude Opus 5 (1M context) --- .github/workflows/ci.yml | 6 + DOCS-latency.md | 2 +- DOCS-liveness-and-trust.md | 40 +++++- README.md | 14 +-- scripts/cold_start.sh | 153 +++++++++++++++++++++++ scripts/signal-bot.service | 30 +++-- signal_bot/app.py | 244 +++++++----------------------------- signal_bot/bot.py | 132 ++++++++++++++++++++ signal_bot/discovery.py | 37 ++---- signal_bot/membership.py | 35 ++++++ signal_bot/startup.py | 248 +++++++++++++++++++++++++++++++++++++ tests/conftest.py | 32 ++++- tests/test_app.py | 232 +++++++--------------------------- tests/test_bot.py | 128 +++++++++++++++++++ tests/test_healthz.py | 17 ++- tests/test_startup.py | 240 +++++++++++++++++++++++++++++++++++ 16 files changed, 1150 insertions(+), 440 deletions(-) create mode 100755 scripts/cold_start.sh create mode 100644 signal_bot/bot.py create mode 100644 signal_bot/startup.py create mode 100644 tests/test_bot.py create mode 100644 tests/test_startup.py diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 341e8a6..9e0906a 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -56,3 +56,9 @@ jobs: # The real bot against the fake Signal server. No account, no network. - name: end-to-end run: ./scripts/e2e.sh + + # Boot order reversed: the bot starts first and Signal appears later, + # which is what a reboot looks like and what put the unit in `failed` + # for eight hours on 2026-08-30. + - name: cold start + run: ./scripts/cold_start.sh diff --git a/DOCS-latency.md b/DOCS-latency.md index 7f6941e..32a706c 100644 --- a/DOCS-latency.md +++ b/DOCS-latency.md @@ -35,7 +35,7 @@ building anything, measure these two separately: because the pool could hold ids instead of bytes. Head-of-line blocking is a separate, confirmed problem and does not need -re-measuring: `app.py` awaits each frame to completion, so one slow upstream +re-measuring: `bot.py` awaits each frame to completion, so one slow upstream fetch delays every other message behind it. Dispatching each frame as its own task under a bounded semaphore fixes that regardless of what the send costs. diff --git a/DOCS-liveness-and-trust.md b/DOCS-liveness-and-trust.md index 3ede1c4..5e2b025 100644 --- a/DOCS-liveness-and-trust.md +++ b/DOCS-liveness-and-trust.md @@ -1,7 +1,7 @@ -# Going deaf, and who may add the bot +# Going deaf, not being up yet, and who may add the bot -Two gates that exist because of one afternoon. Both are referenced from -the README; this is the detail. +Three gates, each from a failure that looked like nothing at the time. All +are referenced from the README; this is the detail. ## When it cannot hear @@ -35,6 +35,40 @@ journalctl --user -u signal-api-watchdog.service -n 20 curl -s -o /dev/null -w '%{http_code}\n' http://127.0.0.1:8137/healthz ``` +## When it is not up yet + +On 2026-08-30 the machine rebooted. The bot started before the `signal-api` +container was ready, its first HTTP call raised +`RemoteProtocolError: Server disconnected without sending a response`, +uvicorn reported `Application startup failed. Exiting.`, and `RestartSec=5` +with `StartLimitBurst=5` gave the container **25 seconds** to appear. It took +minutes. The unit landed in `failed` and stayed there for eight hours, and +the group had no bot for all of them. + +`After=docker.service` cannot fix this and never could: dockerd being up says +nothing about the container inside it, and signal-cli then spends further +minutes loading the account. So the connection is no longer part of starting +up. `signal_bot/startup.py` serves first and connects afterwards: + +- uvicorn begins serving immediately, and `/healthz` answers **503** with + `{"status": "connecting"}` and the actual error until the bot is connected. + A booting bot is visibly unhealthy rather than absent. +- The retry backs off 5s → 60s and never gives up. Recovery needs nobody. +- Errors no retry can fix are still fatal, and still land the unit in + `failed` where `systemctl --user --failed` shows them: a container in the + wrong `MODE`, a `GROUP_IDS` entry naming a group the bot is genuinely not + in, a missing `PHONE_NUMBER`, a taken port. + +The distinction that makes the last point safe: a `GROUP_IDS` entry is only +judged against a group listing that was **actually read**. A failed listing +leaves the watched set empty, and convicting the allowlist on that would turn +"the container is not up yet" into a verdict nothing can retry. + +`scripts/cold_start.sh` is the proof, and runs in CI: it boots the bot with +nothing at the other end, asserts the process stays up and says why, then +starts the fake Signal server underneath it and asserts the bot recovers +unaided with all four groups rediscovered. + ## Who may add the bot to a group `TRUSTED_INVITERS` in `.env` is a comma-separated list of `+E.164` numbers, diff --git a/README.md b/README.md index 0fad240..2566803 100644 --- a/README.md +++ b/README.md @@ -141,9 +141,9 @@ journalctl --user -u signal-bot.service -f `Restart=always` brings it back from a crash; lingering (checked by the installer, because without it the promise is false) starts it at boot with -nobody logged in. `StartLimitBurst=5` stops a config error — a missing -a pinned group it cannot join, a taken port — from hiding inside a -permanent restart loop. +nobody logged in. A container that is not up yet is no longer fatal — the bot +serves a 503 `/healthz` and keeps retrying — so `StartLimitBurst=5` is left +doing only what it was for: catching a config error in a restart loop. The health probe binds `127.0.0.1:8137` (`BIND_PORT`). Not 8000: that port attracts unrelated dev servers, and 8137 sits below the ephemeral range so @@ -184,10 +184,10 @@ Two independent reasons, both verified rather than assumed: ## When it cannot hear, and who may add it -The bot was up, healthy and deaf for three hours on 2026-08-29. `/healthz` -now turns **503** when silence plus three failed `/v1/devices` probes say the -connection to Signal is dead, a two-minute timer restarts the container, and -`TRUSTED_INVITERS` decides who may put this bot in a group: +The bot was up, healthy and deaf for three hours on 2026-08-29, and dead in +`failed` for eight after the 2026-08-30 reboot. `/healthz` now has three +answers — `ok`, `connecting`, `deaf` — a two-minute timer restarts the +container, and `TRUSTED_INVITERS` decides who may add this bot to a group: [DOCS-liveness-and-trust.md](DOCS-liveness-and-trust.md). ## Commands diff --git a/scripts/cold_start.sh b/scripts/cold_start.sh new file mode 100755 index 0000000..611a639 --- /dev/null +++ b/scripts/cold_start.sh @@ -0,0 +1,153 @@ +#!/bin/bash + +# ============================================================================ +# Prove the bot survives being started before Signal exists. +# +# The failure this reproduces: on 2026-08-30 the machine rebooted, the bot +# started before the signal-api container was ready, its first HTTP call +# raised, and systemd's start limit put the unit in `failed` -- where it +# stayed for eight hours while the container had been healthy for most of +# them. Nobody noticed, because nothing was watching the unit. +# +# So: boot the bot with nothing at the other end, then start the fake Signal +# server underneath it and assert the bot recovers on its own. Uses the same +# protocol-faithful fake as e2e.sh. No container, no account, no network. +# ============================================================================ + +set -euo pipefail + +SCRIPT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)" +readonly SCRIPT_DIR +REPO_ROOT="$(dirname "$SCRIPT_DIR")" +readonly REPO_ROOT +readonly PYTHON="${PYTHON:-$REPO_ROOT/.venv/bin/python}" +readonly FAKE_PORT="${FAKE_PORT:-8097}" +readonly BOT_PORT="${BOT_PORT:-8096}" +readonly FAKE_URL="http://127.0.0.1:${FAKE_PORT}" +readonly HEALTH="http://127.0.0.1:${BOT_PORT}/healthz" +# Four groups, because "rediscovers all four groups" is the acceptance +# condition the real deployment is judged on. Both spellings of each id +# are real base64, exactly as /v1/groups reports them: the canonical +# `group.` form is the base64 of the internal form. +readonly GROUP_ROWS='[{"id":"group.WTI5c1pDMXZibVV0WjNKdmRYQXRhV1F0TXpJdFlubDBaWE1oSVNFaElTRT0=","internal_id":"Y29sZC1vbmUtZ3JvdXAtaWQtMzItYnl0ZXMhISEhISE=","name":"cold-one","member":true,"joinable":true},{"id":"group.WTI5c1pDMTBkMjh0WjNKdmRYQXRhV1F0TXpJdFlubDBaWE1oSVNFaElTRT0=","internal_id":"Y29sZC10d28tZ3JvdXAtaWQtMzItYnl0ZXMhISEhISE=","name":"cold-two","member":true,"joinable":true},{"id":"group.WTI5c1pDMTBhSEpsWlMxbmNtOTFjQzFwWkMwek1pMWllWFJsY3lFaElTRT0=","internal_id":"Y29sZC10aHJlZS1ncm91cC1pZC0zMi1ieXRlcyEhISE=","name":"cold-three","member":true,"joinable":true},{"id":"group.WTI5c1pDMW1iM1Z5TFdkeWIzVndMV2xrTFRNeUxXSjVkR1Z6SVNFaElTRT0=","internal_id":"Y29sZC1mb3VyLWdyb3VwLWlkLTMyLWJ5dGVzISEhISE=","name":"cold-four","member":true,"joinable":true}]' + +FAKE_PID="" +BOT_PID="" +TEMP_DIR="" + +cleanup() { + if [[ -n "$BOT_PID" ]]; then + kill "$BOT_PID" 2>/dev/null || true + fi + if [[ -n "$FAKE_PID" ]]; then + kill "$FAKE_PID" 2>/dev/null || true + fi + wait 2>/dev/null || true + if [[ -n "$TEMP_DIR" && -d "$TEMP_DIR" ]]; then + rm -rf "$TEMP_DIR" + fi +} +trap cleanup EXIT + +die() { + echo "Error: $1" >&2 + if [[ -n "$TEMP_DIR" && -f "${TEMP_DIR}/bot.log" ]]; then + echo "--- last 20 lines of the bot log ---" >&2 + tail -20 "${TEMP_DIR}/bot.log" >&2 + fi + exit 1 +} + +validate_requirements() { + if [[ ! -x "$PYTHON" ]]; then + echo "Error: no interpreter at $PYTHON. Run: uv venv .venv && uv pip install -e '.[dev]'" >&2 + exit 1 + fi + command -v curl >/dev/null || die "curl is required" +} + +health_code() { + curl -s -o /dev/null -m 5 -w '%{http_code}' "$HEALTH" || true +} + +# Poll /healthz until it reports this status, or give up after $2 seconds. +wait_for_status() { + local want="$1" budget="$2" waited=0 status="" + while ((waited < budget)); do + status="$(curl -s -m 5 "$HEALTH" | tr -d ' ' | grep -o '"status":"[a-z]*"' || true)" + if [[ "$status" == "\"status\":\"${want}\"" ]]; then + printf '%s' "$waited" + return 0 + fi + sleep 1 + waited=$((waited + 1)) + done + die "/healthz never reported '${want}' (last: ${status:-no answer})" +} + +start_the_bot_with_nothing_to_talk_to() { + echo "== booting the bot on :${BOT_PORT}, pointed at a fake that is not running" + env -u CAT_API \ + PHONE_NUMBER="+15550000000" \ + GROUP_IDS="" \ + TRUSTED_INVITERS="" \ + API_BASE_URL="$FAKE_URL" \ + DATABASE_PATH="${TEMP_DIR}/cold.sqlite3" \ + BIND_PORT="$BOT_PORT" \ + "$PYTHON" -m signal_bot >"${TEMP_DIR}/bot.log" 2>&1 & + BOT_PID=$! +} + +# Step 2 of the acceptance test: the process must stay up and say why it is +# unhealthy. The old code exited 3 here and systemd gave up 25 seconds later. +prove_it_stays_up_and_says_why() { + local waited + waited="$(wait_for_status connecting 30)" + echo "== /healthz answered 503 'connecting' after ${waited}s" + kill -0 "$BOT_PID" 2>/dev/null || die "the bot exited instead of waiting" + [[ "$(health_code)" == "503" ]] || die "'connecting' was not served as 503" + curl -s "$HEALTH" | grep -q "ConnectError" || + die "/healthz went red without naming the connection failure" +} + +bring_signal_up_underneath_it() { + echo "== starting the fake Signal server on :${FAKE_PORT}" + "$PYTHON" -m uvicorn fake_signal.server:app \ + --host 127.0.0.1 --port "$FAKE_PORT" --log-level warning & + FAKE_PID=$! + local attempt=0 + until curl -sf "${FAKE_URL}/v1/about" >/dev/null 2>&1; do + attempt=$((attempt + 1)) + ((attempt < 100)) || die "the fake never came up" + sleep 0.1 + done + curl -sf -X POST "${FAKE_URL}/_control/accounts" \ + -H 'Content-Type: application/json' -d '["+15550000000"]' >/dev/null + curl -sf -X POST "${FAKE_URL}/_control/groups" \ + -H 'Content-Type: application/json' -d "$GROUP_ROWS" >/dev/null +} + +# Step 4: nobody restarts anything. The bot's own retry loop has to notice. +prove_it_recovers_unaided() { + local waited found + # The backoff ceiling is 60s, so one full window plus slack. + waited="$(wait_for_status ok 150)" + echo "== /healthz recovered on its own after ${waited}s, with no intervention" + found="$(grep -c 'watching 4 group(s)' "${TEMP_DIR}/bot.log" || true)" + [[ "$found" != "0" ]] || die "the bot came up without rediscovering all four groups" + echo "== all four groups rediscovered" +} + +main() { + validate_requirements + TEMP_DIR="$(mktemp -d)" + + start_the_bot_with_nothing_to_talk_to + prove_it_stays_up_and_says_why + bring_signal_up_underneath_it + prove_it_recovers_unaided + + echo "== cold start passed" +} + +main "$@" diff --git a/scripts/signal-bot.service b/scripts/signal-bot.service index b41b92b..ef7a88a 100644 --- a/scripts/signal-bot.service +++ b/scripts/signal-bot.service @@ -4,16 +4,24 @@ [Unit] Description=Signal group bot Documentation=file://@REPO_ROOT@/README.md -# The bot's only outbound dependency is signal-cli-rest-api in Docker. That -# container runs --restart=always, so it comes back by itself, but Docker has -# to exist before the bot's first connection attempt. +# The bot's only outbound dependency is signal-cli-rest-api in Docker. This +# ordering is worth having and is NOT a fix: dockerd being up says nothing +# about whether the container inside it has finished starting, and signal-cli +# then spends further minutes loading the account. systemd cannot express +# "after that container is ready", so the bot retries the connection itself +# (signal_bot/startup.py) and serves an unhealthy /healthz meanwhile. After=network-online.target docker.service Wants=network-online.target -# A config error -- missing GROUP_IDS, a port that is taken -- exits non-zero -# instantly, and would otherwise spin forever at RestartSec. Five failures in -# a minute stops the unit in `failed` state, which is visible in `systemctl -# --user status`, instead of hiding as a permanent restart loop. -StartLimitIntervalSec=60 +# The start limit now only has to catch answers, not outages. A config error +# -- a missing PHONE_NUMBER, a taken port, a container in the wrong mode -- +# exits almost instantly and would otherwise spin forever, so five of those +# stop the unit in `failed`, which shows up in `systemctl --user --failed`. +# +# The arithmetic: 5 starts x RestartSec=30 is 120s, comfortably inside the +# 300s window, so a genuine config error still trips the limit. What used to +# trip it was 5 x 5s = 25s of a container being slow to boot; on 2026-08-30 +# that left the group with no bot for eight hours. +StartLimitIntervalSec=300 StartLimitBurst=5 [Service] @@ -21,9 +29,11 @@ Type=exec WorkingDirectory=@REPO_ROOT@ # run.sh execs the interpreter, so this PID is the bot itself. ExecStart=@REPO_ROOT@/run.sh -# `always`, not `on-failure`: this process has no correct reason to exit 0. +# `always`, not `on-failure`: the bot never exits on its own except when +# startup hits something no retry can fix, and that path asks uvicorn to +# shut down cleanly -- so exit 0 must still count as a restart. Restart=always -RestartSec=5 +RestartSec=30 # The bot writes only its SQLite tally database, inside the repo. NoNewPrivileges=true PrivateTmp=true diff --git a/signal_bot/app.py b/signal_bot/app.py index 4e71029..7efd7ea 100644 --- a/signal_bot/app.py +++ b/signal_bot/app.py @@ -1,229 +1,72 @@ # Copyright (c) 2026 Krzysztof Rudnicki. MIT licence. -"""Application wiring and the ASGI entrypoint.""" +"""The ASGI entrypoint, and the one endpoint that says whether the bot works. + +Wiring lives in bot.py and the startup sequence in startup.py. What is left +here is the part uvicorn imports: an app that begins serving immediately, so +that "the bot is still connecting" is a state you can ask about rather than a +process that is not there. +""" from __future__ import annotations import asyncio import contextlib -import datetime as dt import logging -from dataclasses import dataclass, field from typing import TYPE_CHECKING -if TYPE_CHECKING: - from collections.abc import AsyncIterator - - from signal_bot.transport_base import Transport - import httpx from fastapi import FastAPI, Response, status -from signal_bot.animals import register_animal_commands -from signal_bot.announce import announce_all -from signal_bot.changelog import load as load_changelog -from signal_bot.config import Config, load_config -from signal_bot.counting import format_tally -from signal_bot.decorators import cooldown -from signal_bot.discovery import GroupDirectory -from signal_bot.dispatcher import Dispatcher -from signal_bot.http_client import ImageFetcher -from signal_bot.liveness import Liveness -from signal_bot.registry import CommandRegistry -from signal_bot.scheduler import DailyScheduler +from signal_bot.config import load_config +from signal_bot.startup import Starter from signal_bot.store import Store -from signal_bot.transport_rest import RestTransport -from signal_bot.trust import InviteTrust from signal_bot.versioning import POPE, __version__ +if TYPE_CHECKING: + from collections.abc import AsyncIterator + logger = logging.getLogger(__name__) -COOLDOWN_MESSAGE = "BEEP BOOP POCZEKAJ {seconds} SEKUND." HTTP_TIMEOUT_SECONDS = 30.0 # iNaturalist asks automated clients to identify themselves, and Wikimedia's # policy outright refuses the default "python-httpx/x.y" this used to send. USER_AGENT = f"signal-bot/{__version__} (+https://github.com/kuhyx/signal-bot)" -def now_local() -> dt.datetime: - """Current local time, timezone-aware.""" - return dt.datetime.now().astimezone() - - -@dataclass -class Bot: - """The wired-up bot and its two long-running loops.""" - - config: Config - store: Store - transport: Transport - directory: GroupDirectory - dispatcher: Dispatcher - liveness: Liveness - - async def publish_report(self) -> None: - """Post each group's own tally into that group, and reset it. - - Each group is isolated on purpose. One group refusing the report -- - the bot removed from it, a transient send failure -- must not cost - every other group its report, and a tally is cleared only after its - report has actually gone out, so a failed send loses nothing. A - group where nobody spoke is skipped entirely. - """ - for group_id in self.directory.groups: - rows = [(t.display_name or t.uuid, t.count) for t in self.store.tallies(group_id)] - if not rows: - # Logged, not posted. The bot is in every group it was ever - # added to, so posting "nobody spoke" would mean a nightly - # ping into every quiet group, forever. - logger.info("no messages in %s today; not posting a report", group_id) - continue - try: - await self.transport.send_text(format_tally(rows), group_id) - except Exception: - logger.exception("daily report failed for group %s", group_id) - continue - self.store.reset_tallies(group_id) - - async def announce_release(self) -> None: - """Tell every watched group about a version it has not seen yet.""" - await announce_all( - self.transport, - self.store, - list(self.directory.groups), - load_changelog(), - __version__, - POPE.name, - ) - - async def listen(self) -> None: - """Consume frames forever, handing each to the dispatcher.""" - async for frame in self.transport.receive(): - # Every frame counts, including receipts and typing indicators: - # the question this answers is "can anything still reach us?", - # not "did anybody address the bot?". - self.liveness.note_envelope() - await self.dispatcher.handle(frame) - - -def build_bot( - config: Config, - client: httpx.AsyncClient, - store: Store, - transport: Transport, - directory: GroupDirectory, - liveness: Liveness, -) -> Bot: - """Assemble the object graph from its injected dependencies.""" - registry = CommandRegistry() - register_animal_commands( - registry, - ImageFetcher(client), - decorate=cooldown(config.cooldown_seconds, COOLDOWN_MESSAGE), - endpoints=config.image_api_urls, - ) - dispatcher = Dispatcher( - config=config, - directory=directory, - registry=registry, - store=store, - transport=transport, - clock=now_local, - ) - return Bot( - config=config, - store=store, - transport=transport, - directory=directory, - dispatcher=dispatcher, - liveness=liveness, - ) - - -@dataclass -class Runtime: - """Owns everything that must be torn down when the app stops.""" - - bot: Bot - client: httpx.AsyncClient - store: Store - tasks: list[asyncio.Task[None]] = field(default_factory=list) - - def start(self) -> None: - """Spawn the listener and the daily scheduler as background tasks.""" - scheduler = DailyScheduler( - self.bot.config.report_hour, - self.bot.config.report_minute, - self.bot.publish_report, - now_local, - asyncio.sleep, - ) - self.tasks = [ - asyncio.create_task(self.bot.listen()), - asyncio.create_task(scheduler.run()), - # Third loop: without it, a group added later is only noticed - # when somebody happens to speak in it. - asyncio.create_task(self.bot.directory.run()), - # Fourth loop: without it, a dead connection to Signal is - # indistinguishable from a quiet evening, for hours. - asyncio.create_task(self.bot.liveness.run()), - # Fifth, and one-shot: says hello with a changelog when the - # running version is newer than what a group was last told. - asyncio.create_task(self.bot.announce_release()), - ] - - async def stop(self) -> None: - """Cancel the background tasks and close every resource.""" - for task in self.tasks: - task.cancel() - for task in self.tasks: - with contextlib.suppress(asyncio.CancelledError): - await task - await self.client.aclose() - self.store.close() - - -async def create_runtime(config: Config, client: httpx.AsyncClient) -> Runtime: - """Build a Runtime, verifying the container exposes a WebSocket first.""" - store = Store(config.database_path) - transport = RestTransport(config, client) - await transport.verify_mode() - directory = GroupDirectory(config, client, store, InviteTrust(config.trusted_inviters)) - await directory.refresh() - await directory.verify_allowlist() - # No probe here: /v1/devices has been seen to hang past 20s, and a - # startup that can hang is a startup that can burn the unit's restart - # limit. The gate starts healthy and earns its verdict at runtime. - liveness = Liveness(config, client) - return Runtime( - bot=build_bot(config, client, store, transport, directory, liveness), - client=client, - store=store, - ) - - @contextlib.asynccontextmanager async def lifespan(app: FastAPI) -> AsyncIterator[None]: - """Start the background tasks without blocking ASGI startup. + """Serve first, connect to Signal afterwards. - The previous version awaited asyncio.gather() on two infinite tasks inside - an on_event("startup") handler, so uvicorn never finished starting up and - the HTTP app never began serving. + Two earlier versions of this got it wrong in opposite directions. The + first awaited asyncio.gather() on two infinite tasks, so uvicorn never + finished starting and never served at all. The second connected to + signal-cli inline, so a container that was not ready yet failed startup + outright and burned the unit's restart limit in 25 seconds. + + Config errors still fail here and exit non-zero: load_config() raising is + an answer, not an outage, and no amount of waiting fixes a missing + PHONE_NUMBER. Everything that needs the network is handed to Starter. """ config = load_config() client = httpx.AsyncClient(timeout=HTTP_TIMEOUT_SECONDS, headers={"User-Agent": USER_AGENT}) - runtime = await create_runtime(config, client) - runtime.start() - logger.info( - "listening as %s, watching %d group(s): %r", - config.phone_number, - len(runtime.bot.directory.groups), - list(runtime.bot.directory.groups), - ) - app.state.runtime = runtime + # Opened once, here, rather than inside the retried connection attempt: + # a Store per attempt would leak one SQLite handle per failed try, for + # as long as the container stayed down. + store = Store(config.database_path) + starter = Starter(config, client, store) + app.state.starter = starter + connecting = asyncio.create_task(starter.run()) + logger.info("serving on %s:%d while connecting to Signal", config.bind_host, config.bind_port) try: yield finally: - await runtime.stop() + connecting.cancel() + with contextlib.suppress(asyncio.CancelledError): + await connecting + if starter.runtime is not None: + await starter.runtime.stop() + await client.aclose() + store.close() app = FastAPI(lifespan=lifespan) @@ -231,14 +74,21 @@ app = FastAPI(lifespan=lifespan) @app.get("/healthz") async def healthz(response: Response) -> dict[str, str]: - """Liveness probe, and the only place the bot admits it has gone deaf. + """Liveness probe, and the only place the bot admits it is not working. Answering 200 while nothing can reach Signal is what let a three-hour outage look like a quiet evening, so this must go red before anybody - thinks to look at the logs. + thinks to look at the logs. It has three answers, not two: a bot that has + not connected yet is "connecting", which is what a booting machine looks + like, and is not the same thing as one that has gone deaf. """ - liveness: Liveness = app.state.runtime.bot.liveness + starter: Starter = app.state.starter build = {"version": __version__, "pope": POPE.name} + runtime = starter.runtime + if runtime is None: + response.status_code = status.HTTP_503_SERVICE_UNAVAILABLE + return {"status": "connecting", "reason": starter.reason, **build} + liveness = runtime.bot.liveness if liveness.healthy: return {"status": "ok", **build} response.status_code = status.HTTP_503_SERVICE_UNAVAILABLE diff --git a/signal_bot/bot.py b/signal_bot/bot.py new file mode 100644 index 0000000..79b4d4c --- /dev/null +++ b/signal_bot/bot.py @@ -0,0 +1,132 @@ +# Copyright (c) 2026 Krzysztof Rudnicki. MIT licence. +"""The bot object itself: the command wiring and the two loops it owns. + +Split out of app.py, which had grown to the 250-line cap with the ASGI +entrypoint, the object graph and the startup sequence all in one file. This +half is "what the bot does"; startup.py is "how it comes up". +""" + +from __future__ import annotations + +import datetime as dt +import logging +from dataclasses import dataclass +from typing import TYPE_CHECKING + +from signal_bot.animals import register_animal_commands +from signal_bot.announce import announce_all +from signal_bot.changelog import load as load_changelog +from signal_bot.counting import format_tally +from signal_bot.decorators import cooldown +from signal_bot.dispatcher import Dispatcher +from signal_bot.http_client import ImageFetcher +from signal_bot.registry import CommandRegistry +from signal_bot.versioning import POPE, __version__ + +if TYPE_CHECKING: + import httpx + + from signal_bot.config import Config + from signal_bot.discovery import GroupDirectory + from signal_bot.liveness import Liveness + from signal_bot.store import Store + from signal_bot.transport_base import Transport + +logger = logging.getLogger(__name__) + +COOLDOWN_MESSAGE = "BEEP BOOP POCZEKAJ {seconds} SEKUND." + + +def now_local() -> dt.datetime: + """Current local time, timezone-aware.""" + return dt.datetime.now().astimezone() + + +@dataclass +class Bot: + """The wired-up bot and its two long-running loops.""" + + config: Config + store: Store + transport: Transport + directory: GroupDirectory + dispatcher: Dispatcher + liveness: Liveness + + async def publish_report(self) -> None: + """Post each group's own tally into that group, and reset it. + + Each group is isolated on purpose. One group refusing the report -- + the bot removed from it, a transient send failure -- must not cost + every other group its report, and a tally is cleared only after its + report has actually gone out, so a failed send loses nothing. A + group where nobody spoke is skipped entirely. + """ + for group_id in self.directory.groups: + rows = [(t.display_name or t.uuid, t.count) for t in self.store.tallies(group_id)] + if not rows: + # Logged, not posted. The bot is in every group it was ever + # added to, so posting "nobody spoke" would mean a nightly + # ping into every quiet group, forever. + logger.info("no messages in %s today; not posting a report", group_id) + continue + try: + await self.transport.send_text(format_tally(rows), group_id) + except Exception: + logger.exception("daily report failed for group %s", group_id) + continue + self.store.reset_tallies(group_id) + + async def announce_release(self) -> None: + """Tell every watched group about a version it has not seen yet.""" + await announce_all( + self.transport, + self.store, + list(self.directory.groups), + load_changelog(), + __version__, + POPE.name, + ) + + async def listen(self) -> None: + """Consume frames forever, handing each to the dispatcher.""" + async for frame in self.transport.receive(): + # Every frame counts, including receipts and typing indicators: + # the question this answers is "can anything still reach us?", + # not "did anybody address the bot?". + self.liveness.note_envelope() + await self.dispatcher.handle(frame) + + +def build_bot( + config: Config, + client: httpx.AsyncClient, + store: Store, + transport: Transport, + directory: GroupDirectory, + liveness: Liveness, +) -> Bot: + """Assemble the object graph from its injected dependencies.""" + registry = CommandRegistry() + register_animal_commands( + registry, + ImageFetcher(client), + decorate=cooldown(config.cooldown_seconds, COOLDOWN_MESSAGE), + endpoints=config.image_api_urls, + ) + dispatcher = Dispatcher( + config=config, + directory=directory, + registry=registry, + store=store, + transport=transport, + clock=now_local, + ) + return Bot( + config=config, + store=store, + transport=transport, + directory=directory, + dispatcher=dispatcher, + liveness=liveness, + ) diff --git a/signal_bot/discovery.py b/signal_bot/discovery.py index ac55fef..7d130e4 100644 --- a/signal_bot/discovery.py +++ b/signal_bot/discovery.py @@ -23,7 +23,7 @@ from typing import TYPE_CHECKING, Any, Final import httpx from signal_bot.groups import build_alias_map, canonical_group_id -from signal_bot.membership import JoinAttempts, attempt_join, verify_allowlist +from signal_bot.membership import JoinAttempts, join_pending, verify_allowlist if TYPE_CHECKING: from signal_bot.config import Config @@ -112,21 +112,27 @@ class GroupDirectory: return self._trust.note_update(message.group_id, message.source_number, message.source_uuid) - async def refresh(self) -> None: + async def refresh(self) -> bool: """Rebuild the watched set from the account's own group listing. Joins anything the bot was merely invited to, then re-reads the listing so membership is decided by the API rather than by the join endpoint's own optimistic answer. + + Returns: + True when a listing was actually read. False means the API could + not be reached and the previous set still stands -- on which no + caller may conclude the bot is missing from a pinned group. """ entries = await self._fetch() if entries is None: - return - if await self._join_pending(entries): + return False + if await join_pending(self._client, self._config, entries, self._joins, self._permitted): entries = await self._fetch() if entries is None: - return + return False self._adopt(entries) + return True async def refresh_for(self, group_id: str) -> str | None: """Refresh once because a message arrived from an unknown group. @@ -201,27 +207,6 @@ class GroupDirectory: return group_id return group_id if self._trust.allows(group_id, entry) else None - async def _join_pending(self, entries: list[dict[str, Any]]) -> bool: - """Try to accept every invitation worth retrying. - - Args: - entries: The current group listing. - - Returns: - True when at least one join was attempted, so the caller knows - the listing needs re-reading. - """ - attempted = False - for entry in entries: - group_id = self._permitted(entry) - if group_id is None or entry.get("member") or self._joins.has_failed(group_id): - continue - logger.warning("invited to %r but not a member; trying to join", entry.get("name")) - detail = await attempt_join(self._client, self._config, group_id) - self._joins.record_failure(group_id, detail) - attempted = True - return attempted - def _adopt(self, entries: list[dict[str, Any]]) -> None: """Replace the watched set from a listing known to be good.""" groups = tuple( diff --git a/signal_bot/membership.py b/signal_bot/membership.py index 639e093..6734eae 100644 --- a/signal_bot/membership.py +++ b/signal_bot/membership.py @@ -20,6 +20,8 @@ import httpx from signal_bot.groups import group_id_aliases if TYPE_CHECKING: + from collections.abc import Callable + from signal_bot.config import Config logger = logging.getLogger(__name__) @@ -106,6 +108,39 @@ async def attempt_join(client: httpx.AsyncClient, config: Config, group_id: str) return f"join returned HTTP {response.status_code}: {response.text.strip()[:200]}" +async def join_pending( + client: httpx.AsyncClient, + config: Config, + entries: list[dict[str, Any]], + joins: JoinAttempts, + permitted: Callable[[dict[str, Any]], str | None], +) -> bool: + """Try to accept every invitation worth retrying. + + Args: + client: HTTP client for the REST API. + config: Resolved runtime configuration. + entries: The current group listing. + joins: Where a refused join is remembered, so it is tried once. + permitted: Decides whether a listing row is one the bot may watch, + returning its canonical id. + + Returns: + True when at least one join was attempted, so the caller knows the + listing needs re-reading. + """ + attempted = False + for entry in entries: + group_id = permitted(entry) + if group_id is None or entry.get("member") or joins.has_failed(group_id): + continue + logger.warning("invited to %r but not a member; trying to join", entry.get("name")) + detail = await attempt_join(client, config, group_id) + joins.record_failure(group_id, detail) + attempted = True + return attempted + + def verify_allowlist(config: Config, groups: tuple[str, ...], joins: JoinAttempts) -> None: """Refuse to start when GROUP_IDS names a group the bot is not in. diff --git a/signal_bot/startup.py b/signal_bot/startup.py new file mode 100644 index 0000000..ed86988 --- /dev/null +++ b/signal_bot/startup.py @@ -0,0 +1,248 @@ +# Copyright (c) 2026 Krzysztof Rudnicki. MIT licence. +"""Coming up, including when signal-cli is not there yet. + +On 2026-08-30 the machine rebooted, the bot started before the signal-api +container was ready, and its very first HTTP call raised. uvicorn reported +"Application startup failed", the unit burned its five restarts in 25 +seconds, and it sat in `failed` for eight hours while the container had been +healthy for almost all of them. Nobody noticed, because a unit nobody is +watching is indistinguishable from a quiet group. + +So the connection to Signal is no longer part of starting up. uvicorn serves +first, /healthz answers 503 with the reason, and this module keeps trying in +the background until the container answers. A bot that is still connecting is +then *visibly* unhealthy rather than absent. + +The distinction that keeps the systemd start limit meaningful: only errors +that another attempt might fix are retried. A container in the wrong mode, or +a GROUP_IDS entry naming a group the bot is genuinely not in, are answers -- +retrying them forever would replace a visible failure with an invisible one. +""" + +from __future__ import annotations + +import asyncio +import contextlib +import logging +import signal +from collections.abc import Awaitable, Callable +from dataclasses import dataclass, field +from typing import TYPE_CHECKING, Final + +import httpx + +from signal_bot.bot import Bot, build_bot, now_local +from signal_bot.discovery import GroupDirectory +from signal_bot.liveness import Liveness +from signal_bot.membership import MembershipError +from signal_bot.scheduler import DailyScheduler +from signal_bot.transport_rest import RestTransport, TransportError +from signal_bot.trust import InviteTrust + +if TYPE_CHECKING: + from signal_bot.config import Config + from signal_bot.store import Store + +logger = logging.getLogger(__name__) + +FIRST_RETRY_SECONDS: Final = 5.0 +# Docker's own restart of signal-api plus signal-cli's account load took +# minutes on the reboot this exists for, so the ceiling is what the bot +# spends most of that wait at. A minute is short enough that recovery is +# still prompt and long enough that a long outage is not a busy loop. +MAX_RETRY_SECONDS: Final = 60.0 +BACKOFF_FACTOR: Final = 2.0 + + +class NotReadyError(RuntimeError): + """Raised when signal-cli answers but cannot yet say what it knows.""" + + +# Another attempt might fix these: the container is still booting, its HTTP +# server is up but answering 502, or it is returning a holding page that is +# not JSON. ValueError covers the last one -- json.JSONDecodeError is one. +RETRYABLE: Final = (httpx.HTTPError, ValueError, NotReadyError) +# No further attempt will fix these. They are verdicts, not outages. +FATAL: Final = (TransportError, MembershipError) + +Sleeper = Callable[[float], Awaitable[None]] +Stopper = Callable[[], None] + + +@dataclass +class Runtime: + """The running bot and the background tasks it owns.""" + + bot: Bot + tasks: list[asyncio.Task[None]] = field(default_factory=list) + + def start(self) -> None: + """Spawn the listener and the daily scheduler as background tasks.""" + scheduler = DailyScheduler( + self.bot.config.report_hour, + self.bot.config.report_minute, + self.bot.publish_report, + now_local, + asyncio.sleep, + ) + self.tasks = [ + asyncio.create_task(self.bot.listen()), + asyncio.create_task(scheduler.run()), + # Third loop: without it, a group added later is only noticed + # when somebody happens to speak in it. + asyncio.create_task(self.bot.directory.run()), + # Fourth loop: without it, a dead connection to Signal is + # indistinguishable from a quiet evening, for hours. + asyncio.create_task(self.bot.liveness.run()), + # Fifth, and one-shot: says hello with a changelog when the + # running version is newer than what a group was last told. + asyncio.create_task(self.bot.announce_release()), + ] + + async def stop(self) -> None: + """Cancel the background tasks. The caller owns the client and store.""" + for task in self.tasks: + task.cancel() + for task in self.tasks: + with contextlib.suppress(asyncio.CancelledError): + await task + + +async def create_runtime(config: Config, client: httpx.AsyncClient, store: Store) -> Runtime: + """Build a Runtime, verifying the container exposes a WebSocket first. + + Args: + config: Resolved runtime configuration. + client: HTTP client shared by every component. + store: The already-open tally database. Owned by the caller, because + this function is retried and must not leak a connection per try. + + Returns: + A Runtime whose loops have not been started yet. + + Raises: + MembershipError: GROUP_IDS names a group the bot is not a member of, + established against a listing that was actually read. + """ + transport = RestTransport(config, client) + await transport.verify_mode() + directory = GroupDirectory(config, client, store, InviteTrust(config.trusted_inviters)) + # Only a listing that really arrived can convict the allowlist. A refresh + # that failed leaves the watched set empty, and judging GROUP_IDS on that + # would turn "the container is not up yet" into "you are not in your own + # group" -- fatal, and wrong. + if not await directory.refresh(): + msg = f"group listing at {config.groups_url} could not be read" + raise NotReadyError(msg) + await directory.verify_allowlist() + # No probe here: /v1/devices has been seen to hang past 20s, and a + # startup that can hang is a startup that can burn the unit's restart + # limit. The gate starts healthy and earns its verdict at runtime. + liveness = Liveness(config, client) + return Runtime(bot=build_bot(config, client, store, transport, directory, liveness)) + + +# Quoted: Config and Store are imported for type checking only, and this +# alias is evaluated at import time. +Factory = Callable[["Config", httpx.AsyncClient, "Store"], Awaitable[Runtime]] + + +def terminate() -> None: + """Ask uvicorn to shut down, from inside a background task. + + A background task cannot exit the process: SystemExit raised in one only + kills that task, is logged as "Task exception was never retrieved", and + uvicorn keeps serving a bot that will never connect. SIGTERM is the + signal uvicorn already handles, and the unit's start limit then turns the + resulting restart loop into a `failed` unit somebody can see. + """ + signal.raise_signal(signal.SIGTERM) + + +class Starter: + """Connects to signal-cli in the background, retrying until it works.""" + + def __init__( + self, + config: Config, + client: httpx.AsyncClient, + store: Store, + *, + sleeper: Sleeper | None = None, + stopper: Stopper | None = None, + factory: Factory = create_runtime, + ) -> None: + """Wire the retry loop to its config and its injectable I/O. + + Args: + config: Resolved runtime configuration. + client: HTTP client shared by every component. + store: The already-open tally database. + sleeper: Async sleep between attempts. Injected by the tests. + stopper: How to end the process on a fatal error. Injected by + the tests, which must not signal the pytest process. + factory: Builds the runtime. Injected by the tests. + """ + self._config = config + self._client = client + self._store = store + self._sleep = sleeper if sleeper is not None else asyncio.sleep + self._stop = stopper if stopper is not None else terminate + self._factory = factory + self.runtime: Runtime | None = None + self._attempts = 0 + self._detail = "not attempted yet" + self._fatal = False + + @property + def reason(self) -> str: + """Why the bot is not connected yet, in one line for /healthz.""" + return ( + f"connecting to {self._config.api_base_url}, attempt {self._attempts}: {self._detail}" + ) + + async def attempt(self) -> bool: + """Try once to build and start the runtime. + + Returns: + True once the bot is connected and its loops are running. + """ + self._attempts += 1 + try: + runtime = await self._factory(self._config, self._client, self._store) + except FATAL as exc: + self._detail = f"{type(exc).__name__}: {exc}" + self._fatal = True + logger.exception("cannot start, and no retry will help") + self._stop() + return False + except RETRYABLE as exc: + self._detail = f"{type(exc).__name__}: {exc}" + logger.warning("signal-cli not reachable yet (attempt %d): %s", self._attempts, exc) + return False + runtime.start() + self.runtime = runtime + logger.info( + "listening as %s after %d attempt(s), watching %d group(s): %r", + self._config.phone_number, + self._attempts, + len(runtime.bot.directory.groups), + list(runtime.bot.directory.groups), + ) + return True + + async def run(self, iterations: int | None = None) -> None: + """Attempt to connect until it works, or until it provably cannot. + + Args: + iterations: Stop after this many failed attempts. None means + keep trying forever, which is what production wants. + """ + completed = 0 + delay = FIRST_RETRY_SECONDS + while iterations is None or completed < iterations: + if await self.attempt() or self._fatal: + return + await self._sleep(delay) + delay = min(delay * BACKOFF_FACTOR, MAX_RETRY_SECONDS) + completed += 1 diff --git a/tests/conftest.py b/tests/conftest.py index 333a764..b0f8ebc 100644 --- a/tests/conftest.py +++ b/tests/conftest.py @@ -5,7 +5,7 @@ from __future__ import annotations import datetime as dt import json -from typing import Any +from typing import TYPE_CHECKING, Any import httpx import pytest @@ -16,6 +16,9 @@ from signal_bot.store import Store from signal_bot.transport_fake import FakeTransport from signal_bot.trust import InviteTrust +if TYPE_CHECKING: + from collections.abc import Callable + # Canonical ``group.`` ids, the spelling /v1/groups reports and the # only one /v2/send accepts. The *_INTERNAL forms are what an envelope # carries: exactly what the canonical form decodes to. @@ -48,9 +51,30 @@ def group_entry(group_id: str, *, member: bool = True, name: str = "e2e") -> dic def listing_client(entries: list[dict[str, Any]]) -> httpx.AsyncClient: """A client whose /v1/groups always answers with these rows.""" - return httpx.AsyncClient( - transport=httpx.MockTransport(lambda request: httpx.Response(200, json=entries)) - ) + return mock_client(lambda request: httpx.Response(200, json=entries)) + + +# Captured before any monkeypatching, so a test that patches +# httpx.AsyncClient cannot make this helper recurse into itself. +_REAL_ASYNC_CLIENT = httpx.AsyncClient + + +def mock_client(handler: Callable[[httpx.Request], httpx.Response]) -> httpx.AsyncClient: + """A client whose every request is answered by this handler.""" + return _REAL_ASYNC_CLIENT(transport=httpx.MockTransport(handler)) + + +def signal_client( + *group_ids: str, mode: str = "json-rpc", member: bool = True +) -> httpx.AsyncClient: + """Answer both startup probes: the container mode, then the group listing.""" + + def handler(request: httpx.Request) -> httpx.Response: + if "/v1/groups" in request.url.path: + return httpx.Response(200, json=[group_entry(gid, member=member) for gid in group_ids]) + return httpx.Response(200, json={"mode": mode}) + + return mock_client(handler) @pytest.fixture diff --git a/tests/test_app.py b/tests/test_app.py index ebbbf6d..01708ca 100644 --- a/tests/test_app.py +++ b/tests/test_app.py @@ -1,229 +1,81 @@ # Copyright (c) 2026 Krzysztof Rudnicki. MIT licence. -"""Wiring, the background loops, and ASGI startup.""" +"""ASGI startup: the app must serve before it can talk to Signal, not after.""" from __future__ import annotations -import asyncio -from dataclasses import dataclass, replace from typing import TYPE_CHECKING import httpx -import pytest from fastapi.testclient import TestClient from signal_bot import app as app_module -from signal_bot.app import Bot, Runtime, build_bot, create_runtime, lifespan, now_local -from signal_bot.discovery import GroupDirectory -from signal_bot.liveness import Liveness -from signal_bot.membership import MembershipError -from signal_bot.transport_fake import FakeTransport -from signal_bot.transport_rest import TransportError -from signal_bot.trust import InviteTrust +from signal_bot.app import lifespan from signal_bot.versioning import __version__ -from tests.conftest import SECOND_GROUP, WATCHED_GROUP, envelope, group_entry, listing_client +from tests.conftest import WATCHED_GROUP, mock_client, signal_client if TYPE_CHECKING: - from signal_bot.config import Config - from signal_bot.registry import Handler - from signal_bot.store import Store + from collections.abc import Iterator + + import pytest BASE_ENV = { "PHONE_NUMBER": "+15550000000", "GROUP_IDS": "", + "API_BASE_URL": "http://localhost:9922", "DATABASE_PATH": ":memory:", } - -# Captured before any monkeypatching, so a patched httpx.AsyncClient cannot -# recurse into this helper. -_REAL_ASYNC_CLIENT = httpx.AsyncClient +DEAD = httpx.ConnectError("Server disconnected without sending a response.") -def _client(handler: Handler) -> httpx.AsyncClient: - return _REAL_ASYNC_CLIENT(transport=httpx.MockTransport(handler)) +def _offline(request: httpx.Request) -> httpx.Response: + raise DEAD -def _signal(*group_ids: str, mode: str = "json-rpc", member: bool = True) -> Handler: - """Answer both startup probes: the mode check and the group listing.""" - - def handler(request: httpx.Request) -> httpx.Response: - if "/v1/groups" in request.url.path: - return httpx.Response(200, json=[group_entry(gid, member=member) for gid in group_ids]) - return httpx.Response(200, json={"mode": mode}) - - return handler - - -def _bot(config: Config, store: Store, transport: FakeTransport, directory: GroupDirectory) -> Bot: - client = _client(lambda r: httpx.Response(200)) - return build_bot(config, client, store, transport, directory, Liveness(config, client)) - - -def test_now_local_is_timezone_aware() -> None: - assert now_local().tzinfo is not None - - -def test_build_bot_registers_the_animal_commands( - config: Config, store: Store, transport: FakeTransport, directory: GroupDirectory -) -> None: - bot = _bot(config, store, transport, directory) - assert bot.dispatcher.registry.resolve("!cat") is not None - assert bot.dispatcher.registry.resolve("!pies") is not None - - -async def test_publish_report_posts_each_group_its_own_tally( - config: Config, store: Store, transport: FakeTransport, directory: GroupDirectory -) -> None: - """Every group gets its own counts, in its own chat, and only its own.""" - store.increment(WATCHED_GROUP, "u1", "Alice") - store.increment(SECOND_GROUP, "u2", "Bob") - store.increment(SECOND_GROUP, "u2", "Bob") - await _bot(config, store, transport, directory).publish_report() - assert [(m.recipient, m.text) for m in transport.sent] == [ - (WATCHED_GROUP, "Alice 1"), - (SECOND_GROUP, "Bob 2"), - ] - assert store.tallies(WATCHED_GROUP) == [] - assert store.tallies(SECOND_GROUP) == [] - - -async def test_publish_report_falls_back_to_uuid_when_unnamed( - config: Config, store: Store, transport: FakeTransport, directory: GroupDirectory -) -> None: - store.increment(WATCHED_GROUP, "u1", "") - await _bot(config, store, transport, directory).publish_report() - assert transport.texts[0] == "u1 1" - - -async def test_listen_dispatches_every_frame( - config: Config, store: Store, transport: FakeTransport, directory: GroupDirectory -) -> None: - transport.queue([envelope(text="hello", group_id=WATCHED_GROUP)]) - await _bot(config, store, transport, directory).listen() - assert store.tallies(WATCHED_GROUP)[0].count == 1 - - -async def test_create_runtime_verifies_the_container_mode(config: Config) -> None: - runtime = await create_runtime(config, _client(_signal(WATCHED_GROUP, SECOND_GROUP))) - assert isinstance(runtime, Runtime) - await runtime.stop() - - -async def test_create_runtime_refuses_a_polling_container(config: Config) -> None: - with pytest.raises(TransportError): - await create_runtime( - config, _client(lambda r: httpx.Response(200, json={"mode": "normal"})) - ) - - -async def test_runtime_start_and_stop_cancels_tasks( - config: Config, store: Store, transport: FakeTransport, directory: GroupDirectory -) -> None: - client = _client(lambda r: httpx.Response(200)) - runtime = Runtime(bot=_bot(config, store, transport, directory), client=client, store=store) - runtime.start() - # listen, the daily report, the group refresh loop, the deafness gate, - # and the one-shot release announcement. - assert len(runtime.tasks) == 5 - await asyncio.sleep(0) - await runtime.stop() - assert all(task.done() for task in runtime.tasks) - - -def test_healthz_serves_and_startup_completes(monkeypatch: pytest.MonkeyPatch) -> None: - """The old app never finished startup, so no route was ever reachable.""" +def _serving(monkeypatch: pytest.MonkeyPatch, client: httpx.AsyncClient) -> Iterator[TestClient]: for key, value in BASE_ENV.items(): monkeypatch.setenv(key, value) + monkeypatch.setattr(app_module.httpx, "AsyncClient", lambda **kwargs: client) + return TestClient(app_module.app) - def fake_client(**kwargs: object) -> httpx.AsyncClient: - return _client(_signal(WATCHED_GROUP)) - monkeypatch.setattr(app_module.httpx, "AsyncClient", fake_client) - with TestClient(app_module.app) as client: - body = client.get("/healthz").json() +def test_healthz_serves_while_signal_cli_is_unreachable(monkeypatch: pytest.MonkeyPatch) -> None: + """The 2026-08-30 reboot: startup used to fail outright and stay failed.""" + with _serving(monkeypatch, mock_client(_offline)) as client: + response = client.get("/healthz") + assert response.status_code == httpx.codes.SERVICE_UNAVAILABLE + body = response.json() + # Not "deaf": a bot that has never connected is a different state + # from one that could hear and then stopped. + assert body["status"] == "connecting" + assert "attempt" in body["reason"] + assert body["version"] == __version__ + + +def test_healthz_turns_green_once_the_container_answers( + monkeypatch: pytest.MonkeyPatch, +) -> None: + """The old app never finished startup, so no route was ever reachable.""" + with _serving(monkeypatch, signal_client(WATCHED_GROUP)) as client: + body: dict[str, str] = {} + # Each request hands the event loop back to the connecting task. + for _ in range(50): + body = client.get("/healthz").json() + if body["status"] == "ok": + break assert body["status"] == "ok" assert body["version"] == __version__ -async def test_lifespan_is_an_async_context_manager( - monkeypatch: pytest.MonkeyPatch, -) -> None: +async def test_lifespan_is_an_async_context_manager(monkeypatch: pytest.MonkeyPatch) -> None: for key, value in BASE_ENV.items(): monkeypatch.setenv(key, value) monkeypatch.setattr( app_module.httpx, "AsyncClient", - lambda **kwargs: _client(_signal(WATCHED_GROUP)), + lambda **kwargs: signal_client(WATCHED_GROUP), ) async with lifespan(app_module.app): - assert app_module.app.state.runtime is not None - - -async def test_create_runtime_refuses_a_pinned_group_it_cannot_join( - config: Config, -) -> None: - """A pending invite looks healthy from outside; a pinned startup must not.""" - pinned = replace(config, group_ids=(WATCHED_GROUP,)) - with pytest.raises(MembershipError, match="not a joined member"): - await create_runtime(pinned, _client(_signal(WATCHED_GROUP, member=False))) - - -async def test_create_runtime_accepts_an_account_in_no_groups_at_all( - config: Config, -) -> None: - """An unpinned bot with no groups is not broken; it is waiting to be added.""" - runtime = await create_runtime(config, _client(_signal())) - assert runtime.bot.directory.groups == () - await runtime.stop() - - -@dataclass -class RefusingTransport(FakeTransport): - """A transport that rejects one group, the way a removal from it would.""" - - refuses: str = "" - - async def send_text(self, text: str, recipient: str) -> None: - """Record the send, unless this is the group that refuses them.""" - if recipient == self.refuses: - msg = "removed from the group" - raise RuntimeError(msg) - await super().send_text(text, recipient) - - -async def test_one_group_failing_its_report_does_not_cost_the_others( - config: Config, store: Store, directory: GroupDirectory -) -> None: - """A failed send must not clear that group's day, nor skip the next group.""" - store.increment(WATCHED_GROUP, "u1", "Alice") - store.increment(SECOND_GROUP, "u2", "Bob") - transport = RefusingTransport(refuses=WATCHED_GROUP) - - await _bot(config, store, transport, directory).publish_report() - - assert [(m.recipient, m.text) for m in transport.sent] == [(SECOND_GROUP, "Bob 1")] - # The group that failed keeps its counts; the one that succeeded is reset. - assert store.tallies(WATCHED_GROUP)[0].count == 1 - assert store.tallies(SECOND_GROUP) == [] - - -async def test_a_quiet_group_is_logged_rather_than_posted_into( - config: Config, store: Store, transport: FakeTransport, directory: GroupDirectory -) -> None: - """The bot sits in every group it was added to; a nightly ping is noise.""" - store.increment(SECOND_GROUP, "u2", "Bob") - await _bot(config, store, transport, directory).publish_report() - assert [(m.recipient, m.text) for m in transport.sent] == [(SECOND_GROUP, "Bob 1")] - - -async def test_the_report_follows_the_live_group_set( - config: Config, store: Store, transport: FakeTransport -) -> None: - """Groups come from the directory, not from .env, so a new one is included.""" - client = listing_client([group_entry(WATCHED_GROUP), group_entry(SECOND_GROUP)]) - directory = GroupDirectory(config, client, store, InviteTrust(())) - await directory.refresh() - store.increment(WATCHED_GROUP, "u1", "Alice") - store.increment(SECOND_GROUP, "u2", "Bob") - await _bot(config, store, transport, directory).publish_report() - assert [m.recipient for m in transport.sent] == [WATCHED_GROUP, SECOND_GROUP] + # Present immediately, before anything has reached Signal: /healthz + # reads it, and an absent attribute would be a 500 rather than a 503. + assert app_module.app.state.starter is not None diff --git a/tests/test_bot.py b/tests/test_bot.py new file mode 100644 index 0000000..0d124b8 --- /dev/null +++ b/tests/test_bot.py @@ -0,0 +1,128 @@ +# Copyright (c) 2026 Krzysztof Rudnicki. MIT licence. +"""Command wiring, the daily report, and the listen loop.""" + +from __future__ import annotations + +from dataclasses import dataclass +from typing import TYPE_CHECKING + +import httpx + +from signal_bot.bot import Bot, build_bot, now_local +from signal_bot.discovery import GroupDirectory +from signal_bot.liveness import Liveness +from signal_bot.transport_fake import FakeTransport +from signal_bot.trust import InviteTrust +from tests.conftest import ( + SECOND_GROUP, + WATCHED_GROUP, + envelope, + group_entry, + listing_client, + mock_client, +) + +if TYPE_CHECKING: + from signal_bot.config import Config + from signal_bot.store import Store + + +def _bot(config: Config, store: Store, transport: FakeTransport, directory: GroupDirectory) -> Bot: + client = mock_client(lambda r: httpx.Response(200)) + return build_bot(config, client, store, transport, directory, Liveness(config, client)) + + +def test_now_local_is_timezone_aware() -> None: + assert now_local().tzinfo is not None + + +def test_build_bot_registers_the_animal_commands( + config: Config, store: Store, transport: FakeTransport, directory: GroupDirectory +) -> None: + bot = _bot(config, store, transport, directory) + assert bot.dispatcher.registry.resolve("!cat") is not None + assert bot.dispatcher.registry.resolve("!pies") is not None + + +async def test_publish_report_posts_each_group_its_own_tally( + config: Config, store: Store, transport: FakeTransport, directory: GroupDirectory +) -> None: + """Every group gets its own counts, in its own chat, and only its own.""" + store.increment(WATCHED_GROUP, "u1", "Alice") + store.increment(SECOND_GROUP, "u2", "Bob") + store.increment(SECOND_GROUP, "u2", "Bob") + await _bot(config, store, transport, directory).publish_report() + assert [(m.recipient, m.text) for m in transport.sent] == [ + (WATCHED_GROUP, "Alice 1"), + (SECOND_GROUP, "Bob 2"), + ] + assert store.tallies(WATCHED_GROUP) == [] + assert store.tallies(SECOND_GROUP) == [] + + +async def test_publish_report_falls_back_to_uuid_when_unnamed( + config: Config, store: Store, transport: FakeTransport, directory: GroupDirectory +) -> None: + store.increment(WATCHED_GROUP, "u1", "") + await _bot(config, store, transport, directory).publish_report() + assert transport.texts[0] == "u1 1" + + +async def test_listen_dispatches_every_frame( + config: Config, store: Store, transport: FakeTransport, directory: GroupDirectory +) -> None: + transport.queue([envelope(text="hello", group_id=WATCHED_GROUP)]) + await _bot(config, store, transport, directory).listen() + assert store.tallies(WATCHED_GROUP)[0].count == 1 + + +@dataclass +class RefusingTransport(FakeTransport): + """A transport that rejects one group, the way a removal from it would.""" + + refuses: str = "" + + async def send_text(self, text: str, recipient: str) -> None: + """Record the send, unless this is the group that refuses them.""" + if recipient == self.refuses: + msg = "removed from the group" + raise RuntimeError(msg) + await super().send_text(text, recipient) + + +async def test_one_group_failing_its_report_does_not_cost_the_others( + config: Config, store: Store, directory: GroupDirectory +) -> None: + """A failed send must not clear that group's day, nor skip the next group.""" + store.increment(WATCHED_GROUP, "u1", "Alice") + store.increment(SECOND_GROUP, "u2", "Bob") + transport = RefusingTransport(refuses=WATCHED_GROUP) + + await _bot(config, store, transport, directory).publish_report() + + assert [(m.recipient, m.text) for m in transport.sent] == [(SECOND_GROUP, "Bob 1")] + # The group that failed keeps its counts; the one that succeeded is reset. + assert store.tallies(WATCHED_GROUP)[0].count == 1 + assert store.tallies(SECOND_GROUP) == [] + + +async def test_a_quiet_group_is_logged_rather_than_posted_into( + config: Config, store: Store, transport: FakeTransport, directory: GroupDirectory +) -> None: + """The bot sits in every group it was added to; a nightly ping is noise.""" + store.increment(SECOND_GROUP, "u2", "Bob") + await _bot(config, store, transport, directory).publish_report() + assert [(m.recipient, m.text) for m in transport.sent] == [(SECOND_GROUP, "Bob 1")] + + +async def test_the_report_follows_the_live_group_set( + config: Config, store: Store, transport: FakeTransport +) -> None: + """Groups come from the directory, not from .env, so a new one is included.""" + client = listing_client([group_entry(WATCHED_GROUP), group_entry(SECOND_GROUP)]) + directory = GroupDirectory(config, client, store, InviteTrust(())) + await directory.refresh() + store.increment(WATCHED_GROUP, "u1", "Alice") + store.increment(SECOND_GROUP, "u2", "Bob") + await _bot(config, store, transport, directory).publish_report() + assert [m.recipient for m in transport.sent] == [WATCHED_GROUP, SECOND_GROUP] diff --git a/tests/test_healthz.py b/tests/test_healthz.py index 6244ddc..d5eb176 100644 --- a/tests/test_healthz.py +++ b/tests/test_healthz.py @@ -28,8 +28,21 @@ def _gate(config: Config, response: httpx.Response) -> Liveness: def _install(liveness: Liveness) -> None: - """Point the app at a runtime carrying this gate.""" - app_module.app.state.runtime = SimpleNamespace(bot=SimpleNamespace(liveness=liveness)) + """Point the app at a connected starter carrying this gate.""" + runtime = SimpleNamespace(bot=SimpleNamespace(liveness=liveness)) + app_module.app.state.starter = SimpleNamespace(runtime=runtime, reason="") + + +async def test_a_bot_that_has_not_connected_yet_says_connecting() -> None: + """Booting is not deafness, and must not be reported as it.""" + app_module.app.state.starter = SimpleNamespace( + runtime=None, reason="connecting to http://localhost:9922, attempt 3: ConnectError" + ) + response = Response() + body = await healthz(response) + assert response.status_code == httpx.codes.SERVICE_UNAVAILABLE + assert body["status"] == "connecting" + assert "attempt 3" in body["reason"] async def test_a_healthy_bot_answers_ok(config: Config) -> None: diff --git a/tests/test_startup.py b/tests/test_startup.py new file mode 100644 index 0000000..6f9ba7a --- /dev/null +++ b/tests/test_startup.py @@ -0,0 +1,240 @@ +# Copyright (c) 2026 Krzysztof Rudnicki. MIT licence. +"""Coming up while signal-cli is not there yet. + +The failure being nailed down: on 2026-08-30 the machine rebooted, the bot's +first HTTP call raised because the container was still starting, the unit +burned its five restarts in 25 seconds and stayed dead for eight hours. +""" + +from __future__ import annotations + +import asyncio +import signal +from dataclasses import replace +from typing import TYPE_CHECKING + +import httpx +import pytest + +from signal_bot import startup as startup_module +from signal_bot.bot import build_bot +from signal_bot.discovery import GroupDirectory +from signal_bot.liveness import Liveness +from signal_bot.membership import MembershipError +from signal_bot.startup import ( + MAX_RETRY_SECONDS, + NotReadyError, + Runtime, + Starter, + create_runtime, + terminate, +) +from signal_bot.transport_fake import FakeTransport +from signal_bot.transport_rest import TransportError +from signal_bot.trust import InviteTrust +from tests.conftest import SECOND_GROUP, WATCHED_GROUP, mock_client, signal_client + +if TYPE_CHECKING: + from signal_bot.config import Config + from signal_bot.store import Store + +DEAD = httpx.ConnectError("Server disconnected without sending a response.") + + +def _offline(request: httpx.Request) -> httpx.Response: + raise DEAD + + +def _fake_runtime(config: Config, store: Store) -> Runtime: + """A runtime whose loops touch nothing outside the process.""" + client = mock_client(lambda r: httpx.Response(200)) + directory = GroupDirectory(config, client, store, InviteTrust(())) + liveness = Liveness(config, client) + bot = build_bot(config, client, store, FakeTransport(), directory, liveness) + return Runtime(bot=bot) + + +class Sleeps: + """An async sleep that records instead of waiting.""" + + def __init__(self) -> None: + self.delays: list[float] = [] + + async def __call__(self, seconds: float) -> None: + self.delays.append(seconds) + + +async def test_create_runtime_verifies_the_container_mode(config: Config, store: Store) -> None: + runtime = await create_runtime(config, signal_client(WATCHED_GROUP, SECOND_GROUP), store) + assert isinstance(runtime, Runtime) + await runtime.stop() + + +async def test_create_runtime_refuses_a_polling_container(config: Config, store: Store) -> None: + with pytest.raises(TransportError): + await create_runtime(config, signal_client(mode="normal"), store) + + +async def test_create_runtime_refuses_a_pinned_group_it_cannot_join( + config: Config, store: Store +) -> None: + """A pending invite looks healthy from outside; a pinned startup must not.""" + pinned = replace(config, group_ids=(WATCHED_GROUP,)) + with pytest.raises(MembershipError, match="not a joined member"): + await create_runtime(pinned, signal_client(WATCHED_GROUP, member=False), store) + + +async def test_create_runtime_accepts_an_account_in_no_groups_at_all( + config: Config, store: Store +) -> None: + """An unpinned bot with no groups is not broken; it is waiting to be added.""" + runtime = await create_runtime(config, signal_client(), store) + assert runtime.bot.directory.groups == () + await runtime.stop() + + +async def test_an_unreadable_listing_is_not_a_missing_group(config: Config, store: Store) -> None: + """The trap this ordering exists for. + + With the container down, the watched set stays empty. Judging GROUP_IDS + on that empty set would raise MembershipError -- a verdict nothing can + retry -- for a bot that is in its group and simply cannot ask yet. + """ + pinned = replace(config, group_ids=(WATCHED_GROUP,)) + + def half_up(request: httpx.Request) -> httpx.Response: + if "/v1/groups" in request.url.path: + raise DEAD + return httpx.Response(200, json={"mode": "json-rpc"}) + + with pytest.raises(NotReadyError, match="could not be read"): + await create_runtime(pinned, mock_client(half_up), store) + + +async def test_runtime_start_and_stop_cancels_tasks(config: Config, store: Store) -> None: + runtime = _fake_runtime(config, store) + runtime.start() + # listen, the daily report, the group refresh loop, the deafness gate, + # and the one-shot release announcement. + assert len(runtime.tasks) == 5 + await asyncio.sleep(0) + await runtime.stop() + assert all(task.done() for task in runtime.tasks) + + +async def test_starter_connects_on_the_first_attempt(config: Config, store: Store) -> None: + sleeps = Sleeps() + starter = Starter( + config, + mock_client(lambda r: httpx.Response(200)), + store, + sleeper=sleeps, + factory=lambda c, _client, s: _ready(c, s), + ) + await starter.run() + assert starter.runtime is not None + assert sleeps.delays == [] + await starter.runtime.stop() + + +async def _ready(config: Config, store: Store) -> Runtime: + return _fake_runtime(config, store) + + +async def test_starter_survives_a_container_that_is_not_up_yet( + config: Config, store: Store +) -> None: + """The whole point: a slow container costs attempts, never the process.""" + attempts = {"n": 0} + + async def flaky(cfg: Config, _client: httpx.AsyncClient, opened: Store) -> Runtime: + attempts["n"] += 1 + if attempts["n"] < 3: + raise DEAD + return _fake_runtime(cfg, opened) + + stopped: list[bool] = [] + sleeps = Sleeps() + starter = Starter( + config, + mock_client(_offline), + store, + sleeper=sleeps, + stopper=lambda: stopped.append(True), + factory=flaky, + ) + # Unhealthy and honest about why, before it ever succeeds. + assert starter.runtime is None + assert "not attempted yet" in starter.reason + + await starter.run() + + assert attempts["n"] == 3 + assert starter.runtime is not None + # Recovered with nobody touching it, and without ending the process. + assert stopped == [] + assert sleeps.delays == [5.0, 10.0] + await starter.runtime.stop() + + +async def test_starter_backoff_stops_growing(config: Config, store: Store) -> None: + sleeps = Sleeps() + starter = Starter( + config, + mock_client(_offline), + store, + sleeper=sleeps, + stopper=lambda: None, + factory=_always_offline, + ) + await starter.run(iterations=8) + assert starter.runtime is None + assert max(sleeps.delays) == MAX_RETRY_SECONDS + assert f"attempt {len(sleeps.delays)}" in starter.reason + assert "ConnectError" in starter.reason + + +async def _always_offline(config: Config, client: httpx.AsyncClient, store: Store) -> Runtime: + raise DEAD + + +async def test_a_container_in_the_wrong_mode_is_fatal(config: Config, store: Store) -> None: + """Not an outage: no number of retries turns 'normal' into 'json-rpc'.""" + stopped: list[bool] = [] + sleeps = Sleeps() + starter = Starter( + config, + signal_client(mode="normal"), + store, + sleeper=sleeps, + stopper=lambda: stopped.append(True), + ) + await starter.run() + assert starter.runtime is None + assert stopped == [True] + # It gave up rather than backing off forever. + assert sleeps.delays == [] + assert "TransportError" in starter.reason + + +async def test_a_pinned_group_the_bot_is_not_in_is_fatal(config: Config, store: Store) -> None: + stopped: list[bool] = [] + pinned = replace(config, group_ids=(WATCHED_GROUP,)) + starter = Starter( + pinned, + signal_client(WATCHED_GROUP, member=False), + store, + sleeper=Sleeps(), + stopper=lambda: stopped.append(True), + ) + await starter.run() + assert stopped == [True] + assert "MembershipError" in starter.reason + + +def test_terminate_asks_uvicorn_to_shut_down(monkeypatch: pytest.MonkeyPatch) -> None: + """A background task cannot exit the process; SIGTERM is how it asks.""" + sent: list[int] = [] + monkeypatch.setattr(startup_module.signal, "raise_signal", sent.append) + terminate() + assert sent == [signal.SIGTERM]