On Thu, Jan 7, 2021 at 3:20 PM Amit Kapila <amit.kapil...@gmail.com> wrote:
>
> On Wed, Jan 6, 2021 at 3:39 PM Amit Kapila <amit.kapil...@gmail.com> wrote:
> >
> > On Wed, Jan 6, 2021 at 2:13 PM Peter Smith <smithpb2...@gmail.com> wrote:
> > >
> > > I think it makes sense. If there can be a race between the tablesync
> > > re-launching (after error), and the AlterSubscription_refresh removing
> > > some table’s relid from the subscription then there could be lurking
> > > slot/origin tablesync resources (of the removed table) which a
> > > subsequent DROP SUBSCRIPTION cannot discover. I will think more about
> > > how/if it is possible to make this happen. Anyway, I suppose I ought
> > > to refactor/isolate some of the tablesync cleanup code in case it
> > > needs to be commonly called from DropSubscription and/or from
> > > AlterSubscription_refresh.
> > >
> >
> > Fair enough.
> >
>
> I think before implementing, we should once try to reproduce this
> case. I understand this is a timing issue and can be reproduced only
> with the help of debugger but we should do that.
FYI, I was able to reproduce this case in debugger. PSA logs showing details.
----
Kind Regards,
Peter Smith.
Fujitsu Australia
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]
