search

fluent / fluent-plugin-kafka

Kafka input and output plugin for Fluentd
Other
303 stars 176 forks source link

Fluentd process stop consuming messages from kafka #113

Closed sharadgaur closed 7 years ago

sharadgaur commented 7 years ago

Fluentd Process stop consuming messages from kakfa after 15-30 mins of runtime. I also noticed when trying to stop td-agent gracefull I am getting timeout error.

~>service td-agent stop
Stopping td-agent: Timeout error occurred trying to stop td[FAILED].td-agent

Process still shows td-agent is running 

~>service td-agent status**
td-agent is running                                        [  OK  ]

I am using td-agent version 0.14.11**

~>td-agent --version
td-agent 0.14.11

Here is the Environment information:

~> td-agent-gem env
RubyGems Environment:
  - RUBYGEMS VERSION: 2.6.7
  - RUBY VERSION: 2.4.0 (2016-12-24 patchlevel 0) [x86_64-linux]
  - INSTALLATION DIRECTORY: /opt/td-agent/embedded/lib/ruby/gems/2.4.0/
  - USER INSTALLATION DIRECTORY: /root/.gem/ruby/2.4.0
  - RUBY EXECUTABLE: /opt/td-agent/embedded/bin/ruby
  - EXECUTABLE DIRECTORY: /opt/td-agent/embedded/lib/ruby/gems/2.4.0/bin
  - SPEC CACHE DIRECTORY: /root/.gem/specs
  - SYSTEM CONFIGURATION DIRECTORY: /opt/td-agent/embedded/etc
  - RUBYGEMS PLATFORMS:
    - ruby
    - x86_64-linux
  - GEM PATHS:
     - /opt/td-agent/embedded/lib/ruby/gems/2.4.0/
  - GEM CONFIGURATION:
     - :update_sources => true
     - :verbose => true
     - :backtrace => false
     - :bulk_threshold => 1000
  - REMOTE SOURCES:
     - https://rubygems.org/
  - SHELL PATH:
     - /usr/local/bin
     - /sbin
     - /bin
     - /usr/sbin
     - /usr/bin
     - /opt/puppetlabs/bin

Here is the list of gems :

~> td-agent-gem list --local

*** LOCAL GEMS ***

addressable (2.5.0)
aws-sdk (2.6.46)
aws-sdk-core (2.6.46)
aws-sdk-resources (2.6.46)
aws-sigv4 (1.0.0)
bigdecimal (default: 1.3.0)
bundler (1.13.3)
bzip2-ffi (1.0.0)
cool.io (1.4.5)
did_you_mean (1.1.0)
elasticsearch (5.0.0, 1.0.18)
elasticsearch-api (5.0.0, 1.0.18)
elasticsearch-transport (5.0.0, 1.0.18)
excon (0.54.0)
faraday (0.11.0)
ffi (1.9.17)
fluent-logger (0.6.2)
fluent-mixin-config-placeholders (0.4.0)
fluent-mixin-plaintextformatter (0.2.6)
**fluent-mixin-rewrite-tag-name (0.1.0)**
fluent-plugin-dstat (0.3.3)
fluent-plugin-elasticsearch (1.9.2)
fluent-plugin-forest (0.3.3)
fluent-plugin-jvmwatcher (0.1.5)
fluent-plugin-kafka (0.5.3)
fluent-plugin-rewrite-tag-filter (1.5.5)
fluent-plugin-s3 (1.0.0.rc1)
fluent-plugin-td (0.10.29)
fluent-plugin-td-monitoring (0.2.2)
fluent-plugin-top (0.1.1)
fluent-plugin-webhdfs (1.1.0, 0.4.2)
fluentd (0.14.11)
hirb (0.7.3)
http_parser.rb (0.6.0)
httpclient (2.8.2.4)
io-console (default: 0.4.6)
ipaddress (0.8.3)
jmespath (1.3.1)
json (default: 2.0.2)
ltsv (0.1.0)
mini_portile2 (2.1.0)
minitest (5.10.1)
mixlib-cli (1.7.0)
mixlib-config (2.2.4)
mixlib-log (1.7.1)
mixlib-shellout (2.2.7)
msgpack (1.0.2)
multi_json (1.12.1)
multipart-post (2.0.0)
net-telnet (0.1.1)
nokogiri (1.7.0.1)
ohai (6.20.0)
oj (2.18.0)
openssl (default: 2.0.2)
parallel (1.8.0)
power_assert (0.4.1)
psych (default: 2.2.2)
public_suffix (2.0.5)
rake (12.0.0)
rdoc (default: 5.0.0)
ruby-kafka (0.3.16)
ruby-progressbar (1.8.1)
rubyzip (1.1.7)
serverengine (2.0.4)
sigdump (0.2.4)
strptime (0.1.9)
systemu (2.5.2)
td (0.15.2)
td-client (0.8.85)
td-logger (0.3.26)
test-unit (3.2.3)
thread_safe (0.3.5)
tzinfo (1.2.2)
tzinfo-data (1.2016.10)
uuidtools (2.1.5)
webhdfs (0.8.0)
xmlrpc (0.2.1)
yajl-ruby (1.3.0)
zip-zip (0.3)
OS info:
LSB Version:    :base-4.0-amd64:base-4.0-noarch:core-4.0-amd64:core-4.0-noarch
Distributor ID: OracleServer
Description:    Oracle Linux Server release 6.8
Release:    6.8
Codename:   n/a

Here is the td-agent.conf

<source>
  @type kafka_group
  consumer_group fluentd_v1
  brokers somehost:9092,somehost2:9092
  topics topic_name_cl
  format json
  start_from_beginning false
  offset_commit_interval 5s
</source>
<match indexer_v1>
  @type rewrite_tag_filter
  @log_level debug
  rewriterule1 info (.*) hdfs.$1
  rewriterule2 Info (.*) hdfs.$1
</match>

<match hdfs.*>
  @type webhdfs
   namenode somehost3:50070
   standby_namenode somehost5:50070
   path /data/${tag[1]}/%{uuid}.json.index
   username ocingestion
   retry_known_errors yes
   retry_interval  60
  <buffer time,tag>
    @type   file                    
    path    /fluentd/data.*.log
    flush_interval  5s
    timekey 5m
    timekey_wait 10m
  </buffer> 
  <format>
    @type json
  </format>
</match>

<match **>
    @type stdout
</match>

I am producing 60K+ JSON messages per 30 sec in kafka.

Here are the logs td-agent.log.gz

@repeatedly

repeatedly commented 7 years ago

If consuming message is stopped, please try http://docs.fluentd.org/v0.12/articles/trouble-shooting#dump-fluentd-internal-information first. sigdump result shows threads are blocked or not.

sharadgaur commented 7 years ago

Here is the sigdump Sigdump at 2017-02-21 12:36:46 -0600 process 27282 (/usr/sbin/td-agent) when processing is working fine. Sigdump at 2017-02-21 12:58:51 -0600 process 27282 (/usr/sbin/td-agent) when processing stop consuming messages

Sigdump at 2017-02-21 12:36:46 -0600 process 27282 (/usr/sbin/td-agent)
  Thread #<Thread:0x007f24a861a778> status=run priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:52:in `backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:52:in `dump_backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.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.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:33:in `each'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:33:in `dump_all_thread_backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:16:in `block in dump'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:136:in `open'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:136:in `_open_dump_path'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:14:in `dump'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:7:in `block in setup'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `call'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run_once'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/engine.rb:199:in `run'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:570:in `run_engine'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:176:in `block in start'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:366:in `call'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:366:in `main_process'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:170:in `start'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/command/fluentd.rb:173:in `<top (required)>'
      /opt/td-agent/embedded/lib/ruby/site_ruby/2.1.0/rubygems/core_ext/kernel_require.rb:54:in `require'
      /opt/td-agent/embedded/lib/ruby/site_ruby/2.1.0/rubygems/core_ext/kernel_require.rb:54:in `require'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/bin/fluentd:5:in `<top (required)>'
      /opt/td-agent/embedded/bin/fluentd:23:in `load'
      /opt/td-agent/embedded/bin/fluentd:23:in `<top (required)>'
      /usr/sbin/td-agent:7:in `load'
      /usr/sbin/td-agent:7:in `<main>'
  Thread #<Thread:0x007f24a5a2d7a0> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/plugin/buf_file.rb:39:in `write'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/plugin/buf_file.rb:39:in `<<'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/buffer.rb:200:in `block in emit'
      /opt/td-agent/embedded/lib/ruby/2.1.0/monitor.rb:211:in `mon_synchronize'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/buffer.rb:193:in `emit'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:593:in `block in emit'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:592:in `each'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:592:in `emit'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-forest-0.3.3/lib/fluent/plugin/out_forest.rb:175:in `emit'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/event_router.rb:90:in `emit_stream'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/event_router.rb:81:in `emit'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-rewrite-tag-filter-1.5.5/lib/fluent/plugin/out_rewrite_tag_filter.rb:75:in `block in emit'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/event.rb:130:in `call'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/event.rb:130:in `block in each'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/event.rb:129:in `each'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/event.rb:129:in `each'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-rewrite-tag-filter-1.5.5/lib/fluent/plugin/out_rewrite_tag_filter.rb:72:in `emit'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/event_router.rb:90:in `emit_stream'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-kafka-0.5.3/lib/fluent/plugin/in_kafka_group.rb:200:in `emit_events'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-kafka-0.5.3/lib/fluent/plugin/in_kafka_group.rb:183:in `block in run'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/consumer.rb:251:in `block (3 levels) in each_batch'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/instrumenter.rb:21:in `call'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/instrumenter.rb:21:in `instrument'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/instrumenter.rb:33:in `instrument'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/consumer.rb:241:in `block (2 levels) in each_batch'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/consumer.rb:239:in `each'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/consumer.rb:239:in `block in each_batch'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/consumer.rb:282:in `consumer_loop'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/consumer.rb:236:in `each_batch'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-kafka-0.5.3/lib/fluent/plugin/in_kafka_group.rb:157:in `run'
  Thread #<Thread:0x007f24a5a2d408> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/engine.rb:167:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/engine.rb:167:in `log_event_loop'
  Thread #<Thread:0x007f24a0b4a868> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b4a688> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b4a4a8> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b4a2c8> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b4a0e8> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b49f08> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b49d28> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b49b48> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  GC stat:
      count: 149
      heap_used: 844
      heap_length: 844
      heap_increment: 0
      heap_live_slot: 343017
      heap_free_slot: 983
      heap_final_slot: 0
      heap_swept_slot: 161589
      heap_eden_page_length: 844
      heap_tomb_page_length: 0
      total_allocated_object: 17857257
      total_freed_object: 17514240
      malloc_increase: 1498912
      malloc_limit: 32883343
      minor_gc_count: 104
      major_gc_count: 45
      remembered_shady_object: 853
      remembered_shady_object_limit: 1706
      old_object: 128090
      old_object_limit: 256180
      oldmalloc_increase: 1499296
      oldmalloc_limit: 39044899
  Built-in objects:
   344,000: TOTAL
   267,929: T_STRING
    23,093: T_ARRAY
    14,709: T_DATA
    11,095: T_HASH
    10,561: T_NODE
     9,166: T_OBJECT
     2,947: T_CLASS
     1,766: T_MATCH
       893: FREE
       718: T_REGEXP
       672: T_STRUCT
       182: T_ICLASS
       178: T_MODULE
        59: T_RATIONAL
        12: T_FILE
        10: T_BIGNUM
         9: T_FLOAT
         1: T_COMPLEX
Sigdump at 2017-02-21 12:58:51 -0600 process 27282 (/usr/sbin/td-agent)
  Thread #<Thread:0x007f24a861a778> status=run priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:52:in `backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:52:in `dump_backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.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.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:33:in `each'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:33:in `dump_all_thread_backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:16:in `block in dump'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:136:in `open'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:136:in `_open_dump_path'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:14:in `dump'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:7:in `block in setup'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `call'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run_once'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/engine.rb:199:in `run'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:570:in `run_engine'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:176:in `block in start'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:366:in `call'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:366:in `main_process'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:170:in `start'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/command/fluentd.rb:173:in `<top (required)>'
      /opt/td-agent/embedded/lib/ruby/site_ruby/2.1.0/rubygems/core_ext/kernel_require.rb:54:in `require'
      /opt/td-agent/embedded/lib/ruby/site_ruby/2.1.0/rubygems/core_ext/kernel_require.rb:54:in `require'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/bin/fluentd:5:in `<top (required)>'
      /opt/td-agent/embedded/bin/fluentd:23:in `load'
      /opt/td-agent/embedded/bin/fluentd:23:in `<top (required)>'
      /usr/sbin/td-agent:7:in `load'
      /usr/sbin/td-agent:7:in `<main>'
  Thread #<Thread:0x007f24a5a2d7a0> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/socket_with_timeout.rb:60:in `select'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/socket_with_timeout.rb:60:in `read'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/protocol/decoder.rb:95:in `read'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/protocol/decoder.rb:41:in `int32'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/protocol/decoder.rb:81:in `bytes'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/connection.rb:162:in `read_response'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/connection.rb:181:in `block in wait_for_response'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/connection.rb:180:in `loop'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/connection.rb:180:in `wait_for_response'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/connection.rb:94:in `block in send_request'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/instrumenter.rb:21:in `call'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/instrumenter.rb:21:in `instrument'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/connection.rb:86:in `send_request'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/broker.rb:40:in `fetch_messages'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/fetch_operation.rb:68:in `block in execute'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/fetch_operation.rb:59:in `each'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/fetch_operation.rb:59:in `flat_map'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/fetch_operation.rb:59:in `execute'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/consumer.rb:349:in `fetch_batches'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/consumer.rb:237:in `block in each_batch'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/consumer.rb:282:in `consumer_loop'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/consumer.rb:236:in `each_batch'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-kafka-0.5.3/lib/fluent/plugin/in_kafka_group.rb:157:in `run'
  Thread #<Thread:0x007f24a5a2d408> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/engine.rb:167:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/engine.rb:167:in `log_event_loop'
  Thread #<Thread:0x007f24a0b4a868> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b4a688> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b4a4a8> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b4a2c8> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b4a0e8> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b49f08> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b49d28> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b49b48> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  GC stat:
      count: 285
      heap_used: 844
      heap_length: 844
      heap_increment: 0
      heap_live_slot: 343990
      heap_free_slot: 10
      heap_final_slot: 0
      heap_swept_slot: 79416
      heap_eden_page_length: 844
      heap_tomb_page_length: 0
      total_allocated_object: 35832085
      total_freed_object: 35488095
      malloc_increase: 34432
      malloc_limit: 30949538
      minor_gc_count: 207
      major_gc_count: 78
      remembered_shady_object: 860
      remembered_shady_object_limit: 1708
      old_object: 168703
      old_object_limit: 257198
      oldmalloc_increase: 34816
      oldmalloc_limit: 37247976
  Built-in objects:
   344,000: TOTAL
   182,696: T_STRING
    41,829: T_ARRAY
    39,692: T_HASH
    34,059: T_NODE
    28,045: T_DATA
    13,271: T_OBJECT
     2,947: T_CLASS
       718: T_REGEXP
       206: FREE
       182: T_ICLASS
       178: T_MODULE
        84: T_STRUCT
        59: T_RATIONAL
        12: T_FILE
        10: T_BIGNUM
         9: T_FLOAT
         2: T_MATCH
         1: T_COMPLEX
Sigdump at 2017-02-21 13:01:06 -0600 process 27282 (/usr/sbin/td-agent)
  Thread #<Thread:0x007f24a861a778> status=run priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:52:in `backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:52:in `dump_backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.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.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:33:in `each'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:33:in `dump_all_thread_backtrace'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:16:in `block in dump'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:136:in `open'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:136:in `_open_dump_path'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:14:in `dump'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/sigdump-0.2.4/lib/sigdump.rb:7:in `block in setup'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `call'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run_once'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/engine.rb:199:in `run'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:570:in `run_engine'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:176:in `block in start'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:366:in `call'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:366:in `main_process'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/supervisor.rb:170:in `start'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/command/fluentd.rb:173:in `<top (required)>'
      /opt/td-agent/embedded/lib/ruby/site_ruby/2.1.0/rubygems/core_ext/kernel_require.rb:54:in `require'
      /opt/td-agent/embedded/lib/ruby/site_ruby/2.1.0/rubygems/core_ext/kernel_require.rb:54:in `require'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/bin/fluentd:5:in `<top (required)>'
      /opt/td-agent/embedded/bin/fluentd:23:in `load'
      /opt/td-agent/embedded/bin/fluentd:23:in `<top (required)>'
      /usr/sbin/td-agent:7:in `load'
      /usr/sbin/td-agent:7:in `<main>'
  Thread #<Thread:0x007f24a5a2d7a0> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/socket_with_timeout.rb:60:in `select'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/socket_with_timeout.rb:60:in `read'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/protocol/decoder.rb:95:in `read'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/protocol/decoder.rb:41:in `int32'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/protocol/decoder.rb:81:in `bytes'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/connection.rb:162:in `read_response'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/connection.rb:181:in `block in wait_for_response'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/connection.rb:180:in `loop'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/connection.rb:180:in `wait_for_response'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/connection.rb:94:in `block in send_request'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/instrumenter.rb:21:in `call'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/instrumenter.rb:21:in `instrument'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/connection.rb:86:in `send_request'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/broker.rb:40:in `fetch_messages'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/fetch_operation.rb:68:in `block in execute'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/fetch_operation.rb:59:in `each'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/fetch_operation.rb:59:in `flat_map'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/fetch_operation.rb:59:in `execute'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/consumer.rb:349:in `fetch_batches'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/consumer.rb:237:in `block in each_batch'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/consumer.rb:282:in `consumer_loop'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/consumer.rb:236:in `each_batch'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-kafka-0.5.3/lib/fluent/plugin/in_kafka_group.rb:157:in `run'
  Thread #<Thread:0x007f24a5a2d408> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/engine.rb:167:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/engine.rb:167:in `log_event_loop'
  Thread #<Thread:0x007f24a0b4a868> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b4a688> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b4a4a8> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b4a2c8> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b4a0e8> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b49f08> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b49d28> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  Thread #<Thread:0x007f24a0b49b48> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:174:in `cond_wait'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/output.rb:158:in `run'
  GC stat:
      count: 285
      heap_used: 844
      heap_length: 844
      heap_increment: 0
      heap_live_slot: 301375
      heap_free_slot: 42625
      heap_final_slot: 0
      heap_swept_slot: 173165
      heap_eden_page_length: 844
      heap_tomb_page_length: 0
      total_allocated_object: 35883219
      total_freed_object: 35581844
      malloc_increase: 1763920
      malloc_limit: 30949538
      minor_gc_count: 207
      major_gc_count: 78
      remembered_shady_object: 860
      remembered_shady_object_limit: 1708
      old_object: 168703
      old_object_limit: 257198
      oldmalloc_increase: 1764304
      oldmalloc_limit: 37247976
  Built-in objects:
   344,000: TOTAL
   170,668: T_STRING
    42,535: FREE
    35,055: T_ARRAY
    30,581: T_HASH
    27,064: T_NODE
    22,938: T_DATA
    10,940: T_OBJECT
     2,947: T_CLASS
       718: T_REGEXP
       182: T_ICLASS
       178: T_MODULE
        84: T_STRUCT
        59: T_RATIONAL
        18: T_MATCH
        13: T_FILE
        10: T_BIGNUM
         9: T_FLOAT
         1: T_COMPLEX
sharadgaur commented 7 years ago

I forgot to mention we rolled-back to fluentd V0.12 and still having same issue. Above sigdump is form fluentd 0.12.31

sharadgaur commented 7 years ago

@repeatedly ..I am no expert in ruby but I noticed it always stuck at socket_with_timeout.rb 

Thread #<Thread:0x007f4bd0e99e40> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/socket_with_timeout.rb:60:in `select'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/socket_with_timeout.rb:60:in `read'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/protocol/decoder.rb:95:in `read'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/protocol/decoder.rb:41:in `int32'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/protocol/decoder.rb:81:in `bytes'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/connection.rb:162:in `read_response'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/connection.rb:181:in `block in wait_for_response'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/connection.rb:180:in `loop'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/connection.rb:180:in `wait_for_response'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/connection.rb:94:in `block in send_request'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/instrumenter.rb:21:in `call'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/instrumenter.rb:21:in `instrument'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/connection.rb:86:in `send_request'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/broker.rb:40:in `fetch_messages'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/fetch_operation.rb:68:in `block in execute'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/fetch_operation.rb:59:in `each'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/fetch_operation.rb:59:in `flat_map'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/fetch_operation.rb:59:in `execute'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/consumer.rb:349:in `fetch_batches'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/consumer.rb:237:in `block in each_batch'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/consumer.rb:282:in `consumer_loop'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/ruby-kafka-0.3.16/lib/kafka/consumer.rb:236:in `each_batch'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluent-plugin-kafka-0.5.3/lib/fluent/plugin/in_kafka_group.rb:157:in `run'
  Thread #<Thread:0x007f4bd0e997d8> status=sleep priority=0
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/engine.rb:167:in `sleep'
      /opt/td-agent/embedded/lib/ruby/gems/2.1.0/gems/fluentd-0.12.31/lib/fluent/engine.rb:167:in `log_event_loop'
  GC stat:
      count: 330
      heap_used: 705
      heap_length: 844
      heap_increment: 0
      heap_live_slot: 287240
      heap_free_slot: 118
repeatedly commented 7 years ago

I checked ruby-kafka code and ruby-kafka sets 10 second timeout for connection and read/write action. I'm not sure what happen, but it seems IO.select is blocked with timeout. Could you check kafka log which includes reconnection log from in_kafka_group?

sharadgaur commented 7 years ago

yes I am seeing errors in kafka server.log not sure why?

2017-02-22 21:10:13,068 INFO kafka.cluster.Partition: Partition [indexer_v1,4] on broker 1: Expanding ISR for partition [indexer_v1,4] from 1 to 1,2
2017-02-22 21:10:50,441 ERROR kafka.network.Processor: Closing socket for 10.87.21.27:9092-10.87.21.26:56278 because of error
kafka.network.InvalidRequestException: Error getting request for apiKey: 18 and apiVersion: 0
        at kafka.network.RequestChannel$Request.liftedTree2$1(RequestChannel.scala:93)
        at kafka.network.RequestChannel$Request.<init>(RequestChannel.scala:90)
        at kafka.network.Processor$$anonfun$processCompletedReceives$1.apply(SocketServer.scala:488)
        at kafka.network.Processor$$anonfun$processCompletedReceives$1.apply(SocketServer.scala:483)
        at scala.collection.Iterator$class.foreach(Iterator.scala:742)
        at scala.collection.AbstractIterator.foreach(Iterator.scala:1194)
        at scala.collection.IterableLike$class.foreach(IterableLike.scala:72)
        at scala.collection.AbstractIterable.foreach(Iterable.scala:54)
        at kafka.network.Processor.processCompletedReceives(SocketServer.scala:483)
        at kafka.network.Processor.run(SocketServer.scala:413)
        at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.IllegalArgumentException: Unexpected ApiKeys id `18`, it should be between `0` and `16` (inclusive)
        at org.apache.kafka.common.protocol.ApiKeys.forId(ApiKeys.java:69)
        at org.apache.kafka.common.requests.AbstractRequest.getRequest(AbstractRequest.java:39)
        at
sharadgaur commented 7 years ago

@repeatedly I think I figured it out. I am pushing messages way faster than fluentd can consume the messages. I added some logging (for testing) in ruby-kafka code class fetch_operation.rb and noticed its throwingKafka::OffsetOutOfRange exception at line number 74 and not able to recover it after that.

Here is the code:

response.topics.flat_map {|fetched_topic|
          fetched_topic.partitions.map {|fetched_partition|
            begin
              Protocol.handle_error(fetched_partition.error_code)
            rescue Kafka::OffsetOutOfRange => e
              e.topic = fetched_topic.name
              e.partition = fetched_partition.partition

              raise e
            rescue Kafka::Error => e
              topic = fetched_topic.name
              partition = fetched_partition.partition
              @logger.error "Failed to fetch from #{topic}/#{partition}: #{e.message}"
              raise e
            end
sharadgaur commented 7 years ago

Looks like distributing the messages in multiple Kafka topic partitions (64) solve the issue. I wish OffsetOutOfRange exception was visible in trace (-vv) mode.

Things are working great now and I am closing the issue

Thank you @repeatedly