Marge-bot get's stuck in loop due to This project requires squashing commits when merge requests are accepted

[cmavromichalis]

Hello,

Our setup:
Version: GitLab 14.2.0-ee
The project setting has Squash commits when merging as required, users can't deselect the check box.
Our marge-bot user is called merge-bot

We have had marge-bot running fine for over a year now. It might be due to a GitLab error but thought I would open an issue here to handle the looping.

Marge-bot is stuck in a loop when:

1. Marge-bot finds the oldest MR
2. Checks the MR is ready to merge (it is, has all approvals, CI has passed)
3. The MR is reporting 'merge_error': 'This project requires squashing commits when merge requests are accepted.',
4. Marge-bot tries to merge anyway and posts that it is successful but it is not
5. Marge-bot finds the same oldest MR again and loops forever

I am able to click merge button and it works fine in the UI.

I can see the same error in the UI so I think GitLab is having issues but is causing Marge-bot to infinitely loop

Here is the log shortened to show the loop:

2021-10-13 21:44:38,264 INFO Finding out my current projects...
2021-10-13 21:44:47,642 INFO Fetching merge requests assigned to me in PROJECT_NAME...
2021-10-13 21:44:48,000 INFO Got 2 requests to merge;
2021-10-13 21:44:48,001 INFO Attempting to merge the oldest MR...
2021-10-13 21:44:48,001 INFO Processing !2862 - 'docker base image(s): security updates October 01 2021'
2021-10-13 21:44:48,331 INFO Ensuring MR !2862 is mergeable
….
2021-10-13 21:44:55,082 INFO Checking if approvals have reset
2021-10-13 21:45:58,223 INFO Waiting for CI to pass for MR !2862
2021-10-13 21:45:58,355 INFO CI for MR !2862 passed
2021-10-13 21:46:00,357 INFO Waiting for MR !2862 to have merge_status can_be_merged
2021-10-13 21:46:00,517 INFO MR !2862 can be merged on attempt 0
2021-10-13 21:46:00,639 INFO Ensuring MR !2862 is mergeable
2021-10-13 21:46:01,252 INFO merge_request.accept result: {'id': 73993, 'iid': 2862, 'project_id': 15, 'title': 'docker base image(s): security updates October 01 2021', 'description': None, 'state': 'opened', 'created_at': '2021-10-01T10:26:37.062Z', 'updated_at': '2021-10-12T22:33:19.716Z', 'merged_by': None, 'merged_at': None, 'closed_by': None, 'closed_at': None, 'target_branch': 'master', 'source_branch': 'jenkins/docker-updates-1633083995', 'user_notes_count': 1, 'upvotes': 0, 'downvotes': 0, 'author': {'id': 11, 'name': 'GitLab Runner', 'username': 'gitlab-runner', 'state': 'active', 'avatar_url': 'https://gitlab.internal.com/uploads/-/system/user/avatar/11/gitlab-icon.png', 'web_url': 'https://gitlab.internal.com/gitlab-runner'}, 'assignees': [{'id': 11, 'name': 'GitLab Runner', 'username': 'gitlab-runner', 'state': 'active', 'avatar_url': 'https://gitlab.internal.com/uploads/-/system/user/avatar/11/gitlab-icon.png', 'web_url': 'https://gitlab.internal.com/gitlab-runner'}, {'id': 12, 'name': 'Merge Bot', 'username': 'merge-bot', 'state': 'active', 'avatar_url': 'https://gitlab.internal.com/uploads/-/system/user/avatar/12/merged-icon.png', 'web_url': 'https://gitlab.internal.com/merge-bot'}], 'assignee': {'id': 11, 'name': 'GitLab Runner', 'username': 'gitlab-runner', 'state': 'active', 'avatar_url': 'https://gitlab.internal.com/uploads/-/system/user/avatar/11/gitlab-icon.png', 'web_url': 'https://gitlab.internal.com/gitlab-runner'}, 'reviewers': [], 'source_project_id': 15, 'target_project_id': 15, 'labels': [], 'draft': False, 'work_in_progress': False, 'milestone': None, 'merge_when_pipeline_succeeds': False, 'merge_status': 'can_be_merged', 'sha': '256eb7988413c55f0587f3c9b4f009d78a1590ac', 'merge_commit_sha': None, 'squash_commit_sha': None, 'discussion_locked': None, 'should_remove_source_branch': None, 'force_remove_source_branch': True, 'reference': '!2862', 'references': {'short': '!2862', 'relative': '!2862', 'full': 'PROJECT_NAME!2862'}, 'web_url': 'https://gitlab.internal.com/PROJECT_NAME/-/merge_requests/2862', '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, 'approvals_before_merge': None, 'subscribed': True, 'changes_count': '2', 'latest_build_started_at': '2021-10-12T22:30:19.600Z', 'latest_build_finished_at': '2021-10-12T22:33:12.749Z', 'first_deployed_to_production_at': None, 'pipeline': {'id': 271485, 'project_id': 15, 'sha': '256eb7988413c55f0587f3c9b4f009d78a1590ac', 'ref': 'refs/merge-requests/2862/head', 'status': 'success', 'created_at': '2021-10-12T22:30:04.162Z', 'updated_at': '2021-10-12T22:33:12.756Z', 'web_url': 'https://gitlab.internal.com/PROJECT_NAME/-/pipelines/271485'}, 'head_pipeline': {'id': 271485, 'project_id': 15, 'sha': '256eb7988413c55f0587f3c9b4f009d78a1590ac', 'ref': 'refs/merge-requests/2862/head', 'status': 'success', 'created_at': '2021-10-12T22:30:04.162Z', 'updated_at': '2021-10-12T22:33:12.756Z', 'web_url': 'https://gitlab.internal.com/PROJECT_NAME/-/pipelines/271485', 'before_sha': '0000000000000000000000000000000000000000', 'tag': False, 'yaml_errors': None, 'user': {'id': 12, 'name': 'Merge Bot', 'username': 'merge-bot', 'state': 'active', 'avatar_url': 'https://gitlab.internal.com/uploads/-/system/user/avatar/12/merged-icon.png', 'web_url': 'https://gitlab.internal.com/merge-bot'}, 'started_at': '2021-10-12T22:30:19.600Z', 'finished_at': '2021-10-12T22:33:12.749Z', 'committed_at': None, 'duration': 169, 'queued_duration': 15, 'coverage': None, 'detailed_status': {'icon': 'status_success', 'text': 'passed', 'label': 'passed', 'group': 'success', 'tooltip': 'passed', 'has_details': True, 'details_path': '/PROJECT_NAME/-/pipelines/271485', 'illustration': None, 'favicon': '/assets/ci_favicons/favicon_status_success-8451333011eee8ce9f2ab25dc487fe24a8758c694827a582f17f42b0a90446a2.png'}}, 'diff_refs': {'base_sha': '15bd4fbbee381dcc1cc1e7d78969da896057f8ea', 'head_sha': '256eb7988413c55f0587f3c9b4f009d78a1590ac', 'start_sha': '15bd4fbbee381dcc1cc1e7d78969da896057f8ea'}, 'merge_error': 'This project requires squashing commits when merge requests are accepted.', 'user': {'can_merge': True}}
2021-10-13 21:46:01,374 INFO Successfully merged !2862.
2021-10-13 21:46:02,376 INFO Sleeping for 29 seconds...

Loops again here forever

2021-10-13 21:46:31,405 INFO Finding out my current projects...
2021-10-13 21:46:40,551 INFO Fetching merge requests assigned to me in PROJECT_NAME...
2021-10-13 21:46:40,860 INFO Got 2 requests to merge;
2021-10-13 21:46:40,860 INFO Attempting to merge the oldest MR...
2021-10-13 21:46:40,860 INFO Processing !2862 - 'docker base image(s): security updates October 01 2021'
2021-10-13 21:46:41,221 INFO Ensuring MR !2862 is mergeable
….
2021-10-13 21:46:48,046 INFO Checking if approvals have reset
2021-10-13 21:47:51,234 INFO Waiting for CI to pass for MR !2862
2021-10-13 21:47:51,337 INFO CI for MR !2862 passed
2021-10-13 21:47:53,339 INFO Waiting for MR !2862 to have merge_status can_be_merged
2021-10-13 21:47:53,510 INFO MR !2862 can be merged on attempt 0
2021-10-13 21:47:53,706 INFO Ensuring MR !2862 is mergeable
2021-10-13 21:47:54,841 INFO merge_request.accept result: {'id': 73993, 'iid': 2862, 'project_id': 15, 'title': 'docker base image(s): security updates October 01 2021', 'description': None, 'state': 'opened', 'created_at': '2021-10-01T10:26:37.062Z', 'updated_at': '2021-10-12T22:33:19.716Z', 'merged_by': None, 'merged_at': None, 'closed_by': None, 'closed_at': None, 'target_branch': 'master', 'source_branch': 'jenkins/docker-updates-1633083995', 'user_notes_count': 1, 'upvotes': 0, 'downvotes': 0, 'author': {'id': 11, 'name': 'GitLab Runner', 'username': 'gitlab-runner', 'state': 'active', 'avatar_url': 'https://gitlab.internal.com/uploads/-/system/user/avatar/11/gitlab-icon.png', 'web_url': 'https://gitlab.internal.com/gitlab-runner'}, 'assignees': [{'id': 11, 'name': 'GitLab Runner', 'username': 'gitlab-runner', 'state': 'active', 'avatar_url': 'https://gitlab.internal.com/uploads/-/system/user/avatar/11/gitlab-icon.png', 'web_url': 'https://gitlab.internal.com/gitlab-runner'}, {'id': 12, 'name': 'Merge Bot', 'username': 'merge-bot', 'state': 'active', 'avatar_url': 'https://gitlab.internal.com/uploads/-/system/user/avatar/12/merged-icon.png', 'web_url': 'https://gitlab.internal.com/merge-bot'}], 'assignee': {'id': 11, 'name': 'GitLab Runner', 'username': 'gitlab-runner', 'state': 'active', 'avatar_url': 'https://gitlab.internal.com/uploads/-/system/user/avatar/11/gitlab-icon.png', 'web_url': 'https://gitlab.internal.com/gitlab-runner'}, 'reviewers': [], 'source_project_id': 15, 'target_project_id': 15, 'labels': [], 'draft': False, 'work_in_progress': False, 'milestone': None, 'merge_when_pipeline_succeeds': False, 'merge_status': 'can_be_merged', 'sha': '256eb7988413c55f0587f3c9b4f009d78a1590ac', 'merge_commit_sha': None, 'squash_commit_sha': None, 'discussion_locked': None, 'should_remove_source_branch': None, 'force_remove_source_branch': True, 'reference': '!2862', 'references': {'short': '!2862', 'relative': '!2862', 'full': 'PROJECT_NAME!2862'}, 'web_url': 'https://gitlab.internal.com/PROJECT_NAME/-/merge_requests/2862', '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, 'approvals_before_merge': None, 'subscribed': True, 'changes_count': '2', 'latest_build_started_at': '2021-10-12T22:30:19.600Z', 'latest_build_finished_at': '2021-10-12T22:33:12.749Z', 'first_deployed_to_production_at': None, 'pipeline': {'id': 271485, 'project_id': 15, 'sha': '256eb7988413c55f0587f3c9b4f009d78a1590ac', 'ref': 'refs/merge-requests/2862/head', 'status': 'success', 'created_at': '2021-10-12T22:30:04.162Z', 'updated_at': '2021-10-12T22:33:12.756Z', 'web_url': 'https://gitlab.internal.com/PROJECT_NAME/-/pipelines/271485'}, 'head_pipeline': {'id': 271485, 'project_id': 15, 'sha': '256eb7988413c55f0587f3c9b4f009d78a1590ac', 'ref': 'refs/merge-requests/2862/head', 'status': 'success', 'created_at': '2021-10-12T22:30:04.162Z', 'updated_at': '2021-10-12T22:33:12.756Z', 'web_url': 'https://gitlab.internal.com/PROJECT_NAME/-/pipelines/271485', 'before_sha': '0000000000000000000000000000000000000000', 'tag': False, 'yaml_errors': None, 'user': {'id': 12, 'name': 'Merge Bot', 'username': 'merge-bot', 'state': 'active', 'avatar_url': 'https://gitlab.internal.com/uploads/-/system/user/avatar/12/merged-icon.png', 'web_url': 'https://gitlab.internal.com/merge-bot'}, 'started_at': '2021-10-12T22:30:19.600Z', 'finished_at': '2021-10-12T22:33:12.749Z', 'committed_at': None, 'duration': 169, 'queued_duration': 15, 'coverage': None, 'detailed_status': {'icon': 'status_success', 'text': 'passed', 'label': 'passed', 'group': 'success', 'tooltip': 'passed', 'has_details': True, 'details_path': '/PROJECT_NAME/-/pipelines/271485', 'illustration': None, 'favicon': '/assets/ci_favicons/favicon_status_success-8451333011eee8ce9f2ab25dc487fe24a8758c694827a582f17f42b0a90446a2.png'}}, 'diff_refs': {'base_sha': '15bd4fbbee381dcc1cc1e7d78969da896057f8ea', 'head_sha': '256eb7988413c55f0587f3c9b4f009d78a1590ac', 'start_sha': '15bd4fbbee381dcc1cc1e7d78969da896057f8ea'}, 'merge_error': 'This project requires squashing commits when merge requests are accepted.', 'user': {'can_merge': True}}
2021-10-13 21:47:54,956 INFO Successfully merged !2862.

[snim2]

I had a similar problem (with a different error report) a while ago. I never managed to track down the bug that caused it, but it was fixed by restarting and updating marge-bot. It would be useful to know whether your error persists...

[cmavromichalis]

@snim2 I was running with latest marge-bot.

I ended up restarting our GitLab-rails instances (sudo gitlab-ctl restart) since we self host and the error hasn't come back yet. I didn't restart our marge-bot. The projects are pretty active and have had several merge requests go through just fine but will keep watch over the next week to see if it comes back.

I think this is an error with GitLab and not with marge-bot that can cause marge-bot to loop forever. It would be nice for marge-bot to handle this somehow though; maybe confirm that the merge request was actually successful or not. I'll look at submitting an MR for this when I can get the time.

[snim2]

@cmavromichalis thanks. I think your diagnosis that it's a GitLab problem makes a lot of sense.

[bpuertolas]

My company uses the "squash commits" option and there is no way to make the marge-bot working.
In marge bot I have the following logs:

2021-11-15 16:04:33,912 INFO merge_request.accept result: {'id': 12xxxx47, 'iid': 3, 'project_id': 31xxxx520, 'title': 'Resolve "test3"', 'description': 'Closes #3', 'state': 'opened', '...  'merge_error': 'This project requires squashing commits when merge requests are accepted.', 'user': {'can_merge': True}}
2021-11-15 16:08:43,400 INFO Giving 10 more secs for !3 to be merged...
...
2021-11-15 16:09:34,759 WARNING I couldn't merge this branch: It is taking too long to see the request marked as merged!

We are on Gitlab.com and we are using the latest version of marge bot.
Are you sure the problem is coming from gitlab ?

[cmavromichalis]

@bpuertolas Yes I am sure. We are self-hosted. In the logs I provided you can see that GitLab returned a successful http code on merging when in fact it did not merge which is the error with GitLab.

2021-10-13 21:47:53,339 INFO Waiting for MR !2862 to have merge_status can_be_merged
2021-10-13 21:47:53,510 INFO MR !2862 can be merged on attempt 0
2021-10-13 21:47:53,706 INFO Ensuring MR !2862 is mergeable
2021-10-13 21:47:54,841 INFO merge_request.accept result: {'id': 73993, 'iid': 2862, 'project_id': 15, 'title': 'docker base image(s): security updates October 01 2021', 'description': None, 'state': 'opened', 'created_at': '2021-10-01T10:26:37.062Z', 'updated_at': '2021-10-12T22:33:19.716Z', 'merged_by': None, 'merged_at': None, 'closed_by': None, 'closed_at': None, 'target_branch': 'master', 'source_branch': 'jenkins/docker-updates-1633083995', 'user_notes_count': 1, 'upvotes': 0, 'downvotes': 0, 'author': {'id': 11, 'name': 'GitLab Runner', 'username': 'gitlab-runner', 'state': 'active', 'avatar_url': 'https://gitlab.internal.com/uploads/-/system/user/avatar/11/gitlab-icon.png', 'web_url': 'https://gitlab.internal.com/gitlab-runner'}, 'assignees': [{'id': 11, 'name': 'GitLab Runner', 'username': 'gitlab-runner', 'state': 'active', 'avatar_url': 'https://gitlab.internal.com/uploads/-/system/user/avatar/11/gitlab-icon.png', 'web_url': 'https://gitlab.internal.com/gitlab-runner'}, {'id': 12, 'name': 'Merge Bot', 'username': 'merge-bot', 'state': 'active', 'avatar_url': 'https://gitlab.internal.com/uploads/-/system/user/avatar/12/merged-icon.png', 'web_url': 'https://gitlab.internal.com/merge-bot'}], 'assignee': {'id': 11, 'name': 'GitLab Runner', 'username': 'gitlab-runner', 'state': 'active', 'avatar_url': 'https://gitlab.internal.com/uploads/-/system/user/avatar/11/gitlab-icon.png', 'web_url': 'https://gitlab.internal.com/gitlab-runner'}, 'reviewers': [], 'source_project_id': 15, 'target_project_id': 15, 'labels': [], 'draft': False, 'work_in_progress': False, 'milestone': None, 'merge_when_pipeline_succeeds': False, 'merge_status': 'can_be_merged', 'sha': '256eb7988413c55f0587f3c9b4f009d78a1590ac', 'merge_commit_sha': None, 'squash_commit_sha': None, 'discussion_locked': None, 'should_remove_source_branch': None, 'force_remove_source_branch': True, 'reference': '!2862', 'references': {'short': '!2862', 'relative': '!2862', 'full': 'PROJECT_NAME!2862'}, 'web_url': 'https://gitlab.internal.com/PROJECT_NAME/-/merge_requests/2862', '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, 'approvals_before_merge': None, 'subscribed': True, 'changes_count': '2', 'latest_build_started_at': '2021-10-12T22:30:19.600Z', 'latest_build_finished_at': '2021-10-12T22:33:12.749Z', 'first_deployed_to_production_at': None, 'pipeline': {'id': 271485, 'project_id': 15, 'sha': '256eb7988413c55f0587f3c9b4f009d78a1590ac', 'ref': 'refs/merge-requests/2862/head', 'status': 'success', 'created_at': '2021-10-12T22:30:04.162Z', 'updated_at': '2021-10-12T22:33:12.756Z', 'web_url': 'https://gitlab.internal.com/PROJECT_NAME/-/pipelines/271485'}, 'head_pipeline': {'id': 271485, 'project_id': 15, 'sha': '256eb7988413c55f0587f3c9b4f009d78a1590ac', 'ref': 'refs/merge-requests/2862/head', 'status': 'success', 'created_at': '2021-10-12T22:30:04.162Z', 'updated_at': '2021-10-12T22:33:12.756Z', 'web_url': 'https://gitlab.internal.com/PROJECT_NAME/-/pipelines/271485', 'before_sha': '0000000000000000000000000000000000000000', 'tag': False, 'yaml_errors': None, 'user': {'id': 12, 'name': 'Merge Bot', 'username': 'merge-bot', 'state': 'active', 'avatar_url': 'https://gitlab.internal.com/uploads/-/system/user/avatar/12/merged-icon.png', 'web_url': 'https://gitlab.internal.com/merge-bot'}, 'started_at': '2021-10-12T22:30:19.600Z', 'finished_at': '2021-10-12T22:33:12.749Z', 'committed_at': None, 'duration': 169, 'queued_duration': 15, 'coverage': None, 'detailed_status': {'icon': 'status_success', 'text': 'passed', 'label': 'passed', 'group': 'success', 'tooltip': 'passed', 'has_details': True, 'details_path': '/PROJECT_NAME/-/pipelines/271485', 'illustration': None, 'favicon': '/assets/ci_favicons/favicon_status_success-8451333011eee8ce9f2ab25dc487fe24a8758c694827a582f17f42b0a90446a2.png'}}, 'diff_refs': {'base_sha': '15bd4fbbee381dcc1cc1e7d78969da896057f8ea', 'head_sha': '256eb7988413c55f0587f3c9b4f009d78a1590ac', 'start_sha': '15bd4fbbee381dcc1cc1e7d78969da896057f8ea'}, 'merge_error': 'This project requires squashing commits when merge requests are accepted.', 'user': {'can_merge': True}}
2021-10-13 21:47:54,956 INFO Successfully merged !2862.

Your logs are giving a different warning so I think it is a different situation.

[bpuertolas]

We have both the same JSON result which contains 'merge_error': 'This project requires squashing commits when merge requests are accepted.' My marge-bot is waiting for the MR to be merged and not your version, maybe you just run an older version ?
I am wondering if marge-bot really try to merge without squashing ? In which case the error message we have is relevant, right ?

[JohnVillalovos]

So one issue is that GitLab will return success in the API call to merge the branch. But that doesn't mean that it is merged as it is an asynchronous operation.

In our functional tests for python-gitlab we do the merge request but then loop checking the status of the merge request to make sure it gets merged.

https://github.com/python-gitlab/python-gitlab/blob/158238779e4608e76138ae437acf80f3175d5580/tests/functional/api/test_merge_requests.py#L114-L126

[bpuertolas]

Sure it's a issue.
I also found that the Gitlab Merge Request accept API needs a squash boolean to squash all commits into a single one and it don't seem to be implemented in marge-bot (https://github.com/smarkets/marge-bot/blob/master/marge/merge_request.py#L203)

[JohnVillalovos]

Sure it's a issue. I also found that the Gitlab Merge Request accept API needs a squash boolean to squash all commits into a single one and it don't seem to be implemented in marge-bot (https://github.com/smarkets/marge-bot/blob/master/marge/merge_request.py#L203)

From my understanding a Project can set what the squash option should be, also when an MR is created it can set the squash option, and finally when the Merge Request Accept occurs it can set the squash option. If the squash option is not set in the MR Accept, it should then use what the value is set from when the MR is created, and if that is not set it should use the Project default.

I wonder if the MR for some reason got set to not squashing.

https://docs.gitlab.com/ee/api/merge_requests.html#create-mr

https://docs.gitlab.com/ee/api/projects.html#create-project

[bpuertolas]

Yes it should be like that. Unfornutaly, I just try on a test project:

>>> pr.mergerequests.get(4).merge()
No error message but "This project requires squashing commits when merge requests are accepted" is shown on the MR on Gitlab.com.

>>> pr.mergerequests.get(4).merge(squash=True)
The MR is merged correctly.

I will open an issue on the Gitlab project to ask if it's intentional.