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

@@ -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

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

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

spec/lib/gitlab/checks/timed_logger_spec.rb

@@ -3,20 +3,54 @@
 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
+  before do
+    logger.append_message("Checking ref: #{ref}")
+  end
 
-    INTERNAL_TIMEOUT = 50.seconds.freeze
+  describe '#log_timed' do
+    it 'logs message' do
+      Timecop.freeze(start + 30.seconds) do
+        logger.log_timed(log_messages[:foo], start) { bar_check }
+      end
 
-    def initialize(start_time, ref)
-      @logger = Gitlab::Checks::TimedLogger.new(start_time: start_time, timeout: INTERNAL_TIMEOUT)
-      @logger.log << "Checking ref: #{ref}"
+      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
@@ -27,49 +61,3 @@ describe Gitlab::Checks::TimedLogger do
     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