From 2bfa8d8c41eca8df2608021c7b98e3a5b5e50e03 Mon Sep 17 00:00:00 2001 From: Takuro Ashie Date: Tue, 1 Mar 2022 10:07:08 +0900 Subject: [PATCH] retry_state: Fix wrong calcuration of interval The correct total retry time should be: c + c * b^1 + (...) + c*b^(k - 1) But the previous implementation was: c + c * b^0 + c * b^1 + (...) + c*b^(k - 1) where: * c: constant factor, @retry_wait * b: base factor, @retry_exponential_backoff_base * k: number of retry times, @max_retry_times Although the first retry interval is already added at constructor of ExponentialBackoffRetry, same value is added again unexpectedly on the first calc_interval call (as `c * b^0`). Signed-off-by: Takuro Ashie --- lib/fluent/plugin_helper/retry_state.rb | 8 +-- .../plugin/test_output_as_buffered_retries.rb | 4 +- test/plugin_helper/test_retry_state.rb | 61 +++++++++---------- 3 files changed, 35 insertions(+), 38 deletions(-) diff --git a/lib/fluent/plugin_helper/retry_state.rb b/lib/fluent/plugin_helper/retry_state.rb index 7851fd61ea..7a7f2b22ad 100644 --- a/lib/fluent/plugin_helper/retry_state.rb +++ b/lib/fluent/plugin_helper/retry_state.rb @@ -98,7 +98,7 @@ def calc_next_time naive end elsif @current == :secondary - naive = naive_next_time(@steps - @secondary_transition_steps + 1) + naive = naive_next_time(@steps - @secondary_transition_steps) if naive >= @timeout_at @timeout_at else @@ -159,13 +159,13 @@ def naive_next_time(retry_next_times) def calc_max_retry_timeout(max_steps) result = 0 max_steps.times { |i| - result += calc_interval(i + 1) + result += calc_interval(i) } result end def calc_interval(num) - interval = raw_interval(num - 1) + interval = raw_interval(num) if @max_interval && interval > @max_interval @max_interval else @@ -175,7 +175,7 @@ def calc_interval(num) # Calculate previous finite value to avoid inf related errors. If this re-computing is heavy, use cache. until interval.finite? num -= 1 - interval = raw_interval(num - 1) + interval = raw_interval(num) end interval end diff --git a/test/plugin/test_output_as_buffered_retries.rb b/test/plugin/test_output_as_buffered_retries.rb index f3a08e877f..3954513795 100644 --- a/test/plugin/test_output_as_buffered_retries.rb +++ b/test/plugin/test_output_as_buffered_retries.rb @@ -140,13 +140,13 @@ def get_log_time(msg, logs) retry_state = @i.retry_state( @i.buffer_config.retry_randomize ) retry_state.step - assert_equal 1, (retry_state.next_time - now) - retry_state.step assert_equal (1 * (2 ** 1)), (retry_state.next_time - now) retry_state.step assert_equal (1 * (2 ** 2)), (retry_state.next_time - now) retry_state.step assert_equal (1 * (2 ** 3)), (retry_state.next_time - now) + retry_state.step + assert_equal (1 * (2 ** 4)), (retry_state.next_time - now) end test 'does retries correctly when #write fails' do diff --git a/test/plugin_helper/test_retry_state.rb b/test/plugin_helper/test_retry_state.rb index 4edd41bdf9..a6cd7300dc 100644 --- a/test/plugin_helper/test_retry_state.rb +++ b/test/plugin_helper/test_retry_state.rb @@ -202,7 +202,7 @@ class Dummy < Fluent::Plugin::TestBase while i < 300 s.step assert_equal i, s.steps - assert_equal (dummy_current_time + 0.1 * (2 ** (i - 1))), s.next_time + assert_equal (dummy_current_time + 0.1 * (2 ** i)), s.next_time assert !s.limit? i += 1 end @@ -218,22 +218,22 @@ class Dummy < Fluent::Plugin::TestBase assert_equal 0, s.steps assert_equal (dummy_current_time + 0.1), s.next_time - # 0.1 * (2 ** (10 - 1)) == 0.1 * 2 ** 9 == 51.2 - # 0.1 * (2 ** (11 - 1)) == 0.1 * 2 ** 10 == 102.4 + # 0.1 * 2 ** 9 == 51.2 + # 0.1 * 2 ** 10 == 102.4 i = 1 - while i < 11 + while i < 10 s.step assert_equal i, s.steps - assert_equal (dummy_current_time + 0.1 * (2 ** (i - 1))), s.next_time, "start:#{dummy_current_time}, i:#{i}" + assert_equal (dummy_current_time + 0.1 * (2 ** i)), s.next_time, "start:#{dummy_current_time}, i:#{i}" i += 1 end s.step - assert_equal 11, s.steps + assert_equal 10, s.steps assert_equal (dummy_current_time + 100), s.next_time s.step - assert_equal 12, s.steps + assert_equal 11, s.steps assert_equal (dummy_current_time + 100), s.next_time end @@ -249,30 +249,25 @@ class Dummy < Fluent::Plugin::TestBase assert_equal 0, s.steps assert_equal (dummy_current_time + 1), s.next_time - # 1 + 1 + 2 + 4 (=8) + # 1 + 2 + 4 (=7) override_current_time(s, s.next_time) s.step assert_equal 1, s.steps - assert_equal (s.current_time + 1), s.next_time - - override_current_time(s, s.next_time) - s.step - assert_equal 2, s.steps assert_equal (s.current_time + 2), s.next_time override_current_time(s, s.next_time) s.step - assert_equal 3, s.steps + assert_equal 2, s.steps assert_equal (s.current_time + 4), s.next_time assert !s.limit? - # + 8 (=16) > 12 + # + 8 (=15) > 12 override_current_time(s, s.next_time) s.step - assert_equal 4, s.steps + assert_equal 3, s.steps assert_equal s.timeout_at, s.next_time assert s.limit? @@ -293,24 +288,24 @@ class Dummy < Fluent::Plugin::TestBase override_current_time(s, s.next_time) s.step assert_equal 1, s.steps - assert_equal (s.current_time + 1), s.next_time + assert_equal (s.current_time + 2), s.next_time override_current_time(s, s.next_time) s.step assert_equal 2, s.steps - assert_equal (s.current_time + 2), s.next_time + assert_equal (s.current_time + 4), s.next_time override_current_time(s, s.next_time) s.step assert_equal 3, s.steps - assert_equal (s.current_time + 4), s.next_time + assert_equal (s.current_time + 8), s.next_time assert !s.limit? override_current_time(s, s.next_time) s.step assert_equal 4, s.steps - assert_equal (s.current_time + 8), s.next_time + assert_equal (s.current_time + 10), s.next_time assert !s.limit? @@ -341,40 +336,42 @@ class Dummy < Fluent::Plugin::TestBase assert_equal (dummy_current_time + 1), s.next_time assert !s.secondary? - # 1, 1(2), 2(4), 4(8), 8(16), 16(32), 32(64), (80), (81), (83), (87), (95), (100) + # primary: 3, 7, 15, 31, 63, 80 (timeout * threashold) + # secondary: 81, 83, 87, 95, 100 i = 1 - while i < 7 + while i < 6 override_current_time(s, s.next_time) assert !s.secondary? s.step assert_equal i, s.steps - assert_equal (s.current_time + 1 * (2 ** (i - 1))), s.next_time + assert_equal (s.current_time + 1 * (2 ** i)), s.next_time assert !s.limit? i += 1 end - assert_equal 7, i - override_current_time(s, s.next_time) # 64 + assert_equal 6, i + override_current_time(s, s.next_time) # 63 assert !s.secondary? s.step - assert_equal 7, s.steps + assert_equal 6, s.steps assert_equal s.secondary_transition_at, s.next_time assert !s.limit? i += 1 - assert_equal 8, i + assert_equal 7, i override_current_time(s, s.next_time) # 80 assert s.secondary? s.step - assert_equal 8, s.steps + assert_equal 7, s.steps assert_equal s.steps, s.secondary_transition_steps - assert_equal (s.secondary_transition_at + 1.0), s.next_time + assert_equal (s.secondary_transition_at + 1.0), s.next_time # 81 assert !s.limit? + assert_equal :secondary, s.current - # 81, 82, 84, 88, 96, 100 + # 83, 87, 95, 100 j = 1 while j < 4 override_current_time(s, s.next_time) @@ -382,14 +379,14 @@ class Dummy < Fluent::Plugin::TestBase assert_equal :secondary, s.current s.step - assert_equal (8 + j), s.steps + assert_equal (7 + j), s.steps assert_equal (s.current_time + (1 * (2 ** j))), s.next_time assert !s.limit?, "j:#{j}" j += 1 end assert_equal 4, j - override_current_time(s, s.next_time) # 96 + override_current_time(s, s.next_time) # 95 assert s.secondary? s.step