Merge branch '42790-improve-feedback-for-internal-git-access-checks-timeouts' into 'master'

Adds trace of each access check when git push times out

Closes #42790

See merge request gitlab-org/gitlab-ce!22265

6 files changed, 114 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..0ed3940c038
--- /dev/null
+++ b/spec/lib/gitlab/checks/timed_logger_spec.rb
@@ -0,0 +1,63 @@
+# frozen_string_literal: true
+
+require 'spec_helper'
+
+describe Gitlab::Checks::TimedLogger 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
+
+  before do
+    logger.append_message("Checking ref: #{ref}")
+  end
+
+  describe '#log_timed' do
+    it 'logs message' do
+      Timecop.freeze(start + 30.seconds) do
+        logger.log_timed(log_messages[:foo], start) { bar_check }
+      end
+
+      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
+        Timecop.freeze(start + 50.seconds) do
+          expect do
+            logger.log_timed(log_messages[:foo], start) do
+              bar_check
+            end
+          end.to raise_error(described_class::TimeoutError)
+        end
+
+        expect(logger.full_message).to eq("Checking ref: bar\nFoo message... (cancelled)")
+      end
+
+      it 'cancels action with time elapsed if work was performed' do
+        Timecop.freeze(start + 30.seconds) do
+          expect do
+            logger.log_timed(log_messages[:foo], start) do
+              grpc_check
+            end
+          end.to raise_error(described_class::TimeoutError)
+
+          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
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)