[PATCH] tests: send "bug in the test script" errors to the script's stderr

[PATCH] tests: send "bug in the test script" errors to the script's stderr

[SZEDER Gábor]

Some of the functions in our test library check that they were invoked
properly with conditions like this:

  test "$#" = 2 ||
  error "bug in the test script: not 2 parameters to test-expect-success"

If this particular condition is triggered, then 'error' will abort the
whole test script with a bold red error message [1] right away.

However, under certain circumstances the test script will be aborted
completely silently, namely if:

  - a similar condition in a test helper function like
    'test_line_count' is triggered,
  - which is invoked from the test script's "main" shell [2],
  - and the test script is run manually (i.e. './t1234-foo.sh' as
    opposed to 'make t1234-foo.sh' or 'make test') [3]
  - and without the '--verbose' option,

because the error message is printed from within 'test_eval_', where
standard output is redirected either to /dev/null or to a log file.
The only indication that something is wrong is that not all tests in
the script are executed and at the end of the test script's output
there is no "# passed all N tests" message, which are subtle and can
easily go unnoticed, as I had to experience myself.

Send these "bug in the test script" error messages directly to the
test scripts standard error and thus to the terminal, so those bugs
will be much harder to overlook.  Instead of updating all ~20 such
'error' calls with a redirection, let's add a BUG() function to
'test-lib.sh', wrapping an 'error' call with the proper redirection
and also including the common prefix of those error messages, and
convert all those call sites [4] to use this new BUG() function
instead.

[1] That particular error message from 'test_expect_success' is
    printed in color only when running with or without '--verbose';
    with '--tee' or '--verbose-log' the error is printed without
    color, but it is printed to the terminal nonetheless.

[2] If such a condition is triggered in a subshell of a test, then
    'error' won't be able to abort the whole test script, but only the
    subshell, which in turn causes the test to fail in the usual way,
    indicating loudly and clearly that something is wrong.

[3] Well, 'error' aborts the test script the same way when run
    manually or by 'make' or 'prove', but both 'make' and 'prove' pay
    attention to the test script's exit status, and even a silently
    aborted test script would then trigger those tools' usual
    noticable error messages.

[4] Strictly speaking, not all those 'error' calls need that
    redirection to send their output to the terminal, see e.g.
    'test_expect_success' in the opening example, but I think it's
    better to be consistent.

Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>
---
 t/perf/perf-lib.sh      |  4 ++--
 t/t0001-init.sh         |  4 ++--
 t/t4013-diff-various.sh |  2 +-
 t/t5516-fetch-push.sh   |  2 +-
 t/t9902-completion.sh   |  2 +-
 t/test-lib-functions.sh | 25 ++++++++++++-------------
 t/test-lib.sh           | 10 +++++++---
 7 files changed, 26 insertions(+), 23 deletions(-)

diff --git a/t/perf/perf-lib.sh b/t/perf/perf-lib.sh
index 11d1922cf5..2e33ab3ec3 100644
--- a/t/perf/perf-lib.sh
+++ b/t/perf/perf-lib.sh
@@ -82,7 +82,7 @@ test_perf_do_repo_symlink_config_ () {
 
 test_perf_create_repo_from () {
 	test "$#" = 2 ||
-	error "bug in the test script: not 2 parameters to test-create-repo"
+	BUG "not 2 parameters to test-create-repo"
 	repo="$1"
 	source="$2"
 	source_git="$("$MODERN_GIT" -C "$source" rev-parse --git-dir)"
@@ -184,7 +184,7 @@ test_wrapper_ () {
 	test_start_
 	test "$#" = 3 && { test_prereq=$1; shift; } || test_prereq=
 	test "$#" = 2 ||
-	error "bug in the test script: not 2 or 3 parameters to test-expect-success"
+	BUG "not 2 or 3 parameters to test-expect-success"
 	export test_prereq
 	if ! test_skip "$@"
 	then
diff --git a/t/t0001-init.sh b/t/t0001-init.sh
index 182da069f1..42a263cada 100755
--- a/t/t0001-init.sh
+++ b/t/t0001-init.sh
@@ -319,14 +319,14 @@ test_lazy_prereq GETCWD_IGNORES_PERMS '
 	base=GETCWD_TEST_BASE_DIR &&
 	mkdir -p $base/dir &&
 	chmod 100 $base ||
-	error "bug in test script: cannot prepare $base"
+	BUG "cannot prepare $base"
 
 	(cd $base/dir && /bin/pwd -P)
 	status=$?
 
 	chmod 700 $base &&
 	rm -rf $base ||
-	error "bug in test script: cannot clean $base"
+	BUG "cannot clean $base"
 	return $status
 '
 
diff --git a/t/t4013-diff-various.sh b/t/t4013-diff-various.sh
index 73f7038253..7d985ff6b1 100755
--- a/t/t4013-diff-various.sh
+++ b/t/t4013-diff-various.sh
@@ -129,7 +129,7 @@ do
 		case "$magic" in
 		noellipses) ;;
 		*)
-			die "bug in t4103: unknown magic $magic" ;;
+			BUG "unknown magic $magic" ;;
 		esac ;;
 	*)
 		cmd="$magic $cmd" magic=
diff --git a/t/t5516-fetch-push.sh b/t/t5516-fetch-push.sh
index 7316365a24..37e8e80893 100755
--- a/t/t5516-fetch-push.sh
+++ b/t/t5516-fetch-push.sh
@@ -95,7 +95,7 @@ mk_child() {
 
 check_push_result () {
 	test $# -ge 3 ||
-	error "bug in the test script: check_push_result requires at least 3 parameters"
+	BUG "check_push_result requires at least 3 parameters"
 
 	repo_name="$1"
 	shift
diff --git a/t/t9902-completion.sh b/t/t9902-completion.sh
index 175f83d704..b1f901170e 100755
--- a/t/t9902-completion.sh
+++ b/t/t9902-completion.sh
@@ -1249,7 +1249,7 @@ test_expect_success 'teardown after ref completion' '
 
 test_path_completion ()
 {
-	test $# = 2 || error "bug in the test script: not 2 parameters to test_path_completion"
+	test $# = 2 || BUG "not 2 parameters to test_path_completion"
 
 	local cur="$1" expected="$2"
 	echo "$expected" >expected &&
diff --git a/t/test-lib-functions.sh b/t/test-lib-functions.sh
index d158c8d0bf..18784f0152 100644
--- a/t/test-lib-functions.sh
+++ b/t/test-lib-functions.sh
@@ -418,14 +418,14 @@ test_declared_prereq () {
 test_verify_prereq () {
 	test -z "$test_prereq" ||
 	expr >/dev/null "$test_prereq" : '[A-Z0-9_,!]*$' ||
-	error "bug in the test script: '$test_prereq' does not look like a prereq"
+	BUG "'$test_prereq' does not look like a prereq"
 }
 
 test_expect_failure () {
 	test_start_
 	test "$#" = 3 && { test_prereq=$1; shift; } || test_prereq=
 	test "$#" = 2 ||
-	error "bug in the test script: not 2 or 3 parameters to test-expect-failure"
+	BUG "not 2 or 3 parameters to test-expect-failure"
 	test_verify_prereq
 	export test_prereq
 	if ! test_skip "$@"
@@ -445,7 +445,7 @@ test_expect_success () {
 	test_start_
 	test "$#" = 3 && { test_prereq=$1; shift; } || test_prereq=
 	test "$#" = 2 ||
-	error "bug in the test script: not 2 or 3 parameters to test-expect-success"
+	BUG "not 2 or 3 parameters to test-expect-success"
 	test_verify_prereq
 	export test_prereq
 	if ! test_skip "$@"
@@ -472,7 +472,7 @@ test_expect_success () {
 test_external () {
 	test "$#" = 4 && { test_prereq=$1; shift; } || test_prereq=
 	test "$#" = 3 ||
-	error >&5 "bug in the test script: not 3 or 4 parameters to test_external"
+	BUG "not 3 or 4 parameters to test_external"
 	descr="$1"
 	shift
 	test_verify_prereq
@@ -613,7 +613,7 @@ test_path_is_missing () {
 test_line_count () {
 	if test $# != 3
 	then
-		error "bug in the test script: not 3 parameters to test_line_count"
+		BUG "not 3 parameters to test_line_count"
 	elif ! test $(wc -l <"$3") "$1" "$2"
 	then
 		echo "test_line_count: line count for $3 !$1 $2"
@@ -793,13 +793,12 @@ test_i18ngrep () {
 	eval "last_arg=\${$#}"
 
 	test -f "$last_arg" ||
-	error "bug in the test script: test_i18ngrep requires a file" \
-	      "to read as the last parameter"
+	BUG "test_i18ngrep requires a file to read as the last parameter"
 
 	if test $# -lt 2 ||
 	   { test "x!" = "x$1" && test $# -lt 3 ; }
 	then
-		error "bug in the test script: too few parameters to test_i18ngrep"
+		BUG "too few parameters to test_i18ngrep"
 	fi
 
 	if test -n "$GETTEXT_POISON"
@@ -871,7 +870,7 @@ test_seq () {
 	case $# in
 	1)	set 1 "$@" ;;
 	2)	;;
-	*)	error "bug in the test script: not 1 or 2 parameters to test_seq" ;;
+	*)	BUG "not 1 or 2 parameters to test_seq" ;;
 	esac
 	test_seq_counter__=$1
 	while test "$test_seq_counter__" -le "$2"
@@ -909,7 +908,7 @@ test_when_finished () {
 	# doing so on Bash is better than nothing (the test will
 	# silently pass on other shells).
 	test "${BASH_SUBSHELL-0}" = 0 ||
-	error "bug in test script: test_when_finished does nothing in a subshell"
+	BUG "test_when_finished does nothing in a subshell"
 	test_cleanup="{ $*
 		} && (exit \"\$eval_ret\"); eval_ret=\$?; $test_cleanup"
 }
@@ -918,7 +917,7 @@ test_when_finished () {
 # Usage: test_create_repo <directory>
 test_create_repo () {
 	test "$#" = 1 ||
-	error "bug in the test script: not 1 parameter to test-create-repo"
+	BUG "not 1 parameter to test-create-repo"
 	repo="$1"
 	mkdir -p "$repo"
 	(
@@ -1230,7 +1229,7 @@ test_oid_cache () {
 
 		if ! expr "$k" : '[a-z0-9][a-z0-9]*$' >/dev/null
 		then
-			error 'bug in the test script: bad hash algorithm'
+			BUG 'bad hash algorithm'
 		fi &&
 		eval "test_oid_${k}_$tag=\"\$v\""
 	done
@@ -1245,7 +1244,7 @@ test_oid () {
 	# key-hash pair, so exit with an error.
 	if eval "test -z \"\${$var+set}\""
 	then
-		error "bug in the test script: undefined key '$1'" >&2
+		BUG "undefined key '$1'"
 	fi &&
 	eval "printf '%s' \"\${$var}\""
 }
diff --git a/t/test-lib.sh b/t/test-lib.sh
index aba66cafa2..8dd40a6f97 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -382,6 +382,10 @@ error () {
 	exit 1
 }
 
+BUG () {
+	error >&7 "bug in the test script: $*"
+}
+
 say () {
 	say_color info "$*"
 }
@@ -709,7 +713,7 @@ test_run_ () {
 		if $(printf '%s\n' "$1" | sed -f "$GIT_BUILD_DIR/t/chainlint.sed" | grep -q '?![A-Z][A-Z]*?!') ||
 			test "OK-117" != "$(test_eval_ "(exit 117) && $1${LF}${LF}echo OK-\$?" 3>&1)"
 		then
-			error "bug in the test script: broken &&-chain or run-away HERE-DOC: $1"
+			BUG "broken &&-chain or run-away HERE-DOC: $1"
 		fi
 		trace=$trace_tmp
 	fi
@@ -1209,7 +1213,7 @@ test_lazy_prereq SANITY '
 	chmod -w SANETESTD.1 &&
 	chmod -r SANETESTD.1/x &&
 	chmod -rx SANETESTD.2 ||
-	error "bug in test sript: cannot prepare SANETESTD"
+	BUG "cannot prepare SANETESTD"
 
 	! test -r SANETESTD.1/x &&
 	! rm SANETESTD.1/x && ! test -f SANETESTD.2/x
@@ -1217,7 +1221,7 @@ test_lazy_prereq SANITY '
 
 	chmod +rwx SANETESTD.1 SANETESTD.2 &&
 	rm -rf SANETESTD.1 SANETESTD.2 ||
-	error "bug in test sript: cannot clean SANETESTD"
+	BUG "cannot clean SANETESTD"
 	return $status
 '
 
-- 
2.20.0.rc0.134.gf0022f8e60

Re: [PATCH] tests: send "bug in the test script" errors to the script's stderr

[Jeff King]

On Mon, Nov 19, 2018 at 02:13:26PM +0100, SZEDER Gábor wrote:

> Send these "bug in the test script" error messages directly to the
> test scripts standard error and thus to the terminal, so those bugs
> will be much harder to overlook.  Instead of updating all ~20 such
> 'error' calls with a redirection, let's add a BUG() function to
> 'test-lib.sh', wrapping an 'error' call with the proper redirection
> and also including the common prefix of those error messages, and
> convert all those call sites [4] to use this new BUG() function
> instead.

Yes, I think this is an improvement.

> +BUG () {
> +	error >&7 "bug in the test script: $*"
> +}

I naively expected this to go to >&4, but of course that is the
conditional "stderr or /dev/null, depending on --verbose" descriptor. I
have a feeling that we could get rid of descriptors 5 and 7 in favor of
3 and 4, if we did the conditional redirection when running each test,
instead of ahead of time.

But unless we are running out of descriptors, it's not worth the effort
(it's debatable whether we are; 9be795fbce (t5615: avoid re-using
descriptor 4, 2017-12-08) made me nervous, but it's more about the
special-ness of BASHE_XTRACEFD than anything).

Anyway, that's all a tangent to your patch.

I do notice that many of the existing "FATAL:" errors use descriptor 5,
which goes to stdout. I'm not sure if those should actually be going to
stderr (or if there's some TAP significance to those lines).

-Peff

Re: [PATCH] tests: send "bug in the test script" errors to the script's stderr

[SZEDER Gábor]

On Mon, Nov 19, 2018 at 02:44:32PM -0500, Jeff King wrote:
> On Mon, Nov 19, 2018 at 02:13:26PM +0100, SZEDER Gábor wrote:
> 
> > Send these "bug in the test script" error messages directly to the
> > test scripts standard error and thus to the terminal, so those bugs
> > will be much harder to overlook.  Instead of updating all ~20 such
> > 'error' calls with a redirection, let's add a BUG() function to
> > 'test-lib.sh', wrapping an 'error' call with the proper redirection
> > and also including the common prefix of those error messages, and
> > convert all those call sites [4] to use this new BUG() function
> > instead.
> 
> Yes, I think this is an improvement.
> 
> > +BUG () {
> > +	error >&7 "bug in the test script: $*"
> > +}
> 
> I naively expected this to go to >&4, but of course that is the
> conditional "stderr or /dev/null, depending on --verbose" descriptor. 

The first version of this patch did send the error message to fd 4 ;)

> I do notice that many of the existing "FATAL:" errors use descriptor 5,
> which goes to stdout. I'm not sure if those should actually be going to
> stderr (or if there's some TAP significance to those lines).

I chose to send these messages to standard error, because they are,
well, errors.  TAP only cares about stdout, but by aborting the test
script in BUG(), error() or die() we are already violating TAP anyway,
so I don't think it matters whether we send "bug in test script" or
"FATAL" errors to stdout or stderr.

BTW, TAP understands "Bail out!" as bail out from the _entire_ test
suite, but that's not what we want here, I'd think.

https://testanything.org/tap-specification.html#bail-out

Re: [PATCH] tests: send "bug in the test script" errors to the script's stderr

[Jeff King]

On Tue, Nov 20, 2018 at 12:34:04AM +0100, SZEDER Gábor wrote:

> > I do notice that many of the existing "FATAL:" errors use descriptor 5,
> > which goes to stdout. I'm not sure if those should actually be going to
> > stderr (or if there's some TAP significance to those lines).
> 
> I chose to send these messages to standard error, because they are,
> well, errors.  TAP only cares about stdout, but by aborting the test
> script in BUG(), error() or die() we are already violating TAP anyway,
> so I don't think it matters whether we send "bug in test script" or
> "FATAL" errors to stdout or stderr.

Yeah, I agree it probably doesn't matter. I was mostly suggesting to
make the existing ">&5" into ">&7" for consistency. But I don't think
that needs to block your patch.

> BTW, TAP understands "Bail out!" as bail out from the _entire_ test
> suite, but that's not what we want here, I'd think.
> 
> https://testanything.org/tap-specification.html#bail-out

Yes, I added the only existing "Bail out!" to test-lib.sh. :)

I agree that's not what we want here. I actually think the current
behavior (to exit non-zero) does what we want. A TAP harness will
realize that's an error, but not block other scripts.

-Peff

Re: [PATCH] tests: send "bug in the test script" errors to the script's stderr

[Jeff King]

On Tue, Nov 20, 2018 at 05:45:28AM -0500, Jeff King wrote:

> On Tue, Nov 20, 2018 at 12:34:04AM +0100, SZEDER Gábor wrote:
> 
> > > I do notice that many of the existing "FATAL:" errors use descriptor 5,
> > > which goes to stdout. I'm not sure if those should actually be going to
> > > stderr (or if there's some TAP significance to those lines).
> > 
> > I chose to send these messages to standard error, because they are,
> > well, errors.  TAP only cares about stdout, but by aborting the test
> > script in BUG(), error() or die() we are already violating TAP anyway,
> > so I don't think it matters whether we send "bug in test script" or
> > "FATAL" errors to stdout or stderr.
> 
> Yeah, I agree it probably doesn't matter. I was mostly suggesting to
> make the existing ">&5" into ">&7" for consistency. But I don't think
> that needs to block your patch.

By the way, I did check to see whether this might help the situation
where running under "prove" we see only "Dubious..." and not the actual
error() message produced by the test script. But no, it eats both stdout
and stderr. You can sneak a line through by prepending it with "#", but
only if "prove -o" is used (and even then, it's hard to associate it
with a particular test when you're running many in parallel).

So I guess the status quo is not too bad: prove says "dubious", and then
you re-run the test with "./t1234-foo.sh -v -i" and you get to see the
error.

-Peff

Re: [PATCH] tests: send "bug in the test script" errors to the script's stderr

[SZEDER Gábor]

On Tue, Nov 20, 2018 at 05:58:25AM -0500, Jeff King wrote:
> On Tue, Nov 20, 2018 at 05:45:28AM -0500, Jeff King wrote:
> 
> > On Tue, Nov 20, 2018 at 12:34:04AM +0100, SZEDER Gábor wrote:
> > 
> > > > I do notice that many of the existing "FATAL:" errors use descriptor 5,
> > > > which goes to stdout. I'm not sure if those should actually be going to
> > > > stderr (or if there's some TAP significance to those lines).
> > > 
> > > I chose to send these messages to standard error, because they are,
> > > well, errors.  TAP only cares about stdout, but by aborting the test
> > > script in BUG(), error() or die() we are already violating TAP anyway,
> > > so I don't think it matters whether we send "bug in test script" or
> > > "FATAL" errors to stdout or stderr.
> > 
> > Yeah, I agree it probably doesn't matter. I was mostly suggesting to
> > make the existing ">&5" into ">&7" for consistency. But I don't think
> > that needs to block your patch.
> 
> By the way, I did check to see whether this might help the situation
> where running under "prove" we see only "Dubious..." and not the actual
> error() message produced by the test script. But no, it eats both stdout
> and stderr. You can sneak a line through by prepending it with "#", but
> only if "prove -o" is used (and even then, it's hard to associate it
> with a particular test when you're running many in parallel).

Just to be clear: I don't mind if in some combination of test
harnesses and test options a "bug in the test script" message doesn't
reach the terminal as long as I get a clearly visible error from
somewhere.

> So I guess the status quo is not too bad: prove says "dubious", and then
> you re-run the test with "./t1234-foo.sh -v -i" and you get to see the
> error.

And with '--verbose-log' the "bug in the test script" message goes to
the test's log as well, even when it has to go through fd 7 first, so
if you use 'prove' and your GIT_TEST_OPTS includes '--verbose-log'
then you can just look at the log, there's no need to re-run the test.