v0.14 call write before start finished in BufferedOutputPlugin

[mia-0032]

Fluentd v0.14 call write before start finished in BufferedOutputPlugin.
This problem occurs if start method processing time is longer than try_flush_interval and buffer exist Fluentd started.
But the problem occurs not always... another trigger may exist.

• fluentd or td-agent version.

fluentd master branch ( 1f7719e ) and v0.14.2 tag

• Environment information, e.g. OS.

OSX 10.11.6

• Your configuration

<source>
  @type dummy
  tag test
  dummy {"hello":"world"}
</source>

<match test>
  @type test
  buffer_type file
  buffer_path /path/to/fluentd/fluentd/buffer/
  flush_at_shutdown false
  try_flush_interval 0.5
</match>

• Your problem explanation. If you have an error logs, write it together.

I checked writing below plugin.

require 'fluent/output'

module Fluent
  class TestOutputError < StandardError
  end

  class TestOutput < BufferedOutput
    Fluent::Plugin.register_output('test', self)

    config_param :format, :string,  :default => 'json'

    def configure(conf)
      super
      @formatter = Plugin.new_formatter(@format)
      @formatter.configure(conf)
      @has_started = false
    end

    def start
      super
      sleep(3)
      @has_started = true
    end

    def format(tag, time, record)
      @formatter.format(tag, time, record)
    end

    def write(chunk)
      unless @has_started
        raise Fluent::TestOutputError.new 'start method has not been called.'
      end
      chunk.write_to($log)
    end
  end
end

Error message:

$ bundle exec fluentd -c test-fluent.conf -vv
2016-08-27 16:45:13 +0900 [info]: fluent/supervisor.rb:583:read_config: reading config file path="test-fluent.conf"
2016-08-27 16:45:13 +0900 [info]: fluent/supervisor.rb:459:supervise: starting fluentd-0.14.2
2016-08-27 16:45:13 +0900 [info]: fluent/supervisor.rb:480:supervise: spawn command to main: /path/to/.rbenv/versions/2.3.1/bin/ruby -Eascii-8bit:ascii-8bit  -rbundler/setup /path/to/fluentd/fluentd/vendor/bundle/ruby/2.3.0/bin/fluentd -c test-fluent.conf -vv --under-supervisor
2016-08-27 16:45:13 +0900 [info]: fluent/supervisor.rb:583:read_config: reading config file path="test-fluent.conf"
2016-08-27 16:45:13 +0900 [info]: fluent/supervisor.rb:402:run_worker: starting fluentd-0.14.2 without supervision
2016-08-27 16:45:13 +0900 [info]: fluent/engine.rb:116:block in configure: gem 'fluentd' version '0.14.2'
2016-08-27 16:45:13 +0900 [info]: fluent/agent.rb:131:add_match: adding match pattern="test" type="test"
2016-08-27 16:45:13 +0900 [trace]: fluent/plugin.rb:140:register_impl: registered output plugin 'test'
2016-08-27 16:45:13 +0900 [trace]: fluent/plugin.rb:140:register_impl: registered buffer plugin 'file'
2016-08-27 16:45:13 +0900 [trace]: fluent/plugin.rb:140:register_impl: registered formatter plugin 'json'
2016-08-27 16:45:13 +0900 [info]: fluent/root_agent.rb:227:add_source: adding source type="dummy"
2016-08-27 16:45:13 +0900 [trace]: fluent/plugin.rb:140:register_impl: registered input plugin 'dummy'
2016-08-27 16:45:13 +0900 [trace]: fluent/plugin.rb:140:register_impl: registered storage plugin 'local'
2016-08-27 16:45:13 +0900 [warn]: plugin/storage_local.rb:34:configure: both of Plugin @id and path for <storage> are not specified. Using on-memory store.
2016-08-27 16:45:13 +0900 [info]: fluent/engine.rb:123:configure: using configuration file: <ROOT>
  <source>
    @type dummy
    tag "test"
    dummy {"hello":"world"}
  </source>
  <match test>
    @type test
    buffer_type "file"
    buffer_path /path/to/fluentd/fluentd/buffer/
    flush_at_shutdown false
    try_flush_interval 0.5
    <buffer>
      flush_mode interval
      retry_type exponential_backoff
      @type file
      path /path/to/fluentd/fluentd/buffer/
      flush_thread_interval 0.5
      flush_at_shutdown false
    </buffer>
  </match>
</ROOT>
2016-08-27 16:45:13 +0900 [debug]: plugin/buffer.rb:107:start: buffer started instance=70334821550100 stage_size=0 queue_size=378
2016-08-27 16:45:13 +0900 [debug]: plugin/buffer.rb:336:enqueue_all: enqueueing all chunks in buffer instance=70334821550100
2016-08-27 16:45:14 +0900 [debug]: plugin/buffer.rb:354:dequeue_chunk: dequeueing a chunk instance=70334821550100
2016-08-27 16:45:14 +0900 [debug]: plugin/buffer.rb:363:block in dequeue_chunk: chunk dequeued instance=70334821550100 metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=nil, tag=nil, variables=nil>
2016-08-27 16:45:14 +0900 [debug]: plugin/output.rb:774:try_flush: trying flush for a chunk chunk="53b08c972f9869fbe71701e2756221a3"
2016-08-27 16:45:14 +0900 [trace]: plugin/output.rb:799:try_flush: adding write count instance=70334822080460
2016-08-27 16:45:14 +0900 [trace]: plugin/output.rb:801:try_flush: executing sync write chunk="53b08c972f9869fbe71701e2756221a3"
2016-08-27 16:45:14 +0900 [debug]: plugin/output.rb:808:rescue in try_flush: taking back chunk for errors. plugin_id="object:3ff81a15dfcc" chunk="53b08c972f9869fbe71701e2756221a3"
2016-08-27 16:45:14 +0900 [debug]: plugin/buffer.rb:369:takeback_chunk: taking back a chunk instance=70334821550100 chunk_id="53b08c972f9869fbe71701e2756221a3"
2016-08-27 16:45:14 +0900 [debug]: plugin/buffer.rb:374:block in takeback_chunk: chunk taken back instance=70334821550100 chunk_id="53b08c972f9869fbe71701e2756221a3" metadata=#<struct Fluent::Plugin::Buffer::Metadata timekey=nil, tag=nil, variables=nil>
2016-08-27 16:45:14 +0900 [warn]: plugin/output.rb:834:block in try_flush: failed to flush the buffer. plugin_id="object:3ff81a15dfcc" retry_time=0 next_retry=2016-08-27 16:45:15 +0900 chunk="53b08c972f9869fbe71701e2756221a3" error_class=Fluent::TestOutputError error="start method has not been called."
  2016-08-27 16:45:14 +0900 [warn]: plugin/output.rb:787:try_flush: /path/to/fluentd/fluentd/lib/fluent/plugin/out_test.rb:31:in `write'
  2016-08-27 16:45:14 +0900 [warn]: plugin/output.rb:787:try_flush: /path/to/fluentd/fluentd/lib/fluent/compat/output.rb:125:in `write'
  2016-08-27 16:45:14 +0900 [warn]: plugin/output.rb:787:try_flush: /path/to/fluentd/fluentd/lib/fluent/plugin/output.rb:802:in `try_flush'
  2016-08-27 16:45:14 +0900 [warn]: plugin/output.rb:787:try_flush: /path/to/fluentd/fluentd/lib/fluent/plugin/output.rb:979:in `flush_thread_run'
  2016-08-27 16:45:14 +0900 [warn]: plugin/output.rb:787:try_flush: /path/to/fluentd/fluentd/lib/fluent/plugin/output.rb:369:in `block (2 levels) in start'
  2016-08-27 16:45:14 +0900 [warn]: plugin/output.rb:787:try_flush: /path/to/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:66:in `block in thread_create'

[tagomoris]

I confirmed that this error occurs when file buffer resumes chunks in its #start, and runs its flush thread besides Output#start doesn't return yet.

[mia-0032]

@tagomoris Thanks!