Skip to content

fix(orchestrator): deadline-aware, self-healing consuming event drain - #580

Merged
jlong merged 1 commit into
mainfrom
jlong/drain-consuming-event-drain-hangs-past-max-lifetime-and-permanently-wedges-on-a-poison-cursor-silent-death
Aug 18, 2026
Merged

fix(orchestrator): deadline-aware, self-healing consuming event drain#580
jlong merged 1 commit into
mainfrom
jlong/drain-consuming-event-drain-hangs-past-max-lifetime-and-permanently-wedges-on-a-poison-cursor-silent-death

Conversation

@jlong

@jlong jlong commented Aug 18, 2026

Copy link
Copy Markdown
Owner

Task

The orchestrator's consuming event drain (shelbi orchestrator events next --follow) can (a) hang indefinitely past its --max-lifetime, and (b) permanently wedge so its per-project event-cursor freezes and every relaunch instantly re-dies. Observed live: the prbadge project's drain died ~4h ago (cursor frozen while events kept appending) and never recovered; --max-lifetime 2s invocations hang to an external 2-minute kill. This makes an orchestrator go silently blind to its board.

Make the consuming drain honor its deadline and self-heal from a stale/poison cursor instead of dying silently.

Current Behavior

Root cause is in the --follow drain path (crates/shelbi-cli/src/commands/orchestrator.rsrun_feedfeed_loopfeed_loop_with, ~lines 301-351) plus the shared lock primitive.

  1. Hang — deadline/signal only checked between ticks, then blocks in an uninterruptible lock. feed_loop_with checks max_lifetime/signal at the top of each tick (~orchestrator.rs:328-334), then calls read_persisted_cursor and scan_feed_batch, both of which acquire the hub-global advisory lock ~/.shelbi/events.log.lock (event_log.rs:278-280; reads at event_log.rs:671 and 597). The lock primitive acquire_file_lock (crates/shelbi-state/src/lib.rs:587-613) is an unbounded blocking libc::flock(fd, LOCK_EX) (line 602) that re-issues LOCK_EX on EINTR (607-609). So once a tick enters flock, neither the deadline nor SIGTERM can interrupt it — only SIGKILL, which never advances the cursor. Every project's 4 Hz follower poll and every event writer contend on this one global lock, so LOCK_EX (not FIFO-fair) can starve a follower well past its deadline under load.

  2. Permanent freeze — poison cursor after rotation, silent death. The cursor advances only via events ack (ack_deliverywrite_persisted_cursor, ~orchestrator.rs:529-535); the --follow loop never writes it. Any death mid-batch freezes the cursor. The log rotates and retains only one prior generation, so once the frozen cursor falls >1 rotation behind, read_event_log_from returns Err "event cursor {c} predates earliest retained cursor {earliest}" (event_log.rs:605-610). That Err propagates through scan_feed_batch(...)? (orchestrator.rs:335) and run_feed's emit_feed_notice(project, &outcome?) (orchestrator.rs:246) as a bare Err to main with no notice (see doc at orchestrator.rs:399-400). Result: the drain dies silently and every relaunch re-reads the same wedged cursor and re-dies. This is the prbadge failure.

  3. Freeze-while-alive — unacked poison batch. An unacked batch is re-emitted every FEED_VISIBILITY_TIMEOUT (90s, orchestrator.rs:172; redelivery feed_should_scan at 383-396) under a stable delivery id, never advancing the cursor; new events queue behind it forever. A single un-ackable batch wedges the stream.

  4. No supervisor for the drain. crates/shelbi-orchestrator/src/supervision.rs is panes-only; nothing relaunches run_feed after an Err. (Addressed as a follow-up — see below — not required by this task.)

Expected Behavior

  • Honor the deadline and signal even while waiting on the lock. Replace the hot-path blocking LOCK_EX with a bounded, deadline-aware acquire: LOCK_EX | LOCK_NB in a short retry loop that re-checks start.elapsed() >= limit and the termination signal between attempts (or plumb a deadline into acquire_file_lock). --max-lifetime 2s must return Expired within ~2s even under lock contention, and SIGTERM must end the loop promptly (stop the EINTR loop from swallowing the term signal).
  • Reduce global contention: give the per-project cursor read/write its own lock file (e.g. ~/.shelbi/projects/<p>/event-cursor.lock) so a follower's cursor access does not contend with unrelated projects/writers on the hub-global events.log.lock. (Log reads may still use the shared lock, but should be deadline-aware per above.)
  • Self-heal a poison cursor instead of dying. When read_event_log_from reports the cursor predates the earliest retained cursor, the drain must fast-forward the cursor to earliest (or current_base), emit a distinct terminal FeedNotice (e.g. "cursor expired, resynchronized to , skipped events"), and continue — never propagate a silent Err that kills the process and re-dies on restart.
  • Never die silently. Any terminal drain outcome (including genuine errors) must emit a FeedNotice/log line the orchestrator can see, so a dead drain is observable rather than a silent stall.
  • Poison-batch escape (optional but preferred): bound redelivery of an unacked batch (count or age) → quarantine + advance so one un-ackable batch can't wedge the stream indefinitely.

Acceptance Criteria

  • shelbi orchestrator events next --follow --max-lifetime 2s returns within a small multiple of 2s even while another process holds events.log.lock (add a test that holds the lock and asserts timely Expired).
  • SIGTERM to a --follow drain that is blocked on lock acquisition ends it promptly (no reliance on SIGKILL).
  • A drain started with a cursor that predates the earliest retained generation resynchronizes (fast-forwards to earliest/current_base) and continues, emitting a visible "cursor expired/resynchronized" notice, instead of exiting with a silent Err. Add a test simulating a rotated-past cursor.
  • After the above, a relaunched drain on a previously-wedged cursor makes progress (cursor advances) rather than re-dying.
  • Per-project cursor access no longer contends on the hub-global events.log.lock (own lock file), verified by test or by inspection.
  • Every terminal drain outcome emits a FeedNotice/log line (no silent Err to main on the drain path).
  • Existing ack semantics unchanged (at-least-once; cursor still advances only on ack for normally-delivered batches).
  • cargo build --workspace, cargo test --workspace, and cargo clippy --workspace --all-targets -- -D warnings pass.

Follow-up (do NOT do in this task; file separately)

  • Add a real supervisor for the consuming drain with crash-loop backoff (mirror the pane supervisor in shelbi-orchestrator/src/supervision.rs), so a drain that does hit a terminal error is relaunched automatically. With the self-heal above this becomes a backstop rather than the only line of defense.

Context

Reported by the user 2026-08-18 after the prbadge orchestrator reported its background drain died. Confirmed via runtime evidence (prbadge event-cursor frozen 4h at 13391298 while events kept appending) and a code trace on origin/main @ 7be7327. This is core hub-global event infrastructure that every orchestrator depends on for board awareness — review the diff carefully; blast radius is high.


Auto-opened by Shelbi — review at: /Users/jlong/.shelbi/projects/shelbi/tasks/drain-consuming-event-drain-hangs-past-max-lifetime-and-permanently-wedges-on-a-poison-cursor-silent-death.md

The `--follow` drain (`shelbi orchestrator events next --follow`) could hang
past its `--max-lifetime` and permanently wedge on a poison cursor, silently
blinding an orchestrator to its board (observed live on prbadge: cursor frozen
4h while events kept appending, `--max-lifetime 2s` hanging to an external kill).

Root causes and fixes:

1. Hang past deadline/signal. The poll path acquired the hub-global
   `events.log.lock` via an unbounded blocking `flock(LOCK_EX)` that also
   re-issued LOCK_EX on EINTR, so once a tick entered flock neither the deadline
   nor SIGTERM could interrupt it — only SIGKILL, which never advances the cursor.
   Added `acquire_file_lock_deadline` (LOCK_EX|LOCK_NB in a short retry loop that
   re-checks a deadline and a cancel predicate, and does NOT swallow EINTR), plus
   deadline-aware `read_event_log_from_deadline` /
   `read_or_initialize_event_cursor_deadline`. The loop bounds every acquire by
   its remaining lifetime and threads the termination signal in as the cancel
   flag, so `--max-lifetime 2s` returns Expired within ~2s under contention and
   SIGTERM ends a lock-blocked drain promptly.

2. Global contention. Per-project cursor read/write moved off the hub-global
   lock onto a per-project `event-cursor.lock`, so a follower's cursor access no
   longer contends with unrelated projects or event writers. Safe because cursor
   writes stay atomic and rotation reads them via the same atomic snapshots
   (monotonic cursor => rotation still defers correctly). The one-time
   legacy-cursor migration is preserved: a cursor read still establishes the
   index (under the shared lock) while it is absent; once established the read
   stays on the uncontended cursor lock.

3. Poison cursor (the prbadge wedge). A cursor that predates the earliest
   retained generation now surfaces as data (`FeedRead::CursorExpired`) instead
   of a bare Err; the loop fast-forwards the durable cursor to the earliest
   retained position, emits a visible `resynchronized` notice, and continues — so
   a relaunch resumes healed rather than re-reading the wedged cursor and re-dying.

4. Never die silently. Any terminal error now emits a `failed` FeedNotice before
   propagating, so a dead drain is observable on the stream the supervisor
   already watches.

5. Poison-batch escape (the preferred optional): an unacked batch redelivered
   past FEED_MAX_REDELIVERIES (10) is quarantined — cursor advanced past it with
   a loud `quarantined` notice — so one un-ackable batch can't wedge the stream
   forever. A healthy consumer acks within one redelivery and never trips it.

Ack semantics unchanged: the cursor still advances only on ack for
normally-delivered batches; quarantine/resync are bounded escape hatches.

Decisions made without asking: (a) cursor gets its OWN lock rather than plumbing
a deadline through every shared-lock caller — matches the task's explicit
guidance and keeps blast radius on the append/rotation paths at zero; (b)
implemented the optional poison-batch quarantine (cap 10) since it closes case 3
of the wedge and the task prefers it; (c) resync fast-forwards to `earliest`
(max events retained) rather than `current_base`.

Follow-up (NOT in this change, to be filed separately): add a real supervisor
for the consuming drain with crash-loop backoff, mirroring the pane supervisor
in shelbi-orchestrator/src/supervision.rs. With the self-heal here that becomes a
backstop rather than the only line of defense.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
@vercel

vercel Bot commented Aug 18, 2026

Copy link
Copy Markdown

The latest updates on your projects. Learn more about Vercel for GitHub.

Project Deployment Actions Updated (UTC)
shelbi Ready Ready Preview Aug 18, 2026 3:25am

Request Review

@jlong
jlong merged commit eb873b7 into main Aug 18, 2026
3 checks passed
@jlong
jlong deleted the jlong/drain-consuming-event-drain-hangs-past-max-lifetime-and-permanently-wedges-on-a-poison-cursor-silent-death branch August 18, 2026 14:58
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant