racy test failure in tb/upload-pack-filters

> 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.

> 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

> > We can fix it by using test_i18ngrep, which just makes this grep a noop
> > in the poison mode.
> 
> I wonder whether changing that die to
> 
>   die("%s: %s", _("remote error"), buffer + 4)
> 
> would be better.

> On Wed, Aug 05, 2020 at 11:06:41AM +0200, SZEDER Gábor wrote:
>
> > > We can fix it by using test_i18ngrep, which just makes this grep a noop
> > > in the poison mode.
> >
> > I wonder whether changing that die to
> >
> >   die("%s: %s", _("remote error"), buffer + 4)
> >
> > would be better.
>
> That would definitely work, but it seems sad to have to make our code
> uglier. Plus I think it would hurt translations that want to format
> differently (e.g., would an RTL language want to swap the order?).

> It also wouldn't help other poison uses that could be expecting a "%s"
> to be filled.  Another option would be to make our poison code more
> realistic by copying placeholders like "%s" into the poison string. That
> would fix this problem, and allow some tests to relax a bit (e.g., if
> I'm looking for an error message that contains a filename, I _could_
> grep for just that filename, which would never actually be translated).
>
> But I think that gets pretty tricky, as we'd have to understand the
> whole set of placeholders (e.g., that "%s" is complete after two bytes,
> but "%lu" needs three bytes).

> Anyway, it seemed like limiting the damage to the tests themselves was
> the least bad thing.
>
> By the way, grepping for "remote error:" shows that when we get an error
> over sideband 3 we produce the same message but _don't_ translate it.
> That seems inconsistent.
>
> -Peff

> Jeff King <peff@peff.net> writes:
> 
> > By the way, grepping for "remote error:" shows that when we get an error
> > over sideband 3 we produce the same message but _don't_ translate it.
> > That seems inconsistent.
> 
> IOW
> 
>     die(_("remote error: %s"), buf + 1);
> 
> in sideband.c?  I think it makes sense.

> IIRC, the current thinking is to let the remote side localize their
> message before sending them over the wire and we'll worry about how
> we let the receiving end tell what l10n it wants later.  So "remote
> error:" prefix may have to be translated on receiving end and the
> remainder of the line, which is already localized, can just be
> interpolated.

> On Wed, Aug 05, 2020 at 09:28:42AM -0700, Junio C Hamano wrote:
>
>> Jeff King <peff@peff.net> writes:
>> 
>> > By the way, grepping for "remote error:" shows that when we get an error
>> > over sideband 3 we produce the same message but _don't_ translate it.
>> > That seems inconsistent.
>> 
>> IOW
>> 
>>     die(_("remote error: %s"), buf + 1);
>> 
>> in sideband.c?  I think it makes sense.
>
> Yes. Patch is below so we don't forget about it. I'm not sure if we
> ought to be going further, though. The "remote:" prefix for sideband 2
> isn't translated either. It would be easy to do so, but it's much more
> lego-like. We don't have "remote: %s" ever as a string. We just have
> "remote:", and then we maybe_colorize_sideband() the result.
>
> Would that be annoying for translators, especially with RTL languages?
> Do people actually want to see "remote:" (or "remote error:" for that
> matter) translated, or does mixing translated and untranslated messages
> on one line end up more confusing? I'm out of my element here, as I
> wouldn't ever use the translations myself.
>
>> IIRC, the current thinking is to let the remote side localize their
>> message before sending them over the wire and we'll worry about how
>> we let the receiving end tell what l10n it wants later.  So "remote
>> error:" prefix may have to be translated on receiving end and the
>> remainder of the line, which is already localized, can just be
>> interpolated.
>
> Yeah, that part makes sense. The local client shouldn't be translating
> what it gets from the server (and won't, because it is filled in via the
> %s). Adding a capability for preferred language would be easy, though I
> imagine it might be irritating in practice.  As a server admin, I want
> to see everything in the C locale; but what gets shown to users and what
> might get dumped into server logs is not well specified in Git. I have a
> feeling that just setting LANG based on the user's request would be a
> bit broad.
>
> Anyway, here's the patch. It doesn't seem to cause any test failures,
> even with GETTEXT_POISON. :)

>
>   $ GIT_TEST_GETTEXT_POISON=1 ./t5616-partial-clone.sh --stress
>   FAIL 19.1
>   FAIL 15.1
>   OK   26.1
>   OK   16.1
>   ...

> 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

> > -       grep "filter '\''blob:none'\'' not supported" err
> > +       test_i18ngrep "filter '\''blob:none'\'' not supported" err
> 
> Right, this is the one from the intro and the commit message.
> 
> > -       grep "tree filter allows max depth 0, but got 1" err
> > +       test_i18ngrep "tree filter allows max depth 0, but got 1" err
> 
> This one isn't translated, so this hunk could be dropped. Or maybe you
> wanted to knowingly cast a slightly wider net? (And this does fit the
> subject of your patch.)

>
> On Wed, Aug 05, 2020 at 11:27:22AM +0200, Martin Ågren wrote:
>
> > > -       grep "tree filter allows max depth 0, but got 1" err
> > > +       test_i18ngrep "tree filter allows max depth 0, but got 1" err
> >
> > This one isn't translated, so this hunk could be dropped. Or maybe you
> > wanted to knowingly cast a slightly wider net? (And this does fit the
> > subject of your patch.)
>
> Neither message is translated in itself, but the bug can happen with
> either of them (because of the translation of the "remote error"
> string). The tree-depth one was actually in the first failure I saw, but
> when I re-ran it to produce output for the commit message, I got one of
> the other tests.

> 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