fluentd: Fluentd 0.14.11 deadlocked in file output

td-agent 3/fluentd 0.14.11, running on CentOS 6, writing to a file. Senders were all buffering. Multiple sigdumps were identical other than the allocation count, so I feel fairly confident things were deadlocked.

I had a hard time killing the daemon when it was in this state

2017-04-18 21:44:20 +0000 [warn]: thread doesn't exit correctly (killed or other reason) plugin=Fluent::Plugin::FileOutput title=:flush_thread_0 thread=#<Thread:0x007f092a15c720@/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin_helper/thread.rb:58 aborting> error=nil

We rolled back to td-agent 2/fluentd 0.12, and may have seen the same thing, but I am not sure, and we can no longer reproduce the problem.

Sigdump at 2017-04-18 20:47:33 +0000 process 3303 (/usr/sbin/td-agent)
  Thread #<Thread:0x007f0931faf988> status=run priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:52:in `backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:52:in `dump_backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:34:in `block in dump_all_thread_backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:33:in `each'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:33:in `dump_all_thread_backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:16:in `block in dump'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:136:in `open'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:136:in `_open_dump_path'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:14:in `dump'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:7:in `block in setup'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/engine.rb:179:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/engine.rb:179:in `run'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/supervisor.rb:725:in `run_engine'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/supervisor.rb:478:in `block in run_worker'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/supervisor.rb:650:in `main_process'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/supervisor.rb:473:in `run_worker'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/command/fluentd.rb:288:in `<top (required)>'
      /opt/td-agent/embedded/lib/ruby/site_ruby/2.4.0/rubygems/core_ext/kernel_require.rb:55:in `require'
      /opt/td-agent/embedded/lib/ruby/site_ruby/2.4.0/rubygems/core_ext/kernel_require.rb:55:in `require'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/bin/fluentd:5:in `<top (required)>'
      /opt/td-agent/embedded/bin/fluentd:22:in `load'
      /opt/td-agent/embedded/bin/fluentd:22:in `<top (required)>'
      /usr/sbin/td-agent:7:in `load'
      /usr/sbin/td-agent:7:in `<main>'
  Thread #<Thread:0x007f092b55d940> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/output.rb:1250:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/output.rb:1250:in `flush_thread_run'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/output.rb:398:in `block (2 levels) in start'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin_helper/thread.rb:66:in `block in thread_create'
  Thread #<Thread:0x007f092b55d508> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/output.rb:1207:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/output.rb:1207:in `enqueue_thread_run'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin_helper/thread.rb:66:in `block in thread_create'
  Thread #<Thread:0x007f092a15c720> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/2.4.0/monitor.rb:187:in `lock'
      /opt/td-agent/embedded/lib/ruby/2.4.0/monitor.rb:187:in `mon_enter'
      /opt/td-agent/embedded/lib/ruby/2.4.0/monitor.rb:212:in `mon_synchronize'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/buffer.rb:395:in `purge_chunk'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/output.rb:900:in `commit_write'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/output.rb:1013:in `try_flush'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/output.rb:1234:in `flush_thread_run'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/output.rb:398:in `block (2 levels) in start'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin_helper/thread.rb:66:in `block in thread_create'
  Thread #<Thread:0x007f092a15c450> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/2.4.0/monitor.rb:187:in `lock'
      /opt/td-agent/embedded/lib/ruby/2.4.0/monitor.rb:187:in `mon_enter'
      /opt/td-agent/embedded/lib/ruby/2.4.0/monitor.rb:212:in `mon_synchronize'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/buffer.rb:320:in `block in enqueue_chunk'
      /opt/td-agent/embedded/lib/ruby/2.4.0/monitor.rb:214:in `mon_synchronize'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/buffer.rb:316:in `enqueue_chunk'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/buffer.rb:356:in `block (2 levels) in enqueue_all'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/buffer.rb:353:in `each'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/buffer.rb:353:in `block in enqueue_all'
      /opt/td-agent/embedded/lib/ruby/2.4.0/monitor.rb:214:in `mon_synchronize'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/buffer.rb:351:in `enqueue_all'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/output.rb:1197:in `enqueue_thread_run'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin_helper/thread.rb:66:in `block in thread_create'
  Thread #<Thread:0x007f092741f898> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/output.rb:1250:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/output.rb:1250:in `flush_thread_run'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/output.rb:398:in `block (2 levels) in start'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin_helper/thread.rb:66:in `block in thread_create'
  Thread #<Thread:0x007f092741f398> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/output.rb:1207:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/output.rb:1207:in `enqueue_thread_run'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin_helper/thread.rb:66:in `block in thread_create'
  Thread #<Thread:0x007f092741eec0> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run_once'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin_helper/event_loop.rb:77:in `block in start'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin_helper/thread.rb:66:in `block in thread_create'
  Thread #<Thread:0x007f0927413ef8> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/2.4.0/webrick/server.rb:171:in `select'
      /opt/td-agent/embedded/lib/ruby/2.4.0/webrick/server.rb:171:in `block in start'
      /opt/td-agent/embedded/lib/ruby/2.4.0/webrick/server.rb:33:in `start'
      /opt/td-agent/embedded/lib/ruby/2.4.0/webrick/server.rb:158:in `start'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/in_monitor_agent.rb:234:in `block in start'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin_helper/thread.rb:66:in `block in thread_create'
  Thread #<Thread:0x007f0927413638> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run_once'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin_helper/event_loop.rb:77:in `block in start'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin_helper/thread.rb:66:in `block in thread_create'
  Thread #<Thread:0x007f0927df3ec8> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/2.4.0/monitor.rb:187:in `lock'
      /opt/td-agent/embedded/lib/ruby/2.4.0/monitor.rb:187:in `mon_enter'
      /opt/td-agent/embedded/lib/ruby/2.4.0/monitor.rb:212:in `mon_synchronize'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/buffer.rb:457:in `write_once'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/buffer.rb:207:in `block in write'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/buffer.rb:206:in `each'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/buffer.rb:206:in `write'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/output.rb:848:in `block in handle_stream_with_custom_format'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/output.rb:783:in `write_guard'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/output.rb:847:in `handle_stream_with_custom_format'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/output.rb:775:in `execute_chunking'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/output.rb:710:in `emit_buffered'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/event_router.rb:90:in `emit_stream'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/in_forward.rb:292:in `on_message'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/in_forward.rb:203:in `block in handle_connection'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/in_forward.rb:240:in `block (3 levels) in read_messages'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/in_forward.rb:239:in `feed_each'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/in_forward.rb:239:in `block (2 levels) in read_messages'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin/in_forward.rb:248:in `block in read_messages'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin_helper/server.rb:465:in `on_read_without_connection'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/cool.io-1.4.5/lib/cool.io/io.rb:123:in `on_readable'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/cool.io-1.4.5/lib/cool.io/io.rb:186:in `on_readable'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run_once'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin_helper/event_loop.rb:77:in `block in start'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/plugin_helper/thread.rb:66:in `block in thread_create'
  Thread #<Thread:0x007f0927df16c8> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/engine.rb:149:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.11/lib/fluent/engine.rb:149:in `log_event_loop'
  GC stat:
      count: 3840
      heap_allocated_pages: 273
      heap_sorted_length: 273
      heap_allocatable_pages: 0
      heap_available_slots: 111273
      heap_live_slots: 110894
      heap_free_slots: 379
      heap_final_slots: 0
      heap_marked_slots: 66052
      heap_eden_pages: 273
      heap_tomb_pages: 0
      total_allocated_pages: 273
      total_freed_pages: 0
      total_allocated_objects: 142062923
      total_freed_objects: 141952029
      malloc_increase_bytes: 35536
      malloc_increase_bytes_limit: 29739514
      minor_gc_count: 3648
      major_gc_count: 192
      remembered_wb_unprotected_objects: 1658
      remembered_wb_unprotected_objects_limit: 2376
      old_objects: 63003
      old_objects_limit: 121542
      oldmalloc_increase_bytes: 35984
      oldmalloc_increase_bytes_limit: 92131169
  Built-in objects:
   111,273: TOTAL
    27,789: T_STRING
    22,271: T_DATA
    20,514: T_ARRAY
    18,339: T_IMEMO
     6,865: T_RATIONAL
     6,812: T_BIGNUM
     2,492: T_CLASS
     1,848: T_OBJECT
     1,241: T_NODE
     1,114: T_HASH
       590: T_REGEXP
       277: FREE
       277: T_ICLASS
       271: T_FILE
       258: T_STRUCT
       227: T_MODULE
        73: T_SYMBOL
         9: T_FLOAT
         5: T_MATCH
         1: T_COMPLEX
  All objects:
    28,024: String
    11,516: Time
     9,453: Array
     3,711: Rational
     3,658: Integer
     1,431: Class
       993: Hash
       665: Proc
       600: Gem::Requirement
       590: Regexp
       430: Gem::Dependency
       227: Module
       217: File
       208: Thread::Mutex
       180: Fluent::Plugin::Buffer::Metadata
       177: Gem::Version
       106: Fluent::Plugin::Buffer::FileChunk
       101: Encoding
        92: Coolio::IO::Watcher
        77: Gem::Specification
        77: Gem::StubSpecification::StubLine
        77: Gem::StubSpecification
        75: Fluent::Config::ConfigureProxy
        73: Symbol
        56: Range
        46: IO::Buffer
        45: Fluent::PluginHelper::Server::TCPCallbackSocket
        45: Fluent::PluginHelper::Server::EventHandler::TCPServer
        45: TCPSocket
        42: MessagePack::Buffer
        42: MessagePack::Unpacker
        27: MatchData
        24: Fluent::Config::Section
        17: Fluent::Config::Element
        16: OptionParser::Switch::RequiredArgument
        13: Thread::Backtrace
        13: Fluent::Plugin::Base::State
        12: Thread
        12: OptionParser::Switch::NoArgument
        11: Method
         9: Float
         8: Fluent::Registry
         6: OptionParser::OptionMap
         5: IO
         4: Monitor
         4: Object
         3: TCPServer
         3: Fluent::PluginHelper::EventLoop::DefaultWatcher
         3: Coolio::Loop
         3: Fluent::Plugin::Output::FlushThreadState
         3: Fluent::EventRouter::Rule
         3: Fluent::TimeFormatter
         3: Fluent::Plugin::OutFileFormatter
         3: Fluent::Plugin::FileBuffer
         3: Fluent::Plugin::FileOutput
         3: Fluent::PluginHelper::Server::ServerInfo
         3: OptionParser::List
         3: IRB::Notifier::LeveledNotifier
         3: JSON::Ext::Generator::State
         2: Zlib::GzipWriter
         2: Coolio::TCPServer
         2: ThreadGroup
         2: Fluent::GlobMatchPattern
         2: MessagePack::Factory
         2: OpenSSL::PKey::DH
         2: ThreadSafe::Cache
         2: OptionParser::Switch::PlacedArgument
         2: OptionParser::Switch::OptionalArgument
         2: UnboundMethod
         1: WEBrick::HTTPServer::MountTable
         1: Fluent::Plugin::SyslogInput
         1: Thread::SizedQueue
         1: WEBrick::HTTPServer
         1: WEBrick::Log
         1: Fluent::Plugin::ForwardInput
         1: Fluent::MessagePackEventStream
         1: EOFError
         1: Strptime
         1: Fluent::TimeParser
         1: Fluent::Plugin::SyslogParser
         1: Fluent::AllMatchPattern
         1: Fluent::EventRouter::MatchCache
         1: Fluent::EventRouter
         1: Fluent::Agent::NoMatchMatch
         1: Fluent::RootAgent
         1: Fluent::SystemConfig
         1: Fluent::EngineClass
         1: OpenSSL::X509::Store
         1: Resolv::DNS::Config
         1: Resolv::DNS
         1: Resolv::Hosts
         1: Resolv
         1: Fluent::Compat::NullOutputChain
         1: Fluent::PluginHelper::Server::EventHandler::UDPServer
         1: UDPSocket
         1: WEBrick::HTTPVersion
         1: Set
         1: OptionParser
         1: Fluent::Plugin::MonitorAgentInput
         1: IRB::Notifier::NoMsgNotifier
         1: #<Class:0x007f092b4a7d98>
         1: IRB::Notifier::CompositeNotifier
         1: IRB::StdioOutputMethod
         1: Gem::PathSupport
         1: #<Class:0x007f092b51e560>
         1: Gem::Platform
         1: fatal
         1: Data
         1: URI::RFC2396_Parser
         1: URI::RFC3986_Parser
         1: Fluent::Log
         1: Logger::Formatter
         1: ServerEngine::DaemonLogger
         1: Fluent::Supervisor::LoggerInitializer
         1: Fluent::Supervisor
         1: OptionParser::CompletingHash
         1: Complex
         1: IOError
         1: Binding
         1: RubyVM
         1: NoMemoryError
         1: SystemStackError
         1: Random
         1: ARGF.class
  String 19,199,333 bytes
   Array 1 elements
    Hash 14 pairs

About this issue

  • Original URL
  • State: closed
  • Created 7 years ago
  • Comments: 41 (18 by maintainers)

Commits related to this issue

Most upvoted comments

@repeatedly Okay, I’ll try to write a patch 💪

+3
abicky on Oct 17, 2017

It is reproduced on my env. The problem is no buffer lock in write. It causes lock order mismatch. For the performance, giant lock in write is not good. I’m now trying to fix the problem.

+3
repeatedly on Oct 12, 2017

I tried to reproduce this issue in 629c470a2a8412dd51875f8adbea0ea7b47dc914 by the following steps and I found that deadlock occurs if an input plugin thread locks chunks in Buffer#write by chunk.mon_enter and an enqueue thread locks the buffer in Buffer#enqueue_chunk at the same time.

1. Add the following change

diff --git a/lib/fluent/plugin/buffer.rb b/lib/fluent/plugin/buffer.rb
index be66f3e8..d4c6be87 100644
--- a/lib/fluent/plugin/buffer.rb
+++ b/lib/fluent/plugin/buffer.rb
@@ -496,6 +496,7 @@ module Fluent

           if stored
             block.call(chunk, adding_bytesize)
+            sleep 3
           end
         end

2. Prepare a configuration file

<source>
  @type forward
</source>

<match test.*>
  @type file
  format json
  path /tmp/fluentd/file/${tag}-%Y%m%d

  <buffer time, tag>
    path /tmp/fluentd/buffer/test.*.buffer
    flush_mode interval
    flush_interval 1s
    timekey 1d
  </buffer>
</match>

3. Launch fluentd

ruby bin/fluentd -c deadlock.conf

4. Post events

require 'fluent-logger'
logger = Fluent::Logger::FluentLogger.new(nil, host: 'localhost', port: 24224)
logger.send(:write, ['test.a', [[Time.now.to_i - 86400, { msg: 0 }], [Time.now.to_i, { msg: 1 }]]])

5. sigdump

Sigdump at 2017-10-11 17:24:33 +0900 process 84647 (bin/fluentd)
  Thread #<Thread:0x007fb08107ef70> status=run priority=0
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:52:in `backtrace'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:52:in `dump_backtrace'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:34:in `block in dump_all_thread_backtrace'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:33:in `each'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:33:in `dump_all_thread_backtrace'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:16:in `block in dump'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:136:in `open'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:136:in `_open_dump_path'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:14:in `dump'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/sigdump-0.2.4/lib/sigdump.rb:7:in `block in setup'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/engine.rb:228:in `sleep'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/engine.rb:228:in `run'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/supervisor.rb:774:in `run_engine'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/supervisor.rb:523:in `block in run_worker'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/supervisor.rb:699:in `main_process'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/supervisor.rb:518:in `run_worker'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/command/fluentd.rb:316:in `<top (required)>'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/2.4.0/rubygems/core_ext/kernel_require.rb:55:in `require'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/2.4.0/rubygems/core_ext/kernel_require.rb:55:in `require'
      bin/fluentd:5:in `<main>'
  Thread #<Thread:0x007fb080c6e6b0> status=sleep priority=0
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/2.4.0/monitor.rb:187:in `lock'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/2.4.0/monitor.rb:187:in `mon_enter'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/2.4.0/monitor.rb:212:in `mon_synchronize'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/buffer.rb:304:in `queued?'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1015:in `next_flush_time'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1289:in `flush_thread_run'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:438:in `block (2 levels) in start'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
  Thread #<Thread:0x007fb080c6e430> status=sleep priority=0
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/2.4.0/monitor.rb:187:in `lock'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/2.4.0/monitor.rb:187:in `mon_enter'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/2.4.0/monitor.rb:212:in `mon_synchronize'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/buffer.rb:320:in `block in enqueue_chunk'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/2.4.0/monitor.rb:214:in `mon_synchronize'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/buffer.rb:316:in `enqueue_chunk'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/buffer.rb:356:in `block (2 levels) in enqueue_all'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/buffer.rb:353:in `each'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/buffer.rb:353:in `block in enqueue_all'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/2.4.0/monitor.rb:214:in `mon_synchronize'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/buffer.rb:351:in `enqueue_all'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:1249:in `enqueue_thread_run'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
  Thread #<Thread:0x007fb080c6e228> status=sleep priority=0
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/2.4.0/monitor.rb:187:in `lock'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/2.4.0/monitor.rb:187:in `mon_enter'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/2.4.0/monitor.rb:212:in `mon_synchronize'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/buffer.rb:457:in `write_once'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/buffer.rb:207:in `block in write'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/buffer.rb:206:in `each'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/buffer.rb:206:in `write'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:897:in `block in handle_stream_with_custom_format'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:823:in `write_guard'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:896:in `handle_stream_with_custom_format'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:815:in `execute_chunking'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/output.rb:750:in `emit_buffered'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/event_router.rb:96:in `emit_stream'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/in_forward.rb:320:in `on_message'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/in_forward.rb:211:in `block in handle_connection'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/in_forward.rb:248:in `block (3 levels) in read_messages'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/in_forward.rb:247:in `feed_each'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/in_forward.rb:247:in `block (2 levels) in read_messages'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin/in_forward.rb:256:in `block in read_messages'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin_helper/server.rb:576:in `on_read_without_connection'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/cool.io-1.5.1/lib/cool.io/io.rb:123:in `on_readable'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/cool.io-1.5.1/lib/cool.io/io.rb:186:in `on_readable'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/cool.io-1.5.1/lib/cool.io/loop.rb:88:in `run_once'
      /Users/arabiki/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/cool.io-1.5.1/lib/cool.io/loop.rb:88:in `run'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin_helper/event_loop.rb:84:in `block in start'
      /Users/arabiki/.ghq/github.com/fluent/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
  GC stat:
      count: 54
      heap_allocated_pages: 377
      heap_sorted_length: 409
      heap_allocatable_pages: 32
      heap_available_slots: 153663
      heap_live_slots: 153127
      heap_free_slots: 536
      heap_final_slots: 0
      heap_marked_slots: 100124
      heap_eden_pages: 377
      heap_tomb_pages: 0
      total_allocated_pages: 377
      total_freed_pages: 0
      total_allocated_objects: 1135049
      total_freed_objects: 981922
      malloc_increase_bytes: 5486912
      malloc_increase_bytes_limit: 16777216
      minor_gc_count: 47
      major_gc_count: 7
      remembered_wb_unprotected_objects: 1162
      remembered_wb_unprotected_objects_limit: 2320
      old_objects: 97483
      old_objects_limit: 194974
      oldmalloc_increase_bytes: 5710432
      oldmalloc_increase_bytes_limit: 16777216
  Built-in objects:
   153,663: TOTAL
    76,920: T_STRING
    34,229: T_ARRAY
    17,853: T_IMEMO
    11,396: T_OBJECT
     5,465: T_NODE
     2,324: T_CLASS
     2,125: T_HASH
     1,580: T_DATA
       543: T_REGEXP
       460: FREE
       255: T_ICLASS
       232: T_MODULE
        71: T_RATIONAL
        66: T_STRUCT
        58: T_SYMBOL
        28: T_MATCH
        26: T_BIGNUM
        22: T_FILE
         9: T_FLOAT
         1: T_COMPLEX
  All objects:
    69,320: String
    25,693: Array
     4,931: Gem::Requirement
     3,377: Gem::Dependency
     1,899: Hash
     1,318: Class
       844: Time
       769: Gem::StubSpecification
       769: Gem::StubSpecification::StubLine
       769: Gem::Specification
       596: Gem::Version
       543: Regexp
       382: Proc
       232: Module
       101: Encoding
        76: RubyVM::InstructionSequence
        71: Rational
        69: Fluent::Config::ConfigureProxy
        58: Symbol
        53: Range
        46: MatchData
        30: Thread::Mutex
        28: Binding
        26: Integer
        17: OptionParser::Switch::RequiredArgument
        16: File
        14: Thread::Backtrace
        13: OptionParser::Switch::NoArgument
        10: Fluent::Config::Section
         9: Float
         8: Method
         8: Fluent::Config::Element
         8: Fluent::Registry
         6: OptionParser::OptionMap
         4: Thread
         4: Coolio::IO::Watcher
         4: Fluent::Plugin::Buffer::Metadata
         4: Fluent::Plugin::Base::State
         4: Object
         3: IO
         3: OptionParser::List
         3: JSON::Ext::Generator::State
         3: IRB::Notifier::LeveledNotifier
         3: UnboundMethod
         3: MessagePack::Buffer
         2: Fluent::PluginHelper::Server::EventHandler::TCPServer
         2: OptionParser::Switch::PlacedArgument
         2: OptionParser::Switch::OptionalArgument
         2: ThreadSafe::Cache
         2: BigDecimal
         2: Fluent::PluginHelper::Server::ServerInfo
         2: IO::Buffer
         2: OpenSSL::PKey::DH
         2: Monitor
         2: MessagePack::Unpacker
         2: Fluent::Plugin::Output::PlaceholderValidator
         2: MessagePack::Factory
         2: Fluent::Plugin::Buffer::FileChunk
         1: TCPSocket
         1: StringScanner
         1: Fluent::Log
         1: Logger::Formatter
         1: ServerEngine::DaemonLogger
         1: WEBrick::HTTPVersion
         1: #<Class:0x007fb08082e208>
         1: #<Class:0x007fb0808547c8>
         1: IRB::Notifier::CompositeNotifier
         1: IRB::StdioOutputMethod
         1: IRB::Notifier::NoMsgNotifier
         1: Errno::EEXIST
         1: Fluent::Compat::NullOutputChain
         1: Fluent::Plugin::ForwardInput
         1: LoadError
         1: Fluent::Plugin::JSONFormatter
         1: ArgumentError
         1: Coolio::Loop
         1: TCPServer
         1: Fluent::PluginHelper::EventLoop::DefaultWatcher
         1: Fluent::Plugin::Output::FlushThreadState
         1: Complex
         1: ThreadGroup
         1: IOError
         1: RubyVM
         1: NoMemoryError
         1: SystemStackError
         1: Random
         1: ARGF.class
         1: fatal
         1: Data
         1: Gem::PathSupport
         1: Set
         1: OptionParser::CompletingHash
         1: Gem::Platform
         1: Fluent::EngineClass
         1: URI::RFC2396_Parser
         1: URI::RFC3986_Parser
         1: OpenSSL::X509::Store
         1: Resolv::DNS::Config
         1: Resolv::DNS
         1: Resolv::Hosts
         1: Resolv
         1: Fluent::EventRouter::MatchCache
         1: Fluent::EventRouter
         1: Fluent::NoMatchMatch
         1: Fluent::RootAgent
         1: Fluent::SystemConfig
         1: Fluent::Supervisor::LoggerInitializer
         1: Fluent::Supervisor
         1: OptionParser
         1: MessagePack::Packer
         1: Fluent::PluginHelper::Server::EventHandler::UDPServer
         1: UDPSocket
         1: IPAddr
         1: Coolio::TCPServer
         1: Fluent::Plugin::FileOutput
         1: Fluent::Plugin::FileBuffer
         1: Fluent::GlobMatchPattern
         1: Fluent::EventRouter::Rule
         1: Fluent::EventTime
         1: Fluent::MultiEventStream
         1: Fluent::PluginHelper::Server::TCPCallbackSocket
  String 4,318,695 bytes
   Array 3 elements
    Hash 0 pairs
+2
abicky on Oct 12, 2017

I released v0.14.22.rc2 for testing.

+1
repeatedly on Oct 23, 2017
Read more comments on GitHub
← fluentd: Errors with in_tail plugin in 0.14.6
fluentd: Fluentd crashes →