Git pull stuck when Trace2 target set to Unix Stream Socket

Git pull stuck when Trace2 target set to Unix Stream Socket

[Son Luong Ngoc]

Hey folks,

I am trying to write a simple git trace2 event collector and I notice
that when git doing git pull with trace events being sent to a unix
stream socket, the entire operation halted.

Reproduce as follow:
```
cd git/git
git config trace2.eventTarget af_unix:stream:/tmp/git_trace.sock
git config trace2.eventBrief false
(rm /tmp/git_trace.sock | ) &&  nc -lkU /tmp/git_trace.sock

# In a different terminal
git pull # Pull stuck and never complete
```

This does not happen when you set eventBrief to true
```
git config trace2.eventBrief true
```

Worth to note that if eventTarget is a file instead of a socket,
everything works fine.

Cheers,
Son Luong.

Re: Git pull stuck when Trace2 target set to Unix Stream Socket

[Taylor Blau]

On Mon, Apr 13, 2020 at 02:05:00PM +0200, Son Luong Ngoc wrote:
> Hey folks,
>
> I am trying to write a simple git trace2 event collector and I notice
> that when git doing git pull with trace events being sent to a unix
> stream socket, the entire operation halted.
>
> Reproduce as follow:
> ```
> cd git/git
> git config trace2.eventTarget af_unix:stream:/tmp/git_trace.sock
> git config trace2.eventBrief false
> (rm /tmp/git_trace.sock | ) &&  nc -lkU /tmp/git_trace.sock

I doubt that this is important (for a reason that I'll point out below),
but it looks like your invocation here is malformed with the trailing
pipe character.

Did you mean to redirect the output of rm away? If so, '2>&1 >/dev/null'
will do what you want.

> # In a different terminal
> git pull # Pull stuck and never complete
> ```

Odd. From my memory, trace2 will give up trying to connect to the socket
(disabling itself and optionally printing a warning) if 'socket(2)' or
'connect(2)' set the error bit. My guess above is that you don't have a
listening socket (because your shell is waiting for you to close the
'|'), so there's no connection to be made.

> This does not happen when you set eventBrief to true
> ```
> git config trace2.eventBrief true
> ```

Odd. What version of Git are you using? Your description makes it
sound like it may be a bug, so I'd be curious to hear Jeff's
interpretation of things, too.

> Worth to note that if eventTarget is a file instead of a socket,
> everything works fine.
>
> Cheers,
> Son Luong.

Thanks,
Taylor

Re: Git pull stuck when Trace2 target set to Unix Stream Socket

[Jeff King]

On Mon, Apr 13, 2020 at 02:05:00PM +0200, Son Luong Ngoc wrote:

> I am trying to write a simple git trace2 event collector and I notice
> that when git doing git pull with trace events being sent to a unix
> stream socket, the entire operation halted.
> 
> Reproduce as follow:
> ```
> cd git/git
> git config trace2.eventTarget af_unix:stream:/tmp/git_trace.sock
> git config trace2.eventBrief false
> (rm /tmp/git_trace.sock | ) &&  nc -lkU /tmp/git_trace.sock
> 
> # In a different terminal
> git pull # Pull stuck and never complete
> ```

I think the issue is the use of netcat as the server side.

Your git-pull involves multiple simultaneously-running Git processes.
But "nc -k" will only accept() a new client once the old one has
disconnected. So we'd deadlock any time we have this situation:

  - process A opens a stream to the socket, and keeps it open

  - process A spawns process B and waits for it to finish

  - process B tries to open a stream to the socket, which will block
    waiting for netcat to accept()

Now A cannot make forward progress until B finishes, but B will not make
forward progress until A closes the socket.

I was able to reproduce the issue locally, and process "A" was git-pull
and process "B" was git-merge.

Switching to using datagrams ("nc -u" and "af_unix:dgram") makes the
problem go away, because the connections are able to interleave their
packets.

> This does not happen when you set eventBrief to true
> ```
> git config trace2.eventBrief true
> ```

I don't know why this would matter (and it didn't seem to in my tests).

> Worth to note that if eventTarget is a file instead of a socket,
> everything works fine.

That makes sense, since their file writes can be interleaved.

-Peff

Re: Git pull stuck when Trace2 target set to Unix Stream Socket

[Son Luong Ngoc]

Hi Taylor,

Thanks for the swift reply.

> On Apr 13, 2020, at 18:00, Taylor Blau <me@ttaylorr.com> wrote:
> I doubt that this is important (for a reason that I'll point out below),
> but it looks like your invocation here is malformed with the trailing
> pipe character.
> 
> Did you mean to redirect the output of rm away? If so, '2>&1 >/dev/null'
> will do what you want.
It was an emailing mistake. I meant to write
> rm /tmp/git_trace.sock || true
So that the command is reproducible on repeated run.
I must have deleted the remaining part by mistake.

> Odd. From my memory, trace2 will give up trying to connect to the socket
> (disabling itself and optionally printing a warning) if 'socket(2)' or
> 'connect(2)' set the error bit. My guess above is that you don't have a
> listening socket (because your shell is waiting for you to close the
> '|'), so there's no connection to be made.
There is definitely connection still, as I can still receive more events after interupting the stuck git command by Ctrl-C.

> Odd. What version of Git are you using? Your description makes it
> sound like it may be a bug, so I'd be curious to hear Jeff's
> interpretation of things, too.
2.26.0 built from Master git/git

For more info, I have created a paste to demonstrate the bug
https://gist.github.com/sluongng/e14563e4ce3cc9545781ecd5a95169f6
In which, I run `git pull origin` and `git version` on a relatively stale https://gitlab.com/gitlab-org/gitlab.git local copy.

You can get more information from the trace in that paste.
I have annotated the moment which the stuck happened with `It stucks HERE` phrase so look for it.

Cheers,
Son Luong.

Re: Git pull stuck when Trace2 target set to Unix Stream Socket

[Taylor Blau]

On Mon, Apr 13, 2020 at 07:19:03PM +0200, Son Luong Ngoc wrote:
> Hi Taylor,
>
> Thanks for the swift reply.
>
> > On Apr 13, 2020, at 18:00, Taylor Blau <me@ttaylorr.com> wrote:
> > I doubt that this is important (for a reason that I'll point out below),
> > but it looks like your invocation here is malformed with the trailing
> > pipe character.
> >
> > Did you mean to redirect the output of rm away? If so, '2>&1 >/dev/null'
> > will do what you want.
> It was an emailing mistake. I meant to write
> > rm /tmp/git_trace.sock || true

For what it's worth, 'rm -f' would suffice, too, but it doesn't matter.

> So that the command is reproducible on repeated run.
> I must have deleted the remaining part by mistake.
>
> > Odd. From my memory, trace2 will give up trying to connect to the socket
> > (disabling itself and optionally printing a warning) if 'socket(2)' or
> > 'connect(2)' set the error bit. My guess above is that you don't have a
> > listening socket (because your shell is waiting for you to close the
> > '|'), so there's no connection to be made.
> There is definitely connection still, as I can still receive more events after interupting the stuck git command by Ctrl-C.
>
> > Odd. What version of Git are you using? Your description makes it
> > sound like it may be a bug, so I'd be curious to hear Jeff's
> > interpretation of things, too.
> 2.26.0 built from Master git/git
>
> For more info, I have created a paste to demonstrate the bug
> https://gist.github.com/sluongng/e14563e4ce3cc9545781ecd5a95169f6
> In which, I run `git pull origin` and `git version` on a relatively stale https://gitlab.com/gitlab-org/gitlab.git local copy.
>
> You can get more information from the trace in that paste.
> I have annotated the moment which the stuck happened with `It stucks HERE` phrase so look for it.

Hmm. It sounds like maybe there is a bug. If Jeff doesn't have time to
take a look, I'll try to figure out what's going on here.

> Cheers,
> Son Luong.

Thanks,
Taylor

Re: Git pull stuck when Trace2 target set to Unix Stream Socket

[Jeff Hostetler]

On 4/13/2020 1:18 PM, Jeff King wrote:
> On Mon, Apr 13, 2020 at 02:05:00PM +0200, Son Luong Ngoc wrote:
> 
>> I am trying to write a simple git trace2 event collector and I notice
>> that when git doing git pull with trace events being sent to a unix
>> stream socket, the entire operation halted.
>>
>> Reproduce as follow:
>> ```
>> cd git/git
>> git config trace2.eventTarget af_unix:stream:/tmp/git_trace.sock
>> git config trace2.eventBrief false
>> (rm /tmp/git_trace.sock | ) &&  nc -lkU /tmp/git_trace.sock
>>
>> # In a different terminal
>> git pull # Pull stuck and never complete
>> ```
> 
> I think the issue is the use of netcat as the server side.
> 
> Your git-pull involves multiple simultaneously-running Git processes.
> But "nc -k" will only accept() a new client once the old one has
> disconnected. So we'd deadlock any time we have this situation:
> 
>    - process A opens a stream to the socket, and keeps it open
> 
>    - process A spawns process B and waits for it to finish
> 
>    - process B tries to open a stream to the socket, which will block
>      waiting for netcat to accept()
> 
> Now A cannot make forward progress until B finishes, but B will not make
> forward progress until A closes the socket.
> 
> I was able to reproduce the issue locally, and process "A" was git-pull
> and process "B" was git-merge.

Thanks for the great explanation.  Yes, each Git command will open
its own connection to the socket, so you need your server to be
able to process multiple incoming requests, such as the usual listen()
loop.

There is a "trace2.destinationdebug" aka GIT_TRACE2_DST_DEBUG which
when set to a positive integer will print warning messages when
attempting to open the trace2 files or sockets.  This might help you
track down issues.  (These aren't on by default.)

You might find it easier to set the trace2 path to that of an existing
directory.  Then each Git command will create a file, so you don't have
to worry about interleaved output or having your server be alive at all
times.  You could just let the files accumulate in that directory and
have a cron job process and delete them periodically.

Jeff