Add logging

ruby/lib/ci/queue.rb

@@ -13,6 +13,8 @@
 require 'ci/queue/file'
 require 'ci/queue/grind'
 require 'ci/queue/bisect'
+require 'logger'
+require 'fileutils'
 
 module CI
   module Queue
@@ -28,6 +30,21 @@ def requeueable?(test_result)
       requeueable.nil? || requeueable.call(test_result)
     end
 
+    def logger
+      @logger ||= begin
+        FileUtils.mkdir_p("log")
+        Logger.new('log/ci-queue.log')
+      end
+    end
+
+    def with_instrumentation(msg)
+      start = Process.clock_gettime(Process::CLOCK_MONOTONIC, :float_millisecond)
+      result = yield
+      duration = Process.clock_gettime(Process::CLOCK_MONOTONIC, :float_millisecond) - start
+      CI::Queue.logger.info("#{msg} #{duration}ms")
+      result
+    end
+
     def shuffle(tests, random)
       if shuffler
         shuffler.call(tests, random)

ruby/lib/ci/queue/redis/base.rb

@@ -11,9 +11,23 @@ class Base
           ::SocketError, # https://github.com/redis/redis-rb/pull/631
         ].freeze
 
+        module RedisInstrumentation
+          def connect(redis_config)
+            CI::Queue.with_instrumentation("redis connect: ") { super }
+          end
+
+          def call(command, redis_config)
+            CI::Queue.with_instrumentation("redis call #{command}: ") { super }
+          end
+
+          def call_pipelined(commands, redis_config)
+            CI::Queue.with_instrumentation("redis pipeline #{commands}: ") { super }
+          end
+        end
+
         def initialize(redis_url, config)
           @redis_url = redis_url
-          @redis = ::Redis.new(url: redis_url)
+          @redis = ::Redis.new(url: redis_url, middlewares: [RedisInstrumentation])
           @config = config
         end
 
@@ -90,6 +104,8 @@ def test_failed
         def max_test_failed?
           return false if config.max_test_failed.nil?
 
+          CI::Queue.logger.info("Test failed count: #{test_failed}")
+
           test_failed >= config.max_test_failed
         end
 

ruby/lib/ci/queue/redis/worker.rb

@@ -123,6 +123,9 @@ def requeue(test, offset: Redis.requeue_offset)
             argv: [config.max_requeues, global_max_requeues, test_key, offset],
           ) == 1
 
+          CI::Queue.logger.info("global_max_requeues #{global_max_requeues}")
+          CI::Queue.logger.info("Requeued #{test_key} - #{requeued}")
+
           @reserved_test = test_key unless requeued
           requeued
         end

ruby/lib/minitest/queue.rb

@@ -246,6 +246,7 @@ def run_from_queue(reporter, *)
 
         requeued = false
         if failed && CI::Queue.requeueable?(result) && queue.requeue(example)
+          CI::Queue.logger.info("Requesting requeue for #{example.id}")
           requeued = true
           result.requeue!
           reporter.record(result)
@@ -256,6 +257,7 @@ def run_from_queue(reporter, *)
         end
 
         if !requeued && failed
+          CI::Queue.logger.info("Test failed: #{example.id}")
           queue.increment_test_failed
         end
       end