Prove "Tests out of sequence" Error

Prove "Tests out of sequence" Error

[Lars Schneider]

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

[Stefan Beller]

On Thu, Oct 20, 2016 at 9:14 PM, Lars Schneider
<larsxschneider@gmail.com> 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

[Jeff King]

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

[Jeff King]

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

[PATCH 0/3] fix travis TAP/--verbose conflict

[Jeff King]

On Fri, Oct 21, 2016 at 04:43:48AM -0400, Jeff King wrote:

> 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.

Yeah, it was definitely a lot more complicated. This patch series fixes
it.

  [1/3]: test-lib: handle TEST_OUTPUT_DIRECTORY with spaces
  [2/3]: test-lib: add --verbose-log option
  [3/3]: travis: use --verbose-log test option

 .travis.yml   |  2 +-
 t/README      |  6 ++++++
 t/test-lib.sh | 24 ++++++++++++++++++++----
 3 files changed, 27 insertions(+), 5 deletions(-)

-Peff

[PATCH 1/3] test-lib: handle TEST_OUTPUT_DIRECTORY with spaces

[Jeff King]

We are careful in test_done to handle a results directory
with a space in it, but the "--tee" code path does not.
Doing:

  export TEST_OUTPUT_DIRECTORY='/tmp/path with spaces'
  ./t000-init.sh --tee

results in errors. Let's consistently double-quote our path
variables so that this works.

Signed-off-by: Jeff King <peff@peff.net>
---
I imagine nobody cares much about this, but I just happened to notice it
while writing the rest of the patches (and it's obviously quite easy to
fix).

 t/test-lib.sh | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/t/test-lib.sh b/t/test-lib.sh
index 11562bde10..33cbbb7806 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -58,8 +58,8 @@ done,*)
 	mkdir -p "$TEST_OUTPUT_DIRECTORY/test-results"
 	BASE="$TEST_OUTPUT_DIRECTORY/test-results/$(basename "$0" .sh)"
 	(GIT_TEST_TEE_STARTED=done ${SHELL_PATH} "$0" "$@" 2>&1;
-	 echo $? > $BASE.exit) | tee $BASE.out
-	test "$(cat $BASE.exit)" = 0
+	 echo $? >"$BASE.exit") | tee "$BASE.out"
+	test "$(cat "$BASE.exit")" = 0
 	exit
 	;;
 esac
-- 
2.10.1.776.ge0e381e

[PATCH 2/3] test-lib: add --verbose-log option

[Jeff King]

The "--verbose" option redirects output from arbitrary
test commands to stdout. This is useful for examining the
output manually, like:

  ./t5547-push-quarantine.sh -v | less

But it also means that the output is intermingled with the
TAP directives, which can confuse a TAP parser like "prove".
This has always been a potential problem, but became an
issue recently when one test happened to output the word
"ok" on a line by itself, which prove interprets as a test
success:

  $ prove t5547-push-quarantine.sh :: -v
  t5547-push-quarantine.sh .. 1/? To dest.git
   * [new branch]      HEAD -> master
  To dest.git
   ! [remote rejected] reject -> reject (pre-receive hook declined)
  error: failed to push some refs to 'dest.git'
  fatal: git cat-file d08c8eba97f4e683ece08654c7c8d2ba0c03b129: bad file
  t5547-push-quarantine.sh .. Failed -1/4 subtests

  Test Summary Report
  -------------------
  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=1, Tests=5,  0 wallclock secs ( 0.01 usr +  0.01 sys =  0.02 CPU)
  Result: FAIL

One answer is "if it hurts, don't do it", but that's not
quite the whole story. The Travis tests use "--verbose
--tee" so that they can get the benefit of prove's parallel
options, along with a verbose log in case there is a
failure. We just need the verbose output to go to the log,
but keep stdout clean.

Getting this right turns out to be surprisingly difficult.
Here's the progression of alternatives I considered:

 1. Add an option to write verbose output to stderr. This is
    hard to capture, though, because we want each test to
    have its own log (because they're all run in parallel
    and the jumbled output would be useless).

 2. Add an option to write verbose output to a file in
    test-results. This works, but the log is missing all of
    the non-verbose output, which gives context.

 3. Like (2), but teach say_color() to additionally output
    to the log. This mostly works, but misses any output
    that happens outside of the say() functions (which isn't
    a lot, but is a potential maintenance headache).

 4. Like (2), but make the log file the same as the "--tee"
    file. That almost works, but now we have two processes
    opening the same file. That gives us two separate
    descriptors, each with their own idea of the current
    position. They'll each start writing at offset 0, and
    overwrite each other's data.

 5. Like (4), but in each case open the file for appending.
    That atomically positions each write at the end of the
    file.

    It's possible we may still get sheared writes between
    the two processes, but this is already the case when
    writing to stdout. It's not a problem in practice
    because the test harness generally waits for snippets to
    finish before writing the TAP output.

    We can ignore buffering issues with tee, because POSIX
    mandates that it does not buffer. Likewise, POSIX
    specifies "tee -a", so it should be available
    everywhere.

This patch implements option (5), which seems to work well
in practice.

Signed-off-by: Jeff King <peff@peff.net>
---
Arguably we don't need a new option for this, and could just do it
automatically. I wasn't sure when, though:

  - if "--tee --verbose" triggers it, then somebody running that outside
    of "prove" who _wants_ the verbose output on stdout (because they're
    looking at it, but also want to save a copy to the log) would be
    regressed

  - possibly "--tee" could just always write verbose output to the
    logfile (but not stdout). That's kind of weirdly magical, and we'd
    have to update the travis invocation anyway.

So I went with a new option which implies the other ones. No chance of
regression, and it's easy to explain.

 t/README      |  6 ++++++
 t/test-lib.sh | 22 +++++++++++++++++++---
 2 files changed, 25 insertions(+), 3 deletions(-)

diff --git a/t/README b/t/README
index 0f764c0aef..4982d1c521 100644
--- a/t/README
+++ b/t/README
@@ -153,6 +153,12 @@ appropriately before running "make".
 	As the names depend on the tests' file names, it is safe to
 	run the tests with this option in parallel.
 
+--verbose-log::
+	Write verbose output to the same logfile as `--tee`, but do
+	_not_ write it to stdout. Unlike `--tee --verbose`, this option
+	is safe to use when stdout is being consumed by a TAP parser
+	like `prove`. Implies `--tee` and `--verbose`.
+
 --with-dashes::
 	By default tests are run without dashed forms of
 	commands (like git-commit) in the PATH (it only uses
diff --git a/t/test-lib.sh b/t/test-lib.sh
index 33cbbb7806..85946ec40d 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -54,11 +54,21 @@ case "$GIT_TEST_TEE_STARTED, $* " in
 done,*)
 	# do not redirect again
 	;;
-*' --tee '*|*' --va'*)
+*' --tee '*|*' --va'*|*' --verbose-log '*)
 	mkdir -p "$TEST_OUTPUT_DIRECTORY/test-results"
 	BASE="$TEST_OUTPUT_DIRECTORY/test-results/$(basename "$0" .sh)"
+
+	# Make this filename available to the sub-process in case it is using
+	# --verbose-log.
+	GIT_TEST_TEE_OUTPUT_FILE=$BASE.out
+	export GIT_TEST_TEE_OUTPUT_FILE
+
+	# Truncate before calling "tee -a" to get rid of the results
+	# from any previous runs.
+	>"$GIT_TEST_TEE_OUTPUT_FILE"
+
 	(GIT_TEST_TEE_STARTED=done ${SHELL_PATH} "$0" "$@" 2>&1;
-	 echo $? >"$BASE.exit") | tee "$BASE.out"
+	 echo $? >"$BASE.exit") | tee -a "$GIT_TEST_TEE_OUTPUT_FILE"
 	test "$(cat "$BASE.exit")" = 0
 	exit
 	;;
@@ -246,6 +256,9 @@ do
 		trace=t
 		verbose=t
 		shift ;;
+	--verbose-log)
+		verbose_log=t
+		shift ;;
 	*)
 		echo "error: unknown test option '$1'" >&2; exit 1 ;;
 	esac
@@ -319,7 +332,10 @@ fi
 
 exec 5>&1
 exec 6<&0
-if test "$verbose" = "t"
+if test "$verbose_log" = "t"
+then
+	exec 3>>"$GIT_TEST_TEE_OUTPUT_FILE" 4>&3
+elif test "$verbose" = "t"
 then
 	exec 4>&2 3>&1
 else
-- 
2.10.1.776.ge0e381e

[PATCH 3/3] travis: use --verbose-log test option

[Jeff King]

Because we run the tests via "prove", the output from
"--verbose" may interfere with our TAP output. Using
"--verbose-log" solves this while letting us retain our
on-disk log.

Signed-off-by: Jeff King <peff@peff.net>
---
 .travis.yml | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/.travis.yml b/.travis.yml
index 37a1e1fb6d..9a65514d82 100644
--- a/.travis.yml
+++ b/.travis.yml
@@ -31,7 +31,7 @@ env:
     - LINUX_GIT_LFS_VERSION="1.2.0"
     - DEFAULT_TEST_TARGET=prove
     - GIT_PROVE_OPTS="--timer --jobs 3 --state=failed,slow,save"
-    - GIT_TEST_OPTS="--verbose --tee"
+    - GIT_TEST_OPTS="--verbose-log"
     - GIT_TEST_HTTPD=true
     - GIT_TEST_CLONE_2GB=YesPlease
     # t9810 occasionally fails on Travis CI OS X
-- 
2.10.1.776.ge0e381e

Re: Prove "Tests out of sequence" Error

[Jacob Keller]

On Fri, Oct 21, 2016 at 1:43 AM, Jeff King <peff@peff.net> 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

[Jeff King]

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

[Jacob Keller]

On Fri, Oct 21, 2016 at 8:35 AM, Jeff King <peff@peff.net> 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

[Jeff King]

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

[Jacob Keller]

On Fri, Oct 21, 2016 at 8:48 AM, Jeff King <peff@peff.net> 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

Re: [PATCH 2/3] test-lib: add --verbose-log option

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

> This patch implements option (5), which seems to work well
> in practice.

Your journey to reach this final design and implementation may have
been painful---I really like the end result.  This was an accident
waiting to happen.

Thanks for fixing it.

> @@ -319,7 +332,10 @@ fi
>  
>  exec 5>&1
>  exec 6<&0
> -if test "$verbose" = "t"
> +if test "$verbose_log" = "t"
> +then
> +	exec 3>>"$GIT_TEST_TEE_OUTPUT_FILE" 4>&3
> +elif test "$verbose" = "t"
>  then
>  	exec 4>&2 3>&1
>  else

OK, unlike "verbose" case where we give 3 (saved stdout) to 1 and 4
(saved stderr) to 2, we send 3 to the output file and 4 to the same.

Makes sense.

Re: [PATCH 0/3] fix travis TAP/--verbose conflict

[Stefan Beller]

On Fri, Oct 21, 2016 at 3:41 AM, Jeff King <peff@peff.net> wrote:
> On Fri, Oct 21, 2016 at 04:43:48AM -0400, Jeff King wrote:
>
>> 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.
>
> Yeah, it was definitely a lot more complicated. This patch series fixes
> it.
>
>   [1/3]: test-lib: handle TEST_OUTPUT_DIRECTORY with spaces
>   [2/3]: test-lib: add --verbose-log option
>   [3/3]: travis: use --verbose-log test option

All patches look good to me
(1&3 are obvious, and 2 is very well described).

Thanks,
Stefan

Re: [PATCH 2/3] test-lib: add --verbose-log option

[Jeff King]

On Fri, Oct 21, 2016 at 10:12:16AM -0700, Junio C Hamano wrote:

> > -if test "$verbose" = "t"
> > +if test "$verbose_log" = "t"
> > +then
> > +	exec 3>>"$GIT_TEST_TEE_OUTPUT_FILE" 4>&3
> > +elif test "$verbose" = "t"
> >  then
> >  	exec 4>&2 3>&1
> >  else
> 
> OK, unlike "verbose" case where we give 3 (saved stdout) to 1 and 4
> (saved stderr) to 2, we send 3 to the output file and 4 to the same.

Your comment made me double-check whether we ought to be separating the
two in any way. Because my statement earlier in the thread that the
--verbose output goes to stdout is not _entirely_ true. It goes to
stdout and stderr, as written by the various programs in the tests.

So:

  ./t0000-whatever.sh -v | less

isn't quite sufficient. You really do want "2>&1" in there to catch
everything.

But for the case of "--tee", we already do so, in order to make sure it
all goes to the logfile. And since this option always implies "--tee",
it is correct here to send "3" and "4" to the same place.

So the patch is correct. But when I said earlier that people might be
annoyed if we just sent --verbose output to stderr, that probably isn't
true. We could perhaps make:

  prove t0000-whatever.sh :: -v

"just work" by sending all of the verbose output to stderr. I don't
think it really matters, though. Nobody is doing that, because it's
pointless without "--tee".

-Peff

[PATCH 4/3] test-lib: bail out when "-v" used under "prove"

[Jeff King]

On Fri, Oct 21, 2016 at 09:15:28AM -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?
> 
> I am not sure I will find time to do it today, so it wouldn't be for a
> few more days.

I thought I'd just knock this out in 5 minutes before I forgot about it.
But as with so many things, getting it right proved slightly harder than
I thought. But I did learn about TAP's "Bail out!" directive. And
apparently you can pass it back arbitrary YAML (!). And the "--verbose"
output really is violating the spec, and they claim that Test::Harness
will eventually be tightened to complain (though that was in 2007, and
it still hasn't happened, so...).

Anyway. Here is the patch I came up with (on top of the others).

-- >8 --
Subject: test-lib: bail out when "-v" used under "prove"

When there is a TAP harness consuming the output of our test
scripts, the "--verbose" breaks the output by mingling
test command output with TAP. Because the TAP::Harness
module used by "prove" is fairly lenient, this _usually_
works, but it violates the spec, and things get very
confusing if the commands happen to output a line that looks
like TAP (e.g., the word "ok" on its own line).

Let's detect this situation and complain. Just calling
error() isn't great, though; prove will tell us that the
script failed, but the message doesn't make it through to
the user. Instead, we can use the special TAP signal "Bail
out!". This not only shows the message to the user, but
instructs the harness to stop running the tests entirely.
This is exactly what we want here, as the problem is in the
command-line options, and every test script would produce
the same error.

The result looks like this (the first "Bailout called" line
is in red if prove uses color on your terminal):

 $ make GIT_TEST_OPTS='--verbose --tee'
 rm -f -r 'test-results'
 *** prove ***
 Bailout called.  Further testing stopped:  verbose mode forbidden under TAP harness; try --verbose-log
 FAILED--Further testing stopped: verbose mode forbidden under TAP harness; try --verbose-log
 Makefile:39: recipe for target 'prove' failed
 make: *** [prove] Error 255

Signed-off-by: Jeff King <peff@peff.net>
---
 t/test-lib.sh | 10 ++++++++++
 1 file changed, 10 insertions(+)

diff --git a/t/test-lib.sh b/t/test-lib.sh
index 85946ec40d..b859db61ac 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -321,6 +321,16 @@ say () {
 	say_color info "$*"
 }
 
+if test -n "$HARNESS_ACTIVE"
+then
+	if test "$verbose" = t || test -n "$verbose_only"
+	then
+		printf 'Bail out! %s\n' \
+		 'verbose mode forbidden under TAP harness; try --verbose-log'
+		exit 1
+	fi
+fi
+
 test "${test_description}" != "" ||
 error "Test script did not set test_description."
 
-- 
2.10.1.776.ge0e381e

Re: [PATCH 4/3] test-lib: bail out when "-v" used under "prove"

[Jacob Keller]

On Fri, Oct 21, 2016 at 9:45 PM, Jeff King <peff@peff.net> wrote:
> I thought I'd just knock this out in 5 minutes before I forgot about it.
> But as with so many things, getting it right proved slightly harder than
> I thought.

Always seems to be that way, doesn't it?

> But I did learn about TAP's "Bail out!" directive. And
> apparently you can pass it back arbitrary YAML (!). And the "--verbose"
> output really is violating the spec, and they claim that Test::Harness
> will eventually be tightened to complain (though that was in 2007, and
> it still hasn't happened, so...).
>
> Anyway. Here is the patch I came up with (on top of the others).
>

Nice.

> -- >8 --
> Subject: test-lib: bail out when "-v" used under "prove"
>
> When there is a TAP harness consuming the output of our test
> scripts, the "--verbose" breaks the output by mingling
> test command output with TAP. Because the TAP::Harness
> module used by "prove" is fairly lenient, this _usually_
> works, but it violates the spec, and things get very
> confusing if the commands happen to output a line that looks
> like TAP (e.g., the word "ok" on its own line).
>
> Let's detect this situation and complain. Just calling
> error() isn't great, though; prove will tell us that the
> script failed, but the message doesn't make it through to
> the user. Instead, we can use the special TAP signal "Bail
> out!". This not only shows the message to the user, but
> instructs the harness to stop running the tests entirely.
> This is exactly what we want here, as the problem is in the
> command-line options, and every test script would produce
> the same error.
>
> The result looks like this (the first "Bailout called" line
> is in red if prove uses color on your terminal):
>
>  $ make GIT_TEST_OPTS='--verbose --tee'
>  rm -f -r 'test-results'
>  *** prove ***
>  Bailout called.  Further testing stopped:  verbose mode forbidden under TAP harness; try --verbose-log
>  FAILED--Further testing stopped: verbose mode forbidden under TAP harness; try --verbose-log
>  Makefile:39: recipe for target 'prove' failed
>  make: *** [prove] Error 255
>

Nice that makes sense.

> Signed-off-by: Jeff King <peff@peff.net>
> ---
>  t/test-lib.sh | 10 ++++++++++
>  1 file changed, 10 insertions(+)
>
> diff --git a/t/test-lib.sh b/t/test-lib.sh
> index 85946ec40d..b859db61ac 100644
> --- a/t/test-lib.sh
> +++ b/t/test-lib.sh
> @@ -321,6 +321,16 @@ say () {
>         say_color info "$*"
>  }
>
> +if test -n "$HARNESS_ACTIVE"
> +then
> +       if test "$verbose" = t || test -n "$verbose_only"
> +       then
> +               printf 'Bail out! %s\n' \
> +                'verbose mode forbidden under TAP harness; try --verbose-log'
> +               exit 1
> +       fi
> +fi
> +

Not too much code, so that's good. I like it.

Thanks,
Jake

>  test "${test_description}" != "" ||
>  error "Test script did not set test_description."
>
> --
> 2.10.1.776.ge0e381e
>

Re: [PATCH 0/3] fix travis TAP/--verbose conflict

[Lars Schneider]

> On 21 Oct 2016, at 12:41, Jeff King <peff@peff.net> wrote:
> 
> On Fri, Oct 21, 2016 at 04:43:48AM -0400, Jeff King wrote:
> 
>> 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.
> 
> Yeah, it was definitely a lot more complicated. This patch series fixes
> it.

Thanks a lot for this detailed and quick fix :-)

Cheers,
Lars

[PATCH/RFC] test-lib: make --verbose work under prove

[Ævar Arnfjörð Bjarmason]

As explained in 452320f1f5 (test-lib: add --verbose-log option,
2016-10-21) combining the "--verbose" option with the TAP-parsing
"prove" utility would result in broken tests.

This is because "prove" expects valid TAP on stdout, and if there's a
stray line starting with "ok", or other invalid TAP syntax it will
error on the test.

In 452320f1f5 numerous potential methods are discussed for dealing
with this problem, but not the one implemented here, which I think is
a much simpler approach.

When we detect that we're running under "prove" we prefix all
legitimate TAP directives with "GIT_TEST_TEE_STARTED":

    $ GIT_TEST_TEE_STARTED=1 ./t5547-push-quarantine.sh
    GIT_TEST_TEE_STARTED ok 1 - create picky dest repo
    GIT_TEST_TEE_STARTED ok 2 - accepted objects work
    [...]
    GIT_TEST_TEE_STARTED 1..6

Then, instead of piping the output to "tee -a" we pipe it to a helper
which first converts "ok" and other TAP syntax to e.g. "\ok", and then
strips that "GIT_TEST_TEE_STARTED " prefix from the start of the line.

The end result is that we're guaranteed to have valid TAP syntax on
stdout. We can thus get rid of the --verbose-log special-case. Since
that option was meant to get around the TAP issue let's simply make it
an alias for "--verbose --tee".

We can also revert relevant parts of 88c6e9d31c (test-lib: --valgrind
should not override --verbose-log, 2017-09-05) and
f5ba2de6bc (test-lib: make "-x" work with "--verbose-log",
2017-12-08), which were follow-up changes to work around the previous
--verbose-log implementation.

Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
---

On Fri, Oct 21 2016, Jeff King wrote:

> The "--verbose" option redirects output from arbitrary
> test commands to stdout. This is useful for examining the
> output manually, like:
>
>   ./t5547-push-quarantine.sh -v | less
>
> But it also means that the output is intermingled with the
> TAP directives, which can confuse a TAP parser like "prove".
> This has always been a potential problem, but became an
> issue recently when one test happened to output the word
> "ok" on a line by itself, which prove interprets as a test
> success:
>
>   $ prove t5547-push-quarantine.sh :: -v
>   t5547-push-quarantine.sh .. 1/? To dest.git
>    * [new branch]      HEAD -> master
>   To dest.git
>    ! [remote rejected] reject -> reject (pre-receive hook declined)
>   error: failed to push some refs to 'dest.git'
>   fatal: git cat-file d08c8eba97f4e683ece08654c7c8d2ba0c03b129: bad file
>   t5547-push-quarantine.sh .. Failed -1/4 subtests
>
>   Test Summary Report
>   -------------------
>   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=1, Tests=5,  0 wallclock secs ( 0.01 usr +  0.01 sys =  0.02 CPU)
>   Result: FAIL
>
> One answer is "if it hurts, don't do it", but that's not
> quite the whole story. The Travis tests use "--verbose
> --tee" so that they can get the benefit of prove's parallel
> options, along with a verbose log in case there is a
> failure. We just need the verbose output to go to the log,
> but keep stdout clean.
>
> Getting this right turns out to be surprisingly difficult.
> Here's the progression of alternatives I considered:
>
>  1. Add an option to write verbose output to stderr. This is
>     hard to capture, though, because we want each test to
>     have its own log (because they're all run in parallel
>     and the jumbled output would be useless).
>
>  2. Add an option to write verbose output to a file in
>     test-results. This works, but the log is missing all of
>     the non-verbose output, which gives context.
>
>  3. Like (2), but teach say_color() to additionally output
>     to the log. This mostly works, but misses any output
>     that happens outside of the say() functions (which isn't
>     a lot, but is a potential maintenance headache).
>
>  4. Like (2), but make the log file the same as the "--tee"
>     file. That almost works, but now we have two processes
>     opening the same file. That gives us two separate
>     descriptors, each with their own idea of the current
>     position. They'll each start writing at offset 0, and
>     overwrite each other's data.
>
>  5. Like (4), but in each case open the file for appending.
>     That atomically positions each write at the end of the
>     file.
>
>     It's possible we may still get sheared writes between
>     the two processes, but this is already the case when
>     writing to stdout. It's not a problem in practice
>     because the test harness generally waits for snippets to
>     finish before writing the TAP output.
>
>     We can ignore buffering issues with tee, because POSIX
>     mandates that it does not buffer. Likewise, POSIX
>     specifies "tee -a", so it should be available
>     everywhere.
>
> This patch implements option (5), which seems to work well
> in practice.
> 
> Signed-off-by: Jeff King <peff@peff.net>
> ---
> Arguably we don't need a new option for this, and could just do it
> automatically. I wasn't sure when, though:
>
>   - if "--tee --verbose" triggers it, then somebody running that outside
>     of "prove" who _wants_ the verbose output on stdout (because they're
>     looking at it, but also want to save a copy to the log) would be
>     regressed
>
>   - possibly "--tee" could just always write verbose output to the
>     logfile (but not stdout). That's kind of weirdly magical, and we'd
>     have to update the travis invocation anyway.
>
> So I went with a new option which implies the other ones. No chance of
> regression, and it's easy to explain.

I came up with a #6 for this which I found much simpler: We control the
TAP output, so instead of emitting "ok" and having it be corrupted,
let's emit "<some unique string> ok", and then have our own "tee -a" and
search-replace it back & forth.

The above RFC is in the middle of a topic branch I have locally, so it
doesn't apply cleanly to anything.

I just thought I'd send it as an RFC to see if anyone had issues with
the approach, and to simply make --verbose-log a synonym for --verbose
--tee with this fix. Having the verbose output under "prove" doesn't
matter, it will only report on the TAP, so quieting the output had no UI
impact.

The t/lib-test/* changes of calling "sed" once per-line under --tee are
relatively inefficient. But it would be rather trivial to convert this
to a our own "tee -a"-alike t/helper/* using strbuf_getline() and wrote
to stdout and a file if anyone saw a practical issue with that part of
the implementation (e.g. maybe it's very slow on Windows or something).

 t/README                   |  9 ++++++---
 t/lib-test/tapify-tee-a.sh | 10 ++++++++++
 t/lib-test/tapify.sh       |  5 +++++
 t/t0000-basic.sh           |  8 ++++++++
 t/test-lib.sh              | 40 +++++++++++++++++---------------------
 5 files changed, 47 insertions(+), 25 deletions(-)
 create mode 100644 t/lib-test/tapify-tee-a.sh
 create mode 100644 t/lib-test/tapify.sh

diff --git a/t/README b/t/README
index 593d4a4e27..bf1f3313ac 100644
--- a/t/README
+++ b/t/README
@@ -157,10 +157,13 @@ appropriately before running "make". Short options can be bundled, i.e.
 
 -V::
 --verbose-log::
-	Write verbose output to the same logfile as `--tee`, but do
-	_not_ write it to stdout. Unlike `--tee --verbose`, this option
+	An alias for `--verbose --tee`. This option
 	is safe to use when stdout is being consumed by a TAP parser
-	like `prove`. Implies `--tee` and `--verbose`.
+	like `prove`.
+	Historically this option was different from `--verbose --tee`
+	and would not write any verbose output to stdout to ensure the
+	TAP-correctness of the output. The TAP-correctness of the
+	output is now sanity checked by the test library,
 
 --with-dashes::
 	By default tests are run without dashed forms of
diff --git a/t/lib-test/tapify-tee-a.sh b/t/lib-test/tapify-tee-a.sh
new file mode 100644
index 0000000000..f90f9a89c2
--- /dev/null
+++ b/t/lib-test/tapify-tee-a.sh
@@ -0,0 +1,10 @@
+#!/bin/sh
+
+# A 'tee -a'-alike that protects the sanity of the TAP output, for
+# test-lib.sh's --tee option
+
+while read -r line
+do
+      printf "%s\n" "$line"
+      printf "%s\n" "$line" | sed 's/^GIT_TEST_TEE_STARTED //' >>"$1"
+done | $TEST_SHELL_PATH "$TEST_DIRECTORY/lib-test/tapify.sh"
diff --git a/t/lib-test/tapify.sh b/t/lib-test/tapify.sh
new file mode 100644
index 0000000000..bfa66d33b4
--- /dev/null
+++ b/t/lib-test/tapify.sh
@@ -0,0 +1,5 @@
+#!/bin/sh
+
+sed \
+    -e 's/^\(ok\|not ok\|1\.\.\)/\\\1/' \
+    -e 's/^GIT_TEST_TEE_STARTED //'
diff --git a/t/t0000-basic.sh b/t/t0000-basic.sh
index 705d62cc27..2a95a612fb 100755
--- a/t/t0000-basic.sh
+++ b/t/t0000-basic.sh
@@ -76,6 +76,14 @@ _run_sub_test_lib_test_common () {
 		# this variable, so we need a stable setting under which to run
 		# the sub-test.
 		sane_unset HARNESS_ACTIVE &&
+
+		# When under --tee pretend we're not as far as
+		# emitting the "GIT_TEST_TEE_STARTED " TAP sanity
+		# prefix goes. This means we promise not to emit
+		# invalid TAP, least this test fails under --tee under
+		# prove(1).
+		sane_unset GIT_TEST_TEE_STARTED &&
+
 		cd "$name" &&
 		write_script "$name.sh" "$TEST_SHELL_PATH" <<-EOF &&
 		test_description='$descr (run in sub test-lib)
diff --git a/t/test-lib.sh b/t/test-lib.sh
index af7a16fddd..f533cc02e9 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -146,9 +146,11 @@ parse_option () {
 	--no-chain-lint)
 		GIT_TEST_CHAIN_LINT=0 ;;
 	-x)
-		trace=t ;;
+		trace=t
+		verbose=t
+		;;
 	-V|--verbose-log)
-		verbose_log=t
+		verbose=t
 		tee=t
 		;;
 	--write-junit-xml)
@@ -233,7 +235,7 @@ then
 	test -z "$verbose" && verbose_only="$valgrind_only"
 elif test -n "$valgrind"
 then
-	test -z "$verbose_log" && verbose=t
+	verbose=t
 fi
 
 if test -n "$stress"
@@ -364,9 +366,19 @@ then
 	(
 		GIT_TEST_TEE_STARTED=done ${TEST_SHELL_PATH} "$0" "$@" 2>&1
 		echo $? >"$TEST_RESULTS_BASE.exit"
-	) | tee -a "$GIT_TEST_TEE_OUTPUT_FILE"
+	) | $TEST_SHELL_PATH \
+		"$TEST_DIRECTORY/lib-test/tapify-tee-a.sh" \
+		"$GIT_TEST_TEE_OUTPUT_FILE"
 	test "$(cat "$TEST_RESULTS_BASE.exit")" = 0
 	exit
+elif test -n "$verbose" -a -n "$HARNESS_ACTIVE"
+then
+	ret=
+	(
+		GIT_TEST_TEE_STARTED=done ${TEST_SHELL_PATH} "$0" "$@" 2>&1
+		ret=$?
+	) | $TEST_SHELL_PATH "$TEST_DIRECTORY/lib-test/tapify.sh"
+	exit $ret
 fi
 
 if test -n "$trace" && test -n "$test_untraceable"
@@ -392,10 +404,6 @@ then
 		trace=
 	fi
 fi
-if test -n "$trace" && test -z "$verbose_log"
-then
-	verbose=t
-fi
 
 # For repeatability, reset the environment to known value.
 # TERM is sanitized below, after saving color control sequences.
@@ -569,7 +577,7 @@ say_color_tap() {
 	test "$#" = 2 ||
 	BUG "not 2 parameters to say_color_tap"
 
-	say_color "$1" "$2"
+	say_color "$1" "${GIT_TEST_TEE_STARTED:+GIT_TEST_TEE_STARTED }$2"
 }
 
 TERM=dumb
@@ -590,16 +598,6 @@ say () {
 	say_color info "$*"
 }
 
-if test -n "$HARNESS_ACTIVE"
-then
-	if test "$verbose" = t || test -n "$verbose_only"
-	then
-		printf 'Bail out! %s\n' \
-		 'verbose mode forbidden under TAP harness; try --verbose-log'
-		exit 1
-	fi
-fi
-
 test "${test_description}" != "" ||
 error "Test script did not set test_description."
 
@@ -889,9 +887,7 @@ maybe_setup_valgrind () {
 
 trace_level_=0
 want_trace () {
-	test "$trace" = t && {
-		test "$verbose" = t || test "$verbose_log" = t
-	}
+	test "$trace" = t && test "$verbose" = t
 }
 
 # This is a separate function because some tests use
-- 
2.31.0.rc0.126.g04f22c5b82

Re: [PATCH/RFC] test-lib: make --verbose work under prove

[Jeff King]

On Sun, Feb 28, 2021 at 09:25:06PM +0100, Ævar Arnfjörð Bjarmason wrote:

> As explained in 452320f1f5 (test-lib: add --verbose-log option,
> 2016-10-21) combining the "--verbose" option with the TAP-parsing
> "prove" utility would result in broken tests.
> 
> This is because "prove" expects valid TAP on stdout, and if there's a
> stray line starting with "ok", or other invalid TAP syntax it will
> error on the test.
> 
> In 452320f1f5 numerous potential methods are discussed for dealing
> with this problem, but not the one implemented here, which I think is
> a much simpler approach.

I guess I don't really have an objection to this method existing, but I
don't see the point of it now. The original problem has been solved, and
I don't find this any simpler than --verbose-log (on the contrary, I
find it much more complicated). So I don't know why I would want to use
this instead.

-Peff

Re: [PATCH/RFC] test-lib: make --verbose work under prove

[Ævar Arnfjörð Bjarmason]

On Mon, Mar 01 2021, Jeff King wrote:

> On Sun, Feb 28, 2021 at 09:25:06PM +0100, Ævar Arnfjörð Bjarmason wrote:
>
>> As explained in 452320f1f5 (test-lib: add --verbose-log option,
>> 2016-10-21) combining the "--verbose" option with the TAP-parsing
>> "prove" utility would result in broken tests.
>> 
>> This is because "prove" expects valid TAP on stdout, and if there's a
>> stray line starting with "ok", or other invalid TAP syntax it will
>> error on the test.
>> 
>> In 452320f1f5 numerous potential methods are discussed for dealing
>> with this problem, but not the one implemented here, which I think is
>> a much simpler approach.
>
> I guess I don't really have an objection to this method existing, but I
> don't see the point of it now. The original problem has been solved, and
> I don't find this any simpler than --verbose-log (on the contrary, I
> find it much more complicated). So I don't know why I would want to use
> this instead.

I guess that's the problem with picking something from the middle of a
local WIP series I have, I forgot to state the end goal of the whole
thing.

The point is to be able to run "prove -v <test> :: --verbose" and see
the verbose output. See the commit message for when TAP was added for
examples: 5099b99d25 (test-lib: Adjust output to be valid TAP format,
2010-06-24)[1].

Because it's valid TAP with this patch you can easily parse the output:

    HARNESS_ACTIVE=t ./t5547-push-quarantine.sh --verbose -x >t5547-push-quarantine.sh.tap
    perl -MTAP::Parser -MYAML::XS -wE '
        my $parser = TAP::Parser->new( { source => "t5547-push-quarantine.sh.tap" } );
        my @lines;
        while ( my $result = $parser->next ) {
            push @lines => $result;
        };
        say Dump \@lines
    ' >t5547-push-quarantine.sh.tap.parsed

Gives you a stream like:

    [...]
    - !!perl/hash:TAP::Parser::Result::Unknown
      raw: + chmod +x dest.git/hooks/pre-receive
      type: unknown
    - !!perl/hash:TAP::Parser::Result::Unknown
      raw: ''
      type: unknown
    - !!perl/hash:TAP::Parser::Result::Test
      description: '- create picky dest repo'
      directive: ''
      explanation: ''
      ok: ok
      raw: ok 1 - create picky dest repo
      test_num: 1
      type: test
    - !!perl/hash:TAP::Parser::Result::Unknown
      raw: ''
      type: unknown
    - !!perl/hash:TAP::Parser::Result::Unknown
      raw: 'expecting success of 5547.2 ''accepted objects work'': '
      type: unknown
    - !!perl/hash:TAP::Parser::Result::Unknown
      raw: "\ttest_commit ok &&"
      type: unknown
    - !!perl/hash:TAP::Parser::Result::Unknown
      raw: "\tgit push dest.git HEAD &&"
    [...]

The eventual goal was to make ci/print-test-failures.sh and the code
that cares about t/test-results/* capable of working with output like
that.

So e.g. you could optionally get summarized output about just the
specific tests that failed, not all the output for failing tests, as
ci/print-test-failures.sh is spewing out now.

I also wanted to have something similar to Documentation/doc-diff but
for smart test diffing. E.g. now we have an rc0 out, and the set of
tests broken on various test boxes I have access to is different than in
the last release.

But it's a pain to summarize that output currently (or at least I've
always written one-off tools for it).

By being able to parse the tap it's easier to massage that output and
e.g. spew it into a database, or into two text files friendly to "git
diff --no-index".

But yes, the implementation isn't any simpler, it's more complex than
just a "tee -a", but I think it's worth it for machine-readable verbose
test output.

1. As an aside this is a bit tricker/broken in the prove utility than
   when I wrote that code initially, sometimes it won't show you verbose
   output:
   https://github.com/Perl-Toolchain-Gang/Test-Harness/issues/105

[PATCH 0/6 + 1] test-lib: make --verbose output valid TAP

[Ævar Arnfjörð Bjarmason]

This makes the --verbose valid TAP.

This is a non-RFC version of an RFC patch I sent in
https://lore.kernel.org/git/87tupwj5y5.fsf@evledraar.gmail.com/

There's a 7/7 patch that's an RFC at the end. It works for me, but
since I haven't used the JUnit output it's likely subtly broken in
some way (e.g. the new output doesn't include a timestamp attribute),
but it shows how easy it is to add new output targets.

The eventual goal not included in this series is to have multiple
output targets, and e.g. convert ci/print-test-failures.sh to use a
TAP parser.

Machine-readable "TAP --verbose -x" output can bring us a lot of nice
things down the line, I have some local WIP code that's a smarter
version of ci/print-test-failures.sh that knows how to spew out only
the output relevant to the failing test(s).

Future improvements based on that could be showing what specific line
in a &&-chain failed, as well as e.g. running a debug version of a
failing "grep" if we detect that the failing line line was 'grep <pat>
<filename>'.

Ævar Arnfjörð Bjarmason (7):
  test-lib: remove test_external
  test-lib: add say_color_tap helper to emit TAP format
  test-lib: color "ok" TAP directives green under --verbose (or -x)
  test-lib: add tee with TAP support to test-tool
  test-lib: indent and format GIT_TEST_TEE_OUTPUT_FILE code
  test-lib: make --verbose output valid TAP
  test-lib: generate JUnit output via TAP

 Makefile                                      |   2 +-
 .../netrc/t-git-credential-netrc.sh           |   7 +-
 t/README                                      |  35 +--
 t/helper/test-date.c                          |  12 -
 t/helper/test-path-utils.c                    |  21 --
 t/helper/test-tee.c                           |  85 +++++++
 t/helper/test-tool.c                          |   2 +-
 t/helper/test-tool.h                          |   2 +-
 t/helper/test-xml-encode.c                    |  80 -------
 t/t0000-basic.sh                              |   8 +
 t/t0202-gettext-perl.sh                       |  10 +-
 t/t9700-perl-git.sh                           |  10 +-
 t/test-lib-functions.sh                       |  89 +------
 t/test-lib.sh                                 | 226 +++++-------------
 14 files changed, 177 insertions(+), 412 deletions(-)
 create mode 100644 t/helper/test-tee.c
 delete mode 100644 t/helper/test-xml-encode.c

-- 
2.31.0.rc1.210.g0f8085a843c

[PATCH 1/7] test-lib: remove test_external

[Ævar Arnfjörð Bjarmason]

Remove the test_external function(s) in favor of running the Perl
tests with a test_expect_success.

The only advantage of this wrapper added in
fb32c410087 (t/test-lib.sh: add test_external and
test_external_without_stderr, 2008-06-19) was that we got the
Test::More output as-is from the two wrapped scripts.

Now we'll instead hang until the script is finished, and report on its
exit code. The Test::More framework ensures that we exit with non-zero
exit code on failure.

My motivation for this is to eliminate a special case where things
that aren't test-lib.sh are going to produce TAP, for reasons that'll
be clear in subsequent commits.

This also eliminates special cases I added in d998bd4ab67 (test-lib:
Make the test_external_* functions TAP-aware, 2010-06-24) from
test-lib.sh itself.

Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
---
 .../netrc/t-git-credential-netrc.sh           |  7 +-
 t/README                                      | 26 ------
 t/t0202-gettext-perl.sh                       | 10 +--
 t/t9700-perl-git.sh                           | 10 +--
 t/test-lib-functions.sh                       | 89 +------------------
 t/test-lib.sh                                 | 42 ++++-----
 6 files changed, 28 insertions(+), 156 deletions(-)

diff --git a/contrib/credential/netrc/t-git-credential-netrc.sh b/contrib/credential/netrc/t-git-credential-netrc.sh
index 07227d02287..28118a9e194 100755
--- a/contrib/credential/netrc/t-git-credential-netrc.sh
+++ b/contrib/credential/netrc/t-git-credential-netrc.sh
@@ -20,13 +20,10 @@
 		'set up test repository' \
 		'git config --add gpg.program test.git-config-gpg'
 
-	# The external test will outputs its own plan
-	test_external_has_tap=1
-
 	export PERL5LIB="$GITPERLLIB"
-	test_external \
-		'git-credential-netrc' \
+	test_expect_success 'git-credential-netrc' '
 		perl "$GIT_BUILD_DIR"/contrib/credential/netrc/test.pl
+	'
 
 	test_done
 )
diff --git a/t/README b/t/README
index 593d4a4e270..2cc8cbc7185 100644
--- a/t/README
+++ b/t/README
@@ -844,32 +844,6 @@ library for your script to use.
 	    test_done
 	fi
 
- - test_external [<prereq>] <message> <external> <script>
-
-   Execute a <script> with an <external> interpreter (like perl). This
-   was added for tests like t9700-perl-git.sh which do most of their
-   work in an external test script.
-
-	test_external \
-	    'GitwebCache::*FileCache*' \
-	    perl "$TEST_DIRECTORY"/t9503/test_cache_interface.pl
-
-   If the test is outputting its own TAP you should set the
-   test_external_has_tap variable somewhere before calling the first
-   test_external* function. See t9700-perl-git.sh for an example.
-
-	# The external test will outputs its own plan
-	test_external_has_tap=1
-
- - test_external_without_stderr [<prereq>] <message> <external> <script>
-
-   Like test_external but fail if there's any output on stderr,
-   instead of checking the exit code.
-
-	test_external_without_stderr \
-	    'Perl API' \
-	    perl "$TEST_DIRECTORY"/t9700/test.pl
-
  - test_expect_code <exit-code> <command>
 
    Run a command and ensure that it exits with the given exit code.
diff --git a/t/t0202-gettext-perl.sh b/t/t0202-gettext-perl.sh
index a29d166e007..06a93b36790 100755
--- a/t/t0202-gettext-perl.sh
+++ b/t/t0202-gettext-perl.sh
@@ -17,11 +17,9 @@ perl -MTest::More -e 0 2>/dev/null || {
 	test_done
 }
 
-# The external test will outputs its own plan
-test_external_has_tap=1
-
-test_external_without_stderr \
-    'Perl Git::I18N API' \
-    perl "$TEST_DIRECTORY"/t0202/test.pl
+test_expect_success 'run t0202/test.pl to test Git::I18N.pm' '
+	perl "$TEST_DIRECTORY"/t0202/test.pl 2>stderr &&
+	test_must_be_empty stderr
+'
 
 test_done
diff --git a/t/t9700-perl-git.sh b/t/t9700-perl-git.sh
index 102c133112c..574c57b17f1 100755
--- a/t/t9700-perl-git.sh
+++ b/t/t9700-perl-git.sh
@@ -50,11 +50,9 @@ test_expect_success \
      git config --add test.pathmulti bar
      '
 
-# The external test will outputs its own plan
-test_external_has_tap=1
-
-test_external_without_stderr \
-    'Perl API' \
-    perl "$TEST_DIRECTORY"/t9700/test.pl
+test_expect_success 'use t9700/test.pl to test Git.pm' '
+	perl "$TEST_DIRECTORY"/t9700/test.pl 2>stderr &&
+	test_must_be_empty stderr
+'
 
 test_done
diff --git a/t/test-lib-functions.sh b/t/test-lib-functions.sh
index 3dd68091bbf..ead3afb36b3 100644
--- a/t/test-lib-functions.sh
+++ b/t/test-lib-functions.sh
@@ -468,7 +468,7 @@ write_script () {
 # - Explicitly using test_have_prereq.
 #
 # - Implicitly by specifying the prerequisite tag in the calls to
-#   test_expect_{success,failure} and test_external{,_without_stderr}.
+#   test_expect_{success,failure}
 #
 # The single parameter is the prerequisite tag (a simple word, in all
 # capital letters by convention).
@@ -660,93 +660,6 @@ test_expect_success () {
 	return 1
 }
 
-# test_external runs external test scripts that provide continuous
-# test output about their progress, and succeeds/fails on
-# zero/non-zero exit code.  It outputs the test output on stdout even
-# in non-verbose mode, and announces the external script with "# run
-# <n>: ..." before running it.  When providing relative paths, keep in
-# mind that all scripts run in "trash directory".
-# Usage: test_external description command arguments...
-# Example: test_external 'Perl API' perl ../path/to/test.pl
-test_external () {
-	test "$#" = 4 && { test_prereq=$1; shift; } || test_prereq=
-	test "$#" = 3 ||
-	BUG "not 3 or 4 parameters to test_external"
-	descr="$1"
-	shift
-	test_verify_prereq
-	export test_prereq
-	if ! test_skip "$descr" "$@"
-	then
-		# Announce the script to reduce confusion about the
-		# test output that follows.
-		say_color "" "# run $test_count: $descr ($*)"
-		# Export TEST_DIRECTORY, TRASH_DIRECTORY and GIT_TEST_LONG
-		# to be able to use them in script
-		export TEST_DIRECTORY TRASH_DIRECTORY GIT_TEST_LONG
-		# Run command; redirect its stderr to &4 as in
-		# test_run_, but keep its stdout on our stdout even in
-		# non-verbose mode.
-		"$@" 2>&4
-		if test "$?" = 0
-		then
-			if test $test_external_has_tap -eq 0; then
-				test_ok_ "$descr"
-			else
-				say_color "" "# test_external test $descr was ok"
-				test_success=$(($test_success + 1))
-			fi
-		else
-			if test $test_external_has_tap -eq 0; then
-				test_failure_ "$descr" "$@"
-			else
-				say_color error "# test_external test $descr failed: $@"
-				test_failure=$(($test_failure + 1))
-			fi
-		fi
-	fi
-}
-
-# Like test_external, but in addition tests that the command generated
-# no output on stderr.
-test_external_without_stderr () {
-	# The temporary file has no (and must have no) security
-	# implications.
-	tmp=${TMPDIR:-/tmp}
-	stderr="$tmp/git-external-stderr.$$.tmp"
-	test_external "$@" 4> "$stderr"
-	test -f "$stderr" || error "Internal error: $stderr disappeared."
-	descr="no stderr: $1"
-	shift
-	say >&3 "# expecting no stderr from previous command"
-	if test ! -s "$stderr"
-	then
-		rm "$stderr"
-
-		if test $test_external_has_tap -eq 0; then
-			test_ok_ "$descr"
-		else
-			say_color "" "# test_external_without_stderr test $descr was ok"
-			test_success=$(($test_success + 1))
-		fi
-	else
-		if test "$verbose" = t
-		then
-			output=$(echo; echo "# Stderr is:"; cat "$stderr")
-		else
-			output=
-		fi
-		# rm first in case test_failure exits.
-		rm "$stderr"
-		if test $test_external_has_tap -eq 0; then
-			test_failure_ "$descr" "$@" "$output"
-		else
-			say_color error "# test_external_without_stderr test $descr failed: $@: $output"
-			test_failure=$(($test_failure + 1))
-		fi
-	fi
-}
-
 # debugging-friendly alternatives to "test [-f|-d|-e]"
 # The commands test the existence or non-existence of $1
 test_path_is_file () {
diff --git a/t/test-lib.sh b/t/test-lib.sh
index d3f6af6a654..b0a8bc42510 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -631,8 +631,6 @@ test_fixed=0
 test_broken=0
 test_success=0
 
-test_external_has_tap=0
-
 die () {
 	code=$?
 	# This is responsible for running the atexit commands even when a
@@ -1146,27 +1144,24 @@ test_done () {
 	fi
 	case "$test_failure" in
 	0)
-		if test $test_external_has_tap -eq 0
+		if test $test_remaining -gt 0
 		then
-			if test $test_remaining -gt 0
-			then
-				say_color pass "# passed all $msg"
-			fi
-
-			# Maybe print SKIP message
-			test -z "$skip_all" || skip_all="# SKIP $skip_all"
-			case "$test_count" in
-			0)
-				say "1..$test_count${skip_all:+ $skip_all}"
-				;;
-			*)
-				test -z "$skip_all" ||
-				say_color warn "$skip_all"
-				say "1..$test_count"
-				;;
-			esac
+			say_color pass "# passed all $msg"
 		fi
 
+		# Maybe print SKIP message
+		test -z "$skip_all" || skip_all="# SKIP $skip_all"
+		case "$test_count" in
+		0)
+			say "1..$test_count${skip_all:+ $skip_all}"
+			;;
+		*)
+			test -z "$skip_all" ||
+			say_color warn "$skip_all"
+			say "1..$test_count"
+			;;
+		esac
+
 		if test -z "$debug"
 		then
 			test -d "$TRASH_DIRECTORY" ||
@@ -1185,11 +1180,8 @@ test_done () {
 		exit 0 ;;
 
 	*)
-		if test $test_external_has_tap -eq 0
-		then
-			say_color error "# failed $test_failure among $msg"
-			say "1..$test_count"
-		fi
+		say_color error "# failed $test_failure among $msg"
+		say "1..$test_count"
 
 		exit 1 ;;
 
-- 
2.31.0.rc1.210.g0f8085a843c

[PATCH 2/7] test-lib: add say_color_tap helper to emit TAP format

[Ævar Arnfjörð Bjarmason]

Follow-up 5099b99d25 (test-lib: Adjust output to be valid TAP format,
2010-06-24) and make it easy to distinguishing when we're emitting TAP
directives (with the new "say_color_tap"), and when we just want to
say something with colored text "say_color".

This also makes it easier to do any follow-up changes where we'd like
to do something special with the TAP directives, as they're what
drives the test when we run under the prove(1) utility.

Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
---
 t/test-lib.sh | 21 ++++++++++++++-------
 1 file changed, 14 insertions(+), 7 deletions(-)

diff --git a/t/test-lib.sh b/t/test-lib.sh
index b0a8bc42510..9a3a3d8d16d 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -562,6 +562,13 @@ else
 	}
 fi
 
+say_color_tap() {
+	test "$#" = 2 ||
+	BUG "not 2 parameters to say_color_tap"
+
+	say_color "$1" "$2"
+}
+
 TERM=dumb
 export TERM
 
@@ -666,7 +673,7 @@ test_ok_ () {
 		write_junit_xml_testcase "$*"
 	fi
 	test_success=$(($test_success + 1))
-	say_color "" "ok $test_count - $@"
+	say_color_tap "" "ok $test_count - $@"
 }
 
 test_failure_ () {
@@ -691,7 +698,7 @@ test_failure_ () {
 		write_junit_xml_testcase "$1" "      $junit_insert"
 	fi
 	test_failure=$(($test_failure + 1))
-	say_color error "not ok $test_count - $1"
+	say_color_tap error "not ok $test_count - $1"
 	shift
 	printf '%s\n' "$*" | sed -e 's/^/#	/'
 	test "$immediate" = "" || { finalize_junit_xml; GIT_EXIT_OK=t; exit 1; }
@@ -712,7 +719,7 @@ test_known_broken_failure_ () {
 		write_junit_xml_testcase "$* (known breakage)"
 	fi
 	test_broken=$(($test_broken+1))
-	say_color warn "not ok $test_count - $@ # TODO known breakage"
+	say_color_tap warn "not ok $test_count - $@ # TODO known breakage"
 }
 
 test_debug () {
@@ -1027,7 +1034,7 @@ test_skip () {
 				"      <skipped message=\"$message\" />"
 		fi
 
-		say_color skip "ok $test_count # skip $1 ($skipped_reason)"
+		say_color_tap skip "ok $test_count # skip $1 ($skipped_reason)"
 		: true
 		;;
 	*)
@@ -1153,12 +1160,12 @@ test_done () {
 		test -z "$skip_all" || skip_all="# SKIP $skip_all"
 		case "$test_count" in
 		0)
-			say "1..$test_count${skip_all:+ $skip_all}"
+			say_color_tap "" "1..$test_count${skip_all:+ $skip_all}"
 			;;
 		*)
 			test -z "$skip_all" ||
 			say_color warn "$skip_all"
-			say "1..$test_count"
+			say_color_tap "" "1..$test_count"
 			;;
 		esac
 
@@ -1181,7 +1188,7 @@ test_done () {
 
 	*)
 		say_color error "# failed $test_failure among $msg"
-		say "1..$test_count"
+		say_color_tap "" "1..$test_count"
 
 		exit 1 ;;
 
-- 
2.31.0.rc1.210.g0f8085a843c

[PATCH 3/7] test-lib: color "ok" TAP directives green under --verbose (or -x)

[Ævar Arnfjörð Bjarmason]

Change the color of "ok" lines to be green when we run under --verbose
or -x.

When a test fails we color the "not ok" line red, but the "ok" lines
are not colored.

I think that's the right thing to do in the default output, which is
e.g.:

    $ ./t0000-basic.sh
    ok 1 - verify that the running shell supports "local"
    ok 2 - .git/objects should be empty after git init in an empty repo
    ok 3 - .git/objects should have 3 subdirectories
    [...]

Having almost every line colored green in that output would be
distracting.

However, under --verbose we'll typically might emit 10-20 lines of
non-colored stderr and "info" colored output describing the test
itself.

When paging through that output always having the boundaries between
tests highlighted makes the output more readable.

Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
---
 t/test-lib.sh | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/t/test-lib.sh b/t/test-lib.sh
index 9a3a3d8d16d..8562b11b817 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -545,6 +545,7 @@ then
 	say_color_skip=$(tput setaf 4) # blue
 	say_color_warn=$(tput setaf 3) # brown/yellow
 	say_color_pass=$(tput setaf 2) # green
+	say_color_pass_all=$(tput bold; tput setaf 2) # bold green
 	say_color_info=$(tput setaf 6) # cyan
 	say_color_reset=$(tput sgr0)
 	say_color_="" # no formatting for normal text
@@ -673,7 +674,7 @@ test_ok_ () {
 		write_junit_xml_testcase "$*"
 	fi
 	test_success=$(($test_success + 1))
-	say_color_tap "" "ok $test_count - $@"
+	say_color_tap "${verbose:+pass}" "ok $test_count - $@"
 }
 
 test_failure_ () {
-- 
2.31.0.rc1.210.g0f8085a843c

[PATCH 4/7] test-lib: add tee with TAP support to test-tool

[Ævar Arnfjörð Bjarmason]

Add a 'test-tool tee' that behaves similarly to 'tee(1)', except that
it supports sanitizing the TAP emitted on stdout.

This is done by assuming that the TAP is emitted by a friendly library
that promises to prefix valid TAP directives with what we're going to
strip with --strip-prefix="".

Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
---
 Makefile             |  1 +
 t/helper/test-tee.c  | 85 ++++++++++++++++++++++++++++++++++++++++++++
 t/helper/test-tool.c |  1 +
 t/helper/test-tool.h |  1 +
 4 files changed, 88 insertions(+)
 create mode 100644 t/helper/test-tee.c

diff --git a/Makefile b/Makefile
index dfb0f1000fa..d26b9d62ee9 100644
--- a/Makefile
+++ b/Makefile
@@ -742,6 +742,7 @@ TEST_BUILTINS_OBJS += test-string-list.o
 TEST_BUILTINS_OBJS += test-submodule-config.o
 TEST_BUILTINS_OBJS += test-submodule-nested-repo-config.o
 TEST_BUILTINS_OBJS += test-subprocess.o
+TEST_BUILTINS_OBJS += test-tee.o
 TEST_BUILTINS_OBJS += test-trace2.o
 TEST_BUILTINS_OBJS += test-urlmatch-normalization.o
 TEST_BUILTINS_OBJS += test-wildmatch.o
diff --git a/t/helper/test-tee.c b/t/helper/test-tee.c
new file mode 100644
index 00000000000..4ed34e9db93
--- /dev/null
+++ b/t/helper/test-tee.c
@@ -0,0 +1,85 @@
+#include "test-tool.h"
+#include "parse-options.h"
+#include "strbuf.h"
+
+static int line_has_tap(struct strbuf *line)
+{
+	/*
+	 * This is a less permissive version of
+	 * https://metacpan.org/release/Test-Harness/source/lib/TAP/Parser/Grammar.pm
+	 */
+	if (starts_with(line->buf, "ok") ||
+	    starts_with(line->buf, "not ok") ||
+	    starts_with(line->buf, "1..") ||
+	    starts_with(line->buf, "Bail out!") ||
+	    starts_with(line->buf, "TAP version") ||
+	    starts_with(line->buf, "pragma"))
+		return 1;
+	if (starts_with(line->buf, "#"))
+		/*
+		 * We're ignoring comments from now, but might treat them
+		 * specially in the future for sanctioned messaging from the
+		 * test-lib.sh.
+		 */
+		return 0;
+	return  0;
+}
+
+int cmd__tee(int argc, const char **argv)
+{
+	int tap = 0;
+	int escape_stdout = 0, escape_file = 0;
+	char *prefix = NULL;
+	size_t prefix_len = 0;
+	const char *tee_usage[] = {
+		"test-tool tee [<options>] <FILE>",
+		NULL
+	};
+	struct option options[] = {
+		OPT_BOOL(0, "escape-stdout", &escape_stdout,
+			 "escape output on stdout"),
+		OPT_BOOL(0, "escape-file", &escape_file,
+			 "escape output written to file"),
+		OPT_BOOL(0, "tap", &tap,
+			 "output is TAP"),
+		OPT_STRING(0, "prefix", &prefix, "str",
+			   "prefix to strip from the output"),
+		OPT_END()
+	};
+	struct strbuf line = STRBUF_INIT;
+	FILE *logfp = NULL;
+
+	argc = parse_options(argc, argv, NULL, options,
+			     tee_usage, PARSE_OPT_STOP_AT_NON_OPTION);
+	if (argc > 1) {
+		fprintf(stderr, "got bad option: %s\n", argv[0]);
+		usage_with_options(tee_usage, options);
+	}
+	if (prefix)
+		prefix_len = strlen(prefix);
+
+	if (argc)
+		logfp = xfopen(argv[0], "w");
+
+	while (strbuf_getline(&line, stdin) != EOF) {
+		size_t offs = 0;
+		if (prefix && starts_with(line.buf, prefix))
+			offs = prefix_len;
+
+		if (!offs && tap && line_has_tap(&line)) {
+			if (escape_stdout)
+				fprintf(stdout, "\\");
+			if (logfp && escape_file)
+				fprintf(logfp, "\\");
+		}
+
+		fprintf(stdout, "%s\n", line.buf + offs);
+		if (logfp)
+			fprintf(logfp, "%s\n", line.buf + offs);
+	}
+	strbuf_release(&line);
+	if (logfp)
+		fclose(logfp);
+
+	return 0;
+}
diff --git a/t/helper/test-tool.c b/t/helper/test-tool.c
index f97cd9f48a6..1876bad8f42 100644
--- a/t/helper/test-tool.c
+++ b/t/helper/test-tool.c
@@ -70,6 +70,7 @@ static struct test_cmd cmds[] = {
 	{ "submodule-config", cmd__submodule_config },
 	{ "submodule-nested-repo-config", cmd__submodule_nested_repo_config },
 	{ "subprocess", cmd__subprocess },
+	{ "tee", cmd__tee },
 	{ "trace2", cmd__trace2 },
 	{ "urlmatch-normalization", cmd__urlmatch_normalization },
 	{ "xml-encode", cmd__xml_encode },
diff --git a/t/helper/test-tool.h b/t/helper/test-tool.h
index 28072c0ad5a..9b3c1f75267 100644
--- a/t/helper/test-tool.h
+++ b/t/helper/test-tool.h
@@ -60,6 +60,7 @@ int cmd__string_list(int argc, const char **argv);
 int cmd__submodule_config(int argc, const char **argv);
 int cmd__submodule_nested_repo_config(int argc, const char **argv);
 int cmd__subprocess(int argc, const char **argv);
+int cmd__tee(int argc, const char **argv);
 int cmd__trace2(int argc, const char **argv);
 int cmd__urlmatch_normalization(int argc, const char **argv);
 int cmd__xml_encode(int argc, const char **argv);
-- 
2.31.0.rc1.210.g0f8085a843c

[PATCH 5/7] test-lib: indent and format GIT_TEST_TEE_OUTPUT_FILE code

[Ævar Arnfjörð Bjarmason]

Change the indentation and formatting of the GIT_TEST_TEE_OUTPUT_FILE
code block added in 44138559e8 (test-lib.sh: optionally output to
test-results/$TEST.out, too, 2009-02-04).

This brings it in line with the general style in our test library, and
makes it easier to read modifications of it in subsequent commits.

Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
---
 t/test-lib.sh | 6 ++++--
 1 file changed, 4 insertions(+), 2 deletions(-)

diff --git a/t/test-lib.sh b/t/test-lib.sh
index 8562b11b817..aa7068b06b6 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -361,8 +361,10 @@ then
 	# from any previous runs.
 	>"$GIT_TEST_TEE_OUTPUT_FILE"
 
-	(GIT_TEST_TEE_STARTED=done ${TEST_SHELL_PATH} "$0" "$@" 2>&1;
-	 echo $? >"$TEST_RESULTS_BASE.exit") | tee -a "$GIT_TEST_TEE_OUTPUT_FILE"
+	(
+		GIT_TEST_TEE_STARTED=done ${TEST_SHELL_PATH} "$0" "$@" 2>&1
+		echo $? >"$TEST_RESULTS_BASE.exit"
+	) | tee -a "$GIT_TEST_TEE_OUTPUT_FILE"
 	test "$(cat "$TEST_RESULTS_BASE.exit")" = 0
 	exit
 fi
-- 
2.31.0.rc1.210.g0f8085a843c

[PATCH 6/7] test-lib: make --verbose output valid TAP

[Ævar Arnfjörð Bjarmason]

Make the --verbose output be valid TAP, making it machine-readable for
TAP parsers again.

Both the verbose and non-verbose test outputs were valid TAP back when
I added support for TAP in 5099b99d25f (test-lib: Adjust output to be
valid TAP format, 2010-06-24).

Sometime after that the --verbose output broke due to some tests
emitting their own lines starting "ok" (or otherwise invalidate the
TAP). That was noticed and fixed in 452320f1f5 (test-lib: add
--verbose-log option, 2016-10-21) and "fixed" by simply turning off
the verbose mode when we were running under TAP::Harness (e.g. under
"prove").

That solution worked for running under Travis CI. After that fix it
was made to use the --verbose-log option in 041c72de109 (travis: use
--verbose-log test option, 2016-10-21), see 522354d70f4 (Add Travis CI
support, 2015-11-27) for the "cat t/test-results/*.out" code that was
aimed at.

But that solution and others discussed in 452320f1f5 closed the door
on us having reliable machine-readable TAP output.

Let's instead revert the work done in 452320f1f5 and, as well as the
follow-up commits 88c6e9d31c (test-lib: --valgrind should not override
--verbose-log, 2017-09-05) and f5ba2de6bc (test-lib: make "-x" work
with "--verbose-log", 2017-12-08), which were only needed to work
around bugs in the the previous --verbose-log implementation.

Replace it with a simple method for ensuring that we have valid TAP
both on stdout, and in any verbose output we write. When we detect
that we're running under "prove" we prefix all legitimate TAP
directives with "GIT_TEST_TEE_STARTED":

    $ GIT_TEST_TEE_STARTED=1 ./t5547-push-quarantine.sh
    GIT_TEST_TEE_STARTED ok 1 - create picky dest repo
    GIT_TEST_TEE_STARTED ok 2 - accepted objects work
    [...]
    GIT_TEST_TEE_STARTED 1..6

Then, instead of piping the output to "tee -a" we pipe it to a helper
which first converts "ok" and other TAP syntax to e.g. "\ok", and then
strips that "GIT_TEST_TEE_STARTED " prefix from the start of the line.

The end result is that we're guaranteed to have valid TAP syntax on
stdout.

We can thus get rid of the --verbose-log special-case. Since that
option was meant to get around the TAP issue let's simply make it an
alias for "--verbose --tee".

Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
---
 t/README         |  9 ++++++---
 t/t0000-basic.sh |  8 ++++++++
 t/test-lib.sh    | 43 +++++++++++++++++++++----------------------
 3 files changed, 35 insertions(+), 25 deletions(-)

diff --git a/t/README b/t/README
index 2cc8cbc7185..f09d94e754e 100644
--- a/t/README
+++ b/t/README
@@ -157,10 +157,13 @@ appropriately before running "make". Short options can be bundled, i.e.
 
 -V::
 --verbose-log::
-	Write verbose output to the same logfile as `--tee`, but do
-	_not_ write it to stdout. Unlike `--tee --verbose`, this option
+	An alias for `--verbose --tee`. This option
 	is safe to use when stdout is being consumed by a TAP parser
-	like `prove`. Implies `--tee` and `--verbose`.
+	like `prove`.
+	Historically this option was different from `--verbose --tee`
+	and would not write any verbose output to stdout to ensure the
+	TAP-correctness of the output. The TAP-correctness of the
+	output is now sanity checked by the test library,
 
 --with-dashes::
 	By default tests are run without dashed forms of
diff --git a/t/t0000-basic.sh b/t/t0000-basic.sh
index 705d62cc27a..2a95a612fb0 100755
--- a/t/t0000-basic.sh
+++ b/t/t0000-basic.sh
@@ -76,6 +76,14 @@ _run_sub_test_lib_test_common () {
 		# this variable, so we need a stable setting under which to run
 		# the sub-test.
 		sane_unset HARNESS_ACTIVE &&
+
+		# When under --tee pretend we're not as far as
+		# emitting the "GIT_TEST_TEE_STARTED " TAP sanity
+		# prefix goes. This means we promise not to emit
+		# invalid TAP, least this test fails under --tee under
+		# prove(1).
+		sane_unset GIT_TEST_TEE_STARTED &&
+
 		cd "$name" &&
 		write_script "$name.sh" "$TEST_SHELL_PATH" <<-EOF &&
 		test_description='$descr (run in sub test-lib)
diff --git a/t/test-lib.sh b/t/test-lib.sh
index aa7068b06b6..0070d05234b 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -146,9 +146,11 @@ parse_option () {
 	--no-chain-lint)
 		GIT_TEST_CHAIN_LINT=0 ;;
 	-x)
-		trace=t ;;
+		trace=t
+		verbose=t
+		;;
 	-V|--verbose-log)
-		verbose_log=t
+		verbose=t
 		tee=t
 		;;
 	--write-junit-xml)
@@ -233,7 +235,7 @@ then
 	test -z "$verbose" && verbose_only="$valgrind_only"
 elif test -n "$valgrind"
 then
-	test -z "$verbose_log" && verbose=t
+	verbose=t
 fi
 
 if test -n "$stress"
@@ -364,9 +366,22 @@ then
 	(
 		GIT_TEST_TEE_STARTED=done ${TEST_SHELL_PATH} "$0" "$@" 2>&1
 		echo $? >"$TEST_RESULTS_BASE.exit"
-	) | tee -a "$GIT_TEST_TEE_OUTPUT_FILE"
+	) | "$GIT_BUILD_DIR"/t/helper/test-tool tee \
+		--tap --prefix="GIT_TEST_TEE_STARTED " \
+		--escape-stdout ${HARNESS_ACTIVE+--escape-file} \
+		"$GIT_TEST_TEE_OUTPUT_FILE"
 	test "$(cat "$TEST_RESULTS_BASE.exit")" = 0
 	exit
+elif test -n "$verbose" -a -n "$HARNESS_ACTIVE"
+then
+	ret=
+	(
+		GIT_TEST_TEE_STARTED=done ${TEST_SHELL_PATH} "$0" "$@" 2>&1
+		ret=$?
+	) | "$GIT_BUILD_DIR"/t/helper/test-tool tee \
+		--tap --prefix="GIT_TEST_TEE_STARTED " \
+		--escape-stdout
+	exit $ret
 fi
 
 if test -n "$trace" && test -n "$test_untraceable"
@@ -392,10 +407,6 @@ then
 		trace=
 	fi
 fi
-if test -n "$trace" && test -z "$verbose_log"
-then
-	verbose=t
-fi
 
 # For repeatability, reset the environment to known value.
 # TERM is sanitized below, after saving color control sequences.
@@ -569,7 +580,7 @@ say_color_tap() {
 	test "$#" = 2 ||
 	BUG "not 2 parameters to say_color_tap"
 
-	say_color "$1" "$2"
+	say_color "$1" "${GIT_TEST_TEE_STARTED:+GIT_TEST_TEE_STARTED }$2"
 }
 
 TERM=dumb
@@ -590,16 +601,6 @@ say () {
 	say_color info "$*"
 }
 
-if test -n "$HARNESS_ACTIVE"
-then
-	if test "$verbose" = t || test -n "$verbose_only"
-	then
-		printf 'Bail out! %s\n' \
-		 'verbose mode forbidden under TAP harness; try --verbose-log'
-		exit 1
-	fi
-fi
-
 test "${test_description}" != "" ||
 error "Test script did not set test_description."
 
@@ -887,9 +888,7 @@ maybe_setup_valgrind () {
 
 trace_level_=0
 want_trace () {
-	test "$trace" = t && {
-		test "$verbose" = t || test "$verbose_log" = t
-	}
+	test "$trace" = t && test "$verbose" = t
 }
 
 # This is a separate function because some tests use
-- 
2.31.0.rc1.210.g0f8085a843c

[RFC/PATCH 7/7] test-lib: generate JUnit output via TAP

[Ævar Arnfjörð Bjarmason]

Rewrite the home-brew JUnit output generation added in
22231908151 (tests: optionally write results as JUnit-style .xml,
2019-01-29) and other subsequent commits to be generated via the TAP
output.

This is now possible that the TAP output emitted with --tee is
guaranteed to be valid TAP, see the preceding commit.

The JUnit output is not bug-for-bug compatible with the previous
output, but it looks better to me.

This also requires installing TAP::Formatter::JUnit[1], perhaps that's
not palatable to the users of the --write-junit-xml option.

In any case, it'll be easy to whip up our own TAP emitter with a
TAP::Parser and TAP::Formatter, both of whom come with perl itself,
which we already rely on for tests.

It should also be significantly faster on Windows, as we can
e.g. write all the *.out files, and only do that conversion at the end
for all files in a batch, as opposed to the current implementation of
shelling out to test-tool in a loop for each test.

1. https://metacpan.org/pod/distribution/TAP-Formatter-JUnit/script/tap2junit

Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
---
 Makefile                   |   1 -
 t/helper/test-date.c       |  12 ----
 t/helper/test-path-utils.c |  21 -------
 t/helper/test-tool.c       |   1 -
 t/helper/test-tool.h       |   1 -
 t/helper/test-xml-encode.c |  80 ------------------------
 t/test-lib.sh              | 123 ++++---------------------------------
 7 files changed, 12 insertions(+), 227 deletions(-)
 delete mode 100644 t/helper/test-xml-encode.c

diff --git a/Makefile b/Makefile
index d26b9d62ee9..fa7c52f7a42 100644
--- a/Makefile
+++ b/Makefile
@@ -748,7 +748,6 @@ TEST_BUILTINS_OBJS += test-urlmatch-normalization.o
 TEST_BUILTINS_OBJS += test-wildmatch.o
 TEST_BUILTINS_OBJS += test-windows-named-pipe.o
 TEST_BUILTINS_OBJS += test-write-cache.o
-TEST_BUILTINS_OBJS += test-xml-encode.o
 
 # Do not add more tests here unless they have extra dependencies. Add
 # them in TEST_BUILTINS_OBJS above.
diff --git a/t/helper/test-date.c b/t/helper/test-date.c
index 099eff4f0fc..ebf133943b3 100644
--- a/t/helper/test-date.c
+++ b/t/helper/test-date.c
@@ -8,7 +8,6 @@ static const char *usage_msg = "\n"
 "  test-tool date parse [date]...\n"
 "  test-tool date approxidate [date]...\n"
 "  test-tool date timestamp [date]...\n"
-"  test-tool date getnanos [start-nanos]\n"
 "  test-tool date is64bit\n"
 "  test-tool date time_t-is64bit\n";
 
@@ -92,15 +91,6 @@ static void parse_approx_timestamp(const char **argv)
 	}
 }
 
-static void getnanos(const char **argv)
-{
-	double seconds = getnanotime() / 1.0e9;
-
-	if (*argv)
-		seconds -= strtod(*argv, NULL);
-	printf("%lf\n", seconds);
-}
-
 int cmd__date(int argc, const char **argv)
 {
 	const char *x;
@@ -120,8 +110,6 @@ int cmd__date(int argc, const char **argv)
 		parse_approxidate(argv+1);
 	else if (!strcmp(*argv, "timestamp"))
 		parse_approx_timestamp(argv+1);
-	else if (!strcmp(*argv, "getnanos"))
-		getnanos(argv+1);
 	else if (!strcmp(*argv, "is64bit"))
 		return sizeof(timestamp_t) == 8 ? 0 : 1;
 	else if (!strcmp(*argv, "time_t-is64bit"))
diff --git a/t/helper/test-path-utils.c b/t/helper/test-path-utils.c
index 313a153209c..090596ac492 100644
--- a/t/helper/test-path-utils.c
+++ b/t/helper/test-path-utils.c
@@ -407,27 +407,6 @@ int cmd__path_utils(int argc, const char **argv)
 		return !!res;
 	}
 
-	if (argc == 4 && !strcmp(argv[1], "skip-n-bytes")) {
-		int fd = open(argv[2], O_RDONLY), offset = atoi(argv[3]);
-		char buffer[65536];
-
-		if (fd < 0)
-			die_errno("could not open '%s'", argv[2]);
-		if (lseek(fd, offset, SEEK_SET) < 0)
-			die_errno("could not skip %d bytes", offset);
-		for (;;) {
-			ssize_t count = read(fd, buffer, sizeof(buffer));
-			if (count < 0)
-				die_errno("could not read '%s'", argv[2]);
-			if (!count)
-				break;
-			if (write(1, buffer, count) < 0)
-				die_errno("could not write to stdout");
-		}
-		close(fd);
-		return 0;
-	}
-
 	if (argc > 5 && !strcmp(argv[1], "slice-tests")) {
 		int res = 0;
 		long offset, stride, i;
diff --git a/t/helper/test-tool.c b/t/helper/test-tool.c
index 1876bad8f42..3fa02011b61 100644
--- a/t/helper/test-tool.c
+++ b/t/helper/test-tool.c
@@ -73,7 +73,6 @@ static struct test_cmd cmds[] = {
 	{ "tee", cmd__tee },
 	{ "trace2", cmd__trace2 },
 	{ "urlmatch-normalization", cmd__urlmatch_normalization },
-	{ "xml-encode", cmd__xml_encode },
 	{ "wildmatch", cmd__wildmatch },
 #ifdef GIT_WINDOWS_NATIVE
 	{ "windows-named-pipe", cmd__windows_named_pipe },
diff --git a/t/helper/test-tool.h b/t/helper/test-tool.h
index 9b3c1f75267..5028730807e 100644
--- a/t/helper/test-tool.h
+++ b/t/helper/test-tool.h
@@ -63,7 +63,6 @@ int cmd__subprocess(int argc, const char **argv);
 int cmd__tee(int argc, const char **argv);
 int cmd__trace2(int argc, const char **argv);
 int cmd__urlmatch_normalization(int argc, const char **argv);
-int cmd__xml_encode(int argc, const char **argv);
 int cmd__wildmatch(int argc, const char **argv);
 #ifdef GIT_WINDOWS_NATIVE
 int cmd__windows_named_pipe(int argc, const char **argv);
diff --git a/t/helper/test-xml-encode.c b/t/helper/test-xml-encode.c
deleted file mode 100644
index a648bbd961c..00000000000
--- a/t/helper/test-xml-encode.c
+++ /dev/null
@@ -1,80 +0,0 @@
-#include "test-tool.h"
-
-static const char *utf8_replace_character = "&#xfffd;";
-
-/*
- * Encodes (possibly incorrect) UTF-8 on <stdin> to <stdout>, to be embedded
- * in an XML file.
- */
-int cmd__xml_encode(int argc, const char **argv)
-{
-	unsigned char buf[1024], tmp[4], *tmp2 = NULL;
-	ssize_t cur = 0, len = 1, remaining = 0;
-	unsigned char ch;
-
-	for (;;) {
-		if (++cur == len) {
-			len = xread(0, buf, sizeof(buf));
-			if (!len)
-				return 0;
-			if (len < 0)
-				die_errno("Could not read <stdin>");
-			cur = 0;
-		}
-		ch = buf[cur];
-
-		if (tmp2) {
-			if ((ch & 0xc0) != 0x80) {
-				fputs(utf8_replace_character, stdout);
-				tmp2 = NULL;
-				cur--;
-				continue;
-			}
-			*tmp2 = ch;
-			tmp2++;
-			if (--remaining == 0) {
-				fwrite(tmp, tmp2 - tmp, 1, stdout);
-				tmp2 = NULL;
-			}
-			continue;
-		}
-
-		if (!(ch & 0x80)) {
-			/* 0xxxxxxx */
-			if (ch == '&')
-				fputs("&amp;", stdout);
-			else if (ch == '\'')
-				fputs("&apos;", stdout);
-			else if (ch == '"')
-				fputs("&quot;", stdout);
-			else if (ch == '<')
-				fputs("&lt;", stdout);
-			else if (ch == '>')
-				fputs("&gt;", stdout);
-			else if (ch >= 0x20)
-				fputc(ch, stdout);
-			else if (ch == 0x09 || ch == 0x0a || ch == 0x0d)
-				fprintf(stdout, "&#x%02x;", ch);
-			else
-				fputs(utf8_replace_character, stdout);
-		} else if ((ch & 0xe0) == 0xc0) {
-			/* 110XXXXx 10xxxxxx */
-			tmp[0] = ch;
-			remaining = 1;
-			tmp2 = tmp + 1;
-		} else if ((ch & 0xf0) == 0xe0) {
-			/* 1110XXXX 10Xxxxxx 10xxxxxx */
-			tmp[0] = ch;
-			remaining = 2;
-			tmp2 = tmp + 1;
-		} else if ((ch & 0xf8) == 0xf0) {
-			/* 11110XXX 10XXxxxx 10xxxxxx 10xxxxxx */
-			tmp[0] = ch;
-			remaining = 3;
-			tmp2 = tmp + 1;
-		} else
-			fputs(utf8_replace_character, stdout);
-	}
-
-	return 0;
-}
diff --git a/t/test-lib.sh b/t/test-lib.sh
index 0070d05234b..4dc41eeccc2 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -371,6 +371,17 @@ then
 		--escape-stdout ${HARNESS_ACTIVE+--escape-file} \
 		"$GIT_TEST_TEE_OUTPUT_FILE"
 	test "$(cat "$TEST_RESULTS_BASE.exit")" = 0
+	if test -n "$write_junit_xml"
+	then
+		junit_xml_dir="$TEST_OUTPUT_DIRECTORY/out"
+		mkdir -p "$junit_xml_dir"
+		junit_xml_base=${0##*/}
+		junit_xml_path="$junit_xml_dir/TEST-${junit_xml_base%.sh}.xml"
+		junit_attrs="timestamp=\"$(TZ=UTC date +%Y-%m-%dT%H:%M:%S)\""
+		tap2junit --name="$TEST_NAME" - \
+			<"$GIT_TEST_TEE_OUTPUT_FILE" \
+			>"$junit_xml_path"
+	fi
 	exit
 elif test -n "$verbose" -a -n "$HARNESS_ACTIVE"
 then
@@ -588,7 +599,6 @@ export TERM
 
 error () {
 	say_color error "error: $*"
-	finalize_junit_xml
 	GIT_EXIT_OK=t
 	exit 1
 }
@@ -672,56 +682,24 @@ trap '{ code=$?; set +x; } 2>/dev/null; exit $code' INT TERM HUP
 # the test_expect_* functions instead.
 
 test_ok_ () {
-	if test -n "$write_junit_xml"
-	then
-		write_junit_xml_testcase "$*"
-	fi
 	test_success=$(($test_success + 1))
 	say_color_tap "${verbose:+pass}" "ok $test_count - $@"
 }
 
 test_failure_ () {
-	if test -n "$write_junit_xml"
-	then
-		junit_insert="<failure message=\"not ok $test_count -"
-		junit_insert="$junit_insert $(xml_attr_encode "$1")\">"
-		junit_insert="$junit_insert $(xml_attr_encode \
-			"$(if test -n "$GIT_TEST_TEE_OUTPUT_FILE"
-			   then
-				test-tool path-utils skip-n-bytes \
-					"$GIT_TEST_TEE_OUTPUT_FILE" $GIT_TEST_TEE_OFFSET
-			   else
-				printf '%s\n' "$@" | sed 1d
-			   fi)")"
-		junit_insert="$junit_insert</failure>"
-		if test -n "$GIT_TEST_TEE_OUTPUT_FILE"
-		then
-			junit_insert="$junit_insert<system-err>$(xml_attr_encode \
-				"$(cat "$GIT_TEST_TEE_OUTPUT_FILE")")</system-err>"
-		fi
-		write_junit_xml_testcase "$1" "      $junit_insert"
-	fi
 	test_failure=$(($test_failure + 1))
 	say_color_tap error "not ok $test_count - $1"
 	shift
 	printf '%s\n' "$*" | sed -e 's/^/#	/'
-	test "$immediate" = "" || { finalize_junit_xml; GIT_EXIT_OK=t; exit 1; }
+	test "$immediate" = "" || { GIT_EXIT_OK=t; exit 1; }
 }
 
 test_known_broken_ok_ () {
-	if test -n "$write_junit_xml"
-	then
-		write_junit_xml_testcase "$* (breakage fixed)"
-	fi
 	test_fixed=$(($test_fixed+1))
 	say_color error "ok $test_count - $@ # TODO known breakage vanished"
 }
 
 test_known_broken_failure_ () {
-	if test -n "$write_junit_xml"
-	then
-		write_junit_xml_testcase "$* (known breakage)"
-	fi
 	test_broken=$(($test_broken+1))
 	say_color_tap warn "not ok $test_count - $@ # TODO known breakage"
 }
@@ -983,10 +961,6 @@ test_start_ () {
 	test_count=$(($test_count+1))
 	maybe_setup_verbose
 	maybe_setup_valgrind
-	if test -n "$write_junit_xml"
-	then
-		junit_start=$(test-tool date getnanos)
-	fi
 }
 
 test_finish_ () {
@@ -1029,13 +1003,6 @@ test_skip () {
 
 	case "$to_skip" in
 	t)
-		if test -n "$write_junit_xml"
-		then
-			message="$(xml_attr_encode "$skipped_reason")"
-			write_junit_xml_testcase "$1" \
-				"      <skipped message=\"$message\" />"
-		fi
-
 		say_color_tap skip "ok $test_count # skip $1 ($skipped_reason)"
 		: true
 		;;
@@ -1050,53 +1017,6 @@ test_at_end_hook_ () {
 	:
 }
 
-write_junit_xml () {
-	case "$1" in
-	--truncate)
-		>"$junit_xml_path"
-		junit_have_testcase=
-		shift
-		;;
-	esac
-	printf '%s\n' "$@" >>"$junit_xml_path"
-}
-
-xml_attr_encode () {
-	printf '%s\n' "$@" | test-tool xml-encode
-}
-
-write_junit_xml_testcase () {
-	junit_attrs="name=\"$(xml_attr_encode "$this_test.$test_count $1")\""
-	shift
-	junit_attrs="$junit_attrs classname=\"$this_test\""
-	junit_attrs="$junit_attrs time=\"$(test-tool \
-		date getnanos $junit_start)\""
-	write_junit_xml "$(printf '%s\n' \
-		"    <testcase $junit_attrs>" "$@" "    </testcase>")"
-	junit_have_testcase=t
-}
-
-finalize_junit_xml () {
-	if test -n "$write_junit_xml" && test -n "$junit_xml_path"
-	then
-		test -n "$junit_have_testcase" || {
-			junit_start=$(test-tool date getnanos)
-			write_junit_xml_testcase "all tests skipped"
-		}
-
-		# adjust the overall time
-		junit_time=$(test-tool date getnanos $junit_suite_start)
-		sed -e "s/\(<testsuite.*\) time=\"[^\"]*\"/\1/" \
-			-e "s/<testsuite [^>]*/& time=\"$junit_time\"/" \
-			-e '/^ *<\/testsuite/d' \
-			<"$junit_xml_path" >"$junit_xml_path.new"
-		mv "$junit_xml_path.new" "$junit_xml_path"
-
-		write_junit_xml "  </testsuite>" "</testsuites>"
-		write_junit_xml=
-	fi
-}
-
 test_atexit_cleanup=:
 test_atexit_handler () {
 	# In a succeeding test script 'test_atexit_handler' is invoked
@@ -1119,8 +1039,6 @@ test_done () {
 	# removed, so the commands can access pidfiles and socket files.
 	test_atexit_handler
 
-	finalize_junit_xml
-
 	if test -z "$HARNESS_ACTIVE"
 	then
 		mkdir -p "$TEST_RESULTS_DIR"
@@ -1364,23 +1282,6 @@ then
 	test_done
 fi
 
-if test -n "$write_junit_xml"
-then
-	junit_xml_dir="$TEST_OUTPUT_DIRECTORY/out"
-	mkdir -p "$junit_xml_dir"
-	junit_xml_base=${0##*/}
-	junit_xml_path="$junit_xml_dir/TEST-${junit_xml_base%.sh}.xml"
-	junit_attrs="name=\"${junit_xml_base%.sh}\""
-	junit_attrs="$junit_attrs timestamp=\"$(TZ=UTC \
-		date +%Y-%m-%dT%H:%M:%S)\""
-	write_junit_xml --truncate "<testsuites>" "  <testsuite $junit_attrs>"
-	junit_suite_start=$(test-tool date getnanos)
-	if test -n "$GIT_TEST_TEE_OUTPUT_FILE"
-	then
-		GIT_TEST_TEE_OFFSET=0
-	fi
-fi
-
 # Convenience
 # A regexp to match 5, 35 and 40 hexdigits
 _x05='[0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f]'
-- 
2.31.0.rc1.210.g0f8085a843c

Re: [PATCH 0/6 + 1] test-lib: make --verbose output valid TAP

[SZEDER Gábor]

On Tue, Mar 09, 2021 at 05:02:12PM +0100, Ævar Arnfjörð Bjarmason wrote:
> The eventual goal not included in this series is to have multiple
> output targets, and e.g. convert ci/print-test-failures.sh to use a
> TAP parser.
> 
> Machine-readable "TAP --verbose -x" output can bring us a lot of nice
> things down the line, I have some local WIP code that's a smarter
> version of ci/print-test-failures.sh that knows how to spew out only
> the output relevant to the failing test(s).

I wonder what you mean by the word "relevant" here, as I can't imagine
how you could possibly identify what is relevant for a failing test
and what isn't.  If you didn't at all meant "relevant", but that it
will show only the output of the failing test(s), then this is a bad
example.  Our test cases depend too much on previous test cases, and a
failure of one test can be the result of a change in a previous
successful tests.

Therefore, any such change to 'ci/print-test-failures.sh' will have my
firm NACK.

Re: [PATCH 6/7] test-lib: make --verbose output valid TAP

[SZEDER Gábor]

On Tue, Mar 09, 2021 at 05:02:18PM +0100, Ævar Arnfjörð Bjarmason wrote:
> Make the --verbose output be valid TAP, making it machine-readable for
> TAP parsers again.
> 
> Both the verbose and non-verbose test outputs were valid TAP back when
> I added support for TAP in 5099b99d25f (test-lib: Adjust output to be
> valid TAP format, 2010-06-24).
> 
> Sometime after that the --verbose output broke due to some tests
> emitting their own lines starting "ok" (or otherwise invalidate the
> TAP). That was noticed and fixed in 452320f1f5 (test-lib: add
> --verbose-log option, 2016-10-21) and "fixed" by simply turning off
> the verbose mode when we were running under TAP::Harness (e.g. under
> "prove").
> 
> That solution worked for running under Travis CI. After that fix it
> was made to use the --verbose-log option in 041c72de109 (travis: use
> --verbose-log test option, 2016-10-21), see 522354d70f4 (Add Travis CI
> support, 2015-11-27) for the "cat t/test-results/*.out" code that was
> aimed at.
> 
> But that solution and others discussed in 452320f1f5 closed the door
> on us having reliable machine-readable TAP output.
> 
> Let's instead revert the work done in 452320f1f5 and, as well as the
> follow-up commits 88c6e9d31c (test-lib: --valgrind should not override
> --verbose-log, 2017-09-05) and f5ba2de6bc (test-lib: make "-x" work
> with "--verbose-log", 2017-12-08), which were only needed to work
> around bugs in the the previous --verbose-log implementation.
> 
> Replace it with a simple method for ensuring that we have valid TAP
> both on stdout, and in any verbose output we write. When we detect
> that we're running under "prove" we prefix all legitimate TAP
> directives with "GIT_TEST_TEE_STARTED":
> 
>     $ GIT_TEST_TEE_STARTED=1 ./t5547-push-quarantine.sh
>     GIT_TEST_TEE_STARTED ok 1 - create picky dest repo
>     GIT_TEST_TEE_STARTED ok 2 - accepted objects work
>     [...]
>     GIT_TEST_TEE_STARTED 1..6
> 
> Then, instead of piping the output to "tee -a" we pipe it to a helper
> which first converts "ok" and other TAP syntax to e.g. "\ok", and then
> strips that "GIT_TEST_TEE_STARTED " prefix from the start of the line.
> 
> The end result is that we're guaranteed to have valid TAP syntax on
> stdout.
> 
> We can thus get rid of the --verbose-log special-case. Since that
> option was meant to get around the TAP issue let's simply make it an
> alias for "--verbose --tee".
> 
> Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>

After applying this patch series there is still one place where we
look at $verbose_log:

  $ git grep -C4 verbose_log -- test-lib.sh
  test-lib.sh-
  test-lib.sh-exec 5>&1
  test-lib.sh-exec 6<&0
  test-lib.sh-exec 7>&2
  test-lib.sh:if test "$verbose_log" = "t"
  test-lib.sh-then
  test-lib.sh-    exec 3>>"$GIT_TEST_TEE_OUTPUT_FILE" 4>&3
  test-lib.sh-elif test "$verbose" = "t"
  test-lib.sh-then

Re: [PATCH 6/7] test-lib: make --verbose output valid TAP

[SZEDER Gábor]

On Tue, Mar 09, 2021 at 05:02:18PM +0100, Ævar Arnfjörð Bjarmason wrote:
> Make the --verbose output be valid TAP, making it machine-readable for
> TAP parsers again.
> 
> Both the verbose and non-verbose test outputs were valid TAP back when
> I added support for TAP in 5099b99d25f (test-lib: Adjust output to be
> valid TAP format, 2010-06-24).
> 
> Sometime after that the --verbose output broke due to some tests
> emitting their own lines starting "ok" (or otherwise invalidate the
> TAP). That was noticed and fixed in 452320f1f5 (test-lib: add
> --verbose-log option, 2016-10-21) and "fixed" by simply turning off
> the verbose mode when we were running under TAP::Harness (e.g. under
> "prove").
> 
> That solution worked for running under Travis CI. After that fix it
> was made to use the --verbose-log option in 041c72de109 (travis: use
> --verbose-log test option, 2016-10-21), see 522354d70f4 (Add Travis CI
> support, 2015-11-27) for the "cat t/test-results/*.out" code that was
> aimed at.
> 
> But that solution and others discussed in 452320f1f5 closed the door
> on us having reliable machine-readable TAP output.
> 
> Let's instead revert the work done in 452320f1f5 and, as well as the
> follow-up commits 88c6e9d31c (test-lib: --valgrind should not override
> --verbose-log, 2017-09-05) and f5ba2de6bc (test-lib: make "-x" work
> with "--verbose-log", 2017-12-08), which were only needed to work
> around bugs in the the previous --verbose-log implementation.
> 
> Replace it with a simple method for ensuring that we have valid TAP
> both on stdout, and in any verbose output we write. When we detect
> that we're running under "prove" we prefix all legitimate TAP
> directives with "GIT_TEST_TEE_STARTED":
> 
>     $ GIT_TEST_TEE_STARTED=1 ./t5547-push-quarantine.sh
>     GIT_TEST_TEE_STARTED ok 1 - create picky dest repo
>     GIT_TEST_TEE_STARTED ok 2 - accepted objects work
>     [...]
>     GIT_TEST_TEE_STARTED 1..6
> 
> Then, instead of piping the output to "tee -a" we pipe it to a helper
> which first converts "ok" and other TAP syntax to e.g. "\ok", and then
> strips that "GIT_TEST_TEE_STARTED " prefix from the start of the line.
> 
> The end result is that we're guaranteed to have valid TAP syntax on
> stdout.
> 
> We can thus get rid of the --verbose-log special-case. Since that
> option was meant to get around the TAP issue let's simply make it an
> alias for "--verbose --tee".
> 
> Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
> ---
>  t/README         |  9 ++++++---
>  t/t0000-basic.sh |  8 ++++++++
>  t/test-lib.sh    | 43 +++++++++++++++++++++----------------------
>  3 files changed, 35 insertions(+), 25 deletions(-)
> 
> diff --git a/t/README b/t/README
> index 2cc8cbc7185..f09d94e754e 100644
> --- a/t/README
> +++ b/t/README
> @@ -157,10 +157,13 @@ appropriately before running "make". Short options can be bundled, i.e.
>  
>  -V::
>  --verbose-log::
> -	Write verbose output to the same logfile as `--tee`, but do
> -	_not_ write it to stdout. Unlike `--tee --verbose`, this option
> +	An alias for `--verbose --tee`. This option
>  	is safe to use when stdout is being consumed by a TAP parser
> -	like `prove`. Implies `--tee` and `--verbose`.
> +	like `prove`.
> +	Historically this option was different from `--verbose --tee`
> +	and would not write any verbose output to stdout to ensure the
> +	TAP-correctness of the output. The TAP-correctness of the
> +	output is now sanity checked by the test library,

Not everyone is using a TAP harness to run the tests, and, therefore,
'--verbose-log' should not spew out verbose output to the terminal.

Re: [PATCH 6/7] test-lib: make --verbose output valid TAP

[Ævar Arnfjörð Bjarmason]

On Tue, Mar 09 2021, SZEDER Gábor wrote:

> On Tue, Mar 09, 2021 at 05:02:18PM +0100, Ævar Arnfjörð Bjarmason wrote:
>> Make the --verbose output be valid TAP, making it machine-readable for
>> TAP parsers again.
>> 
>> Both the verbose and non-verbose test outputs were valid TAP back when
>> I added support for TAP in 5099b99d25f (test-lib: Adjust output to be
>> valid TAP format, 2010-06-24).
>> 
>> Sometime after that the --verbose output broke due to some tests
>> emitting their own lines starting "ok" (or otherwise invalidate the
>> TAP). That was noticed and fixed in 452320f1f5 (test-lib: add
>> --verbose-log option, 2016-10-21) and "fixed" by simply turning off
>> the verbose mode when we were running under TAP::Harness (e.g. under
>> "prove").
>> 
>> That solution worked for running under Travis CI. After that fix it
>> was made to use the --verbose-log option in 041c72de109 (travis: use
>> --verbose-log test option, 2016-10-21), see 522354d70f4 (Add Travis CI
>> support, 2015-11-27) for the "cat t/test-results/*.out" code that was
>> aimed at.
>> 
>> But that solution and others discussed in 452320f1f5 closed the door
>> on us having reliable machine-readable TAP output.
>> 
>> Let's instead revert the work done in 452320f1f5 and, as well as the
>> follow-up commits 88c6e9d31c (test-lib: --valgrind should not override
>> --verbose-log, 2017-09-05) and f5ba2de6bc (test-lib: make "-x" work
>> with "--verbose-log", 2017-12-08), which were only needed to work
>> around bugs in the the previous --verbose-log implementation.
>> 
>> Replace it with a simple method for ensuring that we have valid TAP
>> both on stdout, and in any verbose output we write. When we detect
>> that we're running under "prove" we prefix all legitimate TAP
>> directives with "GIT_TEST_TEE_STARTED":
>> 
>>     $ GIT_TEST_TEE_STARTED=1 ./t5547-push-quarantine.sh
>>     GIT_TEST_TEE_STARTED ok 1 - create picky dest repo
>>     GIT_TEST_TEE_STARTED ok 2 - accepted objects work
>>     [...]
>>     GIT_TEST_TEE_STARTED 1..6
>> 
>> Then, instead of piping the output to "tee -a" we pipe it to a helper
>> which first converts "ok" and other TAP syntax to e.g. "\ok", and then
>> strips that "GIT_TEST_TEE_STARTED " prefix from the start of the line.
>> 
>> The end result is that we're guaranteed to have valid TAP syntax on
>> stdout.
>> 
>> We can thus get rid of the --verbose-log special-case. Since that
>> option was meant to get around the TAP issue let's simply make it an
>> alias for "--verbose --tee".
>> 
>> Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>

[Relpying to both replies in this sub-thread]

> After applying this patch series there is still one place where we
> look at $verbose_log:
>
>   $ git grep -C4 verbose_log -- test-lib.sh
>   test-lib.sh-
>   test-lib.sh-exec 5>&1
>   test-lib.sh-exec 6<&0
>   test-lib.sh-exec 7>&2
>   test-lib.sh:if test "$verbose_log" = "t"
>   test-lib.sh-then
>   test-lib.sh-    exec 3>>"$GIT_TEST_TEE_OUTPUT_FILE" 4>&3
>   test-lib.sh-elif test "$verbose" = "t"
>   test-lib.sh-then

Yes, well spotted. The way this patch is implemented that exec branch
should have been deleted. I just missed it.

[From your <20210309191230.GG3590451@szeder.dev>]:

>> diff --git a/t/README b/t/README
>> index 2cc8cbc7185..f09d94e754e 100644
>> --- a/t/README
>> +++ b/t/README
>> @@ -157,10 +157,13 @@ appropriately before running "make". Short options can be bundled, i.e.
>>  
>>  -V::
>>  --verbose-log::
>> -	Write verbose output to the same logfile as `--tee`, but do
>> -	_not_ write it to stdout. Unlike `--tee --verbose`, this option
>> +	An alias for `--verbose --tee`. This option
>>  	is safe to use when stdout is being consumed by a TAP parser
>> -	like `prove`. Implies `--tee` and `--verbose`.
>> +	like `prove`.
>> +	Historically this option was different from `--verbose --tee`
>> +	and would not write any verbose output to stdout to ensure the
>> +	TAP-correctness of the output. The TAP-correctness of the
>> +	output is now sanity checked by the test library,
>
> Not everyone is using a TAP harness to run the tests, and, therefore,
> '--verbose-log' should not spew out verbose output to the terminal.

IOW even though --verbose-log was meant as a hack to make prove happy,
you've since come to like the "verbose in log, but not stdout" mode and
want that kept?

Yes, this patch takes that mode away.

Yes, I can change it.

Would your use-case for this be satisfied by having prove(1) just emit
different output for you in this scenario, so you'd need to invoke this
as something like:

    prove <test> :: --verbose --tee # or --verbose-log

Becuse the advantage of this series is that that sort of thing becomes
really trivial without everything needing to be hardcoded in
test-lib.sh, observe (this is with my series):

    
    0 $ PERL5LIB=. prove -v --formatter=SZEDERVerboseLog ./t0201-gettext-fallbacks.sh :: --verbose-log
    # lib-gettext: No is_IS UTF-8 locale available
    # lib-gettext: No is_IS ISO-8859-1 locale available
    ok 1 - sanity: $GIT_INTERNAL_GETTEXT_SH_SCHEME is set (to fallthrough)
    ok 2 - sanity: $GIT_INTERNAL_GETTEXT_TEST_FALLBACKS is set
    ok 3 - sanity: $GIT_INTERNAL_GETTEXT_SH_SCHEME" is fallthrough
    ok 4 - gettext: our gettext() fallback has pass-through semantics
    ok 5 - eval_gettext: our eval_gettext() fallback has pass-through semantics
    ok 6 - eval_gettext: our eval_gettext() fallback can interpolate variables
    ok 7 - eval_gettext: our eval_gettext() fallback can interpolate variables with spaces
    ok 8 - eval_gettext: our eval_gettext() fallback can interpolate variables with spaces and quotes
    # passed all 8 test(s)
    1..8
    ok
    All tests successful.
    Files=1, Tests=8,  1 wallclock secs ( 0.01 usr  0.01 sys +  0.07 cusr  0.01 csys =  0.10 CPU)
    Result: PASS
    $ wc -l test-results/t0201-gettext-fallbacks.out 
    75 test-results/t0201-gettext-fallbacks.out

All without any patching on top to the test-lib.sh, just:
    
    $ cat SZEDERVerboseLog.pm 
    package SZEDERVerboseLog::Session;
    use base 'TAP::Formatter::Console::Session';
    
    sub result {
        my ($self, $result) = @_;
        return if $result->is_unknown;
        return $self->SUPER::result($result);
    }
    
    package SZEDERVerboseLog;
    use strict;
    use warnings;
    use base 'TAP::Formatter::Console';
    
    sub open_test {
        my ($self, $test, $parser) = @_;
        my $session = SZEDERVerboseLog::Session->new( {
            name            => $test,
            formatter       => $self,
            parser          => $parser,
        } );
        return $session;
    }
    
    1;

The "is_unknown" is everything that's not TAP syntax.

Re: [PATCH 0/6 + 1] test-lib: make --verbose output valid TAP

[Ævar Arnfjörð Bjarmason]

On Tue, Mar 09 2021, SZEDER Gábor wrote:

> On Tue, Mar 09, 2021 at 05:02:12PM +0100, Ævar Arnfjörð Bjarmason wrote:
>> The eventual goal not included in this series is to have multiple
>> output targets, and e.g. convert ci/print-test-failures.sh to use a
>> TAP parser.
>> 
>> Machine-readable "TAP --verbose -x" output can bring us a lot of nice
>> things down the line, I have some local WIP code that's a smarter
>> version of ci/print-test-failures.sh that knows how to spew out only
>> the output relevant to the failing test(s).
>
> I wonder what you mean by the word "relevant" here, as I can't imagine
> how you could possibly identify what is relevant for a failing test
> and what isn't.  If you didn't at all meant "relevant", but that it
> will show only the output of the failing test(s), then this is a bad
> example.  Our test cases depend too much on previous test cases, and a
> failure of one test can be the result of a change in a previous
> successful tests.
>
> Therefore, any such change to 'ci/print-test-failures.sh' will have my
> firm NACK.

On e.g. the github CI every step in the run is an collapsable button, so
we could have our cake and eat it too here.

It seems to me like a sane default would be to have an equivalent to
"print-test-failures.sh" that only prints the --verbose output for the
failing tests, and a "print-all-output-for-failing-tests.sh" or whatever
which gave you the full output.

Even then, there seem to me to be some low hanging fruit for
abbreviating even that output. E.g. if you we have 100 tests and we
failed only on the 5th, isn't the --verbose -x output up to and
including the 5th going to be enough, or do we need it for the other 95?

There's also ways to unambiguously abbreviate the output, and that's now
easy to implement as shown in my other just-sent reply to you.

E.g. a lot of our test setup is really repetitive, so under -x you're
sometimes looking at the same 5-10+ lines of test setup. We could just
do a couple of passes over the output and change output like:

    + foo
    + bar
    + he
    + foo
    + bar
    + llo
    + foo
    + bar
    + world

to:

    $1 = +foo
         +bar
    + he
    $1
    + llo
    $1
    + world

Or whatever, I'm not advocating for the specific syntax there, just for
the output to be nicer.

Re: [PATCH 6/7] test-lib: make --verbose output valid TAP

[SZEDER Gábor]

On Tue, Mar 09, 2021 at 09:57:03PM +0100, Ævar Arnfjörð Bjarmason wrote:
> >> diff --git a/t/README b/t/README
> >> index 2cc8cbc7185..f09d94e754e 100644
> >> --- a/t/README
> >> +++ b/t/README
> >> @@ -157,10 +157,13 @@ appropriately before running "make". Short options can be bundled, i.e.
> >>  
> >>  -V::
> >>  --verbose-log::
> >> -	Write verbose output to the same logfile as `--tee`, but do
> >> -	_not_ write it to stdout. Unlike `--tee --verbose`, this option
> >> +	An alias for `--verbose --tee`. This option
> >>  	is safe to use when stdout is being consumed by a TAP parser
> >> -	like `prove`. Implies `--tee` and `--verbose`.
> >> +	like `prove`.
> >> +	Historically this option was different from `--verbose --tee`
> >> +	and would not write any verbose output to stdout to ensure the
> >> +	TAP-correctness of the output. The TAP-correctness of the
> >> +	output is now sanity checked by the test library,
> >
> > Not everyone is using a TAP harness to run the tests, and, therefore,
> > '--verbose-log' should not spew out verbose output to the terminal.
> 
> IOW even though --verbose-log was meant as a hack to make prove happy,
> you've since come to like the "verbose in log, but not stdout" mode and
> want that kept?

Yes, '--verbose-log' proved to be really convenient, even if it was
meant to solve a different issue.

> Yes, this patch takes that mode away.
> 
> Yes, I can change it.
> 
> Would your use-case for this be satisfied by having prove(1) just emit
> different output for you in this scenario, so you'd need to invoke this
> as something like:
> 
>     prove <test> :: --verbose --tee # or --verbose-log

I use prove to run the test suite, but I don't and won't use prove to
run a single test.

The behavior of './t1234-foo.sh -V' with or without '-x' should not
change without _very_ convincing reasons.  "We now output valid TAP
even with --verbose, so we don't need it for the TAP harness" is
definitely not convincing.

> Becuse the advantage of this series is that that sort of thing becomes
> really trivial without everything needing to be hardcoded in
> test-lib.sh, observe (this is with my series):
> 
>     
>     0 $ PERL5LIB=. prove -v --formatter=SZEDERVerboseLog ./t0201-gettext-fallbacks.sh :: --verbose-log

Well, this doesn't look trivial at all, does it?  In fact, I consider
this unusably convoluted.

>     # lib-gettext: No is_IS UTF-8 locale available
>     # lib-gettext: No is_IS ISO-8859-1 locale available
>     ok 1 - sanity: $GIT_INTERNAL_GETTEXT_SH_SCHEME is set (to fallthrough)
>     ok 2 - sanity: $GIT_INTERNAL_GETTEXT_TEST_FALLBACKS is set
>     ok 3 - sanity: $GIT_INTERNAL_GETTEXT_SH_SCHEME" is fallthrough
>     ok 4 - gettext: our gettext() fallback has pass-through semantics
>     ok 5 - eval_gettext: our eval_gettext() fallback has pass-through semantics
>     ok 6 - eval_gettext: our eval_gettext() fallback can interpolate variables
>     ok 7 - eval_gettext: our eval_gettext() fallback can interpolate variables with spaces
>     ok 8 - eval_gettext: our eval_gettext() fallback can interpolate variables with spaces and quotes
>     # passed all 8 test(s)
>     1..8
>     ok
>     All tests successful.
>     Files=1, Tests=8,  1 wallclock secs ( 0.01 usr  0.01 sys +  0.07 cusr  0.01 csys =  0.10 CPU)
>     Result: PASS
>     $ wc -l test-results/t0201-gettext-fallbacks.out 
>     75 test-results/t0201-gettext-fallbacks.out
> 
> All without any patching on top to the test-lib.sh, just:
>     
>     $ cat SZEDERVerboseLog.pm 
>     package SZEDERVerboseLog::Session;
>     use base 'TAP::Formatter::Console::Session';
>     
>     sub result {
>         my ($self, $result) = @_;
>         return if $result->is_unknown;
>         return $self->SUPER::result($result);
>     }
>     
>     package SZEDERVerboseLog;
>     use strict;
>     use warnings;
>     use base 'TAP::Formatter::Console';
>     
>     sub open_test {
>         my ($self, $test, $parser) = @_;
>         my $session = SZEDERVerboseLog::Session->new( {
>             name            => $test,
>             formatter       => $self,
>             parser          => $parser,
>         } );
>         return $session;
>     }
>     
>     1;
> 
> The "is_unknown" is everything that's not TAP syntax.
> 

Re: [PATCH 0/6 + 1] test-lib: make --verbose output valid TAP

[SZEDER Gábor]

On Tue, Mar 09, 2021 at 10:03:54PM +0100, Ævar Arnfjörð Bjarmason wrote:
> 
> On Tue, Mar 09 2021, SZEDER Gábor wrote:
> 
> > On Tue, Mar 09, 2021 at 05:02:12PM +0100, Ævar Arnfjörð Bjarmason wrote:
> >> The eventual goal not included in this series is to have multiple
> >> output targets, and e.g. convert ci/print-test-failures.sh to use a
> >> TAP parser.
> >> 
> >> Machine-readable "TAP --verbose -x" output can bring us a lot of nice
> >> things down the line, I have some local WIP code that's a smarter
> >> version of ci/print-test-failures.sh that knows how to spew out only
> >> the output relevant to the failing test(s).
> >
> > I wonder what you mean by the word "relevant" here, as I can't imagine
> > how you could possibly identify what is relevant for a failing test
> > and what isn't.  If you didn't at all meant "relevant", but that it
> > will show only the output of the failing test(s), then this is a bad
> > example.  Our test cases depend too much on previous test cases, and a
> > failure of one test can be the result of a change in a previous
> > successful tests.
> >
> > Therefore, any such change to 'ci/print-test-failures.sh' will have my
> > firm NACK.
> 
> On e.g. the github CI every step in the run is an collapsable button, so
> we could have our cake and eat it too here.

Well, one of the things I didn't like in GitHub CI is that I had to
click a lot to get to the information I wanted...

> It seems to me like a sane default would be to have an equivalent to
> "print-test-failures.sh" that only prints the --verbose output for the
> failing tests, and a "print-all-output-for-failing-tests.sh" or whatever
> which gave you the full output.
> 
> Even then, there seem to me to be some low hanging fruit for
> abbreviating even that output. E.g. if you we have 100 tests and we
> failed only on the 5th, isn't the --verbose -x output up to and
> including the 5th going to be enough, or do we need it for the other 95?

I have a test fix waiting to be sent out, where a failing git command
in the 'test_when_finished' block of test #21 went unnoticed because
of the broken && chain, and ultimately caused the failure of test
#91.

In my opinion your proposed changes to 'ci/print-test-failures.sh'
would make things worse.

Re: [PATCH 2/7] test-lib: add say_color_tap helper to emit TAP format

[Junio C Hamano]

Ævar Arnfjörð Bjarmason  <avarab@gmail.com> writes:

> Follow-up 5099b99d25 (test-lib: Adjust output to be valid TAP format,
> 2010-06-24) and make it easy to distinguishing when we're emitting TAP
> directives (with the new "say_color_tap"), and when we just want to
> say something with colored text "say_color".

OK.

> @@ -666,7 +673,7 @@ test_ok_ () {
>  		write_junit_xml_testcase "$*"
>  	fi
>  	test_success=$(($test_success + 1))
> -	say_color "" "ok $test_count - $@"
> +	say_color_tap "" "ok $test_count - $@"

Not your fault, but let's not forget that we should clean this up
not to use "$@" here (and instead use $*).

> -	say_color warn "not ok $test_count - $@ # TODO known breakage"
> +	say_color_tap warn "not ok $test_count - $@ # TODO known breakage"

Likewise.

Yes, I know say_color (and hence its heir say_color_tap) accepts
multiple arguments and eventually pastes them into a single string
with "$*", but there is no point in producing multiple arguments out
of "$@" here in this case.



fn0 () {
	cnt=0
	for arg
	do
		echo "$cnt: <$arg>"
		cnt=$(( cnt+1 ))
	done
}

fn1 () {
	fn0 "not - $@ # TODO"
}

fn1 1 "2 3"

---> 

0: <not - 1>
1: <2 3 # TODO>

Re: [PATCH 1/7] test-lib: remove test_external

[Junio C Hamano]

Ævar Arnfjörð Bjarmason  <avarab@gmail.com> writes:

> Remove the test_external function(s) in favor of running the Perl
> tests with a test_expect_success.
> ...
> My motivation for this is to eliminate a special case where things
> that aren't test-lib.sh are going to produce TAP, for reasons that'll
> be clear in subsequent commits.

Puzzled.

>  .../netrc/t-git-credential-netrc.sh           |  7 +-
>  t/README                                      | 26 ------
>  t/t0202-gettext-perl.sh                       | 10 +--
>  t/t9700-perl-git.sh                           | 10 +--
>  t/test-lib-functions.sh                       | 89 +------------------
>  t/test-lib.sh                                 | 42 ++++-----
>  6 files changed, 28 insertions(+), 156 deletions(-)

Reducing the number of lines is always good, but is this essentially
losing what the commit that added test_external wanted to add?

> diff --git a/contrib/credential/netrc/t-git-credential-netrc.sh b/contrib/credential/netrc/t-git-credential-netrc.sh
> index 07227d02287..28118a9e194 100755
> --- a/contrib/credential/netrc/t-git-credential-netrc.sh
> +++ b/contrib/credential/netrc/t-git-credential-netrc.sh
> @@ -20,13 +20,10 @@
>  		'set up test repository' \
>  		'git config --add gpg.program test.git-config-gpg'
>  
> -	# The external test will outputs its own plan
> -	test_external_has_tap=1
> -
>  	export PERL5LIB="$GITPERLLIB"
> -	test_external \
> -		'git-credential-netrc' \
> +	test_expect_success 'git-credential-netrc' '
>  		perl "$GIT_BUILD_DIR"/contrib/credential/netrc/test.pl
> +	'
>  
>  	test_done
>  )

This is valid because we expect nobody runs this under tap?

> diff --git a/t/t0202-gettext-perl.sh b/t/t0202-gettext-perl.sh
> index a29d166e007..06a93b36790 100755
> --- a/t/t0202-gettext-perl.sh
> +++ b/t/t0202-gettext-perl.sh
> @@ -17,11 +17,9 @@ perl -MTest::More -e 0 2>/dev/null || {
>  	test_done
>  }
>  
> -# The external test will outputs its own plan
> -test_external_has_tap=1
> -
> -test_external_without_stderr \
> -    'Perl Git::I18N API' \
> -    perl "$TEST_DIRECTORY"/t0202/test.pl
> +test_expect_success 'run t0202/test.pl to test Git::I18N.pm' '
> +	perl "$TEST_DIRECTORY"/t0202/test.pl 2>stderr &&
> +	test_must_be_empty stderr
> +'

So t0202/test.pl would still produce output that would confuse
whoever is reading our output as TAP, and it is OK?  If the
redirection discards its standard output to /dev/null [*], I would
sort-of understand how this may work (we would have let the perl
script to emit 13 "ok" or "not ok" to our output, but now we discard
that and write just one our own "ok" or "not ok", depending on what
comes out to the standard error stream (e.g. "# Looks like you
failed...").

But that is not what is going on.  We'll let these 13 "ok" or "not ok"
come out from the perl script and then add another on our own.

> diff --git a/t/t9700-perl-git.sh b/t/t9700-perl-git.sh
> index 102c133112c..574c57b17f1 100755
> --- a/t/t9700-perl-git.sh
> +++ b/t/t9700-perl-git.sh
> @@ -50,11 +50,9 @@ test_expect_success \
  >       git config --add test.pathmulti bar
>       '
>  
> -# The external test will outputs its own plan
> -test_external_has_tap=1
> -
> -test_external_without_stderr \
> -    'Perl API' \
> -    perl "$TEST_DIRECTORY"/t9700/test.pl
> +test_expect_success 'use t9700/test.pl to test Git.pm' '
> +	perl "$TEST_DIRECTORY"/t9700/test.pl 2>stderr &&
> +	test_must_be_empty stderr
> +'

Ditto.  It seems that we are still letting the script, i.e. one of
the "things that aren't test-lib.sh" to produce TAP anyway.


[Footnote]

* If we are truly somehow discarding these output that would be TAP
(13 tests in 0202 and uncounted in 9700) from being shown (by e.g.
redirecting output to /dev/null), it would be a regression for those
who debug breakage found by these tests.  They used to be told which
one failed and how but now they don't.  So I do not think that is a
useful way to go, either.

Re: [PATCH 6/7] test-lib: make --verbose output valid TAP

[Junio C Hamano]

Ævar Arnfjörð Bjarmason  <avarab@gmail.com> writes:

> Replace it with a simple method for ensuring that we have valid TAP
> both on stdout, and in any verbose output we write. When we detect
> that we're running under "prove" we prefix all legitimate TAP
> directives with "GIT_TEST_TEE_STARTED":
>
>     $ GIT_TEST_TEE_STARTED=1 ./t5547-push-quarantine.sh
>     GIT_TEST_TEE_STARTED ok 1 - create picky dest repo
>     GIT_TEST_TEE_STARTED ok 2 - accepted objects work
>     [...]
>     GIT_TEST_TEE_STARTED 1..6

Ah, OK, so these perl scripts that use Test::More think they are
emitting TAP, but because the prefix is not added to any of their
output, they are not considered to be a tap output at all.

So did the "external" tests lose a lot of value with this change?
They used to point out individual breakage, but now it is just
"passed as a whole (or not)" boolean?

Re: [PATCH 1/7] test-lib: remove test_external

[Ævar Arnfjörð Bjarmason]

On Wed, Mar 10 2021, Junio C Hamano wrote:

> Ævar Arnfjörð Bjarmason  <avarab@gmail.com> writes:
>
>> Remove the test_external function(s) in favor of running the Perl
>> tests with a test_expect_success.
>> ...
>> My motivation for this is to eliminate a special case where things
>> that aren't test-lib.sh are going to produce TAP, for reasons that'll
>> be clear in subsequent commits.
>
> Puzzled.
>
>>  .../netrc/t-git-credential-netrc.sh           |  7 +-
>>  t/README                                      | 26 ------
>>  t/t0202-gettext-perl.sh                       | 10 +--
>>  t/t9700-perl-git.sh                           | 10 +--
>>  t/test-lib-functions.sh                       | 89 +------------------
>>  t/test-lib.sh                                 | 42 ++++-----
>>  6 files changed, 28 insertions(+), 156 deletions(-)
>
> Reducing the number of lines is always good, but is this essentially
> losing what the commit that added test_external wanted to add?

Yes, I don't think streaming TAP from external sources is a problem
worth solving in the first place.

>> diff --git a/contrib/credential/netrc/t-git-credential-netrc.sh b/contrib/credential/netrc/t-git-credential-netrc.sh
>> index 07227d02287..28118a9e194 100755
>> --- a/contrib/credential/netrc/t-git-credential-netrc.sh
>> +++ b/contrib/credential/netrc/t-git-credential-netrc.sh
>> @@ -20,13 +20,10 @@
>>  		'set up test repository' \
>>  		'git config --add gpg.program test.git-config-gpg'
>>  
>> -	# The external test will outputs its own plan
>> -	test_external_has_tap=1
>> -
>>  	export PERL5LIB="$GITPERLLIB"
>> -	test_external \
>> -		'git-credential-netrc' \
>> +	test_expect_success 'git-credential-netrc' '
>>  		perl "$GIT_BUILD_DIR"/contrib/credential/netrc/test.pl
>> +	'
>>  
>>  	test_done
>>  )
>
> This is valid because we expect nobody runs this under tap?

No, because at this point we suppress the --verbose output under
HARNESS_ACTIVE (but see 6/7 later), and under non-verbose we now emit:
    
    ./t9700-perl-git.sh 
    ok 1 - set up test repository
    ok 2 - use t9700/test.pl to test Git.pm
    # passed all 2 test(s)
    1..2

So that the stdout from t9700/test.pl doesn't screw up the test output
anymore.

>> diff --git a/t/t0202-gettext-perl.sh b/t/t0202-gettext-perl.sh
>> index a29d166e007..06a93b36790 100755
>> --- a/t/t0202-gettext-perl.sh
>> +++ b/t/t0202-gettext-perl.sh
>> @@ -17,11 +17,9 @@ perl -MTest::More -e 0 2>/dev/null || {
>>  	test_done
>>  }
>>  
>> -# The external test will outputs its own plan
>> -test_external_has_tap=1
>> -
>> -test_external_without_stderr \
>> -    'Perl Git::I18N API' \
>> -    perl "$TEST_DIRECTORY"/t0202/test.pl
>> +test_expect_success 'run t0202/test.pl to test Git::I18N.pm' '
>> +	perl "$TEST_DIRECTORY"/t0202/test.pl 2>stderr &&
>> +	test_must_be_empty stderr
>> +'
>
> So t0202/test.pl would still produce output that would confuse
> whoever is reading our output as TAP, and it is OK?  If the
> redirection discards its standard output to /dev/null [*], I would
> sort-of understand how this may work (we would have let the perl
> script to emit 13 "ok" or "not ok" to our output, but now we discard
> that and write just one our own "ok" or "not ok", depending on what
> comes out to the standard error stream (e.g. "# Looks like you
> failed...").
>
> But that is not what is going on.  We'll let these 13 "ok" or "not ok"
> come out from the perl script and then add another on our own.

Yes, but just like we don't have stdout from any other program appear
directly in the output of ./tXXXX*.sh the TAP doesn't get to our stderr
either, i.e. our whole juggling around with FDs 1-4.

>> diff --git a/t/t9700-perl-git.sh b/t/t9700-perl-git.sh
>> index 102c133112c..574c57b17f1 100755
>> --- a/t/t9700-perl-git.sh
>> +++ b/t/t9700-perl-git.sh
>> @@ -50,11 +50,9 @@ test_expect_success \
>   >       git config --add test.pathmulti bar
>>       '
>>  
>> -# The external test will outputs its own plan
>> -test_external_has_tap=1
>> -
>> -test_external_without_stderr \
>> -    'Perl API' \
>> -    perl "$TEST_DIRECTORY"/t9700/test.pl
>> +test_expect_success 'use t9700/test.pl to test Git.pm' '
>> +	perl "$TEST_DIRECTORY"/t9700/test.pl 2>stderr &&
>> +	test_must_be_empty stderr
>> +'
>
> Ditto.  It seems that we are still letting the script, i.e. one of
> the "things that aren't test-lib.sh" to produce TAP anyway.
>
>
> [Footnote]
>
> * If we are truly somehow discarding these output that would be TAP
> (13 tests in 0202 and uncounted in 9700) from being shown (by e.g.
> redirecting output to /dev/null), it would be a regression for those
> who debug breakage found by these tests.  They used to be told which
> one failed and how but now they don't.  So I do not think that is a
> useful way to go, either.

You still get the full TAP output under --verbose for debugging, we just
don't consume it as TAP anymore by "prove" etc, i.e. once we get to 6/7:
    
    $ GIT_TEST_TEE_STARTED=true HARNESS_ACTIVE=t ./t9700-perl-git.sh --verbose --tee
    [...]
    ok 1 - set up test repository
    
    ## expecting success of 9700.2 'use t9700/test.pl to test Git.pm': 
            perl "$TEST_DIRECTORY"/t9700/test.pl 2>stderr &&
            test_must_be_empty stderr
    
    \ok 2 - use Git;
    \ok 3 - open repository
    \ok 4 - config scalar: string
    \ok 5 - config array: string
    \ok 6 - config scalar: nonexistent
    \ok 7 - config array: nonexistent
    [...]
    \ok 44 - cat_blob(outside): size
    \ok 45 - unquote unquoted path
    \ok 46 - unquote simple quoted path
    \ok 47 - unquote escape sequences
    \1..47
    
    ok 2 - use t9700/test.pl to test Git.pm
    
    # passed all 2 test(s)
    1..2

Notice how it's escaped now.

So yes, we don't get the benefit of having e.g. prove/CI say that our
6th test failed anymore in this case.

I think that's a very small price to pay for the benefit of not having
to monkeypatch Perl's TAP emitting in this case to do the back & forth
munging to safe the TAP output I'm doing in 6/7, and only need to do in
one place because I'd gotten rid of this special-case earlier.

Re: [PATCH 6/7] test-lib: make --verbose output valid TAP

[Ævar Arnfjörð Bjarmason]

On Tue, Mar 09 2021, SZEDER Gábor wrote:

> On Tue, Mar 09, 2021 at 09:57:03PM +0100, Ævar Arnfjörð Bjarmason wrote:
>> >> diff --git a/t/README b/t/README
>> >> index 2cc8cbc7185..f09d94e754e 100644
>> >> --- a/t/README
>> >> +++ b/t/README
>> >> @@ -157,10 +157,13 @@ appropriately before running "make". Short options can be bundled, i.e.
>> >>  
>> >>  -V::
>> >>  --verbose-log::
>> >> -	Write verbose output to the same logfile as `--tee`, but do
>> >> -	_not_ write it to stdout. Unlike `--tee --verbose`, this option
>> >> +	An alias for `--verbose --tee`. This option
>> >>  	is safe to use when stdout is being consumed by a TAP parser
>> >> -	like `prove`. Implies `--tee` and `--verbose`.
>> >> +	like `prove`.
>> >> +	Historically this option was different from `--verbose --tee`
>> >> +	and would not write any verbose output to stdout to ensure the
>> >> +	TAP-correctness of the output. The TAP-correctness of the
>> >> +	output is now sanity checked by the test library,
>> >
>> > Not everyone is using a TAP harness to run the tests, and, therefore,
>> > '--verbose-log' should not spew out verbose output to the terminal.
>> 
>> IOW even though --verbose-log was meant as a hack to make prove happy,
>> you've since come to like the "verbose in log, but not stdout" mode and
>> want that kept?
>
> Yes, '--verbose-log' proved to be really convenient, even if it was
> meant to solve a different issue.

Sure, let's keep it then.

>> Yes, this patch takes that mode away.
>> 
>> Yes, I can change it.
>> 
>> Would your use-case for this be satisfied by having prove(1) just emit
>> different output for you in this scenario, so you'd need to invoke this
>> as something like:
>> 
>>     prove <test> :: --verbose --tee # or --verbose-log
>
> I use prove to run the test suite, but I don't and won't use prove to
> run a single test.
>
> The behavior of './t1234-foo.sh -V' with or without '-x' should not
> change without _very_ convincing reasons.

I think I can make it the same, except for emulating the sheared write
issue 452320f1f5 mentions. I.e. moving to this method inherently
requires us to squash together stdout/stderr into one, which isn't what
we're doing now.

> "We now output valid TAP even with --verbose, so we don't need it for
> the TAP harness" is definitely not convincing.

It's more like "we produce one machine-readable output format, so if you
need junit, or an abbreviated format (--verbose-log) or a nyancat
progress bar or whatever, it makes more sense to pipe it to another
process that'll munge that for you... :)

>> Becuse the advantage of this series is that that sort of thing becomes
>> really trivial without everything needing to be hardcoded in
>> test-lib.sh, observe (this is with my series):
>> 
>>     
>>     0 $ PERL5LIB=. prove -v --formatter=SZEDERVerboseLog ./t0201-gettext-fallbacks.sh :: --verbose-log
>
> Well, this doesn't look trivial at all, does it?  In fact, I consider
> this unusably convoluted.

... I meant to say something closer to "does that output look
ok?". Obviously we'd then make the --verbose-log run something like that
under the hood.

But in any case, I found it easier to just add this feature to my "tee"
program than doing it with Perl's TAP libraries, i.e. something like
this on top (will integrate it in an eventual re-roll):

    diff --git a/t/helper/test-tee.c b/t/helper/test-tee.c
    index 4ed34e9db9..063b9277e0 100644
    --- a/t/helper/test-tee.c
    +++ b/t/helper/test-tee.c
    @@ -29,2 +29,3 @@ int cmd__tee(int argc, const char **argv)
     {
    +       int only_tap_on_stdout = 0;
            int tap = 0;
    @@ -38,2 +39,4 @@ int cmd__tee(int argc, const char **argv)
            struct option options[] = {
    +               OPT_BOOL(0, "only-tap-on-stdout", &only_tap_on_stdout,
    +                        "only emit TAP on stdout, not 'unknown' etc."),
                    OPT_BOOL(0, "escape-stdout", &escape_stdout,
    @@ -75,3 +78,7 @@ int cmd__tee(int argc, const char **argv)
     
    -               fprintf(stdout, "%s\n", line.buf + offs);
    +               if (!only_tap_on_stdout)
    +                       fprintf(stdout, "%s\n", line.buf + offs);
    +               else if (offs)
    +                       fprintf(stdout, "%s\n", line.buf + offs);
    +
                    if (logfp)
    diff --git a/t/test-lib.sh b/t/test-lib.sh
    index 479ad4fb38..731ecc36bb 100644
    --- a/t/test-lib.sh
    +++ b/t/test-lib.sh
    @@ -153,2 +153,3 @@ parse_option () {
                    verbose=t
    +               verbose_log=t
                    tee=t
    @@ -371,2 +372,3 @@ then
                    --escape-stdout ${HARNESS_ACTIVE+--escape-file} \
    +               ${verbose_log+--only-tap-on-stdout} \
                    "$GIT_TEST_TEE_OUTPUT_FILE"


>>     # lib-gettext: No is_IS UTF-8 locale available
>>     # lib-gettext: No is_IS ISO-8859-1 locale available
>>     ok 1 - sanity: $GIT_INTERNAL_GETTEXT_SH_SCHEME is set (to fallthrough)
>>     ok 2 - sanity: $GIT_INTERNAL_GETTEXT_TEST_FALLBACKS is set
>>     ok 3 - sanity: $GIT_INTERNAL_GETTEXT_SH_SCHEME" is fallthrough
>>     ok 4 - gettext: our gettext() fallback has pass-through semantics
>>     ok 5 - eval_gettext: our eval_gettext() fallback has pass-through semantics
>>     ok 6 - eval_gettext: our eval_gettext() fallback can interpolate variables
>>     ok 7 - eval_gettext: our eval_gettext() fallback can interpolate variables with spaces
>>     ok 8 - eval_gettext: our eval_gettext() fallback can interpolate variables with spaces and quotes
>>     # passed all 8 test(s)
>>     1..8
>>     ok
>>     All tests successful.
>>     Files=1, Tests=8,  1 wallclock secs ( 0.01 usr  0.01 sys +  0.07 cusr  0.01 csys =  0.10 CPU)
>>     Result: PASS
>>     $ wc -l test-results/t0201-gettext-fallbacks.out 
>>     75 test-results/t0201-gettext-fallbacks.out
>> 
>> All without any patching on top to the test-lib.sh, just:
>>     
>>     $ cat SZEDERVerboseLog.pm 
>>     package SZEDERVerboseLog::Session;
>>     use base 'TAP::Formatter::Console::Session';
>>     
>>     sub result {
>>         my ($self, $result) = @_;
>>         return if $result->is_unknown;
>>         return $self->SUPER::result($result);
>>     }
>>     
>>     package SZEDERVerboseLog;
>>     use strict;
>>     use warnings;
>>     use base 'TAP::Formatter::Console';
>>     
>>     sub open_test {
>>         my ($self, $test, $parser) = @_;
>>         my $session = SZEDERVerboseLog::Session->new( {
>>             name            => $test,
>>             formatter       => $self,
>>             parser          => $parser,
>>         } );
>>         return $session;
>>     }
>>     
>>     1;
>> 
>> The "is_unknown" is everything that's not TAP syntax.
>> 

Re: [PATCH 6/7] test-lib: make --verbose output valid TAP

[Chris Torek]

There is a lot of historical stuff I can't really comment on
here, so I'll just point out this one tiny bit of shell oddity:

On Tue, Mar 9, 2021 at 8:04 AM Ævar Arnfjörð Bjarmason <avarab@gmail.com> wrote:
> Make the --verbose output be valid TAP, making it machine-readable for
> TAP parsers again.
[snippage]

> diff --git a/t/test-lib.sh b/t/test-lib.sh
> index aa7068b06b6..0070d05234b 100644
> --- a/t/test-lib.sh
> +++ b/t/test-lib.sh
[snippage]
> @@ -364,9 +366,22 @@ then
>         (
>                 GIT_TEST_TEE_STARTED=done ${TEST_SHELL_PATH} "$0" "$@" 2>&1
>                 echo $? >"$TEST_RESULTS_BASE.exit"
> -       ) | tee -a "$GIT_TEST_TEE_OUTPUT_FILE"
> +       ) | "$GIT_BUILD_DIR"/t/helper/test-tool tee \
> +               --tap --prefix="GIT_TEST_TEE_STARTED " \
> +               --escape-stdout ${HARNESS_ACTIVE+--escape-file} \
> +               "$GIT_TEST_TEE_OUTPUT_FILE"
>         test "$(cat "$TEST_RESULTS_BASE.exit")" = 0
>         exit
> +elif test -n "$verbose" -a -n "$HARNESS_ACTIVE"
> +then
> +       ret=
> +       (
> +               GIT_TEST_TEE_STARTED=done ${TEST_SHELL_PATH} "$0" "$@" 2>&1
> +               ret=$?
> +       ) | "$GIT_BUILD_DIR"/t/helper/test-tool tee \
> +               --tap --prefix="GIT_TEST_TEE_STARTED " \
> +               --escape-stdout
> +       exit $ret
>  fi
>
>  if test -n "$trace" && test -n "$test_untraceable"
[snippage]

In the block beginning with:

    ret=

we have a subshell:

    ( ... ) | "$GIT_BUILD_DIR"/t/helper/test-tool tee ...

In the subshell itself, we set `ret=$?`.  But this is inside a
subshell, which then exits, so the setting of `ret` will get lost.

Did you perhaps want `{ ...; }` instead here?  Unfortunately the
pipe means that the whole left side may run in a subshell
anyway, so even that doesn't fix the problem.  We need a
temp file, a la the code above that dumps $? into
"$TEST_RESULTS_BASE.exit".

Chris

Re: [PATCH 6/7] test-lib: make --verbose output valid TAP

[Ævar Arnfjörð Bjarmason]

On Wed, Mar 10 2021, Ævar Arnfjörð Bjarmason wrote:

> On Tue, Mar 09 2021, SZEDER Gábor wrote:
>
>> On Tue, Mar 09, 2021 at 09:57:03PM +0100, Ævar Arnfjörð Bjarmason wrote:
[...]
>>> Becuse the advantage of this series is that that sort of thing becomes
>>> really trivial without everything needing to be hardcoded in
>>> test-lib.sh, observe (this is with my series):
>>> 
>>>     
>>>     0 $ PERL5LIB=. prove -v --formatter=SZEDERVerboseLog ./t0201-gettext-fallbacks.sh :: --verbose-log
>>
>> Well, this doesn't look trivial at all, does it?  In fact, I consider
>> this unusably convoluted.
>
> ... I meant to say something closer to "does that output look
> ok?". Obviously we'd then make the --verbose-log run something like that
> under the hood.
>
> But in any case, I found it easier to just add this feature to my "tee"
> program than doing it with Perl's TAP libraries, i.e. something like
> this on top (will integrate it in an eventual re-roll):

FWIW I implemented this. I've got it at https://github.com/avar.git's
avar/support-test-verbose-under-prove-2 if you want to take an early
peek at it. It turned into a 50-some patch slog through refactoring
various test-lib.sh code, so I'm seeing about how I submit it.

The end result is that -V now powered by a proper TAP-parsing tap-tee
program. So you'll have e.g. this working as before:
    
    $ ./t9004-example.sh -V
    ok 1 - decorate
    # passed all 1 test(s)
    1..1

But you can also tweak levels of verbosity to stdout (while retaining
full logging) by suppling -V N to get N-level comments, as now indicated
by N number of prefixed "#"'s:

   # -V0 is a special-case to get 0th level logging (couldn't think of a
   # better name), --verbose-log=0 also works
   $ ./t9004-example.sh -V0
   ok 1 - decorate
   1..1

At level 3 you start getting the source of passing tests (failing tests
are level 1, unexpected TODO tests level 2, trace level 4):
    
    $ ./t9004-example.sh -VVV 
    ok 1 - decorate
    ###
    ###     test-tool example-decorate
    ###
    # passed all 1 test(s)
    1..1

So obviously the devil's in the details, but it would be useful to know
what you think about the approach before I try to roll this into
submitted patches sooner than later.

I'm mainly interesetd in this for this providing building blocks for
more advanced features down the road.

E.g. it would now be pretty easy to do something like run -x behind the
scenes even if the user doesn't ask for it, and then when a test fail
annotate the specific line that failed using fuzzy-matching on the -x
output.

We could do that now, sort of, but once we've got unambiguous TAP
start/end markers that can't be fooled it becomes trivial to write a
function like get_trace_lines_for_nth_test(N-1) to get your own trace
output for test N.

Re: [RFC/PATCH 7/7] test-lib: generate JUnit output via TAP

[Johannes Schindelin]

[-- Attachment #1: Type: text/plain, Size: 15187 bytes --]

Hi Ævar,

On Tue, 9 Mar 2021, Ævar Arnfjörð Bjarmason wrote:

> Rewrite the home-brew JUnit output generation added in
> 22231908151 (tests: optionally write results as JUnit-style .xml,
> 2019-01-29) and other subsequent commits to be generated via the TAP
> output.
>
> This is now possible that the TAP output emitted with --tee is
> guaranteed to be valid TAP, see the preceding commit.
>
> The JUnit output is not bug-for-bug compatible with the previous
> output, but it looks better to me.
>
> This also requires installing TAP::Formatter::JUnit[1], perhaps that's
> not palatable to the users of the --write-junit-xml option.

Indeed. I am trying to keep the dependencies required for the Windows jobs
of our CI/PR builds to a minimum.

Note, also, that the JUnit output was mostly relevant for when we used
Azure Pipelines: it has a specific UI to study test results, figure out
flaky tests, performance, etc.

Now that we use GitHub Actions, we do not have such a nice test aggregator
anymore, but we might get one again in the future, who knows.

> In any case, it'll be easy to whip up our own TAP emitter with a
> TAP::Parser and TAP::Formatter, both of whom come with perl itself,
> which we already rely on for tests.
>
> It should also be significantly faster on Windows,

I really hate to have to harp on this when talking to you, but... well,
how can I say it? Perl is _slooooooooooooow_ on Windows.

Like, _really_ slow. Ridiculously slow.

I know, you recently got riled up when Jeff suggested that the Perl hook
calling FSMonior might be slow, but the truth is: it is super slow. It's
not even funny how slow it is. And it fills me with no joy having to
repeat it every time the question comes up whether running any part of Git
that is written in Perl might affect performance on Windows. I really
dislike having to be that messenger.

I doubt that you will ever be able to replace my (admittedly slightly
hacky) C helper with anything written in Perl that does even come close to
being faster.

In other words, I fear that your work here might not have the outcome you
hoped for.

Ciao,
Johannes

> as we can e.g. write all the *.out files, and only do that conversion at
> the end for all files in a batch, as opposed to the current
> implementation of shelling out to test-tool in a loop for each test.
>
> 1. https://metacpan.org/pod/distribution/TAP-Formatter-JUnit/script/tap2junit
>
> Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
> ---
>  Makefile                   |   1 -
>  t/helper/test-date.c       |  12 ----
>  t/helper/test-path-utils.c |  21 -------
>  t/helper/test-tool.c       |   1 -
>  t/helper/test-tool.h       |   1 -
>  t/helper/test-xml-encode.c |  80 ------------------------
>  t/test-lib.sh              | 123 ++++---------------------------------
>  7 files changed, 12 insertions(+), 227 deletions(-)
>  delete mode 100644 t/helper/test-xml-encode.c
>
> diff --git a/Makefile b/Makefile
> index d26b9d62ee9..fa7c52f7a42 100644
> --- a/Makefile
> +++ b/Makefile
> @@ -748,7 +748,6 @@ TEST_BUILTINS_OBJS += test-urlmatch-normalization.o
>  TEST_BUILTINS_OBJS += test-wildmatch.o
>  TEST_BUILTINS_OBJS += test-windows-named-pipe.o
>  TEST_BUILTINS_OBJS += test-write-cache.o
> -TEST_BUILTINS_OBJS += test-xml-encode.o
>
>  # Do not add more tests here unless they have extra dependencies. Add
>  # them in TEST_BUILTINS_OBJS above.
> diff --git a/t/helper/test-date.c b/t/helper/test-date.c
> index 099eff4f0fc..ebf133943b3 100644
> --- a/t/helper/test-date.c
> +++ b/t/helper/test-date.c
> @@ -8,7 +8,6 @@ static const char *usage_msg = "\n"
>  "  test-tool date parse [date]...\n"
>  "  test-tool date approxidate [date]...\n"
>  "  test-tool date timestamp [date]...\n"
> -"  test-tool date getnanos [start-nanos]\n"
>  "  test-tool date is64bit\n"
>  "  test-tool date time_t-is64bit\n";
>
> @@ -92,15 +91,6 @@ static void parse_approx_timestamp(const char **argv)
>  	}
>  }
>
> -static void getnanos(const char **argv)
> -{
> -	double seconds = getnanotime() / 1.0e9;
> -
> -	if (*argv)
> -		seconds -= strtod(*argv, NULL);
> -	printf("%lf\n", seconds);
> -}
> -
>  int cmd__date(int argc, const char **argv)
>  {
>  	const char *x;
> @@ -120,8 +110,6 @@ int cmd__date(int argc, const char **argv)
>  		parse_approxidate(argv+1);
>  	else if (!strcmp(*argv, "timestamp"))
>  		parse_approx_timestamp(argv+1);
> -	else if (!strcmp(*argv, "getnanos"))
> -		getnanos(argv+1);
>  	else if (!strcmp(*argv, "is64bit"))
>  		return sizeof(timestamp_t) == 8 ? 0 : 1;
>  	else if (!strcmp(*argv, "time_t-is64bit"))
> diff --git a/t/helper/test-path-utils.c b/t/helper/test-path-utils.c
> index 313a153209c..090596ac492 100644
> --- a/t/helper/test-path-utils.c
> +++ b/t/helper/test-path-utils.c
> @@ -407,27 +407,6 @@ int cmd__path_utils(int argc, const char **argv)
>  		return !!res;
>  	}
>
> -	if (argc == 4 && !strcmp(argv[1], "skip-n-bytes")) {
> -		int fd = open(argv[2], O_RDONLY), offset = atoi(argv[3]);
> -		char buffer[65536];
> -
> -		if (fd < 0)
> -			die_errno("could not open '%s'", argv[2]);
> -		if (lseek(fd, offset, SEEK_SET) < 0)
> -			die_errno("could not skip %d bytes", offset);
> -		for (;;) {
> -			ssize_t count = read(fd, buffer, sizeof(buffer));
> -			if (count < 0)
> -				die_errno("could not read '%s'", argv[2]);
> -			if (!count)
> -				break;
> -			if (write(1, buffer, count) < 0)
> -				die_errno("could not write to stdout");
> -		}
> -		close(fd);
> -		return 0;
> -	}
> -
>  	if (argc > 5 && !strcmp(argv[1], "slice-tests")) {
>  		int res = 0;
>  		long offset, stride, i;
> diff --git a/t/helper/test-tool.c b/t/helper/test-tool.c
> index 1876bad8f42..3fa02011b61 100644
> --- a/t/helper/test-tool.c
> +++ b/t/helper/test-tool.c
> @@ -73,7 +73,6 @@ static struct test_cmd cmds[] = {
>  	{ "tee", cmd__tee },
>  	{ "trace2", cmd__trace2 },
>  	{ "urlmatch-normalization", cmd__urlmatch_normalization },
> -	{ "xml-encode", cmd__xml_encode },
>  	{ "wildmatch", cmd__wildmatch },
>  #ifdef GIT_WINDOWS_NATIVE
>  	{ "windows-named-pipe", cmd__windows_named_pipe },
> diff --git a/t/helper/test-tool.h b/t/helper/test-tool.h
> index 9b3c1f75267..5028730807e 100644
> --- a/t/helper/test-tool.h
> +++ b/t/helper/test-tool.h
> @@ -63,7 +63,6 @@ int cmd__subprocess(int argc, const char **argv);
>  int cmd__tee(int argc, const char **argv);
>  int cmd__trace2(int argc, const char **argv);
>  int cmd__urlmatch_normalization(int argc, const char **argv);
> -int cmd__xml_encode(int argc, const char **argv);
>  int cmd__wildmatch(int argc, const char **argv);
>  #ifdef GIT_WINDOWS_NATIVE
>  int cmd__windows_named_pipe(int argc, const char **argv);
> diff --git a/t/helper/test-xml-encode.c b/t/helper/test-xml-encode.c
> deleted file mode 100644
> index a648bbd961c..00000000000
> --- a/t/helper/test-xml-encode.c
> +++ /dev/null
> @@ -1,80 +0,0 @@
> -#include "test-tool.h"
> -
> -static const char *utf8_replace_character = "&#xfffd;";
> -
> -/*
> - * Encodes (possibly incorrect) UTF-8 on <stdin> to <stdout>, to be embedded
> - * in an XML file.
> - */
> -int cmd__xml_encode(int argc, const char **argv)
> -{
> -	unsigned char buf[1024], tmp[4], *tmp2 = NULL;
> -	ssize_t cur = 0, len = 1, remaining = 0;
> -	unsigned char ch;
> -
> -	for (;;) {
> -		if (++cur == len) {
> -			len = xread(0, buf, sizeof(buf));
> -			if (!len)
> -				return 0;
> -			if (len < 0)
> -				die_errno("Could not read <stdin>");
> -			cur = 0;
> -		}
> -		ch = buf[cur];
> -
> -		if (tmp2) {
> -			if ((ch & 0xc0) != 0x80) {
> -				fputs(utf8_replace_character, stdout);
> -				tmp2 = NULL;
> -				cur--;
> -				continue;
> -			}
> -			*tmp2 = ch;
> -			tmp2++;
> -			if (--remaining == 0) {
> -				fwrite(tmp, tmp2 - tmp, 1, stdout);
> -				tmp2 = NULL;
> -			}
> -			continue;
> -		}
> -
> -		if (!(ch & 0x80)) {
> -			/* 0xxxxxxx */
> -			if (ch == '&')
> -				fputs("&amp;", stdout);
> -			else if (ch == '\'')
> -				fputs("&apos;", stdout);
> -			else if (ch == '"')
> -				fputs("&quot;", stdout);
> -			else if (ch == '<')
> -				fputs("&lt;", stdout);
> -			else if (ch == '>')
> -				fputs("&gt;", stdout);
> -			else if (ch >= 0x20)
> -				fputc(ch, stdout);
> -			else if (ch == 0x09 || ch == 0x0a || ch == 0x0d)
> -				fprintf(stdout, "&#x%02x;", ch);
> -			else
> -				fputs(utf8_replace_character, stdout);
> -		} else if ((ch & 0xe0) == 0xc0) {
> -			/* 110XXXXx 10xxxxxx */
> -			tmp[0] = ch;
> -			remaining = 1;
> -			tmp2 = tmp + 1;
> -		} else if ((ch & 0xf0) == 0xe0) {
> -			/* 1110XXXX 10Xxxxxx 10xxxxxx */
> -			tmp[0] = ch;
> -			remaining = 2;
> -			tmp2 = tmp + 1;
> -		} else if ((ch & 0xf8) == 0xf0) {
> -			/* 11110XXX 10XXxxxx 10xxxxxx 10xxxxxx */
> -			tmp[0] = ch;
> -			remaining = 3;
> -			tmp2 = tmp + 1;
> -		} else
> -			fputs(utf8_replace_character, stdout);
> -	}
> -
> -	return 0;
> -}
> diff --git a/t/test-lib.sh b/t/test-lib.sh
> index 0070d05234b..4dc41eeccc2 100644
> --- a/t/test-lib.sh
> +++ b/t/test-lib.sh
> @@ -371,6 +371,17 @@ then
>  		--escape-stdout ${HARNESS_ACTIVE+--escape-file} \
>  		"$GIT_TEST_TEE_OUTPUT_FILE"
>  	test "$(cat "$TEST_RESULTS_BASE.exit")" = 0
> +	if test -n "$write_junit_xml"
> +	then
> +		junit_xml_dir="$TEST_OUTPUT_DIRECTORY/out"
> +		mkdir -p "$junit_xml_dir"
> +		junit_xml_base=${0##*/}
> +		junit_xml_path="$junit_xml_dir/TEST-${junit_xml_base%.sh}.xml"
> +		junit_attrs="timestamp=\"$(TZ=UTC date +%Y-%m-%dT%H:%M:%S)\""
> +		tap2junit --name="$TEST_NAME" - \
> +			<"$GIT_TEST_TEE_OUTPUT_FILE" \
> +			>"$junit_xml_path"
> +	fi
>  	exit
>  elif test -n "$verbose" -a -n "$HARNESS_ACTIVE"
>  then
> @@ -588,7 +599,6 @@ export TERM
>
>  error () {
>  	say_color error "error: $*"
> -	finalize_junit_xml
>  	GIT_EXIT_OK=t
>  	exit 1
>  }
> @@ -672,56 +682,24 @@ trap '{ code=$?; set +x; } 2>/dev/null; exit $code' INT TERM HUP
>  # the test_expect_* functions instead.
>
>  test_ok_ () {
> -	if test -n "$write_junit_xml"
> -	then
> -		write_junit_xml_testcase "$*"
> -	fi
>  	test_success=$(($test_success + 1))
>  	say_color_tap "${verbose:+pass}" "ok $test_count - $@"
>  }
>
>  test_failure_ () {
> -	if test -n "$write_junit_xml"
> -	then
> -		junit_insert="<failure message=\"not ok $test_count -"
> -		junit_insert="$junit_insert $(xml_attr_encode "$1")\">"
> -		junit_insert="$junit_insert $(xml_attr_encode \
> -			"$(if test -n "$GIT_TEST_TEE_OUTPUT_FILE"
> -			   then
> -				test-tool path-utils skip-n-bytes \
> -					"$GIT_TEST_TEE_OUTPUT_FILE" $GIT_TEST_TEE_OFFSET
> -			   else
> -				printf '%s\n' "$@" | sed 1d
> -			   fi)")"
> -		junit_insert="$junit_insert</failure>"
> -		if test -n "$GIT_TEST_TEE_OUTPUT_FILE"
> -		then
> -			junit_insert="$junit_insert<system-err>$(xml_attr_encode \
> -				"$(cat "$GIT_TEST_TEE_OUTPUT_FILE")")</system-err>"
> -		fi
> -		write_junit_xml_testcase "$1" "      $junit_insert"
> -	fi
>  	test_failure=$(($test_failure + 1))
>  	say_color_tap error "not ok $test_count - $1"
>  	shift
>  	printf '%s\n' "$*" | sed -e 's/^/#	/'
> -	test "$immediate" = "" || { finalize_junit_xml; GIT_EXIT_OK=t; exit 1; }
> +	test "$immediate" = "" || { GIT_EXIT_OK=t; exit 1; }
>  }
>
>  test_known_broken_ok_ () {
> -	if test -n "$write_junit_xml"
> -	then
> -		write_junit_xml_testcase "$* (breakage fixed)"
> -	fi
>  	test_fixed=$(($test_fixed+1))
>  	say_color error "ok $test_count - $@ # TODO known breakage vanished"
>  }
>
>  test_known_broken_failure_ () {
> -	if test -n "$write_junit_xml"
> -	then
> -		write_junit_xml_testcase "$* (known breakage)"
> -	fi
>  	test_broken=$(($test_broken+1))
>  	say_color_tap warn "not ok $test_count - $@ # TODO known breakage"
>  }
> @@ -983,10 +961,6 @@ test_start_ () {
>  	test_count=$(($test_count+1))
>  	maybe_setup_verbose
>  	maybe_setup_valgrind
> -	if test -n "$write_junit_xml"
> -	then
> -		junit_start=$(test-tool date getnanos)
> -	fi
>  }
>
>  test_finish_ () {
> @@ -1029,13 +1003,6 @@ test_skip () {
>
>  	case "$to_skip" in
>  	t)
> -		if test -n "$write_junit_xml"
> -		then
> -			message="$(xml_attr_encode "$skipped_reason")"
> -			write_junit_xml_testcase "$1" \
> -				"      <skipped message=\"$message\" />"
> -		fi
> -
>  		say_color_tap skip "ok $test_count # skip $1 ($skipped_reason)"
>  		: true
>  		;;
> @@ -1050,53 +1017,6 @@ test_at_end_hook_ () {
>  	:
>  }
>
> -write_junit_xml () {
> -	case "$1" in
> -	--truncate)
> -		>"$junit_xml_path"
> -		junit_have_testcase=
> -		shift
> -		;;
> -	esac
> -	printf '%s\n' "$@" >>"$junit_xml_path"
> -}
> -
> -xml_attr_encode () {
> -	printf '%s\n' "$@" | test-tool xml-encode
> -}
> -
> -write_junit_xml_testcase () {
> -	junit_attrs="name=\"$(xml_attr_encode "$this_test.$test_count $1")\""
> -	shift
> -	junit_attrs="$junit_attrs classname=\"$this_test\""
> -	junit_attrs="$junit_attrs time=\"$(test-tool \
> -		date getnanos $junit_start)\""
> -	write_junit_xml "$(printf '%s\n' \
> -		"    <testcase $junit_attrs>" "$@" "    </testcase>")"
> -	junit_have_testcase=t
> -}
> -
> -finalize_junit_xml () {
> -	if test -n "$write_junit_xml" && test -n "$junit_xml_path"
> -	then
> -		test -n "$junit_have_testcase" || {
> -			junit_start=$(test-tool date getnanos)
> -			write_junit_xml_testcase "all tests skipped"
> -		}
> -
> -		# adjust the overall time
> -		junit_time=$(test-tool date getnanos $junit_suite_start)
> -		sed -e "s/\(<testsuite.*\) time=\"[^\"]*\"/\1/" \
> -			-e "s/<testsuite [^>]*/& time=\"$junit_time\"/" \
> -			-e '/^ *<\/testsuite/d' \
> -			<"$junit_xml_path" >"$junit_xml_path.new"
> -		mv "$junit_xml_path.new" "$junit_xml_path"
> -
> -		write_junit_xml "  </testsuite>" "</testsuites>"
> -		write_junit_xml=
> -	fi
> -}
> -
>  test_atexit_cleanup=:
>  test_atexit_handler () {
>  	# In a succeeding test script 'test_atexit_handler' is invoked
> @@ -1119,8 +1039,6 @@ test_done () {
>  	# removed, so the commands can access pidfiles and socket files.
>  	test_atexit_handler
>
> -	finalize_junit_xml
> -
>  	if test -z "$HARNESS_ACTIVE"
>  	then
>  		mkdir -p "$TEST_RESULTS_DIR"
> @@ -1364,23 +1282,6 @@ then
>  	test_done
>  fi
>
> -if test -n "$write_junit_xml"
> -then
> -	junit_xml_dir="$TEST_OUTPUT_DIRECTORY/out"
> -	mkdir -p "$junit_xml_dir"
> -	junit_xml_base=${0##*/}
> -	junit_xml_path="$junit_xml_dir/TEST-${junit_xml_base%.sh}.xml"
> -	junit_attrs="name=\"${junit_xml_base%.sh}\""
> -	junit_attrs="$junit_attrs timestamp=\"$(TZ=UTC \
> -		date +%Y-%m-%dT%H:%M:%S)\""
> -	write_junit_xml --truncate "<testsuites>" "  <testsuite $junit_attrs>"
> -	junit_suite_start=$(test-tool date getnanos)
> -	if test -n "$GIT_TEST_TEE_OUTPUT_FILE"
> -	then
> -		GIT_TEST_TEE_OFFSET=0
> -	fi
> -fi
> -
>  # Convenience
>  # A regexp to match 5, 35 and 40 hexdigits
>  _x05='[0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f]'
> --
> 2.31.0.rc1.210.g0f8085a843c
>
>

Re: [RFC/PATCH 7/7] test-lib: generate JUnit output via TAP

[Ævar Arnfjörð Bjarmason]

On Fri, Mar 19 2021, Johannes Schindelin wrote:

> Hi Ævar,
>
> On Tue, 9 Mar 2021, Ævar Arnfjörð Bjarmason wrote:
>
>> Rewrite the home-brew JUnit output generation added in
>> 22231908151 (tests: optionally write results as JUnit-style .xml,
>> 2019-01-29) and other subsequent commits to be generated via the TAP
>> output.
>>
>> This is now possible that the TAP output emitted with --tee is
>> guaranteed to be valid TAP, see the preceding commit.
>>
>> The JUnit output is not bug-for-bug compatible with the previous
>> output, but it looks better to me.
>>
>> This also requires installing TAP::Formatter::JUnit[1], perhaps that's
>> not palatable to the users of the --write-junit-xml option.
>
> Indeed. I am trying to keep the dependencies required for the Windows jobs
> of our CI/PR builds to a minimum.

I'm taking this to mean the dependency of the TAP::Formatter::JUnit CPAN
module. Since the tests already depend on Perl, and presumably that Perl
isn't so broken as to not have the built in TAP modules
(e.g. TAP::Parser).

> Note, also, that the JUnit output was mostly relevant for when we used
> Azure Pipelines: it has a specific UI to study test results, figure out
> flaky tests, performance, etc.
>
> Now that we use GitHub Actions, we do not have such a nice test aggregator
> anymore, but we might get one again in the future, who knows.

So there's no known current active user of this JUnit output target, or
at least if such a user exists it's not you anymore?

I'm guessing we'd be unlikely to miss someone targeting JUnit from
git.git's tests who's not on this list to chime in. So is it not used
currently & could be removed?

>> In any case, it'll be easy to whip up our own TAP emitter with a
>> TAP::Parser and TAP::Formatter, both of whom come with perl itself,
>> which we already rely on for tests.
>>
>> It should also be significantly faster on Windows,
>
> I really hate to have to harp on this when talking to you, but... well,
> how can I say it? Perl is _slooooooooooooow_ on Windows.
>
> Like, _really_ slow. Ridiculously slow.
>
> I know, you recently got riled up when Jeff suggested that the Perl hook
> calling FSMonior might be slow, but the truth is: it is super slow. It's
> not even funny how slow it is. And it fills me with no joy having to
> repeat it every time the question comes up whether running any part of Git
> that is written in Perl might affect performance on Windows. I really
> dislike having to be that messenger.

Riled up? No, perplexed: yes. You're referring to
https://lore.kernel.org/git/87h7lgfchm.fsf@evledraar.gmail.com/

So as an aside about that particular issue / slowness I haven't been
able to reproduce:

If it's really a reference to some Windows-specific issue with Perl on
Windows in particular that would certainly be helpful for the rest of us
trying to follow along wondering where these wildly different
performance numbers come from.

So not that we don't want to more to some other fsmonitor implementation
for other reasons, but the Perl part of that hook would be rather easy
to replace with some C JSON encoder or whatever.

> I doubt that you will ever be able to replace my (admittedly slightly
> hacky) C helper with anything written in Perl that does even come close to
> being faster.
>
> In other words, I fear that your work here might not have the outcome you
> hoped for.

We shell out to your C helper at least once for every test we run. By
converting the TAP after the full run we're only invoking Perl once
per-test.

If that one Perl invocation is still much more expensive than doing that
~20-50 times per-test we can easily move the loop to the Perl script and
invoke Perl once per test suite run. At that point you've got 1 run
v.s. >20k runs for the current helper being called in a loop by
test-lib.sh

But I don't have access to a Windows test box. So maybe it's slower than
I'm imagining. How long do the equivalent of these take on Windows (not
sure if the time built-in is there)?:
    
    $ time perl -MTAP::Harness -wE 'say "hello world"'
    hello world
    
    real    0m0.018s
    user    0m0.013s
    sys     0m0.005s
    
    $ time (echo hi | helper/test-tool xml-encode)
    hi

    real    0m0.002s
    user    0m0.001s
    sys     0m0.002s


In any case, I regret focusing on the TAP::Formatter::JUnit part in this
RFC. The real meaty part is being able to have stable TAP output, and
thus not having to add N number of output formats into test-lib.sh
itself.

A tool that consumes that can then be e.g. Perl's TAP tooling, or just
some C program or shellscript that calls the code that the below quoted
diff is removing (aside from the test-lib.sh part, which would go away).

But it would be easier to write such tools using Perl's tooling, as it
saves one from writing a parser for TAP.

I'd be surprised if Perl was adding much overhead in that context, and I
see that the existing Windows CI jobs are running through "prove", so
presumably even on Windows e.g. this:

    time make T=t000*.sh DEFAULT_TEST_TARGET=prove

Is not much slower than:

    time make T=t000*.sh DEFAULT_TEST_TARGET=test

I think this is the Nth time we've had some variant of this "Perl in
git's tests" discussion.

I'm all for finding solutions to whatever issues you have, but I find it
confusing that in these discussions you seem to conflate and jump
between some or all of (just the ones I'm remembering):

 1. Some imagined future state where there's no Perl whatsoever in the
    test suite or git.git's build toolchain, which isn't the case now,
    or anywhere in the forseeable future.

 2. A future state where GFW etc. don't need to ship a Perl to users (I
    believe this is either close or already there, I haven't kept up..)

 3. The slowness of Perl for: tight loops, a few per test, once per test
    suite run.

 4. How #3 e.g. in a tight loop compares to calling say sed or awk in a
    tight shell loop. Is perl uniquely bad on Windows, or is it really a
    gripe about our use of shellscripting in general?

 6. Not wanting to (understandably) package any more non-core Perl
    stuff, understandable, but we always have the option of extending
    perl/FromCPAN/ if we find something truly useful (in this case just
    having a custom JUnit XML emitter, if it's actually needed by anyone
    anymore, should be rather easy).

So e.g. in this case I can guess at some of the gaps and *think* that
some code in t/ that uses TAP::Parser (a perl core module) and was
invoked either once per test-lib.sh invocation, or better (but perhaps
not needed, as it would make it a bit more complex) once per test-suite
run should be fine.

That code could even be implemented as a prove(1) plugin, at which point
we'd be invoking Perl exactly as many times as we are now, but I'd
rather not paint myself into that particular corner without good reason.


>> as we can e.g. write all the *.out files, and only do that conversion at
>> the end for all files in a batch, as opposed to the current
>> implementation of shelling out to test-tool in a loop for each test.
>>
>> 1. https://metacpan.org/pod/distribution/TAP-Formatter-JUnit/script/tap2junit
>>
>> Signed-off-by: Ævar Arnfjörð Bjarmason <avarab@gmail.com>
>> ---
>>  Makefile                   |   1 -
>>  t/helper/test-date.c       |  12 ----
>>  t/helper/test-path-utils.c |  21 -------
>>  t/helper/test-tool.c       |   1 -
>>  t/helper/test-tool.h       |   1 -
>>  t/helper/test-xml-encode.c |  80 ------------------------
>>  t/test-lib.sh              | 123 ++++---------------------------------
>>  7 files changed, 12 insertions(+), 227 deletions(-)
>>  delete mode 100644 t/helper/test-xml-encode.c
>>
>> diff --git a/Makefile b/Makefile
>> index d26b9d62ee9..fa7c52f7a42 100644
>> --- a/Makefile
>> +++ b/Makefile
>> @@ -748,7 +748,6 @@ TEST_BUILTINS_OBJS += test-urlmatch-normalization.o
>>  TEST_BUILTINS_OBJS += test-wildmatch.o
>>  TEST_BUILTINS_OBJS += test-windows-named-pipe.o
>>  TEST_BUILTINS_OBJS += test-write-cache.o
>> -TEST_BUILTINS_OBJS += test-xml-encode.o
>>
>>  # Do not add more tests here unless they have extra dependencies. Add
>>  # them in TEST_BUILTINS_OBJS above.
>> diff --git a/t/helper/test-date.c b/t/helper/test-date.c
>> index 099eff4f0fc..ebf133943b3 100644
>> --- a/t/helper/test-date.c
>> +++ b/t/helper/test-date.c
>> @@ -8,7 +8,6 @@ static const char *usage_msg = "\n"
>>  "  test-tool date parse [date]...\n"
>>  "  test-tool date approxidate [date]...\n"
>>  "  test-tool date timestamp [date]...\n"
>> -"  test-tool date getnanos [start-nanos]\n"
>>  "  test-tool date is64bit\n"
>>  "  test-tool date time_t-is64bit\n";
>>
>> @@ -92,15 +91,6 @@ static void parse_approx_timestamp(const char **argv)
>>  	}
>>  }
>>
>> -static void getnanos(const char **argv)
>> -{
>> -	double seconds = getnanotime() / 1.0e9;
>> -
>> -	if (*argv)
>> -		seconds -= strtod(*argv, NULL);
>> -	printf("%lf\n", seconds);
>> -}
>> -
>>  int cmd__date(int argc, const char **argv)
>>  {
>>  	const char *x;
>> @@ -120,8 +110,6 @@ int cmd__date(int argc, const char **argv)
>>  		parse_approxidate(argv+1);
>>  	else if (!strcmp(*argv, "timestamp"))
>>  		parse_approx_timestamp(argv+1);
>> -	else if (!strcmp(*argv, "getnanos"))
>> -		getnanos(argv+1);
>>  	else if (!strcmp(*argv, "is64bit"))
>>  		return sizeof(timestamp_t) == 8 ? 0 : 1;
>>  	else if (!strcmp(*argv, "time_t-is64bit"))
>> diff --git a/t/helper/test-path-utils.c b/t/helper/test-path-utils.c
>> index 313a153209c..090596ac492 100644
>> --- a/t/helper/test-path-utils.c
>> +++ b/t/helper/test-path-utils.c
>> @@ -407,27 +407,6 @@ int cmd__path_utils(int argc, const char **argv)
>>  		return !!res;
>>  	}
>>
>> -	if (argc == 4 && !strcmp(argv[1], "skip-n-bytes")) {
>> -		int fd = open(argv[2], O_RDONLY), offset = atoi(argv[3]);
>> -		char buffer[65536];
>> -
>> -		if (fd < 0)
>> -			die_errno("could not open '%s'", argv[2]);
>> -		if (lseek(fd, offset, SEEK_SET) < 0)
>> -			die_errno("could not skip %d bytes", offset);
>> -		for (;;) {
>> -			ssize_t count = read(fd, buffer, sizeof(buffer));
>> -			if (count < 0)
>> -				die_errno("could not read '%s'", argv[2]);
>> -			if (!count)
>> -				break;
>> -			if (write(1, buffer, count) < 0)
>> -				die_errno("could not write to stdout");
>> -		}
>> -		close(fd);
>> -		return 0;
>> -	}
>> -
>>  	if (argc > 5 && !strcmp(argv[1], "slice-tests")) {
>>  		int res = 0;
>>  		long offset, stride, i;
>> diff --git a/t/helper/test-tool.c b/t/helper/test-tool.c
>> index 1876bad8f42..3fa02011b61 100644
>> --- a/t/helper/test-tool.c
>> +++ b/t/helper/test-tool.c
>> @@ -73,7 +73,6 @@ static struct test_cmd cmds[] = {
>>  	{ "tee", cmd__tee },
>>  	{ "trace2", cmd__trace2 },
>>  	{ "urlmatch-normalization", cmd__urlmatch_normalization },
>> -	{ "xml-encode", cmd__xml_encode },
>>  	{ "wildmatch", cmd__wildmatch },
>>  #ifdef GIT_WINDOWS_NATIVE
>>  	{ "windows-named-pipe", cmd__windows_named_pipe },
>> diff --git a/t/helper/test-tool.h b/t/helper/test-tool.h
>> index 9b3c1f75267..5028730807e 100644
>> --- a/t/helper/test-tool.h
>> +++ b/t/helper/test-tool.h
>> @@ -63,7 +63,6 @@ int cmd__subprocess(int argc, const char **argv);
>>  int cmd__tee(int argc, const char **argv);
>>  int cmd__trace2(int argc, const char **argv);
>>  int cmd__urlmatch_normalization(int argc, const char **argv);
>> -int cmd__xml_encode(int argc, const char **argv);
>>  int cmd__wildmatch(int argc, const char **argv);
>>  #ifdef GIT_WINDOWS_NATIVE
>>  int cmd__windows_named_pipe(int argc, const char **argv);
>> diff --git a/t/helper/test-xml-encode.c b/t/helper/test-xml-encode.c
>> deleted file mode 100644
>> index a648bbd961c..00000000000
>> --- a/t/helper/test-xml-encode.c
>> +++ /dev/null
>> @@ -1,80 +0,0 @@
>> -#include "test-tool.h"
>> -
>> -static const char *utf8_replace_character = "&#xfffd;";
>> -
>> -/*
>> - * Encodes (possibly incorrect) UTF-8 on <stdin> to <stdout>, to be embedded
>> - * in an XML file.
>> - */
>> -int cmd__xml_encode(int argc, const char **argv)
>> -{
>> -	unsigned char buf[1024], tmp[4], *tmp2 = NULL;
>> -	ssize_t cur = 0, len = 1, remaining = 0;
>> -	unsigned char ch;
>> -
>> -	for (;;) {
>> -		if (++cur == len) {
>> -			len = xread(0, buf, sizeof(buf));
>> -			if (!len)
>> -				return 0;
>> -			if (len < 0)
>> -				die_errno("Could not read <stdin>");
>> -			cur = 0;
>> -		}
>> -		ch = buf[cur];
>> -
>> -		if (tmp2) {
>> -			if ((ch & 0xc0) != 0x80) {
>> -				fputs(utf8_replace_character, stdout);
>> -				tmp2 = NULL;
>> -				cur--;
>> -				continue;
>> -			}
>> -			*tmp2 = ch;
>> -			tmp2++;
>> -			if (--remaining == 0) {
>> -				fwrite(tmp, tmp2 - tmp, 1, stdout);
>> -				tmp2 = NULL;
>> -			}
>> -			continue;
>> -		}
>> -
>> -		if (!(ch & 0x80)) {
>> -			/* 0xxxxxxx */
>> -			if (ch == '&')
>> -				fputs("&amp;", stdout);
>> -			else if (ch == '\'')
>> -				fputs("&apos;", stdout);
>> -			else if (ch == '"')
>> -				fputs("&quot;", stdout);
>> -			else if (ch == '<')
>> -				fputs("&lt;", stdout);
>> -			else if (ch == '>')
>> -				fputs("&gt;", stdout);
>> -			else if (ch >= 0x20)
>> -				fputc(ch, stdout);
>> -			else if (ch == 0x09 || ch == 0x0a || ch == 0x0d)
>> -				fprintf(stdout, "&#x%02x;", ch);
>> -			else
>> -				fputs(utf8_replace_character, stdout);
>> -		} else if ((ch & 0xe0) == 0xc0) {
>> -			/* 110XXXXx 10xxxxxx */
>> -			tmp[0] = ch;
>> -			remaining = 1;
>> -			tmp2 = tmp + 1;
>> -		} else if ((ch & 0xf0) == 0xe0) {
>> -			/* 1110XXXX 10Xxxxxx 10xxxxxx */
>> -			tmp[0] = ch;
>> -			remaining = 2;
>> -			tmp2 = tmp + 1;
>> -		} else if ((ch & 0xf8) == 0xf0) {
>> -			/* 11110XXX 10XXxxxx 10xxxxxx 10xxxxxx */
>> -			tmp[0] = ch;
>> -			remaining = 3;
>> -			tmp2 = tmp + 1;
>> -		} else
>> -			fputs(utf8_replace_character, stdout);
>> -	}
>> -
>> -	return 0;
>> -}
>> diff --git a/t/test-lib.sh b/t/test-lib.sh
>> index 0070d05234b..4dc41eeccc2 100644
>> --- a/t/test-lib.sh
>> +++ b/t/test-lib.sh
>> @@ -371,6 +371,17 @@ then
>>  		--escape-stdout ${HARNESS_ACTIVE+--escape-file} \
>>  		"$GIT_TEST_TEE_OUTPUT_FILE"
>>  	test "$(cat "$TEST_RESULTS_BASE.exit")" = 0
>> +	if test -n "$write_junit_xml"
>> +	then
>> +		junit_xml_dir="$TEST_OUTPUT_DIRECTORY/out"
>> +		mkdir -p "$junit_xml_dir"
>> +		junit_xml_base=${0##*/}
>> +		junit_xml_path="$junit_xml_dir/TEST-${junit_xml_base%.sh}.xml"
>> +		junit_attrs="timestamp=\"$(TZ=UTC date +%Y-%m-%dT%H:%M:%S)\""
>> +		tap2junit --name="$TEST_NAME" - \
>> +			<"$GIT_TEST_TEE_OUTPUT_FILE" \
>> +			>"$junit_xml_path"
>> +	fi
>>  	exit
>>  elif test -n "$verbose" -a -n "$HARNESS_ACTIVE"
>>  then
>> @@ -588,7 +599,6 @@ export TERM
>>
>>  error () {
>>  	say_color error "error: $*"
>> -	finalize_junit_xml
>>  	GIT_EXIT_OK=t
>>  	exit 1
>>  }
>> @@ -672,56 +682,24 @@ trap '{ code=$?; set +x; } 2>/dev/null; exit $code' INT TERM HUP
>>  # the test_expect_* functions instead.
>>
>>  test_ok_ () {
>> -	if test -n "$write_junit_xml"
>> -	then
>> -		write_junit_xml_testcase "$*"
>> -	fi
>>  	test_success=$(($test_success + 1))
>>  	say_color_tap "${verbose:+pass}" "ok $test_count - $@"
>>  }
>>
>>  test_failure_ () {
>> -	if test -n "$write_junit_xml"
>> -	then
>> -		junit_insert="<failure message=\"not ok $test_count -"
>> -		junit_insert="$junit_insert $(xml_attr_encode "$1")\">"
>> -		junit_insert="$junit_insert $(xml_attr_encode \
>> -			"$(if test -n "$GIT_TEST_TEE_OUTPUT_FILE"
>> -			   then
>> -				test-tool path-utils skip-n-bytes \
>> -					"$GIT_TEST_TEE_OUTPUT_FILE" $GIT_TEST_TEE_OFFSET
>> -			   else
>> -				printf '%s\n' "$@" | sed 1d
>> -			   fi)")"
>> -		junit_insert="$junit_insert</failure>"
>> -		if test -n "$GIT_TEST_TEE_OUTPUT_FILE"
>> -		then
>> -			junit_insert="$junit_insert<system-err>$(xml_attr_encode \
>> -				"$(cat "$GIT_TEST_TEE_OUTPUT_FILE")")</system-err>"
>> -		fi
>> -		write_junit_xml_testcase "$1" "      $junit_insert"
>> -	fi
>>  	test_failure=$(($test_failure + 1))
>>  	say_color_tap error "not ok $test_count - $1"
>>  	shift
>>  	printf '%s\n' "$*" | sed -e 's/^/#	/'
>> -	test "$immediate" = "" || { finalize_junit_xml; GIT_EXIT_OK=t; exit 1; }
>> +	test "$immediate" = "" || { GIT_EXIT_OK=t; exit 1; }
>>  }
>>
>>  test_known_broken_ok_ () {
>> -	if test -n "$write_junit_xml"
>> -	then
>> -		write_junit_xml_testcase "$* (breakage fixed)"
>> -	fi
>>  	test_fixed=$(($test_fixed+1))
>>  	say_color error "ok $test_count - $@ # TODO known breakage vanished"
>>  }
>>
>>  test_known_broken_failure_ () {
>> -	if test -n "$write_junit_xml"
>> -	then
>> -		write_junit_xml_testcase "$* (known breakage)"
>> -	fi
>>  	test_broken=$(($test_broken+1))
>>  	say_color_tap warn "not ok $test_count - $@ # TODO known breakage"
>>  }
>> @@ -983,10 +961,6 @@ test_start_ () {
>>  	test_count=$(($test_count+1))
>>  	maybe_setup_verbose
>>  	maybe_setup_valgrind
>> -	if test -n "$write_junit_xml"
>> -	then
>> -		junit_start=$(test-tool date getnanos)
>> -	fi
>>  }
>>
>>  test_finish_ () {
>> @@ -1029,13 +1003,6 @@ test_skip () {
>>
>>  	case "$to_skip" in
>>  	t)
>> -		if test -n "$write_junit_xml"
>> -		then
>> -			message="$(xml_attr_encode "$skipped_reason")"
>> -			write_junit_xml_testcase "$1" \
>> -				"      <skipped message=\"$message\" />"
>> -		fi
>> -
>>  		say_color_tap skip "ok $test_count # skip $1 ($skipped_reason)"
>>  		: true
>>  		;;
>> @@ -1050,53 +1017,6 @@ test_at_end_hook_ () {
>>  	:
>>  }
>>
>> -write_junit_xml () {
>> -	case "$1" in
>> -	--truncate)
>> -		>"$junit_xml_path"
>> -		junit_have_testcase=
>> -		shift
>> -		;;
>> -	esac
>> -	printf '%s\n' "$@" >>"$junit_xml_path"
>> -}
>> -
>> -xml_attr_encode () {
>> -	printf '%s\n' "$@" | test-tool xml-encode
>> -}
>> -
>> -write_junit_xml_testcase () {
>> -	junit_attrs="name=\"$(xml_attr_encode "$this_test.$test_count $1")\""
>> -	shift
>> -	junit_attrs="$junit_attrs classname=\"$this_test\""
>> -	junit_attrs="$junit_attrs time=\"$(test-tool \
>> -		date getnanos $junit_start)\""
>> -	write_junit_xml "$(printf '%s\n' \
>> -		"    <testcase $junit_attrs>" "$@" "    </testcase>")"
>> -	junit_have_testcase=t
>> -}
>> -
>> -finalize_junit_xml () {
>> -	if test -n "$write_junit_xml" && test -n "$junit_xml_path"
>> -	then
>> -		test -n "$junit_have_testcase" || {
>> -			junit_start=$(test-tool date getnanos)
>> -			write_junit_xml_testcase "all tests skipped"
>> -		}
>> -
>> -		# adjust the overall time
>> -		junit_time=$(test-tool date getnanos $junit_suite_start)
>> -		sed -e "s/\(<testsuite.*\) time=\"[^\"]*\"/\1/" \
>> -			-e "s/<testsuite [^>]*/& time=\"$junit_time\"/" \
>> -			-e '/^ *<\/testsuite/d' \
>> -			<"$junit_xml_path" >"$junit_xml_path.new"
>> -		mv "$junit_xml_path.new" "$junit_xml_path"
>> -
>> -		write_junit_xml "  </testsuite>" "</testsuites>"
>> -		write_junit_xml=
>> -	fi
>> -}
>> -
>>  test_atexit_cleanup=:
>>  test_atexit_handler () {
>>  	# In a succeeding test script 'test_atexit_handler' is invoked
>> @@ -1119,8 +1039,6 @@ test_done () {
>>  	# removed, so the commands can access pidfiles and socket files.
>>  	test_atexit_handler
>>
>> -	finalize_junit_xml
>> -
>>  	if test -z "$HARNESS_ACTIVE"
>>  	then
>>  		mkdir -p "$TEST_RESULTS_DIR"
>> @@ -1364,23 +1282,6 @@ then
>>  	test_done
>>  fi
>>
>> -if test -n "$write_junit_xml"
>> -then
>> -	junit_xml_dir="$TEST_OUTPUT_DIRECTORY/out"
>> -	mkdir -p "$junit_xml_dir"
>> -	junit_xml_base=${0##*/}
>> -	junit_xml_path="$junit_xml_dir/TEST-${junit_xml_base%.sh}.xml"
>> -	junit_attrs="name=\"${junit_xml_base%.sh}\""
>> -	junit_attrs="$junit_attrs timestamp=\"$(TZ=UTC \
>> -		date +%Y-%m-%dT%H:%M:%S)\""
>> -	write_junit_xml --truncate "<testsuites>" "  <testsuite $junit_attrs>"
>> -	junit_suite_start=$(test-tool date getnanos)
>> -	if test -n "$GIT_TEST_TEE_OUTPUT_FILE"
>> -	then
>> -		GIT_TEST_TEE_OFFSET=0
>> -	fi
>> -fi
>> -
>>  # Convenience
>>  # A regexp to match 5, 35 and 40 hexdigits
>>  _x05='[0-9a-f][0-9a-f][0-9a-f][0-9a-f][0-9a-f]'
>> --
>> 2.31.0.rc1.210.g0f8085a843c
>>
>>

Re: [RFC/PATCH 7/7] test-lib: generate JUnit output via TAP

[Johannes Schindelin]

[-- Attachment #1: Type: text/plain, Size: 9815 bytes --]

Hi Ævar,

On Sun, 21 Mar 2021, Ævar Arnfjörð Bjarmason wrote:

> On Fri, Mar 19 2021, Johannes Schindelin wrote:
>
> > On Tue, 9 Mar 2021, Ævar Arnfjörð Bjarmason wrote:
> >
> >> Rewrite the home-brew JUnit output generation added in
> >> 22231908151 (tests: optionally write results as JUnit-style .xml,
> >> 2019-01-29) and other subsequent commits to be generated via the TAP
> >> output.
> >>
> >> This is now possible that the TAP output emitted with --tee is
> >> guaranteed to be valid TAP, see the preceding commit.
> >>
> >> The JUnit output is not bug-for-bug compatible with the previous
> >> output, but it looks better to me.
> >>
> >> This also requires installing TAP::Formatter::JUnit[1], perhaps that's
> >> not palatable to the users of the --write-junit-xml option.
> >
> > Indeed. I am trying to keep the dependencies required for the Windows jobs
> > of our CI/PR builds to a minimum.
>
> I'm taking this to mean the dependency of the TAP::Formatter::JUnit CPAN
> module. Since the tests already depend on Perl, and presumably that Perl
> isn't so broken as to not have the built in TAP modules
> (e.g. TAP::Parser).

I have no idea why you insist on modifying something that works quite
well, but yeah, if you want to depend on the implementation detail that we
_currently_ run even the Visual Studio tests (that do _not_ depend on
`prove`) in an environment that has that dependency of `prove`, well, I
guess I'll have to work on maintaining that state of affairs. Doesn't mean
that it makes me happy. It really looks to me like a whole lot of work,
without any benefit.

> > Note, also, that the JUnit output was mostly relevant for when we used
> > Azure Pipelines: it has a specific UI to study test results, figure out
> > flaky tests, performance, etc.
> >
> > Now that we use GitHub Actions, we do not have such a nice test aggregator
> > anymore, but we might get one again in the future, who knows.
>
> So there's no known current active user of this JUnit output target, or
> at least if such a user exists it's not you anymore?
>
> I'm guessing we'd be unlikely to miss someone targeting JUnit from
> git.git's tests who's not on this list to chime in. So is it not used
> currently & could be removed?

No, I want to keep it because I hope that we'll get that lost
functionality back some time soon.

Sorry for not spelling that out more clearly.

> >> In any case, it'll be easy to whip up our own TAP emitter with a
> >> TAP::Parser and TAP::Formatter, both of whom come with perl itself,
> >> which we already rely on for tests.
> >>
> >> It should also be significantly faster on Windows,
> >
> > I really hate to have to harp on this when talking to you, but... well,
> > how can I say it? Perl is _slooooooooooooow_ on Windows.
> >
> > Like, _really_ slow. Ridiculously slow.
> >
> > I know, you recently got riled up when Jeff suggested that the Perl hook
> > calling FSMonior might be slow, but the truth is: it is super slow. It's
> > not even funny how slow it is. And it fills me with no joy having to
> > repeat it every time the question comes up whether running any part of Git
> > that is written in Perl might affect performance on Windows. I really
> > dislike having to be that messenger.
>
> Riled up? No, perplexed: yes. You're referring to
> https://lore.kernel.org/git/87h7lgfchm.fsf@evledraar.gmail.com/
>
> So as an aside about that particular issue / slowness I haven't been
> able to reproduce:
>
> If it's really a reference to some Windows-specific issue with Perl on
> Windows in particular that would certainly be helpful for the rest of us
> trying to follow along wondering where these wildly different
> performance numbers come from.
>
> So not that we don't want to more to some other fsmonitor implementation

ETOOMANYNEGATIONS, can't parse.

> for other reasons, but the Perl part of that hook would be rather easy
> to replace with some C JSON encoder or whatever.

For the time being, I'd rather avoid discussing that because we already
have an experimental, built-in FSMonitor that I personally use. That
FSMonitor will nicely side-step all of the Perl slowness.

> > I doubt that you will ever be able to replace my (admittedly slightly
> > hacky) C helper with anything written in Perl that does even come close to
> > being faster.
> >
> > In other words, I fear that your work here might not have the outcome you
> > hoped for.
>
> We shell out to your C helper at least once for every test we run. By
> converting the TAP after the full run we're only invoking Perl once
> per-test.
>
> If that one Perl invocation is still much more expensive than doing that
> ~20-50 times per-test we can easily move the loop to the Perl script and
> invoke Perl once per test suite run. At that point you've got 1 run
> v.s. >20k runs for the current helper being called in a loop by
> test-lib.sh
>
> But I don't have access to a Windows test box. So maybe it's slower than
> I'm imagining. How long do the equivalent of these take on Windows (not
> sure if the time built-in is there)?:
>
>     $ time perl -MTAP::Harness -wE 'say "hello world"'
>     hello world
>
>     real    0m0.018s
>     user    0m0.013s
>     sys     0m0.005s
>
>     $ time (echo hi | helper/test-tool xml-encode)
>     hi

>     real    0m0.002s
>     user    0m0.001s
>     sys     0m0.002s

$ time perl -MTAP::Harness -wE 'say "hello world"'
hello world

real    0m0.326s
user    0m0.030s
sys     0m0.124s

$ time perl -MTAP::Harness -wE 'say "hello world"'
hello world

real    0m0.131s
user    0m0.061s
sys     0m0.046s

$ time perl -MTAP::Harness -wE 'say "hello world"'
hello world

real    0m0.209s
user    0m0.015s
sys     0m0.156s

$ time (echo hi | t/helper/test-tool xml-encode)
hi

real    0m0.165s
user    0m0.015s
sys     0m0.093s

$ time (echo hi | t/helper/test-tool xml-encode)
hi

real    0m0.092s
user    0m0.000s
sys     0m0.047s

$ time (echo hi | t/helper/test-tool xml-encode)
hi

real    0m0.075s
user    0m0.000s
sys     0m0.046s

Completely unscientific, but maybe it gives you an idea.

> In any case, I regret focusing on the TAP::Formatter::JUnit part in this
> RFC. The real meaty part is being able to have stable TAP output, and
> thus not having to add N number of output formats into test-lib.sh
> itself.
>
> A tool that consumes that can then be e.g. Perl's TAP tooling, or just
> some C program or shellscript that calls the code that the below quoted
> diff is removing (aside from the test-lib.sh part, which would go away).
>
> But it would be easier to write such tools using Perl's tooling, as it
> saves one from writing a parser for TAP.
>
> I'd be surprised if Perl was adding much overhead in that context, and I
> see that the existing Windows CI jobs are running through "prove", so
> presumably even on Windows e.g. this:
>
>     time make T=t000*.sh DEFAULT_TEST_TARGET=prove
>
> Is not much slower than:
>
>     time make T=t000*.sh DEFAULT_TEST_TARGET=test
>
> I think this is the Nth time we've had some variant of this "Perl in
> git's tests" discussion.

And it is still an issue because the Perl we use is running on top of a
POSIX emulation layer which makes everything slow.

> I'm all for finding solutions to whatever issues you have, but I find it
> confusing that in these discussions you seem to conflate and jump
> between some or all of (just the ones I'm remembering):
>
>  1. Some imagined future state where there's no Perl whatsoever in the
>     test suite or git.git's build toolchain, which isn't the case now,
>     or anywhere in the forseeable future.
>
>  2. A future state where GFW etc. don't need to ship a Perl to users (I
>     believe this is either close or already there, I haven't kept up..)
>
>  3. The slowness of Perl for: tight loops, a few per test, once per test
>     suite run.
>
>  4. How #3 e.g. in a tight loop compares to calling say sed or awk in a
>     tight shell loop. Is perl uniquely bad on Windows, or is it really a
>     gripe about our use of shellscripting in general?
>
>  6. Not wanting to (understandably) package any more non-core Perl
>     stuff, understandable, but we always have the option of extending
>     perl/FromCPAN/ if we find something truly useful (in this case just
>     having a custom JUnit XML emitter, if it's actually needed by anyone
>     anymore, should be rather easy).
>
> So e.g. in this case I can guess at some of the gaps and *think* that
> some code in t/ that uses TAP::Parser (a perl core module) and was
> invoked either once per test-lib.sh invocation, or better (but perhaps
> not needed, as it would make it a bit more complex) once per test-suite
> run should be fine.
>
> That code could even be implemented as a prove(1) plugin, at which point
> we'd be invoking Perl exactly as many times as we are now, but I'd
> rather not paint myself into that particular corner without good reason.

Yes, I would be much happier if Perl was not required to run our tests. I
would be even happier if we did not run our tests through shell,
especially performance tests, because running performance tests through
shell is like getting the most precise stop watch you can think of and
then looking away from the athletes while timing their sprint.

If you provide patches to bring us closer to that reality, I will try to
set aside time to help. But this "let's remove the C helper that serves us
well and instead use Perl, just to shuffle things around" business really
looks like a lot of churn to me, and I want to spend my time elsewhere.

Ciao,
Dscho