Test Scenario ================= OBJECTIVE - Break the connection during table copy (after slot is created) - Later re-establish the connection - Check tablesync is able to recover and finish normally. - Check no slots are left dangling. ================= STEPS 1. Create PUBLISHER 2. Insert some initial table data 3. Create SUBSCRIBER 4. Cause a network connection failure DURING table copy but AFTER the slot is created 4a. Pause in debugger AFTER slot created but before the copy 4b. Make the connect fail by stopping the PUBLISHER Postgres instance at this time 5. Let the tablesync continue. 5a. The tablesync will re-launch but I think it will continue to fail and and fail and fail because cannot create slot which the connection is broken 6. Then fix the connection by starting the PUBLISHER Postgres instance again 6a. The tablesync will attempt to create the slot will ERROR (already exists) at this time but then the PG_CATCH will drop it and the tablesync will be launched yet again… 7. The tablesync should recover 7a. This time when the tablesync is relaunched there is no “already exists” error so it should be able to recover OK. 8. The tablesync worker should finish normally 9. The replicated data should be visible in the subscribed table 10. There should be no dangling slots (e.g. check for warnings during DROP SUBSCRIPTION) ================= ## ## 2. Insert a record at publisher ## [postgres@CentOS7-x64 ~]$ psql -d test_pub -c "INSERT INTO test_tab VALUES(1, 'foo');" INSERT 0 1 ## ## 3. Start Subscription and pause the tablesync after its slot is created but before the copy starts ## [postgres@CentOS7-x64 ~]$ psql -d test_sub -p 54321 -c "CREATE SUBSCRIPTION tap_sub CONNECTION 'host=localhost dbname=test_pub application_name=tap_sub' PUBLICATION tap_pub;" 2021-02-02 16:02:44.094 AEDT [24946] LOG: logical decoding found consistent point at 0/1653EB0 2021-02-02 16:02:44.094 AEDT [24946] DETAIL: There are no running transactions. 2021-02-02 16:02:44.094 AEDT [24946] STATEMENT: CREATE_REPLICATION_SLOT "tap_sub" LOGICAL pgoutput NOEXPORT_SNAPSHOT NOTICE: created replication slot "tap_sub" on publisher CREATE SUBSCRIPTION 2021-02-02 16:02:44.103 AEDT [24947] LOG: logical replication apply worker for subscription "tap_sub" has started 2021-02-02 16:02:44.103 AEDT [24947] LOG: !!>> The apply worker process has PID = 24947 [postgres@CentOS7-x64 ~]$ 2021-02-02 16:02:44.110 AEDT [24954] LOG: starting logical decoding for slot "tap_sub" 2021-02-02 16:02:44.110 AEDT [24954] DETAIL: Streaming transactions committing after 0/1653EE8, reading WAL from 0/1653EB0. 2021-02-02 16:02:44.110 AEDT [24954] STATEMENT: START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2', publication_names '"tap_pub"') 2021-02-02 16:02:44.110 AEDT [24954] LOG: logical decoding found consistent point at 0/1653EB0 2021-02-02 16:02:44.110 AEDT [24954] DETAIL: There are no running transactions. 2021-02-02 16:02:44.110 AEDT [24954] STATEMENT: START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2', publication_names '"tap_pub"') 2021-02-02 16:02:44.110 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:02:44.110 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:02:44.115 AEDT [24955] LOG: logical replication table synchronization worker for subscription "tap_sub", table "test_tab" has started 2021-02-02 16:02:44.115 AEDT [24955] LOG: !!>> The tablesync worker process has PID = 24955 2021-02-02 16:02:44.115 AEDT [24955] LOG: !!>> Sleeping 30 secs. For debugging, attach to process 24955 now! # sync worker is PID 24955 # apply worker is PID 24947 2021-02-02 16:02:44.122 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:02:44.122 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:02:45.137 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:02:45.137 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:02:46.139 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:02:46.139 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:02:47.140 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:02:47.140 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:02:48.143 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:02:48.143 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:02:49.151 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:02:49.151 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:02:50.151 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:02:50.151 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:02:51.168 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:02:51.168 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:02:52.170 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:02:52.171 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:02:53.177 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:02:53.177 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:02:54.179 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:02:54.179 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:02:55.180 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:02:55.180 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:02:56.187 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:02:56.187 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:02:57.191 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:02:57.191 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:02:58.194 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:02:58.194 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:02:59.196 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:02:59.196 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:00.198 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:00.198 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:01.201 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:01.201 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:02.229 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:02.229 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:03.232 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:03.232 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:04.236 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:04.236 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:05.238 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:05.238 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:06.239 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:06.239 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:07.243 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:07.244 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:08.290 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:08.290 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:09.294 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:09.294 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:10.295 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:10.295 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:11.307 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:11.307 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:12.309 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:12.309 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:13.311 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:13.312 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:14.121 AEDT [24955] LOG: !!>> tablesync worker: About to call LogicalRepSyncTableStart to do initial syncing 2021-02-02 16:03:14.314 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:14.314 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:14.314 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:14.314 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:15.314 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:15.314 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:16.315 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:16.315 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:17.316 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:17.316 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:18.323 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:18.323 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:19.325 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:19.325 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:20.362 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:20.362 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:21.364 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:21.365 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:22.367 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:22.367 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:23.370 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:23.370 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:24.382 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:24.382 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:25.383 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:25.383 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:26.390 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:26.390 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:27.391 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:27.391 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:28.392 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:28.392 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:29.394 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:29.394 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:30.398 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:30.398 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:31.400 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:31.400 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:32.402 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:32.403 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:33.405 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:33.405 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:34.407 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:34.407 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:35.407 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:35.407 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:36.409 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:36.409 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:37.411 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:37.411 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:38.412 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:38.412 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:39.413 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:39.413 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:40.414 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:40.414 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:41.418 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:41.418 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:42.421 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:42.421 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:43.422 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:43.422 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:44.425 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:44.425 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:44.426 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:44.426 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:45.427 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:45.428 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:46.428 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:46.428 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:47.429 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:47.429 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:48.431 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:48.431 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:49.432 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:49.433 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:49.603 AEDT [26921] LOG: logical decoding found consistent point at 0/1653EE8 2021-02-02 16:03:49.603 AEDT [26921] DETAIL: There are no running transactions. 2021-02-02 16:03:49.603 AEDT [26921] STATEMENT: CREATE_REPLICATION_SLOT "pg_16398_sync_16385" LOGICAL pgoutput USE_SNAPSHOT 2021-02-02 16:03:49.607 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:49.607 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:50.608 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:50.608 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:51.609 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:51.609 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:52.610 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:52.610 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:53.611 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:53.611 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:54.612 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:54.612 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:55.613 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:55.613 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:56.614 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:56.614 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:57.615 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:57.615 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:58.616 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:58.616 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:03:59.617 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:03:59.617 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:04:00.618 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:04:00.618 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:04:01.619 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:04:01.619 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:04:02.620 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:04:02.620 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:04:03.627 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:04:03.627 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:04:04.629 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:04:04.629 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:04:05.629 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:04:05.629 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:04:06.631 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:04:06.631 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:04:07.632 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:04:07.632 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:04:08.633 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:04:08.633 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables ## ## 4b Here is where I break the connection by stopping the Publisher's PG instance ## pg_ctl -D ./MYDATAOSS_2PC_PUB/ stop2021-02-02 16:04:09.634 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:04:09.634 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables waiting for server to shut down....2021-02-02 16:04:09.906 AEDT [25486] LOG: received fast shutdown request 2021-02-02 16:04:09.921 AEDT [25486] LOG: aborting any active transactions 2021-02-02 16:04:09.922 AEDT [25486] LOG: background worker "logical replication launcher" (PID 25493) exited with exit code 1 2021-02-02 16:04:09.922 AEDT [25488] LOG: shutting down 2021-02-02 16:04:09.922 AEDT [24947] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:04:09.922 AEDT [26921] FATAL: terminating connection due to administrator command ## ## 5a. Now the connection is broken. The apply worker fails because the broken connection..... ## 2021-02-02 16:04:09.923 AEDT [24947] LOG: data stream from publisher has ended 2021-02-02 16:04:09.923 AEDT [24947] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:04:09.923 AEDT [24947] ERROR: could not send end-of-streaming message to primary: server closed the connection unexpectedly This probably means the server terminated abnormally before or while processing the request. no COPY in progress 2021-02-02 16:04:09.923 AEDT [25536] LOG: background worker "logical replication worker" (PID 24947) exited with exit code 1 ## ## 5a. Apply worker cannot connect. It keeps attempting to re-launch again and again and again... ## 2021-02-02 16:04:09.927 AEDT [27457] LOG: logical replication apply worker for subscription "tap_sub" has started 2021-02-02 16:04:09.927 AEDT [27457] LOG: !!>> The apply worker process has PID = 27457 2021-02-02 16:04:09.928 AEDT [27458] FATAL: the database system is shutting down 2021-02-02 16:04:09.928 AEDT [27457] ERROR: could not connect to the publisher: connection to server at "localhost" (::1), port 5432 failed: FATAL: the database system is shutting down 2021-02-02 16:04:09.929 AEDT [25536] LOG: background worker "logical replication worker" (PID 27457) exited with exit code 1 2021-02-02 16:04:09.960 AEDT [25486] LOG: database system is shut down done server stopped [postgres@CentOS7-x64 ~]$ 2021-02-02 16:04:14.938 AEDT [27587] LOG: logical replication apply worker for subscription "tap_sub" has started 2021-02-02 16:04:14.938 AEDT [27587] LOG: !!>> The apply worker process has PID = 27587 2021-02-02 16:04:14.939 AEDT [27587] ERROR: could not connect to the publisher: connection to server at "localhost" (::1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? connection to server at "localhost" (127.0.0.1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? 2021-02-02 16:04:14.939 AEDT [25536] LOG: background worker "logical replication worker" (PID 27587) exited with exit code 1 2021-02-02 16:04:19.949 AEDT [27685] LOG: logical replication apply worker for subscription "tap_sub" has started 2021-02-02 16:04:19.949 AEDT [27685] LOG: !!>> The apply worker process has PID = 27685 2021-02-02 16:04:19.950 AEDT [27685] ERROR: could not connect to the publisher: connection to server at "localhost" (::1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? connection to server at "localhost" (127.0.0.1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? 2021-02-02 16:04:19.950 AEDT [25536] LOG: background worker "logical replication worker" (PID 27685) exited with exit code 1 2021-02-02 16:04:24.982 AEDT [27827] LOG: logical replication apply worker for subscription "tap_sub" has started 2021-02-02 16:04:24.982 AEDT [27827] LOG: !!>> The apply worker process has PID = 27827 2021-02-02 16:04:24.990 AEDT [27827] ERROR: could not connect to the publisher: connection to server at "localhost" (::1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? connection to server at "localhost" (127.0.0.1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? 2021-02-02 16:04:25.000 AEDT [25536] LOG: background worker "logical replication worker" (PID 27827) exited with exit code 1 2021-02-02 16:04:30.018 AEDT [27956] LOG: logical replication apply worker for subscription "tap_sub" has started 2021-02-02 16:04:30.018 AEDT [27956] LOG: !!>> The apply worker process has PID = 27956 2021-02-02 16:04:30.020 AEDT [27956] ERROR: could not connect to the publisher: connection to server at "localhost" (::1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? connection to server at "localhost" (127.0.0.1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? 2021-02-02 16:04:30.021 AEDT [25536] LOG: background worker "logical replication worker" (PID 27956) exited with exit code 1 2021-02-02 16:04:35.030 AEDT [28026] LOG: logical replication apply worker for subscription "tap_sub" has started 2021-02-02 16:04:35.031 AEDT [28026] LOG: !!>> The apply worker process has PID = 28026 2021-02-02 16:04:35.031 AEDT [28026] ERROR: could not connect to the publisher: connection to server at "localhost" (::1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? connection to server at "localhost" (127.0.0.1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? 2021-02-02 16:04:35.032 AEDT [25536] LOG: background worker "logical replication worker" (PID 28026) exited with exit code 1 2021-02-02 16:04:40.044 AEDT [28191] LOG: logical replication apply worker for subscription "tap_sub" has started 2021-02-02 16:04:40.044 AEDT [28191] LOG: !!>> The apply worker process has PID = 28191 2021-02-02 16:04:40.046 AEDT [28191] ERROR: could not connect to the publisher: connection to server at "localhost" (::1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? connection to server at "localhost" (127.0.0.1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? 2021-02-02 16:04:40.047 AEDT [25536] LOG: background worker "logical replication worker" (PID 28191) exited with exit code 1 2021-02-02 16:04:45.080 AEDT [28344] LOG: logical replication apply worker for subscription "tap_sub" has started 2021-02-02 16:04:45.080 AEDT [28344] LOG: !!>> The apply worker process has PID = 28344 2021-02-02 16:04:45.084 AEDT [28344] ERROR: could not connect to the publisher: connection to server at "localhost" (::1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? connection to server at "localhost" (127.0.0.1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? 2021-02-02 16:04:45.085 AEDT [25536] LOG: background worker "logical replication worker" (PID 28344) exited with exit code 1 2021-02-02 16:04:50.084 AEDT [24955] ERROR: table copy could not rollback transaction on publisher 2021-02-02 16:04:50.084 AEDT [24955] DETAIL: The error was: no connection to the server 2021-02-02 16:04:50.085 AEDT [25536] LOG: background worker "logical replication worker" (PID 24955) exited with exit code 1 2021-02-02 16:04:50.090 AEDT [28441] LOG: logical replication apply worker for subscription "tap_sub" has started 2021-02-02 16:04:50.090 AEDT [28441] LOG: !!>> The apply worker process has PID = 28441 2021-02-02 16:04:50.091 AEDT [28441] ERROR: could not connect to the publisher: connection to server at "localhost" (::1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? connection to server at "localhost" (127.0.0.1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? 2021-02-02 16:04:50.091 AEDT [25536] LOG: background worker "logical replication worker" (PID 28441) exited with exit code 1 2021-02-02 16:04:55.104 AEDT [28551] LOG: logical replication apply worker for subscription "tap_sub" has started 2021-02-02 16:04:55.104 AEDT [28551] LOG: !!>> The apply worker process has PID = 28551 2021-02-02 16:04:55.105 AEDT [28551] ERROR: could not connect to the publisher: connection to server at "localhost" (::1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? connection to server at "localhost" (127.0.0.1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? 2021-02-02 16:04:55.106 AEDT [25536] LOG: background worker "logical replication worker" (PID 28551) exited with exit code 1 2021-02-02 16:05:00.117 AEDT [28710] LOG: logical replication apply worker for subscription "tap_sub" has started 2021-02-02 16:05:00.117 AEDT [28710] LOG: !!>> The apply worker process has PID = 28710 2021-02-02 16:05:00.118 AEDT [28710] ERROR: could not connect to the publisher: connection to server at "localhost" (::1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? connection to server at "localhost" (127.0.0.1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? 2021-02-02 16:05:00.119 AEDT [25536] LOG: background worker "logical replication worker" (PID 28710) exited with exit code 1 2021-02-02 16:05:05.128 AEDT [28839] LOG: logical replication apply worker for subscription "tap_sub" has started 2021-02-02 16:05:05.129 AEDT [28839] LOG: !!>> The apply worker process has PID = 28839 2021-02-02 16:05:05.129 AEDT [28839] ERROR: could not connect to the publisher: connection to server at "localhost" (::1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? connection to server at "localhost" (127.0.0.1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? 2021-02-02 16:05:05.130 AEDT [25536] LOG: background worker "logical replication worker" (PID 28839) exited with exit code 1 ## ## 6. Now we re-establish the connection by starting the Publisher instance. ## pg_ctl -D ./MYDATAOSS_2PC_PUB/ start2021-02-02 16:05:10.140 AEDT [28978] LOG: logical replication apply worker for subscription "tap_sub" has started 2021-02-02 16:05:10.140 AEDT [28978] LOG: !!>> The apply worker process has PID = 28978 2021-02-02 16:05:10.141 AEDT [28978] ERROR: could not connect to the publisher: connection to server at "localhost" (::1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? connection to server at "localhost" (127.0.0.1), port 5432 failed: Connection refused Is the server running on that host and accepting TCP/IP connections? 2021-02-02 16:05:10.141 AEDT [25536] LOG: background worker "logical replication worker" (PID 28978) exited with exit code 1 waiting for server to start....2021-02-02 16:05:11.229 AEDT [29017] LOG: starting PostgreSQL 14devel on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-36), 64-bit 2021-02-02 16:05:11.230 AEDT [29017] LOG: listening on IPv6 address "::1", port 5432 2021-02-02 16:05:11.230 AEDT [29017] LOG: listening on IPv4 address "127.0.0.1", port 5432 2021-02-02 16:05:11.234 AEDT [29017] LOG: listening on Unix socket "/tmp/.s.PGSQL.5432" 2021-02-02 16:05:11.240 AEDT [29018] LOG: database system was shut down at 2021-02-02 16:04:09 AEDT 2021-02-02 16:05:11.245 AEDT [29017] LOG: database system is ready to accept connections done server started [postgres@CentOS7-x64 ~]$ 2021-02-02 16:05:15.152 AEDT [29111] LOG: logical replication apply worker for subscription "tap_sub" has started ## ## Now the apply worker can start OK ## 2021-02-02 16:05:15.152 AEDT [29111] LOG: !!>> The apply worker process has PID = 29111 2021-02-02 16:05:15.177 AEDT [29112] LOG: starting logical decoding for slot "tap_sub" 2021-02-02 16:05:15.177 AEDT [29112] DETAIL: Streaming transactions committing after 0/1653EE8, reading WAL from 0/1653EE8. 2021-02-02 16:05:15.177 AEDT [29112] STATEMENT: START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2', publication_names '"tap_pub"') 2021-02-02 16:05:15.177 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:15.177 AEDT [29112] LOG: logical decoding found consistent point at 0/1653EE8 2021-02-02 16:05:15.177 AEDT [29112] DETAIL: There are no running transactions. 2021-02-02 16:05:15.177 AEDT [29112] STATEMENT: START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2', publication_names '"tap_pub"') 2021-02-02 16:05:15.177 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables ## ## 7a. Now the tablesync worker is re-launched ## 2021-02-02 16:05:15.182 AEDT [29113] LOG: logical replication table synchronization worker for subscription "tap_sub", table "test_tab" has started 2021-02-02 16:05:15.182 AEDT [29113] LOG: !!>> The tablesync worker process has PID = 29113 2021-02-02 16:05:15.182 AEDT [29113] LOG: !!>> Sleeping 30 secs. For debugging, attach to process 29113 now! ## Apply worker PID = 29111 ## Sync worker PID = 29113 2021-02-02 16:05:15.188 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:15.188 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:16.194 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:16.194 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:17.199 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:17.199 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:18.211 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:18.211 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:19.212 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:19.212 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:20.214 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:20.215 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:21.217 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:21.217 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:22.241 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:22.241 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:23.278 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:23.278 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:24.309 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:24.309 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:25.312 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:25.312 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:26.317 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:26.317 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:26.435 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:26.435 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:27.437 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:27.437 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:28.443 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:28.443 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:29.444 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:29.444 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:30.445 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:30.445 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:31.447 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:31.447 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:32.449 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:32.449 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:33.450 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:33.450 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:34.452 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:34.452 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:35.452 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:35.452 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:36.454 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:36.454 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:37.456 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:37.456 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:38.457 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:38.457 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:39.459 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:39.459 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:40.461 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:40.461 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:41.461 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:41.462 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:42.465 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:42.465 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:43.466 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:43.466 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:44.468 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:44.468 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:45.185 AEDT [29113] LOG: !!>> tablesync worker: About to call LogicalRepSyncTableStart to do initial syncing 2021-02-02 16:05:45.469 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:45.469 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:46.470 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:46.470 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:47.472 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:47.472 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:48.474 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:48.474 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:49.475 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:49.475 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:50.476 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:50.476 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:51.477 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:51.477 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:52.484 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:52.484 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:53.485 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:53.485 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:54.409 AEDT [30185] ERROR: replication slot "pg_16398_sync_16385" already exists 2021-02-02 16:05:54.409 AEDT [30185] STATEMENT: CREATE_REPLICATION_SLOT "pg_16398_sync_16385" LOGICAL pgoutput USE_SNAPSHOT 2021-02-02 16:05:54.486 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:54.486 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:55.488 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:55.488 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:56.489 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:56.489 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:56.490 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:56.490 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:57.490 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:57.490 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:58.491 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:58.491 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:05:59.492 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:05:59.492 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:00.493 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:00.493 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:01.494 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:01.494 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:02.495 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:02.495 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:03.496 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:03.496 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:04.497 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:04.497 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:05.498 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:05.498 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:06.500 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:06.500 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:07.501 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:07.501 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:08.503 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:08.503 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:09.504 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:09.504 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:10.505 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:10.505 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:11.506 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:11.506 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:12.515 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:12.515 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:13.515 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:13.515 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:14.516 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:14.516 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:15.520 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:15.520 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables ## ## 6a. The tablesync (PID 29113) get expected error when it tried to create the slot with ## same name which already exists. ## 2021-02-02 16:06:15.797 AEDT [29113] ERROR: could not create replication slot "pg_16398_sync_16385": ERROR: replication slot "pg_16398_sync_16385" already exists 2021-02-02 16:06:15.798 AEDT [25536] LOG: background worker "logical replication worker" (PID 29113) exited with exit code 1 ## ## 6a This is where the PG_CATCH code was executed which did a DROP SLOT ## 2021-02-02 16:06:15.798 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:15.798 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables ## ## 7a. And tablesyn is relaunched again ## ## apply worker PID = 29111 ## sync worker PID = 30732 ## 2021-02-02 16:06:15.803 AEDT [30732] LOG: logical replication table synchronization worker for subscription "tap_sub", table "test_tab" has started 2021-02-02 16:06:15.803 AEDT [30732] LOG: !!>> The tablesync worker process has PID = 30732 2021-02-02 16:06:15.803 AEDT [30732] LOG: !!>> Sleeping 30 secs. For debugging, attach to process 30732 now! 2021-02-02 16:06:16.842 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:16.842 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:17.844 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:17.844 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:18.847 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:18.847 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:19.848 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:19.848 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:20.876 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:20.876 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:21.881 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:21.881 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:22.883 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:22.883 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:23.884 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:23.884 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:24.916 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:24.916 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:25.959 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:25.959 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:26.962 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:26.962 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:26.962 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:26.962 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:27.967 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:27.967 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:28.969 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:28.969 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:29.971 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:29.971 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:30.979 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:30.979 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:31.981 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:31.981 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:32.982 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:32.982 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:33.986 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:33.986 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:34.988 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:34.988 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:35.991 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:35.991 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:36.996 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:36.996 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:37.997 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:37.997 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:38.998 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:38.998 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:40.006 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:40.006 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:41.007 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:41.007 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:42.009 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:42.009 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:43.031 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:43.031 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:44.033 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:44.033 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:45.035 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:45.035 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:45.806 AEDT [30732] LOG: !!>> tablesync worker: About to call LogicalRepSyncTableStart to do initial syncing 2021-02-02 16:06:46.037 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:46.037 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:47.039 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:47.039 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:48.046 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:48.047 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:49.048 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:49.048 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:50.048 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:50.048 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:51.069 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:51.069 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:51.178 AEDT [31727] LOG: logical decoding found consistent point at 0/1653FD0 2021-02-02 16:06:51.178 AEDT [31727] DETAIL: There are no running transactions. 2021-02-02 16:06:51.178 AEDT [31727] STATEMENT: CREATE_REPLICATION_SLOT "pg_16398_sync_16385" LOGICAL pgoutput USE_SNAPSHOT 2021-02-02 16:06:51.182 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:51.182 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:52.184 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:52.184 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:53.185 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:53.186 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:54.190 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:54.190 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:55.194 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:55.194 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:56.196 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:56.196 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:57.199 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:57.199 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:58.200 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:58.200 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:06:59.204 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:59.204 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables ## ## 7a. This time there are no more tablesync errors ## 2021-02-02 16:06:59.299 AEDT [30732] LOG: !!>> tablesync worker: wait for CATCHUP state notification 2021-02-02 16:06:59.299 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:06:59.300 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:03.477 AEDT [30732] LOG: !!>> tablesync worker: received CATCHUP state notification 2021-02-02 16:07:03.477 AEDT [30732] LOG: !!>> tablesync worker: Returned from LogicalRepSyncTableStart 2021-02-02 16:07:03.478 AEDT [31727] LOG: starting logical decoding for slot "pg_16398_sync_16385" 2021-02-02 16:07:03.478 AEDT [31727] DETAIL: Streaming transactions committing after 0/1654020, reading WAL from 0/1653FD0. 2021-02-02 16:07:03.478 AEDT [31727] STATEMENT: START_REPLICATION SLOT "pg_16398_sync_16385" LOGICAL 0/1654020 (proto_version '2', publication_names '"tap_pub"') 2021-02-02 16:07:03.478 AEDT [31727] LOG: logical decoding found consistent point at 0/1653FD0 2021-02-02 16:07:03.478 AEDT [31727] DETAIL: There are no running transactions. 2021-02-02 16:07:03.478 AEDT [31727] STATEMENT: START_REPLICATION SLOT "pg_16398_sync_16385" LOGICAL 0/1654020 (proto_version '2', publication_names '"tap_pub"') 2021-02-02 16:07:04.976 AEDT [30732] LOG: !!>> tablesync worker: LogicalRepApplyLoop 2021-02-02 16:07:04.976 AEDT [30732] LOG: !!>> tablesync worker: called process_syncing_tables 2021-02-02 16:07:13.253 AEDT [30732] LOG: logical replication table synchronization worker for subscription "tap_sub", table "test_tab" has finished ## ## 8. The sync worker was able to finish normally. ## 2021-02-02 16:07:13.255 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:13.255 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:14.256 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:14.256 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:15.260 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:15.260 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:16.261 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:16.261 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:17.265 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:17.265 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:18.271 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:18.271 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:19.301 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:19.301 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:20.312 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:20.312 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:21.330 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:21.330 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:21.332 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:21.332 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:22.337 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:22.338 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:23.339 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:23.339 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:24.352 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:24.352 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:25.354 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:25.354 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:26.363 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:26.363 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:27.365 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:27.365 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:28.375 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:28.375 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:29.378 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:29.378 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:30.397 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:30.397 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:31.398 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:31.398 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 16:07:32.399 AEDT [29111] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 16:07:32.399 AEDT [29111] LOG: !!>> apply worker: called process_syncing_tables ## ## 10. Drop Subscription ## psql -d test_sub -p 54321 -c "DROP SUBSCRIPTION tap_sub;" 2021-02-02 16:07:33.286 AEDT [29111] FATAL: terminating logical replication worker due to administrator command 2021-02-02 16:07:33.286 AEDT [25536] LOG: background worker "logical replication worker" (PID 29111) exited with exit code 1 NOTICE: dropped replication slot "tap_sub" on publisher DROP SUBSCRIPTION ## ## There are no dangling slots ## [postgres@CentOS7-x64 ~]$ psql -d test_pub -c "select * from pg_replication_slots;" slot_name | plugin | slot_type | datoid | database | temporary | active | active_pid | xmin | catalog_xmin | restart_lsn | confirmed_flush_ lsn | wal_status | safe_wal_size -----------+--------+-----------+--------+----------+-----------+--------+------------+------+--------------+-------------+----------------- ----+------------+--------------- (0 rows) ## ## The initial row of data was replicated correctly. ## [postgres@CentOS7-x64 ~]$ psql -d test_sub -p 54321 -c "SELECT * FROM test_tab;" a | b | c | d ---+-----+-------------------------------+----- 1 | foo | 2021-02-02 15:11:58.121875+11 | 999 (1 row) [postgres@CentOS7-x64 ~]$