I hit a test failure in the CI job against 'next' tonight, which proved
to be an interesting puzzle. Skip to the scissors line for the
explanation and the fix. Read on if you want to guess. :)
Here's what I saw:
Running t5616 with --stress works fine:
$ ./t5616-partial-clone.sh --stress
...lots of runs...
OK 29.12
...etc...
[I get bored and hit ^C]
If I run it with GETTEXT_POISON, it doesn't fail:
$ GIT_TEST_GETTEXT_POISON=1 ./t5616-partial-clone.sh
...
ok 17 - upload-pack fails banned object filters
but if I do both together, it fails almost instantly:
$ GIT_TEST_GETTEXT_POISON=1 ./t5616-partial-clone.sh --stress
FAIL 19.1
FAIL 15.1
OK 26.1
OK 16.1
...
But here's the really interesting part. The failure log looks like this:
...
+ grep filter 'blob:none' not supported err
error: last command exited with $?=1
not ok 19 - upload-pack fails banned object filters with fallback
#
# test_config -C srv.bare uploadpackfilter.allow false &&
# test_must_fail ok=sigpipe git clone --no-checkout --filter=blob:none \
# "file://$(pwd)/srv.bare" pc3 2>err &&
# grep "filter 'blob:none' not supported" err
#
OK, so what's in that file?
$ cd trash\ directory.t5616-partial-clone.stress-failed/
$ cat err
# GETTEXT POISON #fatal: # GETTEXT POISON #
fatal: filter 'blob:none' not supported
What, it's there!? Is it somehow confusing grep?
$ grep "filter 'blob:none' not supported" err
fatal: filter 'blob:none' not supported
$ echo $?
0
Nope. So what's going on? Turn to page 17 for the exciting conclusion!
-- >8 --
Subject: t5616: use test_i18ngrep for upload-pack errors
The tests added to t5616 in 6dd3456a8c (upload-pack.c: allow banning
certain object filter(s), 2020-08-03) can fail racily, but only with
GETTEXT_POISON enabled.
The tests in question look something like this:
test_must_fail ok=sigpipe git clone --filter=blob:none ... 2>err &&
grep "filter blob:none not supported' err
The remote upload-pack process writes that error message both as an ERR
packet, but also via a die() message. In theory we should see the
message twice in the "err" file. The client relays the message from the
packet to its stderr (with a "remote error:" prefix), and because this
is a local-system clone, upload-pack's stderr goes to the same place.
But because clone may be writing to the pipe when upload-pack calls
die(), it may get SIGPIPE and fail to relay the message. That's why we
need our "ok=sigpipe" trick. But our grep should still work reliably in
that case. Either:
- we got SIGPIPE on the client, which means upload-pack completed its
die(), and we'll see that version of the message.
- the client didn't get SIGPIPE, and so it successfully relays the
message.
In theory we'd see both copies of the message in the second case. But
now always! As soon as the client sees ERR, it exits and we run grep.
But we have no guarantee that the upload-pack process has exited at this
point, or even written its die() message. We might only see the client
version of the message.
Normally that's OK. We only need to see one or the other to pass the
test. But now consider GETTEXT_POISON. upload-pack doesn't translate the
die() message nor the ERR packet. But once the client receives it, it
calls:
die(_("remote error: %s"), buffer + 4);
That message _is_ marked for translation. Normally we'd just replace the
"remote error:" portion of it, but in GETTEXT_POISON mode, we replace
the whole thing with "# GETTEXT POISON #" and don't include the "%s"
part at all. So the whole text from the ERR packet is dropped, and so we
may racily see a test failure if upload-pack's die() call wasn't yet
written.
We can fix it by using test_i18ngrep, which just makes this grep a noop
in the poison mode.
Signed-off-by: Jeff King <peff@xxxxxxxx>
---
t/t5616-partial-clone.sh | 8 ++++----
1 file changed, 4 insertions(+), 4 deletions(-)
diff --git a/t/t5616-partial-clone.sh b/t/t5616-partial-clone.sh
index 4247102b00..9164ad3e63 100755
--- a/t/t5616-partial-clone.sh
+++ b/t/t5616-partial-clone.sh
@@ -239,7 +239,7 @@ test_expect_success 'upload-pack fails banned object filters' '
test_config -C srv.bare uploadpackfilter.blob:none.allow false &&
test_must_fail ok=sigpipe git clone --no-checkout --filter=blob:none \
"file://$(pwd)/srv.bare" pc3 2>err &&
- grep "filter '\''blob:none'\'' not supported" err
+ test_i18ngrep "filter '\''blob:none'\'' not supported" err
'
test_expect_success 'upload-pack fails banned combine object filters' '
@@ -249,14 +249,14 @@ test_expect_success 'upload-pack fails banned combine object filters' '
test_config -C srv.bare uploadpackfilter.blob:none.allow false &&
test_must_fail ok=sigpipe git clone --no-checkout --filter=tree:1 \
--filter=blob:none "file://$(pwd)/srv.bare" pc3 2>err &&
- grep "filter '\''blob:none'\'' not supported" err
+ test_i18ngrep "filter '\''blob:none'\'' not supported" err
'
test_expect_success 'upload-pack fails banned object filters with fallback' '
test_config -C srv.bare uploadpackfilter.allow false &&
test_must_fail ok=sigpipe git clone --no-checkout --filter=blob:none \
"file://$(pwd)/srv.bare" pc3 2>err &&
- grep "filter '\''blob:none'\'' not supported" err
+ test_i18ngrep "filter '\''blob:none'\'' not supported" err
'
test_expect_success 'upload-pack limits tree depth filters' '
@@ -265,7 +265,7 @@ test_expect_success 'upload-pack limits tree depth filters' '
test_config -C srv.bare uploadpackfilter.tree.maxDepth 0 &&
test_must_fail ok=sigpipe git clone --no-checkout --filter=tree:1 \
"file://$(pwd)/srv.bare" pc3 2>err &&
- grep "tree filter allows max depth 0, but got 1" err
+ test_i18ngrep "tree filter allows max depth 0, but got 1" err
'
test_expect_success 'partial clone fetches blobs pointed to by refs even if normally filtered out' '
--
2.28.0.506.gf082c28967
