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. Which means I have to go click through CirrusCI its (pretty terrible) filebrowser UI searching for log files or regression.diffs.
And locally I have the exact same problem when a perl test is failing. Meson often shows no useful output at all, which means I have to find some unknown log file somewhere in my build directory. And then I have to find the useful spot in that log file that actually tells me what the error was. So attached are a few small patches that greatly improve the test output of the most common test failure reasons (at least the ones I tend to run into myself). An example CI run with some intentional failures (attached as the nocfbot patch) can be found here: https://cirrus-ci.com/task/6592551433535488
From 1d961ce0d48e73192a1e7551fbfbd3e5a8dd0495 Mon Sep 17 00:00:00 2001 From: Jelte Fennema-Nio <[email protected]> Date: Mon, 26 Jan 2026 00:16:30 +0100 Subject: [PATCH v1 5/5] Fail some tests --- src/test/authentication/t/001_password.pl | 2 +- src/test/modules/libpq_pipeline/libpq_pipeline.c | 2 +- .../modules/test_cplusplusext/expected/test_cplusplusext.out | 2 +- src/test/regress/expected/oid8.out | 2 +- src/test/regress/sql/drop_if_exists.sql | 2 -- 5 files changed, 4 insertions(+), 6 deletions(-) diff --git a/src/test/authentication/t/001_password.pl b/src/test/authentication/t/001_password.pl index f4d65ba7bae..27b1132ed45 100644 --- a/src/test/authentication/t/001_password.pl +++ b/src/test/authentication/t/001_password.pl @@ -144,7 +144,7 @@ is( $node->psql( $node->safe_psql( 'postgres', "CREATE TABLE sysuser_data (n) AS SELECT NULL FROM generate_series(1, 10); - GRANT ALL ON sysuser_data TO scram_role;"); + GRANT ALL ON sysuser_data TO scram_role '"); $ENV{"PGPASSWORD"} = 'pass'; # Create a role that contains a comma to stress the parsing. diff --git a/src/test/modules/libpq_pipeline/libpq_pipeline.c b/src/test/modules/libpq_pipeline/libpq_pipeline.c index 0fb44be32ce..eb5a1cc91e5 100644 --- a/src/test/modules/libpq_pipeline/libpq_pipeline.c +++ b/src/test/modules/libpq_pipeline/libpq_pipeline.c @@ -194,7 +194,7 @@ wait_for_connection_state(int line, PGconn *monitorConn, int procpid, if (PQresultStatus(res) != PGRES_TUPLES_OK) pg_fatal_impl(line, "could not query pg_stat_activity: %s", PQerrorMessage(monitorConn)); - if (PQntuples(res) != 1) + if (PQntuples(res) == 1) pg_fatal_impl(line, "unexpected number of rows received: %d", PQntuples(res)); if (PQnfields(res) != 1) pg_fatal_impl(line, "unexpected number of columns received: %d", PQnfields(res)); diff --git a/src/test/modules/test_cplusplusext/expected/test_cplusplusext.out b/src/test/modules/test_cplusplusext/expected/test_cplusplusext.out index ab0b04b5c5e..243fe0c2652 100644 --- a/src/test/modules/test_cplusplusext/expected/test_cplusplusext.out +++ b/src/test/modules/test_cplusplusext/expected/test_cplusplusext.out @@ -2,6 +2,6 @@ CREATE EXTENSION test_cplusplusext; SELECT test_cplusplus_add(1, 2); test_cplusplus_add -------------------- - 3 + 9 (1 row) diff --git a/src/test/regress/expected/oid8.out b/src/test/regress/expected/oid8.out index 2e114f1ce70..3711a116aae 100644 --- a/src/test/regress/expected/oid8.out +++ b/src/test/regress/expected/oid8.out @@ -6,7 +6,7 @@ INSERT INTO OID8_TBL(f1) VALUES ('1234'); INSERT INTO OID8_TBL(f1) VALUES ('1235'); INSERT INTO OID8_TBL(f1) VALUES ('987'); INSERT INTO OID8_TBL(f1) VALUES ('-1040'); -INSERT INTO OID8_TBL(f1) VALUES ('99999999'); +INSERT INTO OID8_TBL(f1) VALUES ('88888888'); INSERT INTO OID8_TBL(f1) VALUES ('5 '); INSERT INTO OID8_TBL(f1) VALUES (' 10 '); INSERT INTO OID8_TBL(f1) VALUES ('123456789012345678'); diff --git a/src/test/regress/sql/drop_if_exists.sql b/src/test/regress/sql/drop_if_exists.sql index ac6168b91f8..db4c95f8ed3 100644 --- a/src/test/regress/sql/drop_if_exists.sql +++ b/src/test/regress/sql/drop_if_exists.sql @@ -286,8 +286,6 @@ DROP FUNCTION test_ambiguous_funcname(text); -- Likewise for procedures. CREATE PROCEDURE test_ambiguous_procname(int) as $$ begin end; $$ language plpgsql; CREATE PROCEDURE test_ambiguous_procname(text) as $$ begin end; $$ language plpgsql; -DROP PROCEDURE test_ambiguous_procname; -DROP PROCEDURE IF EXISTS test_ambiguous_procname; -- Check we get a similar error if we use ROUTINE instead of PROCEDURE. DROP ROUTINE IF EXISTS test_ambiguous_procname; -- 2.52.0
From d728f54e5c4f9f2dec92a57ece528b43859800f7 Mon Sep 17 00:00:00 2001 From: Jelte Fennema-Nio <[email protected]> Date: Mon, 26 Jan 2026 00:15:30 +0100 Subject: [PATCH v1 1/5] meson: Include pg_regress diffs in meson output Whenever pg_regress fails there's an indirection to actually get to the failure reason. When running tests locally it's somewhat okay because I can copy paste the filename, but in CI I have to manually traverse the directory structure by clicking and scrolling a bunch of time. This change adds an option to pg_regress to print the diffs so that they become part of the TAP output. So meson can actually display them. --- meson.build | 1 + src/test/regress/pg_regress.c | 41 ++++++++++++++++++++++++++++------- 2 files changed, 34 insertions(+), 8 deletions(-) diff --git a/meson.build b/meson.build index df907b62da3..bbe855a3cb5 100644 --- a/meson.build +++ b/meson.build @@ -3738,6 +3738,7 @@ foreach test_dir : tests '--bindir', '', '--dlpath', test_dir['bd'], '--max-concurrent-tests=20', + '--print-diffs', '--dbname', dbname, ] + t.get('regress_args', []) diff --git a/src/test/regress/pg_regress.c b/src/test/regress/pg_regress.c index b5c0cb647a8..d057573af57 100644 --- a/src/test/regress/pg_regress.c +++ b/src/test/regress/pg_regress.c @@ -119,6 +119,7 @@ static char *dlpath = PKGLIBDIR; static char *user = NULL; static _stringlist *extraroles = NULL; static char *config_auth_datadir = NULL; +static bool print_diffs = false; /* internal variables */ static const char *progname; @@ -1414,6 +1415,7 @@ results_differ(const char *testname, const char *resultsfile, const char *defaul int best_line_count; int i; int l; + long startpos; const char *platform_expectfile; /* @@ -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); } - /* Run diff */ - snprintf(cmd, sizeof(cmd), - "diff %s \"%s\" \"%s\" >> \"%s\"", - pretty_diff_opts, best_expect_file, resultsfile, difffilename); - run_diff(cmd, difffilename); - unlink(diff); return true; } @@ -2044,6 +2064,7 @@ help(void) printf(_(" --outputdir=DIR place output files in DIR (default \".\")\n")); printf(_(" --schedule=FILE use test ordering schedule from FILE\n")); printf(_(" (can be used multiple times to concatenate)\n")); + printf(_(" --print-diffs print diffs to stdout on failure\n")); printf(_(" --temp-instance=DIR create a temporary instance in DIR\n")); printf(_(" --use-existing use an existing installation\n")); printf(_(" -V, --version output version information, then exit\n")); @@ -2096,6 +2117,7 @@ regression_main(int argc, char *argv[], {"config-auth", required_argument, NULL, 24}, {"max-concurrent-tests", required_argument, NULL, 25}, {"expecteddir", required_argument, NULL, 26}, + {"print-diffs", no_argument, NULL, 27}, {NULL, 0, NULL, 0} }; @@ -2224,6 +2246,9 @@ regression_main(int argc, char *argv[], case 26: expecteddir = pg_strdup(optarg); break; + case 27: + print_diffs = true; + break; default: /* getopt_long already emitted a complaint */ pg_log_error_hint("Try \"%s --help\" for more information.", base-commit: a9bdb63bba8a631cd4797393307eecf5fcde9167 -- 2.52.0
From c1db07a8bba54e6b903766585f1b521ef526de12 Mon Sep 17 00:00:00 2001 From: Jelte Fennema-Nio <[email protected]> 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(); + 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("--------------------------"); + }; 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' + 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("------------------------------------"); + }; return; } -- 2.52.0
From c88f1fbf6462da56a1f0739dd83a6284d6bdd389 Mon Sep 17 00:00:00 2001 From: Jelte Fennema-Nio <[email protected]> Date: Mon, 26 Jan 2026 09:32:15 +0100 Subject: [PATCH v1 3/5] perl tap: Show die reason in TAP output In our Perl tests the most commonly used function is probably safe_psql. But if that call failed you would get this totally useless output in the meson output: Tests were run but no plan was declared and done_testing() was not seen. Looks like your test exited with 29 just after 21. With this change you get the actual failure reason too: die: error running SQL: 'psql:<stdin>:2: ERROR: unterminated quoted string at or near "'" LINE 1: GRANT ALL ON sysuser_data TO scram_role ' ^' while running 'psql --no-psqlrc --no-align --tuples-only --quiet --dbname port=18204 host=/tmp/tKBBBekcsW dbname='postgres' --file - --variable ON_ERROR_STOP=1' with sql 'CREATE TABLE sysuser_data (n) AS SELECT NULL FROM generate_series(1, 10); GRANT ALL ON sysuser_data TO scram_role '' at /home/jelte/work/postgres-3/src/test/perl/PostgreSQL/Test/Cluster.pm line 2300. Tests were run but no plan was declared and done_testing() was not seen. Looks like your test exited with 29 just after 21. --- src/test/perl/PostgreSQL/Test/Utils.pm | 8 ++++++++ 1 file changed, 8 insertions(+) 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"); + }; + # Determine output directories, and create them. The base paths are the # TESTDATADIR / TESTLOGDIR environment variables, which are normally set # by the invoking Makefile. -- 2.52.0
From a6b324678293d65f3a417b8f66889b3f3f6a9c29 Mon Sep 17 00:00:00 2001 From: Jelte Fennema-Nio <[email protected]> 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. Output of a failed safe_psql call now looks like this: die: error running SQL at /home/jelte/work/postgres-3/src/test/authentication/t/001_password.pl line 144: 'psql:<stdin>:2: ERROR: unterminated quoted string at or near "'" LINE 1: GRANT ALL ON sysuser_data TO scram_role ' ^' while running 'psql --no-psqlrc --no-align --tuples-only --quiet --dbname port=15305 host=/tmp/lhu1ix_Wgj dbname='postgres' --file - --variable ON_ERROR_STOP=1' with sql 'CREATE TABLE sysuser_data (n) AS SELECT NULL FROM generate_series(1, 10); GRANT ALL ON sysuser_data TO scram_role '' at /home/jelte/work/postgres-3/src/test/perl/PostgreSQL/Test/Cluster.pm line 2305. Tests were run but no plan was declared and done_testing() was not seen. Looks like your test exited with 29 just after 21. --- src/test/perl/PostgreSQL/Test/Cluster.pm | 25 ++++++++++++++---------- 1 file changed, 15 insertions(+), 10 deletions(-) diff --git a/src/test/perl/PostgreSQL/Test/Cluster.pm b/src/test/perl/PostgreSQL/Test/Cluster.pm index e267ba868fe..68bdff2ad4e 100644 --- a/src/test/perl/PostgreSQL/Test/Cluster.pm +++ b/src/test/perl/PostgreSQL/Test/Cluster.pm @@ -2042,7 +2042,8 @@ sub safe_psql stdout => \$stdout, stderr => \$stderr, on_error_die => 1, - on_error_stop => 1); + on_error_stop => 1, + caller => [caller]); # psql can emit stderr from NOTICEs etc if ($stderr ne "") @@ -2213,6 +2214,8 @@ sub psql $$stderr = "" if ref($stderr); my $ret; + my @caller = defined $params{caller} ? @{ $params{caller} } : caller; + my $caller_location = "at $caller[1] line $caller[2]"; # Run psql and capture any possible exceptions. If the exception is # because of a timeout and the caller requested to handle that, just return @@ -2261,7 +2264,7 @@ sub psql } else { - die "psql timed out: stderr: '$$stderr'\n" + die "psql timed out $caller_location: stderr: '$$stderr'\n" . "while running '@psql_params'"; } } @@ -2284,23 +2287,25 @@ sub psql if (defined $ret) { my $core = $ret & 128 ? " (core dumped)" : ""; - die "psql exited with signal " - . ($ret & 127) - . "$core: '$$stderr' while running '@psql_params'" - if $ret & 127; + if ($ret & 127) + { + die "psql exited with signal " + . ($ret & 127) + . "$core $caller_location: '$$stderr' while running '@psql_params'"; + } $ret = $ret >> 8; } if ($ret && $params{on_error_die}) { - die "psql error: stderr: '$$stderr'\nwhile running '@psql_params'" + die "psql error $caller_location: stderr: '$$stderr'\nwhile running '@psql_params'" if $ret == 1; - die "connection error: '$$stderr'\nwhile running '@psql_params'" + die "connection error $caller_location: '$$stderr'\nwhile running '@psql_params'" if $ret == 2; die - "error running SQL: '$$stderr'\nwhile running '@psql_params' with sql '$sql'" + "error running SQL $caller_location: '$$stderr'\nwhile running '@psql_params' with sql '$sql'" if $ret == 3; - die "psql returns $ret: '$$stderr'\nwhile running '@psql_params'"; + die "psql returns $ret $caller_location: '$$stderr'\nwhile running '@psql_params'"; } if (wantarray) -- 2.52.0
