HTTP 500 when creating merge request
Everyone can contribute. Help move this issue forward while earning points, leveling up and collecting rewards.
Summary
Sometimes when creating a MR to a big repo, gitlab simply shows HTTP 500 page.
Steps to reproduce
Have a big repo and create a MR to it. If you're enough unlucky, there will be HTTP 500 page
What is the current bug behavior?
HTTP 500
What is the expected correct behavior?
MR create OK
Relevant logs and/or screenshots
Firstly it was:
Click to expand
{ "method": "POST", "path": "/__REMOVED__/__REMOVED__/-/merge_requests", "format": "html", "controller": "Projects::MergeRequests::CreationsController", "action": "create", "status": 500, "time": "2021-08-10T15:31:17.007Z", "params": [ { "key": "authenticity_token", "value": "[FILTERED]" }, { "key": "merge_request", "value": { "title": "[FILTERED]", "description": "[FILTERED]", "assignee_ids": [ "0" ], "reviewer_ids": [ "0" ], "label_ids": [ "" ], "force_remove_source_branch": "0", "squash": "0", "allow_collaboration": "1", "lock_version": "0", "source_project_id": "1746", "source_branch": "2020.1", "target_project_id": "1572", "target_branch": "2020.1" } }, { "key": "merge_request_diff_head_sha", "value": "229ae637d5a2a15d057b91569cfc5a2a6460c148" }, { "key": "namespace_id", "value": "__REMOVED__" }, { "key": "project_id", "value": "__REMOVED__" } ], "remote_ip": "__REMOVED__", "user_id": 370, "username": "__REMOVED__", "ua": "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.131 Safari/537.36", "correlation_id": "01FCRAXJZ86EKY9X352R3ZNN9Y", "meta.user": "__REMOVED__", "meta.project": "__REMOVED__/__REMOVED__", "meta.root_namespace": "__REMOVED__", "meta.caller_id": "Projects::MergeRequests::CreationsController#create", "meta.remote_ip": "__REMOVED__", "meta.feature_category": "code_review", "meta.client_id": "user/370", "gitaly_calls": 1, "gitaly_duration_s": 109.892609, "redis_calls": 8, "redis_duration_s": 0.001463, "redis_read_bytes": 1414, "redis_write_bytes": 1164, "redis_cache_calls": 7, "redis_cache_duration_s": 0.001146, "redis_cache_read_bytes": 1231, "redis_cache_write_bytes": 418, "redis_shared_state_calls": 1, "redis_shared_state_duration_s": 0.000317, "redis_shared_state_read_bytes": 183, "redis_shared_state_write_bytes": 746, "db_count": 27, "db_write_count": 5, "db_cached_count": 5, "cpu_s": 0.240871, "mem_objects": 30843, "mem_bytes": 3397752, "mem_mallocs": 8387, "mem_total_bytes": 4631472, "exception.class": "Gitlab::Git::CommandTimedOut", "exception.message": "4:Deadline Exceeded.", "exception.backtrace": [ "lib/gitlab/git/wraps_gitaly_errors.rb:13:in `rescue in wrapped_gitaly_errors'", "lib/gitlab/git/wraps_gitaly_errors.rb:6:in `wrapped_gitaly_errors'", "lib/gitlab/git/repository.rb:785:in `fetch_source_branch!'", "app/models/repository.rb:971:in `fetch_source_branch!'", "app/models/merge_request.rb:1402:in `fetch_ref!'", "app/models/merge_request.rb:995:in `create_merge_request_diff'", "app/models/merge_request.rb:991:in `ensure_merge_request_diff'", "app/services/issuable_base_service.rb:210:in `block in create'", "app/services/issuable_base_service.rb:209:in `create'", "app/services/merge_requests/base_service.rb:105:in `create'", "app/services/merge_requests/create_service.rb:29:in `create'", "app/services/merge_requests/create_service.rb:13:in `execute'", "app/controllers/projects/merge_requests/creations_controller.rb:22:in `create'", "app/controllers/application_controller.rb:483:in `set_current_admin'", "lib/gitlab/session.rb:11:in `with_session'", "app/controllers/application_controller.rb:474:in `set_session_storage'", "lib/gitlab/i18n.rb:99:in `with_locale'", "lib/gitlab/i18n.rb:105:in `with_user_locale'", "app/controllers/application_controller.rb:468:in `set_locale'", "app/controllers/application_controller.rb:462:in `set_current_context'", "lib/gitlab/middleware/speedscope.rb:13:in `call'", "lib/gitlab/request_profiler/middleware.rb:17:in `call'", "lib/gitlab/jira/middleware.rb:19:in `call'", "lib/gitlab/middleware/go.rb:20:in `call'", "lib/gitlab/etag_caching/middleware.rb:21:in `call'", "lib/gitlab/middleware/multipart.rb:172:in `call'", "lib/gitlab/middleware/read_only/controller.rb:50:in `call'", "lib/gitlab/middleware/read_only.rb:18:in `call'", "lib/gitlab/middleware/same_site_cookies.rb:27:in `call'", "lib/gitlab/middleware/handle_malformed_strings.rb:21:in `call'", "lib/gitlab/middleware/basic_health_check.rb:25:in `call'", "lib/gitlab/middleware/handle_ip_spoof_attack_error.rb:25:in `call'", "lib/gitlab/middleware/request_context.rb:21:in `call'", "config/initializers/fix_local_cache_middleware.rb:11:in `call'", "lib/gitlab/middleware/rack_multipart_tempfile_factory.rb:19:in `call'", "lib/gitlab/metrics/requests_rack_middleware.rb:74:in `call'", "lib/gitlab/middleware/release_env.rb:12:in `call'" ], "db_duration_s": 0.01216, "view_duration_s": 0.0, "duration_s": 109.97419 }After adjusting puma['worker_timeout'] to 120 it became:
Click to expand
{ "method": "POST", "path": "/__REMOVED__/__REMOVED__/-/merge_requests", "format": "html", "controller": "Projects::MergeRequests::CreationsController", "action": "create", "status": 500, "time": "2021-08-10T15:01:39.402Z", "params": [ { "key": "authenticity_token", "value": "[FILTERED]" }, { "key": "merge_request", "value": { "title": "[FILTERED]", "description": "[FILTERED]", "assignee_ids": [ "0" ], "reviewer_ids": [ "0" ], "label_ids": [ "" ], "force_remove_source_branch": "0", "squash": "0", "allow_collaboration": "1", "lock_version": "0", "source_project_id": "1746", "source_branch": "2020.1", "target_project_id": "1572", "target_branch": "2020.1" } }, { "key": "merge_request_diff_head_sha", "value": "229ae637d5a2a15d057b91569cfc5a2a6460c148" }, { "key": "namespace_id", "value": "__REMOVED__" }, { "key": "project_id", "value": "__REMOVED__" } ], "remote_ip": "__REMOVED__", "user_id": 370, "username": "__REMOVED__", "ua": "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.131 Safari/537.36", "correlation_id": "01FCR98VTZ5AENYT9G8AH5GKN2", "meta.user": "__REMOVED__", "meta.project": "__REMOVED__/__REMOVED__", "meta.root_namespace": "__REMOVED__", "meta.caller_id": "Projects::MergeRequests::CreationsController#create", "meta.remote_ip": "__REMOVED__", "meta.feature_category": "code_review", "meta.client_id": "user/370", "gitaly_calls": 1, "gitaly_duration_s": 0, "redis_calls": 8, "redis_duration_s": 0.00134, "redis_read_bytes": 1414, "redis_write_bytes": 1168, "redis_cache_calls": 7, "redis_cache_duration_s": 0.00116, "redis_cache_read_bytes": 1231, "redis_cache_write_bytes": 418, "redis_shared_state_calls": 1, "redis_shared_state_duration_s": 0.00018, "redis_shared_state_read_bytes": 183, "redis_shared_state_write_bytes": 750, "db_count": 27, "db_write_count": 5, "db_cached_count": 5, "cpu_s": 0.209629, "mem_objects": 35111, "mem_bytes": 4059808, "mem_mallocs": 11824, "mem_total_bytes": 5464248, "exception.class": "Rack::Timeout::RequestTimeoutException", "exception.message": "Request ran for longer than 60000ms", "exception.backtrace": [ "lib/gitlab/gitaly_client.rb:177:in `execute'", "lib/gitlab/gitaly_client/call.rb:18:in `block in call'", "lib/gitlab/gitaly_client/call.rb:55:in `recording_request'", "lib/gitlab/gitaly_client/call.rb:17:in `call'", "lib/gitlab/gitaly_client.rb:167:in `call'", "lib/gitlab/gitaly_client/repository_service.rb:180:in `fetch_source_branch'", "lib/gitlab/git/repository.rb:786:in `block in fetch_source_branch!'", "lib/gitlab/git/wraps_gitaly_errors.rb:7:in `wrapped_gitaly_errors'", "lib/gitlab/git/repository.rb:785:in `fetch_source_branch!'", "app/models/repository.rb:971:in `fetch_source_branch!'", "app/models/merge_request.rb:1402:in `fetch_ref!'", "app/models/merge_request.rb:995:in `create_merge_request_diff'", "app/models/merge_request.rb:991:in `ensure_merge_request_diff'", "app/services/issuable_base_service.rb:210:in `block in create'", "app/services/issuable_base_service.rb:209:in `create'", "app/services/merge_requests/base_service.rb:105:in `create'", "app/services/merge_requests/create_service.rb:29:in `create'", "app/services/merge_requests/create_service.rb:13:in `execute'", "app/controllers/projects/merge_requests/creations_controller.rb:22:in `create'", "app/controllers/application_controller.rb:483:in `set_current_admin'", "lib/gitlab/session.rb:11:in `with_session'", "app/controllers/application_controller.rb:474:in `set_session_storage'", "lib/gitlab/i18n.rb:99:in `with_locale'", "lib/gitlab/i18n.rb:105:in `with_user_locale'", "app/controllers/application_controller.rb:468:in `set_locale'", "app/controllers/application_controller.rb:462:in `set_current_context'", "lib/gitlab/middleware/speedscope.rb:13:in `call'", "lib/gitlab/request_profiler/middleware.rb:17:in `call'", "lib/gitlab/jira/middleware.rb:19:in `call'", "lib/gitlab/middleware/go.rb:20:in `call'", "lib/gitlab/etag_caching/middleware.rb:21:in `call'", "lib/gitlab/middleware/multipart.rb:172:in `call'", "lib/gitlab/middleware/read_only/controller.rb:50:in `call'", "lib/gitlab/middleware/read_only.rb:18:in `call'", "lib/gitlab/middleware/same_site_cookies.rb:27:in `call'", "lib/gitlab/middleware/handle_malformed_strings.rb:21:in `call'", "lib/gitlab/middleware/basic_health_check.rb:25:in `call'", "lib/gitlab/middleware/handle_ip_spoof_attack_error.rb:25:in `call'", "lib/gitlab/middleware/request_context.rb:21:in `call'", "config/initializers/fix_local_cache_middleware.rb:11:in `call'", "lib/gitlab/middleware/rack_multipart_tempfile_factory.rb:19:in `call'", "lib/gitlab/metrics/requests_rack_middleware.rb:74:in `call'", "lib/gitlab/middleware/release_env.rb:12:in `call'" ], "db_duration_s": 3.7426, "view_duration_s": 0.0, "duration_s": 59.98975 }After gitlab_rails['env'] = { 'GITLAB_RAILS_RACK_TIMEOUT' => 120 } it became:
Click to expand
{ "method": "POST", "path": "/__REMOVED__/__REMOVED__/-/merge_requests", "format": "html", "controller": "Projects::MergeRequests::CreationsController", "action": "create", "status": 500, "time": "2021-08-10T15:12:10.017Z", "params": [ { "key": "authenticity_token", "value": "[FILTERED]" }, { "key": "merge_request", "value": { "title": "[FILTERED]", "description": "[FILTERED]", "assignee_ids": [ "0" ], "reviewer_ids": [ "0" ], "label_ids": [ "" ], "force_remove_source_branch": "0", "squash": "0", "allow_collaboration": "1", "lock_version": "0", "source_project_id": "1746", "source_branch": "2020.1", "target_project_id": "1572", "target_branch": "2020.1" } }, { "key": "merge_request_diff_head_sha", "value": "229ae637d5a2a15d057b91569cfc5a2a6460c148" }, { "key": "namespace_id", "value": "__REMOVED__" }, { "key": "project_id", "value": "__REMOVED__" } ], "remote_ip": "__REMOVED__", "user_id": 370, "username": "__REMOVED__", "ua": "Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/92.0.4515.131 Safari/537.36", "correlation_id": "01FCR9TKDPVE5JAEYM6NHS4VKD", "meta.user": "dikan.igor", "meta.project": "__REMOVED__/__REMOVED__", "meta.root_namespace": "__REMOVED__", "meta.caller_id": "Projects::MergeRequests::CreationsController#create", "meta.remote_ip": "__REMOVED__", "meta.feature_category": "code_review", "meta.client_id": "user/370", "gitaly_calls": 1, "gitaly_duration_s": 109.214853, "redis_calls": 6, "redis_duration_s": 0.001067, "redis_read_bytes": 1009, "redis_write_bytes": 1061, "redis_cache_calls": 5, "redis_cache_duration_s": 0.000838, "redis_cache_read_bytes": 826, "redis_cache_write_bytes": 311, "redis_shared_state_calls": 1, "redis_shared_state_duration_s": 0.000229, "redis_shared_state_read_bytes": 183, "redis_shared_state_write_bytes": 750, "db_count": 27, "db_write_count": 5, "db_cached_count": 5, "cpu_s": 0.303356, "mem_objects": 48100, "mem_bytes": 7675216, "mem_mallocs": 25851, "mem_total_bytes": 9599216, "exception.class": "ActiveRecord::StatementInvalid", "exception.message": "PG::ConnectionBad: PQconsumeInput() server closed the connection unexpectedly\n\tThis probably means the server terminated abnormally\n\tbefore or while processing the request.\n", "exception.backtrace": [ "app/services/issuable_base_service.rb:209:in `create'", "app/services/merge_requests/base_service.rb:105:in `create'", "app/services/merge_requests/create_service.rb:29:in `create'", "app/services/merge_requests/create_service.rb:13:in `execute'", "app/controllers/projects/merge_requests/creations_controller.rb:22:in `create'", "app/controllers/application_controller.rb:483:in `set_current_admin'", "lib/gitlab/session.rb:11:in `with_session'", "app/controllers/application_controller.rb:474:in `set_session_storage'", "lib/gitlab/i18n.rb:99:in `with_locale'", "lib/gitlab/i18n.rb:105:in `with_user_locale'", "app/controllers/application_controller.rb:468:in `set_locale'", "app/controllers/application_controller.rb:462:in `set_current_context'", "lib/gitlab/middleware/speedscope.rb:13:in `call'", "lib/gitlab/request_profiler/middleware.rb:17:in `call'", "lib/gitlab/jira/middleware.rb:19:in `call'", "lib/gitlab/middleware/go.rb:20:in `call'", "lib/gitlab/etag_caching/middleware.rb:21:in `call'", "lib/gitlab/middleware/multipart.rb:172:in `call'", "lib/gitlab/middleware/read_only/controller.rb:50:in `call'", "lib/gitlab/middleware/read_only.rb:18:in `call'", "lib/gitlab/middleware/same_site_cookies.rb:27:in `call'", "lib/gitlab/middleware/handle_malformed_strings.rb:21:in `call'", "lib/gitlab/middleware/basic_health_check.rb:25:in `call'", "lib/gitlab/middleware/handle_ip_spoof_attack_error.rb:25:in `call'", "lib/gitlab/middleware/request_context.rb:21:in `call'", "config/initializers/fix_local_cache_middleware.rb:11:in `call'", "lib/gitlab/middleware/rack_multipart_tempfile_factory.rb:19:in `call'", "lib/gitlab/metrics/requests_rack_middleware.rb:74:in `call'", "lib/gitlab/middleware/release_env.rb:12:in `call'" ], "db_duration_s": 0.0284, "view_duration_s": 0.0, "duration_s": 109.39523 }Postgresql logs stated:
FATAL: terminating connection due to idle-in-transaction timeout
After adjusting idle_in_transaction_session_timeout there was no error and for now it works.
So you would adjust default timeouts or you can try to optimize merge request creation code.
Edited  by 🤖 GitLab Bot 🤖