Skip to content

Commit 24ac7da

Browse files
committed
Fix OrderReporter producing empty test_order.log in parallel DRb mode
## Situation OrderReporter writes test identifiers in its before_test method, but in Rails parallel DRb mode (forked processes), before_test is never called. The parallelization server only calls prerecord and record on the parent process's reporters. Since tests execute in forked workers via Minitest.run_one_method (which bypasses reporters entirely), the test_order.log file is truncated on start and never written to. This makes it impossible to bisect order-dependent flaky test failures because the test order is never recorded. ## Execution Instead of relying on the reporter API (which lacks worker identity in DRb mode), prepend a TestOrderTracking module onto Minitest::Test that hooks into before_setup. This fires inside the forked worker process during run_one_method, where Process.pid correctly identifies the worker. Each forked worker writes to its own file (test_order.worker-{pid}.log) with sync writes enabled (workers never call report, so buffered writes risk data loss on crash). The parent process's main test_order.log is used in non-parallel mode where the parent is the test process. On start, stale worker files from previous runs are cleaned up.
1 parent 3e0df3f commit 24ac7da

2 files changed

Lines changed: 128 additions & 26 deletions

File tree

ruby/lib/minitest/queue/order_reporter.rb

Lines changed: 59 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -2,38 +2,87 @@
22
require 'minitest/reporters'
33

44
class Minitest::Queue::OrderReporter < Minitest::Reporters::BaseReporter
5+
# Hook prepended onto Minitest::Test to capture test order from within the
6+
# worker process. In DRb parallel mode, reporters only receive prerecord/record
7+
# in the parent, but before_setup runs inside the forked worker where we can
8+
# identify the process.
9+
module TestOrderTracking
10+
def before_setup
11+
if (reporter = Minitest::Queue::OrderReporter.active_instance)
12+
reporter.track_test_order(self.class.name, self.name)
13+
end
14+
super
15+
end
16+
end
17+
18+
class << self
19+
attr_accessor :active_instance
20+
end
21+
522
def initialize(options = {})
623
@path = options.delete(:path)
7-
@file = nil
24+
@dir = File.dirname(@path)
25+
@basename = File.basename(@path, File.extname(@path))
26+
@ext = File.extname(@path)
827
@flush_every = Integer(ENV.fetch('CI_QUEUE_ORDER_FLUSH_EVERY', '50'))
928
@flush_every = 1 if @flush_every < 1
1029
@pending = 0
30+
@parent_pid = nil
31+
@files = {}
32+
@mutex = Mutex.new
1133
super
1234
end
1335

1436
def start
1537
super
16-
file.truncate(0)
38+
@parent_pid = Process.pid
39+
self.class.active_instance = self
40+
41+
# Clean stale worker files from previous runs
42+
Dir.glob(File.join(@dir, "#{@basename}.worker-*#{@ext}")).each do |f|
43+
File.delete(f)
44+
end
45+
46+
# Truncate the main file
47+
file_for_pid(@parent_pid).truncate(0)
1748
end
1849

19-
def before_test(test)
20-
super
21-
file.puts("#{test.class.name}##{test.name}")
50+
def track_test_order(klass_name, test_name)
51+
pid = Process.pid
52+
f = file_for_pid(pid)
53+
f.puts("#{klass_name}##{test_name}")
2254
@pending += 1
2355
if @pending >= @flush_every
24-
file.flush
56+
f.flush
2557
@pending = 0
2658
end
2759
end
2860

2961
def report
30-
file.flush
31-
file.close
62+
self.class.active_instance = nil
63+
@files.each_value do |f|
64+
f.flush
65+
f.close
66+
end
3267
end
3368

3469
private
3570

36-
def file
37-
@file ||= File.open(@path, 'a+')
71+
def file_for_pid(pid)
72+
@mutex.synchronize do
73+
@files[pid] ||= begin
74+
path = if pid == @parent_pid
75+
@path
76+
else
77+
File.join(@dir, "#{@basename}.worker-#{pid}#{@ext}")
78+
end
79+
f = File.open(path, 'a+')
80+
# Forked workers don't call report, so sync writes to avoid data loss
81+
f.sync = true if pid != @parent_pid
82+
f
83+
end
84+
end
3885
end
3986
end
87+
88+
Minitest::Test.prepend(Minitest::Queue::OrderReporter::TestOrderTracking)

ruby/test/minitest/queue/order_reporter_test.rb

Lines changed: 69 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -9,45 +9,98 @@ def setup
99
@reporter = OrderReporter.new(path: log_path)
1010
end
1111

12+
def teardown
13+
OrderReporter.active_instance = nil
14+
# Clean up worker files
15+
Dir.glob(File.join(File.dirname(log_path), "test_order.worker-*")).each do |f|
16+
File.delete(f)
17+
end
18+
end
19+
1220
def test_start
1321
@reporter.start
1422
@reporter.report
1523
assert_equal [], File.readlines(log_path).map(&:chomp)
1624
end
1725

18-
def test_before_test
26+
def test_track_test_order
1927
@reporter.start
20-
@reporter.before_test(runnable('a'))
21-
@reporter.before_test(runnable('b'))
28+
@reporter.track_test_order('Minitest::Test', 'a')
29+
@reporter.track_test_order('Minitest::Test', 'b')
2230
@reporter.report
2331
assert_equal ['Minitest::Test#a', 'Minitest::Test#b'], File.readlines(log_path).map(&:chomp)
2432
end
2533

34+
def test_before_setup_hook
35+
@reporter.start
36+
# Simulate what happens when a test runs: before_setup fires the hook
37+
test_instance = Minitest::Test.new('a')
38+
test_instance.before_setup
39+
@reporter.report
40+
assert_equal ['Minitest::Test#a'], File.readlines(log_path).map(&:chomp)
41+
end
42+
2643
unless truffleruby?
27-
def test_forking
28-
pid = fork do
29-
@reporter.start
44+
def test_forked_workers_write_per_pid_files
45+
@reporter.start
46+
47+
pids = 3.times.map do
48+
fork do
49+
# Simulate a forked worker running tests
50+
@reporter.track_test_order('Minitest::Test', "test_#{Process.pid}")
51+
# Workers don't call report; sync mode ensures data is written
52+
end
53+
end
54+
pids.each { |pid| Process.waitpid(pid) }
55+
56+
@reporter.report
57+
58+
# Main file should be empty (parent ran no tests)
59+
assert_equal [], File.readlines(log_path).map(&:chomp)
60+
61+
# Each worker should have its own file
62+
pids.each do |pid|
63+
worker_path = File.join(File.dirname(log_path), "test_order.worker-#{pid}.log")
64+
assert File.exist?(worker_path), "Expected #{worker_path} to exist"
65+
assert_equal ["Minitest::Test#test_#{pid}"], File.readlines(worker_path).map(&:chomp)
3066
end
31-
pids = 5.times.map do
67+
end
68+
69+
def test_forked_workers_via_before_setup_hook
70+
@reporter.start
71+
72+
pids = 3.times.map do
3273
fork do
33-
@reporter.before_test(runnable(Process.pid))
34-
@reporter.report
74+
test_instance = Minitest::Test.new("test_#{Process.pid}")
75+
test_instance.before_setup
3576
end
3677
end
37-
(pids + [pid]).map do |pid|
38-
Process.waitpid(pid)
78+
pids.each { |pid| Process.waitpid(pid) }
79+
80+
@reporter.report
81+
82+
# Each worker should have its own file via the hook
83+
pids.each do |pid|
84+
worker_path = File.join(File.dirname(log_path), "test_order.worker-#{pid}.log")
85+
assert File.exist?(worker_path), "Expected #{worker_path} to exist"
86+
assert_equal ["Minitest::Test#test_#{pid}"], File.readlines(worker_path).map(&:chomp)
3987
end
88+
end
89+
90+
def test_start_cleans_stale_worker_files
91+
# Create a stale worker file
92+
stale_path = File.join(File.dirname(log_path), "test_order.worker-99999.log")
93+
File.write(stale_path, "stale\n")
4094

41-
assert_equal pids.map { |pid| "Minitest::Test##{pid}" }.sort, File.readlines(log_path).map(&:chomp).sort
95+
@reporter.start
96+
@reporter.report
97+
98+
refute File.exist?(stale_path), "Stale worker file should be cleaned up"
4299
end
43100
end
44101

45102
private
46103

47-
def delete_log
48-
File.delete(log_path) if File.exists?(log_path)
49-
end
50-
51104
def log_path
52105
@path ||= File.join(Dir.tmpdir, 'test_order.log')
53106
end

0 commit comments

Comments
 (0)