From 084a8b6101c25e5d3d4f97f078abd9a649a2fb64 Mon Sep 17 00:00:00 2001
From: Tiago Botelho <tiagonbotelho@hotmail.com>
Date: Mon, 22 Oct 2018 15:49:20 +0100
Subject: 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
---
 app/controllers/projects/git_http_controller.rb    |   5 +
 ...ack-for-internal-git-access-checks-timeouts.yml |   5 +
 lib/api/internal.rb                                |   2 +
 lib/gitlab/checks/change_access.rb                 | 108 ++++++++++++++-------
 lib/gitlab/checks/lfs_integrity.rb                 |   5 +-
 lib/gitlab/checks/timed_logger.rb                  |  69 +++++++++++++
 lib/gitlab/git/lfs_changes.rb                      |   4 +-
 lib/gitlab/git_access.rb                           |  22 ++++-
 lib/gitlab/gitaly_client/blob_service.rb           |  17 +++-
 spec/lib/gitlab/checks/change_access_spec.rb       |  18 +++-
 spec/lib/gitlab/checks/lfs_integrity_spec.rb       |   3 +-
 spec/lib/gitlab/checks/timed_logger_spec.rb        |  75 ++++++++++++++
 spec/lib/gitlab/git/lfs_changes_spec.rb            |   4 +
 spec/lib/gitlab/git_access_spec.rb                 |  10 ++
 spec/requests/api/internal_spec.rb                 |  18 ++++
 15 files changed, 317 insertions(+), 48 deletions(-)
 create mode 100644 changelogs/unreleased/42790-improve-feedback-for-internal-git-access-checks-timeouts.yml
 create mode 100644 lib/gitlab/checks/timed_logger.rb
 create mode 100644 spec/lib/gitlab/checks/timed_logger_spec.rb

diff --git a/app/controllers/projects/git_http_controller.rb b/app/controllers/projects/git_http_controller.rb
index be708835e30..c0aa39d87c6 100644
--- a/app/controllers/projects/git_http_controller.rb
+++ b/app/controllers/projects/git_http_controller.rb
@@ -8,6 +8,7 @@ class Projects::GitHttpController < Projects::GitHttpClientController
   rescue_from Gitlab::GitAccess::UnauthorizedError, with: :render_403
   rescue_from Gitlab::GitAccess::NotFoundError, with: :render_404
   rescue_from Gitlab::GitAccess::ProjectCreationError, with: :render_422
+  rescue_from Gitlab::GitAccess::TimeoutError, with: :render_503
 
   # GET /foo/bar.git/info/refs?service=git-upload-pack (git pull)
   # GET /foo/bar.git/info/refs?service=git-receive-pack (git push)
@@ -62,6 +63,10 @@ class Projects::GitHttpController < Projects::GitHttpClientController
     render plain: exception.message, status: :unprocessable_entity
   end
 
+  def render_503(exception)
+    render plain: exception.message, status: :service_unavailable
+  end
+
   def access
     @access ||= access_klass.new(access_actor, project,
       'http', authentication_abilities: authentication_abilities,
diff --git a/changelogs/unreleased/42790-improve-feedback-for-internal-git-access-checks-timeouts.yml b/changelogs/unreleased/42790-improve-feedback-for-internal-git-access-checks-timeouts.yml
new file mode 100644
index 00000000000..d58d8da3a0e
--- /dev/null
+++ b/changelogs/unreleased/42790-improve-feedback-for-internal-git-access-checks-timeouts.yml
@@ -0,0 +1,5 @@
+---
+title: Adds trace of each access check when git push times out
+merge_request: 22265
+author:
+type: added
diff --git a/lib/api/internal.rb b/lib/api/internal.rb
index 4dd6b19e353..ae40b5f7557 100644
--- a/lib/api/internal.rb
+++ b/lib/api/internal.rb
@@ -65,6 +65,8 @@ module API
                          result
                        rescue Gitlab::GitAccess::UnauthorizedError => e
                          break response_with_status(code: 401, success: false, message: e.message)
+                       rescue Gitlab::GitAccess::TimeoutError => e
+                         break response_with_status(code: 503, success: false, message: e.message)
                        rescue Gitlab::GitAccess::NotFoundError => e
                          break response_with_status(code: 404, success: false, message: e.message)
                        end
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
diff --git a/lib/gitlab/git/lfs_changes.rb b/lib/gitlab/git/lfs_changes.rb
index f0fab1e76a3..d7148165408 100644
--- a/lib/gitlab/git/lfs_changes.rb
+++ b/lib/gitlab/git/lfs_changes.rb
@@ -6,8 +6,8 @@ module Gitlab
         @newrev = newrev
       end
 
-      def new_pointers(object_limit: nil, not_in: nil)
-        @repository.gitaly_blob_client.get_new_lfs_pointers(@newrev, object_limit, not_in)
+      def new_pointers(object_limit: nil, not_in: nil, dynamic_timeout: nil)
+        @repository.gitaly_blob_client.get_new_lfs_pointers(@newrev, object_limit, not_in, dynamic_timeout)
       end
 
       def all_pointers
diff --git a/lib/gitlab/git_access.rb b/lib/gitlab/git_access.rb
index 827c04ae035..713a98bb556 100644
--- a/lib/gitlab/git_access.rb
+++ b/lib/gitlab/git_access.rb
@@ -9,6 +9,7 @@ module Gitlab
     UnauthorizedError = Class.new(StandardError)
     NotFoundError = Class.new(StandardError)
     ProjectCreationError = Class.new(StandardError)
+    TimeoutError = Class.new(StandardError)
     ProjectMovedError = Class.new(NotFoundError)
 
     ERROR_MESSAGES = {
@@ -26,11 +27,12 @@ module Gitlab
       cannot_push_to_read_only: "You can't push code to a read-only GitLab instance."
     }.freeze
 
+    INTERNAL_TIMEOUT = 50.seconds.freeze
     DOWNLOAD_COMMANDS = %w{git-upload-pack git-upload-archive}.freeze
     PUSH_COMMANDS = %w{git-receive-pack}.freeze
     ALL_COMMANDS = DOWNLOAD_COMMANDS + PUSH_COMMANDS
 
-    attr_reader :actor, :project, :protocol, :authentication_abilities, :namespace_path, :project_path, :redirected_path, :auth_result_type, :changes
+    attr_reader :actor, :project, :protocol, :authentication_abilities, :namespace_path, :project_path, :redirected_path, :auth_result_type, :changes, :logger
 
     def initialize(actor, project, protocol, authentication_abilities:, namespace_path: nil, project_path: nil, redirected_path: nil, auth_result_type: nil)
       @actor    = actor
@@ -44,6 +46,7 @@ module Gitlab
     end
 
     def check(cmd, changes)
+      @logger = Checks::TimedLogger.new(timeout: INTERNAL_TIMEOUT)
       @changes = changes
 
       check_protocol!
@@ -269,14 +272,25 @@ module Gitlab
     end
 
     def check_single_change_access(change, skip_lfs_integrity_check: false)
-      Checks::ChangeAccess.new(
+      change_access = Checks::ChangeAccess.new(
         change,
         user_access: user_access,
         project: project,
         skip_authorization: deploy_key?,
         skip_lfs_integrity_check: skip_lfs_integrity_check,
-        protocol: protocol
-      ).exec
+        protocol: protocol,
+        logger: logger
+      )
+
+      change_access.exec
+    rescue Checks::TimedLogger::TimeoutError
+      header = <<~MESSAGE
+      Push operation timed out
+
+      Timing information for debugging purposes:
+      MESSAGE
+
+      raise TimeoutError, header + logger.log.join("\n")
     end
 
     def deploy_key
diff --git a/lib/gitlab/gitaly_client/blob_service.rb b/lib/gitlab/gitaly_client/blob_service.rb
index 1840bf45154..086ce31e678 100644
--- a/lib/gitlab/gitaly_client/blob_service.rb
+++ b/lib/gitlab/gitaly_client/blob_service.rb
@@ -72,7 +72,7 @@ module Gitlab
         GitalyClient::BlobsStitcher.new(response)
       end
 
-      def get_new_lfs_pointers(revision, limit, not_in)
+      def get_new_lfs_pointers(revision, limit, not_in, dynamic_timeout = nil)
         request = Gitaly::GetNewLFSPointersRequest.new(
           repository: @gitaly_repo,
           revision: encode_binary(revision),
@@ -85,7 +85,20 @@ module Gitlab
           request.not_in_refs += not_in
         end
 
-        response = GitalyClient.call(@gitaly_repo.storage_name, :blob_service, :get_new_lfs_pointers, request, timeout: GitalyClient.medium_timeout)
+        timeout =
+          if dynamic_timeout
+            [dynamic_timeout, GitalyClient.medium_timeout].min
+          else
+            GitalyClient.medium_timeout
+          end
+
+        response = GitalyClient.call(
+          @gitaly_repo.storage_name,
+          :blob_service,
+          :get_new_lfs_pointers,
+          request,
+          timeout: timeout
+        )
 
         map_lfs_pointers(response)
       end
diff --git a/spec/lib/gitlab/checks/change_access_spec.rb b/spec/lib/gitlab/checks/change_access_spec.rb
index 4df426c54ae..81804ba5c76 100644
--- a/spec/lib/gitlab/checks/change_access_spec.rb
+++ b/spec/lib/gitlab/checks/change_access_spec.rb
@@ -10,13 +10,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
 
@@ -30,6 +33,19 @@ describe Gitlab::Checks::ChangeAccess do
       end
     end
 
+    context 'when time limit was reached' do
+      it 'raises a TimeoutError' do
+        logger = Gitlab::Checks::TimedLogger.new(start_time: timeout.ago, timeout: timeout)
+        access = described_class.new(changes,
+                                     project: project,
+                                     user_access: user_access,
+                                     protocol: protocol,
+                                     logger: logger)
+
+        expect { access.exec }.to raise_error(Gitlab::Checks::TimedLogger::TimeoutError)
+      end
+    end
+
     context 'when the user is not allowed to push to the repo' do
       it 'raises an error' do
         expect(user_access).to receive(:can_do_action?).with(:push_code).and_return(false)
diff --git a/spec/lib/gitlab/checks/lfs_integrity_spec.rb b/spec/lib/gitlab/checks/lfs_integrity_spec.rb
index ec22e3a198e..0488720cec8 100644
--- a/spec/lib/gitlab/checks/lfs_integrity_spec.rb
+++ b/spec/lib/gitlab/checks/lfs_integrity_spec.rb
@@ -3,6 +3,7 @@ require 'spec_helper'
 describe Gitlab::Checks::LfsIntegrity do
   include ProjectForksHelper
 
+  let!(:time_left) { 50 }
   let(:project) { create(:project, :repository) }
   let(:repository) { project.repository }
   let(:newrev) do
@@ -15,7 +16,7 @@ describe Gitlab::Checks::LfsIntegrity do
     operations.commit_tree('8856a329dd38ca86dfb9ce5aa58a16d88cc119bd', "New LFS objects")
   end
 
-  subject { described_class.new(project, newrev) }
+  subject { described_class.new(project, newrev, time_left) }
 
   describe '#objects_missing?' do
     let(:blob_object) { repository.blob_at_branch('lfs', 'files/lfs/lfs_object.iso') }
diff --git a/spec/lib/gitlab/checks/timed_logger_spec.rb b/spec/lib/gitlab/checks/timed_logger_spec.rb
new file mode 100644
index 00000000000..726f2bf2144
--- /dev/null
+++ b/spec/lib/gitlab/checks/timed_logger_spec.rb
@@ -0,0 +1,75 @@
+# frozen_string_literal: true
+
+require 'spec_helper'
+
+describe Gitlab::Checks::TimedLogger do
+  let(:log_messages) do
+    {
+      foo: "Foo message..."
+    }
+  end
+
+  class FooCheck
+    attr_accessor :logger
+
+    INTERNAL_TIMEOUT = 50.seconds.freeze
+
+    def initialize(start_time, ref)
+      @logger = Gitlab::Checks::TimedLogger.new(start_time: start_time, timeout: INTERNAL_TIMEOUT)
+      @logger.log << "Checking ref: #{ref}"
+    end
+
+    def bar_check
+      2 + 2
+    end
+
+    def grpc_check
+      raise GRPC::DeadlineExceeded
+    end
+  end
+
+  describe '#log_timed' do
+    it 'logs message' do
+      start = Time.now
+      check = FooCheck.new(start, "bar")
+
+      Timecop.freeze(start + 30.seconds) do
+        check.logger.log_timed(log_messages[:foo], start) { check.bar_check }
+      end
+
+      expect(check.logger.log).to eq(["Checking ref: bar", "Foo message... (30000.0ms)"])
+    end
+
+    context 'when time limit was reached' do
+      it 'cancels action' do
+        start = Time.now
+        check = FooCheck.new(start, "bar")
+
+        Timecop.freeze(start + 50.seconds) do
+          expect do
+            check.logger.log_timed(log_messages[:foo], start) do
+              check.bar_check
+            end
+          end.to raise_error(described_class::TimeoutError)
+        end
+
+        expect(check.logger.log).to eq(["Checking ref: bar", "Foo message... (cancelled)"])
+      end
+
+      it 'cancels action with time elapsed if work was performed' do
+        start = Time.now
+        check = FooCheck.new(start, "bar")
+
+        Timecop.freeze(start + 30.seconds) do
+          expect do
+            check.logger.log_timed(log_messages[:foo], start) do
+              check.grpc_check
+            end
+          end.to raise_error(described_class::TimeoutError)
+
+          expect(check.logger.log).to eq(["Checking ref: bar", "Foo message... (cancelled after 30000.0ms)"])
+        end
+      end
+    end
+  end
+end
diff --git a/spec/lib/gitlab/git/lfs_changes_spec.rb b/spec/lib/gitlab/git/lfs_changes_spec.rb
index c5e7ab959b2..d035df7e0c2 100644
--- a/spec/lib/gitlab/git/lfs_changes_spec.rb
+++ b/spec/lib/gitlab/git/lfs_changes_spec.rb
@@ -15,5 +15,9 @@ describe Gitlab::Git::LfsChanges do
     it 'limits new_objects using object_limit' do
       expect(subject.new_pointers(object_limit: 1)).to eq([])
     end
+
+    it 'times out if given a small dynamic timeout' do
+      expect { subject.new_pointers(dynamic_timeout: 0.001) }.to raise_error(GRPC::DeadlineExceeded)
+    end
   end
 end
diff --git a/spec/lib/gitlab/git_access_spec.rb b/spec/lib/gitlab/git_access_spec.rb
index e7da5565c26..a417ef77c9e 100644
--- a/spec/lib/gitlab/git_access_spec.rb
+++ b/spec/lib/gitlab/git_access_spec.rb
@@ -934,6 +934,16 @@ describe Gitlab::GitAccess do
         # There is still an N+1 query with protected branches
         expect { access.check('git-receive-pack', changes) }.not_to exceed_query_limit(control_count).with_threshold(1)
       end
+
+      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"
+
+        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
     end
   end
 
diff --git a/spec/requests/api/internal_spec.rb b/spec/requests/api/internal_spec.rb
index e0b5b34f9c4..2ebcb787d06 100644
--- a/spec/requests/api/internal_spec.rb
+++ b/spec/requests/api/internal_spec.rb
@@ -494,6 +494,24 @@ describe API::Internal do
       end
     end
 
+    context 'request times out' do
+      context 'git push' do
+        it 'responds with a gateway timeout' do
+          personal_project = create(:project, namespace: user.namespace)
+
+          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)
+          expect(json_response['status']).to be_falsey
+          expect(json_response['message']).to eq("Foo")
+          expect(user.reload.last_activity_on).to be_nil
+        end
+      end
+    end
+
     context "archived project" do
       before do
         project.add_developer(user)
-- 
cgit v1.2.1


From cb5f4d0cad520629aecaa838ddf1e84d7265ff49 Mon Sep 17 00:00:00 2001
From: Tiago Botelho <tiagonbotelho@hotmail.com>
Date: Thu, 25 Oct 2018 09:49:59 +0100
Subject: Refactors TimedLogger to be more OOP compliant

Adds a #full_message method so that external classes
do not have access to the state of the logger.

Adds a #append_message to always append to the array in-place
---
 lib/gitlab/checks/change_access.rb |  2 +-
 lib/gitlab/checks/timed_logger.rb  | 22 +++++++++++++++++-----
 lib/gitlab/git_access.rb           | 16 ++++++++--------
 3 files changed, 26 insertions(+), 14 deletions(-)

diff --git a/lib/gitlab/checks/change_access.rb b/lib/gitlab/checks/change_access.rb
index 52a72de3b15..7036ae9191d 100644
--- a/lib/gitlab/checks/change_access.rb
+++ b/lib/gitlab/checks/change_access.rb
@@ -47,7 +47,7 @@ module Gitlab
         @protocol = protocol
 
         @logger = logger
-        @logger.log << "Running checks for ref: #{@branch_name || @tag_name}"
+        @logger.append_message("Running checks for ref: #{@branch_name || @tag_name}")
       end
 
       def exec(skip_commits_check: false)
diff --git a/lib/gitlab/checks/timed_logger.rb b/lib/gitlab/checks/timed_logger.rb
index cbb079a5383..11c08429d3d 100644
--- a/lib/gitlab/checks/timed_logger.rb
+++ b/lib/gitlab/checks/timed_logger.rb
@@ -5,15 +5,18 @@ module Gitlab
     class TimedLogger
       TimeoutError = Class.new(StandardError)
 
-      attr_reader :start_time
-      attr_accessor :log, :timeout
+      attr_reader :start_time, :header, :log, :timeout
 
-      def initialize(start_time: Time.now, log: [], timeout:)
+      def initialize(start_time: Time.now, log: [], timeout:, header: "")
         @start_time = start_time
         @timeout = timeout
+        @header = header
         @log = log
       end
 
+      # Adds trace of method being tracked with
+      # the correspondent time it took to run it
+      #
       def log_timed(log_message, start = Time.now)
         check_timeout_reached
 
@@ -21,12 +24,12 @@ module Gitlab
 
         yield
 
-        log << log_message + time_suffix_message(start: start)
+        append_message(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)
+        append_message(log_message + time_suffix_message(args))
 
         raise TimeoutError
       end
@@ -41,6 +44,15 @@ module Gitlab
         (start_time + timeout.seconds) - Time.now
       end
 
+      def full_message
+        header + log.join("\n")
+      end
+
+      # We always want to append in-place on the log
+      def append_message(message)
+        log << message
+      end
+
       private
 
       def time_expired?
diff --git a/lib/gitlab/git_access.rb b/lib/gitlab/git_access.rb
index 713a98bb556..1da466cbfd6 100644
--- a/lib/gitlab/git_access.rb
+++ b/lib/gitlab/git_access.rb
@@ -27,6 +27,12 @@ module Gitlab
       cannot_push_to_read_only: "You can't push code to a read-only GitLab instance."
     }.freeze
 
+    LOG_HEADER = <<~MESSAGE
+      Push operation timed out
+
+      Timing information for debugging purposes:
+    MESSAGE
+
     INTERNAL_TIMEOUT = 50.seconds.freeze
     DOWNLOAD_COMMANDS = %w{git-upload-pack git-upload-archive}.freeze
     PUSH_COMMANDS = %w{git-receive-pack}.freeze
@@ -46,7 +52,7 @@ module Gitlab
     end
 
     def check(cmd, changes)
-      @logger = Checks::TimedLogger.new(timeout: INTERNAL_TIMEOUT)
+      @logger = Checks::TimedLogger.new(timeout: INTERNAL_TIMEOUT, header: LOG_HEADER)
       @changes = changes
 
       check_protocol!
@@ -284,13 +290,7 @@ module Gitlab
 
       change_access.exec
     rescue Checks::TimedLogger::TimeoutError
-      header = <<~MESSAGE
-      Push operation timed out
-
-      Timing information for debugging purposes:
-      MESSAGE
-
-      raise TimeoutError, header + logger.log.join("\n")
+      raise TimeoutError, logger.full_message
     end
 
     def deploy_key
-- 
cgit v1.2.1


From e0225aea1beb741601b888d4f505abd97f0f67a6 Mon Sep 17 00:00:00 2001
From: Tiago Botelho <tiagonbotelho@hotmail.com>
Date: Thu, 25 Oct 2018 10:36:40 +0100
Subject: Iterating through commit list times out

Validating each commit on ChangeAccess times out if
it already took too long to complete.

Improves the TimedLogger specs to not make use of a stubbed
class anymore
---
 lib/gitlab/checks/change_access.rb          |  2 +
 lib/gitlab/checks/timed_logger.rb           |  6 ++-
 lib/gitlab/git_access.rb                    |  2 +-
 spec/lib/gitlab/checks/timed_logger_spec.rb | 58 ++++++++++++-----------------
 4 files changed, 30 insertions(+), 38 deletions(-)

diff --git a/lib/gitlab/checks/change_access.rb b/lib/gitlab/checks/change_access.rb
index 7036ae9191d..28ec6beb7e0 100644
--- a/lib/gitlab/checks/change_access.rb
+++ b/lib/gitlab/checks/change_access.rb
@@ -159,6 +159,8 @@ module Gitlab
           # 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))
             end
           end
diff --git a/lib/gitlab/checks/timed_logger.rb b/lib/gitlab/checks/timed_logger.rb
index 11c08429d3d..f365e0a43f6 100644
--- a/lib/gitlab/checks/timed_logger.rb
+++ b/lib/gitlab/checks/timed_logger.rb
@@ -7,7 +7,7 @@ module Gitlab
 
       attr_reader :start_time, :header, :log, :timeout
 
-      def initialize(start_time: Time.now, log: [], timeout:, header: "")
+      def initialize(start_time: Time.now, log: [], header: "", timeout:)
         @start_time = start_time
         @timeout = timeout
         @header = header
@@ -15,7 +15,9 @@ module Gitlab
       end
 
       # Adds trace of method being tracked with
-      # the correspondent time it took to run it
+      # the correspondent time it took to run it.
+      # We make use of the start default argument
+      # on unit tests related to this method
       #
       def log_timed(log_message, start = Time.now)
         check_timeout_reached
diff --git a/lib/gitlab/git_access.rb b/lib/gitlab/git_access.rb
index 1da466cbfd6..802fa65dd63 100644
--- a/lib/gitlab/git_access.rb
+++ b/lib/gitlab/git_access.rb
@@ -27,13 +27,13 @@ module Gitlab
       cannot_push_to_read_only: "You can't push code to a read-only GitLab instance."
     }.freeze
 
+    INTERNAL_TIMEOUT = 50.seconds.freeze
     LOG_HEADER = <<~MESSAGE
       Push operation timed out
 
       Timing information for debugging purposes:
     MESSAGE
 
-    INTERNAL_TIMEOUT = 50.seconds.freeze
     DOWNLOAD_COMMANDS = %w{git-upload-pack git-upload-archive}.freeze
     PUSH_COMMANDS = %w{git-receive-pack}.freeze
     ALL_COMMANDS = DOWNLOAD_COMMANDS + PUSH_COMMANDS
diff --git a/spec/lib/gitlab/checks/timed_logger_spec.rb b/spec/lib/gitlab/checks/timed_logger_spec.rb
index 726f2bf2144..0ed3940c038 100644
--- a/spec/lib/gitlab/checks/timed_logger_spec.rb
+++ b/spec/lib/gitlab/checks/timed_logger_spec.rb
@@ -3,73 +3,61 @@
 require 'spec_helper'
 
 describe Gitlab::Checks::TimedLogger do
-  let(:log_messages) do
+  let!(:timeout) { 50.seconds }
+  let!(:start) { Time.now }
+  let!(:ref) { "bar" }
+  let!(:logger) { described_class.new(start_time: start, timeout: timeout) }
+  let!(:log_messages) do
     {
       foo: "Foo message..."
     }
   end
 
-  class FooCheck
-    attr_accessor :logger
-
-    INTERNAL_TIMEOUT = 50.seconds.freeze
-
-    def initialize(start_time, ref)
-      @logger = Gitlab::Checks::TimedLogger.new(start_time: start_time, timeout: INTERNAL_TIMEOUT)
-      @logger.log << "Checking ref: #{ref}"
-    end
-
-    def bar_check
-      2 + 2
-    end
-
-    def grpc_check
-      raise GRPC::DeadlineExceeded
-    end
+  before do
+    logger.append_message("Checking ref: #{ref}")
   end
 
   describe '#log_timed' do
     it 'logs message' do
-      start = Time.now
-      check = FooCheck.new(start, "bar")
-
       Timecop.freeze(start + 30.seconds) do
-        check.logger.log_timed(log_messages[:foo], start) { check.bar_check }
+        logger.log_timed(log_messages[:foo], start) { bar_check }
       end
 
-      expect(check.logger.log).to eq(["Checking ref: bar", "Foo message... (30000.0ms)"])
+      expect(logger.full_message).to eq("Checking ref: bar\nFoo message... (30000.0ms)")
     end
 
     context 'when time limit was reached' do
       it 'cancels action' do
-        start = Time.now
-        check = FooCheck.new(start, "bar")
-
         Timecop.freeze(start + 50.seconds) do
           expect do
-            check.logger.log_timed(log_messages[:foo], start) do
-              check.bar_check
+            logger.log_timed(log_messages[:foo], start) do
+              bar_check
             end
           end.to raise_error(described_class::TimeoutError)
         end
 
-        expect(check.logger.log).to eq(["Checking ref: bar", "Foo message... (cancelled)"])
+        expect(logger.full_message).to eq("Checking ref: bar\nFoo message... (cancelled)")
       end
 
       it 'cancels action with time elapsed if work was performed' do
-        start = Time.now
-        check = FooCheck.new(start, "bar")
-
         Timecop.freeze(start + 30.seconds) do
           expect do
-            check.logger.log_timed(log_messages[:foo], start) do
-              check.grpc_check
+            logger.log_timed(log_messages[:foo], start) do
+              grpc_check
             end
           end.to raise_error(described_class::TimeoutError)
 
-          expect(check.logger.log).to eq(["Checking ref: bar", "Foo message... (cancelled after 30000.0ms)"])
+          expect(logger.full_message).to eq("Checking ref: bar\nFoo message... (cancelled after 30000.0ms)")
         end
       end
     end
   end
+
+  def bar_check
+    2 + 2
+  end
+
+  def grpc_check
+    raise GRPC::DeadlineExceeded
+  end
 end
-- 
cgit v1.2.1


From 41fe3fdfc39092e63a3fe1ae9b323e5204c2bdce Mon Sep 17 00:00:00 2001
From: Tiago Botelho <tiagonbotelho@hotmail.com>
Date: Fri, 26 Oct 2018 09:50:44 +0100
Subject: Reverts commits_check message

---
 lib/gitlab/checks/change_access.rb | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/lib/gitlab/checks/change_access.rb b/lib/gitlab/checks/change_access.rb
index 28ec6beb7e0..074afe9c412 100644
--- a/lib/gitlab/checks/change_access.rb
+++ b/lib/gitlab/checks/change_access.rb
@@ -28,7 +28,7 @@ module Gitlab
         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
+        commits_check: "Validating commit contents..."
       }.freeze
 
       attr_reader :user_access, :project, :skip_authorization, :skip_lfs_integrity_check, :protocol, :oldrev, :newrev, :ref, :branch_name, :tag_name, :logger
-- 
cgit v1.2.1


From c6c17f1ca636f879c245133cffeae531a7d3df55 Mon Sep 17 00:00:00 2001
From: Tiago Botelho <tiagonbotelho@hotmail.com>
Date: Fri, 26 Oct 2018 10:18:34 +0100
Subject: Bumps GitLab Shell version

---
 GITLAB_SHELL_VERSION | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/GITLAB_SHELL_VERSION b/GITLAB_SHELL_VERSION
index 9da0a092a0d..6da4de57dc6 100644
--- a/GITLAB_SHELL_VERSION
+++ b/GITLAB_SHELL_VERSION
@@ -1 +1 @@
-8.4.0
\ No newline at end of file
+8.4.1
-- 
cgit v1.2.1