{"thread":{"id":"51764","subject":"[PATCH 0/1] upload-pack: fix race condition in t5516","startedAt":"2019-08-28T01:43:33Z","lastAt":"2019-09-10T12:09:07Z","messageCount":15,"participants":["Derrick Stolee via GitGitGadget","SZEDER Gábor","Jeff King","Derrick Stolee"],"isPatch":true,"patchVersion":1,"patchTotal":1},"messages":[{"id":"381415","messageId":"pull.324.git.gitgitgadget@gmail.com","threadId":"51764","inReplyTo":null,"subject":"[PATCH 0/1] upload-pack: fix race condition in t5516","fromName":"Derrick Stolee via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2019-08-28T01:43:29Z","receivedAt":"2019-08-28T01:43:33Z","isPatch":true,"sender":{"key":"stolee@gmail.com","avatar":"https://avatars.githubusercontent.com/u/570044?v=4"},"body":"This patch fixes a strange race condition that was hitting our PR builds on\nmicrosoft/git rather frequently. See [1] for an example.\n\nIt was only happening on the MSVC builds, so somehow that compiler/platform\ncombination was leading to this race condition happening more often than\nother platforms. See the commit message for the race condition.\n\nThe thing I am worried about is that I replaced a die() statement with an\nerror() and exit() pair. Is that OK? Or is there a preferred option?\n\nThanks, -Stolee\n\n[1] https://gvfs.visualstudio.com/ci/_build/results?buildId=16068\n\nDerrick Stolee (1):\n  upload-pack: fix race condition in error messages\n\n upload-pack.c | 5 +++--\n 1 file changed, 3 insertions(+), 2 deletions(-)\n\n\nbase-commit: 5fa0f5238b0cd46cfe7f6fa76c3f526ea98148d9\nPublished-As: https://github.com/gitgitgadget/git/releases/tag/pr-324%2Fderrickstolee%2Ft5516-fix-v1\nFetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-324/derrickstolee/t5516-fix-v1\nPull-Request: https://github.com/gitgitgadget/git/pull/324\n-- \ngitgitgadget\n"},{"id":"381416","messageId":"5c313aba7e97cb93e7d07f6d5dfaf0febe8a2f8b.1566956608.git.gitgitgadget@gmail.com","threadId":"51764","inReplyTo":"pull.324.git.gitgitgadget@gmail.com","subject":"[PATCH 1/1] upload-pack: fix race condition in error messages","fromName":"Derrick Stolee via GitGitGadget","fromEmail":"gitgitgadget@gmail.com","sentAt":"2019-08-28T01:43:29Z","receivedAt":"2019-08-28T01:43:34Z","isPatch":true,"sender":{"key":"stolee@gmail.com","avatar":"https://avatars.githubusercontent.com/u/570044?v=4"},"body":"From: Derrick Stolee <dstolee@microsoft.com>\n\nTest t5516-fetch-push.sh has a test 'deny fetch unreachable SHA1,\nallowtipsha1inwant=true' that checks stderr for a specific error\nstring from the remote. In some build environments the error sent\nover the remote connection gets mingled with the error from the\ndie() statement. Since both signals are being output to the same\nfile descriptor (but from parent and child processes), the output\nwe are matching with grep gets split.\n\nTo reduce the risk of this failure, follow this process instead:\n\n1. Write an error message to stderr.\n2. Write an error message across the connection.\n3. exit(1).\n\nThis reorders the events so the error is written entirely before\nthe client receives a message from the remote, removing the race\ncondition.\n\nSigned-off-by: Derrick Stolee <dstolee@microsoft.com>\n---\n upload-pack.c | 5 +++--\n 1 file changed, 3 insertions(+), 2 deletions(-)\n\ndiff --git a/upload-pack.c b/upload-pack.c\nindex 222cd3ad89..b0d3e028d1 100644\n--- a/upload-pack.c\n+++ b/upload-pack.c\n@@ -613,11 +613,12 @@ static void check_non_tip(struct object_array *want_obj,\n \tfor (i = 0; i < want_obj->nr; i++) {\n \t\tstruct object *o = want_obj->objects[i].item;\n \t\tif (!is_our_ref(o)) {\n+\t\t\twarning(\"git upload-pack: not our ref %s\",\n+\t\t\t\toid_to_hex(&o->oid));\n \t\t\tpacket_writer_error(writer,\n \t\t\t\t\t    \"upload-pack: not our ref %s\",\n \t\t\t\t\t    oid_to_hex(&o->oid));\n-\t\t\tdie(\"git upload-pack: not our ref %s\",\n-\t\t\t    oid_to_hex(&o->oid));\n+\t\t\texit(1);\n \t\t}\n \t}\n }\n-- \ngitgitgadget\n"},{"id":"381428","messageId":"20190828093408.GD8571@szeder.dev","threadId":"51764","inReplyTo":"5c313aba7e97cb93e7d07f6d5dfaf0febe8a2f8b.1566956608.git.gitgitgadget@gmail.com","subject":"Re: [PATCH 1/1] upload-pack: fix race condition in error messages","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2019-08-28T09:34:08Z","receivedAt":"2019-08-28T09:34:15Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"On Tue, Aug 27, 2019 at 06:43:29PM -0700, Derrick Stolee via GitGitGadget wrote:\n> Test t5516-fetch-push.sh has a test 'deny fetch unreachable SHA1,\n> allowtipsha1inwant=true' that checks stderr for a specific error\n> string from the remote. In some build environments the error sent\n> over the remote connection gets mingled with the error from the\n> die() statement. Since both signals are being output to the same\n> file descriptor (but from parent and child processes), the output\n> we are matching with grep gets split.\n\nIn the spirit of \"An error message is worth a thousand words\", I think\nit's worth to include the error message causing the failure:\n\n  error: 'grep not our ref.*64ea4c133d59fa98e86a771eda009872d6ab2886 err' didn't find a match in:\n  fatal: git upload-pack: not our ref 64ea4c13fatal: remote error: upload-pack: not our ref 63d59fa98e86a771eda009872d6ab2886\n  4ea4c133d59fa98e86a771eda009872d6ab2886\n  error: last command exited with $?=1\n\nI tried to reproduce this specific error on Linux and macOS, but\ncouldn't yet.\n\n> To reduce the risk of this failure, follow this process instead:\n\nHere you talk about reducing the risk ...\n\n> 1. Write an error message to stderr.\n> 2. Write an error message across the connection.\n> 3. exit(1).\n> \n> This reorders the events so the error is written entirely before\n> the client receives a message from the remote, removing the race\n> condition.\n\n... but here you talk about removing the race condition.\n\nI don't understand how this change would remove the race condition.\nAfter all, the occasional failure is caused by two messages racing\nthrough different file descriptors, and merely sending them in reverse\norder doesn't change that they would still be racing.\n\n> Signed-off-by: Derrick Stolee <dstolee@microsoft.com>\n> ---\n>  upload-pack.c | 5 +++--\n>  1 file changed, 3 insertions(+), 2 deletions(-)\n> \n> diff --git a/upload-pack.c b/upload-pack.c\n> index 222cd3ad89..b0d3e028d1 100644\n> --- a/upload-pack.c\n> +++ b/upload-pack.c\n> @@ -613,11 +613,12 @@ static void check_non_tip(struct object_array *want_obj,\n>  \tfor (i = 0; i < want_obj->nr; i++) {\n>  \t\tstruct object *o = want_obj->objects[i].item;\n>  \t\tif (!is_our_ref(o)) {\n> +\t\t\twarning(\"git upload-pack: not our ref %s\",\n> +\t\t\t\toid_to_hex(&o->oid));\n>  \t\t\tpacket_writer_error(writer,\n>  \t\t\t\t\t    \"upload-pack: not our ref %s\",\n>  \t\t\t\t\t    oid_to_hex(&o->oid));\n> -\t\t\tdie(\"git upload-pack: not our ref %s\",\n> -\t\t\t    oid_to_hex(&o->oid));\n> +\t\t\texit(1);\n\n\nSo, the error coming from the 'git fetch' command in question\ncurrently looks like this:\n\n  fatal: git upload-pack: not our ref 64ea4c133d59fa98e86a771eda009872d6ab2886\n  fatal: remote error: upload-pack: not our ref 64ea4c133d59fa98e86a771eda009872d6ab2886\n\nChanging die() to a warning() changes the prefix of the message from\n\"fatal:\" to \"warning:\", i.e. with this patch I got this:\n\n  warning: git upload-pack: not our ref 64ea4c133d59fa98e86a771eda009872d6ab2886\n  fatal: remote error: upload-pack: not our ref 64ea4c133d59fa98e86a771eda009872d6ab2886\n\nI don't think that \"demoting\" that message from fatal to warning\nmatters much to users, because they would see the (arguably redundant)\nsecond line starting with \"fatal:\".\n\nAs for the problematic test, it checks this error with:\n\n  test_i18ngrep \"remote error:.*not our ref.*$SHA1_3\\$\" err\n\nso changing that prefix shouldn't affect the test, either.\n\n\nUnfortunately, however, while running './t5516-fetch-push.sh -r 1,79\n--stress' to try to reproduce a failure caused by those mingled\nmessages, the same check only failed for a different reason so far\n(both on Linux and macOS (on Travis CI)):\n\n  error: 'grep remote error:.*not our ref.*64ea4c133d59fa98e86a771eda009872d6ab2886$ err' didn't find a match in:\n  fatal: git upload-pack: not our ref 64ea4c133d59fa98e86a771eda009872d6ab2886\n  fatal: unable to write to remote: Broken pipe\n  error: last command exited with $?=1\n\nAnd with this patch:\n\n  error: 'grep remote error:.*not our ref.*64ea4c133d59fa98e86a771eda009872d6ab2886$ err' didn't find a match in:\n  warning: git upload-pack: not our ref 64ea4c133d59fa98e86a771eda009872d6ab2886\n  fatal: unable to write to remote: Broken pipe\n  error: last command exited with $?=1\n\nWe could make the test pass by relaxing the 'grep' pattern to look\nonly for 'not our ref.*<SHA...>', but I doubt that ignoring a broken\npipe is a such good idea.\n\n"},{"id":"381440","messageId":"20190828145412.GB14432@sigill.intra.peff.net","threadId":"51764","inReplyTo":"20190828093408.GD8571@szeder.dev","subject":"Re: [PATCH 1/1] upload-pack: fix race condition in error messages","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2019-08-28T14:54:12Z","receivedAt":"2019-08-28T14:54:15Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Aug 28, 2019 at 11:34:08AM +0200, SZEDER Gábor wrote:\n\n> On Tue, Aug 27, 2019 at 06:43:29PM -0700, Derrick Stolee via GitGitGadget wrote:\n> > Test t5516-fetch-push.sh has a test 'deny fetch unreachable SHA1,\n> > allowtipsha1inwant=true' that checks stderr for a specific error\n> > string from the remote. In some build environments the error sent\n> > over the remote connection gets mingled with the error from the\n> > die() statement. Since both signals are being output to the same\n> > file descriptor (but from parent and child processes), the output\n> > we are matching with grep gets split.\n> \n> In the spirit of \"An error message is worth a thousand words\", I think\n> it's worth to include the error message causing the failure:\n> \n>   error: 'grep not our ref.*64ea4c133d59fa98e86a771eda009872d6ab2886 err' didn't find a match in:\n>   fatal: git upload-pack: not our ref 64ea4c13fatal: remote error: upload-pack: not our ref 63d59fa98e86a771eda009872d6ab2886\n>   4ea4c133d59fa98e86a771eda009872d6ab2886\n>   error: last command exited with $?=1\n> \n> I tried to reproduce this specific error on Linux and macOS, but\n> couldn't yet.\n\nI suspect it depends on write() to a file not being atomic, since we\nshould be able to get the full message out to a single write in both\ncases. It's _possible_ that stderr is fully buffered on Windows, but it\ngenerally shouldn't be. If it is, then this might help:\n\ndiff --git a/usage.c b/usage.c\nindex 2fdb20086b..d6df31bc5b 100644\n--- a/usage.c\n+++ b/usage.c\n@@ -10,13 +10,19 @@ void vreportf(const char *prefix, const char *err, va_list params)\n {\n \tchar msg[4096];\n \tchar *p;\n-\n-\tvsnprintf(msg, sizeof(msg), err, params);\n+\tsize_t len;\n+\n+\t/* truncation is OK here, but make sure we have a newline */\n+\tlen = xsnprintf(msg, sizeof(msg), \"%s\", prefix);\n+\tlen += vsnprintf(msg + len, sizeof(msg) - len, err, params);\n+\tif (len >= sizeof(msg) - 1)\n+\t\tlen--;\n+\tlen += xsnprintf(msg + len, sizeof(msg) - len, \"\\n\");\n \tfor (p = msg; *p; p++) {\n \t\tif (iscntrl(*p) && *p != '\\t' && *p != '\\n')\n \t\t\t*p = '?';\n \t}\n-\tfprintf(stderr, \"%s%s\\n\", prefix, msg);\n+\twrite(2, msg, len);\n }\n \n static NORETURN void usage_builtin(const char *err, va_list params)\n\nBut again, I'm doubtful.\n\n> Here you talk about reducing the risk ...\n> \n> > 1. Write an error message to stderr.\n> > 2. Write an error message across the connection.\n> > 3. exit(1).\n> > \n> > This reorders the events so the error is written entirely before\n> > the client receives a message from the remote, removing the race\n> > condition.\n> \n> ... but here you talk about removing the race condition.\n> \n> I don't understand how this change would remove the race condition.\n> After all, the occasional failure is caused by two messages racing\n> through different file descriptors, and merely sending them in reverse\n> order doesn't change that they would still be racing.\n\nI had the same puzzlement. I think the answer might be that in the\noriginal, we can have two write()s happening simultaneously:\n\n  1. upload-pack sends the packet to the client\n\n  2. client receives packet\n\n  3a. upload-pack then writes to stderr\n\n  3b. simultaneously, the client writes to stderr\n\nBut by reordering, step 3a is completed before step 1.\n\n> > +\t\t\twarning(\"git upload-pack: not our ref %s\",\n> > +\t\t\t\toid_to_hex(&o->oid));\n> >  \t\t\tpacket_writer_error(writer,\n> >  \t\t\t\t\t    \"upload-pack: not our ref %s\",\n> >  \t\t\t\t\t    oid_to_hex(&o->oid));\n> > -\t\t\tdie(\"git upload-pack: not our ref %s\",\n> > -\t\t\t    oid_to_hex(&o->oid));\n> > +\t\t\texit(1);\n> \n> \n> So, the error coming from the 'git fetch' command in question\n> currently looks like this:\n> \n>   fatal: git upload-pack: not our ref 64ea4c133d59fa98e86a771eda009872d6ab2886\n>   fatal: remote error: upload-pack: not our ref 64ea4c133d59fa98e86a771eda009872d6ab2886\n> \n> Changing die() to a warning() changes the prefix of the message from\n> \"fatal:\" to \"warning:\", i.e. with this patch I got this:\n> \n>   warning: git upload-pack: not our ref 64ea4c133d59fa98e86a771eda009872d6ab2886\n>   fatal: remote error: upload-pack: not our ref 64ea4c133d59fa98e86a771eda009872d6ab2886\n> \n> I don't think that \"demoting\" that message from fatal to warning\n> matters much to users, because they would see the (arguably redundant)\n> second line starting with \"fatal:\".\n\nAn interesting thing about this message is that many users won't see it\nat all! It requires that they be connected to the stderr of upload-pack,\nwhich happens only for local-filesystem clones, and for git-over-ssh to\na vanilla ssh session.\n\nIt won't be seen for git:// nor for https://, which go to the stderr of\ngit-daemon and the webserver respectively. Nor would it be seen on any\nhosting site which uses something other than vanilla sshd to terminate\nthe connection (at GitHub for example, ssh terminates in a proxy layer\nwhich then uses a different protocol to run upload-pack on the backend).\n\nThat's why we've been adding this sideband-level errors: so everybody\ncan see them. So unless the client is a 2005-era version of Git that\nlacks sideband, the die message is either invisible to the user, or\nredundant.\n\nI'd almost suggest it is worth dropping the die() message altogether\nhere, but it does carry some value to people collecting them on the\nserver side[1].\n\nAnother solution is for Git to redirect the stderr of the child\nupload-pack it runs, which puts all invocations on the same footing,\nregardless of protocol. But that risks losing useful messages from\nbefore the sideband starts up (e.g., ssh failures).\n\n[1] At GitHub, we record the exit status of every Git process, and we've\n    hooked die() to record the message, which is often helpful for\n    post-facto debugging. I'd hate to lose it, but we could certainly\n    work around it for this case, perhaps by hooking\n    packet_writer_error() in a similar way.\n\n> Unfortunately, however, while running './t5516-fetch-push.sh -r 1,79\n> --stress' to try to reproduce a failure caused by those mingled\n> messages, the same check only failed for a different reason so far\n> (both on Linux and macOS (on Travis CI)):\n\nThere's some hand-waving argument that this should be race-free in\n014ade7484 (upload-pack: send ERR packet for non-tip objects,\n2019-04-13), but I am not too surprised if there is a flaw in that\nlogic.\n\nThis kind of race is a problem anytime upload-pack dies. And it's not\njust a test issue, but a real problem for users: they might see EPIPE\ninstead of the error message from the server (it used to be SIGPIPE but\nwe recently relaxed that).\n\nThere's details and a possible path forward discussed in:\n\n  https://public-inbox.org/git/20190305041139.GA19800@sigill.intra.peff.net/\n\n-Peff\n"},{"id":"381452","messageId":"20190828153944.GA29715@sigill.intra.peff.net","threadId":"51764","inReplyTo":"20190828145412.GB14432@sigill.intra.peff.net","subject":"Re: [PATCH 1/1] upload-pack: fix race condition in error messages","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2019-08-28T15:39:44Z","receivedAt":"2019-08-28T15:39:46Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Aug 28, 2019 at 10:54:12AM -0400, Jeff King wrote:\n\n> > Unfortunately, however, while running './t5516-fetch-push.sh -r 1,79\n> > --stress' to try to reproduce a failure caused by those mingled\n> > messages, the same check only failed for a different reason so far\n> > (both on Linux and macOS (on Travis CI)):\n> \n> There's some hand-waving argument that this should be race-free in\n> 014ade7484 (upload-pack: send ERR packet for non-tip objects,\n> 2019-04-13), but I am not too surprised if there is a flaw in that\n> logic.\n\nBy the way, I've not been able to reproduce this locally after ~10\nminutes of running \"./t5516-fetch-push.sh -r 1,79 --stress\" on my Linux\nbox. I wonder what's different.\n\nAre you running the tip of master?\n\n-Peff\n"},{"id":"381457","messageId":"20190828161552.GE8571@szeder.dev","threadId":"51764","inReplyTo":"20190828153944.GA29715@sigill.intra.peff.net","subject":"Re: [PATCH 1/1] upload-pack: fix race condition in error messages","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2019-08-28T16:15:52Z","receivedAt":"2019-08-28T16:15:58Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"On Wed, Aug 28, 2019 at 11:39:44AM -0400, Jeff King wrote:\n> On Wed, Aug 28, 2019 at 10:54:12AM -0400, Jeff King wrote:\n> \n> > > Unfortunately, however, while running './t5516-fetch-push.sh -r 1,79\n> > > --stress' to try to reproduce a failure caused by those mingled\n> > > messages, the same check only failed for a different reason so far\n> > > (both on Linux and macOS (on Travis CI)):\n> > \n> > There's some hand-waving argument that this should be race-free in\n> > 014ade7484 (upload-pack: send ERR packet for non-tip objects,\n> > 2019-04-13), but I am not too surprised if there is a flaw in that\n> > logic.\n> \n> By the way, I've not been able to reproduce this locally after ~10\n> minutes of running \"./t5516-fetch-push.sh -r 1,79 --stress\" on my Linux\n> box. I wonder what's different.\n> \n> Are you running the tip of master?\n\nYeah, but this seems to be one of those \"you have to be really lucky,\neven with --stress\" cases.\n\nSo...  I was away for keyboard for over an hour and let it run on\n'master', but it didn't fail.  Then I figured that I give it a try\nwith Derrick's patch, because, well, why not, and then I got this\nbroken pipe error in ~150 repetitions.  Run it again, same error after\n~200 reps.  However, I didn't understand how that patch could lead to\nbroken pipe, so went back to stressing master...  nothing.  So I\nstarted writing the reply to that patch saying that it seems to cause\nsome racy failures on Linux, and was already proofreading before\nsending when the damn thing finally did fail.  Oh, well.\n\nThen tried it on macOS, and it failed fairly quickly.  For lack of\nbetter options I used Travis CI's debug shell to access a mac VM, and\ncould reproduce the failure both with and without the patch before it\ntimeouted.\n\n"},{"id":"381503","messageId":"4d5773f9-4637-d8a3-d683-82624950f319@gmail.com","threadId":"51764","inReplyTo":"20190828161552.GE8571@szeder.dev","subject":"Re: [PATCH 1/1] upload-pack: fix race condition in error messages","fromName":"Derrick Stolee","fromEmail":"stolee@gmail.com","sentAt":"2019-08-29T12:58:55Z","receivedAt":"2019-08-29T12:58:59Z","isPatch":true,"sender":{"key":"stolee@gmail.com","avatar":"https://avatars.githubusercontent.com/u/570044?v=4"},"body":"On 8/28/2019 12:15 PM, SZEDER Gábor wrote:\n> On Wed, Aug 28, 2019 at 11:39:44AM -0400, Jeff King wrote:\n>> On Wed, Aug 28, 2019 at 10:54:12AM -0400, Jeff King wrote:\n>>\n>>>> Unfortunately, however, while running './t5516-fetch-push.sh -r 1,79\n>>>> --stress' to try to reproduce a failure caused by those mingled\n>>>> messages, the same check only failed for a different reason so far\n>>>> (both on Linux and macOS (on Travis CI)):\n>>>\n>>> There's some hand-waving argument that this should be race-free in\n>>> 014ade7484 (upload-pack: send ERR packet for non-tip objects,\n>>> 2019-04-13), but I am not too surprised if there is a flaw in that\n>>> logic.\n>>\n>> By the way, I've not been able to reproduce this locally after ~10\n>> minutes of running \"./t5516-fetch-push.sh -r 1,79 --stress\" on my Linux\n>> box. I wonder what's different.\n>>\n>> Are you running the tip of master?\n> \n> Yeah, but this seems to be one of those \"you have to be really lucky,\n> even with --stress\" cases.\n> \n> So...  I was away for keyboard for over an hour and let it run on\n> 'master', but it didn't fail.  Then I figured that I give it a try\n> with Derrick's patch, because, well, why not, and then I got this\n> broken pipe error in ~150 repetitions.  Run it again, same error after\n> ~200 reps.  However, I didn't understand how that patch could lead to\n> broken pipe, so went back to stressing master...  nothing.  So I\n> started writing the reply to that patch saying that it seems to cause\n> some racy failures on Linux, and was already proofreading before\n> sending when the damn thing finally did fail.  Oh, well.\n> \n> Then tried it on macOS, and it failed fairly quickly.  For lack of\n> better options I used Travis CI's debug shell to access a mac VM, and\n> could reproduce the failure both with and without the patch before it\n> timeouted.\n\nI'm running these tests under --stress now, but not seeing the error\nyou saw.\n\nHowever, I do have a theory: the process exits before flushing the\npacket line. Adding this line before exit(1) should fix it:\n\n\tpacket_writer_flush(writer);\n\nI can send this in a v2, but it would be nice if you could test this\nin your environment that already demonstrated the failure.\n\nThanks,\n-Stolee\n\n"},{"id":"381510","messageId":"20190829141307.GE1797@sigill.intra.peff.net","threadId":"51764","inReplyTo":"4d5773f9-4637-d8a3-d683-82624950f319@gmail.com","subject":"Re: [PATCH 1/1] upload-pack: fix race condition in error messages","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2019-08-29T14:13:07Z","receivedAt":"2019-08-29T14:13:10Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Aug 29, 2019 at 08:58:55AM -0400, Derrick Stolee wrote:\n\n> However, I do have a theory: the process exits before flushing the\n> packet line. Adding this line before exit(1) should fix it:\n> \n> \tpacket_writer_flush(writer);\n> \n> I can send this in a v2, but it would be nice if you could test this\n> in your environment that already demonstrated the failure.\n\nI don't think we should need such a call. For one thing, if it were\nnecessary, that would mean we're not writing out the packet at all. But\nyour whole problem is that we're writing the message twice, one of which\ncomes from the packet.\n\nSecond is that this is not \"flush the output stream\", but \"write a flush\npacket\". The packet_writer_error() function immediately calls write()\nwithout buffering. And no matter where we are in the conversation, a\nflush packet would not be necessary, because the error packet we send\nwould be interpreted immediately by the client as aborting the\nconnection.\n\n-Peff\n"},{"id":"381511","messageId":"131dfa37-0f65-f0c3-6f30-5b6eca12d9c0@gmail.com","threadId":"51764","inReplyTo":"20190829141307.GE1797@sigill.intra.peff.net","subject":"Re: [PATCH 1/1] upload-pack: fix race condition in error messages","fromName":"Derrick Stolee","fromEmail":"stolee@gmail.com","sentAt":"2019-08-29T14:27:16Z","receivedAt":"2019-08-29T14:27:21Z","isPatch":true,"sender":{"key":"stolee@gmail.com","avatar":"https://avatars.githubusercontent.com/u/570044?v=4"},"body":"On 8/29/2019 10:13 AM, Jeff King wrote:\n> On Thu, Aug 29, 2019 at 08:58:55AM -0400, Derrick Stolee wrote:\n> \n>> However, I do have a theory: the process exits before flushing the\n>> packet line. Adding this line before exit(1) should fix it:\n>>\n>> \tpacket_writer_flush(writer);\n>>\n>> I can send this in a v2, but it would be nice if you could test this\n>> in your environment that already demonstrated the failure.\n> \n> I don't think we should need such a call. For one thing, if it were\n> necessary, that would mean we're not writing out the packet at all. But\n> your whole problem is that we're writing the message twice, one of which\n> comes from the packet.\n\nThe problem the flush() was trying to solve was the new \"Broken pipe\" error,\nwhich I had assumed was due to a communication race. (Looking at the message\nmore closely now, I see that Szeder was able to repro this broken pipe both\nwith and without my change. I am still unable to repro the broken pipe.)\n\n> Second is that this is not \"flush the output stream\", but \"write a flush\n> packet\". The packet_writer_error() function immediately calls write()\n> without buffering. And no matter where we are in the conversation, a\n> flush packet would not be necessary, because the error packet we send\n> would be interpreted immediately by the client as aborting the\n> connection.\n\nThis clearly shows that my proposed solution is absolutely wrong.\n\nThanks,\n-Stolee\n\n"},{"id":"381515","messageId":"20190829143805.GB1746@sigill.intra.peff.net","threadId":"51764","inReplyTo":"131dfa37-0f65-f0c3-6f30-5b6eca12d9c0@gmail.com","subject":"Re: [PATCH 1/1] upload-pack: fix race condition in error messages","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2019-08-29T14:38:05Z","receivedAt":"2019-08-29T14:38:55Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Aug 29, 2019 at 10:27:16AM -0400, Derrick Stolee wrote:\n\n> > I don't think we should need such a call. For one thing, if it were\n> > necessary, that would mean we're not writing out the packet at all. But\n> > your whole problem is that we're writing the message twice, one of which\n> > comes from the packet.\n> \n> The problem the flush() was trying to solve was the new \"Broken pipe\" error,\n> which I had assumed was due to a communication race. (Looking at the message\n> more closely now, I see that Szeder was able to repro this broken pipe both\n> with and without my change. I am still unable to repro the broken pipe.)\n\nI think the broken pipe is coming the _other_ way. We do send the packet\nfrom the server to the client, but since the client is still writing\nwhen the server has hung up, we get a write error instead of seeing the\nerror packet.\n\nSo any fixes there have to happen on the client side. I am still\nconfused about why the client is writing in this case, per the argument\nin 014ade7484 (upload-pack: send ERR packet for non-tip objects,\n2019-04-13). It would be nice to use GIT_TRACE_PACKET to see what it's\ntrying to write, but I still haven't been able to reproduce the issue.\n\n-Peff\n"},{"id":"381544","messageId":"20190829215818.GG8571@szeder.dev","threadId":"51764","inReplyTo":"20190829143805.GB1746@sigill.intra.peff.net","subject":"Re: [PATCH 1/1] upload-pack: fix race condition in error messages","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2019-08-29T21:58:18Z","receivedAt":"2019-08-29T21:58:25Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"On Thu, Aug 29, 2019 at 10:38:05AM -0400, Jeff King wrote:\n> So any fixes there have to happen on the client side. I am still\n> confused about why the client is writing in this case, per the argument\n> in 014ade7484 (upload-pack: send ERR packet for non-tip objects,\n> 2019-04-13). It would be nice to use GIT_TRACE_PACKET to see what it's\n> trying to write, but I still haven't been able to reproduce the issue.\n\nIt's the \"done\" line:\n\n  + cat trace-packet\n  packet:  upload-pack> 5e26403b4485d7a44fd8b65dc3f71e21c0dd6fad HEAD\\0multi_ack thin-pack side-band side-band-64k ofs-delta shallow deepen-since deepen-not deepen-relative no-progress include-tag multi_ack_detailed allow-tip-sha1-in-want allow-reachable-sha1-in-want symref=HEAD:refs/heads/master agent=git/2.23.0.40.g4d780d4382.dirty\n  packet:  upload-pack> 5e26403b4485d7a44fd8b65dc3f71e21c0dd6fad refs/heads/master\n  packet:  upload-pack> 0000\n  packet:        fetch< 5e26403b4485d7a44fd8b65dc3f71e21c0dd6fad HEAD\\0multi_ack thin-pack side-band side-band-64k ofs-delta shallow deepen-since deepen-not deepen-relative no-progress include-tag multi_ack_detailed allow-tip-sha1-in-want allow-reachable-sha1-in-want symref=HEAD:refs/heads/master agent=git/2.23.0.40.g4d780d4382.dirty\n  packet:        fetch< 5e26403b4485d7a44fd8b65dc3f71e21c0dd6fad refs/heads/master\n  packet:        fetch< 0000\n  packet:        fetch> want 64ea4c133d59fa98e86a771eda009872d6ab2886 multi_ack_detailed side-band-64k thin-pack no-progress ofs-delta deepen-since deepen-not agent=git/2.23.0.40.g4d780d4382.dirty\n  packet:        fetch> 0000\n  packet:  upload-pack< want 64ea4c133d59fa98e86a771eda009872d6ab2886 multi_ack_detailed side-band-64k thin-pack no-progress ofs-delta deepen-since deepen-not agent=git/2.23.0.40.g4d780d4382.dirty\n  packet:  upload-pack< 0000\n  packet:  upload-pack> ERR upload-pack: not our ref 64ea4c133d59fa98e86a771eda009872d6ab2886\n  packet:  upload-pack> 0000\n  packet:        fetch> done\n\nIn the avarage successful run that \"fetch> done\" pkt-line is\nimmediately after the \"fetch> 0000\".\n\nThe above is on my Linux box; here is a failure on macOS, essentially\nthe same:\n\n  https://travis-ci.org/szeder/git/jobs/578555606#L3453\n\n\n"},{"id":"381545","messageId":"20190829220630.GH8571@szeder.dev","threadId":"51764","inReplyTo":"20190829215818.GG8571@szeder.dev","subject":"Re: [PATCH 1/1] upload-pack: fix race condition in error messages","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2019-08-29T22:06:30Z","receivedAt":"2019-08-29T22:06:37Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"On Thu, Aug 29, 2019 at 11:58:18PM +0200, SZEDER Gábor wrote:\n> On Thu, Aug 29, 2019 at 10:38:05AM -0400, Jeff King wrote:\n> > So any fixes there have to happen on the client side. I am still\n> > confused about why the client is writing in this case, per the argument\n> > in 014ade7484 (upload-pack: send ERR packet for non-tip objects,\n> > 2019-04-13). It would be nice to use GIT_TRACE_PACKET to see what it's\n> > trying to write, but I still haven't been able to reproduce the issue.\n> \n> It's the \"done\" line:\n> \n>   + cat trace-packet\n>   packet:  upload-pack> 5e26403b4485d7a44fd8b65dc3f71e21c0dd6fad HEAD\\0multi_ack thin-pack side-band side-band-64k ofs-delta shallow deepen-since deepen-not deepen-relative no-progress include-tag multi_ack_detailed allow-tip-sha1-in-want allow-reachable-sha1-in-want symref=HEAD:refs/heads/master agent=git/2.23.0.40.g4d780d4382.dirty\n>   packet:  upload-pack> 5e26403b4485d7a44fd8b65dc3f71e21c0dd6fad refs/heads/master\n>   packet:  upload-pack> 0000\n>   packet:        fetch< 5e26403b4485d7a44fd8b65dc3f71e21c0dd6fad HEAD\\0multi_ack thin-pack side-band side-band-64k ofs-delta shallow deepen-since deepen-not deepen-relative no-progress include-tag multi_ack_detailed allow-tip-sha1-in-want allow-reachable-sha1-in-want symref=HEAD:refs/heads/master agent=git/2.23.0.40.g4d780d4382.dirty\n>   packet:        fetch< 5e26403b4485d7a44fd8b65dc3f71e21c0dd6fad refs/heads/master\n>   packet:        fetch< 0000\n>   packet:        fetch> want 64ea4c133d59fa98e86a771eda009872d6ab2886 multi_ack_detailed side-band-64k thin-pack no-progress ofs-delta deepen-since deepen-not agent=git/2.23.0.40.g4d780d4382.dirty\n>   packet:        fetch> 0000\n>   packet:  upload-pack< want 64ea4c133d59fa98e86a771eda009872d6ab2886 multi_ack_detailed side-band-64k thin-pack no-progress ofs-delta deepen-since deepen-not agent=git/2.23.0.40.g4d780d4382.dirty\n>   packet:  upload-pack< 0000\n>   packet:  upload-pack> ERR upload-pack: not our ref 64ea4c133d59fa98e86a771eda009872d6ab2886\n>   packet:  upload-pack> 0000\n>   packet:        fetch> done\n> \n> In the avarage successful run that \"fetch> done\" pkt-line is\n> immediately after the \"fetch> 0000\".\n> \n> The above is on my Linux box; here is a failure on macOS, essentially\n> the same:\n> \n>   https://travis-ci.org/szeder/git/jobs/578555606#L3453\n> \n\nTry this patch to reliably reproduce this failure:\n\ndiff --git a/fetch-pack.c b/fetch-pack.c\nindex 65be043f2a..e18864458b 100644\n--- a/fetch-pack.c\n+++ b/fetch-pack.c\n@@ -471,6 +471,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n \t}\n done:\n \tif (!got_ready || !no_done) {\n+\t\tsleep(1);\n \t\tpacket_buf_write(&req_buf, \"done\\n\");\n \t\tsend_request(args, fd[1], &req_buf);\n \t}\ndiff --git a/t/t5516-fetch-push.sh b/t/t5516-fetch-push.sh\nindex c81ca360ac..ebecc81c89 100755\n--- a/t/t5516-fetch-push.sh\n+++ b/t/t5516-fetch-push.sh\n@@ -1252,7 +1252,9 @@ do\n \t\t\tgit fetch ../testrepo/.git $SHA1_2 &&\n \t\t\tgit cat-file commit $SHA1_2 &&\n \t\t\ttest_must_fail env GIT_TEST_PROTOCOL_VERSION= \\\n+\t\t\t\tGIT_TRACE_PACKET=\"$(pwd)/trace-packet\" \\\n \t\t\t\tgit fetch ../testrepo/.git $SHA1_3 2>err &&\n+\t\t\tcat trace-packet &&\n \t\t\ttest_i18ngrep \"remote error:.*not our ref.*$SHA1_3\\$\" err\n \t\t)\n \t'\n\n"},{"id":"381571","messageId":"20190830121005.GI8571@szeder.dev","threadId":"51764","inReplyTo":"20190829220630.GH8571@szeder.dev","subject":"Re: [PATCH 1/1] upload-pack: fix race condition in error messages","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2019-08-30T12:10:05Z","receivedAt":"2019-08-30T12:10:11Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"On Fri, Aug 30, 2019 at 12:06:30AM +0200, SZEDER Gábor wrote:\n> On Thu, Aug 29, 2019 at 11:58:18PM +0200, SZEDER Gábor wrote:\n> > On Thu, Aug 29, 2019 at 10:38:05AM -0400, Jeff King wrote:\n> > > So any fixes there have to happen on the client side. I am still\n> > > confused about why the client is writing in this case, per the argument\n> > > in 014ade7484 (upload-pack: send ERR packet for non-tip objects,\n> > > 2019-04-13). It would be nice to use GIT_TRACE_PACKET to see what it's\n> > > trying to write, but I still haven't been able to reproduce the issue.\n> > \n> > It's the \"done\" line:\n> > \n> >   + cat trace-packet\n[...]\n> >   packet:  upload-pack> 0000\n> >   packet:        fetch> done\n> > \n> > In the avarage successful run that \"fetch> done\" pkt-line is\n> > immediately after the \"fetch> 0000\".\n\nSo instead of immediately die()int after write_in_full() returned an\nerror, fetch should first try to read all incoming packets in the hope\nthat the remote did send an ERR packet before it died, and then die\nwith the error in that packet, or fall back to the current generic\nerror message if there is no ERR packet (e.g. remote segfaulted or\nsomething similarly horrible).  This fixes the test failure with that\nstrategically-placed sleep() in 'fetch-pack.c'.\n\n  https://travis-ci.org/szeder/git/jobs/578778749#L2689\n\nAlas, passing a 'reader' to a function called send_request() doesn't\nlook quite right, does it...  And I'm not sure about the stateless\ncommunication, it still uses write_or_die().\n\n\ndiff --git a/fetch-pack.c b/fetch-pack.c\nindex e18864458b..773d9c7904 100644\n--- a/fetch-pack.c\n+++ b/fetch-pack.c\n@@ -186,14 +186,27 @@ static enum ack_type get_ack(struct packet_reader *reader,\n }\n \n static void send_request(struct fetch_pack_args *args,\n-\t\t\t int fd, struct strbuf *buf)\n+\t\t\t int fd, struct strbuf *buf,\n+\t\t\t struct packet_reader *reader)\n {\n \tif (args->stateless_rpc) {\n \t\tsend_sideband(fd, -1, buf->buf, buf->len, LARGE_PACKET_MAX);\n \t\tpacket_flush(fd);\n \t} else {\n-\t\tif (write_in_full(fd, buf->buf, buf->len) < 0)\n+\t\tif (write_in_full(fd, buf->buf, buf->len) < 0) {\n+\t\t\tint save_errno = errno;\n+\t\t\t/*\n+\t\t\t * Read everything the remote has sent to us.\n+\t\t\t * If there is an ERR packet, then the loop die()s\n+\t\t\t * with the received error message.\n+\t\t\t * If we reach EOF without seeing an ERR, then die()\n+\t\t\t * with a generic error message, most likely \"Broken\n+\t\t\t * pipe\".\n+\t\t\t */\n+\t\t\twhile (packet_reader_read(reader) != PACKET_READ_EOF);\n+\t\t\terrno = save_errno;\n \t\t\tdie_errno(_(\"unable to write to remote\"));\n+\t\t}\n \t}\n }\n \n@@ -353,7 +366,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n \t\tconst char *arg;\n \t\tstruct object_id oid;\n \n-\t\tsend_request(args, fd[1], &req_buf);\n+\t\tsend_request(args, fd[1], &req_buf, &reader);\n \t\twhile (packet_reader_read(&reader) == PACKET_READ_NORMAL) {\n \t\t\tif (skip_prefix(reader.line, \"shallow \", &arg)) {\n \t\t\t\tif (get_oid_hex(arg, &oid))\n@@ -376,7 +389,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n \t\t\tdie(_(\"expected shallow/unshallow, got %s\"), reader.line);\n \t\t}\n \t} else if (!args->stateless_rpc)\n-\t\tsend_request(args, fd[1], &req_buf);\n+\t\tsend_request(args, fd[1], &req_buf, &reader);\n \n \tif (!args->stateless_rpc) {\n \t\t/* If we aren't using the stateless-rpc interface\n@@ -398,7 +411,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n \t\t\tint ack;\n \n \t\t\tpacket_buf_flush(&req_buf);\n-\t\t\tsend_request(args, fd[1], &req_buf);\n+\t\t\tsend_request(args, fd[1], &req_buf, &reader);\n \t\t\tstrbuf_setlen(&req_buf, state_len);\n \t\t\tflushes++;\n \t\t\tflush_at = next_flush(args->stateless_rpc, count);\n@@ -473,7 +486,7 @@ static int find_common(struct fetch_negotiator *negotiator,\n \tif (!got_ready || !no_done) {\n \t\tsleep(1);\n \t\tpacket_buf_write(&req_buf, \"done\\n\");\n-\t\tsend_request(args, fd[1], &req_buf);\n+\t\tsend_request(args, fd[1], &req_buf, &reader);\n \t}\n \tprint_verbose(args, _(\"done\"));\n \tif (retval != 0) {\n\n"},{"id":"381791","messageId":"20190904050441.GB6488@sigill.intra.peff.net","threadId":"51764","inReplyTo":"20190830121005.GI8571@szeder.dev","subject":"Re: [PATCH 1/1] upload-pack: fix race condition in error messages","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2019-09-04T05:04:42Z","receivedAt":"2019-09-04T05:04:45Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Fri, Aug 30, 2019 at 02:10:05PM +0200, SZEDER Gábor wrote:\n\n> On Fri, Aug 30, 2019 at 12:06:30AM +0200, SZEDER Gábor wrote:\n> > On Thu, Aug 29, 2019 at 11:58:18PM +0200, SZEDER Gábor wrote:\n> > > On Thu, Aug 29, 2019 at 10:38:05AM -0400, Jeff King wrote:\n> > > > So any fixes there have to happen on the client side. I am still\n> > > > confused about why the client is writing in this case, per the argument\n> > > > in 014ade7484 (upload-pack: send ERR packet for non-tip objects,\n> > > > 2019-04-13). It would be nice to use GIT_TRACE_PACKET to see what it's\n> > > > trying to write, but I still haven't been able to reproduce the issue.\n> > > \n> > > It's the \"done\" line:\n> > > \n> > >   + cat trace-packet\n> [...]\n> > >   packet:  upload-pack> 0000\n> > >   packet:        fetch> done\n> > > \n> > > In the avarage successful run that \"fetch> done\" pkt-line is\n> > > immediately after the \"fetch> 0000\".\n\nThanks for all of your persistent digging on this. I had forgotten about\nthe \"done\" packet, but it explains all of the symptoms we've seen.\n\n> So instead of immediately die()int after write_in_full() returned an\n> error, fetch should first try to read all incoming packets in the hope\n> that the remote did send an ERR packet before it died, and then die\n> with the error in that packet, or fall back to the current generic\n> error message if there is no ERR packet (e.g. remote segfaulted or\n> something similarly horrible).  This fixes the test failure with that\n> strategically-placed sleep() in 'fetch-pack.c'.\n> \n>   https://travis-ci.org/szeder/git/jobs/578778749#L2689\n> \n> Alas, passing a 'reader' to a function called send_request() doesn't\n> look quite right, does it...  And I'm not sure about the stateless\n> communication, it still uses write_or_die().\n\nAnd thank you for putting this patch together. I had taken a stab at it\na while ago, but got discouraged by figuring out at which layer to add\nthe \"reader\" info (I had envisioned it much lower in packet_write(), but\nit is clear from your patch that fetch-pack does most of its own\nwriting).\n\nI agree passing around the reader is a bit weird; I wonder if we should\nbe representing the full-duplex connection more clearly as a single\nstruct. But I suspect that creates other headaches, and what you have\nhere doesn't look _too_ bad. As you note, it probably doesn't cover all\ncode paths, but it at least fixes some of them, and gives us a template\nfor addressing the others.\n\n>  \t} else {\n> -\t\tif (write_in_full(fd, buf->buf, buf->len) < 0)\n> +\t\tif (write_in_full(fd, buf->buf, buf->len) < 0) {\n> +\t\t\tint save_errno = errno;\n> +\t\t\t/*\n> +\t\t\t * Read everything the remote has sent to us.\n> +\t\t\t * If there is an ERR packet, then the loop die()s\n> +\t\t\t * with the received error message.\n> +\t\t\t * If we reach EOF without seeing an ERR, then die()\n> +\t\t\t * with a generic error message, most likely \"Broken\n> +\t\t\t * pipe\".\n> +\t\t\t */\n> +\t\t\twhile (packet_reader_read(reader) != PACKET_READ_EOF);\n> +\t\t\terrno = save_errno;\n>  \t\t\tdie_errno(_(\"unable to write to remote\"));\n> +\t\t}\n\nOne unfortunate thing here is that we could block indefinitely in\npacket_reader_read(). That shouldn't happen, I don't think, but since\nthis is an error case where we've been cutoff, anything's possible.\n\nWe maybe could get away with using non-blocking I/O. We're looking for\nan ERR packet the other side sent us _before_ it hung up, so in theory\nwe've have received the data before any FIN packet (or EOF on a pipe).\nBut I'm wary of introducing new races there.\n\nIt might be enough to put in an actual timer, waiting for an ERR packet,\nEOF, or something like 5 seconds. Or maybe I'm just being overly\nparanoid.\n\n-Peff\n"},{"id":"382124","messageId":"20190910120859.GG32087@szeder.dev","threadId":"51764","inReplyTo":"20190904050441.GB6488@sigill.intra.peff.net","subject":"Re: [PATCH 1/1] upload-pack: fix race condition in error messages","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2019-09-10T12:08:59Z","receivedAt":"2019-09-10T12:09:07Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"On Wed, Sep 04, 2019 at 01:04:42AM -0400, Jeff King wrote:\n> On Fri, Aug 30, 2019 at 02:10:05PM +0200, SZEDER Gábor wrote:\n> \n> > On Fri, Aug 30, 2019 at 12:06:30AM +0200, SZEDER Gábor wrote:\n> > > On Thu, Aug 29, 2019 at 11:58:18PM +0200, SZEDER Gábor wrote:\n> > > > On Thu, Aug 29, 2019 at 10:38:05AM -0400, Jeff King wrote:\n> > > > > So any fixes there have to happen on the client side. I am still\n> > > > > confused about why the client is writing in this case, per the argument\n> > > > > in 014ade7484 (upload-pack: send ERR packet for non-tip objects,\n> > > > > 2019-04-13). It would be nice to use GIT_TRACE_PACKET to see what it's\n> > > > > trying to write, but I still haven't been able to reproduce the issue.\n> > > > \n> > > > It's the \"done\" line:\n> > > > \n> > > >   + cat trace-packet\n> > [...]\n> > > >   packet:  upload-pack> 0000\n> > > >   packet:        fetch> done\n> > > > \n> > > > In the avarage successful run that \"fetch> done\" pkt-line is\n> > > > immediately after the \"fetch> 0000\".\n> \n> Thanks for all of your persistent digging on this.\n\nYeah, I can be easily distracted by an interesting looking bug... was\ntold it's a character flaw ;)\n\n> I had forgotten about\n> the \"done\" packet, but it explains all of the symptoms we've seen.\n> \n> > So instead of immediately die()int after write_in_full() returned an\n> > error, fetch should first try to read all incoming packets in the hope\n> > that the remote did send an ERR packet before it died, and then die\n> > with the error in that packet, or fall back to the current generic\n> > error message if there is no ERR packet (e.g. remote segfaulted or\n> > something similarly horrible).  This fixes the test failure with that\n> > strategically-placed sleep() in 'fetch-pack.c'.\n> > \n> >   https://travis-ci.org/szeder/git/jobs/578778749#L2689\n> > \n> > Alas, passing a 'reader' to a function called send_request() doesn't\n> > look quite right, does it...  And I'm not sure about the stateless\n> > communication, it still uses write_or_die().\n> \n> And thank you for putting this patch together. I had taken a stab at it\n> a while ago, but got discouraged by figuring out at which layer to add\n> the \"reader\" info (I had envisioned it much lower in packet_write(), but\n> it is clear from your patch that fetch-pack does most of its own\n> writing).\n> \n> I agree passing around the reader is a bit weird;\n\nI considered renaming send_request() so that 'reader' won't look that\nout of place among its parameters, but all my ideas were ridiculous,\ne.g. send_request_and_process_ERR_pkt_on_error()...\n\n> I wonder if we should\n> be representing the full-duplex connection more clearly as a single\n> struct. But I suspect that creates other headaches, and what you have\n> here doesn't look _too_ bad. As you note, it probably doesn't cover all\n> code paths, but it at least fixes some of them, and gives us a template\n> for addressing the others.\n> \n> >  \t} else {\n> > -\t\tif (write_in_full(fd, buf->buf, buf->len) < 0)\n> > +\t\tif (write_in_full(fd, buf->buf, buf->len) < 0) {\n> > +\t\t\tint save_errno = errno;\n> > +\t\t\t/*\n> > +\t\t\t * Read everything the remote has sent to us.\n> > +\t\t\t * If there is an ERR packet, then the loop die()s\n> > +\t\t\t * with the received error message.\n> > +\t\t\t * If we reach EOF without seeing an ERR, then die()\n> > +\t\t\t * with a generic error message, most likely \"Broken\n> > +\t\t\t * pipe\".\n> > +\t\t\t */\n> > +\t\t\twhile (packet_reader_read(reader) != PACKET_READ_EOF);\n> > +\t\t\terrno = save_errno;\n> >  \t\t\tdie_errno(_(\"unable to write to remote\"));\n> > +\t\t}\n> \n> One unfortunate thing here is that we could block indefinitely in\n> packet_reader_read(). That shouldn't happen, I don't think, but since\n> this is an error case where we've been cutoff, anything's possible.\n\nYeah, when we use different file descriptors for reading and writing,\nthen any error on the writing fd doesn't necessarily mean that there\nis on an error on the reading fd as well.  I mean, we could get an\nEBADF or EFAULT as well, but those would rather indicate a bug in Git\nthan an error with the connection itself.\n\nI wondered whether we could avoid blocking indefinitely by looking for\nan ERR packet only if the write() resulted in ECONNRESET or EPIPE,\ni.e. that indicate a connection error.  I suppose 'git upload-pack'\n(or an alternative implementation) could be buggy and could\ninadvertently close() the other end of the fd that fetch-pack writes\nto but not the fd where it reads from, so the write() would get\nECONNRESET, but then packet_reader_read() could still hang on the\nstill open read fd.  I'm not sure whether it's worth worrying about; I\nmean a buggy 'git upload-pack' can do all kinds of weird things that\nwould lead to a hang.\n\nAnyway, after write_in_full() returns with error we could first print\nan error message with error_errno() and then go on to look for an ERR\npacket.  So even if packet_reader_read() hangs, at least there will be\nan error message for the user to see.  It wouldn't help automation,\nthough.\n\n> We maybe could get away with using non-blocking I/O. We're looking for\n> an ERR packet the other side sent us _before_ it hung up, so in theory\n> we've have received the data before any FIN packet (or EOF on a pipe).\n> But I'm wary of introducing new races there.\n> \n> It might be enough to put in an actual timer, waiting for an ERR packet,\n> EOF, or something like 5 seconds. Or maybe I'm just being overly\n> paranoid.\n\nI think the timeout would be the safest bet, but then we would have to\npass that timeout parameter through a couple of a function calls...\n\n"}]}