[RFC/PATCH] WIP: Report intra-test progress with TAP subtests

[RFC/PATCH] WIP: Report intra-test progress with TAP subtests

[Ævar Arnfjörð Bjarmason]

It can be a PITA to debug Git's tests. They're a maze of chained &&'s,
and if one bit fails it can be hard to find out what that bit is.

As I mentioned in the comments for the "user friendly alterantives to
-d -f.." series we could do this with TAP subtests:

    $ perl -MTest::More=no_plan -E '
       subtest "A git test" => sub {
           pass("doing test -f file");
           pass("git commit ...");
           pass("test_tick...");
           done_testing();
       } for 1 .. 2
   '
       ok 1 - doing test -f file
       ok 2 - git commit ...
       ok 3 - test_tick...
       1..3
   ok 1 - A git test
       ok 1 - doing test -f file
       ok 2 - git commit ...
       ok 3 - test_tick...
       1..3
   ok 2 - A git test
   1..2

Here's an attempt at that, I've convented test_commit, test_merge and
test_cmp to report intra-test progress. The only problem is that it
doesn't quite work.

It works lik this:

    $ ./t0100-previous.sh  --verbose 2>&1 | ack '(?:^\s*ok|^\s*not ok|\d\.\.\d)'
        ok 1 - test_commit file:<A.t> message:<A> contents<A>
        1..1
    ok 1 - branch -d @{-1}
    ok 2 - branch -d @{-12} when there is not enough switches yet
        ok 3 - test_commit file:<B.t> message:<B> contents<B>
        ok 3 - test_commit file:<C.t> message:<C> contents<C>
        1..2
    ok 3 - merge @{-1}
    ok 4 - merge @{-1} when there is not enough switches yet
    1..4

But the problem is that the subtest code is evaluated in the context of the test itself:

	eval >&3 2>&4 "$1"

So when you run it you'll just get:

    $ ./t0100-previous.sh
        1..1
    ok 1 - branch -d @{-1}
    ok 2 - branch -d @{-12} when there is not enough switches yet
        1..2
    ok 3 - merge @{-1}
    ok 4 - merge @{-1} when there is not enough switches yet
    # passed all 4 test(s)
    1..4

Is there some filedescriptor saving/redirection magic I can do within
the subtest code to print things to the *real* stdout and stderr, not
the new file descriptors Git has aliased stdout/stderr to in the eval?

Another way to to it would be to buffer up the subtest output in a
shell variable and spew it out all at once when the whole test
finishes, but then it would be out of context with the --verbose
output, and it'd be ugly.
---
 t/test-lib.sh |   66 +++++++++++++++++++++++++++++++++++++++++++++++++-------
 1 files changed, 57 insertions(+), 9 deletions(-)

diff --git a/t/test-lib.sh b/t/test-lib.sh
index 4e73fff..2380cb9 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -208,6 +208,11 @@ test_success=0
 
 test_external_has_tap=0
 
+# subtest state
+in_subtest=
+subtest_count=0
+tap_prefix=
+
 die () {
 	code=$?
 	if test -n "$GIT_EXIT_OK"
@@ -290,20 +295,38 @@ test_tick () {
 
 test_commit () {
 	file=${2:-"$1.t"}
-	echo "${3-$1}" > "$file" &&
-	git add "$file" &&
-	test_tick &&
-	git commit -m "$1" &&
-	git tag "$1"
+	subtest_count=$(($subtest_count + 1))
+
+	if echo "${3-$1}" > "$file" &&
+		git add "$file" &&
+		test_tick &&
+		git commit -m "$1" &&
+		git tag "$1"
+	then
+		test_ok_ "test_commit file:<$file> message:<$1> contents<${3-$1}>"
+		true
+	else
+		test_failure_ "test_commit file:<$file> message:<$1> contents<${3-$1}>"
+		true
+	fi
 }
 
 # Call test_merge with the arguments "<message> <commit>", where <commit>
 # can be a tag pointing to the commit-to-merge.
 
 test_merge () {
-	test_tick &&
-	git merge -m "$1" "$2" &&
-	git tag "$1"
+
+	subtest_count=$(($subtest_count + 1))
+	if test_tick &&
+		git merge -m "$1" "$2" &&
+		git tag "$1"
+	then
+		test_ok_ "test_merge: file<$2> message<$1> tag:<$1>"
+		true
+	else
+		test_failure_ "test_merge: file<$2> message<$1> tag:<$1>"
+		false
+	fi
 }
 
 # This function helps systems where core.filemode=false is set.
@@ -353,7 +376,7 @@ test_have_prereq () {
 
 test_ok_ () {
 	test_success=$(($test_success + 1))
-	say_color "" "ok $test_count - $@"
+	say_color "" "${tap_prefix}ok $test_count - $@"
 }
 
 test_failure_ () {
@@ -380,9 +403,25 @@ test_debug () {
 
 test_run_ () {
 	test_cleanup=:
+
+	# Run the test in a subtest scope
+	in_subtest=1
+	subtest_count=0
+	tap_prefix='    '
 	eval >&3 2>&4 "$1"
+	in_subtest=
+
 	eval_ret=$?
 	eval >&3 2>&4 "$test_cleanup"
+
+	# Report the subtest plan
+	if test $subtest_count -gt 0
+	then
+		say "${tap_prefix}1..$subtest_count"
+		subtest_count=0
+	fi
+	tap_prefix=
+
 	if test "$verbose" = "t" && test -n "$HARNESS_ACTIVE"; then
 		echo ""
 	fi
@@ -602,6 +641,15 @@ test_might_fail () {
 
 test_cmp() {
 	$GIT_TEST_CMP "$@"
+	subtest_count=$(($subtest_count + 1))
+	if test "$?" = 0
+	then
+		test_ok_ "test_cmp '$@'"
+		true
+	else
+		test_failure_ "test_cmp '$@'"
+		false
+	fi
 }
 
 # This function can be used to schedule some commands to be run
-- 
1.7.2.1.295.gd03d

Re: [RFC/PATCH] WIP: Report intra-test progress with TAP subtests

[Jonathan Nieder]

Hi Ævar,

Ævar Arnfjörð Bjarmason wrote:

>    ok 1 - A git test
>        ok 1 - doing test -f file
>        ok 2 - git commit ...
>        ok 3 - test_tick...
>        1..3
>    ok 2 - A git test
>    1..2
> 
> Here's an attempt at that, I've convented test_commit, test_merge and
> test_cmp to report intra-test progress.

What if a test uses none of those commands?

The ultimate conclusion of such an approach would be to use
replacements for common commands like “git” and “cd”, making tests a
lot harder to read and write for the uninitiated.

If we get peeks where the infrastructure has a chance to provide
them, maybe it would be nice to allow explicitly inserting such
checkpoints, too?  Like:

	mv init init2 &&
	checkpoint &&
	git config -f .gitmodules submodule.example.url "$(pwd)/init2" &&
	checkpoint &&
	git config --remove-section submodule.example &&
	checkpoint &&
	[...]

while debugging.

However, I would rather see those inserted automatically.
Two ideas without code to back them up:

1. Script parsing.

Yes, parsing shell command language is hard, but tests use only
a subset of it.  In particular the &&-chaining means it might
be relatively easy to find where each command starts and ends.

The hard bits: “if”, “while”, and “for” flow control constructs.

The payoff of even partial progress in this would be very high,
since it should make static analysis of &&-chaining possible.

2. Letting the shell trace for us.

When tests fail, I generally use

	sh -x ./failing-test.sh -v -i

and scroll back through the log to the important part.

Maybe the test harness could automate that a little, by using
set -x at the beginning and set +x at the end of each test.

Hope that helps,
Jonathan

Re: [RFC/PATCH] WIP: Report intra-test progress with TAP subtests

[Ævar Arnfjörð Bjarmason]

On Wed, Aug 11, 2010 at 00:44, Jonathan Nieder <jrnieder@gmail.com> wrote:
> Hi Ævar,
>
> Ævar Arnfjörð Bjarmason wrote:
>
>>    ok 1 - A git test
>>        ok 1 - doing test -f file
>>        ok 2 - git commit ...
>>        ok 3 - test_tick...
>>        1..3
>>    ok 2 - A git test
>>    1..2
>>
>> Here's an attempt at that, I've convented test_commit, test_merge and
>> test_cmp to report intra-test progress.
>
> What if a test uses none of those commands?

Then it won't get any progress output.

> The ultimate conclusion of such an approach would be to use
> replacements for common commands like “git” and “cd”, making tests a
> lot harder to read and write for the uninitiated.

Yes, but there's a middle ground here. We use a lot of utility
functions in the tests, adding tracing to these makes it easier to see
what's going on, especially in large tests.

> If we get peeks where the infrastructure has a chance to provide
> them, maybe it would be nice to allow explicitly inserting such
> checkpoints, too?  Like:
>
>        mv init init2 &&
>        checkpoint &&
>        git config -f .gitmodules submodule.example.url "$(pwd)/init2" &&
>        checkpoint &&
>        git config --remove-section submodule.example &&
>        checkpoint &&
>        [...]
>
> while debugging.

Yeah. I was going to add something like that if I got this working.

> However, I would rather see those inserted automatically.
> Two ideas without code to back them up:
>
> 1. Script parsing.
>
> Yes, parsing shell command language is hard, but tests use only
> a subset of it.  In particular the &&-chaining means it might
> be relatively easy to find where each command starts and ends.
>
> The hard bits: “if”, “while”, and “for” flow control constructs.
>
> The payoff of even partial progress in this would be very high,
> since it should make static analysis of &&-chaining possible.

Sounds like a good long term project, and shouldn't be so hard for the
simple case.

> 2. Letting the shell trace for us.
>
> When tests fail, I generally use
>
>        sh -x ./failing-test.sh -v -i
>
> and scroll back through the log to the important part.
>
> Maybe the test harness could automate that a little, by using
> set -x at the beginning and set +x at the end of each test.

The main use case for this for me is the smoke tester output, where
you won't get access to the original machine (without asking). Having
a few intra-test checkpoints helps you to see where things might have
gone wrong.

Re: [RFC/PATCH] WIP: Report intra-test progress with TAP subtests

[Jonathan Nieder]

Ævar Arnfjörð Bjarmason wrote:
> On Wed, Aug 11, 2010 at 00:44, Jonathan Nieder <jrnieder@gmail.com> wrote:

>> Maybe the test harness could automate that a little, by using
>> set -x at the beginning and set +x at the end of each test.
>
> The main use case for this for me is the smoke tester output, where
> you won't get access to the original machine (without asking). Having
> a few intra-test checkpoints helps you to see where things might have
> gone wrong.

I meant something like this:
-- 8< --
diff --git a/t/test-lib.sh b/t/test-lib.sh
index e5523dd..a4bc358 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -368,9 +368,11 @@ test_debug () {
 
 test_run_ () {
 	test_cleanup=:
+	set -x
 	eval >&3 2>&4 "$1"
 	eval_ret=$?
 	eval >&3 2>&4 "$test_cleanup"
+	set +x
 	if test "$verbose" = "t" && test -n "$HARNESS_ACTIVE"; then
 		echo ""
 	fi
-- >8 --

but made optional and with output munged into parsable format by
changing PS4 (or "set -T" with a DEBUG trap, if that’s portable
enough).

Re: [RFC/PATCH] WIP: Report intra-test progress with TAP subtests

[Jonathan Nieder]

Ævar Arnfjörð Bjarmason wrote:

> Here's an attempt at that, I've convented test_commit, test_merge and
> test_cmp to report intra-test progress. The only problem is that it
> doesn't quite work.

I forgot to say: thanks for the demonstration.  This is neat stuff.

> 	eval >&3 2>&4 "$1"
> 
> So when you run it you'll just get:
> 
>     $ ./t0100-previous.sh
>         1..1
>     ok 1 - branch -d @{-1}
>     ok 2 - branch -d @{-12} when there is not enough switches yet
>         1..2
>     ok 3 - merge @{-1}
>     ok 4 - merge @{-1} when there is not enough switches yet
>     # passed all 4 test(s)
>     1..4
> 
> Is there some filedescriptor saving/redirection magic I can do within
> the subtest code to print things to the *real* stdout and stderr

Descriptor 5 is a pass-through for stdout: see v0.99.5~24^2~4
(Trapping exit in tests, 2005-08-10).

Do you need a pass-through for stderr, too, or was that theoretical?

> @@ -290,20 +295,38 @@ test_tick () {
>  
>  test_commit () {
>  	file=${2:-"$1.t"}
> -	echo "${3-$1}" > "$file" &&
> -	git add "$file" &&
> -	test_tick &&
> -	git commit -m "$1" &&
> -	git tag "$1"
> +	subtest_count=$(($subtest_count + 1))
> +
> +	if echo "${3-$1}" > "$file" &&
> +		git add "$file" &&
> +		test_tick &&
> +		git commit -m "$1" &&
> +		git tag "$1"
> +	then
> +		test_ok_ "test_commit file:<$file> message:<$1> contents<${3-$1}>"
> +		true
> +	else
> +		test_failure_ "test_commit file:<$file> message:<$1> contents<${3-$1}>"
> +		true
> +	fi

This would make the test continue after the subtest, right?  Is that
intended?

Re: [RFC/PATCH] WIP: Report intra-test progress with TAP subtests

[Johannes Sixt]

Am 8/11/2010 3:04, schrieb Jonathan Nieder:
> I meant something like this:
> -- 8< --
> diff --git a/t/test-lib.sh b/t/test-lib.sh
> index e5523dd..a4bc358 100644
> --- a/t/test-lib.sh
> +++ b/t/test-lib.sh
> @@ -368,9 +368,11 @@ test_debug () {
>  
>  test_run_ () {
>  	test_cleanup=:
> +	set -x
>  	eval >&3 2>&4 "$1"
>  	eval_ret=$?
>  	eval >&3 2>&4 "$test_cleanup"
> +	set +x
>  	if test "$verbose" = "t" && test -n "$HARNESS_ACTIVE"; then
>  		echo ""
>  	fi
> -- >8 --

Heh. I use something like this in my private build. It breaks a number of
tests due to additional output from test_must_fail invocations. I work
around it by adding 'set +x' inside the test case code. See

http://repo.or.cz/w/git/mingw/j6t.git/commitdiff/3943fd12f69da58937ac67a20be440f0ed532f18

-- Hannes

Re: [RFC/PATCH] WIP: Report intra-test progress with TAP subtests

[Ævar Arnfjörð Bjarmason]

On Wed, Aug 11, 2010 at 05:28, Jonathan Nieder <jrnieder@gmail.com> wrote:
> Ævar Arnfjörð Bjarmason wrote:
>
>> Here's an attempt at that, I've convented test_commit, test_merge and
>> test_cmp to report intra-test progress. The only problem is that it
>> doesn't quite work.
>
> I forgot to say: thanks for the demonstration.  This is neat stuff.
>
>>       eval >&3 2>&4 "$1"
>>
>> So when you run it you'll just get:
>>
>>     $ ./t0100-previous.sh
>>         1..1
>>     ok 1 - branch -d @{-1}
>>     ok 2 - branch -d @{-12} when there is not enough switches yet
>>         1..2
>>     ok 3 - merge @{-1}
>>     ok 4 - merge @{-1} when there is not enough switches yet
>>     # passed all 4 test(s)
>>     1..4
>>
>> Is there some filedescriptor saving/redirection magic I can do within
>> the subtest code to print things to the *real* stdout and stderr
>
> Descriptor 5 is a pass-through for stdout: see v0.99.5~24^2~4
> (Trapping exit in tests, 2005-08-10).
>
> Do you need a pass-through for stderr, too, or was that theoretical?

Nope, thanks. Using >&5 works.

>> @@ -290,20 +295,38 @@ test_tick () {
>>
>>  test_commit () {
>>       file=${2:-"$1.t"}
>> -     echo "${3-$1}" > "$file" &&
>> -     git add "$file" &&
>> -     test_tick &&
>> -     git commit -m "$1" &&
>> -     git tag "$1"
>> +     subtest_count=$(($subtest_count + 1))
>> +
>> +     if echo "${3-$1}" > "$file" &&
>> +             git add "$file" &&
>> +             test_tick &&
>> +             git commit -m "$1" &&
>> +             git tag "$1"
>> +     then
>> +             test_ok_ "test_commit file:<$file> message:<$1> contents<${3-$1}>"
>> +             true
>> +     else
>> +             test_failure_ "test_commit file:<$file> message:<$1> contents<${3-$1}>"
>> +             true
>> +     fi
>
> This would make the test continue after the subtest, right?  Is that
> intended?

No, should be return 0/1. Changed that in my working branch.

I'm going to drop this for a while until my pending patches to test
stuff get into pu. But initial experiments with using >&5 everywhere
for test progress are promising:

    http://github.com/avar/git/tree/test-intra-progress-using-tap-subtests-v2