Horton

Thread

Commits

  1. Fix two-phase commit test for recovery mode

  1. More replication race conditions

    Tom Lane <tgl@sss.pgh.pa.us> — 2017-08-24T17:54:32Z

    sungazer just failed with

pg_recvlogical exited with code '256', stdout '' and stderr 'pg_recvlogical: could not send replication command "START_REPLICATION SLOT "test_slot" LOGICAL 0/0 ("include-xids" '0', "skip-empty-xacts" '1')": ERROR:  replication slot "test_slot" is active for PID 8913148
pg_recvlogical: disconnected
' at /home/nm/farm/gcc64/HEAD/pgsql.build/src/test/recovery/../../../src/test/perl/PostgresNode.pm line 1657.

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=sungazer&dt=2017-08-24%2015%3A16%3A10

Looks like we're still not there on preventing replication startup
race conditions.

			regards, tom lane

  2. Re: More replication race conditions

    Petr Jelinek <petr.jelinek@2ndquadrant.com> — 2017-08-25T10:09:00Z

    On 24/08/17 19:54, Tom Lane wrote:
> sungazer just failed with
> 
> pg_recvlogical exited with code '256', stdout '' and stderr 'pg_recvlogical: could not send replication command "START_REPLICATION SLOT "test_slot" LOGICAL 0/0 ("include-xids" '0', "skip-empty-xacts" '1')": ERROR:  replication slot "test_slot" is active for PID 8913148
> pg_recvlogical: disconnected
> ' at /home/nm/farm/gcc64/HEAD/pgsql.build/src/test/recovery/../../../src/test/perl/PostgresNode.pm line 1657.
> 
> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=sungazer&dt=2017-08-24%2015%3A16%3A10
> 
> Looks like we're still not there on preventing replication startup
> race conditions.

Hmm, that looks like "by design" behavior. Slot acquiring will throw
error if the slot is already used by somebody else (slots use their own
locking mechanism that does not wait). In this case it seems the
walsender which was using slot for previous previous step didn't finish
releasing the slot by the time we start new command. We can work around
this by changing the test to wait perhaps.

-- 
  Petr Jelinek                  http://www.2ndQuadrant.com/
  PostgreSQL Development, 24x7 Support, Training & Services

  3. Re: More replication race conditions

    Noah Misch <noah@leadboat.com> — 2017-08-27T02:32:49Z

    On Fri, Aug 25, 2017 at 12:09:00PM +0200, Petr Jelinek wrote:
> On 24/08/17 19:54, Tom Lane wrote:
> > sungazer just failed with
> > 
> > pg_recvlogical exited with code '256', stdout '' and stderr 'pg_recvlogical: could not send replication command "START_REPLICATION SLOT "test_slot" LOGICAL 0/0 ("include-xids" '0', "skip-empty-xacts" '1')": ERROR:  replication slot "test_slot" is active for PID 8913148
> > pg_recvlogical: disconnected
> > ' at /home/nm/farm/gcc64/HEAD/pgsql.build/src/test/recovery/../../../src/test/perl/PostgresNode.pm line 1657.
> > 
> > https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=sungazer&dt=2017-08-24%2015%3A16%3A10
> > 
> > Looks like we're still not there on preventing replication startup
> > race conditions.
> 
> Hmm, that looks like "by design" behavior. Slot acquiring will throw
> error if the slot is already used by somebody else (slots use their own
> locking mechanism that does not wait). In this case it seems the
> walsender which was using slot for previous previous step didn't finish
> releasing the slot by the time we start new command. We can work around
> this by changing the test to wait perhaps.

[Action required within three days.  This is a generic notification.]

The above-described topic is currently a PostgreSQL 10 open item.  Simon,
since you committed the patch believed to have created it, you own this open
item.  If some other commit is more relevant or if this does not belong as a
v10 open item, please let us know.  Otherwise, please observe the policy on
open item ownership[1] and send a status update within three calendar days of
this message.  Include a date for your subsequent status update.  Testers may
discover new open items at any time, and I want to plan to get them all fixed
well in advance of shipping v10.  Consequently, I will appreciate your efforts
toward speedy resolution.  Thanks.

[1] https://www.postgresql.org/message-id/20170404140717.GA2675809%40tornado.leadboat.com

  4. Re: More replication race conditions

    Tom Lane <tgl@sss.pgh.pa.us> — 2017-08-27T03:03:52Z

    And *another* replication test race condition just now:

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=dangomushi&dt=2017-08-26%2019%3A37%3A08

As best I can interpret this, it's pointing out that this bit in
src/test/recovery/t/009_twophase.pl:

$cur_master->psql(
	'postgres', "
	BEGIN;
	CREATE TABLE t_009_tbl2 (id int, msg text);
	SAVEPOINT s1;
	INSERT INTO t_009_tbl2 VALUES (27, 'issued to ${cur_master_name}');
	PREPARE TRANSACTION 'xact_009_13';
	-- checkpoint will issue XLOG_STANDBY_LOCK that can conflict with lock
	-- held by 'create table' statement
	CHECKPOINT;
	COMMIT PREPARED 'xact_009_13';");

$cur_standby->psql(
	'postgres',
	"SELECT count(*) FROM t_009_tbl2",
	stdout => \$psql_out);
is($psql_out, '1', "Replay prepared transaction with DDL");

contains exactly no means of ensuring that the master's transaction has
been replayed on the standby before we check for its results.  It's not
real clear why it seems to work 99.99% of the time, because, well, there
isn't any frickin' interlock there ...

			regards, tom lane

  5. Re: More replication race conditions

    Michael Paquier <michael.paquier@gmail.com> — 2017-08-27T06:34:05Z

    On Sun, Aug 27, 2017 at 12:03 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> And *another* replication test race condition just now:
>
> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=dangomushi&dt=2017-08-26%2019%3A37%3A08
>
> As best I can interpret this, it's pointing out that this bit in
> src/test/recovery/t/009_twophase.pl:
>
> $cur_master->psql(
>         'postgres', "
>         BEGIN;
>         CREATE TABLE t_009_tbl2 (id int, msg text);
>         SAVEPOINT s1;
>         INSERT INTO t_009_tbl2 VALUES (27, 'issued to ${cur_master_name}');
>         PREPARE TRANSACTION 'xact_009_13';
>         -- checkpoint will issue XLOG_STANDBY_LOCK that can conflict with lock
>         -- held by 'create table' statement
>         CHECKPOINT;
>         COMMIT PREPARED 'xact_009_13';");
>
> $cur_standby->psql(
>         'postgres',
>         "SELECT count(*) FROM t_009_tbl2",
>         stdout => \$psql_out);
> is($psql_out, '1', "Replay prepared transaction with DDL");
>
> contains exactly no means of ensuring that the master's transaction has
> been replayed on the standby before we check for its results.  It's not
> real clear why it seems to work 99.99% of the time, because, well, there
> isn't any frickin' interlock there ...

I have noticed this one this morning, and I am planning to address it
with a proper patch soonishly. (I am still fighting a bit to get
dangomushi in a more stable stable, and things run slow on it, so it
is good at catching race conditions of this kind).
-- 
Michael

  6. Re: More replication race conditions

    Petr Jelinek <petr.jelinek@2ndquadrant.com> — 2017-08-27T09:32:23Z

    On 27/08/17 04:32, Noah Misch wrote:
> On Fri, Aug 25, 2017 at 12:09:00PM +0200, Petr Jelinek wrote:
>> On 24/08/17 19:54, Tom Lane wrote:
>>> sungazer just failed with
>>>
>>> pg_recvlogical exited with code '256', stdout '' and stderr 'pg_recvlogical: could not send replication command "START_REPLICATION SLOT "test_slot" LOGICAL 0/0 ("include-xids" '0', "skip-empty-xacts" '1')": ERROR:  replication slot "test_slot" is active for PID 8913148
>>> pg_recvlogical: disconnected
>>> ' at /home/nm/farm/gcc64/HEAD/pgsql.build/src/test/recovery/../../../src/test/perl/PostgresNode.pm line 1657.
>>>
>>> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=sungazer&dt=2017-08-24%2015%3A16%3A10
>>>
>>> Looks like we're still not there on preventing replication startup
>>> race conditions.
>>
>> Hmm, that looks like "by design" behavior. Slot acquiring will throw
>> error if the slot is already used by somebody else (slots use their own
>> locking mechanism that does not wait). In this case it seems the
>> walsender which was using slot for previous previous step didn't finish
>> releasing the slot by the time we start new command. We can work around
>> this by changing the test to wait perhaps.
> 
> [Action required within three days.  This is a generic notification.]
> 
> The above-described topic is currently a PostgreSQL 10 open item.  Simon,
> since you committed the patch believed to have created it, you own this open
> item.  If some other commit is more relevant or if this does not belong as a
> v10 open item, please let us know.  Otherwise, please observe the policy on
> open item ownership[1] and send a status update within three calendar days of
> this message.  Include a date for your subsequent status update.  Testers may
> discover new open items at any time, and I want to plan to get them all fixed
> well in advance of shipping v10.  Consequently, I will appreciate your efforts
> toward speedy resolution.  Thanks.
> 
> [1] https://www.postgresql.org/message-id/20170404140717.GA2675809%40tornado.leadboat.com
> 

Attached should fix this.

-- 
  Petr Jelinek                  http://www.2ndQuadrant.com/
  PostgreSQL Development, 24x7 Support, Training & Services

  7. Re: More replication race conditions

    Michael Paquier <michael.paquier@gmail.com> — 2017-08-27T23:25:19Z

    On Sun, Aug 27, 2017 at 3:34 PM, Michael Paquier
<michael.paquier@gmail.com> wrote:
> On Sun, Aug 27, 2017 at 12:03 PM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
>> contains exactly no means of ensuring that the master's transaction has
>> been replayed on the standby before we check for its results.  It's not
>> real clear why it seems to work 99.99% of the time, because, well, there
>> isn't any frickin' interlock there ...
>
> I have noticed this one this morning, and I am planning to address it
> with a proper patch soonishly. (I am still fighting a bit to get
> dangomushi in a more stable stable, and things run slow on it, so it
> is good at catching race conditions of this kind).

Today's run has finished with the same failure:
https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=dangomushi&dt=2017-08-27%2018%3A00%3A13
Attached is a patch to make this code path wait that the transaction
has been replayed. We could use as well synchronous_commit = apply,
but I prefer the solution of this patch with a wait query.
-- 
Michael

  8. Re: More replication race conditions

    Tom Lane <tgl@sss.pgh.pa.us> — 2017-08-27T23:33:55Z

    Michael Paquier <michael.paquier@gmail.com> writes:
> Attached is a patch to make this code path wait that the transaction
> has been replayed. We could use as well synchronous_commit = apply,
> but I prefer the solution of this patch with a wait query.

Petr proposed a different patch to fix the same problem at
https://www.postgresql.org/message-id/1636c52e-c144-993a-6665-9358f322deda%402ndquadrant.com

Which one is better?

			regards, tom lane

  9. Re: More replication race conditions

    Michael Paquier <michael.paquier@gmail.com> — 2017-08-27T23:36:08Z

    On Sun, Aug 27, 2017 at 6:32 PM, Petr Jelinek
<petr.jelinek@2ndquadrant.com> wrote:
> Attached should fix this.

+$node_master->poll_query_until('postgres',
+"SELECT EXISTS (SELECT 1 FROM pg_replication_slots WHERE slot_name =
'test_slot' AND active_pid IS NULL)"
+)
+  or die "slot never became inactive";
+
 $stdout_recv = $node_master->pg_recvlogical_upto(
I am wondering if a similar check should actually go into
pg_recvlogical_upto() instead. I tend to think that we've learned
things the hard way with 3043c1dd and such.
-- 
Michael

  10. Re: More replication race conditions

    Michael Paquier <michael.paquier@gmail.com> — 2017-08-27T23:39:05Z

    On Mon, Aug 28, 2017 at 8:33 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
> Michael Paquier <michael.paquier@gmail.com> writes:
>> Attached is a patch to make this code path wait that the transaction
>> has been replayed. We could use as well synchronous_commit = apply,
>> but I prefer the solution of this patch with a wait query.
>
> Petr proposed a different patch to fix the same problem at
> https://www.postgresql.org/message-id/1636c52e-c144-993a-6665-9358f322deda%402ndquadrant.com
>
> Which one is better?

Petr's patch is here to fix the race condition in test 006 for logical
decoding. My patch involves the failures that dangomushi sees since
yesterday with 2PC test 009. (Note: It took me a while to put this
animal in an environment with a more stable connection, so now I hope
that we'll get again daily reports)
-- 
Michael

  11. Re: More replication race conditions

    Petr Jelinek <petr.jelinek@2ndquadrant.com> — 2017-08-27T23:44:14Z

    On 28/08/17 01:36, Michael Paquier wrote:
> On Sun, Aug 27, 2017 at 6:32 PM, Petr Jelinek
> <petr.jelinek@2ndquadrant.com> wrote:
>> Attached should fix this.
> 
> +$node_master->poll_query_until('postgres',
> +"SELECT EXISTS (SELECT 1 FROM pg_replication_slots WHERE slot_name =
> 'test_slot' AND active_pid IS NULL)"
> +)
> +  or die "slot never became inactive";
> +
>  $stdout_recv = $node_master->pg_recvlogical_upto(
> I am wondering if a similar check should actually go into
> pg_recvlogical_upto() instead. I tend to think that we've learned
> things the hard way with 3043c1dd and such.
> 

Putting it there can lead to tests that take forever to finish if
written incorrectly. This way they at least just fail.

-- 
  Petr Jelinek                  http://www.2ndQuadrant.com/
  PostgreSQL Development, 24x7 Support, Training & Services

  12. Re: More replication race conditions

    Michael Paquier <michael.paquier@gmail.com> — 2017-08-29T11:44:42Z

    On Mon, Aug 28, 2017 at 8:25 AM, Michael Paquier
<michael.paquier@gmail.com> wrote:
> Today's run has finished with the same failure:
> https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=dangomushi&dt=2017-08-27%2018%3A00%3A13
> Attached is a patch to make this code path wait that the transaction
> has been replayed. We could use as well synchronous_commit = apply,
> but I prefer the solution of this patch with a wait query.

I have added an open item for this issue for PG10. The 2PC tests in
src/test/recovery are new in PG10, introduced by 3082098.
-- 
Michael

  13. Re: More replication race conditions

    Noah Misch <noah@leadboat.com> — 2017-08-31T03:15:59Z

    On Sun, Aug 27, 2017 at 02:32:49AM +0000, Noah Misch wrote:
> On Fri, Aug 25, 2017 at 12:09:00PM +0200, Petr Jelinek wrote:
> > On 24/08/17 19:54, Tom Lane wrote:
> > > sungazer just failed with
> > > 
> > > pg_recvlogical exited with code '256', stdout '' and stderr 'pg_recvlogical: could not send replication command "START_REPLICATION SLOT "test_slot" LOGICAL 0/0 ("include-xids" '0', "skip-empty-xacts" '1')": ERROR:  replication slot "test_slot" is active for PID 8913148
> > > pg_recvlogical: disconnected
> > > ' at /home/nm/farm/gcc64/HEAD/pgsql.build/src/test/recovery/../../../src/test/perl/PostgresNode.pm line 1657.
> > > 
> > > https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=sungazer&dt=2017-08-24%2015%3A16%3A10
> > > 
> > > Looks like we're still not there on preventing replication startup
> > > race conditions.
> > 
> > Hmm, that looks like "by design" behavior. Slot acquiring will throw
> > error if the slot is already used by somebody else (slots use their own
> > locking mechanism that does not wait). In this case it seems the
> > walsender which was using slot for previous previous step didn't finish
> > releasing the slot by the time we start new command. We can work around
> > this by changing the test to wait perhaps.
> 
> [Action required within three days.  This is a generic notification.]
> 
> The above-described topic is currently a PostgreSQL 10 open item.  Simon,
> since you committed the patch believed to have created it, you own this open
> item.  If some other commit is more relevant or if this does not belong as a
> v10 open item, please let us know.  Otherwise, please observe the policy on
> open item ownership[1] and send a status update within three calendar days of
> this message.  Include a date for your subsequent status update.  Testers may
> discover new open items at any time, and I want to plan to get them all fixed
> well in advance of shipping v10.  Consequently, I will appreciate your efforts
> toward speedy resolution.  Thanks.
> 
> [1] https://www.postgresql.org/message-id/20170404140717.GA2675809%40tornado.leadboat.com

This PostgreSQL 10 open item is past due for your status update.  Kindly send
a status update within 24 hours, and include a date for your subsequent status
update.  Refer to the policy on open item ownership:
https://www.postgresql.org/message-id/20170404140717.GA2675809%40tornado.leadboat.com

  14. Re: More replication race conditions

    Noah Misch <noah@leadboat.com> — 2017-08-31T03:19:28Z

    On Tue, Aug 29, 2017 at 08:44:42PM +0900, Michael Paquier wrote:
> On Mon, Aug 28, 2017 at 8:25 AM, Michael Paquier
> <michael.paquier@gmail.com> wrote:
> > Today's run has finished with the same failure:
> > https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=dangomushi&dt=2017-08-27%2018%3A00%3A13
> > Attached is a patch to make this code path wait that the transaction
> > has been replayed. We could use as well synchronous_commit = apply,
> > but I prefer the solution of this patch with a wait query.
> 
> I have added an open item for this issue for PG10. The 2PC tests in
> src/test/recovery are new in PG10, introduced by 3082098.

[Action required within three days.  This is a generic notification.]

The above-described topic is currently a PostgreSQL 10 open item.  Álvaro,
since you committed the patch believed to have created it, you own this open
item.  If some other commit is more relevant or if this does not belong as a
v10 open item, please let us know.  Otherwise, please observe the policy on
open item ownership[1] and send a status update within three calendar days of
this message.  Include a date for your subsequent status update.  Testers may
discover new open items at any time, and I want to plan to get them all fixed
well in advance of shipping v10.  Consequently, I will appreciate your efforts
toward speedy resolution.  Thanks.

[1] https://www.postgresql.org/message-id/20170404140717.GA2675809%40tornado.leadboat.com

  15. Re: More replication race conditions

    Simon Riggs <simon@2ndquadrant.com> — 2017-08-31T11:54:35Z

    On 27 August 2017 at 03:32, Noah Misch <noah@leadboat.com> wrote:
> On Fri, Aug 25, 2017 at 12:09:00PM +0200, Petr Jelinek wrote:
>> On 24/08/17 19:54, Tom Lane wrote:
>> > sungazer just failed with
>> >
>> > pg_recvlogical exited with code '256', stdout '' and stderr 'pg_recvlogical: could not send replication command "START_REPLICATION SLOT "test_slot" LOGICAL 0/0 ("include-xids" '0', "skip-empty-xacts" '1')": ERROR:  replication slot "test_slot" is active for PID 8913148
>> > pg_recvlogical: disconnected
>> > ' at /home/nm/farm/gcc64/HEAD/pgsql.build/src/test/recovery/../../../src/test/perl/PostgresNode.pm line 1657.
>> >
>> > https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=sungazer&dt=2017-08-24%2015%3A16%3A10
>> >
>> > Looks like we're still not there on preventing replication startup
>> > race conditions.
>>
>> Hmm, that looks like "by design" behavior. Slot acquiring will throw
>> error if the slot is already used by somebody else (slots use their own
>> locking mechanism that does not wait). In this case it seems the
>> walsender which was using slot for previous previous step didn't finish
>> releasing the slot by the time we start new command. We can work around
>> this by changing the test to wait perhaps.
>
> [Action required within three days.  This is a generic notification.]
>
> The above-described topic is currently a PostgreSQL 10 open item.  Simon,
> since you committed the patch believed to have created it, you own this open
> item.  If some other commit is more relevant or if this does not belong as a
> v10 open item, please let us know.  Otherwise, please observe the policy on
> open item ownership[1] and send a status update within three calendar days of
> this message.  Include a date for your subsequent status update.  Testers may
> discover new open items at any time, and I want to plan to get them all fixed
> well in advance of shipping v10.  Consequently, I will appreciate your efforts
> toward speedy resolution.  Thanks.
>
> [1] https://www.postgresql.org/message-id/20170404140717.GA2675809%40tornado.leadboat.com

I acknowledge receipt of the reminder and will fix by end of day tomorrow.

-- 
Simon Riggs                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

  16. Re: More replication race conditions

    Simon Riggs <simon@2ndquadrant.com> — 2017-09-01T13:58:27Z

    On 31 August 2017 at 12:54, Simon Riggs <simon@2ndquadrant.com> wrote:

>> The above-described topic is currently a PostgreSQL 10 open item.  Simon,
>> since you committed the patch believed to have created it, you own this open
>> item.  If some other commit is more relevant or if this does not belong as a
>> v10 open item, please let us know.  Otherwise, please observe the policy on
>> open item ownership[1] and send a status update within three calendar days of
>> this message.  Include a date for your subsequent status update.  Testers may
>> discover new open items at any time, and I want to plan to get them all fixed
>> well in advance of shipping v10.  Consequently, I will appreciate your efforts
>> toward speedy resolution.  Thanks.
>>
>> [1] https://www.postgresql.org/message-id/20170404140717.GA2675809%40tornado.leadboat.com
>
> I acknowledge receipt of the reminder and will fix by end of day tomorrow.

Applied. Thanks for the patch, Petr.

-- 
Simon Riggs                http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

  17. Re: More replication race conditions

    Alvaro Herrera <alvherre@alvh.no-ip.org> — 2017-09-01T15:03:43Z

    Michael Paquier wrote:
> On Mon, Aug 28, 2017 at 8:25 AM, Michael Paquier
> <michael.paquier@gmail.com> wrote:
> > Today's run has finished with the same failure:
> > https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=dangomushi&dt=2017-08-27%2018%3A00%3A13
> > Attached is a patch to make this code path wait that the transaction
> > has been replayed. We could use as well synchronous_commit = apply,
> > but I prefer the solution of this patch with a wait query.
> 
> I have added an open item for this issue for PG10. The 2PC tests in
> src/test/recovery are new in PG10, introduced by 3082098.

Thanks, pushed.

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

  18. Re: More replication race conditions

    Michael Paquier <michael.paquier@gmail.com> — 2017-09-02T00:11:59Z

    On Sat, Sep 2, 2017 at 12:03 AM, Alvaro Herrera <alvherre@alvh.no-ip.org> wrote:
> Michael Paquier wrote:
>> On Mon, Aug 28, 2017 at 8:25 AM, Michael Paquier
>> <michael.paquier@gmail.com> wrote:
>> > Today's run has finished with the same failure:
>> > https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=dangomushi&dt=2017-08-27%2018%3A00%3A13
>> > Attached is a patch to make this code path wait that the transaction
>> > has been replayed. We could use as well synchronous_commit = apply,
>> > but I prefer the solution of this patch with a wait query.
>>
>> I have added an open item for this issue for PG10. The 2PC tests in
>> src/test/recovery are new in PG10, introduced by 3082098.
>
> Thanks, pushed.

Thanks, the error has now not happened for 5 runs. Let's see if it
ever shows up again.
-- 
Michael