From: Tom Lane <tgl@sss.pgh.pa.us>
To: pgsql-hackers@postgreSQL.org
Subject: Re: Race-like failure in recovery/t/009_twophase.pl
In-reply-to: <908.1498965681@sss.pgh.pa.us>
References: <908.1498965681@sss.pgh.pa.us>
Comments: In-reply-to Tom Lane <tgl@sss.pgh.pa.us>
	message dated "Sat, 01 Jul 2017 23:21:21 -0400"
MIME-Version: 1.0
Content-Type: text/plain; charset="us-ascii"
Content-ID: <2587.1499028049.1@sss.pgh.pa.us>
Content-Transfer-Encoding: quoted-printable
Date: Sun, 02 Jul 2017 16:40:49 -0400
Message-ID: <2588.1499028049@sss.pgh.pa.us>
Precedence: bulk
Sender: pgsql-hackers-owner@postgresql.org

I wrote:
> The reporting critters are all on the slow side, so I suspected
> a timing problem, especially since it only started to show up
> after changing pg_ctl's timing behavior.  I can't reproduce it
> locally on unmodified sources, but I could after putting my thumb
> on the scales like this:
>=20
> diff --git a/src/backend/replication/walreceiver.c b/src/backend/replicat=
ion/walreceiver.c
> index ea9d21a..7ef22c1 100644
> *** a/src/backend/replication/walreceiver.c
> --- b/src/backend/replication/walreceiver.c
> *************** WalReceiverMain(void)
> *** 446,451 ****
> --- 446,454 ----
>   							 * Something was received from master, so reset
>   							 * timeout
>   							 */
> +=20
> + 							pg_usleep(100000); /* be slow about processing */
> +=20
>   							last_recv_timestamp =3D GetCurrentTimestamp();
>   							ping_sent =3D false;
>   							XLogWalRcvProcessMsg(buf[0], &buf[1], len - 1);


BTW, I neglected to mention that this hack also produces a second failure
in the recovery test suite:

[20:28:31] t/001_stream_rep.pl .................. 11/28=20
#   Failed test 'xmin of cascaded slot null with no hs_feedback'
#   at t/001_stream_rep.pl line 178.
#          got: undef
#     expected: ''

#   Failed test 'catalog xmin of cascaded slot null with no hs_feedback'
#   at t/001_stream_rep.pl line 179.
#          got: undef
#     expected: ''
[20:28:31] t/001_stream_rep.pl .................. 28/28 # Looks like you fa=
iled 2 tests of 28.
[20:28:31] t/001_stream_rep.pl .................. Dubious, test returned 2 =
(wstat 512, 0x200)
Failed 2/28 subtests=20

I had supposed last night that this was merely a matter of needing
to insert a wait_slot_xmins() call before those tests, but doing so
doesn't help.  And, looking closer, the report is complaining that
$xmin and $catalog_xmin are coming back as undef, not empty strings.
My Perl-fu is too weak to figure out how that could possibly be ---
the documentation for PostgresNode::query_hash certainly states
flatly that it will never happen.  And it even more certainly
shouldn't happen if we already successfully probed the
pg_replication_slots row in wait_slot_xmins().

The corresponding entries in the postmaster's log don't look abnormal:

2017-07-02 20:07:29.313 UTC [30862] LOG:  database system is ready to accep=
t read only connections
2017-07-02 20:07:29.318 UTC [30867] LOG:  started streaming WAL from primar=
y at 0/3000000 on timeline 1
2017-07-02 20:07:29.415 UTC [30870] t/001_stream_rep.pl LOG:  statement: SE=
LECT pg_create_physical_replication_slot('standby_2');
2017-07-02 20:07:29.619 UTC [30863] LOG:  redo starts at 0/3029458
2017-07-02 20:07:29.665 UTC [30882] t/001_stream_rep.pl LOG:  statement:=20
			SELECT xmin IS NULL AND catalog_xmin IS NULL
			FROM pg_catalog.pg_replication_slots
			WHERE slot_name =3D 'standby_2';
=09=09
2017-07-02 20:07:29.679 UTC [30884] t/001_stream_rep.pl LOG:  statement: SE=
LECT plugin, slot_type, datoid, database, active, active_pid, xmin, catalog=
_xmin, restart_lsn FROM pg_catalog.pg_replication_slots WHERE slot_name =3D=
 'standby_2'

(This is from a run with a wait_slot_xmins() call added, else the
statement logged by PID 30882 would not have been issued.)

Any ideas what's wrong there?

			regards, tom lane


--=20
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers