Adds tracing messages for slow git pushes

Whenever a git push takes more than 50 seconds the user
will receive a trace from each check performed along with
their timings

3 files changed, 144 insertions, 38 deletions

diff --git a/lib/gitlab/checks/change_access.rb b/lib/gitlab/checks/change_access.rb
index 49e7f7e1fd7..52a72de3b15 100644
--- a/lib/gitlab/checks/change_access.rb
+++ b/lib/gitlab/checks/change_access.rb
@@ -18,11 +18,24 @@ module Gitlab
         lfs_objects_missing: 'LFS objects are missing. Ensure LFS is properly set up or try a manual "git lfs push --all".'
       }.freeze
 
-      attr_reader :user_access, :project, :skip_authorization, :skip_lfs_integrity_check, :protocol, :oldrev, :newrev, :ref, :branch_name, :tag_name
+      LOG_MESSAGES = {
+        push_checks: "Checking if you are allowed to push...",
+        delete_default_branch_check: "Checking if default branch is being deleted...",
+        protected_branch_checks: "Checking if you are force pushing to a protected branch...",
+        protected_branch_push_checks: "Checking if you are allowed to push to the protected branch...",
+        protected_branch_deletion_checks: "Checking if you are allowed to delete the protected branch...",
+        tag_checks: "Checking if you are allowed to change existing tags...",
+        protected_tag_checks: "Checking if you are creating, updating or deleting a protected tag...",
+        lfs_objects_exist_check: "Scanning repository for blobs stored in LFS and verifying their files have been uploaded to GitLab...",
+        commits_check_file_paths_validation: "Validating commits' file paths...",
+        commits_check: "Validating commits..." # different message in EE
+      }.freeze
+
+      attr_reader :user_access, :project, :skip_authorization, :skip_lfs_integrity_check, :protocol, :oldrev, :newrev, :ref, :branch_name, :tag_name, :logger
 
       def initialize(
         change, user_access:, project:, skip_authorization: false,
-        skip_lfs_integrity_check: false, protocol:
+        skip_lfs_integrity_check: false, protocol:, logger:
       )
         @oldrev, @newrev, @ref = change.values_at(:oldrev, :newrev, :ref)
         @branch_name = Gitlab::Git.branch_name(@ref)
@@ -32,6 +45,9 @@ module Gitlab
         @skip_authorization = skip_authorization
         @skip_lfs_integrity_check = skip_lfs_integrity_check
         @protocol = protocol
+
+        @logger = logger
+        @logger.log << "Running checks for ref: #{@branch_name || @tag_name}"
       end
 
       def exec(skip_commits_check: false)
@@ -49,26 +65,32 @@ module Gitlab
       protected
 
       def push_checks
-        unless can_push?
-          raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:push_code]
+        logger.log_timed(LOG_MESSAGES[__method__]) do
+          unless can_push?
+            raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:push_code]
+          end
         end
       end
 
       def branch_checks
         return unless branch_name
 
-        if deletion? && branch_name == project.default_branch
-          raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:delete_default_branch]
+        logger.log_timed(LOG_MESSAGES[:delete_default_branch_check]) do
+          if deletion? && branch_name == project.default_branch
+            raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:delete_default_branch]
+          end
         end
 
         protected_branch_checks
       end
 
       def protected_branch_checks
-        return unless ProtectedBranch.protected?(project, branch_name)
+        logger.log_timed(LOG_MESSAGES[__method__]) do
+          return unless ProtectedBranch.protected?(project, branch_name) # rubocop:disable Cop/AvoidReturnFromBlocks
 
-        if forced_push?
-          raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:force_push_protected_branch]
+          if forced_push?
+            raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:force_push_protected_branch]
+          end
         end
 
         if deletion?
@@ -79,23 +101,27 @@ module Gitlab
       end
 
       def protected_branch_deletion_checks
-        unless user_access.can_delete_branch?(branch_name)
-          raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:non_master_delete_protected_branch]
-        end
+        logger.log_timed(LOG_MESSAGES[__method__]) do
+          unless user_access.can_delete_branch?(branch_name)
+            raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:non_master_delete_protected_branch]
+          end
 
-        unless updated_from_web?
-          raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:non_web_delete_protected_branch]
+          unless updated_from_web?
+            raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:non_web_delete_protected_branch]
+          end
         end
       end
 
       def protected_branch_push_checks
-        if matching_merge_request?
-          unless user_access.can_merge_to_branch?(branch_name) || user_access.can_push_to_branch?(branch_name)
-            raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:merge_protected_branch]
-          end
-        else
-          unless user_access.can_push_to_branch?(branch_name)
-            raise GitAccess::UnauthorizedError, push_to_protected_branch_rejected_message
+        logger.log_timed(LOG_MESSAGES[__method__]) do
+          if matching_merge_request?
+            unless user_access.can_merge_to_branch?(branch_name) || user_access.can_push_to_branch?(branch_name)
+              raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:merge_protected_branch]
+            end
+          else
+            unless user_access.can_push_to_branch?(branch_name)
+              raise GitAccess::UnauthorizedError, push_to_protected_branch_rejected_message
+            end
           end
         end
       end
@@ -103,21 +129,25 @@ module Gitlab
       def tag_checks
         return unless tag_name
 
-        if tag_exists? && user_access.cannot_do_action?(:admin_project)
-          raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:change_existing_tags]
+        logger.log_timed(LOG_MESSAGES[__method__]) do
+          if tag_exists? && user_access.cannot_do_action?(:admin_project)
+            raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:change_existing_tags]
+          end
         end
 
         protected_tag_checks
       end
 
       def protected_tag_checks
-        return unless ProtectedTag.protected?(project, tag_name)
+        logger.log_timed(LOG_MESSAGES[__method__]) do
+          return unless ProtectedTag.protected?(project, tag_name) # rubocop:disable Cop/AvoidReturnFromBlocks
 
-        raise(GitAccess::UnauthorizedError, ERROR_MESSAGES[:update_protected_tag]) if update?
-        raise(GitAccess::UnauthorizedError, ERROR_MESSAGES[:delete_protected_tag]) if deletion?
+          raise(GitAccess::UnauthorizedError, ERROR_MESSAGES[:update_protected_tag]) if update?
+          raise(GitAccess::UnauthorizedError, ERROR_MESSAGES[:delete_protected_tag]) if deletion?
 
-        unless user_access.can_create_tag?(tag_name)
-          raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:create_protected_tag]
+          unless user_access.can_create_tag?(tag_name)
+            raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:create_protected_tag]
+          end
         end
       end
 
@@ -125,14 +155,18 @@ module Gitlab
         return if deletion? || newrev.nil?
         return unless should_run_commit_validations?
 
-        # n+1: https://gitlab.com/gitlab-org/gitlab-ee/issues/3593
-        ::Gitlab::GitalyClient.allow_n_plus_1_calls do
-          commits.each do |commit|
-            commit_check.validate(commit, validations_for_commit(commit))
+        logger.log_timed(LOG_MESSAGES[__method__]) do
+          # n+1: https://gitlab.com/gitlab-org/gitlab-ee/issues/3593
+          ::Gitlab::GitalyClient.allow_n_plus_1_calls do
+            commits.each do |commit|
+              commit_check.validate(commit, validations_for_commit(commit))
+            end
           end
         end
 
-        commit_check.validate_file_paths
+        logger.log_timed(LOG_MESSAGES[:commits_check_file_paths_validation]) do
+          commit_check.validate_file_paths
+        end
       end
 
       # Method overwritten in EE to inject custom validations
@@ -194,10 +228,12 @@ module Gitlab
       end
 
       def lfs_objects_exist_check
-        lfs_check = Checks::LfsIntegrity.new(project, newrev)
+        logger.log_timed(LOG_MESSAGES[__method__]) do
+          lfs_check = Checks::LfsIntegrity.new(project, newrev, logger.time_left)
 
-        if lfs_check.objects_missing?
-          raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:lfs_objects_missing]
+          if lfs_check.objects_missing?
+            raise GitAccess::UnauthorizedError, ERROR_MESSAGES[:lfs_objects_missing]
+          end
         end
       end
 
diff --git a/lib/gitlab/checks/lfs_integrity.rb b/lib/gitlab/checks/lfs_integrity.rb
index fa3dc1808df..1652d5a30a4 100644
--- a/lib/gitlab/checks/lfs_integrity.rb
+++ b/lib/gitlab/checks/lfs_integrity.rb
@@ -3,9 +3,10 @@
 module Gitlab
   module Checks
     class LfsIntegrity
-      def initialize(project, newrev)
+      def initialize(project, newrev, time_left)
         @project = project
         @newrev = newrev
+        @time_left = time_left
       end
 
       # rubocop: disable CodeReuse/ActiveRecord
@@ -13,7 +14,7 @@ module Gitlab
         return false unless @newrev && @project.lfs_enabled?
 
         new_lfs_pointers = Gitlab::Git::LfsChanges.new(@project.repository, @newrev)
-                                                  .new_pointers(object_limit: ::Gitlab::Git::Repository::REV_LIST_COMMIT_LIMIT)
+                                                  .new_pointers(object_limit: ::Gitlab::Git::Repository::REV_LIST_COMMIT_LIMIT, dynamic_timeout: @time_left)
 
         return false unless new_lfs_pointers.present?
 
diff --git a/lib/gitlab/checks/timed_logger.rb b/lib/gitlab/checks/timed_logger.rb
new file mode 100644
index 00000000000..cbb079a5383
--- /dev/null
+++ b/lib/gitlab/checks/timed_logger.rb
@@ -0,0 +1,69 @@
+# frozen_string_literal: true
+
+module Gitlab
+  module Checks
+    class TimedLogger
+      TimeoutError = Class.new(StandardError)
+
+      attr_reader :start_time
+      attr_accessor :log, :timeout
+
+      def initialize(start_time: Time.now, log: [], timeout:)
+        @start_time = start_time
+        @timeout = timeout
+        @log = log
+      end
+
+      def log_timed(log_message, start = Time.now)
+        check_timeout_reached
+
+        timed = true
+
+        yield
+
+        log << log_message + time_suffix_message(start: start)
+      rescue GRPC::DeadlineExceeded, TimeoutError
+        args = { cancelled: true }
+        args[:start] = start if timed
+
+        log << log_message + time_suffix_message(args)
+
+        raise TimeoutError
+      end
+
+      def check_timeout_reached
+        return unless time_expired?
+
+        raise TimeoutError
+      end
+
+      def time_left
+        (start_time + timeout.seconds) - Time.now
+      end
+
+      private
+
+      def time_expired?
+        time_left <= 0
+      end
+
+      def time_suffix_message(cancelled: false, start: nil)
+        return " (#{elapsed_time(start)}ms)" unless cancelled
+
+        if start
+          " (cancelled after #{elapsed_time(start)}ms)"
+        else
+          " (cancelled)"
+        end
+      end
+
+      def elapsed_time(start)
+        to_ms(Time.now - start)
+      end
+
+      def to_ms(elapsed)
+        (elapsed.to_f * 1000).round(2)
+      end
+    end
+  end
+end