Merge branch 'sh-instrument-geo-downloads' into 'master'

Log Geo update delay and download times of repository sync

Closes #3020

See merge request !2721

app/services/geo/base_sync_service.rb

@@ -85,5 +85,25 @@ def update_registry(started_at: nil, finished_at: nil)
     def type
       self.class.type
     end
+
+    def update_delay_in_seconds
+      # We don't track the last update time of repositories and Wiki
+      # separately in the main database
+      return unless project.last_repository_updated_at
+
+      (last_successful_sync_at.to_f - project.last_repository_updated_at.to_f).round(3)
+    end
+
+    def download_time_in_seconds
+      (last_successful_sync_at.to_f - last_synced_at.to_f).round(3)
+    end
+
+    def last_successful_sync_at
+      registry.public_send("last_#{type}_successful_sync_at") # rubocop:disable GitlabSecurity/PublicSend
+    end
+
+    def last_synced_at
+      registry.public_send("last_#{type}_synced_at") # rubocop:disable GitlabSecurity/PublicSend
+    end
   end
 end

app/services/geo/repository_sync_service.rb

@@ -18,6 +18,9 @@ def fetch_project_repository
         project.repository.fetch_geo_mirror(ssh_url_to_repo)
         update_registry(finished_at: DateTime.now)
+        log_info("Finished repository sync",
+                 update_delay_s: update_delay_in_seconds,
+                 download_time_s: download_time_in_seconds)
       rescue Gitlab::Shell::Error, Geo::EmptyCloneUrlPrefixError => e
         log_error('Error syncing repository', e)
       rescue Gitlab::Git::Repository::NoRepository => e

app/services/geo/wiki_sync_service.rb

@@ -17,6 +17,9 @@ def fetch_wiki_repository
         project.wiki.repository.fetch_geo_mirror(ssh_url_to_wiki)
         update_registry(finished_at: DateTime.now)
+        log_info("Finished wiki sync",
+                 update_delay_s: update_delay_in_seconds,
+                 download_time_s: download_time_in_seconds)
       rescue Gitlab::Git::Repository::NoRepository,
              Gitlab::Shell::Error,
              ProjectWiki::CouldNotCreateWikiError,

lib/gitlab/geo/project_log_helpers.rb

 module Gitlab
   module Geo
     module ProjectLogHelpers
-      def log_info(message)
+      def log_info(message, details = {})
         data = base_log_data(message)
+        data.merge!(details) if details
         Gitlab::Geo::Logger.info(data)
       end

spec/services/geo/repository_sync_service_spec.rb

@@ -79,17 +79,24 @@
       context 'when repository sync succeed' do
         let(:registry) { Geo::ProjectRegistry.find_by(project_id: project.id) }
-        before do
+        it 'sets last_repository_synced_at' do
           subject.execute
-        end
-        it 'sets last_repository_synced_at' do
           expect(registry.last_repository_synced_at).not_to be_nil
         end
         it 'sets last_repository_successful_sync_at' do
+          subject.execute
+
           expect(registry.last_repository_successful_sync_at).not_to be_nil
         end
+
+        it 'logs success with timings' do
+          allow(Gitlab::Geo::Logger).to receive(:info).and_call_original
+          expect(Gitlab::Geo::Logger).to receive(:info).with(hash_including(:message, :update_delay_s, :download_time_s)).and_call_original
+
+          subject.execute
+        end
       end
       context 'when repository sync fail' do

spec/services/geo/wiki_sync_service_spec.rb

@@ -69,17 +69,24 @@
       context 'when repository sync succeed' do
         let(:registry) { Geo::ProjectRegistry.find_by(project_id: project.id) }
-        before do
+        it 'sets last_wiki_synced_at' do
           subject.execute
-        end
-        it 'sets last_wiki_synced_at' do
           expect(registry.last_wiki_synced_at).not_to be_nil
         end
         it 'sets last_wiki_successful_sync_at' do
+          subject.execute
+
           expect(registry.last_wiki_successful_sync_at).not_to be_nil
         end
+
+        it 'logs success with timings' do
+          allow(Gitlab::Geo::Logger).to receive(:info).and_call_original
+          expect(Gitlab::Geo::Logger).to receive(:info).with(hash_including(:message, :update_delay_s, :download_time_s)).and_call_original
+
+          subject.execute
+        end
       end
       context 'when wiki sync fail' do