Git push race condition?

Git push race condition?

[Scott Sandler]

Hi folks,

I run a private Git repository (using Gitlab) with about 200 users
doing about 100 pushes per day.

I've noticed that a few times in the past several weeks, we've had
events where pushes have been lost when two people pushed at just
about the same time. The scenario is that two users both have commits
based on commit A, call them B and B'. The user with commit B pushes
at about the same time as the user who pushes B'. Both pushes are
determined to be fast-forwards and both succeed, but B' overwrites B
and B is no longer on origin/master. The server does have B in its
.git directory but the commit isn't on any branch.

I'm confident nobody is force pushing (we have a hook to disallow it
on master branches and I've seen screenshots of both user's clients
after they pushed). Both git clients say "successfully pushed A..B
master -> master" (or A..B') in the output of their push commands.
However, when the user that had B does a fetch, it shows master as
having been force updated.

We have a few pre-receive hooks and post-receive hooks that run on
pushes, and Gitlab has an update hook as well. My original theory was
that this was happening because Git checks if it's a fast-forward
before running hooks, and that the hooks taking a few seconds creates
more opportunity for a race condition to occur.

However, after reading
http://git.661346.n2.nabble.com/push-race-td7569254.html and doing
some of my own testing (creating a hook that runs for 60 seconds and
pushing from two locations to a test repo) this theory seems to be
wrong. With the 60 second sleep hook (tried as an update hook and a
pre-receive hook), I wasn't able to reproduce the problem. The second
pusher always got an error like this:

error: Ref refs/heads/master is at
4584c1f34e07cea2df6abc8e0d407fe016017130 but expected
61b79b6d35b066d054fb3deab550f1c51598cf5f
remote: error: failed to lock refs/heads/master

Which looks like exactly what I'd want Git to be doing in this
scenario, and supports what that archived thread says about how this
should work.

So the question is, how might this be happening and what can I do about it?

Thanks,
Scott

Re: Git push race condition?

[Matthieu Moy]

Scott Sandler <scott.m.sandler@gmail.com> writes:

> Both pushes are
> determined to be fast-forwards and both succeed, but B' overwrites B
> and B is no longer on origin/master. The server does have B in its
> .git directory but the commit isn't on any branch.

Is the reflog enabled on the server? If so, does it say anything about B
and B'?

What filesystem do you use on the server? Is there any kind of NFS, and
if so are you sure that there's only one machine accessing the
filesystem at the same time?

-- 
Matthieu Moy
http://www-verimag.imag.fr/~moy/

Re: Git push race condition?

[Scott Sandler]

It's a bare repo and I didn't realize server-side reflogs were a
thing. Just ran "git config core.logallrefupdates true" in the repo on
the server which seems to be what I should do to enable that.

The server does know about B, it shows up when you do "git show B".
However "git branch --contains B" returns nothing.

The filesystem is ext4 on linux. It's on a virtual machine in our own
datacenter. It's not an NFS share or anything like that, there is
definitely only one server accessing the filesystem at a time.

Gitlab's update hook maintains an event log when any push event
happens, who pushed and which commits. The most recent time this
happened, the first push which was lost occured at 2014-03-24 19:04:51
and the one that overwrote it happened at 2014-03-24 19:05:04. That's
when the update hook ran, not necessarily when the user hit "git
push", but it is notable that it's 13 seconds apart which is a pretty
long time. We do run several hooks for checking coding syntax and
various other things so it's believable to me that the hooks would
take more than 13 seconds on occasion, but based on the testing I did
with the sleep hook it didn't seem like the hooks were actually the
problem.

On Mon, Mar 24, 2014 at 3:44 PM, Matthieu Moy
<Matthieu.Moy@grenoble-inp.fr> wrote:
> Scott Sandler <scott.m.sandler@gmail.com> writes:
>
>> Both pushes are
>> determined to be fast-forwards and both succeed, but B' overwrites B
>> and B is no longer on origin/master. The server does have B in its
>> .git directory but the commit isn't on any branch.
>
> Is the reflog enabled on the server? If so, does it say anything about B
> and B'?
>
> What filesystem do you use on the server? Is there any kind of NFS, and
> if so are you sure that there's only one machine accessing the
> filesystem at the same time?
>
> --
> Matthieu Moy
> http://www-verimag.imag.fr/~moy/

Re: Git push race condition?

[Ævar Arnfjörð Bjarmason]

On Mon, Mar 24, 2014 at 8:18 PM, Scott Sandler
<scott.m.sandler@gmail.com> wrote:
> I run a private Git repository (using Gitlab) with about 200 users
> doing about 100 pushes per day.

Ditto but about 2x those numbers.

> error: Ref refs/heads/master is at
> 4584c1f34e07cea2df6abc8e0d407fe016017130 but expected
> 61b79b6d35b066d054fb3deab550f1c51598cf5f
> remote: error: failed to lock refs/heads/master

I also see this error once in a while. I read the code a while back
and it's basically because there's two levels of locks that
receive-pack tries to get, and it's possible for two pushers to get
the first lock due to a race condition.

I've never seen data loss due to this though, because the inner lock is atomic.

Re: Git push race condition?

[Scott Sandler]

Right. Receiving that error is what happens during my testing with a
hook that sleeps for 60s, and that outcome makes sense. But whatever
is occurring in production must be different, since both users see
successful pushes with the first one just being overwritten.

On Mon, Mar 24, 2014 at 5:16 PM, Ævar Arnfjörð Bjarmason
<avarab@gmail.com> wrote:
> On Mon, Mar 24, 2014 at 8:18 PM, Scott Sandler
> <scott.m.sandler@gmail.com> wrote:
>> I run a private Git repository (using Gitlab) with about 200 users
>> doing about 100 pushes per day.
>
> Ditto but about 2x those numbers.
>
>> error: Ref refs/heads/master is at
>> 4584c1f34e07cea2df6abc8e0d407fe016017130 but expected
>> 61b79b6d35b066d054fb3deab550f1c51598cf5f
>> remote: error: failed to lock refs/heads/master
>
> I also see this error once in a while. I read the code a while back
> and it's basically because there's two levels of locks that
> receive-pack tries to get, and it's possible for two pushers to get
> the first lock due to a race condition.
>
> I've never seen data loss due to this though, because the inner lock is atomic.

Re: Git push race condition?

[Matthieu Moy]

Scott Sandler <scott.m.sandler@gmail.com> writes:

> It's a bare repo and I didn't realize server-side reflogs were a
> thing. Just ran "git config core.logallrefupdates true" in the repo on
> the server which seems to be what I should do to enable that.

That should be it, yes.

> The server does know about B, it shows up when you do "git show B".
> However "git branch --contains B" returns nothing.

That is "normal": git push sends objects to the object store in a
lockless manner, and then updates the reference corresponding to the
branch you're pushing to. So in case of concurrent access, the objects
may be sent, but the reference update will fail. Objects would be
garbage collected by a further "git gc [--prune]".

The "not normal" part is that the race condition on the ref update does
actually break for you.

> Gitlab's update hook maintains an event log when any push event
> happens, who pushed and which commits. The most recent time this
> happened, the first push which was lost occured at 2014-03-24 19:04:51
> and the one that overwrote it happened at 2014-03-24 19:05:04. That's
> when the update hook ran, not necessarily when the user hit "git
> push", but it is notable that it's 13 seconds apart which is a pretty
> long time. We do run several hooks for checking coding syntax and
> various other things so it's believable to me that the hooks would
> take more than 13 seconds on occasion, but based on the testing I did
> with the sleep hook it didn't seem like the hooks were actually the
> problem.

Are you really, really, really sure that there's no force-push involved?
(either "push --force" or "push remotename +branchname")

What you describe really looks like a force-push, or a hook doing a ref
update (e.g. a hook on a dev branch that updates master if the code
passes tests or so).

-- 
Matthieu Moy
http://www-verimag.imag.fr/~moy/

Re: Git push race condition?

[Junio C Hamano]

Matthieu Moy <Matthieu.Moy@grenoble-inp.fr> writes:

> What you describe really looks like a force-push, or a hook doing a ref
> update (e.g. a hook on a dev branch that updates master if the code
> passes tests or so).

... or a filesystem that is broken.  But I thought this is just a
plain-vanilla ext4, nothing exotic, so....  Puzzled.

Re: Git push race condition?

[Jeff King]

On Mon, Mar 24, 2014 at 10:16:52PM +0100, Ævar Arnfjörð Bjarmason wrote:

> > error: Ref refs/heads/master is at
> > 4584c1f34e07cea2df6abc8e0d407fe016017130 but expected
> > 61b79b6d35b066d054fb3deab550f1c51598cf5f
> > remote: error: failed to lock refs/heads/master
> 
> I also see this error once in a while. I read the code a while back
> and it's basically because there's two levels of locks that
> receive-pack tries to get, and it's possible for two pushers to get
> the first lock due to a race condition.
> 
> I've never seen data loss due to this though, because the inner lock is atomic.

The reason is that there are not 2 locks. Each side remembers the "old"
value when it started the operation, and only takes a lock when it comes
time to write the ref (and then checks that the old value is still
current). Two pushes happening simultaneously do not have any idea that
the other is occurring.

-Peff

Re: Git push race condition?

[Jeff King]

On Mon, Mar 24, 2014 at 03:18:14PM -0400, Scott Sandler wrote:

> I've noticed that a few times in the past several weeks, we've had
> events where pushes have been lost when two people pushed at just
> about the same time. The scenario is that two users both have commits
> based on commit A, call them B and B'. The user with commit B pushes
> at about the same time as the user who pushes B'. Both pushes are
> determined to be fast-forwards and both succeed, but B' overwrites B
> and B is no longer on origin/master. The server does have B in its
> .git directory but the commit isn't on any branch.

What version of git are you running on the server? Is it possible that
there is a simultaneous process running `git pack-refs` (e.g., a `git
gc` run by a cron job or similar)?

There were some race conditions fixed last year wherein git could see
stale values of refs, but I do not think they could impact writing to a
ref like this.  When we take the lock on the ref, we always go straight
to the filesystem, so the value we see is up-to-date.

-Peff

Re: Git push race condition?

[Nasser Grainawi]

On Mar 24, 2014, at 4:54 PM, Jeff King <peff@peff.net> wrote:

> On Mon, Mar 24, 2014 at 03:18:14PM -0400, Scott Sandler wrote:
> 
>> I've noticed that a few times in the past several weeks, we've had
>> events where pushes have been lost when two people pushed at just
>> about the same time. The scenario is that two users both have commits
>> based on commit A, call them B and B'. The user with commit B pushes
>> at about the same time as the user who pushes B'. Both pushes are
>> determined to be fast-forwards and both succeed, but B' overwrites B
>> and B is no longer on origin/master. The server does have B in its
>> .git directory but the commit isn't on any branch.
> 
> What version of git are you running on the server? Is it possible that
> there is a simultaneous process running `git pack-refs` (e.g., a `git
> gc` run by a cron job or similar)?

`git gc --auto` could be getting triggered as well, so if you suspect
that you could set gc.auto=0 on the server side.

> 
> There were some race conditions fixed last year wherein git could see
> stale values of refs, but I do not think they could impact writing to a
> ref like this.  When we take the lock on the ref, we always go straight
> to the filesystem, so the value we see is up-to-date.
> 
> -Peff
> --
> To unsubscribe from this list: send the line "unsubscribe git" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

-- 
The Qualcomm Innovation Center, Inc. is a member of Code Aurora 
Forum, hosted by The Linux Foundation

Re: Git push race condition?

[Scott Sandler]

Version of git on the server? git version 1.8.3-rc0

Is there a hook or cron job that updates or gcs this repository or any
refs? No. No cron jobs touching the repo at all, and all the hooks are
read-only. There are pre-receive hooks that either reject a push or
don't based on some checks, there are post-receive hooks that curl to
notify external services like jenkins, and there is gitlab's update
hook which just either allows or denies a push based on gitlab's own
permissions check, and then updates a redis queue
(https://github.com/gitlabhq/gitlab-shell/blob/master/lib/gitlab_update.rb).

Am I absolutely positively sure that it's not a force push? I'm pretty
confident they're not force pushing. This has happened now to 5
different pairs of developers using a variety of Git clients (Git
bash, git cli on mac and linux, sourcetree) and most of them didn't
even know what force push was until I asked them if they had done it.
They're all using ssh URLs for the git remote, not http, in case
that's relevant, and they showed me their git configurations and
nothing looks amiss.

After the first time it happened I also put a pre-receive hook in the
repository to prevent force pushes to master, since I thought that's
what had happened:

while read OLDREV NEWREV REFNAME
do
  if [ "$REFNAME" == "refs/heads/master" -a "$OLDREV" != $(git
merge-base $OLDREV $NEWREV) ]; then
    echo "ERROR: It seems like you are trying to force-push on master."
    exit 1
  fi
done

I did this so that people could still force push on other branches if
they really wanted to (since many mentioned they do this on their
remote branches sometimes). I'm under the impression this hook works
properly since it rejects my attempted force pushes to master.


On Mon, Mar 24, 2014 at 6:59 PM, Nasser Grainawi <nasser@codeaurora.org> wrote:
> On Mar 24, 2014, at 4:54 PM, Jeff King <peff@peff.net> wrote:
>
>> On Mon, Mar 24, 2014 at 03:18:14PM -0400, Scott Sandler wrote:
>>
>>> I've noticed that a few times in the past several weeks, we've had
>>> events where pushes have been lost when two people pushed at just
>>> about the same time. The scenario is that two users both have commits
>>> based on commit A, call them B and B'. The user with commit B pushes
>>> at about the same time as the user who pushes B'. Both pushes are
>>> determined to be fast-forwards and both succeed, but B' overwrites B
>>> and B is no longer on origin/master. The server does have B in its
>>> .git directory but the commit isn't on any branch.
>>
>> What version of git are you running on the server? Is it possible that
>> there is a simultaneous process running `git pack-refs` (e.g., a `git
>> gc` run by a cron job or similar)?
>
> `git gc --auto` could be getting triggered as well, so if you suspect
> that you could set gc.auto=0 on the server side.
>
>>
>> There were some race conditions fixed last year wherein git could see
>> stale values of refs, but I do not think they could impact writing to a
>> ref like this.  When we take the lock on the ref, we always go straight
>> to the filesystem, so the value we see is up-to-date.
>>
>> -Peff
>> --
>> To unsubscribe from this list: send the line "unsubscribe git" in
>> the body of a message to majordomo@vger.kernel.org
>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>
> --
> The Qualcomm Innovation Center, Inc. is a member of Code Aurora
> Forum, hosted by The Linux Foundation
>

Re: Git push race condition?

[Matthieu Moy]

Scott Sandler <scott.m.sandler@gmail.com> writes:

> Is there a hook or cron job that updates or gcs this repository or any
> refs? No. No cron jobs touching the repo at all, and all the hooks are
> read-only.

If you activated the reflog, you can double-check that. Running git
reflog on the server should give you something like this:

$ git reflog show master
bf40764 (HEAD, master) master@{0}: push
2c4fc6d master@{1}: push
e72211a master@{2}: push
...

It should be possible to check the reflog for non-fast forward. I don't
find an obvious way, but a script going through the sha1 list and
checking that each line is an ancestor of the previous should be easy.

I can't exclude the hypothesis of a bug in Git, but my feeling is that
there's an issue with your setup.

-- 
Matthieu Moy
http://www-verimag.imag.fr/~moy/

Re: Git push race condition?

[Scott Sandler]

I'm definitely open to the possibility there's a problem with my
setup. I've got the reflog on now and will check what that looks like
next time the issue happens. So far it looks like you described:

b2b202d master@{0}: push
7c01312 master@{1}: push
3635312 master@{2}: push
aea29bf master@{3}: push
8bfe464 master@{4}: push
fb35676 master@{5}: push
267114e master@{6}: push
2b5c822 master@{7}: push
9d7206f master@{8}: push
8fbeaf9 master@{9}: push

I'd like to see it happen again under these conditions and get that
information, then enable receive.denyNonFastForwards explicitly just
to be sure it's not force pushes, and see if it still happens. If
anyone has other ideas of things to look into or test, let me know.

Thanks,
Scott

On Tue, Mar 25, 2014 at 10:03 AM, Matthieu Moy
<Matthieu.Moy@grenoble-inp.fr> wrote:
> Scott Sandler <scott.m.sandler@gmail.com> writes:
>
>> Is there a hook or cron job that updates or gcs this repository or any
>> refs? No. No cron jobs touching the repo at all, and all the hooks are
>> read-only.
>
> If you activated the reflog, you can double-check that. Running git
> reflog on the server should give you something like this:
>
> $ git reflog show master
> bf40764 (HEAD, master) master@{0}: push
> 2c4fc6d master@{1}: push
> e72211a master@{2}: push
> ...
>
> It should be possible to check the reflog for non-fast forward. I don't
> find an obvious way, but a script going through the sha1 list and
> checking that each line is an ancestor of the previous should be easy.
>
> I can't exclude the hypothesis of a bug in Git, but my feeling is that
> there's an issue with your setup.
>
> --
> Matthieu Moy
> http://www-verimag.imag.fr/~moy/

Re: Git push race condition?

[Matthieu Moy]

(please, don't top-post on this list)

Scott Sandler <scott.m.sandler@gmail.com> writes:

> I'd like to see it happen again under these conditions and get that
> information, then enable receive.denyNonFastForwards explicitly just
> to be sure it's not force pushes, and see if it still happens.

To be really sure, you also have to set receive.denyDeletes to true.
Otherwise, a workaround to perform a non-fast forward is to delete the
branch, and re-create it somewhere else in history.

-- 
Matthieu Moy
http://www-verimag.imag.fr/~moy/

Re: Git push race condition?

[Jeff King]

On Tue, Mar 25, 2014 at 09:45:20AM -0400, Scott Sandler wrote:

> Version of git on the server? git version 1.8.3-rc0

There was significant work done between v1.8.3 and v1.8.4 on handling
races in the ref code. As I said before, I don't think the symptoms you
are describing are anything we have seen, or that could be triggered by
the races we found (which were mostly to do with ref enumeration, not
ref writing). But I would suggest upgrading to a newer version of git as
a precaution.

You mentioned elsewhere turning on the reflog, which I think is a good
idea. If there is a race of this sort, you will see a "hole" in the
reflog, where a ref goes from A->B, then again from A->B' (whereas with
normal writes, it would be B->B').

-Peff

Re: Git push race condition?

[Scott Sandler]

On Tue, Mar 25, 2014 at 10:57 AM, Jeff King <peff@peff.net> wrote:
> On Tue, Mar 25, 2014 at 09:45:20AM -0400, Scott Sandler wrote:
>
>> Version of git on the server? git version 1.8.3-rc0
>
> There was significant work done between v1.8.3 and v1.8.4 on handling
> races in the ref code. As I said before, I don't think the symptoms you
> are describing are anything we have seen, or that could be triggered by
> the races we found (which were mostly to do with ref enumeration, not
> ref writing). But I would suggest upgrading to a newer version of git as
> a precaution.
>
> You mentioned elsewhere turning on the reflog, which I think is a good
> idea. If there is a race of this sort, you will see a "hole" in the
> reflog, where a ref goes from A->B, then again from A->B' (whereas with
> normal writes, it would be B->B').
>
> -Peff

This finally happened again. Here's what the reflog looks like:

2805f68 master@{0}: push
96eebc0 master@{1}: push
75bd4a6 master@{2}: push
abc30da master@{3}: push
eba874f master@{4}: push
10981e7 master@{5}: push
76b3957 master@{6}: push
2e3ea06 master@{7}: push
9d4e778 master@{8}: push
dbd70ae master@{9}: push
508ab4f master@{10}: push
36a0ce4 master@{11}: push
ddc258e master@{12}: push
cf025de master@{13}: push
dbd70ae master@{14}: push
95d33eb master@{15}: push
75b8e9a master@{16}: push

The commit that was lost does not show in the reflog at all, its short
hash was e0de949aa. The commit that "won the race" against it is
9d4e778 (I'm inferring this based on timing since it was pushed at
about the same time as the lost commit).

One interesting thing to note is that dbd70ae shows up at two separate
points in the reflog though, one being directly before the 9d4e778
commit that won the race. According to Gitlab's event log that commit
was just pushed once, right after 95d33eb and before cf025de as it
shows in master@{14} there. The fact that the same commit shows up
again in master@{9} is interesting.

Now that it has happened again and I've got this data, I'm going to
upgrade git but let me know if this provides any insight in the mean
time.

-Scott

Re: Git push race condition?

[Matthieu Moy]

> This finally happened again. Here's what the reflog looks like:
>
> 2805f68 master@{0}: push
> 96eebc0 master@{1}: push
> 75bd4a6 master@{2}: push
> abc30da master@{3}: push
> eba874f master@{4}: push
> 10981e7 master@{5}: push
> 76b3957 master@{6}: push
> 2e3ea06 master@{7}: push
> 9d4e778 master@{8}: push
> dbd70ae master@{9}: push
> 508ab4f master@{10}: push
> 36a0ce4 master@{11}: push
> ddc258e master@{12}: push
> cf025de master@{13}: push
> dbd70ae master@{14}: push
> 95d33eb master@{15}: push
> 75b8e9a master@{16}: push

You can have a look at the actual reflog (.git/logs/refs/heads/master)
which contains a bit more information. It will show you the pairs
(source, destination) for each change.

Normally, the destination of a push is the source of the next one, but
that would be worth checking.

> One interesting thing to note is that dbd70ae shows up at two separate
> points in the reflog though, one being directly before the 9d4e778
> commit that won the race. According to Gitlab's event log that commit
> was just pushed once, right after 95d33eb and before cf025de as it
> shows in master@{14} there. The fact that the same commit shows up
> again in master@{9} is interesting.

My interpretation is that someone/something did a non-fast forward push
at master@{9}, which reverted the history back to dbd70ae, and then
master@{8} did a fast-forward, non-race condition, absolutely normal
push.

Look at the complete reflog line corresponding to master@{9}, it may
give you more information.

> Now that it has happened again and I've got this data, I'm going to
> upgrade git but let me know if this provides any insight in the mean
> time.

If I were you, I'd keep a copy of the complete repo (including reflog &
all) in case.

-- 
Matthieu Moy
http://www-verimag.imag.fr/~moy/