Date: Mon, 23 Mar 2020 12:47:36 -0700
From: Andres Freund <andres@anarazel.de>
To: Peter Eisentraut <peter.eisentraut@2ndquadrant.com>
Cc: Kyotaro Horiguchi <horikyota.ntt@gmail.com>, michael@paquier.xyz,
	pgsql-hackers@lists.postgresql.org
Subject: Re: Make mesage at end-of-recovery less scary.
Message-ID: <20200323194736.uijmupfle2ccvyah@alap3.anarazel.de>
References: <20200228.160100.2210969269596489579.horikyota.ntt@gmail.com>
 <20200228073318.GD2688@paquier.xyz>
 <20200228.172806.1107809554616271723.horikyota.ntt@gmail.com>
 <20200305.160650.1027844943773682801.horikyota.ntt@gmail.com>
 <4a9fc5b1-34c8-46ec-9b71-d4763d70311d@2ndquadrant.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <4a9fc5b1-34c8-46ec-9b71-d4763d70311d@2ndquadrant.com>
Precedence: bulk

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?


> > | [20851] LOG:  reached end of WAL at 0/30001C8 on timeline 1 in archive during standby mode
> > | [20851] DETAIL:  invalid record length at 0/30001C8: wanted 24, got 0
> > 
> > I changed the above to the below, which looks more adequate.
> > 
> > | [24271]  LOG:  replication terminated by primary server on timeline 1 at 0/3000240.
> > | [24271]  FATAL:  could not send end-of-streaming message to primary: no COPY in progress
> > | [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?

Greetings,

Andres Freund