Date: Tue, 24 Mar 2020 10:52:50 +0900 (JST)
Message-Id: <20200324.105250.1584846618506385212.horikyota.ntt@gmail.com>
To: andres@anarazel.de
Cc: peter.eisentraut@2ndquadrant.com, michael@paquier.xyz,
 pgsql-hackers@lists.postgresql.org
Subject: Re: Make mesage at end-of-recovery less scary.
From: Kyotaro Horiguchi <horikyota.ntt@gmail.com>
In-Reply-To: <20200323194736.uijmupfle2ccvyah@alap3.anarazel.de>
References: <20200305.160650.1027844943773682801.horikyota.ntt@gmail.com>
	<4a9fc5b1-34c8-46ec-9b71-d4763d70311d@2ndquadrant.com>
	<20200323194736.uijmupfle2ccvyah@alap3.anarazel.de>
User-Agent: Mew version 6.8 on Emacs 26.1
Mime-Version: 1.0
Content-Type: Multipart/Mixed;
 boundary="--Next_Part(Tue_Mar_24_10_52_50_2020_211)--"
Content-Transfer-Encoding: 7bit
Precedence: bulk

----Next_Part(Tue_Mar_24_10_52_50_2020_211)--
Content-Type: Text/Plain; charset=us-ascii
Content-Transfer-Encoding: 7bit

At Mon, 23 Mar 2020 12:47:36 -0700, Andres Freund <andres@anarazel.de> wrote in 
> Hi,
> 
> On 2020-03-23 10:37:16 +0100, Peter Eisentraut wrote:
> > On 2020-03-05 08:06, Kyotaro Horiguchi wrote:
> > > | [20866] LOG:  replication terminated by primary server
> > > | [20866] DETAIL:  End of WAL reached on timeline 1 at 0/30001C8.
> > > | [20866] FATAL:  could not send end-of-streaming message to primary: no COPY in progress
> 
> IMO it's a bug that we see this FATAL. I seem to recall that we didn't
> use to get that?

I thought that it is a convention that A auxiliary process uses ERROR
(which is turned into FATAL in ereport) to exit, which I didn't like
so much, but it was out of scope of this patch.

As for the message bove, the FATAL is preceded by the "LOG:
replication terminated by" message, that means walreceiver tries to
send new data after disconnection just to fail, which is
unreasonable. I think we should exit immediately after detecting
disconnection. The FATAL is gone by the attached.

> > > | [24267]  LOG:  reached end of WAL at 0/3000240 on timeline 1 in archive during standby mode
> > > | [24267]  DETAIL:  invalid record length at 0/3000240: wanted 24, got 0
> > 
> > Is this the before and after?  That doesn't seem like a substantial
> > improvement to me.  You still get the "scary" message at the end.
> 
> It seems like a minor improvement - folding the DETAIL into the message
> makes sense to me here. But it indeed doesn't really address the main
> issue.
> 
> I think we don't want to elide the information about how the end of the
> WAL was detected - there are some issues where I found that quite
> helpful. But we could reformulate it to be clearer that it's informative
> output, not a bug.  E.g. something roughly like
> 
> LOG:  reached end of WAL at 0/3000240 on timeline 1 in archive during standby mode
> DETAIL: End detected due to invalid record length at 0/3000240: expected 24, got 0
> (I first elided the position in the DETAIL, but it could differ from the
> one in LOG)
> 
> I don't find that very satisfying, but I can't come up with something
> that provides the current information, while being less scary than my
> suggestion?

The 0-length record is not an "invalid" state during recovery, so we
can add the message for the state as "record length is 0 at %X/%X". I
think if other states found there, it implies something wrong.

LSN is redundantly shown but I'm not sure if it is better to remove it
from either of the two lines.

| LOG:  reached end of WAL at 0/3000850 on timeline 1 in pg_wal during crash recovery
| DETAIL:  record length is 0 at 0/3000850

regards.

-- 
Kyotaro Horiguchi
NTT Open Source Software Center

----Next_Part(Tue_Mar_24_10_52_50_2020_211)--
Content-Type: Text/X-Patch; charset=us-ascii
Content-Transfer-Encoding: 7bit
Content-Disposition: inline;
 filename="v3-0001-Make-End-Of-Recovery-error-less-scary.patch"