diff --git a/app/reconcile.py b/app/reconcile.py new file mode 100644 index 0000000..08bc60e --- /dev/null +++ b/app/reconcile.py @@ -0,0 +1,171 @@ +"""Asking the carrier what actually happened. + +A provider's 2xx means it accepted the message. It does not mean anyone +received it. Twilio answers `201 Created` and then, seconds later, the carrier +may refuse the message outright — and nothing in an estate that only watches +HTTP status codes will ever notice. + +That is not hypothetical here. On 2026-08-19 the ledger showed **48 consecutive +messages to one number, every one undelivered, going back to January**, +including a daily send for seven weeks. Each was recorded upstream as a +success, and each was billed. + +Two decisions worth keeping: + +**We poll; we are not called back.** The obvious design is Twilio's +`StatusCallback` webhook, but this relay binds to loopback on purpose — a +publicly reachable relay is a spam relay — so no carrier can reach it. Polling +costs one API call per run and keeps that property. + +**We reconcile against the provider's ledger, not our own record.** Our record +is exactly the thing that was wrong, and it only knows about messages we sent. +Twilio's ledger knows about every message on the account, including the ones a +different service sent — which is how those 48 would have been caught even +though nothing here sent them. +""" + +from __future__ import annotations + +import base64 +import json +import urllib.parse +from dataclasses import dataclass +from datetime import datetime, timedelta, timezone +from typing import Any, Callable + +from app.providers import Post, Response, post as default_post + +LIST_URL = "https://api.twilio.com/2010-04-01/Accounts/{sid}/Messages.json" + +# Twilio's terminal states. `sent` means it left Twilio and the carrier has not +# reported back — for a US handset that is usually followed by `delivered` or +# `undelivered`, so it is treated as "still in flight" rather than as success. +DELIVERED = frozenset({"delivered", "received"}) +FAILED = frozenset({"undelivered", "failed"}) +IN_FLIGHT = frozenset({"queued", "accepted", "sending", "sent", "scheduled"}) + + +@dataclass(frozen=True) +class Message: + sid: str + to: str + status: str + error_code: str | None + sent_at: str | None + + @property + def failed(self) -> bool: + return self.status in FAILED + + +@dataclass(frozen=True) +class Report: + delivered: int + failed: list[Message] + in_flight: int + unknown: list[str] + + @property + def ok(self) -> bool: + return not self.failed + + def summary(self) -> str: + if not (self.delivered or self.failed or self.in_flight): + return "no messages in the window" + parts = [f"{self.delivered} delivered", f"{len(self.failed)} failed", f"{self.in_flight} in flight"] + return ", ".join(parts) + + +def _mask(number: str) -> str: + """Enough to recognise a number, not enough to publish one.""" + return f"***{number[-4:]}" if number and len(number) > 4 else "***" + + +def fetch( + *, + account_sid: str, + auth_token: str, + since: datetime, + timeout: float = 15.0, + page_size: int = 200, + post: Post | None = None, + get: Callable[..., Response] | None = None, +) -> list[Message]: + """Every message Twilio has recorded since `since`, whoever sent it.""" + fetcher = get or _get + query = urllib.parse.urlencode({ + # Twilio filters on the date a message was sent, at day granularity for + # the inclusive form; asking from the start of the day is deliberate, + # since a run just after midnight must still see last night's failures. + "DateSent>": since.strftime("%Y-%m-%d"), + "PageSize": str(page_size), + }) + reply = fetcher( + LIST_URL.format(sid=urllib.parse.quote(account_sid, safe="")) + "?" + query, + headers={"Authorization": "Basic " + base64.b64encode( + f"{account_sid}:{auth_token}".encode()).decode()}, + timeout=timeout, + ) + if reply.status >= 400: + raise RuntimeError(f"twilio refused the ledger query with {reply.status}") + + payload: dict[str, Any] = json.loads(reply.body or "{}") + out: list[Message] = [] + for row in payload.get("messages") or []: + sent = row.get("date_sent") or row.get("date_created") + out.append(Message( + sid=str(row.get("sid") or ""), + to=str(row.get("to") or ""), + status=str(row.get("status") or "").lower(), + error_code=str(row["error_code"]) if row.get("error_code") else None, + sent_at=str(sent) if sent else None, + )) + return out + + +def reconcile(messages: list[Message]) -> Report: + delivered = sum(1 for m in messages if m.status in DELIVERED) + failed = [m for m in messages if m.failed] + in_flight = sum(1 for m in messages if m.status in IN_FLIGHT) + unknown = sorted({m.status for m in messages + if m.status and m.status not in DELIVERED | FAILED | IN_FLIGHT}) + return Report(delivered=delivered, failed=failed, in_flight=in_flight, unknown=unknown) + + +def describe(report: Report) -> str: + """A message an operator can act on, with no numbers in full.""" + lines = [f"SMS reconciliation: {report.summary()}."] + if report.failed: + lines.append("") + lines.append("These were accepted by Twilio and then not delivered:") + by_reason: dict[str, list[Message]] = {} + for m in report.failed: + by_reason.setdefault(m.error_code or "no error code", []).append(m) + for reason, group in sorted(by_reason.items(), key=lambda kv: -len(kv[1])): + recipients = ", ".join(sorted({_mask(m.to) for m in group})[:6]) + lines.append(f" {len(group):>3}x error {reason} -> {recipients}") + lines.append("") + lines.append("Error 30032 means the sending number is an unverified toll-free " + "number; the carrier blocks it and no retry will help.") + if report.unknown: + lines.append(f"Statuses this checker does not classify: {', '.join(report.unknown)}") + return "\n".join(lines) + + +def _get(url: str, *, headers: dict[str, str], timeout: float) -> Response: + import urllib.error + import urllib.request + + request = urllib.request.Request(url, method="GET", headers={ + **headers, "User-Agent": "channel-exit-reconcile/1.0"}) + try: + with urllib.request.urlopen(request, timeout=timeout) as reply: + return Response(status=reply.status, body=reply.read().decode(errors="replace"), + headers=dict(reply.headers)) + except urllib.error.HTTPError as error: + return Response(status=error.code, body=error.read().decode(errors="replace"), + headers=dict(error.headers or {})) + + +def window_start(hours: int) -> datetime: + return datetime.now(timezone.utc) - timedelta(hours=hours) diff --git a/scripts/reconcile.py b/scripts/reconcile.py new file mode 100644 index 0000000..8732ba3 --- /dev/null +++ b/scripts/reconcile.py @@ -0,0 +1,67 @@ +#!/usr/bin/env python3 +"""Check what the carrier did with the messages we handed over. + +Run on a schedule. Exits non-zero when anything was accepted and then not +delivered, so a cron mailer or a supervisor surfaces it — the point being that +somebody hears about it. Forty-eight consecutive failures went unnoticed for +seven months because nothing ever asked this question. + + python3 scripts/reconcile.py # last 24 hours + python3 scripts/reconcile.py --hours 168 # last week + python3 scripts/reconcile.py --email you@example.com # and post the report + +Reporting by email goes through this relay's own send path, so the alert +travels the one channel that is known to work. If SMS is the thing that is +broken, an SMS alert about it would be the last thing to arrive. +""" + +from __future__ import annotations + +import argparse +import os +import sys + +sys.path.insert(0, os.path.dirname(os.path.dirname(os.path.abspath(__file__)))) + +from app.config import Settings # noqa: E402 +from app.reconcile import describe, fetch, reconcile, window_start # noqa: E402 + + +def main() -> int: + parser = argparse.ArgumentParser(description=__doc__) + parser.add_argument("--hours", type=int, default=24, help="how far back to look") + parser.add_argument("--email", help="send the report to this address as well") + parser.add_argument("--quiet-when-clean", action="store_true", + help="print nothing when every message was delivered") + args = parser.parse_args() + + settings = Settings() + if not (settings.twilio_sid and settings.twilio_token): + print("no Twilio credentials configured; nothing to reconcile", file=sys.stderr) + return 0 + + messages = fetch(account_sid=settings.twilio_sid, auth_token=settings.twilio_token, + since=window_start(args.hours), timeout=settings.timeout) + report = reconcile(messages) + text = describe(report) + + if report.ok and args.quiet_when_clean: + return 0 + print(text) + + if args.email and report.failed: + # Only on failure: a daily "everything is fine" email is a thing people + # filter, and then the one that matters is filtered too. + from app.providers import send_email + + outcome = send_email( + to=args.email, subject=f"SMS not delivered: {len(report.failed)} in the last {args.hours}h", + body=text, api_key=settings.sendgrid_key, sender=settings.email_from, + timeout=settings.timeout) + print(f"report emailed: provider status {outcome.status}", file=sys.stderr) + + return 1 if report.failed else 0 + + +if __name__ == "__main__": + raise SystemExit(main()) diff --git a/tests/test_reconcile.py b/tests/test_reconcile.py new file mode 100644 index 0000000..528a1a6 --- /dev/null +++ b/tests/test_reconcile.py @@ -0,0 +1,101 @@ +"""Reconciliation. + +These exist because the estate spent seven months treating "the provider +accepted it" as "the person got it". Every test here is about telling those two +apart. +""" + +from __future__ import annotations + +import json +from datetime import datetime, timezone + +import pytest + +from app.providers import Response +from app.reconcile import Message, describe, fetch, reconcile, window_start + + +def ledger(*rows) -> Response: + return Response(status=200, body=json.dumps({"messages": list(rows)}), headers={}) + + +def row(sid="SM1", to="+15550001111", status="delivered", error=None): + return {"sid": sid, "to": to, "status": status, "error_code": error, + "date_sent": "Tue, 19 Aug 2026 00:00:00 +0000"} + + +def test_an_accepted_message_the_carrier_refused_is_a_failure_not_a_success(): + """The whole point. Twilio said 201 at send time for every one of these.""" + report = reconcile([ + Message("SM1", "+15550001111", "delivered", None, None), + Message("SM2", "+15550002222", "undelivered", "30032", None), + Message("SM3", "+15550003333", "failed", "30006", None), + ]) + assert report.delivered == 1 + assert [m.sid for m in report.failed] == ["SM2", "SM3"] + assert report.ok is False + + +def test_sent_is_not_delivered(): + """Twilio's `sent` means it left Twilio, not that a handset received it — + counting it as success is the same mistake one layer down.""" + report = reconcile([Message("SM1", "+15550001111", "sent", None, None)]) + assert report.delivered == 0 + assert report.in_flight == 1 + assert report.ok is True # not yet a failure, but not a delivery either + + +def test_a_clean_window_is_ok(): + report = reconcile([Message("SM1", "+1555", "delivered", None, None)]) + assert report.ok and not report.failed + + +def test_an_unrecognised_status_is_surfaced_rather_than_assumed_good(): + report = reconcile([Message("SM1", "+1555", "carrier_shrugged", None, None)]) + assert report.unknown == ["carrier_shrugged"] + assert report.delivered == 0 + + +def test_the_report_groups_by_reason_and_never_prints_a_full_number(): + report = reconcile([ + Message("SM1", "+17066762576", "undelivered", "30032", None), + Message("SM2", "+17066762576", "undelivered", "30032", None), + Message("SM3", "+15551230000", "failed", "30006", None), + ]) + text = describe(report) + assert "2x error 30032" in text.replace(" ", " ") + assert "***2576" in text + assert "+17066762576" not in text, "a report that leaks full numbers cannot be pasted anywhere" + assert "unverified toll-free" in text + + +def test_the_ledger_query_reads_every_sender_not_just_ours(): + """Reconciling against our own record would have missed the failures that + started this, because a different service sent them.""" + captured = {} + + def fake_get(url, *, headers, timeout): + captured["url"] = url + return ledger(row(sid="SMx", status="undelivered", error="30032")) + + found = fetch(account_sid="AC123", auth_token="secret", + since=datetime(2026, 8, 12, tzinfo=timezone.utc), get=fake_get) + + assert "Messages.json" in captured["url"] + assert "2026-08-12" in captured["url"] + assert "secret" not in captured["url"], "credentials belong in the header, not the query" + assert [m.status for m in found] == ["undelivered"] + assert found[0].error_code == "30032" + + +def test_a_refused_ledger_query_is_loud(): + def refuse(url, *, headers, timeout): + return Response(status=401, body="unauthorized", headers={}) + + with pytest.raises(RuntimeError): + fetch(account_sid="AC1", auth_token="bad", since=window_start(24), get=refuse) + + +def test_window_start_looks_backwards(): + assert window_start(24) < datetime.now(timezone.utc)