Output plugins sometimes drop all chunks without transition to secondary, in other words, before @secondary_transition_at of RetryState if flush_thread_count is a little large.
I think this is not expected behavior.
My environment is here:
- fluentd version: v1.2.5 (33fe27e)
- OS: macOS 10.13.6
I describe a simple example to reproduce the issue blow.
fluent.conf
<source>
@type dummy
auto_increment_key id
tag dummy
</source>
<match dummy.**>
@type sleep_and_fail # the definition is described later
<buffer id>
flush_thread_count 10
flush_mode interval
flush_interval 15
retry_max_times 15
</buffer>
<secondary>
@type file
path /tmp/log/fluentd-${id}
</secondary>
</match>
out_sleep_and_fail.rb
require 'fluent/plugin/output'
module Fluent::Plugin
class SleepAndFailOutput < Output
Fluent::Plugin.register_output('sleep_and_fail', self)
def write(chunk)
sleep 5
raise "error"
end
end
endfluentd diff for debug
diff --git a/lib/fluent/plugin/output.rb b/lib/fluent/plugin/output.rb
index 7d70098f..e4daeff3 100644
--- a/lib/fluent/plugin/output.rb
+++ b/lib/fluent/plugin/output.rb
@@ -1072,8 +1072,11 @@ module Fluent
def try_flush
chunk = @buffer.dequeue_chunk
- return unless chunk
-
+ unless chunk
+ log.info "#{::Thread.current[:_fluentd_plugin_helper_thread_title]} no chunk found"
+ return
+ end
+ log.info "#{::Thread.current[:_fluentd_plugin_helper_thread_title]} try_flush", chunK: dump_unique_id_hex(chunk.unique_id)
log.on_trace { log.trace "trying flush for a chunk", chunk: dump_unique_id_hex(chunk.unique_id) }
output = self
@@ -1385,6 +1388,7 @@ module Fluent
interval = state.next_clock - current_clock
elsif next_retry_time && next_retry_time > Time.now
interval = next_retry_time.to_f - Time.now.to_f
+ log.info "#{::Thread.current[:_fluentd_plugin_helper_thread_title]} next_retry_time is #{next_retry_time} and set interval to #{interval}"
else
try_flush
Example logs
We can receive a message like below and the message indicates the secondary is not used.
failed to flush the buffer, and hit limit for retries. dropping all chunks in the buffer queue. retry_times=15 records=144 error_class=RuntimeError error="error"
% bundle exec ./bin/fluentd -c /path/to/fluent.conf
2018-09-09 11:04:04 +0900 [info]: parsing config file is succeeded path="fluent.conf"
2018-09-09 11:04:04 +0900 [warn]: secondary type should be same with primary one primary="Fluent::Plugin::SleepAndFailOutput" secondary="Fluent::Plugin::FileOutput"
2018-09-09 11:04:04 +0900 [warn]: both of Plugin @id and path for <storage> are not specified. Using on-memory store.
2018-09-09 11:04:04 +0900 [warn]: both of Plugin @id and path for <storage> are not specified. Using on-memory store.
2018-09-09 11:04:04 +0900 [info]: using configuration file: <ROOT>
<source>
@type dummy
auto_increment_key "id"
tag "dummy"
</source>
<match dummy.**>
@type sleep_and_fail
<buffer id>
flush_thread_count 10
flush_mode interval
flush_interval 15
retry_max_times 15
</buffer>
<secondary>
@type "file"
path "/tmp/log/fluentd-${id}"
<buffer time>
path /tmp/log/fluentd-${id}
</buffer>
</secondary>
</match>
</ROOT>
2018-09-09 11:04:04 +0900 [info]: starting fluentd-1.2.5 pid=6640 ruby="2.4.2"
2018-09-09 11:04:04 +0900 [info]: spawn command to main: cmdline=["/Users/arabiki/.anyenv/envs/rbenv/versions/2.4.2/bin/ruby", "-Eascii-8bit:ascii-8bit", "-rbundler/setup", "./bin/fluentd", "-c", "fluent.conf", "--under-supervisor"]
2018-09-09 11:04:05 +0900 [info]: gem 'fluentd' version '1.2.5'
2018-09-09 11:04:05 +0900 [info]: adding match pattern="dummy.**" type="sleep_and_fail"
2018-09-09 11:04:05 +0900 [warn]: #0 secondary type should be same with primary one primary="Fluent::Plugin::SleepAndFailOutput" secondary="Fluent::Plugin::FileOutput"
2018-09-09 11:04:05 +0900 [info]: adding source type="dummy"
2018-09-09 11:04:05 +0900 [warn]: #0 both of Plugin @id and path for <storage> are not specified. Using on-memory store.
2018-09-09 11:04:05 +0900 [warn]: #0 both of Plugin @id and path for <storage> are not specified. Using on-memory store.
2018-09-09 11:04:05 +0900 [info]: #0 starting fluentd worker pid=6673 ppid=6640 worker=0
2018-09-09 11:04:05 +0900 [info]: #0 fluentd worker is now running worker=0
2018-09-09 11:04:06 +0900 [info]: #0 flush_thread_0 no chunk found
(snip)
2018-09-09 11:04:21 +0900 [info]: #0 flush_thread_5 no chunk found
2018-09-09 11:04:22 +0900 [info]: #0 flush_thread_2 try_flush chunK="57566a7cf162bbf8f667ad51a5202c20"
2018-09-09 11:04:22 +0900 [info]: #0 flush_thread_4 try_flush chunK="57566a7ded0b78c838eb46567149dc4a"
2018-09-09 11:04:22 +0900 [info]: #0 flush_thread_8 no chunk found
2018-09-09 11:04:22 +0900 [info]: #0 flush_thread_9 no chunk found
2018-09-09 11:04:22 +0900 [info]: #0 flush_thread_3 no chunk found
2018-09-09 11:04:22 +0900 [info]: #0 flush_thread_1 no chunk found
2018-09-09 11:04:22 +0900 [info]: #0 flush_thread_0 no chunk found
2018-09-09 11:04:22 +0900 [info]: #0 flush_thread_6 no chunk found
2018-09-09 11:04:22 +0900 [info]: #0 flush_thread_7 no chunk found
2018-09-09 11:04:22 +0900 [info]: #0 flush_thread_5 no chunk found
2018-09-09 11:04:23 +0900 [info]: #0 flush_thread_8 try_flush chunK="57566a7ee9b79f4b82e2e77d5a36df48"
2018-09-09 11:04:23 +0900 [info]: #0 flush_thread_3 no chunk found
2018-09-09 11:04:23 +0900 [info]: #0 flush_thread_1 no chunk found
2018-09-09 11:04:23 +0900 [info]: #0 flush_thread_9 no chunk found
2018-09-09 11:04:23 +0900 [info]: #0 flush_thread_0 no chunk found
2018-09-09 11:04:23 +0900 [info]: #0 flush_thread_6 no chunk found
2018-09-09 11:04:23 +0900 [info]: #0 flush_thread_7 no chunk found
2018-09-09 11:04:23 +0900 [info]: #0 flush_thread_5 no chunk found
2018-09-09 11:04:24 +0900 [info]: #0 flush_thread_3 no chunk found
2018-09-09 11:04:24 +0900 [info]: #0 flush_thread_9 no chunk found
2018-09-09 11:04:24 +0900 [info]: #0 flush_thread_0 no chunk found
2018-09-09 11:04:24 +0900 [info]: #0 flush_thread_6 no chunk found
2018-09-09 11:04:24 +0900 [info]: #0 flush_thread_1 no chunk found
2018-09-09 11:04:24 +0900 [info]: #0 flush_thread_7 no chunk found
2018-09-09 11:04:24 +0900 [info]: #0 flush_thread_5 no chunk found
2018-09-09 11:04:25 +0900 [info]: #0 flush_thread_1 try_flush chunK="57566a7fce43c8bd6c27366dc1bceb31"
2018-09-09 11:04:25 +0900 [info]: #0 flush_thread_0 no chunk found
2018-09-09 11:04:25 +0900 [info]: #0 flush_thread_6 no chunk found
2018-09-09 11:04:25 +0900 [info]: #0 flush_thread_5 no chunk found
2018-09-09 11:04:25 +0900 [info]: #0 flush_thread_3 no chunk found
2018-09-09 11:04:25 +0900 [info]: #0 flush_thread_7 no chunk found
2018-09-09 11:04:25 +0900 [info]: #0 flush_thread_9 no chunk found
2018-09-09 11:04:26 +0900 [info]: #0 flush_thread_5 try_flush chunK="57566a80c8fa5754e44f9ce0be5c63d5"
2018-09-09 11:04:26 +0900 [info]: #0 flush_thread_3 try_flush chunK="57566a81c5d75d43565b4fbdf3682c40"
2018-09-09 11:04:26 +0900 [info]: #0 flush_thread_7 no chunk found
2018-09-09 11:04:26 +0900 [info]: #0 flush_thread_9 no chunk found
2018-09-09 11:04:26 +0900 [info]: #0 flush_thread_6 no chunk found
2018-09-09 11:04:26 +0900 [info]: #0 flush_thread_0 no chunk found
2018-09-09 11:04:27 +0900 [warn]: #0 failed to flush the buffer. retry_time=0 next_retry_seconds=2018-09-09 11:04:28 +0900 chunk="57566a7cf162bbf8f667ad51a5202c20" error_class=RuntimeError error="error"
2018-09-09 11:04:27 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/out_sleep_and_fail.rb:9:in `write'
2018-09-09 11:04:27 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1113:in `try_flush'
2018-09-09 11:04:27 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1393:in `flush_thread_run'
2018-09-09 11:04:27 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:444:in `block (2 levels) in start'
2018-09-09 11:04:27 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2018-09-09 11:04:27 +0900 [warn]: #0 failed to flush the buffer. retry_time=0 next_retry_seconds=2018-09-09 11:04:28 +0900 chunk="57566a7ded0b78c838eb46567149dc4a" error_class=RuntimeError error="error"
2018-09-09 11:04:27 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/out_sleep_and_fail.rb:9:in `write'
2018-09-09 11:04:27 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1113:in `try_flush'
2018-09-09 11:04:27 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1393:in `flush_thread_run'
2018-09-09 11:04:27 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:444:in `block (2 levels) in start'
2018-09-09 11:04:27 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2018-09-09 11:04:27 +0900 [info]: #0 flush_thread_9 next_retry_time is 2018-09-09 11:04:28 +0900 and set interval to 0.899587869644165
2018-09-09 11:04:27 +0900 [info]: #0 flush_thread_7 next_retry_time is 2018-09-09 11:04:28 +0900 and set interval to 0.8983850479125977
2018-09-09 11:04:27 +0900 [info]: #0 flush_thread_6 next_retry_time is 2018-09-09 11:04:28 +0900 and set interval to 0.8982276916503906
2018-09-09 11:04:27 +0900 [info]: #0 flush_thread_0 next_retry_time is 2018-09-09 11:04:28 +0900 and set interval to 0.897918701171875
2018-09-09 11:04:28 +0900 [info]: #0 flush_thread_0 try_flush chunK="57566a7cf162bbf8f667ad51a5202c20"
2018-09-09 11:04:28 +0900 [info]: #0 flush_thread_6 try_flush chunK="57566a82aa4e81960c3b280243f6d356"
2018-09-09 11:04:28 +0900 [info]: #0 flush_thread_7 no chunk found
2018-09-09 11:04:28 +0900 [info]: #0 flush_thread_4 try_flush chunK="57566a7ded0b78c838eb46567149dc4a"
2018-09-09 11:04:28 +0900 [info]: #0 flush_thread_9 no chunk found
2018-09-09 11:04:28 +0900 [info]: #0 flush_thread_2 no chunk found
2018-09-09 11:04:28 +0900 [warn]: #0 failed to flush the buffer. retry_time=1 next_retry_seconds=2018-09-09 11:04:28 +0900 chunk="57566a7ee9b79f4b82e2e77d5a36df48" error_class=RuntimeError error="error"
2018-09-09 11:04:28 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/out_sleep_and_fail.rb:9:in `write'
2018-09-09 11:04:28 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1113:in `try_flush'
2018-09-09 11:04:28 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1393:in `flush_thread_run'
2018-09-09 11:04:28 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:444:in `block (2 levels) in start'
2018-09-09 11:04:28 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2018-09-09 11:04:29 +0900 [info]: #0 flush_thread_7 next_retry_time is 2018-09-09 11:04:30 +0900 and set interval to 1.1657297611236572
2018-09-09 11:04:29 +0900 [info]: #0 flush_thread_9 next_retry_time is 2018-09-09 11:04:30 +0900 and set interval to 1.1653547286987305
2018-09-09 11:04:29 +0900 [info]: #0 flush_thread_2 next_retry_time is 2018-09-09 11:04:30 +0900 and set interval to 1.0875165462493896
2018-09-09 11:04:30 +0900 [warn]: #0 failed to flush the buffer. retry_time=2 next_retry_seconds=2018-09-09 11:04:30 +0900 chunk="57566a7fce43c8bd6c27366dc1bceb31" error_class=RuntimeError error="error"
2018-09-09 11:04:30 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/out_sleep_and_fail.rb:9:in `write'
2018-09-09 11:04:30 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1113:in `try_flush'
2018-09-09 11:04:30 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1393:in `flush_thread_run'
2018-09-09 11:04:30 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:444:in `block (2 levels) in start'
2018-09-09 11:04:30 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2018-09-09 11:04:30 +0900 [info]: #0 flush_thread_9 next_retry_time is 2018-09-09 11:04:34 +0900 and set interval to 3.070816993713379
2018-09-09 11:04:30 +0900 [info]: #0 flush_thread_8 next_retry_time is 2018-09-09 11:04:34 +0900 and set interval to 3.0705909729003906
2018-09-09 11:04:30 +0900 [info]: #0 flush_thread_2 next_retry_time is 2018-09-09 11:04:34 +0900 and set interval to 3.0708751678466797
2018-09-09 11:04:30 +0900 [info]: #0 flush_thread_7 next_retry_time is 2018-09-09 11:04:34 +0900 and set interval to 3.0694739818573
2018-09-09 11:04:31 +0900 [warn]: #0 failed to flush the buffer. retry_time=3 next_retry_seconds=2018-09-09 11:04:34 +0900 chunk="57566a81c5d75d43565b4fbdf3682c40" error_class=RuntimeError error="error"
2018-09-09 11:04:31 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/out_sleep_and_fail.rb:9:in `write'
2018-09-09 11:04:31 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1113:in `try_flush'
2018-09-09 11:04:31 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1393:in `flush_thread_run'
2018-09-09 11:04:31 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:444:in `block (2 levels) in start'
2018-09-09 11:04:31 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2018-09-09 11:04:31 +0900 [warn]: #0 failed to flush the buffer. retry_time=4 next_retry_seconds=2018-09-09 11:04:39 +0900 chunk="57566a80c8fa5754e44f9ce0be5c63d5" error_class=RuntimeError error="error"
2018-09-09 11:04:31 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/out_sleep_and_fail.rb:9:in `write'
2018-09-09 11:04:31 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1113:in `try_flush'
2018-09-09 11:04:31 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1393:in `flush_thread_run'
2018-09-09 11:04:31 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:444:in `block (2 levels) in start'
2018-09-09 11:04:31 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2018-09-09 11:04:33 +0900 [warn]: #0 failed to flush the buffer. retry_time=5 next_retry_seconds=2018-09-09 11:04:49 +0900 chunk="57566a7cf162bbf8f667ad51a5202c20" error_class=RuntimeError error="error"
2018-09-09 11:04:33 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/out_sleep_and_fail.rb:9:in `write'
2018-09-09 11:04:33 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1113:in `try_flush'
2018-09-09 11:04:33 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1393:in `flush_thread_run'
2018-09-09 11:04:33 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:444:in `block (2 levels) in start'
2018-09-09 11:04:33 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2018-09-09 11:04:33 +0900 [warn]: #0 failed to flush the buffer. retry_time=6 next_retry_seconds=2018-09-09 11:05:07 +0900 chunk="57566a82aa4e81960c3b280243f6d356" error_class=RuntimeError error="error"
2018-09-09 11:04:33 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/out_sleep_and_fail.rb:9:in `write'
2018-09-09 11:04:33 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1113:in `try_flush'
2018-09-09 11:04:33 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1393:in `flush_thread_run'
2018-09-09 11:04:33 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:444:in `block (2 levels) in start'
2018-09-09 11:04:33 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2018-09-09 11:04:33 +0900 [warn]: #0 failed to flush the buffer. retry_time=7 next_retry_seconds=2018-09-09 11:05:33 +0900 chunk="57566a7ded0b78c838eb46567149dc4a" error_class=RuntimeError error="error"
2018-09-09 11:04:33 +0900 [warn]: #0 suppressed same stacktrace
2018-09-09 11:04:34 +0900 [info]: #0 flush_thread_8 next_retry_time is 2018-09-09 11:06:39 +0900 and set interval to 125.85099935531616
2018-09-09 11:04:34 +0900 [info]: #0 flush_thread_9 next_retry_time is 2018-09-09 11:06:39 +0900 and set interval to 125.85086727142334
2018-09-09 11:04:34 +0900 [info]: #0 flush_thread_2 next_retry_time is 2018-09-09 11:06:39 +0900 and set interval to 125.85073828697205
2018-09-09 11:04:34 +0900 [info]: #0 flush_thread_1 next_retry_time is 2018-09-09 11:06:39 +0900 and set interval to 125.8511872291565
2018-09-09 11:04:34 +0900 [info]: #0 flush_thread_7 next_retry_time is 2018-09-09 11:06:39 +0900 and set interval to 125.85045742988586
2018-09-09 11:04:39 +0900 [info]: #0 flush_thread_3 next_retry_time is 2018-09-09 11:06:39 +0900 and set interval to 119.91533041000366
2018-09-09 11:04:49 +0900 [info]: #0 flush_thread_5 next_retry_time is 2018-09-09 11:06:39 +0900 and set interval to 110.59803819656372
2018-09-09 11:05:07 +0900 [info]: #0 flush_thread_0 next_retry_time is 2018-09-09 11:06:39 +0900 and set interval to 92.13840818405151
2018-09-09 11:05:33 +0900 [info]: #0 flush_thread_6 next_retry_time is 2018-09-09 11:06:39 +0900 and set interval to 66.30322027206421
2018-09-09 11:06:39 +0900 [info]: #0 flush_thread_6 try_flush chunK="57566a7ded0b78c838eb46567149dc4a"
2018-09-09 11:06:39 +0900 [info]: #0 flush_thread_0 try_flush chunK="57566a82aa4e81960c3b280243f6d356"
2018-09-09 11:06:39 +0900 [info]: #0 flush_thread_3 try_flush chunK="57566a7cf162bbf8f667ad51a5202c20"
2018-09-09 11:06:39 +0900 [info]: #0 flush_thread_5 try_flush chunK="57566a81c5d75d43565b4fbdf3682c40"
2018-09-09 11:06:39 +0900 [info]: #0 flush_thread_4 try_flush chunK="57566a80c8fa5754e44f9ce0be5c63d5"
2018-09-09 11:06:39 +0900 [info]: #0 flush_thread_8 try_flush chunK="57566a7fce43c8bd6c27366dc1bceb31"
2018-09-09 11:06:39 +0900 [info]: #0 flush_thread_1 try_flush chunK="57566a7ee9b79f4b82e2e77d5a36df48"
2018-09-09 11:06:39 +0900 [info]: #0 flush_thread_2 try_flush chunK="57566a83a83f91f9aca2c29397c26d63"
2018-09-09 11:06:39 +0900 [info]: #0 flush_thread_9 try_flush chunK="57566a848a4aa0ff368dfca1bf6b2be2"
2018-09-09 11:06:39 +0900 [info]: #0 flush_thread_7 try_flush chunK="57566a8585199f235a2fbba76042cf0d"
2018-09-09 11:06:44 +0900 [warn]: #0 failed to flush the buffer. retry_time=8 next_retry_seconds=2018-09-09 11:06:39 +0900 chunk="57566a7ded0b78c838eb46567149dc4a" error_class=RuntimeError error="error"
2018-09-09 11:06:44 +0900 [warn]: #0 suppressed same stacktrace
2018-09-09 11:06:44 +0900 [warn]: #0 failed to flush the buffer. retry_time=9 next_retry_seconds=2018-09-09 11:11:07 +0900 chunk="57566a82aa4e81960c3b280243f6d356" error_class=RuntimeError error="error"
2018-09-09 11:06:44 +0900 [warn]: #0 suppressed same stacktrace
2018-09-09 11:06:44 +0900 [warn]: #0 failed to flush the buffer. retry_time=10 next_retry_seconds=2018-09-09 11:15:23 +0900 chunk="57566a7cf162bbf8f667ad51a5202c20" error_class=RuntimeError error="error"
2018-09-09 11:06:44 +0900 [warn]: #0 suppressed same stacktrace
2018-09-09 11:06:44 +0900 [warn]: #0 failed to flush the buffer. retry_time=11 next_retry_seconds=2018-09-09 11:25:10 +0900 chunk="57566a81c5d75d43565b4fbdf3682c40" error_class=RuntimeError error="error"
2018-09-09 11:06:44 +0900 [warn]: #0 suppressed same stacktrace
2018-09-09 11:06:44 +0900 [warn]: #0 failed to flush the buffer. retry_time=12 next_retry_seconds=2018-09-09 11:37:47 +0900 chunk="57566a7fce43c8bd6c27366dc1bceb31" error_class=RuntimeError error="error"
2018-09-09 11:06:44 +0900 [warn]: #0 suppressed same stacktrace
2018-09-09 11:06:44 +0900 [warn]: #0 failed to flush the buffer. retry_time=13 next_retry_seconds=2018-09-09 12:22:43 +0900 chunk="57566a848a4aa0ff368dfca1bf6b2be2" error_class=RuntimeError error="error"
2018-09-09 11:06:44 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/out_sleep_and_fail.rb:9:in `write'
2018-09-09 11:06:44 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1113:in `try_flush'
2018-09-09 11:06:44 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1393:in `flush_thread_run'
2018-09-09 11:06:44 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:444:in `block (2 levels) in start'
2018-09-09 11:06:44 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2018-09-09 11:06:44 +0900 [warn]: #0 failed to flush the buffer. retry_time=14 next_retry_seconds=2018-09-09 13:36:36 +0900 chunk="57566a8585199f235a2fbba76042cf0d" error_class=RuntimeError error="error"
2018-09-09 11:06:44 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/out_sleep_and_fail.rb:9:in `write'
2018-09-09 11:06:44 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1113:in `try_flush'
2018-09-09 11:06:44 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1393:in `flush_thread_run'
2018-09-09 11:06:44 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:444:in `block (2 levels) in start'
2018-09-09 11:06:44 +0900 [warn]: #0 /Users/arabiki/ghq/src/github.com/fluent/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2018-09-09 11:06:44 +0900 [error]: #0 failed to flush the buffer, and hit limit for retries. dropping all chunks in the buffer queue. retry_times=15 records=144 error_class=RuntimeError error="error"
2018-09-09 11:06:44 +0900 [error]: #0 suppressed same stacktrace
Output plugins sometimes drop all chunks without transition to secondary, in other words, before
@secondary_transition_atofRetryStateifflush_thread_countis a little large.I think this is not expected behavior.
My environment is here:
I describe a simple example to reproduce the issue blow.
fluent.conf
out_sleep_and_fail.rb
fluentd diff for debug
Example logs
We can receive a message like below and the message indicates the secondary is not used.