diff --git a/CHANGELOG.md b/CHANGELOG.md index 2395a72..7ab36cc 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -7,6 +7,57 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 ## [Unreleased] +### Added + +- Bounded unpaused-stream liveness detection (`receive_timeout`, default 60s), + reply-requested idle probes, generation-fenced timers and value-free health / + receive-timeout telemetry. Silent half-open connections now enter the existing + durable-checkpoint reconnect path. Intentional pauses and exported snapshots + are excluded; missing/invalidated slot recovery still fails closed. + + +### Changed + +- `max_inflight_lag` now bounds queued payload bytes and separately retained + transaction/batch payload, rather than WAL-position distance. The historical + option name and 64 MiB default remain. Queue intake also pauses at 512 messages + and resumes below half of both thresholds. This is not a process-memory cap. +- Slow sinks pause instead of halting with `:sink_too_slow`. Migrate alerts to + `[:replicant, :connection, :stalled]` plus slot-retention alerts. Queued frames + with no completed assembler frame for five seconds emit telemetry and a warning, + paused or not, repeating every five seconds without progress. `duration` is time + since the last completion (or initial enqueue), in milliseconds. This replaces + the draft `:pause_ongoing` event. Slow but progressing sinks still require monitoring. + Monitor + PostgreSQL slot WAL retention and disk space separately: feedback keeps the + slot alive but never acknowledges undelivered data. There is no automatic + pause deadline; configure a server-side WAL retention limit for disk protection. +- Retained payload exhaustion halts with `:buffer_limit_exceeded`. With spill + enabled, non-streamed transactions retain the compatibility ceiling of + `max_inflight_lag + max_spill_bytes`; they use memory, not spill files. Configure + this allowance deliberately, since PostgreSQL can send transactions smaller + than `logical_decoding_work_mem` without streaming even with protocol v2 enabled. + +### Fixed + +- Drain old assembler work before reconnect replay, preventing queue multiplication + and spill-file cleanup races when a sink is blocked. +- Track retained batch bytes incrementally, release aborted subtransaction row-payload + accounting, and spill reclaimable row buffers until within budget. +- Streamed messages carry pgoutput's top-level xid even inside a savepoint; do + not claim to discard sub-aborted messages using that field. Their resident bytes + remain charged. Savepoint-message delivery semantics require separate work. +- Do not re-track an already received transaction on a buffer-triggered batch flush. +- Idle open transactions no longer indefinitely block snapshot windows. +- Pace replication intake using queued payload bytes and message counts, rather + than WAL-position distance. Pause without releasing slot ownership, continue + durable-only feedback, and reject stale drain credits after reconnects. +- Pace incremental snapshot windows using queued stream work. WAL archive + segment gaps no longer halt streaming or indefinitely defer snapshot reads. +- Fail closed on actual buffer/spill exhaustion without confusing a slow sink + with a large WAL-position gap. Streamed message bytes remain charged after + changes are spilled. + ## [1.5.1] - 2026-10-10 ### Fixed diff --git a/README.md b/README.md index bf50731..b2738ec 100644 --- a/README.md +++ b/README.md @@ -260,6 +260,16 @@ detected at the next change or within `schema_check_interval` (default 30 s). ## Configuration reference +**Backpressure.** `max_inflight_lag` retains its historical name but now limits +queued and retained payload bytes rather than WAL-position distance. Replication +input pauses while the sink drains and resumes without disconnecting. This is a +payload budget, not an exact process-memory limit. With spill enabled, non-streamed +transactions retain a memory allowance of `max_inflight_lag + max_spill_bytes`; +they cannot use the stream spill reader. Tune this alongside PostgreSQL's +`logical_decoding_work_mem`, since enabling streaming does not force every +transaction to stream. Incremental snapshots yield to queued WAL, not idle open +transactions. Reconnects wait for the previous assembler queue before replay. + All options go to `Replicant.start_link/1`; `Replicant.Config` validates them. | Option | Default | Purpose | @@ -274,7 +284,8 @@ All options go to `Replicant.start_link/1`; `Replicant.Config` validates them. | `checkpoint_store:` | off | `[connection:, table:, progress_table:, max_retries: 5, retry_backoff_ms: 1000, batch: [...]]`: library-owned checkpoint for non-transactional sinks | | `batch_delivery:` | off | `[max_transactions: 100, max_delay_ms: 1000]`: atomic batches through `handle_batch/1` | | `streaming:` | off | `[max_concurrent_txns: 64, spill: [dir:, max_spill_bytes:]]`: in-progress streaming and disk spill | -| `max_inflight_lag:` | 64 MiB | WAL the connection may run ahead of the durable checkpoint before halting `:sink_too_slow` | +| `max_inflight_lag:` | 64 MiB | Queued payload budget for pause/resume and a separate retained transaction/batch budget; oversized unspillable transactions halt `:buffer_limit_exceeded` | +| `receive_timeout:` | `60_000` ms | Unpaused stream receive-silence limit; probes every half-timeout, reconnects after silence reaches the limit (up to one probe interval later). `:infinity` disables it. | | `max_command_retries:` | `5` | connect cycles a pre-stream replication command may fail before the pipeline halts instead of reconnecting forever | | `messages:` | `false` | deliver `pg_logical_emit_message` payloads; the sink must implement `handle_message/2` | | `failover:` | `false` | create a `FAILOVER` slot on PostgreSQL 17+ | @@ -296,8 +307,26 @@ rejections are in [`usage-rules.md`](usage-rules.md). Two to alert on: - `[:replicant, :pipeline, :halted]` with the structural `reason` atom, on every fail-closed halt; -- `[:replicant, :connection, :disconnected]` with `reason: :sink_too_slow` and a signed - `lag` measurement, when the sink falls behind the in-flight window. +- `[:replicant, :buffer, :exhausted]` with `reason: :buffer_limit_exceeded`, when + retained transaction data cannot fit within the configured budget. + +`[:replicant, :connection, :paused]` and `:resumed` report normal backpressure, with +queued payload bytes and message counts. Paused connections send durable feedback +every five seconds; configure `wal_sender_timeout` comfortably above that interval. +`[:replicant, :connection, :stalled]` and a warning log fire after five seconds +with queued frames but no completed assembler frame, then repeat every five seconds +without progress. This includes quiet publications below the pause thresholds and +queues waiting across reconnects. Measurements are queued `byte_size`, `change_count` +(frames), and `duration` (milliseconds since the last completion, or initial enqueue). +The log remains visible without a telemetry handler; neither signal contains row or +message payloads. Completion resets the stall clock; draining cancels the timer. + +Replace `:sink_too_slow` alerts with stall alerts **and** PostgreSQL slot-retention / +primary-disk monitoring. A slow sink that keeps completing frames, including short +pause/resume cycles, does not trigger a stall alert but can still accumulate WAL. +Configure `max_slot_wal_keep_size` for a server-side retention bound. A +retention-limit invalidation requires rebuilding the consumer; disconnecting alone +does not release retained WAL. ## Documentation @@ -329,3 +358,23 @@ The `pgoutput` byte parser, OID type database, type caster and array parser deri chain (cainophile, Supabase Realtime, epgsql). MIT. See [LICENSE](LICENSE). + +### Silent replication connections + +The receive watchdog requests an immediate PostgreSQL keepalive using the standard +standby-status reply bit, including when the publication is idle or the server's +`wal_sender_timeout` is disabled. Probes acknowledge only the durable checkpoint. +`receive_timeout` applies to streaming (including concurrent incremental backfill), +not the connect/query chain or an exported snapshot. Intentional socket pauses and +assembler draining are excluded; resuming starts a fresh receive grace period. +The assembler-stall event monitors sink progress independently of receive silence. + +`[:replicant, :connection, :health]` reports receive age in milliseconds as +`duration`, with `slot_name`. `[:replicant, :connection, :receive_timeout]` reports +the same age and `reason: :receive_timeout` before disconnect. No payload values +are emitted. Timer tokens fence reconnects and pause/resume races. + +A timeout uses Postgrex's existing disconnect path and command retry budget; +`max_command_retries: 0` hands recovery to the supervising application immediately. +Reconnect reads the durable checkpoint and retains all slot/source identity and +lost-slot guards. It never resets a checkpoint or recreates a lost mirror. diff --git a/docs/adr/0005-spill-is-ephemeral-scratch.md b/docs/adr/0005-spill-is-ephemeral-scratch.md index 69c6793..dfefd36 100644 --- a/docs/adr/0005-spill-is-ephemeral-scratch.md +++ b/docs/adr/0005-spill-is-ephemeral-scratch.md @@ -23,11 +23,16 @@ of the transaction. Two design questions follow: reconnect. There is **no fsync** — spill is not a WAL; a crash re-streams the transaction from the durable `confirmed_flush` LSN (the spill is discarded, never replayed). (`lib/replicant/spill.ex`, `lib/replicant/spill/reader.ex`.) -- **Two ceilings**, not one: resident RAM is bounded by `max_inflight_lag` (the spill trigger), - and disk is bounded by `max_spill_bytes` (a transaction exceeding it halts `:spill_exhausted`). - The §4 in-flight numerator is `received − floor − spilled` compared to `max_inflight_lag + - max_spill_bytes`, so a legitimately-spilling transaction is not double-counted toward the RAM - halt. +- **Independent queue, resident, and disk budgets.** Socket intake pauses on actual + queued payload bytes at `max_inflight_lag` (or 512 frames); completed assembler + frames release credits. WAL-position distance is not used as a memory estimate. + Streamed resident payload spills reclaimable row buffers above `max_inflight_lag`; + messages remain in memory and charged. Spill repeats until the budget is met or + no row payload can be reclaimed. `max_spill_bytes` separately limits spill files + (exceeding it halts `:spill_exhausted`). With spill configured, non-streamed + transactions retain a `max_inflight_lag + max_spill_bytes` **memory** allowance + for compatibility, since they cannot use the streamed spill path. None of these + budgets is an exact RSS limit: decoded-term overhead and socket buffers are extra. - **No in-lib encryption.** Key management is a separable subsystem with its own operational surface (KMS, rotation, envelope keys) that this library does not own. The operator places the spill `dir` on a secure/encrypted volume and cleans it on decommission; the default `dir` is a diff --git a/examples/replication_pipeline/mix.exs b/examples/replication_pipeline/mix.exs index 42a580d..47418b4 100644 --- a/examples/replication_pipeline/mix.exs +++ b/examples/replication_pipeline/mix.exs @@ -26,8 +26,9 @@ defmodule ReplicationPipeline.MixProject do [ # The CDC engine, from THIS checkout (the example is part of its repo). {:replicant, path: "../.."}, - # Destination client (mirrors the library's own floor). - {:postgrex, "~> 0.22.4"}, + # Match the CDC engine's pause/resume-capable transport pin. + {:postgrex, + github: "elixir-ecto/postgrex", ref: "a209c8b96c5d92cfff9a35df8ed31ed123943bc2"}, # Static gates (same tooling as the library itself; dev/test only). {:credo, "~> 1.7", only: [:dev, :test], runtime: false}, {:dialyxir, "~> 1.4", only: [:dev, :test], runtime: false} diff --git a/examples/replication_pipeline/mix.lock b/examples/replication_pipeline/mix.lock index 31ddabd..a473004 100644 --- a/examples/replication_pipeline/mix.lock +++ b/examples/replication_pipeline/mix.lock @@ -7,6 +7,6 @@ "erlex": {:hex, :erlex, "0.2.9", "7debbbaa9f4f368b8cd648983e0f1d7963028508e9c59e9d4ed504e94ef52a55", [:mix], [], "hexpm", "8cfffc0ec7159e6d73de2ab28a588064de80f88b2798d5cbe4482cbbc200178b"}, "file_system": {:hex, :file_system, "1.1.1", "31864f4685b0148f25bd3fbef2b1228457c0c89024ad67f7a81a3ffbc0bbad3a", [:mix], [], "hexpm", "7a15ff97dfe526aeefb090a7a9d3d03aa907e100e262a0f8f7746b78f8f87a5d"}, "jason": {:hex, :jason, "1.4.5", "2e3a008590b0b8d7388c20293e9dcc9cf3e5d642fd2a114e4cbbb52e595d940a", [:mix], [{:decimal, "~> 1.0 or ~> 2.0 or ~> 3.0", [hex: :decimal, repo: "hexpm", optional: true]}], "hexpm", "b0c823996102bcd0239b3c2444eb00409b72f6a140c1950bc8b457d836b30684"}, - "postgrex": {:hex, :postgrex, "0.22.4", "d271f595dfd25230b6398354e19d17bb5e2d20130fd2d9bdca7e15f125d43552", [:mix], [{:db_connection, "~> 2.9", [hex: :db_connection, repo: "hexpm", optional: false]}, {:decimal, "~> 1.5 or ~> 2.0 or ~> 3.0", [hex: :decimal, repo: "hexpm", optional: false]}, {:jason, "~> 1.0", [hex: :jason, repo: "hexpm", optional: true]}, {:table, "~> 0.1.0", [hex: :table, repo: "hexpm", optional: true]}], "hexpm", "4aae45a2d60e35b04eea2602440be152fae332901f1fc7a60fc7cb7f0f9a9c5a"}, + "postgrex": {:git, "https://github.com/elixir-ecto/postgrex.git", "a209c8b96c5d92cfff9a35df8ed31ed123943bc2", [ref: "a209c8b96c5d92cfff9a35df8ed31ed123943bc2"]}, "telemetry": {:hex, :telemetry, "1.4.2", "a0cb522801dffb1c49fe6e30561badffc7b6d0e180db1300df759faa22062855", [:rebar3], [], "hexpm", "928f6495066506077862c0d1646609eed891a4326bee3126ba54b60af61febb1"}, } diff --git a/lib/replicant/assembler.ex b/lib/replicant/assembler.ex index d4b990f..aee9c81 100644 --- a/lib/replicant/assembler.ex +++ b/lib/replicant/assembler.ex @@ -86,6 +86,7 @@ defmodule Replicant.Assembler do batch: keyword() | nil, batch_count: non_neg_integer(), batch_txns: [Transaction.t()], + batch_bytes: non_neg_integer(), batch_spill_paths: [String.t()], last_buffered_changes: [Change.t()] | :spilled, pending_lsn: lsn() | nil, @@ -112,6 +113,8 @@ defmodule Replicant.Assembler do messages: [Message.t()], byte_size: non_neg_integer(), resident_bytes: non_neg_integer(), + change_bytes: %{non_neg_integer() => non_neg_integer()}, + message_bytes: %{non_neg_integer() => non_neg_integer()}, spilled_bytes: non_neg_integer(), spilled_by_subxid: %{non_neg_integer() => non_neg_integer()}, aborted: MapSet.t(non_neg_integer()), @@ -136,6 +139,7 @@ defmodule Replicant.Assembler do batch: nil, batch_count: 0, batch_txns: [], + batch_bytes: 0, batch_spill_paths: [], last_buffered_changes: [], pending_lsn: nil, @@ -176,10 +180,10 @@ defmodule Replicant.Assembler do end @doc """ - Accumulate the raw WAL payload byte-size of the message about to be handled into + Accumulate the raw WAL payload byte-size of the message just handled into the open transaction buffer, for the `byte_size` metadata on `[:replicant, :transaction, :assembled]` (spec §10). `Replicant.AssemblerServer` - calls this with `byte_size(payload)` before each `handle_message/2`. It is a + calls this with `byte_size(payload)` after each non-terminal `handle_message/2`. It is a no-op before any `Begin` (bytes arriving outside a transaction — a lone Relation/Type/Origin — have no buffer to attribute to), so a stray pre-Begin payload never crashes here. @@ -193,7 +197,7 @@ defmodule Replicant.Assembler do def observe_bytes(%__MODULE__{current_stream_xid: xid, stream_txns: streams} = asm, bytes) when is_integer(xid) and is_integer(bytes) and bytes >= 0 and is_map_key(streams, xid) do buf = Map.fetch!(streams, xid) - buf = %{buf | byte_size: buf.byte_size + bytes, resident_bytes: buf.resident_bytes + bytes} + buf = __MODULE__.Streaming.account_bytes(buf, xid, bytes) asm = %{asm | stream_txns: Map.put(streams, xid, buf)} case __MODULE__.Streaming.maybe_spill(asm) do @@ -209,6 +213,16 @@ defmodule Replicant.Assembler do %{asm | txn: %{buffer | byte_size: buffer.byte_size + bytes}} end + @doc false + def buffered_bytes(asm) do + transaction_bytes = if asm.txn, do: asm.txn.byte_size, else: 0 + + streamed_bytes = + Enum.reduce(asm.stream_txns, 0, fn {_xid, buf}, n -> n + buf.resident_bytes end) + + transaction_bytes + streamed_bytes + asm.batch_bytes + end + @doc """ Handle one decoded message. Returns: * `{:ok, t()}` — accumulated, no boundary crossed. @@ -1045,6 +1059,7 @@ defmodule Replicant.Assembler do | batch_count: 0, pending_lsn: nil, batch_txns: [], + batch_bytes: 0, batch_spill_paths: [], last_buffered_changes: [] } diff --git a/lib/replicant/assembler/batch.ex b/lib/replicant/assembler/batch.ex index 6a413c5..324e9ab 100644 --- a/lib/replicant/assembler/batch.ex +++ b/lib/replicant/assembler/batch.ex @@ -82,6 +82,7 @@ defmodule Replicant.Assembler.Batch do | batch_count: count, pending_lsn: lsn, batch_txns: [txn | asm.batch_txns], + batch_bytes: asm.batch_bytes + :erlang.external_size(txn), batch_spill_paths: prepend_path(asm.batch_spill_paths, spill_path) } @@ -157,6 +158,7 @@ defmodule Replicant.Assembler.Batch do | batch_count: 0, pending_lsn: nil, batch_txns: [], + batch_bytes: 0, batch_spill_paths: [], lib_checkpoint: max(asm.lib_checkpoint || 0, lsn) }} diff --git a/lib/replicant/assembler/streaming.ex b/lib/replicant/assembler/streaming.ex index 2336464..a27a8ee 100644 --- a/lib/replicant/assembler/streaming.ex +++ b/lib/replicant/assembler/streaming.ex @@ -13,6 +13,26 @@ defmodule Replicant.Assembler.Streaming do alias Messages.{Message, StreamAbort, StreamCommit, StreamStart, StreamStop} + # Wire bytes are charged once after appending. Separate row/message counters let + # spilling release only row payloads and aborts release exactly the discarded tail. + def account_bytes(buf, top, bytes) do + {subxid, kind} = latest_entry(buf, top) + counters = Map.update(Map.fetch!(buf, kind), subxid, bytes, &(&1 + bytes)) + + buf + |> Map.put(kind, counters) + |> Map.put(:byte_size, buf.byte_size + bytes) + |> Map.put(:resident_bytes, buf.resident_bytes + bytes) + end + + defp latest_entry(%{changes: [{sx, change} | _], messages: [msg | _]}, _top) do + if change.ordinal > msg.ordinal, do: {sx, :change_bytes}, else: {msg.xid, :message_bytes} + end + + defp latest_entry(%{changes: [{sx, _} | _]}, _top), do: {sx, :change_bytes} + defp latest_entry(%{messages: [msg | _]}, _top), do: {msg.xid, :message_bytes} + defp latest_entry(_buf, top), do: {top, :change_bytes} + # --- aggregate-resident spill (spec §5) --- # Aggregate-resident spill (spec §5): keep total in-memory reassembly ≈ max_inflight_lag. When the @@ -25,15 +45,34 @@ defmodule Replicant.Assembler.Streaming do resident_total = Enum.reduce(streams, 0, fn {_xid, b}, acc -> acc + b.resident_bytes end) cond do - resident_total <= (bound || 0) -> {:ok, asm} - map_size(streams) == 0 -> {:ok, asm} - true -> spill_largest(asm) + resident_total <= (bound || 0) -> + {:ok, asm} + + map_size(streams) == 0 -> + {:ok, asm} + + true -> + case spill_largest(asm) do + {:ok, ^asm} -> {:ok, asm} + {:ok, %{spill_fault: nil} = spilled} -> maybe_spill(spilled) + result -> result + end end end def spill_largest(%Assembler{stream_txns: streams} = asm) do - {top, buf} = Enum.max_by(streams, fn {_xid, b} -> b.resident_bytes end) + candidate = + streams + |> Enum.reject(fn {_xid, buf} -> buf.changes == [] end) + |> Enum.max_by(fn {_xid, buf} -> Enum.sum(Map.values(buf.change_bytes)) end, fn -> nil end) + + case candidate do + nil -> {:ok, asm} + {top, buf} -> spill_buffer(asm, top, buf) + end + end + defp spill_buffer(%Assembler{stream_txns: streams} = asm, top, buf) do case flush_buffer_tail(asm, top, buf) do {:ok, spill_handle, wrote} -> # Per-subxid frame counts of the flushed tail — so a spilled txn that later filters to EMPTY @@ -47,7 +86,8 @@ defmodule Replicant.Assembler.Streaming do buf = %{ buf | changes: [], - resident_bytes: 0, + resident_bytes: Enum.sum(Map.values(buf.message_bytes)), + change_bytes: %{}, spilled_bytes: buf.spilled_bytes + wrote, spilled_by_subxid: by_subxid, spill: spill_handle @@ -58,9 +98,8 @@ defmodule Replicant.Assembler.Streaming do Telemetry.event([:replicant, :stream, :spilled], %{}, %{byte_size: wrote, change_count: 0}) - # Disk ceiling (spec §8): the frame is already on disk; record the breach on `spill_fault` — - # the next StreamCommit halts on it (do_handle_message's spill_fault clause matches - # `%StreamCommit{}` only; the halt is DEFERRED to a commit boundary). Do NOT deliver past it. + # The server checks this fault immediately after observation, without + # waiting for a Commit that an oversized transaction may never send. if spilled_total > Keyword.fetch!(asm.spill, :max_spill_bytes) do # Surface the disk-ceiling breach as the advertised value-free event (spec §11): byte_size is # a count, reason is allowlisted (no telemetry.ex change). Lets operators observe exhaustion @@ -139,12 +178,13 @@ defmodule Replicant.Assembler.Streaming do spilled_total: asm.spilled_total - buf.spilled_bytes } - # Transactional messages tagged to an aborted subxid are dropped (mirrors the change-reject - # above); the surviving ones must RIDE the txn even when it carries zero row-changes — the v1 + # pgoutput tags streamed messages with the top-level xid, even inside a savepoint. + # We cannot identify sub-aborted messages from that field. Messages still ride a + # transaction even when it carries zero row-changes — the v1 # path (Begin→Message→Commit) delivers exactly that (effect-once, spec §7.1). A message-bearing # txn is therefore v1-DISTINGUISHABLE and must NOT be empty-suppressed, or the message is # silently lost (regression: the suppression keyed on row-changes alone). - live_messages = Enum.reject(buf.messages, &(&1.xid in buf.aborted)) + live_messages = buf.messages cond do resident == [] and spilled_live == 0 and live_messages == [] -> @@ -192,7 +232,7 @@ defmodule Replicant.Assembler.Streaming do # deliver via the shared apply_sink path, threading the spill PATH so cleanup happens after durable # delivery (per-txn / lib+batch delete the file; sink-owned batch keeps it until flush, Task 8). def deliver_spilled_stream_commit(%Assembler{} = asm, lsn, ts, buf, reader) do - buf_messages = Enum.reject(buf.messages, &(&1.xid in buf.aborted)) + buf_messages = buf.messages txn = %Transaction{ commit_lsn: lsn, @@ -305,6 +345,8 @@ defmodule Replicant.Assembler.Streaming do messages: [], byte_size: 0, resident_bytes: 0, + change_bytes: %{}, + message_bytes: %{}, spilled_bytes: 0, spilled_by_subxid: %{}, aborted: MapSet.new(), @@ -367,7 +409,17 @@ defmodule Replicant.Assembler.Streaming do # append-only file, so record `sub` in the aborted set — replay skips any spilled frame # tagged `sub` (spec §5). kept = Enum.reject(buf.changes, fn {subxid, _change} -> subxid == sub end) - buf = %{buf | changes: kept, aborted: MapSet.put(buf.aborted, sub)} + changes = Map.delete(buf.change_bytes, sub) + + buf = %{ + buf + | changes: kept, + change_bytes: changes, + resident_bytes: + Enum.sum(Map.values(changes)) + Enum.sum(Map.values(buf.message_bytes)), + aborted: MapSet.put(buf.aborted, sub) + } + {:ok, %{asm | stream_txns: Map.put(asm.stream_txns, top, buf)}} {:error, _} -> diff --git a/lib/replicant/assembler_server.ex b/lib/replicant/assembler_server.ex index f91126b..d27124c 100644 --- a/lib/replicant/assembler_server.ex +++ b/lib/replicant/assembler_server.ex @@ -29,8 +29,7 @@ defmodule Replicant.AssemblerServer do @doc """ Open the drop-set tracking window for a table BEFORE the reader captures LW - (spec §2 R1). The reply is DEFERRED while the assembler-local in-flight estimate - (frontier − last applied LSN) exceeds max_inflight_lag ÷ 2 — the pacing gate + (spec §2 R1). The reply is DEFERRED while queued WAL work remains — the pacing gate (spec §4 R2): stream drain gets priority, chunks fill idle capacity. Replies `{:ok, epoch}` — the window GENERATION the reader now operates under. The @@ -110,6 +109,7 @@ defmodule Replicant.AssemblerServer do asm: asm, halted: false, conn_pid: nil, + flow_queue: nil, batch_timer: nil, window: snapshot_window, floor_lsn: 0, @@ -221,9 +221,31 @@ defmodule Replicant.AssemblerServer do end end + @impl true + def handle_cast({:flow_queue, queue}, state), do: {:noreply, %{state | flow_queue: queue}} + + def handle_cast({:drain_before_reconnect, from, token}, state) do + unless state.halted, do: send(from, {:assembler_drained, token}) + {:noreply, state} + end + + def handle_cast( + {:message, message, bytes, from, {epoch, total_bytes, total_messages, queue}}, + state + ) do + {:noreply, state} = + handle_cast({:message, message, bytes, from}, %{state | flow_queue: queue}) + + :atomics.sub(queue, 1, 1) + + unless state.halted, + do: send(from, {:assembler_processed, epoch, total_bytes, total_messages}) + + {:noreply, if(state.halted, do: state, else: release_capacity(state))} + end + # Post-halt: drop WAL. The pipeline teardown (Supervisor.halt) is in flight and # will terminate this process; reprocessing here would be wasted and unsafe. - @impl true def handle_cast({:message, _message, _bytes, _from}, %{halted: true} = state) do {:noreply, state} end @@ -231,25 +253,11 @@ defmodule Replicant.AssemblerServer do def handle_cast({:message, message, bytes, from}, state) do state = %{state | conn_pid: from} - # Append the change (handle_message) BEFORE accounting its WAL bytes + running the spill trigger - # (observe_bytes → maybe_spill): a change that crosses the RAM bound must be in the buffer when - # maybe_spill flushes, else it stays resident + unaccounted and a single row > max_inflight_lag - # never spills (CV2). Only a non-terminal {:ok, asm} carries a live buffer to account. - # - # Then signal the Connection its NET spilled total (up on a fresh spill, DOWN when a spilled txn - # commits/aborts and frees disk) so the §4 in-flight-lag numerator can subtract spilled bytes - # (spec §5 — they are on disk, not RAM, so a legitimately-spilling txn does not trip the halt). - # Casting the NET post-dispatch total (not the observe delta) keeps the numerator from stranding - # stale-high after a large spilled txn commits. A plain send → the Connection's handle_info, - # matching the {:sink_committed, _} dispatch idiom. - before = state.asm.spilled_total + # Account after appending so a threshold-crossing change is included in any spill. + # Processing credits are returned only after synchronous sink work completes. result = account_after_handle(Assembler.handle_message(state.asm, message), bytes) - {:noreply, new_state} = disp = dispatch(result, from, state) - - if new_state.asm.spilled_total != before, - do: send(from, {:spilled_bytes, new_state.asm.spilled_total}) - - disp + {:noreply, state} = dispatch(result, from, state) + {:noreply, if(state.halted, do: state, else: release_capacity(state))} end # The Connection seeds the lib-mode watermark from its connect-time store read, before streaming. @@ -436,9 +444,39 @@ defmodule Replicant.AssemblerServer do # Account WAL bytes + run the spill trigger AFTER the change is appended (CV2). Only a non-terminal # {:ok, asm} carries a resident buffer worth accounting; every terminal result already delivered or # deleted its buffer, so its trivial frame bytes are skipped. - defp account_after_handle({:ok, asm}, bytes), do: {:ok, Assembler.observe_bytes(asm, bytes)} + defp account_after_handle({:ok, asm}, bytes) do + asm = Assembler.observe_bytes(asm, bytes) + check_buffer({:ok, asm}, asm) + end + + defp account_after_handle({:buffered, _asm} = result, _bytes), do: result defp account_after_handle(result, _bytes), do: result + defp check_buffer(result, asm) do + limit = asm.max_inflight_lag || Replicant.Connection.default_max_inflight_lag() + + cond do + asm.spill_fault != nil -> {:halt, asm.spill_fault, asm} + within_buffer_limit?(asm, limit) -> result + asm.batch_txns != [] -> {:flush_buffer, asm} + true -> {:halt, %Replicant.Error{reason: :buffer_limit_exceeded}, asm} + end + end + + # Non-streamed transactions cannot use the stream spill reader. Preserve the + # historical spill-enabled allowance for them, while independently bounding + # the remaining streamed/batched payload. This allowance is resident memory. + defp within_buffer_limit?(%{txn: %{byte_size: bytes}, spill: spill} = asm, limit) + when is_list(spill) do + retained = Assembler.buffered_bytes(asm) + retained - bytes <= limit and retained <= limit + Keyword.fetch!(spill, :max_spill_bytes) + end + + defp within_buffer_limit?(asm, limit), do: Assembler.buffered_bytes(asm) <= limit + + defp dispatch({:flush_buffer, asm}, _from, state), + do: do_flush(%{state | asm: asm}, :max_buffer_bytes) + defp dispatch({:ok, asm}, _from, state), do: {:noreply, %{state | asm: asm}} defp dispatch({:transaction, txn, lsn, asm}, from, state) do @@ -519,7 +557,11 @@ defmodule Replicant.AssemblerServer do # Track the just-buffered txn's PKs at RECEIPT (convergence-safe) so a colliding snapshot # chunk row is dropped — a no-op when incremental is off. state = track_window(%{state | asm: asm}, buffered_changes(asm), buffered_lsn(asm)) - {:noreply, ensure_batch_timer(state)} + + case check_buffer({:ok, asm}, asm) do + {:ok, _} -> {:noreply, ensure_batch_timer(state)} + result -> dispatch(result, state.conn_pid, state) + end end defp dispatch({:flush, reason, asm}, _from, state) do @@ -540,12 +582,19 @@ defmodule Replicant.AssemblerServer do # `reason` is already value-free. Terminate the whole pipeline permanently; cancel the # flush timer and mark halted so a stale :batch_timeout cannot drive a store write during # teardown (spec §9). Do NOT self-crash (a crash exit would race :one_for_all restart). - Replicant.Supervisor.halt(state.slot_name, reason) + if match?(%Replicant.Error{reason: :buffer_limit_exceeded}, reason) do + Telemetry.event( + [:replicant, :buffer, :exhausted], + %{byte_size: Assembler.buffered_bytes(halted_asm)}, + %{slot_name: state.slot_name, reason: :buffer_limit_exceeded} + ) + end + # Discard any open spill files: a halt tears the pipeline down without a reset cast, so the # halted assembler's stream/batch spill files would leak on disk otherwise (spec §5 cleanup). - # The returned assembler is dropped — this process is terminating; we run the resets purely - # for the file-delete side effect. + # Clean up before scheduling teardown, which can otherwise terminate us mid-cleanup. _ = halted_asm |> Replicant.Assembler.reset_streams() |> Replicant.Assembler.reset_batch() + Replicant.Supervisor.halt(state.slot_name, reason) {:noreply, %{cancel_batch_timer(state) | halted: true}} end @@ -577,7 +626,8 @@ defmodule Replicant.AssemblerServer do case Assembler.flush_batch(state.asm, reason) do {:ok, lsn, asm} -> send(state.conn_pid, {:sink_committed, lsn}) - {:noreply, %{state | asm: asm}} + {:noreply, state} = dispatch(check_buffer({:ok, asm}, asm), state.conn_pid, state) + {:noreply, if(state.halted, do: state, else: release_capacity(state))} {:error, error, asm} -> Replicant.Supervisor.halt(state.slot_name, error) @@ -839,16 +889,8 @@ defmodule Replicant.AssemblerServer do defp release_deferred(%{deferred_drain: {from, _, _}}, reply), do: GenServer.reply(from, reply) defp release_deferred(_state, _reply), do: :ok - # The pacing gate (spec §4 R2): assembler-local in-flight estimate vs max_inflight_lag ÷ 2 — - # stream drain gets priority, chunks fill idle capacity. The in-flight base is - # `max(last_applied, floor_lsn)`, NOT last_applied alone: `frontier` is seeded from ABSOLUTE - # wal_end LSNs (large — e.g. 1e9), but `last_applied` is 0 until the first commit, so on a fresh - # slot / idle DB `frontier − 0` is astronomically larger than max_inflight_lag ÷ 2 and the window - # would be paced open indefinitely (backfill never starts). Before any commit, "applied" is the - # backfill's consistent-point floor (`floor_lsn`, from {:snapshot_floor}). Same fresh-slot - # large-absolute-LSN class the batching span-cap base fixed via max(lib_checkpoint, stream_floor). - defp paced?(%{window: %{frontier: f}, last_applied: a, floor_lsn: floor, asm: asm}) do - max_lag = asm.max_inflight_lag || Replicant.Connection.default_max_inflight_lag() - f - max(a, floor) > div(max_lag, 2) - end + # Give queued WAL priority. Retained open transactions cannot drain until the + # producer commits, so they must not indefinitely starve independent backfill. + defp paced?(%{flow_queue: nil}), do: false + defp paced?(%{flow_queue: queue}), do: :atomics.get(queue, 1) > 0 end diff --git a/lib/replicant/config.ex b/lib/replicant/config.ex index 9ab67f3..107f3d1 100644 --- a/lib/replicant/config.ex +++ b/lib/replicant/config.ex @@ -34,6 +34,7 @@ defmodule Replicant.Config do snapshot: boolean() | keyword(), max_inflight_lag: pos_integer(), max_command_retries: non_neg_integer(), + receive_timeout: pos_integer() | :infinity, checkpoint_store: keyword() | nil, failover: boolean(), messages: boolean(), @@ -76,6 +77,7 @@ defmodule Replicant.Config do {:ok, checkpoint_store} <- fetch_checkpoint_store(opts), {:ok, max_inflight_lag} <- fetch_max_inflight_lag(opts), {:ok, max_command_retries} <- fetch_max_command_retries(opts), + {:ok, receive_timeout} <- fetch_receive_timeout(opts), {:ok, batch_delivery} <- fetch_batch_delivery(opts, checkpoint_store, max_inflight_lag), {:ok, sink} <- fetch_sink(opts, checkpoint_store != nil, batch_delivery != nil), {:ok, messages} <- fetch_messages(opts, sink), @@ -100,6 +102,7 @@ defmodule Replicant.Config do snapshot: snapshot, max_inflight_lag: max_inflight_lag, max_command_retries: max_command_retries, + receive_timeout: receive_timeout, checkpoint_store: checkpoint_store, failover: failover, batch: batch, @@ -374,7 +377,15 @@ defmodule Replicant.Config do if supported?, do: :ok, else: {:error, :snapshot_unsupported} end - # The bounded in-flight window ceiling (WAL bytes, spec §4). Omitted → the + defp fetch_receive_timeout(opts) do + case Keyword.get(opts, :receive_timeout, 60_000) do + :infinity -> {:ok, :infinity} + timeout when is_integer(timeout) and timeout >= 2 -> {:ok, timeout} + _ -> {:error, :config_invalid} + end + end + + # The queued payload and retained-data budget (not WAL-position distance). Omitted → the # Connection default. A present value must be a positive integer; anything else is # a config error (never a silent fallback that would mask a mis-set bound). defp fetch_max_inflight_lag(opts) do diff --git a/lib/replicant/connection.ex b/lib/replicant/connection.ex index 76dca18..97c89fa 100644 --- a/lib/replicant/connection.ex +++ b/lib/replicant/connection.ex @@ -15,17 +15,12 @@ defmodule Replicant.Connection do * decodes each XLogData payload behind Plan 1's value-free boundary and forwards the decoded message to `Replicant.AssemblerServer` — it never applies the sink, so it is always free to answer keepalives; - * tracks a **bounded in-flight window** (spec §4): the high-water received LSN - (`received_lsn`, the latest XLogData `wal_end`) minus the confirmed-durable - floor is the in-flight WAL lag — un-drained WAL, a proxy for the transaction - BACKLOG accumulating ahead of the sink. A single non-blocking integer - comparison in `handle_data/2` compares it to `max_inflight_lag` (a - backlog-sized ceiling, default 64 MiB); - * when the in-flight lag exceeds the bound the sink is genuinely lagging: it - **halts fail-closed** with `{:sink_too_slow, lag}` (surfaced telemetry + - `Replicant.Supervisor.halt/2` + `{:disconnect, :sink_too_slow}`) — never a - silent reconnect livelock or an unbounded-mailbox OOM. On restart it resumes - from the checkpoint (loss=0 by the §6 idempotent dedup); + * counts payload bytes and messages sent to, but not yet processed by, the + assembler. WAL-position distance is not a queue-size estimate: unrelated + WAL and segment switches can advance positions without publication data; + * pauses socket delivery at `max_inflight_lag` payload bytes (default 64 MiB) + or 512 queued messages and resumes below both half-watermarks. Cumulative, + connection-scoped processing credits cannot advance the durable checkpoint; * advances the ack asynchronously on `{:sink_committed, L}` from the AssemblerServer; * on connect/reconnect detects an invalidated slot (`wal_status = 'lost'` or `conflicting` on PG16) and halts the pipeline fail-closed — never silently @@ -36,20 +31,23 @@ defmodule Replicant.Connection do `:invalidation_check` → (`:create_slot` if absent) → `:streaming`. - ## Why a fail-closed halt and not soft pacing (Postgrex flow-control) + ## Backpressure and retained transactions - `Postgrex.ReplicationConnection` re-arms the replication socket (`active: :once`) - **automatically** after each `handle_data/2` batch — the handler's return value has - no way to defer socket re-activation, so there is no lever to pause TCP reading - from the handler. `:max_messages` bounds only Postgrex's per-batch socket buffer, - not the downstream `AssemblerServer` mailbox. So true socket-level pacing is not - available; the bounded in-flight window is enforced by the fail-closed halt at the - ceiling — which bounds memory (the pipeline tears down before the mailbox grows - unbounded) and surfaces the overload rather than silently livelocking. + This implementation requires Postgrex's pause/resume callback extension. Pausing keeps + the connection and slot ownership alive. A five-second timer sends durable + feedback because incoming keepalives are also paused; configure the server's + `wal_sender_timeout` comfortably above that interval. + + The assembler separately budgets retained transaction/batch payloads, spilling + streamed transactions or flushing committed batches. An oversized transaction + that cannot spill halts with `:buffer_limit_exceeded`, not a pause that would + prevent its own Commit from arriving. Neither budget is an exact RSS cap: + decoded-term overhead, socket buffers, and a one-message overshoot are additional. """ use Postgrex.ReplicationConnection + require Logger - alias Replicant.{AssemblerServer, Decoder, QueryBuilder, Telemetry} + alias Replicant.{AssemblerServer, Decoder, FlowControl, QueryBuilder, Telemetry} alias Replicant.Decoder.Messages.{Begin, Commit, StreamAbort, StreamCommit, StreamStart} alias Replicant.Decoder.Messages.Relation alias Replicant.Decoder.Messages.Relation.Column @@ -61,21 +59,7 @@ defmodule Replicant.Connection do @pg_epoch DateTime.to_unix(~U[2000-01-01 00:00:00Z], :microsecond) - # Default in-flight-lag ceiling in WAL bytes (spec §4 bounded in-flight window) — - # the multi-transaction BACKLOG bound. `received_lsn` advances per XLogData frame - # while `checkpoint_lsn` only advances at a Commit boundary, so the in-flight lag - # transiently includes the WAL of the single transaction currently mid-stream. This - # ceiling (64 MiB) is therefore sized to sit comfortably above any single - # normal-but-large transaction (bulk insert/update, large/TOASTed rows) so it fires - # ONLY when the sink is genuinely lagging and a real backlog of un-drained - # transactions accumulates — never on one in-flight txn. Override per pipeline via - # `Replicant.Config`'s `:max_inflight_lag`. - # - # PROTO-V1 LIMITATION: a single transaction whose own buffered WAL exceeds the bound - # would still trip the halt mid-transaction (there is no Commit boundary to advance - # the checkpoint until the whole txn arrives). Unbounded single-transaction size is - # a future slice (proto-v2 streaming of in-progress transactions); for v1, size the - # bound above the largest expected single transaction. + # Legacy option name retained for compatibility; the unit is delivered payload bytes. @default_max_inflight_lag 67_108_864 # A6 command-error watchdog default budget — sourced DIRECTLY from the store retry family's @@ -94,6 +78,7 @@ defmodule Replicant.Connection do @type step :: :disconnected + | :draining_assembler | :identity_check | :recovery_check | :publication_check @@ -120,10 +105,7 @@ defmodule Replicant.Connection do received_lsn: Replicant.lsn(), stream_floor_lsn: Replicant.lsn() | nil, max_inflight_lag: pos_integer(), - # The spill accounting pair rides ONE map field (the 31-flat-field BEAM - # boundary the struct comment above documents): the assembler-reported - # spilled byte mirror and the configured disk ceiling. - spill: %{bytes: non_neg_integer(), max: non_neg_integer() | nil}, + flow: FlowControl.t(), checkpoint_store: keyword() | nil, batch_delivery: keyword() | nil, failover: boolean(), @@ -179,8 +161,8 @@ defmodule Replicant.Connection do checkpoint_lsn: 0, checkpoint_state: :empty, received_lsn: 0, + flow: %FlowControl{}, max_inflight_lag: @default_max_inflight_lag, - spill: %{bytes: 0, max: nil}, checkpoint_store: nil, batch_delivery: nil, failover: false, @@ -201,7 +183,7 @@ defmodule Replicant.Connection do decoder: @decoder_defaults ] - @doc "The default in-flight-lag ceiling (WAL bytes) when the config omits it." + @doc "The default queued/retained payload budget in bytes when the config omits it." @spec default_max_inflight_lag() :: pos_integer() def default_max_inflight_lag, do: @default_max_inflight_lag @@ -247,7 +229,7 @@ defmodule Replicant.Connection do received_lsn: 0, stream_floor_lsn: nil, max_inflight_lag: Map.get(config, :max_inflight_lag, @default_max_inflight_lag), - spill: %{bytes: 0, max: spill_ceiling(Map.get(config, :streaming))}, + flow: FlowControl.new(Map.get(config, :receive_timeout, 60_000)), checkpoint_store: Map.get(config, :checkpoint_store), batch_delivery: Map.get(config, :batch_delivery), failover: Map.get(config, :failover, false), @@ -287,7 +269,23 @@ defmodule Replicant.Connection do Replicant.CheckpointStore.retry_decision(faults - 1, max_retries) == :halt do halt_command_error(state) else + await_assembler(state) + end + end + + defp await_assembler(state) do + if FlowControl.queued_messages(state.flow) == 0 do handle_connect_proceed(state) + else + token = make_ref() + + GenServer.cast( + AssemblerServer.via(state.slot_name), + {:drain_before_reconnect, self(), token} + ) + + flow = %{state.flow | reconnect_barrier: token} + {:noreply, %{state | step: :draining_assembler, flow: flow}} end end @@ -380,6 +378,8 @@ defmodule Replicant.Connection do end defp begin_recovery(state) do + cancel_stall_timer(state.flow) + # Read the durable checkpoint (off the keepalive path — a blocking read is fine # here). In lib mode the store is the connect authority (a read FAULT halts # fail-closed in :invalidation_check — never fail-open, since a non-idempotent @@ -392,12 +392,7 @@ defmodule Replicant.Connection do # retry accumulates toward the bound. Delegated to a @doc false helper (unit-tested). store_retry_count = reset_retry_count(state.store_retry_count, checkpoint_state) - # Reset the in-flight window on (re)connect. `stream_floor_lsn` is re-derived from - # the FIRST XLogData frame of the new stream (see `inflight_lag/1`) — PG clamps - # `START_REPLICATION` to the slot's server-side `confirmed_flush_lsn`, which for a - # fresh/empty checkpoint is the slot-creation LSN (a large absolute value), NOT 0. - # Measuring lag against that per-stream floor (never against absolute 0) is what - # keeps the very first frame from reading as a ~50 MB false "lag". + # Reset per-stream progress. Queue accounting is independent of these WAL positions. {:query, QueryBuilder.recovery_and_version(), %{ state @@ -409,7 +404,7 @@ defmodule Replicant.Connection do in_txn: false, open_streams: MapSet.new(), last_commit_lsn: 0, - spill: %{state.spill | bytes: 0}, + flow: FlowControl.new(state.flow.receive_timeout), # The frontier epoch is KEPT across (re)connect (monotonic; only `start_streaming` # bumps it) so a fresh window always adopts a strictly-higher epoch than any # in-flight pre-reconnect frontier cast (85672f1 stale-epoch class). The per-stream @@ -455,7 +450,24 @@ defmodule Replicant.Connection do do: %{ce | store_paced: false}, else: %{ce | count: ce.count + 1} - {:noreply, %{state | step: :disconnected, command_error: command_error}} + cancel_feedback(state.flow) + cancel_health_timer(state.flow) + + {:noreply, + %{ + state + | step: :disconnected, + command_error: command_error, + flow: %{ + state.flow + | paused: false, + timer: nil, + paused_at: nil, + health_timer: nil, + last_received: nil, + probing: false + } + }} end @impl true @@ -1165,17 +1177,12 @@ defmodule Replicant.Connection do end @impl true - # XLogData: advance the in-flight high-water to this frame's `wal_end`, then decode - # behind the value-free boundary and forward the decoded message + raw byte-size to - # the AssemblerServer. A decode error halts fail-closed. When the in-flight WAL lag - # (`inflight_lag/1`, received frontier minus the confirmed-durable floor) exceeds - # the bound, the sink cannot keep up: halt fail-closed (§4) before the mailbox grows - # unbounded — a single non-blocking integer comparison, so keepalives are never - # starved. + # Track WAL progress for durability/snapshot boundaries, independently of queue credits. def handle_data(<>, state) do + state = received(state) + # Capture the per-stream floor from the FIRST frame — the position PG actually - # began streaming at (its clamped `confirmed_flush_lsn`), so lag is measured - # relative to the stream, never absolute 0. + # began streaming at (its clamped `confirmed_flush_lsn`) for batch-span accounting. stream_floor_lsn = state.stream_floor_lsn || wal_end # On the FIRST frame of a (re)connected stream, report the floor to the AssemblerServer — it is @@ -1223,19 +1230,15 @@ defmodule Replicant.Connection do state end - lag = inflight_lag(state) - - if lag > effective_lag_bound(state) do - halt_sink_too_slow(state, lag) - else - forward_message(payload, state) - end + forward_message(payload, state) end # Primary keepalive (spec A1 §3.1): forward the frontier in incremental mode, then dispatch to # keepalive_ack/3 — idle-advance a state mirror to wal_end, while an append log and every # non-idle sink reply only with the durable checkpoint (never the received wal_end). def handle_data(<>, state) do + state = received(state) + # Whenever the pipeline is in incremental MODE (incremental?/1 stays true for the whole # pipeline lifetime, not only during an active backfill), forward the keepalive frontier so # a pending chunk window can close on an idle/trickle source (spec §2 D3). Cheap: one cast @@ -1264,6 +1267,101 @@ defmodule Replicant.Connection do def handle_data(_other, state), do: {:noreply, state} @impl true + def handle_info( + {:assembler_drained, token}, + %{step: :draining_assembler, flow: %{reconnect_barrier: token}} = state + ) do + cancel_feedback(state.flow) + handle_connect_proceed(%{state | flow: %{state.flow | reconnect_barrier: nil, timer: nil}}) + end + + def handle_info({:assembler_drained, _token}, state), do: {:noreply, state} + + def handle_info({:assembler_processed, epoch, bytes, messages}, state) do + flow = state.flow |> FlowControl.processed(epoch, bytes, messages) |> manage_stall_timer() + state = %{state | flow: flow} + + if flow.paused and FlowControl.drained?(flow, state.max_inflight_lag) do + cancel_feedback(flow) + flow_event(:resumed, state) + {:resume, arm_health(%{state | flow: %{flow | paused: false, timer: nil, paused_at: nil}})} + else + {:noreply, state} + end + end + + def handle_info( + {:flow_feedback, epoch, token}, + %{flow: %{epoch: epoch, paused: true, timer: {_timer, token}}} = state + ) do + flow = schedule_feedback(state.flow) + {:noreply, [encode_status_update(state.checkpoint_lsn)], %{state | flow: flow}} + end + + # Independent of socket pause state: even one uncompleted Commit can pin WAL. + def handle_info( + {:assembler_stall, epoch, token}, + %{flow: %{epoch: epoch, stall_timer: {_, token}}} = state + ) do + flow = %{state.flow | stall_timer: nil} + + if FlowControl.queued_messages(flow) > 0 do + duration = max(System.monotonic_time(:millisecond) - flow.stall_since, 0) + + if duration >= 5_000 do + measurements = %{ + byte_size: FlowControl.queued_bytes(flow), + change_count: FlowControl.queued_messages(flow), + duration: duration + } + + Telemetry.event([:replicant, :connection, :stalled], measurements, %{ + slot_name: state.slot_name + }) + + Logger.warning( + "Replicant assembler stalled for slot #{state.slot_name}: no completed frames for #{duration}ms " <> + "(queued_messages=#{measurements.change_count}, queued_bytes=#{measurements.byte_size})" + ) + end + end + + {:noreply, %{state | flow: manage_stall_timer(flow)}} + end + + def handle_info({:assembler_stall, _epoch, _token}, state), do: {:noreply, state} + + def handle_info( + {:receive_watchdog, token}, + %{step: :streaming, flow: %{health_timer: {_, token}}} = state + ) do + flow = state.flow + age = max(System.monotonic_time(:millisecond) - flow.last_received, 0) + + cond do + flow.paused -> + {:noreply, arm_health(state)} + + flow.probing and age >= flow.receive_timeout -> + Telemetry.event([:replicant, :connection, :receive_timeout], %{duration: age}, %{ + slot_name: state.slot_name, + reason: :receive_timeout + }) + + {:disconnect, :receive_timeout} + + true -> + Telemetry.event([:replicant, :connection, :health], %{duration: age}, %{ + slot_name: state.slot_name + }) + + flow = schedule_health(%{flow | probing: true}) + {:noreply, [encode_status_update(state.checkpoint_lsn, 1)], %{state | flow: flow}} + end + end + + def handle_info({:receive_watchdog, _token}, state), do: {:noreply, state} + # Async ack: the AssemblerServer durably committed a txn ending at `lsn`. # Advance monotonically and report the new flush position. The in-memory advance # and the telemetry are UNCONDITIONAL; the standby-status-update buffer is emitted @@ -1296,7 +1394,9 @@ defmodule Replicant.Connection do {:stream, sql, [], %{ - arm_schema_guard(state) + (state + |> arm_schema_guard() + |> arm_health()) | step: :streaming, checkpoint_lsn: lsn, received_lsn: lsn, @@ -1344,15 +1444,6 @@ defmodule Replicant.Connection do {:noreply, state} end - # The AssemblerServer reports its running spilled-byte total so the §4 numerator can subtract it - # (spilled bytes are on disk, not RAM). Coarse: the last value wins; a frame or two of staleness - # is acceptable for this guard (spec §9/§10). MUST precede the catch-all below, or the catch-all - # swallows it and the spill window never extends. - - def handle_info({:spilled_bytes, total}, state) when is_integer(total) do - {:noreply, %{state | spill: %{state.spill | bytes: total}}} - end - # ---- wal2json periodic schema guard (ADR-0009 divergence resolution) ---- # A dropped VARLENA column on an update-only table is wire-indistinguishable from # the unchanged-TOAST sentinel (the decoder's insert/fixed-width rules cover every @@ -1477,9 +1568,11 @@ defmodule Replicant.Connection do is 0 (we volunteer status). `clock` is microseconds since the PG 2000 epoch. """ @spec encode_status_update(Replicant.lsn()) :: binary() - def encode_status_update(lsn) when is_integer(lsn) and lsn >= 0 do + def encode_status_update(lsn), do: encode_status_update(lsn, 0) + + defp encode_status_update(lsn, reply) when is_integer(lsn) and lsn >= 0 do clock = System.os_time(:microsecond) - @pg_epoch - <> + <> end # On a keepalive: when a STATE MIRROR is IDLE (no open transaction AND every received commit @@ -1592,17 +1685,6 @@ defmodule Replicant.Connection do defp streaming?(%{streaming: s}), do: is_list(s) defp streaming?(_), do: false - # The disk spill ceiling (bytes) from `streaming[:spill][:max_spill_bytes]`, or nil when - # spill is not configured. Resolved once at `init/1` and extends the §4 halt ceiling. - defp spill_ceiling(streaming) when is_list(streaming) do - case Keyword.get(streaming, :spill) do - spill when is_list(spill) -> Keyword.get(spill, :max_spill_bytes) - _ -> nil - end - end - - defp spill_ceiling(_), do: nil - @doc false @spec lib_go_forward_violation?(map()) :: boolean() def lib_go_forward_violation?(%{ @@ -1822,29 +1904,6 @@ defmodule Replicant.Connection do def reset_retry_count(_count, _success), do: 0 - # In-flight WAL lag (bytes): received frontier minus the confirmed-durable floor, - # LESS the bytes already spilled to disk (§5 — spilled bytes are no longer resident, - # so they must not count toward the RAM-bounded numerator). The floor is the higher - # of the durable `checkpoint_lsn` (once a commit advances it to a real absolute LSN) - # and the per-stream `stream_floor_lsn` (the position PG began streaming at, used - # before the first commit while checkpoint is still 0). A cheap integer subtraction — - # safe to call on the keepalive-free hot path. - defp inflight_lag(%{ - received_lsn: received, - checkpoint_lsn: cp, - stream_floor_lsn: floor, - spill: %{bytes: spilled} - }) do - received - max(cp, floor || received) - spilled - end - - # The §4 halt ceiling. No spill configured (`spill.max: nil`): the base - # `max_inflight_lag` (RAM-only bound, unchanged). Spill configured: extend the ceiling - # by the disk budget — resident lag may run up to RAM + disk before the sink is - # genuinely too slow (the numerator already subtracts the spilled bytes). - defp effective_lag_bound(%{max_inflight_lag: base, spill: %{max: nil}}), do: base - defp effective_lag_bound(%{max_inflight_lag: base, spill: %{max: ceil}}), do: base + ceil - defp forward_message(payload, state) do case Decoder.decode(payload, decoder: decoder_kind(state), @@ -1868,8 +1927,16 @@ defmodule Replicant.Connection do # message: a multi-message payload (wal2json's relation + change) must not # double-count in txn.byte_size and the spill accounting. state = forward_each_message(messages, payload, state) - - {:noreply, state} + state = %{state | flow: manage_stall_timer(state.flow)} + + if FlowControl.full?(state.flow, state.max_inflight_lag) do + flow = %{state.flow | paused: true, paused_at: System.monotonic_time(:millisecond)} + state = %{state | flow: flow} + flow_event(:paused, state) + {:pause, %{state | flow: schedule_feedback(flow)}} + else + {:noreply, state} + end {:error, error} -> Replicant.Supervisor.halt(state.slot_name, error) @@ -1883,15 +1950,90 @@ defmodule Replicant.Connection do |> Enum.reduce(state, fn {message, i}, acc -> bytes = if i == 0, do: byte_size(payload), else: 0 + flow = FlowControl.push(acc.flow, bytes) + GenServer.cast( AssemblerServer.via(state.slot_name), - {:message, message, bytes, self()} + {:message, message, bytes, self(), + {flow.epoch, flow.sent_bytes, flow.sent_messages, flow.queue}} ) - acc |> update_in_stream(message) |> track_txn(message) + %{acc | flow: flow} |> update_in_stream(message) |> track_txn(message) end) end + defp manage_stall_timer(flow) do + cond do + FlowControl.queued_messages(flow) == 0 -> + cancel_stall_timer(flow) + %{flow | stall_timer: nil} + + flow.stall_timer != nil -> + flow + + true -> + token = make_ref() + age = max(System.monotonic_time(:millisecond) - flow.stall_since, 0) + delay = if age >= 5_000, do: 5_000, else: 5_000 - age + timer = Process.send_after(self(), {:assembler_stall, flow.epoch, token}, delay) + %{flow | stall_timer: {timer, token}} + end + end + + defp cancel_stall_timer(%{stall_timer: {timer, _}}), do: Process.cancel_timer(timer) + defp cancel_stall_timer(_flow), do: :ok + + # Timer tokens fence both reconnects and re-arming after a deliberate pause. + # Only actual protocol frames prove health; sending feedback cannot do so. + defp received(state) do + %{ + state + | flow: %{state.flow | last_received: System.monotonic_time(:millisecond), probing: false} + } + end + + defp arm_health(state) do + cancel_health_timer(state.flow) + state = received(state) + %{state | flow: schedule_health(state.flow)} + end + + defp schedule_health(%{receive_timeout: :infinity} = flow), do: %{flow | health_timer: nil} + + defp schedule_health(flow) do + token = make_ref() + timer = Process.send_after(self(), {:receive_watchdog, token}, div(flow.receive_timeout, 2)) + %{flow | health_timer: {timer, token}} + end + + defp cancel_health_timer(%{health_timer: {timer, _}}), do: Process.cancel_timer(timer) + defp cancel_health_timer(_flow), do: :ok + + defp schedule_feedback(flow) do + token = make_ref() + timer = Process.send_after(self(), {:flow_feedback, flow.epoch, token}, 5_000) + %{flow | timer: {timer, token}} + end + + defp flow_event(event, state) do + Telemetry.event( + [:replicant, :connection, event], + %{ + byte_size: FlowControl.queued_bytes(state.flow), + change_count: FlowControl.queued_messages(state.flow), + duration: + if(state.flow.paused_at, + do: max(System.monotonic_time(:millisecond) - state.flow.paused_at, 0), + else: 0 + ) + }, + %{slot_name: state.slot_name} + ) + end + + defp cancel_feedback(%{timer: nil}), do: :ok + defp cancel_feedback(%{timer: {timer, _token}}), do: Process.cancel_timer(timer) + # Track the streaming decode context: StreamStart opens it (the following change messages carry # the (sub)xid prefix that only decodes correctly with streaming: true), StreamStop closes it. # Reset to false on every (re)connect (see start_streaming / snapshot handoff) so a mid-stream @@ -1956,21 +2098,6 @@ defmodule Replicant.Connection do def track_txn(state, _msg), do: state - # Fail-closed lag-halt (spec §4): the sink is not draining fast enough — the - # in-flight window is exceeded. Surface it with value-free telemetry (the `reason` - # meta key is allowlisted; the `lag` measurement is a WAL-byte count, never a row - # value), tear the pipeline down permanently, and disconnect. This BOUNDS memory - # (no unbounded mailbox) and SURFACES the overload (no silent livelock). Restart - # resumes from the durable checkpoint (loss=0 by §6 dedup). - defp halt_sink_too_slow(state, lag) do - Telemetry.event([:replicant, :connection, :disconnected], %{lag: lag}, %{ - reason: :sink_too_slow - }) - - Replicant.Supervisor.halt(state.slot_name, {:sink_too_slow, lag}) - {:disconnect, :sink_too_slow} - end - defp start_streaming(state) do # SINGLE WRITER of frontier_epoch: an incremental (re)connect opens a fresh window epoch # (fe + 1) HERE and nowhere else, so the {:reset_snapshot_window, epoch} prime_assembler @@ -1988,7 +2115,10 @@ defmodule Replicant.Connection do defp stream_now(state) do {:ok, sql} = start_replication_sql(state, state.checkpoint_lsn) - {:stream, sql, [], arm_schema_guard(%{state | step: :streaming, in_stream: false})} + {:stream, sql, [], + %{state | step: :streaming, in_stream: false} + |> arm_schema_guard() + |> arm_health()} end # The START_REPLICATION command for the configured decoder (ADR-0009 §2): the plugin @@ -2039,6 +2169,7 @@ defmodule Replicant.Connection do # and the fresh reader resumes from durable progress. Ordering: retire → reset → spawn. state = retire_reader(state) server = AssemblerServer.via(state.slot_name) + GenServer.cast(server, {:flow_queue, state.flow.queue}) GenServer.cast(server, {:reset_snapshot_window, frontier_epoch(state) + 1}) GenServer.cast(server, {:snapshot_floor, floor}) @@ -2072,6 +2203,8 @@ defmodule Replicant.Connection do # batch (reset) so a transient reconnect re-buffers a fresh batch (spec §9; the span base # lib_checkpoint is left to the assembler). Per-transaction sink-owned mode: no-op. defp prime_assembler(state, seed_lsn) do + GenServer.cast(AssemblerServer.via(state.slot_name), {:flow_queue, state.flow.queue}) + # Streaming is orthogonal to the checkpoint mode: on every (re)connect discard any # partially-buffered streamed transactions (spec §9) so a mid-stream reconnect never # replays a half-received in-progress txn. Runs before the mode-specific seed/reset. diff --git a/lib/replicant/error.ex b/lib/replicant/error.ex index 5c7f2e6..ec69e1d 100644 --- a/lib/replicant/error.ex +++ b/lib/replicant/error.ex @@ -20,6 +20,7 @@ defmodule Replicant.Error do | :too_many_streams | :spill_io_failed | :spill_exhausted + | :buffer_limit_exceeded | :snapshot_failed | :snapshot_column_list_conflict | :snapshot_no_publishable_columns diff --git a/lib/replicant/flow_control.ex b/lib/replicant/flow_control.ex new file mode 100644 index 0000000..f40268a --- /dev/null +++ b/lib/replicant/flow_control.ex @@ -0,0 +1,89 @@ +defmodule Replicant.FlowControl do + @moduledoc "Connection-local flow control state." + + # Cumulative, connection-generation-scoped credits cover the assembler mailbox. + # They are independent of WAL positions and of durable checkpoint acknowledgements. + @max_messages 512 + + @type t :: %__MODULE__{ + receive_timeout: pos_integer() | :infinity, + last_received: integer() | nil, + health_timer: {reference(), reference()} | nil, + probing: boolean(), + epoch: reference() | nil, + reconnect_barrier: reference() | nil, + queue: :atomics.atomics_ref() | nil, + paused_at: integer() | nil, + stall_since: integer() | nil, + stall_timer: {reference(), reference()} | nil, + sent_bytes: non_neg_integer(), + sent_messages: non_neg_integer(), + processed_bytes: non_neg_integer(), + processed_messages: non_neg_integer(), + paused: boolean(), + timer: {reference(), reference()} | nil + } + + defstruct receive_timeout: 60_000, + last_received: nil, + health_timer: nil, + probing: false, + epoch: nil, + reconnect_barrier: nil, + queue: nil, + paused_at: nil, + stall_since: nil, + stall_timer: nil, + sent_bytes: 0, + sent_messages: 0, + processed_bytes: 0, + processed_messages: 0, + paused: false, + timer: nil + + def new(timeout \\ 60_000), + do: %__MODULE__{epoch: make_ref(), queue: :atomics.new(1, []), receive_timeout: timeout} + + def push(%{epoch: nil}, bytes), do: push(new(), bytes) + + def push(flow, bytes) do + :atomics.add(flow.queue, 1, 1) + + since = + if queued_messages(flow) == 0, + do: System.monotonic_time(:millisecond), + else: flow.stall_since + + %{ + flow + | sent_bytes: flow.sent_bytes + bytes, + sent_messages: flow.sent_messages + 1, + stall_since: since + } + end + + def processed(flow, epoch, bytes, messages) + when epoch == flow.epoch and bytes >= flow.processed_bytes and + bytes <= flow.sent_bytes and messages >= flow.processed_messages and + messages <= flow.sent_messages do + since = + cond do + messages == flow.sent_messages -> nil + messages > flow.processed_messages -> System.monotonic_time(:millisecond) + true -> flow.stall_since + end + + %{flow | processed_bytes: bytes, processed_messages: messages, stall_since: since} + end + + def processed(flow, _epoch, _bytes, _messages), do: flow + + def queued_bytes(flow), do: flow.sent_bytes - flow.processed_bytes + def queued_messages(flow), do: flow.sent_messages - flow.processed_messages + + def full?(flow, limit), + do: queued_bytes(flow) >= limit or queued_messages(flow) >= @max_messages + + def drained?(flow, limit), + do: queued_bytes(flow) <= div(limit, 2) and queued_messages(flow) <= div(@max_messages, 2) +end diff --git a/lib/replicant/telemetry.ex b/lib/replicant/telemetry.ex index c3d1dea..964f3a9 100644 --- a/lib/replicant/telemetry.ex +++ b/lib/replicant/telemetry.ex @@ -13,6 +13,12 @@ defmodule Replicant.Telemetry do attacker-controlled terms. The guard therefore cannot leak the bytes it exists to keep out. Mirrors `arcadic`'s allowlist pattern. + `[:replicant, :connection, :stalled]` reports queued frames without assembler + progress for five seconds, independent of pause state. Measurements are + `byte_size`, `change_count` (queued frames), and `duration` (milliseconds without + completion); metadata contains `slot_name`. A warning is also logged, and both + signals repeat every five seconds until progress resumes. + `[:replicant, :pipeline, :halted]` fires before permanent pipeline teardown. Measurements are empty; metadata contains `slot_name`, the structural `reason` atom, and optional `kind`. Snapshot refusals also emit @@ -51,9 +57,9 @@ defmodule Replicant.Telemetry do # Measurements (the 2nd arg): key => value-shape contract. # * :non_neg_integer — `duration` (ms), `byte_size`, `change_count`. - # * :integer — `lag` is SIGNED: `received - max(cp, floor) - spilled` is - # WAL-byte arithmetic that can go negative, so a non-negative guard would - # over-reject a legitimate emission. + # * :integer — `lag` is SIGNED: `received - max(cp, floor)` is WAL-position + # arithmetic, not a payload or memory budget. Preserve the signed contract + # for diagnostic consumers. @measurement_shapes %{ duration: :non_neg_integer, lag: :integer, diff --git a/mix.exs b/mix.exs index 62a5ef0..80492d1 100644 --- a/mix.exs +++ b/mix.exs @@ -58,8 +58,9 @@ defmodule Replicant.MixProject do # - 0.22.2 floors CVE-2026-32687 (SQLi in Postgrex.Notifications.listen/3) # - 0.22.3 fixes CVE-2026-58225 (dollar-quote in Notifications reconnect replay) # - 0.22.4 fixes CVE-2026-66838 (SQLi via the :comment option in Postgrex.stream/4) - # No ReplicationConnection API change across 0.22.2 → 0.22.4 (security patches only). - {:postgrex, "~> 0.22.4"}, + # Pin the merged pause/resume API until it is available in a Hex release. + {:postgrex, + github: "elixir-ecto/postgrex", ref: "a209c8b96c5d92cfff9a35df8ed31ed123943bc2"}, # Dev/Test {:ex_doc, "~> 0.31", only: :dev, runtime: false}, {:credo, "~> 1.7", only: [:dev, :test], runtime: false}, diff --git a/mix.lock b/mix.lock index 97c343c..316347a 100644 --- a/mix.lock +++ b/mix.lock @@ -14,7 +14,7 @@ "makeup_erlang": {:hex, :makeup_erlang, "1.1.0", "835f7e60792e08824cda445639555d7bf1bbbddb1b60b306e33cb6f6db24dc74", [:mix], [{:makeup, "~> 1.0", [hex: :makeup, repo: "hexpm", optional: false]}], "hexpm", "1cd6780fb1dd1a03979abaed0fe82712b0625118fd5257d3ebbf73f960c73c3c"}, "mix_audit": {:hex, :mix_audit, "2.1.5", "c0f77cee6b4ef9d97e37772359a187a166c7a1e0e08b50edf5bf6959dfe5a016", [:make, :mix], [{:jason, "~> 1.4", [hex: :jason, repo: "hexpm", optional: false]}, {:yaml_elixir, "~> 2.11", [hex: :yaml_elixir, repo: "hexpm", optional: false]}], "hexpm", "87f9298e21da32f697af535475860dc1d3617a010e0b418d2ec6142bc8b42d69"}, "nimble_parsec": {:hex, :nimble_parsec, "1.4.2", "8efba0122db06df95bfaa78f791344a89352ba04baedd3849593bfce4d0dc1c6", [:mix], [], "hexpm", "4b21398942dda052b403bbe1da991ccd03a053668d147d53fb8c4e0efe09c973"}, - "postgrex": {:hex, :postgrex, "0.22.4", "d271f595dfd25230b6398354e19d17bb5e2d20130fd2d9bdca7e15f125d43552", [:mix], [{:db_connection, "~> 2.9", [hex: :db_connection, repo: "hexpm", optional: false]}, {:decimal, "~> 1.5 or ~> 2.0 or ~> 3.0", [hex: :decimal, repo: "hexpm", optional: false]}, {:jason, "~> 1.0", [hex: :jason, repo: "hexpm", optional: true]}, {:table, "~> 0.1.0", [hex: :table, repo: "hexpm", optional: true]}], "hexpm", "4aae45a2d60e35b04eea2602440be152fae332901f1fc7a60fc7cb7f0f9a9c5a"}, + "postgrex": {:git, "https://github.com/elixir-ecto/postgrex.git", "a209c8b96c5d92cfff9a35df8ed31ed123943bc2", [ref: "a209c8b96c5d92cfff9a35df8ed31ed123943bc2"]}, "telemetry": {:hex, :telemetry, "1.4.2", "a0cb522801dffb1c49fe6e30561badffc7b6d0e180db1300df759faa22062855", [:rebar3], [], "hexpm", "928f6495066506077862c0d1646609eed891a4326bee3126ba54b60af61febb1"}, "yamerl": {:hex, :yamerl, "0.10.0", "4ff81fee2f1f6a46f1700c0d880b24d193ddb74bd14ef42cb0bcf46e81ef2f8e", [:rebar3], [], "hexpm", "346adb2963f1051dc837a2364e4acf6eb7d80097c0f53cbdc3046ec8ec4b4e6e"}, "yaml_elixir": {:hex, :yaml_elixir, "2.12.2", "9dd1330fb4cd9a36a7b0f502e5b12486eff632792ee4a5f0eba52a4d4ec32c9c", [:mix], [{:yamerl, "~> 0.10", [hex: :yamerl, repo: "hexpm", optional: false]}], "hexpm", "e7c1b10122f973e6558462d51c39026ba0e14afbc6745318e990ea82cfe9e159"}, diff --git a/notebooks/getting_started.livemd b/notebooks/getting_started.livemd index 89e5c37..e2c95f5 100644 --- a/notebooks/getting_started.livemd +++ b/notebooks/getting_started.livemd @@ -1059,7 +1059,7 @@ only, never a row value — critical rule 1). | Knob (default) | Bounds | On exhaustion | Telemetry | | --- | --- | --- | --- | -| `max_inflight_lag: 64 * 1024 * 1024` | how far the received WAL frontier may run ahead of the durable checkpoint before the sink is "too slow" | halt fail-closed (sink can't keep up) | rides `[:replicant, :connection, :disconnected]` with `reason: :sink_too_slow` + a signed `lag` measurement | +| `max_inflight_lag: 64 * 1024 * 1024` | queued payload budget and a separate retained transaction/batch budget | pause/resume for queued work; halt `:buffer_limit_exceeded` for unspillable retained data | `[:replicant, :connection, :paused]` / `:resumed` with queued `byte_size` and `change_count`; `[:replicant, :buffer, :exhausted]` on exhaustion | | `checkpoint_store: [max_retries: 5, retry_backoff_ms: 1000]` (lib mode) | transient checkpoint-store faults (connect-read + mid-stream write) | halt after N retries; a permanent fault (schema/config) halts at once; `max_retries: 0` = halt-now | `[:replicant, :checkpoint_store, :retrying]` per attempt | | `max_command_retries: 5` | a persistent **pre-frame** replication-command error — slot exhaustion, a slot already active for another consumer, a forward-incompatible result — that otherwise reconnects forever | halt after N failed connect cycles; `max_command_retries: 0` = halt-now | `[:replicant, :connection, :command_error_halt]` on halt | | `failover: true` (PG17+) | enables an HA failover slot that survives a promoted standby | below PG17 halts `{:config, :failover_unsupported}`; an unpromoted synced slot halts fail-closed | — | diff --git a/test/integration/backpressure_test.exs b/test/integration/backpressure_test.exs new file mode 100644 index 0000000..d0f7605 --- /dev/null +++ b/test/integration/backpressure_test.exs @@ -0,0 +1,190 @@ +defmodule Replicant.BackpressureTest do + use ExUnit.Case, async: false + + alias Replicant.Test.PG16 + + @moduletag :integration + @moduletag :pg10 + + defmodule SlowSink do + @behaviour Replicant.Sink + + def checkpoint, do: {:ok, Agent.get(__MODULE__, & &1.lsn)} + + def handle_transaction(txn) do + {owner, block?} = Agent.get(__MODULE__, &{&1.owner, &1.lsn == nil}) + + if block? do + send(owner, {:sink_blocked, self()}) + + receive do + :release_sink -> :ok + after + 60_000 -> raise "test sink was not released" + end + end + + Agent.update(__MODULE__, fn state -> + %{state | lsn: txn.commit_lsn, transactions: [txn | state.transactions]} + end) + + {:ok, txn.commit_lsn} + end + end + + @tag timeout: 90_000 + test "a blocked sink pauses input, keeps its slot alive, then drains every transaction in order" do + owner = self() + + start_supervised!(%{ + id: SlowSink, + start: + {Agent, :start_link, + [fn -> %{owner: owner, lsn: nil, transactions: []} end, [name: SlowSink]]} + }) + + telemetry_id = {__MODULE__, make_ref()} + + :telemetry.attach( + telemetry_id, + [:replicant, :connection, :stalled], + fn _, measurements, metadata, owner -> + send(owner, {:stalled, measurements, metadata}) + end, + owner + ) + + on_exit(fn -> :telemetry.detach(telemetry_id) end) + + ctrl = start_supervised!({Postgrex, PG16.pg_opts()}) + slot = "rep_pressure_#{System.unique_integer([:positive])}" + table = slot <> "_rows" + publication = slot <> "_pub" + Postgrex.query!(ctrl, "CREATE TABLE #{table} (id int PRIMARY KEY, payload text)", []) + Postgrex.query!(ctrl, "CREATE PUBLICATION #{publication} FOR TABLE #{table}", []) + + on_exit(fn -> + Replicant.stop(slot) + {:ok, cleanup} = Postgrex.start_link(PG16.pg_opts()) + + PG16.wait_until(fn -> + Postgrex.query!(cleanup, "SELECT active FROM pg_replication_slots WHERE slot_name=$1", [ + slot + ]).rows in [[], [[false]]] + end) + + Postgrex.query!( + cleanup, + "SELECT pg_drop_replication_slot(slot_name) FROM pg_replication_slots WHERE slot_name=$1", + [slot] + ) + + Postgrex.query!(cleanup, "DROP PUBLICATION #{publication}", []) + Postgrex.query!(cleanup, "DROP TABLE #{table}", []) + PG16.stop_conn(cleanup) + end) + + {:ok, _pipeline} = + Replicant.start_link( + connection: + PG16.pg_opts() ++ [parameters: [wal_sender_timeout: "8000", application_name: slot]], + slot_name: slot, + publication: publication, + sink: SlowSink, + go_forward_only: true, + max_inflight_lag: 2048, + receive_timeout: 800, + max_command_retries: 10 + ) + + PG16.wait_until(fn -> connection_state(slot).step == :streaming end) + [[backend, initial_flush]] = slot_status(ctrl, slot) + + Postgrex.query!(ctrl, "INSERT INTO #{table} VALUES (1, repeat('x', 300))", []) + assert_receive {:sink_blocked, assembler}, 5000 + + for id <- 2..100 do + Postgrex.query!(ctrl, "INSERT INTO #{table} VALUES ($1, repeat('x', 300))", [id]) + end + + PG16.wait_until(fn -> connection_state(slot).flow.paused end) + paused = connection_state(slot) + assert Replicant.FlowControl.queued_bytes(paused.flow) < 2500 + assert Replicant.FlowControl.queued_messages(paused.flow) <= 512 + assert SlowSink.checkpoint() == {:ok, nil} + + # Longer than wal_sender_timeout: outgoing durable feedback must keep the + # same backend alive even though incoming keepalive delivery is paused. + Process.sleep(10_000) + assert [[^backend, ^initial_flush]] = slot_status(ctrl, slot) + assert connection_state(slot).flow.paused + assert connection_state(slot).flow.sent_bytes == paused.flow.sent_bytes + assert_receive {:stalled, %{duration: duration, byte_size: queued}, %{slot_name: ^slot}} + assert duration >= 5000 + assert queued > 0 + + # Repeated socket failures must not admit another full queue while the sink + # remains blocked. The replacement connection waits before starting replay. + for _ <- 1..3 do + PG16.wait_until(fn -> + Postgrex.query!(ctrl, "SELECT count(*) FROM pg_stat_activity WHERE application_name=$1", [ + slot + ]).rows == [[1]] + end) + + [[true]] = + Postgrex.query!( + ctrl, + "SELECT pg_terminate_backend(pid) FROM pg_stat_activity WHERE application_name=$1", + [slot] + ).rows + + PG16.wait_until(fn -> connection_state(slot).step == :draining_assembler end, 1000) + assert connection_state(slot).flow.sent_bytes == paused.flow.sent_bytes + assert connection_state(slot).flow.stall_since == paused.flow.stall_since + assert connection_state(slot).flow.stall_timer != nil + refute connection_state(slot).flow.paused + assert [[nil, ^initial_flush]] = slot_status(ctrl, slot) + end + + send(assembler, :release_sink) + PG16.wait_until(fn -> Agent.get(SlowSink, &(length(&1.transactions) == 100)) end) + PG16.wait_until(fn -> not connection_state(slot).flow.paused end) + PG16.wait_until(fn -> connection_state(slot).step == :streaming end) + assert [[new_backend, _flush]] = slot_status(ctrl, slot) + assert new_backend != backend + + transactions = Agent.get(SlowSink, &Enum.reverse(&1.transactions)) + + assert Enum.flat_map(transactions, fn txn -> Enum.map(txn.changes, & &1.record["id"]) end) == + Enum.to_list(1..100) + + lsns = Enum.map(transactions, & &1.commit_lsn) + assert lsns == Enum.sort(Enum.uniq(lsns)) + + # A segment switch advances WAL positions without adding publication rows. + Postgrex.query!(ctrl, "SELECT pg_switch_wal()", []) + Postgrex.query!(ctrl, "INSERT INTO #{table} VALUES (101, 'after switch')", []) + PG16.wait_until(fn -> Agent.get(SlowSink, &(length(&1.transactions) == 101)) end) + assert [[^new_backend, _flush]] = slot_status(ctrl, slot) + end + + defp connection_state(slot) do + case Registry.lookup(Replicant.Registry, {slot, :connection}) do + [{pid, _}] -> + {:no_state, %{state: {Replicant.Connection, state}}} = :sys.get_state(pid) + state + + [] -> + %{step: :disconnected} + end + end + + defp slot_status(ctrl, slot) do + Postgrex.query!( + ctrl, + "SELECT active_pid, confirmed_flush_lsn::text FROM pg_replication_slots WHERE slot_name=$1", + [slot] + ).rows + end +end diff --git a/test/integration/crash_injection_test.exs b/test/integration/crash_injection_test.exs index 1c8069e..14d2ebf 100644 --- a/test/integration/crash_injection_test.exs +++ b/test/integration/crash_injection_test.exs @@ -8,14 +8,7 @@ defmodule Replicant.CrashInjectionTest do alias Replicant.Test.{LedgerSink, PauseGate, PausingLedgerSink, PG16} - # The §4 spike tests drive an EXPLICIT small in-flight ceiling (128 KiB) via the - # `:max_inflight_lag` override, sized against the live 25ms/txn slow sink so a - # normal 200-txn burst (~40-75 KB peak lag incl. same-server pollution, see below) - # drains under it while a pathological 900-txn burst / a stuck sink trip the - # fail-closed halt. The PRODUCTION default is - # the far-larger backlog ceiling (`Replicant.Connection.default_max_inflight_lag/0`, - # 64 MiB) — this small override only makes the mechanism observable at test scale; - # it is NOT the shipped default. + # A small payload budget makes pause/resume observable with a 25ms/txn sink. @spike_bound 131_072 setup do @@ -303,31 +296,7 @@ defmodule Replicant.CrashInjectionTest do assert applied_counts(ctrl) |> Map.values() |> Enum.all?(&(&1 == 1)) end - # RISK #2 (spec §4 bounded in-flight window, proven against the live stream). The - # prior `max_len < 800` spike was VACUOUS: with no in-flight bound the mailbox scaled - # linearly with burst, so a threshold chosen for one burst is meaningless at another. - # These three tests encode the REAL §4 property: the in-flight WAL lag ceiling - # (`received_lsn - max(checkpoint_lsn, stream_floor_lsn)`) holds INDEPENDENT of burst — - # a small burst drains under it, a large one (or a stuck sink) halts fail-closed before - # the mailbox grows unbounded. No silent OOM/livelock either way. - # - # They drive an EXPLICIT `max_inflight_lag: @spike_bound` (128 KiB) so the mechanism is - # observable at test scale — NOT the production default (64 MiB backlog ceiling). - # - # WHY 128 KiB, not the original 64 KiB (de-flake, 2026-07-05, root-caused): `received_lsn` - # is pgoutput's `wal_end` = the SERVER's TOTAL WAL position, so it also counts WAL the - # TEST sink writes to the SAME PG16 (sink_orders/_replicant_checkpoint/_replicant_calls) - # plus post-churn autovacuum — "same-server pollution" of ~30-40 KB on top of the ~35 KB - # of real `orders` WAL for a 200-txn burst. At a 64 KiB ceiling the 200-burst peak (~40 KB - # baseline) sat only ~24 KB under the bound, and that pollution variance occasionally - # crossed it, HALTING the burst this test asserts must DRAIN (reproduced 1/15 under CPU - # load; test A alone never halted — only after the 900-txn B/C tests churned the DB). A - # real sink writes to a DIFFERENT mirror DB, so this is a test artifact. 128 KiB keeps the - # ~65-75 KB polluted 200-burst peak a safe ~55+ KB under the ceiling while the widened - # 900-txn bursts (~159 KB orders + pollution) still clear it decisively. - # Sizing (live PG16, 25ms/txn slow sink, @spike_bound = 131_072 B): - # * 200-txn burst → peak lag ~40-75 KB (orders ~35 KB + pollution) → UNDER 128 KiB → drains. - # * 900-txn burst → lag ~159 KB+ → OVER 128 KiB → fail-closed halt (fires ~740 txns in). + # Bursts must remain bounded regardless of unrelated WAL or sink write volume. @tag :spike @tag timeout: 120_000 test "bounded in-flight window: the lag ceiling holds independent of burst size", %{ @@ -366,53 +335,42 @@ defmodule Replicant.CrashInjectionTest do @tag :spike @tag timeout: 120_000 - test "bounded in-flight window: a 900-txn burst trips the fail-closed :sink_too_slow halt", %{ + test "a 900-transaction burst pauses and drains without disconnecting", %{ ctrl: ctrl, slot: slot } do - # (B) A PATHOLOGICAL 900-txn burst at the same slow sink exceeds the ceiling and - # halts fail-closed BEFORE the mailbox grows unbounded (the vacuous RED grew it). - attach_sink_too_slow(slot) + attach_pause(slot) start_pipeline(slot, sink: Replicant.Test.SlowLedgerSink, max_inflight_lag: @spike_bound) + conn = connection_pid(slot) for i <- 1..900, do: insert(ctrl, i, "n#{i}") - assert_receive {:sink_too_slow, %{lag: lag}}, 15_000 - IO.puts("\n[spike B] 900-txn burst tripped :sink_too_slow at in-flight lag = #{lag} B") - assert lag > @spike_bound - - # The pipeline is torn down permanently (fail-closed) — not livelocking/OOMing. - PG16.wait_until( - fn -> Registry.lookup(Replicant.Registry, {slot, :pipeline}) == [] end, - 400 - ) - - :telemetry.detach({__MODULE__, {:too_slow, slot}}) + assert_receive {:paused, %{change_count: count}}, 15_000 + assert count <= 512 + PG16.wait_until(fn -> count(ctrl, "sink_orders") == 900 end, 2400) + assert connection_pid(slot) == conn + assert applied_counts(ctrl) |> Map.values() |> Enum.all?(&(&1 == 1)) end @tag :spike @tag timeout: 120_000 - test "fail-closed halt: a genuinely-stuck sink halts (no silent OOM/livelock)", %{ + test "a permanently stuck sink stops input without acknowledging undelivered rows", %{ ctrl: ctrl, slot: slot } do - # The sink blocks forever on its first txn → the checkpoint never advances → the - # in-flight lag grows monotonically past the ceiling and MUST fail-closed halt. - attach_sink_too_slow(slot) + attach_pause(slot) start_pipeline(slot, sink: Replicant.Test.StuckLedgerSink, max_inflight_lag: @spike_bound) for i <- 1..900, do: insert(ctrl, i, "n#{i}") - assert_receive {:sink_too_slow, %{lag: lag}}, 15_000 - IO.puts("\n[spike C] stuck sink tripped :sink_too_slow at in-flight lag = #{lag} B") - assert lag > @spike_bound - - PG16.wait_until( - fn -> Registry.lookup(Replicant.Registry, {slot, :pipeline}) == [] end, - 400 - ) + assert_receive {:paused, %{change_count: count}}, 15_000 + assert count <= 512 + conn = connection_pid(slot) + paused = safe_conn_state(conn) + Process.sleep(200) + assert safe_conn_state(conn).flow.sent_bytes == paused.flow.sent_bytes + assert safe_conn_state(conn).flow.paused # Nothing was durably applied (the stuck sink never committed) — no partial state. assert count(ctrl, "sink_orders") == 0 - :telemetry.detach({__MODULE__, {:too_slow, slot}}) end # R01 (live): an UNKNOWN checkpoint (a raising `sink.checkpoint/0` → read fault, read as @@ -481,11 +439,11 @@ defmodule Replicant.CrashInjectionTest do sample(n - 1, acc, reader) end - # The live in-flight WAL lag from the running Connection's state (0 if unreadable, + # Queued payload bytes from the running Connection's state (0 if unreadable, # e.g. mid-teardown after a halt). defp inflight_lag(conn) do case safe_conn_state(conn) do - %Replicant.Connection{received_lsn: r, checkpoint_lsn: c} -> r - c + %Replicant.Connection{flow: flow} -> Replicant.FlowControl.queued_bytes(flow) _ -> 0 end end @@ -567,15 +525,17 @@ defmodule Replicant.CrashInjectionTest do _, _ -> :unreadable end - defp attach_sink_too_slow(slot) do + defp attach_pause(slot) do :telemetry.attach( - {__MODULE__, {:too_slow, slot}}, - [:replicant, :connection, :disconnected], + {__MODULE__, {:paused, slot}}, + [:replicant, :connection, :paused], fn _e, meas, meta, pid -> - if meta[:reason] == :sink_too_slow, do: send(pid, {:sink_too_slow, meas}) + if meta[:slot_name] == slot, do: send(pid, {:paused, meas}) end, self() ) + + on_exit(fn -> :telemetry.detach({__MODULE__, {:paused, slot}}) end) end defp start_pipeline(slot, opts \\ []) do diff --git a/test/integration/incremental_snapshot_test.exs b/test/integration/incremental_snapshot_test.exs index 0372156..8d8784f 100644 --- a/test/integration/incremental_snapshot_test.exs +++ b/test/integration/incremental_snapshot_test.exs @@ -151,6 +151,10 @@ defmodule Replicant.IncrementalSnapshotTest do if PG16.enabled?() do setup_int_table(ctrl, "inc_orders", "inc_pub", 5_000) + failed = attach_snapshot_failed(slot) + on_exit(fn -> detach(failed) end) + IncrementalSnapshotSink.set_fail_after_chunks(10) + start_incremental(slot, "inc_pub", chunk_rows: 200, max_pending_chunks: 2) # A concurrent writer for the whole backfill (started AFTER the pipeline is streaming, @@ -160,14 +164,8 @@ defmodule Replicant.IncrementalSnapshotTest do # streamed value) + INSERT ids 5001..5200. This is what makes the drop-set RED-able. {writer, go} = start_writer(fn w, n -> write_orders(w, n, "inc_orders", 5_000) end) - # Arm the fault after ~10 chunk ledger entries → the NEXT chunk halts fail-closed. - wait_chunks(10, 4_000) - failed = attach_snapshot_failed(slot) - IncrementalSnapshotSink.set_fail_next_chunk(true) - - # Halt occurred: the snapshot :failed telemetry fired AND the pipeline tore down. Generous - # timeout: the fault lands on the NEXT chunk, but under full-suite load on the shared PG16 the - # applier can be starved (the documented "TIMEOUT ≠ logic bug" trap) — 30s absorbs that jitter. + # The sink fails the eleventh chunk before any effects, independently of + # scheduler speed. Progress must survive the fail-closed teardown. assert_receive {:snapshot_failed, _reason}, 30_000 detach(failed) PG16.wait_until(fn -> Registry.lookup(Replicant.Registry, {slot, :pipeline}) == [] end, 800) @@ -177,6 +175,7 @@ defmodule Replicant.IncrementalSnapshotTest do assert token != nil refute backfill_complete?() + assert chunk_count() == 10 pre_restart_len = length(IncrementalSnapshotSink.ledger()) # Restart against the SAME durable sink state (after the PG-side slot is released). @@ -413,12 +412,23 @@ defmodule Replicant.IncrementalSnapshotTest do failed = attach_snapshot_failed(slot) retried = attach_snapshot_retried(slot) + # Start the writer before the reader: a fast one-batch snapshot can otherwise + # finish before the writer even connects, leaving no contention to observe. + owner = self() + + {writer, go} = + start_writer(fn w, n -> + update_random_nopk(w, n, "inc_nopk_c") + if n == 1, do: send(owner, :contention_writer_started) + end) + + assert_receive :contention_writer_started, 5_000 + on_exit(fn -> :atomics.put(go, 1, 0) end) + start_incremental(slot, "incnopkc_pub", chunk_rows: 500, max_pending_chunks: 4) - # A CONTINUOUS writer: the keyless path has NO drop-set, so ANY concurrent write taints the - # whole read → redo. After @max_table_attempts (3) the reader halts :snapshot_table_contended - # (spec §6.4), emitting :chunk_retried on each redo (spec §9 "no silent re-read loops"). - {writer, go} = start_writer(fn w, n -> update_random_nopk(w, n, "inc_nopk_c") end) + # The keyless path has no drop-set: concurrent writes taint the whole read. + # Three contended attempts must halt with a retry event for each redo. # 90s of the test's 120s ceiling: three taint-redo cycles against a continuous # writer are wall-clock, and a loaded host (or a CI 2-core runner) stretches the @@ -555,34 +565,29 @@ defmodule Replicant.IncrementalSnapshotTest do end # --------------------------------------------------------------------------- - # Test 7 (§12.5) — §4 backpressure: a slow sink halts :sink_too_slow mid-backfill; resume continues. + # Backpressure composes with an incremental backfill without tearing it down. # --------------------------------------------------------------------------- @tag timeout: 120_000 - test "§4 backpressure: a slow sink trips :sink_too_slow DURING an incremental backfill (§12.5 composition)", + test "a slow sink pauses during incremental backfill then converges without restart", %{ctrl: ctrl, slot: slot} do if PG16.enabled?() do setup_int_table(ctrl, "inc_slow", "incslow_pub", 3_000) - too_slow = attach_sink_too_slow(slot) + paused = attach_pause(slot) IncrementalSnapshotSink.set_txn_delay(40) - # Tiny max_inflight_lag + a slow sink (40 ms/txn) + a heavy writer → the applier falls behind - # and the in-flight lag trips the §4 bound → :sink_too_slow halt DURING an in-flight incremental - # backfill (the §4 backpressure composes with the snapshot, not just v1 streaming — spec §4/§12.5). + # A small payload budget makes backpressure observable during snapshot delivery. start_incremental_slow(slot, "incslow_pub", 8_192, chunk_rows: 200, max_pending_chunks: 2) {writer, go} = start_writer(fn w, n -> write_orders(w, n, "inc_slow", 3_000) end) - assert_receive {:sink_too_slow, %{lag: lag}}, 30_000 - assert lag > 8_192 - detach(too_slow) + assert_receive {:paused, %{byte_size: bytes, change_count: count}}, 30_000 + assert bytes >= 8_192 or count == 512 + detach(paused) stop_writer(writer, go) IncrementalSnapshotSink.set_txn_delay(0) - PG16.wait_until(fn -> Registry.lookup(Replicant.Registry, {slot, :pipeline}) == [] end, 800) - - # The halt was genuinely MID-backfill (not after completion). The resume-from-partial-progress - # mechanism itself is the proven Test-1 gate (its sink-fault halt exercises the same resume path); - # this test's unique coverage is the :sink_too_slow TRIGGER composing with an incremental backfill. - refute backfill_complete?() + PG16.wait_until(fn -> backfill_complete?() end, 1600) + wait_converged(ctrl, "inc_slow") + assert Registry.lookup(Replicant.Registry, {slot, :pipeline}) != [] end end @@ -971,7 +976,7 @@ defmodule Replicant.IncrementalSnapshotTest do end # SLOW-sink incremental (§12.5): the delay-configurable sink + an explicit max_inflight_lag so a - # tiny bound trips the §4 :sink_too_slow halt. Same readiness gate as start_incremental/3. + # small budget triggers socket backpressure. Same readiness gate as start_incremental/3. defp start_incremental_slow(slot, pub, max_inflight_lag, snap_opts) do ref = make_ref() test_pid = self() @@ -1182,15 +1187,15 @@ defmodule Replicant.IncrementalSnapshotTest do ) end - defp attach_sink_too_slow(slot) do - ref = {__MODULE__, :too_slow, make_ref()} + defp attach_pause(slot) do + ref = {__MODULE__, :paused, make_ref()} test_pid = self() :telemetry.attach( ref, - [:replicant, :connection, :disconnected], + [:replicant, :connection, :paused], fn _e, meas, meta, _ -> - if meta[:reason] == :sink_too_slow, do: send(test_pid, {:sink_too_slow, meas}) + if meta[:slot_name] == slot, do: send(test_pid, {:paused, meas}) end, nil ) diff --git a/test/integration/receive_watchdog_test.exs b/test/integration/receive_watchdog_test.exs new file mode 100644 index 0000000..05d80db --- /dev/null +++ b/test/integration/receive_watchdog_test.exs @@ -0,0 +1,203 @@ +defmodule Replicant.ReceiveWatchdogTest do + use ExUnit.Case, async: false + alias Replicant.Test.{PG16, SilentProxy} + @moduletag :integration + @moduletag :pg10 + + defmodule Sink do + @behaviour Replicant.Sink + def checkpoint, do: {:ok, Agent.get(__MODULE__, & &1.lsn)} + + def handle_transaction(txn) do + Agent.update(__MODULE__, fn state -> + %{ + state + | lsn: txn.commit_lsn, + rows: state.rows ++ Enum.map(txn.changes, & &1.record["id"]) + } + end) + + {:ok, txn.commit_lsn} + end + end + + defmodule SnapshotSink do + @behaviour Replicant.Sink + defdelegate checkpoint(), to: Sink + defdelegate handle_transaction(txn), to: Sink + + def handle_snapshot(changes, _context) do + send(Agent.get(Sink, & &1.owner), :snapshot_entered) + Process.sleep(1200) + Agent.update(Sink, &%{&1 | rows: Enum.map(changes, fn change -> change.record["id"] end)}) + :ok + end + + def handle_snapshot_complete(lsn) do + Agent.update(Sink, &%{&1 | lsn: lsn}) + {:ok, lsn} + end + end + + setup context do + owner = self() + snapshot? = Map.get(context, :snapshot, false) + + start_supervised!(%{ + id: Sink, + start: {Agent, :start_link, [fn -> %{lsn: nil, rows: [], owner: owner} end, [name: Sink]]} + }) + + ctrl = start_supervised!({Postgrex, PG16.pg_opts()}) + proxy = start_supervised!({SilentProxy, PG16.pg_opts()}) + slot = "rep_health_#{System.unique_integer([:positive])}" + Postgrex.query!(ctrl, "CREATE TABLE #{slot} (id int PRIMARY KEY)", []) + Postgrex.query!(ctrl, "CREATE PUBLICATION #{slot} FOR TABLE #{slot}", []) + owner = self() + telemetry_id = {__MODULE__, make_ref()} + + :telemetry.attach( + telemetry_id, + [:replicant, :connection, :receive_timeout], + fn _, m, meta, pid -> send(pid, {:timeout, m, meta}) end, + owner + ) + + on_exit(fn -> + :telemetry.detach(telemetry_id) + Replicant.stop(slot) + {:ok, conn} = Postgrex.start_link(PG16.pg_opts()) + + PG16.wait_until(fn -> + Postgrex.query!(conn, "SELECT active FROM pg_replication_slots WHERE slot_name=$1", [slot]).rows in [ + [], + [[false]] + ] + end) + + Postgrex.query!( + conn, + "SELECT pg_drop_replication_slot(slot_name) FROM pg_replication_slots WHERE slot_name=$1", + [slot] + ) + + Postgrex.query!(conn, "DROP PUBLICATION #{slot}", []) + Postgrex.query!(conn, "DROP TABLE #{slot}", []) + PG16.stop_conn(conn) + end) + + opts = + Keyword.merge(PG16.pg_opts(), + hostname: "127.0.0.1", + port: SilentProxy.port(proxy), + parameters: [wal_sender_timeout: "0"] + ) + + if snapshot?, do: Postgrex.query!(ctrl, "INSERT INTO #{slot} VALUES (1)", []) + + {:ok, _} = + Replicant.start_link( + connection: opts, + slot_name: slot, + publication: slot, + sink: if(snapshot?, do: SnapshotSink, else: Sink), + go_forward_only: not snapshot?, + snapshot: snapshot?, + max_command_retries: Map.get(context, :max_retries, 5), + receive_timeout: 800 + ) + + unless snapshot? do + PG16.wait_until(fn -> state(slot).step == :streaming end) + Postgrex.query!(ctrl, "INSERT INTO #{slot} VALUES (1)", []) + PG16.wait_until(fn -> Agent.get(Sink, & &1.rows) == [1] end) + end + + %{ctrl: ctrl, proxy: proxy, slot: slot} + end + + @tag snapshot: true + test "exported snapshot may exceed the receive timeout before streaming starts", %{ + ctrl: ctrl, + slot: slot + } do + assert_receive :snapshot_entered, 3000 + assert state(slot).step == :snapshotting + assert state(slot).flow.health_timer == nil + PG16.wait_until(fn -> state(slot).step == :streaming end) + Postgrex.query!(ctrl, "INSERT INTO #{slot} VALUES (2)", []) + PG16.wait_until(fn -> Agent.get(Sink, & &1.rows) == [1, 2] end) + refute_receive {:timeout, _, _} + end + + test "healthy idle ping, silent half-open socket recovery, durable replay and stale timer fencing", + %{ctrl: ctrl, proxy: proxy, slot: slot} do + initial = state(slot) + # Server keepalives disabled: reply-requested client probes keep idle healthy. + Process.sleep(2000) + refute_receive {:timeout, _, _} + assert state(slot).flow.epoch == initial.flow.epoch + {_, stale_token} = state(slot).flow.health_timer + {:ok, checkpoint} = Sink.checkpoint() + :ok = SilentProxy.blackhole(proxy) + Postgrex.query!(ctrl, "INSERT INTO #{slot} VALUES (2)", []) + + assert_receive {:timeout, %{duration: age}, %{slot_name: ^slot, reason: :receive_timeout}}, + 2000 + + assert age >= 800 + PG16.wait_until(fn -> Agent.get(Sink, & &1.rows) == [1, 2] end) + recovered = state(slot) + assert recovered.flow.epoch != initial.flow.epoch + assert recovered.checkpoint_lsn >= checkpoint + send(connection(slot), {:receive_watchdog, stale_token}) + Process.sleep(1000) + assert state(slot).flow.epoch == recovered.flow.epoch + assert Agent.get(Sink, & &1.rows) == [1, 2] + refute_receive {:timeout, _, _} + end + + @tag max_retries: 0 + test "zero retry budget hands a silent connection failure to the application supervisor", %{ + proxy: proxy, + slot: slot + } do + :ok = SilentProxy.blackhole(proxy) + assert_receive {:timeout, _, %{slot_name: ^slot}}, 2000 + PG16.wait_until(fn -> Registry.lookup(Replicant.Registry, {slot, :connection}) == [] end) + assert Agent.get(Sink, & &1.rows) == [1] + end + + test "slot lost during silent outage halts without recreating or skipping data", %{ + ctrl: ctrl, + proxy: proxy, + slot: slot + } do + :ok = SilentProxy.blackhole(proxy) + + PG16.wait_until(fn -> + Postgrex.query!(ctrl, "SELECT active FROM pg_replication_slots WHERE slot_name=$1", [slot]).rows == + [[false]] + end) + + Postgrex.query!(ctrl, "SELECT pg_drop_replication_slot($1)", [slot]) + Postgrex.query!(ctrl, "INSERT INTO #{slot} VALUES (2)", []) + assert_receive {:timeout, _, %{slot_name: ^slot}}, 2000 + PG16.wait_until(fn -> Registry.lookup(Replicant.Registry, {slot, :connection}) == [] end) + + assert Postgrex.query!( + ctrl, + "SELECT slot_name FROM pg_replication_slots WHERE slot_name=$1", + [slot] + ).rows == [] + + assert Agent.get(Sink, & &1.rows) == [1] + end + + defp connection(slot), do: GenServer.whereis(Replicant.Connection.via(slot)) + + defp state(slot) do + {_, %{state: {_, state}}} = :sys.get_state(connection(slot)) + state + end +end diff --git a/test/integration/stall_detection_test.exs b/test/integration/stall_detection_test.exs new file mode 100644 index 0000000..e6cfec5 --- /dev/null +++ b/test/integration/stall_detection_test.exs @@ -0,0 +1,157 @@ +defmodule Replicant.StallDetectionTest do + use ExUnit.Case, async: false + import ExUnit.CaptureLog + alias Replicant.Test.PG16 + @moduletag :integration + @moduletag :pg10 + + defmodule Sink do + @behaviour Replicant.Sink + def checkpoint, do: {:ok, Agent.get(__MODULE__, & &1.lsn)} + + def handle_transaction(txn) do + {owner, block?} = + Agent.get_and_update(__MODULE__, &{{&1.owner, &1.block?}, %{&1 | block?: false}}) + + if block? do + send(owner, {:blocked, self()}) + + receive do + :release -> :ok + after + 30_000 -> raise "test sink was not released" + end + end + + Agent.update(__MODULE__, &%{&1 | lsn: txn.commit_lsn, count: &1.count + 1}) + {:ok, txn.commit_lsn} + end + end + + setup context do + owner = self() + + start_supervised!(%{ + id: Sink, + start: + {Agent, :start_link, + [fn -> %{owner: owner, lsn: nil, count: 0, block?: true} end, [name: Sink]]} + }) + + ctrl = start_supervised!({Postgrex, PG16.pg_opts()}) + slot = "rep_stall_#{System.unique_integer([:positive])}" + Postgrex.query!(ctrl, "CREATE TABLE #{slot} (id int PRIMARY KEY)", []) + Postgrex.query!(ctrl, "CREATE PUBLICATION #{slot} FOR TABLE #{slot}", []) + handler = {__MODULE__, make_ref()} + + :telemetry.attach( + handler, + [:replicant, :connection, :stalled], + fn _, measurements, metadata, pid -> send(pid, {:stalled, measurements, metadata}) end, + owner + ) + + on_exit(fn -> + :telemetry.detach(handler) + Replicant.stop(slot) + {:ok, conn} = Postgrex.start_link(PG16.pg_opts()) + + PG16.wait_until(fn -> + Postgrex.query!(conn, "SELECT active FROM pg_replication_slots WHERE slot_name=$1", [slot]).rows in [ + [], + [[false]] + ] + end) + + Postgrex.query!( + conn, + "SELECT pg_drop_replication_slot(slot_name) FROM pg_replication_slots WHERE slot_name=$1", + [slot] + ) + + Postgrex.query!(conn, "DROP PUBLICATION #{slot}", []) + Postgrex.query!(conn, "DROP TABLE #{slot}", []) + PG16.stop_conn(conn) + end) + + {:ok, _} = + Replicant.start_link( + connection: PG16.pg_opts(), + slot_name: slot, + publication: slot, + sink: Sink, + go_forward_only: true, + max_inflight_lag: Map.get(context, :budget, 1_000_000) + ) + + PG16.wait_until(fn -> state(slot).step == :streaming end) + %{ctrl: ctrl, slot: slot, handler: handler} + end + + @tag :quiet + test "quiet hung sink signals without pausing, warns without a handler, and stops after drain", + %{ctrl: ctrl, slot: slot, handler: handler} do + log = + capture_log(fn -> + Postgrex.query!(ctrl, "INSERT INTO #{slot} VALUES (1)", []) + assert_receive {:blocked, sink}, 3000 + refute state(slot).flow.paused + assert Replicant.FlowControl.queued_messages(state(slot).flow) > 0 + + assert_receive {:stalled, %{duration: duration, change_count: count}, + %{slot_name: ^slot}}, + 11_000 + + assert duration >= 5000 + assert count > 0 + refute state(slot).flow.paused + :telemetry.detach(handler) + # A second notification must still warn when nobody subscribes to telemetry. + Process.sleep(5500) + send(sink, :release) + PG16.wait_until(fn -> Replicant.FlowControl.queued_messages(state(slot).flow) == 0 end) + assert state(slot).flow.stall_timer == nil + + IO.puts( + "STALL-QUIET paused=false queued=#{count} first_duration_ms=#{duration} drained=true" + ) + end) + + assert length(Regex.scan(~r/Replicant assembler stalled/, log)) >= 2 + assert capture_log(fn -> Process.sleep(5500) end) == "" + end + + @tag budget: 256 + test "short pause cycles with completed frames do not accumulate into a stall", %{ + ctrl: ctrl, + slot: slot + } do + log = + capture_log(fn -> + for cycle <- 1..6 do + Agent.update(Sink, &%{&1 | block?: true}) + + for offset <- 1..12 do + Postgrex.query!(ctrl, "INSERT INTO #{slot} VALUES ($1)", [cycle * 100 + offset]) + end + + assert_receive {:blocked, sink}, 3000 + PG16.wait_until(fn -> state(slot).flow.paused end) + Process.sleep(1000) + send(sink, :release) + PG16.wait_until(fn -> Agent.get(Sink, & &1.count) == cycle * 12 end) + PG16.wait_until(fn -> Replicant.FlowControl.queued_messages(state(slot).flow) == 0 end) + end + + refute_receive {:stalled, _, _} + IO.puts("STALL-PROGRESS short_pause_cycles=6 committed_transactions=72 false_stalls=0") + end) + + refute log =~ "Replicant assembler stalled" + end + + defp state(slot) do + {_, %{state: {_, state}}} = :sys.get_state(GenServer.whereis(Replicant.Connection.via(slot))) + state + end +end diff --git a/test/integration/streamed_savepoint_messages_test.exs b/test/integration/streamed_savepoint_messages_test.exs new file mode 100644 index 0000000..fac3d59 --- /dev/null +++ b/test/integration/streamed_savepoint_messages_test.exs @@ -0,0 +1,136 @@ +defmodule Replicant.StreamedSavepointMessagesTest do + use ExUnit.Case, async: false + alias Replicant.Test.PG16 + @moduletag :integration + @moduletag :pg14 + + defmodule Sink do + @behaviour Replicant.Sink + def checkpoint, do: {:ok, Agent.get(__MODULE__, & &1.lsn)} + + def handle_transaction(txn) do + ids = Enum.map(txn.changes, & &1.record["id"]) + Agent.update(__MODULE__, &%{&1 | lsn: txn.commit_lsn, ids: ids}) + {:ok, txn.commit_lsn} + end + + def handle_message(_message, _context), do: :ok + end + + for spill? <- [false, true] do + @tag spill: spill? + test "live pgoutput savepoint message attribution, spill=#{spill?}", %{spill: spill?} do + start_supervised!(%{ + id: Sink, + start: {Agent, :start_link, [fn -> %{lsn: nil, ids: []} end, [name: Sink]]} + }) + + ctrl = start_supervised!({Postgrex, PG16.pg_opts()}) + flush = start_supervised!(Supervisor.child_spec({Postgrex, PG16.pg_opts()}, id: :flush)) + slot = "rep_savepoint_msg_#{System.unique_integer([:positive])}" + spill_dir = Path.join(System.tmp_dir!(), slot) + Postgrex.query!(ctrl, "CREATE TABLE #{slot} (id int PRIMARY KEY, payload text)", []) + Postgrex.query!(ctrl, "CREATE PUBLICATION #{slot} FOR TABLE #{slot}", []) + [[version]] = Postgrex.query!(ctrl, "SHOW server_version_num", []).rows + + on_exit(fn -> + Replicant.stop(slot) + {:ok, conn} = Postgrex.start_link(PG16.pg_opts()) + + PG16.wait_until(fn -> + Postgrex.query!(conn, "SELECT active FROM pg_replication_slots WHERE slot_name=$1", [ + slot + ]).rows in [[], [[false]]] + end) + + Postgrex.query!( + conn, + "SELECT pg_drop_replication_slot(slot_name) FROM pg_replication_slots WHERE slot_name=$1", + [slot] + ) + + Postgrex.query!(conn, "DROP PUBLICATION #{slot}", []) + Postgrex.query!(conn, "DROP TABLE #{slot}", []) + PG16.stop_conn(conn) + File.rm_rf!(spill_dir) + end) + + streaming = if spill?, do: [spill: [dir: spill_dir, max_spill_bytes: 8_000_000]], else: [] + + {:ok, _} = + Replicant.start_link( + connection: PG16.pg_opts() ++ [parameters: [logical_decoding_work_mem: "64kB"]], + slot_name: slot, + publication: slot, + sink: Sink, + go_forward_only: true, + messages: true, + streaming: streaming, + max_inflight_lag: if(spill?, do: 32_000, else: 8_000_000) + ) + + PG16.wait_until(fn -> + Postgrex.query!(ctrl, "SELECT active FROM pg_replication_slots WHERE slot_name=$1", [slot]).rows == + [[true]] + end) + + {:ok, :ok} = + Postgrex.transaction( + ctrl, + fn conn -> + Postgrex.query!(conn, "INSERT INTO #{slot} VALUES (1, 'parent')", []) + [[top]] = Postgrex.query!(conn, "SELECT txid_current()", []).rows + Postgrex.query!(conn, "SAVEPOINT discarded", []) + + Postgrex.query!( + conn, + "SELECT pg_logical_emit_message(true, 'savepoint_test', 'synthetic')", + [] + ) + + Postgrex.query!( + conn, + "INSERT INTO #{slot} SELECT g, repeat(md5(g::text), 64) FROM generate_series(2, 1001) g", + [] + ) + + flush_wal(flush) + PG16.wait_until(fn -> match?(%{messages: [_ | _]}, buffer(slot, top)) end, 200) + before = buffer(slot, top) + message_xids = Enum.map(before.messages, & &1.xid) |> Enum.uniq() + + subxids = + (Enum.map(before.changes, &elem(&1, 0)) ++ Map.keys(before.spilled_by_subxid)) + |> Enum.uniq() + |> Enum.reject(&(&1 == top)) + + assert message_xids == [top] + assert [sub] = subxids + if spill?, do: assert(before.spill != nil) + Postgrex.query!(conn, "ROLLBACK TO SAVEPOINT discarded", []) + flush_wal(flush) + PG16.wait_until(fn -> MapSet.member?(buffer(slot, top).aborted, sub) end, 200) + after_abort = buffer(slot, top) + + IO.puts( + "SAVEPOINT-WIRE pg=#{version} spill=#{spill?} top_xid=#{top} row_subxid=#{sub} message_xids=#{inspect(message_xids)} messages_after_abort=#{length(after_abort.messages)} resident_before=#{before.resident_bytes} resident_after=#{after_abort.resident_bytes}" + ) + + Postgrex.query!(conn, "INSERT INTO #{slot} VALUES (1002, 'parent_after')", []) + :ok + end, + timeout: 20_000 + ) + + PG16.wait_until(fn -> Agent.get(Sink, & &1.ids) == [1, 1002] end) + assert Postgrex.query!(ctrl, "SELECT id FROM #{slot} ORDER BY id", []).rows == [[1], [1002]] + end + end + + defp buffer(slot, top), + do: + :sys.get_state(GenServer.whereis(Replicant.AssemblerServer.via(slot))).asm.stream_txns[top] + + defp flush_wal(conn), + do: Postgrex.query!(conn, "SELECT pg_logical_emit_message(false, 'flush_test', '')", []) +end diff --git a/test/integration/streaming_spill_test.exs b/test/integration/streaming_spill_test.exs index f7cb9dc..7c971a9 100644 --- a/test/integration/streaming_spill_test.exs +++ b/test/integration/streaming_spill_test.exs @@ -123,7 +123,7 @@ defmodule Replicant.StreamingSpillTest do end end - test "an oversized never-committing streamed txn halts fail-closed :sink_too_slow (the §4 backstop pre-empts the deferred disk-ceiling halt) and cleans up", + test "an oversized streamed transaction halts on disk exhaustion and cleans up", %{ ctrl: ctrl, slot: slot, @@ -135,7 +135,7 @@ defmodule Replicant.StreamingSpillTest do :telemetry.attach( {__MODULE__, ref, :disc}, - [:replicant, :connection, :disconnected], + [:replicant, :stream, :spill_exhausted], fn _e, _m, meta, _ -> send(test_pid, {:disc, ref, meta}) end, nil ) @@ -146,14 +146,7 @@ defmodule Replicant.StreamingSpillTest do Postgrex.transaction(ctrl, fn c -> bulk_insert(c, 40_000) end, timeout: 120_000) - # A single in-progress txn far larger than max_inflight_lag + max_spill_bytes arrives as a - # burst: the Connection reads its WAL faster than the assembler spills it, so the §4 - # in-flight-lag backstop (`received − floor − spilled` > RAM + disk) halts fail-closed FIRST. - # The disk-ceiling `:spill_exhausted` halt is DEFERRED to the next StreamCommit — which never - # arrives for a never-committing oversized txn — so it cannot fire here; the disk ceiling is - # covered deterministically at the unit level. Red-capable on the halt REASON (a wrong-reason - # halt would fail this), unlike the prior registry-only assertion. - assert_receive {:disc, ^ref, %{reason: :sink_too_slow}}, 20_000 + assert_receive {:disc, ^ref, %{reason: :spill_exhausted}}, 20_000 PG16.wait_until( fn -> Registry.lookup(Replicant.Registry, {slot, :pipeline}) == [] end, @@ -165,6 +158,47 @@ defmodule Replicant.StreamingSpillTest do end end + test "32 MiB non-streamed transaction fits the spill-enabled compatibility allowance", + %{ctrl: ctrl, slot: slot, spill_dir: spill_dir} do + Postgrex.query!(ctrl, "ALTER ROLE CURRENT_USER SET logical_decoding_work_mem = '64MB'", []) + Postgrex.query!(ctrl, "ALTER TABLE sp_orders ADD COLUMN payload text", []) + ref = make_ref() + owner = self() + + :telemetry.attach_many( + {__MODULE__, ref}, + [ + [:replicant, :transaction, :assembled], + [:replicant, :stream, :committed], + [:replicant, :stream, :spilled] + ], + fn event, _, metadata, _ -> send(owner, {ref, event, metadata}) end, + nil + ) + + on_exit(fn -> :telemetry.detach({__MODULE__, ref}) end) + + start_pipeline(slot, spill_dir, + max_inflight_lag: 16 * 1024 * 1024, + max_spill_bytes: 64 * 1024 * 1024 + ) + + Postgrex.query!( + ctrl, + "INSERT INTO sp_orders SELECT id, repeat('test-payload-', 21846) FROM generate_series(1, 128) id", + [], + timeout: 30_000 + ) + + PG16.wait_until(fn -> MapSet.size(row_ids(ctrl)) == 128 end, 1200) + assert calls_count(ctrl) == 1 + assert_receive {^ref, [:replicant, :transaction, :assembled], %{byte_size: bytes}} + assert bytes > 32 * 1024 * 1024 + refute_received {^ref, [:replicant, :stream, :committed], _} + refute_received {^ref, [:replicant, :stream, :spilled], _} + assert spill_files(spill_dir, slot) == [] + end + defp start_pipeline(slot, spill_dir, opts) do ref = make_ref() test_pid = self() diff --git a/test/replicant/assembler_server_test.exs b/test/replicant/assembler_server_test.exs index 365b35b..b4d24ca 100644 --- a/test/replicant/assembler_server_test.exs +++ b/test/replicant/assembler_server_test.exs @@ -89,6 +89,37 @@ defmodule Replicant.AssemblerServerTest do refute :sys.get_state(pid).halted end + test "an oversized unspillable transaction halts without processing credit or durable ack" do + {:ok, pid} = + AssemblerServer.start_link( + slot_name: "srv_budget", + sink: RecordingSink, + max_inflight_lag: 50 + ) + + epoch = make_ref() + message = %Begin{final_lsn: 0x2A, commit_timestamp: ~U[2026-07-04 00:00:00Z], xid: 7} + queue = :atomics.new(1, []) + :atomics.put(queue, 1, 1) + GenServer.cast(pid, {:message, message, 60, self(), {epoch, 60, 1, queue}}) + assert :sys.get_state(pid).halted + refute_received {:assembler_processed, _, _, _} + refute_received {:sink_committed, _} + assert RecordingSink.seen() == [] + end + + test "processing credits do not acknowledge an uncommitted transaction" do + pid = start("srv_credit", RecordingSink) + epoch = make_ref() + message = %Begin{final_lsn: 0x2A, commit_timestamp: ~U[2026-07-04 00:00:00Z], xid: 7} + queue = :atomics.new(1, []) + :atomics.put(queue, 1, 1) + GenServer.cast(pid, {:message, message, 20, self(), {epoch, 20, 1, queue}}) + assert_receive {:assembler_processed, ^epoch, 20, 1} + refute_received {:sink_committed, _} + assert :sys.get_state(pid).asm.txn != nil + end + test "the ack advances to txn.commit_lsn, NEVER a higher sink-returned LSN (no over-advance loss)" do pid = start("srv_wrong_lsn", WrongHighLsnSink) cast(pid, %Begin{final_lsn: 0x2A, commit_timestamp: ~U[2026-07-04 00:00:00Z], xid: 7}, 20) @@ -609,7 +640,7 @@ defmodule Replicant.AssemblerServerTest do alias Replicant.Decoder.Messages.Relation alias Replicant.Decoder.Messages.Relation.Column - test "the server builds a spill-capable assembler and signals {:spilled_bytes, total} to the connection after a spill" do + test "the server builds a spill-capable assembler and accounts its retained payload" do base = Path.join(System.tmp_dir!(), "srv_spill_#{System.unique_integer([:positive])}") on_exit(fn -> File.rm_rf(base) end) @@ -643,16 +674,13 @@ defmodule Replicant.AssemblerServerTest do {:message, %Insert{xid: 100, relation_id: 1, tuple_data: {"#{v}"}}, 60, self()} ) - # The AssemblerServer signals the Connection via a PLAIN send → its handle_info substrate - # (the same idiom the existing dispatch/3 uses for {:sink_committed, lsn}). Task 10's - # Connection handles {:spilled_bytes, total} in handle_info. So assert the plain message, - # NOT a {:"$gen_cast", ...} wrapper. The 2s budget (not the 100ms default) matches - # the sibling spill asserts below: the spill is real file I/O, and a loaded host - # pages it out past 100ms without any defect (OBSERVED under load, 2026-09-30). - assert_receive {:spilled_bytes, total} when total > 0, 2_000 + state = :sys.get_state(pid) + assert state.asm.spilled_total > 0 + assert Replicant.Assembler.buffered_bytes(state.asm) <= 100 + refute state.halted end - test "a spilled txn COMMITTING re-casts {:spilled_bytes} with the LOWER total (frees disk bytes; the §4 numerator un-strands after a large spilled txn commits)" do + test "committing a spilled transaction releases its retained payload and disk usage" do base = Path.join(System.tmp_dir!(), "srv_spdec_#{System.unique_integer([:positive])}") on_exit(fn -> File.rm_rf(base) end) @@ -694,20 +722,18 @@ defmodule Replicant.AssemblerServerTest do GenServer.cast(pid, {:message, %Replicant.Decoder.Messages.StreamStop{}, 4, self()}) - # The spill fires → an INCREASE cast (2s budget: real file I/O under host load). - assert_receive {:spilled_bytes, up} when up > 0, 2_000 + assert :sys.get_state(pid).asm.spilled_total > 0 - # The commit delivers the spilled txn and frees its disk bytes → spilled_total drops → a NET - # re-cast with the LOWER total (RED before the CV3 fix cast the delta, not the net total — - # the numerator would strand stale-high after the commit). GenServer.cast( pid, {:message, %StreamCommit{xid: 100, commit_lsn: 900, end_lsn: 901, commit_timestamp: nil}, 8, self()} ) - assert_receive {:spilled_bytes, down} when down < up, 2_000 - assert :sys.get_state(pid).asm.spilled_total == down + assert_receive {:sink_committed, 900} + state = :sys.get_state(pid) + assert state.asm.spilled_total == 0 + assert Replicant.Assembler.buffered_bytes(state.asm) == 0 end test "a SINGLE row larger than max_inflight_lag spills — the bound-crossing change is appended BEFORE the spill trigger runs (CV2)" do @@ -815,11 +841,7 @@ defmodule Replicant.AssemblerServerTest do ) # Force the spill and capture the on-disk file path from xid 100's stream buffer. - # The 2000ms window (not the 100ms default) is load tolerance, not a weaker - # assertion: the casts are already in the server's mailbox and the signal MUST - # arrive — under a saturated test VM the 100ms window flaked 1-in-5 (OBSERVED - # 2026-09-30) while the spill always landed. - assert_receive {:spilled_bytes, total} when total > 0, 2_000 + assert :sys.get_state(pid).asm.spilled_total > 0 state = :sys.get_state(pid) spill_path = state.asm.stream_txns[100].spill.path assert File.exists?(spill_path) @@ -1200,21 +1222,29 @@ defmodule Replicant.AssemblerServerTest do assert {:ok, {:ok, _epoch}} = Task.yield(task, 1_000) || Task.shutdown(task) end - test "F-PACE: open_snapshot_window IS still deferred when the frontier gap from the floor exceeds max_inflight_lag/2" do - # Same absolute floor, but the frontier is 600_000 above it — OVER the 500_000 gate. The gate - # still fires (stream drain has genuine priority) → the call is DEFERRED (no reply). This half - # proves the fix did not defeat the pacing gate (the estimate is now floor-relative, not 0). + test "snapshot pacing waits for queued work, not an idle open transaction" do pid = start_incremental_server(ChunkLedgerSink, "asrv_pace_defer") - floor = 1_000_000_000 - GenServer.cast(pid, {:snapshot_floor, floor}) - GenServer.cast(pid, {:snapshot_frontier, 0, floor + 600_000}) - :sys.get_state(pid) + + flow = + Replicant.FlowControl.new() + |> Replicant.FlowControl.push(20) + |> Replicant.FlowControl.push(8) + + begin = %Begin{final_lsn: 600_000, commit_timestamp: ~U[2026-07-04 00:00:00Z], xid: 7} + GenServer.cast(pid, {:message, begin, 20, self(), {flow.epoch, 20, 1, flow.queue}}) + assert_receive {:assembler_processed, _, 20, 1} task = Task.async(fn -> Replicant.AssemblerServer.open_snapshot_window(pid, "public.orders") end) - refute Task.yield(task, 300) - Task.shutdown(task, :brutal_kill) + refute Task.yield(task, 100) + + GenServer.cast( + pid, + {:message, %Commit{lsn: 600_000}, 8, self(), {flow.epoch, 28, 2, flow.queue}} + ) + + assert {:ok, _epoch} = Task.await(task) end test "F-TAINT lib+batch: a stream write to an UNTRACKED table leaves a cold backfill table's chunk intact (drop-filter no-op, not taint-all)" do diff --git a/test/replicant/backpressure_regression_test.exs b/test/replicant/backpressure_regression_test.exs new file mode 100644 index 0000000..5c301c4 --- /dev/null +++ b/test/replicant/backpressure_regression_test.exs @@ -0,0 +1,209 @@ +defmodule Replicant.BackpressureRegressionTest do + use ExUnit.Case, async: true + + alias Replicant.{Assembler, AssemblerServer} + + alias Replicant.Decoder.Messages.{ + Begin, + Commit, + Insert, + Message, + Relation, + StreamAbort, + StreamStart, + StreamStop + } + + alias Replicant.Decoder.Messages.Relation.Column + + defmodule Sink do + @behaviour Replicant.Sink + def checkpoint, do: {:ok, nil} + def handle_transaction(txn), do: {:ok, txn.commit_lsn} + def handle_batch(txns), do: {:ok, List.last(txns).commit_lsn} + end + + defp relation do + %Relation{ + id: 1, + namespace: "public", + name: "t", + replica_identity: :default, + columns: [%Column{name: "id", type: "int4", flags: [:key], type_modifier: -1}] + } + end + + defp handle(asm, msg, bytes) do + {:ok, asm} = Assembler.handle_message(asm, msg) + Assembler.observe_bytes(asm, bytes) + end + + setup do + dir = Path.join(System.tmp_dir!(), "pressure_#{System.unique_integer([:positive])}") + on_exit(fn -> File.rm_rf!(dir) end) + + asm = + Assembler.new(Sink, + slot_name: "pressure", + max_inflight_lag: 1000, + spill: [dir: dir, max_spill_bytes: 1_000_000] + ) + + {:ok, asm} = Assembler.handle_message(asm, relation()) + %{asm: asm, dir: dir} + end + + test "partial abort releases row bytes while top-level message bytes remain", %{asm: asm} do + asm = handle(asm, %StreamStart{xid: 1, first_segment: true}, 0) + asm = handle(asm, %Insert{xid: 2, relation_id: 1, tuple_data: {"2"}}, 800) + + asm = + handle( + asm, + %Message{xid: 1, transactional?: true, prefix: "test", content: "retained"}, + 200 + ) + + {:ok, asm} = Assembler.handle_message(asm, %StreamAbort{xid: 1, subxid: 2}) + assert [%Message{xid: 1}] = asm.stream_txns[1].messages + assert Assembler.buffered_bytes(asm) == 200 + asm = handle(asm, %Insert{xid: 1, relation_id: 1, tuple_data: {"1"}}, 800) + assert asm.stream_txns[1].spill == nil + Assembler.reset_streams(asm) + end + + test "message-heavy stream cannot prevent spilling a different stream", %{asm: asm} do + asm = handle(asm, %StreamStart{xid: 1, first_segment: true}, 0) + + asm = + handle( + asm, + %Message{ + xid: 1, + transactional?: true, + prefix: "test", + content: String.duplicate("x", 650) + }, + 700 + ) + + {:ok, asm} = Assembler.handle_message(asm, %StreamStop{}) + asm = handle(asm, %StreamStart{xid: 2, first_segment: true}, 0) + asm = handle(asm, %Insert{xid: 2, relation_id: 1, tuple_data: {"2"}}, 400) + assert Assembler.buffered_bytes(asm) <= 1000 + assert asm.stream_txns[1].spill == nil + assert asm.stream_txns[2].spill != nil + Assembler.reset_streams(asm) + end + + test "spill repeats until all reclaimable tails fit", %{asm: asm} do + asm = %{asm | max_inflight_lag: 2000} + asm = handle(asm, %StreamStart{xid: 1, first_segment: true}, 0) + + asm = + handle(asm, %Message{xid: 1, transactional?: true, prefix: "test", content: "keep"}, 600) + + asm = handle(asm, %Insert{xid: 1, relation_id: 1, tuple_data: {"1"}}, 400) + {:ok, asm} = Assembler.handle_message(asm, %StreamStop{}) + asm = handle(asm, %StreamStart{xid: 2, first_segment: true}, 0) + asm = handle(asm, %Insert{xid: 2, relation_id: 1, tuple_data: {"2"}}, 350) + {:ok, asm} = Assembler.Streaming.maybe_spill(%{asm | max_inflight_lag: 900}) + assert Assembler.buffered_bytes(asm) == 600 + assert asm.stream_txns[1].spill != nil + assert asm.stream_txns[2].spill != nil + Assembler.reset_streams(asm) + end + + test "buffer-triggered flush never re-tracks an earlier receipt in a new window" do + slot = "pressure_#{System.unique_integer([:positive])}" + + pid = + start_supervised!( + {AssemblerServer, + slot_name: slot, + sink: Sink, + max_inflight_lag: 1000, + batch: [max_transactions: 100, max_delay_ms: 60_000, max_span: 1_000_000], + snapshot_window: [chunk_rows: 10, max_pending_chunks: 2]} + ) + + for msg <- [ + %Begin{final_lsn: 100, xid: 1}, + relation(), + %Insert{relation_id: 1, tuple_data: {"1"}}, + %Commit{lsn: 100} + ] do + GenServer.cast(pid, {:message, msg, 10, self()}) + end + + asm = :sys.get_state(pid).asm + assert asm.batch_bytes == Enum.reduce(asm.batch_txns, 0, &(:erlang.external_size(&1) + &2)) + assert asm.batch_bytes > 200 + assert Assembler.reset_batch(asm).batch_bytes == 0 + assert {:ok, 0} = AssemblerServer.open_snapshot_window(pid, "public.t") + GenServer.cast(pid, {:message, %Begin{final_lsn: 200, xid: 2}, 800, self()}) + assert_receive {:sink_committed, 100} + state = :sys.get_state(pid) + refute state.halted + assert state.asm.batch_bytes == 0 + assert state.asm.txn.byte_size == 800 + assert MapSet.size(state.window.tracking["public.t"].pks) == 0 + + for msg <- [%Insert{relation_id: 1, tuple_data: {"2"}}, %Commit{lsn: 200}] do + GenServer.cast(pid, {:message, msg, 10, self()}) + end + + state = :sys.get_state(pid) + assert state.asm.batch_bytes > 0 + assert MapSet.size(state.window.tracking["public.t"].pks) == 1 + end + + test "non-streamed transaction retains spill-enabled compatibility allowance", %{dir: dir} do + slot = "pressure_#{System.unique_integer([:positive])}" + + pid = + start_supervised!( + {AssemblerServer, + slot_name: slot, + sink: Sink, + max_inflight_lag: 100, + streaming: [spill: [dir: dir, max_spill_bytes: 1000]]} + ) + + for {msg, bytes} <- [ + {%Begin{final_lsn: 100, xid: 1}, 10}, + {relation(), 10}, + {%Insert{relation_id: 1, tuple_data: {"1"}}, 200}, + {%Commit{lsn: 100}, 10} + ] do + GenServer.cast(pid, {:message, msg, bytes, self()}) + end + + assert_receive {:sink_committed, 100} + refute :sys.get_state(pid).halted + end + + test "open streamed transaction does not starve an idle snapshot window" do + slot = "pressure_#{System.unique_integer([:positive])}" + + pid = + start_supervised!( + {AssemblerServer, + slot_name: slot, + sink: Sink, + max_inflight_lag: 1000, + snapshot_window: [chunk_rows: 10, max_pending_chunks: 2]} + ) + + for {msg, bytes} <- [ + {%StreamStart{xid: 1, first_segment: true}, 0}, + {relation(), 0}, + {%Insert{xid: 1, relation_id: 1, tuple_data: {"1"}}, 600}, + {%StreamStop{}, 0} + ] do + GenServer.cast(pid, {:message, msg, bytes, self()}) + end + + assert {:ok, 0} = GenServer.call(pid, {:open_snapshot_window, "public.t"}, 1000) + end +end diff --git a/test/replicant/config_test.exs b/test/replicant/config_test.exs index 769276f..c424e5a 100644 --- a/test/replicant/config_test.exs +++ b/test/replicant/config_test.exs @@ -28,6 +28,20 @@ defmodule Replicant.ConfigTest do alias Replicant.Config + test "receive silence timeout has a bounded default and an explicit opt-out" do + opts = base_opts() ++ [sink: StateMirrorPersisted] + assert {:ok, %{receive_timeout: 60_000}} = Config.validate(opts) + + assert {:ok, %{receive_timeout: :infinity}} = + Config.validate(opts ++ [receive_timeout: :infinity]) + + assert {:ok, %{receive_timeout: 800}} = Config.validate(opts ++ [receive_timeout: 800]) + + for invalid <- [nil, false, 0, -1, 1, "800", 0.5] do + assert {:error, :config_invalid} = Config.validate(opts ++ [receive_timeout: invalid]) + end + end + # --- stub sinks (each a minimal valid Replicant.Sink) --- defmodule StateMirrorEmpty do diff --git a/test/replicant/connection_buffer_accounting_test.exs b/test/replicant/connection_buffer_accounting_test.exs new file mode 100644 index 0000000..664a4a2 --- /dev/null +++ b/test/replicant/connection_buffer_accounting_test.exs @@ -0,0 +1,180 @@ +defmodule Replicant.ConnectionBufferAccountingTest do + use ExUnit.Case, async: false + + alias Replicant.Connection + alias Replicant.Decoder.Wal2json + + test "payload bytes pause intake until the assembler drains without advancing the checkpoint" do + slot = "buffer_pause_#{System.unique_integer([:positive])}" + {:ok, _} = Registry.register(Replicant.Registry, {slot, :assembler}, nil) + payload = <> + + state = %Connection{ + slot_name: slot, + checkpoint_lsn: 1_000, + max_inflight_lag: byte_size(payload) + } + + assert {:pause, state} = Connection.handle_data(frame(payload), state) + assert_receive {:"$gen_cast", {:message, _, _, _, {epoch, bytes, messages, _queue}}} + assert state.flow.paused + assert state.checkpoint_lsn == 1_000 + + assert {:noreply, unchanged} = + Connection.handle_info({:assembler_processed, make_ref(), bytes, messages}, state) + + assert unchanged == state + + {_timer, token} = state.flow.timer + + assert {:noreply, [ack], state} = + Connection.handle_info({:flow_feedback, epoch, token}, state) + + assert <> = IO.iodata_to_binary(ack) + + assert {:resume, state} = + Connection.handle_info({:assembler_processed, epoch, bytes, messages}, state) + + assert state.flow.timer == nil + refute state.flow.paused + assert state.checkpoint_lsn == 1_000 + assert {:noreply, ^state} = Connection.handle_info({:flow_feedback, epoch, token}, state) + end + + test "message count bounds a queue of tiny messages" do + slot = "buffer_count_#{System.unique_integer([:positive])}" + {:ok, _} = Registry.register(Replicant.Registry, {slot, :assembler}, nil) + state = %Connection{slot_name: slot} + payload = <> + + state = + Enum.reduce(1..511, state, fn _, state -> + assert {:noreply, state} = Connection.handle_data(frame(payload), state) + state + end) + + assert {:pause, state} = Connection.handle_data(frame(payload), state) + assert Replicant.FlowControl.queued_messages(state.flow) == 512 + assert {:noreply, state} = Connection.handle_disconnect(state) + refute state.flow.paused + assert Replicant.FlowControl.queued_messages(state.flow) == 512 + end + + test "a WAL segment gap is not buffered transaction data" do + slot = "buffer_gap_#{System.unique_integer([:positive])}" + {:ok, _} = Registry.register(Replicant.Registry, {slot, :assembler}, nil) + + state = %Connection{ + slot_name: slot, + checkpoint_lsn: 1_000, + checkpoint_state: :present, + max_inflight_lag: 1_024 + } + + commit_lsn = 128 * 1_024 * 1_024 + begin_payload = <> + commit_payload = <> + + assert {:noreply, state} = + Connection.handle_data( + <>, + state + ) + + assert {:noreply, state} = + Connection.handle_data( + <>, + state + ) + + assert state.checkpoint_lsn == 1_000 + assert_receive {:"$gen_cast", {:message, %Replicant.Decoder.Messages.Begin{}, _, _, _}} + assert_receive {:"$gen_cast", {:message, %Replicant.Decoder.Messages.Commit{}, _, _, _}} + end + + test "a pending sink commit keeps keepalive acknowledgement at the durable checkpoint" do + slot = "buffer_pending_#{System.unique_integer([:positive])}" + {:ok, _} = Registry.register(Replicant.Registry, {slot, :assembler}, nil) + + state = %Connection{ + slot_name: slot, + checkpoint_lsn: 1_000, + checkpoint_state: :present, + in_txn: true, + last_commit_lsn: 1_000, + stream_floor_lsn: 1_000, + max_inflight_lag: 1_024 + } + + commit_lsn = 128 * 1_024 * 1_024 + commit_payload = <> + + assert {:noreply, state} = + Connection.handle_data( + <>, + state + ) + + assert {:noreply, [ack], _state} = + Connection.handle_data(<>, state) + + assert <> = + IO.iodata_to_binary(ack) + end + + test "a wal2json payload counts bytes once and credits both ordered messages" do + slot = "buffer_plugin_#{System.unique_integer([:positive])}" + {:ok, _} = Registry.register(Replicant.Registry, {slot, :assembler}, nil) + + payload = + "test/fixtures/wal2json_pg12.jsons" + |> File.read!() + |> String.split("\n", trim: true) + |> Enum.find(&(Jason.decode!(&1)["action"] == "I")) + + bytes = byte_size(payload) + state = %Connection{slot_name: slot, max_inflight_lag: bytes} + decoder = %{state.decoder | kind: :wal2json, cache: Wal2json.init_cache([])} + assert {:pause, state} = Connection.handle_data(frame(payload), %{state | decoder: decoder}) + + assert_receive {:"$gen_cast", + {:message, %Replicant.Decoder.Messages.Relation{}, ^bytes, _, + {epoch, ^bytes, 1, queue}}} + + assert_receive {:"$gen_cast", + {:message, %Replicant.Decoder.Messages.Insert{}, 0, _, + {^epoch, ^bytes, 2, ^queue}}} + + assert Replicant.FlowControl.queued_bytes(state.flow) == bytes + assert Replicant.FlowControl.queued_messages(state.flow) == 2 + + assert {:resume, state} = + Connection.handle_info({:assembler_processed, epoch, bytes, 2}, state) + + assert Replicant.FlowControl.queued_bytes(state.flow) == 0 + assert Replicant.FlowControl.queued_messages(state.flow) == 0 + end + + test "only fresh completed-frame credits reset the stall clock, and stale timers are ignored" do + alias Replicant.FlowControl + flow = FlowControl.new() |> FlowControl.push(20) |> FlowControl.push(30) + old = System.monotonic_time(:millisecond) - 10_000 + flow = %{flow | stall_since: old} + assert FlowControl.processed(flow, make_ref(), 20, 1).stall_since == old + assert FlowControl.processed(flow, flow.epoch, 0, 0).stall_since == old + advanced = FlowControl.processed(flow, flow.epoch, 20, 1) + assert advanced.stall_since > old + assert FlowControl.processed(advanced, flow.epoch, 20, 1) == advanced + assert FlowControl.processed(advanced, flow.epoch, 50, 2).stall_since == nil + token = make_ref() + state = %Connection{flow: %{flow | stall_timer: {make_ref(), token}}} + + assert {:noreply, ^state} = + Connection.handle_info({:assembler_stall, make_ref(), token}, state) + + assert {:noreply, ^state} = + Connection.handle_info({:assembler_stall, flow.epoch, make_ref()}, state) + end + + defp frame(payload), do: <> +end diff --git a/test/replicant/connection_test.exs b/test/replicant/connection_test.exs index 511e8a2..5c15ee6 100644 --- a/test/replicant/connection_test.exs +++ b/test/replicant/connection_test.exs @@ -239,7 +239,9 @@ defmodule Replicant.ConnectionTest do last_commit_lsn: 0x1000 ) - assert {:noreply, ^st} = Connection.handle_data(<>, st) + assert {:noreply, updated} = Connection.handle_data(<>, st) + assert %{updated | flow: st.flow} == st + assert is_integer(updated.flow.last_received) end test "IDLE + no reply requested: VOLUNTEERS a status update acking wal_end (A1)" do @@ -317,7 +319,9 @@ defmodule Replicant.ConnectionTest do state(checkpoint_lsn: 0x1000, received_lsn: 0x1000, in_txn: true, last_commit_lsn: 0x1000) keepalive = <> - assert {:noreply, ^st} = Connection.handle_data(keepalive, st) + assert {:noreply, updated} = Connection.handle_data(keepalive, st) + assert %{updated | flow: st.flow} == st + assert is_integer(updated.flow.last_received) end test "IDLE but wal_end <= checkpoint + no reply: no redundant send" do @@ -330,7 +334,9 @@ defmodule Replicant.ConnectionTest do ) keepalive = <> - assert {:noreply, ^st} = Connection.handle_data(keepalive, st) + assert {:noreply, updated} = Connection.handle_data(keepalive, st) + assert %{updated | flow: st.flow} == st + assert is_integer(updated.flow.last_received) end test "ordering invariant (A1 §3.2): a Begin forwarded via forward_message blocks the next keepalive's idle-ack" do @@ -378,7 +384,7 @@ defmodule Replicant.ConnectionTest do begin_payload = <<"B", 0::64, 0::64, 7::32>> frame = <> assert {:noreply, _} = Connection.handle_data(frame, advanced) - assert_receive {:"$gen_cast", {:message, %Begin{xid: 7}, _b, _f}} + assert_receive {:"$gen_cast", {:message, %Begin{xid: 7}, _b, _f, _credit}} end end @@ -438,7 +444,7 @@ defmodule Replicant.ConnectionTest do xlog = <> assert {:noreply, _state} = Connection.handle_data(xlog, state(slot_name: "conn_xlog")) - assert_receive {:"$gen_cast", {:message, %Begin{xid: 7}, bytes, from}} + assert_receive {:"$gen_cast", {:message, %Begin{xid: 7}, bytes, from, _credit}} assert bytes == byte_size(begin_payload) assert from == self() end @@ -471,7 +477,7 @@ defmodule Replicant.ConnectionTest do assert {:noreply, new_state} = Connection.handle_data(xlog, st) assert new_state.received_lsn == 50_000_000 assert new_state.stream_floor_lsn == 50_000_000 - assert_receive {:"$gen_cast", {:message, %Begin{xid: 7}, _bytes, _from}} + assert_receive {:"$gen_cast", {:message, %Begin{xid: 7}, _bytes, _from, _credit}} end test "an XLogData whose lag over the stream floor is at/under the bound still forwards" do @@ -490,14 +496,14 @@ defmodule Replicant.ConnectionTest do assert {:noreply, new_state} = Connection.handle_data(xlog, st) assert new_state.received_lsn == 1100 - assert_receive {:"$gen_cast", {:message, %Begin{xid: 7}, _bytes, _from}} + assert_receive {:"$gen_cast", {:message, %Begin{xid: 7}, _bytes, _from, _credit}} end end # ---- §4 bounded in-flight window / fail-closed sink-lag halt ---- describe "handle_data(XLogData) — bounded in-flight window (spec §4)" do - test "over-bound in-flight lag halts fail-closed with :sink_too_slow and forwards nothing" do + test "a WAL-position gap does not halt a small payload" do :telemetry.attach( {__MODULE__, :too_slow}, [:replicant, :connection, :disconnected], @@ -507,7 +513,7 @@ defmodule Replicant.ConnectionTest do {:ok, _} = Registry.register(Replicant.Registry, {"conn_slow", :assembler}, nil) begin_payload = <<"B", 0::64, 0::64, 7::32>> - # floor 1000, wal_end 1201, checkpoint 0, bound 100 → lag 201 > 100 → halt. + # The position gap exceeds the payload budget, but contains no buffered bytes. xlog = <> st = @@ -518,14 +524,14 @@ defmodule Replicant.ConnectionTest do max_inflight_lag: 100 ) - assert {:disconnect, :sink_too_slow} = Connection.handle_data(xlog, st) - - assert_received {:disc, %{lag: 201}, %{reason: :sink_too_slow}} - refute_received {:"$gen_cast", _} + assert {:noreply, state} = Connection.handle_data(xlog, st) + assert Replicant.FlowControl.queued_bytes(state.flow) == byte_size(begin_payload) + refute_received {:disc, _, _} + assert_received {:"$gen_cast", {:message, %Begin{}, _, _, _}} :telemetry.detach({__MODULE__, :too_slow}) end - test "lag is measured against the durable checkpoint once it advances past the floor" do + test "a durable checkpoint does not turn WAL-position lag into buffered bytes" do :telemetry.attach( {__MODULE__, :cp_floor}, [:replicant, :connection, :disconnected], @@ -535,8 +541,7 @@ defmodule Replicant.ConnectionTest do {:ok, _} = Registry.register(Replicant.Registry, {"conn_cpfloor", :assembler}, nil) begin_payload = <<"B", 0::64, 0::64, 7::32>> - # checkpoint has advanced to 5000 (a real commit LSN) above the 1000 floor; - # wal_end 5150 → lag = 5150 - max(5000, 1000) = 150 > 100 → halt. + # Checkpoint and WAL-frontier bookkeeping must remain independent of credits. xlog = <> st = @@ -547,8 +552,10 @@ defmodule Replicant.ConnectionTest do max_inflight_lag: 100 ) - assert {:disconnect, :sink_too_slow} = Connection.handle_data(xlog, st) - assert_received {:disc, %{lag: 150}, %{reason: :sink_too_slow}} + assert {:noreply, state} = Connection.handle_data(xlog, st) + assert state.checkpoint_lsn == 5000 + assert Replicant.FlowControl.queued_bytes(state.flow) == byte_size(begin_payload) + refute_received {:disc, _, _} :telemetry.detach({__MODULE__, :cp_floor}) end @@ -1811,14 +1818,18 @@ defmodule Replicant.ConnectionTest do refute_received :checkpoint_read end - test "a reconnect resets the spilled_bytes mirror to 0 (never carries a stale-high value)" do - # init/1 runs ONCE; RECONNECTS re-enter through handle_connect/1. The assembler zeroes its - # spilled_total on reconnect (reset_streams), but the {:spilled_bytes,_} signal only fires on - # a CHANGE during message observation — never on reset. So handle_connect MUST re-zero the - # Connection's mirror, or a stale-high spilled_bytes over-subtracts the §4 numerator and a - # slow-sink reconnect that does not re-spill evades the RAM-bound halt indefinitely. + test "recovery starts a fresh processing-credit generation" do + flow = Replicant.FlowControl.push(Replicant.FlowControl.new(), 4242) + + {:noreply, waiting} = Connection.handle_connect(state(flow: flow, step: :disconnected)) + assert waiting.step == :draining_assembler + assert Replicant.FlowControl.queued_bytes(waiting.flow) == 4242 + + assert {:noreply, ^waiting} = + Connection.handle_info({:assembler_drained, make_ref()}, waiting) + {:query, _sql, identity_state} = - Connection.handle_connect(state(spill: %{bytes: 4242, max: nil}, step: :disconnected)) + Connection.handle_info({:assembler_drained, waiting.flow.reconnect_barrier}, waiting) identity_result = [ %Postgrex.Result{rows: [["7436598280501831754", "7", "0/16B6C50", "source_db"]]} @@ -1826,7 +1837,8 @@ defmodule Replicant.ConnectionTest do {:query, _sql, new_state} = Connection.handle_result(identity_result, identity_state) - assert new_state.spill.bytes == 0 + assert Replicant.FlowControl.queued_bytes(new_state.flow) == 0 + refute new_state.flow.epoch == flow.epoch end test "recovery_check emits [:connection, :connected] with the source kind" do @@ -1990,12 +2002,12 @@ defmodule Replicant.ConnectionTest do assert {:noreply, s1} = Replicant.Connection.handle_data(start_frame, st_state("conn_st", :streaming)) - assert_receive {:"$gen_cast", {:message, %StreamStart{xid: 100}, _, _}} + assert_receive {:"$gen_cast", {:message, %StreamStart{xid: 100}, _, _, _}} assert s1.in_stream == true stop_frame = <> assert {:noreply, s2} = Replicant.Connection.handle_data(stop_frame, s1) - assert_receive {:"$gen_cast", {:message, %StreamStop{}, _, _}} + assert_receive {:"$gen_cast", {:message, %StreamStop{}, _, _, _}} assert s2.in_stream == false end @@ -2028,7 +2040,7 @@ defmodule Replicant.ConnectionTest do end end - describe "spill in-flight-lag accounting (spec §4/§9)" do + describe "payload accounting with streaming enabled" do defp sp_state(slot, extra \\ %{}) do Map.merge( %Replicant.Connection{ @@ -2043,7 +2055,6 @@ defmodule Replicant.ConnectionTest do received_lsn: 0, stream_floor_lsn: 0, in_stream: false, - spill: %{bytes: 0, max: 500}, max_inflight_lag: 100, step: :streaming }, @@ -2051,37 +2062,31 @@ defmodule Replicant.ConnectionTest do ) end - test "the halt ceiling is max_inflight_lag + max_spill_bytes (RAM + disk)" do - # received-floor 620, spilled 0 → resident lag 620 > 100 + 500 = 600 → halt - s = %{sp_state("c2") | received_lsn: 620, spill: %{sp_state("c2").spill | bytes: 0}} + test "disk budget does not turn an LSN gap into queued work" do + {:ok, _} = Registry.register(Replicant.Registry, {"c2", :assembler}, nil) + s = %{sp_state("c2") | received_lsn: 620} frame = <> - assert {:disconnect, :sink_too_slow} = Replicant.Connection.handle_data(frame, s) + assert {:noreply, state} = Replicant.Connection.handle_data(frame, s) + assert Replicant.FlowControl.queued_bytes(state.flow) == 1 end - test "spilled bytes lower the numerator so the SAME frame that halts at spilled=0 forwards when spilled is high" do - # WITHOUT the -spilled subtraction, received-floor 620 halts; WITH spilled=550, - # 620-550=70 < 600 → no halt (forwards) + test "spill accounting cannot release assembler mailbox credits" do {:ok, _} = Registry.register(Replicant.Registry, {"c2b", :assembler}, nil) - s = %{sp_state("c2b") | received_lsn: 620, spill: %{sp_state("c2b").spill | bytes: 550}} + s = %{sp_state("c2b") | received_lsn: 620} frame = <> - refute match?({:disconnect, :sink_too_slow}, Replicant.Connection.handle_data(frame, s)) - end - - test "a {:spilled_bytes, total} message updates the connection's spilled counter (handled, not swallowed by the catch-all)" do - s = sp_state("c3") - assert {:noreply, s2} = Replicant.Connection.handle_info({:spilled_bytes, 400}, s) - assert s2.spill.bytes == 400 + assert {:noreply, state} = Replicant.Connection.handle_data(frame, s) + assert Replicant.FlowControl.queued_bytes(state.flow) == 1 + assert {:noreply, ^state} = Replicant.Connection.handle_info({:spilled_bytes, 550}, state) end - test "a NON-spill connection (max_spill_bytes: nil) halts at EXACTLY max_inflight_lag (ceiling unchanged)" do - # No spill config → max_spill_bytes nil → effective_lag_bound returns the base - # max_inflight_lag verbatim (byte-identical to the pre-task §4 halt for existing users). + test "a NON-spill connection also accounts payload bytes instead of LSN distance" do {:ok, _} = Registry.register(Replicant.Registry, {"c4", :assembler}, nil) - # floor 500, bound 100 → wal_end 601 gives lag 101 > 100 → halt. + # A one-byte control payload is one queued byte on either side of the old LSN limit. halt_state = state(slot_name: "c4", stream_floor_lsn: 500, max_inflight_lag: 100) halt_frame = <> - assert {:disconnect, :sink_too_slow} = Connection.handle_data(halt_frame, halt_state) + assert {:noreply, state} = Connection.handle_data(halt_frame, halt_state) + assert Replicant.FlowControl.queued_bytes(state.flow) == 1 # wal_end 600 gives lag 100 == bound (not OVER) → forwards. fwd_state = state(slot_name: "c4", stream_floor_lsn: 500, max_inflight_lag: 100) diff --git a/test/replicant/flow_control_test.exs b/test/replicant/flow_control_test.exs new file mode 100644 index 0000000..e7801f9 --- /dev/null +++ b/test/replicant/flow_control_test.exs @@ -0,0 +1,19 @@ +defmodule Replicant.FlowControlTest do + use ExUnit.Case, async: true + alias Replicant.FlowControl + + test "only cumulative credits from the current generation release queued bytes" do + flow = FlowControl.new() |> FlowControl.push(100) |> FlowControl.push(200) + assert FlowControl.full?(flow, 300) + assert flow == FlowControl.processed(flow, make_ref(), 300, 2) + assert flow == FlowControl.processed(flow, flow.epoch, 301, 2) + assert flow == FlowControl.processed(flow, flow.epoch, 300, 3) + flow = FlowControl.processed(flow, flow.epoch, 100, 1) + assert FlowControl.queued_bytes(flow) == 200 + refute FlowControl.drained?(flow, 300) + assert flow == FlowControl.processed(flow, flow.epoch, 0, 0) + flow = FlowControl.processed(flow, flow.epoch, 300, 2) + assert FlowControl.drained?(flow, 300) + assert FlowControl.queued_messages(flow) == 0 + end +end diff --git a/test/support/incremental_snapshot_sink.ex b/test/support/incremental_snapshot_sink.ex index 23cc478..7f1ce7a 100644 --- a/test/support/incremental_snapshot_sink.ex +++ b/test/support/incremental_snapshot_sink.ex @@ -144,7 +144,7 @@ defmodule Replicant.Test.IncrementalSnapshotSink do @impl true def handle_snapshot(changes, %{table: table, first_for_table?: first?} = ctx) do cond do - take_fail_next_chunk?() -> + take_fail_next_chunk?() or take_fail_after_chunks?() -> {:error, :fail_next_chunk} Map.get(ctx, :backfill_complete?, false) and take_fail_completion?() -> @@ -261,6 +261,30 @@ defmodule Replicant.Test.IncrementalSnapshotSink do :ok end + @doc "Fails once after exactly count successful snapshot calls; arm before starting the pipeline." + @spec set_fail_after_chunks(pos_integer()) :: :ok + def set_fail_after_chunks(count) when is_integer(count) and count > 0 do + :ets.insert(@control_table, {:fail_after_chunks, count}) + :ok + end + + # Snapshot calls are serialized by the assembler. Count at the sink boundary + # so a fast backfill cannot complete between a test's poll and fault arming. + defp take_fail_after_chunks? do + case :ets.lookup(@control_table, :fail_after_chunks) do + [{:fail_after_chunks, 0}] -> + :ets.delete(@control_table, :fail_after_chunks) + true + + [{:fail_after_chunks, _remaining}] -> + :ets.update_counter(@control_table, :fail_after_chunks, {2, -1}) + false + + [] -> + false + end + end + # -- internal -------------------------------------------------------------- # Upsert (insert/update) an entry; delete tombstones it (kept, not removed, so the @@ -324,10 +348,9 @@ defmodule Replicant.Test.IncrementalSnapshotSink do end @doc """ - Sets a per-`handle_transaction/1` delay (ms) in the shared control ETS — the §4 `:sink_too_slow` - halt-resume marquee (§12.5): a positive delay makes the applier fall behind so the in-flight lag - trips the bound; a restart with `set_txn_delay(0)` is normal-speed. Persists across pipeline - restarts (the flag lives on the sink-owned Agent, not the pipeline). + Sets a per-`handle_transaction/1` delay (ms) in the shared control ETS. A positive + delay makes queued work fill the intake budget and pause delivery. Setting zero + restores normal speed. The setting persists across pipeline restarts. """ @spec set_txn_delay(non_neg_integer()) :: :ok def set_txn_delay(ms) when is_integer(ms) and ms >= 0 do @@ -381,10 +404,9 @@ end defmodule Replicant.Test.SlowIncrementalSnapshotSink do @moduledoc """ `IncrementalSnapshotSink` with a configurable per-txn delay (`IncrementalSnapshotSink.set_txn_delay/1`) - — the §4 `:sink_too_slow` halt-then-resume marquee (§12.5). Snapshot / progress / checkpoint - delegate to the base sink (shared ETS); `handle_transaction/1` sleeps the configured delay before - applying, so under a tiny `max_inflight_lag` + a heavy writer the in-flight lag trips the §4 bound. - A restart with delay 0 is normal-speed and resumes the backfill from durable progress. + for pause/resume coverage. Snapshot / progress / checkpoint delegate to the base + sink. A tiny payload budget plus a heavy writer pauses intake until the sink + drains; setting delay to zero restores normal speed. """ @behaviour Replicant.Sink diff --git a/test/support/ledger_sink.ex b/test/support/ledger_sink.ex index 08ba40f..5c69a93 100644 --- a/test/support/ledger_sink.ex +++ b/test/support/ledger_sink.ex @@ -111,11 +111,9 @@ end defmodule Replicant.Test.StuckLedgerSink do @moduledoc """ A sink whose `handle_transaction/1` blocks forever, so the AssemblerServer never - drains and the durable checkpoint never advances. Used to prove the fail-closed - sink-lag halt: with the checkpoint pinned, the Connection's in-flight lag - (`received_lsn - max(checkpoint_lsn, stream_floor_lsn)`) grows monotonically past - the ceiling and trips `:sink_too_slow` instead of OOMing. `checkpoint/0` delegates - to `LedgerSink` (a real durable read). + drains and the durable checkpoint never advances. Used to prove bounded intake: + queued payload fills the budget and pauses socket delivery without acknowledging + undelivered WAL. `checkpoint/0` delegates to `LedgerSink` (a real durable read). """ @behaviour Replicant.Sink diff --git a/test/support/silent_proxy.ex b/test/support/silent_proxy.ex new file mode 100644 index 0000000..eb860f1 --- /dev/null +++ b/test/support/silent_proxy.ex @@ -0,0 +1,101 @@ +defmodule Replicant.Test.SilentProxy do + @moduledoc false + use GenServer + + def start_link(opts), do: GenServer.start_link(__MODULE__, opts) + def port(pid), do: GenServer.call(pid, :port) + def blackhole(pid), do: GenServer.call(pid, :blackhole) + + @impl true + def init(opts) do + Process.flag(:trap_exit, true) + {:ok, listener} = :gen_tcp.listen(0, [:binary, active: false, ip: {127, 0, 0, 1}]) + {:ok, {_, port}} = :inet.sockname(listener) + owner = self() + acceptor = spawn_link(fn -> accept(listener, owner, opts) end) + {:ok, %{listener: listener, port: port, acceptor: acceptor, workers: []}} + end + + @impl true + def handle_call(:port, _, state), do: {:reply, state.port, state} + + def handle_call(:blackhole, _, state) do + Enum.each(state.workers, fn worker -> + if Process.alive?(worker) do + ref = make_ref() + send(worker, {:blackhole, self(), ref}) + + receive do + {:blackholed, ^ref} -> :ok + after + 1000 -> raise "proxy did not blackhole" + end + end + end) + + {:reply, :ok, state} + end + + @impl true + def handle_info({:worker, pid}, state), + do: {:noreply, %{state | workers: [pid | state.workers]}} + + def handle_info({:EXIT, pid, reason}, %{acceptor: pid} = state), do: {:stop, reason, state} + + @impl true + def terminate(_, state) do + :gen_tcp.close(state.listener) + Process.exit(state.acceptor, :shutdown) + Enum.each(state.workers, &Process.exit(&1, :shutdown)) + end + + defp accept(listener, owner, opts) do + case :gen_tcp.accept(listener) do + {:ok, client} -> + worker = spawn(fn -> connect(opts) end) + :ok = :gen_tcp.controlling_process(client, worker) + send(worker, {:client, client}) + send(owner, {:worker, worker}) + accept(listener, owner, opts) + + {:error, :closed} -> + :ok + end + end + + defp connect(opts) do + receive do + {:client, client} -> + {:ok, server} = + :gen_tcp.connect(String.to_charlist(opts[:hostname]), opts[:port], [ + :binary, + active: true + ]) + + :ok = :inet.setopts(client, active: true) + relay(client, server, false) + end + end + + defp relay(client, server, dropping) do + receive do + {:blackhole, caller, ref} -> + # Model the server timing out its end of a VIP-moved connection without + # any FIN/RST reaching the client. New TCP connections still pass through. + :gen_tcp.close(server) + send(caller, {:blackholed, ref}) + relay(client, server, true) + + {:tcp, socket, bytes} -> + unless dropping, do: :gen_tcp.send(if(socket == client, do: server, else: client), bytes) + relay(client, server, dropping) + + {:tcp_closed, ^server} when dropping -> + relay(client, server, dropping) + + {:tcp_closed, _} -> + :gen_tcp.close(client) + :gen_tcp.close(server) + end + end +end diff --git a/usage-rules.md b/usage-rules.md index 61971ca..f04f2bd 100644 --- a/usage-rules.md +++ b/usage-rules.md @@ -141,9 +141,12 @@ _A framework-agnostic Elixir CDC consumer for Postgres logical replication (`pgo `handle_message/2`). `streaming: [max_concurrent_txns: N]` (default 64) opts into proto-v2 in-progress transaction streaming; its nested `spill: [dir:, max_spill_bytes:]` opts into consumer-side disk spill for oversized streamed transactions. - `max_inflight_lag` (default 64 MiB) bounds how far the received WAL frontier may - run ahead of the durable checkpoint before the sink is "too slow" - (see the halt-reason table below). + `max_inflight_lag` (default 64 MiB) budgets queued payload bytes and, separately, + retained transaction/batch data. Intake pauses at that byte budget or 512 queued + messages and resumes at or below both half-watermarks without releasing the slot. + Processing credits never advance the durable checkpoint. Paused connections send + feedback every five seconds; set `wal_sender_timeout` comfortably above that. + These are payload budgets, not exact process-memory limits. - **Snapshot column lists** — both readers project only published columns in physical order: pgoutput's effective `attnames` on PostgreSQL 15+ (non-dropped columns before 15, excluding generated columns on PG12–15), @@ -249,7 +252,9 @@ off-list key or a wrong shape — never ships a row value). Events: | --- | --- | --- | --- | | `[:replicant, :pipeline, :halted]` | a permanent fail-closed halt, before asynchronous teardown | — | `slot_name`, structural atom `reason`, optional atom `kind`; arbitrary details discarded | | `[:replicant, :connection, :connected]` | replication connection established (each connect/reconnect) | — | `kind` (`:primary`/recovery kind) | -| `[:replicant, :connection, :disconnected]` | connection dropped — **also carries the lag measurement for the `:sink_too_slow` halt** (with `reason: :sink_too_slow` and a signed `lag` measurement in bytes) | `lag` (halt only) | `reason` (halt only) | +| `[:replicant, :connection, :disconnected]` | connection dropped | — | — | +| `[:replicant, :connection, :paused]` / `:resumed` | intake crosses the queue watermarks | `byte_size`, `change_count` | `slot_name` | +| `[:replicant, :buffer, :exhausted]` | retained transaction data exceeds the budget and cannot be spilled or flushed | `byte_size` | `slot_name`, `reason: :buffer_limit_exceeded` | | `[:replicant, :connection, :slot_active]` | the slot is created/owned and streaming begins | — | — | | `[:replicant, :connection, :slot_invalidated]` | slot invalidation / fail-closed config rejection | — | `reason` (`:failover_unsupported`, `:publication_missing`, invalidation class) | | `[:replicant, :connection, :session_identity_rejected]` | the sink vetoed the replication-session identity | — | `reason: :session_identity_rejected` | @@ -279,10 +284,8 @@ off-list key or a wrong shape — never ships a row value). Events: | `[:replicant, :stream, :spilled]` | an oversized streamed transaction's tail spilled to disk | — | `byte_size`, `change_count` | | `[:replicant, :stream, :spill_exhausted]` | the disk ceiling was reached (halt follows) | — | `byte_size`, `reason: :spill_exhausted` | -The two-column trap to know: the **lag halt** (`:sink_too_slow`) rides -`[:replicant, :connection, :disconnected]`; `[:replicant, :pipeline, :halted]` -also reports its structural reason but carries no lag measurement. Alert on -`reason: :sink_too_slow`, not on the event name alone. +A slow sink triggers pause/resume, not a permanent halt. Actual retained-buffer or +disk exhaustion still halts fail-closed; the halt table below describes recovery. ## Halt reasons (operator reference) @@ -293,7 +296,7 @@ durable checkpoint (loss = 0; duplicates bounded by the mode's contract). | Halt signal | Cause | Operator action | | --- | --- | --- | | `[:replicant, :sink, :failed]` | the sink returned an error or raised | fix the sink/store it writes; restart the pipeline | -| `:disconnected` + `reason: :sink_too_slow` | received WAL ran `max_inflight_lag` (default 64 MiB) past the durable checkpoint | speed the sink up, batch (`batch_delivery`), or raise the bound | +| `:buffer_limit_exceeded` | retained transaction data exceeds `max_inflight_lag` and cannot be spilled or flushed | reduce transaction size, enable streaming with disk spill where supported, or raise the budget | | `[:replicant, :connection, :slot_invalidated]` | the slot was invalidated (`wal_status = 'lost'`), a requested publication vanished, or failover config was rejected | recreate the slot (accept the re-stream from its origin — see `handle_slot_origin/2` for append sinks); restore/rename the publication; drop `failover:` on PG<17 | | `[:replicant, :connection, :command_error_halt]` | persistent pre-frame command errors (slot exhaustion, slot already active, forward-incompatible result) | free a replication slot / disconnect the other consumer; then restart | | `[:replicant, :connection, :session_identity_rejected]` | the sink vetoed the actual replication-session identity | point at the intended source, or update the sink's accepted identity |