Stack not ready after 5000ms. Reason: Timeout waiting for shape data to be loaded

[mwildehahn]

Versions

• Client: electricsql/electric:1.2.8
• Electric: electricsql/electric:1.2.8

Bug description
When running locally I'll sometimes run into the following error:

22:40:48.348 pid=<0.9585.0> [error] GenServer {:"Electric.ProcessRegistry:single_stack", {Electric.Replication.ShapeLogCollector, nil}} terminating
** (stop) exited in: GenServer.call({:via, Registry, {:"Electric.ProcessRegistry:single_stack", {Electric.Shapes.Consumer.Materializer, "22238533-1765579774154582"}}}, :get_link_values, 5000)
    ** (EXIT) no process: the process is not alive or there's no process currently associated with the given name, possibly because its application isn't started
    (elixir 1.19.1) lib/gen_server.ex:1135: GenServer.call/3
    (electric 1.2.8) lib/electric/shapes/consumer/materializer.ex:65: anonymous fn/2 in Electric.Shapes.Consumer.Materializer.get_all_as_refs/2
    (elixir 1.19.1) lib/enum.ex:1688: Enum."-map/2-lists^map/1-1-"/2
    (elixir 1.19.1) lib/map.ex:267: Map.new_from_enum/2
    (electric 1.2.8) lib/electric/shapes/filter/where_condition.ex:209: anonymous fn/6 in Electric.Shapes.Filter.WhereCondition.other_shapes_affected/5
    (stdlib 7.1) maps.erl:894: :maps.fold_1/4
    (electric 1.2.8) lib/electric/shapes/filter/where_condition.ex:207: anonymous fn/4 in Electric.Shapes.Filter.WhereCondition.other_shapes_affected/5
    (electric 1.2.8) lib/electric/telemetry/open_telemetry.ex:89: anonymous fn/5 in Electric.Telemetry.OpenTelemetry.do_with_span/5
    (telemetry 1.3.0) /builder/electric/deps/telemetry/src/telemetry.erl:324: :telemetry.span/3
    (electric 1.2.8) lib/electric/shapes/filter/where_condition.ex:170: Electric.Shapes.Filter.WhereCondition.affected_shapes/4
    (electric 1.2.8) lib/electric/shapes/filter.ex:165: Electric.Shapes.Filter.shapes_affected_by_change/2
    (electric 1.2.8) lib/electric/shapes/filter.ex:123: anonymous fn/2 in Electric.Shapes.Filter.affected_shapes/2
    (stdlib 7.1) timer.erl:599: :timer.tc/2
    (electric 1.2.8) lib/electric/telemetry/open_telemetry.ex:134: Electric.Telemetry.OpenTelemetry.timed_fun/3
    (electric 1.2.8) lib/electric/shapes/event_router.ex:149: Electric.Shapes.EventRouter.find_affected_shapes_for_change/2
    (electric 1.2.8) lib/electric/shapes/event_router.ex:106: Electric.Shapes.EventRouter.route_change/3
    (elixir 1.19.1) lib/enum.ex:2520: Enum."-reduce/3-lists^foldl/2-0-"/3
    (electric 1.2.8) lib/electric/shapes/event_router.ex:83: Electric.Shapes.EventRouter.event_by_shape_handle/2
    (electric 1.2.8) lib/electric/replication/shape_log_collector.ex:505: Electric.Replication.ShapeLogCollector.publish/2
    (electric 1.2.8) lib/electric/replication/shape_log_collector.ex:492: Electric.Replication.ShapeLogCollector.handle_txn_fragment/2
    (electric 1.2.8) lib/electric/replication/shape_log_collector.ex:428: anonymous fn/2 in Electric.Replication.ShapeLogCollector.do_handle_event/2
    (electric 1.2.8) lib/electric/telemetry/open_telemetry.ex:89: anonymous fn/5 in Electric.Telemetry.OpenTelemetry.do_with_span/5
    (telemetry 1.3.0) /builder/electric/deps/telemetry/src/telemetry.erl:324: :telemetry.span/3
    (electric 1.2.8) lib/electric/replication/shape_log_collector.ex:286: Electric.Replication.ShapeLogCollector.handle_call/3
    (stdlib 7.1) gen_server.erl:2470: :gen_server.try_handle_call/4
    (stdlib 7.1) gen_server.erl:2499: :gen_server.handle_msg/3
    (stdlib 7.1) proc_lib.erl:333: :proc_lib.init_p_do_apply/3
Process Label: {:shape_log_collector, "single_stack"}
Last message (from #PID<0.3270.0>): {:handle_event, %Electric.Replication.Changes.TransactionFragment{xid: 887013, lsn: #Lsn<0/7D9814E0>, last_log_offset: LogOffset.new(2107118816, 0), has_begin?: true, commit: %Electric.Replication.Changes.Commit{commit_timestamp: ~U[2025-12-17 22:40:48.160826Z], transaction_size: 448, txn_change_count: 1}, changes: [%Electric.Replication.Changes.UpdatedRecord{relation: {"public", "user"}, old_record: %{"created_at" => "2025-12-03 00:39:53.176267+00", "email" => "[redacted]", "first_name" => "[redactd]", "id" => "019ae1a6-c05d-765c-958e-3de600c86ba2", "last_name" => "[redacted]", "last_read_activity_id" => nil, "onboarded_at" => "2025-12-07 20:20:59.467435+00","updated_at" => "2025-12-17 21:06:05.901255+00", "version" => "259788335784927231"}, record: %{"avatar_color" => nil, "avatar_url" => nil, "created_at" => "2025-12-03 00:39:53.176267+00", "email" => "[redacted]", "first_name" => "Michael", "id" => "019ae1a6-c05d-765c-958e-3de600c86ba2", "last_name" => "[redacted]", "last_read_activity_id" => nil, "onboarded_at" => "2025-12-07 20:20:59.467435+00", "updated_at" => "2025-12-17 22:40:48.145055+00", "version" => "259812168885608447"}, log_offset: LogOffset.new(2107118816, 0), key: nil, old_key: nil, move_tags: [], removed_move_tags: [], changed_columns: MapSet.new(["updated_at", "version"]), last?: false}], affected_relations: MapSet.new([{"public", "user"}]), change_count: 1}, {:undefined, %{}}}

22:40:48.349 pid=<0.2951.0> [warning] Electric.StatusMonitor condition failed: :shape_log_collector_ready. Status %{conn: :up, shape: :starting}

22:40:48.349 pid=<0.2951.0> [warning] Electric.StatusMonitor condition failed: :supervisor_processes_ready. Status %{conn: :up, shape: :starting}

Expected behavior
Not to time out

[mwildehahn]

trying to restart the container:

22:50:56.919 pid=<0.2905.0> [info] Admission control initialized with table: electric_admission_control

22:50:56.926 pid=<0.2909.0> [notice] Starting telemetry reporter. Electric will send anonymous usage data to https://checkpoint.electric-sql.com. You can configure this with `ELECTRIC_USAGE_REPORTING` environment variable, see https://electric-sql.com/docs/reference/telemetry for more information.

22:50:56.926 pid=<0.2913.0> [notice] Starting telemetry reporter. Electric will send anonymous usage data to https://checkpoint.electric-sql.com. You can configure this with `ELECTRIC_USAGE_REPORTING` environment variable, see https://electric-sql.com/docs/reference/telemetry for more information.

22:50:56.935 pid=<0.2902.0> [info] Running Electric.Plug.Router with Bandit 1.8.0 at 0.0.0.0:3000 (http)

22:50:56.946 pid=<0.3271.0> [info] Acquiring lock from postgres with name electric_slot_default

22:50:56.946 pid=<0.2958.0> [info] Postgres server version = 170007, system identifier = 7579374135119876134, timeline_id = 1

22:50:56.946 pid=<0.3271.0> [info] Lock acquired from postgres with name electric_slot_default

22:50:56.950 pid=<0.2953.0> [info] Loaded shape status from backup at ./persistent/shapes/single_stack/.meta/backups/shape_status_backups

22:50:56.958 pid=<0.3281.0> [info] Connection pool [snapshot: postgres-dev:5432] is ready with 16 connections

22:50:56.958 pid=<0.3300.0> [info] Connection pool [admin: postgres-dev:5432] is ready with 4 connections

22:50:56.959 pid=<0.2958.0> [info] Connected to Postgres 7579374135119876134 and timeline 1

22:50:56.959 pid=<0.3308.0> [info] Starting shape replication pipeline

22:50:56.963 pid=<0.3312.0> [info] Restored filters for 67 shapes

22:50:56.963 pid=<0.3335.0> [notice] Consumers ready in 0ms (67 shapes)

22:50:56.963 pid=<0.2958.0> [info] Starting replication from postgres

22:50:56.992 pid=<0.3312.0> [info] Received relation "public"."user"

22:50:57.000 pid=<0.3312.0> [error] GenServer {:"Electric.ProcessRegistry:single_stack", {Electric.Replication.ShapeLogCollector, nil}} terminating
** (stop) exited in: GenServer.call({:via, Registry, {:"Electric.ProcessRegistry:single_stack", {Electric.Shapes.Consumer.Materializer, "22238533-1765579774154582"}}}, :get_link_values, 5000)
    ** (EXIT) no process: the process is not alive or there's no process currently associated with the given name, possibly because its application isn't started
    (elixir 1.19.1) lib/gen_server.ex:1135: GenServer.call/3
    (electric 1.2.8) lib/electric/shapes/consumer/materializer.ex:65: anonymous fn/2 in Electric.Shapes.Consumer.Materializer.get_all_as_refs/2
    (elixir 1.19.1) lib/enum.ex:1688: Enum."-map/2-lists^map/1-1-"/2
    (elixir 1.19.1) lib/map.ex:267: Map.new_from_enum/2
    (electric 1.2.8) lib/electric/shapes/filter/where_condition.ex:209: anonymous fn/6 in Electric.Shapes.Filter.WhereCondition.other_shapes_affected/5
    (stdlib 7.1) maps.erl:894: :maps.fold_1/4
    (electric 1.2.8) lib/electric/shapes/filter/where_condition.ex:207: anonymous fn/4 in Electric.Shapes.Filter.WhereCondition.other_shapes_affected/5
    (electric 1.2.8) lib/electric/telemetry/open_telemetry.ex:89: anonymous fn/5 in Electric.Telemetry.OpenTelemetry.do_with_span/5
    (telemetry 1.3.0) /builder/electric/deps/telemetry/src/telemetry.erl:324: :telemetry.span/3
    (electric 1.2.8) lib/electric/shapes/filter/where_condition.ex:170: Electric.Shapes.Filter.WhereCondition.affected_shapes/4
    (electric 1.2.8) lib/electric/shapes/filter.ex:165: Electric.Shapes.Filter.shapes_affected_by_change/2
    (electric 1.2.8) lib/electric/shapes/filter.ex:123: anonymous fn/2 in Electric.Shapes.Filter.affected_shapes/2
    (stdlib 7.1) timer.erl:599: :timer.tc/2
    (electric 1.2.8) lib/electric/telemetry/open_telemetry.ex:134: Electric.Telemetry.OpenTelemetry.timed_fun/3
    (electric 1.2.8) lib/electric/shapes/event_router.ex:149: Electric.Shapes.EventRouter.find_affected_shapes_for_change/2
    (electric 1.2.8) lib/electric/shapes/event_router.ex:106: Electric.Shapes.EventRouter.route_change/3
    (elixir 1.19.1) lib/enum.ex:2520: Enum."-reduce/3-lists^foldl/2-0-"/3
    (electric 1.2.8) lib/electric/shapes/event_router.ex:83: Electric.Shapes.EventRouter.event_by_shape_handle/2
    (electric 1.2.8) lib/electric/replication/shape_log_collector.ex:505: Electric.Replication.ShapeLogCollector.publish/2
    (electric 1.2.8) lib/electric/replication/shape_log_collector.ex:492: Electric.Replication.ShapeLogCollector.handle_txn_fragment/2
    (electric 1.2.8) lib/electric/replication/shape_log_collector.ex:428: anonymous fn/2 in Electric.Replication.ShapeLogCollector.do_handle_event/2
    (electric 1.2.8) lib/electric/telemetry/open_telemetry.ex:89: anonymous fn/5 in Electric.Telemetry.OpenTelemetry.do_with_span/5
    (telemetry 1.3.0) /builder/electric/deps/telemetry/src/telemetry.erl:324: :telemetry.span/3
    (electric 1.2.8) lib/electric/replication/shape_log_collector.ex:286: Electric.Replication.ShapeLogCollector.handle_call/3
    (stdlib 7.1) gen_server.erl:2470: :gen_server.try_handle_call/4
    (stdlib 7.1) gen_server.erl:2499: :gen_server.handle_msg/3
    (stdlib 7.1) proc_lib.erl:333: :proc_lib.init_p_do_apply/3
Process Label: {:shape_log_collector, "single_stack"}
Last message (from #PID<0.3271.0>): {:handle_event, %Electric.Replication.Changes.TransactionFragment{xid: 887013, lsn: #Lsn<0/7D9814E0>, last_log_offset: LogOffset.new(2107118816, 0), has_begin?: true, commit: %Electric.Replication.Changes.Commit{commit_timestamp: ~U[2025-12-17 22:40:48.160826Z], transaction_size: 448, txn_change_count: 1}, changes: [%Electric.Replication.Changes.UpdatedRecord{relation: {"public", "user"}, old_record: %{...data above}, record: %{...data above}, log_offset: LogOffset.new(2107118816, 0), key: nil, old_key: nil, move_tags: [], removed_move_tags: [], changed_columns: MapSet.new(["updated_at", "version"]), last?: false}], affected_relations: MapSet.new([{"public", "user"}]), change_count: 1}, {:undefined, %{}}}

22:50:57.002 pid=<0.2952.0> [warning] Electric.StatusMonitor condition failed: :shape_log_collector_ready. Status %{conn: :up, shape: :starting}

22:50:57.002 pid=<0.2952.0> [warning] Electric.StatusMonitor condition failed: :supervisor_processes_ready. Status %{conn: :up, shape: :starting}

[alco]

Hey @mwildehahn. Thanks for the report!

The timeout message itself is fine: client requests get this error when Electric is not able to fulfill the shape request.

The underlying problem looks like a bug with subqueries. Can you share the config you're running Electric with (with sensitive info like PG password redacted) and the shapes you're creating?

[mwildehahn]

Just ran into this again:

  Image: electricsql/electric:1.2.8
  DATABASE_URL: postgresql://user:***@host:5432/db?sslmode=disable
  ELECTRIC_INSECURE: true
  ELECTRIC_FEATURE_FLAGS: allow_subqueries

  Shapes with Subqueries

  Shape 1 - Nested subqueries:
  deleted_at IS NULL
  AND id IN (
    SELECT fk1 FROM table_b
    WHERE status = 'x'
    AND fk1 IN (
      SELECT fk2 FROM table_c
      WHERE type = 'y'
      AND fk3 IN ($1, $2, ...)
    )
  )

  Shape 2 - OR with subquery:
  deleted_at IS NULL
  AND (
    user_id = '<uuid>'
    OR id IN (
      SELECT fk1 FROM table_b
      WHERE fk2 IN ('<uuid>', '<uuid>', ...)
    )
  )

  Shape 3 - Simple subquery:
  fk1 IN (
    SELECT id FROM table_b
    WHERE fk2 IN ('<uuid>', '<uuid>', ...)
  )

  Shape 4 - OR with subquery:
  (
    id IN ('<uuid>', '<uuid>')
    OR id IN (
      SELECT fk1 FROM table_b
      WHERE fk2 IN ('<uuid>', '<uuid>', ...)
    )
  )

this is our docker compose config and these our roughly the subqueries we're using