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

[Johannes Schindelin <Johannes.Schindelin@gmx.de>]

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

Hi Victoria,

[sorry for the long delay, I was being pulled into too many directions,
but am incredibly grateful for your fantastic investigation.]

On Thu, 24 Mar 2022, Victoria Dye wrote:

> Johannes Schindelin via GitGitGadget wrote:
> > Changes since v1:
> >
> >  * In the patch that removed MAKE_TARGETS, a stale comment about that
> >    variable is also removed.
> >  * The comment about set -x has been adjusted because it no longer applies
> >    as-is.
> >  * The commit message of "ci: make it easier to find failed tests' logs in
> >    the GitHub workflow" has been adjusted to motivate the improvement
> >    better.
> >
> >
> > Background
> > ==========
> >
> > Recent patches intended to help readers figure out CI failures much quicker
> > than before. Unfortunately, they haven't been entirely positive for me. For
> > example, they broke the branch protections in Microsoft's fork of Git, where
> > we require Pull Requests to pass a certain set of Checks (which are
> > identified by their names) and therefore caused follow-up work.
> >
> > Using CI and in general making it easier for new contributors is an area I'm
> > passionate about, and one I'd like to see improved.
> >
> >
> > The current situation
> > =====================
> >
> > Let me walk you through the current experience when a PR build fails: I get
> > a notification mail that only says that a certain job failed. There's no
> > indication of which test failed (or was it the build?). I can click on a
> > link at it takes me to the workflow run. Once there, all it says is "Process
> > completed with exit code 1", or even "code 2". Sure, I can click on one of
> > the failed jobs. It even expands the failed step's log (collapsing the other
> > steps). And what do I see there?
> >
> > Let's look at an example of a failed linux-clang (ubuntu-latest) job
> > [https://github.com/git-for-windows/git/runs/4822802185?check_suite_focus=true]:
> >
> > [...]
> > Test Summary Report
> > -------------------
> > t1092-sparse-checkout-compatibility.sh           (Wstat: 256 Tests: 53 Failed: 1)
> >   Failed test:  49
> >   Non-zero exit status: 1
> > t3701-add-interactive.sh                         (Wstat: 0 Tests: 71 Failed: 0)
> >   TODO passed:   45, 47
> > Files=957, Tests=25489, 645 wallclock secs ( 5.74 usr  1.56 sys + 866.28 cusr 364.34 csys = 1237.92 CPU)
> > Result: FAIL
> > make[1]: *** [Makefile:53: prove] Error 1
> > make[1]: Leaving directory '/home/runner/work/git/git/t'
> > make: *** [Makefile:3018: test] Error 2
> >
> >
> > That's it. I count myself lucky not to be a new contributor being faced with
> > something like this.
> >
> > Now, since I am active in the Git project for a couple of days or so, I can
> > make sense of the "TODO passed" label and know that for the purpose of
> > fixing the build failures, I need to ignore this, and that I need to focus
> > on the "Failed test" part instead.
> >
> > I also know that I do not have to get myself an ubuntu-latest box just to
> > reproduce the error, I do not even have to check out the code and run it
> > just to learn what that "49" means.
> >
> > I know, and I do not expect any new contributor, not even most seasoned
> > contributors to know, that I have to patiently collapse the "Run
> > ci/run-build-and-tests.sh" job's log, and instead expand the "Run
> > ci/print-test-failures.sh" job log (which did not fail and hence does not
> > draw any attention to it).
> >
>
> You can count me as one of the ones that, until this series, had no idea
> this information existed in the CI logs. And it definitely would have been
> helpful in figuring out some of the OS-specific bugs I've run into in the
> past. :)

Excellent. I think I have enough accounts to consider it a universal truth
that our CI output _needs_ something like this here patch series.

> > I know, and again: I do not expect many others to know this, that I then
> > have to click into the "Search logs" box (not the regular web browser's
> > search via Ctrl+F!) and type in "not ok" to find the log of the failed test
> > case (and this might still be a "known broken" one that is marked via
> > test_expect_failure and once again needs to be ignored).
> >
> > To be excessively clear: This is not a great experience!
> >
> >
> > Improved output
> > ===============
> >
> > Our previous Azure Pipelines-based CI builds had a much nicer UI, one that
> > even showed flaky tests, and trends e.g. how long the test cases ran. When I
> > ported Git's CI over to GitHub workflows (to make CI more accessible to new
> > contributors), I knew fully well that we would leave this very nice UI
> > behind, and I had hoped that we would get something similar back via new,
> > community-contributed GitHub Actions that can be used in GitHub workflows.
> > However, most likely because we use a home-grown test framework implemented
> > in opinionated POSIX shells scripts, that did not happen.
> >
> > So I had a look at what standards exist e.g. when testing PowerShell
> > modules, in the way of marking up their test output in GitHub workflows, and
> > I was not disappointed: GitHub workflows support "grouping" of output lines,
> > i.e. marking sections of the output as a group that is then collapsed by
> > default and can be expanded. And it is this feature I decided to use in this
> > patch series, along with GitHub workflows' commands to display errors or
> > notices that are also shown on the summary page of the workflow run. Now, in
> > addition to "Process completed with exit code" on the summary page, we also
> > read something like:
> >
> > ⊗ linux-gcc (ubuntu-latest)
> >    failed: t9800.20 submit from detached head
> >
> >
> > Even better, this message is a link, and following that, the reader is
> > presented with something like this
> > [https://github.com/dscho/git/runs/4840190622?check_suite_focus=true]:
> >
> > ⏵ Run ci/run-build-and-tests.sh
> > ⏵ CI setup
> >   + ln -s /home/runner/none/.prove t/.prove
> >   + run_tests=t
> >   + export GIT_TEST_DEFAULT_INITIAL_BRANCH_NAME=main
> >   + group Build make
> >   + set +x
> > ⏵ Build
> > ⏵ Run tests
> >   === Failed test: t9800-git-p4-basic ===
> > ⏵ ok: t9800.1 start p4d
> > ⏵ ok: t9800.2 add p4 files
> > ⏵ ok: t9800.3 basic git p4 clone
> > ⏵ ok: t9800.4 depot typo error
> > ⏵ ok: t9800.5 git p4 clone @all
> > ⏵ ok: t9800.6 git p4 sync uninitialized repo
> > ⏵ ok: t9800.7 git p4 sync new branch
> > ⏵ ok: t9800.8 clone two dirs
> > ⏵ ok: t9800.9 clone two dirs, @all
> > ⏵ ok: t9800.10 clone two dirs, @all, conflicting files
> > ⏵ ok: t9800.11 clone two dirs, each edited by submit, single git commit
> > ⏵ ok: t9800.12 clone using non-numeric revision ranges
> > ⏵ ok: t9800.13 clone with date range, excluding some changes
> > ⏵ ok: t9800.14 exit when p4 fails to produce marshaled output
> > ⏵ ok: t9800.15 exit gracefully for p4 server errors
> > ⏵ ok: t9800.16 clone --bare should make a bare repository
> > ⏵ ok: t9800.17 initial import time from top change time
> > ⏵ ok: t9800.18 unresolvable host in P4PORT should display error
> > ⏵ ok: t9800.19 run hook p4-pre-submit before submit
> >   Error: failed: t9800.20 submit from detached head
> > ⏵ failure: t9800.20 submit from detached head
> >   Error: failed: t9800.21 submit from worktree
> > ⏵ failure: t9800.21 submit from worktree
> >   === Failed test: t9801-git-p4-branch ===
> >   [...]
> >
> >
> > The "Failed test:" lines are colored in yellow to give a better visual clue
> > about the logs' structure, the "Error:" label is colored in red to draw the
> > attention to the important part of the log, and the "⏵" characters indicate
> > that part of the log is collapsed and can be expanded by clicking on it.
> >
> > To drill down, the reader merely needs to expand the (failed) test case's
> > log by clicking on it, and then study the log. If needed (e.g. when the test
> > case relies on side effects from previous test cases), the logs of preceding
> > test cases can be expanded as well. In this example, when expanding
> > t9800.20, it looks like this (for ease of reading, I cut a few chunks of
> > lines, indicated by "[...]"):
> >
> > [...]
> > ⏵ ok: t9800.19 run hook p4-pre-submit before submit
> >   Error: failed: t9800.20 submit from detached head
> > ⏷ failure: t9800.20 submit from detached head
> >       test_when_finished cleanup_git &&
> >       git p4 clone --dest="$git" //depot &&
> >         (
> >           cd "$git" &&
> >           git checkout p4/master &&
> >           >detached_head_test &&
> >           git add detached_head_test &&
> >           git commit -m "add detached_head" &&
> >           git config git-p4.skipSubmitEdit true &&
> >           git p4 submit &&
> >             git p4 rebase &&
> >             git log p4/master | grep detached_head
> >         )
> >     [...]
> >     Depot paths: //depot/
> >     Import destination: refs/remotes/p4/master
> >
> >     Importing revision 9 (100%)Perforce db files in '.' will be created if missing...
> >     Perforce db files in '.' will be created if missing...
> >
> >     Traceback (most recent call last):
> >       File "/home/runner/work/git/git/git-p4", line 4455, in <module>
> >         main()
> >       File "/home/runner/work/git/git/git-p4", line 4449, in main
> >         if not cmd.run(args):
> >       File "/home/runner/work/git/git/git-p4", line 2590, in run
> >         rebase.rebase()
> >       File "/home/runner/work/git/git/git-p4", line 4121, in rebase
> >         if len(read_pipe("git diff-index HEAD --")) > 0:
> >       File "/home/runner/work/git/git/git-p4", line 297, in read_pipe
> >         retcode, out, err = read_pipe_full(c, *k, **kw)
> >       File "/home/runner/work/git/git/git-p4", line 284, in read_pipe_full
> >         p = subprocess.Popen(
> >       File "/usr/lib/python3.8/subprocess.py", line 858, in __init__
> >         self._execute_child(args, executable, preexec_fn, close_fds,
> >       File "/usr/lib/python3.8/subprocess.py", line 1704, in _execute_child
> >         raise child_exception_type(errno_num, err_msg, err_filename)
> >     FileNotFoundError: [Errno 2] No such file or directory: 'git diff-index HEAD --'
> >     error: last command exited with $?=1
> >     + cleanup_git
> >     + retry_until_success rm -r /home/runner/work/git/git/t/trash directory.t9800-git-p4-basic/git
> >     + nr_tries_left=60
> >     + rm -r /home/runner/work/git/git/t/trash directory.t9800-git-p4-basic/git
> >     + test_path_is_missing /home/runner/work/git/git/t/trash directory.t9800-git-p4-basic/git
> >     + test 1 -ne 1
> >     + test -e /home/runner/work/git/git/t/trash directory.t9800-git-p4-basic/git
> >     + retry_until_success mkdir /home/runner/work/git/git/t/trash directory.t9800-git-p4-basic/git
> >     + nr_tries_left=60
> >     + mkdir /home/runner/work/git/git/t/trash directory.t9800-git-p4-basic/git
> >     + exit 1
> >     + eval_ret=1
> >     + :
> >     not ok 20 - submit from detached head
> >     #
> >     #        test_when_finished cleanup_git &&
> >     #        git p4 clone --dest="$git" //depot &&
> >     #        (
> >     #            cd "$git" &&
> >     #            git checkout p4/master &&
> >     #            >detached_head_test &&
> >     #            git add detached_head_test &&
> >     #            git commit -m "add detached_head" &&
> >     #            git config git-p4.skipSubmitEdit true &&
> >     #            git p4 submit &&
> >     #            git p4 rebase &&
> >     #            git log p4/master | grep detached_head
> >     #        )
> >     #
> >   Error: failed: t9800.21 submit from worktree
> >   [...]
> >
> >
> > Is this the best UI we can have for test failures in CI runs? I hope we can
> > do better. Having said that, this patch series presents a pretty good start,
> > and offers a basis for future improvements.
> >
>
> I think these are really valuable improvements over our current state, but I
> also understand the concerns about performance elsewhere in this thread
> (it's really slow to load for me as well, and scrolling/expanding the log
> groups can be a bit glitchy in my browser). That said, I think there are a
> couple ways you could improve the load time without sacrificing the (very
> helpful) improvements you've made to error log visibility. I experimented a
> bit (example result [1]) and came up with some things that may help:
>
> * group errors by test file, rather than by test case (to reduce
>   parsing/rendering time for lots of groups).

I really would like to avoid that, based on my past experience with
diagnosing test failures. It is definitely helpful if the structure lets
the reader expand individual test cases.

> * print the verbose logs only for the failed test cases (to massively cut
>   down on the size of the log, particularly when there's only a couple
>   failures in a test file with a lot of passing tests).

That's an amazingly simple trick to improve the speed by a ton, indeed.
Thank you for this splendid idea!

> * skip printing the full text of the test in 'finalize_test_case_output'
>   when creating the group, i.e., use '$1' instead of '$*' (in both passing
>   and failing tests, this information is already printed via some other
>   means).
>
> If you wanted to make sure a user could still access the full failure logs
> (i.e., including the "ok" test results), you could print a link to the
> artifacts page as well - that way, all of the information we currently
> provide to users can still be found somewhere.

That's a good point, I added that hint to the output (the link is
unfortunately not available at the time we print that advice).

>
> [1] https://github.com/vdye/git/runs/5666973267
>
> > Johannes Schindelin (9):
> >   ci: fix code style
> >   ci/run-build-and-tests: take a more high-level view
> >   ci: make it easier to find failed tests' logs in the GitHub workflow
> >   ci/run-build-and-tests: add some structure to the GitHub workflow
> >     output
> >   tests: refactor --write-junit-xml code
> >   test(junit): avoid line feeds in XML attributes
> >   ci: optionally mark up output in the GitHub workflow
> >   ci: use `--github-workflow-markup` in the GitHub workflow
> >   ci: call `finalize_test_case_output` a little later
> >
>
> The organization of these commits makes the series a bit confusing to read,
> mainly due to the JUnit changes in the middle. Patches 5-6 don't appear to
> be dependent on patches 1-4, so they could be moved to the beginning (after
> patch 1). With that change, I think this series would flow more smoothly:
> "Cleanup/non-functional change" -> "JUnit XML improvements" -> "Log UX
> improvements".

Great feedback! I changed the order as suggested.

Again, thank you so much for helping me improve the user experience of
Git's CI/PR builds.

Ciao,
Dscho