From 87824e0c3a769fbfec0343999e954cb6cca0f8dd Mon Sep 17 00:00:00 2001 From: Christian Bruckmayer Date: Thu, 21 Dec 2023 12:44:14 +0000 Subject: [PATCH] Write warnings to file instead of STDOUT --- ruby/lib/ci/queue/configuration.rb | 5 +- ruby/lib/ci/queue/redis/build_record.rb | 1 + ruby/lib/minitest/queue/runner.rb | 25 ++++--- ruby/test/integration/minitest_redis_test.rb | 75 +++++++++++++------- 4 files changed, 70 insertions(+), 36 deletions(-) diff --git a/ruby/lib/ci/queue/configuration.rb b/ruby/lib/ci/queue/configuration.rb index c766368d..1a87c8f8 100644 --- a/ruby/lib/ci/queue/configuration.rb +++ b/ruby/lib/ci/queue/configuration.rb @@ -5,7 +5,7 @@ class Configuration attr_accessor :timeout, :worker_id, :max_requeues, :grind_count, :failure_file, :export_flaky_tests_file attr_accessor :requeue_tolerance, :namespace, :failing_test, :statsd_endpoint attr_accessor :max_test_duration, :max_test_duration_percentile, :track_test_duration - attr_accessor :max_test_failed, :redis_ttl + attr_accessor :max_test_failed, :redis_ttl, :warnings_file attr_reader :circuit_breakers attr_writer :seed, :build_id attr_writer :queue_init_timeout, :report_timeout, :inactive_workers_timeout @@ -36,7 +36,7 @@ def initialize( grind_count: nil, max_duration: nil, failure_file: nil, max_test_duration: nil, max_test_duration_percentile: 0.5, track_test_duration: false, max_test_failed: nil, queue_init_timeout: nil, redis_ttl: 8 * 60 * 60, report_timeout: nil, inactive_workers_timeout: nil, - export_flaky_tests_file: nil + export_flaky_tests_file: nil, warnings_file: nil ) @build_id = build_id @circuit_breakers = [CircuitBreaker::Disabled] @@ -61,6 +61,7 @@ def initialize( @report_timeout = report_timeout @inactive_workers_timeout = inactive_workers_timeout @export_flaky_tests_file = export_flaky_tests_file + @warnings_file = warnings_file end def queue_init_timeout diff --git a/ruby/lib/ci/queue/redis/build_record.rb b/ruby/lib/ci/queue/redis/build_record.rb index c70c6781..fdbb2eb1 100644 --- a/ruby/lib/ci/queue/redis/build_record.rb +++ b/ruby/lib/ci/queue/redis/build_record.rb @@ -21,6 +21,7 @@ def failed_tests redis.hkeys(key('error-reports')) end + TOTAL_KEY = "___total___" def requeued_tests requeues = redis.hgetall(key('requeues-count')) requeues.delete(TOTAL_KEY) diff --git a/ruby/lib/minitest/queue/runner.rb b/ruby/lib/minitest/queue/runner.rb index d30b02d5..1f19f18b 100644 --- a/ruby/lib/minitest/queue/runner.rb +++ b/ruby/lib/minitest/queue/runner.rb @@ -298,17 +298,17 @@ def require_worker_id! end def display_warnings(build) - build.pop_warnings.each do |type, attributes| + return unless queue_config.warnings_file + + warnings = build.pop_warnings.map do |type, attributes| case type when CI::Queue::Warnings::RESERVED_LOST_TEST - puts reopen_previous_step - puts yellow( - "[WARNING] #{attributes[:test]} was picked up by another worker because it didn't complete in the allocated #{attributes[:timeout]} seconds.\n" \ - "You may want to either optimize this test or bump ci-queue timeout.\n" \ - "It's also possible that the worker that was processing it was terminated without being able to report back.\n" - ) + "[WARNING] #{attributes[:test]} was picked up by another worker because it didn't complete in the allocated #{attributes[:timeout]} seconds.\n" \ + "You may want to either optimize this test or bump ci-queue timeout.\n" \ + "It's also possible that the worker that was processing it was terminated without being able to report back.\n" end - end + end.compact + File.write(queue_config.warnings_file, warnings.join("\n")) end def run_tests_in_fork(queue) @@ -528,6 +528,15 @@ def parser queue_config.export_flaky_tests_file = file end + help = <<~EOS + Defines a file where warnings during the execution are written to. + Defaults to disabled. + EOS + opts.separator "" + opts.on('--warnings-file FILE', help) do |file| + queue_config.warnings_file = file + end + help = <<~EOS Defines after how many consecutive failures the worker will be considered unhealthy and terminate itself. Defaults to disabled. diff --git a/ruby/test/integration/minitest_redis_test.rb b/ruby/test/integration/minitest_redis_test.rb index ea517836..a8e99cc8 100644 --- a/ruby/test/integration/minitest_redis_test.rb +++ b/ruby/test/integration/minitest_redis_test.rb @@ -731,37 +731,60 @@ def test_redis_reporter output = normalize(out.lines.last.strip) assert_equal 'Ran 11 tests, 8 assertions, 2 failures, 1 errors, 1 skips, 4 requeues in X.XXs', output - out, err = capture_subprocess_io do - system( - @exe, 'report', - '--queue', @redis_url, - '--build', '1', - '--timeout', '1', - chdir: 'test/fixtures/', - ) - end - assert_empty err - output = normalize(out) - expected_output = <<~END - Waiting for workers to complete + Tempfile.open('warnings') do |warnings_file| + out, err = capture_subprocess_io do + system( + @exe, 'report', + '--queue', @redis_url, + '--build', '1', + '--timeout', '1', + '--warnings-file', warnings_file.path, + chdir: 'test/fixtures/', + ) + end - [WARNING] Atest#test_bar was picked up by another worker because it didn't complete in the allocated 2 seconds. - You may want to either optimize this test or bump ci-queue timeout. - It's also possible that the worker that was processing it was terminated without being able to report back. + warning = <<~END + [WARNING] Atest#test_bar was picked up by another worker because it didn't complete in the allocated 2 seconds. + You may want to either optimize this test or bump ci-queue timeout. + It's also possible that the worker that was processing it was terminated without being able to report back. + END - Ran 7 tests, 8 assertions, 2 failures, 1 errors, 1 skips, 4 requeues in X.XXs (aggregated) + warnings_file.rewind + assert_equal warning, warnings_file.read - FAIL ATest#test_bar - Expected false to be truthy. - test/dummy_test.rb:10:in `test_bar' + assert_empty err + output = normalize(out) + expected_output = <<~END + Waiting for workers to complete + Ran 7 tests, 8 assertions, 2 failures, 1 errors, 1 skips, 4 requeues in X.XXs (aggregated) - FAIL ATest#test_flaky_fails_retry - Expected false to be truthy. - test/dummy_test.rb:23:in `test_flaky_fails_retry' + FAIL ATest#test_bar + Expected false to be truthy. + test/dummy_test.rb:10:in `test_bar' - ERROR BTest#test_bar - END - assert_includes output, expected_output + FAIL ATest#test_flaky_fails_retry + Expected false to be truthy. + test/dummy_test.rb:23:in `test_flaky_fails_retry' + + ERROR BTest#test_bar + END + assert_includes output, expected_output + + expected_output = <<~END + REQUEUE + ATest#test_bar (requeued 1 times) + + REQUEUE + ATest#test_flaky (requeued 1 times) + + REQUEUE + ATest#test_flaky_fails_retry (requeued 1 times) + + REQUEUE + BTest#test_bar (requeued 1 times) + END + assert_includes output, expected_output + end end def test_utf8_tests_and_marshal