bug(SUB-003): rate-limit events never age out due to SQLite string-compare bug; retries amplify outages

[vybe]

Summary

auto_switch_subscriptions effectively marks alternative subscriptions as rate-limited for the entire UTC day after a single 429, then fails to find viable alternatives for hours. The surface symptom is "slow ping-pong through exhausted subscriptions"; the actual root cause is a broken string comparison in SQLite — rate-limit events never age out within the same UTC day, regardless of when they occurred.

A secondary problem compounds this: scheduled executions that fail during the outage generate pending_retry records that all become due around the same time.

Component

Backend / db/subscriptions.py + src/scheduler/service.py

Priority

P1

Root Cause

Bug 1 — SQLite lexicographic comparison across formats (the real bug)

utils/helpers.py:43 stores timestamps in ISO-8601 with T separator and Z suffix:

datetime.now(timezone.utc).strftime('%Y-%m-%dT%H:%M:%S.%fZ')
# → "2026-04-23T08:01:12.123456Z"

SQLite's datetime('now', '-2 hours') returns:

"2026-04-23 06:01:12"   ← space separator, no Z

The "last 2 hours" filter in db/subscriptions.py:503, 515, 535 compares these lexicographically:

WHERE occurred_at > datetime('now', '-2 hours')

At position 10, T (0x54) > space (0x20), so the comparison returns true as soon as the date prefix matches — the rest of the timestamp is never evaluated. Every event with today's date passes the "last 2 hours" check, regardless of actual clock time.

Bug 2 — Events are never cleared on successful execution

clear_rate_limit_events(agent, subscription) exists in db/subscriptions.py:519 but has zero callers in the codebase. The only cleanup path is cleanup_old_rate_limit_events() (24h), which has the same lexicographic bug.

Net effect

A subscription that gets a single rate-limit event at 00:05 UTC will be treated as rate-limited until 23:59:59 UTC of the same day (when the date prefix rolls over). With multiple subscriptions accumulating one event each during the day, select_best_alternative_subscription() runs out of candidates within minutes of the first real outage, not 2 hours.

This explains the observed symptom: "no viable alternative subscription found" appearing persistently rather than every 2 hours as the 2h window design would suggest.

Bug 3 — Default max_retries=1 for schedules generates unnecessary retry load

db_models.py:120 defaults max_retries = 1 per schedule. During a multi-hour subscription outage, every failed scheduled execution generates a pending_retry record. _recover_pending_retries() at src/scheduler/service.py:1260 then fires all overdue retries with retry_at = now + timedelta(seconds=5) on scheduler restart — all within 5 seconds of each other.

For the typical Trinity use case (agents are stateful/idempotent; the next cron tick catches up), retries add no value and amplify load during outages.

Fix

Three small, independent changes. No schema change. No error-body parsing. No rate_limited_until column.

Change 1 — Fix the string comparison

Compute the cutoff in Python in the same format as stored values, pass as parameter:

# db/subscriptions.py
from datetime import datetime, timezone, timedelta

def _cutoff_iso(hours: int) -> str:
    """Compute a cutoff timestamp in the same format as utc_now_iso()."""
    return (datetime.now(timezone.utc) - timedelta(hours=hours)).strftime('%Y-%m-%dT%H:%M:%S.%fZ')

Update three query sites:

# record_rate_limit_event (line 499-504)
cursor.execute("""
    SELECT COUNT(*) as cnt
    FROM subscription_rate_limit_events
    WHERE agent_name = ? AND subscription_id = ?
      AND occurred_at > ?
""", (agent_name, subscription_id, _cutoff_iso(2)))

# is_subscription_rate_limited (line 511-516)
cursor.execute("""
    SELECT COUNT(*) as cnt
    FROM subscription_rate_limit_events
    WHERE subscription_id = ?
      AND occurred_at > ?
""", (subscription_id, _cutoff_iso(2)))

# cleanup_old_rate_limit_events (line 533-536)
cursor.execute("""
    DELETE FROM subscription_rate_limit_events
    WHERE occurred_at < ?
""", (_cutoff_iso(24),))

After this, the 2h window actually works. A 2h ping-pong between genuinely rate-limited subscriptions is acceptable — it's not worth parsing Anthropic's error message format (fragile, Anthropic can change it anytime) to avoid.

Change 2 — Default max_retries=0

src/backend/db_models.py:120, 147 and src/scheduler/models.py:52:

max_retries: int = 0  # 0 = disabled (default). 1-5 opt-in for schedules that truly need retry.

Update the comment and corresponding frontend/API docs. Schedules that explicitly set a value are unaffected.

Rationale: Scheduled agents are expected to catch up on the next tick. Retrying a failed run rarely adds value and generates unnecessary load during outages. This is opt-in, not opt-out.

Change 3 — Consistency: ensure cleanup_old_rate_limit_events() runs

Verify it's scheduled (e.g. via maintenance service). If not, wire it into an existing cleanup path — without it, the table grows unbounded once Change 1 is in.

Deliberately out of scope

These were considered and rejected:

• subscription_credentials.rate_limited_until column + 429-body parsing. Fragile — parses a human-readable error string from Anthropic that's not part of any API contract. Timezone parsing edge cases. Silent failure modes. The simpler fix (Change 1) delivers the same net behavior: subscriptions that are actually rate-limited stay rate-limited for 2 hours.
• Thundering-herd / staggered retry replay. Unnecessary once max_retries=0 is the default. If a user explicitly opts into retries for a specific schedule, the existing 2x-delay-on-429 behavior is adequate.
• Calling clear_rate_limit_events() on successful execution. Not needed. The 2h window (now working) is the correct signal. A subscription that succeeds naturally stops accumulating events.

Verification

1. Unit test for _cutoff_iso() — confirm format matches utc_now_iso().
2. Integration test — insert an event with occurred_at 3 hours ago (via _cutoff_iso(3)), run is_subscription_rate_limited(), assert False. Insert an event 1 hour ago, assert True.
3. Manual check — on a db with existing rate-limit events from earlier today, verify SELECT COUNT(*) FROM subscription_rate_limit_events WHERE occurred_at > ? (with the Python cutoff) now returns ~0 instead of all events from today.
4. Retry default — create a new schedule via UI/API; confirm max_retries stored as 0.

Environment

• Trinity version: f72b153
• Affects all instances using subscription_type = max with auto_switch_subscriptions = true (Bug 1+2)
• Affects all instances with scheduled agents (Bug 3)

Related

• Parent bug: bug(SUB-003): auto-switch ping-pongs between rate-limited subscriptions due to clear_rate_limit_events destroying detection signal #444 (fast ping-pong — fixed in f72b153)
• db/subscriptions.py:474-505, 507-517, 529-539 — three query sites
• utils/helpers.py:43 — utc_now_iso() format that created the mismatch
• db_models.py:120, 147, src/scheduler/models.py:52 — max_retries default

[vybe]

Critical Finding: Root cause is a SQLite datetime format mismatch bug

After deeper investigation, the "no viable alternative subscription found" message is caused by a broken is_subscription_rate_limited check — not by subscriptions actually being exhausted.

The Bug

occurred_at timestamps are stored using Python's datetime.isoformat() which produces ISO 8601 with a T separator:

2026-04-23T08:00:02.228350

But SQLite's datetime('now', '-2 hours') returns a space separator:

2026-04-23 14:14:17

SQLite compares these as plain strings. 'T' (ASCII 84) > ' ' (ASCII 32), so every event with a T-separator occurred_at always evaluates as newer than datetime('now', '-2 hours'), regardless of actual timestamp value.

Evidence

The following query returns 2 events for eugene-ability and trinity-org subscriptions:

SELECT subscription_id, COUNT(*) FROM subscription_rate_limit_events
WHERE occurred_at > datetime('now', '-2 hours')
GROUP BY subscription_id;
-- Returns: eugene-ability=2, eugene-personal=2, trinity-org=2, andrii-personal=82

But the actual events for those subscriptions occurred at 02:30, 08:00, and 08:30 UTC — 6-14 hours before the query ran. When the cutoff is expressed with a T separator (matching the stored format), none of them appear:

SELECT COUNT(*) FROM subscription_rate_limit_events
WHERE occurred_at > '2026-04-23T14:00:00';
-- Returns: 0 rows for eugene-ability/personal/trinity-org

Impact

This means is_subscription_rate_limited() returns True for any subscription that has ever accumulated 2+ events, permanently. Auto-switch can never find a viable alternative once any subscription has a rate-limit history, regardless of how stale those events are.

Fix

In db/subscriptions.py, normalize the timestamp format in the comparison:

# BROKEN — 'T' vs ' ' string comparison always favors stored timestamps:
cursor.execute("""
    SELECT COUNT(*) FROM subscription_rate_limit_events
    WHERE subscription_id = ? AND occurred_at > datetime('now', '-2 hours')
""", (subscription_id,))

# FIXED — wrap occurred_at in datetime() to normalize the format:
cursor.execute("""
    SELECT COUNT(*) FROM subscription_rate_limit_events
    WHERE subscription_id = ? AND datetime(occurred_at) > datetime('now', '-2 hours')
""", (subscription_id,))

Or alternatively, store occurred_at using SQLite's format:

# Instead of: datetime.now(UTC).isoformat()
# Use:
datetime.now(UTC).strftime('%Y-%m-%d %H:%M:%S')

The datetime(occurred_at) wrapper approach is safer as it fixes the query without requiring a data migration.

This is the primary bug blocking auto-switch from working. The rate_limited_until persistence proposed in the original report is still valuable as a long-term fix, but wrapping occurred_at in datetime() in the WHERE clause will immediately restore correct auto-switch behavior.

[vybe]

Update: The actual bug is much worse than the 2h window being "too short"

While operating on an affected instance I proved that the 2h window check is completely broken due to a string-comparison bug in SQLite.

Root cause

subscription_rate_limit_events.occurred_at is stored in ISO-8601 format with a T separator (via Python's datetime.isoformat()):

2026-04-23T08:01:12.054209

But SQLite's datetime('now') returns the space-separated format:

2026-04-23 16:47:01

The is_subscription_rate_limited() query compares them as raw strings:

WHERE occurred_at > datetime('now', '-2 hours')

Character 10 of the stored value is T (ASCII 84). Character 10 of the SQLite output is (ASCII 32). T > is always true, so **any event stored today appears to be newer thannow - 2h` regardless of actual time**.

Proof

sqlite> SELECT '2026-04-23T08:01:12' > datetime('now', '-2 hours');
1   -- TRUE, i.e. 8am event treated as "within last 2 hours" at 4:47pm

sqlite> SELECT datetime('2026-04-23T08:01:12') > datetime('now', '-2 hours');
0   -- FALSE, correct when both sides are wrapped in datetime()

Real-world impact (observed)

An instance with 4 Max subscriptions, 11 agents, and ~300 pending_retry entries had:

• andrii-personal: 82 recent events (genuinely exhausted)
• eugene-ability: 2 events from 08:00 UTC (9+ hours earlier)
• eugene-personal: 2 events from 02:30 UTC (14+ hours earlier)
• trinity-org: 2 events from 08:30 UTC (8+ hours earlier)

All three alternative subscriptions were reported as "rate-limited in the last 2 hours" by is_subscription_rate_limited(). Auto-switch logged "no viable alternative subscription found" repeatedly. Meanwhile the alternatives were tested manually and all three were actually working.

After deleting events older than 2h using a proper datetime(occurred_at) <= datetime('now', '-2 hours') query, 386 stale events were removed and auto-switch immediately became able to find viable alternatives.

Additional fix (minimal)

In addition to the rate_limited_until persistence proposed above, the is_subscription_rate_limited query needs:

# db/subscriptions.py
cursor.execute("""
    SELECT COUNT(*) FROM subscription_rate_limit_events
    WHERE subscription_id = ? 
      AND datetime(occurred_at) > datetime('now', '-2 hours')
""", (subscription_id,))

Or — and this is better — store occurred_at in the same format SQLite returns (space separator, no T, no microseconds):

# When inserting the event
occurred_at = datetime.now(UTC).strftime('%Y-%m-%d %H:%M:%S')

Same fix needed in cleanup_old_rate_limit_events — its 24h cleanup is also broken by the same string comparison, which means rate-limit events never actually age out until the date rolls over to a different year-month-day lexicographically greater than the T-padded current date, i.e. never in practice. The event table grows unbounded. On the observed instance there were 600+ events accumulated from just the past 24 hours.

This string-comparison bug renders the entire SUB-003 rate-limit tracking effectively a no-op. Every event is treated as fresh; nothing ages out. That's why the original fast ping-pong in #444 happened despite a 2h window being designed in.

Recommended patch priority

This should be P0, not P1 — the entire rate-limit-aware auto-switch is broken in production. The original #444 fix stopped the fast ping-pong via a different mechanism (not clearing events), but is_subscription_rate_limited itself has never worked correctly.