Add --debug-log configuration

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

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?

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."
 

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(