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:

quoted

quoted

  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