Re: [PATCH v2 0/9] ci: make Git's GitHub workflow output much more helpful

On Tue, Mar 01 2022, Johannes Schindelin via GitGitGadget wrote:

Just briefly: Much of the feedback I had on v1 is still unanswered, or in the case of the performance issues I think just saying that this output is aimed at non-long-time-contributors doesn't really justify the large observed slowdowns.

I've been clicking around on the various "seen" links you posted, and while some of the output is improved it's *much* slower, to the point where I don't find those gains worth it.

For the early part of this series teaching the "ci/" this GitHub markdown that's something that's unnecessary in my alternate approach in [1]. This series is is obviously a relatively shorter way to get there, but knowing that you *can* do it in a simpler way now it's odd that the v2 doesn't discuss why getting from "A" to that "B" is still desirable with this method.

As for the later parts:

I think (and I pointed out to you before) that I really don't see why teaching the test-lib.sh N output formats when we already have a machine-readable output format with TAP *and* are in fact running code with "prove" that is parsing that output format into nicely arranged objects/structures makes sense.

So as a demo for how that can work, here's a quick POC I hacked up a while ago to use "prove" output plugins for this sort of thing.

First we intentionally break a test:

	$ git -P diff
	diff --git a/t/t0002-gitfile.sh b/t/t0002-gitfile.sh
	index 76052cb5620..f085188baf9 100755
	--- a/t/t0002-gitfile.sh
	+++ b/t/t0002-gitfile.sh
	@@ -44,7 +44,7 @@ test_expect_success 'check hash-object' '
	 
	 test_expect_success 'check cat-file' '
	        git cat-file blob $SHA >actual &&
	-       test_cmp bar actual
	+       test_cmp /dev/null actual
	 '
	 
	 test_expect_success 'check update-index' '
	@@ -67,7 +67,7 @@ test_expect_success 'check commit-tree' '
	 
	 test_expect_success 'check rev-list' '
	        git update-ref "HEAD" "$SHA" &&
	-       test "$SHA" = "$(git rev-list HEAD)"
	+       test "$SHA" = "$(xgit rev-list HEAD)"
	 '

And here's the resulting output, which is the same as the existing "prove" summary output, but then followed by nicely formatted details about just the failing tests:

	$ PERL5LIB=$PWD prove --formatter Fmt t0002-gitfile.sh :: -vx
	 
	 test_expect_success 'setup_git_dir twice in subdir' '
	t0002-gitfile.sh .. Dubious, test returned 1 (wstat 256, 0x100)
	Failed 2/14 subtests 
	
	Test Summary Report
	-------------------
	t0002-gitfile.sh (Wstat: 256 Tests: 14 Failed: 2)
	  Failed tests:  6, 10
	  Non-zero exit status: 1
	Files=1, Tests=14,  0 wallclock secs ( 0.02 usr  0.00 sys +  0.13 cusr  0.05 csys =  0.20 CPU)
	Result: FAIL
	Failed in t0002-gitfile.sh#6:
	 ==> test   => not ok 6 - check cat-file
	 ==> source => #
	 ==> source => #        git cat-file blob $SHA >actual &&
	 ==> source => #        test_cmp /dev/null actual
	 ==> source => #
	 ==> trace  => + git cat-file blob 257cc5642cb1a054f08cc83f2d943e56fd3ebe99
	 ==> trace  => + test_cmp /dev/null actual
	 ==> trace  => + test 2 -ne 2
	 ==> trace  => + eval diff -u "$@"
	 ==> trace  => + diff -u /dev/null actual
	 ==> output => --- /dev/null    2022-01-25 04:40:50.187529644 +0000
	 ==> output => +++ actual       2022-03-02 12:29:28.217960535 +0000
	 ==> output => @@ -0,0 +1 @@
	 ==> output => +foo
	 ==> output => error: last command exited with $?=1
	 ==> output => 
	Failed in t0002-gitfile.sh#10:
	 ==> test   => not ok 10 - check rev-list
	 ==> source => #
	 ==> source => #        git update-ref "HEAD" "$SHA" &&
	 ==> source => #        test "$SHA" = "$(xgit rev-list HEAD)"
	 ==> source => #
	 ==> trace  => + git update-ref HEAD f2e10ff57e8c01fe514c650d9de97e913257ba0c
	 ==> trace  => + xgit rev-list HEAD
	 ==> trace  => + test f2e10ff57e8c01fe514c650d9de97e913257ba0c = 
	 ==> output => t0002-gitfile.sh: 5: eval: xgit: not found
	 ==> output => error: last command exited with $?=1
	 ==> output => 

Now, some of that is on top of some output changes to test-lib.sh I had locally, but the "test", "source" etc. there is not a hardcoded part of the output, it's corresponding to (some of which I re-labeled, e.g. "comment" => "source") the individual object types the TAP::Parser emits.

The code to do that is below, with brief (unindented) comments:

	package Git::TAP::Formatter::Session;
	use v5.18.2;
	use strict;
	use warnings;
	use base 'TAP::Formatter::Console::ParallelSession';
	
	our %STATE;
	sub result {
		my $self = shift;
		my $result = shift;

So here we just have the TAP object for the current tests (as in "ok",
"not ok" etc.), and save all of those away (both for successful and
non-successful) tests in %STATE for later:
	
		my $res = $self->SUPER::result($result);
		my $test_name = $self->name;
	
		# An AoO of test numbers and their output lines
		$STATE{$test_name} ||= [{lines => []}];
	
		push @{$STATE{$test_name}->[-1]->{lines}} => $result;
	
		# When we see a new test add a new AoA for its output. We do
		# end up with the "plan" type as part of the last test, and
		# might want to split it up
		if ($result->type eq 'test') {
			push @{$STATE{$test_name}} => {};
		}
	
		return $res;
	}

This "Fmt" package is a "prove" plugin. It's just hooking into the code that emits the current summary, now it just shows the "Test Summary Report" that your CL notes issues with, but this shows how easy it is to change or amend it (you can override another accessor here to fully suppress the current output, I just didn't do that):

	package Fmt;
	use strict;
	use warnings;
	use List::MoreUtils qw(firstidx);
	use base 'TAP::Formatter::Console';
	
	sub open_test {
		my $self = shift;
	
		my $session = $self->SUPER::open_test(@_);
		use Data::Dumper;
		#warn "session is = " . Dumper $session;
		return bless $session => 'Git::TAP::Formatter::Session';
	}
	
	sub summary {
		my $self = shift;
		$self->SUPER::summary(@_);
	
		## This state machine needs to go past the "ok" line and grab
		## the comments emitted by e.g. "say_color_tap_comment_lines" in
		## test_ok_()
		for my $test (sort keys %STATE) {
			for (my $i = 1; $i <= $#{$STATE{$test}}; $i++) {
				my @lines = @{$STATE{$test}->[$i]->{lines}};
				my $break = firstidx { $_->raw eq '' } @lines;
				my @source = splice @lines, 0, $break;
	
				splice @lines, 0, 1; # Splice out the '' item
				push @{$STATE{$test}->[$i - 1]->{lines}} => @source;
	
				$STATE{$test}->[$i]->{lines} = \@lines;
	
				# Since we parsed out the source already,
				# let's make it easily machine-readable, and
				# parse the rest.
				$STATE{$test}->[$i]->{source} = \@source;
				my @trace = map { $_->{is_trace} = 1 } grep { $_->raw =~ /^\+ / } @lines;
				$STATE{$test}->[$i]->{trace} = \@trace if @trace;
			}
		}
	
		my $aggregator = $_[0];
		for my $failed ($aggregator->failed) {
			my ($parser) = $aggregator->parsers($failed);
			for my $i ($parser->failed) {
				my $idx = $i - 1;
				my @lines = @{$STATE{$failed}->[$idx]->{lines}};
				my ($test) = grep { $_->is_test } @lines;
	
				say "Failed in $failed#$i:";
				say join "\n", map {
					s/^/ ==> /gr;
				} map {
					sprintf("%-6s => %s",
					     $_->{is_trace} ? "trace" :
					     $_->is_unknown ? "output" :
					     $_->is_comment ? "source" :
					     $_->type,
					     $_->raw,
				     );
				} sort {
					# the "is_trace" may be undef
					no warnings qw(uninitialized);
					# The "[not ]ok" line first...
					$b->is_test <=> $a->is_test ||
					# Then "comment" (i.e. test source)
					$b->is_comment <=> $a->is_comment ||
					# Then the "+ " trace of execution
					$b->{is_trace} <=> $a->{is_trace}
				} @lines;
			}
		}
	}
	
	1;

1. https://lore.kernel.org/git/cover-00.25-00000000000-20220221T143936Z-avarab@gmail.com/
2. https://lore.kernel.org/git/220222.86y2236ndp.gmgdl@evledraar.gmail.com/