Thread: Race conditions with TAP test for syncrep

Hi all,

Alvaro has reported a rather rare buildfarm failure involving
007_sync_rep.pl to which I have responded here:
https://www.postgresql.org/message-id/20190613060123.GC1643@paquier.xyz

The buildfarm failure is here:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=chipmunk&dt=2019-05-12%2020%3A37%3A11

It involves a race condition related to the way the standbys of the
test are stopped and restarted to ensure that they appear in the
correct order in the WAL sender array of the primary, but feel free to
look at the message above for all the details.

Attached is a patch to improve the stability of the test.  The fix I
am proposing is very simple: in order to make sure that a standby is
added into the WAL sender array of the primary, let's check after
pg_stat_replication after a standby is started.  This can be done
consistently with a small wrapper in the tests.

Any thoughts?
--
Michael

On 2019-Jun-17, Michael Paquier wrote:

> Attached is a patch to improve the stability of the test.  The fix I
> am proposing is very simple: in order to make sure that a standby is
> added into the WAL sender array of the primary, let's check after
> pg_stat_replication after a standby is started.  This can be done
> consistently with a small wrapper in the tests.
> 
> Any thoughts?

Hmm, this introduces a bit of latency: it waits for each standby to be
fully up before initializing the next standby.  Maybe it would be more
convenient to split the primitives: keep the current one to start the
standby, and add a separate one to wait for it to be registered.  Then
we could do
standby1->start;
standby2->start;
standby3->start;
foreach my $sby (@standbys) {
    $sby->wait_for_standby
}

so they all start in parallel, saving a bit of time.

> +    print "### Waiting for standby \"$standby_name\" on \"$master_name\"\n";

I think this should be note() rather than print(), or maybe diag().  (I
see that we have a couple of other cases which use print() in the tap
tests, which I think should be note() as well.)

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On Mon, Jun 17, 2019 at 10:50:39AM -0400, Alvaro Herrera wrote:
> Hmm, this introduces a bit of latency: it waits for each standby to be
> fully up before initializing the next standby.  Maybe it would be more
> convenient to split the primitives: keep the current one to start the
> standby, and add a separate one to wait for it to be registered.  Then
> we could do
> standby1->start;
> standby2->start;
> standby3->start;
> foreach my $sby (@standbys) {
>     $sby->wait_for_standby
> }

It seems to me that this sequence could still lead to inconsistencies:
1) standby 1 starts, reaches consistency so pg_ctl start -w exits.
2) standby 2 starts, reaches consistency.
3) standby 2 starts a WAL receiver, gets the first WAL sender slot of
the primary.
4) standby 1 starts a WAL receiver, gets the second slot.

> I think this should be note() rather than print(), or maybe diag().  (I
> see that we have a couple of other cases which use print() in the tap
> tests, which I think should be note() as well.)

OK.  Let's change it for this patch.  For the rest, I can always send
a different patch.  Just writing down your comment..
--
Michael

On 2019-Jun-18, Michael Paquier wrote:

> On Mon, Jun 17, 2019 at 10:50:39AM -0400, Alvaro Herrera wrote:
> > Hmm, this introduces a bit of latency: it waits for each standby to be
> > fully up before initializing the next standby.  Maybe it would be more
> > convenient to split the primitives: keep the current one to start the
> > standby, and add a separate one to wait for it to be registered.  Then
> > we could do
> > standby1->start;
> > standby2->start;
> > standby3->start;
> > foreach my $sby (@standbys) {
> >     $sby->wait_for_standby
> > }
> 
> It seems to me that this sequence could still lead to inconsistencies:
> 1) standby 1 starts, reaches consistency so pg_ctl start -w exits.
> 2) standby 2 starts, reaches consistency.
> 3) standby 2 starts a WAL receiver, gets the first WAL sender slot of
> the primary.
> 4) standby 1 starts a WAL receiver, gets the second slot.

Ho ho .. you know what misled me into thinking that that would work?
Just look at the name of the test that failed, "asterisk comes before
another standby name".  That doesn't seem to be what the test is
testing!

# poll_query_until timed out executing this query:
# SELECT application_name, sync_priority, sync_state FROM pg_stat_replication ORDER BY application_name;
# expecting this output:
# standby1|1|sync
# standby2|2|sync
# standby3|2|potential
# standby4|2|potential
# last actual query output:
# standby1|1|sync
# standby2|2|potential
# standby3|2|sync
# standby4|2|potential
# with stderr:

#   Failed test 'asterisk comes before another standby name'

-- 
Álvaro Herrera                https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

On Wed, Jun 19, 2019 at 04:08:44PM -0400, Alvaro Herrera wrote:
> Ho ho .. you know what misled me into thinking that that would work?
> Just look at the name of the test that failed, "asterisk comes before
> another standby name".  That doesn't seem to be what the test is
> testing!

I agree that the wording is poor here.  Perhaps a better description
in the comment block would be "standby1 is selected as sync as it has
the highest priority, and is followed by a second standby listed first
in the WAL sender array, in this case standby2".  We could change the
description like that "second standby chosen as sync is the first one
in WAL sender array".  The follow-up test using '2(*)' is actually
worse in terms of ordering dependency as all standbys could be
selected.  The last test with a quorum lookup on all the standbys is
fine from this perspective thanks to the ORDER BY on application_name
when doing the lookup of pg_stat_replication.
--
Michael

On Tue, Jun 18, 2019 at 09:59:08AM +0900, Michael Paquier wrote:
> On Mon, Jun 17, 2019 at 10:50:39AM -0400, Alvaro Herrera wrote:
> > I think this should be note() rather than print(), or maybe diag().  (I
> > see that we have a couple of other cases which use print() in the tap
> > tests, which I think should be note() as well.)
> 
> OK.  Let's change it for this patch.

PostgresNode uses "print" the same way.  The patch does close the intended
race conditions, and its implementation choices look fine to me.

On Mon, Jul 22, 2019 at 11:45:53PM -0700, Noah Misch wrote:
> PostgresNode uses "print" the same way.  The patch does close the intended
> race conditions, and its implementation choices look fine to me.

Thanks Noah for the review.  I have reviewed the thread and improved a
couple of comments based on Alvaro's previous input.  Attached is v2.
If there are no objections, I would be fine to commit it.
--
Michael

On Tue, Jul 23, 2019 at 05:04:32PM +0900, Michael Paquier wrote:
> Thanks Noah for the review.  I have reviewed the thread and improved a
> couple of comments based on Alvaro's previous input.  Attached is v2.
> If there are no objections, I would be fine to commit it.

Applied and back-patched down to 9.6 where it applies.  Thanks for the
reviews.
--
Michael