threads / patch / 51580

patchtest-lib-functions: show the test name at the start of verbose output

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

## tl;dr

9 messages between Aug 3, 2019 and Aug 8, 2019. Diffs are folded; open one to read it.

replies: 8people: 3as markdown or json

SZEDER Gábor· Aug 3, 2019, 08:01 UTC · lore
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(-)
Show changes to 2 files +6 −6

t/t0000-basic.sh, t/test-lib-functions.sh

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
Johannes Schindelin· Aug 4, 2019, 19:14 UTC · re: SZEDER Gábor · lore

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

Hi,
On Sat, 3 Aug 2019, SZEDER Gábor wrote:
Show 5 quoted lines
> 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 UTC · re: Johannes Schindelin · lore

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

On Sun, Aug 04, 2019 at 09:14:46PM +0200, Johannes Schindelin wrote:
Show 14 quoted lines
> 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 UTC · re: SZEDER Gábor · lore

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

Hi Gábor,
On Mon, 5 Aug 2019, SZEDER Gábor wrote:
Show 28 quoted lines
> 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

SZEDER Gábor· Aug 5, 2019, 21:04 UTC · re: SZEDER Gábor · lore

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

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
SZEDER Gábor· Aug 5, 2019, 21:04 UTC · re: SZEDER Gábor · lore

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

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(-)
Show changes to 3 files +8 −6

t/t0000-basic.sh, t/test-lib-functions.sh, t/test-lib.sh

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
SZEDER Gábor· Aug 5, 2019, 21:04 UTC · re: SZEDER Gábor · lore

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

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(-)
Show changes to t/t0000-basic.sh +6 −6
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
Johannes Schindelin· Aug 8, 2019, 20:12 UTC · re: SZEDER Gábor · lore

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

Hi Gábor,
On Mon, 5 Aug 2019, SZEDER Gábor wrote:
Show 12 quoted lines
> 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

Show 14 quoted lines
>
> 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
>
>
Junio C Hamano· Aug 8, 2019, 22:09 UTC · re: Johannes Schindelin · lore

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

Johannes Schindelin <Johannes.Schindelin@gmx.de> writes:
Show 8 quoted lines
> 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.

← back to recent threads