Re: BUG #18415: Logical replication errors.

On Fri, 29 Mar 2024 at 05:50, koderan <koderan@yandex.ru> wrote:
>
> There is publisher and subscriber logs, but the logs on both nodes did not give me clarity.
> Master (time when errors start to appear):
>
> 2024-03-28 22:26:08.459 +07 [1004642] ERROR:  could not start WAL streaming: ERROR:  replication slot
"pg_975006_sync_972467_7293549148661379912"does not exist 
> 2024-03-28 22:26:08.462 +07 [1597281] LOG:  background worker "logical replication worker" (PID 1004642) exited with
exitcode 1 
> 2024-03-28 22:26:08.466 +07 [1048261] LOG:  logical replication table synchronization worker for subscription
"log_rep_sub",table "scan_type_i18n" has started 
> 2024-03-28 22:26:08.542 +07 [1048261] LOG:  logical replication table synchronization worker for subscription
"log_rep_sub",table "scan_type_i18n" has finished 
> 2024-03-28 22:26:08.548 +07 [1048263] LOG:  logical replication table synchronization worker for subscription
"log_rep_sub",table "phone_type_i18n" has started 
> 2024-03-28 22:26:08.641 +07 [1048263] LOG:  logical replication table synchronization worker for subscription
"log_rep_sub",table "phone_type_i18n" has finished 
> 2024-03-28 22:26:08.644 +07 [1048264] LOG:  logical replication table synchronization worker for subscription
"log_rep_sub",table "reply_status_type_i18n" has started 
> 2024-03-28 22:26:08.690 +07 [1048264] LOG:  logical replication table synchronization worker for subscription
"log_rep_sub",table "reply_status_type_i18n" has finished 
> 2024-03-28 22:26:08.693 +07 [1048265] LOG:  logical replication table synchronization worker for subscription
"log_rep_sub",table "user" has started 
> 2024-03-28 22:26:09.054 +07 [1048265] LOG:  logical replication table synchronization worker for subscription
"log_rep_sub",table "user" has finished 
> 2024-03-28 22:26:09.059 +07 [1048267] LOG:  logical replication table synchronization worker for subscription
"log_rep_sub",table "queue_event" has started 
> 2024-03-28 22:26:09.141 +07 [1048267] LOG:  logical replication table synchronization worker for subscription
"log_rep_sub",table "queue_event" has finished 
> 2024-03-28 22:26:09.146 +07 [1048274] LOG:  logical replication table synchronization worker for subscription
"log_rep_sub",table "credit" has started 
> 2024-03-28 22:26:09.163 +07 [1048274] ERROR:  could not start WAL streaming: ERROR:  replication slot
"pg_975006_sync_972243_7293549148661379912"does not exist 
> 2024-03-28 22:26:09.165 +07 [1597281] LOG:  background worker "logical replication worker" (PID 1048274) exited with
exitcode 1 
> 2024-03-28 22:26:09.167 +07 [1048281] LOG:  logical replication table synchronization worker for subscription
"log_rep_sub",table "requisite_value_contragent" has started 
> 2024-03-28 22:26:09.184 +07 [1048281] ERROR:  could not start WAL streaming: ERROR:  replication slot
"pg_975006_sync_972563_7293549148661379912"does not exist 
> 2024-03-28 22:26:09.186 +07 [1597281] LOG:  background worker "logical replication worker" (PID 1048281) exited with
exitcode 1 
> 2024-03-28 22:26:09.189 +07 [1048282] LOG:  logical replication table synchronization worker for subscription
"log_rep_sub",table "order_registry_np" has started 
>
> The same time on replica:
>
> 2024-03-28 22:26:07.967 +07 [25424] postgres@claims LOG:  duration: 2406278.201 ms  statement: COPY public.orders
(id,order_number, order_date, order_amount, payment_info_code, payer_code, payer_name, receiver_code, receiver_name,
sender_code,sender_name, cargo_description, cargo_volume_weight, cargo_weight, declared_price, currency_code,
internet_store_number,subdivision_code, cfo_code, active, date_created, date_updated, delay) TO STDOUT 
> 2024-03-28 22:26:08.426 +07 [25424] postgres@claims ERROR:  replication slot
"pg_975006_sync_972467_7293549148661379912"does not exist 
> 2024-03-28 22:26:08.466 +07 [1170] postgres@claims LOG:  logical decoding found initial starting point at
B1C5/BFBA3410
> 2024-03-28 22:26:08.466 +07 [1170] postgres@claims DETAIL:  Waiting for transactions (approximately 1) older than
2998665818to end. 
> 2024-03-28 22:26:08.469 +07 [1165] [unknown]@[unknown] LOG:  could not accept SSL connection: EOF detected
> 2024-03-28 22:26:08.496 +07 [1170] postgres@claims LOG:  logical decoding found consistent point at B1C5/BFBA4580
> 2024-03-28 22:26:08.496 +07 [1170] postgres@claims DETAIL:  There are no running transactions.
> 2024-03-28 22:26:08.507 +07 [1170] postgres@claims LOG:  starting logical decoding for slot
"pg_975006_sync_971138_7293549148661379912"
> 2024-03-28 22:26:08.507 +07 [1170] postgres@claims DETAIL:  Streaming transactions committing after B1C5/BFBA45B8,
readingWAL from B1C5/BFBA3290. 
> 2024-03-28 22:26:08.507 +07 [1170] postgres@claims LOG:  logical decoding found consistent point at B1C5/BFBA3410
> 2024-03-28 22:26:08.507 +07 [1170] postgres@claims DETAIL:  Logical decoding will begin using saved snapshot.
> 2024-03-28 22:26:08.546 +07 [1172] postgres@claims LOG:  logical decoding found initial starting point at
B1C5/BFBAA200
> 2024-03-28 22:26:08.546 +07 [1172] postgres@claims DETAIL:  Waiting for transactions (approximately 2) older than
2998665822to end. 
> 2024-03-28 22:26:08.594 +07 [1172] postgres@claims LOG:  logical decoding found consistent point at B1C5/BFBB5E80
> 2024-03-28 22:26:08.594 +07 [1172] postgres@claims DETAIL:  There are no running transactions.
> 2024-03-28 22:26:08.602 +07 [1172] postgres@claims LOG:  starting logical decoding for slot
"pg_975006_sync_970776_7293549148661379912"
> 2024-03-28 22:26:08.602 +07 [1172] postgres@claims DETAIL:  Streaming transactions committing after B1C5/BFBB5EB8,
readingWAL from B1C5/BFBA5290. 
> 2024-03-28 22:26:08.602 +07 [1172] postgres@claims LOG:  logical decoding found consistent point at B1C5/BFBAA200
> 2024-03-28 22:26:08.602 +07 [1172] postgres@claims DETAIL:  Logical decoding will begin using saved snapshot.
> 2024-03-28 22:26:08.645 +07 [1173] postgres@claims LOG:  logical decoding found consistent point at B1C5/BFBB8E28
> 2024-03-28 22:26:08.645 +07 [1173] postgres@claims DETAIL:  There are no running transactions.
> 2024-03-28 22:26:08.652 +07 [1173] postgres@claims LOG:  starting logical decoding for slot
"pg_975006_sync_971808_7293549148661379912"
> 2024-03-28 22:26:08.652 +07 [1173] postgres@claims DETAIL:  Streaming transactions committing after B1C5/BFBB8E60,
readingWAL from B1C5/BFBB8E28. 
> 2024-03-28 22:26:08.652 +07 [1173] postgres@claims LOG:  logical decoding found consistent point at B1C5/BFBB8E28
> 2024-03-28 22:26:08.652 +07 [1173] postgres@claims DETAIL:  There are no running transactions.
> 2024-03-28 22:26:08.697 +07 [1174] postgres@claims LOG:  logical decoding found consistent point at B1C5/BFBBE588
> 2024-03-28 22:26:08.697 +07 [1174] postgres@claims DETAIL:  There are no running transactions.
> 2024-03-28 22:26:09.019 +07 [1174] postgres@claims LOG:  starting logical decoding for slot
"pg_975006_sync_971995_7293549148661379912"
> 2024-03-28 22:26:09.019 +07 [1174] postgres@claims DETAIL:  Streaming transactions committing after B1C5/BFBBE5C0,
readingWAL from B1C5/BFBBE588. 
> 2024-03-28 22:26:09.019 +07 [1174] postgres@claims LOG:  logical decoding found consistent point at B1C5/BFBBE588
> 2024-03-28 22:26:09.019 +07 [1174] postgres@claims DETAIL:  There are no running transactions.
> 2024-03-28 22:26:09.056 +07 [1180] postgres@claims LOG:  logical decoding found consistent point at B1C5/BFBE0C88
> 2024-03-28 22:26:09.056 +07 [1180] postgres@claims DETAIL:  There are no running transactions.
> 2024-03-28 22:26:09.105 +07 [1180] postgres@claims LOG:  starting logical decoding for slot
"pg_975006_sync_972492_7293549148661379912"
> 2024-03-28 22:26:09.105 +07 [1180] postgres@claims DETAIL:  Streaming transactions committing after B1C5/BFBE0CC0,
readingWAL from B1C5/BFBE0C88. 
> 2024-03-28 22:26:09.105 +07 [1180] postgres@claims LOG:  logical decoding found consistent point at B1C5/BFBE0C88
> 2024-03-28 22:26:09.105 +07 [1180] postgres@claims DETAIL:  There are no running transactions.
> 2024-03-28 22:26:09.129 +07 [1181] postgres@claims ERROR:  replication slot
"pg_975006_sync_972243_7293549148661379912"does not exist 
> 2024-03-28 22:26:09.151 +07 [1182] postgres@claims ERROR:  replication slot
"pg_975006_sync_972563_7293549148661379912"does not exist 
> 2024-03-28 22:26:09.172 +07 [1184] postgres@claims ERROR:  replication slot
"pg_975006_sync_972454_7293549148661379912"does not exist 
> 2024-03-28 22:26:09.196 +07 [1185] postgres@claims ERROR:  replication slot
"pg_975006_sync_972467_7293549148661379912"does not exist 
>
>
> 28.03.2024, 20:03, "David G. Johnston" <david.g.johnston@gmail.com>:
>
> On Thu, Mar 28, 2024 at 9:59 AM PG Bug reporting form <noreply@postgresql.org> wrote:
>
> The following bug has been logged on the website:
>
> Bug reference:      18415
> Logged by:          Andy Kosheen
> Email address:      koderan@yandex.ru
> PostgreSQL version: 15.4
> Operating system:   Oracle Linux Server 8.4
> Description:
>
> In the process of logical replication from version 13.3 (on Ubuntu 16.04.6
> LTS) to version 15.4 (on Oracle Linux Server 8.4), when most of the data has
> already been transferred, the following errors begin to occur, appearing
> endlessly until you stop the replication process (this situation occurs on
> databases larger than at least 50GB, even if there is a small number of
> transactions on the source database):
> 2024-03-20 03:19:41.410 +07 [3433858] LOG:  logical replication apply worker
> for subscription "log_rep_sub" has started
> 2024-03-20 03:19:41.425 +07 [3433858] ERROR:  could not start WAL streaming:
> ERROR:  replication slot "log_rep_sub" does not exist

By any chance do you have a reproducible test case for this. Also are
there any other abnormalities in the log. What was the
max_replication_slots configuration set in the publisher and what are
the replication slots that were being used in the publisher at that
point(select * from pg_replication_slots).

Regards,
Vignesh