test-lib-functions: show the test name at the start of verbose output
diff mbox series

Message ID 20190803080126.29488-1-szeder.dev@gmail.com
State New
Headers show
Series
  • test-lib-functions: show the test name at the start of verbose output
Related show

Commit Message

SZEDER Gábor Aug. 3, 2019, 8:01 a.m. UTC
The verbose output of every test looks something like this:

  expecting success:
          echo content >file &&
          git add file &&
          git commit -m "add file"

  [master (root-commit) d1fbfbd] add file
   Author: A U Thor <author@example.com>
   1 file changed, 1 insertion(+)
   create mode 100644 file
  ok 1 - commit works

i.e. first an "expecting success" (or "checking known breakage") line
followed by the commands to be executed, then the output of those
comamnds, and finally an "ok"/"not ok" line containing the test name.
Note that the test's name is only shown at the very end.

With '-x' tracing enabled and/or in longer tests the verbose output
might be several screenfulls long, making it harder than necessary to
find where the output of the test with a given name starts (especially
when the outputs to different file descriptors are racing, and the
"expecting success"/command block arrives earlier than the "ok" line
of the previous test).

Print the test name at the start of the test's verbose output, i.e. at
the end of the "expecting success" and "checking known breakage"
lines, to make the start of a particular test a bit easier to
recognize.

So the dummy test above would start like this:

  expecting success of 'commit works':
          echo content >file &&
  [...]

Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>
---

I remember being annoyed by this every once in a while for years, and
https://public-inbox.org/git/20190802100956.GV20404@szeder.dev/
reminded me again to finally do something about it.

 t/t0000-basic.sh        | 8 ++++----
 t/test-lib-functions.sh | 4 ++--
 2 files changed, 6 insertions(+), 6 deletions(-)

Comments

Johannes Schindelin Aug. 4, 2019, 7:14 p.m. UTC | #1
Hi,

On Sat, 3 Aug 2019, SZEDER Gábor wrote:

> So the dummy test above would start like this:
>
>   expecting success of 'commit works':
>           echo content >file &&
>   [...]

Maybe it would make sense to also mention the test and test case number,
like so?

	expecting success of t9876.54 'it works':

Ciao,
Dscho
SZEDER Gábor Aug. 5, 2019, 10:12 a.m. UTC | #2
On Sun, Aug 04, 2019 at 09:14:46PM +0200, Johannes Schindelin wrote:
> Hi,
> 
> On Sat, 3 Aug 2019, SZEDER Gábor wrote:
> 
> > So the dummy test above would start like this:
> >
> >   expecting success of 'commit works':
> >           echo content >file &&
> >   [...]
> 
> Maybe it would make sense to also mention the test and test case number,
> like so?
> 
> 	expecting success of t9876.54 'it works':

It's easy enough to do so, but I don't readily see any benefits.

The '--verbose-log' of each test script is written to a separate
file, whose name already contains the test number, so there is no use
including it for each test case in there.  When running a test script
and looking at its '--verbose' output, then surely all test numbers
must be from that particular test script, so there is no use, either.

As for the test case number, since the test cases are not numbered in
the test scripts, I just ignore them right away, and look for test
names anyway.

Could you give an example?
Johannes Schindelin Aug. 5, 2019, 11:32 a.m. UTC | #3
Hi Gábor,

On Mon, 5 Aug 2019, SZEDER Gábor wrote:

> On Sun, Aug 04, 2019 at 09:14:46PM +0200, Johannes Schindelin wrote:
> >
> > On Sat, 3 Aug 2019, SZEDER Gábor wrote:
> >
> > > So the dummy test above would start like this:
> > >
> > >   expecting success of 'commit works':
> > >           echo content >file &&
> > >   [...]
> >
> > Maybe it would make sense to also mention the test and test case number,
> > like so?
> >
> > 	expecting success of t9876.54 'it works':
>
> It's easy enough to do so, but I don't readily see any benefits.
>
> The '--verbose-log' of each test script is written to a separate
> file, whose name already contains the test number, so there is no use
> including it for each test case in there.  When running a test script
> and looking at its '--verbose' output, then surely all test numbers
> must be from that particular test script, so there is no use, either.
>
> As for the test case number, since the test cases are not numbered in
> the test scripts, I just ignore them right away, and look for test
> names anyway.
>
> Could you give an example?

Oh, my common way to read test logs is to sift through CI builds' logs,
in particular for the branches on https://github.com/gitster/git that
are based on commits without support for the convenient Tests tab in
Azure Pipelines.

So I hit Ctrl+F and look for `not ok` in literally hundreds/thousands of
lines. Of course, this is already the unrolled log _only_ of the failed
test scripts. Still, it is no fun to scoll back from test case 64 all
the way to 1 just to find out which test script contains this particular
failed test case.

Ciao,
Dscho

Patch
diff mbox series

diff --git a/t/t0000-basic.sh b/t/t0000-basic.sh
index e89438e619..6bd21aacab 100755
--- a/t/t0000-basic.sh
+++ b/t/t0000-basic.sh
@@ -285,14 +285,14 @@  test_expect_success C_LOCALE_OUTPUT 'test --verbose' '
 	mv test-verbose/out test-verbose/out+ &&
 	grep -v "^Initialized empty" test-verbose/out+ >test-verbose/out &&
 	check_sub_test_lib_test test-verbose <<-\EOF
-	> expecting success: true
+	> expecting success of '\''passing test'\'': true
 	> ok 1 - passing test
 	> Z
-	> expecting success: echo foo
+	> expecting success of '\''test with output'\'': echo foo
 	> foo
 	> ok 2 - test with output
 	> Z
-	> expecting success: false
+	> expecting success of '\''failing test'\'': false
 	> not ok 3 - failing test
 	> #	false
 	> Z
@@ -313,7 +313,7 @@  test_expect_success 'test --verbose-only' '
 	check_sub_test_lib_test test-verbose-only-2 <<-\EOF
 	> ok 1 - passing test
 	> Z
-	> expecting success: echo foo
+	> expecting success of '\''test with output'\'': echo foo
 	> foo
 	> ok 2 - test with output
 	> Z
diff --git a/t/test-lib-functions.sh b/t/test-lib-functions.sh
index d4f199391f..165e1e51c7 100644
--- a/t/test-lib-functions.sh
+++ b/t/test-lib-functions.sh
@@ -580,7 +580,7 @@  test_expect_failure () {
 	export test_prereq
 	if ! test_skip "$@"
 	then
-		say >&3 "checking known breakage: $2"
+		say >&3 "checking known breakage of '$1': $2"
 		if test_run_ "$2" expecting_failure
 		then
 			test_known_broken_ok_ "$1"
@@ -600,7 +600,7 @@  test_expect_success () {
 	export test_prereq
 	if ! test_skip "$@"
 	then
-		say >&3 "expecting success: $2"
+		say >&3 "expecting success of '$1': $2"
 		if test_run_ "$2"
 		then
 			test_ok_ "$1"