git@vger.kernel.org mailing list mirror (one of many)
 help / color / mirror / code / Atom feed
* racy test failure in tb/upload-pack-filters
@ 2020-08-05  8:42 Jeff King
  2020-08-05  9:06 ` SZEDER Gábor
                   ` (2 more replies)
  0 siblings, 3 replies; 11+ messages in thread
From: Jeff King @ 2020-08-05  8:42 UTC (permalink / raw)
  To: Taylor Blau; +Cc: SZEDER Gábor, Junio C Hamano, git

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@peff.net>
---
 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

^ permalink raw reply related	[flat|nested] 11+ messages in thread

end of thread, other threads:[~2020-08-07 20:18 UTC | newest]

Thread overview: 11+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2020-08-05  8:42 racy test failure in tb/upload-pack-filters Jeff King
2020-08-05  9:06 ` SZEDER Gábor
2020-08-05  9:26   ` Jeff King
2020-08-05 15:10     ` Taylor Blau
2020-08-05 16:28     ` Junio C Hamano
2020-08-07  8:56       ` [PATCH] sideband: mark "remote error:" prefix for translation Jeff King
2020-08-07 20:18         ` Junio C Hamano
2020-08-05  9:27 ` racy test failure in tb/upload-pack-filters Martin Ågren
2020-08-05 10:03   ` Jeff King
2020-08-05 11:35     ` Martin Ågren
2020-08-05 15:08 ` Taylor Blau

Code repositories for project(s) associated with this public inbox

	https://80x24.org/mirrors/git.git

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).