Received: from malur.postgresql.org ([217.196.149.56]) by arkaria.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1iBQoC-0003yR-7F for pgsql-hackers@arkaria.postgresql.org; Fri, 20 Sep 2019 21:51:20 +0000 Received: from localhost ([127.0.0.1] helo=malur.postgresql.org) by malur.postgresql.org with esmtp (Exim 4.89) (envelope-from ) id 1iBQoA-0000rS-Ub for pgsql-hackers@arkaria.postgresql.org; Fri, 20 Sep 2019 21:51:18 +0000 Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29]) by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1iBQoA-0000rI-JH for pgsql-hackers@lists.postgresql.org; Fri, 20 Sep 2019 21:51:18 +0000 Received: from sss.pgh.pa.us ([66.207.139.130]) by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA1:256) (Exim 4.89) (envelope-from ) id 1iBQo6-0003b4-NJ for pgsql-hackers@lists.postgresql.org; Fri, 20 Sep 2019 21:51:18 +0000 Received: from sss1.sss.pgh.pa.us (localhost [127.0.0.1]) by sss.pgh.pa.us (8.14.4/8.14.4) with ESMTP id x8KLp6sF002753; Fri, 20 Sep 2019 17:51:06 -0400 From: Tom Lane To: Andres Freund cc: Andrew Dunstan , Kuntal Ghosh , Michael Paquier , Tomas Vondra , Robert Haas , Thomas Munro , PostgreSQL Hackers Subject: Re: subscriptionCheck failures on nightjar In-reply-to: <2636.1569016167@sss.pgh.pa.us> References: <7361.1568738373@sss.pgh.pa.us> <20190917194510.iqwyl3be62pz7l27@development> <20190918005815.GB8909@paquier.xyz> <20190918215808.yonxqgycme6pbctp@development> <20190919042305.GA21144@paquier.xyz> <20190920170831.aaljabal6lyivre5@alap3.anarazel.de> <29511.1569011121@sss.pgh.pa.us> <20190920212603.7zlgrlwtdirbmuw7@alap3.anarazel.de> <2636.1569016167@sss.pgh.pa.us> Comments: In-reply-to Tom Lane message dated "Fri, 20 Sep 2019 17:49:27 -0400" MIME-Version: 1.0 Content-Type: multipart/mixed; boundary="----- =_aaaaaaaaaa0" Content-ID: <2729.1569016245.0@sss.pgh.pa.us> Date: Fri, 20 Sep 2019 17:51:06 -0400 Message-ID: <2752.1569016266@sss.pgh.pa.us> List-Id: List-Help: List-Subscribe: List-Post: List-Owner: List-Archive: Precedence: bulk ------- =_aaaaaaaaaa0 Content-Type: text/plain; charset="us-ascii" Content-ID: <2729.1569016245.1@sss.pgh.pa.us> Sigh, forgot about attaching the attachments ... regards, tom lane ------- =_aaaaaaaaaa0 Content-Type: text/x-diff; name="more-logging.patch"; charset="us-ascii" Content-ID: <2729.1569016245.2@sss.pgh.pa.us> Content-Description: more-logging.patch Content-Transfer-Encoding: quoted-printable diff --git a/src/backend/replication/logical/snapbuild.c b/src/backend/rep= lication/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 th= is * as a serialization point. diff --git a/src/test/subscription/t/010_truncate.pl b/src/test/subscripti= on/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 =3D> 9; = my $node_publisher =3D get_new_node('publisher'); $node_publisher->init(allows_streaming =3D> 'logical'); +$node_publisher->append_conf('postgresql.conf', q{ +log_checkpoints =3D on +log_min_messages =3D 'debug1' +log_error_verbosity =3D verbose +}); $node_publisher->start; = my $node_subscriber =3D get_new_node('subscriber'); ------- =_aaaaaaaaaa0 Content-Type: text/plain; name="010_truncate_publisher.log"; charset="us-ascii" Content-ID: <2729.1569016245.3@sss.pgh.pa.us> Content-Description: 010_truncate_publisher.log Content-Transfer-Encoding: quoted-printable 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, b= gworker.c:855 2019-09-20 17:08:54.362 EDT [34418] LOG: 00000: starting PostgreSQL 13dev= el on x86_64-unknown-freebsd9.0, compiled by gcc (GCC) 4.2.1 20070831 patc= hed [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/15D= 07F0; 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: 49= 0; 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; ne= xt 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 transac= tion 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 ol= dest/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 lim= it is 2147484130, limited by database with OID 1 2019-09-20 17:08:54.363 EDT [34419] LOCATION: SetTransactionIdLimit, vars= up.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, multix= act.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, sl= ot.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, multix= act.c:2271 2019-09-20 17:08:54.363 EDT [34419] DEBUG: 00000: MultiXact member stop l= imit is now 4294914944 based on MultiXact 1 2019-09-20 17:08:54.363 EDT [34419] LOCATION: SetOffsetVacuumLimit, multi= xact.c:2634 2019-09-20 17:08:54.364 EDT [34418] DEBUG: 00000: starting background wor= ker process "logical replication launcher" 2019-09-20 17:08:54.364 EDT [34418] LOCATION: do_start_bgworker, postmast= er.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 sta= rted 2019-09-20 17:08:54.365 EDT [34423] LOCATION: AutoVacLauncherMain, autova= cuum.c:441 2019-09-20 17:08:54.365 EDT [34425] DEBUG: 00000: logical replication lau= ncher 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: buildin= g 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: buildin= g 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: buildin= g 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: buildin= g 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 =3D 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 DI= STINCT 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, pos= tgres.c:1045 2019-09-20 17:08:55.392 EDT [34471] sub1 LOG: 00000: received replication= command: CREATE_REPLICATION_SLOT "sub1" LOGICAL pgoutput NOEXPORT_SNAPSHO= T 2019-09-20 17:08:55.392 EDT [34471] sub1 LOCATION: exec_replication_comma= nd, walsender.c:1487 2019-09-20 17:08:55.392 EDT [34471] sub1 DEBUG: 00000: searching for logi= cal decoding starting point, starting at 0/15FA830 2019-09-20 17:08:55.392 EDT [34471] sub1 LOCATION: DecodingContextFindSta= rtpoint, logical.c:476 2019-09-20 17:08:55.392 EDT [34471] sub1 LOG: 00000: logical decoding fou= nd consistent point at 0/15FA830 2019-09-20 17:08:55.392 EDT [34471] sub1 DETAIL: There are no running tra= nsactions. 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_comma= nd, 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', pu= blication_names '"pub1"') 2019-09-20 17:08:55.397 EDT [34474] sub1 LOCATION: exec_replication_comma= nd, walsender.c:1487 2019-09-20 17:08:55.397 EDT [34474] sub1 LOG: 00000: starting logical dec= oding for slot "sub1" 2019-09-20 17:08:55.397 EDT [34474] sub1 DETAIL: Streaming transactions c= ommitting 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 fou= nd consistent point at 0/15FA830 2019-09-20 17:08:55.397 EDT [34474] sub1 DETAIL: There are no running tra= nsactions. 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 cau= ght 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 DI= STINCT 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, pos= tgres.c:1045 2019-09-20 17:08:55.401 EDT [34478] sub1_16412_sync_16384 LOG: 00000: sta= tement: 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: rec= eived 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 snapsh= ot to pg_logical/snapshots/0-15FA868.snap 2019-09-20 17:08:55.402 EDT [34474] sub1 LOCATION: SnapBuildSerialize, sn= apbuild.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/snap= shots/0-15FA868.snap 2019-09-20 17:08:55.402 EDT [34474] sub1 LOCATION: SnapBuildSerialize, sn= apbuild.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, sn= apbuild.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/15F= A868, current after 0/15FA868, flushed up to 0/15FA868 2019-09-20 17:08:55.402 EDT [34474] sub1 LOCATION: LogicalIncreaseRestart= DecodingForSlot, logical.c:992 2019-09-20 17:08:55.402 EDT [34474] sub1 DEBUG: 00000: updated xmin: 0 re= start: 1 2019-09-20 17:08:55.402 EDT [34474] sub1 LOCATION: LogicalConfirmReceived= Location, logical.c:1061 2019-09-20 17:08:55.402 EDT [34478] sub1_16412_sync_16384 DEBUG: 00000: s= earching for logical decoding starting point, starting at 0/15FA868 2019-09-20 17:08:55.402 EDT [34478] sub1_16412_sync_16384 LOCATION: Decod= ingContextFindStartpoint, logical.c:476 2019-09-20 17:08:55.402 EDT [34478] sub1_16412_sync_16384 LOG: 00000: log= ical decoding found consistent point at 0/15FA868 2019-09-20 17:08:55.402 EDT [34478] sub1_16412_sync_16384 DETAIL: There a= re no running transactions. 2019-09-20 17:08:55.402 EDT [34478] sub1_16412_sync_16384 LOCATION: SnapB= uildFindSnapshot, snapbuild.c:1272 2019-09-20 17:08:55.402 EDT [34478] sub1_16412_sync_16384 LOG: 00000: sta= tement: SELECT c.oid, c.relreplident FROM pg_catalog.pg_class c INNER JO= IN pg_catalog.pg_namespace n ON (c.relnamespace =3D n.oid) WHERE n.= nspname =3D 'public' AND c.relname =3D 'tab1' AND c.relkind =3D '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: sta= tement: SELECT a.attname, a.atttypid, a.atttypmod, a.att= num =3D ANY(i.indkey) FROM pg_catalog.pg_attribute a LEFT JOIN pg_catalo= g.pg_index i ON (i.indexrelid =3D pg_get_replica_identity_index(1638= 4)) WHERE a.attnum > 0::pg_catalog.int2 AND NOT a.attisdropped AND a.att= generated =3D '' AND a.attrelid =3D 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_SNAPSHO= T 2019-09-20 17:08:55.403 EDT [34477] sub2 LOCATION: exec_replication_comma= nd, walsender.c:1487 2019-09-20 17:08:55.403 EDT [34474] sub1 DEBUG: 00000: serializing snapsh= ot to pg_logical/snapshots/0-15FA8A0.snap 2019-09-20 17:08:55.403 EDT [34474] sub1 LOCATION: SnapBuildSerialize, sn= apbuild.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/snap= shots/0-15FA8A0.snap 2019-09-20 17:08:55.403 EDT [34474] sub1 LOCATION: SnapBuildSerialize, sn= apbuild.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, sn= apbuild.c:1679 2019-09-20 17:08:55.404 EDT [34474] sub1 DEBUG: 00000: got new restart ls= n 0/15FA8A0 at 0/15FA8A0 2019-09-20 17:08:55.404 EDT [34474] sub1 LOCATION: LogicalIncreaseRestart= DecodingForSlot, logical.c:979 2019-09-20 17:08:55.404 EDT [34477] sub2 DEBUG: 00000: searching for logi= cal decoding starting point, starting at 0/15FA8A0 2019-09-20 17:08:55.404 EDT [34477] sub2 LOCATION: DecodingContextFindSta= rtpoint, logical.c:476 2019-09-20 17:08:55.404 EDT [34477] sub2 LOG: 00000: logical decoding fou= nd consistent point at 0/15FA8A0 2019-09-20 17:08:55.404 EDT [34477] sub2 DETAIL: There are no running tra= nsactions. 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: sta= tement: 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: sta= tement: 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 re= start: 1 2019-09-20 17:08:55.406 EDT [34474] sub1 LOCATION: LogicalConfirmReceived= Location, logical.c:1061 2019-09-20 17:08:55.411 EDT [34481] sub3 LOG: 00000: statement: SELECT DI= STINCT 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, pos= tgres.c:1045 2019-09-20 17:08:55.414 EDT [34481] sub3 LOG: 00000: received replication= command: CREATE_REPLICATION_SLOT "sub3" LOGICAL pgoutput NOEXPORT_SNAPSHO= T 2019-09-20 17:08:55.414 EDT [34481] sub3 LOCATION: exec_replication_comma= nd, walsender.c:1487 2019-09-20 17:08:55.414 EDT [34474] sub1 DEBUG: 00000: serializing snapsh= ot to pg_logical/snapshots/0-15FA8D8.snap 2019-09-20 17:08:55.414 EDT [34474] sub1 LOCATION: SnapBuildSerialize, sn= apbuild.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/snap= shots/0-15FA8D8.snap 2019-09-20 17:08:55.414 EDT [34474] sub1 LOCATION: SnapBuildSerialize, sn= apbuild.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, sn= apbuild.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/15F= A8D8, current after 0/15FA8D8, flushed up to 0/15FA8D8 2019-09-20 17:08:55.414 EDT [34474] sub1 LOCATION: LogicalIncreaseRestart= DecodingForSlot, logical.c:992 2019-09-20 17:08:55.414 EDT [34481] sub3 DEBUG: 00000: searching for logi= cal decoding starting point, starting at 0/15FA8D8 2019-09-20 17:08:55.414 EDT [34481] sub3 LOCATION: DecodingContextFindSta= rtpoint, logical.c:476 2019-09-20 17:08:55.414 EDT [34474] sub1 DEBUG: 00000: updated xmin: 0 re= start: 1 2019-09-20 17:08:55.414 EDT [34474] sub1 LOCATION: LogicalConfirmReceived= Location, logical.c:1061 2019-09-20 17:08:55.414 EDT [34481] sub3 LOG: 00000: logical decoding fou= nd consistent point at 0/15FA8D8 2019-09-20 17:08:55.414 EDT [34481] sub3 DETAIL: There are no running tra= nsactions. 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_comma= nd, 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', pu= blication_names '"pub2"') 2019-09-20 17:08:55.925 EDT [34493] sub2 LOCATION: exec_replication_comma= nd, walsender.c:1487 2019-09-20 17:08:55.925 EDT [34493] sub2 LOG: 00000: starting logical dec= oding for slot "sub2" 2019-09-20 17:08:55.925 EDT [34493] sub2 DETAIL: Streaming transactions c= ommitting 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 fou= nd consistent point at 0/15FA8A0 2019-09-20 17:08:55.925 EDT [34493] sub2 DETAIL: There are no running tra= nsactions. 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/15F= A8D8, current after 0/15FA8D8, flushed up to 0/15FA8D8 2019-09-20 17:08:55.925 EDT [34493] sub2 LOCATION: LogicalIncreaseRestart= DecodingForSlot, logical.c:992 2019-09-20 17:08:55.925 EDT [34493] sub2 DEBUG: 00000: updated xmin: 0 re= start: 1 2019-09-20 17:08:55.925 EDT [34493] sub2 LOCATION: LogicalConfirmReceived= Location, logical.c:1061 2019-09-20 17:08:55.925 EDT [34493] sub2 DEBUG: 00000: "sub2" has now cau= ght 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: sta= tement: 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: rec= eived 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 snapsh= ot to pg_logical/snapshots/0-15FA910.snap 2019-09-20 17:08:55.930 EDT [34474] sub1 LOCATION: SnapBuildSerialize, sn= apbuild.c:1554 2019-09-20 17:08:55.930 EDT [34493] sub2 DEBUG: 00000: serializing snapsh= ot to pg_logical/snapshots/0-15FA910.snap 2019-09-20 17:08:55.930 EDT [34493] sub2 LOCATION: SnapBuildSerialize, sn= apbuild.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/snap= shots/0-15FA910.snap 2019-09-20 17:08:55.930 EDT [34474] sub1 LOCATION: SnapBuildSerialize, sn= apbuild.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/snap= shots/0-15FA910.snap 2019-09-20 17:08:55.930 EDT [34493] sub2 LOCATION: SnapBuildSerialize, sn= apbuild.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, sn= apbuild.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/15F= A910, current after 0/15FA910, flushed up to 0/15FA910 2019-09-20 17:08:55.930 EDT [34474] sub1 LOCATION: LogicalIncreaseRestart= DecodingForSlot, 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, sn= apbuild.c:1679 2019-09-20 17:08:55.930 EDT [34493] sub2 DEBUG: 00000: got new restart ls= n 0/15FA910 at 0/15FA910 2019-09-20 17:08:55.930 EDT [34493] sub2 LOCATION: LogicalIncreaseRestart= DecodingForSlot, logical.c:979 2019-09-20 17:08:55.930 EDT [34495] sub2_16413_sync_16389 DEBUG: 00000: s= earching for logical decoding starting point, starting at 0/15FA910 2019-09-20 17:08:55.930 EDT [34495] sub2_16413_sync_16389 LOCATION: Decod= ingContextFindStartpoint, logical.c:476 2019-09-20 17:08:55.930 EDT [34474] sub1 DEBUG: 00000: updated xmin: 0 re= start: 1 2019-09-20 17:08:55.930 EDT [34474] sub1 LOCATION: LogicalConfirmReceived= Location, logical.c:1061 2019-09-20 17:08:55.930 EDT [34495] sub2_16413_sync_16389 LOG: 00000: log= ical decoding found consistent point at 0/15FA910 2019-09-20 17:08:55.930 EDT [34495] sub2_16413_sync_16389 DETAIL: There a= re no running transactions. 2019-09-20 17:08:55.930 EDT [34495] sub2_16413_sync_16389 LOCATION: SnapB= uildFindSnapshot, snapbuild.c:1272 2019-09-20 17:08:55.930 EDT [34495] sub2_16413_sync_16389 LOG: 00000: sta= tement: SELECT c.oid, c.relreplident FROM pg_catalog.pg_class c INNER JO= IN pg_catalog.pg_namespace n ON (c.relnamespace =3D n.oid) WHERE n.= nspname =3D 'public' AND c.relname =3D 'tab2' AND c.relkind =3D '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_comma= nd, 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', pu= blication_names '"pub3"') 2019-09-20 17:08:55.931 EDT [34497] sub3 LOCATION: exec_replication_comma= nd, walsender.c:1487 2019-09-20 17:08:55.931 EDT [34497] sub3 LOG: 00000: starting logical dec= oding for slot "sub3" 2019-09-20 17:08:55.931 EDT [34497] sub3 DETAIL: Streaming transactions c= ommitting 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 fou= nd consistent point at 0/15FA8D8 2019-09-20 17:08:55.931 EDT [34497] sub3 DETAIL: There are no running tra= nsactions. 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/15F= A910, current after 0/15FA910, flushed up to 0/15FA910 2019-09-20 17:08:55.931 EDT [34497] sub3 LOCATION: LogicalIncreaseRestart= DecodingForSlot, logical.c:992 2019-09-20 17:08:55.931 EDT [34497] sub3 DEBUG: 00000: updated xmin: 0 re= start: 1 2019-09-20 17:08:55.931 EDT [34497] sub3 LOCATION: LogicalConfirmReceived= Location, logical.c:1061 2019-09-20 17:08:55.931 EDT [34497] sub3 DEBUG: 00000: "sub3" has now cau= ght 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: sta= tement: SELECT a.attname, a.atttypid, a.atttypmod, a.att= num =3D ANY(i.indkey) FROM pg_catalog.pg_attribute a LEFT JOIN pg_catalo= g.pg_index i ON (i.indexrelid =3D pg_get_replica_identity_index(1638= 9)) WHERE a.attnum > 0::pg_catalog.int2 AND NOT a.attisdropped AND a.att= generated =3D '' AND a.attrelid =3D 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: sta= tement: 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: sta= tement: 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 re= start: 1 2019-09-20 17:08:55.934 EDT [34493] sub2 LOCATION: LogicalConfirmReceived= Location, logical.c:1061 2019-09-20 17:08:56.941 EDT [34517] sub3_16414_sync_16394 LOG: 00000: sta= tement: 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: rec= eived 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 snapsh= ot to pg_logical/snapshots/0-15FA948.snap 2019-09-20 17:08:56.942 EDT [34474] sub1 LOCATION: SnapBuildSerialize, sn= apbuild.c:1554 2019-09-20 17:08:56.942 EDT [34493] sub2 DEBUG: 00000: serializing snapsh= ot to pg_logical/snapshots/0-15FA948.snap 2019-09-20 17:08:56.942 EDT [34493] sub2 LOCATION: SnapBuildSerialize, sn= apbuild.c:1554 2019-09-20 17:08:56.942 EDT [34497] sub3 DEBUG: 00000: serializing snapsh= ot to pg_logical/snapshots/0-15FA948.snap 2019-09-20 17:08:56.942 EDT [34497] sub3 LOCATION: SnapBuildSerialize, sn= apbuild.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/snap= shots/0-15FA948.snap 2019-09-20 17:08:56.942 EDT [34474] sub1 LOCATION: SnapBuildSerialize, sn= apbuild.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, sn= apbuild.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/15F= A948, current after 0/15FA948, flushed up to 0/15FA948 2019-09-20 17:08:56.942 EDT [34474] sub1 LOCATION: LogicalIncreaseRestart= DecodingForSlot, 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/snap= shots/0-15FA948.snap 2019-09-20 17:08:56.942 EDT [34493] sub2 LOCATION: SnapBuildSerialize, sn= apbuild.c:1673 2019-09-20 17:08:56.942 EDT [34517] sub3_16414_sync_16394 DEBUG: 00000: s= earching for logical decoding starting point, starting at 0/15FA948 2019-09-20 17:08:56.942 EDT [34517] sub3_16414_sync_16394 LOCATION: Decod= ingContextFindStartpoint, 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, sn= apbuild.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/snap= shots/0-15FA948.snap 2019-09-20 17:08:56.942 EDT [34497] sub3 LOCATION: SnapBuildSerialize, sn= apbuild.c:1673 2019-09-20 17:08:56.942 EDT [34474] sub1 DEBUG: 00000: updated xmin: 0 re= start: 1 2019-09-20 17:08:56.942 EDT [34474] sub1 LOCATION: LogicalConfirmReceived= Location, 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/15F= A948, current after 0/15FA948, flushed up to 0/15FA948 2019-09-20 17:08:56.942 EDT [34493] sub2 LOCATION: LogicalIncreaseRestart= DecodingForSlot, logical.c:992 2019-09-20 17:08:56.942 EDT [34517] sub3_16414_sync_16394 LOG: 00000: log= ical decoding found consistent point at 0/15FA948 2019-09-20 17:08:56.942 EDT [34517] sub3_16414_sync_16394 DETAIL: There a= re no running transactions. 2019-09-20 17:08:56.942 EDT [34517] sub3_16414_sync_16394 LOCATION: SnapB= uildFindSnapshot, 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, sn= apbuild.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/15F= A948, current after 0/15FA948, flushed up to 0/15FA948 2019-09-20 17:08:56.942 EDT [34497] sub3 LOCATION: LogicalIncreaseRestart= DecodingForSlot, logical.c:992 2019-09-20 17:08:56.942 EDT [34493] sub2 DEBUG: 00000: updated xmin: 0 re= start: 1 2019-09-20 17:08:56.942 EDT [34493] sub2 LOCATION: LogicalConfirmReceived= Location, logical.c:1061 2019-09-20 17:08:56.942 EDT [34497] sub3 DEBUG: 00000: updated xmin: 0 re= start: 1 2019-09-20 17:08:56.942 EDT [34497] sub3 LOCATION: LogicalConfirmReceived= Location, logical.c:1061 2019-09-20 17:08:56.942 EDT [34517] sub3_16414_sync_16394 LOG: 00000: sta= tement: SELECT c.oid, c.relreplident FROM pg_catalog.pg_class c INNER JO= IN pg_catalog.pg_namespace n ON (c.relnamespace =3D n.oid) WHERE n.= nspname =3D 'public' AND c.relname =3D 'tab3' AND c.relkind =3D '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: sta= tement: SELECT a.attname, a.atttypid, a.atttypmod, a.att= num =3D ANY(i.indkey) FROM pg_catalog.pg_attribute a LEFT JOIN pg_catalo= g.pg_index i ON (i.indexrelid =3D pg_get_replica_identity_index(1639= 4)) WHERE a.attnum > 0::pg_catalog.int2 AND NOT a.attisdropped AND a.att= generated =3D '' AND a.attrelid =3D 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: sta= tement: 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: sta= tement: 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: sta= tement: 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: rec= eived 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 snapsh= ot to pg_logical/snapshots/0-15FA980.snap 2019-09-20 17:08:57.957 EDT [34493] sub2 LOCATION: SnapBuildSerialize, sn= apbuild.c:1554 2019-09-20 17:08:57.957 EDT [34474] sub1 DEBUG: 00000: serializing snapsh= ot to pg_logical/snapshots/0-15FA980.snap 2019-09-20 17:08:57.957 EDT [34474] sub1 LOCATION: SnapBuildSerialize, sn= apbuild.c:1554 2019-09-20 17:08:57.957 EDT [34497] sub3 DEBUG: 00000: serializing snapsh= ot to pg_logical/snapshots/0-15FA980.snap 2019-09-20 17:08:57.957 EDT [34497] sub3 LOCATION: SnapBuildSerialize, sn= apbuild.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/snap= shots/0-15FA980.snap 2019-09-20 17:08:57.957 EDT [34493] sub2 LOCATION: SnapBuildSerialize, sn= apbuild.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/snap= shots/0-15FA980.snap 2019-09-20 17:08:57.957 EDT [34474] sub1 LOCATION: SnapBuildSerialize, sn= apbuild.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, sn= apbuild.c:1679 2019-09-20 17:08:57.957 EDT [34493] sub2 PANIC: 58P01: could not open fil= e "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/15F= A980, current after 0/15FA980, flushed up to 0/15FA980 2019-09-20 17:08:57.957 EDT [34474] sub1 LOCATION: LogicalIncreaseRestart= DecodingForSlot, logical.c:992 2019-09-20 17:08:57.958 EDT [34537] sub3_16414_sync_16399 DEBUG: 00000: s= earching for logical decoding starting point, starting at 0/15FA980 2019-09-20 17:08:57.958 EDT [34537] sub3_16414_sync_16399 LOCATION: Decod= ingContextFindStartpoint, 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/snap= shots/0-15FA980.snap 2019-09-20 17:08:57.958 EDT [34497] sub3 LOCATION: SnapBuildSerialize, sn= apbuild.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, sn= apbuild.c:1679 2019-09-20 17:08:57.958 EDT [34537] sub3_16414_sync_16399 LOG: 00000: log= ical decoding found consistent point at 0/15FA980 2019-09-20 17:08:57.958 EDT [34537] sub3_16414_sync_16399 DETAIL: There a= re no running transactions. 2019-09-20 17:08:57.958 EDT [34537] sub3_16414_sync_16399 LOCATION: SnapB= uildFindSnapshot, 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/15F= A980, current after 0/15FA980, flushed up to 0/15FA980 2019-09-20 17:08:57.958 EDT [34497] sub3 LOCATION: LogicalIncreaseRestart= DecodingForSlot, logical.c:992 2019-09-20 17:08:57.958 EDT [34474] sub1 DEBUG: 00000: updated xmin: 0 re= start: 1 2019-09-20 17:08:57.958 EDT [34474] sub1 LOCATION: LogicalConfirmReceived= Location, logical.c:1061 2019-09-20 17:08:57.958 EDT [34497] sub3 DEBUG: 00000: updated xmin: 0 re= start: 1 2019-09-20 17:08:57.958 EDT [34497] sub3 LOCATION: LogicalConfirmReceived= Location, logical.c:1061 2019-09-20 17:08:57.958 EDT [34537] sub3_16414_sync_16399 LOG: 00000: sta= tement: SELECT c.oid, c.relreplident FROM pg_catalog.pg_class c INNER JO= IN pg_catalog.pg_namespace n ON (c.relnamespace =3D n.oid) WHERE n.= nspname =3D 'public' AND c.relname =3D 'tab4' AND c.relkind =3D '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: sta= tement: SELECT a.attname, a.atttypid, a.atttypmod, a.att= num =3D ANY(i.indkey) FROM pg_catalog.pg_attribute a LEFT JOIN pg_catalo= g.pg_index i ON (i.indexrelid =3D pg_get_replica_identity_index(1639= 9)) WHERE a.attnum > 0::pg_catalog.int2 AND NOT a.attisdropped AND a.att= generated =3D '' AND a.attrelid =3D 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: sta= tement: 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_comma= nd, walsender.c:1487 2019-09-20 17:08:57.966 EDT [34537] sub3_16414_sync_16399 LOG: 00000: sta= tement: 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', pu= blication_names '"pub2"') 2019-09-20 17:08:57.966 EDT [34540] sub2 LOCATION: exec_replication_comma= nd, 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 act= ive server processes 2019-09-20 17:08:57.977 EDT [34418] LOCATION: HandleChildCrash, postmaste= r.c:3428 2019-09-20 17:08:57.977 EDT [34474] sub1 WARNING: 57P02: terminating conn= ection because of crash of another server process 2019-09-20 17:08:57.977 EDT [34474] sub1 DETAIL: The postmaster has comma= nded this server process to roll back the current transaction and exit, be= cause another server process exited abnormally and possibly corrupted shar= ed 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:2= 737 2019-09-20 17:08:57.977 EDT [34497] sub3 WARNING: 57P02: terminating conn= ection because of crash of another server process 2019-09-20 17:08:57.977 EDT [34497] sub3 DETAIL: The postmaster has comma= nded this server process to roll back the current transaction and exit, be= cause another server process exited abnormally and possibly corrupted shar= ed 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:2= 737 2019-09-20 17:08:57.978 EDT [34423] WARNING: 57P02: terminating connectio= n 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 me= mory. 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 d= own 2019-09-20 17:08:57.979 EDT [34418] LOCATION: UnlinkLockFiles, miscinit.c= :860 ------- =_aaaaaaaaaa0--