Received: from malur.postgresql.org ([217.196.149.56])
	by arkaria.postgresql.org with esmtp (Exim 4.84_2)
	(envelope-from
 <pgsql-hackers-owner+M330859=pgsql-hackers-arkari@postgresql.org>)
	id 1dRmwu-0001Sq-Li
	for pgsql-hackers@arkaria.postgresql.org; Sun, 02 Jul 2017 22:02:36 +0000
Received: from localhost ([127.0.0.1] helo=postgresql.org)
	by malur.postgresql.org with smtp (Exim 4.84_2)
	(envelope-from
 <pgsql-hackers-owner+M330859=pgsql-hackers-arkari@postgresql.org>)
	id 1dRmwt-0007zm-Ve
	for pgsql-hackers@arkaria.postgresql.org; Sun, 02 Jul 2017 22:02:36 +0000
Received: from magus.postgresql.org ([2a02:c0:301:0:ffff::29])
	by malur.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256)
	(Exim 4.84_2)
	(envelope-from <tgl@sss.pgh.pa.us>)
	id 1dRmwr-0007y4-QG
	for pgsql-hackers@postgreSQL.org; Sun, 02 Jul 2017 22:02:33 +0000
Received: from sss.pgh.pa.us ([66.207.139.130])
	by magus.postgresql.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_CBC_SHA384:256)
	(Exim 4.84_2)
	(envelope-from <tgl@sss.pgh.pa.us>)
	id 1dRmwj-000755-RV
	for pgsql-hackers@postgreSQL.org; Sun, 02 Jul 2017 22:02:33 +0000
Received: from sss1.sss.pgh.pa.us (localhost [127.0.0.1])
	by sss.pgh.pa.us (8.14.4/8.14.4) with ESMTP id v62M2Ow1031664
	for <pgsql-hackers@postgreSQL.org>; Sun, 2 Jul 2017 18:02:24 -0400
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: <31662.1499032944.1@sss.pgh.pa.us>
Content-Transfer-Encoding: quoted-printable
Date: Sun, 02 Jul 2017 18:02:24 -0400
Message-ID: <31663.1499032944@sss.pgh.pa.us>
List-Archive: <http://archives.postgresql.org/pgsql-hackers>
List-Help: <mailto:majordomo@postgresql.org?body=help>
List-ID: <pgsql-hackers.postgresql.org>
List-Owner: <mailto:pgsql-hackers-owner@postgresql.org>
List-Post: <mailto:pgsql-hackers@postgresql.org>
List-Subscribe: <mailto:majordomo@postgresql.org?body=sub%20pgsql-hackers>
List-Unsubscribe: <mailto:majordomo@postgresql.org?body=unsub%20pgsql-hackers>
X-Mailing-List: pgsql-hackers
Precedence: bulk
Sender: pgsql-hackers-owner@postgresql.org

I wrote:
> Anyway, having vented about that ... it's not very clear to me whether the
> test script is at fault for not being careful to let the slave catch up to
> the master before we promote it (and then deem the master to be usable as
> a slave without rebuilding it first), or whether we actually imagine that
> should work, in which case there's a replication logic bug here someplace.

OK, now that I can make some sense of what's going on in the 009 test
script ... it seems like that test script is presuming synchronous
replication behavior, but it's only actually set up sync rep in one
direction, namely the london->paris direction.  The failure occurs
when we lose data in the paris->london direction.  Specifically,
with the delay hack in place, I find this in the log before things
go south completely:

# Now london is master and paris is slave
ok 11 - Restore prepared transactions from files with master down
### Enabling streaming replication for node "paris"
### Starting node "paris"
# Running: pg_ctl -D /home/postgres/pgsql/src/test/recovery/tmp_check/data_=
paris_xSFF/pgdata -l /home/postgres/pgsql/src/test/recovery/tmp_check/log/0=
09_twophase_paris.log start
waiting for server to start.... done
server started
# Postmaster PID for node "paris" is 30930
psql:<stdin>:1: ERROR:  prepared transaction with identifier "xact_009_11" =
does not exist

That ERROR is being reported by the london node, at line 267 of the
current script:
	$cur_master->psql('postgres', "COMMIT PREPARED 'xact_009_11'");
So london is missing a prepared transaction that was created while
paris was master, a few lines earlier.  (It's not real good that
the test script isn't bothering to check the results of any of
these queries, although the end-state test I just added should close
the loop on that.)  london has no idea that it's missing data, but
when we restart the paris node a little later, it notices that its
WAL is past where london is.

I'm now inclined to think that the correct fix is to ensure that we
run synchronous rep in both directions, rather than to insert delays
to substitute for that.  Just setting synchronous_standby_names for
node paris at the top of the script doesn't work, because there's
at least one place where the script intentionally issues commands
to paris while london is stopped.  But we could turn off sync rep
for that step, perhaps.

Anyone have a different view of what to fix here?

			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