Date: Tue, 30 Mar 2021 21:24:00 -0300
From: "'alvherre@alvh.no-ip.org'" <alvherre@alvh.no-ip.org>
To: "iwata.aya@fujitsu.com" <iwata.aya@fujitsu.com>
Cc: "tsunakawa.takay@fujitsu.com" <tsunakawa.takay@fujitsu.com>,
	'Kyotaro Horiguchi' <horikyota.ntt@gmail.com>,
	"tgl@sss.pgh.pa.us" <tgl@sss.pgh.pa.us>,
	"k.jamison@fujitsu.com" <k.jamison@fujitsu.com>,
	"pgsql-hackers@lists.postgresql.org" <pgsql-hackers@lists.postgresql.org>
Subject: Re: libpq debug log
Message-ID: <20210331002400.GA21316@alvherre.pgsql>
MIME-Version: 1.0
Content-Type: text/plain; charset=iso-8859-1
Content-Disposition: inline
Content-Transfer-Encoding: 8bit
In-Reply-To: <20210330235255.GA17949@alvherre.pgsql>
User-Agent: Mutt/1.10.1 (2018-07-13)
Archived-At: 
 <https://www.postgresql.org/message-id/20210331002400.GA21316%40alvherre.pgsql>
Precedence: bulk


So crake failed.  The failure is that it doesn't print the DataRow
messages.  That's quite odd.  We see this in the trace log:

Mar 30 20:05:15 # F	54	Parse	 "" "SELECT 1.0/g FROM generate_series(3, -1, -1) g" 0
Mar 30 20:05:15 # F	12	Bind	 "" "" 0 0 0
Mar 30 20:05:15 # F	6	Describe	 P ""
Mar 30 20:05:15 # F	9	Execute	 "" 0
Mar 30 20:05:15 # F	4	Sync
Mar 30 20:05:15 # B	4	ParseComplete
Mar 30 20:05:15 # B	4	BindComplete
Mar 30 20:05:15 # B	33	RowDescription	 1 "?column?" NNNN 0 NNNN 65535 -1 0
Mar 30 20:05:15 # B	70	ErrorResponse	 S "ERROR" V "ERROR" C "22012" M "division by zero" F "SSSS" L "SSSS" R "SSSS" \\x00
Mar 30 20:05:15 # B	5	ReadyForQuery	 I

and the expected is this:

Mar 30 20:05:15 # F	54	Parse	 "" "SELECT 1.0/g FROM generate_series(3, -1, -1) g" 0
Mar 30 20:05:15 # F	12	Bind	 "" "" 0 0 0
Mar 30 20:05:15 # F	6	Describe	 P ""
Mar 30 20:05:15 # F	9	Execute	 "" 0
Mar 30 20:05:15 # F	4	Sync
Mar 30 20:05:15 # B	4	ParseComplete
Mar 30 20:05:15 # B	4	BindComplete
Mar 30 20:05:15 # B	33	RowDescription	 1 "?column?" NNNN 0 NNNN 65535 -1 0
Mar 30 20:05:15 # B	32	DataRow	 1 22 '0.33333333333333333333'
Mar 30 20:05:15 # B	32	DataRow	 1 22 '0.50000000000000000000'
Mar 30 20:05:15 # B	32	DataRow	 1 22 '1.00000000000000000000'
Mar 30 20:05:15 # B	70	ErrorResponse	 S "ERROR" V "ERROR" C "22012" M "division by zero" F "SSSS" L "SSSS" R "SSSS" \\x00
Mar 30 20:05:15 # B	5	ReadyForQuery	 I


...

I wonder if this is a libpq pipeline problem rather than a PQtrace
problem.  In that test case we're using the libpq singlerow mode, so we
should see three rows before the error is sent, but for some reason
crake is not doing that.

aborted pipeline... NOTICE:  table "pq_pipeline_demo" does not exist, skipping
ok
got expected ERROR:  cannot insert multiple commands into a prepared statement
got expected division-by-zero
ok 5 - libpq_pipeline pipeline_abort
not ok 6 - pipeline_abort trace match


Other hosts seem to get it right:

# Running: libpq_pipeline -t /Users/buildfarm/bf-data/HEAD/pgsql.build/src/test/modules/libpq_pipeline/tmp_check/log/pipeline_abort.trace pipeline_abort port=49797 host=/var/folders/md/8mp8j5m5169ccgy11plb4w_80000gp/T/iA9YP9_IHa dbname='postgres' 10000
aborted pipeline... NOTICE:  table "pq_pipeline_demo" does not exist, skipping
ok
got expected ERROR:  cannot insert multiple commands into a prepared statement
got row: 0.33333333333333333333
got row: 0.50000000000000000000
got row: 1.00000000000000000000
got expected division-by-zero
ok 5 - libpq_pipeline pipeline_abort
ok 6 - pipeline_abort trace match


-- 
Álvaro Herrera       Valdivia, Chile
"This is what I like so much about PostgreSQL.  Most of the surprises
are of the "oh wow!  That's cool" Not the "oh shit!" kind.  :)"
Scott Marlowe, http://archives.postgresql.org/pgsql-admin/2008-10/msg00152.php