{"thread":{"id":"54968","subject":"Is t5516 somehow flakey only on macOS?","startedAt":"2021-01-09T00:38:49Z","lastAt":"2021-01-10T03:24:07Z","messageCount":9,"participants":["Junio C Hamano","Eric Sunshine","Jeff King","SZEDER Gábor"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"413900","messageId":"xmqq35zbgd2a.fsf@gitster.c.googlers.com","threadId":"54968","inReplyTo":null,"subject":"Is t5516 somehow flakey only on macOS?","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2021-01-09T00:37:49Z","receivedAt":"2021-01-09T00:38:49Z","isPatch":false,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"I've seen this breakage only on \"regular (osx-clang, clang,\nmacos-latest)\" so far, but that does not necessarily mean clang on\nmacOS is miscompiling or anything like that.\n\n https://github.com/git/git/runs/1671504998?check_suite_focus=true\n\nWhat is frustrating is that the same CI/PR #1087 fully passes when\ntold to \"Re-run jobs\".\n\n https://github.com/git/git/runs/1671626677?check_suite_focus=true\n\nThey are testing exactly the same commit 820e568 that has a tree\nidentical to that of ed0fd57b97 in seen in today's pushout.\n\nAny interest in helping to find out what's going on from folks in\nthe macOS land?\n\nThanks.\n"},{"id":"413904","messageId":"CAPig+cQ3U4s0qmzoLL=ZBeSyCZm=QqjWz2P36ZUxMzNAyYn-WQ@mail.gmail.com","threadId":"54968","inReplyTo":"xmqq35zbgd2a.fsf@gitster.c.googlers.com","subject":"Re: Is t5516 somehow flakey only on macOS?","fromName":"Eric Sunshine","fromEmail":"sunshine@sunshineco.com","sentAt":"2021-01-09T09:11:09Z","receivedAt":"2021-01-09T09:14:01Z","isPatch":false,"sender":{"key":"sunshine@sunshineco.com","avatar":"https://avatars.githubusercontent.com/u/163641?v=4"},"body":"On Fri, Jan 8, 2021 at 7:39 PM Junio C Hamano wrote:\n> I've seen this breakage only on \"regular (osx-clang, clang,\n> macos-latest)\" so far, but that does not necessarily mean clang on\n> macOS is miscompiling or anything like that.\n>\n> https://github.com/git/git/runs/1671504998?check_suite_focus=true\n>\n> Any interest in helping to find out what's going on from folks in\n> the macOS land?\n\nSomething seems to be dying prematurely. The code in question from\ntest #86 \"deny fetch unreachable SHA1, allowtipsha1inwant=false\" is:\n\n test_must_fail env GIT_TEST_PROTOCOL_VERSION=0 \\\n git fetch ../testrepo/.git $SHA1_3 2>err &&\n test_i18ngrep \"remote error:.*not our ref.*$SHA1_3\\$\" err\n\nIn a successful run, the content of `err` is:\n\n fatal: git upload-pack: not our ref 64ea4c133d59fa98e86a771eda009872d6ab2886\n fatal: remote error: upload-pack: not our ref\n64ea4c133d59fa98e86a771eda009872d6ab2886\n\nHowever, in the unsuccessful run from CI, it is:\n\n fatal: git upload-pack: not our ref 64ea4c133d59fa98e86a771eda009872d6ab2886\n fatal: unable to write to remote: Broken pipe\n\nPerhaps this means something to someone familiar with this area of the code.\n"},{"id":"413905","messageId":"X/mGnY3wR1fGoxcf@coredump.intra.peff.net","threadId":"54968","inReplyTo":"CAPig+cQ3U4s0qmzoLL=ZBeSyCZm=QqjWz2P36ZUxMzNAyYn-WQ@mail.gmail.com","subject":"Re: Is t5516 somehow flakey only on macOS?","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-01-09T10:34:05Z","receivedAt":"2021-01-09T10:42:09Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sat, Jan 09, 2021 at 04:11:09AM -0500, Eric Sunshine wrote:\n\n> In a successful run, the content of `err` is:\n> \n> fatal: git upload-pack: not our ref 64ea4c133d59fa98e86a771eda009872d6ab2886\n> fatal: remote error: upload-pack: not our ref\n> 64ea4c133d59fa98e86a771eda009872d6ab2886\n> \n> However, in the unsuccessful run from CI, it is:\n> \n> fatal: git upload-pack: not our ref 64ea4c133d59fa98e86a771eda009872d6ab2886\n> fatal: unable to write to remote: Broken pipe\n> \n> Perhaps this means something to someone familiar with this area of the code.\n\nThis is the same issue discussed in this sub-thread:\n\n https://lore.kernel.org/git/20190828153944.GA29715@sigill.intra.peff.net/\n\nIt's not macOS-specific, but for whatever reason it's much easier to\ntrigger there. There's a reliable reproduction with a sleep() in:\n\n https://lore.kernel.org/git/20190829220630.GH8571@szeder.dev/\n\nThe solution is something like the \"after a write() error, pump the read\nchannel to see if we got an ERR packet\" patch Gábor showed in the reply\nto that message.\n\nBut an interesting thing to note: this particular race only happens with\nprotocol v0 (and the test is forcing v0, because v2 would not produce a\n\"not our ref\" error in the first place). In general I'd suspect that v2\nis a bit less susceptible to these types of races, because it has more\nof a request/response flow. But it's still possible (e.g., if the server\nside ever aborts before reading the whole request).\n\nFor this _particular_ test, since we know that it is testing a v0-only\nbehavior, we might want to just loosen the test. This goes against the\npoint of adding it in 014ade7484 (upload-pack: send ERR packet for\nnon-tip objects, 2019-04-13), but it's the best we can do for now.\nSomething like this:\n\ndiff --git a/t/t5516-fetch-push.sh b/t/t5516-fetch-push.sh\nindex 01004ff680..8726d80250 100755\n--- a/t/t5516-fetch-push.sh\n+++ b/t/t5516-fetch-push.sh\n@@ -1260,7 +1260,20 @@ do\n \t\t\tgit cat-file commit $SHA1_2 &&\n \t\t\ttest_must_fail env GIT_TEST_PROTOCOL_VERSION=0 \\\n \t\t\t\tgit fetch ../testrepo/.git $SHA1_3 2>err &&\n-\t\t\ttest_i18ngrep \"remote error:.*not our ref.*$SHA1_3\\$\" err\n+\t\t\t# ideally we would insist this be on a \"remote error:\"\n+\t\t\t# line to make sure an ERR packet was sent. But\n+\t\t\t# checking that is racy, because the client may see the\n+\t\t\t# pipe close while they are still writing their \"done\"\n+\t\t\t# line. So check only that it appears in stderr at all,\n+\t\t\t# which will generally pick up the copy that\n+\t\t\t# upload-pack sends to stderr. This is a hack, because\n+\t\t\t# in the real world the upload-pack stderr would often\n+\t\t\t# not be shown to the client at all (e.g., over git://\n+\t\t\t# or over an ssh channel to a non-vanilla server). So\n+\t\t\t# this is papering over a real racy bug that users\n+\t\t\t# might see in the wild, but this is the best we can do\n+\t\t\t# for now to make our tests robust.\n+\t\t\ttest_i18ngrep \"not our ref.*$SHA1_3\\$\" err\n \t\t)\n \t'\n done\n\n-Peff\n"},{"id":"413906","messageId":"X/mJ6gHrKVxQqPX4@coredump.intra.peff.net","threadId":"54968","inReplyTo":"X/mGnY3wR1fGoxcf@coredump.intra.peff.net","subject":"Re: Is t5516 somehow flakey only on macOS?","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-01-09T10:48:10Z","receivedAt":"2021-01-09T10:48:53Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sat, Jan 09, 2021 at 05:34:05AM -0500, Jeff King wrote:\n\n> For this _particular_ test, since we know that it is testing a v0-only\n> behavior, we might want to just loosen the test. This goes against the\n> point of adding it in 014ade7484 (upload-pack: send ERR packet for\n> non-tip objects, 2019-04-13), but it's the best we can do for now.\n> Something like this:\n\nSince this issue has been languishing for a while now with several\n\"something like this\" patches, I've packaged it up into something more\npalatable. I think we should just apply this and move on. We may still\nrun into other similar races, but I don't think this one is worth\nspending more mental effort on.\n\n-- >8 --\nSubject: [PATCH] t5516: loosen \"not our ref\" error check\n\nCommit 014ade7484 (upload-pack: send ERR packet for non-tip objects,\n2019-04-13) added a test that greps the output of a failed fetch to make\nsure that upload-pack sent us the ERR packet we expected. But checking\nthis is racy; despite the argument in that commit, the client may still\nbe sending a \"done\" line when the server exits, causing it to die() on a\nfailed write() and never see the ERR packet at all.\n\nThis fails quite rarely on Linux, but more often on macOS. However, it\ncan be triggered reliably with:\n\n\tdiff --git a/fetch-pack.c b/fetch-pack.c\n\tindex 876f90c759..cf40de9092 100644\n\t--- a/fetch-pack.c\n\t+++ b/fetch-pack.c\n\t@@ -489,6 +489,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n\t done:\n\t \ttrace2_region_leave(\"fetch-pack\", \"negotiation_v0_v1\", the_repository);\n\t \tif (!got_ready || !no_done) {\n\t+\t\tsleep(1);\n\t \t\tpacket_buf_write(&req_buf, \"done\\n\");\n\t \t\tsend_request(args, fd[1], &req_buf);\n\t \t}\n\nThis is a real user-visible race that it would be nice to fix, but it's\ntricky to do so: the client would have to speculatively try to read an\nERR packet after hitting a write() error. And at least for this error,\nit's specific to v0 (since v2 does not enforce reachability at all).\n\nSo let's loosen to test to avoid annoying racy failures. If we\neventually do the read-after-failed-write thing, we can tighten it. And\nif not, v0 will grow increasingly obsolete as servers support v2, so the\nutility of this test will decrease over time anyway.\n\nNote that we can still check stderr to make sure upload-pack bailed for\nthe reason we expected. It writes a similar message to stderr, and\nbecause the server side is just another process connected by pipes,\nwe'll reliably see it. This would not be the case for git://, or for\nssh servers that do not relay stderr (e.g., GitHub's custom endpoint\ndoes not).\n\nHelped-by: SZEDER Gábor \nSigned-off-by: Jeff King \n---\n t/t5516-fetch-push.sh | 4 +++-\n 1 file changed, 3 insertions(+), 1 deletion(-)\n\ndiff --git a/t/t5516-fetch-push.sh b/t/t5516-fetch-push.sh\nindex 01004ff680..3ed121d0ce 100755\n--- a/t/t5516-fetch-push.sh\n+++ b/t/t5516-fetch-push.sh\n@@ -1260,7 +1260,9 @@ do\n \t\t\tgit cat-file commit $SHA1_2 &&\n \t\t\ttest_must_fail env GIT_TEST_PROTOCOL_VERSION=0 \\\n \t\t\t\tgit fetch ../testrepo/.git $SHA1_3 2>err &&\n-\t\t\ttest_i18ngrep \"remote error:.*not our ref.*$SHA1_3\\$\" err\n+\t\t\t# ideally we would insist this be on a \"remote error:\"\n+\t\t\t# line, but it is racy; see the commit message\n+\t\t\ttest_i18ngrep \"not our ref.*$SHA1_3\\$\" err\n \t\t)\n \t'\n done\n-- \n2.30.0.453.g66a128ec8e\n\n"},{"id":"413908","messageId":"CAPig+cSgeciRLJ07busWu-M9CP4DLWfQxZc3jNmVBaGL0Uq=MA@mail.gmail.com","threadId":"54968","inReplyTo":"X/mJ6gHrKVxQqPX4@coredump.intra.peff.net","subject":"Re: Is t5516 somehow flakey only on macOS?","fromName":"Eric Sunshine","fromEmail":"sunshine@sunshineco.com","sentAt":"2021-01-09T10:57:36Z","receivedAt":"2021-01-09T10:58:45Z","isPatch":false,"sender":{"key":"sunshine@sunshineco.com","avatar":"https://avatars.githubusercontent.com/u/163641?v=4"},"body":"On Sat, Jan 9, 2021 at 5:48 AM Jeff King wrote:\n> Commit 014ade7484 (upload-pack: send ERR packet for non-tip objects,\n> 2019-04-13) added a test that greps the output of a failed fetch to make\n> sure that upload-pack sent us the ERR packet we expected. But checking\n> this is racy; despite the argument in that commit, the client may still\n> be sending a \"done\" line when the server exits, causing it to die() on a\n> failed write() and never see the ERR packet at all.\n> [...]\n> So let's loosen to test to avoid annoying racy failures. If we\n\ns/to test to/the test to/\n\n> eventually do the read-after-failed-write thing, we can tighten it. And\n> if not, v0 will grow increasingly obsolete as servers support v2, so the\n> utility of this test will decrease over time anyway.\n>\n> Note that we can still check stderr to make sure upload-pack bailed for\n> the reason we expected. It writes a similar message to stderr, and\n> because the server side is just another process connected by pipes,\n> we'll reliably see it. This would not be the case for git://, or for\n> ssh servers that do not relay stderr (e.g., GitHub's custom endpoint\n> does not).\n>\n> Helped-by: SZEDER Gábor \n> Signed-off-by: Jeff King \n"},{"id":"413919","messageId":"20210109173336.GS8396@szeder.dev","threadId":"54968","inReplyTo":"X/mJ6gHrKVxQqPX4@coredump.intra.peff.net","subject":"Re: Is t5516 somehow flakey only on macOS?","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2021-01-09T17:33:36Z","receivedAt":"2021-01-09T17:34:22Z","isPatch":false,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"On Sat, Jan 09, 2021 at 05:48:10AM -0500, Jeff King wrote:\n> On Sat, Jan 09, 2021 at 05:34:05AM -0500, Jeff King wrote:\n> \n> > For this _particular_ test, since we know that it is testing a v0-only\n> > behavior, we might want to just loosen the test. This goes against the\n> > point of adding it in 014ade7484 (upload-pack: send ERR packet for\n> > non-tip objects, 2019-04-13), but it's the best we can do for now.\n> > Something like this:\n> \n> Since this issue has been languishing for a while now with several\n> \"something like this\" patches, I've packaged it up into something more\n> palatable. I think we should just apply this and move on. We may still\n> run into other similar races, but I don't think this one is worth\n> spending more mental effort on.\n> \n> -- >8 --\n> Subject: [PATCH] t5516: loosen \"not our ref\" error check\n> \n> Commit 014ade7484 (upload-pack: send ERR packet for non-tip objects,\n> 2019-04-13) added a test that greps the output of a failed fetch to make\n> sure that upload-pack sent us the ERR packet we expected. But checking\n> this is racy; despite the argument in that commit, the client may still\n> be sending a \"done\" line when the server exits, causing it to die() on a\n\nNit: I think using the word \"after\" would make the problematic\nsequence of events a tad clearer, i.e. \"... after the server has\nexited, ...\".\n\n> failed write() and never see the ERR packet at all.\n> \n> This fails quite rarely on Linux, but more often on macOS. However, it\n> can be triggered reliably with:\n> \n> \tdiff --git a/fetch-pack.c b/fetch-pack.c\n> \tindex 876f90c759..cf40de9092 100644\n> \t--- a/fetch-pack.c\n> \t+++ b/fetch-pack.c\n> \t@@ -489,6 +489,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n> \t done:\n> \t \ttrace2_region_leave(\"fetch-pack\", \"negotiation_v0_v1\", the_repository);\n> \t \tif (!got_ready || !no_done) {\n> \t+\t\tsleep(1);\n> \t \t\tpacket_buf_write(&req_buf, \"done\\n\");\n> \t \t\tsend_request(args, fd[1], &req_buf);\n> \t \t}\n\nFWIW (not much?), I've run the test suite with that sleep(1) in place,\nand there were no other test failures.\n\n> This is a real user-visible race that it would be nice to fix, but it's\n> tricky to do so: the client would have to speculatively try to read an\n> ERR packet after hitting a write() error. And at least for this error,\n> it's specific to v0 (since v2 does not enforce reachability at all).\n> \n> So let's loosen to test to avoid annoying racy failures. If we\n> eventually do the read-after-failed-write thing, we can tighten it. And\n> if not, v0 will grow increasingly obsolete as servers support v2, so the\n> utility of this test will decrease over time anyway.\n\nMakes sense. Back then when I investigated this issue the default\nprotocol was still v0; now that we default to v2 I agree its better to\nwork around the issue in the test instead of \"fixing\" the root cause\nwith that \"trying to read ERR packet on error\" hack.\n\nGood, a year-and-a-half old entry checked off from my todo list :)\nThanks.\n\n"},{"id":"413937","messageId":"xmqqsg79eobz.fsf@gitster.c.googlers.com","threadId":"54968","inReplyTo":"X/mJ6gHrKVxQqPX4@coredump.intra.peff.net","subject":"Re: Is t5516 somehow flakey only on macOS?","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2021-01-09T22:29:36Z","receivedAt":"2021-01-09T22:30:28Z","isPatch":false,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jeff King writes:\n\n> Since this issue has been languishing for a while now with several\n> \"something like this\" patches, I've packaged it up into something more\n> palatable. I think we should just apply this and move on. We may still\n> run into other similar races, but I don't think this one is worth\n> spending more mental effort on.\n\nThanks, will queue.\n"},{"id":"413939","messageId":"xmqqo8hxenpr.fsf@gitster.c.googlers.com","threadId":"54968","inReplyTo":"20210109173336.GS8396@szeder.dev","subject":"Re: Is t5516 somehow flakey only on macOS?","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2021-01-09T22:42:56Z","receivedAt":"2021-01-09T22:43:42Z","isPatch":false,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"SZEDER Gábor writes:\n\n>> Commit 014ade7484 (upload-pack: send ERR packet for non-tip objects,\n>> 2019-04-13) added a test that greps the output of a failed fetch to make\n>> sure that upload-pack sent us the ERR packet we expected. But checking\n>> this is racy; despite the argument in that commit, the client may still\n>> be sending a \"done\" line when the server exits, causing it to die() on a\n>\n> Nit: I think using the word \"after\" would make the problematic\n> sequence of events a tad clearer, i.e. \"... after the server has\n> exited, ...\".\n\nThanks everybody for helping with extra clarity. I do find it\neasier to follow with \"after the server has exited\" to picture\nthe sequence of events in my mind.\n"},{"id":"413951","messageId":"X/pzHU917VpQOjfL@coredump.intra.peff.net","threadId":"54968","inReplyTo":"xmqqo8hxenpr.fsf@gitster.c.googlers.com","subject":"Re: Is t5516 somehow flakey only on macOS?","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2021-01-10T03:23:09Z","receivedAt":"2021-01-10T03:24:07Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Sat, Jan 09, 2021 at 02:42:56PM -0800, Junio C Hamano wrote:\n\n> SZEDER Gábor writes:\n> \n> >> Commit 014ade7484 (upload-pack: send ERR packet for non-tip objects,\n> >> 2019-04-13) added a test that greps the output of a failed fetch to make\n> >> sure that upload-pack sent us the ERR packet we expected. But checking\n> >> this is racy; despite the argument in that commit, the client may still\n> >> be sending a \"done\" line when the server exits, causing it to die() on a\n> >\n> > Nit: I think using the word \"after\" would make the problematic\n> > sequence of events a tad clearer, i.e. \"... after the server has\n> > exited, ...\".\n> \n> Thanks everybody for helping with extra clarity. I do find it\n> easier to follow with \"after the server has exited\" to picture\n> the sequence of events in my mind.\n\nAgreed. Here's the same patch with the commit message updated to use\n\"after\", plus Eric's typofix.\n\n-- >8 --\nSubject: [PATCH] t5516: loosen \"not our ref\" error check\n\nCommit 014ade7484 (upload-pack: send ERR packet for non-tip objects,\n2019-04-13) added a test that greps the output of a failed fetch to make\nsure that upload-pack sent us the ERR packet we expected. But checking\nthis is racy; despite the argument in that commit, the client may still\nbe sending a \"done\" line after the server exits, causing it to die() on\na failed write() and never see the ERR packet at all.\n\nThis fails quite rarely on Linux, but more often on macOS. However, it\ncan be triggered reliably with:\n\n\tdiff --git a/fetch-pack.c b/fetch-pack.c\n\tindex 876f90c759..cf40de9092 100644\n\t--- a/fetch-pack.c\n\t+++ b/fetch-pack.c\n\t@@ -489,6 +489,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n\t done:\n\t \ttrace2_region_leave(\"fetch-pack\", \"negotiation_v0_v1\", the_repository);\n\t \tif (!got_ready || !no_done) {\n\t+\t\tsleep(1);\n\t \t\tpacket_buf_write(&req_buf, \"done\\n\");\n\t \t\tsend_request(args, fd[1], &req_buf);\n\t \t}\n\nThis is a real user-visible race that it would be nice to fix, but it's\ntricky to do so: the client would have to speculatively try to read an\nERR packet after hitting a write() error. And at least for this error,\nit's specific to v0 (since v2 does not enforce reachability at all).\n\nSo let's loosen the test to avoid annoying racy failures. If we\neventually do the read-after-failed-write thing, we can tighten it. And\nif not, v0 will grow increasingly obsolete as servers support v2, so the\nutility of this test will decrease over time anyway.\n\nNote that we can still check stderr to make sure upload-pack bailed for\nthe reason we expected. It writes a similar message to stderr, and\nbecause the server side is just another process connected by pipes,\nwe'll reliably see it. This would not be the case for git://, or for\nssh servers that do not relay stderr (e.g., GitHub's custom endpoint\ndoes not).\n\nHelped-by: SZEDER Gábor \nSigned-off-by: Jeff King \n---\n t/t5516-fetch-push.sh | 4 +++-\n 1 file changed, 3 insertions(+), 1 deletion(-)\n\ndiff --git a/t/t5516-fetch-push.sh b/t/t5516-fetch-push.sh\nindex 01004ff680..3ed121d0ce 100755\n--- a/t/t5516-fetch-push.sh\n+++ b/t/t5516-fetch-push.sh\n@@ -1260,7 +1260,9 @@ do\n \t\t\tgit cat-file commit $SHA1_2 &&\n \t\t\ttest_must_fail env GIT_TEST_PROTOCOL_VERSION=0 \\\n \t\t\t\tgit fetch ../testrepo/.git $SHA1_3 2>err &&\n-\t\t\ttest_i18ngrep \"remote error:.*not our ref.*$SHA1_3\\$\" err\n+\t\t\t# ideally we would insist this be on a \"remote error:\"\n+\t\t\t# line, but it is racy; see the commit message\n+\t\t\ttest_i18ngrep \"not our ref.*$SHA1_3\\$\" err\n \t\t)\n \t'\n done\n-- \n2.30.0.455.g8a2dc96235\n\n"}]}