[PATCH] test-lib-functions: show the test name at the start of verbose output

[PATCH] test-lib-functions: show the test name at the start of verbose output

[SZEDER Gábor]

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(-)

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"
-- 
2.23.0.rc1.309.g896d8c5f5f

Re: [PATCH] test-lib-functions: show the test name at the start of verbose output

[Johannes Schindelin]

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

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

Re: [PATCH] test-lib-functions: show the test name at the start of verbose output

[SZEDER Gábor]

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?

Re: [PATCH] test-lib-functions: show the test name at the start of verbose output

[Johannes Schindelin]

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

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 v2 0/2] tests: show the test name and number at the start of verbose output

[SZEDER Gábor]

Include the test script number, test number, and the test name at the
start of the verbose output of each test, to help navigating the
tests' logs.

Changes since v1:

  - Include not only the test name, but the test script number and
    test number as well.

  - An additional small adjustment was necessary to 't0000-basic.sh',
    which I thought is better as a separate preparatory patch, to ease
    review a bit.

SZEDER Gábor (2):
  t0000-basic: use realistic test script names in the verbose tests
  tests: show the test name and number at the start of verbose output

 t/t0000-basic.sh        | 20 ++++++++++----------
 t/test-lib-functions.sh |  4 ++--
 t/test-lib.sh           |  2 ++
 3 files changed, 14 insertions(+), 12 deletions(-)

-- 
2.23.0.rc1.309.g896d8c5f5f

[PATCH v2 1/2] t0000-basic: use realistic test script names in the verbose tests

[SZEDER Gábor]

Our test scripts are named something like 't1234-command.sh', but the
script names used in 't0000-basic.sh' don't follow this naming
convention.  Normally this doesn't matter, because the test scripts
themselves don't care how they are called.  However, the next patch
will start to include the test number in the test's verbose output, so
the test script's name will matter in the two tests checking the
verbose output.

Update the tests 'test --verbose' and 'test --verbose-only' to follow
out test script naming convention.

Leave the other tests in 't0000' unchanged: changing the names of
their test scripts would be only pointless code churn.

Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>
---
 t/t0000-basic.sh | 12 ++++++------
 1 file changed, 6 insertions(+), 6 deletions(-)

diff --git a/t/t0000-basic.sh b/t/t0000-basic.sh
index e89438e619..d2b3dde89e 100755
--- a/t/t0000-basic.sh
+++ b/t/t0000-basic.sh
@@ -276,15 +276,15 @@ test_expect_success 'pretend we have a mix of all possible results' "
 
 test_expect_success C_LOCALE_OUTPUT 'test --verbose' '
 	test_must_fail run_sub_test_lib_test \
-		test-verbose "test verbose" --verbose <<-\EOF &&
+		t1234-verbose "test verbose" --verbose <<-\EOF &&
 	test_expect_success "passing test" true
 	test_expect_success "test with output" "echo foo"
 	test_expect_success "failing test" false
 	test_done
 	EOF
-	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
+	mv t1234-verbose/out t1234-verbose/out+ &&
+	grep -v "^Initialized empty" t1234-verbose/out+ >t1234-verbose/out &&
+	check_sub_test_lib_test t1234-verbose <<-\EOF
 	> expecting success: true
 	> ok 1 - passing test
 	> Z
@@ -303,14 +303,14 @@ test_expect_success C_LOCALE_OUTPUT 'test --verbose' '
 
 test_expect_success 'test --verbose-only' '
 	test_must_fail run_sub_test_lib_test \
-		test-verbose-only-2 "test verbose-only=2" \
+		t2345-verbose-only-2 "test verbose-only=2" \
 		--verbose-only=2 <<-\EOF &&
 	test_expect_success "passing test" true
 	test_expect_success "test with output" "echo foo"
 	test_expect_success "failing test" false
 	test_done
 	EOF
-	check_sub_test_lib_test test-verbose-only-2 <<-\EOF
+	check_sub_test_lib_test t2345-verbose-only-2 <<-\EOF
 	> ok 1 - passing test
 	> Z
 	> expecting success: echo foo
-- 
2.23.0.rc1.309.g896d8c5f5f

[PATCH v2 2/2] tests: show the test name and number at the start of verbose output

[SZEDER Gábor]

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.  Also print the test script and test case numbers, to help
those poor souls who regularly have to scan through the combined
verbose output of several test scripts.

So the dummy test above would start like this:

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

Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>
---
 t/t0000-basic.sh        | 8 ++++----
 t/test-lib-functions.sh | 4 ++--
 t/test-lib.sh           | 2 ++
 3 files changed, 8 insertions(+), 6 deletions(-)

diff --git a/t/t0000-basic.sh b/t/t0000-basic.sh
index d2b3dde89e..360eae5348 100755
--- a/t/t0000-basic.sh
+++ b/t/t0000-basic.sh
@@ -285,14 +285,14 @@ test_expect_success C_LOCALE_OUTPUT 'test --verbose' '
 	mv t1234-verbose/out t1234-verbose/out+ &&
 	grep -v "^Initialized empty" t1234-verbose/out+ >t1234-verbose/out &&
 	check_sub_test_lib_test t1234-verbose <<-\EOF
-	> expecting success: true
+	> expecting success of 1234.1 '\''passing test'\'': true
 	> ok 1 - passing test
 	> Z
-	> expecting success: echo foo
+	> expecting success of 1234.2 '\''test with output'\'': echo foo
 	> foo
 	> ok 2 - test with output
 	> Z
-	> expecting success: false
+	> expecting success of 1234.3 '\''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 t2345-verbose-only-2 <<-\EOF
 	> ok 1 - passing test
 	> Z
-	> expecting success: echo foo
+	> expecting success of 2345.2 '\''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..a3d06899e2 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 $TEST_NUMBER.$test_count '$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 $TEST_NUMBER.$test_count '$1': $2"
 		if test_run_ "$2"
 		then
 			test_ok_ "$1"
diff --git a/t/test-lib.sh b/t/test-lib.sh
index 30b07e310f..a9d45642a5 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -212,6 +212,8 @@ fi
 
 TEST_STRESS_JOB_SFX="${GIT_TEST_STRESS_JOB_NR:+.stress-$GIT_TEST_STRESS_JOB_NR}"
 TEST_NAME="$(basename "$0" .sh)"
+TEST_NUMBER="${TEST_NAME%%-*}"
+TEST_NUMBER="${TEST_NUMBER#t}"
 TEST_RESULTS_DIR="$TEST_OUTPUT_DIRECTORY/test-results"
 TEST_RESULTS_BASE="$TEST_RESULTS_DIR/$TEST_NAME$TEST_STRESS_JOB_SFX"
 TRASH_DIRECTORY="trash directory.$TEST_NAME$TEST_STRESS_JOB_SFX"
-- 
2.23.0.rc1.309.g896d8c5f5f

Re: [PATCH v2 0/2] tests: show the test name and number at the start of verbose output

[Johannes Schindelin]

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

Hi Gábor,

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

> Include the test script number, test number, and the test name at the
> start of the verbose output of each test, to help navigating the
> tests' logs.
>
> Changes since v1:
>
>   - Include not only the test name, but the test script number and
>     test number as well.
>
>   - An additional small adjustment was necessary to 't0000-basic.sh',
>     which I thought is better as a separate preparatory patch, to ease
>     review a bit.

Looks good to me!

Thanks,
Dscho

>
> SZEDER Gábor (2):
>   t0000-basic: use realistic test script names in the verbose tests
>   tests: show the test name and number at the start of verbose output
>
>  t/t0000-basic.sh        | 20 ++++++++++----------
>  t/test-lib-functions.sh |  4 ++--
>  t/test-lib.sh           |  2 ++
>  3 files changed, 14 insertions(+), 12 deletions(-)
>
> --
> 2.23.0.rc1.309.g896d8c5f5f
>
>

Re: [PATCH v2 0/2] tests: show the test name and number at the start of verbose output

[Junio C Hamano]

Johannes Schindelin <Johannes.Schindelin@gmx.de> writes:

> On Mon, 5 Aug 2019, SZEDER Gábor wrote:
>
>> Include the test script number, test number, and the test name at the
>> start of the verbose output of each test, to help navigating the
>> tests' logs.
>> ...
>
> Looks good to me!

Thanks, both.