Merge branch 'mk/add-logs-to-out-of-date-check' into 'master'

Geo: Add logs to out-of-date check

See merge request https://gitlab.com/gitlab-org/gitlab/-/merge_requests/157238



Merged-by: Mario Celi <mcelicalderon@gitlab.com>
Approved-by: Tiger Watson <twatson@gitlab.com>
Approved-by: Mario Celi <mcelicalderon@gitlab.com>
Co-authored-by: Mike Kozono <mkozono@gitlab.com>

ee/app/models/geo/project_repository_registry.rb

@@ -5,6 +5,7 @@ class ProjectRepositoryRegistry < Geo::BaseRegistry
     include IgnorableColumns
     include ::Geo::ReplicableRegistry
     include ::Geo::VerifiableRegistry
+    extend ::Gitlab::Geo::LogHelpers
 
     MODEL_CLASS = ::Project
     MODEL_FOREIGN_KEY = :project_id
@@ -17,41 +18,86 @@ class ProjectRepositoryRegistry < Geo::BaseRegistry
     def self.repository_out_of_date?(project_id, synchronous_request_required = false)
       return false unless ::Gitlab::Geo.secondary_with_primary?
 
-      registry = find_by(project_id: project_id)
+      registry = find_or_initialize_by(project_id: project_id)
 
-      # Out-of-date if registry or project don't exist
-      return true if registry.nil? || registry.project.nil?
+      registry.repository_out_of_date?(synchronous_request_required)
+    end
 
-      # Out-of-date if sync failed
-      return true if registry.failed?
+    # @return [Boolean] whether the project repository is out-of-date on this site
+    def repository_out_of_date?(synchronous_request_required = false)
+      return out_of_date("registry doesn't exist") unless persisted?
+      return out_of_date("project doesn't exist") if project.nil?
+      return out_of_date("sync failed") if failed?
 
-      # Up-to-date if there is no timestamp for the latest change to the repo
-      return false unless registry.project.last_repository_updated_at
+      unless project.last_repository_updated_at
+        return up_to_date("there is no timestamp for the latest change to the repo")
+      end
 
-      # Out-of-date if the repo has never been synced
-      return true unless registry.last_synced_at
+      return out_of_date("it has never been synced") unless last_synced_at
+      return out_of_date("not verified yet") unless verification_succeeded?
 
-      # Out-of-date unless verification succeeded
-      return true unless registry.verification_succeeded?
+      # Relatively expensive check
+      return synchronous_pipeline_check if synchronous_request_required
 
-      if synchronous_request_required
-        secondary_pipeline_refs = registry.project.repository.list_refs(['refs/pipelines/']).collect(&:name)
-        primary_pipeline_refs = ::Gitlab::Geo.primary_pipeline_refs(project_id)
+      best_guess_with_local_information
+    end
 
-        return !(primary_pipeline_refs - secondary_pipeline_refs).empty?
+    # @return [Boolean] whether the latest pipeline refs are present on the secondary
+    def synchronous_pipeline_check
+      secondary_pipeline_refs = project.repository.list_refs(['refs/pipelines/']).collect(&:name)
+      primary_pipeline_refs = ::Gitlab::Geo.primary_pipeline_refs(project_id)
+      missing_refs = primary_pipeline_refs - secondary_pipeline_refs
+
+      if !missing_refs.empty?
+        out_of_date("secondary is missing pipeline refs", missing_refs: missing_refs.take(30))
+      else
+        up_to_date("secondary has all pipeline refs")
       end
+    end
+
+    # Current limitations:
+    #
+    # - We assume last_repository_updated_at is a timestamp of the latest change
+    # - But last_repository_updated_at touches are throttled within Event::REPOSITORY_UPDATED_AT_INTERVAL minutes
+    # - And Postgres replication is asynchronous so it may be lagging behind
+    #
+    # @return [Boolean] whether the latest change is replicated
+    def best_guess_with_local_information
+      last_updated_at = project.last_repository_updated_at
+
+      if last_synced_at <= last_updated_at
+        out_of_date("last successfully synced before latest change",
+          last_synced_at: last_synced_at, last_updated_at: last_updated_at)
+      else
+        up_to_date("last successfully synced after latest change",
+          last_synced_at: last_synced_at, last_updated_at: last_updated_at)
+      end
+    end
+
+    def out_of_date(reason, details = {})
+      details
+        .merge!(replicator.replicable_params)
+        .merge!({
+          class: self.class.name,
+          reason: reason
+        })
+
+      log_info("out-of-date", details)
+
+      true
+    end
 
-      # Return whether the latest change is replicated
-      #
-      # Current limitations:
-      #
-      # - We assume last_repository_updated_at is a timestamp of the latest change
-      # - last_repository_updated_at touches are throttled within Event::REPOSITORY_UPDATED_AT_INTERVAL minutes
-      last_updated_at = registry.project.last_repository_updated_at
+    def up_to_date(reason, details = {})
+      details
+        .merge!(replicator.replicable_params)
+        .merge!({
+          class: self.class.name,
+          reason: reason
+        })
 
-      last_synced_at = registry.last_synced_at
+      log_info("up-to-date", details)
 
-      last_synced_at <= last_updated_at
+      false
     end
   end
 end

ee/spec/models/geo/project_repository_registry_spec.rb

@@ -51,6 +51,9 @@
 
           context 'when project_repository_registry entry does not exist' do
             it 'returns true' do
+              expect(Gitlab::Geo::Logger).to receive(:info).with(hash_including(
+                message: "out-of-date", reason: "registry doesn't exist"))
+
               expect(described_class.repository_out_of_date?(project.id)).to be_truthy
             end
           end
@@ -61,6 +64,9 @@
                 registry = create(:geo_project_repository_registry, :synced, project: project)
                 registry.project.update!(last_repository_updated_at: nil)
 
+                expect(Gitlab::Geo::Logger).to receive(:info).with(hash_including(
+                  message: "up-to-date", reason: "there is no timestamp for the latest change to the repo"))
+
                 expect(described_class.repository_out_of_date?(registry.project_id)).to be_falsey
               end
             end
@@ -77,6 +83,10 @@
                 it 'returns true' do
                   allow(::Gitlab::Geo).to receive(:primary_pipeline_refs)
                     .with(registry.project_id).and_return(secondary_pipeline_refs)
+
+                  expect(Gitlab::Geo::Logger).to receive(:info).with(hash_including(
+                    message: "out-of-date", reason: "secondary is missing pipeline refs"))
+
                   expect(described_class.repository_out_of_date?(registry.project_id, true)).to be_truthy
                 end
               end
@@ -85,6 +95,10 @@
                 it 'returns false' do
                   allow(::Gitlab::Geo).to receive(:primary_pipeline_refs)
                     .with(registry.project_id).and_return(some_secondary_pipeline_refs)
+
+                  expect(Gitlab::Geo::Logger).to receive(:info).with(hash_including(
+                    message: "up-to-date", reason: "secondary has all pipeline refs"))
+
                   expect(described_class.repository_out_of_date?(registry.project_id, true)).to be_falsey
                 end
               end
@@ -93,6 +107,10 @@
                 it 'returns false' do
                   allow(::Gitlab::Geo).to receive(:primary_pipeline_refs)
                     .with(registry.project_id).and_return(secondary_pipeline_refs)
+
+                  expect(Gitlab::Geo::Logger).to receive(:info).with(hash_including(
+                    message: "up-to-date", reason: "secondary has all pipeline refs"))
+
                   expect(described_class.repository_out_of_date?(registry.project_id, true)).to be_falsey
                 end
               end
@@ -103,6 +121,9 @@
                 it 'returns true' do
                   registry = create(:geo_project_repository_registry, :failed, project: project)
 
+                  expect(Gitlab::Geo::Logger).to receive(:info).with(hash_including(
+                    message: "out-of-date", reason: "sync failed"))
+
                   expect(described_class.repository_out_of_date?(registry.project_id)).to be_truthy
                 end
               end
@@ -111,6 +132,9 @@
                 it 'returns true' do
                   registry = create(:geo_project_repository_registry, project: project, last_synced_at: nil)
 
+                  expect(Gitlab::Geo::Logger).to receive(:info).with(hash_including(
+                    message: "out-of-date", reason: "it has never been synced"))
+
                   expect(described_class.repository_out_of_date?(registry.project_id)).to be_truthy
                 end
               end
@@ -119,6 +143,9 @@
                 it 'returns true' do
                   registry = create(:geo_project_repository_registry, :verification_failed, project: project)
 
+                  expect(Gitlab::Geo::Logger).to receive(:info).with(hash_including(
+                    message: "out-of-date", reason: "not verified yet"))
+
                   expect(described_class.repository_out_of_date?(registry.project_id)).to be_truthy
                 end
               end
@@ -128,6 +155,9 @@
                   registry = create(:geo_project_repository_registry, :verification_succeeded,
                     project: project, last_synced_at: Time.current + 5.minutes)
 
+                  expect(Gitlab::Geo::Logger).to receive(:info).with(hash_including(
+                    message: "up-to-date", reason: "last successfully synced after latest change"))
+
                   expect(described_class.repository_out_of_date?(registry.project_id)).to be_falsey
                 end
               end
@@ -151,6 +181,9 @@
                   end
 
                   it 'returns the expected value' do
+                    message = expected ? 'out-of-date' : 'up-to-date'
+
+                    expect(Gitlab::Geo::Logger).to receive(:info).with(hash_including(message: message))
                     expect(described_class.repository_out_of_date?(project.id)).to eq(expected)
                   end
                 end