Add logging to MergeTrains::RefreshMergeRequestsService

This will help us to debug stuck merge trains

ee/app/services/merge_trains/refresh_merge_requests_service.rb

@@ -10,44 +10,60 @@ module MergeTrains
     # merge_request ... A merge request pointer in a merge train.
     #                   All the merge requests following the specified merge request will be refreshed.
     def execute(merge_request)
+      @merge_request = merge_request
+
       return unless merge_request.on_train?
 
-      queue = Gitlab::BatchPopQueueing.new('merge_trains', queue_id(merge_request))
+      queue = Gitlab::BatchPopQueueing.new('merge_trains', queue_id)
 
       result = queue.safe_execute([merge_request.id], lock_timeout: 15.minutes) do |items|
+        logging("Successfuly obtained the exclusive lock. Found merge requests to be refreshed", merge_request_ids: items.map(&:to_i))
+
         first_merge_request = MergeTrain.first_in_train_from(items)
         unsafe_refresh(first_merge_request)
       end
 
+      if result[:status] == :enqueued
+        logging("This merge request was enqueued because the exclusive lock is obtained by the other process.")
+      end
+
       if result[:status] == :finished && result[:new_items].present?
-        MergeTrain.first_in_train_from(result[:new_items]).try do |merge_request|
-          AutoMergeProcessWorker.perform_async(merge_request.id)
+        logging("Found more merge requests to be refreshed", merge_request_ids: result[:new_items].map(&:to_i))
+
+        MergeTrain.first_in_train_from(result[:new_items]).try do |first_merge_request|
+          logging("Rescheduled to refresh the merge train from", merge_request_ids: [first_merge_request.id])
+
+          AutoMergeProcessWorker.perform_async(first_merge_request.id)
         end
       end
     end
 
     private
 
-    def unsafe_refresh(merge_request)
+    attr_reader :merge_request
+
+    def unsafe_refresh(first_merge_request)
       require_next_recreate = false
 
-      following_merge_requests_from(merge_request).each do |merge_request|
-        break if merge_request.merge_train.index >= max_concurrency
+      following_merge_requests_from(first_merge_request).each do |following_mr|
+        logging("Started refreshing", merge_request_ids: [following_mr.id])
+
+        break if following_mr.merge_train.index >= max_concurrency
 
         result = MergeTrains::RefreshMergeRequestService
-          .new(merge_request.project, merge_request.merge_user,
+          .new(following_mr.project, following_mr.merge_user,
                require_recreate: require_next_recreate)
-          .execute(merge_request)
+          .execute(following_mr)
 
         require_next_recreate = (result[:status] == :error || result[:pipeline_created])
       end
     end
 
-    def following_merge_requests_from(merge_request)
-      merge_request.merge_train.all_next.to_a.unshift(merge_request)
+    def following_merge_requests_from(first_merge_request)
+      first_merge_request.merge_train.all_next.to_a.unshift(first_merge_request)
     end
 
-    def queue_id(merge_request)
+    def queue_id
       "#{merge_request.target_project_id}:#{merge_request.target_branch}"
     end
 
@@ -56,5 +72,13 @@ module MergeTrains
         DEFAULT_CONCURRENCY
       end
     end
+
+    def logging(message, extra = {})
+      return unless Feature.enabled?(:ci_merge_train_logging, merge_request.project)
+
+      Sidekiq.logger.info(
+        { class: self.class.to_s, args: [merge_request.id.to_s], message: message }.merge(extra)
+      )
+    end
   end
 end

ee/spec/services/merge_trains/refresh_merge_requests_service_spec.rb

@@ -45,6 +45,28 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
       allow(refresh_service_2).to receive(:execute) { refresh_service_2_result }
     end
 
+    shared_examples 'logging results' do |count|
+      context 'when ci_merge_train_logging is enabled' do
+        it 'logs results' do
+          expect(Sidekiq.logger).to receive(:info).exactly(count).times
+
+          subject
+        end
+      end
+
+      context 'when ci_merge_train_logging is disabled' do
+        before do
+          stub_feature_flags(ci_merge_train_logging: false)
+        end
+
+        it 'does not log results' do
+          expect(Sidekiq.logger).not_to receive(:info)
+
+          subject
+        end
+      end
+    end
+
     context 'when merge request 1 is passed' do
       let(:merge_request) { merge_request_1 }
 
@@ -55,6 +77,8 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
         subject
       end
 
+      it_behaves_like 'logging results', 3
+
       context 'when refresh service 1 returns error status' do
         let(:refresh_service_1_result) { { status: :error, message: 'Failed to create ref' } }
 
@@ -64,6 +88,8 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
 
           subject
         end
+
+        it_behaves_like 'logging results', 3
       end
 
       context 'when refresh service 1 returns success status and did not create a pipeline' do
@@ -75,6 +101,8 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
 
           subject
         end
+
+        it_behaves_like 'logging results', 3
       end
 
       context 'when refresh service 1 returns success status and created a pipeline' do
@@ -86,6 +114,8 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
 
           subject
         end
+
+        it_behaves_like 'logging results', 3
       end
 
       context 'when merge request 1 is not on a merge train' do
@@ -97,6 +127,8 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
 
           subject
         end
+
+        it_behaves_like 'logging results', 0
       end
 
       context 'when merge request 1 was on a merge train' do
@@ -110,6 +142,8 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
 
           subject
         end
+
+        it_behaves_like 'logging results', 0
       end
 
       context 'when the other thread has already been processing the merge train' do
@@ -132,6 +166,8 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
 
           subject
         end
+
+        it_behaves_like 'logging results', 1
       end
     end
 
@@ -145,6 +181,8 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
         subject
       end
 
+      it_behaves_like 'logging results', 2
+
       context 'when merge request 1 was tried to be refreshed while the system is refreshing merge request 2' do
         before do
           allow_any_instance_of(described_class).to receive(:unsafe_refresh).with(merge_request_2) do
@@ -158,6 +196,8 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
           subject
         end
 
+        it_behaves_like 'logging results', 4
+
         context 'when merge request 1 has already been merged' do
           before do
             allow(merge_request_1.merge_train).to receive(:cleanup_ref)
@@ -169,6 +209,8 @@ RSpec.describe MergeTrains::RefreshMergeRequestsService do
 
             subject
           end
+
+          it_behaves_like 'logging results', 1
         end
       end
     end