Scheduler: proven-live outbox drain replay-storms — no attempt cap + FIFO head-of-line break re-pastes a never-confirming wake every tick and immortalizes zombie rows (live incident: 7+ dup deliveries/hr on Pi)

[olegbrok]

Summary

The #981 proven-live heartbeat drain turns a single never-confirming outbox row into an unbounded replay storm: the head-of-line row is re-pasted into the live session on every proven-live boundary, each replay costs the agent a full session turn (token burn), and the FIFO break means zombie rows queued behind it are never reaped. Live incident on the Pi fleet box (agent geordi), 2026-08-03 13:54–14:50 PDT: 7+ duplicate wake deliveries in under an hour, accelerating to ~1 per 1–3 min, from 13 stranded rows.

Live evidence (geordi@pi, all times PDT, verified against artifacts before acting — zero double-executions)

• 13:58 — soup-watchdog 4:30am prompt re-delivered (morning run fully logged; no new firing behind it)
• 13:54 + 14:02 — two deliveries of the feat: Agent config tabbed navigation #99 sweep prompt for the 14:00 slot (executed once)
• 14:46:29 — third feat: Agent config tabbed navigation #99 delivery carrying pre-1:48pm prompt text (row serialized at fire time; schedule prompt had since been edited)
• 14:45:02 legit Add Signal as outreach channel #154 tick, then duplicate deliveries 14:45:51 and 14:48:25
• pending_schedule_wakes (conversations_agents.db): 13 stranded geordi rows, fired_at 05:00→08:00 (ids 9–18 = schedule_ids 99,99,140,138,135,137,99,126,128,99; fired_at 1785758409→1785772828), each created_at 30–90 min after fired_at — consistent with rows minted by _record_schedule_undelivered → persist_schedule_wake after morning deliveries failed to confirm behind busy sessions
• Schedules Fix CI: skip pinky-web tests when web extras missing #140/Smart dates on chat message timestamps #138/Fix stacked modals z-index on Agents page #135/Add timestamps to chat messages #137 were deleted at 13:46 yet their rows persisted — because the loop never reaches them (head-of-line block, below)
• Replay bursts cluster after send_heartbeat calls (13:56, 14:05) — consistent with the _check_heartbeats → _drain_outbox_if_pending trigger

Code trace (scheduler.py @ c1d544b, unchanged on 17ab1cc)

1. _check_heartbeats calls _drain_outbox_if_pending on EVERY tick (~30s) whenever the agent is proven live and rows are pending (scheduler.py:899, :943). No per-row attempt count, no backoff, no cap.
2. _replay_pending_locked (:751) iterates FIFO by fired_at. Per row: zombie check (deleted/reassigned/disabled-non-oneshot → discard) then delivery attempt; on not confirmed → break (:785–790).
3. Consequence A — unbounded re-paste: a head row whose replay pastes but never yields a confirmed receipt survives, so every proven-live tick spawns a fresh replay task that re-pastes the same prompt. The docstring's "never double-delivers" (:962) holds only for confirmation; the transport-visible paste (and the session turn it burns) repeats indefinitely.
4. Consequence B — head-of-line blocking defeats zombie reaping: the break sits before rows behind the head are ever zombie-checked, so rows for deleted schedules are immortal while the head is stuck.
5. Open sub-question — why does the head row never confirm? The sessions demonstrably accepted the replayed prompts (the agent no-op'd them), so either the wake callback returns non-True on the replay path or receipt matching fails against the pane acceptance (fix(scheduler): duplicate-execution guard — timeout decisions read transport execution state, not receipt state #983 semantics). journalctl pull pending to distinguish remains pending: no positive receipt vs was confirmed but outbox retirement did not match a row (:797) vs zombie lines.

Note: byte-identical last_run floats across two schedules stamped in one tick (observed 1785793514.3285415 on #154 and #157) are the documented cohort-stamp design (agent_registry.py:3238 comment), not a defect.

Impact

• Duplicate wake prompts at ~1/min sustained = token burn plus real double-execution risk on any fleet agent without geordi's artifact-check discipline.
• Outbox rows for deleted schedules never reap while a head row is stuck.
• Stale serialized prompt text replays after schedule edits (correct-by-design for a durable outbox, but combined with A it re-delivers obsolete instructions repeatedly).

Mitigation used (no DB writes)

remove_wake_schedule for every schedule still holding stranded rows (#99, #126, #128, #154) → next proven-live drain zombie-drops all rows in order → storm stops; recreate the needed schedules afterward.

Fix directions

1. Per-row replay attempt counter + backoff, with a cap: after N failed replay attempts, park the row (dead-letter state) and send ONE owner alert instead of re-pasting forever.
2. Reap zombies in a pre-pass over the whole outbox before any delivery attempt, so a stuck head cannot immortalize deleted-schedule rows.
3. Root-cause the replay-path receipt mismatch (sub-question 5) — likely the actual bug that armed this loop.

Related: #981 (drain trigger), #983 (receipt semantics), #984 (same family: wake lifecycle vs transport truth).

🤖 Opened by Barsik

[olegbrok]

journalctl verdict (geordi@pi, pinkybot.service, since 13:45 PDT) — sub-question 5 resolved

• Retirement works when receipts confirm: 13:53:54 persisted wake delivery confirmed for 'email-sweep-hourly-24x7' (#99) and 13:58:32 ... 'soup-395-watchdog-430am' (#111) — two rows retired normally earlier in the same afternoon.
• The storm is the receipt path: 14:44:06 persisted wake #9 for 'geordi' remains pending: no positive receipt — the 05:00 feat: Agent config tabbed navigation #99 row (outbox id 9) is the stuck head. The :797 retirement-mismatch branch never fired.
• Wrinkle for the fix: prompt arrivals kept landing in the session at 14:45:51 / 14:46:29 / 14:48:25 with only that one remains pending line logged at 14:44:06 — paste-count exceeds receipt-failure-log-count. Worth checking the transport-side paste path when root-causing: either the wake callback re-pastes within one _wait_for_wake_confirmation extension cycle, or drain-triggered replay tasks are pasting without a terminal per-attempt log line.
• Deployed HEAD on the affected box: c1d544b (the fix(scheduler): drain stranded wake outbox on proven-live heartbeat #981 commit itself, = 26.08.001).

Mitigation executed 14:58 PDT (no DB writes)

All six live schedules holding stranded rows removed and recreated with faithful prompts (#99, #115, #126, #128, #152, #154 → new ids 159–164; shared-minute seniority preserved). Next proven-live drain should zombie-drop all 13 rows via the existing deleted-schedule path. Storm-stop confirmation pending; will update here.

So the fix ranking from the issue body stands, with 3 now sharpened: root cause is replayed prompts are pasted and accepted by the session but the per-prompt receipt never resolves positive — while the same afternoon's earlier replays DID confirm. Whatever differs between those two populations (prompt text drift vs receipt matcher keying? pane busy-state at paste time?) is the bug that arms the loop.

🤖 Barsik

[olegbrok]

Storm-stop verify: DEVIATION — and it exposes defect 3 + rewrites the arming story

Observed (geordi@pi, 15:10 PDT): expected 13 PERSISTED_WAKE_ZOMBIE_DROPPED after the mitigation (all row-holding schedules deleted+recreated); observed zero, and no drain has fired at all since 14:44. Outbox now holds 14 rows (one more from old #154, fired before recreation finished); all 14 reference deleted schedule ids — all zombie-eligible under the deployed c1d544b logic.

Root cause of the non-drain — defect 3, verified in code: _check_heartbeats gates _drain_outbox_if_pending on hb.status == "alive" (scheduler.py:933), but "alive" is only written by the SDK tool-use heartbeat hook (hooks.py:427). Tmux-rails agents self-report via POST /agents/{name}/heartbeat with ok|busy|finishing, stored verbatim (api.py:10091) — never "alive". _reconcile_server_liveness requires a CONNECTED streaming session or fresh server-stamped last_seen_at, neither of which tmux rails produce. The #981 heartbeat drain path is structurally unreachable for tmux-transport agents — live-confirmed: agent continuously running tools for 20+ min with 14 pending rows and zero drain lines.

Corrected arming story for the afternoon storm: the replays were triggered by the other replay path — on_wake_delivered → replay_pending_for_agent (api.py:3091, the #949 startup/wake catch-up) — armed by the 14:00 legit #99 delivery. The earlier send_heartbeat correlation was coincidence. One long replay pass ran 13:53→14:44 (confirming and retiring two rows on the way — retirement itself healthy), stalled on the never-confirming head row, broke, and nothing has re-armed since.

Fix for defect 3 (added to the in-flight PR spec): accept hb.status in {"alive", "ok", "busy", "finishing"} in the drain gate (existing freshness check unchanged). All four statuses are only written by agent/hook activity — an agent-initiated heartbeat POST is transport-observed execution evidence — while the scheduler's own writes use "stale"/"dead", so the proven-live-only policy from the #981 review is preserved.

Open watch: the next confirmed scheduled-wake delivery on the box should still trigger the #949 replay path and zombie-sweep all 14 rows. If a delivered wake does NOT sweep them, the #949 trigger is broken too — will report either way.

🤖 Barsik

[olegbrok]

Fix merged: #992 (squash 71fb580) — attempt cap + dead-letter park with one owner alert, zombie pre-pass over the full outbox, and the drain-gate liveness vocabulary fix (agent-authored alive/ok/busy/finishing accepted; scheduler-authored stale/dead still excluded, pinned by test). Release 26.08.003 cutting now; Pi fleet picks it up at the 4:45am auto-update. On that restart the daemon-start replay's zombie pre-pass should reap all 14 stranded rows on the affected box regardless of head state — geordi verifying the count. Leaving this issue OPEN for defect: replayed prompts pasted+accepted but receipt never resolves (the paste-count>log-count wrinkle) — that root cause still needs transport-side forensics.

🤖 Barsik

[olegbrok]

Incident resolution verified on the affected box (geordi@pi, evening context_restart 15:39-15:41 PDT, still on pre-fix c1d544b): the lifecycle-wake replay trigger (#949 path) fired at 15:39:00 and zombie-dropped exactly 14 rows (pending #9–#22, outbox_retired=True on every line), covering all 10 deleted schedules (99×4, 154×2 among them). Verified two ways: journalctl count and a post-restart file-copy read of the table — zero deleted-schedule rows remain. One residual row is legit (live watcher #164, in-flight during restart, agent no-op'd the duplicate). Note this cleanup worked on the OLD code only because the mitigation had made every stranded row zombie-eligible — with a live head schedule the pre-fix FIFO would have stalled again, which is what #992's pre-pass + cap now prevent structurally.

Remaining open scope for this issue — transport-side receipt forensics:

1. Replayed prompts pasted+accepted but receipt never resolved (the original storm head).
2. Paste-count > scheduler-log-count during the storm (arrivals 14:45–14:49 with no corresponding scheduler lines).
3. New datum 15:38: a live cron wake (Add KB librarian agent — daily wiki curation #164) re-delivered ~1 min after the agent's turn ended, outside the outbox path entirely — same re-delivery family, scheduler never logged it.

26.08.003 rollout: Mini at tonight's 21:30 restart, Pi fleet at the 4:45am auto-update.

🤖 Barsik

[olegbrok]

Receipt-forensics breakthrough — duplicate mechanism caught live and confirmed in code (geordi@pi, 15:41–15:43 PDT, raw lines in his issue_991_evidence_20260803.md):

Row 23 (#164 watcher): 15:41:16 FIRED BUT UNDELIVERED (mid-restart) → row persisted; then TWO delivery confirmed for schedule #164 events (15:43:07, 15:43:35), each producing a delivered prompt — and the row was STILL in pending_schedule_wakes after both (file-copy read).

Code confirmation: confirm_pending_schedule_wake (the only outbox retirement on the delivery path) is called solely from the REPLAY path (scheduler.py:792). The PRIMARY fire path's confirmed branch (scheduler.py:539–562) stamps update_schedule_last_delivered and returns — it never retires the outbox row that _record_schedule_undelivered persisted for the same firing (:564→persist_schedule_wake). So: fire → receipt timeout → row persisted → pasted prompt accepted late → primary delivery confirms → row survives → every later replay boundary re-delivers an already-executed wake. This is a plausible single explanation for the duplicate-delivery family (15:38 dup, paste>log wrinkle) and likely fed the storm.

Fix dispatched (follow-up to #992): primary confirmed branch must also retire the matching outbox row by (schedule_id, fired_at=schedule.last_run) — the table's UNIQUE key. Still open after that: why the two confirms fired 28s apart for one firing (exact log-line provenance needed — replay-path vs primary-path confirm), and the pre-restart storm head's receipt behavior.

Separate finding, tracked config-side: owner-notify on the Pi daemon 409s ("No telegram token bound to destination account brad-telegram") — scheduler alerts to owner silently dead on that host. The #985/#986 host-local fallback rides 26.08.003 (arrives 4:45am); the underlying token binding is a box-config task.

🤖 Barsik

[olegbrok]

Double-confirm provenance resolved (verbatim lines from the box): both 15:43 confirms are PRIMARY-path (delivery confirmed for schedule, scheduler.py:557), 28s apart, neither on a cron boundary; the replay path spoke once at 15:46:06 (persisted wake delivery confirmed) and that is what retired row 23 — outbox now empty. Full sequence for one stranded firing: persist (15:41:16) → primary confirm ×2 (15:43:07, 15:43:35 — no retire) → legit 15:45:00 cron fire → replay confirm (15:46:06, retires) = 3 duplicate prompts + 1 legit in five minutes, all no-op'd by the agent's artifact discipline.

Scope consequences:

• The dispatched late-confirm-retire fix addresses the replay duplicate (would have retired the row at 15:43:07).
• NEW sub-defect: two primary-path confirms for one firing means something dispatched a second _deliver_schedule for an already-fired schedule — each confirm line requires its own invocation reaching confirmed=True, and each had its own api-layer queued confirmed-delivery wake (api.py:10337, logged per _wake_callback receipt await). Context: agent session context_restart in that window, daemon up throughout. Caller unknown — candidates: reconnect/resume re-attempt of recent undelivered schedules, or a surviving delivery task racing a second dispatch. Tracking here until the caller is identified.

🤖 Barsik

[olegbrok]

Window recount + wrinkle 4 characterized (further verbatim data from the box): a 5th prompt landed 15:47:47 (primary confirm 15:47:42) — and the log shows the REAL :45 cron fire was 15:45:21, immediately followed by 15:45:22 scheduler: cohort-start synchronization timed out; blocked delivery tasks remain queued. Recount: the 15:45:00-confirmed prompt was duplicate #4 of the stranded 15:05 wake (it arrived before the real fire dispatched); 15:47:42 was the legit delivery, late. Net: 4 duplicates + 1 late real = 5 prompts for one watcher in ~7 minutes.

Code read on the cohort line: it is benign-by-design (scheduler.py:418–428, #702) — the tick waits ≤1.0s only for the cohort task to START, then moves on; the task remains queued behind the per-agent delivery lock and runs when the lock frees. So the late real fire is a symptom of the duplicate storm (lock serialized behind duplicate deliveries), not an independent parking defect. Fixing the duplicates fixes the off-cadence drains.

Also verified: that cohort line is the ONLY one since 15:39 — no cohort event near 15:43, so the 28s primary-path double-confirm remains unexplained (open hunt).

Tripwire on the box: next real fire ~15:55:21; repeated off-cadence arrivals past it get flagged storm-grade. Outbox re-verified empty.

🤖 Barsik

[olegbrok]

Double-primary sub-defect narrowed (murzik read-only caller scan): _deliver_schedule has exactly one production caller — _deliver_schedule_group (scheduler.py:471), created only by _check_schedules (:410). No reconnect/resume re-entry path exists. Therefore two primary confirms for one firing imply duplicate cohort dispatch: the due-check fired the same schedule twice (or two live scheduler instances — unlikely, daemon stayed up).

Leading hypothesis given the 28s spacing (≈ one 30s tick): stale last_run visibility — the cohort stamps last_run at fire time, but if the next tick's due-check read a stale WAL snapshot that didn't yet reflect the stamp, it would re-fire the same schedule one tick later; both deliveries then queue behind the busy per-agent lock and confirm serially (observed 15:43:07 / 15:43:35). This repo has prior art for exactly this failure shape: #956 (stale-WAL reads healed in task_store) and #942 (busy_timeout on thread-local store connections) — the schedules table read path deserves the same audit. Next step after the in-flight PR: check whether the tick loop's registry reads share the writer's connection or can serve pre-stamp snapshots.

🤖 Barsik

[olegbrok]

Second fix merged and released: #993 (squash c44682d) → 26.08.004 — late-confirmed primary deliveries now retire their persisted outbox row by (schedule_id, fired_at), parked rows included, with PERSISTED_WAKE_RETIRED_ON_LATE_CONFIRM logged on a match. Rollout: Mini at tonight's 21:30 restart, Pi fleet at 4:45am.

Remaining open scope on this issue: (1) duplicate cohort dispatch — the 28s primary-path double-confirm; leading hypothesis stale last_run WAL visibility on the due-check read path (#956/#942 family), audit queued; (2) the pre-restart storm head's receipt never confirming on replay while later replays confirmed fine.

🤖 Barsik

[olegbrok]

Evening addendum, 2026-08-03 (post-release live data from the Pi box)

1. Unplanned pre-fix window (16:32–17:08). The Pi hard-rebooted at 16:32 — two abrupt terminations ~4 min apart (boot 16:28:22 died 16:30:06, no shutdown lines; current boot 16:32:10), power-instability shape, PSU suspected, unrelated to the scheduler. The box was still on pre-fix 26.08.001, and the reboot produced 2 stranded outbox rows (16:35 receipt-timeout; 16:55 orphaned by a deliberate session restart). Both were retired cleanly by their pre-deploy confirms (16:59:25 / 17:01:06). An initial read of this window as "pre-fix #993 non-retirement reproducing" was wrong — it was a log-adjacency misread: each persisted wake delivery confirmed line was followed by queued confirmed-delivery wake, which is the next FIFO item starting delivery, not the confirmed row re-queueing. Pair queued lines to their own row ids before claiming non-retirement. Net: the afternoon window did not reproduce the #993 defect; the morning storm evidence (4 duplicates + 1 late real for one watcher in 7 min) carries that case on its own.

2. Early deploy of 26.08.004 to the Pi (17:08:25, pre-empting the 4:45am cron). Rationale: pre-fix code + active replay traffic + no attempt cap = ~12h of bleed. Post-deploy book is clean:

Check	Expected (calibrated)	Observed
Restart-killed rows (#159 sweep killed mid-delivery 17:07:27, #164 watcher canceled 17:07:28)	replay → retire via replay path	#159 retired 17:11:33 ✓, #164 at next tick ✓ (deviation-only watch, none reported)
PERSISTED_WAKE_ZOMBIE_DROPPED	0 — pre-pass reaps only deleted/reassigned/disabled-schedule rows; active-schedule strands take the replay path	0 ✓
PERSISTED_WAKE_RETIRED_ON_LATE_CONFIRM	0 — see path split below	0 ✓
PERSISTED_WAKE_PARKED	0	0 ✓

3. Grep discipline for future verification — two distinct retirement exit paths:

• Replay path (scheduler.py:859 → confirm_pending_schedule_wake by row id): how restart-killed/stranded rows exit. Logs persisted wake delivery confirmed under the scheduler: prefix, and only after successful retirement (a mismatch logs outbox retirement did not match a row).
• Live-fire late-confirm path (scheduler.py:549 → confirm_pending_schedule_wake_by_fire, keyed schedule_id+fired_at — the fix(scheduler): retire late-confirmed persisted wakes #993 fix): fires only on the fire → 600s receipt-timeout → persist → late-receipt shape. Logs PERSISTED_WAKE_RETIRED_ON_LATE_CONFIRM under the agent_registry: prefix, not scheduler:.

Consequence: zero late-confirm lines after a restart is healthy, not a fix failure. The first live proof of the #993 fix is still pending a natural receipt-timeout event (schedule firing while the agent is mid-long-turn); the overnight soak may produce one.

4. New datapoint, filed without a claim: 17:00:13, sweep schedule #159 (post-reboot, pre-deploy) fired with cohort-start synchronization timed out; blocked delivery tasks remain queued; the sweep was run manually. Benign-by-design per #702 (tick waits ≤1s for cohort start only), but logging the occurrence since it sat adjacent to the replay traffic.

Open threads unchanged: (a) dup-cohort dispatch — two primary confirms for one firing ~28s apart; single-caller topology proven; leading hypothesis is stale last_run WAL visibility on the due-check read path (#956/#942 family) — audit dispatch to the codex lane planned after overnight soak data; (b) storm-head receipt-never-confirms.

🤖 Barsik (evidence: geordi@pi live logs + issue_991_evidence_20260803.md on the Pi)

[olegbrok]

NEW DEFECT (same family, found live on 26.08.004 tonight, incident closed): mid-turn-consumed replay paste → unbounded extend holding the per-agent lock → full schedule-pipeline deadlock

Follow-up to my evening addendum above; this happened after it was posted. Cross-ref #984 — this is the concrete availability case for its fix-item 2 (receipt resolution for non-pane deliveries).

Mechanism (code-verified at c44682d):

• A replayed wake's prompt was pasted mid-turn into a busy session (Pi/geordi, 17:12), consumed and handled inside that turn — so no dedicated per-turn receipt ever posts (the known Wake delivery reports FALSE NEGATIVES: a wake that triggers >600s of work is logged 'FIRED BUT UNDELIVERED' despite succeeding #966 blindness: acceptance tracking only observes the pane path).
• _wait_for_wake_confirmation (scheduler.py:650-675) then extends forever. Its only two exits are (a) the receipt resolving — never coming — or (b) _wake_prompt_inflight going False. The inflight check (scheduler.py:893) reads the transport's pasted-pending marker, which nothing clears for a consumed-mid-turn paste; with heartbeat_interval=0 (the fleet-default supervision opt-out) there is also no reconciler sweep to clear it. The loop never reads pending_schedule_wakes, so surgically deleting the row does not release anything.
• The waiter runs under the per-agent delivery lock (_replay_pending_locked), and normal fires shield-await behind the in-flight replay — so every subsequent schedule delivery for that agent deadlocks. Observed: 6 fires blocked over 45 min (a 10-min watcher ×5, a one-shot build, the hourly sweep); only the clock-aligned heartbeat path got through. Journal signature: receipt still pending for schedule ... prompt is already pasted to the transport — a cancel cannot recall it ... extending, repeating every ~10 min (first 17:21:33).

Note the #983 guard behaved correctly — cancelling a pasted prompt would risk duplicate execution. The gap is that the guard has no exit for "consumed via a route the receipt tracker cannot observe": the missing third state again.

Blast radius — one important correction over our first read: blocked fires do NOT vanish. Their delivery tasks stay alive in-memory awaiting the lock, and daemon shutdown persists them (FIRED BUT UNDELIVERED ... delivery canceled before attempt). Instrument trap: a mid-deadlock DB copy shows no row for a blocked fire because the task is still in-memory — that is "not yet persisted," not "lost."

Resolution (18:07-18:16, all timestamps PDT 2026-08-03): restart_daemon to an idle session is the only clean release. Shutdown persisted 9 rows; +1 already-stuck row = 10 replays. Boot 18:08:11 → all 10 drained 18:09:43→18:11:14 via the replay path, each delivered to an idle turn, no-op'd against run ledgers, confirmed + retired. Outbox verified empty by DB copy. Next live fire (18:15) confirmed in 1s. Final book: 10 replay confirms / 0 late-confirms / 0 parks / 0 zombie-drops / 0 duplicate executions / 1 restart.

Operator-side mitigations until #984 item 2 ships:

1. During any outbox drain, keep turns SHORT — end the turn immediately after each no-op so every replay lands on an idle session (the trigger is precisely a replay pasted mid-turn).
2. Peers: hold non-urgent inbound messages to a draining agent — an inbound turn manufactures the busy window the hazard needs.
3. Detection: the repeating ...extending journal line above; remedy is a restart, never a live-DB edit.

Primary artifact: issue_991_evidence_20260803.md on the Pi (geordi), complete through resolution — includes the journal excerpts verbatim.

🤖 Barsik (mechanism verified against source; live evidence: geordi@pi)