Received: from malur.postgresql.org ([217.196.149.56])
	by arkaria.postgresql.org with esmtp (Exim 4.84_2)
	(envelope-from
 <pgsql-hackers-owner+M330861=pgsql-hackers-arkari@postgresql.org>)
	id 1dRoj9-00075D-WF
	for pgsql-hackers@arkaria.postgresql.org; Sun, 02 Jul 2017 23:56:32 +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+M330861=pgsql-hackers-arkari@postgresql.org>)
	id 1dRoj7-0002x8-Hl
	for pgsql-hackers@arkaria.postgresql.org; Sun, 02 Jul 2017 23:56:29 +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 1dRohZ-00009s-UQ
	for pgsql-hackers@postgreSQL.org; Sun, 02 Jul 2017 23:54:53 +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 1dRohW-0000te-3k
	for pgsql-hackers@postgreSQL.org; Sun, 02 Jul 2017 23:54:53 +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 v62NsmTR011905
	for <pgsql-hackers@postgreSQL.org>; Sun, 2 Jul 2017 19:54:48 -0400
From: Tom Lane <tgl@sss.pgh.pa.us>
To: pgsql-hackers@postgreSQL.org
Subject: More race conditions in logical replication
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="----- =_aaaaaaaaaa0"
Content-ID: <11716.1499039348.0@sss.pgh.pa.us>
Date: Sun, 02 Jul 2017 19:54:48 -0400
Message-ID: <11904.1499039688@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

------- =_aaaaaaaaaa0
Content-Type: text/plain; charset="us-ascii"
Content-ID: <11716.1499039348.1@sss.pgh.pa.us>
Content-Transfer-Encoding: quoted-printable

I noticed a recent failure that looked suspiciously like a race condition:

https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=3Dhornet&dt=3D2017-=
07-02%2018%3A02%3A07

The critical bit in the log file is

error running SQL: 'psql:<stdin>:1: ERROR:  could not drop the replication =
slot "tap_sub" on publisher
DETAIL:  The error was: ERROR:  replication slot "tap_sub" is active for PI=
D 3866790'
while running 'psql -XAtq -d port=3D59543 host=3D/tmp/QpCJtafT7R dbname=3D'=
postgres' -f - -v ON_ERROR_STOP=3D1' with sql 'DROP SUBSCRIPTION tap_sub' a=
t /home/nm/farm/xlc64/HEAD/pgsql.build/src/test/subscription/../../../src/t=
est/perl/PostgresNode.pm line 1198.

After poking at it a bit, I found that I can cause several different
failures of this ilk in the subscription tests by injecting delays at
the points where a slot's active_pid is about to be cleared, as in the
attached patch (which also adds some extra printouts for debugging
purposes; none of that is meant for commit).  It seems clear that there
is inadequate interlocking going on when we kill and restart a logical
rep worker: we're trying to start a new one before the old one has
gotten out of the slot.

I'm not particularly interested in fixing this myself, so I'm just
going to add it to the open items list.

			regards, tom lane


------- =_aaaaaaaaaa0
Content-Type: text/x-diff; name="break_repl_slot_management.patch";
	charset="us-ascii"
Content-ID: <11716.1499039348.2@sss.pgh.pa.us>
Content-Description: break_repl_slot_management.patch
Content-Transfer-Encoding: quoted-printable

diff --git a/src/backend/replication/slot.c b/src/backend/replication/slot.c
index dc7de20..78cd416 100644
*** a/src/backend/replication/slot.c
--- b/src/backend/replication/slot.c
*************** ReplicationSlotAcquire(const char *name)
*** 358,364 ****
  	if (active_pid !=3D MyProcPid)
  		ereport(ERROR,
  				(errcode(ERRCODE_OBJECT_IN_USE),
! 				 errmsg("replication slot \"%s\" is active for PID %d",
  						name, active_pid)));
=20=20
  	/* We made this slot active, so it's ours now. */
--- 358,364 ----
  	if (active_pid !=3D MyProcPid)
  		ereport(ERROR,
  				(errcode(ERRCODE_OBJECT_IN_USE),
! 				 errmsg("replication slot \"%s\" is active for PID %d (acq)",
  						name, active_pid)));
=20=20
  	/* We made this slot active, so it's ours now. */
*************** ReplicationSlotRelease(void)
*** 391,396 ****
--- 391,398 ----
  		 * Mark persistent slot inactive.  We're not freeing it, just
  		 * disconnecting.
  		 */
+ 		pg_usleep(100000);
+ 		elog(LOG, "ReplicationSlotRelease: unmarking persistent slot");
  		SpinLockAcquire(&slot->mutex);
  		slot->active_pid =3D 0;
  		SpinLockRelease(&slot->mutex);
*************** ReplicationSlotDropPtr(ReplicationSlot *
*** 523,528 ****
--- 525,532 ----
  	{
  		bool		fail_softly =3D slot->data.persistency !=3D RS_PERSISTENT;
=20=20
+ 		pg_usleep(100000);
+ 		elog(LOG, "ReplicationSlotDropPtr: unmarking slot after rename fail");
  		SpinLockAcquire(&slot->mutex);
  		slot->active_pid =3D 0;
  		SpinLockRelease(&slot->mutex);
*************** ReplicationSlotDropPtr(ReplicationSlot *
*** 540,545 ****
--- 544,551 ----
  	 * and nobody can be attached to this slot and thus access it without
  	 * scanning the array.
  	 */
+ 	pg_usleep(100000);
+ 	elog(LOG, "ReplicationSlotDropPtr: unmarking slot");
  	LWLockAcquire(ReplicationSlotControlLock, LW_EXCLUSIVE);
  	slot->active_pid =3D 0;
  	slot->in_use =3D false;
*************** restart:
*** 876,882 ****
  		if (active_pid)
  			ereport(ERROR,
  					(errcode(ERRCODE_OBJECT_IN_USE),
! 					 errmsg("replication slot \"%s\" is active for PID %d",
  							slotname, active_pid)));
=20=20
  		/*
--- 882,888 ----
  		if (active_pid)
  			ereport(ERROR,
  					(errcode(ERRCODE_OBJECT_IN_USE),
! 					 errmsg("replication slot \"%s\" is active for PID %d (drop)",
  							slotname, active_pid)));
=20=20
  		/*

------- =_aaaaaaaaaa0
Content-Type: text/plain
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
MIME-Version: 1.0


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

------- =_aaaaaaaaaa0--