{"thread":{"id":"53986","subject":"racy test failure in tb/upload-pack-filters","startedAt":"2020-08-05T08:42:45Z","lastAt":"2020-08-07T20:18:55Z","messageCount":11,"participants":["Jeff King","SZEDER Gábor","Martin Ågren","Taylor Blau","Junio C Hamano"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"402902","messageId":"20200805084240.GA1802257@coredump.intra.peff.net","threadId":"53986","inReplyTo":null,"subject":"racy test failure in tb/upload-pack-filters","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2020-08-05T08:42:40Z","receivedAt":"2020-08-05T08:42:45Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"I hit a test failure in the CI job against 'next' tonight, which proved\nto be an interesting puzzle. Skip to the scissors line for the\nexplanation and the fix. Read on if you want to guess. :)\n\nHere's what I saw:\n\nRunning t5616 with --stress works fine:\n\n  $ ./t5616-partial-clone.sh  --stress\n  ...lots of runs...\n  OK   29.12\n  ...etc...\n  [I get bored and hit ^C]\n\nIf I run it with GETTEXT_POISON, it doesn't fail:\n\n  $ GIT_TEST_GETTEXT_POISON=1 ./t5616-partial-clone.sh\n  ...\n  ok 17 - upload-pack fails banned object filters\n\nbut if I do both together, it fails almost instantly:\n\n  $ GIT_TEST_GETTEXT_POISON=1 ./t5616-partial-clone.sh --stress\n  FAIL 19.1\n  FAIL 15.1\n  OK   26.1\n  OK   16.1\n  ...\n\nBut here's the really interesting part. The failure log looks like this:\n\n  ...\n  + grep filter 'blob:none' not supported err\n  error: last command exited with $?=1\n  not ok 19 - upload-pack fails banned object filters with fallback\n  #\t\n  #\t\ttest_config -C srv.bare uploadpackfilter.allow false &&\n  #\t\ttest_must_fail ok=sigpipe git clone --no-checkout --filter=blob:none \\\n  #\t\t\t\"file://$(pwd)/srv.bare\" pc3 2>err &&\n  #\t\tgrep \"filter 'blob:none' not supported\" err\n  #\t\n\nOK, so what's in that file?\n\n  $ cd trash\\ directory.t5616-partial-clone.stress-failed/\n  $ cat err\n  # GETTEXT POISON #fatal: # GETTEXT POISON #\n  fatal: filter 'blob:none' not supported\n\nWhat, it's there!? Is it somehow confusing grep?\n\n  $ grep \"filter 'blob:none' not supported\" err\n  fatal: filter 'blob:none' not supported\n  $ echo $?\n  0\n\nNope. So what's going on? Turn to page 17 for the exciting conclusion!\n\n-- >8 --\nSubject: t5616: use test_i18ngrep for upload-pack errors\n\nThe tests added to t5616 in 6dd3456a8c (upload-pack.c: allow banning\ncertain object filter(s), 2020-08-03) can fail racily, but only with\nGETTEXT_POISON enabled.\n\nThe tests in question look something like this:\n\n  test_must_fail ok=sigpipe git clone --filter=blob:none ... 2>err &&\n  grep \"filter blob:none not supported' err\n\nThe remote upload-pack process writes that error message both as an ERR\npacket, but also via a die() message. In theory we should see the\nmessage twice in the \"err\" file. The client relays the message from the\npacket to its stderr (with a \"remote error:\" prefix), and because this\nis a local-system clone, upload-pack's stderr goes to the same place.\n\nBut because clone may be writing to the pipe when upload-pack calls\ndie(), it may get SIGPIPE and fail to relay the message. That's why we\nneed our \"ok=sigpipe\" trick. But our grep should still work reliably in\nthat case. Either:\n\n  - we got SIGPIPE on the client, which means upload-pack completed its\n    die(), and we'll see that version of the message.\n\n  - the client didn't get SIGPIPE, and so it successfully relays the\n    message.\n\nIn theory we'd see both copies of the message in the second case. But\nnow always! As soon as the client sees ERR, it exits and we run grep.\nBut we have no guarantee that the upload-pack process has exited at this\npoint, or even written its die() message. We might only see the client\nversion of the message.\n\nNormally that's OK. We only need to see one or the other to pass the\ntest. But now consider GETTEXT_POISON. upload-pack doesn't translate the\ndie() message nor the ERR packet. But once the client receives it, it\ncalls:\n\n  die(_(\"remote error: %s\"), buffer + 4);\n\nThat message _is_ marked for translation. Normally we'd just replace the\n\"remote error:\" portion of it, but in GETTEXT_POISON mode, we replace\nthe whole thing with \"# GETTEXT POISON #\" and don't include the \"%s\"\npart at all. So the whole text from the ERR packet is dropped, and so we\nmay racily see a test failure if upload-pack's die() call wasn't yet\nwritten.\n\nWe can fix it by using test_i18ngrep, which just makes this grep a noop\nin the poison mode.\n\nSigned-off-by: Jeff King <peff@peff.net>\n---\n t/t5616-partial-clone.sh | 8 ++++----\n 1 file changed, 4 insertions(+), 4 deletions(-)\n\ndiff --git a/t/t5616-partial-clone.sh b/t/t5616-partial-clone.sh\nindex 4247102b00..9164ad3e63 100755\n--- a/t/t5616-partial-clone.sh\n+++ b/t/t5616-partial-clone.sh\n@@ -239,7 +239,7 @@ test_expect_success 'upload-pack fails banned object filters' '\n \ttest_config -C srv.bare uploadpackfilter.blob:none.allow false &&\n \ttest_must_fail ok=sigpipe git clone --no-checkout --filter=blob:none \\\n \t\t\"file://$(pwd)/srv.bare\" pc3 2>err &&\n-\tgrep \"filter '\\''blob:none'\\'' not supported\" err\n+\ttest_i18ngrep \"filter '\\''blob:none'\\'' not supported\" err\n '\n \n test_expect_success 'upload-pack fails banned combine object filters' '\n@@ -249,14 +249,14 @@ test_expect_success 'upload-pack fails banned combine object filters' '\n \ttest_config -C srv.bare uploadpackfilter.blob:none.allow false &&\n \ttest_must_fail ok=sigpipe git clone --no-checkout --filter=tree:1 \\\n \t\t--filter=blob:none \"file://$(pwd)/srv.bare\" pc3 2>err &&\n-\tgrep \"filter '\\''blob:none'\\'' not supported\" err\n+\ttest_i18ngrep \"filter '\\''blob:none'\\'' not supported\" err\n '\n \n test_expect_success 'upload-pack fails banned object filters with fallback' '\n \ttest_config -C srv.bare uploadpackfilter.allow false &&\n \ttest_must_fail ok=sigpipe git clone --no-checkout --filter=blob:none \\\n \t\t\"file://$(pwd)/srv.bare\" pc3 2>err &&\n-\tgrep \"filter '\\''blob:none'\\'' not supported\" err\n+\ttest_i18ngrep \"filter '\\''blob:none'\\'' not supported\" err\n '\n \n test_expect_success 'upload-pack limits tree depth filters' '\n@@ -265,7 +265,7 @@ test_expect_success 'upload-pack limits tree depth filters' '\n \ttest_config -C srv.bare uploadpackfilter.tree.maxDepth 0 &&\n \ttest_must_fail ok=sigpipe git clone --no-checkout --filter=tree:1 \\\n \t\t\"file://$(pwd)/srv.bare\" pc3 2>err &&\n-\tgrep \"tree filter allows max depth 0, but got 1\" err\n+\ttest_i18ngrep \"tree filter allows max depth 0, but got 1\" err\n '\n \n test_expect_success 'partial clone fetches blobs pointed to by refs even if normally filtered out' '\n-- \n2.28.0.506.gf082c28967\n"},{"id":"402903","messageId":"20200805090641.GR2898@szeder.dev","threadId":"53986","inReplyTo":"20200805084240.GA1802257@coredump.intra.peff.net","subject":"Re: racy test failure in tb/upload-pack-filters","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2020-08-05T09:06:41Z","receivedAt":"2020-08-05T09:06:48Z","isPatch":false,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"On Wed, Aug 05, 2020 at 04:42:40AM -0400, Jeff King wrote:\n> I hit a test failure in the CI job against 'next' tonight, which proved\n> to be an interesting puzzle. Skip to the scissors line for the\n> explanation and the fix. Read on if you want to guess. :)\n> \n> Here's what I saw:\n> \n> Running t5616 with --stress works fine:\n> \n>   $ ./t5616-partial-clone.sh  --stress\n>   ...lots of runs...\n>   OK   29.12\n>   ...etc...\n>   [I get bored and hit ^C]\n> \n> If I run it with GETTEXT_POISON, it doesn't fail:\n> \n>   $ GIT_TEST_GETTEXT_POISON=1 ./t5616-partial-clone.sh\n>   ...\n>   ok 17 - upload-pack fails banned object filters\n> \n> but if I do both together, it fails almost instantly:\n> \n>   $ GIT_TEST_GETTEXT_POISON=1 ./t5616-partial-clone.sh --stress\n>   FAIL 19.1\n>   FAIL 15.1\n>   OK   26.1\n>   OK   16.1\n>   ...\n> \n> But here's the really interesting part. The failure log looks like this:\n> \n>   ...\n>   + grep filter 'blob:none' not supported err\n>   error: last command exited with $?=1\n>   not ok 19 - upload-pack fails banned object filters with fallback\n>   #\t\n>   #\t\ttest_config -C srv.bare uploadpackfilter.allow false &&\n>   #\t\ttest_must_fail ok=sigpipe git clone --no-checkout --filter=blob:none \\\n>   #\t\t\t\"file://$(pwd)/srv.bare\" pc3 2>err &&\n>   #\t\tgrep \"filter 'blob:none' not supported\" err\n>   #\t\n> \n> OK, so what's in that file?\n> \n>   $ cd trash\\ directory.t5616-partial-clone.stress-failed/\n>   $ cat err\n>   # GETTEXT POISON #fatal: # GETTEXT POISON #\n>   fatal: filter 'blob:none' not supported\n> \n> What, it's there!? Is it somehow confusing grep?\n> \n>   $ grep \"filter 'blob:none' not supported\" err\n>   fatal: filter 'blob:none' not supported\n>   $ echo $?\n>   0\n> \n> Nope. So what's going on? Turn to page 17 for the exciting conclusion!\n> \n> -- >8 --\n> Subject: t5616: use test_i18ngrep for upload-pack errors\n> \n> The tests added to t5616 in 6dd3456a8c (upload-pack.c: allow banning\n> certain object filter(s), 2020-08-03) can fail racily, but only with\n> GETTEXT_POISON enabled.\n> \n> The tests in question look something like this:\n> \n>   test_must_fail ok=sigpipe git clone --filter=blob:none ... 2>err &&\n>   grep \"filter blob:none not supported' err\n> \n> The remote upload-pack process writes that error message both as an ERR\n> packet, but also via a die() message. In theory we should see the\n> message twice in the \"err\" file. The client relays the message from the\n> packet to its stderr (with a \"remote error:\" prefix), and because this\n> is a local-system clone, upload-pack's stderr goes to the same place.\n> \n> But because clone may be writing to the pipe when upload-pack calls\n> die(), it may get SIGPIPE and fail to relay the message. That's why we\n> need our \"ok=sigpipe\" trick. But our grep should still work reliably in\n> that case. Either:\n> \n>   - we got SIGPIPE on the client, which means upload-pack completed its\n>     die(), and we'll see that version of the message.\n> \n>   - the client didn't get SIGPIPE, and so it successfully relays the\n>     message.\n> \n> In theory we'd see both copies of the message in the second case. But\n> now always! As soon as the client sees ERR, it exits and we run grep.\n> But we have no guarantee that the upload-pack process has exited at this\n> point, or even written its die() message. We might only see the client\n> version of the message.\n> \n> Normally that's OK. We only need to see one or the other to pass the\n> test. But now consider GETTEXT_POISON. upload-pack doesn't translate the\n> die() message nor the ERR packet. But once the client receives it, it\n> calls:\n> \n>   die(_(\"remote error: %s\"), buffer + 4);\n> \n> That message _is_ marked for translation. Normally we'd just replace the\n> \"remote error:\" portion of it, but in GETTEXT_POISON mode, we replace\n> the whole thing with \"# GETTEXT POISON #\" and don't include the \"%s\"\n> part at all. So the whole text from the ERR packet is dropped, and so we\n> may racily see a test failure if upload-pack's die() call wasn't yet\n> written.\n\nOh, this is a good one! :)\n\n> We can fix it by using test_i18ngrep, which just makes this grep a noop\n> in the poison mode.\n\nI wonder whether changing that die to\n\n  die(\"%s: %s\", _(\"remote error\"), buffer + 4)\n\nwould be better.  \n\n> Signed-off-by: Jeff King <peff@peff.net>\n> ---\n>  t/t5616-partial-clone.sh | 8 ++++----\n>  1 file changed, 4 insertions(+), 4 deletions(-)\n> \n> diff --git a/t/t5616-partial-clone.sh b/t/t5616-partial-clone.sh\n> index 4247102b00..9164ad3e63 100755\n> --- a/t/t5616-partial-clone.sh\n> +++ b/t/t5616-partial-clone.sh\n> @@ -239,7 +239,7 @@ test_expect_success 'upload-pack fails banned object filters' '\n>  \ttest_config -C srv.bare uploadpackfilter.blob:none.allow false &&\n>  \ttest_must_fail ok=sigpipe git clone --no-checkout --filter=blob:none \\\n>  \t\t\"file://$(pwd)/srv.bare\" pc3 2>err &&\n> -\tgrep \"filter '\\''blob:none'\\'' not supported\" err\n> +\ttest_i18ngrep \"filter '\\''blob:none'\\'' not supported\" err\n>  '\n>  \n>  test_expect_success 'upload-pack fails banned combine object filters' '\n> @@ -249,14 +249,14 @@ test_expect_success 'upload-pack fails banned combine object filters' '\n>  \ttest_config -C srv.bare uploadpackfilter.blob:none.allow false &&\n>  \ttest_must_fail ok=sigpipe git clone --no-checkout --filter=tree:1 \\\n>  \t\t--filter=blob:none \"file://$(pwd)/srv.bare\" pc3 2>err &&\n> -\tgrep \"filter '\\''blob:none'\\'' not supported\" err\n> +\ttest_i18ngrep \"filter '\\''blob:none'\\'' not supported\" err\n>  '\n>  \n>  test_expect_success 'upload-pack fails banned object filters with fallback' '\n>  \ttest_config -C srv.bare uploadpackfilter.allow false &&\n>  \ttest_must_fail ok=sigpipe git clone --no-checkout --filter=blob:none \\\n>  \t\t\"file://$(pwd)/srv.bare\" pc3 2>err &&\n> -\tgrep \"filter '\\''blob:none'\\'' not supported\" err\n> +\ttest_i18ngrep \"filter '\\''blob:none'\\'' not supported\" err\n>  '\n>  \n>  test_expect_success 'upload-pack limits tree depth filters' '\n> @@ -265,7 +265,7 @@ test_expect_success 'upload-pack limits tree depth filters' '\n>  \ttest_config -C srv.bare uploadpackfilter.tree.maxDepth 0 &&\n>  \ttest_must_fail ok=sigpipe git clone --no-checkout --filter=tree:1 \\\n>  \t\t\"file://$(pwd)/srv.bare\" pc3 2>err &&\n> -\tgrep \"tree filter allows max depth 0, but got 1\" err\n> +\ttest_i18ngrep \"tree filter allows max depth 0, but got 1\" err\n>  '\n>  \n>  test_expect_success 'partial clone fetches blobs pointed to by refs even if normally filtered out' '\n> -- \n> 2.28.0.506.gf082c28967\n"},{"id":"402904","messageId":"CAN0heSqsHGL2Pb37d2dWL+RCWac4z8mjpM-v6v6zsxH_8cWQjQ@mail.gmail.com","threadId":"53986","inReplyTo":"20200805084240.GA1802257@coredump.intra.peff.net","subject":"Re: racy test failure in tb/upload-pack-filters","fromName":"Martin Ågren","fromEmail":"martin.agren@gmail.com","sentAt":"2020-08-05T09:27:22Z","receivedAt":"2020-08-05T09:28:45Z","isPatch":false,"sender":{"key":"martin.agren@gmail.com","avatar":null},"body":"On Wed, 5 Aug 2020 at 10:45, Jeff King <peff@peff.net> wrote:\n>\n>   $ GIT_TEST_GETTEXT_POISON=1 ./t5616-partial-clone.sh --stress\n>   FAIL 19.1\n>   FAIL 15.1\n>   OK   26.1\n>   OK   16.1\n>   ...\n\n[...]\n> OK, so what's in that file?\n>\n>   $ cd trash\\ directory.t5616-partial-clone.stress-failed/\n>   $ cat err\n>   # GETTEXT POISON #fatal: # GETTEXT POISON #\n>   fatal: filter 'blob:none' not supported\n>\n> What, it's there!? Is it somehow confusing grep?\n>\n>   $ grep \"filter 'blob:none' not supported\" err\n>   fatal: filter 'blob:none' not supported\n>   $ echo $?\n>   0\n\nNice. :-)\n\n> -- >8 --\n> Subject: t5616: use test_i18ngrep for upload-pack errors\n\n[...snipping lots of good stuff...]\n\n> In theory we'd see both copies of the message in the second case. But\n> now always! As soon as the client sees ERR, it exits and we run grep.\n\ns/now/not/\n\nVery nicely explained, as always.\n\n> -       grep \"filter '\\''blob:none'\\'' not supported\" err\n> +       test_i18ngrep \"filter '\\''blob:none'\\'' not supported\" err\n\nRight, this is the one from the intro and the commit message.\n\n> -       grep \"tree filter allows max depth 0, but got 1\" err\n> +       test_i18ngrep \"tree filter allows max depth 0, but got 1\" err\n\nThis one isn't translated, so this hunk could be dropped. Or maybe you\nwanted to knowingly cast a slightly wider net? (And this does fit the\nsubject of your patch.)\n\nMartin\n"},{"id":"402905","messageId":"20200805092658.GA1803042@coredump.intra.peff.net","threadId":"53986","inReplyTo":"20200805090641.GR2898@szeder.dev","subject":"Re: racy test failure in tb/upload-pack-filters","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2020-08-05T09:26:58Z","receivedAt":"2020-08-05T09:29:01Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Aug 05, 2020 at 11:06:41AM +0200, SZEDER Gábor wrote:\n\n> > We can fix it by using test_i18ngrep, which just makes this grep a noop\n> > in the poison mode.\n> \n> I wonder whether changing that die to\n> \n>   die(\"%s: %s\", _(\"remote error\"), buffer + 4)\n> \n> would be better.\n\nThat would definitely work, but it seems sad to have to make our code\nuglier. Plus I think it would hurt translations that want to format\ndifferently (e.g., would an RTL language want to swap the order?).\n\nIt also wouldn't help other poison uses that could be expecting a \"%s\"\nto be filled.  Another option would be to make our poison code more\nrealistic by copying placeholders like \"%s\" into the poison string. That\nwould fix this problem, and allow some tests to relax a bit (e.g., if\nI'm looking for an error message that contains a filename, I _could_\ngrep for just that filename, which would never actually be translated).\n\nBut I think that gets pretty tricky, as we'd have to understand the\nwhole set of placeholders (e.g., that \"%s\" is complete after two bytes,\nbut \"%lu\" needs three bytes).\n\nAnyway, it seemed like limiting the damage to the tests themselves was\nthe least bad thing.\n\nBy the way, grepping for \"remote error:\" shows that when we get an error\nover sideband 3 we produce the same message but _don't_ translate it.\nThat seems inconsistent.\n\n-Peff\n"},{"id":"402906","messageId":"20200805100351.GA2126375@coredump.intra.peff.net","threadId":"53986","inReplyTo":"CAN0heSqsHGL2Pb37d2dWL+RCWac4z8mjpM-v6v6zsxH_8cWQjQ@mail.gmail.com","subject":"Re: racy test failure in tb/upload-pack-filters","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2020-08-05T10:03:51Z","receivedAt":"2020-08-05T10:04:25Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Aug 05, 2020 at 11:27:22AM +0200, Martin Ågren wrote:\n\n> > In theory we'd see both copies of the message in the second case. But\n> > now always! As soon as the client sees ERR, it exits and we run grep.\n> \n> s/now/not/\n\nOops, thanks.\n\n> > -       grep \"filter '\\''blob:none'\\'' not supported\" err\n> > +       test_i18ngrep \"filter '\\''blob:none'\\'' not supported\" err\n> \n> Right, this is the one from the intro and the commit message.\n> \n> > -       grep \"tree filter allows max depth 0, but got 1\" err\n> > +       test_i18ngrep \"tree filter allows max depth 0, but got 1\" err\n> \n> This one isn't translated, so this hunk could be dropped. Or maybe you\n> wanted to knowingly cast a slightly wider net? (And this does fit the\n> subject of your patch.)\n\nNeither message is translated in itself, but the bug can happen with\neither of them (because of the translation of the \"remote error\"\nstring). The tree-depth one was actually in the first failure I saw, but\nwhen I re-ran it to produce output for the commit message, I got one of\nthe other tests.\n\n-Peff\n"},{"id":"402911","messageId":"CAN0heSqmsrvf8-Xq6TNqfGONLJir2w9+4QA3_6KKkFiVH2Rc9w@mail.gmail.com","threadId":"53986","inReplyTo":"20200805100351.GA2126375@coredump.intra.peff.net","subject":"Re: racy test failure in tb/upload-pack-filters","fromName":"Martin Ågren","fromEmail":"martin.agren@gmail.com","sentAt":"2020-08-05T11:35:28Z","receivedAt":"2020-08-05T16:44:15Z","isPatch":false,"sender":{"key":"martin.agren@gmail.com","avatar":null},"body":"On Wed, 5 Aug 2020 at 12:03, Jeff King <peff@peff.net> wrote:\n>\n> On Wed, Aug 05, 2020 at 11:27:22AM +0200, Martin Ågren wrote:\n>\n> > > -       grep \"tree filter allows max depth 0, but got 1\" err\n> > > +       test_i18ngrep \"tree filter allows max depth 0, but got 1\" err\n> >\n> > This one isn't translated, so this hunk could be dropped. Or maybe you\n> > wanted to knowingly cast a slightly wider net? (And this does fit the\n> > subject of your patch.)\n>\n> Neither message is translated in itself, but the bug can happen with\n> either of them (because of the translation of the \"remote error\"\n> string). The tree-depth one was actually in the first failure I saw, but\n> when I re-ran it to produce output for the commit message, I got one of\n> the other tests.\n\nBraino! Thanks for (re-)explaining so patiently. I even tried dropping\nthat hunk and running a fair amount of \"--stress\" -- never failed.\nWithout the other hunks, \"--stress\" hit the failure pretty much\ninstantly. Oh well, brute force doesn't always beat actual thinking.\n\nMartin\n"},{"id":"402943","messageId":"20200805150850.GA9546@syl.lan","threadId":"53986","inReplyTo":"20200805084240.GA1802257@coredump.intra.peff.net","subject":"Re: racy test failure in tb/upload-pack-filters","fromName":"Taylor Blau","fromEmail":"me@ttaylorr.com","sentAt":"2020-08-05T15:08:50Z","receivedAt":"2020-08-05T19:48:50Z","isPatch":false,"sender":{"key":"me@ttaylorr.com","avatar":"https://avatars.githubusercontent.com/u/301000140?v=4"},"body":"On Wed, Aug 05, 2020 at 04:42:40AM -0400, Jeff King wrote:\n> I hit a test failure in the CI job against 'next' tonight, which proved\n> to be an interesting puzzle. Skip to the scissors line for the\n> explanation and the fix. Read on if you want to guess. :)\n>\n> Here's what I saw:\n>\n> Running t5616 with --stress works fine:\n>\n>   $ ./t5616-partial-clone.sh  --stress\n>   ...lots of runs...\n>   OK   29.12\n>   ...etc...\n>   [I get bored and hit ^C]\n>\n> If I run it with GETTEXT_POISON, it doesn't fail:\n>\n>   $ GIT_TEST_GETTEXT_POISON=1 ./t5616-partial-clone.sh\n>   ...\n>   ok 17 - upload-pack fails banned object filters\n>\n> but if I do both together, it fails almost instantly:\n>\n>   $ GIT_TEST_GETTEXT_POISON=1 ./t5616-partial-clone.sh --stress\n>   FAIL 19.1\n>   FAIL 15.1\n>   OK   26.1\n>   OK   16.1\n>   ...\n>\n> But here's the really interesting part. The failure log looks like this:\n>\n>   ...\n>   + grep filter 'blob:none' not supported err\n>   error: last command exited with $?=1\n>   not ok 19 - upload-pack fails banned object filters with fallback\n>   #\n>   #\t\ttest_config -C srv.bare uploadpackfilter.allow false &&\n>   #\t\ttest_must_fail ok=sigpipe git clone --no-checkout --filter=blob:none \\\n>   #\t\t\t\"file://$(pwd)/srv.bare\" pc3 2>err &&\n>   #\t\tgrep \"filter 'blob:none' not supported\" err\n>   #\n>\n> OK, so what's in that file?\n>\n>   $ cd trash\\ directory.t5616-partial-clone.stress-failed/\n>   $ cat err\n>   # GETTEXT POISON #fatal: # GETTEXT POISON #\n>   fatal: filter 'blob:none' not supported\n>\n> What, it's there!? Is it somehow confusing grep?\n>\n>   $ grep \"filter 'blob:none' not supported\" err\n>   fatal: filter 'blob:none' not supported\n>   $ echo $?\n>   0\n>\n> Nope. So what's going on? Turn to page 17 for the exciting conclusion!\n>\n> -- >8 --\n> Subject: t5616: use test_i18ngrep for upload-pack errors\n>\n> The tests added to t5616 in 6dd3456a8c (upload-pack.c: allow banning\n> certain object filter(s), 2020-08-03) can fail racily, but only with\n> GETTEXT_POISON enabled.\n>\n> The tests in question look something like this:\n>\n>   test_must_fail ok=sigpipe git clone --filter=blob:none ... 2>err &&\n>   grep \"filter blob:none not supported' err\n>\n> The remote upload-pack process writes that error message both as an ERR\n> packet, but also via a die() message. In theory we should see the\n> message twice in the \"err\" file. The client relays the message from the\n> packet to its stderr (with a \"remote error:\" prefix), and because this\n> is a local-system clone, upload-pack's stderr goes to the same place.\n>\n> But because clone may be writing to the pipe when upload-pack calls\n> die(), it may get SIGPIPE and fail to relay the message. That's why we\n> need our \"ok=sigpipe\" trick. But our grep should still work reliably in\n> that case. Either:\n>\n>   - we got SIGPIPE on the client, which means upload-pack completed its\n>     die(), and we'll see that version of the message.\n>\n>   - the client didn't get SIGPIPE, and so it successfully relays the\n>     message.\n>\n> In theory we'd see both copies of the message in the second case. But\n> now always! As soon as the client sees ERR, it exits and we run grep.\n> But we have no guarantee that the upload-pack process has exited at this\n> point, or even written its die() message. We might only see the client\n> version of the message.\n>\n> Normally that's OK. We only need to see one or the other to pass the\n> test. But now consider GETTEXT_POISON. upload-pack doesn't translate the\n> die() message nor the ERR packet. But once the client receives it, it\n> calls:\n>\n>   die(_(\"remote error: %s\"), buffer + 4);\n>\n> That message _is_ marked for translation. Normally we'd just replace the\n> \"remote error:\" portion of it, but in GETTEXT_POISON mode, we replace\n> the whole thing with \"# GETTEXT POISON #\" and don't include the \"%s\"\n> part at all. So the whole text from the ERR packet is dropped, and so we\n> may racily see a test failure if upload-pack's die() call wasn't yet\n> written.\n\nYikes. I knew I should have thought more about switching from\n'test_i18ngrep' back to normal 'grep', but I wouldn't have expected\nsomething like this ;).\n\nI agree with your find and fix, and thanks for the enjoyable read in the\nmeantime.\n\n  Acked-by: Taylor Blau <me@ttaylorr.com>\n\n> We can fix it by using test_i18ngrep, which just makes this grep a noop\n> in the poison mode.\n>\n> Signed-off-by: Jeff King <peff@peff.net>\n> ---\n>  t/t5616-partial-clone.sh | 8 ++++----\n>  1 file changed, 4 insertions(+), 4 deletions(-)\n>\n> diff --git a/t/t5616-partial-clone.sh b/t/t5616-partial-clone.sh\n> index 4247102b00..9164ad3e63 100755\n> --- a/t/t5616-partial-clone.sh\n> +++ b/t/t5616-partial-clone.sh\n> @@ -239,7 +239,7 @@ test_expect_success 'upload-pack fails banned object filters' '\n>  \ttest_config -C srv.bare uploadpackfilter.blob:none.allow false &&\n>  \ttest_must_fail ok=sigpipe git clone --no-checkout --filter=blob:none \\\n>  \t\t\"file://$(pwd)/srv.bare\" pc3 2>err &&\n> -\tgrep \"filter '\\''blob:none'\\'' not supported\" err\n> +\ttest_i18ngrep \"filter '\\''blob:none'\\'' not supported\" err\n>  '\n>\n>  test_expect_success 'upload-pack fails banned combine object filters' '\n> @@ -249,14 +249,14 @@ test_expect_success 'upload-pack fails banned combine object filters' '\n>  \ttest_config -C srv.bare uploadpackfilter.blob:none.allow false &&\n>  \ttest_must_fail ok=sigpipe git clone --no-checkout --filter=tree:1 \\\n>  \t\t--filter=blob:none \"file://$(pwd)/srv.bare\" pc3 2>err &&\n> -\tgrep \"filter '\\''blob:none'\\'' not supported\" err\n> +\ttest_i18ngrep \"filter '\\''blob:none'\\'' not supported\" err\n>  '\n>\n>  test_expect_success 'upload-pack fails banned object filters with fallback' '\n>  \ttest_config -C srv.bare uploadpackfilter.allow false &&\n>  \ttest_must_fail ok=sigpipe git clone --no-checkout --filter=blob:none \\\n>  \t\t\"file://$(pwd)/srv.bare\" pc3 2>err &&\n> -\tgrep \"filter '\\''blob:none'\\'' not supported\" err\n> +\ttest_i18ngrep \"filter '\\''blob:none'\\'' not supported\" err\n>  '\n>\n>  test_expect_success 'upload-pack limits tree depth filters' '\n> @@ -265,7 +265,7 @@ test_expect_success 'upload-pack limits tree depth filters' '\n>  \ttest_config -C srv.bare uploadpackfilter.tree.maxDepth 0 &&\n>  \ttest_must_fail ok=sigpipe git clone --no-checkout --filter=tree:1 \\\n>  \t\t\"file://$(pwd)/srv.bare\" pc3 2>err &&\n> -\tgrep \"tree filter allows max depth 0, but got 1\" err\n> +\ttest_i18ngrep \"tree filter allows max depth 0, but got 1\" err\n>  '\n>\n>  test_expect_success 'partial clone fetches blobs pointed to by refs even if normally filtered out' '\n> --\n> 2.28.0.506.gf082c28967\nThanks,\nTaylor\n"},{"id":"402951","messageId":"20200805151012.GB9546@syl.lan","threadId":"53986","inReplyTo":"20200805092658.GA1803042@coredump.intra.peff.net","subject":"Re: racy test failure in tb/upload-pack-filters","fromName":"Taylor Blau","fromEmail":"me@ttaylorr.com","sentAt":"2020-08-05T15:10:12Z","receivedAt":"2020-08-05T20:06:12Z","isPatch":false,"sender":{"key":"me@ttaylorr.com","avatar":"https://avatars.githubusercontent.com/u/301000140?v=4"},"body":"On Wed, Aug 05, 2020 at 05:26:58AM -0400, Jeff King wrote:\n> On Wed, Aug 05, 2020 at 11:06:41AM +0200, SZEDER Gábor wrote:\n>\n> > > We can fix it by using test_i18ngrep, which just makes this grep a noop\n> > > in the poison mode.\n> >\n> > I wonder whether changing that die to\n> >\n> >   die(\"%s: %s\", _(\"remote error\"), buffer + 4)\n> >\n> > would be better.\n>\n> That would definitely work, but it seems sad to have to make our code\n> uglier. Plus I think it would hurt translations that want to format\n> differently (e.g., would an RTL language want to swap the order?).\n\nThis is reason enough to not do this; I know that we are pretty averse\nto translation lego, and even though this one seems innocuous, I think\nit may be a deal breaker for such languages.\n\n> It also wouldn't help other poison uses that could be expecting a \"%s\"\n> to be filled.  Another option would be to make our poison code more\n> realistic by copying placeholders like \"%s\" into the poison string. That\n> would fix this problem, and allow some tests to relax a bit (e.g., if\n> I'm looking for an error message that contains a filename, I _could_\n> grep for just that filename, which would never actually be translated).\n>\n> But I think that gets pretty tricky, as we'd have to understand the\n> whole set of placeholders (e.g., that \"%s\" is complete after two bytes,\n> but \"%lu\" needs three bytes).\n\nMight be a good direction to go in, but I agree it's outside of the\nscope of this patch.\n\n> Anyway, it seemed like limiting the damage to the tests themselves was\n> the least bad thing.\n>\n> By the way, grepping for \"remote error:\" shows that when we get an error\n> over sideband 3 we produce the same message but _don't_ translate it.\n> That seems inconsistent.\n>\n> -Peff\n\nThanks,\nTaylor\n"},{"id":"402955","messageId":"xmqqwo2dnjk5.fsf@gitster.c.googlers.com","threadId":"53986","inReplyTo":"20200805092658.GA1803042@coredump.intra.peff.net","subject":"Re: racy test failure in tb/upload-pack-filters","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2020-08-05T16:28:42Z","receivedAt":"2020-08-05T20:10:32Z","isPatch":false,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jeff King <peff@peff.net> writes:\n\n> By the way, grepping for \"remote error:\" shows that when we get an error\n> over sideband 3 we produce the same message but _don't_ translate it.\n> That seems inconsistent.\n\nIOW\n\n    die(_(\"remote error: %s\"), buf + 1);\n\nin sideband.c?  I think it makes sense.\n\nIIRC, the current thinking is to let the remote side localize their\nmessage before sending them over the wire and we'll worry about how\nwe let the receiving end tell what l10n it wants later.  So \"remote\nerror:\" prefix may have to be translated on receiving end and the\nremainder of the line, which is already localized, can just be\ninterpolated.\n\n\n\n"},{"id":"403125","messageId":"20200807085649.GA34210@coredump.intra.peff.net","threadId":"53986","inReplyTo":"xmqqwo2dnjk5.fsf@gitster.c.googlers.com","subject":"[PATCH] sideband: mark \"remote error:\" prefix for translation","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2020-08-07T08:56:49Z","receivedAt":"2020-08-07T08:56:52Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Aug 05, 2020 at 09:28:42AM -0700, Junio C Hamano wrote:\n\n> Jeff King <peff@peff.net> writes:\n> \n> > By the way, grepping for \"remote error:\" shows that when we get an error\n> > over sideband 3 we produce the same message but _don't_ translate it.\n> > That seems inconsistent.\n> \n> IOW\n> \n>     die(_(\"remote error: %s\"), buf + 1);\n> \n> in sideband.c?  I think it makes sense.\n\nYes. Patch is below so we don't forget about it. I'm not sure if we\nought to be going further, though. The \"remote:\" prefix for sideband 2\nisn't translated either. It would be easy to do so, but it's much more\nlego-like. We don't have \"remote: %s\" ever as a string. We just have\n\"remote:\", and then we maybe_colorize_sideband() the result.\n\nWould that be annoying for translators, especially with RTL languages?\nDo people actually want to see \"remote:\" (or \"remote error:\" for that\nmatter) translated, or does mixing translated and untranslated messages\non one line end up more confusing? I'm out of my element here, as I\nwouldn't ever use the translations myself.\n\n> IIRC, the current thinking is to let the remote side localize their\n> message before sending them over the wire and we'll worry about how\n> we let the receiving end tell what l10n it wants later.  So \"remote\n> error:\" prefix may have to be translated on receiving end and the\n> remainder of the line, which is already localized, can just be\n> interpolated.\n\nYeah, that part makes sense. The local client shouldn't be translating\nwhat it gets from the server (and won't, because it is filled in via the\n%s). Adding a capability for preferred language would be easy, though I\nimagine it might be irritating in practice.  As a server admin, I want\nto see everything in the C locale; but what gets shown to users and what\nmight get dumped into server logs is not well specified in Git. I have a\nfeeling that just setting LANG based on the user's request would be a\nbit broad.\n\nAnyway, here's the patch. It doesn't seem to cause any test failures,\neven with GETTEXT_POISON. :)\n\n-- >8 --\nSubject: [PATCH] sideband: mark \"remote error:\" prefix for translation\n\nA Git client may produce a \"remote error:\" message (along with whatever\nerror the other side sent us) in two places:\n\n  - when we see an ERR packet\n\n  - when we're using a sideband and see sideband 3\n\nWe can't reliably translate the message the other side sent us, but we\ncan do so for our own prefix. However, we translate only the ERR-packet\ncase but not the sideband-3 case. Let's make them consistent (by marking\nboth for translation).\n\nSigned-off-by: Jeff King <peff@peff.net>\n---\nI really just care about consistency between the two spots, so swapping\nthis to translate neither would be to me, too. I guess this does create\ninconsistency with \"remote: \" though. Not sure if it's incremental\nforward progress, or just a bad idea. ;)\n\n sideband.c | 2 +-\n 1 file changed, 1 insertion(+), 1 deletion(-)\n\ndiff --git a/sideband.c b/sideband.c\nindex ef851113c4..0a60662fa6 100644\n--- a/sideband.c\n+++ b/sideband.c\n@@ -147,7 +147,7 @@ int demultiplex_sideband(const char *me, char *buf, int len,\n \tswitch (band) {\n \tcase 3:\n \t\tif (die_on_error)\n-\t\t\tdie(\"remote error: %s\", buf + 1);\n+\t\t\tdie(_(\"remote error: %s\"), buf + 1);\n \t\tstrbuf_addf(scratch, \"%s%s\", scratch->len ? \"\\n\" : \"\",\n \t\t\t    DISPLAY_PREFIX);\n \t\tmaybe_colorize_sideband(scratch, buf + 1, len);\n-- \n2.28.0.520.g10e2ce7e11\n\n"},{"id":"403147","messageId":"xmqq4kpegqfs.fsf@gitster.c.googlers.com","threadId":"53986","inReplyTo":"20200807085649.GA34210@coredump.intra.peff.net","subject":"Re: [PATCH] sideband: mark \"remote error:\" prefix for translation","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2020-08-07T20:18:47Z","receivedAt":"2020-08-07T20:18:55Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jeff King <peff@peff.net> writes:\n\n> On Wed, Aug 05, 2020 at 09:28:42AM -0700, Junio C Hamano wrote:\n>\n>> Jeff King <peff@peff.net> writes:\n>> \n>> > By the way, grepping for \"remote error:\" shows that when we get an error\n>> > over sideband 3 we produce the same message but _don't_ translate it.\n>> > That seems inconsistent.\n>> \n>> IOW\n>> \n>>     die(_(\"remote error: %s\"), buf + 1);\n>> \n>> in sideband.c?  I think it makes sense.\n>\n> Yes. Patch is below so we don't forget about it. I'm not sure if we\n> ought to be going further, though. The \"remote:\" prefix for sideband 2\n> isn't translated either. It would be easy to do so, but it's much more\n> lego-like. We don't have \"remote: %s\" ever as a string. We just have\n> \"remote:\", and then we maybe_colorize_sideband() the result.\n>\n> Would that be annoying for translators, especially with RTL languages?\n> Do people actually want to see \"remote:\" (or \"remote error:\" for that\n> matter) translated, or does mixing translated and untranslated messages\n> on one line end up more confusing? I'm out of my element here, as I\n> wouldn't ever use the translations myself.\n>\n>> IIRC, the current thinking is to let the remote side localize their\n>> message before sending them over the wire and we'll worry about how\n>> we let the receiving end tell what l10n it wants later.  So \"remote\n>> error:\" prefix may have to be translated on receiving end and the\n>> remainder of the line, which is already localized, can just be\n>> interpolated.\n>\n> Yeah, that part makes sense. The local client shouldn't be translating\n> what it gets from the server (and won't, because it is filled in via the\n> %s). Adding a capability for preferred language would be easy, though I\n> imagine it might be irritating in practice.  As a server admin, I want\n> to see everything in the C locale; but what gets shown to users and what\n> might get dumped into server logs is not well specified in Git. I have a\n> feeling that just setting LANG based on the user's request would be a\n> bit broad.\n>\n> Anyway, here's the patch. It doesn't seem to cause any test failures,\n> even with GETTEXT_POISON. :)\n\n;-)  Thanks.  Queued.\n"}]}