Adds tracing to EE-only push checks

Enterprise Edition adds additional push checks.
This commit adds tracing for those checks as well
by leveraging the TimedLogger class

ee/lib/ee/gitlab/checks/change_access.rb

@@ -13,6 +13,13 @@ module EE
           push_rule_committer_not_allowed: "You cannot push commits for '%{committer_email}'. You can only push commits that were committed with one of your own verified emails."
         }.freeze
 
+        LOG_MESSAGES = {
+          push_rule_tag_check: "Checking if you are allowed to delete a tag...",
+          push_rule_branch_check: "Checking if branch follows the naming patterns defined by the project...",
+          push_rule_commits_check: "Checking if commits follow defined push rules...",
+          file_size_check: "Checking if any files are larger than the allowed size..."
+        }.freeze
+
         override :exec
         def exec
           return true if skip_authorization
@@ -33,15 +40,17 @@ module EE
         def file_size_check
           return if push_rule.nil? || push_rule.max_file_size.zero?
 
-          max_file_size = push_rule.max_file_size
-          blobs = project.repository.new_blobs(newrev)
+          logger.log_timed(LOG_MESSAGES[__method__]) do
+            max_file_size = push_rule.max_file_size
+            blobs = project.repository.new_blobs(newrev)
 
-          large_blob = blobs.find do |blob|
-            ::Gitlab::Utils.bytes_to_megabytes(blob.size) > max_file_size
-          end
+            large_blob = blobs.find do |blob|
+              ::Gitlab::Utils.bytes_to_megabytes(blob.size) > max_file_size
+            end
 
-          if large_blob
-            raise ::Gitlab::GitAccess::UnauthorizedError, %Q{File "#{large_blob.path}" is larger than the allowed size of #{max_file_size} MB}
+            if large_blob
+              raise ::Gitlab::GitAccess::UnauthorizedError, %Q{File "#{large_blob.path}" is larger than the allowed size of #{max_file_size} MB}
+            end
           end
         end
 
@@ -60,23 +69,29 @@ module EE
         end
 
         def push_rule_tag_check
-          if tag_deletion_denied_by_push_rule?
-            raise ::Gitlab::GitAccess::UnauthorizedError, 'You cannot delete a tag'
+          logger.log_timed(LOG_MESSAGES[__method__]) do
+            if tag_deletion_denied_by_push_rule?
+              raise ::Gitlab::GitAccess::UnauthorizedError, 'You cannot delete a tag'
+            end
           end
         end
 
         def push_rule_branch_check
-          unless branch_name_allowed_by_push_rule?
-            message = ERROR_MESSAGES[:push_rule_branch_name] % { branch_name_regex: push_rule.branch_name_regex }
-            raise ::Gitlab::GitAccess::UnauthorizedError.new(message)
+          logger.log_timed(LOG_MESSAGES[__method__]) do
+            unless branch_name_allowed_by_push_rule?
+              message = ERROR_MESSAGES[:push_rule_branch_name] % { branch_name_regex: push_rule.branch_name_regex }
+              raise ::Gitlab::GitAccess::UnauthorizedError.new(message)
+            end
           end
 
           commit_validation = push_rule.try(:commit_validation?)
           # if newrev is blank, the branch was deleted
           return if deletion? || !commit_validation
 
-          commits.each do |commit|
-            push_rule_commit_check(commit)
+          logger.log_timed(LOG_MESSAGES[:push_rule_commits_check]) do
+            commits.each do |commit|
+              push_rule_commit_check(commit)
+            end
           end
         rescue ::PushRule::MatchError => e
           raise ::Gitlab::GitAccess::UnauthorizedError, e.message

ee/spec/lib/gitlab/checks/change_access_spec.rb

@@ -12,13 +12,16 @@ describe Gitlab::Checks::ChangeAccess do
     let(:ref) { 'refs/heads/master' }
     let(:changes) { { oldrev: oldrev, newrev: newrev, ref: ref } }
     let(:protocol) { 'ssh' }
+    let(:timeout) { Gitlab::GitAccess::INTERNAL_TIMEOUT }
+    let(:logger) { Gitlab::Checks::TimedLogger.new(timeout: timeout) }
 
     subject(:change_access) do
       described_class.new(
         changes,
         project: project,
         user_access: user_access,
-        protocol: protocol
+        protocol: protocol,
+        logger: logger
       )
     end
 

lib/gitlab/checks/change_access.rb

@@ -29,7 +29,8 @@ module Gitlab
         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_file_paths_validation: "Validating commits' file paths...",
+        commits_check: "Validating commits against blacklisted file names and locked paths..."
       }.freeze
 
       attr_reader :user_access, :project, :skip_authorization, :skip_lfs_integrity_check, :protocol, :oldrev, :newrev, :ref, :branch_name, :tag_name, :logger
@@ -157,12 +158,14 @@ 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|
-            logger.check_timeout_reached
+        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|
+              logger.check_timeout_reached
 
-            commit_check.validate(commit, validations_for_commit(commit))
+              commit_check.validate(commit, validations_for_commit(commit))
+            end
           end
         end
 

spec/lib/gitlab/git_access_spec.rb

@@ -1058,7 +1058,9 @@ describe Gitlab::GitAccess do
       it 'raises TimeoutError when #check_single_change_access raises a timeout error' do
         message = "Push operation timed out\n\nTiming information for debugging purposes:\nRunning checks for ref: wow"
 
-        allow_any_instance_of(Gitlab::Checks::ChangeAccess).to receive(:exec).and_raise(Gitlab::Checks::TimedLogger::TimeoutError)
+        expect_next_instance_of(Gitlab::Checks::ChangeAccess) do |check|
+          expect(check).to receive(:exec).and_raise(Gitlab::Checks::TimedLogger::TimeoutError)
+        end
 
         expect { access.check('git-receive-pack', changes) }.to raise_error(described_class::TimeoutError, message)
       end

spec/requests/api/internal_spec.rb

@@ -499,7 +499,9 @@ describe API::Internal do
         it 'responds with a gateway timeout' do
           personal_project = create(:project, namespace: user.namespace)
 
-          allow_any_instance_of(Gitlab::GitAccess).to receive(:check).and_raise(Gitlab::GitAccess::TimeoutError, "Foo")
+          expect_next_instance_of(Gitlab::GitAccess) do |access|
+            expect(access).to receive(:check).and_raise(Gitlab::GitAccess::TimeoutError, "Foo")
+          end
           push(key, personal_project)
 
           expect(response).to have_gitlab_http_status(503)