error 30036: messages expire in the queue before they send

"""Report Twilio messages that expired in the queue (30036) and the TTL rejections near it.

Read only. GET requests and nothing else: give this an API Key with read access
rather than the account auth token. The repair is printed, never performed,
because this script holds a credential to an account that can send messages and
spend money.
"""
import argparse
import datetime as dt
import logging
import os
import sys

import requests

logging.basicConfig(level=logging.INFO, format="%(asctime)s %(levelname)s %(message)s")
log = logging.getLogger("twilio_validity_period_audit")

HOST = "https://api.twilio.com"
BASE = HOST + "/2010-04-01"
MESSAGING = "https://messaging.twilio.com/v1"

EXPIRED = 30036         # queued past its ValidityPeriod and dropped
OUT_OF_RANGE = 30045    # ValidityPeriod outside 1..36000, rejected at request time
TTL_TOO_SMALL = 30012   # TTL below what the route accepts, rejected at request time

MAX_VALIDITY = 36000


def error_code(message):
    """Read error_code as an integer, or None.

    Null on healthy messages, a number on failed ones, and a string often enough
    that comparing the raw value against 30036 quietly reports nothing.
    """
    raw = message.get("error_code")
    if raw is None or raw == "":
        return None
    try:
        return int(raw)
    except (TypeError, ValueError):
        return None


def tally(messages):
    """Bucket the three TTL codes by the sender whose queue they waited in.

    Pure, so the grouping can be tested without a network. The codes are kept
    apart rather than summed: 30045 and 30012 never reached a queue at all, so
    folding them into the expiry count produces a number that points at no
    particular repair.
    """
    out = {}
    for m in messages:
        if str(m.get("direction") or "").startswith("inbound"):
            continue
        key = m.get("messaging_service_sid") or m.get("from") or "unknown sender"
        row = out.setdefault(key, {"total": 0, "expired": 0, "out_of_range": 0,
                                   "ttl_too_small": 0, "sids": []})
        row["total"] += 1
        code = error_code(m)
        if code == EXPIRED:
            row["expired"] += 1
        elif code == OUT_OF_RANGE:
            row["out_of_range"] += 1
        elif code == TTL_TOO_SMALL:
            row["ttl_too_small"] += 1
        else:
            continue
        if len(row["sids"]) < 3:
            row["sids"].append(m.get("sid"))
    return out


def verdict(stats, validity_period=None, floor=3600):
    """Classify one sender. Pure, so the ordering and the thresholds are visible.

    validity_period is the service-level cap in seconds, or None when the sender
    is a bare From number with no Messaging Service behind it.

    The request-time codes are checked first on purpose. When both kinds are
    present the caller is constructing bad sends, and changing the service
    setting fixes none of those.

    Returns (state, detail).
    """
    total = int(stats.get("total") or 0)
    expired = int(stats.get("expired") or 0)
    out_of_range = int(stats.get("out_of_range") or 0)
    ttl_too_small = int(stats.get("ttl_too_small") or 0)

    if out_of_range:
        return ("out-of-range",
                "%d message(s) rejected with 30045. ValidityPeriod has to be 1 to "
                "%d seconds and something is passing a value outside that, so "
                "those sends never entered a queue. Usually a unit mix-up: "
                "milliseconds where seconds were meant."
                % (out_of_range, MAX_VALIDITY))

    if ttl_too_small:
        return ("ttl-too-small",
                "%d message(s) rejected with 30012: the TTL asked for is below "
                "what the route will accept, so the send was refused before "
                "anything was queued. Fix it where the send is built."
                % ttl_too_small)

    if not expired:
        return ("clean", "%d message(s), none expired in queue" % total)

    rate = (expired / total) if total else 1.0

    if validity_period is not None and validity_period < floor:
        return ("service-too-low",
                "%d of %d expired with 30036 (%.1f%%) and this Messaging Service "
                "caps every message at %d second(s). The queue in front of these "
                "messages is deeper than that deadline, so they died waiting for "
                "a sender that was never going to be free in time."
                % (expired, total, rate * 100, validity_period))

    allowed = ("no service-level cap" if validity_period is None
               else "the service allows %d second(s)" % validity_period)
    return ("per-message",
            "%d of %d expired with 30036 (%.1f%%) while there is %s. The short "
            "deadline is coming from the send call itself, or the queue really is "
            "hours deep, which is a throughput problem wearing a TTL error code."
            % (expired, total, rate * 100, allowed))


def get(session, url, **params):
    r = session.get(url, params=params, timeout=30)
    if r.status_code in (401, 403):
        raise SystemExit("%d from Twilio: check TWILIO_ACCOUNT_SID and that the "
                         "API key belongs to that account with read access"
                         % r.status_code)
    r.raise_for_status()
    return r.json()


def list_messages(session, account, since, limit):
    """Page Messages.json. No Status or ErrorCode filter exists on this resource,
    so the date window and the page cap are the only bounds available."""
    url = "%s/Accounts/%s/Messages.json" % (BASE, account)
    params = {"PageSize": 1000, "DateSent>=": since}
    out = []
    while url and len(out) < limit:
        page = get(session, url, **params)
        out.extend(page.get("messages", []))
        nxt = page.get("next_page_uri")
        url, params = (HOST + nxt) if nxt else None, {}
    return out[:limit]


def service_validity(session, service_sid):
    """Read validity_period off one Messaging Service, or None if it is not
    readable. A bare From number has no service and therefore no cap."""
    if not str(service_sid or "").startswith("MG"):
        return None
    svc = get(session, "%s/Services/%s" % (MESSAGING, service_sid))
    raw = svc.get("validity_period")
    try:
        return int(raw)
    except (TypeError, ValueError):
        return None


def main():
    ap = argparse.ArgumentParser(description=__doc__)
    ap.add_argument("--days", type=int, default=7,
                    help="how far back to read the Messages list")
    ap.add_argument("--max-messages", type=int, default=20000,
                    help="stop paging after this many messages")
    ap.add_argument("--floor", type=int, default=3600,
                    help="a service cap below this is treated as the cause")
    args = ap.parse_args()

    account = os.environ.get("TWILIO_ACCOUNT_SID")
    key = os.environ.get("TWILIO_API_KEY")
    secret = os.environ.get("TWILIO_API_SECRET")
    if not (account and key and secret):
        log.error("set TWILIO_ACCOUNT_SID, TWILIO_API_KEY and TWILIO_API_SECRET "
                  "(an API Key with read access, not the auth token)")
        return 2

    session = requests.Session()
    session.auth = (key, secret)

    since = (dt.date.today() - dt.timedelta(days=args.days)).isoformat()
    messages = list_messages(session, account, since, args.max_messages)
    if not messages:
        log.info("no messages sent since %s", since)
        return 0

    senders = tally(messages)
    bad = 0
    for sender, stats in sorted(senders.items()):
        cap = service_validity(session, sender)
        state, detail = verdict(stats, cap, args.floor)
        line = "%-15s %s  %s" % (state, sender, detail)
        if state == "clean":
            log.info(line)
            continue
        bad += 1
        log.warning(line)
        log.warning("  message sids: %s", ", ".join(str(s) for s in stats["sids"]))
        if state in ("out-of-range", "ttl-too-small"):
            log.warning("  repair: fix the ValidityPeriod argument where the send "
                        "is constructed. It must be 1 to %d seconds, and no "
                        "service setting can rescue a rejected request.",
                        MAX_VALIDITY)
        elif state == "service-too-low":
            log.warning("  repair: raise the cap with a write to %s/Services/%s "
                        "(ValidityPeriod), then widen the sender pool so the "
                        "queue drains inside the new deadline.", MESSAGING, sender)
        else:
            log.warning("  repair: stop passing a short per-message "
                        "ValidityPeriod, and add senders to the pool or rate "
                        "limit the producer. The deadline is the symptom; the "
                        "queue length is the problem.")

    log.info("%d sender(s) over %d day(s), %d with an expiry problem",
             len(senders), args.days, bad)
    return 1 if bad else 0


if __name__ == "__main__":
    sys.exit(main())

/**
 * Report Twilio messages that expired in the queue (30036) and the TTL rejections
 * near it.
 *
 * Read only. GET requests and nothing else: give this an API Key with read
 * access rather than the account auth token. The repair is printed, never
 * performed.
 */
const HOST = 'https://api.twilio.com';
const BASE = `${HOST}/2010-04-01`;
const MESSAGING = 'https://messaging.twilio.com/v1';

const EXPIRED = 30036;        // queued past its ValidityPeriod and dropped
const OUT_OF_RANGE = 30045;   // ValidityPeriod outside 1..36000, rejected outright
const TTL_TOO_SMALL = 30012;  // TTL below what the route accepts, rejected outright

const MAX_VALIDITY = 36000;

/**
 * Read error_code as a number, or null. Null on healthy messages, a number on
 * failed ones, and a string often enough that comparing the raw value against
 * 30036 quietly reports nothing.
 */
export function errorCode(message) {
  const raw = message.error_code;
  if (raw === null || raw === undefined || raw === '') return null;
  const n = Number(raw);
  return Number.isFinite(n) ? n : null;
}

/**
 * Bucket the three TTL codes by the sender whose queue they waited in. Pure, so
 * the grouping can be tested without a network. The codes are kept apart rather
 * than summed: 30045 and 30012 never reached a queue at all.
 */
export function tally(messages) {
  const out = new Map();
  for (const m of messages) {
    if (String(m.direction ?? '').startsWith('inbound')) continue;
    const key = m.messaging_service_sid || m.from || 'unknown sender';
    if (!out.has(key)) {
      out.set(key, { total: 0, expired: 0, out_of_range: 0, ttl_too_small: 0,
                     sids: [] });
    }
    const row = out.get(key);
    row.total += 1;
    const code = errorCode(m);
    if (code === EXPIRED) row.expired += 1;
    else if (code === OUT_OF_RANGE) row.out_of_range += 1;
    else if (code === TTL_TOO_SMALL) row.ttl_too_small += 1;
    else continue;
    if (row.sids.length < 3) row.sids.push(m.sid);
  }
  return out;
}

/**
 * Classify one sender. Pure, so the ordering and the thresholds are visible.
 * validityPeriod is the service-level cap in seconds, or null for a bare From
 * number. The request-time codes are checked first on purpose: when both kinds
 * are present the caller is building bad sends and the service setting fixes
 * none of them. Returns [state, detail].
 */
export function verdict(stats, validityPeriod = null, floor = 3600) {
  const total = Number(stats.total ?? 0);
  const expired = Number(stats.expired ?? 0);
  const outOfRange = Number(stats.out_of_range ?? 0);
  const ttlTooSmall = Number(stats.ttl_too_small ?? 0);

  if (outOfRange) {
    return ['out-of-range',
      `${outOfRange} message(s) rejected with 30045. ValidityPeriod has to be 1 ` +
      `to ${MAX_VALIDITY} seconds and something is passing a value outside that, ` +
      'so those sends never entered a queue. Usually a unit mix-up: milliseconds ' +
      'where seconds were meant.'];
  }

  if (ttlTooSmall) {
    return ['ttl-too-small',
      `${ttlTooSmall} message(s) rejected with 30012: the TTL asked for is below ` +
      'what the route will accept, so the send was refused before anything was ' +
      'queued. Fix it where the send is built.'];
  }

  if (!expired) return ['clean', `${total} message(s), none expired in queue`];

  const rate = total ? expired / total : 1;
  const pct = (rate * 100).toFixed(1);

  if (validityPeriod !== null && validityPeriod !== undefined
      && validityPeriod < floor) {
    return ['service-too-low',
      `${expired} of ${total} expired with 30036 (${pct}%) and this Messaging ` +
      `Service caps every message at ${validityPeriod} second(s). The queue in ` +
      'front of these messages is deeper than that deadline, so they died ' +
      'waiting for a sender that was never going to be free in time.'];
  }

  const allowed = (validityPeriod === null || validityPeriod === undefined)
    ? 'no service-level cap'
    : `the service allows ${validityPeriod} second(s)`;
  return ['per-message',
    `${expired} of ${total} expired with 30036 (${pct}%) while there is ${allowed}. ` +
    'The short deadline is coming from the send call itself, or the queue really ' +
    'is hours deep, which is a throughput problem wearing a TTL error code.'];
}

function authHeader(key, secret) {
  return `Basic ${Buffer.from(`${key}:${secret}`).toString('base64')}`;
}

async function get(auth, url, params = {}) {
  const u = new URL(url);
  for (const [k, v] of Object.entries(params)) u.searchParams.set(k, v);
  const res = await fetch(u, { headers: { Authorization: auth } });
  if (res.status === 401 || res.status === 403) {
    throw new Error(`${res.status} from Twilio: check TWILIO_ACCOUNT_SID and ` +
                    'that the API key belongs to that account with read access');
  }
  if (!res.ok) throw new Error(`${res.status} from ${u.pathname}`);
  return res.json();
}

export async function listMessages(auth, account, since, limit = 20000) {
  let url = `${BASE}/Accounts/${account}/Messages.json`;
  let params = { PageSize: 1000, 'DateSent>=': since };
  const out = [];
  while (url && out.length < limit) {
    const page = await get(auth, url, params);
    out.push(...(page.messages ?? []));
    url = page.next_page_uri ? HOST + page.next_page_uri : null;
    params = {};
  }
  return out.slice(0, limit);
}

async function serviceValidity(auth, serviceSid) {
  if (!String(serviceSid ?? '').startsWith('MG')) return null;
  const svc = await get(auth, `${MESSAGING}/Services/${serviceSid}`);
  const n = Number(svc.validity_period);
  return Number.isFinite(n) ? n : null;
}

async function main() {
  const account = process.env.TWILIO_ACCOUNT_SID;
  const key = process.env.TWILIO_API_KEY;
  const secret = process.env.TWILIO_API_SECRET;
  if (!account || !key || !secret) {
    console.error('set TWILIO_ACCOUNT_SID, TWILIO_API_KEY and TWILIO_API_SECRET ' +
                  '(an API Key with read access, not the auth token)');
    process.exitCode = 2;
    return;
  }
  const auth = authHeader(key, secret);

  const days = Number(process.argv.includes('--days')
    ? process.argv[process.argv.indexOf('--days') + 1] : 7) || 7;
  const since = new Date(Date.now() - days * 86400000).toISOString().slice(0, 10);

  const messages = await listMessages(auth, account, since);
  if (messages.length === 0) {
    console.log(`no messages sent since ${since}`);
    return;
  }

  const senders = tally(messages);
  let bad = 0;
  for (const [sender, stats] of [...senders.entries()].sort()) {
    const cap = await serviceValidity(auth, sender);
    const [state, detail] = verdict(stats, cap);
    const line = `${state.padEnd(15)} ${sender}  ${detail}`;
    if (state === 'clean') { console.log(line); continue; }
    bad += 1;
    console.warn(line);
    console.warn(`  message sids: ${stats.sids.join(', ')}`);
    if (state === 'out-of-range' || state === 'ttl-too-small') {
      console.warn('  repair: fix the ValidityPeriod argument where the send is ' +
                   `constructed. It must be 1 to ${MAX_VALIDITY} seconds, and no ` +
                   'service setting can rescue a rejected request.');
    } else if (state === 'service-too-low') {
      console.warn(`  repair: raise the cap with a write to ${MESSAGING}/Services/` +
                   `${sender} (ValidityPeriod), then widen the sender pool so the ` +
                   'queue drains inside the new deadline.');
    } else {
      console.warn('  repair: stop passing a short per-message ValidityPeriod, ' +
                   'and add senders to the pool or rate limit the producer. The ' +
                   'deadline is the symptom; the queue length is the problem.');
    }
  }

  console.log(`${senders.size} sender(s) over ${days} day(s), ${bad} with an ` +
              'expiry problem');
  process.exitCode = bad ? 1 : 0;
}

// Only run when invoked directly. The test file imports this module, and without
// the guard main() would run there too, fail on the missing credentials and set a
// non-zero exit code that fails the whole test file even as every test passes.
if (import.meta.url === `file://${process.argv[1]}`) {
  main().catch((err) => { console.error(err.message); process.exitCode = 2; });
}

from twilio_validity_period_audit import error_code, tally, verdict


def msg(sid, code=None, sender="+15550001111"):
    return {"sid": sid, "from": sender, "status": "undelivered",
            "error_code": code, "direction": "outbound-api"}


def test_error_code_reads_strings_and_numbers_the_same():
    assert error_code({"error_code": 30036}) == 30036
    assert error_code({"error_code": "30036"}) == 30036
    assert error_code({"error_code": None}) is None
    assert error_code({}) is None


def test_tally_keeps_the_three_codes_apart():
    rows = tally([msg("SM1", 30036), msg("SM2", 30045), msg("SM3", 30012),
                  msg("SM4")])
    row = rows["+15550001111"]
    assert row["total"] == 4
    assert row["expired"] == 1
    assert row["out_of_range"] == 1
    assert row["ttl_too_small"] == 1


def test_tally_groups_on_the_messaging_service_when_there_is_one():
    m = msg("SM1", 30036)
    m["messaging_service_sid"] = "MG1"
    rows = tally([m])
    assert set(rows) == {"MG1"}


def test_tally_ignores_inbound_and_caps_the_sids():
    rows = tally([msg("SM%d" % i, 30036) for i in range(7)]
                 + [{"sid": "SM9", "direction": "inbound", "status": "received"}])
    assert rows["+15550001111"]["sids"] == ["SM0", "SM1", "SM2"]
    assert len(rows) == 1


def test_no_expiries_is_clean():
    state, detail = verdict({"total": 400, "expired": 0})
    assert state == "clean"
    assert "400" in detail


def test_a_request_time_rejection_outranks_the_queue_timeout():
    # 30045 never queued, so the service cap is irrelevant to it. Reporting
    # service-too-low here would send someone to change the wrong setting.
    state, detail = verdict({"total": 100, "expired": 50, "out_of_range": 1},
                            validity_period=300)
    assert state == "out-of-range"
    assert "36000" in detail


def test_a_ttl_below_the_route_minimum_is_its_own_state():
    state, detail = verdict({"total": 100, "expired": 50, "ttl_too_small": 2},
                            validity_period=300)
    assert state == "ttl-too-small"
    assert "before anything was queued" in detail


def test_a_low_service_cap_behind_expiries_is_the_cause():
    state, detail = verdict({"total": 100, "expired": 40}, validity_period=300)
    assert state == "service-too-low"
    assert "300 second(s)" in detail


def test_expiries_at_the_default_cap_point_at_the_send_call_or_the_queue():
    state, detail = verdict({"total": 100, "expired": 40}, validity_period=36000)
    assert state == "per-message"
    assert "throughput problem" in detail


def test_a_bare_from_number_has_no_service_cap_to_blame():
    state, detail = verdict({"total": 100, "expired": 40}, validity_period=None)
    assert state == "per-message"
    assert "no service-level cap" in detail

import { test } from 'node:test';
import assert from 'node:assert/strict';
import { errorCode, tally, verdict } from './twilio-validity-period-audit.mjs';

const msg = (sid, code = null, sender = '+15550001111') => ({
  sid, from: sender, status: 'undelivered', error_code: code,
  direction: 'outbound-api',
});

test('error code reads strings and numbers the same', () => {
  assert.equal(errorCode({ error_code: 30036 }), 30036);
  assert.equal(errorCode({ error_code: '30036' }), 30036);
  assert.equal(errorCode({ error_code: null }), null);
  assert.equal(errorCode({}), null);
});

test('tally keeps the three codes apart', () => {
  const rows = tally([msg('SM1', 30036), msg('SM2', 30045), msg('SM3', 30012),
                      msg('SM4')]);
  const row = rows.get('+15550001111');
  assert.equal(row.total, 4);
  assert.equal(row.expired, 1);
  assert.equal(row.out_of_range, 1);
  assert.equal(row.ttl_too_small, 1);
});

test('tally groups on the messaging service when there is one', () => {
  const rows = tally([{ ...msg('SM1', 30036), messaging_service_sid: 'MG1' }]);
  assert.deepEqual([...rows.keys()], ['MG1']);
});

test('tally ignores inbound and caps the sids', () => {
  const rows = tally([
    ...[0, 1, 2, 3, 4, 5, 6].map((i) => msg(`SM${i}`, 30036)),
    { sid: 'SM9', direction: 'inbound', status: 'received' },
  ]);
  assert.deepEqual(rows.get('+15550001111').sids, ['SM0', 'SM1', 'SM2']);
  assert.equal(rows.size, 1);
});

test('no expiries is clean', () => {
  const [state, detail] = verdict({ total: 400, expired: 0 });
  assert.equal(state, 'clean');
  assert.match(detail, /400/);
});

test('a request-time rejection outranks the queue timeout', () => {
  // 30045 never queued, so the service cap is irrelevant to it.
  const [state, detail] = verdict(
    { total: 100, expired: 50, out_of_range: 1 }, 300);
  assert.equal(state, 'out-of-range');
  assert.match(detail, /36000/);
});

test('a TTL below the route minimum is its own state', () => {
  const [state, detail] = verdict(
    { total: 100, expired: 50, ttl_too_small: 2 }, 300);
  assert.equal(state, 'ttl-too-small');
  assert.match(detail, /before anything was queued/);
});

test('a low service cap behind expiries is the cause', () => {
  const [state, detail] = verdict({ total: 100, expired: 40 }, 300);
  assert.equal(state, 'service-too-low');
  assert.match(detail, /300 second\(s\)/);
});

test('expiries at the default cap point at the send call or the queue', () => {
  const [state, detail] = verdict({ total: 100, expired: 40 }, 36000);
  assert.equal(state, 'per-message');
  assert.match(detail, /throughput problem/);
});

test('a bare From number has no service cap to blame', () => {
  const [state, detail] = verdict({ total: 100, expired: 40}, null);
  assert.equal(state, 'per-message');
  assert.match(detail, /no service-level cap/);
});