Skip to content

Commit c2ae8bd

Browse files
robacourtclaude
andauthored
Skip already-processed transactions on restart (#4668)
## Summary On restart, the persistent replication slot can replay transactions the consumer has already applied and persisted. The consumer deduplicated these on its multi-fragment path, but the complete-transaction **fast paths short-circuited before reaching that check** — so a replayed transaction was re-written to the shape log (duplicating ops) and re-notified to dependent subquery materializers, which re-applied it and crashed with `Key ... already exists`. This is **bug 2** from the restart-aware oracle property-test triage (see #4648 / `packages/sync-service/bugs.md`). ## Problem After a `StackSupervisor` restart, the source consumer reconnects to the persistent slot and replays from its confirmed LSN, which can lag the shape's on-disk offset. Complete single-fragment transactions (the common case — one statement per txn) took the fast path and were re-processed: - **Normal shapes:** duplicate / orphan operations appended to the shape log. - **Subquery shapes:** the re-notified duplicate is re-applied by the dependency materializer, which is a stateful reducer and crashes on the duplicate insert (`"Key ... already exists"`). That crash then cascades into tearing down and *removing* the healthy dependent shapes and returning `409 must-refetch` to clients. ## Solution Consolidate the offset dedup into a **single `handle_txn_fragment/2` clause** that skips any fragment already at or below `latest_offset` (routing to the existing `skip_txn_fragment`), placed before the complete-transaction fast paths. The dedup now lives in one place and covers single- and multi-fragment paths uniformly, replacing the separate `fragment_already_processed?/2` check. Normal operation is untouched: new transactions have `offset > latest_offset`, so the guard is false and they fall through to the existing clauses. This relies on a transaction's fragments being entirely at-or-below or entirely above `latest_offset` (which only advances at commit boundaries) — the same assumption the previous per-fragment check already made. ## Test Plan - [x] `test/electric/shapes/consumer_test.exs` — two regression tests (single-fragment and multi-fragment) replay an already-applied transaction straight to the consumer, bypassing the log collector's own dedup (as happens on restart with a fresh collector), and assert it is skipped: no `append_to_log!`, no `:new_changes` notification, log unchanged. Fail without the fix. - [x] `test/electric/shapes/` + `test/electric/replication/` — 937 tests, 100 doctests, 6 properties, 0 failures. --- Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
1 parent ed04ee4 commit c2ae8bd

3 files changed

Lines changed: 183 additions & 6 deletions

File tree

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,5 @@
1+
---
2+
'@core/sync-service': patch
3+
---
4+
5+
Fix shapes processing duplicate operations after a server restart.

packages/sync-service/lib/electric/shapes/consumer.ex

Lines changed: 35 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -587,6 +587,22 @@ defmodule Electric.Shapes.Consumer do
587587
State.add_to_buffer(state, txn_fragment)
588588
end
589589

590+
# Skip transactions already applied and persisted (e.g. replayed from the persistent
591+
# replication slot on restart) - ones at or below `latest_offset`.
592+
#
593+
# This skips whole transactions, relying on a replayed transaction being entirely
594+
# at-or-below or entirely above `latest_offset`, never straddling it. In-memory
595+
# `latest_offset` advances per written fragment (see `write_txn_fragment_to_storage/2`),
596+
# not only at commit — but on the replay path the guarantee holds: after a restart
597+
# `latest_offset` is restored from storage at a commit boundary
598+
# (`Storage.fetch_latest_offset/1`, from `last_{seen,persisted}_txn_offset`), and the
599+
# replication slot replays whole transactions from a commit boundary
600+
# (`confirmed_flush_lsn`).
601+
defp handle_txn_fragment(%TransactionFragment{last_log_offset: offset} = txn_fragment, state)
602+
when LogOffset.is_log_offset_lte(offset, state.latest_offset) do
603+
skip_txn_fragment(state, txn_fragment)
604+
end
605+
590606
# Short-circuit clauses for the most common case of a single-fragment transaction
591607
defp handle_txn_fragment(%TransactionFragment{} = txn_fragment, state)
592608
when TransactionFragment.complete_transaction?(txn_fragment) and
@@ -652,13 +668,30 @@ defmodule Electric.Shapes.Consumer do
652668

653669
defp handle_txn_fragment(txn_fragment, state), do: process_txn_fragment(txn_fragment, state)
654670

671+
# Defensive: this is only ever reached with a `pending_txn` set — a transaction's
672+
# BEGIN fragment creates it (see the `has_begin?` clauses above) before any fragment
673+
# gets here. The only way to arrive with `pending_txn: nil` is a transaction that
674+
# straddled `latest_offset`: its BEGIN fragment skipped by the already-applied clause
675+
# while a later fragment was not. The commit-aligned restore + whole-transaction replay
676+
# invariant (documented on that clause) rules this out; fail loudly with a clear message
677+
# rather than crash on `nil.consider_flushed?` if it is ever violated.
678+
defp process_txn_fragment(%TransactionFragment{last_log_offset: offset}, %State{
679+
pending_txn: nil
680+
}) do
681+
raise "consumer received a transaction fragment at #{inspect(offset)} with no pending " <>
682+
"transaction — a transaction straddling latest_offset was partially skipped, " <>
683+
"which should be impossible"
684+
end
685+
655686
defp process_txn_fragment(
656687
%TransactionFragment{} = txn_fragment,
657688
%State{pending_txn: txn} = state
658689
) do
659690
cond do
660-
# Fragments belonging to the same transaction can all be skipped either via xid-filtering or log offset filtering.
661-
txn.consider_flushed? or fragment_already_processed?(txn_fragment, state) ->
691+
# Fragments of a transaction whose xid is already in the initial snapshot are
692+
# skipped here. (Offset-based dedup of replayed transactions is handled earlier,
693+
# in `handle_txn_fragment/2`.)
694+
txn.consider_flushed? ->
662695
skip_txn_fragment(state, txn_fragment)
663696

664697
# With write_unit=txn all fragments are buffered until the Commit change is seen. At that
@@ -1097,10 +1130,6 @@ defmodule Electric.Shapes.Consumer do
10971130
Kernel.max(0, DateTime.diff(now, commit_timestamp, :millisecond))
10981131
end
10991132

1100-
defp fragment_already_processed?(%TransactionFragment{last_log_offset: offset}, state) do
1101-
LogOffset.is_log_offset_lte(offset, state.latest_offset)
1102-
end
1103-
11041133
defp consider_flushed(%State{} = state, log_offset) do
11051134
if state.txn_offset_mapping == [] do
11061135
# No relevant txns have been observed and unflushed, we can notify immediately

packages/sync-service/test/electric/shapes/consumer_test.exs

Lines changed: 143 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -725,6 +725,62 @@ defmodule Electric.Shapes.ConsumerTest do
725725
get_log_items_from_storage(LogOffset.last_before_real_offsets(), shape_storage)
726726
end
727727

728+
test "skips an already-applied transaction replayed past a fresh log collector", ctx do
729+
# Simulates a restart: the persistent replication slot replays a transaction
730+
# the consumer has already applied and persisted. A freshly-started
731+
# ShapeLogCollector hasn't seen the offset, so (unlike the test above) it
732+
# won't drop it — the consumer itself must skip it, because its restored
733+
# `latest_offset` is already at/past the transaction. Otherwise the fragment
734+
# is re-written to the log (duplicating ops) and re-notified to dependent
735+
# materializers, which re-apply it and crash.
736+
{shape_handle, _} = ShapeCache.get_or_create_shape_handle(@shape1, ctx.stack_id)
737+
:started = ShapeCache.await_snapshot_start(shape_handle, ctx.stack_id)
738+
739+
ref = Shapes.Consumer.register_for_changes(ctx.stack_id, shape_handle)
740+
741+
xid = 11
742+
lsn = Lsn.from_integer(10)
743+
744+
txn =
745+
complete_txn_fragment(xid, lsn, [
746+
%Changes.NewRecord{
747+
relation: {"public", "test_table"},
748+
record: %{"id" => "1"},
749+
log_offset: LogOffset.new(lsn, 0)
750+
}
751+
])
752+
753+
consumer_pid = Shapes.Consumer.whereis(ctx.stack_id, shape_handle)
754+
shape_storage = Storage.for_shape(shape_handle, ctx.storage)
755+
756+
# First delivery: applied normally, advancing the consumer's latest_offset.
757+
assert :ok = ShapeLogCollector.handle_event(txn, ctx.stack_id)
758+
last_log_offset = LogOffset.new(lsn, 0)
759+
assert_receive {^ref, :new_changes, ^last_log_offset}
760+
761+
assert [op1] =
762+
get_log_items_from_storage(LogOffset.last_before_real_offsets(), shape_storage)
763+
764+
# Replay the same, already-applied transaction straight to the consumer,
765+
# bypassing the collector's own offset de-dup (as happens on restart with a
766+
# fresh collector). The consumer must skip it: no storage write, no
767+
# notification, log unchanged.
768+
enable_storage_tracer_for(consumer_pid)
769+
770+
assert :ok =
771+
GenServer.call(
772+
Shapes.Consumer.name(ctx.stack_id, shape_handle),
773+
{:handle_event, txn, Electric.Telemetry.OpenTelemetry.get_current_context()},
774+
:infinity
775+
)
776+
777+
assert [] == Support.Trace.collect_traced_calls()
778+
refute_receive {^ref, :new_changes, _}
779+
780+
assert [op1] ==
781+
get_log_items_from_storage(LogOffset.last_before_real_offsets(), shape_storage)
782+
end
783+
728784
@tag allow_subqueries: false
729785
test "duplicate txn fragment handling is idempotent", ctx do
730786
{shape_handle, _} = ShapeCache.get_or_create_shape_handle(@shape1, ctx.stack_id)
@@ -834,6 +890,93 @@ defmodule Electric.Shapes.ConsumerTest do
834890
refute_receive {^ref, :new_changes, _}
835891
end
836892

893+
@tag allow_subqueries: false
894+
test "skips an already-applied multi-fragment transaction replayed past a fresh log collector",
895+
ctx do
896+
# Multi-fragment variant of "skips an already-applied transaction replayed
897+
# past a fresh log collector". On restart the persistent slot can replay a
898+
# multi-statement transaction the consumer has already applied. This drives
899+
# the offset-dedup on the multi-fragment path (BEGIN / middle / COMMIT
900+
# fragments), not the single-fragment fast path — the consumer must skip
901+
# every fragment without re-writing or re-notifying.
902+
{shape_handle, _} = ShapeCache.get_or_create_shape_handle(@shape1, ctx.stack_id)
903+
:started = ShapeCache.await_snapshot_start(shape_handle, ctx.stack_id)
904+
905+
ref = Shapes.Consumer.register_for_changes(ctx.stack_id, shape_handle)
906+
907+
xid = 11
908+
lsn = Lsn.from_integer(10)
909+
910+
[f1, f2, f3] =
911+
txn_fragments(xid, lsn, [
912+
%{
913+
has_begin?: true,
914+
changes: [
915+
%Changes.NewRecord{
916+
relation: {"public", "test_table"},
917+
record: %{"id" => "1"},
918+
log_offset: LogOffset.new(lsn, 0)
919+
}
920+
]
921+
},
922+
%{
923+
changes: [
924+
%Changes.NewRecord{
925+
relation: {"public", "test_table"},
926+
record: %{"id" => "2"},
927+
log_offset: LogOffset.new(lsn, 2)
928+
}
929+
]
930+
},
931+
%{
932+
has_commit?: true,
933+
changes: [
934+
%Changes.NewRecord{
935+
relation: {"public", "test_table"},
936+
record: %{"id" => "3"},
937+
log_offset: LogOffset.new(lsn, 4)
938+
}
939+
]
940+
}
941+
])
942+
943+
consumer_pid = Shapes.Consumer.whereis(ctx.stack_id, shape_handle)
944+
shape_storage = Storage.for_shape(shape_handle, ctx.storage)
945+
946+
# First delivery via the collector: applied normally, advancing latest_offset
947+
# to the commit offset.
948+
Enum.each([f1, f2, f3], &assert(:ok = ShapeLogCollector.handle_event(&1, ctx.stack_id)))
949+
950+
commit_offset = LogOffset.new(lsn, 4)
951+
assert_receive {^ref, :new_changes, ^commit_offset}
952+
953+
assert [_, _, _] =
954+
ops =
955+
get_log_items_from_storage(LogOffset.last_before_real_offsets(), shape_storage)
956+
957+
# Replay every fragment straight to the consumer, bypassing the collector's
958+
# offset de-dup (as on restart with a fresh collector). The consumer's restored
959+
# latest_offset is already at the commit, so all fragments — including the
960+
# BEGIN fragment, which now skips without ever setting up `pending_txn` — must
961+
# be skipped: no storage writes, no notification, log unchanged.
962+
enable_storage_tracer_for(consumer_pid)
963+
964+
Enum.each([f1, f2, f3], fn f ->
965+
assert :ok =
966+
GenServer.call(
967+
Shapes.Consumer.name(ctx.stack_id, shape_handle),
968+
{:handle_event, f, Electric.Telemetry.OpenTelemetry.get_current_context()},
969+
:infinity
970+
)
971+
end)
972+
973+
assert [] == Support.Trace.collect_traced_calls()
974+
refute_receive {^ref, :new_changes, _}
975+
976+
assert ops ==
977+
get_log_items_from_storage(LogOffset.last_before_real_offsets(), shape_storage)
978+
end
979+
837980
@tag pg_snapshot: {10, 13, [10, 12]},
838981
delay_snapshot_creation?: true,
839982
with_pure_file_storage_opts: [flush_period: 1]

0 commit comments

Comments
 (0)