TEST SCENARIO Purpose: See if using ALTER PUBLICATION/SUBSCRIPTION might expose a gap in the tablesync slot cleanups Note: The "!!>>" is extra logging added for testing, not a normal part of PG. Steps: 1. CREATE PUBLICATION for some table T1 2. CREATE SUBSCRIPTION for that publication 3. Pause the tablesync worker in CATCHUP mode (eg after created slot but before dropped that tablesyn slot) 4. Show the slots 5. ALTER PUBLICATION to DROP TABLE T1 6. ALTER SUBSCRIPTION REFRESH PUBLICATION // will discover table T1 is no longer subscribed to. 7. Show the slots 8. DROP SUBSCRIPTION // since subscription no longer knows about T1 this would not drop the tablesync slot. So if step 6 does no T1 slots cleanup maybe nobody will 9. Show the slots // see if the T1 tablesync slot is still present or not ================== ## ## Normal PUBLICATION of a table ## [postgres@CentOS7-x64 ~]$ psql -d test_pub -c "CREATE PUBLICATION tap_pub FOR TABLE test_tab;" CREATE PUBLICATION ## ## Create subscription, and pause the tablesync in the debugger when it gets to CATCHUP state ## [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-01-08 11:36:38.418 AEDT [22468] LOG: logical decoding found consistent point at 0/1639360 2021-01-08 11:36:38.418 AEDT [22468] DETAIL: There are no running transactions. 2021-01-08 11:36:38.418 AEDT [22468] STATEMENT: CREATE_REPLICATION_SLOT "tap_sub" LOGICAL pgoutput NOEXPORT_SNAPSHOT NOTICE: created replication slot "tap_sub" on publisher CREATE SUBSCRIPTION 2021-01-08 11:36:38.428 AEDT [22469] LOG: logical replication apply worker for subscription "tap_sub" has started 2021-01-08 11:36:38.428 AEDT [22469] LOG: !!>> The apply worker process has PID = 22469 [postgres@CentOS7-x64 ~]$ 2021-01-08 11:36:38.445 AEDT [22474] LOG: starting logical decoding for slot "tap_sub" 2021-01-08 11:36:38.445 AEDT [22474] DETAIL: Streaming transactions committing after 0/1639398, reading WAL from 0/1639360. 2021-01-08 11:36:38.445 AEDT [22474] STATEMENT: START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2', publication_names '"tap_pub"') 2021-01-08 11:36:38.445 AEDT [22474] LOG: logical decoding found consistent point at 0/1639360 2021-01-08 11:36:38.445 AEDT [22474] DETAIL: There are no running transactions. 2021-01-08 11:36:38.445 AEDT [22474] STATEMENT: START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2', publication_names '"tap_pub"') 2021-01-08 11:36:38.446 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:38.446 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:38.453 AEDT [22477] LOG: logical replication table synchronization worker for subscription "tap_sub", table "test_tab" has started 2021-01-08 11:36:38.453 AEDT [22477] LOG: !!>> The tablesync worker process has PID = 22477 2021-01-08 11:36:38.453 AEDT [22477] LOG: !!>> Sleeping 30 secs. For debugging, attach to process 22477 now! 2021-01-08 11:36:39.458 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:39.458 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:40.461 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:40.461 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:41.464 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:41.464 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:42.467 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:42.467 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:43.469 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:43.469 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:44.475 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:44.475 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:45.476 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:45.476 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:46.479 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:46.479 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:47.480 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:47.480 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:48.482 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:48.482 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:49.484 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:49.484 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:50.486 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:50.486 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:51.488 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:51.488 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:52.491 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:52.491 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:53.492 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:53.492 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:54.494 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:54.494 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:55.496 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:55.496 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:56.498 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:56.498 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:57.500 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:57.500 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:58.505 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:58.505 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:36:59.506 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:36:59.506 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:00.508 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:00.508 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:01.516 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:01.516 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:02.524 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:02.524 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:03.527 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:03.527 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:04.536 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:04.536 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:05.539 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:05.539 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:06.541 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:06.541 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:07.544 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:07.544 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:08.453 AEDT [22477] LOG: !!>> tablesync worker: About to call LogicalRepSyncTableStart to do initial syncing 2021-01-08 11:37:08.545 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:08.545 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:08.546 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:08.546 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:09.547 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:09.547 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:10.550 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:10.550 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:11.556 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:11.556 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:12.558 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:12.558 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:13.559 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:13.559 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:14.559 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:14.559 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:15.562 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:15.562 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:16.562 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:16.562 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:17.572 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:17.572 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:18.573 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:18.573 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:19.582 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:19.582 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:20.590 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:20.590 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:21.595 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:21.595 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:22.597 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:22.597 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:23.603 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:23.604 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:24.606 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:24.606 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:25.200 AEDT [22477] LOG: !!>> LogicalRepSyncTableStart: walrcv_create_slot for "pg_24610_sync_16385". 2021-01-08 11:37:25.221 AEDT [23797] LOG: logical decoding found consistent point at 0/1639398 2021-01-08 11:37:25.221 AEDT [23797] DETAIL: There are no running transactions. 2021-01-08 11:37:25.221 AEDT [23797] STATEMENT: CREATE_REPLICATION_SLOT "pg_24610_sync_16385" LOGICAL pgoutput USE_SNAPSHOT 2021-01-08 11:37:25.226 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:25.227 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:37:25.247 AEDT [22477] LOG: !!>> LogicalRepSyncTableStart: 1 replorigin_create "pg_24610_16385". 2021-01-08 11:37:25.248 AEDT [22477] LOG: !!>> LogicalRepSyncTableStart: 1 replorigin_session_setup "pg_24610_16385". 2021-01-08 11:37:25.248 AEDT [22477] LOG: !!>> LogicalRepSyncTableStart: 1 replorigin_advance "pg_24610_16385". 2021-01-08 11:37:25.248 AEDT [22477] LOG: !!>> LogicalRepSyncTableStart: 'pg_24610_16385' origin_startpos lsn 0/16393D0 2021-01-08 11:37:25.248 AEDT [22477] LOG: !!>> tablesync worker: wait for CATCHUP state notification 2021-01-08 11:37:25.248 AEDT [22469] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:37:25.248 AEDT [22469] LOG: !!>> apply worker: called process_syncing_tables ## ## Show the tablesync slot exists ## [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_x min | restart_lsn | confirmed_flush_lsn | wal_status | safe_wal_size ---------------------+----------+-----------+--------+----------+-----------+--------+------------+------+---------- ----+-------------+---------------------+------------+--------------- tap_sub | pgoutput | logical | 16384 | test_pub | f | t | 22474 | | 530 | 0/16393D0 | 0/16393D0 | reserved | pg_24610_sync_16385 | pgoutput | logical | 16384 | test_pub | f | f | | | 530 | 0/1639398 | 0/16393D0 | reserved | (2 rows) ## ## ALTER PUBLICATION to drop the table previously published ## [postgres@CentOS7-x64 ~]$ psql -d test_pub -c "ALTER PUBLICATION tap_pub DROP TABLE test_tab;" ALTER PUBLICATION 2021-01-08 11:49:46.939 AEDT [22474] LOG: !!>> pgoutput_begin_txn 2021-01-08 11:49:46.939 AEDT [22474] CONTEXT: slot "tap_sub", output plugin "pgoutput", in the begin callback, associated LSN 0/16394B8 2021-01-08 11:49:46.939 AEDT [22474] STATEMENT: START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2', publication_names '"tap_pub"') 2021-01-08 11:49:46.939 AEDT [22474] LOG: !!>> pgoutput_commit_txn 2021-01-08 11:49:46.939 AEDT [22474] CONTEXT: slot "tap_sub", output plugin "pgoutput", in the commit callback, associated LSN 0/163ACA0 2021-01-08 11:49:46.939 AEDT [22474] STATEMENT: START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2', publication_names '"tap_pub"') [postgres@CentOS7-x64 ~]$ ## ## ALTER SUBSCRIPTION to REFRESH the publication ## This blocks on some latch until the tablesync worker dies, then it continues ## [postgres@CentOS7-x64 ~]$ psql -d test_sub -p 54321 -c "ALTER SUBSCRIPTION tap_sub REFRESH PUBLICATION;" 2021-01-08 11:57:07.801 AEDT [3218] LOG: background worker "logical replication worker" (PID 22477) was terminated by signal 5: Trace/breakpoint trap 2021-01-08 11:57:07.801 AEDT [3218] LOG: terminating any other active server processes WARNING: terminating connection because of crash of another server process DETAIL: The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory. HINT: In a moment you should be able to reconnect to the database and repeat your command. server closed the connection unexpectedly This probably means the server terminated abnormally before or while processing the request. connection to server was lost 2021-01-08 11:57:07.804 AEDT [3218] LOG: all server processes terminated; reinitializing 2021-01-08 11:57:07.804 AEDT [22474] LOG: could not receive data from client: Connection reset by peer 2021-01-08 11:57:07.804 AEDT [22474] STATEMENT: START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2', publication_names '"tap_pub"') 2021-01-08 11:57:07.804 AEDT [22474] LOG: unexpected EOF on standby connection 2021-01-08 11:57:07.804 AEDT [22474] STATEMENT: START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2', publication_names '"tap_pub"') [postgres@CentOS7-x64 ~]$ 2021-01-08 11:57:07.847 AEDT [24741] LOG: database system was interrupted; last known up at 2021-01-08 11:39:54 AEDT 2021-01-08 11:57:08.581 AEDT [24741] LOG: recovered replication state of node 1 to 0/0 2021-01-08 11:57:08.582 AEDT [24741] LOG: recovered replication state of node 2 to 0/16393D0 2021-01-08 11:57:08.582 AEDT [24741] LOG: database system was not properly shut down; automatic recovery in progress 2021-01-08 11:57:08.585 AEDT [24741] LOG: redo starts at 0/162F948 2021-01-08 11:57:08.585 AEDT [24741] LOG: invalid record length at 0/16300F8: wanted 24, got 0 2021-01-08 11:57:08.585 AEDT [24741] LOG: redo done at 0/16300C0 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s 2021-01-08 11:57:08.606 AEDT [3218] LOG: database system is ready to accept connections 2021-01-08 11:57:08.635 AEDT [24765] LOG: logical replication apply worker for subscription "tap_sub" has started 2021-01-08 11:57:08.635 AEDT [24765] LOG: !!>> The apply worker process has PID = 24765 2021-01-08 11:57:08.644 AEDT [24766] LOG: starting logical decoding for slot "tap_sub" 2021-01-08 11:57:08.644 AEDT [24766] DETAIL: Streaming transactions committing after 0/16393D0, reading WAL from 0/16393D0. 2021-01-08 11:57:08.644 AEDT [24766] STATEMENT: START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2', publication_names '"tap_pub"') 2021-01-08 11:57:08.644 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:08.644 AEDT [24766] LOG: logical decoding found consistent point at 0/16393D0 2021-01-08 11:57:08.644 AEDT [24766] DETAIL: There are no running transactions. 2021-01-08 11:57:08.644 AEDT [24766] STATEMENT: START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2', publication_names '"tap_pub"') 2021-01-08 11:57:08.644 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:08.644 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:08.644 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:08.645 AEDT [24766] LOG: !!>> pgoutput_begin_txn 2021-01-08 11:57:08.645 AEDT [24766] CONTEXT: slot "tap_sub", output plugin "pgoutput", in the begin callback, associated LSN 0/16394B8 2021-01-08 11:57:08.645 AEDT [24766] STATEMENT: START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2', publication_names '"tap_pub"') 2021-01-08 11:57:08.645 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:08.645 AEDT [24765] LOG: !!>> apply worker: apply_dispatch for message kind 'B' 2021-01-08 11:57:08.646 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:08.646 AEDT [24765] LOG: !!>> apply worker: apply_dispatch for message kind 'C' 2021-01-08 11:57:08.646 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:08.646 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:08.656 AEDT [24766] LOG: !!>> pgoutput_commit_txn 2021-01-08 11:57:08.656 AEDT [24766] CONTEXT: slot "tap_sub", output plugin "pgoutput", in the commit callback, associated LSN 0/163ACA0 2021-01-08 11:57:08.656 AEDT [24766] STATEMENT: START_REPLICATION SLOT "tap_sub" LOGICAL 0/0 (proto_version '2', publication_names '"tap_pub"') ## ## Apply worker main loop continues... Now the publication/subscription has no tables ## 2021-01-08 11:57:08.663 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:08.663 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:09.664 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:09.665 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:10.666 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:10.666 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:11.668 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:11.668 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:12.669 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:12.669 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:13.670 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:13.670 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:14.672 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:14.672 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:15.679 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:15.680 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:16.680 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:16.680 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:17.681 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:17.681 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:18.683 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:18.683 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:19.684 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:19.684 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:20.686 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:20.686 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:21.692 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:21.692 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:22.693 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:22.694 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:23.698 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:23.698 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:24.703 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:24.703 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:25.705 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:25.705 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:26.713 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:26.713 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:27.719 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:27.719 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:28.726 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:28.726 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:29.729 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:29.729 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:30.732 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:30.732 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:31.734 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:31.734 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:32.739 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:32.739 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables ## ## See what slots are still present: ## ## Notice that the tablesync slot is still there ## psql -d test_pub -c "select * from pg_replication_slots;"2021-01-08 11:57:33.741 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:33.741 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables slot_name | plugin | slot_type | datoid | database | temporary | active | active_pid | xmin | catalog_x min | restart_lsn | confirmed_flush_lsn | wal_status | safe_wal_size ---------------------+----------+-----------+--------+----------+-----------+--------+------------+------+---------- ----+-------------+---------------------+------------+--------------- tap_sub | pgoutput | logical | 16384 | test_pub | f | t | 24766 | | 531 | 0/163AD50 | 0/163AE38 | reserved | pg_24610_sync_16385 | pgoutput | logical | 16384 | test_pub | f | f | | | 530 | 0/1639398 | 0/16393D0 | reserved | (2 rows) [postgres@CentOS7-x64 ~]$ 2021-01-08 11:57:34.742 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:34.742 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:35.745 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:35.745 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:36.746 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:36.746 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:37.749 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:37.749 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:38.754 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:38.754 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:38.754 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:38.754 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:39.755 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:39.756 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:40.757 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:40.757 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:41.758 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:41.758 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:42.760 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:42.760 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:43.761 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:43.761 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:44.763 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:44.763 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:45.771 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:45.771 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:46.772 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:46.772 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:47.775 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:47.775 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:48.778 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:48.778 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:49.783 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:49.783 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:50.804 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:50.804 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:51.804 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:51.804 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:52.806 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:52.806 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:53.806 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:53.807 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:54.807 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:54.807 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:55.810 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:55.810 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:56.813 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:56.813 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:57.814 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:57.814 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:58.814 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:58.814 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:57:59.817 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:57:59.817 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:58:00.820 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:58:00.820 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:58:01.820 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:58:01.822 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables ## ## Now DROP the subscription ## psql -d test_sub -p 54321 -c "DROP SUBSCRIPTION tap_sub;"2021-01-08 11:58:02.824 AEDT [24765] LOG: !!>> apply worker: LogicalRepApplyLoop 2021-01-08 11:58:02.824 AEDT [24765] LOG: !!>> apply worker: called process_syncing_tables 2021-01-08 11:58:03.079 AEDT [24765] FATAL: terminating logical replication worker due to administrator command 2021-01-08 11:58:03.080 AEDT [3218] LOG: background worker "logical replication worker" (PID 24765) exited with exit code 1 NOTICE: dropped replication slot "tap_sub" on publisher DROP SUBSCRIPTION ## ## And check what slots are left. ## ## Notice that ## - the main replication slot "tap_sub" is cleaned up by the DropSubscription ## - the tablesync slot "pg_24610_sync_16385" was not cleaned up by DropSubscription because it did not know about this relid anymore ## [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_x min | restart_lsn | confirmed_flush_lsn | wal_status | safe_wal_size ---------------------+----------+-----------+--------+----------+-----------+--------+------------+------+---------- ----+-------------+---------------------+------------+--------------- pg_24610_sync_16385 | pgoutput | logical | 16384 | test_pub | f | f | | | 530 | 0/1639398 | 0/16393D0 | reserved | (1 row) [END]