Merge pull request #281 from Shopify/cbruckmayer/leader-elected

Add logs around leader election

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

@@ -185,6 +185,12 @@ def max_test_failed?
 
         attr_reader :redis, :redis_url
 
+        def measure
+          starting = Process.clock_gettime(Process::CLOCK_MONOTONIC)
+          yield
+          Process.clock_gettime(Process::CLOCK_MONOTONIC) - starting
+        end
+
         def key(*args)
           ['build', build_id, *args].join(':')
         end

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

@@ -47,12 +47,6 @@ def wait_for_workers
 
         private
 
-        def measure
-          starting = Process.clock_gettime(Process::CLOCK_MONOTONIC)
-          yield
-          Process.clock_gettime(Process::CLOCK_MONOTONIC) - starting
-        end
-
         def active_workers?
           # if there are running jobs we assume there are still agents active
           redis.zrangebyscore(key('running'), CI::Queue.time_now.to_f - config.timeout, "+inf", limit: [0,1]).count > 0

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

@@ -204,15 +204,22 @@ def push(tests)
           @total = tests.size
 
           if @master = redis.setnx(key('master-status'), 'setup')
-            redis.multi do |transaction|
-              transaction.lpush(key('queue'), tests) unless tests.empty?
-              transaction.set(key('total'), @total)
-              transaction.set(key('master-status'), 'ready')
-
-              transaction.expire(key('queue'), config.redis_ttl)
-              transaction.expire(key('total'), config.redis_ttl)
-              transaction.expire(key('master-status'), config.redis_ttl)
+            puts "Worker electected as leader, pushing #{@total} tests to the queue."
+            puts
+
+            duration = measure do
+              redis.multi do |transaction|
+                transaction.lpush(key('queue'), tests) unless tests.empty?
+                transaction.set(key('total'), @total)
+                transaction.set(key('master-status'), 'ready')
+
+                transaction.expire(key('queue'), config.redis_ttl)
+                transaction.expire(key('total'), config.redis_ttl)
+                transaction.expire(key('master-status'), config.redis_ttl)
+              end
             end
+
+            puts "Finished pushing #{@total} tests to the queue in #{duration.round(2)}s."
           end
           register
           redis.expire(key('workers'), config.redis_ttl)

ruby/lib/minitest/queue/runner.rb

@@ -223,7 +223,7 @@ def bisect_command
 
         failing_order = queue.candidates
         step("Final validation")
-        status = if run_tests_in_fork(failing_order)
+        if run_tests_in_fork(failing_order)
           step(yellow("The bisection was inconclusive, there might not be any leaky test here."))
           File.write('log/test_order.log', "")
           exit! 1
@@ -314,7 +314,8 @@ def report_grind_command
       private
 
       attr_reader :queue_config, :options, :command, :argv
-      attr_accessor :queue, :queue_url, :grind_list, :grind_count, :load_paths, :verbose
+      attr_writer :queue_url
+      attr_accessor :queue, :grind_list, :grind_count, :load_paths, :verbose
 
       def require_worker_id!
         if queue.distributed?

ruby/test/ci/queue/redis_supervisor_test.rb

@@ -48,7 +48,7 @@ def test_wait_for_workers_timeout
     thread.wakeup
     worker(1)
     thread.join
-    assert_includes io, "Aborting, it seems all workers died.\n"
+    assert_includes io.join, "Aborting, it seems all workers died.\n"
   end
 
   def test_num_workers

ruby/test/integration/minitest_redis_test.rb

@@ -216,7 +216,6 @@ def test_max_test_failed
       assert_equal 'Ran 47 tests, 47 assertions, 3 failures, 0 errors, 0 skips, 44 requeues in X.XXs', output
 
       # Run the reporter
-      exit_code = nil
       out, err = capture_subprocess_io do
         system(
           @exe, 'report',
@@ -862,12 +861,6 @@ def test_redis_reporter
           )
         end
 
-        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
-
         warnings_file.rewind
         content = JSON.parse(warnings_file.read)
         assert_equal 1, content.size
@@ -953,7 +946,7 @@ def test_application_error
 
       assert_equal 42, $?.exitstatus
 
-      out, err = capture_subprocess_io do
+      out, _ = capture_subprocess_io do
         system(
           @exe, 'report',
           '--queue', @redis_url,

ruby/test/integration/rspec_redis_test.rb

@@ -34,6 +34,9 @@ def test_redis_runner
 
       assert_empty err
       expected_output = strip_heredoc <<-EOS
+        Worker electected as leader, pushing 3 tests to the queue.
+
+        Finished pushing 3 tests to the queue in X.XXs.
 
         Randomized with seed 123
         ..*.
@@ -88,6 +91,9 @@ def test_redis_runner_retry
 
       assert_empty err
       expected_output = strip_heredoc <<-EOS
+        Worker electected as leader, pushing 3 tests to the queue.
+
+        Finished pushing 3 tests to the queue in X.XXs.
 
         Randomized with seed 123
         ..*.
@@ -267,6 +273,9 @@ def test_before_suite_errors
 
       assert_empty err
       expected_output = strip_heredoc <<-EOS
+        Worker electected as leader, pushing 2 tests to the queue.
+
+        Finished pushing 2 tests to the queue in X.XXs.
 
         Randomized with seed 123
 
@@ -308,6 +317,9 @@ def test_report
 
       assert_empty err
       expected_output = strip_heredoc <<-EOS
+        Worker electected as leader, pushing 3 tests to the queue.
+
+        Finished pushing 3 tests to the queue in X.XXs.
 
         Randomized with seed 123
         ..F
@@ -379,11 +391,12 @@ def test_world_wants_to_quit
       end
 
       assert_empty err
+
       expected_output = strip_heredoc <<-EOS
 
 
-        Finished in X.XXXXX seconds (files took X.XXXXX seconds to load)
-        0 examples, 0 failures
+      Finished in X.XXXXX seconds (files took X.XXXXX seconds to load)
+      0 examples, 0 failures
 
       EOS
       assert_equal expected_output, normalize(out)
@@ -405,6 +418,9 @@ def test_world_wants_to_quit
 
       assert_empty err
       expected_output = strip_heredoc <<-EOS
+        Worker electected as leader, pushing 1 tests to the queue.
+
+        Finished pushing 1 tests to the queue in X.XXs.
 
         Randomized with seed 123
         F

ruby/test/support/shared_queue_assertions.rb

@@ -6,7 +6,7 @@ module SharedQueueAssertions
   include QueueHelper
 
   def setup
-    @queue = populate(build_queue)
+    capture_io { @queue = populate(build_queue) }
   end
 
   def test_progess