Add logging for GeoBackfillWorker to check what it's doing

[ci skip]

app/services/geo/repository_backfill_service.rb

@@ -11,10 +11,13 @@ module Geo
     def execute
       try_obtain_lease do
         fetch_repositories do |started_at, finished_at|
+          log('Tracking sync information')
           registry = Geo::ProjectRegistry.find_or_create_by(project_id: project.id)
           registry.last_repository_synced_at = started_at
           registry.last_repository_successful_sync_at = finished_at if finished_at
           registry.save
+
+          log('Finished repository sync')
         end
       end
     end
@@ -25,35 +28,43 @@ module Geo
       started_at  = DateTime.now
       finished_at = nil
 
+      log('Started repository sync')
+
       begin
         project.create_repository unless project.repository_exists?
         project.repository.after_create if project.empty_repo?
+        log('Fetching repository')
         project.repository.fetch_geo_mirror(ssh_url_to_repo)
 
         # Second .wiki call returns a Gollum::Wiki, and it will always create the physical repository when not found
         if project.wiki_enabled? && project.wiki.wiki.exist?
+          log('Fetching wiki repository')
           project.wiki.repository.fetch_geo_mirror(ssh_url_to_wiki)
         end
 
+        log('Expiring caches')
         project.repository.expire_all_method_caches
         project.repository.expire_branch_cache
         project.repository.expire_content_cache
 
         finished_at = DateTime.now
       rescue Gitlab::Shell::Error => e
-        Rails.logger.error("Error backfilling repository #{project.path_with_namespace}: #{e}")
+        Rails.logger.error "Error syncing repository for project #{project.path_with_namespace}: #{e}"
       end
 
       yield started_at, finished_at
     end
 
     def try_obtain_lease
+      log('Trying to obtain lease to sync repository')
+
       uuid = Gitlab::ExclusiveLease.new(lease_key, timeout: LEASE_TIMEOUT).try_obtain
 
-      return unless uuid
+      log('Could not obtain lease to sync repository') and return unless uuid
 
       yield
 
+      log('Releasing lease to sync repository')
       release_lease(uuid)
     end
 
@@ -76,5 +87,9 @@ module Geo
     def ssh_url_to_wiki
       "#{primary_ssh_path_prefix}#{project.path_with_namespace}.wiki.git"
     end
+
+    def log(message)
+      Rails.logger.info "#{self.class.name}: #{message} for project #{project.path_with_namespace} (#{project.id})"
+    end
   end
 end

app/workers/geo_backfill_worker.rb

@@ -7,6 +7,9 @@ class GeoBackfillWorker
 
   def perform
     start = Time.now
+    project_ids = find_project_ids
+
+    logger.info "Started Geo backfilling for #{project_ids.length} project(s)"
 
     project_ids.each do |project_id|
       break if Time.now - start >= RUN_TIME
@@ -19,11 +22,13 @@ class GeoBackfillWorker
         Geo::RepositoryBackfillService.new(project).execute
       end
     end
+
+    logger.info "Finished Geo backfilling for #{project_ids.length} project(s)"
   end
 
   private
 
-  def project_ids
+  def find_project_ids
     return [] if Project.count == Geo::ProjectRegistry.count
 
     Project.where.not(id: Geo::ProjectRegistry.pluck(:id))
@@ -32,12 +37,14 @@ class GeoBackfillWorker
   end
 
   def try_obtain_lease
+    logger.info 'Trying to obtain lease to backfill repositories'
     uuid = Gitlab::ExclusiveLease.new(lease_key, timeout: LEASE_TIMEOUT).try_obtain
 
-    return unless uuid
+    logger.info 'Could not obtain lease to backfill repositories' and return unless uuid
 
     yield
 
+    logger.info('Releasing lease to backfill repositories')
     release_lease(uuid)
   end