Skip to content

Commit 8396b98

Browse files
authored
Bound subscriber statements so loops reconnect after a silent primary loss (#262)
* Bound subscriber statements so loops reconnect after a silent primary loss A fetch or terminal write on a connection whose primary vanished without closing it (power loss, network partition) hung until the kernel's TCP timeout, so the subscriber stopped consuming after a failover. Each fetch, delete, batch delete and retry update is now capped at the new query_timeout_seconds subscriber option (default: lease_ttl_seconds); on timeout the connection is invalidated and the loop reconnects. Adds failover drills (just test-dr): a primary/streaming-replica compose cluster where the primary is either killed or cut off from the network and the replica is promoted. Not part of CI. * Skip failover drills unless DR_CLUSTER_DSN is set The floors job runs pytest . and sets POSTGRES_DSN, so the drills were collected and tried to connect to a cluster that does not exist.
1 parent 84c5fe5 commit 8396b98

19 files changed

Lines changed: 494 additions & 24 deletions

‎AGENTS.md‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,9 @@ the vocabulary. Read it before naming a concept in code, a test name, or an issu
1919
pytest`; `tests/test_integration.py` skips if `POSTGRES_DSN` is unreachable. The compose Postgres
2020
publishes no host port, so run the DB tests through `just test`. The coverage gate is on by
2121
default, so a partial run trips it; pass `--no-cov` while iterating.
22+
- `just test-dr` runs the failover drills in `tests_dr/` (primary killed, primary cut off from the
23+
network), each on a fresh primary/replica cluster from `docker-compose.dr.yml`. It needs the Docker
24+
socket, takes a few minutes, and is not in CI.
2225
- Nothing validates Markdown links outside `docs/`. `just docs-build` runs `mkdocs --strict` over
2326
the site only; root Markdown, `.github/`, and `docs/agents/` are unchecked.
2427

‎docker-compose.dr.yml‎

Lines changed: 52 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,52 @@
1+
name: outbox-dr
2+
3+
services:
4+
dr:
5+
build:
6+
context: .
7+
dockerfile: ./Dockerfile
8+
user: root
9+
volumes:
10+
- .:/code
11+
- /code/.venv
12+
- /var/run/docker.sock:/var/run/docker.sock
13+
depends_on:
14+
pg-replica:
15+
condition: service_healthy
16+
environment:
17+
- DR_CLUSTER_DSN=postgresql+asyncpg://outbox:outbox@/outbox?host=pg-primary:5432&host=pg-replica:5432&target_session_attrs=primary
18+
- PRIMARY_DSN=postgresql://outbox:outbox@pg-primary:5432/outbox
19+
- REPLICA_DSN=postgresql://outbox:outbox@pg-replica:5432/outbox
20+
21+
pg-primary:
22+
image: postgres:17
23+
container_name: outbox-dr-primary
24+
environment:
25+
- POSTGRES_USER=outbox
26+
- POSTGRES_PASSWORD=outbox
27+
- POSTGRES_DB=outbox
28+
volumes:
29+
- ./tests_dr/primary-init.sh:/docker-entrypoint-initdb.d/primary-init.sh:ro
30+
healthcheck:
31+
test: ["CMD-SHELL", "pg_isready -U outbox -d outbox"]
32+
interval: 1s
33+
timeout: 3s
34+
retries: 30
35+
36+
pg-replica:
37+
image: postgres:17
38+
container_name: outbox-dr-replica
39+
user: postgres
40+
entrypoint: ["bash", "/replica-entrypoint.sh"]
41+
environment:
42+
- PGPASSWORD=outbox
43+
volumes:
44+
- ./tests_dr/replica-entrypoint.sh:/replica-entrypoint.sh:ro
45+
depends_on:
46+
pg-primary:
47+
condition: service_healthy
48+
healthcheck:
49+
test: ["CMD-SHELL", "pg_isready -U outbox -d outbox"]
50+
interval: 1s
51+
timeout: 3s
52+
retries: 60

‎docs/operations/checklist.md‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -25,6 +25,11 @@ story.
2525
cutoff is server-side `make_interval(...)`, immune to clock skew.
2626
Tuning: [Subscriber § Slow handlers: dedicated
2727
queue](../usage/subscriber.md#slow-handlers-dedicated-queue).
28+
- [ ] Engine URL follows the primary across a failover (a proxy, or a
29+
multi-host URL with `target_session_attrs=primary`). Subscribers with a
30+
long lease set a shorter `query_timeout_seconds`; recovery from a primary
31+
that went silent takes about twice that value. See [Subscriber § Database
32+
failover](../usage/subscriber.md#database-failover).
2833
- [ ] Slow handlers segregated onto their own subscriber with a
2934
taller `lease_ttl_seconds`. Don't raise it globally; that delays
3035
reclaim of *actually* stuck rows everywhere.

‎docs/usage/subscriber.md‎

Lines changed: 34 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -90,6 +90,7 @@ Per-subscriber knobs, passed to `@broker.subscriber("…", …)`:
9090
| `min_fetch_interval` | `1.0` s | Base for the adaptive idle backoff (jittered ±50%, so an actual wait can land below it); no sleep at all while fetches keep returning rows |
9191
| `max_fetch_interval` | `10.0` s | Ceiling for the adaptive idle backoff (with jitter) |
9292
| `lease_ttl_seconds` | `60.0` s | How long a claim is valid before another fetch may reclaim it. Must exceed your handler's P99 with margin. |
93+
| `query_timeout_seconds` | `None` (uses `lease_ttl_seconds`) | Client-side cap on each fetch and terminal write. A statement still running when it expires is abandoned, its connection is closed, and the loop reconnects. Set it below a long lease so a lost primary is noticed sooner. Must be `> 0` and at most `lease_ttl_seconds`. See [Database failover](#database-failover). |
9394
| `max_deliveries` | `None` (unbounded) | Total claims (including lease-expiry re-claims) after which the row is dropped without invoking the handler. Defends against handlers that consistently wedge. Must be at least `1`; use `None`, not `0`, for no cap. |
9495
| `terminal_flush_batch_size` | `1` (off) | Coalesce completed terminal `DELETE`s into one `DELETE … RETURNING` per N rows. `1` is one round-trip per message (unchanged). Higher trades a wider crash-redelivery window for far fewer round-trips. See [Batching terminal deletes](#batching-terminal-deletes). |
9596
| `ack_policy` | `AckPolicy.NACK_ON_ERROR` | See [Ack policy](#ack-policy) |
@@ -360,6 +361,39 @@ startup with `FATAL: too many connections`.
360361

361362
*Operator-side: [Production checklist § Sizing](../operations/checklist.md#sizing).*
362363

364+
## Database failover
365+
366+
Point the engine at whichever node is currently primary, either through a proxy
367+
or virtual IP, or with a multi-host URL that asks asyncpg for the writable node:
368+
369+
```python
370+
engine = create_async_engine(
371+
"postgresql+asyncpg://user:pass@/app?host=pg-1:5432&host=pg-2:5432&target_session_attrs=primary",
372+
)
373+
```
374+
375+
Without `target_session_attrs=primary`, a reconnect can land on a standby, where
376+
the fetch fails with a read-only error.
377+
378+
How fast the subscriber recovers depends on how the old primary went away:
379+
380+
- **It closed its connections** (the process crashed or was killed). The next
381+
statement fails at once, and the fetch and worker loops back off and
382+
reconnect within seconds.
383+
- **It went silent** (the host lost power, or the network was partitioned).
384+
Statements hang because no error ever arrives. Each fetch and terminal write
385+
is capped at `query_timeout_seconds`, after which the connection is dropped and
386+
the loop reconnects. The fetch loop hits that cap first; the worker hits it
387+
again on its own stale connection once it gets a row. Recovery takes about
388+
`2 × query_timeout_seconds`, which is two minutes with the default 60 s lease.
389+
A subscriber with a long lease for slow handlers should set a shorter
390+
`query_timeout_seconds`.
391+
392+
With asynchronous replication the new primary can miss the last commits on the
393+
old one. A lost insert disappears together with the business rows from the same
394+
transaction. A lost terminal `DELETE` brings a handled row back, so it is
395+
delivered again; handlers are idempotent for that reason anyway.
396+
363397
## Read-only inspection
364398

365399
`subscriber.get_one()` and `async for msg in subscriber:` are not

‎faststream_outbox/fastapi/router.py‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -167,6 +167,7 @@ def subscriber( # ty: ignore[invalid-method-override] # noqa: PLR0913
167167
min_fetch_interval: float = 1.0,
168168
max_fetch_interval: float = 10.0,
169169
lease_ttl_seconds: float = 60.0,
170+
query_timeout_seconds: float | None = None,
170171
max_deliveries: int | None = None,
171172
terminal_flush_batch_size: int = 1,
172173
ack_policy: AckPolicy | None = None,
@@ -200,6 +201,7 @@ def subscriber( # ty: ignore[invalid-method-override] # noqa: PLR0913
200201
min_fetch_interval=min_fetch_interval,
201202
max_fetch_interval=max_fetch_interval,
202203
lease_ttl_seconds=lease_ttl_seconds,
204+
query_timeout_seconds=query_timeout_seconds,
203205
max_deliveries=max_deliveries,
204206
terminal_flush_batch_size=terminal_flush_batch_size,
205207
ack_policy=ack_policy,

‎faststream_outbox/registrator.py‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -33,6 +33,7 @@ def subscriber( # ty: ignore[invalid-method-override]
3333
min_fetch_interval: float = 1.0,
3434
max_fetch_interval: float = 10.0,
3535
lease_ttl_seconds: float = 60.0,
36+
query_timeout_seconds: float | None = None,
3637
max_deliveries: int | None = None,
3738
terminal_flush_batch_size: int = 1,
3839
ack_policy: AckPolicy | None = None,
@@ -56,6 +57,7 @@ def subscriber( # ty: ignore[invalid-method-override]
5657
min_fetch_interval=min_fetch_interval,
5758
max_fetch_interval=max_fetch_interval,
5859
lease_ttl_seconds=lease_ttl_seconds,
60+
query_timeout_seconds=query_timeout_seconds,
5961
max_deliveries=max_deliveries,
6062
terminal_flush_batch_size=terminal_flush_batch_size,
6163
ack_policy=ack_policy,

‎faststream_outbox/router.py‎

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,7 @@ def __init__( # noqa: PLR0913
3131
min_fetch_interval: float = 1.0,
3232
max_fetch_interval: float = 10.0,
3333
lease_ttl_seconds: float = 60.0,
34+
query_timeout_seconds: float | None = None,
3435
max_deliveries: int | None = None,
3536
terminal_flush_batch_size: int = 1,
3637
ack_policy: AckPolicy | None = None,
@@ -51,6 +52,7 @@ def __init__( # noqa: PLR0913
5152
min_fetch_interval=min_fetch_interval,
5253
max_fetch_interval=max_fetch_interval,
5354
lease_ttl_seconds=lease_ttl_seconds,
55+
query_timeout_seconds=query_timeout_seconds,
5456
max_deliveries=max_deliveries,
5557
terminal_flush_batch_size=terminal_flush_batch_size,
5658
ack_policy=ack_policy,

‎faststream_outbox/subscriber/config.py‎

Lines changed: 23 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -74,6 +74,7 @@ class OutboxSubscriberConfig(SubscriberUsecaseConfig):
7474
min_fetch_interval: float
7575
max_fetch_interval: float
7676
lease_ttl_seconds: float
77+
query_timeout_seconds: float | None = None
7778
max_deliveries: int | None
7879
terminal_flush_batch_size: int
7980
propagate_inbound_headers: bool
@@ -127,6 +128,7 @@ def _validate(self) -> None: # noqa: C901 # flat sequence of independent knob
127128
if self.lease_ttl_seconds <= 0:
128129
msg = f"lease_ttl_seconds must be > 0, got {self.lease_ttl_seconds}"
129130
raise ValueError(msg)
131+
self._validate_query_timeout()
130132
if self.min_fetch_interval > self.max_fetch_interval:
131133
msg = (
132134
f"min_fetch_interval ({self.min_fetch_interval}) must be <= max_fetch_interval "
@@ -169,6 +171,20 @@ def _validate(self) -> None: # noqa: C901 # flat sequence of independent knob
169171
f"2 * max_fetch_interval + P99(handler).",
170172
)
171173

174+
def _validate_query_timeout(self) -> None:
175+
if self.query_timeout_seconds is None:
176+
return
177+
if self.query_timeout_seconds <= 0:
178+
msg = f"query_timeout_seconds must be > 0, got {self.query_timeout_seconds}"
179+
raise ValueError(msg)
180+
if self.query_timeout_seconds > self.lease_ttl_seconds:
181+
msg = (
182+
f"query_timeout_seconds ({self.query_timeout_seconds}) must be <= lease_ttl_seconds "
183+
f"({self.lease_ttl_seconds}): a fetch or terminal write still running past the lease "
184+
f"has already lost the row to reclaim."
185+
)
186+
raise ValueError(msg)
187+
172188
def _validate_numbers(self) -> None:
173189
"""Reject bools passed as counts, NaN or infinite intervals, and a ``max_deliveries`` below 1."""
174190
for name in ("max_workers", "fetch_batch_size", "terminal_flush_batch_size", "max_deliveries"):
@@ -178,14 +194,19 @@ def _validate_numbers(self) -> None:
178194
if isinstance(value, bool) or not isinstance(value, int):
179195
msg = f"{name} must be an int, got {value!r}"
180196
raise TypeError(msg)
181-
for name in ("min_fetch_interval", "max_fetch_interval", "lease_ttl_seconds"):
182-
if not math.isfinite(getattr(self, name)):
197+
for name in ("min_fetch_interval", "max_fetch_interval", "lease_ttl_seconds", "query_timeout_seconds"):
198+
if getattr(self, name) is not None and not math.isfinite(getattr(self, name)):
183199
msg = f"{name} must be a finite number, got {getattr(self, name)}"
184200
raise ValueError(msg)
185201
if self.max_deliveries is not None and self.max_deliveries < 1:
186202
msg = f"max_deliveries must be >= 1 or None (unlimited), got {self.max_deliveries}"
187203
raise ValueError(msg)
188204

205+
@property
206+
def query_timeout(self) -> float:
207+
"""Client-side cap on each fetch and terminal write; ``lease_ttl_seconds`` unless set."""
208+
return self.lease_ttl_seconds if self.query_timeout_seconds is None else self.query_timeout_seconds
209+
189210
@property
190211
def ack_policy(self) -> AckPolicy:
191212
if self._ack_policy is EMPTY:

‎faststream_outbox/subscriber/factory.py‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -13,7 +13,7 @@
1313
from faststream_outbox.retry import RetryStrategyProto
1414

1515

16-
def create_subscriber(
16+
def create_subscriber( # noqa: PLR0913
1717
*,
1818
queues: list[str],
1919
max_workers: int,
@@ -25,6 +25,7 @@ def create_subscriber(
2525
max_deliveries: int | None,
2626
terminal_flush_batch_size: int,
2727
config: "OutboxBrokerConfig",
28+
query_timeout_seconds: float | None = None,
2829
ack_policy: AckPolicy | None = None,
2930
propagate_inbound_headers: bool = False,
3031
title_: str | None = None,
@@ -43,6 +44,7 @@ def create_subscriber(
4344
min_fetch_interval=min_fetch_interval,
4445
max_fetch_interval=max_fetch_interval,
4546
lease_ttl_seconds=lease_ttl_seconds,
47+
query_timeout_seconds=query_timeout_seconds,
4648
max_deliveries=max_deliveries,
4749
terminal_flush_batch_size=terminal_flush_batch_size,
4850
propagate_inbound_headers=propagate_inbound_headers,

‎faststream_outbox/subscriber/usecase.py‎

Lines changed: 36 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -103,6 +103,8 @@ class _PendingFlush:
103103
# the kernel keepalive; cap it and fall back to an immediate terminate.
104104
_LISTEN_CLOSE_TIMEOUT = 5.0
105105

106+
_T = typing.TypeVar("_T")
107+
106108

107109
def _compute_backoff(attempt: int, ceiling: float, *, base: float = 1.0) -> float:
108110
"""Exponential backoff with ±50% jitter, capped at *ceiling*.
@@ -427,11 +429,14 @@ async def _fetch_inner(
427429
# fetch_conn is None only in the test-broker path against FakeOutboxClient
428430
# (which ignores conn); the real OutboxClient raises if conn is None. The
429431
# AbstractOutboxClient surface admits None so both implementations type-check.
430-
rows = await self._client.fetch(
432+
rows = await self._bounded(
431433
fetch_conn,
432-
self._queues,
433-
limit=free,
434-
lease_ttl_seconds=self._config.lease_ttl_seconds,
434+
self._client.fetch(
435+
fetch_conn,
436+
self._queues,
437+
limit=free,
438+
lease_ttl_seconds=self._config.lease_ttl_seconds,
439+
),
435440
)
436441
for row in rows:
437442
self._inflight.put_nowait(row)
@@ -528,6 +533,20 @@ def _on_notify(self, *args: object) -> None:
528533
if payload is None or payload in self._served_queues:
529534
self._notify_event.set()
530535

536+
async def _bounded(self, conn: "AsyncConnection | None", statement: Awaitable[_T]) -> _T:
537+
"""Cap a fetch/terminal write at ``query_timeout`` so a silently dropped socket raises.
538+
539+
On timeout the connection is invalidated (closed without a round-trip on the dead
540+
socket) and the error propagates, so the outer loop reconnects.
541+
"""
542+
try:
543+
async with asyncio.timeout(self._config.query_timeout):
544+
return await statement
545+
except TimeoutError:
546+
if conn is not None:
547+
await conn.invalidate()
548+
raise
549+
531550
async def _worker_loop(self) -> None:
532551
"""Thin wrapper around :meth:`_run_with_reconnect` for the worker path."""
533552
await self._run_with_reconnect(
@@ -862,7 +881,7 @@ async def _flush_buffer(
862881
return
863882
pairs = [(p.row.id, p.row.acquired_token) for p in buffer if p.row.acquired_token is not None]
864883
try:
865-
deleted = await self._client.delete_batch_with_lease(writer_conn, pairs)
884+
deleted = await self._bounded(writer_conn, self._client.delete_batch_with_lease(writer_conn, pairs))
866885
except BaseException: # incl. CancelledError from the exit-flush timeout: balance task_done before re-raising
867886
for pending in buffer:
868887
self._emit_dispatch_abandoned(pending.row)
@@ -944,11 +963,9 @@ async def _flush_terminal(
944963
self._outer_config.last_exception_renderer,
945964
),
946965
}
947-
deleted = await self._client.delete_with_lease(
966+
deleted = await self._bounded(
948967
writer_conn,
949-
row.id,
950-
row.acquired_token,
951-
dlq_payload=dlq_payload,
968+
self._client.delete_with_lease(writer_conn, row.id, row.acquired_token, dlq_payload=dlq_payload),
952969
)
953970
if not deleted:
954971
self._emit_lease_lost(row, phase="terminal")
@@ -977,14 +994,17 @@ async def _flush_retry(
977994
# P19: first_attempt_at / last_attempt_at are the worker's clock; next_attempt_at
978995
# is computed server-side (now() + delay) inside mark_pending_with_lease, so the
979996
# reschedule time stays clock-skew-immune even though these audit timestamps don't.
980-
updated = await self._client.mark_pending_with_lease(
997+
updated = await self._bounded(
981998
writer_conn,
982-
row.id,
983-
row.acquired_token,
984-
delay_seconds=row.pending_delay_seconds,
985-
attempts_count=row.attempts_count,
986-
first_attempt_at=row.first_attempt_at, # ty: ignore[invalid-argument-type]
987-
last_attempt_at=row.last_attempt_at, # ty: ignore[invalid-argument-type]
999+
self._client.mark_pending_with_lease(
1000+
writer_conn,
1001+
row.id,
1002+
row.acquired_token,
1003+
delay_seconds=row.pending_delay_seconds,
1004+
attempts_count=row.attempts_count,
1005+
first_attempt_at=row.first_attempt_at, # ty: ignore[invalid-argument-type]
1006+
last_attempt_at=row.last_attempt_at, # ty: ignore[invalid-argument-type]
1007+
),
9881008
)
9891009
if not updated:
9901010
self._emit_lease_lost(row, phase="retry")

0 commit comments

Comments
 (0)