Orchestration messages can livelock permanently: lock lease is computed from a pre-wait timestamp, and max_attempts disposition depends on that lease

[affandar]

Summary

Under dispatcher concurrency, an orchestration message can enter a state from which the runtime cannot recover by any mechanism — including the one designed for exactly this situation, max_attempts.

The chain:

1. All dispatchers deterministically select the same queue row, then serialize on a blocking pg_advisory_xact_lock.
2. The lock lease is computed from p_now_ms — a timestamp supplied by the caller, before that wait, and never refreshed. If the wait exceeds p_lock_timeout_ms, the lease is written already expired.
3. Terminal disposition (poison), backoff, and the attempt-count increment all commit through an ack keyed on that dead lease. All three fail together.

The message is therefore never poisoned, never backed off, and never abandoned with a delay. Its lock simply expires and it becomes visible again — so the retry interval collapses to exactly the lock lease, the most aggressive retry the system can produce, applied to the message that most needs to be left alone.

Membership in this trapped set is monotonic: nothing leaves it without manual out-of-band deletion.

Symptoms

Two log lines, repeating indefinitely, one immediately after the other:

WARN duroxide::runtime::dispatchers::orchestration: Orchestration message exceeded max attempts,
     marking as poison instance=<id> attempt_count=78874 max_attempts=10
WARN duroxide::runtime::dispatchers::orchestration: ack_orchestration_item failed with
     non-retryable error error=ack_orchestration_item: Invalid lock token

They are logged at the same level, adjacent, and never connected — which is a large part of why this can run for days unnoticed. The first line reads as "the runtime is handling it"; the second reads as a transient. Together they mean permanently unrecoverable.

Query-level signature:

SELECT max(attempt_count) FROM <schema>.orchestrator_queue;

Healthy is 0. Any value above max_attempts means at least one message is trapped and will never leave on its own.

Root cause

All three defects are in fetch_orchestration_item in the Postgres provider.

Defect 1 — deterministic candidate selection + a blocking advisory lock

LOOP
    SELECT q.instance_id INTO v_instance_id
      FROM <schema>.orchestrator_queue q
     WHERE q.visible_at <= TO_TIMESTAMP(p_now_ms / 1000.0)
       AND NOT EXISTS (SELECT 1 FROM <schema>.instance_locks il
                        WHERE il.instance_id = q.instance_id
                          AND il.locked_until > p_now_ms)
     ORDER BY q.visible_at, q.id
     LIMIT 1;                                                   -- deterministic

    IF NOT FOUND THEN RETURN; END IF;

    PERFORM pg_advisory_xact_lock(hashtext(v_instance_id));      -- blocking
    ...
    SELECT ... FOR UPDATE OF q SKIP LOCKED;                      -- too late

ORDER BY … LIMIT 1 is deterministic, so every dispatcher in the fleet independently computes the same candidate and then blocks on the same advisory key. Thundering herd → convoy. The SKIP LOCKED further down cannot prevent this; the blocking already happened. It is the one blocking call in an otherwise carefully non-blocking function.

This compounds with Defect 3: because nothing commits, a trapped message's visible_at never advances, so it remains permanently the oldest row — selected first, by every dispatcher, on every poll, indefinitely.

Defect 2 — the lease is computed from a pre-wait timestamp

-- p_now_ms was computed by the CALLER, before this call began
PERFORM pg_advisory_xact_lock(hashtext(v_instance_id));   -- may block for seconds

v_locked_until := p_now_ms + p_lock_timeout_ms;           -- clock never refreshed

INSERT INTO <schema>.instance_locks (instance_id, lock_token, locked_until, locked_at)
VALUES (v_instance_id, v_lock_token, v_locked_until, p_now_ms)
ON CONFLICT (instance_id) DO UPDATE ...;

If the advisory wait exceeds p_lock_timeout_ms, the lease is dead on arrival:

t=0.0s   caller computes now_ms = T; calls fetch_orchestration_item(T, 5000)
t=0.0s   -> blocks on pg_advisory_xact_lock
t=6.0s   <- lock acquired
t=6.0s   writes locked_until = T + 5000ms  ==  wall-clock t=5.0s
                                            -> ALREADY EXPIRED, 1 second ago
t=6.4s   returns the item with a dead lease
t=6.4s   turn executes, acks -> "Invalid lock token"

Deterministic, not intermittent — consistent with a 100% ack-failure rate rather than a flaky one.

The same stale p_now_ms is also the liveness reference in three predicates inside an unbounded retry loop:

WHERE q.visible_at <= TO_TIMESTAMP(p_now_ms / 1000.0)              -- (a)
  AND NOT EXISTS (... AND il.locked_until > p_now_ms)              -- (b)
...
 WHERE <schema>.instance_locks.locked_until <= p_now_ms;           -- (c)
GET DIAGNOSTICS v_lock_acquired = ROW_COUNT;
IF v_lock_acquired = 0 THEN CONTINUE; END IF;                      -- (d) unbounded

which produces a spiral within a single call:

# p_now_ms is FIXED for the whole call; wall-clock advances past it
loop:
    candidate = oldest_eligible(as_of = p_now_ms)   # (a)(b) increasingly stale
    block_until_advisory_lock(candidate)            # unbounded wait
    # the longer the call runs, the further p_now_ms recedes, so
    # `locked_until <= p_now_ms` (c) becomes HARDER to satisfy
    if not acquired:                                # fails more as the call ages
        continue                                    # (d) another blocking wait

So one fetch_orchestration_item call can take many blocking advisory locks in sequence, with no bound and no backoff, and each iteration makes the next more likely to fail.

Defect 3 — terminal disposition depends on the lease it is trying to escape

if attempt_count > self.options.max_attempts {
    warn!(..., "Orchestration message exceeded max attempts, marking as poison");
    self.fail_orchestration_as_poison(&item, lock_token, attempt_count).await;
    return;
}

fail_orchestration_as_poison(item, lock_token, attempt_count) commits via an ack keyed on lock_token. When that token is dead, the poison marking is silently lost — as is the backoff and the attempt increment, since they ride the same ack.

The function already carries an explicit invariant comment on this ack:

// IMPORTANT: The ack below MUST succeed despite corrupted history rows in the DB.

That requirement was reasoned about for the corrupted history path, but not for the expired lease path. The only escape from the retry loop is gated behind the exact thing that is failing.

Reproduction

A. Minimal — isolates Defect 2, single connection, no concurrency required

Passing a stale p_now_ms reproduces exactly what a long advisory wait produces naturally.

Given an instance with a visible queued orchestration message:

-- simulate a 10s wait before the lease is written
SELECT out_instance_id, out_lock_token
FROM <schema>.fetch_orchestration_item(
       p_now_ms          => (EXTRACT(EPOCH FROM clock_timestamp()) * 1000)::bigint - 10000,
       p_lock_timeout_ms => 5000);

-- the lease it just granted is already in the past
SELECT instance_id,
       locked_until,
       (EXTRACT(EPOCH FROM clock_timestamp()) * 1000)::bigint AS now_ms,
       locked_until < (EXTRACT(EPOCH FROM clock_timestamp()) * 1000)::bigint AS already_expired
FROM <schema>.instance_locks;
--  already_expired = t

Any ack_orchestration_item with the returned token then fails with Invalid lock token. If the instance's attempt_count also exceeds max_attempts, the poison marking is lost with it and the message is permanently trapped.

B. Full livelock — reproduces the emergent behaviour

1. Postgres provider; run enough dispatchers that several contend for one instance (we observed it with orchestration_concurrency: 4 across 8 processes = 32 dispatchers).
2. Introduce an orchestration that fails deterministically, so attempt_count climbs past max_attempts.
3. Ensure the advisory-lock wait for that instance exceeds orchestrator_lock_timeout (default 5s). Convoy depth does this on its own once a hot instance exists.
4. Observe the paired log lines above repeating, and attempt_count growing without bound in orchestrator_queue.
5. Confirm the message never drains: it is not poisoned, not backed off, and its visible_at never advances.

Evidence from a production deployment

Observed on a PilotSwarm deployment: 8 worker processes × orchestration_concurrency: 4 = 32 orchestration dispatchers against one Postgres-backed queue. Ran for 5 days before manual intervention.

Metric	Value
Max attempt_count on one instance	78,987 (against max_attempts: 10)
Total accumulated attempts	781,446 across 12 instances
fetch_orchestration_item latency	~6.4 s vs a 5 s lease
Effective throughput	zero
Instances recovered without manual deletion	0

Backoff is provably absent. Deriving the implied retry interval as attempt_count ÷ elapsed wall time:

instance	stuck for	attempts	implied interval
A	115.2 h	78,896	5.26 s
B	21.1 h	12,680	6.00 s
C	20.6 h	12,394	5.99 s
D	20.4 h	12,275	5.99 s
E	20.1 h	12,055	5.99 s
F	20.0 h	12,007	5.99 s
G	17.8 h	10,697	5.98 s
H	5.4 h	3,192	6.09 s
I	1.9 h	1,159	6.05 s
J	1.7 h	1,042	6.04 s

Mean 5.96 s against a 5 s lease — flat regardless of attempt_count (1,042 → 78,896) or age (1.7 h → 115 h). Functioning exponential backoff would space attempt 12,000 by days. Instance A sits slightly lower because it was the only trapped message for its first three days, when fleet load and therefore fetch latency were lower.

Observed latency clustered unusually tightly (6.40, 6.39, 6.39, 6.26, 6.27, 6.45 s). Ordinary lock contention produces a spread; a spiral against a fixed reference point converges on a characteristic value, which is consistent with the Defect 2 loop.

Ruled out by measurement

• Holder work is not slow. The history load — JSONB_AGG(h.event_data::JSONB ORDER BY h.event_id), where event_data is text, so ::JSONB is a per-row parse — measures 0.4–44 ms depending on payload bytes. Reaching a 5 s lease this way would require ~230 MB of current-execution history.
• Not heap bloat. The queue visibility scan plans as Index Scan, Buffers: shared hit=1, 0.014 ms execution.
• Not history size selecting victims. One trapped instance had 78 history events; a never-trapped instance carried 21 MB.

The latency is queueing and looping, not work.

Suggested fixes

1. Refresh the clock after the advisory wait. Must be clock_timestamp() — now() and transaction_timestamp() return the transaction start time, which predates the wait (the advisory lock is transaction-scoped) and is equally stale. Using now() here would look like a fix and change nothing.

PERFORM pg_advisory_xact_lock(hashtext(v_instance_id));
v_now_ms       := (EXTRACT(EPOCH FROM clock_timestamp()) * 1000)::bigint;
v_locked_until := v_now_ms + p_lock_timeout_ms;

2. Do not block on the advisory lock. If another dispatcher holds the instance, find a different one — matching the non-blocking intent of SKIP LOCKED and the NOT EXISTS instance_locks guard already in the same function.

IF NOT pg_try_advisory_xact_lock(hashtext(v_instance_id)) THEN
    CONTINUE;
END IF;

3. Bound the retry loop and refresh the clock per iteration, so no single call can spiral:

LOOP
    v_now_ms := (EXTRACT(EPOCH FROM clock_timestamp()) * 1000)::bigint;
    v_iters  := v_iters + 1;
    IF v_iters > <max_candidate_attempts> THEN RETURN; END IF;  -- empty; caller re-polls
    ...  -- use v_now_ms, never p_now_ms, for every liveness predicate
END LOOP;

4. Break the herd — select from a small candidate set rather than a single deterministic row:

SELECT instance_id FROM (
    SELECT q.instance_id FROM <schema>.orchestrator_queue q
     WHERE ... ORDER BY q.visible_at, q.id LIMIT <fanout>
) c ORDER BY random() LIMIT 1;

5. Make terminal disposition independent of a live lease. A message that has exceeded max_attempts should be markable as poison even when its lock has lapsed — e.g. keyed on (instance_id, execution_id, attempt_count) rather than on the lock token. This is the defence in depth: with it, none of the above being imperfect can produce an immortal message.

6. Surface the unrecoverable combination. An ack failing with an invalid lock token on the poison path specifically is not retryable, it is terminal-and-lost. It deserves a distinct, loud diagnostic rather than two adjacent warnings that must be correlated by a human.

Notes

• orchestrator_lock_timeout is configurable in the crate but is not exposed through the Node bindings' JsRuntimeOptions, so Node consumers have no mitigation available at all: Expose orchestrator_lock_timeout in JsRuntimeOptions (Rust supports it, Node bindings do not) duroxide-node#11. Note that raising it only widens the margin — it does not fix a lease computed from a pre-wait timestamp, because the advisory wait is unbounded.
• The trigger for the first excursion past the lease is environment-specific and will differ per deployment. The absence of any recovery path once it happens is not. Defect 2 alone guarantees that any advisory wait exceeding the lease yields an expired-on-arrival lock, on any deployment, at any scale.

Environment

• duroxide (crate) 0.1.29, duroxide (npm bindings) 0.1.27
• Postgres-backed provider
• orchestration_concurrency: 4 × 8 processes, max_attempts: 10, orchestrator_lock_timeout: 5s (default)

[affandar]

Bindings-gap counterpart filed against the Node bindings: microsoft/duroxide-node#11 — orchestrator_lock_timeout is configurable here in the crate but is not mapped into JsRuntimeOptions, so Node consumers had no mitigation available while this was happening.

[affandar]

Superseded — the measurements and analysis from this comment are folded into the issue description above.

[affandar]

Superseded — the provider-SQL analysis from this comment is folded into the issue description above.