Merge branch 'sh-geo-json-logging' into 'master'

Migrate Geo logs to structured JSON in geo.log

See merge request !2482

app/services/geo/base_sync_service.rb

@@ -4,6 +4,8 @@ module Geo
   EmptyCloneUrlPrefixError = Class.new(StandardError)
 
   class BaseSyncService
+    include ::Gitlab::Geo::ProjectLogHelpers
+
     class << self
       attr_accessor :type
     end
@@ -19,9 +21,9 @@ module Geo
 
     def execute
       try_obtain_lease do
-        log("Started #{type} sync")
+        log_info("Started #{type} sync")
         sync_repository
-        log("Finished #{type} sync")
+        log_info("Finished #{type} sync")
       end
     end
 
@@ -46,11 +48,11 @@ module Geo
     end
 
     def try_obtain_lease
-      log("Trying to obtain lease to sync #{type}")
+      log_info("Trying to obtain lease to sync #{type}")
       repository_lease = Gitlab::ExclusiveLease.new(lease_key, timeout: LEASE_TIMEOUT).try_obtain
 
       unless repository_lease
-        log("Could not obtain lease to sync #{type}")
+        log_info("Could not obtain lease to sync #{type}")
         return
       end
 
@@ -59,14 +61,14 @@ module Geo
       # We should release the lease for a repository, only if we have obtained
       # it. If something went wrong when syncing the repository, we should wait
       # for the lease timeout to try again.
-      log("Releasing leases to sync #{type}")
+      log_info("Releasing leases to sync #{type}")
       Gitlab::ExclusiveLease.cancel(lease_key, repository_lease)
     end
 
     def update_registry(type, started_at: nil, finished_at: nil)
       return unless started_at || finished_at
 
-      log("Updating #{type} sync information")
+      log_info("Updating #{type} sync information")
 
       attrs = {}
 
@@ -83,9 +85,5 @@ module Geo
     def type
       self.class.type
     end
-
-    def log(message)
-      Rails.logger.info("#{self.class.name}: #{message} for project #{project.path_with_namespace} (#{project.id})")
-    end
   end
 end

app/services/geo/event_store.rb

@@ -33,7 +33,7 @@ module Geo
 
       Geo::EventLog.create!("#{self.class.event_type}" => build_event)
     rescue ActiveRecord::RecordInvalid, NoMethodError => e
-      log("#{self.event_type.to_s.humanize} could not be created", e)
+      log_error("#{self.event_type.to_s.humanize} could not be created", e)
     end
 
     private
@@ -43,8 +43,13 @@ module Geo
         "#{self.class} does not implement #{__method__}"
     end
 
-    def log(message, error)
-      Rails.logger.error("#{self.class.name}: #{message} for project #{project.path_with_namespace} (#{project.id}): #{error}")
+    def log_error(message, error)
+      Gitlab::Geo::Logger.error(
+        class: self.class.name,
+        message: message,
+        error: error,
+        project_id: project.id,
+        project_path: project.path_with_namespace)
     end
   end
 end

app/services/geo/file_download_service.rb

@@ -15,8 +15,8 @@ module Geo
     def downloader
       klass = "Gitlab::Geo::#{service_klass_name}Downloader".constantize
       klass.new(object_type, object_db_id)
-    rescue NameError
-      log("Unknown file type: #{object_type}")
+    rescue NameError => e
+      log_error('Unknown file type', e)
       raise
     end
 

app/services/geo/file_service.rb

@@ -27,8 +27,24 @@ module Geo
       klass_name.camelize
     end
 
-    def log(message)
-      Rails.logger.info "#{self.class.name}: #{message}"
+    def log_info(message)
+      data = log_base_data(message)
+      Gitlab::Geo::Logger.info(data)
+    end
+
+    def log_error(message, error)
+      data = log_base_data(message)
+      data[:error] = error
+      Gitlab::Geo::Logger.error(data)
+    end
+
+    def log_base_data(message)
+      {
+        class: self.class.name,
+        object_type: object_type,
+        object_db_id: object_db_id,
+        message: message
+      }
     end
   end
 end

app/services/geo/file_upload_service.rb

@@ -21,8 +21,8 @@ module Geo
 
     def uploader_klass
       "Gitlab::Geo::#{service_klass_name}Uploader".constantize
-    rescue NameError
-      log("Unknown file type: #{object_type}")
+    rescue NameError => e
+      log_error('Unknown file type', e)
       raise
     end
   end

app/services/geo/notify_nodes_service.rb

@@ -20,10 +20,15 @@ module Geo
         next unless node.enabled?
 
         notify_url = node.send(notify_url_method.to_sym)
-        success, message = notify(notify_url, content)
+        success, details = notify(notify_url, content)
 
         unless success
-          Rails.logger.error("GitLab failed to notify #{node.url} to #{notify_url} : #{message}")
+          Gitlab::Geo::Logger.error(
+            class: self.class.name,
+            message: "GitLab failed to notify",
+            error: details,
+            node_url: node.url,
+            notify_url: notify_url)
           queue.store_batched_data(projects)
         end
       end

app/services/geo/repository_sync_service.rb

@@ -10,7 +10,7 @@ module Geo
     end
 
     def fetch_project_repository
-      log('Fetching project repository')
+      log_info('Fetching project repository')
       update_registry(:repository, started_at: DateTime.now)
 
       begin
@@ -19,16 +19,16 @@ module Geo
 
         update_registry(:repository, finished_at: DateTime.now)
       rescue Gitlab::Shell::Error, Geo::EmptyCloneUrlPrefixError => e
-        Rails.logger.error("#{self.class.name}: Error syncing repository for project #{project.path_with_namespace}: #{e}")
+        log_error("Error syncing repository", e)
       rescue Gitlab::Git::Repository::NoRepository => e
-        Rails.logger.error("#{self.class.name}: Error invalid repository for project #{project.path_with_namespace}: #{e}")
-        log('Expiring caches')
+        log_error("Invalid repository", e)
+        log_info('Expiring caches')
         project.repository.after_create
       end
     end
 
     def expire_repository_caches
-      log('Expiring caches')
+      log_info('Expiring caches')
       project.repository.after_sync
     end
 

app/services/geo/repository_update_service.rb

 module Geo
   class RepositoryUpdateService
+    include Gitlab::Geo::ProjectLogHelpers
+
     attr_reader :project, :clone_url, :logger
 
     LEASE_TIMEOUT = 1.hour.freeze
@@ -21,21 +23,21 @@ module Geo
         project.repository.expire_content_cache
       end
     rescue Gitlab::Shell::Error => e
-      logger.error "#{self.class.name}: Error fetching repository for project #{project.path_with_namespace}: #{e}"
+      log_error('Error fetching repository for project', e)
     rescue Gitlab::Git::Repository::NoRepository => e
-      logger.error "#{self.class.name}: Error invalid repository for project #{project.path_with_namespace}: #{e}"
-      logger.warn "#{self.class.name}: Invalidating cache for project #{project.path_with_namespace}"
+      log_error('Error invalid repository', e)
+      log_info('Invalidating cache for project')
       project.repository.after_create
     end
 
     private
 
     def try_obtain_lease
-      log('Trying to obtain lease to sync repository')
+      log_info('Trying to obtain lease to sync repository')
 
       repository_lease = Gitlab::ExclusiveLease.new(lease_key, timeout: LEASE_TIMEOUT).try_obtain
       unless repository_lease.present?
-        log('Could not obtain lease to sync repository')
+        log_info('Could not obtain lease to sync repository')
 
         return
       end
@@ -43,7 +45,7 @@ module Geo
       begin
         yield
       ensure
-        log('Releasing leases to sync repository')
+        log_info('Releasing leases to sync repository')
         Gitlab::ExclusiveLease.cancel(lease_key, repository_lease)
       end
     end
@@ -51,9 +53,5 @@ module Geo
     def lease_key
       @lease_key ||= "#{LEASE_KEY_PREFIX}:#{project.id}"
     end
-
-    def log(message)
-      logger.info("#{self.class.name}: #{message} for project #{project.path_with_namespace} (#{project.id})")
-    end
   end
 end

app/services/geo/wiki_sync_service.rb

@@ -9,7 +9,7 @@ module Geo
     end
 
     def fetch_wiki_repository
-      log('Fetching wiki repository')
+      log_info('Fetching wiki repository')
       update_registry(:wiki, started_at: DateTime.now)
 
       begin
@@ -21,7 +21,7 @@ module Geo
              Gitlab::Shell::Error,
              ProjectWiki::CouldNotCreateWikiError,
              Geo::EmptyCloneUrlPrefixError => e
-        Rails.logger.error("#{self.class.name}: Error syncing wiki repository for project #{project.path_with_namespace}: #{e}")
+        log_error("Error syncing wiki repository", e)
       end
     end
 

lib/gitlab/geo/logger.rb

+module Gitlab
+  module Geo
+    class Logger < ::Gitlab::JsonLogger
+      def self.file_name_noext
+        'geo'
+      end
+    end
+  end
+end

lib/gitlab/geo/project_log_helpers.rb

+module Gitlab
+  module Geo
+    module ProjectLogHelpers
+      def log_info(message)
+        data = base_log_data(message)
+        Gitlab::Geo::Logger.info(data)
+      end
+
+      def log_error(message, error)
+        data = base_log_data(message)
+        data[:error] = error
+        Gitlab::Geo::Logger.error(data)
+      end
+
+      private
+
+      def base_log_data(message)
+        {
+          class: self.class.name,
+          project_id: project.id,
+          project_path: project.path_with_namespace,
+          message: message
+        }
+      end
+    end
+  end
+end

lib/gitlab/json_logger.rb

+module Gitlab
+  class JsonLogger < ::Gitlab::Logger
+    def self.file_name_noext
+      raise NotImplementedError
+    end
+
+    def format_message(severity, timestamp, progname, message)
+      data = {}
+      data[:severity] = severity
+      data[:time] = timestamp.utc.iso8601(3)
+
+      case message
+      when String
+        data[:message] = message
+      when Hash
+        data.merge!(message)
+      end
+
+      data.to_json + "\n"
+    end
+  end
+end