Discussion:
[PATCH 0/3] "-x" tracing option for tests
Jeff King
2014-10-10 06:06:37 UTC
Permalink
These patches are pulled out of the prune-mtime series I posted
earlier[1]. The discussion veered off and there's no reason that the two
topics need to be part of the same series.

The first patch is the same cleanup as before.

The second one uses Michael's suggested "verbose" function, like:

$ verbose test 1 = 2
command failed: 'test' '1' '=' '2'

(you can see that I used rev-parse's --sq-quote, which is a little eager
to use quotes where they are not needed. I wonder if we should teach it
to produce prettier output when there is nothing outside of
[A-Za-z0-9=] or similar).

The third one is a cleanup of the "set -x" patch I posted earlier. I
made the implementation a little less gross, the output a little
cleaner, and wired it up to "-x". I think it's clean enough and useful
enough to add to our bag of test-debugging tricks.

[1/3]: t5304: use test_path_is_* instead of "test -f"
[2/3]: t5304: use helper to report failure of "test foo = bar"
[3/3]: test-lib.sh: support -x option for shell-tracing

-Peff

[1] http://thread.gmane.org/gmane.comp.version-control.git/257850/focus=257859
Jeff King
2014-10-10 06:07:00 UTC
Permalink
This is slightly more robust (checking "! test -f" would not
notice a directory of the same name, though that is not
likely to happen here). It also makes debugging easier, as
the test script will output a message on failure.

Signed-off-by: Jeff King <***@peff.net>
---
t/t5304-prune.sh | 46 +++++++++++++++++++++++-----------------------
1 file changed, 23 insertions(+), 23 deletions(-)

diff --git a/t/t5304-prune.sh b/t/t5304-prune.sh
index 01c6a3f..b0ffb05 100755
--- a/t/t5304-prune.sh
+++ b/t/t5304-prune.sh
@@ -14,7 +14,7 @@ add_blob() {
BLOB=$(echo aleph_0 | git hash-object -w --stdin) &&
BLOB_FILE=.git/objects/$(echo $BLOB | sed "s/^../&\//") &&
test $((1 + $before)) = $(git count-objects | sed "s/ .*//") &&
- test -f $BLOB_FILE &&
+ test_path_is_file $BLOB_FILE &&
test-chmtime =+0 $BLOB_FILE
}

@@ -35,9 +35,9 @@ test_expect_success 'prune stale packs' '
: > .git/objects/tmp_2.pack &&
test-chmtime =-86501 .git/objects/tmp_1.pack &&
git prune --expire 1.day &&
- test -f $orig_pack &&
- test -f .git/objects/tmp_2.pack &&
- ! test -f .git/objects/tmp_1.pack
+ test_path_is_file $orig_pack &&
+ test_path_is_file .git/objects/tmp_2.pack &&
+ test_path_is_missing .git/objects/tmp_1.pack

'

@@ -46,11 +46,11 @@ test_expect_success 'prune --expire' '
add_blob &&
git prune --expire=1.hour.ago &&
test $((1 + $before)) = $(git count-objects | sed "s/ .*//") &&
- test -f $BLOB_FILE &&
+ test_path_is_file $BLOB_FILE &&
test-chmtime =-86500 $BLOB_FILE &&
git prune --expire 1.day &&
test $before = $(git count-objects | sed "s/ .*//") &&
- ! test -f $BLOB_FILE
+ test_path_is_missing $BLOB_FILE

'

@@ -60,11 +60,11 @@ test_expect_success 'gc: implicit prune --expire' '
test-chmtime =-$((2*$week-30)) $BLOB_FILE &&
git gc &&
test $((1 + $before)) = $(git count-objects | sed "s/ .*//") &&
- test -f $BLOB_FILE &&
+ test_path_is_file $BLOB_FILE &&
test-chmtime =-$((2*$week+1)) $BLOB_FILE &&
git gc &&
test $before = $(git count-objects | sed "s/ .*//") &&
- ! test -f $BLOB_FILE
+ test_path_is_missing $BLOB_FILE

'

@@ -110,7 +110,7 @@ test_expect_success 'prune: do not prune detached HEAD with no reflog' '
git commit --allow-empty -m "detached commit" &&
# verify that there is no reflogs
# (should be removed and disabled by previous test)
- test ! -e .git/logs &&
+ test_path_is_missing .git/logs &&
git prune -n >prune_actual &&
: >prune_expected &&
test_cmp prune_actual prune_expected
@@ -145,7 +145,7 @@ test_expect_success 'gc --no-prune' '
git config gc.pruneExpire 2.days.ago &&
git gc --no-prune &&
test 1 = $(git count-objects | sed "s/ .*//") &&
- test -f $BLOB_FILE
+ test_path_is_file $BLOB_FILE

'

@@ -153,10 +153,10 @@ test_expect_success 'gc respects gc.pruneExpire' '

git config gc.pruneExpire 5002.days.ago &&
git gc &&
- test -f $BLOB_FILE &&
+ test_path_is_file $BLOB_FILE &&
git config gc.pruneExpire 5000.days.ago &&
git gc &&
- test ! -f $BLOB_FILE
+ test_path_is_missing $BLOB_FILE

'

@@ -165,9 +165,9 @@ test_expect_success 'gc --prune=<date>' '
add_blob &&
test-chmtime =-$((5001*$day)) $BLOB_FILE &&
git gc --prune=5002.days.ago &&
- test -f $BLOB_FILE &&
+ test_path_is_file $BLOB_FILE &&
git gc --prune=5000.days.ago &&
- test ! -f $BLOB_FILE
+ test_path_is_missing $BLOB_FILE

'

@@ -175,9 +175,9 @@ test_expect_success 'gc --prune=never' '

add_blob &&
git gc --prune=never &&
- test -f $BLOB_FILE &&
+ test_path_is_file $BLOB_FILE &&
git gc --prune=now &&
- test ! -f $BLOB_FILE
+ test_path_is_missing $BLOB_FILE

'

@@ -186,10 +186,10 @@ test_expect_success 'gc respects gc.pruneExpire=never' '
git config gc.pruneExpire never &&
add_blob &&
git gc &&
- test -f $BLOB_FILE &&
+ test_path_is_file $BLOB_FILE &&
git config gc.pruneExpire now &&
git gc &&
- test ! -f $BLOB_FILE
+ test_path_is_missing $BLOB_FILE

'

@@ -197,9 +197,9 @@ test_expect_success 'prune --expire=never' '

add_blob &&
git prune --expire=never &&
- test -f $BLOB_FILE &&
+ test_path_is_file $BLOB_FILE &&
git prune &&
- test ! -f $BLOB_FILE
+ test_path_is_missing $BLOB_FILE

'

@@ -210,10 +210,10 @@ test_expect_success 'gc: prune old objects after local clone' '
(
cd aclone &&
test 1 = $(git count-objects | sed "s/ .*//") &&
- test -f $BLOB_FILE &&
+ test_path_is_file $BLOB_FILE &&
git gc --prune &&
test 0 = $(git count-objects | sed "s/ .*//") &&
- ! test -f $BLOB_FILE
+ test_path_is_missing $BLOB_FILE
)
'

@@ -250,7 +250,7 @@ test_expect_success 'prune .git/shallow' '
grep $SHA1 .git/shallow &&
grep $SHA1 out &&
git prune &&
- ! test -f .git/shallow
+ test_path_is_missing .git/shallow
'

test_done
--
2.1.2.596.g7379948
Jeff King
2014-10-10 06:11:14 UTC
Permalink
For small outputs, we sometimes use:

test "$(some_cmd)" = "something we expect"

instead of a full test_cmp. The downside of this is that
when it fails, there is no output at all from the script.
Let's introduce a small helper to make tests easier to
debug.

Signed-off-by: Jeff King <***@peff.net>
---
I kind of like the elegance of this, but I'd also be OK with dropping
it. The solution from the third patch does the same thing. And while the
output isn't quite as nice, it magically works for all existing tests,
without having to convert them to use verbose().

I wondered if there was any problem with defining a function with the
same name as a variable ($verbose). A few weeks ago, I would have said
they were completely different namespaces, but after seeing the
shellshock vulnerability I am not so sure. :) This seems to work fine
in bash and dash, but maybe there is some more obscure shell that would
not like it?

Technically this function is the opposite of test_must_fail. We could
call it test_must_succeed, but that is a little wordy for my taste (I
actually considered calling it just v() if we are going to use it a
lot, but that may be going too far).

t/t5304-prune.sh | 16 ++++++++--------
t/test-lib-functions.sh | 9 +++++++++
2 files changed, 17 insertions(+), 8 deletions(-)

diff --git a/t/t5304-prune.sh b/t/t5304-prune.sh
index b0ffb05..e32e46d 100755
--- a/t/t5304-prune.sh
+++ b/t/t5304-prune.sh
@@ -13,7 +13,7 @@ add_blob() {
before=$(git count-objects | sed "s/ .*//") &&
BLOB=$(echo aleph_0 | git hash-object -w --stdin) &&
BLOB_FILE=.git/objects/$(echo $BLOB | sed "s/^../&\//") &&
- test $((1 + $before)) = $(git count-objects | sed "s/ .*//") &&
+ verbose test $((1 + $before)) = $(git count-objects | sed "s/ .*//") &&
test_path_is_file $BLOB_FILE &&
test-chmtime =+0 $BLOB_FILE
}
@@ -45,11 +45,11 @@ test_expect_success 'prune --expire' '

add_blob &&
git prune --expire=1.hour.ago &&
- test $((1 + $before)) = $(git count-objects | sed "s/ .*//") &&
+ verbose test $((1 + $before)) = $(git count-objects | sed "s/ .*//") &&
test_path_is_file $BLOB_FILE &&
test-chmtime =-86500 $BLOB_FILE &&
git prune --expire 1.day &&
- test $before = $(git count-objects | sed "s/ .*//") &&
+ verbose test $before = $(git count-objects | sed "s/ .*//") &&
test_path_is_missing $BLOB_FILE

'
@@ -59,11 +59,11 @@ test_expect_success 'gc: implicit prune --expire' '
add_blob &&
test-chmtime =-$((2*$week-30)) $BLOB_FILE &&
git gc &&
- test $((1 + $before)) = $(git count-objects | sed "s/ .*//") &&
+ verbose test $((1 + $before)) = $(git count-objects | sed "s/ .*//") &&
test_path_is_file $BLOB_FILE &&
test-chmtime =-$((2*$week+1)) $BLOB_FILE &&
git gc &&
- test $before = $(git count-objects | sed "s/ .*//") &&
+ verbose test $before = $(git count-objects | sed "s/ .*//") &&
test_path_is_missing $BLOB_FILE

'
@@ -144,7 +144,7 @@ test_expect_success 'gc --no-prune' '
test-chmtime =-$((5001*$day)) $BLOB_FILE &&
git config gc.pruneExpire 2.days.ago &&
git gc --no-prune &&
- test 1 = $(git count-objects | sed "s/ .*//") &&
+ verbose test 1 = $(git count-objects | sed "s/ .*//") &&
test_path_is_file $BLOB_FILE

'
@@ -209,10 +209,10 @@ test_expect_success 'gc: prune old objects after local clone' '
git clone --no-hardlinks . aclone &&
(
cd aclone &&
- test 1 = $(git count-objects | sed "s/ .*//") &&
+ verbose test 1 = $(git count-objects | sed "s/ .*//") &&
test_path_is_file $BLOB_FILE &&
git gc --prune &&
- test 0 = $(git count-objects | sed "s/ .*//") &&
+ verbose test 0 = $(git count-objects | sed "s/ .*//") &&
test_path_is_missing $BLOB_FILE
)
'
diff --git a/t/test-lib-functions.sh b/t/test-lib-functions.sh
index dafd6ad..b7957b8 100644
--- a/t/test-lib-functions.sh
+++ b/t/test-lib-functions.sh
@@ -634,6 +634,15 @@ test_cmp_bin() {
cmp "$@"
}

+# Call any command "$@" but be more verbose about its
+# failure. This is handy for commands like "test" which do
+# not output anything when they fail.
+verbose () {
+ "$@" && return 0
+ echo >&2 "command failed: $(git rev-parse --sq-quote "$@")"
+ return 1
+}
+
# Check if the file expected to be empty is indeed empty, and barfs
# otherwise.
--
2.1.2.596.g7379948
Jonathan Nieder
2014-10-13 16:10:22 UTC
Permalink
Post by Jeff King
test "$(some_cmd)" = "something we expect"
instead of a full test_cmp. The downside of this is that
when it fails, there is no output at all from the script.
There's another downside to that construct: it loses the exit
status from some_cmd.

[...]
Post by Jeff King
--- a/t/t5304-prune.sh
+++ b/t/t5304-prune.sh
@@ -13,7 +13,7 @@ add_blob() {
before=$(git count-objects | sed "s/ .*//") &&
BLOB=$(echo aleph_0 | git hash-object -w --stdin) &&
BLOB_FILE=.git/objects/$(echo $BLOB | sed "s/^../&\//") &&
- test $((1 + $before)) = $(git count-objects | sed "s/ .*//") &&
+ verbose test $((1 + $before)) = $(git count-objects | sed "s/ .*//") &&
So ideally this would be something like:

git count-objects >output &&
verbose test "$((1 + $before))" = "$(sed "s/ .*//" output)" &&

[...]
Post by Jeff King
@@ -45,11 +45,11 @@ test_expect_success 'prune --expire' '
add_blob &&
git prune --expire=1.hour.ago &&
- test $((1 + $before)) = $(git count-objects | sed "s/ .*//") &&
+ verbose test $((1 + $before)) = $(git count-objects | sed "s/ .*//") &&
and likewise elsewhere in the file.

Alternatively, maybe there could be a helper in the same spirit as
test_cmp_rev?

test_object_count () {
git count-objects >output &&
sed "s/ .*//" output >count &&
printf "%s\n" "$1" >expect &&
test_cmp expect count
}

My two cents,
Jonathan
Jeff King
2014-10-13 21:15:25 UTC
Permalink
Post by Jonathan Nieder
Post by Jeff King
test "$(some_cmd)" = "something we expect"
instead of a full test_cmp. The downside of this is that
when it fails, there is no output at all from the script.
There's another downside to that construct: it loses the exit
status from some_cmd.
Yes, although I think in many cases it's not a big deal. For example,
here we lose the exit code of count-objects, but it also is very
unlikely to fail _and_ produce our expected output.
Post by Jonathan Nieder
Alternatively, maybe there could be a helper in the same spirit as
test_cmp_rev?
test_object_count () {
git count-objects >output &&
sed "s/ .*//" output >count &&
printf "%s\n" "$1" >expect &&
test_cmp expect count
}
One of my goals was to provide a more generic helper so that we don't
have to make little helpers like this for every command. So I'd much
rather something like:

test_output () {
printf "%s\n" "$1" >expect &&
shift &&
"$@" >output &&
test_cmp expect output
}

The "\n" handling there feels a little hacky, but is probably OK in
practice (the few commands that really do generate an output without a
newline can use test_cmp manually). It should probably also "rm" the
files on success to avoid polluting the working tree.

It also doesn't help cases that want to do "test $foo -lt 3" or other
non-equality checks. But those are probably the minority.

I dunno. I am OK with what I posted, but if we feel strongly about
testing the exit code, I can re-roll as test_output as above.

-Peff
Jonathan Nieder
2014-10-13 21:31:32 UTC
Permalink
Post by Jeff King
Post by Jonathan Nieder
There's another downside to that construct: it loses the exit
status from some_cmd.
Yes, although I think in many cases it's not a big deal. For example,
here we lose the exit code of count-objects, but it also is very
unlikely to fail _and_ produce our expected output.
It could segfault after producing the good output, but sure,
count-objects code doesn't change very often.

[...]
Post by Jeff King
One of my goals was to provide a more generic helper so that we don't
have to make little helpers like this for every command. So I'd much
test_output () {
printf "%s\n" "$1" >expect &&
shift &&
test_cmp expect output
}
I agree with the principle in general.

Unfortunately that wouldn't help here --- the "$@" is a command with a
pipe to sed in it and we still lose the exit status from
count-objects.

Hoping that clarifies,
Jonathan
Junio C Hamano
2014-10-13 21:33:48 UTC
Permalink
Post by Jonathan Nieder
Post by Jeff King
Post by Jonathan Nieder
There's another downside to that construct: it loses the exit
status from some_cmd.
Yes, although I think in many cases it's not a big deal. For example,
here we lose the exit code of count-objects, but it also is very
unlikely to fail _and_ produce our expected output.
It could segfault after producing the good output, but sure,
count-objects code doesn't change very often.
"Doesn't change very often" is not the issue. Here we are not testing
if it can count correctly without crashing, which *is* the real reason
why it is perfectly fine to use $(git count-objects | sed ...) pattern here.

There of course should be a test for count-objects to make sure it
counts correctly without crashing.
Jonathan Nieder
2014-10-13 21:38:08 UTC
Permalink
Post by Junio C Hamano
Post by Jonathan Nieder
It could segfault after producing the good output, but sure,
count-objects code doesn't change very often.
"Doesn't change very often" is not the issue. Here we are not testing
if it can count correctly without crashing, which *is* the real reason
why it is perfectly fine to use $(git count-objects | sed ...) pattern here.
There of course should be a test for count-objects to make sure it
counts correctly without crashing.
That also makes sense, but it is a pretty big change from the general
strategy used in git tests today.

Currently they use &&-chaining to check the status from git commands
used along the way. That way, unrelated bugs in git commands that are
only used incidentally get caught, as long as they cause the command
to crash. This has helped me in the past to find weird bugs early
when they cause some particular command to crash on some platforms.
Sometimes they are races that show up on more popular platforms later.

Jonathan
Junio C Hamano
2014-10-13 21:56:18 UTC
Permalink
Post by Jonathan Nieder
Post by Junio C Hamano
Post by Jonathan Nieder
It could segfault after producing the good output, but sure,
count-objects code doesn't change very often.
"Doesn't change very often" is not the issue. Here we are not testing
if it can count correctly without crashing, which *is* the real reason
why it is perfectly fine to use $(git count-objects | sed ...) pattern here.
There of course should be a test for count-objects to make sure it
counts correctly without crashing.
That also makes sense, but it is a pretty big change from the general
strategy used in git tests today.
I would have to say that you are mistaken in reading what the
"strategy used today" is. There is a subtle trade-off involved.

When we test, say, "git add a b", we may want to test these things:

- "git add" when given addable paths a and b finishes without
crashing;

- "git add" will leave these paths in the index as expected.

And we write

git add a b &&
test_write_lines a b >expect &&
git ls-files a b >actual &&
test_cmp expect actual

NOT because we expect "printf" (which underlies test_write_lines) or
"git ls-files" could somehow misbehave and dump core, but primarily
because compared to an alternative, e.g.

git add a b || return 1
test_write_lines a b >expect
git ls-files a b >actual
test_cmp expect actual

it is far cleaner and easier to read with a rhythm. It is just an
added bonus that we may catch errors due to filesystem quota when
writing to "expect" or ls-files crashing. If the alternative had
enough advantage over the established pattern (and here is where the
trade off comes in---you need a certain taste to judge the
advantage), it is perfectly fine to trade the exit value off and
favor the advantage the alternative offers (e.g. a test that is
easier to read).

Between these two, it is very sensible to take A. over B.

A.
git create-garbage &&
test $(git count-objects | sed ... | wc -l) = 0

B.
git create-garbage &&
test_when_finished "rm -f tmp" &&
git count-objects >tmp &&
test $(sed ... tmp | wc -l) = 0

It will shift the trade-off if the more verbose alternative gets
wrapped into a helper that is well constructed, though, because
readability advantage of A over B melts away when we do so.
Jeff King
2014-10-13 21:36:33 UTC
Permalink
Post by Jonathan Nieder
Post by Jeff King
One of my goals was to provide a more generic helper so that we don't
have to make little helpers like this for every command. So I'd much
test_output () {
printf "%s\n" "$1" >expect &&
shift &&
test_cmp expect output
}
I agree with the principle in general.
pipe to sed in it and we still lose the exit status from
count-objects.
Thanks, I missed that subtlety from what you posted earlier. That's
another good reason that something like test_output is not really
sufficient (you could eval() a snippet of shell, but then we have not
really improved on the "verbose test $a = $b" version, since as you note
we are still missing the exit code).

-Peff
Jeff King
2014-10-10 06:13:56 UTC
Permalink
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.net>
---
Having finally figured out how to drop the "set +x" from the output, I
have noticed that I kind of liked the "test_eval_ret=$?" part of the
trace (which is now gone, too), because it pretty explicitly tells you
that the last traced command failed. But now that it has been silenced,
there's no reason we couldn't add back in our own output to make it more
clear.

t/README | 4 ++++
t/test-lib.sh | 34 ++++++++++++++++++++++++++++++----
2 files changed, 34 insertions(+), 4 deletions(-)

diff --git a/t/README b/t/README
index 52c77ae..38cb078 100644
--- a/t/README
+++ b/t/README
@@ -82,6 +82,10 @@ appropriately before running "make".
numbers matching <pattern>. The number matched against is
simply the running count of the test within the file.

+-x::
+ Turn on shell tracing (i.e., `set -x`) during the tests
+ themselves. Implies `--verbose`.
+
-d::
--debug::
This may help the person who is developing a new test.
diff --git a/t/test-lib.sh b/t/test-lib.sh
index 82095e3..a60ec75 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -187,6 +187,8 @@ export _x05 _x40 _z40 LF
) &&
color=t

+test_eval_start_=
+test_eval_end_=
while test "$#" -ne 0
do
case "$1" in
@@ -233,6 +235,11 @@ do
--root=*)
root=$(expr "z$1" : 'z[^=]*=\(.*\)')
shift ;;
+ -x)
+ test_eval_start_='set -x'
+ test_eval_end_='set +x'
+ verbose=t
+ shift ;;
*)
echo "error: unknown test option '$1'" >&2; exit 1 ;;
esac
@@ -517,10 +524,28 @@ maybe_setup_valgrind () {
fi
}

+# This is a separate function because some tests use
+# "return" to end a test_expect_success block early
+# (and we want to make sure we run any $test_eval_end_).
+test_eval_inner_ () {
+ eval "$test_eval_start_ $*"
+}
+
test_eval_ () {
- # This is a separate function because some tests use
- # "return" to end a test_expect_success block early.
- eval </dev/null >&3 2>&4 "$*"
+ # We run this block with stderr redirected to avoid extra cruft
+ # during a "-x" trace. Once in "set -x" mode, we cannot prevent
+ # the shell from printing the "set +x" to turn it off (nor the saving
+ # of $? before that). But we can make sure that the output goes to
+ # /dev/null.
+ #
+ # The test itself is run with stderr put back to &4 (so either to
+ # /dev/null, or to the original stderr if --verbose was used).
+ {
+ test_eval_inner_ "$@" </dev/null >&3 2>&4
+ test_eval_ret_=$?
+ $test_eval_end_
+ } 2>/dev/null
+ return $test_eval_ret_
}

test_run_ () {
@@ -531,7 +556,8 @@ test_run_ () {
eval_ret=$?
teardown_malloc_check

- if test -z "$immediate" || test $eval_ret = 0 || test -n "$expecting_failure"
+ if test -z "$immediate" || test $eval_ret = 0 ||
+ test -n "$expecting_failure" && test "$test_cleanup" != ":"
then
setup_malloc_check
test_eval_ "$test_cleanup"
--
2.1.2.596.g7379948
Jeff King
2014-10-10 06:21:56 UTC
Permalink
Post by Jeff King
Having finally figured out how to drop the "set +x" from the output, I
have noticed that I kind of liked the "test_eval_ret=$?" part of the
trace (which is now gone, too), because it pretty explicitly tells you
that the last traced command failed. But now that it has been silenced,
there's no reason we couldn't add back in our own output to make it more
clear.
Like:

diff --git a/t/test-lib.sh b/t/test-lib.sh
index a60ec75..81ceb23 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -237,7 +237,11 @@ do
shift ;;
-x)
test_eval_start_='set -x'
- test_eval_end_='set +x'
+ test_eval_end_='
+ set +x
+ test "$test_eval_ret_" = 0 ||
+ say_color error >&4 "last command exited with \$?=$?"
+ '
verbose=t
shift ;;
*)
@@ -543,7 +547,7 @@ test_eval_ () {
{
test_eval_inner_ "$@" </dev/null >&3 2>&4
test_eval_ret_=$?
- $test_eval_end_
+ eval "$test_eval_end_"
} 2>/dev/null
return $test_eval_ret_
}

I think we can probably do away with this excessive use of eval, and
just keep a boolean flag for "is -x in effect" and check it inside
test_eval_. Originally I was trying to keep the number of executed
commands down, because everything until the "set +x" ran (including
checks for an "is -x in effect" flag) was shown to the user. But since
that is no longer the case, we can be less stingy with the conditionals.

-Peff
Jeff King
2014-10-10 06:27:22 UTC
Permalink
Post by Jeff King
+ -x)
+ test_eval_start_='set -x'
[...]
+ eval "$test_eval_start_ $*"
+}
Hmph. I had originally intended to make this "set -x;" with a semicolon,
to keep it split from $*. But I forgot to, and much to my surprise, all
of the tests still passed. I think that is because each of the tests
is one of:

1. Long, in which case we split the commands into their own line,
like:

test_expect_success 'foo' '
some command
'

and the leading newline serves as the separator.

or

2. Short, like:

test_expect_success 'foo' 'bar'

in which case we did not run the test at all, but merely set $1 to
'bar', which of course succeeded. Whoops!

Still, I'm surprised that nothing failed due to case 2. I'll send a
re-roll in a moment.

-Peff
Jeff King
2014-10-10 06:47:27 UTC
Permalink
Post by Jeff King
diff --git a/t/test-lib.sh b/t/test-lib.sh
index a60ec75..81ceb23 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -237,7 +237,11 @@ do
shift ;;
-x)
test_eval_start_='set -x'
- test_eval_end_='set +x'
+ test_eval_end_='
+ set +x
+ test "$test_eval_ret_" = 0 ||
+ say_color error >&4 "last command exited with \$?=$?"
That should be \$?=$test_eval_ret_, of course. The patch below fixes it.
Post by Jeff King
I think we can probably do away with this excessive use of eval, and
just keep a boolean flag for "is -x in effect" and check it inside
test_eval_. Originally I was trying to keep the number of executed
commands down, because everything until the "set +x" ran (including
checks for an "is -x in effect" flag) was shown to the user. But since
that is no longer the case, we can be less stingy with the conditionals.
The patch below does so. The result is much cleaner.
Post by Jeff King
Hmph. I had originally intended to make this "set -x;" with a semicolon,
to keep it split from $*. But I forgot to, and much to my surprise, all
of the tests still passed.
And by "all" I mean "all of the handful that I ran with -x". Of course
the bug does not show up when "-x" is not in use, which it was not when
I ran "make test". *forehead palm*

Trying to run the whole test suite with "-x" does fail. Some tests
invoke shell functions and redirect their stderr. The "set -x" will
pollute that output. There's not much we can do; it's sort of inherent
in "set -x" (and it only seems to affect about 25 of the scripts, so I
think it's still a useful tool to have). I've added a warning to the
README.

Rerolled patch is below. Sorry for all the emails. I'll stop looking at
it now to give you guys a chance to find any remaining mistakes. ;)

-- >8 --
Subject: 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.net>
---
t/README | 6 ++++++
t/test-lib.sh | 42 ++++++++++++++++++++++++++++++++++++++----
2 files changed, 44 insertions(+), 4 deletions(-)

diff --git a/t/README b/t/README
index 52c77ae..9952261 100644
--- a/t/README
+++ b/t/README
@@ -82,6 +82,12 @@ appropriately before running "make".
numbers matching <pattern>. The number matched against is
simply the running count of the test within the file.

+-x::
+ Turn on shell tracing (i.e., `set -x`) during the tests
+ themselves. Implies `--verbose`. Note that this can cause
+ failures in some tests which redirect and test the
+ output of shell functions. Use with caution.
+
-d::
--debug::
This may help the person who is developing a new test.
diff --git a/t/test-lib.sh b/t/test-lib.sh
index 82095e3..4dab575 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -233,6 +233,10 @@ do
--root=*)
root=$(expr "z$1" : 'z[^=]*=\(.*\)')
shift ;;
+ -x)
+ trace=t
+ verbose=t
+ shift ;;
*)
echo "error: unknown test option '$1'" >&2; exit 1 ;;
esac
@@ -517,10 +521,39 @@ maybe_setup_valgrind () {
fi
}

+# This is a separate function because some tests use
+# "return" to end a test_expect_success block early
+# (and we want to make sure we run any cleanup like
+# "set +x").
+test_eval_inner_ () {
+ eval "
+ test \"$trace\" = t && set -x
+ $*
+ "
+}
+
test_eval_ () {
- # This is a separate function because some tests use
- # "return" to end a test_expect_success block early.
- eval </dev/null >&3 2>&4 "$*"
+ # We run this block with stderr redirected to avoid extra cruft
+ # during a "-x" trace. Once in "set -x" mode, we cannot prevent
+ # the shell from printing the "set +x" to turn it off (nor the saving
+ # of $? before that). But we can make sure that the output goes to
+ # /dev/null.
+ #
+ # The test itself is run with stderr put back to &4 (so either to
+ # /dev/null, or to the original stderr if --verbose was used).
+ {
+ test_eval_inner_ "$@" </dev/null >&3 2>&4
+ test_eval_ret_=$?
+ if test "$trace" = t
+ then
+ set +x
+ if test "$test_eval_ret_" != 0
+ then
+ say_color error >&4 "error: last command exited with \$?=$test_eval_ret_"
+ fi
+ fi
+ } 2>/dev/null
+ return $test_eval_ret_
}

test_run_ () {
@@ -531,7 +564,8 @@ test_run_ () {
eval_ret=$?
teardown_malloc_check

- if test -z "$immediate" || test $eval_ret = 0 || test -n "$expecting_failure"
+ if test -z "$immediate" || test $eval_ret = 0 ||
+ test -n "$expecting_failure" && test "$test_cleanup" != ":"
then
setup_malloc_check
test_eval_ "$test_cleanup"
--
2.1.2.596.g7379948
Junio C Hamano
2014-10-13 18:43:32 UTC
Permalink
Post by Jeff King
Post by Jeff King
Hmph. I had originally intended to make this "set -x;" with a semicolon,
to keep it split from $*. But I forgot to, and much to my surprise, all
of the tests still passed.
Yup, I was wondering why you posted a version without the semicolon,
which looked obviously bogus, as I've never seen you post an
untested thing without marking as such.
Post by Jeff King
+ # The test itself is run with stderr put back to &4 (so either to
+ # /dev/null, or to the original stderr if --verbose was used).
+ {
+ test_eval_ret_=$?
+ if test "$trace" = t
+ then
+ set +x
+ if test "$test_eval_ret_" != 0
+ then
+ say_color error >&4 "error: last command exited with \$?=$test_eval_ret_"
+ fi
+ fi
+ } 2>/dev/null
Hmph, that is a clever way to squelch output from set+x (and
everything that runs after the eval returns) I never thought of.

Nice.
Junio C Hamano
2014-10-13 22:22:50 UTC
Permalink
Post by Jeff King
Post by Jeff King
diff --git a/t/test-lib.sh b/t/test-lib.sh
index a60ec75..81ceb23 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -237,7 +237,11 @@ do
shift ;;
-x)
test_eval_start_='set -x'
- test_eval_end_='set +x'
+ test_eval_end_='
+ set +x
+ test "$test_eval_ret_" = 0 ||
+ say_color error >&4 "last command exited with \$?=$?"
That should be \$?=$test_eval_ret_, of course. The patch below fixes it.
Rerolled patch is below. Sorry for all the emails. I'll stop looking at
it now to give you guys a chance to find any remaining mistakes. ;)
Does 1308 pass with this patch for you (running it without "-x")?

The original that expects a hardcoded line number (not relative to
the original or something) is a bad taste, and also the test setup
procedure is broken (see below for a fix of that breakage, which
does not fix the breakage this patch seems to bring in anyway).

But still it is disturbing to see that there is a blank line
difference with and without this change in the file created by the
test (i.e. the client of the code this patch touches).

t/t1308-config-set.sh | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/t/t1308-config-set.sh b/t/t1308-config-set.sh
index ea0bce2..462bb64 100755
--- a/t/t1308-config-set.sh
+++ b/t/t1308-config-set.sh
@@ -23,7 +23,7 @@ check_config () {
}

test_expect_success 'setup default config' '
- cat >.git/config <<\EOF
+ cat >.git/config <<-\EOF
[case]
penguin = very blue
Movie = BadPhysics
Junio C Hamano
2014-10-13 22:31:49 UTC
Permalink
Post by Junio C Hamano
Does 1308 pass with this patch for you (running it without "-x")?
The original that expects a hardcoded line number (not relative to
the original or something) is a bad taste, and also the test setup
procedure is broken (see below for a fix of that breakage, which
does not fix the breakage this patch seems to bring in anyway).
But still it is disturbing to see that there is a blank line
difference with and without this change in the file created by the
test (i.e. the client of the code this patch touches).
This is even more disturbing. With this fix (which is correct as
far as I can tell) queued on top of ta/config-set, the shell-tracing
patch does not fail any more.

I suspect that the broken test in the original ended the .git/config
file with an incomplete line or something, and with the attached fix
we no longer do so and that is why shell-tracing patch no longer
breaks it, it seems. So if there is a test that does want to create
a file that ends with an incomplete line, we may see the real
breakage again with the shell-tracing patch in.



-- >8 --
Subject: [PATCH] t1308: fix broken here document in test script

Signed-off-by: Junio C Hamano <***@pobox.com>
---
t/t1308-config-set.sh | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/t/t1308-config-set.sh b/t/t1308-config-set.sh
index 7fdf840..243d612 100755
--- a/t/t1308-config-set.sh
+++ b/t/t1308-config-set.sh
@@ -23,7 +23,7 @@ check_config () {
}

test_expect_success 'setup default config' '
- cat >.git/config <<\EOF
+ cat >.git/config <<-\EOF
[case]
penguin = very blue
Movie = BadPhysics
@@ -185,7 +185,7 @@ test_expect_success 'proper error on error in default config files' '
cp .git/config .git/config.old &&
test_when_finished "mv .git/config.old .git/config" &&
echo "[" >>.git/config &&
- echo "fatal: bad config file line 35 in .git/config" >expect &&
+ echo "fatal: bad config file line 34 in .git/config" >expect &&
test_expect_code 128 test-config get_value foo.bar 2>actual &&
test_cmp expect actual
'
--
2.1.2-468-g1a77c5b
Jeff King
2014-10-13 22:33:03 UTC
Permalink
Post by Junio C Hamano
Post by Jeff King
Rerolled patch is below. Sorry for all the emails. I'll stop looking at
it now to give you guys a chance to find any remaining mistakes. ;)
Does 1308 pass with this patch for you (running it without "-x")?
Hmph. It does not. I know that "make test" passed with an earlier
iteration, but I must have gotten so wrapped up in testing "make
GIT_TEST_OPTS=-x test" that I never ran a vanilla "make test" on
what I finally posted. Sorry.
Post by Junio C Hamano
The original that expects a hardcoded line number (not relative to
the original or something) is a bad taste, and also the test setup
procedure is broken (see below for a fix of that breakage, which
does not fix the breakage this patch seems to bring in anyway).
Yeah, I agree, and your patch below looks reasonable.
Post by Junio C Hamano
But still it is disturbing to see that there is a blank line
difference with and without this change in the file created by the
test (i.e. the client of the code this patch touches).
This fixes it:

diff --git a/t/test-lib.sh b/t/test-lib.sh
index 4dab575..059bb25 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -528,8 +528,7 @@ maybe_setup_valgrind () {
test_eval_inner_ () {
eval "
test \"$trace\" = t && set -x
- $*
- "
+ $*"
}

test_eval_ () {


My patch definitely expands the snippet with an extra trailing newline.
But what I really don't understand is why that would impact the
_contents_ of the config file.

I'll dig further, but I'm about to leave the computer for dinner for a
few hours, so please don't hold your breath. :)

-Peff
Junio C Hamano
2014-10-13 22:38:53 UTC
Permalink
Post by Jeff King
diff --git a/t/test-lib.sh b/t/test-lib.sh
index 4dab575..059bb25 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -528,8 +528,7 @@ maybe_setup_valgrind () {
test_eval_inner_ () {
eval "
test \"$trace\" = t && set -x
- $*
- "
+ $*"
}
test_eval_ () {
My patch definitely expands the snippet with an extra trailing newline.
But what I really don't understand is why that would impact the
_contents_ of the config file.
Ahh, OK. The inside of eval begins with

cat >.git/config <<\EOF
...

and ends with "<HT>EOF", which is _ignored_ because it is not "EOF"
alone on a line, so the shell takes everything, i.e. including the
additional LF your dq. No wonder we got one extra line.

And with that additional LF fixed, even if we do not fix t1308, it
should work (with some definition of "work") as before.

Thanks, that clears it up.
Jeff King
2014-10-13 22:43:43 UTC
Permalink
Post by Jeff King
Post by Junio C Hamano
But still it is disturbing to see that there is a blank line
difference with and without this change in the file created by the
test (i.e. the client of the code this patch touches).
diff --git a/t/test-lib.sh b/t/test-lib.sh
index 4dab575..059bb25 100644
--- a/t/test-lib.sh
+++ b/t/test-lib.sh
@@ -528,8 +528,7 @@ maybe_setup_valgrind () {
test_eval_inner_ () {
eval "
test \"$trace\" = t && set -x
- $*
- "
+ $*"
}
test_eval_ () {
My patch definitely expands the snippet with an extra trailing newline.
But what I really don't understand is why that would impact the
_contents_ of the config file.
I'll dig further, but I'm about to leave the computer for dinner for a
few hours, so please don't hold your breath. :)
OK, I lied. I couldn't resist spending 5 more minutes on it.

If you instrument t1308 on master to look at the contents of .git/config
directly after the setup step, you'll see that the file ends with (tabs
marked as ^I):

[...]
^I^Ihorns
^IEOF

Which makes sense. We forgot the tab-eating "<<-" in the here-doc, so
the tab-indented EOF was not counted as the end of the input. So this
test is bogus and broken, and the breakage introduced by my patch is
only triggered because of that (which isn't to say we shouldn't
necessarily adjust my patch, but we definitely should fix this test).

What really surprises me is that the shell is fine with a here-doc
ending inside an eval. Bash at least warns:

$ bash -c "eval 'cat <<EOF
content'"
bash: line 2: warning: here-document at line 1 delimited by end-of-file (wanted `EOF')
content

but dash silently accepts it:
$ dash -c "eval 'cat <<EOF
content'"
content

Maybe this is something that every shell does, but it certainly seems
like something we should not be relying on (and it was definitely not
something the test meant to rely on, as evidenced by the bogus EOF
marker it included).

-Peff
Junio C Hamano
2014-10-13 23:14:59 UTC
Permalink
Post by Jeff King
OK, I lied. I couldn't resist spending 5 more minutes on it.
If you instrument t1308 on master to look at the contents of .git/config
directly after the setup step, you'll see that the file ends with (tabs
[...]
^I^Ihorns
^IEOF
Which makes sense. We forgot the tab-eating "<<-" in the here-doc, so
the tab-indented EOF was not counted as the end of the input. So this
test is bogus and broken, and the breakage introduced by my patch is
only triggered because of that (which isn't to say we shouldn't
necessarily adjust my patch, but we definitely should fix this test).
We came to more or less the same conclusion. With your $*" fixed,
the test "works" as before, with the same definition of "works",
because without your patch the file ends with <HT>EOF<LF> and with
your original $*<LF><HT>" the file ends with <HT>EOF<LF> with these
extra <LF><HT> appended, which was what made me notice, and with $*"
the file ends with the same <HT>EOF<LF> as before.

I've queued a fix for the original test on ta/config-set and also
amended your $*".
Post by Jeff King
What really surprises me is that the shell is fine with a here-doc
ending inside an eval.
Yup, it smells somewhat mis-feature-ish, doesn't it?

Anyway, you do not need to respond to this message in a hurry.

Enjoy your dinner ;-)
Jeff King
2014-10-14 00:46:23 UTC
Permalink
Post by Junio C Hamano
We came to more or less the same conclusion. With your $*" fixed,
the test "works" as before, with the same definition of "works",
because without your patch the file ends with <HT>EOF<LF> and with
your original $*<LF><HT>" the file ends with <HT>EOF<LF> with these
extra <LF><HT> appended, which was what made me notice, and with $*"
the file ends with the same <HT>EOF<LF> as before.
Yeah. I think the fact that fixing the test to properly respect EOF
required you to later change the line number is a good indication that
the test was broken in the first place. :)
Post by Junio C Hamano
I've queued a fix for the original test on ta/config-set and also
amended your $*".
Thanks. Note that my patch still technically adds a tab in front of the
$*. I can't imagine that would matter, but if we wanted to be extra
conservative, we would make it:

eval "test ... && set -x
$*"

with no indentation at all.
Post by Junio C Hamano
Enjoy your dinner ;-)
Thanks, I did. :)

-Peff
Junio C Hamano
2014-10-13 18:24:42 UTC
Permalink
Post by Jeff King
These patches are pulled out of the prune-mtime series I posted
earlier[1]. The discussion veered off and there's no reason that the two
topics need to be part of the same series.
These look all sensible.

Is your plan to reroll the prune-mtime stuff on top of these? The
additional safety those patches would give us is valuable and they
are pretty straight-forward---I was hoping to have them in the 2.2
release.

Thanks.
Jeff King
2014-10-13 21:07:29 UTC
Permalink
Post by Junio C Hamano
Post by Jeff King
These patches are pulled out of the prune-mtime series I posted
earlier[1]. The discussion veered off and there's no reason that the two
topics need to be part of the same series.
These look all sensible.
Is your plan to reroll the prune-mtime stuff on top of these? The
additional safety those patches would give us is valuable and they
are pretty straight-forward---I was hoping to have them in the 2.2
release.
Yes, I've delayed while thinking about the issues that Michael raised.
There are basically two paths I see:

1. These do not solve all problems/races, but are a solid base and
sensible path forward for further changes which we can worry about
later.

2. There is a better way to provide prune safety, and these patches
will get in the way of doing that.

I wanted to make sure we are on path (1) and not path (2). :)

I'll try to send out a re-roll tonight.

-Peff
Michael Haggerty
2014-10-14 08:52:30 UTC
Permalink
Post by Jeff King
Post by Junio C Hamano
[...]
Is your plan to reroll the prune-mtime stuff on top of these? The
additional safety those patches would give us is valuable and they
are pretty straight-forward---I was hoping to have them in the 2.2
release.
Yes, I've delayed while thinking about the issues that Michael raised.
1. These do not solve all problems/races, but are a solid base and
sensible path forward for further changes which we can worry about
later.
2. There is a better way to provide prune safety, and these patches
will get in the way of doing that.
I wanted to make sure we are on path (1) and not path (2). :)
FWIW I think we are on path (1).

Michael
--
Michael Haggerty
***@alum.mit.edu
Jeff King
2014-10-14 13:44:15 UTC
Permalink
Post by Michael Haggerty
Post by Jeff King
Post by Junio C Hamano
Is your plan to reroll the prune-mtime stuff on top of these? The
additional safety those patches would give us is valuable and they
are pretty straight-forward---I was hoping to have them in the 2.2
release.
Yes, I've delayed while thinking about the issues that Michael raised.
1. These do not solve all problems/races, but are a solid base and
sensible path forward for further changes which we can worry about
later.
2. There is a better way to provide prune safety, and these patches
will get in the way of doing that.
I wanted to make sure we are on path (1) and not path (2). :)
FWIW I think we are on path (1).
Good. :)

I was preparing this to re-send, but I realized there is one snag. I
mentioned that we should probably be ignoring already-broken links from
recent objects to missing objects. For the traversal in pack-objects, we
can use revs->ignore_missing_links for this. But for the one in
git-prune itself, we use mark_reachable, which does not respect that
option.

I think mark_reachable's traversal is essentially the same as the one in
list-objects.c, and the two can be merged. I'll look into that, but I
ran out of time for it tonight (er, this morning. Oops).

-Peff

Continue reading on narkive:
Loading...