Date: Fri, 20 Sep 2019 10:08:31 -0700
From: Andres Freund <andres@anarazel.de>
To: Kuntal Ghosh <kuntalghosh.2007@gmail.com>
Cc: Michael Paquier <michael@paquier.xyz>,
	Tomas Vondra <tomas.vondra@2ndquadrant.com>,
	Tom Lane <tgl@sss.pgh.pa.us>, Robert Haas <robertmhaas@gmail.com>,
	Thomas Munro <thomas.munro@enterprisedb.com>,
	PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>
Subject: Re: subscriptionCheck failures on nightjar
Message-ID: <20190920170831.aaljabal6lyivre5@alap3.anarazel.de>
References: <20190813080435.GL2551@paquier.xyz>
 <20190826132904.3ayuw36qzl2c4ktr@development>
 <CA+TgmoaNOMG9+Ho9d3CX+-10O7+nqqvmSpXb1m0F3dqWB4C-8g@mail.gmail.com>
 <7361.1568738373@sss.pgh.pa.us>
 <20190917194510.iqwyl3be62pz7l27@development>
 <20190918005815.GB8909@paquier.xyz>
 <CAGz5QCJv5JbRDsATDTkJqq7h9F7u0QLnNnLHfxR1nEOa4DnkJQ@mail.gmail.com>
 <20190918215808.yonxqgycme6pbctp@development>
 <20190919042305.GA21144@paquier.xyz>
 <CAGz5QC+5_mPFoDj7ZSMV0gwvMY+kdOp4t1w=TTDpzuV9F2-X6g@mail.gmail.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: 
 <CAGz5QC+5_mPFoDj7ZSMV0gwvMY+kdOp4t1w=TTDpzuV9F2-X6g@mail.gmail.com>
Precedence: bulk

Hi,

On 2019-09-19 17:20:15 +0530, Kuntal Ghosh wrote:
> It seems there is a pattern how the error is occurring in different
> systems. Following are the relevant log snippets:
> 
> nightjar:
> sub3 LOG:  received replication command: CREATE_REPLICATION_SLOT
> "sub3_16414_sync_16394" TEMPORARY LOGICAL pgoutput USE_SNAPSHOT
> sub3 LOG:  logical decoding found consistent point at 0/160B578
> sub1 PANIC:  could not open file
> "pg_logical/snapshots/0-160B578.snap": No such file or directory
> 
> dromedary scenario 1:
> sub3_16414_sync_16399 LOG:  received replication command:
> CREATE_REPLICATION_SLOT "sub3_16414_sync_16399" TEMPORARY LOGICAL
> pgoutput USE_SNAPSHOT
> sub3_16414_sync_16399 LOG:  logical decoding found consistent point at 0/15EA694
> sub2 PANIC:  could not open file
> "pg_logical/snapshots/0-15EA694.snap": No such file or directory
> 
> 
> dromedary scenario 2:
> sub3_16414_sync_16399 LOG:  received replication command:
> CREATE_REPLICATION_SLOT "sub3_16414_sync_16399" TEMPORARY LOGICAL
> pgoutput USE_SNAPSHOT
> sub3_16414_sync_16399 LOG:  logical decoding found consistent point at 0/15EA694
> sub1 PANIC:  could not open file
> "pg_logical/snapshots/0-15EA694.snap": No such file or directory
> 
> While subscription 3 is created, it eventually reaches to a consistent
> snapshot point and prints the WAL location corresponding to it. It
> seems sub1/sub2 immediately fails to serialize the snapshot to the
> .snap file having the same WAL location.

Since now a number of people (I tried as well), failed to reproduce this
locally, I propose that we increase the log-level during this test on
master. And perhaps expand the set of debugging information. With the
hope that the additional information on the cases encountered on the bf
helps us build a reproducer or, even better, diagnose the issue
directly.  If people agree, I'll come up with a patch.

Greetings,

Andres Freund