A provider 2xx means it accepted the message, not that anyone received it. Twilio answers 201 Created and the carrier may refuse seconds later, and nothing watching HTTP status codes will ever know. That is not hypothetical: the ledger shows 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 rather than take a StatusCallback, because this relay binds to loopback on purpose and no carrier can reach it - polling costs one API call per run and keeps that property. And we reconcile against the provider's ledger rather than our own record, because our own record is exactly what was wrong, and it only knows about messages we sent; Twilio's knows about the ones another service sent too, which is how those 48 would have been caught. Co-Authored-By: Claude Opus 5 (1M context) <[email protected]>
This commit is contained in:
co-authored by
Claude Opus 5
parent
399487862c
commit
349f03015f
@@ -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)
|
||||
@@ -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 [email protected] # 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())
|
||||
@@ -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)
|
||||
Reference in New Issue
Block a user