MR merge DB transaction fails on `user_interacted_project` insertion
Summary
When one of my users tried to merge the first MR on a project as the owner of its group, the merge job failed, leaving the MR in an invalid state, marked as not mergeable. Logs trace it back to a failed user_interacted_project
insertion.
Steps to reproduce
Sadly, none so far
What is the current bug behavior?
The MR is merged, but the active MR number "bubble" for the project didn't decrement (even though the project active MR states the correct number), and Gitlab doesn't seem to have recorded the identity of the merge action author. When looking at the MR itself, there are confusing error messages and missing state.
What is the expected correct behavior?
Ideally, the merge action is successfully recorded, or at least Gitlab figures out after the facts that the MR has been merged. But I'll settle for a way to manually correct this MR ;-)
Relevant logs and/or screenshots
When looking through the logs, I find the following sidekiq warnings :
Sidekiq messages
[
{
"meta.root_namespace" : "helm",
"enqueued_at" : "2020-10-20T15:06:26.334Z",
"db_write_count" : 12,
"created_at" : "2020-10-20T15:06:26.333Z",
"error_backtrace" : [
"app/models/user_interacted_project.rb:25:in `block in track'",
"app/models/user_interacted_project.rb:42:in `cached_exists?'",
"lib/gitlab/metrics/instrumentation.rb:160:in `block in cached_exists?'",
"lib/gitlab/metrics/method_call.rb:27:in `measure'",
"lib/gitlab/metrics/instrumentation.rb:160:in `cached_exists?'",
"app/models/user_interacted_project.rb:24:in `track'",
"lib/gitlab/metrics/instrumentation.rb:160:in `block in track'",
"lib/gitlab/metrics/method_call.rb:27:in `measure'",
"lib/gitlab/metrics/instrumentation.rb:160:in `track'",
"app/models/event.rb:82:in `block in <class:Event>'",
"app/services/event_create_service.rb:203:in `create_event'",
"app/services/event_create_service.rb:137:in `create_record_event'",
"app/services/event_create_service.rb:42:in `merge_mr'",
"app/services/merge_requests/post_merge_service.rb:45:in `create_merge_event'",
"lib/gitlab/metrics/instrumentation.rb:160:in `block in create_merge_event'",
"lib/gitlab/metrics/method_call.rb:27:in `measure'",
"lib/gitlab/metrics/instrumentation.rb:160:in `create_merge_event'",
"app/services/merge_requests/post_merge_service.rb:52:in `block in create_event'",
"app/services/merge_requests/post_merge_service.rb:51:in `create_event'",
"lib/gitlab/metrics/instrumentation.rb:160:in `block in create_event'",
"lib/gitlab/metrics/method_call.rb:27:in `measure'",
"lib/gitlab/metrics/instrumentation.rb:160:in `create_event'",
"app/services/merge_requests/post_merge_service.rb:16:in `execute'",
"lib/gitlab/metrics/instrumentation.rb:160:in `block in execute'",
"lib/gitlab/metrics/method_call.rb:27:in `measure'",
"lib/gitlab/metrics/instrumentation.rb:160:in `execute'",
"app/services/merge_requests/merge_service.rb:102:in `after_merge'",
"lib/gitlab/metrics/instrumentation.rb:160:in `block in after_merge'",
"lib/gitlab/metrics/method_call.rb:27:in `measure'",
"lib/gitlab/metrics/instrumentation.rb:160:in `after_merge'",
"app/services/merge_requests/merge_service.rb:26:in `block in execute'",
"app/models/merge_request.rb:1299:in `in_locked_state'",
"lib/gitlab/metrics/instrumentation.rb:160:in `block in in_locked_state'",
"lib/gitlab/metrics/method_call.rb:27:in `measure'",
"lib/gitlab/metrics/instrumentation.rb:160:in `in_locked_state'",
"app/services/merge_requests/merge_service.rb:24:in `execute'",
"lib/gitlab/metrics/instrumentation.rb:160:in `block in execute'",
"lib/gitlab/metrics/method_call.rb:27:in `measure'",
"lib/gitlab/metrics/instrumentation.rb:160:in `execute'",
"app/workers/merge_worker.rb:17:in `perform'",
"lib/gitlab/metrics/sidekiq_middleware.rb:18:in `block in call'",
"lib/gitlab/metrics/transaction.rb:61:in `run'",
"lib/gitlab/metrics/sidekiq_middleware.rb:18:in `call'",
"lib/gitlab/sidekiq_middleware/duplicate_jobs/strategies/until_executing.rb:32:in `perform'",
"lib/gitlab/sidekiq_middleware/duplicate_jobs/duplicate_job.rb:40:in `perform'",
"lib/gitlab/sidekiq_middleware/duplicate_jobs/server.rb:8:in `call'",
"lib/gitlab/sidekiq_middleware/worker_context.rb:9:in `wrap_in_optional_context'",
"lib/gitlab/sidekiq_middleware/worker_context/server.rb:16:in `call'",
"lib/gitlab/sidekiq_status/server_middleware.rb:7:in `call'",
"lib/gitlab/sidekiq_versioning/middleware.rb:9:in `call'",
"lib/gitlab/sidekiq_middleware/admin_mode/server.rb:8:in `call'",
"lib/gitlab/sidekiq_middleware/instrumentation_logger.rb:7:in `call'",
"lib/gitlab/sidekiq_middleware/batch_loader.rb:7:in `call'",
"lib/gitlab/sidekiq_middleware/extra_done_log_metadata.rb:7:in `call'",
"lib/gitlab/sidekiq_middleware/request_store_middleware.rb:10:in `block in call'",
"lib/gitlab/with_request_store.rb:17:in `enabling_request_store'",
"lib/gitlab/with_request_store.rb:10:in `with_request_store'",
"lib/gitlab/sidekiq_middleware/request_store_middleware.rb:9:in `call'",
"lib/gitlab/sidekiq_middleware/server_metrics.rb:35:in `call'",
"lib/gitlab/sidekiq_middleware/monitor.rb:8:in `block in call'",
"lib/gitlab/sidekiq_daemon/monitor.rb:49:in `within_job'",
"lib/gitlab/sidekiq_middleware/monitor.rb:7:in `call'",
"lib/gitlab/sidekiq_logging/structured_logger.rb:18:in `call'"
],
"db_cached_count" : 2,
"args" : [
"139",
"10",
"{\"should_remove_source_branch\"=>true, \"commit_message\"=>\"Merge branch 'S202043' into 'master'\\n\\nmediation, rating, charging, antifraud, el_indexing -> 1.0.106\\n\\nSee merge request helm/colbert!1\", \"sha\"=>\"6a467753e5e433811c71495b933a5857d4aa1524\"}"
],
"retry" : 3,
"jid" : "c42ac9d22fd4b7dee0edf425",
"time" : "2020-10-20T15:06:27.053Z",
"severity" : "WARN",
"error_message" : "PG::InFailedSqlTransaction: ERROR: current transaction is aborted, commands ignored until end of transaction block\n",
"meta.project" : "helm/colbert",
"correlation_id" : "tccLahUJmc6",
"version" : 0,
"class" : "MergeWorker",
"error_class" : "ActiveRecord::StatementInvalid",
"meta.user" : "REDACTED",
"context" : "Job raised exception",
"queue" : "merge",
"db_count" : 39,
"meta.caller_id" : "Projects::MergeRequestsController#merge"
},
{
"duration_s" : 0.709315,
"pid" : 10871,
"job_status" : "fail",
"error_message" : "Sidekiq::JobRetry::Skip",
"jid" : "c42ac9d22fd4b7dee0edf425",
"created_at" : "2020-10-20T15:06:26.333Z",
"meta.root_namespace" : "helm",
"db_cached_count" : 2,
"completed_at" : "2020-10-20T15:06:27.045Z",
"meta.caller_id" : "Projects::MergeRequestsController#merge",
"scheduling_latency_s" : 0.001533,
"message" : "MergeWorker JID-c42ac9d22fd4b7dee0edf425: fail: 0.709315 sec",
"time" : "2020-10-20T15:06:27.045Z",
"severity" : "WARN",
"correlation_id" : "tccLahUJmc6",
"meta.project" : "helm/colbert",
"retry" : 3,
"enqueued_at" : "2020-10-20T15:06:26.334Z",
"db_duration_s" : 0.236887,
"db_write_count" : 12,
"meta.user" : "REDACTED",
"cpu_s" : 0.108459,
"queue" : "merge",
"db_count" : 39,
"version" : 0,
"class" : "MergeWorker",
"error_class" : "Sidekiq::JobRetry::Skip"
},
{
"meta.root_namespace" : "helm",
"enqueued_at" : "2020-10-20T15:06:26.334Z",
"created_at" : "2020-10-20T15:06:26.333Z",
"db_write_count" : 12,
"error_backtrace" : [
"app/models/user_interacted_project.rb:25:in `block in track'",
"app/models/user_interacted_project.rb:42:in `cached_exists?'",
"lib/gitlab/metrics/instrumentation.rb:160:in `block in cached_exists?'",
"lib/gitlab/metrics/method_call.rb:27:in `measure'",
"lib/gitlab/metrics/instrumentation.rb:160:in `cached_exists?'",
"app/models/user_interacted_project.rb:24:in `track'",
"lib/gitlab/metrics/instrumentation.rb:160:in `block in track'",
"lib/gitlab/metrics/method_call.rb:27:in `measure'",
"lib/gitlab/metrics/instrumentation.rb:160:in `track'",
"app/models/event.rb:82:in `block in <class:Event>'",
"app/services/event_create_service.rb:203:in `create_event'",
"app/services/event_create_service.rb:137:in `create_record_event'",
"app/services/event_create_service.rb:42:in `merge_mr'",
"app/services/merge_requests/post_merge_service.rb:45:in `create_merge_event'",
"lib/gitlab/metrics/instrumentation.rb:160:in `block in create_merge_event'",
"lib/gitlab/metrics/method_call.rb:27:in `measure'",
"lib/gitlab/metrics/instrumentation.rb:160:in `create_merge_event'",
"app/services/merge_requests/post_merge_service.rb:52:in `block in create_event'",
"app/services/merge_requests/post_merge_service.rb:51:in `create_event'",
"lib/gitlab/metrics/instrumentation.rb:160:in `block in create_event'",
"lib/gitlab/metrics/method_call.rb:27:in `measure'",
"lib/gitlab/metrics/instrumentation.rb:160:in `create_event'",
"app/services/merge_requests/post_merge_service.rb:16:in `execute'",
"lib/gitlab/metrics/instrumentation.rb:160:in `block in execute'",
"lib/gitlab/metrics/method_call.rb:27:in `measure'",
"lib/gitlab/metrics/instrumentation.rb:160:in `execute'",
"app/services/merge_requests/merge_service.rb:102:in `after_merge'",
"lib/gitlab/metrics/instrumentation.rb:160:in `block in after_merge'",
"lib/gitlab/metrics/method_call.rb:27:in `measure'",
"lib/gitlab/metrics/instrumentation.rb:160:in `after_merge'",
"app/services/merge_requests/merge_service.rb:26:in `block in execute'",
"app/models/merge_request.rb:1299:in `in_locked_state'",
"lib/gitlab/metrics/instrumentation.rb:160:in `block in in_locked_state'",
"lib/gitlab/metrics/method_call.rb:27:in `measure'",
"lib/gitlab/metrics/instrumentation.rb:160:in `in_locked_state'",
"app/services/merge_requests/merge_service.rb:24:in `execute'",
"lib/gitlab/metrics/instrumentation.rb:160:in `block in execute'",
"lib/gitlab/metrics/method_call.rb:27:in `measure'",
"lib/gitlab/metrics/instrumentation.rb:160:in `execute'",
"app/workers/merge_worker.rb:17:in `perform'",
"lib/gitlab/metrics/sidekiq_middleware.rb:18:in `block in call'",
"lib/gitlab/metrics/transaction.rb:61:in `run'",
"lib/gitlab/metrics/sidekiq_middleware.rb:18:in `call'",
"lib/gitlab/sidekiq_middleware/duplicate_jobs/strategies/until_executing.rb:32:in `perform'",
"lib/gitlab/sidekiq_middleware/duplicate_jobs/duplicate_job.rb:40:in `perform'",
"lib/gitlab/sidekiq_middleware/duplicate_jobs/server.rb:8:in `call'",
"lib/gitlab/sidekiq_middleware/worker_context.rb:9:in `wrap_in_optional_context'",
"lib/gitlab/sidekiq_middleware/worker_context/server.rb:16:in `call'",
"lib/gitlab/sidekiq_status/server_middleware.rb:7:in `call'",
"lib/gitlab/sidekiq_versioning/middleware.rb:9:in `call'",
"lib/gitlab/sidekiq_middleware/admin_mode/server.rb:8:in `call'",
"lib/gitlab/sidekiq_middleware/instrumentation_logger.rb:7:in `call'",
"lib/gitlab/sidekiq_middleware/batch_loader.rb:7:in `call'",
"lib/gitlab/sidekiq_middleware/extra_done_log_metadata.rb:7:in `call'",
"lib/gitlab/sidekiq_middleware/request_store_middleware.rb:10:in `block in call'",
"lib/gitlab/with_request_store.rb:17:in `enabling_request_store'",
"lib/gitlab/with_request_store.rb:10:in `with_request_store'",
"lib/gitlab/sidekiq_middleware/request_store_middleware.rb:9:in `call'",
"lib/gitlab/sidekiq_middleware/server_metrics.rb:35:in `call'",
"lib/gitlab/sidekiq_middleware/monitor.rb:8:in `block in call'",
"lib/gitlab/sidekiq_daemon/monitor.rb:49:in `within_job'",
"lib/gitlab/sidekiq_middleware/monitor.rb:7:in `call'",
"lib/gitlab/sidekiq_logging/structured_logger.rb:18:in `call'"
],
"db_cached_count" : 2,
"args" : [
"139",
"10",
"{\"should_remove_source_branch\"=>true, \"commit_message\"=>\"Merge branch 'S202043' into 'master'\\n\\nmediation, rating, charging, antifraud, el_indexing -> 1.0.106\\n\\nSee merge request helm/colbert!1\", \"sha\"=>\"6a467753e5e433811c71495b933a5857d4aa1524\"}"
],
"jid" : "c42ac9d22fd4b7dee0edf425",
"retry" : 3,
"severity" : "WARN",
"error_message" : "PG::InFailedSqlTransaction: ERROR: current transaction is aborted, commands ignored until end of transaction block\n",
"time" : "2020-10-20T15:06:27.053Z",
"meta.project" : "helm/colbert",
"correlation_id" : "tccLahUJmc6",
"version" : 0,
"class" : "MergeWorker",
"error_class" : "ActiveRecord::StatementInvalid",
"meta.user" : "REDACTED",
"context" : "Job raised exception",
"db_count" : 39,
"queue" : "merge",
"meta.caller_id" : "Projects::MergeRequestsController#merge"
}
]
And here are the matching Postgresql logs
PGSQL logs
2020-10-20_15:06:26.91271 ERROR: duplicate key value violates unique constraint "index_user_interacted_projects_on_project_id_and_user_id"
2020-10-20_15:06:26.91274 DETAIL: Key (project_id, user_id)=(72, 10) already exists.
2020-10-20_15:06:26.91274 STATEMENT: INSERT INTO "user_interacted_projects" ("user_id", "project_id") VALUES (10, 72)
2020-10-20_15:06:26.92600 ERROR: current transaction is aborted, commands ignored until end of transaction block
2020-10-20_15:06:26.92605 STATEMENT: RELEASE SAVEPOINT active_record_1
Output of checks
Results of GitLab environment info
Expand for output related to GitLab environment info
System information System: Debian 10 Current User: git Using RVM: no Ruby Version: 2.6.6p146 Gem Version: 2.7.10 Bundler Version:1.17.3 Rake Version: 12.3.3 Redis Version: 5.0.9 Git Version: 2.28.0 Sidekiq Version:5.2.9 Go Version: unknown GitLab information Version: 13.4.1 Revision: c90be62bdef Directory: /opt/gitlab/embedded/service/gitlab-rails DB Adapter: PostgreSQL DB Version: 11.7 URL: https://gitlab.alphalink.tech HTTP Clone URL: https://gitlab.alphalink.tech/some-group/some-project.git SSH Clone URL: git@gitlab.alphalink.tech:some-group/some-project.git Using LDAP: no Using Omniauth: yes Omniauth Providers: openid_connect GitLab Shell Version: 13.7.0 Repository storage paths: - default: /var/opt/gitlab/git-data/repositories GitLab Shell path: /opt/gitlab/embedded/service/gitlab-shell Git: /opt/gitlab/embedded/bin/git
Results of GitLab application Check
Expand for output related to the GitLab application check
Checking GitLab subtasks ...Checking GitLab Shell ...
GitLab Shell: ... GitLab Shell version >= 13.7.0 ? ... OK (13.7.0) Running /opt/gitlab/embedded/service/gitlab-shell/bin/check Internal API available: OK Redis available via internal API: OK gitlab-shell self-check successful
Checking GitLab Shell ... Finished
Checking Gitaly ...
Gitaly: ... default ... OK
Checking Gitaly ... Finished
Checking Sidekiq ...
Sidekiq: ... Running? ... yes Number of Sidekiq processes ... 1
Checking Sidekiq ... Finished
Checking Incoming Email ...
Incoming Email: ... Reply by email is disabled in config/gitlab.yml
Checking Incoming Email ... Finished
Checking LDAP ...
LDAP: ... LDAP is disabled in config/gitlab.yml
Checking LDAP ... Finished
Checking GitLab App ...
Git configured correctly? ... yes Database config exists? ... yes All migrations up? ... yes Database contains orphaned GroupMembers? ... no GitLab config exists? ... yes GitLab config up to date? ... yes Log directory writable? ... yes Tmp directory writable? ... yes Uploads directory exists? ... yes Uploads directory has correct permissions? ... yes Uploads directory tmp has correct permissions? ... yes Init script exists? ... skipped (omnibus-gitlab has no init script) Init script up-to-date? ... skipped (omnibus-gitlab has no init script) Projects have namespace: ... 1/1 ... yes 1/2 ... yes 3/3 ... yes 3/4 ... yes 3/5 ... yes 3/6 ... yes 3/7 ... yes 5/8 ... yes 3/9 ... yes 4/10 ... yes 4/11 ... yes 6/14 ... yes 6/15 ... yes 7/16 ... yes 5/17 ... yes 5/18 ... yes 3/20 ... yes 5/21 ... yes 10/22 ... yes 10/23 ... yes 10/24 ... yes 10/25 ... yes 10/26 ... yes 10/27 ... yes 10/28 ... yes 10/29 ... yes 10/30 ... yes 10/31 ... yes 3/32 ... yes 5/33 ... yes 3/34 ... yes 6/37 ... yes 13/38 ... yes 3/39 ... yes 3/40 ... yes 19/41 ... yes 19/42 ... yes 5/43 ... yes 4/44 ... yes 4/45 ... yes 20/46 ... yes 20/47 ... yes 20/48 ... yes 20/49 ... yes 4/50 ... yes 18/51 ... yes 18/52 ... yes 5/53 ... yes 4/55 ... yes 18/56 ... yes 3/57 ... yes 5/58 ... yes 18/59 ... yes 18/60 ... yes 18/61 ... yes 18/62 ... yes 3/63 ... yes 3/64 ... yes 25/65 ... yes 25/66 ... yes 25/67 ... yes 3/68 ... yes 25/69 ... yes 3/70 ... yes 3/71 ... yes 28/72 ... yes 28/73 ... yes 28/74 ... yes 28/75 ... yes 28/76 ... yes 22/77 ... yes 18/83 ... yes 25/84 ... yes 18/85 ... yes 18/86 ... yes 5/87 ... yes 5/88 ... yes 18/89 ... yes 5/90 ... yes 5/91 ... yes 3/92 ... yes 18/93 ... yes 18/94 ... yes 18/95 ... yes 3/96 ... yes 33/97 ... yes 34/98 ... yes 34/99 ... yes 30/100 ... yes 30/101 ... yes 30/102 ... yes 30/103 ... yes 30/104 ... yes 30/105 ... yes 29/106 ... yes 22/107 ... yes 34/108 ... yes 18/109 ... yes 28/110 ... yes 15/111 ... yes 21/112 ... yes 3/113 ... yes 21/114 ... yes 3/115 ... yes 6/116 ... yes 15/117 ... yes 6/119 ... yes 25/120 ... yes 30/121 ... yes 15/122 ... yes 26/123 ... yes Redis version >= 4.0.0? ... yes Ruby version >= 2.5.3 ? ... yes (2.6.6) Git version >= 2.24.0 ? ... yes (2.28.0) Git user has default SSH configuration? ... yes Active users: ... 21 Is authorized keys file accessible? ... yes GitLab configured to store new projects in hashed storage? ... yes All projects are in hashed storage? ... yes
Checking GitLab App ... Finished
Checking GitLab subtasks ... Finished
Possible fixes
TBD