fetch_orchestration_item writes an already-expired lock lease when the advisory lock wait exceeds the lock timeout #21

Summary

fetch_orchestration_item can return an orchestration item whose lock lease has already expired at the moment it is returned. Every subsequent ack against that lease fails with Invalid lock token, so the turn's work is discarded, the message becomes visible again immediately, and the cycle repeats indefinitely.

Two independent defects in the stored procedure combine to produce this. A third defect in the core runtime (tracked separately in microsoft/duroxide) means the runtime's own escape hatch — max_attempts poisoning — cannot terminate the loop either.

Verified against main at commit 6109a41e18ef01887522c612574dd1e5e2a7e9f6.

Symptoms

Two log lines from the core runtime, 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 and never correlated, which is a large part of why this can run for days unnoticed. The first 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;

A value far above max_attempts means at least one message is trapped and will never leave on its own.

Defect 1 — deterministic candidate selection followed by a blocking advisory lock

migrations/0019_add_kv_last_updated.sql carries the current definition of fetch_orchestration_item:

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

IF NOT FOUND THEN RETURN; END IF;

PERFORM pg_advisory_xact_lock(hashtext(v_instance_id));   -- line 96: blocking

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. The FOR UPDATE OF q SKIP LOCKED re-verification at line 127 cannot prevent this — the blocking has already happened. This is the one blocking call in an otherwise carefully non-blocking function.

This compounds with the defect below: because a trapped message never commits, its visible_at never advances, so it remains permanently the oldest row and is selected first by every dispatcher on every poll.

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

p_now_ms is minted by the Rust caller before the call begins (src/provider.rs:942, let now_ms = Self::now_millis();, bound as $1 at lines 957-961) and is never refreshed inside the function:

PERFORM pg_advisory_xact_lock(hashtext(v_instance_id));   -- line 96, may block for seconds
...
v_locked_until := p_now_ms + p_lock_timeout_ms;           -- line 136, clock never refreshed

INSERT INTO %I.instance_locks (instance_id, lock_token, locked_until, locked_at)
VALUES (v_instance_id, v_lock_token, v_locked_until, p_now_ms)      -- line 138
ON CONFLICT(instance_id) DO UPDATE ...
WHERE %I.instance_locks.locked_until <= p_now_ms;                   -- line 144

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"

This is 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 the predicates at lines 82/85, 144, and 150-151, inside a retry loop whose CONTINUE paths (lines 131 and 149) are unbounded and un-backed-off. This produces a spiral within a single call: the longer the call runs, the further p_now_ms recedes from wall clock, so locked_until <= p_now_ms at line 144 becomes progressively harder to satisfy, and each failure takes another unbounded blocking advisory lock.

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 advisory-lock wait before the lease is written, with a 5s lock timeout.
SELECT out_instance_id, out_lock_token
  FROM <schema>.fetch_orchestration_item(
         (EXTRACT(EPOCH FROM now()) * 1000)::BIGINT - 10000,  -- p_now_ms, 10s stale
         5000                                                  -- p_lock_timeout_ms
       );

-- The returned lease is already expired:
SELECT instance_id,
       locked_until,
       (EXTRACT(EPOCH FROM now()) * 1000)::BIGINT AS now_ms,
       locked_until - (EXTRACT(EPOCH FROM now()) * 1000)::BIGINT AS remaining_ms
  FROM <schema>.instance_locks;
-- remaining_ms is NEGATIVE: the lease expired ~5s before it was handed out.

Any ack keyed on that out_lock_token then fails with Invalid lock token.

B. Organic — Defects 1 and 2 together

Run N dispatchers (N >= 8) against one database with a single hot instance and an orchestrator_lock_timeout at or below the observed advisory-lock wait. The convoy from Defect 1 lengthens the wait; once the wait exceeds the timeout, Defect 2 makes every lease dead on arrival, and attempt_count for the affected row climbs without bound.

Suggested direction

Not prescriptive, but the shape that follows from the analysis:

1. Refresh the clock after the wait. Compute the lease from a timestamp taken after the advisory lock is acquired, inside the function, rather than from the caller's p_now_ms. The liveness predicates should use the same refreshed value.
2. Do not block on a deterministic candidate. Either use pg_try_advisory_xact_lock and move to the next candidate on failure, or randomize/partition candidate selection so dispatchers do not converge on one key.
3. Bound the loop. The CONTINUE paths are currently unbounded and un-backed-off.

A regression test asserting that a returned lease is still valid at the moment it is returned would cover this directly.

Note that a fix here should be considered alongside the core-side hardening: a provider that ever returns an expired lease will still trap the runtime until that is addressed.

Related

• microsoft/duroxide #32 must keep the acknowledge fix from #44 (migration 0026 and ack_orchestration_item) #46 — umbrella issue where this was first analyzed
• The same defect class exists independently in the optimized provider, at different files and line numbers. The two implementations are not forks of each other and each needs its own fix.