Adds logging when mirror starts and finishes

app/models/ee/project.rb

@@ -84,6 +84,20 @@ module EE
       mirror? && self.mirror_last_update_at
     end
 
+    def mirror_waiting_duration
+      return unless mirror?
+
+      (mirror_data.last_update_started_at.to_i -
+        mirror_data.last_update_scheduled_at.to_i).seconds
+    end
+
+    def mirror_update_duration
+      return unless mirror?
+
+      (mirror_last_update_at.to_i -
+        mirror_data.last_update_started_at.to_i).seconds
+    end
+
     def mirror_with_content?
       mirror? && !empty_repo?
     end
@@ -190,6 +204,7 @@ module EE
         super
       elsif mirror?
         ::Gitlab::Mirror.increment_metric(:mirrors_scheduled, 'Mirrors scheduled count')
+        Rails.logger.info("Mirror update for #{full_path} was scheduled.")
 
         RepositoryUpdateMirrorWorker.perform_async(self.id)
       end

app/workers/repository_update_mirror_worker.rb

@@ -41,19 +41,23 @@ class RepositoryUpdateMirrorWorker
 
   def start_mirror(project)
     project.import_start
+
     Gitlab::Mirror.increment_metric(:mirrors_running, 'Mirrors running count')
+    Rails.logger.info("Mirror update for #{project.full_path} started. Waiting duration: #{project.mirror_waiting_duration}")
   end
 
   def fail_mirror(project, message)
-    project.mark_import_as_failed(message)
+    error_message = "Mirror update for #{project.full_path} failed with the following message: #{message}"
+    project.mark_import_as_failed(error_message)
 
     Gitlab::Mirror.increment_metric(:mirrors_failed, 'Mirrors failed count')
-    Rails.logger.error(message)
+    Rails.logger.error(error_message)
   end
 
   def finish_mirror(project)
     project.import_finish
 
     Gitlab::Mirror.increment_metric(:mirrors_finished, 'Mirrors successfully finished count')
+    Rails.logger.info("Mirror update for #{project.full_path} successfully finished. Update duration: #{project.mirror_update_duration}}.")
   end
 end

spec/factories/projects.rb

@@ -28,10 +28,18 @@ FactoryGirl.define do
 
     trait :import_scheduled do
       import_status :scheduled
+
+      after(:create) do |project, _|
+        project.mirror_data&.update_attributes(last_update_scheduled_at: Time.now)
+      end
     end
 
     trait :import_started do
       import_status :started
+
+      after(:create) do |project, _|
+        project.mirror_data&.update_attributes(last_update_started_at: Time.now)
+      end
     end
 
     trait :import_finished do

spec/models/ee/project_spec.rb

@@ -117,6 +117,27 @@ describe Project, models: true do
     end
   end
 
+  describe '#mirror_waiting_duration' do
+    it 'returns in seconds the time spent in the queue' do
+      project = create(:empty_project, :mirror, :import_scheduled)
+      mirror_data = project.mirror_data
+
+      mirror_data.update_attributes(last_update_started_at: mirror_data.last_update_scheduled_at + 5.minutes)
+
+      expect(project.mirror_waiting_duration).to eq(300)
+    end
+  end
+
+  describe '#mirror_update_duration' do
+    it 'returns in seconds the time spent updating' do
+      project = create(:empty_project, :mirror, :import_started)
+
+      project.update_attributes(mirror_last_update_at: project.mirror_data.last_update_started_at + 5.minutes)
+
+      expect(project.mirror_update_duration).to eq(300)
+    end
+  end
+
   describe '#any_runners_limit' do
     let(:project) { create(:empty_project, shared_runners_enabled: shared_runners_enabled) }
     let(:specific_runner) { create(:ci_runner) }

spec/workers/repository_update_mirror_worker_spec.rb

@@ -49,7 +49,7 @@ describe RepositoryUpdateMirrorWorker do
     end
 
     context 'threshold_reached?' do
-      let(:mirror) { create(:project, :mirror) }
+      let(:mirror) { create(:project, :mirror, :import_scheduled) }
 
       before do
         expect_any_instance_of(Projects::UpdateMirrorService).to receive(:execute).and_return(status: :success)