Test Scenario 1. INSERT data so tablesync should copy something 2. While paused in LogicalRepSyncTableStart do a DROP TABLE to rip the rug out from under the sync worker! 3. Continue the sync worker.... see what happens ============== ## ## Insert data ## [postgres@CentOS7-x64 ~]$ psql -d test_pub -c "INSERT INTO test_tab VALUES(1, 'foo');" INSERT 0 1 ## ## SUBSCRIBE and continue to breakpoint at top of tablesync function LogicalRepSyncTableStart ## [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 19:29:16.578 AEDT [26402] LOG: logical decoding found consistent point at 0/165F800 2021-02-02 19:29:16.578 AEDT [26402] DETAIL: There are no running transactions. 2021-02-02 19:29:16.578 AEDT [26402] STATEMENT: CREATE_REPLICATION_SLOT "tap_sub" LOGICAL pgoutput NOEXPORT_SNAPSHOT NOTICE: created replication slot "tap_sub" on publisher CREATE SUBSCRIPTION 2021-02-02 19:29:16.587 AEDT [26405] LOG: logical replication apply worker for subscription "tap_sub" has started 2021-02-02 19:29:16.587 AEDT [26405] LOG: !!>> The apply worker process has PID = 26405 2021-02-02 19:29:16.597 AEDT [26411] LOG: starting logical decoding for slot "tap_sub" 2021-02-02 19:29:16.597 AEDT [26411] DETAIL: Streaming transactions committing after 0/165F838, reading WAL from 0/165F800. 2021-02-02 19:29:16.597 AEDT [26411] STATEMENT: START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2', publication_names '"tap_pub"') 2021-02-02 19:29:16.598 AEDT [26411] LOG: logical decoding found consistent point at 0/165F800 2021-02-02 19:29:16.598 AEDT [26411] DETAIL: There are no running transactions. 2021-02-02 19:29:16.598 AEDT [26411] STATEMENT: START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2', publication_names '"tap_pub"') 2021-02-02 19:29:16.598 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:16.598 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables [postgres@CentOS7-x64 ~]$ 2021-02-02 19:29:16.602 AEDT [26415] LOG: logical replication table synchronization worker for subscription "tap_sub", table "test_tab" has started 2021-02-02 19:29:16.602 AEDT [26415] LOG: !!>> The tablesync worker process has PID = 26415 2021-02-02 19:29:16.602 AEDT [26415] LOG: !!>> Sleeping 30 secs. For debugging, attach to process 26415 now! 2021-02-02 19:29:17.610 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:17.610 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:18.611 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:18.611 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:19.612 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:19.612 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:20.613 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:20.613 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:21.614 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:21.614 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:22.615 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:22.615 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:23.615 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:23.615 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:24.658 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:24.658 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:25.661 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:25.661 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:26.662 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:26.662 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:27.664 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:27.664 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:28.664 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:28.664 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:29.666 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:29.666 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:30.667 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:30.667 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:31.668 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:31.668 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:32.669 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:32.669 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:33.670 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:33.670 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:34.676 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:34.676 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:35.679 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:35.679 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:36.680 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:36.680 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:37.681 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:37.681 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:38.682 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:38.682 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:39.692 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:39.692 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:40.695 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:40.695 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:41.703 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:41.703 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:42.708 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:42.708 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:43.713 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:43.713 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:44.714 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:44.714 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:45.732 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:45.732 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:46.603 AEDT [26415] LOG: !!>> tablesync worker: About to call LogicalRepSyncTableStart to do initial syncing 2021-02-02 19:29:46.734 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:46.734 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:46.734 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:46.734 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:47.737 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:47.737 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:48.740 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:48.740 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:49.742 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:49.742 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:50.744 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:50.744 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:51.745 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:51.745 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:52.747 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:52.747 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:53.748 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:53.748 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:54.750 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:54.750 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:55.753 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:55.753 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:56.756 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:56.756 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:57.757 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:57.758 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:58.759 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:58.759 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:29:59.765 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:29:59.765 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:00.766 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:00.766 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:01.767 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:01.767 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:02.768 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:02.768 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:03.771 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:03.771 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:04.775 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:04.775 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:05.797 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:05.797 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:06.808 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:06.808 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:07.809 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:07.809 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:08.811 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:08.811 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:09.812 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:09.812 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:10.814 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:10.814 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:11.815 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:11.815 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:12.817 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:12.817 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:13.819 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:13.819 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:15.120 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:15.120 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:16.131 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:16.131 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:17.137 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:17.137 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:17.137 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:17.137 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:18.139 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:18.139 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:19.152 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:19.152 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:20.155 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:20.155 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:21.157 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:21.157 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:22.159 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:22.159 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:23.161 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:23.161 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:24.169 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:24.169 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:25.171 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:25.171 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:26.176 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:26.176 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:27.177 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:27.178 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:28.179 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:28.179 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:29.183 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:29.183 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:30.221 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:30.222 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:31.224 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:31.224 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:32.225 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:32.225 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:33.227 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:33.227 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:34.235 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:34.235 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:35.236 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:35.237 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:36.239 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:36.239 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:37.242 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:37.242 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:38.245 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:38.245 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:39.249 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:39.249 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:40.250 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:40.250 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:41.252 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:41.258 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:42.260 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:42.260 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:43.263 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:43.263 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:44.264 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:44.264 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:45.267 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:45.267 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:46.268 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:46.268 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:47.269 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:47.269 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:47.270 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:47.270 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:48.271 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:48.271 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:49.273 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:49.273 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables ## ## While paused in debugger do DROP TABLE on subscriber. ## Note we have not done any ALTER SUBSCRIPTION. ## psql -d test_sub -p 54321 -c "DROP TABLE test_tab;" DROP TABLE ## ## And let the tablesync function continue... ## ## A debugging stacktrace occurs ## [postgres@CentOS7-x64 ~]$ 2021-02-02 19:30:50.274 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:50.274 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:51.277 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:51.277 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:52.278 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:52.278 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:53.283 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:53.283 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:54.286 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:54.286 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:55.289 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:55.289 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:56.291 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:56.291 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables # Here it the first sign something is bad... 2021-02-02 19:30:56.350 AEDT [26415] WARNING: relcache reference leak: relation "pg_subscription_rel" not closed 2021-02-02 19:30:57.295 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:57.295 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:58.303 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:58.303 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:30:59.305 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:30:59.305 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables # Then the stacktrace TRAP: FailedAssertion("strvalue != NULL", File: "snprintf.c", Line: 442, PID: 26415) postgres: logical replication worker for subscription 24616 sync 24603 (ExceptionalCondition+0xb9)[0xad97cd] postgres: logical replication worker for subscription 24616 sync 24603 [0xb4cf70] postgres: logical replication worker for subscription 24616 sync 24603 (pg_vsnprintf+0x7c)[0xb4c8f4] postgres: logical replication worker for subscription 24616 sync 24603 (pvsnprintf+0x30)[0xb3faf1] postgres: logical replication worker for subscription 24616 sync 24603 (appendStringInfoVA+0x80)[0xb41538] postgres: logical replication worker for subscription 24616 sync 24603 (errmsg+0x183)[0xada5b5] postgres: logical replication worker for subscription 24616 sync 24603 [0x8c57bc] postgres: logical replication worker for subscription 24616 sync 24603 (LogicalRepSyncTableStart+0xba)[0x8c6d52] postgres: logical replication worker for subscription 24616 sync 24603 (ApplyWorkerMain+0x42d)[0x8cc9ae] postgres: logical replication worker for subscription 24616 sync 24603 (StartBackgroundWorker+0x21f)[0x87efe3] postgres: logical replication worker for subscription 24616 sync 24603 [0x893653] postgres: logical replication worker for subscription 24616 sync 24603 [0x893a01] postgres: logical replication worker for subscription 24616 sync 24603 [0x892a3c] /lib64/libpthread.so.0(+0xf5d0)[0x7fec4988d5d0] /lib64/libc.so.6(__select+0x13)[0x7fec48e980d3] postgres: logical replication worker for subscription 24616 sync 24603 [0x88e6ba] postgres: logical replication worker for subscription 24616 sync 24603 (PostmasterMain+0x114f)[0x88e0a9] postgres: logical replication worker for subscription 24616 sync 24603 [0x791843] /lib64/libc.so.6(__libc_start_main+0xf5)[0x7fec48dc5495] postgres: logical replication worker for subscription 24616 sync 24603 [0x480e69] 2021-02-02 19:31:00.306 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop ## ## gdb backtrace for this sync process shows more details: ## Program received signal SIGABRT, Aborted. 0x00007fec48dd92c7 in raise () from /lib64/libc.so.6 (gdb) bt #0 0x00007fec48dd92c7 in raise () from /lib64/libc.so.6 #1 0x00007fec48dda9b8 in abort () from /lib64/libc.so.6 #2 0x0000000000ad97fa in ExceptionalCondition (conditionName=0xd58a0b "strvalue != NULL", errorType=0xd589fb "FailedAssertion", fileName=0xd589f0 "snprintf.c", lineNumber=442) at assert.c:69 #3 0x0000000000b4cf70 in dopr (target=0x7ffda4e5fd80, format=0xc8fc49 "\" has finished", args=0x7ffda4e5fe58) at snprintf.c:442 #4 0x0000000000b4c8f4 in pg_vsnprintf ( str=0x26a7690 "logical replication table synchronization worker for subscription \"tap_sub\", table \"", '\177' ..., count=1024, fmt=0xc8fbf8 "logical replication table synchronization worker for subscription \"%s\", table \"%s\" has finished", args=0x7ffda4e5fe58) at snprintf.c:195 #5 0x0000000000b3faf1 in pvsnprintf ( buf=0x26a7690 "logical replication table synchronization worker for subscription \"tap_sub\", table \"", '\177' ..., len=1024, fmt=0xc8fbf8 "logical replication table synchronization worker for subscription \"%s\", table \"%s\" has finished", args=0x7ffda4e5fe58) at psprintf.c:110 #6 0x0000000000b41538 in appendStringInfoVA (str=0x7ffda4e5fe70, fmt=0xc8fbf8 "logical replication table synchronization worker for subscription \"%s\", table \"%s\" has finished", args=0x7ffda4e5fe58) at stringinfo.c:149 #7 0x0000000000ada5b5 in errmsg ( fmt=0xc8fbf8 "logical replication table synchronization worker for subscription \"%s\", table \"%s\" has finished") at elog.c:925 #8 0x00000000008c57bc in finish_sync_worker () at tablesync.c:182 #9 0x00000000008c6d52 in LogicalRepSyncTableStart (origin_startpos=0x7ffda4e60148) at tablesync.c:973 #10 0x00000000008cc9ae in ApplyWorkerMain (main_arg=1) at worker.c:3055 #11 0x000000000087efe3 in StartBackgroundWorker () at bgworker.c:879 #12 0x0000000000893653 in do_start_bgworker (rw=0x26ccdc0) at postmaster.c:5833 #13 0x0000000000893a01 in maybe_start_bgworkers () at postmaster.c:6058 #14 0x0000000000892a3c in sigusr1_handler (postgres_signal_arg=10) at postmaster.c:5215 #15 #16 0x00007fec48e980d3 in __select_nocancel () from /lib64/libc.so.6 ## ## This code in finish_sync_worker is not new code. So I think in this test we have exposed an existing bug ## where the relid known to the MyLogicalRepWorker has become no longer valid after the DROP TABLE pulled ## the rug from under the sync worker. ## ================ ereport(LOG, (errmsg("logical replication table synchronization worker for subscription \"%s\", table \"%s\" has finished", MySubscription->name, get_rel_name(MyLogicalRepWorker->relid)))); ================ ## ## ... the rest does not matter much .... ## 2021-02-02 19:31:00.306 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:31:01.307 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:31:01.307 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:31:02.313 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:31:02.313 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:31:03.316 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:31:03.316 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:31:04.318 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:31:04.318 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:31:05.319 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:31:05.319 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:31:06.321 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:31:06.322 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:31:07.322 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:31:07.322 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:31:08.324 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:31:08.324 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:31:09.326 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:31:09.326 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:31:10.328 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:31:10.328 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:31:11.331 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:31:11.331 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:31:12.332 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:31:12.332 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:31:13.336 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:31:13.336 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables psql -d test_sub -p 54321 -c "DROP SUBSCRIPTION tap_sub;"2021-02-02 19:31:14.337 AEDT [26405] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-02-02 19:31:14.337 AEDT [26405] LOG: !!>> apply worker: called process_syncing_tables 2021-02-02 19:31:15.106 AEDT [26405] FATAL: terminating logical replication worker due to administrator command 2021-02-02 19:31:15.107 AEDT [22118] LOG: background worker "logical replication worker" (PID 26405) exited with exit code 1