[v2,4/5] tests: do not let lazy prereqs inside `test_expect_*` turn off tracing

Commit Message

Linus Arver via GitGitGadget March 25, 2020, 5:41 a.m. UTC

From: Johannes Schindelin <[e-mail]>

The `test_expect_*` functions use `test_eval_` and so does
`test_run_lazy_prereq_`. If tracing is enabled via the `-x` option,
`test_eval_` turns on tracing while evaluating the code block, and turns
it off directly after it.

This is unwanted for nested invocations.

One somewhat surprising example of this is when running a test that
calls `test_i18ngrep`: that function requires the `C_LOCALE_OUTPUT`
prereq, and that prereq is a lazy one, so it is evaluated via
`test_eval_`, the command tracing is turned off, and the test case
continues to run _without tracing the commands_.

Another somewhat surprising example is when one lazy prereq depends on
another lazy prereq: the former will call `test_have_prereq` with the
latter one, which in turn calls `test_eval_` and -- you guessed it --
tracing (if enabled) will be turned off _before_ returning to evaluating
the other lazy prereq.

As we will introduce just such a scenario with the GPG, GPGSM and
RFC1991 prereqs, let's fix that by introducing a variable that keeps
track of the current trace level: nested `test_eval_` calls will
increment and then decrement the level, and only when it reaches 0, the
tracing will _actually_ be turned off.

Signed-off-by: Johannes Schindelin <[e-mail]>
---
 t/t0000-basic.sh | 13 +++++++++++++
 t/test-lib.sh    |  6 ++++--
 2 files changed, 17 insertions(+), 2 deletions(-)

Comments

Junio C Hamano March 25, 2020, 5:23 p.m. UTC | #1

"Johannes Schindelin via GitGitGadget" <[e-mail]>
writes:

> The `test_expect_*` functions use `test_eval_` and so does
> `test_run_lazy_prereq_`. If tracing is enabled via the `-x` option,
> `test_eval_` turns on tracing while evaluating the code block, and turns
> it off directly after it.
>
> This is unwanted for nested invocations.

Nice finding.

> As we will introduce just such a scenario with the GPG, GPGSM and
> RFC1991 prereqs, let's fix that by introducing a variable that keeps
> track of the current trace level: nested `test_eval_` calls will
> increment and then decrement the level, and only when it reaches 0, the
> tracing will _actually_ be turned off.

Doesn't this explanation urge us to reorder these patches?  It
sounds to me that it argues to have this step before 3/5.

Other than that, both the explanation and the code look correctly
done.  It looks to me that the surrounding code favors trailing "_"
instead of leading one for private names, so we might want to rename
the variable to $trace_level_ but that is minor.

Thanks.

> Signed-off-by: Johannes Schindelin <[e-mail]>
> ---
>  t/t0000-basic.sh | 13 +++++++++++++
>  t/test-lib.sh    |  6 ++++--
>  2 files changed, 17 insertions(+), 2 deletions(-)
>
> diff --git a/t/t0000-basic.sh b/t/t0000-basic.sh
> index 3e440c078d5..b8597216200 100755
> --- a/t/t0000-basic.sh
> +++ b/t/t0000-basic.sh
> @@ -833,6 +833,19 @@ then
>  	exit 1
>  fi
>  
> +test_expect_success 'lazy prereqs do not turn off tracing' "
> +	run_sub_test_lib_test lazy-prereq-and-tracing \
> +		'lazy prereqs and -x' -v -x <<-\\EOF &&
> +	test_lazy_prereq LAZY true
> +
> +	test_expect_success lazy 'test_have_prereq LAZY && echo trace'
> +
> +	test_done
> +	EOF
> +
> +	grep 'echo trace' lazy-prereq-and-tracing/err
> +"
> +
>  test_expect_success 'tests clean up even on failures' "
>  	run_sub_test_lib_test_err \
>  		failing-cleanup 'Failing tests with cleanup commands' <<-\\EOF &&
> diff --git a/t/test-lib.sh b/t/test-lib.sh
> index 0ea1e5a05ed..dbf25348106 100644
> --- a/t/test-lib.sh
> +++ b/t/test-lib.sh
> @@ -882,6 +882,7 @@ maybe_setup_valgrind () {
>  	fi
>  }
>  
> +_trace_level=0
>  want_trace () {
>  	test "$trace" = t && {
>  		test "$verbose" = t || test "$verbose_log" = t
> @@ -895,7 +896,7 @@ want_trace () {
>  test_eval_inner_ () {
>  	# Do not add anything extra (including LF) after '$*'
>  	eval "
> -		want_trace && set -x
> +		want_trace && _trace_level=$(($_trace_level+1)) && set -x
>  		$*"
>  }
>  
> @@ -926,7 +927,8 @@ test_eval_ () {
>  		test_eval_ret_=$?
>  		if want_trace
>  		then
> -			set +x
> +			test 1 = $_trace_level && set +x
> +			_trace_level=$(($_trace_level-1))
>  		fi
>  	} 2>/dev/null 4>&2

Jeff King March 26, 2020, 8:49 a.m. UTC | #2

On Wed, Mar 25, 2020 at 05:41:20AM +0000, Johannes Schindelin via GitGitGadget wrote:

> From: Johannes Schindelin <[e-mail]>
> 
> The `test_expect_*` functions use `test_eval_` and so does
> `test_run_lazy_prereq_`. If tracing is enabled via the `-x` option,
> `test_eval_` turns on tracing while evaluating the code block, and turns
> it off directly after it.
> 
> This is unwanted for nested invocations.
> 
> One somewhat surprising example of this is when running a test that
> calls `test_i18ngrep`: that function requires the `C_LOCALE_OUTPUT`
> prereq, and that prereq is a lazy one, so it is evaluated via
> `test_eval_`, the command tracing is turned off, and the test case
> continues to run _without tracing the commands_.

Good catch. I didn't see this when looking at the GPG stuff earlier
because I didn't nest the lazy prereqs. But it is worth fixing
regardless, because as you note it comes up in other places.

> @@ -926,7 +927,8 @@ test_eval_ () {
>  		test_eval_ret_=$?
>  		if want_trace
>  		then
> -			set +x
> +			test 1 = $_trace_level && set +x
> +			_trace_level=$(($_trace_level-1))
>  		fi
>  	} 2>/dev/null 4>&2

I briefly wondered if adding more logic here might upset our delicate
balance of avoiding writing cruft to the "-x" output. But the answer is
"no", due to the descriptor hackery at the end of that {} block.

Of course, any test evaluating a lazy prereq already gets tons of cruft
anyway, because the outer level of tracing sees all of our internal
function calls checking the prereq and setting up the inner level of
tracing. But there's not much we can do about that.

-Peff

Johannes Schindelin March 26, 2020, 1:45 p.m. UTC | #3

Hi Junio,

On Wed, 25 Mar 2020, Junio C Hamano wrote:

> "Johannes Schindelin via GitGitGadget" <[e-mail]>
> writes:
>
> > The `test_expect_*` functions use `test_eval_` and so does
> > `test_run_lazy_prereq_`. If tracing is enabled via the `-x` option,
> > `test_eval_` turns on tracing while evaluating the code block, and turns
> > it off directly after it.
> >
> > This is unwanted for nested invocations.
>
> Nice finding.

Heh. I found this ages ago, and mistook it for "all prereqs turn off
tracing" when I reported it, but Gábor pointed out that that is incorrect.

That was a long time ago, maybe even a year, and I finally used this patch
series as an excuse to finally dig deep on this.

> > As we will introduce just such a scenario with the GPG, GPGSM and
> > RFC1991 prereqs, let's fix that by introducing a variable that keeps
> > track of the current trace level: nested `test_eval_` calls will
> > increment and then decrement the level, and only when it reaches 0, the
> > tracing will _actually_ be turned off.
>
> Doesn't this explanation urge us to reorder these patches?  It
> sounds to me that it argues to have this step before 3/5.

Yes, that's where I had meant to put this patch. Sorry for the confusion.

> Other than that, both the explanation and the code look correctly
> done.  It looks to me that the surrounding code favors trailing "_"
> instead of leading one for private names, so we might want to rename
> the variable to $trace_level_ but that is minor.

Good point, I had missed that. Will be fixed in the next iteration.

Ciao,
Dscho

>
> Thanks.
>
> > Signed-off-by: Johannes Schindelin <[e-mail]>
> > ---
> >  t/t0000-basic.sh | 13 +++++++++++++
> >  t/test-lib.sh    |  6 ++++--
> >  2 files changed, 17 insertions(+), 2 deletions(-)
> >
> > diff --git a/t/t0000-basic.sh b/t/t0000-basic.sh
> > index 3e440c078d5..b8597216200 100755
> > --- a/t/t0000-basic.sh
> > +++ b/t/t0000-basic.sh
> > @@ -833,6 +833,19 @@ then
> >  	exit 1
> >  fi
> >
> > +test_expect_success 'lazy prereqs do not turn off tracing' "
> > +	run_sub_test_lib_test lazy-prereq-and-tracing \
> > +		'lazy prereqs and -x' -v -x <<-\\EOF &&
> > +	test_lazy_prereq LAZY true
> > +
> > +	test_expect_success lazy 'test_have_prereq LAZY && echo trace'
> > +
> > +	test_done
> > +	EOF
> > +
> > +	grep 'echo trace' lazy-prereq-and-tracing/err
> > +"
> > +
> >  test_expect_success 'tests clean up even on failures' "
> >  	run_sub_test_lib_test_err \
> >  		failing-cleanup 'Failing tests with cleanup commands' <<-\\EOF &&
> > diff --git a/t/test-lib.sh b/t/test-lib.sh
> > index 0ea1e5a05ed..dbf25348106 100644
> > --- a/t/test-lib.sh
> > +++ b/t/test-lib.sh
> > @@ -882,6 +882,7 @@ maybe_setup_valgrind () {
> >  	fi
> >  }
> >
> > +_trace_level=0
> >  want_trace () {
> >  	test "$trace" = t && {
> >  		test "$verbose" = t || test "$verbose_log" = t
> > @@ -895,7 +896,7 @@ want_trace () {
> >  test_eval_inner_ () {
> >  	# Do not add anything extra (including LF) after '$*'
> >  	eval "
> > -		want_trace && set -x
> > +		want_trace && _trace_level=$(($_trace_level+1)) && set -x
> >  		$*"
> >  }
> >
> > @@ -926,7 +927,8 @@ test_eval_ () {
> >  		test_eval_ret_=$?
> >  		if want_trace
> >  		then
> > -			set +x
> > +			test 1 = $_trace_level && set +x
> > +			_trace_level=$(($_trace_level-1))
> >  		fi
> >  	} 2>/dev/null 4>&2
>

Johannes Schindelin March 26, 2020, 2:34 p.m. UTC | #4

Hi Peff,

On Thu, 26 Mar 2020, Jeff King wrote:

> On Wed, Mar 25, 2020 at 05:41:20AM +0000, Johannes Schindelin via GitGitGadget wrote:
>
> > From: Johannes Schindelin <[e-mail]>
> >
> > The `test_expect_*` functions use `test_eval_` and so does
> > `test_run_lazy_prereq_`. If tracing is enabled via the `-x` option,
> > `test_eval_` turns on tracing while evaluating the code block, and turns
> > it off directly after it.
> >
> > This is unwanted for nested invocations.
> >
> > One somewhat surprising example of this is when running a test that
> > calls `test_i18ngrep`: that function requires the `C_LOCALE_OUTPUT`
> > prereq, and that prereq is a lazy one, so it is evaluated via
> > `test_eval_`, the command tracing is turned off, and the test case
> > continues to run _without tracing the commands_.
>
> Good catch. I didn't see this when looking at the GPG stuff earlier
> because I didn't nest the lazy prereqs. But it is worth fixing
> regardless, because as you note it comes up in other places.
>
> > @@ -926,7 +927,8 @@ test_eval_ () {
> >  		test_eval_ret_=$?
> >  		if want_trace
> >  		then
> > -			set +x
> > +			test 1 = $_trace_level && set +x
> > +			_trace_level=$(($_trace_level-1))
> >  		fi
> >  	} 2>/dev/null 4>&2
>
> I briefly wondered if adding more logic here might upset our delicate
> balance of avoiding writing cruft to the "-x" output. But the answer is
> "no", due to the descriptor hackery at the end of that {} block.
>
> Of course, any test evaluating a lazy prereq already gets tons of cruft
> anyway, because the outer level of tracing sees all of our internal
> function calls checking the prereq and setting up the inner level of
> tracing. But there's not much we can do about that.

We could turn off the tracing specifically in those cases. At some point,
though, it strikes me as rather ridiculous through how many hoops we jump
just because our test suite framework is implemented in portable Unix
shell script, as opposed to a more powerful language such as, say, C.

For example, we could prevent the `test_eval_ret_=$?` line from being
traced by default, simply by redirecting fd `4` to `/dev/null`. At that
stage, we would of course have to open yet another fd to support the use
case where the `-x` is passed to `sh` itself (`sh -x t0000-*.sh -i -v`).

In the context of this here patch series, which really is about enabling
the GPG-related tests on Windows, I will refrain from going down that
particular rabbit hole. My ego might get stuck.

Ciao,
Dscho

Patch

diff --git a/t/t0000-basic.sh b/t/t0000-basic.sh
index 3e440c078d5..b8597216200 100755
--- a/t/t0000-basic.sh
+++ b/t/t0000-basic.sh
@@ -833,6 +833,19 @@  then
 	exit 1
 fi
 
+test_expect_success 'lazy prereqs do not turn off tracing' "
+	run_sub_test_lib_test lazy-prereq-and-tracing \
+		'lazy prereqs and -x' -v -x <<-\\EOF &&
+	test_lazy_prereq LAZY true
+
+	test_expect_success lazy 'test_have_prereq LAZY && echo trace'
+
+	test_done
+	EOF
+
+	grep 'echo trace' lazy-prereq-and-tracing/err
+"
+
 test_expect_success 'tests clean up even on failures' "
 	run_sub_test_lib_test_err \
 		failing-cleanup 'Failing tests with cleanup commands' <<-\\EOF &&
diff --git a/t/test-lib.sh b/t/test-lib.sh
index 0ea1e5a05ed..dbf25348106 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -882,6 +882,7 @@  maybe_setup_valgrind () {
 	fi
 }
 
+_trace_level=0
 want_trace () {
 	test "$trace" = t && {
 		test "$verbose" = t || test "$verbose_log" = t
@@ -895,7 +896,7 @@  want_trace () {
 test_eval_inner_ () {
 	# Do not add anything extra (including LF) after '$*'
 	eval "
-		want_trace && set -x
+		want_trace && _trace_level=$(($_trace_level+1)) && set -x
 		$*"
 }
 
@@ -926,7 +927,8 @@  test_eval_ () {
 		test_eval_ret_=$?
 		if want_trace
 		then
-			set +x
+			test 1 = $_trace_level && set +x
+			_trace_level=$(($_trace_level-1))
 		fi
 	} 2>/dev/null 4>&2