Merge branch 'acunskis-logging-improvements' into 'master'

E2E: Reduce repeater log verbosity if first attempt is successfull

See merge request gitlab-org/gitlab!72455

qa/qa/support/matchers/eventually_matcher.rb

@@ -59,8 +59,10 @@ module QA
             def wait_and_check(actual, expectation_name)
               attempt = 0
 
-              QA::Runtime::Logger.debug("Running eventually matcher with '#{operator_msg}' operator")
-              QA::Support::Retrier.retry_until(**@retry_args) do
+              QA::Runtime::Logger.debug(
+                "Running eventually matcher with '#{operator_msg}' operator with: #{@retry_args}"
+              )
+              QA::Support::Retrier.retry_until(**@retry_args, log: false) do
                 QA::Runtime::Logger.debug("evaluating expectation, attempt: #{attempt += 1}")
 
                 public_send(expectation_name, actual)

qa/qa/support/repeater.rb

@@ -25,10 +25,26 @@ module QA
 
         begin
           while remaining_attempts?(attempts, max_attempts) && remaining_time?(start, max_duration)
-            QA::Runtime::Logger.debug("Attempt number #{attempts + 1}") if max_attempts && log
+            # start logging from the second attempt
+            if log && attempts == 1
+              msg = ["Retrying action with:"]
+              msg << "max_attempts: #{max_attempts};" if max_attempts
+              msg << "max_duration: #{max_duration};" if max_duration
+              msg << "reload_page: #{reload_page};" if reload_page
+              msg << "sleep_interval: #{sleep_interval};"
+              msg << "raise_on_failure: #{raise_on_failure};"
+              msg << "retry_on_exception: #{retry_on_exception}"
+
+              QA::Runtime::Logger.debug(msg.join(' '))
+            end
+
+            QA::Runtime::Logger.debug("Attempt number #{attempts + 1}") if log && max_attempts && attempts > 0
 
             result = yield
-            return result if result
+            if result
+              log_completion(log, attempts)
+              return result
+            end
 
             sleep_and_reload_if_needed(sleep_interval, reload_page)
             attempts += 1
@@ -54,6 +70,8 @@ module QA
           raise WaitExceededError, "Wait condition not met after #{max_duration} #{'second'.pluralize(max_duration)}"
         end
 
+        log_completion(log, attempts)
+
         false
       end
 
@@ -71,6 +89,17 @@ module QA
       def remaining_time?(start, max_duration)
         max_duration ? Time.now - start < max_duration : true
       end
+
+      # Log completion if more than one attempt performed
+      #
+      # @param [Boolean] log
+      # @param [Integer] attempts
+      # @return [void]
+      def log_completion(log, attempts)
+        return unless log && attempts > 0
+
+        QA::Runtime::Logger.debug('ended retry')
+      end
     end
   end
 end

qa/qa/support/retrier.rb

@@ -8,13 +8,6 @@ module QA
       module_function
 
       def retry_on_exception(max_attempts: 3, reload_page: nil, sleep_interval: 0.5, log: true)
-        if log
-          msg = ["with retry_on_exception: max_attempts: #{max_attempts}"]
-          msg << "reload_page: #{reload_page}" if reload_page
-          msg << "sleep_interval: #{sleep_interval}"
-          QA::Runtime::Logger.debug(msg.join('; '))
-        end
-
         result = nil
         repeat_until(
           max_attempts: max_attempts,
@@ -29,7 +22,6 @@ module QA
           # We set it to `true` so that it doesn't repeat if there's no exception
           true
         end
-        QA::Runtime::Logger.debug("ended retry_on_exception") if log
 
         result
       end
@@ -46,20 +38,6 @@ module QA
         # For backwards-compatibility
         max_attempts = 3 if max_attempts.nil? && max_duration.nil?
 
-        if log
-          start_msg = ["with retry_until:"]
-          start_msg << "max_attempts: #{max_attempts};" if max_attempts
-          start_msg << "max_duration: #{max_duration};" if max_duration
-          start_msg.push(*[
-                           "reload_page: #{reload_page};",
-                           "sleep_interval: #{sleep_interval};",
-                           "raise_on_failure: #{raise_on_failure};",
-                           "retry_on_exception: #{retry_on_exception}"
-                         ])
-
-          QA::Runtime::Logger.debug(start_msg.join(' '))
-        end
-
         result = nil
         repeat_until(
           max_attempts: max_attempts,
@@ -72,7 +50,6 @@ module QA
         ) do
           result = yield
         end
-        QA::Runtime::Logger.debug("ended retry_until") if log
 
         result
       end

qa/qa/support/waiter.rb

@@ -7,20 +7,16 @@ module QA
 
       module_function
 
-      def wait_until(max_duration: singleton_class::DEFAULT_MAX_WAIT_TIME, reload_page: nil, sleep_interval: 0.1, raise_on_failure: true, retry_on_exception: false, log: true)
-        if log
-          QA::Runtime::Logger.debug(
-            <<~MSG.tr("\n", ' ')
-              with wait_until: max_duration: #{max_duration};
-              reload_page: #{reload_page};
-              sleep_interval: #{sleep_interval};
-              raise_on_failure: #{raise_on_failure}
-            MSG
+      def wait_until(
+        max_duration: singleton_class::DEFAULT_MAX_WAIT_TIME,
+        reload_page: nil,
+        sleep_interval: 0.1,
+        raise_on_failure: true,
+        retry_on_exception: false,
+        log: true
       )
-        end
-
         result = nil
-        self.repeat_until(
+        repeat_until(
           max_duration: max_duration,
           reload_page: reload_page,
           sleep_interval: sleep_interval,
@@ -30,7 +26,6 @@ module QA
         ) do
           result = yield
         end
-        QA::Runtime::Logger.debug("ended wait_until") if log
 
         result
       end

qa/spec/support/repeater_spec.rb

@@ -380,34 +380,67 @@ RSpec.describe QA::Support::Repeater do
       end
     end
 
-    it 'logs attempts' do
-      attempted = false
+    context 'with logging' do
+      before do
+        allow(QA::Runtime::Logger).to receive(:debug)
+      end
 
-      expect do
-        subject.repeat_until(max_attempts: 1) do
-          unless attempted
-            attempted = true
-            break false
+      it 'skips logging single attempt with max_attempts' do
+        subject.repeat_until(max_attempts: 3) do
+          true
+        end
+
+        expect(QA::Runtime::Logger).not_to have_received(:debug)
       end
 
+      it 'skips logging single attempt with max_duration' do
+        subject.repeat_until(max_duration: 3) do
           true
         end
-      end.to output(/Attempt number/).to_stdout_from_any_process
+
+        expect(QA::Runtime::Logger).not_to have_received(:debug)
       end
 
       it 'allows logging to be silenced' do
-      attempted = false
+        subject.repeat_until(max_attempts: 3, log: false, raise_on_failure: false) do
+          false
+        end
 
-      expect do
-        subject.repeat_until(max_attempts: 1, log: false) do
-          unless attempted
-            attempted = true
-            break false
+        expect(QA::Runtime::Logger).not_to have_received(:debug)
       end
 
-          true
+      it 'starts logging on subsequent attempts for max_duration' do
+        subject.repeat_until(max_duration: 0.3, sleep_interval: 0.1, raise_on_failure: false) do
+          false
+        end
+
+        aggregate_failures do
+          expect(QA::Runtime::Logger).to have_received(:debug).with(<<~MSG.strip).ordered.once
+            Retrying action with: max_duration: 0.3; sleep_interval: 0.1; raise_on_failure: false; retry_on_exception: false
+          MSG
+          expect(QA::Runtime::Logger).to have_received(:debug).with('ended retry').ordered.once
+          expect(QA::Runtime::Logger).not_to have_received(:debug).with(/Attempt number/)
+        end
+      end
+
+      it 'starts logging subsequent attempts for max_attempts' do
+        attempts = 0
+        subject.repeat_until(max_attempts: 4, raise_on_failure: false) do
+          next true if attempts == 2
+
+          attempts += 1
+          false
+        end
+
+        aggregate_failures do
+          expect(QA::Runtime::Logger).to have_received(:debug).with(<<~MSG.strip).ordered.once
+            Retrying action with: max_attempts: 4; sleep_interval: 0; raise_on_failure: false; retry_on_exception: false
+          MSG
+          expect(QA::Runtime::Logger).to have_received(:debug).with('Attempt number 2').ordered.once
+          expect(QA::Runtime::Logger).to have_received(:debug).with('Attempt number 3').ordered.once
+          expect(QA::Runtime::Logger).to have_received(:debug).with('ended retry').ordered.once
+        end
       end
-      end.not_to output.to_stdout_from_any_process
     end
   end
 end

qa/spec/support/retrier_spec.rb

 # frozen_string_literal: true
 
 RSpec.describe QA::Support::Retrier do
-  before do
-    logger = ::Logger.new $stdout
-    logger.level = ::Logger::DEBUG
-    QA::Runtime::Logger.logger = logger
-  end
-
   describe '.retry_until' do
-    context 'when the condition is true' do
-      it 'logs max attempts (3 by default)' do
-        expect { subject.retry_until { true } }
-          .to output(/with retry_until: max_attempts: 3; reload_page: ; sleep_interval: 0; raise_on_failure: true; retry_on_exception: false/).to_stdout_from_any_process
-      end
-
-      it 'logs max duration' do
-        expect { subject.retry_until(max_duration: 1) { true } }
-          .to output(/with retry_until: max_duration: 1; reload_page: ; sleep_interval: 0; raise_on_failure: true; retry_on_exception: false/).to_stdout_from_any_process
-      end
-
-      it 'logs the end' do
-        expect { subject.retry_until { true } }
-        .to output(/ended retry_until$/).to_stdout_from_any_process
-      end
-    end
-
-    context 'when the condition is false' do
-      it 'logs the start' do
-        expect { subject.retry_until(max_duration: 0, raise_on_failure: false) { false } }
-          .to output(/with retry_until: max_duration: 0; reload_page: ; sleep_interval: 0; raise_on_failure: false; retry_on_exception: false/).to_stdout_from_any_process
-      end
-
-      it 'logs the end' do
-        expect { subject.retry_until(max_duration: 0, raise_on_failure: false) { false } }
-        .to output(/ended retry_until$/).to_stdout_from_any_process
-      end
-    end
-
     context 'when max_duration and max_attempts are nil' do
       it 'sets max attempts to 3 by default' do
         expect(subject).to receive(:repeat_until).with(hash_including(max_attempts: 3))
@@ -62,35 +27,15 @@ RSpec.describe QA::Support::Retrier do
 
       subject.retry_until
     end
-  end
 
-  describe '.retry_on_exception' do
-    context 'when the condition is true' do
-      it 'logs max_attempts, reload_page, and sleep_interval parameters' do
-        message = /with retry_on_exception: max_attempts: 1; reload_page: true; sleep_interval: 0/
-        expect { subject.retry_on_exception(max_attempts: 1, reload_page: true, sleep_interval: 0) { true } }
-          .to output(message).to_stdout_from_any_process
-      end
+    it 'allows logs to be silenced' do
+      expect(subject).to receive(:repeat_until).with(hash_including(log: false))
 
-      it 'logs the end' do
-        expect { subject.retry_on_exception(max_attempts: 1, reload_page: nil, sleep_interval: 0) { true } }
-        .to output(/ended retry_on_exception$/).to_stdout_from_any_process
-      end
-    end
-
-    context 'when the condition is false' do
-      it 'logs the start' do
-        message = /with retry_on_exception: max_attempts: 1; reload_page: true; sleep_interval: 0/
-        expect { subject.retry_on_exception(max_attempts: 1, reload_page: true, sleep_interval: 0) { false } }
-          .to output(message).to_stdout_from_any_process
-      end
-
-      it 'logs the end' do
-        expect { subject.retry_on_exception(max_attempts: 1, reload_page: nil, sleep_interval: 0) { false } }
-        .to output(/ended retry_on_exception$/).to_stdout_from_any_process
+      subject.retry_until(log: false)
     end
   end
 
+  describe '.retry_on_exception' do
     it 'does not repeat if no exception is raised' do
       loop_counter = 0
       return_value = "test passed"
@@ -121,5 +66,11 @@ RSpec.describe QA::Support::Retrier do
 
       subject.retry_on_exception
     end
+
+    it 'allows logs to be silenced' do
+      expect(subject).to receive(:repeat_until).with(hash_including(log: false))
+
+      subject.retry_on_exception(log: false)
+    end
   end
 end

qa/spec/support/waiter_spec.rb

 # frozen_string_literal: true
 
 RSpec.describe QA::Support::Waiter do
-  before do
-    logger = ::Logger.new $stdout
-    logger.level = ::Logger::DEBUG
-    QA::Runtime::Logger.logger = logger
-  end
-
   describe '.wait_until' do
-    context 'when the condition is true' do
-      it 'logs the start' do
-        expect { subject.wait_until(max_duration: 0, raise_on_failure: false) { true } }
-        .to output(/with wait_until: max_duration: 0; reload_page: ; sleep_interval: 0.1/).to_stdout_from_any_process
-      end
-
-      it 'logs the end' do
-        expect { subject.wait_until(max_duration: 0, raise_on_failure: false) { true } }
-        .to output(/ended wait_until$/).to_stdout_from_any_process
-      end
-    end
-
-    context 'when the condition is false' do
-      it 'logs the start' do
-        expect { subject.wait_until(max_duration: 0, raise_on_failure: false) { false } }
-        .to output(/with wait_until: max_duration: 0; reload_page: ; sleep_interval: 0.1/).to_stdout_from_any_process
-      end
-
-      it 'logs the end' do
-        expect { subject.wait_until(max_duration: 0, raise_on_failure: false) { false } }
-        .to output(/ended wait_until$/).to_stdout_from_any_process
-      end
-    end
-
     it 'allows logs to be silenced' do
-      expect { subject.wait_until(max_duration: 0, raise_on_failure: false, log: false) { false } }
-        .not_to output.to_stdout_from_any_process
+      expect(subject).to receive(:repeat_until).with(hash_including(log: false))
+
+      subject.wait_until(log: false)
     end
 
     it 'sets max_duration to 60 by default' do