cannot start electric after a wipe

[MichalNemec]

2024-04-21 23:10:30 21:10:30.294 pid=<0.2770.0> [info] Starting ElectricSQL 0.10.1 in logical_replication mode.
2024-04-21 23:10:30 21:10:30.303 pid=<0.2771.0> [info] Running Electric.Plug.Router with Bandit 1.1.3 at 0.0.0.0:5133 (http)
2024-04-21 23:10:30 21:10:30.305 pid=<0.3390.0> origin=postgres_1 [info] Electric.Replication.Postgres.Client.with_conn(%{database: ~c"electric", host: ~c"192.168.0.117", ip_addr: ~c"192.168.0.117", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5433, ssl: true, ssl_opts: [server_name_indication: ~c"192.168.0.117"], timeout: 5000, username: ~c"postgres"})
2024-04-21 23:10:30 21:10:30.332 pid=<0.3390.0> origin=postgres_1 [info] Running extension migration: 20230328113927
2024-04-21 23:10:30 21:10:30.345 pid=<0.3390.0> origin=postgres_1 [info] Running extension migration: 20230424154425
2024-04-21 23:10:30 21:10:30.402 pid=<0.3390.0> origin=postgres_1 [info] Running extension migration: 20230512000000
2024-04-21 23:10:30 21:10:30.420 pid=<0.3390.0> origin=postgres_1 [info] Running extension migration: 20230605141256
2024-04-21 23:10:30 21:10:30.424 pid=<0.3390.0> origin=postgres_1 [info] Running extension migration: 20230715000000
2024-04-21 23:10:30 21:10:30.426 pid=<0.3390.0> origin=postgres_1 [info] Running extension migration: 20230814170123
2024-04-21 23:10:30 21:10:30.494 pid=<0.3390.0> origin=postgres_1 [info] Running extension migration: 20230814170745
2024-04-21 23:10:30 21:10:30.508 pid=<0.3390.0> origin=postgres_1 [info] Running extension migration: 20230829000000
2024-04-21 23:10:30 21:10:30.513 pid=<0.3390.0> origin=postgres_1 [info] Running extension migration: 20230918115714
2024-04-21 23:10:30 21:10:30.515 pid=<0.3390.0> origin=postgres_1 [info] Running extension migration: 20230921161045
2024-04-21 23:10:30 21:10:30.516 pid=<0.3390.0> origin=postgres_1 [info] Running extension migration: 20230921161418
2024-04-21 23:10:30 21:10:30.533 pid=<0.3390.0> origin=postgres_1 [info] Running extension migration: 20231009121515
2024-04-21 23:10:30 21:10:30.538 pid=<0.3390.0> origin=postgres_1 [info] Running extension migration: 20231010123118
2024-04-21 23:10:30 21:10:30.540 pid=<0.3390.0> origin=postgres_1 [info] Running extension migration: 20231016141000
2024-04-21 23:10:30 21:10:30.542 pid=<0.3390.0> origin=postgres_1 [info] Running extension migration: 20231206130400
2024-04-21 23:10:30 21:10:30.545 pid=<0.3390.0> origin=postgres_1 [info] Running extension migration: 20240110110200
2024-04-21 23:10:30 21:10:30.547 pid=<0.3390.0> origin=postgres_1 [info] Running extension migration: 20240205141200
2024-04-21 23:10:30 21:10:30.551 pid=<0.3390.0> origin=postgres_1 [info] Running extension migration: 20240213160300
2024-04-21 23:10:30 21:10:30.621 pid=<0.3390.0> origin=postgres_1 [info] Successfully initialized origin postgres_1 at extension version 20240213160300
2024-04-21 23:10:30 21:10:30.621 pid=<0.3395.0> [info] Starting Proxy server listening on port 65432
2024-04-21 23:10:30 21:10:30.621 pid=<0.3396.0> pg_producer=postgres_1 [info] Starting Elixir.Electric.Postgres.Extension.SchemaCache for postgres_1
2024-04-21 23:10:30 21:10:30.621 pid=<0.3396.0> pg_producer=postgres_1 [warning] SchemaCache "postgres_1" registered as the global instance
2024-04-21 23:10:30 21:10:30.622 pid=<0.3399.0> [info] Starting replication from postgres_1
2024-04-21 23:10:30 21:10:30.622 pid=<0.3399.0> [info] Electric.Replication.Postgres.LogicalReplicationProducer.init(%{database: ~c"electric", host: ~c"192.168.0.117", ip_addr: ~c"192.168.0.117", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5433, replication: ~c"database", ssl: true, ssl_opts: [server_name_indication: ~c"192.168.0.117"], timeout: 5000, username: ~c"postgres"})
2024-04-21 23:10:30 21:10:30.641 pid=<0.3403.0> pg_producer=postgres_1 [info] Starting Elixir.Electric.Replication.Postgres.MigrationConsumer using Elixir.Electric.Postgres.Extension.SchemaCache backend
2024-04-21 23:10:30 21:10:30.647 pid=<0.3390.0> origin=postgres_1 [info] Successfully initialized Postgres connector "postgres_1".
2024-04-21 23:10:30 21:10:30.647 pid=<0.3390.0> origin=postgres_1 [info] Electric.Replication.Postgres.Client.with_conn(%{database: ~c"electric", host: ~c"192.168.0.117", ip_addr: ~c"192.168.0.117", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5433, ssl: true, ssl_opts: [server_name_indication: ~c"192.168.0.117"], timeout: 5000, username: ~c"postgres"})
2024-04-21 23:10:30 21:10:30.650 pid=<0.3400.0> [error] GenServer #PID<0.3400.0> terminating
2024-04-21 23:10:30 ** (stop) {:error, {:error, :error, "42704", :undefined_object, "publication \"electric_publication\" does not exist", [file: "pg_publication.c", line: "533", routine: "get_publication_oid", severity: "ERROR", where: "slot \"electric_replication_out_electric\", output plugin \"pgoutput\", in the change callback, associated LSN 0/E5C2D10"]}}
2024-04-21 23:10:30 Last message: {:tcp, #Port<0.15>, <<69, 0, 0, 0, 239, 83, 69, 82, 82, 79, 82, 0, 86, 69, 82, 82, 79, 82, 0, 67, 52, 50, 55, 48, 52, 0, 77, 112, 117, 98, 108, 105, 99, 97, 116, 105, 111, 110, 32, 34, 101, 108, 101, 99, 116, 114, 105, ...>>}
2024-04-21 23:10:30 21:10:30.650 pid=<0.3403.0> pg_producer=postgres_1 [warning] producer is down: {:via, :gproc, {:n, :l, {Electric.Replication.Postgres.LogicalReplicationProducer, "postgres_1"}}}
2024-04-21 23:10:30 21:10:30.650 pid=<0.3711.0> [info] Starting replication from postgres_1
2024-04-21 23:10:30 21:10:30.651 pid=<0.3711.0> [info] Electric.Replication.Postgres.LogicalReplicationProducer.init(%{database: ~c"electric", host: ~c"192.168.0.117", ip_addr: ~c"192.168.0.117", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5433, replication: ~c"database", ssl: true, ssl_opts: [server_name_indication: ~c"192.168.0.117"], timeout: 5000, username: ~c"postgres"})
2024-04-21 23:10:30 21:10:30.669 pid=<0.3404.0> origin=postgres_1 pg_slot=postgres_1 [info] Starting replication to postgres_1
2024-04-21 23:10:30 21:10:30.674 pid=<0.3712.0> [error] GenServer #PID<0.3712.0> terminating
2024-04-21 23:10:30 ** (stop) {:error, {:error, :error, "42704", :undefined_object, "publication \"electric_publication\" does not exist", [file: "pg_publication.c", line: "533", routine: "get_publication_oid", severity: "ERROR", where: "slot \"electric_replication_out_electric\", output plugin \"pgoutput\", in the change callback, associated LSN 0/E5C2D10"]}}
2024-04-21 23:10:30 Last message: {:tcp, #Port<0.20>, <<100, 0, 0, 0, 50, 119, 0, 0, 0, 0, 14, 91, 240, 72, 0, 0, 0, 0, 14, 91, 240, 72, 0, 2, 185, 160, 132, 255, 159, 244, 66, 0, 0, 0, 0, 14, 92, 49, 32, 0, 2, 185, 159, 192, 154, 161, 195, ...>>}
2024-04-21 23:10:30 21:10:30.674 pid=<0.3396.0> pg_producer=postgres_1 [info] CREATE TABLE acknowledged_client_lsns (...)
2024-04-21 23:10:30 21:10:30.675 pid=<0.3403.0> pg_producer=postgres_1 [warning] producer is down: {:via, :gproc, {:n, :l, {Electric.Replication.Postgres.LogicalReplicationProducer, "postgres_1"}}}
2024-04-21 23:10:30 21:10:30.675 pid=<0.3717.0> [info] Starting replication from postgres_1
2024-04-21 23:10:30 21:10:30.675 pid=<0.3717.0> [info] Electric.Replication.Postgres.LogicalReplicationProducer.init(%{database: ~c"electric", host: ~c"192.168.0.117", ip_addr: ~c"192.168.0.117", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5433, replication: ~c"database", ssl: true, ssl_opts: [server_name_indication: ~c"192.168.0.117"], timeout: 5000, username: ~c"postgres"})
2024-04-21 23:10:30 21:10:30.682 pid=<0.3390.0> origin=postgres_1 [notice] subscription started for postgres_1
2024-04-21 23:10:30 21:10:30.698 pid=<0.3718.0> [error] GenServer #PID<0.3718.0> terminating
2024-04-21 23:10:30 ** (stop) {:error, {:error, :error, "42704", :undefined_object, "publication \"electric_publication\" does not exist", [file: "pg_publication.c", line: "533", routine: "get_publication_oid", severity: "ERROR", where: "slot \"electric_replication_out_electric\", output plugin \"pgoutput\", in the change callback, associated LSN 0/E5C2D10"]}}
2024-04-21 23:10:30 Last message: {:tcp, #Port<0.24>, <<69, 0, 0, 0, 239, 83, 69, 82, 82, 79, 82, 0, 86, 69, 82, 82, 79, 82, 0, 67, 52, 50, 55, 48, 52, 0, 77, 112, 117, 98, 108, 105, 99, 97, 116, 105, 111, 110, 32, 34, 101, 108, 101, 99, 116, 114, 105, ...>>}
2024-04-21 23:10:30 21:10:30.699 pid=<0.3403.0> pg_producer=postgres_1 [warning] producer is down: {:via, :gproc, {:n, :l, {Electric.Replication.Postgres.LogicalReplicationProducer, "postgres_1"}}}
2024-04-21 23:10:30 21:10:30.699 pid=<0.3720.0> [info] Starting replication from postgres_1
2024-04-21 23:10:30 21:10:30.699 pid=<0.3720.0> [info] Electric.Replication.Postgres.LogicalReplicationProducer.init(%{database: ~c"electric", host: ~c"192.168.0.117", ip_addr: ~c"192.168.0.117", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5433, replication: ~c"database", ssl: true, ssl_opts: [server_name_indication: ~c"192.168.0.117"], timeout: 5000, username: ~c"postgres"})
2024-04-21 23:10:30 21:10:30.719 pid=<0.3721.0> [error] GenServer #PID<0.3721.0> terminating
2024-04-21 23:10:30 ** (stop) {:error, {:error, :error, "42704", :undefined_object, "publication \"electric_publication\" does not exist", [file: "pg_publication.c", line: "533", routine: "get_publication_oid", severity: "ERROR", where: "slot \"electric_replication_out_electric\", output plugin \"pgoutput\", in the change callback, associated LSN 0/E5C2D10"]}}
2024-04-21 23:10:30 Last message: {:tcp, #Port<0.26>, <<69, 0, 0, 0, 239, 83, 69, 82, 82, 79, 82, 0, 86, 69, 82, 82, 79, 82, 0, 67, 52, 50, 55, 48, 52, 0, 77, 112, 117, 98, 108, 105, 99, 97, 116, 105, 111, 110, 32, 34, 101, 108, 101, 99, 116, 114, 105, ...>>}
2024-04-21 23:10:30 21:10:30.719 pid=<0.3403.0> pg_producer=postgres_1 [warning] producer is down: {:via, :gproc, {:n, :l, {Electric.Replication.Postgres.LogicalReplicationProducer, "postgres_1"}}}
2024-04-21 23:10:30 21:10:30.723 pid=<0.3390.0> origin=postgres_1 [info] schedule retry: 2000
2024-04-21 23:10:32 21:10:32.724 pid=<0.3390.0> origin=postgres_1 [info] Electric.Replication.Postgres.Client.with_conn(%{database: ~c"electric", host: ~c"192.168.0.117", ip_addr: ~c"192.168.0.117", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5433, ssl: true, ssl_opts: [server_name_indication: ~c"192.168.0.117"], timeout: 5000, username: ~c"postgres"})
2024-04-21 23:10:32 21:10:32.782 pid=<0.3390.0> origin=postgres_1 [info] Successfully initialized origin postgres_1 at extension version 
2024-04-21 23:10:32 21:10:32.782 pid=<0.3724.0> [info] Starting Proxy server listening on port 65432
2024-04-21 23:10:32 21:10:32.782 pid=<0.3725.0> pg_producer=postgres_1 [info] Starting Elixir.Electric.Postgres.Extension.SchemaCache for postgres_1
2024-04-21 23:10:32 21:10:32.782 pid=<0.3725.0> pg_producer=postgres_1 [warning] SchemaCache "postgres_1" registered as the global instance
2024-04-21 23:10:32 21:10:32.782 pid=<0.3728.0> [info] Starting replication from postgres_1
2024-04-21 23:10:32 21:10:32.782 pid=<0.3728.0> [info] Electric.Replication.Postgres.LogicalReplicationProducer.init(%{database: ~c"electric", host: ~c"192.168.0.117", ip_addr: ~c"192.168.0.117", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5433, replication: ~c"database", ssl: true, ssl_opts: [server_name_indication: ~c"192.168.0.117"], timeout: 5000, username: ~c"postgres"})
2024-04-21 23:10:32 21:10:32.805 pid=<0.3732.0> pg_producer=postgres_1 [info] Starting Elixir.Electric.Replication.Postgres.MigrationConsumer using Elixir.Electric.Postgres.Extension.SchemaCache backend
2024-04-21 23:10:32 21:10:32.809 pid=<0.3390.0> origin=postgres_1 [info] Successfully initialized Postgres connector "postgres_1".
2024-04-21 23:10:32 21:10:32.809 pid=<0.3390.0> origin=postgres_1 [info] Electric.Replication.Postgres.Client.with_conn(%{database: ~c"electric", host: ~c"192.168.0.117", ip_addr: ~c"192.168.0.117", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5433, ssl: true, ssl_opts: [server_name_indication: ~c"192.168.0.117"], timeout: 5000, username: ~c"postgres"})
2024-04-21 23:10:32 21:10:32.818 pid=<0.3729.0> [error] GenServer #PID<0.3729.0> terminating
2024-04-21 23:10:32 ** (stop) {:error, {:error, :error, "42704", :undefined_object, "publication \"electric_publication\" does not exist", [file: "pg_publication.c", line: "533", routine: "get_publication_oid", severity: "ERROR", where: "slot \"electric_replication_out_electric\", output plugin \"pgoutput\", in the change callback, associated LSN 0/E5C2D10"]}}
2024-04-21 23:10:32 Last message: {:tcp, #Port<0.29>, <<69, 0, 0, 0, 239, 83, 69, 82, 82, 79, 82, 0, 86, 69, 82, 82, 79, 82, 0, 67, 52, 50, 55, 48, 52, 0, 77, 112, 117, 98, 108, 105, 99, 97, 116, 105, 111, 110, 32, 34, 101, 108, 101, 99, 116, 114, 105, ...>>}
2024-04-21 23:10:32 21:10:32.818 pid=<0.3732.0> pg_producer=postgres_1 [warning] producer is down: {:via, :gproc, {:n, :l, {Electric.Replication.Postgres.LogicalReplicationProducer, "postgres_1"}}}
2024-04-21 23:10:32 21:10:32.818 pid=<0.4040.0> [info] Starting replication from postgres_1
2024-04-21 23:10:32 21:10:32.818 pid=<0.4040.0> [info] Electric.Replication.Postgres.LogicalReplicationProducer.init(%{database: ~c"electric", host: ~c"192.168.0.117", ip_addr: ~c"192.168.0.117", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5433, replication: ~c"database", ssl: true, ssl_opts: [server_name_indication: ~c"192.168.0.117"], timeout: 5000, username: ~c"postgres"})
2024-04-21 23:10:32 21:10:32.826 pid=<0.3725.0> pg_producer=postgres_1 [info] CREATE TABLE acknowledged_client_lsns (...)
2024-04-21 23:10:32 21:10:32.829 pid=<0.3390.0> origin=postgres_1 [notice] subscription started for postgres_1
2024-04-21 23:10:32 21:10:32.839 pid=<0.4041.0> [error] GenServer #PID<0.4041.0> terminating
2024-04-21 23:10:32 ** (stop) {:error, {:error, :error, "42704", :undefined_object, "publication \"electric_publication\" does not exist", [file: "pg_publication.c", line: "533", routine: "get_publication_oid", severity: "ERROR", where: "slot \"electric_replication_out_electric\", output plugin \"pgoutput\", in the change callback, associated LSN 0/E5C2D10"]}}
2024-04-21 23:10:32 Last message: {:tcp, #Port<0.34>, <<69, 0, 0, 0, 239, 83, 69, 82, 82, 79, 82, 0, 86, 69, 82, 82, 79, 82, 0, 67, 52, 50, 55, 48, 52, 0, 77, 112, 117, 98, 108, 105, 99, 97, 116, 105, 111, 110, 32, 34, 101, 108, 101, 99, 116, 114, 105, ...>>}
2024-04-21 23:10:32 21:10:32.840 pid=<0.3732.0> pg_producer=postgres_1 [warning] producer is down: {:via, :gproc, {:n, :l, {Electric.Replication.Postgres.LogicalReplicationProducer, "postgres_1"}}}
2024-04-21 23:10:32 21:10:32.840 pid=<0.4044.0> [info] Starting replication from postgres_1
2024-04-21 23:10:32 21:10:32.840 pid=<0.4044.0> [info] Electric.Replication.Postgres.LogicalReplicationProducer.init(%{database: ~c"electric", host: ~c"192.168.0.117", ip_addr: ~c"192.168.0.117", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5433, replication: ~c"database", ssl: true, ssl_opts: [server_name_indication: ~c"192.168.0.117"], timeout: 5000, username: ~c"postgres"})
2024-04-21 23:10:32 21:10:32.854 pid=<0.4045.0> [error] GenServer #PID<0.4045.0> terminating
2024-04-21 23:10:32 ** (stop) {:error, {:error, :error, "42704", :undefined_object, "publication \"electric_publication\" does not exist", [file: "pg_publication.c", line: "533", routine: "get_publication_oid", severity: "ERROR", where: "slot \"electric_replication_out_electric\", output plugin \"pgoutput\", in the change callback, associated LSN 0/E5C2D10"]}}
2024-04-21 23:10:32 Last message: {:tcp, #Port<0.37>, <<69, 0, 0, 0, 239, 83, 69, 82, 82, 79, 82, 0, 86, 69, 82, 82, 79, 82, 0, 67, 52, 50, 55, 48, 52, 0, 77, 112, 117, 98, 108, 105, 99, 97, 116, 105, 111, 110, 32, 34, 101, 108, 101, 99, 116, 114, 105, ...>>}
2024-04-21 23:10:32 21:10:32.854 pid=<0.3732.0> pg_producer=postgres_1 [warning] producer is down: {:via, :gproc, {:n, :l, {Electric.Replication.Postgres.LogicalReplicationProducer, "postgres_1"}}}
2024-04-21 23:10:32 21:10:32.854 pid=<0.4047.0> [info] Starting replication from postgres_1
2024-04-21 23:10:32 21:10:32.854 pid=<0.4047.0> [info] Electric.Replication.Postgres.LogicalReplicationProducer.init(%{database: ~c"electric", host: ~c"192.168.0.117", ip_addr: ~c"192.168.0.117", ipv6: false, nulls: [nil, :null, :undefined], password: ~c"******", port: 5433, replication: ~c"database", ssl: true, ssl_opts: [server_name_indication: ~c"192.168.0.117"], timeout: 5000, username: ~c"postgres"})
2024-04-21 23:10:32 21:10:32.868 pid=<0.4048.0> [error] GenServer #PID<0.4048.0> terminating
2024-04-21 23:10:32 ** (stop) {:error, {:error, :error, "42704", :undefined_object, "publication \"electric_publication\" does not exist", [file: "pg_publication.c", line: "533", routine: "get_publication_oid", severity: "ERROR", where: "slot \"electric_replication_out_electric\", output plugin \"pgoutput\", in the change callback, associated LSN 0/E5C2D10"]}}
2024-04-21 23:10:32 Last message: {:tcp, #Port<0.39>, <<69, 0, 0, 0, 239, 83, 69, 82, 82, 79, 82, 0, 86, 69, 82, 82, 79, 82, 0, 67, 52, 50, 55, 48, 52, 0, 77, 112, 117, 98, 108, 105, 99, 97, 116, 105, 111, 110, 32, 34, 101, 108, 101, 99, 116, 114, 105, ...>>}
2024-04-21 23:10:32 21:10:32.868 pid=<0.3732.0> pg_producer=postgres_1 [warning] producer is down: {:via, :gproc, {:n, :l, {Electric.Replication.Postgres.LogicalReplicationProducer, "postgres_1"}}}
2024-04-21 23:10:32 21:10:32.871 pid=<0.3390.0> origin=postgres_1 [info] schedule retry: 2000
2024-04-21 23:10:33 21:10:33.831 pid=<0.2763.0> [info] tzdata release in place is from a file last modified Fri, 22 Oct 2021 02:20:47 GMT. Release file on server was last modified Thu, 01 Feb 2024 18:40:48 GMT.
2024-04-21 23:10:34 
2024-04-21 23:10:34 BREAK: (a)bort (A)bort with dump (c)ontinue (p)roc info (i)nfo
2024-04-21 23:10:34        (l)oaded (v)ersion (k)ill (D)b-tables (d)istribution
2024-04-21 23:10:34 [os_mon] cpu supervisor port (cpu_sup): Erlang has closed
2024-04-21 23:10:34 [os_mon] memory supervisor port (memsup): Erlang has closed

[linear]

VAX-1803 cannot start electric after a wipe

[MichalNemec]

SELECT slot_name,
       slot_type,
       database,
       active,
       restart_lsn,
       confirmed_flush_lsn
FROM pg_replication_slots;

showed me after wipe, that the replication still existed, wasnt cleared properly i assume, deleting it fixed it.
Could be also a good hint for people to check that.

[alco]

Hey @MichalNemec . Could you give us more details about the wiping process? What did you remove? Was Electric running at that time?

[MichalNemec]

My usecase is a little bit different, dotnet backend holds migrations, so in the development process when i create a migration on backend side, then electric does not know about new changes in database schema.

What im doing is this:

1. kill electric docker container
2. use https://electric-sql.com/docs/reference/roadmap#failure-modes code to wipe it
3. start electric again
4. do app migration (only enable electric on tables)
5. generate schema and continue with the work

However step 2 probably got messed up and step 3 didnt hint me that i didnt remove everything properly.

im doing this process because app should reflect what is in the database and backend holds the "real" database, so backend should be doing migrations. App should only get stuff from cli and generate db. Thats my usecase tho.

[alco]

@MichalNemec Thanks for sharing the details. We'll review that documentation page and bring it up to date.