Re: bailing out in tap tests nearly always a bad idea

Hi,

On 2022-02-22 09:28:37 -0800, Andres Freund wrote:
> On 2022-02-14 09:46:20 -0800, Andres Freund wrote:
> > > t/die-immediately.t .... aieee at t/die-immediately.t line 1.
> > > t/die-immediately.t .... Dubious, test returned 255 (wstat 65280, 0xff00)
> > > No subtests run
> >
> > Hm. Looks different when a test is including our test helpers.
> >
> > t/000_die_pg_test_utils.pl .. Dubious, test returned 25 (wstat 6400, 0x1900)
> > No subtests run
> > t/000_die_test_more.pl ...... error at t/000_die_test_more.pl line 2.
> > t/000_die_test_more.pl ...... Dubious, test returned 255 (wstat 65280, 0xff00)
> > No subtests run
> >
> > So I think we broke something... I think it's the log file redirection stuff
> > in INIT.
>
> Any chance somebody with more perl knowledge could look into this? Clearly our
> effort to copy all the output the original file descriptors isn't successful
> here.
>
> $ perl -I /home/andres/src/postgresql/src/test/perl/ -e "use PostgreSQL::Test::Utils; die 'blorb';"
> $ perl -I /home/andres/src/postgresql/src/test/perl/ -e "use Test::More; die 'blorb';"
> blorb at -e line 1.

So the problem is that die just outputs to stderr, but we've decided to have
stderr connected to the output going to tap for some reason. I guess that
prevents us from messing up the tap output, but it's still weird. Because of
that redirection, die printing to stderr isn't visible to tap.

Seems we can use black magic to "fix" that... Putting the following into
INIT{} seems to do the trick:

# Because of the above redirection the tap output wouldn't contain
# information about tests failing due to die etc. Fix that by also
# printing the failure to the original stderr.
$SIG{__DIE__} = sub
{
# Don't redirect if it's a syntax error ($^S is undefined) or in an
# eval block ($^S == 1).
if (defined $^S and $^S == 0)
{
print $orig_stderr "$_[0]\n";
#fail("died: $_[0]");
#done_testing();
}
};

$ cat /tmp/die_pg_utils.pl
use PostgreSQL::Test::Utils;
use Test::More;

ok(1, "foo");
die 'blorb';
done_testing();

With the print we get something like:

$ perl -I /home/andres/src/postgresql/src/test/perl/ /tmp/die_pg_utils.pl
ok 1 - foo
blorb at /tmp/die_pg_utils.pl line 5.

# Tests were run but no plan was declared and done_testing() was not seen.
# Looks like your test exited with 25 just after 1.

With the fail() and done_testing() we get

$ perl -I /home/andres/src/postgresql/src/test/perl/ /tmp/die_pg_utils.pl
ok 1 - foo
not ok 2 - died: blorb at /tmp/die_pg_utils.pl line 5.
#
# Failed test 'died: blorb at /tmp/die_pg_utils.pl line 5.
# '
# at /home/andres/src/postgresql/src/test/perl/PostgreSQL/Test/Utils.pm line 235.
1..2
# Looks like your test exited with 25 just after 2.

The latter output doesn't confuse with stuff about plans and exit codes. But
contains redundant messages (whatever) and it doesn't seem particularly clean
to hijack a "test number".

Greetings,

Andres Freund