Output plugins sometimes drop all chunks without transition to secondary #2123

abicky · 2018-09-09T02:25:49Z

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
end

fluentd 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

The text was updated successfully, but these errors were encountered:

to avoid reaching the retry limit cf. fluent/fluentd#2123

repeatedly · 2018-09-12T03:58:02Z

Thanks for the report. Will check soon.

abicky · 2018-10-10T11:18:17Z

Do you have any progress? My colleague (@YAMASHITAHiroki) says he want to try to resolve this issue. If you don't have any plan to resolve this issue in the near future, I ask him to resolve it.

repeatedly · 2018-10-10T12:24:13Z

@abicky

he want to try to resolve this issue.

I'm currently busy for other issue and customer support so this is very helpful.

abicky · 2018-10-10T19:13:48Z

Ok, I'll ask him.

ali2992 · 2020-03-06T16:36:22Z

Any updates on this? I'm seeing this behaviour on fluentd 1.9.0

abicky · 2020-12-14T15:36:20Z

I took over this issue from my colleague, so I'll send a pull request.

@Retry

This commit resolves fluent#2123 by avoiding the situation when @Retry.step is called almost as many times as the number of flush threads in a short time.

@Retry

This commit resolves fluent#2123 by avoiding the situation when @Retry.step is called almost as many times as the number of flush threads in a short time.

@Retry

This commit resolves fluent#2123 by avoiding the situation when @Retry.step is called almost as many times as the number of flush threads in a short time.

@Retry

This commit resolves fluent#2123 by avoiding the situation when @Retry.step is called almost as many times as the number of flush threads in a short time.

@Retry

This commit resolves fluent#2123 by avoiding the situation when @Retry.step is called almost as many times as the number of flush threads in a short time. Signed-off-by: abicky <[email protected]>

abicky · 2020-12-14T19:49:05Z

I created a pull request #3203.

abicky added a commit to abicky/fluent-plugin-bigquery that referenced this issue Sep 9, 2018

Create a new table via insert_job in create_load_job

39df63c

to avoid reaching the retry limit cf. fluent/fluentd#2123

abicky added a commit to abicky/fluent-plugin-bigquery that referenced this issue Sep 9, 2018

Retry to insert after creating a new table

da35e19

to avoid reaching the retry limit cf. fluent/fluentd#2123

abicky added a commit to abicky/fluent-plugin-bigquery that referenced this issue Sep 9, 2018

Create a new table via insert_job in create_load_job

c2f9ea0

to avoid reaching the retry limit cf. fluent/fluentd#2123

abicky added a commit to abicky/fluent-plugin-bigquery that referenced this issue Sep 9, 2018

Retry to insert after creating a new table

57186c4

to avoid reaching the retry limit cf. fluent/fluentd#2123

abicky mentioned this issue Sep 9, 2018

Deprecate "table created" error fluent-plugins-nursery/fluent-plugin-bigquery#167

Merged

ganmacs added the bug Something isn't working label Jul 1, 2019

abicky mentioned this issue Dec 14, 2020

Prevent retry.step from being called too many times in a short time #3203

Merged

repeatedly closed this as completed in #3203 Dec 16, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Output plugins sometimes drop all chunks without transition to secondary #2123

Output plugins sometimes drop all chunks without transition to secondary #2123

abicky commented Sep 9, 2018 •

edited

Loading

repeatedly commented Sep 12, 2018

abicky commented Oct 10, 2018

repeatedly commented Oct 10, 2018

abicky commented Oct 10, 2018

ali2992 commented Mar 6, 2020

abicky commented Dec 14, 2020

abicky commented Dec 14, 2020

Output plugins sometimes drop all chunks without transition to secondary #2123

Output plugins sometimes drop all chunks without transition to secondary #2123

Comments

abicky commented Sep 9, 2018 • edited Loading

fluent.conf

out_sleep_and_fail.rb

fluentd diff for debug

Example logs

repeatedly commented Sep 12, 2018

abicky commented Oct 10, 2018

repeatedly commented Oct 10, 2018

abicky commented Oct 10, 2018

ali2992 commented Mar 6, 2020

abicky commented Dec 14, 2020

abicky commented Dec 14, 2020

abicky commented Sep 9, 2018 •

edited

Loading