Git push fails with "error: 'trunk@46129' is out of date: it has been modified externally at r46130"

On two different occasions this month, our users have been unable to do a “git push” because of a message like the one above. I quote in detail:

----snip----
harold@gpu-P1080-1:~/d2s_sw$ git push
Enumerating objects: 139, done.
Counting objects: 100% (87/87), done.
Delta compression using up to 4 threads.
Compressing objects: 100% (19/19), done.
Writing objects: 100% (19/19), 2.31 KiB | 2.31 MiB/s, done.
Total 19 (delta 14), reused 0 (delta 0)
remote: error: ‘trunk@46129’ is out of date: it has been modified externally at r46130; retry the operation once again
remote:
remote: Fetching revisions from SVN repository:
remote: up to date
remote: Sending commits to SVN repository:
To http://githost:7990/scm/dp/d2s_sw.git
! [remote rejected] master -> master (pre-receive hook declined)
error: failed to push some refs to ‘http://harold@githost:7990/scm/dp/d2s_sw.git
harold@gpu-P1080-1:~/d2s_sw$
----snip----

We’ve been able to work around this issue by going to the svn tree and checking in a trivial change. This isn’t a good long term solution, though.

Any ideas?

–Harold Z.

Hello Harold,
may I ask you to send to us the logs from GIT_REPO/subgit/logs/ directory (svnmirror.log file corresponding to that error and time period)?

From the first glance it looks like a normal out-of-date error and if this is really is so (the log should give the answers), the solution is simple: run
{code}
git pull --rebase
{code}
command and then retry pushing:
{code}
git push
{code}
Probably we should have these instructions included into the error message.

I’ll give you some more details about why the error happens. When you run “git push”, SVN Mirror add-on starts a new SVN revision creation transaction, something like this:
{code}
openRoot //i.e. begin SVN revision creation transaction

… //describe some changes to be made in that new SVN revsion to be created

closeDir
// <------ at this moment it checks SVN whether the transaction is not out-of-date
closeEdit //i.e. commit the transaction (or abortEdit to rollback the transaction)
{code}

You can see these openRoot/…/closeDir/closeEdit commands in the log. Before committing the transaction it checks that the transaction is not out-of-date, i.e. if there’re no other revisions created in the same SVN branch in this period. And in your case there’s one: trunk@46130. In this case instead of committing the transaction with “closeEdit” command it rolls it back with “abortEdit” command and reports an error (the one you see).

So this is not something extraordinary, probably the error message is just misleading, we should make it more clear.

There’s one more possible situation:
{code}
openRoot //i.e. begin SVN revision creation transaction

… //describe some changes to be made in that new SVN revsion to be created

closeDir
// <------ at this moment it checks SVN whether the transaction is not out-of-date

// <------ but at this moment a new SVN revision appears

closeEdit //i.e. commit the transaction, because the check didn’t find any external change
// <----- perform one more check here
{code}
i.e. a new external revision appeared after the check. There’re 2 possibities:

  • if that new external revision changes at least one file changed in this transaction (the condition is a bit more complicated than that, but for the majority of the cases it’s like this), then SVN server automatically refuses our transaction and SVN Mirror add-on shows an out-of-date error and proposes to run “git pull --rebase”; I’m sure you saw that many times;
  • but if that new external revision changes different set of files, the SVN server creates the new revision on the top of the external revision(!).

In the latter case, SVN Mirror add-on rejects “git push” despite the fact that the new SVN revision was created. In this case you have to run “git pull --rebase”. After this command you’ll have your commit effectively pushed.

This is because SVN Mirror add-on then translates the new SVN revision it just created back to Git. It will be effectively the same commit like the one you tried to push except that it is now created on the top of the externally created revision, not on the top of the original commit you have locally. When you run “git pull --rebase”, Git will realize that your local (“rejected”) commit has the same changes as that commit translated from SVN and will make ‘origin/master’ point to ‘master’, as if your push is successful.

I hope my explanation is clear, feel free to ask any questions if no.

In either case whenever you have an out-of-date error, the rule of thumb: run
{code}
git pull --rebase
{code}
and retry pushing if you still have local commits.

I’ve attached the svnmirror.log file.

I should note that this particular issue led to “git push” failing consistently for nearly a dozen hours, until it was resolved by doing a bogus change and an “svn commit” on the local svn tree. It isn’t a race condition; this was a persistent issue.

I’ll inform my team to try “git pull --rebase” or something similar (I assume a plain “git pull” would work).

Is it possible that this could happen if someone made an svn change to some part of the tree that isn’t being mirrored? I’m just brainstorming, here.

Thanks for the quick response.

I don’t see the error in the log. Could it be another log file in the same directory or even another repository? Or better attach the whole directory. In the log attached I see 46096 and then immediately 46113; the error was about trunk but the URL is svn://…/tags/dev

“git pull” is not the same as “git pull --rebase” and I highly recommend you to prefer the latter variant; although “git pull” might work as well in the scenario I described it could lead to a history with 2 commits with the same messages that might be confusing.

Is it possible that this could happen if someone made an svn change to some part of the tree that isn’t being mirrored? — this is possible as well if it’s the same branch, even when it changes the part of the tree that is mirrored but other files were changed.

Sorry, wrong repository. Here’s the proper log, I think.

Thanks, now the log is correct. If you don’t mind, I’ll have a closer look at it tomorrow as it’s a deep night here.

As I see, revisions 46129, 46130, 46131 were created from Git, so the situation is not as simple as I imagined it originally.
My first guess: there could be a .lock file left somewhere in GIT_REPO/refs/… for some reasons, so the references couldn’t be updated, but a random change to SVN could force the add-on to remove the .lock file. So if this happens again, check:
{code}
find GIT_REPO/refs/ | grep lock
{code}
and remove the lock file if there’s any.

But I have to discuss the problem with colleagues, I’ll do that tomorrow or on Friday.

We have a workaround for now (checking something in to the svn tree), so take your time.

Closer analysis shows the following.

{code}
r46129: updates trunk (i.e. ‘master’) 2b1e6ced483db9e227c05c3a48b483970384926c->377324f2e9b37e43f8f1e05202d07761354634c2
r46130: updates trunk (i.e. ‘master’) 377324f2e9b37e43f8f1e05202d07761354634c2->66e4d2fba8de0ee08985bba3ee6893560040d77f
{code}

There’s a detail: the SVN Mirror add-on updates only refs/svn/root/… references while to update refs/heads/master we rely on Bitbucket. The process is like the following:

  1. the user pushes a change to ‘master’ to the repository;
  2. when processing this push, Bitbucket Server doesn’t updates the reference first, but instead it allows SVN Mirror add-on to do its job and passes the information about the old and new SHA-1 hashes — where refs/heads/master points and will point;
  3. the job of SVN Mirror add-on is to create an SVN revision and to update refs/svn/root/trunk reference to point to the new refs/heads/master position; so when Bitbucket Server will finally update refs/heads/master, both reference will point to the same commit (it’s a normal state of the repository);
  4. once SVN Mirror add-on and other hooks finish their jobs, Bitbucket Server updates the reference.

The corresponding place in the log — end of (3) before (4) should happen:
{code}
2019-01-15 15:31:58,374 sync - about to refresh repository
2019-01-15 15:31:58,374 sync - ref delta: 372860e4c60c52d3c2ca103e0e9152d40126b5bd 470c67f5187ddaf8018cf7a88cbcd5c3e839fb64 refs/tags/dev
2019-01-15 15:31:58,374 sync - ref delta: 66e4d2fba8de0ee08985bba3ee6893560040d77f 377324f2e9b37e43f8f1e05202d07761354634c2 refs/heads/master
{code}

I suspect that for some reasons (I think, it’s a bug in Bitbucket Server), the Bitbucket Server doesn’t perform step (4) i.e. it doesn’t update refs/heads/master.

Could I ask you to attach BITBUCKET_HOME/log/atlassian-bitbucket.log (or the one corresponding to “2019-01-15 15:31:58”)? I’m curious if Bitbucket Server reports any errors near that time stamp, or just silently skips updating refs/heads/master. Or you could lookup that yourself instead of attaching.

As result, the most probably refs/heads/master stay at its old value 377324f2e9b37e43f8f1e05202d07761354634c2 and then later another “git push” comes:

{code}
NEW REVISION: tries to update trunk (i.e. ‘master’) 377324f2e9b37e43f8f1e05202d07761354634c2 ->ff414c83f1b59d142bb312980ca397a5a026b508
{code}

So it updates refs/heads/master from “377324…” to some another commit although after r46130 refs/heads/master already should point to “66e4d2…”, but as I suspect, Bitbucket Server didn’t perform step (4), i.e. didn’t update refs/heads/master.

So the repository is in invalid state as result. When you change trunk directly from SVN, SVN Mirror add-on translates the change to Git and updates refs/heads/master to the correct commit thus solving the problem.

Another thing I would ask you to do is to run
{code}
git log -p refs/svn/map
{code}
to see if all 46129, 46130, 46131 or attach the whole output if you’re not sure.

I’ll discuss the problem with my colleagues tomorrow to see whether the problem could be caused by something else than by Bitbucket Server bug.

The atlassian-bitbucket-2019-01-15.log is pretty boring. There are some messages from a few minutes after the checkin in question. I’m not sure if they’re relevant or not:

—snip—
2019-01-15 03:16:22,196 INFO [Caesium-1-3] c.a.b.i.s.c.j.c.HealthCheckRunner Running up to 2 search health checks
2019-01-15 03:16:22,202 INFO [I/O dispatcher 209] c.a.b.s.s.t.DefaultElasticsearchConnectionTester Connected to Elasticsearch version 5.5.3
2019-01-15 03:16:22,213 INFO [Caesium-1-3] c.a.b.i.s.c.j.c.HealthCheckRunner Health checks will run again after PT12H
2019-01-15 09:47:09,870 WARN [Caesium-1-2] com.atlassian.upm.pac.PacClientImpl Update check request may take longer because of the number of apps
2019-01-15 15:16:22,213 INFO [Caesium-1-4] c.a.b.i.s.c.j.c.HealthCheckRunner Running up to 2 search health checks
2019-01-15 15:16:22,225 INFO [I/O dispatcher 217] c.a.b.s.s.t.DefaultElasticsearchConnectionTester Connected to Elasticsearch version 5.5.3
2019-01-15 15:16:22,235 INFO [Caesium-1-4] c.a.b.i.s.c.j.c.HealthCheckRunner Health checks will run again after PT12H
2019-01-15 15:37:50,819 INFO [io-pump:thread-95] @6GA02Kx937x11663x0 10.16.0.80 “POST /scm/dp/d2s_sw.git/git-upload-pack HTTP/1.1” c.a.s.i.w.filters.StreamGuardFilter The remote client has aborted the connection
2019-01-15 15:37:50,821 INFO [io-pump:thread-97] @6GA02Kx937x11666x3 10.16.0.80 “POST /scm/dp/d2s_sw.git/git-upload-pack HTTP/1.1” c.a.s.i.w.filters.StreamGuardFilter The remote client has aborted the connection
2019-01-15 15:37:50,832 INFO [io-pump:thread-83] @6GA02Kx937x11665x2 10.16.0.80 “POST /scm/dp/d2s_sw.git/git-upload-pack HTTP/1.1” c.a.s.i.w.filters.StreamGuardFilter The remote client has aborted the connection
2019-01-15 19:29:25,318 INFO [hook-callback:thread-2] lusha @6GA02Kx1169x12216x0 10.16.0.125 “POST /scm/dp/d2s_sw.git/git-receive-pack HTTP/1.1” c.a.s.i.h.r.DefaultRepositoryHookService [DP/d2s_sw[13]] hook ‘svnmirror-hook’ vetoed the push request
2019-01-15 19:47:14,529 INFO [hook-callback:thread-2] lusha @6GA02Kx1187x12221x0 10.16.0.125 “POST /scm/dp/d2s_sw.git/git-receive-pack HTTP/1.1” c.a.s.i.h.r.DefaultRepositoryHookService [DP/d2s_sw[13]] hook ‘svnmirror-hook’ vetoed the push request
2019-01-15 19:47:33,367 INFO [hook-callback:thread-2] lusha @6GA02Kx1187x12226x0 10.16.0.125 “POST /scm/dp/d2s_sw.git/git-receive-pack HTTP/1.1” c.a.s.i.h.r.DefaultRepositoryHookService [DP/d2s_sw[13]] hook ‘svnmirror-hook’ vetoed the push request
2019-01-15 19:48:29,201 INFO [hook-callback:thread-2] lusha @6GA02Kx1188x12232x0 10.16.0.125 “POST /scm/dp/d2s_sw.git/git-receive-pack HTTP/1.1” c.a.s.i.h.r.DefaultRepositoryHookService [DP/d2s_sw[13]] hook ‘svnmirror-hook’ vetoed the push request
—snip—

Your proposed “git log” command didn’t work. I’m a relative git novice–the one-eyed man leading the blind–so it wouldn’t surprise me if there’s some magic detail missing that would be obvious to an expert. However, this is what I got:

—snip—
harold@gpu-P1080-1:~/d2s_sw$ git log -p refs/svn/map
fatal: ambiguous argument ‘refs/svn/map’: unknown revision or path not in the working tree.
Use ‘–’ to separate paths from revisions, like this:
‘git […] – […]’
harold@gpu-P1080-1:~/d2s_sw$
—snip—

I’ve discussed the problem with my colleagues. The most likely you had a lock file left for refs/svn/root/trunk reference, i.e. GIT_REPO/refs/svn/root/trunk.lock file. It created problems while pushing, but when you changed trunk in SVN, SVN Mirror add-on’s mechanism removed the lock thus fixing the problem (you could also have fixed the problem just by removing the lock file).

Thanks for the log, it is boring indeed.

Regarding “git log -v refs/svn/map”, it should be run from within the GIT repository in Bitbucket Server (you can find the repository path on repository settings page, looks like BITBUCKET_HOME/shared/data/repositories/). This is optional, but it’s better to check that you have all these strings in the output: “r46129”, “r46130”, “r46131”. If yes, we can be 100% calm. But if you decide not to check, that’s still ok.

Ah. Here’s the rest of the log, and it does contain all the strings in question.

So, I’m glad we can be 100% calm. Is there a way to arrange for this problem not to recur? :-) We’ve had it twice this month, which is, by definition, not a one-off. Is there some monitoring we could do, should it recur?

At the moment we don’t know what to do to prevent this problem (if we knew we would make the add-on to do itself). We will try to find out.

Maybe the what could be monitored is lock files in GIT_REPO/refs, like
{code}
GIT_REPO/refs/svn/root/trunk.lock
GIT_REPO/refs/svn/root/branches/branch.lock
GIT_REPO/refs/svn/root/tags/tag.lock
{code}
and so on. So the command would be
{code}
find -name *.lock GIT_REPO/refs
{code}
If it finds something and no operation is in progress (difficult to check that, though), the lock could cause the problem, one would better remove it. Though I’m afraid this way one could remove a good lock at unfortunate moment and thus cause a problem instead.

So maybe it’s better not to do anything from your side and from our side to try to find out why the problem happens and fix that.

FYI, it happened again yesterday, and was worked around the same way. I’ve spread the word to a few more users about running the find command to see if that helps.