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

5 files changed, 108 insertions, 2 deletions

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