Feedback-ID: id4a34324:Fastmail
Date: Mon, 26 Jan 2026 11:42:16 -0500
From: Andres Freund <andres@anarazel.de>
To: Jelte Fennema-Nio <postgres@jeltef.nl>
Cc: PostgreSQL Hackers <pgsql-hackers@lists.postgresql.org>, 
	Nazir Bilal Yavuz <byavuz81@gmail.com>
Subject: Re: meson: Make test output much more useful on failure (both in CI
 and locally)
Message-ID: <luhx26gz3tiqkndldbobukt4zeaeu2ppd5qgsibf6hknhq6d7e@kngeuarhk5dg>
References: <DFYFWM053WHS.10K8ZPJ605UFK@jeltef.nl>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <DFYFWM053WHS.10K8ZPJ605UFK@jeltef.nl>
Archived-At: <https://www.postgresql.org/message-id/luhx26gz3tiqkndldbobukt4zeaeu2ppd5qgsibf6hknhq6d7e%40kngeuarhk5dg>
Precedence: bulk

Hi,

On 2026-01-26 11:13:57 +0100, Jelte Fennema-Nio wrote:
> I've gotten totally fed up with the amount of clicking I need to do
> every time a test fails in CI to find out what exactly failed. The
> output that meson gives in its main output is completely useless
> currently.

This doesn't really seem meson specific, right? It just seems about the output
of our own test tooling?

Meson can't really output something that we hide from it...

I agree that what we currently do is pretty unhelpful.


> Subject: [PATCH v1 1/5] meson: Include pg_regress diffs in meson output

This isn't about meson, it's about adding a new argument to pg_regress.


I think we'd need to limit the size of the output here somewhat. If e.g. the
server crashes, you end up with all subsequent tests failing and printing out
a couple hundred kB of pointless diff output.


> @@ -1521,22 +1523,40 @@ results_differ(const char *testname, const char *resultsfile, const char *defaul
>  	 * append to the diffs summary file.
>  	 */
>  
> -	/* Write diff header */
> -	difffile = fopen(difffilename, "a");
> +	difffile = fopen(difffilename, "a+");
>  	if (difffile)
>  	{
> +		fseek(difffile, 0, SEEK_END);
> +		startpos = ftell(difffile);
>  		fprintf(difffile,
>  				"diff %s %s %s\n",
>  				pretty_diff_opts, best_expect_file, resultsfile);
> +		fflush(difffile);
> +
> +		/* Run diff */
> +		snprintf(cmd, sizeof(cmd),
> +				 "diff %s \"%s\" \"%s\" >> \"%s\"",
> +				 pretty_diff_opts, best_expect_file, resultsfile, difffilename);
> +		run_diff(cmd, difffilename);
> +
> +		/* Emit diff as TAP diagnostics if requested */
> +		if (print_diffs)
> +		{
> +			char		line[1024];
> +
> +			fseek(difffile, startpos, SEEK_SET);
> +			while (fgets(line, sizeof(line), difffile))
> +			{
> +				size_t		len = strlen(line);
> +
> +				if (len > 0 && line[len - 1] == '\n')
> +					line[len - 1] = '\0';
> +				diag("%s", line);
> +			}
> +		}
>  		fclose(difffile);
>  	}

I'm a bit confused. Why are we rerunning diffs and appending to the diff file?


> From c1db07a8bba54e6b903766585f1b521ef526de12 Mon Sep 17 00:00:00 2001
> From: Jelte Fennema-Nio <postgres@jeltef.nl>
> Date: Mon, 26 Jan 2026 09:09:11 +0100
> Subject: [PATCH v1 2/5] perl tap: Show failed command output
> 
> This adds the output of failed commands to the TAP output. Before a
> failed libpq_pipeline test would look like this:
> 
>   Failed test 'libpq_pipeline cancel'
>   at /home/jelte/work/postgres-3/src/test/modules/libpq_pipeline/t/001_libpq_pipeline.pl line 55.
> 
> Now you can actually see the reason of the failure:
> 
>   Failed test 'libpq_pipeline cancel'
>   at /home/jelte/work/postgres-3/src/test/modules/libpq_pipeline/t/001_libpq_pipeline.pl line 55.
> ----- command failed -----
> libpq_pipeline -r 700 cancel port=14309 host=/tmp/htMib451qD dbname='postgres' max_protocol_version=latest
> --------- stderr ---------
> test cancellations...
> libpq_pipeline:315: unexpected number of rows received: 1
> --------------------------
> ---
>  src/test/perl/PostgreSQL/Test/Utils.pm | 36 +++++++++++++++++++++++---
>  1 file changed, 32 insertions(+), 4 deletions(-)
> 
> diff --git a/src/test/perl/PostgreSQL/Test/Utils.pm b/src/test/perl/PostgreSQL/Test/Utils.pm
> index ff843eecc6e..bd1e981c6f0 100644
> --- a/src/test/perl/PostgreSQL/Test/Utils.pm
> +++ b/src/test/perl/PostgreSQL/Test/Utils.pm
> @@ -955,8 +955,22 @@ sub command_ok
>  {
>  	local $Test::Builder::Level = $Test::Builder::Level + 1;
>  	my ($cmd, $test_name) = @_;
> -	my $result = run_log($cmd);
> -	ok($result, $test_name);
> +	# Doesn't rely on detecting end of file on the file descriptors,
> +	# which can fail, causing the process to hang, notably on Msys
> +	# when used with 'pg_ctl start'
> +	my $stdoutfile = File::Temp->new();
> +	my $stderrfile = File::Temp->new();

I'm afraid that the creation of this many additional tempfiles would slow down
the tests on some platforms...

> +	my $result = IPC::Run::run $cmd, '>' => $stdoutfile, '2>' => $stderrfile;
> +	ok($result, $test_name) or do
> +	{
> +		my $stdout = slurp_file($stdoutfile);
> +		my $stderr = slurp_file($stderrfile);
> +		diag("----- command failed -----");
> +		diag(join(" ", @$cmd));
> +		diag("--------- stdout ---------"), diag($stdout) if $stdout;
> +		diag("--------- stderr ---------"), diag($stderr) if $stderr;
> +		diag("--------------------------");
> +	};

Outputting the entire file seems to again have the danger of completely
swamping the output.

>  	return;
>  }
>  
> @@ -972,8 +986,22 @@ sub command_fails
>  {
>  	local $Test::Builder::Level = $Test::Builder::Level + 1;
>  	my ($cmd, $test_name) = @_;
> -	my $result = run_log($cmd);
> -	ok(!$result, $test_name);
> +	# Doesn't rely on detecting end of file on the file descriptors,
> +	# which can fail, causing the process to hang, notably on Msys
> +	# when used with 'pg_ctl start'

Huh? Any more details?

> +	my $stdoutfile = File::Temp->new();
> +	my $stderrfile = File::Temp->new();
> +	my $result = IPC::Run::run $cmd, '>' => $stdoutfile, '2>' => $stderrfile;
> +	ok(!$result, $test_name) or do
> +	{
> +		my $stdout = slurp_file($stdoutfile);
> +		my $stderr = slurp_file($stderrfile);
> +		diag("-- command succeeded unexpectedly --");
> +		diag(join(" ", @$cmd));
> +		diag("-------------- stdout --------------"), diag($stdout) if $stdout;
> +		diag("-------------- stderr --------------"), diag($stderr) if $stderr;
> +		diag("------------------------------------");
> +	};

I don't think it makes sense to duplicate the logic for this multiple times.


> From c88f1fbf6462da56a1f0739dd83a6284d6bdd389 Mon Sep 17 00:00:00 2001
> From: Jelte Fennema-Nio <postgres@jeltef.nl>
> Date: Mon, 26 Jan 2026 09:32:15 +0100
> Subject: [PATCH v1 3/5] perl tap: Show die reason in TAP output
>...
> diff --git a/src/test/perl/PostgreSQL/Test/Utils.pm b/src/test/perl/PostgreSQL/Test/Utils.pm
> index bd1e981c6f0..df328d0f571 100644
> --- a/src/test/perl/PostgreSQL/Test/Utils.pm
> +++ b/src/test/perl/PostgreSQL/Test/Utils.pm
> @@ -206,6 +206,14 @@ INIT
>  	# test may still fail, but it's more likely to report useful facts.
>  	$SIG{PIPE} = 'IGNORE';
>  
> +	# Emit die messages as TAP diagnostics so they appear in test output.
> +	$SIG{__DIE__} = sub {
> +		return if $^S;    # Ignore dies inside eval
> +		my $msg = shift;
> +		chomp $msg;
> +		diag("die: $msg");
> +	};
> +

This looked familiar - turns out I had complained about this in the past and
then forgotten about it :(

https://www.postgresql.org/message-id/20220222181924.eehi7o4pmneeb4hm%40alap3.anarazel.de

At least at the time I found it necessary to separately test for $^S, to avoid
triggering the logic for syntax errors.  Not sure why I concluded that though.

In a reply Andrew suggested to use done_testing(), which avoids the pointless
  "Tests were run but no plan was declared and done_testing() was not seen."
which does seem like an improvement.


> From a6b324678293d65f3a417b8f66889b3f3f6a9c29 Mon Sep 17 00:00:00 2001
> From: Jelte Fennema-Nio <postgres@jeltef.nl>
> Date: Mon, 26 Jan 2026 10:04:44 +0100
> Subject: [PATCH v1 4/5] perl tap: Include caller in die messages of psql
> 
> This way by looking at the error output you can actually figure out
> where it occured, instead of just knowing that is in the very often
> called psql function.

I think this is too localized a fix. Right now every die in a .pm file has
this issue.  The easiest fix would probably be to just replace all uses of die
in .pm files with croak (which we already, inconsistently, use).

stderr:
# die: error running SQL: 'psql:<stdin>:1: ERROR:  syntax error at or near "I"
# LINE 1: I am the worst
#         ^'
# while running 'psql --no-psqlrc --no-align --tuples-only --quiet --dbname port=20878 host=/tmp/K5V48mzFx9 dbname='postgres' --file - --variable ON_ERROR_STOP=1' with sql 'I am the worst' at /home/andres/src/postgresql/src/bin/scripts/t/020_createdb.pl line 19.

Note that the failure now is reported as coming from the actual test file.


We could also use Test::More->builder->croak(), but that's a heck of a lot
longer, and would require us to be more liberal about sprinkling

	local $Test::Builder::Level = $Test::Builder::Level + 1;
around. I don't see an improvement in the output either.

In contrast Carp.pm just looks for a caller outside of the current package. If
we are worried about errors across Cluster.pm/Utils.pm, we could just fix that
in one place by using @CARP_NOT.

Maybe there's a way to do that more centrally?

Greetings,

Andres Freund