After seeing Ajin's test [ac0202] which did a DROP TABLE, I have also
tried a simple test where I do a DROP TABLE with very bad timing for
the tablesync worker. It seems that doing this can cause the sync
worker's MyLogicalRepWorker->relid to become invalid.
In my test this caused a stack trace within some logging, but I
imagine other bad things can happen if the tablesync worker can be
executed with an invalid relid.
Possibly this is an existing PG bug which has just never been seen
before; The ereport which has failed here is not new code.
PSA the log for the test steps and the stack trace details.
----
[ac0202]
https://www.postgresql.org/message-id/CAFPTHDYzjaNfzsFHpER9idAPB8v5j%3DSUbWL0AKj5iVy0BKbTpg%40mail.gmail.com
Kind Regards,
Peter Smith.
Fujitsu Australia
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' <repeats 116 times>..., 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' <repeats 116 times>..., 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 <signal handler called>
#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
