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 OID 1
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 REFERENCES tab3)
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" LOGICAL pgoutput 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" LOGICAL 0/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 REPEATABLE READ
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.tmp to
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, starting at 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_class c 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 AND a.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" LOGICAL pgoutput 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.tmp to
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" LOGICAL pgoutput 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.tmp to
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" LOGICAL 0/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 REPEATABLE READ
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.tmp to
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.tmp to
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, starting at 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_class c 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" LOGICAL 0/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 AND a.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 REPEATABLE READ
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.tmp to
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.tmp to
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, starting at 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.tmp to
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_class c 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 AND a.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 REPEATABLE READ
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.tmp to
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.tmp to
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 such file 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, starting at 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.tmp to
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_class c 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 AND a.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" LOGICAL 0/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 current transaction 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 your command.
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 current transaction 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 your command.
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 transaction and 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
