Skip to content

Commit

Permalink
test_child_process: Try to fix unstable tests
Browse files Browse the repository at this point in the history
On CI environment, these tests sometimes observe unexepected 3rd command
invocation due to delayed shutdown:

```
2022-06-13T23:57:56.4703110Z Failure: test: can execute external command many times, with leading once executed immediately(ChildProcessTest)
2022-06-13T23:57:56.4704700Z /Users/runner/work/fluentd/fluentd/test/plugin_helper/test_child_process.rb:345:in `block (2 levels) in <class:ChildProcessTest>'
2022-06-13T23:57:56.4705540Z      342:       end
2022-06-13T23:57:56.4706110Z      343:       sleep 1.9 # 1sec(second invocation) + 0.9sec
2022-06-13T23:57:56.4706880Z      344:       @d.stop; @d.shutdown; @d.close; @d.terminate
2022-06-13T23:57:56.4707620Z   => 345:       assert_equal 2, ary.size
2022-06-13T23:57:56.4708220Z      346:       assert_equal [], @d.log.out.logs
2022-06-13T23:57:56.4708800Z      347:     end
2022-06-13T23:57:56.4709330Z      348:   end
2022-06-13T23:57:56.4709970Z /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/2.7.0/timeout.rb:95:in `block in timeout'
2022-06-13T23:57:56.4710800Z /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/2.7.0/timeout.rb:33:in `block in catch'
2022-06-13T23:57:56.4711540Z /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/2.7.0/timeout.rb:33:in `catch'
2022-06-13T23:57:56.4712240Z /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/2.7.0/timeout.rb:33:in `catch'
2022-06-13T23:57:56.4712940Z /Users/runner/hostedtoolcache/Ruby/2.7.6/x64/lib/ruby/2.7.0/timeout.rb:110:in `timeout'
2022-06-13T23:57:56.4713660Z /Users/runner/work/fluentd/fluentd/test/plugin_helper/test_child_process.rb:339:in `block in <class:ChildProcessTest>'
2022-06-13T23:57:56.4714530Z <2> expected but was
2022-06-13T23:57:56.4715340Z <3>
```

To avoid it, check only 1st & 2nd elapsed time.

Signed-off-by: Takuro Ashie <ashie@clear-code.com>
  • Loading branch information
ashie committed Jun 15, 2022
1 parent 96baa73 commit 60417a9
Showing 1 changed file with 16 additions and 4 deletions.
20 changes: 16 additions & 4 deletions test/plugin_helper/test_child_process.rb
Expand Up @@ -321,28 +321,40 @@ def configure(conf)
ary = []
arguments = ["okay"]
Timeout.timeout(TEST_DEADLOCK_TIMEOUT) do
start_time = Fluent::Clock.now
@d.child_process_execute(:t5, "echo", arguments: arguments, interval: 1, mode: [:read]) do |io|
ary << io.read.split("\n").map(&:chomp).join
end
sleep 2.9 # 2sec(second invocation) + 0.9sec
1.upto(2) do |i|
sleep 0.1 while ary.size < i
elapsed = Fluent::Clock.now - start_time
assert_equal(i, ary.size)
assert_true(elapsed > i && elapsed < i + 0.5,
"actual elapsed: #{elapsed}")
end
assert_equal [], @d.log.out.logs
@d.stop
assert_equal [], @d.log.out.logs
@d.shutdown; @d.close; @d.terminate
assert_equal 2, ary.size
end
end

test 'can execute external command many times, with leading once executed immediately' do
ary = []
arguments = ["okay"]
Timeout.timeout(TEST_DEADLOCK_TIMEOUT) do
start_time = Fluent::Clock.now
@d.child_process_execute(:t6, "echo", arguments: arguments, interval: 1, immediate: true, mode: [:read]) do |io|
ary << io.read.split("\n").map(&:chomp).join
end
sleep 1.9 # 1sec(second invocation) + 0.9sec
0.upto(1) do |i|
sleep 0.1 while ary.size < i + 1
elapsed = Fluent::Clock.now - start_time
assert_equal(i + 1, ary.size)
assert_true(elapsed > i && elapsed < i + 0.5,
"actual elapsed: #{elapsed}")
end
@d.stop; @d.shutdown; @d.close; @d.terminate
assert_equal 2, ary.size
assert_equal [], @d.log.out.logs
end
end
Expand Down

0 comments on commit 60417a9

Please sign in to comment.