Skip to content

Commit c56cf1f

Browse files
committed
fix: preserve row in dispatch_one when consume() early-exits on shutdown
If stop() flips running=False between a worker pulling a row from _inflight and dispatch_one entering consume(), FastStream's base SubscriberUsecase.consume() returns None via its early-exit guard without invoking the handler. dispatch_one previously fell into assert_state_set → reject() → _safe_flush, silently DELETEing the row and emitting an 'acked' metric for work that never ran. Restructure the consume() block so a None return + running=False short-circuits before the flush path; the lease lives until lease_ttl_seconds expires and another replica reclaims the row on next start. Behavior is preserved for the consume()-raises path because the outer except already returned without flushing, making the previous finally-driven state_set mutation a no-op. Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com> # Conflicts: # CLAUDE.md
1 parent 7c1f5f0 commit c56cf1f

3 files changed

Lines changed: 47 additions & 4 deletions

File tree

CLAUDE.md

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -76,6 +76,8 @@ Lease-loss is logged at WARNING with `extra={"event": "lease_lost", "phase": "te
7676

7777
**Writer-connection autocommit.** `_open_worker_resources` configures the per-worker writer connection with `isolation_level="AUTOCOMMIT"`. The two terminal-state writes (`delete_with_lease`, `mark_pending_with_lease`) are each a single statement, so an explicit BEGIN/COMMIT would just add two Postgres round-trips per row with no benefit. Autocommit collapses the per-row cost from three round-trips (BEGIN + DELETE/UPDATE + COMMIT) to one while preserving the lease-token guard — the `WHERE acquired_token = …` clause is what enforces the invariant, not the transaction wrapping the statement. The fetch connection is **not** autocommit-configured: it owns LISTEN/NOTIFY and the CTE-update flow is paid once per batch, where the BEGIN/COMMIT amortizes naturally.
7878

79+
**Shutdown race in `dispatch_one`.** If `stop()` flips `running=False` between a worker pulling a row from `_inflight` and `consume()` being entered, FastStream's base `SubscriberUsecase.consume()` early-exits (`if not self.running: return None`) without running the handler. `dispatch_one` detects this state — `not row.state_set and not self.running` after `consume()` returns without raising — and returns before the `assert_state_set → reject() → _safe_flush` path that would otherwise silently DELETE the row. The lease lives until `lease_ttl_seconds` expires and another replica reclaims the row on next start. No metric fires at this site (the row is neither acked nor nacked). Without this guard, busy subscribers leak rows on every rolling deploy.
80+
7981
### Test broker
8082

8183
`TestOutboxBroker` (in `testing.py`) swaps in a `FakeOutboxClient` (in-memory list of `_FakeRow` dicts). Two dispatch modes:

faststream_outbox/subscriber/usecase.py

Lines changed: 9 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -439,17 +439,22 @@ async def dispatch_one(
439439
)
440440
start_perf = time.perf_counter()
441441
try:
442-
try:
443-
await self.consume(row)
444-
finally:
445-
await row.assert_state_set(logger)
442+
await self.consume(row)
446443
except Exception as e: # noqa: BLE001
447444
# No metric emitted here intentionally: the row was never marked
448445
# terminal/retry, so its state is undefined — flushing or emitting an
449446
# ack/nack would lie. The lease will expire and the row will be
450447
# reclaimed; the ERROR log is the operator signal.
451448
self._log(log_level=logging.ERROR, message=f"Outbox worker error: {e!r}", exc_info=e)
452449
return
450+
# Shutdown race: SubscriberUsecase.consume() returns None without invoking
451+
# process_message when self.running has been flipped to False by stop().
452+
# Detecting that here lets us preserve the row instead of falling through
453+
# to assert_state_set → reject() → _safe_flush → DELETE. The row's lease
454+
# expires after lease_ttl_seconds and is reclaimed on next start.
455+
if not row.state_set and not self.running:
456+
return
457+
await row.assert_state_set(logger)
453458
duration_seconds = time.perf_counter() - start_perf
454459
common = {**base, "deliveries_count": row.deliveries_count, "duration_seconds": duration_seconds}
455460
if row.last_exception is None:

tests/test_unit.py

Lines changed: 36 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1578,6 +1578,42 @@ async def _boom(_row: object) -> None:
15781578
await sub.dispatch_one(msg, writer_conn=None)
15791579

15801580

1581+
async def test_dispatch_one_preserves_row_when_consume_early_exits_on_shutdown() -> None:
1582+
"""
1583+
Shutdown race in dispatch_one.
1584+
1585+
``SubscriberUsecase.consume()`` returns ``None`` without invoking
1586+
``process_message`` when ``running`` is False. Previously ``dispatch_one`` fell
1587+
into ``assert_state_set → reject() → _safe_flush`` and silently DELETEd the row.
1588+
The early-return guard preserves the row so its lease expires and another
1589+
replica reclaims it.
1590+
"""
1591+
events, recorder = _events_recorder()
1592+
metadata = MetaData()
1593+
table = make_outbox_table(metadata)
1594+
broker = OutboxBroker(outbox_table=table, metrics_recorder=recorder)
1595+
1596+
@broker.subscriber("orders")
1597+
async def handle(body: dict) -> None: ...
1598+
1599+
fake = FakeOutboxClient()
1600+
test_broker = TestOutboxBroker(broker)
1601+
test_broker.fake_client = fake
1602+
msg = _make_msg(queue="orders")
1603+
1604+
async with test_broker:
1605+
sub = next(iter(broker._subscribers)) # noqa: SLF001
1606+
# Simulate the race: a worker has pulled a row from _inflight, then stop()
1607+
# flipped running to False before dispatch_one's consume() call.
1608+
sub.running = False
1609+
with patch.object(fake, "delete_with_lease", new=AsyncMock(return_value=True)) as delete_spy:
1610+
await sub.dispatch_one(msg, writer_conn=None)
1611+
1612+
delete_spy.assert_not_awaited()
1613+
assert not any(e == "acked" for e, _ in events)
1614+
assert not any(e.startswith("nacked") for e, _ in events)
1615+
1616+
15811617
async def test_flush_terminal_logs_lease_lost_at_warning_with_structured_fields() -> None:
15821618
"""M7: when delete returns rowcount=0 (lease reclaimed) the broker emits a WARNING with structured fields."""
15831619

0 commit comments

Comments
 (0)