Re: subscriptionCheck failures on nightjar

Sigh, forgot about attaching the attachments ...

            regards, tom lane

diff --git a/src/backend/replication/logical/snapbuild.c b/src/backend/replication/logical/snapbuild.c
index 0bd1d0f..53fd33c 100644
--- a/src/backend/replication/logical/snapbuild.c
+++ b/src/backend/replication/logical/snapbuild.c
@@ -1670,11 +1670,14 @@ SnapBuildSerialize(SnapBuild *builder, XLogRecPtr lsn)
                  errmsg("could not rename file \"%s\" to \"%s\": %m",
                         tmppath, path)));
     }
+    elog(DEBUG1, "renamed serialized snapshot %s to %s", tmppath, path);

     /* make sure we persist */
     fsync_fname(path, false);
     fsync_fname("pg_logical/snapshots", true);

+    elog(DEBUG1, "fsynced %s", path);
+
     /*
      * Now there's no way we can loose the dumped state anymore, remember this
      * as a serialization point.
diff --git a/src/test/subscription/t/010_truncate.pl b/src/test/subscription/t/010_truncate.pl
index be2c0bd..2986582 100644
--- a/src/test/subscription/t/010_truncate.pl
+++ b/src/test/subscription/t/010_truncate.pl
@@ -9,6 +9,11 @@ use Test::More tests => 9;

 my $node_publisher = get_new_node('publisher');
 $node_publisher->init(allows_streaming => 'logical');
+$node_publisher->append_conf('postgresql.conf', q{
+log_checkpoints = on
+log_min_messages = 'debug1'
+log_error_verbosity = verbose
+});
 $node_publisher->start;

 my $node_subscriber = get_new_node('subscriber');
2019-09-20 17:08:54.361 EDT [34418] DEBUG:  00000: registering background worker "logical replication launcher"
2019-09-20 17:08:54.361 EDT [34418] LOCATION:  RegisterBackgroundWorker, bgworker.c:855
2019-09-20 17:08:54.362 EDT [34418] LOG:  00000: starting PostgreSQL 13devel on x86_64-unknown-freebsd9.0, compiled by
gcc(GCC) 4.2.1 20070831 patched [FreeBSD], 64-bit 
2019-09-20 17:08:54.362 EDT [34418] LOCATION:  PostmasterMain, postmaster.c:1104
2019-09-20 17:08:54.362 EDT [34418] LOG:  00000: listening on Unix socket "/tmp/2lehMLoBNn/.s.PGSQL.65366"
2019-09-20 17:08:54.362 EDT [34418] LOCATION:  StreamServerPort, pqcomm.c:587
2019-09-20 17:08:54.363 EDT [34419] LOG:  00000: database system was shut down at 2019-09-20 17:08:54 EDT
2019-09-20 17:08:54.363 EDT [34419] LOCATION:  StartupXLOG, xlog.c:6241
2019-09-20 17:08:54.363 EDT [34419] DEBUG:  00000: checkpoint record is at 0/15D07F0
2019-09-20 17:08:54.363 EDT [34419] LOCATION:  StartupXLOG, xlog.c:6531
2019-09-20 17:08:54.363 EDT [34419] DEBUG:  00000: redo record is at 0/15D07F0; shutdown true
2019-09-20 17:08:54.363 EDT [34419] LOCATION:  StartupXLOG, xlog.c:6609
2019-09-20 17:08:54.363 EDT [34419] DEBUG:  00000: next transaction ID: 490; next OID: 12674
2019-09-20 17:08:54.363 EDT [34419] LOCATION:  StartupXLOG, xlog.c:6613
2019-09-20 17:08:54.363 EDT [34419] DEBUG:  00000: next MultiXactId: 1; next MultiXactOffset: 0
2019-09-20 17:08:54.363 EDT [34419] LOCATION:  StartupXLOG, xlog.c:6616
2019-09-20 17:08:54.363 EDT [34419] DEBUG:  00000: oldest unfrozen transaction ID: 483, in database 1
2019-09-20 17:08:54.363 EDT [34419] LOCATION:  StartupXLOG, xlog.c:6619
2019-09-20 17:08:54.363 EDT [34419] DEBUG:  00000: oldest MultiXactId: 1, in database 1
2019-09-20 17:08:54.363 EDT [34419] LOCATION:  StartupXLOG, xlog.c:6622
2019-09-20 17:08:54.363 EDT [34419] DEBUG:  00000: commit timestamp Xid oldest/newest: 0/0
2019-09-20 17:08:54.363 EDT [34419] LOCATION:  StartupXLOG, xlog.c:6626
2019-09-20 17:08:54.363 EDT [34419] DEBUG:  00000: transaction ID wrap limit is 2147484130, limited by database with
OID1 
2019-09-20 17:08:54.363 EDT [34419] LOCATION:  SetTransactionIdLimit, varsup.c:410
2019-09-20 17:08:54.363 EDT [34419] DEBUG:  00000: MultiXactId wrap limit is 2147483648, limited by database with OID 1
2019-09-20 17:08:54.363 EDT [34419] LOCATION:  SetMultiXactIdLimit, multixact.c:2271
2019-09-20 17:08:54.363 EDT [34419] DEBUG:  00000: starting up replication slots
2019-09-20 17:08:54.363 EDT [34419] LOCATION:  StartupReplicationSlots, slot.c:1114
2019-09-20 17:08:54.363 EDT [34419] DEBUG:  00000: MultiXactId wrap limit is 2147483648, limited by database with OID 1
2019-09-20 17:08:54.363 EDT [34419] LOCATION:  SetMultiXactIdLimit, multixact.c:2271
2019-09-20 17:08:54.363 EDT [34419] DEBUG:  00000: MultiXact member stop limit is now 4294914944 based on MultiXact 1
2019-09-20 17:08:54.363 EDT [34419] LOCATION:  SetOffsetVacuumLimit, multixact.c:2634
2019-09-20 17:08:54.364 EDT [34418] DEBUG:  00000: starting background worker process "logical replication launcher"
2019-09-20 17:08:54.364 EDT [34418] LOCATION:  do_start_bgworker, postmaster.c:5749
2019-09-20 17:08:54.364 EDT [34418] LOG:  00000: database system is ready to accept connections
2019-09-20 17:08:54.364 EDT [34418] LOCATION:  reaper, postmaster.c:3017
2019-09-20 17:08:54.365 EDT [34423] DEBUG:  00000: autovacuum launcher started
2019-09-20 17:08:54.365 EDT [34423] LOCATION:  AutoVacLauncherMain, autovacuum.c:441
2019-09-20 17:08:54.365 EDT [34425] DEBUG:  00000: logical replication launcher started
2019-09-20 17:08:54.365 EDT [34425] LOCATION:  ApplyLauncherMain, launcher.c:977
2019-09-20 17:08:55.294 EDT [34444] 010_truncate.pl LOG:  00000: statement: CREATE TABLE tab1 (a int PRIMARY KEY)
2019-09-20 17:08:55.294 EDT [34444] 010_truncate.pl LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:55.297 EDT [34444] 010_truncate.pl DEBUG:  00000: CREATE TABLE / PRIMARY KEY will create implicit
index"tab1_pkey" for table "tab1" 
2019-09-20 17:08:55.297 EDT [34444] 010_truncate.pl LOCATION:  DefineIndex, indexcmds.c:938
2019-09-20 17:08:55.298 EDT [34444] 010_truncate.pl DEBUG:  00000: building index "tab1_pkey" on table "tab1" serially
2019-09-20 17:08:55.298 EDT [34444] 010_truncate.pl LOCATION:  index_build, index.c:2724
2019-09-20 17:08:55.313 EDT [34448] 010_truncate.pl LOG:  00000: statement: CREATE TABLE tab2 (a int PRIMARY KEY)
2019-09-20 17:08:55.313 EDT [34448] 010_truncate.pl LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:55.315 EDT [34448] 010_truncate.pl DEBUG:  00000: CREATE TABLE / PRIMARY KEY will create implicit
index"tab2_pkey" for table "tab2" 
2019-09-20 17:08:55.315 EDT [34448] 010_truncate.pl LOCATION:  DefineIndex, indexcmds.c:938
2019-09-20 17:08:55.315 EDT [34448] 010_truncate.pl DEBUG:  00000: building index "tab2_pkey" on table "tab2" serially
2019-09-20 17:08:55.315 EDT [34448] 010_truncate.pl LOCATION:  index_build, index.c:2724
2019-09-20 17:08:55.327 EDT [34452] 010_truncate.pl LOG:  00000: statement: CREATE TABLE tab3 (a int PRIMARY KEY)
2019-09-20 17:08:55.327 EDT [34452] 010_truncate.pl LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:55.329 EDT [34452] 010_truncate.pl DEBUG:  00000: CREATE TABLE / PRIMARY KEY will create implicit
index"tab3_pkey" for table "tab3" 
2019-09-20 17:08:55.329 EDT [34452] 010_truncate.pl LOCATION:  DefineIndex, indexcmds.c:938
2019-09-20 17:08:55.329 EDT [34452] 010_truncate.pl DEBUG:  00000: building index "tab3_pkey" on table "tab3" serially
2019-09-20 17:08:55.329 EDT [34452] 010_truncate.pl LOCATION:  index_build, index.c:2724
2019-09-20 17:08:55.341 EDT [34456] 010_truncate.pl LOG:  00000: statement: CREATE TABLE tab4 (x int PRIMARY KEY, y int
REFERENCEStab3) 
2019-09-20 17:08:55.341 EDT [34456] 010_truncate.pl LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:55.343 EDT [34456] 010_truncate.pl DEBUG:  00000: CREATE TABLE / PRIMARY KEY will create implicit
index"tab4_pkey" for table "tab4" 
2019-09-20 17:08:55.343 EDT [34456] 010_truncate.pl LOCATION:  DefineIndex, indexcmds.c:938
2019-09-20 17:08:55.343 EDT [34456] 010_truncate.pl DEBUG:  00000: building index "tab4_pkey" on table "tab4" serially
2019-09-20 17:08:55.343 EDT [34456] 010_truncate.pl LOCATION:  index_build, index.c:2724
2019-09-20 17:08:55.369 EDT [34464] 010_truncate.pl LOG:  00000: statement: CREATE PUBLICATION pub1 FOR TABLE tab1
2019-09-20 17:08:55.369 EDT [34464] 010_truncate.pl LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:55.375 EDT [34466] 010_truncate.pl LOG:  00000: statement: CREATE PUBLICATION pub2 FOR TABLE tab2 WITH
(publish= insert) 
2019-09-20 17:08:55.375 EDT [34466] 010_truncate.pl LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:55.380 EDT [34468] 010_truncate.pl LOG:  00000: statement: CREATE PUBLICATION pub3 FOR TABLE tab3,
tab4
2019-09-20 17:08:55.380 EDT [34468] 010_truncate.pl LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:55.388 EDT [34471] sub1 LOG:  00000: statement: SELECT DISTINCT t.schemaname, t.tablename
      FROM pg_catalog.pg_publication_tables t
     WHERE t.pubname IN ('pub1')
2019-09-20 17:08:55.388 EDT [34471] sub1 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:55.392 EDT [34471] sub1 LOG:  00000: received replication command: CREATE_REPLICATION_SLOT "sub1"
LOGICALpgoutput NOEXPORT_SNAPSHOT 
2019-09-20 17:08:55.392 EDT [34471] sub1 LOCATION:  exec_replication_command, walsender.c:1487
2019-09-20 17:08:55.392 EDT [34471] sub1 DEBUG:  00000: searching for logical decoding starting point, starting at
0/15FA830
2019-09-20 17:08:55.392 EDT [34471] sub1 LOCATION:  DecodingContextFindStartpoint, logical.c:476
2019-09-20 17:08:55.392 EDT [34471] sub1 LOG:  00000: logical decoding found consistent point at 0/15FA830
2019-09-20 17:08:55.392 EDT [34471] sub1 DETAIL:  There are no running transactions.
2019-09-20 17:08:55.392 EDT [34471] sub1 LOCATION:  SnapBuildFindSnapshot, snapbuild.c:1272
2019-09-20 17:08:55.397 EDT [34474] sub1 LOG:  00000: received replication command: IDENTIFY_SYSTEM
2019-09-20 17:08:55.397 EDT [34474] sub1 LOCATION:  exec_replication_command, walsender.c:1487
2019-09-20 17:08:55.397 EDT [34474] sub1 LOG:  00000: received replication command: START_REPLICATION SLOT "sub1"
LOGICAL0/0 (proto_version '1', publication_names '"pub1"') 
2019-09-20 17:08:55.397 EDT [34474] sub1 LOCATION:  exec_replication_command, walsender.c:1487
2019-09-20 17:08:55.397 EDT [34474] sub1 LOG:  00000: starting logical decoding for slot "sub1"
2019-09-20 17:08:55.397 EDT [34474] sub1 DETAIL:  Streaming transactions committing after 0/15FA868, reading WAL from
0/15FA830.
2019-09-20 17:08:55.397 EDT [34474] sub1 LOCATION:  CreateDecodingContext, logical.c:448
2019-09-20 17:08:55.397 EDT [34474] sub1 LOG:  00000: logical decoding found consistent point at 0/15FA830
2019-09-20 17:08:55.397 EDT [34474] sub1 DETAIL:  There are no running transactions.
2019-09-20 17:08:55.397 EDT [34474] sub1 LOCATION:  SnapBuildFindSnapshot, snapbuild.c:1272
2019-09-20 17:08:55.397 EDT [34474] sub1 DEBUG:  00000: "sub1" has now caught up with upstream server
2019-09-20 17:08:55.397 EDT [34474] sub1 LOCATION:  WalSndLoop, walsender.c:2224
2019-09-20 17:08:55.400 EDT [34477] sub2 LOG:  00000: statement: SELECT DISTINCT t.schemaname, t.tablename
      FROM pg_catalog.pg_publication_tables t
     WHERE t.pubname IN ('pub2')
2019-09-20 17:08:55.400 EDT [34477] sub2 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:55.401 EDT [34478] sub1_16412_sync_16384 LOG:  00000: statement: BEGIN READ ONLY ISOLATION LEVEL
REPEATABLEREAD 
2019-09-20 17:08:55.401 EDT [34478] sub1_16412_sync_16384 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:55.401 EDT [34478] sub1_16412_sync_16384 LOG:  00000: received replication command:
CREATE_REPLICATION_SLOT"sub1_16412_sync_16384" TEMPORARY LOGICAL pgoutput USE_SNAPSHOT 
2019-09-20 17:08:55.401 EDT [34478] sub1_16412_sync_16384 LOCATION:  exec_replication_command, walsender.c:1487
2019-09-20 17:08:55.402 EDT [34474] sub1 DEBUG:  00000: serializing snapshot to pg_logical/snapshots/0-15FA868.snap
2019-09-20 17:08:55.402 EDT [34474] sub1 LOCATION:  SnapBuildSerialize, snapbuild.c:1554
2019-09-20 17:08:55.402 EDT [34474] sub1 DEBUG:  00000: renamed serialized snapshot
pg_logical/snapshots/0-15FA868.snap.34474.tmpto pg_logical/snapshots/0-15FA868.snap 
2019-09-20 17:08:55.402 EDT [34474] sub1 LOCATION:  SnapBuildSerialize, snapbuild.c:1673
2019-09-20 17:08:55.402 EDT [34474] sub1 DEBUG:  00000: fsynced pg_logical/snapshots/0-15FA868.snap
2019-09-20 17:08:55.402 EDT [34474] sub1 LOCATION:  SnapBuildSerialize, snapbuild.c:1679
2019-09-20 17:08:55.402 EDT [34474] sub1 DEBUG:  00000: failed to increase restart lsn: proposed 0/15FA868, after
0/15FA868,current candidate 0/15FA868, current after 0/15FA868, flushed up to 0/15FA868 
2019-09-20 17:08:55.402 EDT [34474] sub1 LOCATION:  LogicalIncreaseRestartDecodingForSlot, logical.c:992
2019-09-20 17:08:55.402 EDT [34474] sub1 DEBUG:  00000: updated xmin: 0 restart: 1
2019-09-20 17:08:55.402 EDT [34474] sub1 LOCATION:  LogicalConfirmReceivedLocation, logical.c:1061
2019-09-20 17:08:55.402 EDT [34478] sub1_16412_sync_16384 DEBUG:  00000: searching for logical decoding starting point,
startingat 0/15FA868 
2019-09-20 17:08:55.402 EDT [34478] sub1_16412_sync_16384 LOCATION:  DecodingContextFindStartpoint, logical.c:476
2019-09-20 17:08:55.402 EDT [34478] sub1_16412_sync_16384 LOG:  00000: logical decoding found consistent point at
0/15FA868
2019-09-20 17:08:55.402 EDT [34478] sub1_16412_sync_16384 DETAIL:  There are no running transactions.
2019-09-20 17:08:55.402 EDT [34478] sub1_16412_sync_16384 LOCATION:  SnapBuildFindSnapshot, snapbuild.c:1272
2019-09-20 17:08:55.402 EDT [34478] sub1_16412_sync_16384 LOG:  00000: statement: SELECT c.oid, c.relreplident  FROM
pg_catalog.pg_classc  INNER JOIN pg_catalog.pg_namespace n        ON (c.relnamespace = n.oid) WHERE n.nspname =
'public'  AND c.relname = 'tab1'   AND c.relkind = 'r' 
2019-09-20 17:08:55.402 EDT [34478] sub1_16412_sync_16384 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:55.403 EDT [34478] sub1_16412_sync_16384 LOG:  00000: statement: SELECT a.attname,       a.atttypid,
   a.atttypmod,       a.attnum = ANY(i.indkey)  FROM pg_catalog.pg_attribute a  LEFT JOIN pg_catalog.pg_index i
ON(i.indexrelid = pg_get_replica_identity_index(16384)) WHERE a.attnum > 0::pg_catalog.int2   AND NOT a.attisdropped
ANDa.attgenerated = ''   AND a.attrelid = 16384 ORDER BY a.attnum 
2019-09-20 17:08:55.403 EDT [34478] sub1_16412_sync_16384 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:55.403 EDT [34477] sub2 LOG:  00000: received replication command: CREATE_REPLICATION_SLOT "sub2"
LOGICALpgoutput NOEXPORT_SNAPSHOT 
2019-09-20 17:08:55.403 EDT [34477] sub2 LOCATION:  exec_replication_command, walsender.c:1487
2019-09-20 17:08:55.403 EDT [34474] sub1 DEBUG:  00000: serializing snapshot to pg_logical/snapshots/0-15FA8A0.snap
2019-09-20 17:08:55.403 EDT [34474] sub1 LOCATION:  SnapBuildSerialize, snapbuild.c:1554
2019-09-20 17:08:55.403 EDT [34474] sub1 DEBUG:  00000: renamed serialized snapshot
pg_logical/snapshots/0-15FA8A0.snap.34474.tmpto pg_logical/snapshots/0-15FA8A0.snap 
2019-09-20 17:08:55.403 EDT [34474] sub1 LOCATION:  SnapBuildSerialize, snapbuild.c:1673
2019-09-20 17:08:55.404 EDT [34474] sub1 DEBUG:  00000: fsynced pg_logical/snapshots/0-15FA8A0.snap
2019-09-20 17:08:55.404 EDT [34474] sub1 LOCATION:  SnapBuildSerialize, snapbuild.c:1679
2019-09-20 17:08:55.404 EDT [34474] sub1 DEBUG:  00000: got new restart lsn 0/15FA8A0 at 0/15FA8A0
2019-09-20 17:08:55.404 EDT [34474] sub1 LOCATION:  LogicalIncreaseRestartDecodingForSlot, logical.c:979
2019-09-20 17:08:55.404 EDT [34477] sub2 DEBUG:  00000: searching for logical decoding starting point, starting at
0/15FA8A0
2019-09-20 17:08:55.404 EDT [34477] sub2 LOCATION:  DecodingContextFindStartpoint, logical.c:476
2019-09-20 17:08:55.404 EDT [34477] sub2 LOG:  00000: logical decoding found consistent point at 0/15FA8A0
2019-09-20 17:08:55.404 EDT [34477] sub2 DETAIL:  There are no running transactions.
2019-09-20 17:08:55.404 EDT [34477] sub2 LOCATION:  SnapBuildFindSnapshot, snapbuild.c:1272
2019-09-20 17:08:55.405 EDT [34478] sub1_16412_sync_16384 LOG:  00000: statement: COPY public.tab1 TO STDOUT
2019-09-20 17:08:55.405 EDT [34478] sub1_16412_sync_16384 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:55.406 EDT [34478] sub1_16412_sync_16384 LOG:  00000: statement: COMMIT
2019-09-20 17:08:55.406 EDT [34478] sub1_16412_sync_16384 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:55.406 EDT [34474] sub1 DEBUG:  00000: updated xmin: 0 restart: 1
2019-09-20 17:08:55.406 EDT [34474] sub1 LOCATION:  LogicalConfirmReceivedLocation, logical.c:1061
2019-09-20 17:08:55.411 EDT [34481] sub3 LOG:  00000: statement: SELECT DISTINCT t.schemaname, t.tablename
      FROM pg_catalog.pg_publication_tables t
     WHERE t.pubname IN ('pub3')
2019-09-20 17:08:55.411 EDT [34481] sub3 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:55.414 EDT [34481] sub3 LOG:  00000: received replication command: CREATE_REPLICATION_SLOT "sub3"
LOGICALpgoutput NOEXPORT_SNAPSHOT 
2019-09-20 17:08:55.414 EDT [34481] sub3 LOCATION:  exec_replication_command, walsender.c:1487
2019-09-20 17:08:55.414 EDT [34474] sub1 DEBUG:  00000: serializing snapshot to pg_logical/snapshots/0-15FA8D8.snap
2019-09-20 17:08:55.414 EDT [34474] sub1 LOCATION:  SnapBuildSerialize, snapbuild.c:1554
2019-09-20 17:08:55.414 EDT [34474] sub1 DEBUG:  00000: renamed serialized snapshot
pg_logical/snapshots/0-15FA8D8.snap.34474.tmpto pg_logical/snapshots/0-15FA8D8.snap 
2019-09-20 17:08:55.414 EDT [34474] sub1 LOCATION:  SnapBuildSerialize, snapbuild.c:1673
2019-09-20 17:08:55.414 EDT [34474] sub1 DEBUG:  00000: fsynced pg_logical/snapshots/0-15FA8D8.snap
2019-09-20 17:08:55.414 EDT [34474] sub1 LOCATION:  SnapBuildSerialize, snapbuild.c:1679
2019-09-20 17:08:55.414 EDT [34474] sub1 DEBUG:  00000: failed to increase restart lsn: proposed 0/15FA8D8, after
0/15FA8D8,current candidate 0/15FA8D8, current after 0/15FA8D8, flushed up to 0/15FA8D8 
2019-09-20 17:08:55.414 EDT [34474] sub1 LOCATION:  LogicalIncreaseRestartDecodingForSlot, logical.c:992
2019-09-20 17:08:55.414 EDT [34481] sub3 DEBUG:  00000: searching for logical decoding starting point, starting at
0/15FA8D8
2019-09-20 17:08:55.414 EDT [34481] sub3 LOCATION:  DecodingContextFindStartpoint, logical.c:476
2019-09-20 17:08:55.414 EDT [34474] sub1 DEBUG:  00000: updated xmin: 0 restart: 1
2019-09-20 17:08:55.414 EDT [34474] sub1 LOCATION:  LogicalConfirmReceivedLocation, logical.c:1061
2019-09-20 17:08:55.414 EDT [34481] sub3 LOG:  00000: logical decoding found consistent point at 0/15FA8D8
2019-09-20 17:08:55.414 EDT [34481] sub3 DETAIL:  There are no running transactions.
2019-09-20 17:08:55.414 EDT [34481] sub3 LOCATION:  SnapBuildFindSnapshot, snapbuild.c:1272
2019-09-20 17:08:55.924 EDT [34493] sub2 LOG:  00000: received replication command: IDENTIFY_SYSTEM
2019-09-20 17:08:55.924 EDT [34493] sub2 LOCATION:  exec_replication_command, walsender.c:1487
2019-09-20 17:08:55.925 EDT [34493] sub2 LOG:  00000: received replication command: START_REPLICATION SLOT "sub2"
LOGICAL0/0 (proto_version '1', publication_names '"pub2"') 
2019-09-20 17:08:55.925 EDT [34493] sub2 LOCATION:  exec_replication_command, walsender.c:1487
2019-09-20 17:08:55.925 EDT [34493] sub2 LOG:  00000: starting logical decoding for slot "sub2"
2019-09-20 17:08:55.925 EDT [34493] sub2 DETAIL:  Streaming transactions committing after 0/15FA8D8, reading WAL from
0/15FA8A0.
2019-09-20 17:08:55.925 EDT [34493] sub2 LOCATION:  CreateDecodingContext, logical.c:448
2019-09-20 17:08:55.925 EDT [34493] sub2 LOG:  00000: logical decoding found consistent point at 0/15FA8A0
2019-09-20 17:08:55.925 EDT [34493] sub2 DETAIL:  There are no running transactions.
2019-09-20 17:08:55.925 EDT [34493] sub2 LOCATION:  SnapBuildFindSnapshot, snapbuild.c:1272
2019-09-20 17:08:55.925 EDT [34493] sub2 DEBUG:  00000: failed to increase restart lsn: proposed 0/15FA8D8, after
0/15FA8D8,current candidate 0/15FA8D8, current after 0/15FA8D8, flushed up to 0/15FA8D8 
2019-09-20 17:08:55.925 EDT [34493] sub2 LOCATION:  LogicalIncreaseRestartDecodingForSlot, logical.c:992
2019-09-20 17:08:55.925 EDT [34493] sub2 DEBUG:  00000: updated xmin: 0 restart: 1
2019-09-20 17:08:55.925 EDT [34493] sub2 LOCATION:  LogicalConfirmReceivedLocation, logical.c:1061
2019-09-20 17:08:55.925 EDT [34493] sub2 DEBUG:  00000: "sub2" has now caught up with upstream server
2019-09-20 17:08:55.925 EDT [34493] sub2 LOCATION:  WalSndLoop, walsender.c:2224
2019-09-20 17:08:55.929 EDT [34495] sub2_16413_sync_16389 LOG:  00000: statement: BEGIN READ ONLY ISOLATION LEVEL
REPEATABLEREAD 
2019-09-20 17:08:55.929 EDT [34495] sub2_16413_sync_16389 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:55.930 EDT [34495] sub2_16413_sync_16389 LOG:  00000: received replication command:
CREATE_REPLICATION_SLOT"sub2_16413_sync_16389" TEMPORARY LOGICAL pgoutput USE_SNAPSHOT 
2019-09-20 17:08:55.930 EDT [34495] sub2_16413_sync_16389 LOCATION:  exec_replication_command, walsender.c:1487
2019-09-20 17:08:55.930 EDT [34474] sub1 DEBUG:  00000: serializing snapshot to pg_logical/snapshots/0-15FA910.snap
2019-09-20 17:08:55.930 EDT [34474] sub1 LOCATION:  SnapBuildSerialize, snapbuild.c:1554
2019-09-20 17:08:55.930 EDT [34493] sub2 DEBUG:  00000: serializing snapshot to pg_logical/snapshots/0-15FA910.snap
2019-09-20 17:08:55.930 EDT [34493] sub2 LOCATION:  SnapBuildSerialize, snapbuild.c:1554
2019-09-20 17:08:55.930 EDT [34474] sub1 DEBUG:  00000: renamed serialized snapshot
pg_logical/snapshots/0-15FA910.snap.34474.tmpto pg_logical/snapshots/0-15FA910.snap 
2019-09-20 17:08:55.930 EDT [34474] sub1 LOCATION:  SnapBuildSerialize, snapbuild.c:1673
2019-09-20 17:08:55.930 EDT [34493] sub2 DEBUG:  00000: renamed serialized snapshot
pg_logical/snapshots/0-15FA910.snap.34493.tmpto pg_logical/snapshots/0-15FA910.snap 
2019-09-20 17:08:55.930 EDT [34493] sub2 LOCATION:  SnapBuildSerialize, snapbuild.c:1673
2019-09-20 17:08:55.930 EDT [34474] sub1 DEBUG:  00000: fsynced pg_logical/snapshots/0-15FA910.snap
2019-09-20 17:08:55.930 EDT [34474] sub1 LOCATION:  SnapBuildSerialize, snapbuild.c:1679
2019-09-20 17:08:55.930 EDT [34474] sub1 DEBUG:  00000: failed to increase restart lsn: proposed 0/15FA910, after
0/15FA910,current candidate 0/15FA910, current after 0/15FA910, flushed up to 0/15FA910 
2019-09-20 17:08:55.930 EDT [34474] sub1 LOCATION:  LogicalIncreaseRestartDecodingForSlot, logical.c:992
2019-09-20 17:08:55.930 EDT [34493] sub2 DEBUG:  00000: fsynced pg_logical/snapshots/0-15FA910.snap
2019-09-20 17:08:55.930 EDT [34493] sub2 LOCATION:  SnapBuildSerialize, snapbuild.c:1679
2019-09-20 17:08:55.930 EDT [34493] sub2 DEBUG:  00000: got new restart lsn 0/15FA910 at 0/15FA910
2019-09-20 17:08:55.930 EDT [34493] sub2 LOCATION:  LogicalIncreaseRestartDecodingForSlot, logical.c:979
2019-09-20 17:08:55.930 EDT [34495] sub2_16413_sync_16389 DEBUG:  00000: searching for logical decoding starting point,
startingat 0/15FA910 
2019-09-20 17:08:55.930 EDT [34495] sub2_16413_sync_16389 LOCATION:  DecodingContextFindStartpoint, logical.c:476
2019-09-20 17:08:55.930 EDT [34474] sub1 DEBUG:  00000: updated xmin: 0 restart: 1
2019-09-20 17:08:55.930 EDT [34474] sub1 LOCATION:  LogicalConfirmReceivedLocation, logical.c:1061
2019-09-20 17:08:55.930 EDT [34495] sub2_16413_sync_16389 LOG:  00000: logical decoding found consistent point at
0/15FA910
2019-09-20 17:08:55.930 EDT [34495] sub2_16413_sync_16389 DETAIL:  There are no running transactions.
2019-09-20 17:08:55.930 EDT [34495] sub2_16413_sync_16389 LOCATION:  SnapBuildFindSnapshot, snapbuild.c:1272
2019-09-20 17:08:55.930 EDT [34495] sub2_16413_sync_16389 LOG:  00000: statement: SELECT c.oid, c.relreplident  FROM
pg_catalog.pg_classc  INNER JOIN pg_catalog.pg_namespace n        ON (c.relnamespace = n.oid) WHERE n.nspname =
'public'  AND c.relname = 'tab2'   AND c.relkind = 'r' 
2019-09-20 17:08:55.930 EDT [34495] sub2_16413_sync_16389 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:55.931 EDT [34497] sub3 LOG:  00000: received replication command: IDENTIFY_SYSTEM
2019-09-20 17:08:55.931 EDT [34497] sub3 LOCATION:  exec_replication_command, walsender.c:1487
2019-09-20 17:08:55.931 EDT [34497] sub3 LOG:  00000: received replication command: START_REPLICATION SLOT "sub3"
LOGICAL0/0 (proto_version '1', publication_names '"pub3"') 
2019-09-20 17:08:55.931 EDT [34497] sub3 LOCATION:  exec_replication_command, walsender.c:1487
2019-09-20 17:08:55.931 EDT [34497] sub3 LOG:  00000: starting logical decoding for slot "sub3"
2019-09-20 17:08:55.931 EDT [34497] sub3 DETAIL:  Streaming transactions committing after 0/15FA910, reading WAL from
0/15FA8D8.
2019-09-20 17:08:55.931 EDT [34497] sub3 LOCATION:  CreateDecodingContext, logical.c:448
2019-09-20 17:08:55.931 EDT [34497] sub3 LOG:  00000: logical decoding found consistent point at 0/15FA8D8
2019-09-20 17:08:55.931 EDT [34497] sub3 DETAIL:  There are no running transactions.
2019-09-20 17:08:55.931 EDT [34497] sub3 LOCATION:  SnapBuildFindSnapshot, snapbuild.c:1272
2019-09-20 17:08:55.931 EDT [34497] sub3 DEBUG:  00000: failed to increase restart lsn: proposed 0/15FA910, after
0/15FA910,current candidate 0/15FA910, current after 0/15FA910, flushed up to 0/15FA910 
2019-09-20 17:08:55.931 EDT [34497] sub3 LOCATION:  LogicalIncreaseRestartDecodingForSlot, logical.c:992
2019-09-20 17:08:55.931 EDT [34497] sub3 DEBUG:  00000: updated xmin: 0 restart: 1
2019-09-20 17:08:55.931 EDT [34497] sub3 LOCATION:  LogicalConfirmReceivedLocation, logical.c:1061
2019-09-20 17:08:55.931 EDT [34497] sub3 DEBUG:  00000: "sub3" has now caught up with upstream server
2019-09-20 17:08:55.931 EDT [34497] sub3 LOCATION:  WalSndLoop, walsender.c:2224
2019-09-20 17:08:55.932 EDT [34495] sub2_16413_sync_16389 LOG:  00000: statement: SELECT a.attname,       a.atttypid,
   a.atttypmod,       a.attnum = ANY(i.indkey)  FROM pg_catalog.pg_attribute a  LEFT JOIN pg_catalog.pg_index i
ON(i.indexrelid = pg_get_replica_identity_index(16389)) WHERE a.attnum > 0::pg_catalog.int2   AND NOT a.attisdropped
ANDa.attgenerated = ''   AND a.attrelid = 16389 ORDER BY a.attnum 
2019-09-20 17:08:55.932 EDT [34495] sub2_16413_sync_16389 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:55.933 EDT [34495] sub2_16413_sync_16389 LOG:  00000: statement: COPY public.tab2 TO STDOUT
2019-09-20 17:08:55.933 EDT [34495] sub2_16413_sync_16389 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:55.934 EDT [34495] sub2_16413_sync_16389 LOG:  00000: statement: COMMIT
2019-09-20 17:08:55.934 EDT [34495] sub2_16413_sync_16389 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:55.934 EDT [34493] sub2 DEBUG:  00000: updated xmin: 0 restart: 1
2019-09-20 17:08:55.934 EDT [34493] sub2 LOCATION:  LogicalConfirmReceivedLocation, logical.c:1061
2019-09-20 17:08:56.941 EDT [34517] sub3_16414_sync_16394 LOG:  00000: statement: BEGIN READ ONLY ISOLATION LEVEL
REPEATABLEREAD 
2019-09-20 17:08:56.941 EDT [34517] sub3_16414_sync_16394 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:56.942 EDT [34517] sub3_16414_sync_16394 LOG:  00000: received replication command:
CREATE_REPLICATION_SLOT"sub3_16414_sync_16394" TEMPORARY LOGICAL pgoutput USE_SNAPSHOT 
2019-09-20 17:08:56.942 EDT [34517] sub3_16414_sync_16394 LOCATION:  exec_replication_command, walsender.c:1487
2019-09-20 17:08:56.942 EDT [34474] sub1 DEBUG:  00000: serializing snapshot to pg_logical/snapshots/0-15FA948.snap
2019-09-20 17:08:56.942 EDT [34474] sub1 LOCATION:  SnapBuildSerialize, snapbuild.c:1554
2019-09-20 17:08:56.942 EDT [34493] sub2 DEBUG:  00000: serializing snapshot to pg_logical/snapshots/0-15FA948.snap
2019-09-20 17:08:56.942 EDT [34493] sub2 LOCATION:  SnapBuildSerialize, snapbuild.c:1554
2019-09-20 17:08:56.942 EDT [34497] sub3 DEBUG:  00000: serializing snapshot to pg_logical/snapshots/0-15FA948.snap
2019-09-20 17:08:56.942 EDT [34497] sub3 LOCATION:  SnapBuildSerialize, snapbuild.c:1554
2019-09-20 17:08:56.942 EDT [34474] sub1 DEBUG:  00000: renamed serialized snapshot
pg_logical/snapshots/0-15FA948.snap.34474.tmpto pg_logical/snapshots/0-15FA948.snap 
2019-09-20 17:08:56.942 EDT [34474] sub1 LOCATION:  SnapBuildSerialize, snapbuild.c:1673
2019-09-20 17:08:56.942 EDT [34474] sub1 DEBUG:  00000: fsynced pg_logical/snapshots/0-15FA948.snap
2019-09-20 17:08:56.942 EDT [34474] sub1 LOCATION:  SnapBuildSerialize, snapbuild.c:1679
2019-09-20 17:08:56.942 EDT [34474] sub1 DEBUG:  00000: failed to increase restart lsn: proposed 0/15FA948, after
0/15FA948,current candidate 0/15FA948, current after 0/15FA948, flushed up to 0/15FA948 
2019-09-20 17:08:56.942 EDT [34474] sub1 LOCATION:  LogicalIncreaseRestartDecodingForSlot, logical.c:992
2019-09-20 17:08:56.942 EDT [34493] sub2 DEBUG:  00000: renamed serialized snapshot
pg_logical/snapshots/0-15FA948.snap.34493.tmpto pg_logical/snapshots/0-15FA948.snap 
2019-09-20 17:08:56.942 EDT [34493] sub2 LOCATION:  SnapBuildSerialize, snapbuild.c:1673
2019-09-20 17:08:56.942 EDT [34517] sub3_16414_sync_16394 DEBUG:  00000: searching for logical decoding starting point,
startingat 0/15FA948 
2019-09-20 17:08:56.942 EDT [34517] sub3_16414_sync_16394 LOCATION:  DecodingContextFindStartpoint, logical.c:476
2019-09-20 17:08:56.942 EDT [34493] sub2 DEBUG:  00000: fsynced pg_logical/snapshots/0-15FA948.snap
2019-09-20 17:08:56.942 EDT [34493] sub2 LOCATION:  SnapBuildSerialize, snapbuild.c:1679
2019-09-20 17:08:56.942 EDT [34497] sub3 DEBUG:  00000: renamed serialized snapshot
pg_logical/snapshots/0-15FA948.snap.34497.tmpto pg_logical/snapshots/0-15FA948.snap 
2019-09-20 17:08:56.942 EDT [34497] sub3 LOCATION:  SnapBuildSerialize, snapbuild.c:1673
2019-09-20 17:08:56.942 EDT [34474] sub1 DEBUG:  00000: updated xmin: 0 restart: 1
2019-09-20 17:08:56.942 EDT [34474] sub1 LOCATION:  LogicalConfirmReceivedLocation, logical.c:1061
2019-09-20 17:08:56.942 EDT [34493] sub2 DEBUG:  00000: failed to increase restart lsn: proposed 0/15FA948, after
0/15FA948,current candidate 0/15FA948, current after 0/15FA948, flushed up to 0/15FA948 
2019-09-20 17:08:56.942 EDT [34493] sub2 LOCATION:  LogicalIncreaseRestartDecodingForSlot, logical.c:992
2019-09-20 17:08:56.942 EDT [34517] sub3_16414_sync_16394 LOG:  00000: logical decoding found consistent point at
0/15FA948
2019-09-20 17:08:56.942 EDT [34517] sub3_16414_sync_16394 DETAIL:  There are no running transactions.
2019-09-20 17:08:56.942 EDT [34517] sub3_16414_sync_16394 LOCATION:  SnapBuildFindSnapshot, snapbuild.c:1272
2019-09-20 17:08:56.942 EDT [34497] sub3 DEBUG:  00000: fsynced pg_logical/snapshots/0-15FA948.snap
2019-09-20 17:08:56.942 EDT [34497] sub3 LOCATION:  SnapBuildSerialize, snapbuild.c:1679
2019-09-20 17:08:56.942 EDT [34497] sub3 DEBUG:  00000: failed to increase restart lsn: proposed 0/15FA948, after
0/15FA948,current candidate 0/15FA948, current after 0/15FA948, flushed up to 0/15FA948 
2019-09-20 17:08:56.942 EDT [34497] sub3 LOCATION:  LogicalIncreaseRestartDecodingForSlot, logical.c:992
2019-09-20 17:08:56.942 EDT [34493] sub2 DEBUG:  00000: updated xmin: 0 restart: 1
2019-09-20 17:08:56.942 EDT [34493] sub2 LOCATION:  LogicalConfirmReceivedLocation, logical.c:1061
2019-09-20 17:08:56.942 EDT [34497] sub3 DEBUG:  00000: updated xmin: 0 restart: 1
2019-09-20 17:08:56.942 EDT [34497] sub3 LOCATION:  LogicalConfirmReceivedLocation, logical.c:1061
2019-09-20 17:08:56.942 EDT [34517] sub3_16414_sync_16394 LOG:  00000: statement: SELECT c.oid, c.relreplident  FROM
pg_catalog.pg_classc  INNER JOIN pg_catalog.pg_namespace n        ON (c.relnamespace = n.oid) WHERE n.nspname =
'public'  AND c.relname = 'tab3'   AND c.relkind = 'r' 
2019-09-20 17:08:56.942 EDT [34517] sub3_16414_sync_16394 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:56.944 EDT [34517] sub3_16414_sync_16394 LOG:  00000: statement: SELECT a.attname,       a.atttypid,
   a.atttypmod,       a.attnum = ANY(i.indkey)  FROM pg_catalog.pg_attribute a  LEFT JOIN pg_catalog.pg_index i
ON(i.indexrelid = pg_get_replica_identity_index(16394)) WHERE a.attnum > 0::pg_catalog.int2   AND NOT a.attisdropped
ANDa.attgenerated = ''   AND a.attrelid = 16394 ORDER BY a.attnum 
2019-09-20 17:08:56.944 EDT [34517] sub3_16414_sync_16394 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:56.946 EDT [34517] sub3_16414_sync_16394 LOG:  00000: statement: COPY public.tab3 TO STDOUT
2019-09-20 17:08:56.946 EDT [34517] sub3_16414_sync_16394 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:56.946 EDT [34517] sub3_16414_sync_16394 LOG:  00000: statement: COMMIT
2019-09-20 17:08:56.946 EDT [34517] sub3_16414_sync_16394 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:57.957 EDT [34537] sub3_16414_sync_16399 LOG:  00000: statement: BEGIN READ ONLY ISOLATION LEVEL
REPEATABLEREAD 
2019-09-20 17:08:57.957 EDT [34537] sub3_16414_sync_16399 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:57.957 EDT [34537] sub3_16414_sync_16399 LOG:  00000: received replication command:
CREATE_REPLICATION_SLOT"sub3_16414_sync_16399" TEMPORARY LOGICAL pgoutput USE_SNAPSHOT 
2019-09-20 17:08:57.957 EDT [34537] sub3_16414_sync_16399 LOCATION:  exec_replication_command, walsender.c:1487
2019-09-20 17:08:57.957 EDT [34493] sub2 DEBUG:  00000: serializing snapshot to pg_logical/snapshots/0-15FA980.snap
2019-09-20 17:08:57.957 EDT [34493] sub2 LOCATION:  SnapBuildSerialize, snapbuild.c:1554
2019-09-20 17:08:57.957 EDT [34474] sub1 DEBUG:  00000: serializing snapshot to pg_logical/snapshots/0-15FA980.snap
2019-09-20 17:08:57.957 EDT [34474] sub1 LOCATION:  SnapBuildSerialize, snapbuild.c:1554
2019-09-20 17:08:57.957 EDT [34497] sub3 DEBUG:  00000: serializing snapshot to pg_logical/snapshots/0-15FA980.snap
2019-09-20 17:08:57.957 EDT [34497] sub3 LOCATION:  SnapBuildSerialize, snapbuild.c:1554
2019-09-20 17:08:57.957 EDT [34493] sub2 DEBUG:  00000: renamed serialized snapshot
pg_logical/snapshots/0-15FA980.snap.34493.tmpto pg_logical/snapshots/0-15FA980.snap 
2019-09-20 17:08:57.957 EDT [34493] sub2 LOCATION:  SnapBuildSerialize, snapbuild.c:1673
2019-09-20 17:08:57.957 EDT [34474] sub1 DEBUG:  00000: renamed serialized snapshot
pg_logical/snapshots/0-15FA980.snap.34474.tmpto pg_logical/snapshots/0-15FA980.snap 
2019-09-20 17:08:57.957 EDT [34474] sub1 LOCATION:  SnapBuildSerialize, snapbuild.c:1673
2019-09-20 17:08:57.957 EDT [34474] sub1 DEBUG:  00000: fsynced pg_logical/snapshots/0-15FA980.snap
2019-09-20 17:08:57.957 EDT [34474] sub1 LOCATION:  SnapBuildSerialize, snapbuild.c:1679
2019-09-20 17:08:57.957 EDT [34493] sub2 PANIC:  58P01: could not open file "pg_logical/snapshots/0-15FA980.snap": No
suchfile or directory 
2019-09-20 17:08:57.957 EDT [34493] sub2 LOCATION:  fsync_fname_ext, fd.c:3376
2019-09-20 17:08:57.957 EDT [34474] sub1 DEBUG:  00000: failed to increase restart lsn: proposed 0/15FA980, after
0/15FA980,current candidate 0/15FA980, current after 0/15FA980, flushed up to 0/15FA980 
2019-09-20 17:08:57.957 EDT [34474] sub1 LOCATION:  LogicalIncreaseRestartDecodingForSlot, logical.c:992
2019-09-20 17:08:57.958 EDT [34537] sub3_16414_sync_16399 DEBUG:  00000: searching for logical decoding starting point,
startingat 0/15FA980 
2019-09-20 17:08:57.958 EDT [34537] sub3_16414_sync_16399 LOCATION:  DecodingContextFindStartpoint, logical.c:476
2019-09-20 17:08:57.958 EDT [34497] sub3 DEBUG:  00000: renamed serialized snapshot
pg_logical/snapshots/0-15FA980.snap.34497.tmpto pg_logical/snapshots/0-15FA980.snap 
2019-09-20 17:08:57.958 EDT [34497] sub3 LOCATION:  SnapBuildSerialize, snapbuild.c:1673
2019-09-20 17:08:57.958 EDT [34497] sub3 DEBUG:  00000: fsynced pg_logical/snapshots/0-15FA980.snap
2019-09-20 17:08:57.958 EDT [34497] sub3 LOCATION:  SnapBuildSerialize, snapbuild.c:1679
2019-09-20 17:08:57.958 EDT [34537] sub3_16414_sync_16399 LOG:  00000: logical decoding found consistent point at
0/15FA980
2019-09-20 17:08:57.958 EDT [34537] sub3_16414_sync_16399 DETAIL:  There are no running transactions.
2019-09-20 17:08:57.958 EDT [34537] sub3_16414_sync_16399 LOCATION:  SnapBuildFindSnapshot, snapbuild.c:1272
2019-09-20 17:08:57.958 EDT [34497] sub3 DEBUG:  00000: failed to increase restart lsn: proposed 0/15FA980, after
0/15FA980,current candidate 0/15FA980, current after 0/15FA980, flushed up to 0/15FA980 
2019-09-20 17:08:57.958 EDT [34497] sub3 LOCATION:  LogicalIncreaseRestartDecodingForSlot, logical.c:992
2019-09-20 17:08:57.958 EDT [34474] sub1 DEBUG:  00000: updated xmin: 0 restart: 1
2019-09-20 17:08:57.958 EDT [34474] sub1 LOCATION:  LogicalConfirmReceivedLocation, logical.c:1061
2019-09-20 17:08:57.958 EDT [34497] sub3 DEBUG:  00000: updated xmin: 0 restart: 1
2019-09-20 17:08:57.958 EDT [34497] sub3 LOCATION:  LogicalConfirmReceivedLocation, logical.c:1061
2019-09-20 17:08:57.958 EDT [34537] sub3_16414_sync_16399 LOG:  00000: statement: SELECT c.oid, c.relreplident  FROM
pg_catalog.pg_classc  INNER JOIN pg_catalog.pg_namespace n        ON (c.relnamespace = n.oid) WHERE n.nspname =
'public'  AND c.relname = 'tab4'   AND c.relkind = 'r' 
2019-09-20 17:08:57.958 EDT [34537] sub3_16414_sync_16399 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:57.962 EDT [34537] sub3_16414_sync_16399 LOG:  00000: statement: SELECT a.attname,       a.atttypid,
   a.atttypmod,       a.attnum = ANY(i.indkey)  FROM pg_catalog.pg_attribute a  LEFT JOIN pg_catalog.pg_index i
ON(i.indexrelid = pg_get_replica_identity_index(16399)) WHERE a.attnum > 0::pg_catalog.int2   AND NOT a.attisdropped
ANDa.attgenerated = ''   AND a.attrelid = 16399 ORDER BY a.attnum 
2019-09-20 17:08:57.962 EDT [34537] sub3_16414_sync_16399 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:57.966 EDT [34537] sub3_16414_sync_16399 LOG:  00000: statement: COPY public.tab4 TO STDOUT
2019-09-20 17:08:57.966 EDT [34537] sub3_16414_sync_16399 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:57.966 EDT [34540] sub2 LOG:  00000: received replication command: IDENTIFY_SYSTEM
2019-09-20 17:08:57.966 EDT [34540] sub2 LOCATION:  exec_replication_command, walsender.c:1487
2019-09-20 17:08:57.966 EDT [34537] sub3_16414_sync_16399 LOG:  00000: statement: COMMIT
2019-09-20 17:08:57.966 EDT [34537] sub3_16414_sync_16399 LOCATION:  exec_simple_query, postgres.c:1045
2019-09-20 17:08:57.966 EDT [34540] sub2 LOG:  00000: received replication command: START_REPLICATION SLOT "sub2"
LOGICAL0/0 (proto_version '1', publication_names '"pub2"') 
2019-09-20 17:08:57.966 EDT [34540] sub2 LOCATION:  exec_replication_command, walsender.c:1487
2019-09-20 17:08:57.966 EDT [34540] sub2 ERROR:  55006: replication slot "sub2" is active for PID 34493
2019-09-20 17:08:57.966 EDT [34540] sub2 LOCATION:  ReplicationSlotAcquire, slot.c:399
2019-09-20 17:08:57.977 EDT [34418] LOG:  00000: server process (PID 34493) was terminated by signal 6: Abort trap: 6
2019-09-20 17:08:57.977 EDT [34418] LOCATION:  LogChildExit, postmaster.c:3708
2019-09-20 17:08:57.977 EDT [34418] LOG:  00000: terminating any other active server processes
2019-09-20 17:08:57.977 EDT [34418] LOCATION:  HandleChildCrash, postmaster.c:3428
2019-09-20 17:08:57.977 EDT [34474] sub1 WARNING:  57P02: terminating connection because of crash of another server
process
2019-09-20 17:08:57.977 EDT [34474] sub1 DETAIL:  The postmaster has commanded this server process to roll back the
currenttransaction and exit, because another server process exited abnormally and possibly corrupted shared memory. 
2019-09-20 17:08:57.977 EDT [34474] sub1 HINT:  In a moment you should be able to reconnect to the database and repeat
yourcommand. 
2019-09-20 17:08:57.977 EDT [34474] sub1 LOCATION:  quickdie, postgres.c:2737
2019-09-20 17:08:57.977 EDT [34497] sub3 WARNING:  57P02: terminating connection because of crash of another server
process
2019-09-20 17:08:57.977 EDT [34497] sub3 DETAIL:  The postmaster has commanded this server process to roll back the
currenttransaction and exit, because another server process exited abnormally and possibly corrupted shared memory. 
2019-09-20 17:08:57.977 EDT [34497] sub3 HINT:  In a moment you should be able to reconnect to the database and repeat
yourcommand. 
2019-09-20 17:08:57.977 EDT [34497] sub3 LOCATION:  quickdie, postgres.c:2737
2019-09-20 17:08:57.978 EDT [34423] WARNING:  57P02: terminating connection because of crash of another server process
2019-09-20 17:08:57.978 EDT [34423] DETAIL:  The postmaster has commanded this server process to roll back the current
transactionand exit, because another server process exited abnormally and possibly corrupted shared memory. 
2019-09-20 17:08:57.978 EDT [34423] HINT:  In a moment you should be able to reconnect to the database and repeat your
command.
2019-09-20 17:08:57.978 EDT [34423] LOCATION:  quickdie, postgres.c:2737
2019-09-20 17:08:57.979 EDT [34418] LOG:  00000: database system is shut down
2019-09-20 17:08:57.979 EDT [34418] LOCATION:  UnlinkLockFiles, miscinit.c:860