Apparent bug in credential tool running...

Apparent bug in credential tool running...

[Erik Brady -X (brady - ROBERT HALF INTERNATIONAL INC at Cisco)]

Hi git Experts,

I believe we've encountered a bug in git.  I built the latest, git 2.16.3, and it still appears to be a problem.  I'm not a git expert and my C is ridiculously rusty but I think a co-worker and I figured it out... apologies if we are incorrect in any assumptions (as I do not wish to waste anyone's time).

The location of the problem is in credential.c, run_credential_helper()... this code:

   ...
    fp = xfdopen(helper.in, "w");
    credential_write(c, fp);
    fclose(fp);
   ..

Which I think needs to become something like this:

    fp = xfdopen(helper.in, "w");
    sigchain_push(SIGPIPE, SIG_IGN);
    credential_write(c, fp);
    fclose(fp);
    sigchain_pop(SIGPIPE);

The basics are that we wrote a credential helper in Go and, for the store action, it simply exits 0.  It is fast.  This is similar to the example here:

https://git-scm.com/book/en/v2/Git-Tools-Credential-Storage#_a_custom_credential_cache

Which is, of course, in Ruby, not Go (so, not so fast).  It exits if it is not a get cred helper action without reading stdin.  Anyhow, for our credential helper the store operation completes very quickly.  What we've found is that occasionally the git command will be killed off just after running the credential store operation.  We can see that our credential helper is being fired up (it has a debug mode) and it quickly exits.  We can see that git dies on the fclose(fp) by putting trace_printf() calls before and after that fclose in the git source code (ie: the trace message before the fclose() prints, the trace message after the fclose does not).

Our belief is that the write is buffered and written at the time of fclose()... and that the credential helper tool has already exited "sometimes" (as it is very fast, but even so this doesn't fail very often).  For those times when our cred helper has exited "quickly enough", a SIGPIPE can be generated... and, as SIGPIPE is not ignored, git goes "kaboom!" and dies.

To catch this scenario we wrote a simple hack Perl tool to run a bunch of serial git ls-remote commands like so:

#!/usr/cisco/bin/perl -w

$ENV{'GIT_TRACE'} = 2;
$ENV{'GIT_TRACE_CURL'} = 2;
$ENV{'GIT_TRACE_PERFORMANCE'} = 1;
$ENV{'GIT_TRACE_PACKET'} = 1;

for ( my $i = 1; $i<=100000; $i++) {
    print("Run: $i\n");
    my $output = `/ws/brady-sjc/git/git-2.16.3/bin/git ls-remote https://hostname.company.com/git/path/repo.git HEAD 2>&1`;
    if ( $? != 0 ) {
        print("FAIL: output:\n$output\n");
        exit(1);
    }
}
exit(0);

The problem seemed to come up most commonly on older linux VM's... in this case running 2.6.18-416.el5 #1 SMP.  The tool will iterate for a while and then, boom, it blows up (usually within 1000 iterations, sometimes a couple/few thousand but usually well before that).

Anyhow... we did a few things to test our theory that it is, indeed, SIGPIPE causing git to exit:

1) My co-worker modified our credential manager to read in the data sent by git before exiting... that solved the problem as we accept the data written so the child is still there and no SIGPIPE is generated... this is our current workaround (so we are OK, but would be good to fix this in the git code we think)

2) I modified the above code to use a signal handler in credential.c (instead of SIG_IGN) and put a trace_printf() and an exit(1) inside the signal handler... similar to the problem we're seeing it'll run a bunch successfully until, boom, timing is hit such that the child exits quickly enough and causes the SIGPIPE to occur at which point git is killed.... so using the cheesy Perl test script it ran through a couple hundred iterations fine and then a SIGPIPE was seen and it died in the signal handler I wrote... so clearly SIGPIPE is being generated but only occasionally (it is timing based, so occurs only now and then... and we almost never see it on some of our boxes)

3) I modified the git code (using our old cred helper which exits quickly) per the above recommended credential.c changes (you folks can likely do a better fix)... and re-run the Perl test script... no longer fails now that we are ignoring SIGPIPE (ran about 20,000+ iterations).

Note that the build-in credential manager was not failing... it reads the cred helper store data so it would not have the problem.

Let me know if you need any additional information... and thanks for your time and consideration.

Erik
brady@cisco.com

Re: Apparent bug in credential tool running...

[Jeff King]

On Wed, Mar 28, 2018 at 06:26:08PM +0000, Erik Brady -X (brady - ROBERT HALF INTERNATIONAL INC at Cisco) wrote:

> The location of the problem is in credential.c, run_credential_helper()... this code:
> 
>    ...
>     fp = xfdopen(helper.in, "w");
>     credential_write(c, fp);
>     fclose(fp);
>    ..
> 
> Which I think needs to become something like this:
> 
>     fp = xfdopen(helper.in, "w");
>     sigchain_push(SIGPIPE, SIG_IGN);
>     credential_write(c, fp);
>     fclose(fp);
>     sigchain_pop(SIGPIPE);
> 
> The basics are that we wrote a credential helper in Go and, for the
> store action, it simply exits 0.  It is fast.  This is similar to the
> example here:

Yeah, that makes sense. Generally a pipe buffer would be plenty to hold
a credential, but we're racing against whether the other process exits
before we even write anything, so it's bound to fail eventually in a
racy way.

I don't think we've ever made a promise[1] about whether credential
helpers have to read their input, but it makes sense to me for Git to be
friendly and handle this case. We've done similar things for hooks.

Curiously, I have a very similar helper myself, which I did as an inline
shell snippet in my ~/.gitconfig:

  [credential "https://github.com"]
  username = peff
  helper = "!f() { test $1 = get && echo password=`pass peff/github/oauth`; }; f"

I guess I've never lost the race because of the sheer number of
sub-processes that get spawned (shell to "pass" which is itself a shell
script, which spawns gpg -- yikes!).

Do you want to send your change as a patch? There's some guidance in
Documentation/SubmittingPatches.

-Peff

[1] I know you pulled a similar example from the Pro Git book content,
    which we mirror on git-scm.com.  The quality there is usually quite
    good, but I don't consider it as authoritative as the manpages. :)

Re: Apparent bug in credential tool running...

[Erik Brady -X (brady - ROBERT HALF INTERNATIONAL INC at Cisco)]

Sure, I can submit a patch if the change looks good to you (with my lack of experience in the git source and very rusty C I would, of course, defer to an expert in the area on exactly where to place the SIGPIPE ignore push and pop and such... but what's below seems to avoid the race for us.... so I can submit that as-is).

Thanks for the quick response!
Erik

On 3/28/18, 11:46 AM, "Jeff King" <peff@peff.net> wrote:

    On Wed, Mar 28, 2018 at 06:26:08PM +0000, Erik Brady -X (brady - ROBERT HALF INTERNATIONAL INC at Cisco) wrote:
    
    > The location of the problem is in credential.c, run_credential_helper()... this code:
    > 
    >    ...
    >     fp = xfdopen(helper.in, "w");
    >     credential_write(c, fp);
    >     fclose(fp);
    >    ..
    > 
    > Which I think needs to become something like this:
    > 
    >     fp = xfdopen(helper.in, "w");
    >     sigchain_push(SIGPIPE, SIG_IGN);
    >     credential_write(c, fp);
    >     fclose(fp);
    >     sigchain_pop(SIGPIPE);
    > 
    > The basics are that we wrote a credential helper in Go and, for the
    > store action, it simply exits 0.  It is fast.  This is similar to the
    > example here:
    
    Yeah, that makes sense. Generally a pipe buffer would be plenty to hold
    a credential, but we're racing against whether the other process exits
    before we even write anything, so it's bound to fail eventually in a
    racy way.
    
    I don't think we've ever made a promise[1] about whether credential
    helpers have to read their input, but it makes sense to me for Git to be
    friendly and handle this case. We've done similar things for hooks.
    
    Curiously, I have a very similar helper myself, which I did as an inline
    shell snippet in my ~/.gitconfig:
    
      [credential "https://github.com"]
      username = peff
      helper = "!f() { test $1 = get && echo password=`pass peff/github/oauth`; }; f"
    
    I guess I've never lost the race because of the sheer number of
    sub-processes that get spawned (shell to "pass" which is itself a shell
    script, which spawns gpg -- yikes!).
    
    Do you want to send your change as a patch? There's some guidance in
    Documentation/SubmittingPatches.
    
    -Peff
    
    [1] I know you pulled a similar example from the Pro Git book content,
        which we mirror on git-scm.com.  The quality there is usually quite
        good, but I don't consider it as authoritative as the manpages. :)
    

Re: Apparent bug in credential tool running...

[Erik Brady -X (brady - ROBERT HALF INTERNATIONAL INC at Cisco)]

Quick note: I did submit the patch, look for subject line " [PATCH] credential: cred helper fast exit can cause SIGPIPE, crash".

Thanks again Jeff,
Erik