test-lib: pass --tee and --verbose{,-log} through a TAP validator

Change the output under --tee and --verbose so that instead of passing
the output through "tee -a" we use our own home-grown "test-tool
tee-tap" (the "--verbose" output only goes through it under
HARNESS_ACTIVE=true, see below).

This ensures the output is valid TAP, allowing our test output to be
machine-readable. The --verbose-log mode is the first consumer of that
machine-readability, see further discussion below.

First, on the history of machine readable TAP output: Both the verbose
and non-verbose test outputs were valid TAP back when I added support
for TAP in 5099b99 (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 invalidating the
TAP). That was noticed and fixed in 452320f (test-lib: add
--verbose-log option, 2016-10-21), the problem was that the fix simply
turned off the 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 041c72d (travis: use
--verbose-log test option, 2016-10-21), see 522354d (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 452320f closed the door
on us having reliable machine-readable TAP output.

Let's instead revert the work done in 452320f and, as well as the
follow-up commits 88c6e9d (test-lib: --valgrind should not override
--verbose-log, 2017-09-05) and f5ba2de (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,
resulting in:

    $ HARNESS_ACTIVE=t ./t5547-push-quarantine.sh -v 2>&1 | grep -E '^.?ok'
    ok 1 - create picky dest repo
    \ok
    ok 2 - accepted objects work
    ok 3 - rejected objects are not installed
    ok 4 - rejected objects are removed
    ok 5 - push to repo path with path separator (colon)
    ok 6 - updating a ref from quarantine is forbidden

We are thus guaranteed to have valid TAP syntax both on stdout, and in
the *.out files in the test-results/* directory. Validating the *.out
files isn't needed for now, but will be once we have anything that
wants to re-parse that output, e.g. to re-format it on-demand after
the tests have been run.

These changes would allow us to entirely get rid of the --verbose-log
special-case, as noted in 452320f it was only needed to deal with a
problem in the TAP output that's now gone away. We might think that
it's now redundant to using the -v run to prove itself:

    prove <test> :: --verbose --tee
    prove -v <test> :: --verbose --tee

However, since its introduction developers have also come to rely on
relied on --verbose-log for manually invoking the tests. So we're
keeping it.

Better yet, since we previous commits set us up to understand TAP
verbosity levels. The tests can now be run at differing levels of
verbosity, while ensuring that the full output gets logged to
test-results/*.out.

The -V option (or --verbose-log=1) will emit the same output as it did
before.

Supplying -V0 (or --verbose-log=0) will strip that output down to have
no comments at all, i.e. just TAP directives.

Supplying -VV (or --verbose-log=2) will include second-level comments,
-VVV (or --verbose-log=3) 3rd-level comments etc. See the comment
above "say_color_tap_comment()" introduced in preceding commits for
what levels of output are currently emitted.

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

Author: avar

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

t/lib-subtest.sh

@@ -39,6 +39,12 @@ _run_sub_test_lib_test_common () {
 		# the sub-test.
 		sane_unset HARNESS_ACTIVE &&
 
+		# Under a top-level --verbose-log we'd get the
+		# "GIT_TEST_TEE_STARTED " prefix in all our output
+		# without resetting GIT_TEST_TEE_STARTED (normally it
+		# guards against recursion).
+		sane_unset GIT_TEST_TEE_STARTED &&
+
 		export TEST_DIRECTORY &&
 		# The child test re-sources GIT-BUILD-OPTIONS and may thus
 		# override the test output directory. We thus pass it as an

t/test-lib.sh

@@ -162,10 +162,31 @@ parse_option () {
 	--no-chain-lint)
 		GIT_TEST_CHAIN_LINT=0 ;;
 	-x)
-		trace=t ;;
-	-V|--verbose-log)
-		verbose_log=t
+		trace=t
+		verbose=t
+		;;
+	--verbose-log=0)
+
+		verbose_log_comment_level=-1
+		parse_option "--verbose-log"
+		;;
+	-V0|-V|--verbose-log)
+		verbose=t
 		tee=t
+
+		if test "$opt" = "-V0"
+		then
+			verbose_log_comment_level=-1
+		fi
+
+		# --verbose-log, unlike --verbose --tee, shows only
+		# --the TAP on stdout,
+		verbose_log=--out-only-tap
+
+		# TAP comment level via --verbose-log=0, -V, -VV, -VVV etc.
+		verbose_log_comment_level=${verbose_log_comment_level:-0}
+		verbose_log_comment_level=$(($verbose_log_comment_level + 1))
+
 		;;
 	--write-junit-xml)
 		write_junit_xml=t
@@ -220,7 +241,7 @@ do
 	fi
 
 	case "$opt" in
-	--*|-?)
+	--*|-?|-V0)
 		parse_option "$opt" ;;
 	-?*)
 		# bundled short options must be fed separately to parse_option
@@ -249,7 +270,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"
@@ -380,7 +401,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 " \
+		--file-escape \
+		${verbose_log:---out-escape} ${verbose_log:+--out-comment-level=$verbose_log_comment_level} \
+		"$GIT_TEST_TEE_OUTPUT_FILE"
+	test "$(cat "$TEST_RESULTS_BASE.exit")" = 0
+	exit
+elif test -n "$verbose" && test -n "$HARNESS_ACTIVE"
+then
+	mkdir -p "$TEST_RESULTS_DIR"
+	(
+		GIT_TEST_TEE_STARTED=done ${TEST_SHELL_PATH} "$0" "$@" 2>&1
+		echo $? >"$TEST_RESULTS_BASE.exit"
+	) | "$GIT_BUILD_DIR"/t/helper/test-tool tee-tap \
+		--prefix="GIT_TEST_TEE_STARTED " \
+		--out-escape
 	test "$(cat "$TEST_RESULTS_BASE.exit")" = 0
 	exit
 fi
@@ -408,10 +444,6 @@ then
 		trace=
 	fi
 fi
-if test -n "$trace" && test -z "$verbose_log"
-then
-	verbose=t
-fi
 
 # Since bash 5.0, checkwinsize is enabled by default which does
 # update the COLUMNS variable every time a non-builtin command
@@ -626,7 +658,10 @@ else
 fi
 
 say_color_tap() {
-	say_color "$@"
+	say_color_tap=$1
+	shift
+	printf "%s" "${GIT_TEST_TEE_STARTED:+GIT_TEST_TEE_STARTED }"
+	say_color "$say_color_tap" "$@"
 }
 
 # Comments starting with "#" are TAP syntax, we add our own comment
@@ -661,10 +696,11 @@ say_color_tap_comment_lines() {
 	say_color=$1
 	shift
 	say_start=$(say_color_start "$say_color" "")
+	say_prefix="${GIT_TEST_TEE_STARTED:+GIT_TEST_TEE_STARTED }"
 	say_reset=$(say_color_reset)
 
 	printf '%s\n' "$*" | sed \
-		-e "s/^/${say_start}${say_level}/" \
+		-e "s/^/${say_prefix}${say_start}${say_level}/" \
 		-e "s/$/${say_reset}/"
 }
 
@@ -712,14 +748,6 @@ say () {
 	say_color info "$*"
 }
 
-if test -n "$HARNESS_ACTIVE"
-then
-	if test "$verbose" = t || test -n "$verbose_only"
-	then
-		BAIL_OUT 'verbose mode forbidden under TAP harness; try --verbose-log'
-	fi
-fi
-
 test "${test_description}" != "" ||
 error "Test script did not set test_description."
 
@@ -729,10 +757,7 @@ then
 	exit 0
 fi
 
-if test "$verbose_log" = "t"
-then
-	exec 3>>"$GIT_TEST_TEE_OUTPUT_FILE" 4>&3
-elif test "$verbose" = "t"
+if test "$verbose" = "t"
 then
 	exec 4>&2 3>&1
 else
@@ -1023,9 +1048,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