Re: subscriptionCheck failures on nightjar - Mailing list pgsql-hackers
| From | Tom Lane |
|---|---|
| Subject | Re: subscriptionCheck failures on nightjar |
| Date | |
| Msg-id | 2752.1569016266@sss.pgh.pa.us Whole thread Raw |
| In response to | Re: subscriptionCheck failures on nightjar (Tom Lane <tgl@sss.pgh.pa.us>) |
| List | pgsql-hackers |
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
pgsql-hackers by date: