Feedback-ID: i0fe9450f:Fastmail
Date: Mon, 21 Apr 2025 15:22:28 +0900
From: Michael Paquier <michael@paquier.xyz>
To: "a.kozhemyakin" <a.kozhemyakin@postgrespro.ru>
Cc: Daniel Verite <daniel@manitou-mail.org>,
	Anthonin Bonnefoy <anthonin.bonnefoy@datadoghq.com>,
	Jelte Fennema-Nio <postgres@jeltef.nl>,
	PostgreSQL Hackers <pgsql-hackers@postgresql.org>
Subject: Re: Add Pipelining support in psql
Message-ID: <aAXkJIOildLUA7vQ@paquier.xyz>
References: <CAO6_Xqroaof=Gu_NCg4bZfpdgwOjNW9fg753cuuts-FBnv9UGw@mail.gmail.com>
 <a96682c3-9505-456f-b5c7-1b9d1e6303b4@manitou-mail.org>
 <Z8kilUVjYAHko17g@paquier.xyz>
 <ebf6ce77-b180-4d6b-8eab-71f641499ddf@postgrespro.ru>
 <Z__YOQJqBJYhezm2@paquier.xyz>
MIME-Version: 1.0
Content-Type: multipart/signed; micalg=pgp-sha512;
	protocol="application/pgp-signature"; boundary="Ve7KesJZF/ELFuMh"
Content-Disposition: inline
In-Reply-To: <Z__YOQJqBJYhezm2@paquier.xyz>
Archived-At: <https://www.postgresql.org/message-id/aAXkJIOildLUA7vQ%40paquier.xyz>
Precedence: bulk


--Ve7KesJZF/ELFuMh
Content-Type: multipart/mixed; boundary="tPTN7wbpNh+FjgHs"
Content-Disposition: inline


--tPTN7wbpNh+FjgHs
Content-Type: text/plain; charset=iso-8859-1
Content-Disposition: inline
Content-Transfer-Encoding: quoted-printable

On Wed, Apr 16, 2025 at 09:18:01AM -0700, Michael Paquier wrote:
> On Wed, Apr 16, 2025 at 09:31:59PM +0700, a.kozhemyakin wrote:
>> After commit 2cce0fe on master
>>=20
>> ERROR:=A0 unexpected message type 0x50 during COPY from stdin
>> CONTEXT:=A0 COPY psql_pipeline, line 1
>> Pipeline aborted, command did not run
>> psql: common.c:1510: discardAbortedPipelineResults: Assertion `res =3D=
=3D ((void
>> *)0) || result_status =3D=3D PGRES_PIPELINE_ABORTED' failed.
>> Aborted (core dumped)
>=20
> Reproduced here, thanks for the report.  I'll look at that at the
> beginning of next week, adding an open item for now.

The failure is not related to 2cce0fe.  The following sequence fails
as well, as long as we have one SELECT after the COPY to mess up with
the \getresults that causes a PGRES_FATAL_ERROR combined with a
"terminating connection because protocol synchronization was lost" on
the backend side, because the server expects some data while the
client does not send it but psql is not able to cope with this state:
\startpipeline
COPY psql_pipeline FROM STDIN \bind \sendpipeline
SELECT $1 \bind 'val1' \sendpipeline
\syncpipeline
\getresults
\endpipeline

It's actually nice that we are able to emulate such query patterns
with psql using all these meta-commands, I don't think we have
any coverage for the backend synchronization loss case yet like this
one?

2cce0fe makes that easier to reach by allowing more command patterns,
but it's the mix of COPY followed by a SELECT that causes psql to be
confused.  All the tests that we have don't check this kind of
scenarios, for COPY TO/FROM, with always use a flush or a sync
followed quickly by \getresults, but we don't have tests where we mix
things.

Anyway, I don't think that there is much we can do under a
PGRES_FATAL_ERROR in this code path when discarding the pipe results.
As far as I can tell, the server has failed the query suddenly and the
whole pipeline flow is borked.  The best thing that I can think of is
to discard all the results while decrementing the counters, then let
psql complain about that like in the attached.  I've added two tests
in TAP, as these trigger a FATAL in the backend so we cannot use the
normal SQL route, so as we have some coverage.

@Anthonin: Any thoughts or comments, perhaps?  A second opinion would
be welcome here.
--
Michael

--tPTN7wbpNh+FjgHs
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
	filename="0001-psql-Fix-assertion-failure-with-pipeline-mode.patch"
Content-Transfer-Encoding: quoted-printable

=46rom cec3613b43f536ec1f91a75a034264ed304cd628 Mon Sep 17 00:00:00 2001
=46rom: Michael Paquier <michael@paquier.xyz>
Date: Mon, 21 Apr 2025 15:17:43 +0900
Subject: [PATCH] psql: Fix assertion failure with pipeline mode

---
 src/bin/psql/common.c       | 20 ++++++++++++++++++++
 src/bin/psql/t/001_basic.pl | 35 +++++++++++++++++++++++++++++++----
 2 files changed, 51 insertions(+), 4 deletions(-)

diff --git a/src/bin/psql/common.c b/src/bin/psql/common.c
index 21d660a8961a..6eb56d7bb66e 100644
--- a/src/bin/psql/common.c
+++ b/src/bin/psql/common.c
@@ -1478,6 +1478,26 @@ discardAbortedPipelineResults(void)
 			 */
 			return res;
 		}
+		else if (result_status =3D=3D PGRES_FATAL_ERROR)
+		{
+			/*
+			 * Fatal error found from a query execution failure, there is not
+			 * much that can be done, so give up and clear all the results
+			 * available.  There may be more than one result stacked.
+			 */
+			PQclear(res);
+
+			if (pset.available_results > 0)
+				pset.available_results--;
+			if (pset.requested_results > 0)
+				pset.requested_results--;
+
+			/* leave if no more results */
+			if (pset.requested_results =3D=3D 0)
+				return NULL;
+			else
+				continue;
+		}
 		else if (res =3D=3D NULL)
 		{
 			/* A query was processed, decrement the counters */
diff --git a/src/bin/psql/t/001_basic.pl b/src/bin/psql/t/001_basic.pl
index 739cb4397087..91c56cd7c08c 100644
--- a/src/bin/psql/t/001_basic.pl
+++ b/src/bin/psql/t/001_basic.pl
@@ -34,11 +34,13 @@ sub psql_fails_like
 {
 	local $Test::Builder::Level =3D $Test::Builder::Level + 1;
=20
-	my ($node, $sql, $expected_stderr, $test_name) =3D @_;
+	my ($node, $sql, $expected_stderr, $test_name, $replication) =3D @_;
+
+	# Use the context of a WAL sender, if requested by the caller.
+	$replication =3D '' unless defined($replication);
=20
-	# Use the context of a WAL sender, some of the tests rely on that.
 	my ($ret, $stdout, $stderr) =3D
-	  $node->psql('postgres', $sql, replication =3D> 'database');
+	  $node->psql('postgres', $sql, replication =3D> $replication);
=20
 	isnt($ret, 0, "$test_name: exit code not 0");
 	like($stderr, $expected_stderr, "$test_name: matches");
@@ -79,7 +81,8 @@ psql_fails_like(
 	$node,
 	'START_REPLICATION 0/0',
 	qr/unexpected PQresultStatus: 8$/,
-	'handling of unexpected PQresultStatus');
+	'handling of unexpected PQresultStatus',
+	'database');
=20
 # test \timing
 psql_like(
@@ -481,4 +484,28 @@ psql_like($node, "copy (values ('foo'),('bar')) to std=
out \\g | $pipe_cmd",
 my $c4 =3D slurp_file($g_file);
 like($c4, qr/foo.*bar/s);
=20
+# Tests with pipelines.  These trigger FATAL failures in the backend,
+# so they cannot be tested through the SQL regression tests.
+$node->safe_psql('postgres', 'CREATE TABLE psql_pipeline()');
+psql_fails_like(
+	$node,
+	qq{\\startpipeline
+COPY psql_pipeline FROM STDIN;
+SELECT 'val1';
+\\syncpipeline
+\\getresults
+\\endpipeline},
+	qr/unexpected message type 0x50 during COPY from stdin/,
+	'handling of protocol synchronization loss with pipelines');
+psql_fails_like(
+	$node,
+	qq{\\startpipeline
+COPY psql_pipeline FROM STDIN \\bind \\sendpipeline
+SELECT 'val1' \\bind \\sendpipeline
+\\syncpipeline
+\\getresults
+\\endpipeline},
+	qr/unexpected message type 0x50 during COPY from stdin/,
+	'handling of protocol synchronization loss with pipelines');
+
 done_testing();
--=20
2.49.0


--tPTN7wbpNh+FjgHs--

--Ve7KesJZF/ELFuMh
Content-Type: application/pgp-signature; name="signature.asc"

-----BEGIN PGP SIGNATURE-----

iQIzBAABCgAdFiEEG72nH6vTowiyblFKnvQgOdbyQH0FAmgF5CQACgkQnvQgOdby
QH1uyg//VLEhBZoakgt9Z3oZGRmsRPW6Q4gSMBFXGTZDmTq2DZetQwTv+/cPnON8
d1xVqLVkTu+H91D1KDyYm2P8lvq7zjlIHTPJtTEqsDZ1TQSSc1fNm03F5aIVURKJ
M2GE1EQTIn87AIUh+acrJHSz/TI5dgIVMQA4iZDoXP0dtOE3bJ1oYz89Tgy2/xWw
fmkxh4Z1du0NrYm4Xuohnhz5S6IWjTb7AjRBRwEjUA77ts0rO84VqZ8vaLWvBrAn
9zwtKbhOELsH8X/VGlVBb8hPGPzvzhZ8e4+st+bieUkrZCtAJlMn6iHcqOnIneNd
TeelYtQF+rUK7xN+TVmtXksm9iU/HrPiqBPTmbHZzJKeM44msmf/Mt0nk/5lSRtp
AfmH4rNdBjwyztxrBuVUKORrkddL/Lyom/+zokMjBy39Pb+/SBbjAGtm+gijuKM2
u+ZaVJm7rXa3C7QTd6jJZbe+MVtpCqJBE2VOYuqfpMcye8SOshIBUuMDtlViSCEq
sfV1mZtm57KSwxKM67BAXc14jwnY9dvVr+VT3450Buz8/VTScq0qqBQT0jHVw7e0
smQijF6rWUX2MFxsS7pXzcG0tabGbgip4f6ojNNUsubBAldHSBHP51GomxQ/1bcz
k/DV6k9ntkJR5M/RFGTuBGyW9B6nPZjotmCRM5KYDJXWQh/QO8w=
=gXWo
-----END PGP SIGNATURE-----

--Ve7KesJZF/ELFuMh--