{"thread":{"id":"53214","subject":"Git pull stuck when Trace2 target set to Unix Stream Socket","startedAt":"2020-04-13T12:14:51Z","lastAt":"2020-04-13T18:42:50Z","messageCount":6,"participants":["Son Luong Ngoc","Taylor Blau","Jeff King","Jeff Hostetler"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"395330","messageId":"CAL3xRKceuniEOq+PqN15FC4-mxsWJd4+e2fu1Ku9q_+8JmR9pw@mail.gmail.com","threadId":"53214","inReplyTo":null,"subject":"Git pull stuck when Trace2 target set to Unix Stream Socket","fromName":"Son Luong Ngoc","fromEmail":"sluongng@gmail.com","sentAt":"2020-04-13T12:05:00Z","receivedAt":"2020-04-13T12:14:51Z","isPatch":false,"sender":{"key":"sluongng@gmail.com","avatar":"https://avatars.githubusercontent.com/u/26684313?v=4"},"body":"Hey folks,\n\nI am trying to write a simple git trace2 event collector and I notice\nthat when git doing git pull with trace events being sent to a unix\nstream socket, the entire operation halted.\n\nReproduce as follow:\n```\ncd git/git\ngit config trace2.eventTarget af_unix:stream:/tmp/git_trace.sock\ngit config trace2.eventBrief false\n(rm /tmp/git_trace.sock | ) &&  nc -lkU /tmp/git_trace.sock\n\n# In a different terminal\ngit pull # Pull stuck and never complete\n```\n\nThis does not happen when you set eventBrief to true\n```\ngit config trace2.eventBrief true\n```\n\nWorth to note that if eventTarget is a file instead of a socket,\neverything works fine.\n\nCheers,\nSon Luong.\n"},{"id":"395349","messageId":"20200413160051.GB59601@syl.local","threadId":"53214","inReplyTo":"CAL3xRKceuniEOq+PqN15FC4-mxsWJd4+e2fu1Ku9q_+8JmR9pw@mail.gmail.com","subject":"Re: Git pull stuck when Trace2 target set to Unix Stream Socket","fromName":"Taylor Blau","fromEmail":"me@ttaylorr.com","sentAt":"2020-04-13T16:00:51Z","receivedAt":"2020-04-13T16:00:57Z","isPatch":false,"sender":{"key":"me@ttaylorr.com","avatar":"https://avatars.githubusercontent.com/u/301000140?v=4"},"body":"On Mon, Apr 13, 2020 at 02:05:00PM +0200, Son Luong Ngoc wrote:\n> Hey folks,\n>\n> I am trying to write a simple git trace2 event collector and I notice\n> that when git doing git pull with trace events being sent to a unix\n> stream socket, the entire operation halted.\n>\n> Reproduce as follow:\n> ```\n> cd git/git\n> git config trace2.eventTarget af_unix:stream:/tmp/git_trace.sock\n> git config trace2.eventBrief false\n> (rm /tmp/git_trace.sock | ) &&  nc -lkU /tmp/git_trace.sock\n\nI doubt that this is important (for a reason that I'll point out below),\nbut it looks like your invocation here is malformed with the trailing\npipe character.\n\nDid you mean to redirect the output of rm away? If so, '2>&1 >/dev/null'\nwill do what you want.\n\n> # In a different terminal\n> git pull # Pull stuck and never complete\n> ```\n\nOdd. From my memory, trace2 will give up trying to connect to the socket\n(disabling itself and optionally printing a warning) if 'socket(2)' or\n'connect(2)' set the error bit. My guess above is that you don't have a\nlistening socket (because your shell is waiting for you to close the\n'|'), so there's no connection to be made.\n\n> This does not happen when you set eventBrief to true\n> ```\n> git config trace2.eventBrief true\n> ```\n\nOdd. What version of Git are you using? Your description makes it\nsound like it may be a bug, so I'd be curious to hear Jeff's\ninterpretation of things, too.\n\n> Worth to note that if eventTarget is a file instead of a socket,\n> everything works fine.\n>\n> Cheers,\n> Son Luong.\n\nThanks,\nTaylor\n"},{"id":"395362","messageId":"20200413171812.GA8183@coredump.intra.peff.net","threadId":"53214","inReplyTo":"CAL3xRKceuniEOq+PqN15FC4-mxsWJd4+e2fu1Ku9q_+8JmR9pw@mail.gmail.com","subject":"Re: Git pull stuck when Trace2 target set to Unix Stream Socket","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2020-04-13T17:18:12Z","receivedAt":"2020-04-13T17:18:16Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Mon, Apr 13, 2020 at 02:05:00PM +0200, Son Luong Ngoc wrote:\n\n> I am trying to write a simple git trace2 event collector and I notice\n> that when git doing git pull with trace events being sent to a unix\n> stream socket, the entire operation halted.\n> \n> Reproduce as follow:\n> ```\n> cd git/git\n> git config trace2.eventTarget af_unix:stream:/tmp/git_trace.sock\n> git config trace2.eventBrief false\n> (rm /tmp/git_trace.sock | ) &&  nc -lkU /tmp/git_trace.sock\n> \n> # In a different terminal\n> git pull # Pull stuck and never complete\n> ```\n\nI think the issue is the use of netcat as the server side.\n\nYour git-pull involves multiple simultaneously-running Git processes.\nBut \"nc -k\" will only accept() a new client once the old one has\ndisconnected. So we'd deadlock any time we have this situation:\n\n  - process A opens a stream to the socket, and keeps it open\n\n  - process A spawns process B and waits for it to finish\n\n  - process B tries to open a stream to the socket, which will block\n    waiting for netcat to accept()\n\nNow A cannot make forward progress until B finishes, but B will not make\nforward progress until A closes the socket.\n\nI was able to reproduce the issue locally, and process \"A\" was git-pull\nand process \"B\" was git-merge.\n\nSwitching to using datagrams (\"nc -u\" and \"af_unix:dgram\") makes the\nproblem go away, because the connections are able to interleave their\npackets.\n\n> This does not happen when you set eventBrief to true\n> ```\n> git config trace2.eventBrief true\n> ```\n\nI don't know why this would matter (and it didn't seem to in my tests).\n\n> Worth to note that if eventTarget is a file instead of a socket,\n> everything works fine.\n\nThat makes sense, since their file writes can be interleaved.\n\n-Peff\n"},{"id":"395363","messageId":"D350F464-61DE-4EB6-BBE1-514A0C051F38@gmail.com","threadId":"53214","inReplyTo":"20200413160051.GB59601@syl.local","subject":"Re: Git pull stuck when Trace2 target set to Unix Stream Socket","fromName":"Son Luong Ngoc","fromEmail":"sluongng@gmail.com","sentAt":"2020-04-13T17:19:03Z","receivedAt":"2020-04-13T17:19:19Z","isPatch":false,"sender":{"key":"sluongng@gmail.com","avatar":"https://avatars.githubusercontent.com/u/26684313?v=4"},"body":"Hi Taylor,\n\nThanks for the swift reply.\n\n> On Apr 13, 2020, at 18:00, Taylor Blau <me@ttaylorr.com> wrote:\n> I doubt that this is important (for a reason that I'll point out below),\n> but it looks like your invocation here is malformed with the trailing\n> pipe character.\n> \n> Did you mean to redirect the output of rm away? If so, '2>&1 >/dev/null'\n> will do what you want.\nIt was an emailing mistake. I meant to write\n> rm /tmp/git_trace.sock || true\nSo that the command is reproducible on repeated run.\nI must have deleted the remaining part by mistake.\n\n> Odd. From my memory, trace2 will give up trying to connect to the socket\n> (disabling itself and optionally printing a warning) if 'socket(2)' or\n> 'connect(2)' set the error bit. My guess above is that you don't have a\n> listening socket (because your shell is waiting for you to close the\n> '|'), so there's no connection to be made.\nThere is definitely connection still, as I can still receive more events after interupting the stuck git command by Ctrl-C.\n\n> Odd. What version of Git are you using? Your description makes it\n> sound like it may be a bug, so I'd be curious to hear Jeff's\n> interpretation of things, too.\n2.26.0 built from Master git/git\n\nFor more info, I have created a paste to demonstrate the bug\nhttps://gist.github.com/sluongng/e14563e4ce3cc9545781ecd5a95169f6\nIn which, I run `git pull origin` and `git version` on a relatively stale https://gitlab.com/gitlab-org/gitlab.git local copy.\n\nYou can get more information from the trace in that paste.\nI have annotated the moment which the stuck happened with `It stucks HERE` phrase so look for it.\n\nCheers,\nSon Luong.\n\n"},{"id":"395365","messageId":"20200413172316.GA63249@syl.local","threadId":"53214","inReplyTo":"D350F464-61DE-4EB6-BBE1-514A0C051F38@gmail.com","subject":"Re: Git pull stuck when Trace2 target set to Unix Stream Socket","fromName":"Taylor Blau","fromEmail":"me@ttaylorr.com","sentAt":"2020-04-13T17:23:16Z","receivedAt":"2020-04-13T17:23:23Z","isPatch":false,"sender":{"key":"me@ttaylorr.com","avatar":"https://avatars.githubusercontent.com/u/301000140?v=4"},"body":"On Mon, Apr 13, 2020 at 07:19:03PM +0200, Son Luong Ngoc wrote:\n> Hi Taylor,\n>\n> Thanks for the swift reply.\n>\n> > On Apr 13, 2020, at 18:00, Taylor Blau <me@ttaylorr.com> wrote:\n> > I doubt that this is important (for a reason that I'll point out below),\n> > but it looks like your invocation here is malformed with the trailing\n> > pipe character.\n> >\n> > Did you mean to redirect the output of rm away? If so, '2>&1 >/dev/null'\n> > will do what you want.\n> It was an emailing mistake. I meant to write\n> > rm /tmp/git_trace.sock || true\n\nFor what it's worth, 'rm -f' would suffice, too, but it doesn't matter.\n\n> So that the command is reproducible on repeated run.\n> I must have deleted the remaining part by mistake.\n>\n> > Odd. From my memory, trace2 will give up trying to connect to the socket\n> > (disabling itself and optionally printing a warning) if 'socket(2)' or\n> > 'connect(2)' set the error bit. My guess above is that you don't have a\n> > listening socket (because your shell is waiting for you to close the\n> > '|'), so there's no connection to be made.\n> There is definitely connection still, as I can still receive more events after interupting the stuck git command by Ctrl-C.\n>\n> > Odd. What version of Git are you using? Your description makes it\n> > sound like it may be a bug, so I'd be curious to hear Jeff's\n> > interpretation of things, too.\n> 2.26.0 built from Master git/git\n>\n> For more info, I have created a paste to demonstrate the bug\n> https://gist.github.com/sluongng/e14563e4ce3cc9545781ecd5a95169f6\n> In which, I run `git pull origin` and `git version` on a relatively stale https://gitlab.com/gitlab-org/gitlab.git local copy.\n>\n> You can get more information from the trace in that paste.\n> I have annotated the moment which the stuck happened with `It stucks HERE` phrase so look for it.\n\nHmm. It sounds like maybe there is a bug. If Jeff doesn't have time to\ntake a look, I'll try to figure out what's going on here.\n\n> Cheers,\n> Son Luong.\n\nThanks,\nTaylor\n"},{"id":"395368","messageId":"dde14102-1eeb-71dc-5333-30b21a1ef17a@jeffhostetler.com","threadId":"53214","inReplyTo":"20200413171812.GA8183@coredump.intra.peff.net","subject":"Re: Git pull stuck when Trace2 target set to Unix Stream Socket","fromName":"Jeff Hostetler","fromEmail":"git@jeffhostetler.com","sentAt":"2020-04-13T18:42:43Z","receivedAt":"2020-04-13T18:42:50Z","isPatch":false,"sender":{"key":"git@jeffhostetler.com","avatar":null},"body":"\n\nOn 4/13/2020 1:18 PM, Jeff King wrote:\n> On Mon, Apr 13, 2020 at 02:05:00PM +0200, Son Luong Ngoc wrote:\n> \n>> I am trying to write a simple git trace2 event collector and I notice\n>> that when git doing git pull with trace events being sent to a unix\n>> stream socket, the entire operation halted.\n>>\n>> Reproduce as follow:\n>> ```\n>> cd git/git\n>> git config trace2.eventTarget af_unix:stream:/tmp/git_trace.sock\n>> git config trace2.eventBrief false\n>> (rm /tmp/git_trace.sock | ) &&  nc -lkU /tmp/git_trace.sock\n>>\n>> # In a different terminal\n>> git pull # Pull stuck and never complete\n>> ```\n> \n> I think the issue is the use of netcat as the server side.\n> \n> Your git-pull involves multiple simultaneously-running Git processes.\n> But \"nc -k\" will only accept() a new client once the old one has\n> disconnected. So we'd deadlock any time we have this situation:\n> \n>    - process A opens a stream to the socket, and keeps it open\n> \n>    - process A spawns process B and waits for it to finish\n> \n>    - process B tries to open a stream to the socket, which will block\n>      waiting for netcat to accept()\n> \n> Now A cannot make forward progress until B finishes, but B will not make\n> forward progress until A closes the socket.\n> \n> I was able to reproduce the issue locally, and process \"A\" was git-pull\n> and process \"B\" was git-merge.\n\nThanks for the great explanation.  Yes, each Git command will open\nits own connection to the socket, so you need your server to be\nable to process multiple incoming requests, such as the usual listen()\nloop.\n\nThere is a \"trace2.destinationdebug\" aka GIT_TRACE2_DST_DEBUG which\nwhen set to a positive integer will print warning messages when\nattempting to open the trace2 files or sockets.  This might help you\ntrack down issues.  (These aren't on by default.)\n\nYou might find it easier to set the trace2 path to that of an existing\ndirectory.  Then each Git command will create a file, so you don't have\nto worry about interleaved output or having your server be alive at all\ntimes.  You could just let the files accumulate in that directory and\nhave a cron job process and delete them periodically.\n\nJeff\n"}]}