p24-infra Docs

worker-queue-err1-3s-subscription-exhaustion

9 min read

Worker queue: every job fails ~3 s with err_1 runtime=3s

Incident: 2026-10-08 ~12:58 UTC — all dev-issue / et-operational-platform queue jobs failed ~3 s after spawn with result_summary='err_1 runtime=3s'. Last successful job 12:23 UTC. Tracked in #7575. RCA + the two latent code fixes shipped alongside it are recorded here.

This is a layered failure: one operational trigger that stops work, plus two latent code bugs the incident surfaced. Treat each layer separately — fixing the code bugs does not bring the fleet back; re-auth does.

Layer 0 — operational trigger (ROOT CAUSE, human action) ⟵ fix this first

Both Claude accounts on bms-4 were simultaneously unable to run workers:

  1. claude-runner-2 (ecotrans.automation) — the credentials file had no refreshToken and its access token had already expired (~170 h, file last written 2026-10-01). The hourly claude-token-refresh cron was running but cannot passively refresh without a refresh token. The dispatcher tries this account first, the worker is killed post-spawn (OAuth token revoked detected post-spawn … exit 7, #6447) — this is the err_1 runtime=3s symptom. The script-level Discord/Telegram terminal-failure alert (refresh-claude-token.py → _should_send_terminal_alert) is rate-limited to 1 per 6 h, so it is easy to miss in a fast-moving outage.
  2. claude-runner (radieu) — token healthy, but 7-day subscription usage_pct=97.0. spawn-worker.sh _check_subscription blocks dispatch at ≥95 % (exit 5). No other host could take over (windows-dev / dev-laptop / lap2 rejected by the HEALTH-GATE as stale/unknown).

Recovery (human / sys-admin — NOT a dev-coder action): re-auth claude-runner-2 in a browser (Telegram /auth-worker claude-runner-2 + /auth-code <code>, or Option A/B in claude-oauth-reauth.md). Never copy .credentials.json between accounts (claude-oauth-reauth.md Option C — forbidden). The radieu usage window resets 2026-10-13. After re-auth: claude -p say-ok as claude-runner-2, then re-queue the exhausted rows (12087 = p24-infra#7571, 12089 = et-operational-platform#2340 — both had retry_count 2/2).

Why the Prometheus alert did not catch #1 cleanly: ClaudeRunnerTokenExpired (monitoring/prometheus/rules/claude-token-expiry.yml) fires on claude_runner_token_expires_seconds <= 0 only while the push is fresh (< 1500 s) and unless p4_claude_auth_valid == 1. A credentials file with no refreshToken is an unusual state: check-sub-usage.py may push a stale/absent gauge (→ ClaudeRunnerTokenGaugeStale, warning only) rather than a fresh negative, and the authoritative real-auth backstop is ClaudeAuthSyntheticFailing (p4_claude_auth_valid == 0 for 30m). Follow-up (not shipped here — touches the heavily-constrained alert rule + vps-i1 deploy, sys-admin scope): consider a dedicated “refresh_token missing” signal from refresh-claude-token.py with a shorter page cadence than the shared 6 h terminal-alert window, so this exact state pages within minutes.

Layer 1 — latent bug A: spawn-worker.sh label-count crash (#7575, FIXED)

The duplicate-agent guard counted the ai-dev-spawned label with … --jq '.labels[].name' | grep -c "ai-dev-spawned" || echo 0. grep -c prints 0 and exits 1 when nothing matches, so under set -o pipefail the pipeline failed and || echo 0 appended a second 0 — HAS_SPAWNED became the two-line value 0\n0, and [ "${HAS_SPAWNED}" -gt 0 ] aborted with [: 0\n0: integer expression expected.

Non-fatal (the numeric test lives in an if condition, exempt from set -e, so the guard just degraded to “not spawned” and proceeded) but it spewed the error into every non-duplicate spawn’s log, muddying diagnosis during the outage.

Fix: count inside gh with jq, which returns a single integer and exits 0 even on zero matches:

HAS_SPAWNED=$(GH_TOKEN="$GH_TOKEN_VAL" gh issue view "$ISSUE_NUM" --repo "$_REPO_FOR_GUARD" \
  --json labels --jq '[.labels[].name | select(. == "ai-dev-spawned")] | length' 2>/dev/null || echo 0)

The || echo 0 now only fires if the whole gh call fails. Regression test: scripts/tests/test_spawn_worker_spawn_guard_count.py.

Layer 2 — latent bug B: exit-5 requeue writes a CHECK-invalid server_preference (#7575, FIXED)

When a worker exits 5 (all subscriptions at limit), the dispatcher re-queues with a 1 h backoff and points server_preference at “a different server” so an exhausted host doesn’t monopolise retries. It derived that label straight from SERVERS (DISPATCHER_SERVERS) with no filter:

other_servers = [s["server_label"] for s in SERVERS if s["server_label"] != name]
next_server_pref = other_servers[0] if other_servers else None

dev_r_worker_queue.server_preference carries a CHECK allowing only {'vps-i1','bms-4'} or NULL (supabase/migrations/20260627_worker_queue_role_routing.sql). DISPATCHER_SERVERS also lists dispatch hosts outside that set (windows-dev, dev-laptop, lap2). Whenever other_servers[0] landed on one of those, the requeue PATCH hit Postgres 23514 / HTTP 400 over REST and silently failed — the row stayed non-queued and never retried. This stranded rows 12081-12088 during the incident ("requeued with 1h backoff" nie zapisuje się).

Fix: intersect the candidate labels with a new _VALID_SERVER_PREFERENCES = ("vps-i1","bms-4") constant (mirrors the CHECK) before choosing a reroute target. Regression test: scripts/tests/test_dispatcher_loop_exit5.py.

General rule: any code deriving a server_preference from a live server_label must intersect with _VALID_SERVER_PREFERENCES first. The three reroute_pref sites (exit 2/255/6) are already safe because they default to "bms-4" and only ever reuse an existing (already CHECK-valid) DB value — but keep this constraint in mind when adding new reroute paths. Related: worker-queue-constraint-vs-function-mismatch.md, stranded-done-row-redispatch.md.

Layer 3 — second cause: the 5-hour session limit was not recognised (#7662, FIXED)

A second, distinct exhaustion mode caused the same err_1 runtime=1-3s storm on 2026-10-08/09 (32 rows failed_permanently, ~20 issues/PRs wrongly labelled human-action). The root cause was text-matching, not operations:

  • claude-runner was at 100 % of its 7-day window (unified_status=rejected claim=seven_day, reset 2026-10-13), so ALL traffic fell on claude-runner-2, whose 5-hour window was then exhausted. Claude Code printed You've hit your session limit · resets 12:30am (UTC) and exited.
  • spawn-worker.sh only converted the weekly phrasings to exit 5 (You've hit your weekly limit, You've used 100%, hit your usage limit). session limit matched none of them, so the mid-run exit was scored err_1 → failed_permanently, and the dispatcher never marked the account depleted — the next cycle re-picked the same blocked account and burned retries.
  • queue-analyst then dead-ended those rows on human-action, even though the only thing needed was to wait for the 5-hour window to reset.

Fixes (all shipped under #7662):

  1. spawn-worker.sh — recognise every limit phrasing. The pre-spawn _check_subscription now blocks (exit 5) on unified_status=rejected for either rolling window (5-hour or 7-day — usage_pct can sit well below 95 % while the 5-hour window is rejected, so the old percentage gates never fired). Both post-spawn detectors (the detached worker-exit classifier and the 5-second watcher) now grep the broadened, case-insensitive hit your .*limit (plus you've used 100% / usage limit), which covers weekly and session uniformly. The watcher echoes SESSION_LIMIT_RESET=<phrase> on stdout.
  2. Mid-run limit → migrate, don’t fail. A subscription limit hit while the detached worker is already running is now classified sub_limit (not err_1) and the queue row is re-queued immediately (status=queued, next_attempt_at=now, ownership cleared) instead of being marked failed or left for the 3-minute staleness watchdog. The next dispatch cycle re-ranks accounts; the now-rejected account is blocked by the pre-spawn gate, so the job migrates to the other account if it has headroom — the two-subscription fixed capacity is used fully and automatically.
  3. queue-dispatcher-loop.py — back off to the real reset. _parse_session_limit_reset() turns resets 12:30am/5pm (UTC) or an ISO reset_at into an absolute UTC instant (today, or tomorrow if that clock time is already past); _subscription_backoff_iso() returns that reset when known, else the legacy 1-hour fallback. spawn_worker() hands the earliest reset across the exit-5 accounts up to the main loop (stdout slot), which sets next_attempt_at to it. A limit-driven exit 5 bumps no retry_count / spawn_failures and sets no failure_reason. When both accounts are depleted the row simply stays queued behind next_attempt_at — no human-action, no “trying anyway” spawn storm.
  4. queue-analyst.py — usage limit ≠ auth failure. _QUOTA_PATTERNS was split into _USAGE_LIMIT_PATTERNS (weekly / session / usage / spend → requeue, no human-action, comment “waiting for the subscription to reset”) and _AUTH_FAIL_PATTERNS (not logged in / invalid api key → still escalate, a human must re-auth).
  5. Ranker near-limit cache bypass (owner criterion #3). The dispatch ranker orders accounts by _account_headroom, which caches each account’s sub-status.json-derived headroom for a 5-minute TTL (_ACCOUNT_USAGE_TTL_S). An account sitting just below a limit can run out within that window, so a stale cached number could still rank a just-depleted account ahead of an idle one. lib/account_routing.account_headroom (and the dispatcher’s byte-for-byte inline fallback) now re-read sub-status.json live even inside the TTL whenever the cached headroom is at or below NEAR_LIMIT_HEADROOM_PCT (10 %) — i.e. binding usage ≥ 90 %. A comfortably-idle account keeps the TTL cache (no extra SSH), an unknown (None) headroom is not “near a limit” and stays cached (it already sorts last among non-depleted), so the extra read only ever costs anything for an account that is already almost out. This is the ordering guard that complements the Fix #1 pre-spawn gate: the pre-spawn re-read exit 5s a rejected account unconditionally (correctness), while this keeps the ranking from preferring a near-dead account in the first place.

Regression tests: scripts/tests/test_session_limit_exit5.py (reset parsing, backoff, dispatcher exit-5 reset-aware requeue, analyst split), scripts/tests/test_account_routing.py (near-limit cache bypass, boundary, idle-stays-cached, unknown-stays-cached, end-to-end ranking) plus the updated test_spawn_worker_exit_status.py / test_spawn_worker_post_spawn_auth_check.py / test_queue_analyst.py.

Note on Layer 0 vs Layer 3. Layer 0 (a dead/refreshToken-less token, exit 7) still needs a human re-auth and is not a usage limit — it correctly keeps escalating. Layer 3 is purely the transient rate-limit case: it must self-heal on reset and migrate between accounts without human action. Distinguish them by the log banner (OAuth access token has been revoked / 401 = auth; hit your … limit / resets … (UTC) = usage) and by unified_status (unknown = down/auth; rejected = quota).

Diagnosis checklist (next time err_1 runtime=3s appears fleet-wide)

  1. Accounts first (this is almost always Layer 0):
    • tail /var/log/claude-token-refresh.log on bms-4 → look for no refreshToken / refreshToken missing.
    • Subscription headroom: scripts/check-sub-usage.py output / Grafana claude_runner_token_*.
    • p4_claude_auth_valid per {account,machine} in Prometheus — 0 = real 401.
  2. Stranded rows: dev_r_worker_queue rows stuck claimed/running with no matching live session, or failed/err_1 with exhausted retry_count. A requeue PATCH returning HTTP 400 / 23514 means a bad column value (historically server_preference, Layer 2) — check the dispatcher log for the 23514 detail.
  3. Noise vs cause: [: 0\n0: integer expression expected in the spawn log is Layer 1 (now fixed) — noise, not the trigger.

Graph View

Backlinks