From: Tom Lane <tgl@sss.pgh.pa.us>
To: Thomas Munro <thomas.munro@gmail.com>
cc: Alexander Lakhin <exclusion@gmail.com>,
        Andrew Dunstan <andrew@dunslane.net>,
        pgsql-hackers <pgsql-hackers@postgresql.org>
Subject: Re: Why is src/test/modules/committs/t/002_standby.pl flaky?
In-reply-to: <CA+hUKG+o_QzN1LrEPGJLa6JiZU4DpLRybkwZjdCErs2qsB6axg@mail.gmail.com>
References: <CA+hUKG+OeoETZQ=Qw5Ub5h3tmwQhBmDA=nuNO3KG=zWfUypFAw@mail.gmail.com> <e4ddf83b-b399-aea4-498d-eb8e35e055e9@dunslane.net> <1600941.1641685316@sss.pgh.pa.us> <1609152.1641691036@sss.pgh.pa.us> <c20eb022-f576-0cc5-d796-91ffaf10a2ca@gmail.com> <CA+hUKGKwiqnkmuj6tJ6E+wBDDDhB3d6_Lzmm3O=ZhRb9P8ETAA@mail.gmail.com> <CA+hUKG+9kOBvurZoouprt0it=7XutQR17NMpfTeyYJNyc6V_5w@mail.gmail.com> <3b904d7b-ef84-6f1b-9326-9f88c1374eb8@gmail.com> <CA+hUKGKaq1Nv79sQptmDCgJc2tGUKogW-YxAyTyF1WvJerR0RQ@mail.gmail.com> <CA+hUKGKPpbC2EM2tSy5-1cfj+-1d2PVwLU4kBNg8E+og+B3fbg@mail.gmail.com> <5d507424-13ce-d19f-2f5d-ab4c6a987316@gmail.com> <CA+hUKG+o_QzN1LrEPGJLa6JiZU4DpLRybkwZjdCErs2qsB6axg@mail.gmail.com>
Comments: In-reply-to Thomas Munro <thomas.munro@gmail.com>
	message dated "Tue, 11 Jan 2022 09:52:01 +1300"
MIME-Version: 1.0
Content-Type: text/plain; charset="us-ascii"
Content-ID: <2411750.1641849927.1@sss.pgh.pa.us>
Content-Transfer-Encoding: quoted-printable
Date: Mon, 10 Jan 2022 16:25:27 -0500
Message-ID: <2411751.1641849927@sss.pgh.pa.us>
Archived-At: <https://www.postgresql.org/message-id/2411751.1641849927%40sss.pgh.pa.us>
Precedence: bulk

Thomas Munro <thomas.munro@gmail.com> writes:
> Hmm, one thing I'm still unclear on: did this problem really start
> with 6051857fc/ed52c3707?  My initial email in this thread lists
> similar failures going back further, doesn't it?  (And what's tern
> doing mixed up in this mess?)

Well, those earlier ones may be committs failures, but a lot of
them contain different-looking symptoms, eg pg_ctl failures.

tern's failure at
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Dtern&dt=3D2021-0=
7-17+10%3A57%3A49
does look similar, but we can see in its log that the standby
*did* notice the primary disconnection and then reconnect:

2021-07-17 16:29:08.248 UTC [17498380:2] LOG:  replication terminated by p=
rimary server
2021-07-17 16:29:08.248 UTC [17498380:3] DETAIL:  End of WAL reached on ti=
meline 1 at 0/30378F8.
2021-07-17 16:29:08.248 UTC [17498380:4] FATAL:  could not send end-of-str=
eaming message to primary: no COPY in progress
2021-07-17 16:29:08.248 UTC [25166230:5] LOG:  invalid record length at 0/=
30378F8: wanted 24, got 0
2021-07-17 16:29:08.350 UTC [16318578:1] FATAL:  could not connect to the =
primary server: server closed the connection unexpectedly
		This probably means the server terminated abnormally
		before or while processing the request.
2021-07-17 16:29:36.369 UTC [7077918:1] FATAL:  could not connect to the p=
rimary server: FATAL:  the database system is starting up
2021-07-17 16:29:36.380 UTC [11338028:1] FATAL:  could not connect to the =
primary server: FATAL:  the database system is starting up
...
2021-07-17 16:29:36.881 UTC [17367092:1] LOG:  started streaming WAL from =
primary at 0/3000000 on timeline 1

So I'm not sure what happened there, but it's not an instance
of this problem.  One thing that looks a bit suspicious is
this in the primary's log:

2021-07-17 16:26:47.832 UTC [12386550:1] LOG:  using stale statistics inst=
ead of current ones because stats collector is not responding

which makes me wonder if the timeout is down to out-of-date
pg_stats data.  The loop in 002_standby.pl doesn't appear to
depend on the stats collector:

my $primary_lsn =3D
  $primary->safe_psql('postgres', 'select pg_current_wal_lsn()');
$standby->poll_query_until('postgres',
	qq{SELECT '$primary_lsn'::pg_lsn <=3D pg_last_wal_replay_lsn()})
  or die "standby never caught up";

but maybe I'm missing the connection.

Apropos of that, it's worth noting that wait_for_catchup *is*
dependent on up-to-date stats, and here's a recent run where
it sure looks like the timeout cause is AWOL stats collector:

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Dsungazer&dt=3D20=
22-01-10%2004%3A51%3A34

I wonder if we should refactor wait_for_catchup to probe the
standby directly instead of relying on the upstream's view.

			regards, tom lane