test-lib.sh: support -x option for shell-tracing

Usually running a test under "-v" makes it clear which command is failing. However, sometimes it can be useful to also see a complete trace of the shell commands being run in the test. You can do so without any support from the test suite by running "sh -x tXXXX-foo.sh". However, this produces quite a large bit of output, as we see a trace of the entire test suite. This patch instead introduces a "-x" option to the test scripts (i.e., "./tXXXX-foo.sh -x"). When enabled, this turns on "set -x" only for the tests themselves. This can still be a bit verbose, but should keep things to a more manageable level. You can even use "--verbose-only" to see the trace only for a specific test. The implementation is a little invasive. We turn on the "set -x" inside the "eval" of the test code. This lets the eval itself avoid being reported in the trace (which would be long, and redundant with the verbose listing we already showed). And then after the eval runs, we do some trickery with stderr to avoid showing the "set +x" to the user. We also show traces for test_cleanup functions (since they can impact the test outcome, too). However, we do avoid running the noop ":" cleanup (the default if the test does not use test_cleanup at all), as it creates unnecessary noise in the "set -x" output. Signed-off-by: Jeff King <peff@peff.net> Signed-off-by: Junio C Hamano <gitster@pobox.com>

Jeff King committed Oct 10, 2014 at 02:47 UTC a136f6d8ff290ab486c85cd12d1a9a47d53b432d
2 files changed +44 -4
t/README
+6
@@ -82,6 +82,12 @@ appropriately before running "make".
82 numbers matching <pattern>. The number matched against is
83 simply the running count of the test within the file.
84
85 +-x::
86 + Turn on shell tracing (i.e., `set -x`) during the tests
87 + themselves. Implies `--verbose`. Note that this can cause
88 + failures in some tests which redirect and test the
89 + output of shell functions. Use with caution.
90 +
91 -d::
92 --debug::
93 This may help the person who is developing a new test.
t/test-lib.sh
+38 -4
@@ -233,6 +233,10 @@ do
233 --root=*)
234 root=$(expr "z$1" : 'z[^=]*=\(.*\)')
235 shift ;;
236 + -x)
237 + trace=t
238 + verbose=t
239 + shift ;;
240 *)
241 echo "error: unknown test option '$1'" >&2; exit 1 ;;
242 esac
@@ -517,10 +521,39 @@ maybe_setup_valgrind () {
521 fi
522 }
523
524 +# This is a separate function because some tests use
525 +# "return" to end a test_expect_success block early
526 +# (and we want to make sure we run any cleanup like
527 +# "set +x").
528 +test_eval_inner_ () {
529 + # Do not add anything extra (including LF) after '$*'
530 + eval "
531 + test \"$trace\" = t && set -x
532 + $*"
533 +}
534 +
535 test_eval_ () {
521 - # This is a separate function because some tests use
522 - # "return" to end a test_expect_success block early.
523 - eval </dev/null >&3 2>&4 "$*"
536 + # We run this block with stderr redirected to avoid extra cruft
537 + # during a "-x" trace. Once in "set -x" mode, we cannot prevent
538 + # the shell from printing the "set +x" to turn it off (nor the saving
539 + # of $? before that). But we can make sure that the output goes to
540 + # /dev/null.
541 + #
542 + # The test itself is run with stderr put back to &4 (so either to
543 + # /dev/null, or to the original stderr if --verbose was used).
544 + {
545 + test_eval_inner_ "$@" </dev/null >&3 2>&4
546 + test_eval_ret_=$?
547 + if test "$trace" = t
548 + then
549 + set +x
550 + if test "$test_eval_ret_" != 0
551 + then
552 + say_color error >&4 "error: last command exited with \$?=$test_eval_ret_"
553 + fi
554 + fi
555 + } 2>/dev/null
556 + return $test_eval_ret_
557 }
558
559 test_run_ () {
@@ -531,7 +564,8 @@ test_run_ () {
564 eval_ret=$?
565 teardown_malloc_check
566
534 - if test -z "$immediate" || test $eval_ret = 0 || test -n "$expecting_failure"
567 + if test -z "$immediate" || test $eval_ret = 0 ||
568 + test -n "$expecting_failure" && test "$test_cleanup" != ":"
569 then
570 setup_malloc_check
571 test_eval_ "$test_cleanup"