Restore subquery materializer state from disk after server restart by robacourt · Pull Request #4651 · electric-sql/electric

robacourt · 2026-06-24T13:51:36Z

Summary

Fixes bug 1 from the restart-aware oracle property test triage (see #4648 / bugs.md): subquery shapes diverge from Postgres after a StackSupervisor restart that restores from disk.

A shape whose where clause contains a subquery — e.g. project_id IN (SELECT id FROM projects WHERE active = true) — could, after a server restart, return stale results (missing rows) or a 409 must-refetch on an optimized: true shape.

Problem

Two compounding root causes:

The dependency materializer only replayed the first chunk of the source shape's persisted history on startup. Storage.get_log_stream/3 returns at most one snapshot chunk per call; the materializer called it once and treated that as the full history, silently dropping later snapshot chunks and persisted log entries. Its value_counts was wrong from the moment it came up.
Dependent (outer) subquery consumers were not restarted after a stack restart. The router only delivers events to a consumer when its own root_table changes, so a shape whose movement is driven entirely by its dependency stayed dormant — its materializer was never started, the SubqueryIndex never seeded, and its on-disk view never updated when the dependency changed.

Solution

materializer.ex — replace the single-call get_stream_up_to_offset/3 with read_history_up_to_subscribed/2, which iterates snapshot chunks (via Storage.get_chunk_end_log_offset/2) up to the subscribed offset, stopping the moment the read steps into the main log so it never re-applies already-applied entries.
shape_cache.ex — in handle_continue(:wait_for_restore, …), eagerly restart consumers for every shape with shape_dependencies != [] (before ShapeLogCollector.mark_as_ready), re-establishing the materializer subscription before live events flow.

Test Plan

New integration repro test/integration/oracle_restore_test.exs (oracle_restore_bug_1) — fails on main (client view missing the reactivated project's issues), passes with the fix. Uses a readable projects → issues domain schema.
New materializer unit test (startup history replay) — directly pins root cause Working with Postgres WAL format from Elixir #1; fails on the pre-fix single-chunk read (value_counts = {10} instead of {99}).
New shape_cache_test describe block (wait_for_restore eager subquery consumer start) — asserts subquery shapes are eagerly restored while non-subquery shapes are not; existing start_consumer_for_handle test updated for the new eager behavior.
mix test test/electric/shapes/ — 572 tests, 0 failures.

Run the focused repro:

cd packages/sync-service
mix test --only oracle test/integration/oracle_restore_test.exs

Generated with Claude Code

Recreates the bug-1 regression test from #4648 as a standalone, deterministic reproduction: a subquery shape (issues belonging to active projects) diverges from the oracle after a StackSupervisor restart because the subquery materializer state is not restored from disk. Uses a small, readable "issue tracker" domain schema (projects -> issues) rather than the abstract level_N hierarchy. Fails on main; will pass once the materializer/shape_cache restore fix lands. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

Fixes bug 1: subquery shapes diverged from the oracle after a StackSupervisor restart (either missing rows or a 409 must-refetch on an optimized shape). Two compounding causes: 1. The materializer only replayed the first chunk of the source shape's persisted history on startup. `Storage.get_log_stream/3` returns at most one snapshot chunk per call, so the materializer's value_counts were wrong from the moment it came up. Replaced the single-call `get_stream_up_to_offset/3` with `read_history_up_to_subscribed/2`, which iterates snapshot chunks up to the subscribed offset and stops before re-reading the main log. 2. Dependent (outer) subquery consumers were not restarted after a stack restart, so movements driven entirely by the dependency never reached their on-disk view. `ShapeCache` now eagerly restarts consumers for shapes with dependencies during `:wait_for_restore`, re-establishing the materializer subscription before the log collector starts dispatching events. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

Lower-level regression test for bug 1's root cause: the materializer must iterate storage chunks on startup so it replays the source shape's full persisted history (snapshot + main log), not just the first chunk. Seeds a snapshot row at value=10 plus a main-log UPDATE to value=99 persisted before subscription, then asserts the restored value_counts reflect the UPDATE. Fails on the pre-fix single-chunk read (value_counts = {10}). Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

The bug-1 fix makes ShapeCache eagerly restart subquery shape consumers during `:wait_for_restore`, so the existing "start_consumer_for_handle" test's assertion that no consumers run after restart no longer holds. Update it to wait for the eagerly-restarted consumer + materializer, and add a focused describe block asserting that subquery shapes are eagerly started on restore while non-subquery shapes are not. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

codecov · 2026-06-24T13:54:08Z

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 60.00%. Comparing base (e6c3767) to head (d95a06b).
⚠️ Report is 3 commits behind head on main.
✅ All tests successful. No failed tests found.

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #4651      +/-   ##
==========================================
+ Coverage   59.66%   60.00%   +0.34%     
==========================================
  Files         385      395      +10     
  Lines       43021    43747     +726     
  Branches    12372    12581     +209     
==========================================
+ Hits        25667    26251     +584     
- Misses      17276    17418     +142     
  Partials       78       78

Flag	Coverage Δ
packages/agents	`72.64% <ø> (ø)`
packages/agents-mcp	`77.70% <ø> (ø)`
packages/agents-mobile	`80.67% <ø> (ø)`
packages/agents-runtime	`83.73% <ø> (+0.30%)`	⬆️
packages/agents-server	`75.47% <ø> (+0.02%)`	⬆️
packages/agents-server-ui	`8.32% <ø> (-0.03%)`	⬇️
packages/electric-ax	`51.06% <ø> (ø)`
packages/experimental	`87.73% <ø> (ø)`
packages/react-hooks	`86.48% <ø> (ø)`
packages/start	`82.83% <ø> (ø)`
packages/typescript-client	`91.83% <ø> (ø)`
packages/y-electric	`56.05% <ø> (ø)`
typescript	`60.00% <ø> (+0.34%)`	⬆️
unit-tests	`60.00% <ø> (+0.34%)`	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Harness.
📢 Have feedback on the report? Share it here.

🚀 New features to boost your workflow:

📦 JS Bundle Analysis: Save yourself from yourself by tracking and limiting bundle sizes in JS merges.

claude · 2026-06-24T13:59:50Z

Claude Code Review

Summary

Fixes subquery shapes diverging from Postgres after a StackSupervisor restart by (1) replaying the full persisted history in the dependency materializer instead of just the first chunk, and (2) eagerly restarting dependent subquery consumers during wait_for_restore before live events flow. Since iteration 2 the author has resolved the one open Important issue and gone a step further. The PR looks ready to merge.

What's Working Well

Iteration-2 Important issue fully resolved. await_snapshot_start/2 at shape_cache.ex:353-363 is now wrapped in try/catch :exit (commit 079fd22), so a consumer dying before/during the call — or a call timeout — can no longer propagate out of handle_continue(:wait_for_restore, …) and crash ShapeCache before mark_as_ready. This closes the stack-wide restart-loop failure mode.
The follow-up purge (11b9d1f) is the more correct fix. Rather than log-and-continue (my iteration-2 suggestion), the author purges the shape via clean_shape/2 when the await can't be confirmed. The reasoning in the inline comment (shape_cache.ex:341-352) is exactly right: leaving a subquery shape alive-but-unconfirmed would silently reintroduce the post-restart divergence this whole path exists to prevent. Purge → client refetches → consistency is guaranteed rather than inferred. The choice also mirrors restore_shape_and_dependencies' own clean_shape-on-failure (shape_cache.ex:553), so it's consistent with established behavior.
The purge path is well-guarded against re-triggering the crash it's recovering from. I checked the wedged-consumer scenario specifically: Consumer.stop/2 wraps its GenServer.call(pid, {:stop, …}) in its own catch :exit, _ -> :ok (consumer.ex:98-106), so purging a wedged consumer (the exact case where the await timed out) won't itself exit and crash ShapeCache. Good defensive layering.
New test (d95a06b) pins the purge branch. It mocks the start chain to reach {:ok, pid}, forces the await to exit, and asserts ShapeCleaner.remove_shape is called for the shape — directly covering the branch and failing against the prior log-only version. Argument order (stack_id, handle) matches the real clean_shape → ShapeCleaner.remove_shape call.

Issues Found

Critical (Must Fix)

None.

Important (Should Fix)

None. (The iteration-2 Important issue is resolved.)

Suggestions (Nice to Have)

Observability of eager purges at scale (shape_cache.ex:328-368). The shift from log-and-continue to purge-on-await-failure changes the semantics of a timeout: a transiently-slow-but-healthy consumer that exceeds the default 45s await — plausible when many shapes restore simultaneously and snapshot reads contend on disk at restart-under-load — is now destroyed and forces a full client refetch, rather than just being logged. Snapshots are on disk so the normal case returns fast and this should be rare, and the tradeoff is deliberate and well-documented. But at 10k–150k shapes a wave of false-positive purges at exactly the worst moment (restart under load) would be invisible today beyond per-shape warning lines. Consider a counter/telemetry for how many subquery consumers were eagerly restored vs. purged, so a refetch wave is detectable. (This also subsumes the iteration-2 "scale visibility" suggestion.)
Remaining minor iteration-2 nits (all optional, none blocking): for used purely for side effects (shape_cache.ex:336) reads slightly more clearly as Enum.each/2; the explicit shape_handle: in the materializer Logger.warning (materializer.ex:232) duplicates init/1's Logger.metadata; and a one-line "defensive" note on the is_real_offset(state.offset) branch (materializer.ex:215) would save a future reader some puzzling.

Issue Conformance

No issue is linked directly on the PR, but the description references the triage doc / #4648 (bugs.md, "bug 1") with clear acceptance criteria (the oracle_restore_bug_1 repro fails on main, passes with the fix). Implementation matches the described scope without scope creep. Linking the tracking issue on the PR would still be ideal per convention. The changeset (.changeset/restore-subquery-materializer.md, @core/sync-service: patch) is present and correctly formatted.

Previous Review Status

Addressed (iteration 2 → 3):
- Important issue Working with Postgres WAL format from Elixir #1 — unguarded await_snapshot_start/2 — resolved by the try/catch :exit guard (079fd22) and hardened further with purge-on-failure (11b9d1f) plus a dedicated test (d95a06b).
- @magnetised's inline request for a Logger.warning on the non-advancing chunk_end branch — addressed in iteration 2 (fe34afd57).
Still open (optional only): the scale-visibility / observability suggestion above and the three minor style nits. None are blockers.

Review iteration: 3 | 2026-06-25

magnetised

Cool

magnetised · 2026-06-24T14:20:05Z

+
+            is_log_offset_lte(next_offset, state.offset) ->
+              # Defensive: chunk_end did not advance. Stop to avoid an
+              # infinite loop. This shouldn't happen in normal operation.


Logger.warning...?

Done — added a Logger.warning in this defensive branch (fe34afd) so the non-advancing chunk_end condition is surfaced if it ever happens.

Addresses PR review feedback: the defensive branch that guards against a non-advancing chunk_end (which shouldn't happen in normal operation) now emits a Logger.warning so the condition is visible if it ever occurs, rather than silently stopping the replay. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

Addresses PR review feedback: eagerly_start_subquery_shape_consumers/1 called await_snapshot_start/2 (a GenServer.call) with no try/catch on the critical restore path. If the just-started consumer died before/during the call, the :exit would propagate out of handle_continue(:wait_for_restore) and crash ShapeCache before mark_as_ready — turning a shape that reliably fails its snapshot into a stack-wide restart loop. Mirror the materializer's try/catch :exit and log + continue so one bad subquery shape can't take down restore for the whole stack. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

Follow-up to the await guard: catching the :exit and continuing left the shape alive but unconfirmed. The eager start exists to guarantee the subquery shape's consumer comes back subscribed-and-correct, so a surviving shape whose await failed (consumer died, or timed out while wedged) would silently reintroduce the post-restart divergence this path fixes. Purge the shape on failure — mirroring restore_shape_and_dependencies' own clean_shape-on-error — so the client refetches from scratch and consistency is guaranteed rather than inferred. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

Covers the purge-on-failure branch: when the eager consumer start succeeds but await_snapshot_start exits (consumer died or wedged), ShapeCache must clean the shape so the client refetches from scratch rather than leaving it alive-but-unconfirmed. Mocks the start chain to reach {:ok, pid}, forces the await to exit, and asserts ShapeCleaner.remove_shape is called for the shape. Fails on the prior log-only version. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

github-actions · 2026-06-25T19:31:58Z

This PR has been released! 🚀

The following packages include changes from this PR:

@core/sync-service@1.7.4

Thanks for contributing to Electric!

The `start_consumer_for_handle/2 starts a consumer plus dependencies` test called `wait_until(1000, fn -> ... end)`, but #4635 changed the signature to `wait_until(fun, timeout_ms \\ 500)` (function first). The new call site was added by #4651 using the old arg order; the two merged cleanly in git but not in meaning, so `1000` was bound to `fun`, failed the `is_function(fun, 0)` guard, and raised FunctionClauseError whenever the slow suite ran on main. Swap the arguments to match the current signature. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

…es that have a request id that is not the standard 20 bytes. (#4658) ## Summary Fixes an unbounded `process_type` cardinality leak in telemetry for request-handling processes. ## Problem `process_type` for request-handling processes is derived from the process label set by `Electric.Plug.LabelProcessPlug`, which looks like: ``` Request F-jPUudNHxbD8lIAABQG - GET /v1/shape?table=users&offset=-1 ``` `parse_binary_label/1` is meant to strip the request id and query, collapsing this to a bounded `GET /v1/shape`. But it did so with a fixed-width binary match that assumes the request id is exactly 20 bytes: ```elixir "Request " <> <<_req_id::binary-20, " - ", rest::binary>> -> ... ``` That holds for ids `Plug.RequestId` self-generates, but `Plug.RequestId` reuses an incoming `x-request-id` header when a client/proxy supplies one. A UUID (36 chars), an Envoy/nginx id, or an LB trace id is not 20 bytes, so the clause falls through to the generic branch that returns the first 20 bytes of the whole label — i.e. `Request <first 12 chars of the id>`. Every distinct incoming request id that GCs slowly then adds a permanent new series to `prometheus_metrics_dist` for events like `vm.monitor.long_gc` and `vm.monitor.long_schedule`. Request handlers building large shape responses are exactly the processes that trip those monitors, so the table grows without bound when a fronting proxy injects `x-request-id`. ## Solution Keep the fast fixed-width binary match for the common 20-byte case (`Plug.RequestId`'s self-generated ids), and add a slow path that only runs when the id is a different length: it splits on the `" - "` delimiter regardless of request-id length, then strips the query string. All requests to a route collapse to a single `process_type` (e.g. `GET /v1/shape`) regardless of request-id source or length. A `"Request "` label with no delimiter falls back to truncation. --- ## Also includes: unrelated CI fix CI for this PR was failing on `Electric.ShapeCacheTest` (in `sync-service`, unrelated to the telemetry change). The cause is a semantic merge collision already on `main`: #4635 changed `wait_until`'s signature to `wait_until(fun, timeout_ms)` (function first), while #4651 added a new call site at `shape_cache_test.exs:1582` using the old arg order `wait_until(1000, fn -> ... end)`. The two merged cleanly in git but not in meaning, so the slow suite raised a `FunctionClauseError` on every run. This PR swaps the arguments to match the current signature, unblocking both `main` and this PR. --------- Co-authored-by: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

…(bug 4) (#4670) ## Summary Adds a deterministic regression test for **bug 4** from the restore-from-file bug triage in #4648 (bug doc: `packages/sync-service/bugs.md`). This is a **test-only** change. Bug 4's production fix — the two main-log short-circuits in `Materializer.read_history_up_to_subscribed/2` — already shipped alongside the bug 1 fix in #4651; it just lacked dedicated regression coverage. ## Problem (bug 4) On startup recovery the subquery materializer replays the source shape's persisted history (snapshot + main log) up to its subscribed offset. `Storage.get_log_stream/3` returns one chunk per call for the **snapshot**, but returns the **entire** requested range for the **main log** in a single call. When the source shape's main log spans more than one chunk, a replay loop that keeps advancing through chunk boundaries past the first main-log chunk re-reads main-log entries it has already applied. Re-applying a `NewRecord` for an existing key raises `Key ... already exists`, crashing the materializer (and taking the dependent shape's consumer down with it → 409 must-refetch on the next poll). ## Solution / coverage The fix (already merged in #4651) stops iterating as soon as the read steps into the main log. This PR adds the missing regression test: `test/electric/shapes/consumer/materializer_test.exs` → `"does not re-read main-log entries when the main log spans multiple chunks"` - Sets `chunk_bytes_threshold: 10` to force the source shape's main log across ≥2 chunks (asserts the first main-log chunk ends strictly before the subscribed offset). - Persists two `NewRecord` inserts in separate main-log chunks, subscribes past both, and asserts startup replay yields the correct `value_counts` exactly once. ## Test Plan - [x] Passes with the fix in place (`59 tests, 0 failures` in the file). - [x] Fails without the fix: reverting the short-circuits makes the test crash with `** (RuntimeError) Key "public"."test_table"/"3" already exists` from `read_history_up_to_subscribed/2` — confirming it's a genuine failing-first regression test. - [x] `mix format --check-formatted` clean. ## Notes An end-to-end variant in `oracle_restore_test.exs` was prototyped but not included: it does trigger the crash, but the failure self-heals via a client refetch that re-syncs to the oracle, so it passes with and without the fix — false-confidence coverage. The deterministic unit test is the reliable regression guard. --- Generated with [Claude Code](https://claude.com/claude-code) --------- Co-authored-by: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

robacourt and others added 5 commits June 24, 2026 14:23

Add changeset for subquery materializer restore fix

12cc1c4

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>

robacourt added the claude label Jun 24, 2026

robacourt requested a review from alco June 24, 2026 13:53

magnetised approved these changes Jun 24, 2026

View reviewed changes

robacourt and others added 2 commits June 24, 2026 17:51

robacourt self-assigned this Jun 25, 2026

robacourt and others added 2 commits June 25, 2026 13:55

electric-sql deleted a comment from claude Bot Jun 25, 2026

robacourt merged commit 44eafb6 into main Jun 25, 2026
70 checks passed

robacourt deleted the rob/subquery-restore-bug-1 branch June 25, 2026 13:11

robacourt mentioned this pull request Jun 30, 2026

fix(electric-telemetry): Fix process_type parsing for request processes that have a request id that is not the standard 20 bytes. #4658

Merged

robacourt mentioned this pull request Jul 1, 2026

Add regression test for subquery materializer multi-chunk log replay (bug 4) #4670

Merged

3 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Restore subquery materializer state from disk after server restart#4651

Restore subquery materializer state from disk after server restart#4651
robacourt merged 9 commits into
mainfrom
rob/subquery-restore-bug-1

robacourt commented Jun 24, 2026

Uh oh!

codecov Bot commented Jun 24, 2026 •

edited

Loading

Uh oh!

claude Bot commented Jun 24, 2026 •

edited

Loading

Uh oh!

magnetised left a comment

Uh oh!

magnetised Jun 24, 2026

Uh oh!

robacourt Jun 24, 2026

Uh oh!

Uh oh!

github-actions Bot commented Jun 25, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

Uh oh!

Conversation

robacourt commented Jun 24, 2026

Summary

Problem

Solution

Test Plan

Uh oh!

codecov Bot commented Jun 24, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

claude Bot commented Jun 24, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Claude Code Review

Summary

What's Working Well

Issues Found

Critical (Must Fix)

Important (Should Fix)

Suggestions (Nice to Have)

Issue Conformance

Previous Review Status

Uh oh!

magnetised left a comment

Choose a reason for hiding this comment

Uh oh!

magnetised Jun 24, 2026

Choose a reason for hiding this comment

Uh oh!

robacourt Jun 24, 2026

Choose a reason for hiding this comment

Uh oh!

Uh oh!

github-actions Bot commented Jun 25, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

codecov Bot commented Jun 24, 2026 •

edited

Loading

claude Bot commented Jun 24, 2026 •

edited

Loading