From e4c67a31b701ea6290a03c74dd432ba468ef37ee Mon Sep 17 00:00:00 2001 From: Christian Bruckmayer Date: Thu, 11 Jan 2024 21:20:05 +0000 Subject: [PATCH] Add --debug-log configuration --- ruby/lib/ci/queue/configuration.rb | 7 +++-- ruby/lib/ci/queue/redis/base.rb | 33 +++++++++++++++++++- ruby/lib/minitest/queue/runner.rb | 4 +++ ruby/test/integration/minitest_redis_test.rb | 27 ++++++++++++++++ 4 files changed, 67 insertions(+), 4 deletions(-) diff --git a/ruby/lib/ci/queue/configuration.rb b/ruby/lib/ci/queue/configuration.rb index 1a87c8f8..0b69c057 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, :warnings_file + attr_accessor :max_test_failed, :redis_ttl, :warnings_file, :debug_log attr_reader :circuit_breakers attr_writer :seed, :build_id attr_writer :queue_init_timeout, :report_timeout, :inactive_workers_timeout @@ -19,6 +19,7 @@ def from_env(env) flaky_tests: load_flaky_tests(env['CI_QUEUE_FLAKY_TESTS']), statsd_endpoint: env['CI_QUEUE_STATSD_ADDR'], redis_ttl: env['CI_QUEUE_REDIS_TTL']&.to_i || 8 * 60 * 60, + debug_log: env['CI_QUEUE_DEBUG_LOG'], ) end @@ -36,8 +37,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, warnings_file: nil - ) + export_flaky_tests_file: nil, warnings_file: nil, debug_log: nil) @build_id = build_id @circuit_breakers = [CircuitBreaker::Disabled] @failure_file = failure_file @@ -62,6 +62,7 @@ def initialize( @inactive_workers_timeout = inactive_workers_timeout @export_flaky_tests_file = export_flaky_tests_file @warnings_file = warnings_file + @debug_log = debug_log end def queue_init_timeout diff --git a/ruby/lib/ci/queue/redis/base.rb b/ruby/lib/ci/queue/redis/base.rb index dd073239..3619e29f 100644 --- a/ruby/lib/ci/queue/redis/base.rb +++ b/ruby/lib/ci/queue/redis/base.rb @@ -11,19 +11,50 @@ class Base ::SocketError, # https://github.com/redis/redis-rb/pull/631 ].freeze + module RedisInstrumentation + def call(command, redis_config) + result = super + logger = redis_config.custom[:debug_log] + logger.info("#{command}: #{result}") + result + end + + def call_pipelined(commands, redis_config) + result = super + logger = redis_config.custom[:debug_log] + logger.info("#{commands}: #{result}") + result + end + end + def initialize(redis_url, config) @redis_url = redis_url + @config = config if ::Redis::VERSION > "5.0.0" @redis = ::Redis.new( url: redis_url, # Booting a CI worker is costly, so in case of a Redis blip, # it makes sense to retry for a while before giving up. reconnect_attempts: [0, 0, 0.1, 0.5, 1, 3, 5], + middlewares: custom_middlewares, + custom: custom_config, ) else @redis = ::Redis.new(url: redis_url) end - @config = config + end + + def custom_config + return unless config.debug_log + + require 'logger' + { debug_log: Logger.new(config.debug_log) } + end + + def custom_middlewares + return unless config.debug_log + + [RedisInstrumentation] end def exhausted? diff --git a/ruby/lib/minitest/queue/runner.rb b/ruby/lib/minitest/queue/runner.rb index b81fdbed..cac4a5a1 100644 --- a/ruby/lib/minitest/queue/runner.rb +++ b/ruby/lib/minitest/queue/runner.rb @@ -586,6 +586,10 @@ def parser self.verbose = true end + opts.on("--debug-log FILE", "Path to debug log file for e.g. Redis instrumentation") do |path| + queue_config.debug_log = path + end + opts.separator "" opts.separator " retry: Replays a previous run in the same order." diff --git a/ruby/test/integration/minitest_redis_test.rb b/ruby/test/integration/minitest_redis_test.rb index 3b6c56c6..0bd9f8d7 100644 --- a/ruby/test/integration/minitest_redis_test.rb +++ b/ruby/test/integration/minitest_redis_test.rb @@ -72,6 +72,33 @@ def test_verbose_reporter assert_equal '--- Ran 11 tests, 8 assertions, 2 failures, 1 errors, 1 skips, 4 requeues in X.XXs', result end + def test_debug_log + Tempfile.open('debug_log') do |log_file| + out, err = capture_subprocess_io do + system( + { 'BUILDKITE' => '1' }, + @exe, 'run', + '--queue', @redis_url, + '--seed', 'foobar', + '--build', '1', + '--worker', '1', + '--timeout', '1', + '--max-requeues', '1', + '--requeue-tolerance', '1', + '-Itest', + 'test/dummy_test.rb', + '--debug-log', log_file.path, + chdir: 'test/fixtures/', + ) + end + + assert_includes File.read(log_file.path), 'INFO -- : ["exists", "build:1:worker:1:queue"]: 0' + assert_empty err + result = normalize(out.lines.last.strip) + assert_equal '--- Ran 11 tests, 8 assertions, 2 failures, 1 errors, 1 skips, 4 requeues in X.XXs', result + end + end + def test_buildkite_output out, err = capture_subprocess_io do system(