Thread: [HACKERS] Inadequate traces in TAP tests
If you look at this failure case <https://buildfarm.postgresql.org/cgi-bin/show_log.pl?nm=jacana&dt=2017-03-19%2000%3A00%3A18> you see: t/002_pg_dump.........1..4449 # Looks like your test died before it could output anything. dubious Test returnedstatus 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. 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.. Thoughts? cheers andrew -- Andrew Dunstan https://www.2ndQuadrant.com PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
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&dt=2017-03-19%2000%3A00%3A18> > 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
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
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
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
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
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