This merge issue happened when a repo-fork:bookmark/elastic was pull requested to repo-orig:/branch/default

The PR said merge cannot continue because of conflicts, the real error was that commit id c2118069d55a20e9f015eb9d48738398e698a69f (which was bookmark/elastic) - was not in the repo - and it was raised because vcs hg/repository.py was trying to find ancestor(source_commit, target_commit) - BEFORE ever making a shadow repo to try the merge....so this means that mercurial couldn't find the commit id in the repo - which according to:

rhodecode@internal-code:~/rhodecode/repositories/u/dan/rhodecode-enterprise-ee-fork$ hg bookmarks
  elasticsearch             142:c2118069d55a
  tools-0.8.0               139:e60fd9fdee6a

was there...Marcin said he tried to remerge the PR the next day, and everything worked...just fine

Chat transcript continues:

interesting: https://internal-code.rhodecode.com/rhodecode-enterprise-ee/pull-request/2294

[5:21]  
conflicts on PR

[5:23]  
also i found this log: https://ae.rhodecode.com/ui/logs?resource=9&request_id=00de9059dbac4147b133efa5d29a132f
 ae.rhodecode.com
Application performance, exception and error monitoring for Python,         Django, Flask and Javascript - App Enlight
App Enlight provides a helpful interface to let you and your team save time spent on debugging and reproducing issues from a production environment. 

dan [5:23 PM]  
yep

[5:24]  
unknown revision, yet revision is there

[5:25]  
and no shadow repo was made either

[5:25]  
or if it was, it was cleaned up

marcink [5:26 PM]  
anything in logs ?

dan [5:27 PM]  
nope just that log you found

marcink [5:28 PM]  
is there a code that would remove shadow repo in case of an error

dan [5:28 PM]  
it didnt reach that line

[5:28]  
it died at ancestor

[5:28]  
because, it couldnt find commit id

marcink [5:29 PM]  
smeels like caching issue

dan [5:29 PM]  
so it tried to find ancestor of the 2 commits, book:elastic vs branch:default

[5:29]  
and died

[5:29]  
because book:elastic wasn’t in the repo

[5:29]  
caching, or race condition?

marcink [5:30 PM]  
since upgrade to latest hg we constantly get random 500 errors when pushing new bookmarks and trying to pull/push

dan [5:31 PM]  
i dont understand how this code works

[5:32]  
   @reraise_safe_exceptions
    def ancestor(self, wire, revision1, revision2):
        repo = self._factory.repo(wire)
        baseui = self._factory._create_config(wire['config'])
        output = io.BytesIO()
        baseui.write = output.write
        commands.debugancestor(baseui, repo, revision1, revision2)

        return output.getvalue()


[5:32]  
what is debugancestor

[5:32]  
just mercurial command?

marcink [5:32 PM]  
yeah that’s HG internals

[5:33]  
https://internal-code.rhodecode.com/legacy/mercurial/raw/8c8442523eefac2d53e3f10ff1ebf37f4d3c63c3/mercurial/commands.py

[5:33]  
not sure why we use the very high level command in there

[5:34]  
ugh this code is really ugly, io.BytesIO() catching stdout :D

[5:34]  
jesus

[5:35]  
this code debugancestor has like 7 lines of code

dan [5:42 PM]  
well the problem is 100% mercurial

[5:42]  
since you can’t get to a state of pull requesting a commit if it’s not in the repo

marcink [5:43 PM]  
true

[5:43]  
problem is using commands.* is dangerous people from hg use different tricks t omake it fast , and cache stuff

dan [5:44 PM]  
hmmm

[5:44]  
we could just do it ourselves with revlog

[5:45]  
assuming that also doesnt pass through commans.

[5:45]  
rhodecode@internal-code:~/rhodecode/repositories/u/dan/rhodecode-enterprise-ee-fork$ hg bookmarks
  elasticsearch             142:c2118069d55a
  tools-0.8.0               139:e60fd9fdee6a

                        Failure when doing local merge on hg shadow repo
Traceback (most recent call last):
  File "/nix/store/dflb4s8v48p5k8fmmjp84rlb1a1bffda-python2.7-rhodecode-enterprise-ce-4.1.0+20160607x111426x0e0e958e5d88/lib/python2.7/site-packages/rhodecode/lib/vcs/backends/hg/repository.py", line 686, in _merge_repo
    source_ref)
  File "/nix/store/dflb4s8v48p5k8fmmjp84rlb1a1bffda-python2.7-rhodecode-enterprise-ce-4.1.0+20160607x111426x0e0e958e5d88/lib/python2.7/site-packages/rhodecode/lib/vcs/backends/hg/repository.py", line 590, in _local_merge
    ancestor = self._ancestor(target_ref.commit_id, source_ref.commit_id)
  File "/nix/store/dflb4s8v48p5k8fmmjp84rlb1a1bffda-python2.7-rhodecode-enterprise-ce-4.1.0+20160607x111426x0e0e958e5d88/lib/python2.7/site-packages/rhodecode/lib/vcs/backends/hg/repository.py", line 566, in _ancestor
    revision1, revision2).strip().split(':')[-1]
  File "/nix/store/dflb4s8v48p5k8fmmjp84rlb1a1bffda-python2.7-rhodecode-enterprise-ce-4.1.0+20160607x111426x0e0e958e5d88/lib/python2.7/site-packages/rhodecode/lib/vcs/client_http.py", line 102, in f
    return self._call(name, *args, **kwargs)
  File "/nix/store/dflb4s8v48p5k8fmmjp84rlb1a1bffda-python2.7-rhodecode-enterprise-ce-4.1.0+20160607x111426x0e0e958e5d88/lib/python2.7/site-packages/rhodecode/lib/vcs/client_http.py", line 120, in _call_with_logging
    return RemoteRepo._call(self, name, *args, **kwargs)
  File "/nix/store/dflb4s8v48p5k8fmmjp84rlb1a1bffda-python2.7-rhodecode-enterprise-ce-4.1.0+20160607x111426x0e0e958e5d88/lib/python2.7/site-packages/rhodecode/lib/vcs/exceptions.py", line 182, in wrapper
    raise _EXCEPTION_MAP[kind](*e.args)
CommitDoesNotExistError: unknown revision 'c2118069d55a20e9f015eb9d48738398e698a69f'
                  ~~~

Another one with the CommitDoesNotExistError:

Failure when doing local merge on hg shadow repo Traceback (most recent call last): File "/nix/store/8q1gs7v64sp78jb4qzxvyzlhd36x7h9y-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x140837xfd19366cd1f5/lib/python2.7/site-packages/rhodecode/lib/vcs/backends/hg/repository.py", line 686, in _merge_repo source_ref) File "/nix/store/8q1gs7v64sp78jb4qzxvyzlhd36x7h9y-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x140837xfd19366cd1f5/lib/python2.7/site-packages/rhodecode/lib/vcs/backends/hg/repository.py", line 590, in _local_merge ancestor = self._ancestor(target_ref.commit_id, source_ref.commit_id) File "/nix/store/8q1gs7v64sp78jb4qzxvyzlhd36x7h9y-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x140837xfd19366cd1f5/lib/python2.7/site-packages/rhodecode/lib/vcs/backends/hg/repository.py", line 566, in _ancestor revision1, revision2).strip().split(':')[-1] File "/nix/store/8q1gs7v64sp78jb4qzxvyzlhd36x7h9y-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x140837xfd19366cd1f5/lib/python2.7/site-packages/rhodecode/lib/vcs/client_http.py", line 102, in f return self._call(name, *args, **kwargs) File "/nix/store/8q1gs7v64sp78jb4qzxvyzlhd36x7h9y-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x140837xfd19366cd1f5/lib/python2.7/site-packages/rhodecode/lib/vcs/client_http.py", line 120, in _call_with_logging return RemoteRepo._call(self, name, *args, **kwargs) File "/nix/store/8q1gs7v64sp78jb4qzxvyzlhd36x7h9y-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x140837xfd19366cd1f5/lib/python2.7/site-packages/rhodecode/lib/vcs/exceptions.py", line 182, in wrapper raise _EXCEPTION_MAP[kind](*e.args) CommitDoesNotExistError: unknown revision 'd295e7cc2c6ae68cc4200a3717f59ce4791b7918' 

This one is with a fresh PR which contains only one commit. The PR was pointing to default in the target and we tried to mere it right after it has been created, so there was no change in the target of the pull request.

The "missing" commit ID is the one commit in the pull request which should be added to the target repository.

Added more logging into the code base in various PRs around 2313.

Investigation notes:

Shadow repository¶

On the file system¶

drwxr-xr-x  12 rhodecode rhodecode  4096 Jun  8 20:06 .__shadow_rhodecode-enterprise-ce_pr-2307

Looked at the commit history in the shadow repository¶

o  changeset:   141:d295e7cc2c6a
|  bookmark:    issue-3995
|  tag:         tip
|  user:        Johannes Bornhold <johannes@rhodecode.com>
|  date:        Wed Jun 08 22:02:30 2016 +0200
|  summary:     dependencies: Add futures as a dependency of Gunicorn.
|
@  changeset:   140:fd19366cd1f5
|  bookmark:    mercurial-3.8.2
|  user:        Johannes Bornhold <johannes@rhodecode.com>
|  date:        Wed Jun 08 14:37:37 2016 +0200
|  summary:     tests: Adapt test to new mercurial version (3.8.2)
|
[...]

This is quite interesting, since it shows us that the commit does exist in the
shadow repository and that the currently checked out commit is the target
commit. This means everything is in the correct state at this point.

It is not clear yet why Mercurial was not able to find the commit. Possible
causes:

• If the shadow repository is created in an asynchronous operation and if this operation did not yet finish at the point in time when the merge status has been checked, we would see an issue where the commit cannot be found.
• If Mercurial has internal caching in place which is not invalidated correctly, then we could also observe this problem.

So far it seems that we did not yet see a successful reproduction of this
problem on a local developer machine, in most cases celery is not involved
there. Based on this it seems to make sense to inspect the code and check how
the shadow repository is created.

Code inspection¶

Creating a pull request¶

• starts in models/pull_request.py
• create()
  • creates an entry in the database via db.PullRequest
  • adds reviewers
  • adds status entries via ChangesetStatusModel
• Interestingly this does not seem to create the shadow repository yet.
• Inspection of the Controller
  • controllers/pullrequests.py
  • The view show calls into PullRequestModel.merge_status()

PullRequestModel.mergestatus¶

• calls to try_merge()
• try_merge()
  • check locked state
  • try merge if _needs_merge_state_refresh
  • otherwise use _last_merge_status
• _refresh_merge_state calls target_vcs.merge
• Conclusions
  • Trying the merge calls in the end to shadow_repo._local_merge
  • _local_merge is running on the shadow
  • right before the commits have been fetched in

Handling of the shadow repository¶

• When checking the merge status, the shadow is created on demand
• Before trying the merge, we pull in the target and the source ref
• If the commit cannot be found, we might indeed hit some caching
• _local_pull
  • remote.pull_cmd
• _local_merge

Observations during investigation¶

• Pull Request https://internal-code.rhodecode.com/rhodecode-enterprise-ce/pull-request/2313
  • Failed as well.
  • This pull request was shown as mergeable.
  • When clicking the merge button the problem appeared.
  • So it seems we face the issue during the regular merge and not during the trial run of the merge to find out the initial status.

Also observed another one with the remote head exception, but was not able to grab the shadow repo

Did collect all potentially related errors which I could find on the logs of internal-code to get a better overview:

failure doing the merge¶

2016-06-08 22:27:33.064 ERROR [rhodecode.lib.vcs.backends.hg.repository] Failure when doing local merge on hg shadow repo
Traceback (most recent call last):
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/lib/vcs/backends/hg/repository.py", line 690, in _merge_repo
    source_ref)
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/lib/vcs/backends/hg/repository.py", line 612, in _local_merge
    self._remote.rebase(abort=True)
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/lib/vcs/client_http.py", line 102, in f
    return self._call(name, *args, **kwargs)
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/lib/vcs/client_http.py", line 120, in _call_with_logging
    return RemoteRepo._call(self, name, *args, **kwargs)
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/lib/vcs/exceptions.py", line 182, in wrapper
    raise _EXCEPTION_MAP[kind](*e.args)
RepositoryError: no rebase in progress

exception around Git repositories in hooks¶

2016-06-08 22:25:52.626 ERROR [rhodecode.lib.hooks_daemon] Exception when handling hook <function post_push at 0x7f8abe52b230>
Traceback (most recent call last):
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/lib/hooks_daemon.py", line 241, in _call_hook
    result = hook(extras)
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/lib/hooks_base.py", line 178, in post_push
    **extras)
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/lib/hooks_base.py", line 234, in __call__
    return callback(**kwargs_to_pass)
  File "/home/rhodecode/rhodecode/rcextensions/__init__.py", line 215, in wrapper
    return func(*args, **kwargs)
  File "/home/rhodecode/rhodecode/rcextensions/__init__.py", line 196, in wrapper
    return func(*args, **kwargs)
  File "/home/rhodecode/rhodecode/rcextensions/__init__.py", line 538, in _push_hook
    extracted_commits = call(**kwargs)
  File "/home/rhodecode/rhodecode/rcextensions/extract_commits.py", line 47, in run
    vcs_repo = repo.scm_instance(cache=False)
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/model/db.py", line 1920, in scm_instance
    return self._get_instance(cache=bool(cache), config=config)
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/model/db.py", line 1939, in _get_instance
    vcs_alias = get_scm(repo_full_path)[0]
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/lib/vcs/utils/helpers.py", line 62, in get_scm
    found_scms = get_scms(path)
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/lib/vcs/utils/helpers.py", line 60, in get_scms
    return [(scm, path) for scm in get_scms_for_path(path)]
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/lib/vcs/utils/helpers.py", line 111, in get_scms_for_path
    if backend.is_valid_repository(path):
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/lib/vcs/backends/git/repository.py", line 141, in is_valid_repository
    GitRepository(path)
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/lib/vcs/backends/git/repository.py", line 70, in __init__
    self._init_repo(create, src_url, update_after_clone, bare)
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/lib/vcs/backends/git/repository.py", line 166, in _init_repo
    self._remote.assert_correct_path()
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/lib/vcs/client_http.py", line 102, in f
    return self._call(name, *args, **kwargs)
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/lib/vcs/client_http.py", line 120, in _call_with_logging
    return RemoteRepo._call(self, name, *args, **kwargs)
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/lib/vcs/exceptions.py", line 162, in wrapper
    return func(*args, **kwargs)
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/lib/vcs/client_http.py", line 116, in _call
    return _remote_call(self.url, payload, EXCEPTIONS_MAP, self._session)
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/lib/vcs/client_http.py", line 157, in _remote_call
    response = session.post(url, data=msgpack.packb(payload))
  File "/nix/store/zl9m2fhh4nk1aal8giz5fmnddvas95w1-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x222417xbffdfabf403b/lib/python2.7/site-packages/rhodecode/lib/vcs/__init__.py", line 246, in post
    curl.setopt(curl.URL, url)
error: cannot invoke setopt() - perform() is currently running

failure in doing local push¶

2016-06-08 22:18:54.964 ERROR [rhodecode.lib.vcs.backends.hg.repository] Failure when doing local push on hg shadow repo
Traceback (most recent call last):
  File "/nix/store/075dlcr2xflb0l02iz6i5kxf5ql7p2nd-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x214312xe4b1972a451a/lib/python2.7/site-packages/rhodecode/lib/vcs/backends/hg/repository.py", line 715, in _merge_repo
    enable_hooks=True)
  File "/nix/store/075dlcr2xflb0l02iz6i5kxf5ql7p2nd-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x214312xe4b1972a451a/lib/python2.7/site-packages/rhodecode/lib/vcs/backends/hg/repository.py", line 578, in _local_push
    push_branches=push_branches)
  File "/nix/store/075dlcr2xflb0l02iz6i5kxf5ql7p2nd-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x214312xe4b1972a451a/lib/python2.7/site-packages/rhodecode/lib/vcs/client_http.py", line 102, in f
    return self._call(name, *args, **kwargs)
  File "/nix/store/075dlcr2xflb0l02iz6i5kxf5ql7p2nd-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x214312xe4b1972a451a/lib/python2.7/site-packages/rhodecode/lib/vcs/client_http.py", line 120, in _call_with_logging
    return RemoteRepo._call(self, name, *args, **kwargs)
  File "/nix/store/075dlcr2xflb0l02iz6i5kxf5ql7p2nd-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x214312xe4b1972a451a/lib/python2.7/site-packages/rhodecode/lib/vcs/exceptions.py", line 182, in wrapper
    raise _EXCEPTION_MAP[kind](*e.args)
RepositoryError: push creates new remote head 2d23d04921f2!

failure in doing local merge¶

2016-06-08 20:06:14.346 ERROR [rhodecode.lib.vcs.backends.hg.repository] Failure when doing local merge on hg shadow repo
Traceback (most recent call last):
  File "/nix/store/8q1gs7v64sp78jb4qzxvyzlhd36x7h9y-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x140837xfd19366cd1f5/lib/python2.7/site-packages/rhodecode/lib/vcs/backends/hg/repository.py", line 686, in _merge_repo
    source_ref)
  File "/nix/store/8q1gs7v64sp78jb4qzxvyzlhd36x7h9y-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x140837xfd19366cd1f5/lib/python2.7/site-packages/rhodecode/lib/vcs/backends/hg/repository.py", line 590, in _local_merge
    ancestor = self._ancestor(target_ref.commit_id, source_ref.commit_id)
  File "/nix/store/8q1gs7v64sp78jb4qzxvyzlhd36x7h9y-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x140837xfd19366cd1f5/lib/python2.7/site-packages/rhodecode/lib/vcs/backends/hg/repository.py", line 566, in _ancestor
    revision1, revision2).strip().split(':')[-1]
  File "/nix/store/8q1gs7v64sp78jb4qzxvyzlhd36x7h9y-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x140837xfd19366cd1f5/lib/python2.7/site-packages/rhodecode/lib/vcs/client_http.py", line 102, in f
    return self._call(name, *args, **kwargs)
  File "/nix/store/8q1gs7v64sp78jb4qzxvyzlhd36x7h9y-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x140837xfd19366cd1f5/lib/python2.7/site-packages/rhodecode/lib/vcs/client_http.py", line 120, in _call_with_logging
    return RemoteRepo._call(self, name, *args, **kwargs)
  File "/nix/store/8q1gs7v64sp78jb4qzxvyzlhd36x7h9y-python2.7-rhodecode-enterprise-ce-4.1.0+20160608x140837xfd19366cd1f5/lib/python2.7/site-packages/rhodecode/lib/vcs/exceptions.py", line 182, in wrapper
    raise _EXCEPTION_MAP[kind](*e.args)
CommitDoesNotExistError: unknown revision 'd295e7cc2c6ae68cc4200a3717f59ce4791b7918'