Prove "Tests out of sequence" Error
Hi, on TravisCI I see these weird "Tests out of sequence" errors with prove and they seem to not go away. I assume the reason that they not go away is that the ".prove" file is carried over from on build to another (but I can't look into this file on TravisCI). Has anyone an idea where these errors might come from? t5547-push-quarantine.sh (Wstat: 0 Tests: 5 Failed: 0) Parse errors: Tests out of sequence. Found (2) but expected (3) Tests out of sequence. Found (3) but expected (4) Tests out of sequence. Found (4) but expected (5) Bad plan. You planned 4 tests but ran 5. Files=760, Tests=15109, 679 wallclock secs (21.91 usr 1.78 sys + 320.79 cusr 529.13 csys = 873.61 CPU) Result: FAIL make[1]: *** [prove] Error 1 make: *** [test] Error 2 Example: https://s3.amazonaws.com/archive.travis-ci.org/jobs/169385219/log.txt Thanks, Lars
Re: Prove "Tests out of sequence" Error
On Thu, Oct 20, 2016 at 9:14 PM, Lars Schneider wrote: > Hi, > > on TravisCI I see these weird "Tests out of sequence" errors with prove > and they seem to not go away. I assume the reason that they not go away > is that the ".prove" file is carried over from on build to another (but I > can't > look into this file on TravisCI). > > Has anyone an idea where these errors might come from? > > > t5547-push-quarantine.sh (Wstat: 0 Tests: 5 Failed: 0) push quarantine is a new thing made by Jeff 2 weeks ago, IIRC. > Parse errors: Tests out of sequence. Found (2) but expected (3) > Tests out of sequence. Found (3) but expected (4) > Tests out of sequence. Found (4) but expected (5) > Bad plan. You planned 4 tests but ran 5. > Files=760, Tests=15109, 679 wallclock secs (21.91 usr 1.78 sys + 320.79 cusr > 529.13 csys = 873.61 CPU) > Result: FAIL > make[1]: *** [prove] Error 1 > make: *** [test] Error 2 > > > Example: > https://s3.amazonaws.com/archive.travis-ci.org/jobs/169385219/log.txt > > Thanks, > Lars
Re: Prove "Tests out of sequence" Error
On Thu, Oct 20, 2016 at 11:10:39PM -0700, Stefan Beller wrote: > > on TravisCI I see these weird "Tests out of sequence" errors with prove > > and they seem to not go away. I assume the reason that they not go away > > is that the ".prove" file is carried over from on build to another (but I > > can't > > look into this file on TravisCI). > > > > Has anyone an idea where these errors might come from? > > > > > > t5547-push-quarantine.sh (Wstat: 0 Tests: 5 Failed: > > 0) > > push quarantine is a new thing made by Jeff 2 weeks ago, IIRC. Yes, but I do not see how it can trigger this: > > Parse errors: Tests out of sequence. Found (2) but expected (3) > > Tests out of sequence. Found (3) but expected (4) > > Tests out of sequence. Found (4) but expected (5) > > Bad plan. You planned 4 tests but ran 5. The TAP output from one of our tests should look something like: ok 1 - subject one ok 2 - subject two ok 3 - subject three ok 4 - subject four # passed all 4 test(s) 1..4 the "plan" is the bit at the end. That looks like $test_count accidentally got incremented by one and we generated something like: ok 1 - subject one ok 3 - subject two ok 4 - subject three ok 5 - subject four 1..4 which would explain the "out of sequence" errors as well as the "planned 4 but ran 5". But I do not see how the test script could screw that up. The counting is handled entirely by the harness in test-lib.sh. Nor do I see how a stale .prove file could matter. It does not store information about the test plan at all. E.g., here is the entry from mine for t5547: t5547-push-quarantine.sh: elapsed: 0.0762169361114502 gen: 1 last_pass_time: 1477037708.741 last_result: 0 last_run_time: 1477037708.741 last_todo: 0 seq: 437 total_passes: 1 Puzzling. -Peff
Re: Prove "Tests out of sequence" Error
On Fri, Oct 21, 2016 at 04:20:35AM -0400, Jeff King wrote: > Yes, but I do not see how it can trigger this: > > > > Parse errors: Tests out of sequence. Found (2) but expected (3) > > > Tests out of sequence. Found (3) but expected (4) > > > Tests out of sequence. Found (4) but expected (5) > > > Bad plan. You planned 4 tests but ran 5. > > The TAP output from one of our tests should look something like: > > ok 1 - subject one > ok 2 - subject two > ok 3 - subject three > ok 4 - subject four > # passed all 4 test(s) > 1..4 > > the "plan" is the bit at the end. That looks like $test_count > accidentally got incremented by one and we generated something like: > > ok 1 - subject one > ok 3 - subject two > ok 4 - subject three > ok 5 - subject four > 1..4 > > which would explain the "out of sequence" errors as well as the "planned > 4 but ran 5". Hmm, actually the numbering problem is the other way around. It finds 2 but expects 3, so it is more like: ok 1 - subject one ok 2 - something else stuck in here! ok 2 - subject two ... which gives us a clue. And thanks to TAP auto-numbering, you can also trigger this like: ok 1 - subject one ok ok 2 - subject two The "ok" by itself is taken to mean "ok 2". And now I have enough to generate this locally. t5547 does: test_commit ok && ... git cat-file commit $commit which will print a line with just "ok" on it. Normally this is not sent to stdout at all; test output goes to /dev/null unless "--verbose" is given. When "--verbose" is used, we get all manner of random program output intermingled with our TAP output, which is an accident waiting to happen. Usually nobody cares, because they only use "--verbose" when debugging a test individually (and nothing is parsing the TAP output). But I can trigger the problem with: prove t5547-push-quarantine.sh :: -v The Travis tests do exactly this (along with --tee to actually save the output). It seems like a minor miracle that this is the first test output that has actually triggered as TAP input. I'd suggest that the problem is not in the test, though, but that our "--verbose" option is unsuitable for using with a TAP harness. The obvious fix would be to send "--verbose" output to stderr, but I suspect that would end up annoying for people who do: ./t5547-push-quarantine.sh -v | less to read long output. Probably we need some option like "--log" which logs in the same way that "--tee" does, but _without_ sending the data to stdout. Naively, that just means replacing the "tee" invocation with "cat", but I suspect it will be a lot more complicated than that, because we still need to let the TAP output go to stdout. -Peff
Re: Prove "Tests out of sequence" Error
On Fri, Oct 21, 2016 at 1:43 AM, Jeff King wrote: > prove t5547-push-quarantine.sh :: -v > > The Travis tests do exactly this (along with --tee to actually save the > output). It seems like a minor miracle that this is the first test > output that has actually triggered as TAP input. I'd suggest that the > problem is not in the test, though, but that our "--verbose" option is > unsuitable for using with a TAP harness. > > The obvious fix would be to send "--verbose" output to stderr, but I > suspect that would end up annoying for people who do: > > ./t5547-push-quarantine.sh -v | less > > to read long output. Probably we need some option like "--log" which > logs in the same way that "--tee" does, but _without_ sending the data > to stdout. Naively, that just means replacing the "tee" invocation with > "cat", but I suspect it will be a lot more complicated than that, > because we still need to let the TAP output go to stdout. > > -Peff Can we determine that we're running with something monitoring the TAP output? Because then we could make verbose go to stderr instead dynamically? Thanks, Jake
Re: Prove "Tests out of sequence" Error
On Fri, Oct 21, 2016 at 08:29:49AM -0700, Jacob Keller wrote: > > The Travis tests do exactly this (along with --tee to actually save the > > output). It seems like a minor miracle that this is the first test > > output that has actually triggered as TAP input. I'd suggest that the > > problem is not in the test, though, but that our "--verbose" option is > > unsuitable for using with a TAP harness. > > > > The obvious fix would be to send "--verbose" output to stderr, but I > > suspect that would end up annoying for people who do: > > > > ./t5547-push-quarantine.sh -v | less > > > > to read long output. Probably we need some option like "--log" which > > logs in the same way that "--tee" does, but _without_ sending the data > > to stdout. Naively, that just means replacing the "tee" invocation with > > "cat", but I suspect it will be a lot more complicated than that, > > because we still need to let the TAP output go to stdout. > > Can we determine that we're running with something monitoring the TAP > output? Because then we could make verbose go to stderr instead > dynamically? I think $HARNESS_ACTIVE could tell us that. But the hard part isn't activating it; it's directing the verbose output to the log without sending it to stdout. See the patch I posted later in the thread, and my musings on auto-activating it. I guess we could do so safely when we see $HARNESS_ACTIVE along with "--tee" and "--verbose", though I don't know if it's worth the trouble. For $HARNESS_ACTIVE with _just_ "--verbose", I don't think it would be a good idea to activate it. We should either silently ignore --verbose then, or complain and die. -Peff
Re: Prove "Tests out of sequence" Error
On Fri, Oct 21, 2016 at 8:35 AM, Jeff King wrote: > On Fri, Oct 21, 2016 at 08:29:49AM -0700, Jacob Keller wrote: > >> > The Travis tests do exactly this (along with --tee to actually save the >> > output). It seems like a minor miracle that this is the first test >> > output that has actually triggered as TAP input. I'd suggest that the >> > problem is not in the test, though, but that our "--verbose" option is >> > unsuitable for using with a TAP harness. >> > >> > The obvious fix would be to send "--verbose" output to stderr, but I >> > suspect that would end up annoying for people who do: >> > >> > ./t5547-push-quarantine.sh -v | less >> > >> > to read long output. Probably we need some option like "--log" which >> > logs in the same way that "--tee" does, but _without_ sending the data >> > to stdout. Naively, that just means replacing the "tee" invocation with >> > "cat", but I suspect it will be a lot more complicated than that, >> > because we still need to let the TAP output go to stdout. >> >> Can we determine that we're running with something monitoring the TAP >> output? Because then we could make verbose go to stderr instead >> dynamically? > > I think $HARNESS_ACTIVE could tell us that. But the hard part isn't > activating it; it's directing the verbose output to the log without > sending it to stdout. > > See the patch I posted later in the thread, and my musings on > auto-activating it. I guess we could do so safely when we see > $HARNESS_ACTIVE along with "--tee" and "--verbose", though I don't know > if it's worth the trouble. > > For $HARNESS_ACTIVE with _just_ "--verbose", I don't think it would be a > good idea to activate it. We should either silently ignore --verbose > then, or complain and die. > We should probably do that to make sure people realize what might happen. I read your series and it has a good explanation of the possible alternatives. I like the approach you chose. Thanks, Jake > -Peff
Re: Prove "Tests out of sequence" Error
On Fri, Oct 21, 2016 at 08:42:58AM -0700, Jacob Keller wrote: > > For $HARNESS_ACTIVE with _just_ "--verbose", I don't think it would be a > > good idea to activate it. We should either silently ignore --verbose > > then, or complain and die. > > We should probably do that to make sure people realize what might > happen. I read your series and it has a good explanation of the > possible alternatives. I like the approach you chose. Thanks. Do you want to make a patch on top of my series? -Peff
Re: Prove "Tests out of sequence" Error
On Fri, Oct 21, 2016 at 8:48 AM, Jeff King wrote: > On Fri, Oct 21, 2016 at 08:42:58AM -0700, Jacob Keller wrote: > >> > For $HARNESS_ACTIVE with _just_ "--verbose", I don't think it would be a >> > good idea to activate it. We should either silently ignore --verbose >> > then, or complain and die. >> >> We should probably do that to make sure people realize what might >> happen. I read your series and it has a good explanation of the >> possible alternatives. I like the approach you chose. > > Thanks. Do you want to make a patch on top of my series? > > -Peff I am not sure I will find time to do it today, so it wouldn't be for a few more days. Thanks, Jake
