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

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