"Branch cannot be merged" still happening on 0.9.4

[csymeonides-mf]

Presumably the same issue as #263 (merge fails intermittently with "Branch cannot be merged" error, succeeds when assigning back to Marge)

Marge version: 0.9.4 We are running it in docker using the stable tag which is currently sha256:5d5d9406d087d8119a2267d6561f22d7b5b090b75bf109817e3cbaaf8b8e7d71

Gitlab version: 13.5.2 (187cae1b32b)

Marge log:

2021-02-08 10:49:34,243 INFO Fetching merge requests assigned to me in research/horizon...
2021-02-08 10:49:34,387 INFO Got 1 requests to merge;
2021-02-08 10:49:34,388 INFO Attempting to merge the oldest MR...
2021-02-08 10:49:34,388 INFO Processing !1270 - 'Resolve HZN-1180 "Data append services final"'
2021-02-08 10:49:34,626 INFO Ensuring MR !1270 is mergeable
2021-02-08 10:49:34,730 INFO Running git -C /tmplbsyiugf/tmprdfi58f_ fetch --prune origin
2021-02-08 10:49:35,494 INFO Running git -C /tmplbsyiugf/tmprdfi58f_ checkout -B HZN-1180-data-append-services-final origin/HZN-1180-data-append-services-final --
2021-02-08 10:49:35,538 INFO Running git -C /tmplbsyiugf/tmprdfi58f_ rebase origin/master
2021-02-08 10:49:35,778 INFO Running git -C /tmplbsyiugf/tmprdfi58f_ rev-parse HEAD
2021-02-08 10:49:35,785 INFO Running git -C /tmplbsyiugf/tmprdfi58f_ rev-parse origin/master
2021-02-08 10:49:35,789 INFO Adding trailers for MR !1270
2021-02-08 10:49:35,790 INFO Running git -C /tmplbsyiugf/tmprdfi58f_ checkout HZN-1180-data-append-services-final --
2021-02-08 10:49:35,810 INFO Running git -C /tmplbsyiugf/tmprdfi58f_ diff-index --quiet HEAD
2021-02-08 10:49:35,824 INFO Running git -C /tmplbsyiugf/tmprdfi58f_ ls-files --others
2021-02-08 10:49:35,955 INFO Running git -C /tmplbsyiugf/tmprdfi58f_ push --force origin HZN-1180-data-append-services-final:HZN-1180-data-append-services-final
2021-02-08 10:49:36,790 INFO Commit id to merge '3617fa232847ebe2c640803a320d87a4aba294f2' (into: 'f14982e26146ad9480deb08b207ce7ac77beade6')
2021-02-08 10:49:41,870 INFO Waiting for CI to pass for MR !1270
2021-02-08 11:01:02,093 INFO CI for MR !1270 passed
2021-02-08 11:01:04,475 INFO Ensuring MR !1270 is mergeable
2021-02-08 11:01:04,754 WARNING I couldn't merge this branch: Merge request was rejected by GitLab: 'Branch cannot be merged'

Gitlab log:

{
  "time": "2021-02-08T11:01:04.648Z",
  "severity": "INFO",
  "duration_s": 0.07378,
  "db_duration_s": 0.01856,
  "view_duration_s": 0.05522,
  "status": 406,
  "method": "PUT",
  "path": "/api/v4/projects/155/merge_requests/1270/merge",
  "params": [
    {
      "key": "should_remove_source_branch",
      "value": null
    },
    {
      "key": "merge_when_pipeline_succeeds",
      "value": null
    },
    {
      "key": "sha",
      "value": "3617fa232847ebe2c640803a320d87a4aba294f2"
    }
  ],
  "host": "gitlab.mflocal.com",
  "remote_ip": "172.30.2.46, 127.0.0.1",
  "ua": "python-requests/2.21.0",
  "route": "/api/:version/projects/:id/merge_requests/:merge_request_iid/merge",
  "user_id": 43,
  "username": "Marge",
  "queue_duration_s": 0.038645,
  "redis_calls": 8,
  "redis_duration_s": 0.002152,
  "redis_read_bytes": 222,
  "redis_write_bytes": 601,
  "redis_cache_calls": 6,
  "redis_cache_duration_s": 0.001022,
  "redis_cache_read_bytes": 222,
  "redis_cache_write_bytes": 320,
  "redis_shared_state_calls": 2,
  "redis_shared_state_duration_s": 0.00113,
  "redis_shared_state_write_bytes": 281,
  "correlation_id": "IGw14MQxe88",
  "meta.user": "Marge",
  "meta.project": "research/horizon",
  "meta.root_namespace": "research",
  "meta.caller_id": "/api/:version/projects/:id/merge_requests/:merge_request_iid/merge"
}

Then when re-assigning to Marge:

2021-02-08 11:44:58,544 INFO Fetching merge requests assigned to me in research/horizon...
2021-02-08 11:44:58,699 INFO Got 1 requests to merge;
2021-02-08 11:44:58,700 INFO Attempting to merge the oldest MR...
2021-02-08 11:44:58,700 INFO Processing !1270 - 'Resolve HZN-1180 "Data append services final"'
2021-02-08 11:44:58,920 INFO Ensuring MR !1270 is mergeable
2021-02-08 11:44:59,043 INFO Running git -C /tmpnhsrjp54/tmpskf5r91r fetch --prune origin
2021-02-08 11:44:59,481 INFO Running git -C /tmpnhsrjp54/tmpskf5r91r checkout -B HZN-1180-data-append-services-final origin/HZN-1180-data-append-services-final --
2021-02-08 11:44:59,559 INFO Running git -C /tmpnhsrjp54/tmpskf5r91r rebase origin/master
2021-02-08 11:44:59,650 INFO Running git -C /tmpnhsrjp54/tmpskf5r91r rev-parse HEAD
2021-02-08 11:44:59,654 INFO Running git -C /tmpnhsrjp54/tmpskf5r91r rev-parse origin/master
2021-02-08 11:44:59,658 INFO Adding trailers for MR !1270
2021-02-08 11:44:59,659 INFO Running git -C /tmpnhsrjp54/tmpskf5r91r checkout HZN-1180-data-append-services-final --
2021-02-08 11:44:59,678 INFO Running git -C /tmpnhsrjp54/tmpskf5r91r diff-index --quiet HEAD
2021-02-08 11:44:59,692 INFO Running git -C /tmpnhsrjp54/tmpskf5r91r ls-files --others
2021-02-08 11:44:59,702 INFO Running git -C /tmpnhsrjp54/tmpskf5r91r push --force origin HZN-1180-data-append-services-final:HZN-1180-data-append-services-final
2021-02-08 11:45:00,171 INFO Commit id to merge '3617fa232847ebe2c640803a320d87a4aba294f2' (into: 'f14982e26146ad9480deb08b207ce7ac77beade6')
2021-02-08 11:45:05,277 INFO Waiting for CI to pass for MR !1270
2021-02-08 11:45:05,392 INFO CI for MR !1270 passed
2021-02-08 11:45:07,540 INFO Ensuring MR !1270 is mergeable
2021-02-08 11:45:10,611 INFO merge_request.accept result: {'id': 7481, 'iid': 1270, 'project_id': 155, 'title': 'Resolve HZN-1180 "Data append services final"', 'description': 'Closes HZN-1180', 'state': 'merged', 'created_at': '2021-02-04T16:14:08.062Z', 'updated_at': '2021-02-08T11:45:07.927Z', 'merged_by': {'id': 43, 'name': 'Marge', 'username': 'Marge', 'state': 'active', 'avatar_url': 'https://gitlab.mflocal.com/uploads/-/system/user/avatar/43/Untitled.png', 'web_url': 'https://gitlab.mflocal.com/Marge'}, 'merged_at': '2021-02-08T11:45:10.077Z', 'closed_by': None, 'closed_at': None, 'target_branch': 'master', 'source_branch': 'HZN-1180-data-append-services-final', 'user_notes_count': 45, 'upvotes': 0, 'downvotes': 0, 'author': {'id': 30, 'name': 'Nicolo Andronio', 'username': 'nicolo.andronio', 'state': 'active', 'avatar_url': 'https://gitlab.mflocal.com/uploads/-/system/user/avatar/30/avatar.png', 'web_url': 'https://gitlab.mflocal.com/nicolo.andronio'}, 'assignees': [{'id': 43, 'name': 'Marge', 'username': 'Marge', 'state': 'active', 'avatar_url': 'https://gitlab.mflocal.com/uploads/-/system/user/avatar/43/Untitled.png', 'web_url': 'https://gitlab.mflocal.com/Marge'}], 'assignee': {'id': 43, 'name': 'Marge', 'username': 'Marge', 'state': 'active', 'avatar_url': 'https://gitlab.mflocal.com/uploads/-/system/user/avatar/43/Untitled.png', 'web_url': 'https://gitlab.mflocal.com/Marge'}, 'source_project_id': 155, 'target_project_id': 155, 'labels': [], 'work_in_progress': False, 'milestone': None, 'merge_when_pipeline_succeeds': False, 'merge_status': 'can_be_merged', 'sha': '3617fa232847ebe2c640803a320d87a4aba294f2', 'merge_commit_sha': 'c088d8b39a746ccb711cf60d5cf79a790e969b96', 'squash_commit_sha': None, 'discussion_locked': None, 'should_remove_source_branch': None, 'force_remove_source_branch': True, 'reference': '!1270', 'references': {'short': '!1270', 'relative': '!1270', 'full': 'research/horizon!1270'}, 'web_url': 'https://gitlab.mflocal.com/research/horizon/-/merge_requests/1270', 'time_stats': {'time_estimate': 0, 'total_time_spent': 0, 'human_time_estimate': None, 'human_total_time_spent': None}, 'squash': False, 'task_completion_status': {'count': 0, 'completed_count': 0}, 'has_conflicts': False, 'blocking_discussions_resolved': True, 'subscribed': True, 'changes_count': '32', 'latest_build_started_at': '2021-02-08T10:49:41.656Z', 'latest_build_finished_at': '2021-02-08T11:00:54.741Z', 'first_deployed_to_production_at': None, 'pipeline': {'id': 52570, 'sha': '3617fa232847ebe2c640803a320d87a4aba294f2', 'ref': 'HZN-1180-data-append-services-final', 'status': 'success', 'created_at': '2021-02-08T10:49:38.365Z', 'updated_at': '2021-02-08T11:00:54.746Z', 'web_url': 'https://gitlab.mflocal.com/research/horizon/-/pipelines/52570'}, 'head_pipeline': {'id': 52570, 'sha': '3617fa232847ebe2c640803a320d87a4aba294f2', 'ref': 'HZN-1180-data-append-services-final', 'status': 'success', 'created_at': '2021-02-08T10:49:38.365Z', 'updated_at': '2021-02-08T11:00:54.746Z', 'web_url': 'https://gitlab.mflocal.com/research/horizon/-/pipelines/52570', 'before_sha': '1062b0bb7b32b4e89a23bdd1d7e3546c2e29765f', 'tag': False, 'yaml_errors': None, 'user': {'id': 43, 'name': 'Marge', 'username': 'Marge', 'state': 'active', 'avatar_url': 'https://gitlab.mflocal.com/uploads/-/system/user/avatar/43/Untitled.png', 'web_url': 'https://gitlab.mflocal.com/Marge'}, 'started_at': '2021-02-08T10:49:41.656Z', 'finished_at': '2021-02-08T11:00:54.741Z', 'committed_at': None, 'duration': 673, 'coverage': '73.00', 'detailed_status': {'icon': 'status_success', 'text': 'passed', 'label': 'passed', 'group': 'success', 'tooltip': 'passed', 'has_details': True, 'details_path': '/research/horizon/-/pipelines/52570', 'illustration': None, 'favicon': '/assets/ci_favicons/favicon_status_success-8451333011eee8ce9f2ab25dc487fe24a8758c694827a582f17f42b0a90446a2.png'}}, 'diff_refs': {'base_sha': 'f14982e26146ad9480deb08b207ce7ac77beade6', 'head_sha': '3617fa232847ebe2c640803a320d87a4aba294f2', 'start_sha': 'f14982e26146ad9480deb08b207ce7ac77beade6'}, 'merge_error': None, 'user': {'can_merge': True}}
2021-02-08 11:45:10,796 INFO Successfully merged !1270.

And the Gitlab log:

{
  "time": "2021-02-08T11:45:10.606Z",
  "severity": "INFO",
  "duration_s": 3.00011,
  "db_duration_s": 0.09316,
  "view_duration_s": 2.90695,
  "status": 200,
  "method": "PUT",
  "path": "/api/v4/projects/155/merge_requests/1270/merge",
  "params": [
    {
      "key": "should_remove_source_branch",
      "value": null
    },
    {
      "key": "merge_when_pipeline_succeeds",
      "value": null
    },
    {
      "key": "sha",
      "value": "3617fa232847ebe2c640803a320d87a4aba294f2"
    }
  ],
  "host": "gitlab.mflocal.com",
  "remote_ip": "172.30.2.46, 127.0.0.1",
  "ua": "python-requests/2.21.0",
  "route": "/api/:version/projects/:id/merge_requests/:merge_request_iid/merge",
  "user_id": 43,
  "username": "Marge",
  "queue_duration_s": 0.019303,
  "gitaly_calls": 11,
  "gitaly_duration_s": 0.251597,
  "redis_calls": 49,
  "redis_duration_s": 0.0072429999999999994,
  "redis_read_bytes": 1960,
  "redis_write_bytes": 16684,
  "redis_cache_calls": 30,
  "redis_cache_duration_s": 0.004324,
  "redis_cache_read_bytes": 1664,
  "redis_cache_write_bytes": 2898,
  "redis_queues_calls": 13,
  "redis_queues_duration_s": 0.001547,
  "redis_queues_read_bytes": 268,
  "redis_queues_write_bytes": 13078,
  "redis_shared_state_calls": 6,
  "redis_shared_state_duration_s": 0.001372,
  "redis_shared_state_read_bytes": 28,
  "redis_shared_state_write_bytes": 708,
  "correlation_id": "XYYxf226CJ9",
  "meta.user": "Marge",
  "meta.project": "research/horizon",
  "meta.root_namespace": "research",
  "meta.caller_id": "/api/:version/projects/:id/merge_requests/:merge_request_iid/merge"
}

[snim2]

Yes, I'm seeing this again too now :(

@csymeonides-mf are you using batch-mode?

[sysadmiral]

The linear backoff change (https://github.com/smarkets/marge-bot/pull/265) was merged but it isn't part of release 0.9.4.

Until a new release is generated you could run the branch version... 😞

[csymeonides-mf]

@sysadmiral oops my bad, I saw the date on the PR and assumed it was included in the release. Any idea when the next release will happen?

@snim2 we aren't using batch mode, would that help?

[snim2]

@csymeonides-mf I'm pretty sure that the linear back-off isn't in use in batch mode (I wrote the PR BTW), so I'd stick with what you've got TBH!

[csymeonides-mf]

Will wait for the next release and try again.

[tclh123]

Hey @csymeonides-mf , you could also try smarkets/marge-bot:master image before the new release.

[tclh123]

Yes, I'm seeing this again too now :(

@snim2 Do you mean your last PR may be insufficient to fix this issue?

[snim2]

@tclh123 I think we are running the latest release rather than master, but I will check for you later today...

[snim2]

@tclh123 yep, we have this in our marge-bot.service:

ExecStartPre=/usr/bin/docker pull smarkets/marge-bot

and we restart with cron every night.

[tclh123]

Marge version 0.9.5 released, which contains @snim2 's fix. You could also use the latest image tag.

[csymeonides-mf]

Thank you! Will report back if the problem reoccurs.