Inadequate traces in TAP tests

Andrew,

* Andrew Dunstan (andrew.dunstan@2ndquadrant.com) wrote:

If you look at this failure case
<https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=jacana&amp;dt=2017-03-19%2000%3A00%3A18&gt;
you see:

t/002_pg_dump.........1..4449
# Looks like your test died before it could output anything.
dubious
Test returned status 255 (wstat 65280, 0xff00)
DIED. FAILED tests 1-4449
Failed 4449/4449 tests, 0.00% okay

That's really not helpful. We have no idea where things went wrong.

The detail is in the logs, which is where I discovered the issue with
collations not being supported on all platforms and added a check to
skip the collation tests on those platforms.

ISTM that the test setup and breakdown code, both in individual tests
and in PostgresNode.pm should be liberally sprinkled with diag() calls
to make it easier to narrow down errors..

While I'm generally in favor of adding diag() info into the testing for
when things go wrong, what I don't want to do is increase the amount of
output that these tests produce without good cause. I really wish there
was a "quiet" mode for the TAP tests which didn't report anything when
things are 'ok'.

Thanks!

Stephen

Stephen Frost <sfrost@snowman.net> writes:

* Andrew Dunstan (andrew.dunstan@2ndquadrant.com) wrote:

ISTM that the test setup and breakdown code, both in individual tests
and in PostgresNode.pm should be liberally sprinkled with diag() calls
to make it easier to narrow down errors..

While I'm generally in favor of adding diag() info into the testing for
when things go wrong, what I don't want to do is increase the amount of
output that these tests produce without good cause. I really wish there
was a "quiet" mode for the TAP tests which didn't report anything when
things are 'ok'.

FWIW, the problem I've got with the TAP tests is that when one fails
in the buildfarm, you've got to dig through megabytes of all-alike-looking
output just to try to determine which one failed; and once you do, you
still know nothing because the script output never really says why it
thinks there was a problem. If you're lucky, you can identify the
postmaster log file(s) corresponding to the failed test script, and then
you can try to guess from the log entries what went wrong.

I am *absolutely* not in favor of adding anything to the scripts' routine
output, because it will just make this problem worse by bloating the
buildfarm logs even more. What I'd like to see is for the scripts to
always report something along the lines of "this is what I got, this is
what I expected to get" --- but only when there is a failure. The less
output there is from a successful test, the better, IMO.

regards, tom lane

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Stephen Frost wrote:

Andrew,

* Andrew Dunstan (andrew.dunstan@2ndquadrant.com) wrote:

ISTM that the test setup and breakdown code, both in individual tests
and in PostgresNode.pm should be liberally sprinkled with diag() calls
to make it easier to narrow down errors..

While I'm generally in favor of adding diag() info into the testing for
when things go wrong, what I don't want to do is increase the amount of
output that these tests produce without good cause. I really wish there
was a "quiet" mode for the TAP tests which didn't report anything when
things are 'ok'.

That's diag's idea; you use it like
"ok() or diag('failed because of snow')".
so nothing is printed unless there is a problem. You're not supposed to
call it unconditionally.

Something that would probably be helpful would be to put the server log
lines corresponding to the failure in diag(); for example we could keep
the log file open, do a seek(SEEK_END) just before running the test, and
reading from that point onwards; probably stop reading after 5 lines or
so. They wouldn't be output unless there is a failure. (Of course,
this'd have to be done in the harness, not the test itself, to avoid
cluttering already ugly individual test files.)

--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

On 20 Mar. 2017 22:10, "Tom Lane" <tgl@sss.pgh.pa.us> wrote:

FWIW, the problem I've got with the TAP tests is that when one fails
in the buildfarm, you've got to dig through megabytes of all-alike-looking
output just to try to determine which one failed; and once you do, you
still know nothing because the script output never really says why it
thinks there was a problem.

Yeah, it's not super helpful.

I'd like to enable Carp's features to use confess for traces, and switch
all use of die to that. We could learn a lot about unplanned-for test
failures where a test script dies rather than failing a test if we used
carp effectively.

If you're lucky, you can identify the
postmaster log file(s) corresponding to the failed test script

What's the problem with doing that?

Maybe we need to structure the build farm output better. Send an archive of
tmp_check/logs/ or mime-multipart it or something, so it's all cleanly
split up.

I am *absolutely* not in favor of adding anything to the scripts' routine
output, because it will just make this problem worse by bloating the
buildfarm logs even more. What I'd like to see is for the scripts to
always report something along the lines of "this is what I got, this is
what I expected to get" --- but only when there is a failure.

That's what they -should- do already, with 'ok', 'is', etc tests. Though
sometimes diagnostic output is useful we should be using 'note' to dump it
in the script's log, not in its main output. Whenever possible we should be
using TAP facilities to only emit it when there is a failure - most
usefully just by testing the test return code e.g.

if (!is(some_test, 1, 'test description')) {
diag "useful info: $relevant_variable";
}

TAP has a diag like function that dumps data structures too, Data::Dumper
style.

Hm. Maybe the tap test readme needs a mini test writing style guide. Very
mini.

BTW I've used diag in a few and those should be either changed to note or
moved to post-fail. Will post a patch.

The less
output there is from a successful test, the better, IMO.

The trouble there is that we don't always know we're going to fail. Nor
will we always fail in a clean, anticipated way. A test script might die
because some setup it does fails with an unexpected ERROR for example.

That's why I think some diagnostic output is good. But it should definitely
be in the script logs not the main TAP output. And it should be moderate.

Alvaro,

* Alvaro Herrera (alvherre@2ndquadrant.com) wrote:

Stephen Frost wrote:

* Andrew Dunstan (andrew.dunstan@2ndquadrant.com) wrote:

ISTM that the test setup and breakdown code, both in individual tests
and in PostgresNode.pm should be liberally sprinkled with diag() calls
to make it easier to narrow down errors..

While I'm generally in favor of adding diag() info into the testing for
when things go wrong, what I don't want to do is increase the amount of
output that these tests produce without good cause. I really wish there
was a "quiet" mode for the TAP tests which didn't report anything when
things are 'ok'.

That's diag's idea; you use it like
"ok() or diag('failed because of snow')".
so nothing is printed unless there is a problem. You're not supposed to
call it unconditionally.

That seems reasonable then.

Something that would probably be helpful would be to put the server log
lines corresponding to the failure in diag(); for example we could keep
the log file open, do a seek(SEEK_END) just before running the test, and
reading from that point onwards; probably stop reading after 5 lines or
so. They wouldn't be output unless there is a failure. (Of course,
this'd have to be done in the harness, not the test itself, to avoid
cluttering already ugly individual test files.)

Agreed, this should be in the harness.

Is there any hope of getting a "quiet" mode, where all the "ok" lines
aren't printed when things work..?

Thanks!

Stephen

On 03/20/2017 10:08 AM, Tom Lane wrote:

I am *absolutely* not in favor of adding anything to the scripts' routine
output, because it will just make this problem worse by bloating the
buildfarm logs even more. What I'd like to see is for the scripts to
always report something along the lines of "this is what I got, this is
what I expected to get" --- but only when there is a failure. The less
output there is from a successful test, the better, IMO.

The problem in the current instance is that the error occurred before it
ever tried to run a test. It died in the setup code for the test set.

cheers

andrew

--

Andrew Dunstan https://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Stephen Frost wrote:

Is there any hope of getting a "quiet" mode, where all the "ok" lines
aren't printed when things work..?

Well, we currently have --verbose in PROVE_FLAGS. Maybe you can take it
out, or even add --quiet or --QUIET (see the prove(1) manpage).

--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Alvaro,

* Alvaro Herrera (alvherre@2ndquadrant.com) wrote:

Stephen Frost wrote:

Is there any hope of getting a "quiet" mode, where all the "ok" lines
aren't printed when things work..?

Well, we currently have --verbose in PROVE_FLAGS. Maybe you can take it
out, or even add --quiet or --QUIET (see the prove(1) manpage).

Ok, yes, removing --verbose got rid of the per-test 'ok' lines, making
the output quite a bit nicer, at least to me.

Thanks!

Stephen

On 03/20/2017 10:25 AM, Craig Ringer wrote:

I'd like to enable Carp's features to use confess for traces, and
switch all use of die to that. We could learn a lot about
unplanned-for test failures where a test script dies rather than
failing a test if we used carp effectively.

Good idea. But there is no obvious call to die() or BAIL_OUT() that's
causing the error I saw.

cheers

andrew

--
Andrew Dunstan https://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

Andrew,

* Andrew Dunstan (andrew.dunstan@2ndquadrant.com) wrote:

On 03/20/2017 10:25 AM, Craig Ringer wrote:

I'd like to enable Carp's features to use confess for traces, and
switch all use of die to that. We could learn a lot about
unplanned-for test failures where a test script dies rather than
failing a test if we used carp effectively.

Good idea. But there is no obvious call to die() or BAIL_OUT() that's
causing the error I saw.

I'll look at adding that. I should be able to get the psql output with
the ERROR in it and that's mainly what you'll want for this.

Thanks!

Stephen

On 20 March 2017 at 22:39, Alvaro Herrera <alvherre@2ndquadrant.com> wrote:

Stephen Frost wrote:

Is there any hope of getting a "quiet" mode, where all the "ok" lines
aren't printed when things work..?

Well, we currently have --verbose in PROVE_FLAGS. Maybe you can take it
out, or even add --quiet or --QUIET (see the prove(1) manpage).

If so, please preserve the current behaviour via something like

$(or $(PROVE_VERBOSITY),'--quiet')

since it's very useful to have more output when running individual
tests interactively.

--
Craig Ringer http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers