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

["Ævar Arnfjörð Bjarmason" <avarab@gmail.com>]

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.