From 60417a9b2c6db53568b37c4c168e9781163ee72f Mon Sep 17 00:00:00 2001 From: Takuro Ashie Date: Wed, 15 Jun 2022 16:51:41 +0900 Subject: [PATCH] test_child_process: Try to fix unstable tests 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 ' 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 ' 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 --- test/plugin_helper/test_child_process.rb | 20 ++++++++++++++++---- 1 file changed, 16 insertions(+), 4 deletions(-) diff --git a/test/plugin_helper/test_child_process.rb b/test/plugin_helper/test_child_process.rb index 278b36178e..67eef96afb 100644 --- a/test/plugin_helper/test_child_process.rb +++ b/test/plugin_helper/test_child_process.rb @@ -321,15 +321,21 @@ 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 @@ -337,12 +343,18 @@ def configure(conf) 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