Date: Sat, 2 May 2020 15:16:47 -0700
From: Noah Misch <noah@leadboat.com>
To: Thomas Munro <thomas.munro@enterprisedb.com>, craig@2ndquadrant.com
Cc: Pg Hackers <pgsql-hackers@postgresql.org>
Subject: Re: Failed test 'pg_recvlogical acknowledged changes, nothing
 pending on slot'
Message-ID: <20200502221647.GA3941274@rfd.leadboat.com>
References: 
 <CAEepm=1MzM2Z_xNe4foGwZ1a+MO_2S9oYDq3M5D11=JDU_+0Nw@mail.gmail.com>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="/9DWx/yDrRhgMJTb"
Content-Disposition: inline
In-Reply-To: 
 <CAEepm=1MzM2Z_xNe4foGwZ1a+MO_2S9oYDq3M5D11=JDU_+0Nw@mail.gmail.com>
User-Agent: Mutt/1.5.24 (2015-08-30)
Precedence: bulk


--/9DWx/yDrRhgMJTb
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

On Mon, Jan 29, 2018 at 10:09:49AM +1300, Thomas Munro wrote:
> https://travis-ci.org/postgresql-cfbot/postgresql/builds/334334417
> 
> #   Failed test 'pg_recvlogical acknowledged changes, nothing pending on slot'
> #   at t/006_logical_decoding.pl line 91.
> #          got: 'BEGIN
> # table public.decoding_test: INSERT: x[integer]:1 y[text]:'1'
> # table public.decoding_test: INSERT: x[integer]:2 y[text]:'2'
> # table public.decoding_test: INSERT: x[integer]:3 y[text]:'3'
> # table public.decoding_test: INSERT: x[integer]:4 y[text]:'4'
> # COMMIT'
> #     expected: ''
> # Looks like you failed 1 test of 16.

The problem is this StreamLogicalLog() code:

	if (PQresultStatus(res) == PGRES_COPY_OUT)
	{
		/*
		 * We're doing a client-initiated clean exit and have sent CopyDone to
		 * the server. We've already sent replay confirmation and fsync'd so
		 * we can just clean up the connection now.
		 */
		goto error;
	}

Once pg_recvlogical receives the XLogData containing the sought-after end
position, that code makes pg_recvlogical exit without draining the remainder
of the backend messages.  If pg_recvlogical exits quickly enough, the backend
send()s libpq messages after pg_recvlogical disconnects, which can cause
internal_flush() to fail with EPIPE ("LOG:  could not send data to client:
Broken pipe").  If that precedes LogicalConfirmReceivedLocation(), the test
fails as you experienced.  Such failure happened once on the buildfarm[1];
post-LogicalConfirmReceivedLocation() EPIPE also happens[2].  The first
attached patch causes this failure to happen almost every run.  The fix
(second attachment) is to call PQgetCopyData() until no records remain, then
issue PQresultStatus() again[3].  This closes an additional defect, described
in the log message.


I looked at the other instances of "Broken pipe" in a couple of check-world
runs.  Clients might prevent those with cleaner shutdown on error, but it's
cosmetic.  They appeared in cases where the client or the server had already
recognized some other failure, whereas $SUBJECT taints a successful run.


This led me to notice other pg_recvlogical bugs, which I left unchanged:

1) An "unexpected termination of replication stream" error doesn't preclude
exit(0).

2) sigint_handler() doesn't trigger a PQputCopyEnd().  The connection status
remains PGRES_COPY_BOTH, prompting this weird message:

$ pg_recvlogical --create-slot --start -S foo -d postgres -f- && echo success
^Cpg_recvlogical: error: unexpected termination of replication stream: 
success

Other aspects of signal handling surprised me, but they may not be bugs.  The
documentation says that --start continues "until terminated by a signal".  We
don't trap SIGTERM, just SIGINT (initiate clean exit) and SIGHUP (reopen
output file).  pg_recvlogical copied SIGINT behavior from pg_receivewal, and
the pg_receivewal documentation is specific about signals.  Both programs
react to SIGINT with exit(0), whether or not they reached --endpos.
sigint_handler() doesn't trigger a flushAndSendFeedback(), so the slot's next
pg_recvlogical will repeat messages that followed the last fsync/feedback.

3) sendFeedback() wants s/last_fsync_lsn !=/last_fsync_lsn ==/.  This just
changes the volume of feedback messages.


[1] https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=frogfish&dt=2020-03-07%2018%3A49%3A34
[2] https://buildfarm.postgresql.org/cgi-bin/show_stage_log.pl?nm=florican&dt=2020-04-27%2017%3A25%3A08&stg=recovery-check
[3] https://www.postgresql.org/docs/devel/libpq-copy.html writes "After
    PQgetCopyData returns -1, call PQgetResult to obtain the final result
    status of the COPY command. One can wait for this result to be available
    in the usual way. Then return to normal operation."

--/9DWx/yDrRhgMJTb
Content-Type: text/plain; charset=us-ascii
Content-Disposition: attachment; filename="repro-recvlogical-epipe-v0.patch"

Author:     Noah Misch <noah@leadboat.com>
Commit:     Noah Misch <noah@leadboat.com>

    (not for commit) Reproduce failure seen here:
    
    https://postgr.es/m/CAEepm=1MzM2Z_xNe4foGwZ1a+MO_2S9oYDq3M5D11=JDU_+0Nw@mail.gmail.com
    https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=frogfish&dt=2020-03-07%2018%3A49%3A34

diff --git a/src/backend/libpq/pqcomm.c b/src/backend/libpq/pqcomm.c
index 7717bb2..2268009 100644
--- a/src/backend/libpq/pqcomm.c
+++ b/src/backend/libpq/pqcomm.c
@@ -1448,7 +1448,8 @@ internal_flush(void)
 				last_reported_send_errno = errno;
 				ereport(COMMERROR,
 						(errcode_for_socket_access(),
-						 errmsg("could not send data to client: %m")));
+						 errmsg("could not send data to client: %m"),
+						 errbacktrace()));
 			}
 
 			/*
diff --git a/src/backend/replication/walsender.c b/src/backend/replication/walsender.c
index ae4a9cb..d660038 100644
--- a/src/backend/replication/walsender.c
+++ b/src/backend/replication/walsender.c
@@ -1229,6 +1229,19 @@ WalSndWriteData(LogicalDecodingContext *ctx, XLogRecPtr lsn, TransactionId xid,
 	if (pq_flush_if_writable() != 0)
 		WalSndShutdown();
 
+	/*
+	 * If this XLogData message causes pg_recvlogical to reach its --endpos,
+	 * pg_recvlogical will exit during this sleep.
+	 */
+	pg_usleep(15 * 1000);
+	/*
+	 * Send a long NoticeResponse.  If the peer has exited, internal_flush()
+	 * will observe EPIPE and ereport(COMMERROR).
+	 */
+	elog(WARNING, "long notice %065535d", 7);
+	if (pq_flush_if_writable() != 0)
+		WalSndShutdown();
+
 	/* Try taking fast path unless we get too close to walsender timeout. */
 	if (now < TimestampTzPlusMilliseconds(last_reply_timestamp,
 										  wal_sender_timeout / 2) &&

--/9DWx/yDrRhgMJTb
Content-Type: text/plain; charset=us-ascii
Content-Disposition: attachment; filename="recvlogical-end-copy-v1.patch"

Author:     Noah Misch <noah@leadboat.com>
Commit:     Noah Misch <noah@leadboat.com>

    In successful pg_recvlogical, end PGRES_COPY_OUT cleanly.
    
    pg_recvlogical merely called PQfinish(), so the backend sent messages
    after the disconnect.  When that caused EPIPE in internal_flush(),
    before a LogicalConfirmReceivedLocation(), the next pg_recvlogical would
    repeat already-acknowledged records.  Whether or not the defect causes
    EPIPE, post-disconnect messages could contain an ErrorResponse that the
    user should see.  One properly ends PGRES_COPY_OUT by repeating
    PQgetCopyData() until it returns a negative value.  Augment one of the
    tests to cover the case of WAL past --endpos.  Back-patch to v10, where
    commit 7c030783a5bd07cadffc2a1018bc33119a4c7505 first appeared.  Before
    that commit, pg_recvlogical never reached PGRES_COPY_OUT.
    
    Reviewed by FIXME.  Reported by Thomas Munro.
    
    Discussion: https://postgr.es/m/CAEepm=1MzM2Z_xNe4foGwZ1a+MO_2S9oYDq3M5D11=JDU_+0Nw@mail.gmail.com

diff --git a/src/bin/pg_basebackup/pg_recvlogical.c b/src/bin/pg_basebackup/pg_recvlogical.c
index 0da3277..1304b27 100644
--- a/src/bin/pg_basebackup/pg_recvlogical.c
+++ b/src/bin/pg_basebackup/pg_recvlogical.c
@@ -580,14 +580,40 @@ StreamLogicalLog(void)
 	res = PQgetResult(conn);
 	if (PQresultStatus(res) == PGRES_COPY_OUT)
 	{
+		PQclear(res);
+
 		/*
 		 * We're doing a client-initiated clean exit and have sent CopyDone to
-		 * the server. We've already sent replay confirmation and fsync'd so
-		 * we can just clean up the connection now.
+		 * the server. Drain any messages, so we don't miss a last-minute
+		 * ErrorResponse. The walsender stops generating XLogData records once
+		 * it sees CopyDone, so expect this to finish quickly. After CopyDone,
+		 * it's too late for sendFeedback(), even if this were to take a long
+		 * time. Hence, use synchronous-mode PQgetCopyData().
 		 */
-		goto error;
+		while (1)
+		{
+			int			r;
+
+			if (copybuf != NULL)
+			{
+				PQfreemem(copybuf);
+				copybuf = NULL;
+			}
+			r = PQgetCopyData(conn, &copybuf, 0);
+			if (r == -1)
+				break;
+			if (r == -2)
+			{
+				pg_log_error("could not read COPY data: %s",
+							 PQerrorMessage(conn));
+				time_to_abort = false;	/* unclean exit */
+				goto error;
+			}
+		}
+
+		res = PQgetResult(conn);
 	}
-	else if (PQresultStatus(res) != PGRES_COMMAND_OK)
+	if (PQresultStatus(res) != PGRES_COMMAND_OK)
 	{
 		pg_log_error("unexpected termination of replication stream: %s",
 					 PQresultErrorMessage(res));
diff --git a/src/test/recovery/t/006_logical_decoding.pl b/src/test/recovery/t/006_logical_decoding.pl
index 0bcd1d0..1334bf6 100644
--- a/src/test/recovery/t/006_logical_decoding.pl
+++ b/src/test/recovery/t/006_logical_decoding.pl
@@ -71,6 +71,11 @@ my $endpos = $node_master->safe_psql('postgres',
 );
 print "waiting to replay $endpos\n";
 
+# Insert some rows after $endpos, which we won't read.
+$node_master->safe_psql('postgres',
+	qq[INSERT INTO decoding_test(x,y) SELECT s, s::text FROM generate_series(5,50) s;]
+);
+
 my $stdout_recv = $node_master->pg_recvlogical_upto(
 	'postgres', 'test_slot', $endpos, 180,
 	'include-xids'     => '0',
@@ -89,7 +94,7 @@ $stdout_recv = $node_master->pg_recvlogical_upto(
 	'skip-empty-xacts' => '1');
 chomp($stdout_recv);
 is($stdout_recv, '',
-	'pg_recvlogical acknowledged changes, nothing pending on slot');
+	'pg_recvlogical acknowledged changes');
 
 $node_master->safe_psql('postgres', 'CREATE DATABASE otherdb');
 

--/9DWx/yDrRhgMJTb--