Merge Requests: error noise in logs and useless retries
Looking at the background jobs logs for other reasons, I see lots of this:
{"severity":"WARN","time":"2021-02-13T11:33:27.112Z","error_class":"Gitlab::Git::Repository::GitError","error_message":"Refs cannot be manually deleted in Mercurial","context":"Job raised exception","class":"MergeRequestCleanupRefsWorker","args":["6826"],"retry":3,"queue":"merge_request_cleanup_refs","version":0,"jid":"530747ab24cc504962114008","created_at":"2021-02-13T11:32:34.052Z","enqueued_at":"2021-02-13T11:33:27.022Z","meta.caller_id":"ScheduleMergeRequestCleanupRefsWorker","meta.feature_category":"code_review","correlation_id":"0840b2f6d148d798dcc47b8b78497f4e","failed_at":"2021-02-13T11:32:49.778Z","retry_count":0,"error_backtrace":["lib/gitlab/gitaly_client/ref_service.rb:158:in `delete_refs'","lib/gitlab/git/repository.rb:1194:in `gitaly_delete_refs'","lib/gitlab/git/repository.rb:741:in `block in delete_refs'","lib/gitlab/git/wraps_gitaly_errors.rb:7:in `wrapped_gitaly_errors'","lib/gitlab/git/repository.rb:740:in `delete_refs'","app/models/repository.rb:912:in `delete_refs'","app/services/merge_requests/cleanup_refs_service.rb:80:in `delete_refs'","app/services/merge_requests/cleanup_refs_service.rb:34:in `execute'","app/workers/merge_request_cleanup_refs_worker.rb:17:in `perform'","lib/gitlab/sidekiq_middleware/duplicate_jobs/strategies/until_executing.rb:16: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:17:in `block in call'","lib/gitlab/application_context.rb:54:in `block in use'","lib/gitlab/application_context.rb:54:in `use'","lib/gitlab/application_context.rb:21:in `with_context'","lib/gitlab/sidekiq_middleware/worker_context/server.rb:15: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:37: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'"]}
Early versions of MR merge treatment (around the time of Heptapod 0.8 or 0.12) were careful not to try removing branches from the Rails code and/or managed not to make this an error, but this is obviously not working properly any more.
This is very common because a topic publication is a branch removal from the point of view of the Rails app.
In turn, this leads to unwanted retries that certainly have a non trivial impact on the overall performance of the systes.
Also this makes investigation of problems harder because of the noise it generates in logs and various reporting about background jobs.