Fluentd: Failed to write data into buffer by buffer overflow

Created on 8 Sep 2016  路  14Comments  路  Source: fluent/fluentd
  • fluentd 0.14.4 - 0.14.6
  • Centos 7
  • Your configuration
<source>
    @type tail
    format /REGEX_HERE/
    tag http.*
    path /data/data.log
</source>


<match **>
  @type forward
  send_timeout 60s
  recover_wait 10s
  heartbeat_interval 1s
  phi_threshold 16
  hard_timeout 60s

  <server>
    host 172.16.1.1
    port 24224
    weight 60
  </server>
</match>

After a couple o minutes of log tail (logs are streaming) I get this warn/error 

  2016-09-08 17:41:16 +0000 [warn]: suppressed same stacktrace
2016-09-08 17:41:16 +0000 [error]: failed to emit fluentd's log event tag="fluent.warn" event={"message"=>"failed to write data into buffer by buffer overflow"} error_class=Fluent::Plugin::Buffer::BufferOverflowError error="buffer space has too many data"
2016-09-08 17:41:16 +0000 [warn]: failed to write data into buffer by buffer overflow
2016-09-08 17:41:16 +0000 [warn]: emit transaction failed: error_class=Fluent::Plugin::Buffer::BufferOverflowError error="buffer space has too many data" tag="fluent.warn"
  2016-09-08 17:41:16 +0000 [warn]: suppressed same stacktrace
2016-09-08 17:41:16 +0000 [error]: failed to emit fluentd's log event tag="fluent.warn" event={"error"=>"#<Fluent::Plugin::Buffer::BufferOverflowError: buffer space has too many data>", "tag"=>"<tag_here>", "message"=>"emit transaction failed: error_class=Fluent::Plugin::Buffer::BufferOverflowError error=\"buffer space has too many data\" tag=\"<tag_here>\""} error_class=Fluent::Plugin::Buffer::BufferOverflowError error="buffer space has too many data"
2016-09-08 17:41:16 +0000 [warn]: failed to write data into buffer by buffer overflow
2016-09-08 17:41:16 +0000 [warn]: emit transaction failed: error_class=Fluent::Plugin::Buffer::BufferOverflowError error="buffer space has too many data" tag="<tag_here>"
  2016-09-08 17:41:16 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/buffer.rb:186:in `write'
  2016-09-08 17:41:16 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/output.rb:704:in `block in handle_stream_simple'
  2016-09-08 17:41:16 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/output.rb:610:in `write_guard'
  2016-09-08 17:41:16 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/output.rb:703:in `handle_stream_simple'
  2016-09-08 17:41:16 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/output.rb:600:in `execute_chunking'
  2016-09-08 17:41:16 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/output.rb:544:in `emit_buffered'
  2016-09-08 17:41:16 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/event_router.rb:90:in `emit_stream'
  2016-09-08 17:41:16 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:310:in `receive_lines'
  2016-09-08 17:41:16 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:420:in `wrap_receive_lines'
  2016-09-08 17:41:16 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:579:in `on_notify'
  2016-09-08 17:41:16 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:444:in `on_notify'
  2016-09-08 17:41:16 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin_helper/timer.rb:76:in `on_timer'
  2016-09-08 17:41:16 +0000 [warn]: /var/lib/gems/2.3.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run_once'
  2016-09-08 17:41:16 +0000 [warn]: /var/lib/gems/2.3.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run'
  2016-09-08 17:41:16 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin_helper/event_loop.rb:71:in `block in start'
  2016-09-08 17:41:16 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin_helper/thread.rb:66:in `block in thread_create'
2016-09-08 17:41:17 +0000 [warn]: failed to write data into buffer by buffer overflow
2016-09-08 17:41:17 +0000 [warn]: emit transaction failed: error_class=Fluent::Plugin::Buffer::BufferOverflowError error="buffer space has too many data" tag="fluent.warn"
  2016-09-08 17:41:17 +0000 [warn]: suppressed same stacktrace
2016-09-08 17:41:17 +0000 [error]: failed to emit fluentd's log event tag="fluent.warn" event={"message"=>"failed to write data into buffer by buffer overflow"} error_class=Fluent::Plugin::Buffer::BufferOverflowError error="buffer space has too many data"
2016-09-08 17:41:17 +0000 [warn]: failed to write data into buffer by buffer overflow
2016-09-08 17:41:17 +0000 [warn]: emit transaction failed: error_class=Fluent::Plugin::Buffer::BufferOverflowError error="buffer space has too many data" tag="fluent.warn"
  2016-09-08 17:41:17 +0000 [warn]: suppressed same stacktrace
2016-09-08 17:41:17 +0000 [warn]: failed to write data into buffer by buffer overflow
2016-09-08 17:41:17 +0000 [warn]: emit transaction failed: error_class=Fluent::Plugin::Buffer::BufferOverflowError error="buffer space has too many data" tag="<tag_here>"
  2016-09-08 17:41:17 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/buffer.rb:186:in `write'
  2016-09-08 17:41:17 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/output.rb:704:in `block in handle_stream_simple'
  2016-09-08 17:41:17 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/output.rb:610:in `write_guard'
  2016-09-08 17:41:17 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/output.rb:703:in `handle_stream_simple'
  2016-09-08 17:41:17 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/output.rb:600:in `execute_chunking'
2016-09-08 17:41:17 +0000 [error]: failed to emit fluentd's log event tag="fluent.warn" event={"error"=>"#<Fluent::Plugin::Buffer::BufferOverflowError: buffer space has too many data>", "tag"=>"<tag_here>", "message"=>"emit transaction failed: error_class=Fluent::Plugin::Buffer::BufferOverflowError error=\"buffer space has too many data\" tag=\"<tag_here>\""} error_class=Fluent::Plugin::Buffer::BufferOverflowError error="buffer space has too many data"
  2016-09-08 17:41:17 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/output.rb:544:in `emit_buffered'
  2016-09-08 17:41:17 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/event_router.rb:90:in `emit_stream'
  2016-09-08 17:41:17 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:310:in `receive_lines'
  2016-09-08 17:41:17 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:420:in `wrap_receive_lines'
  2016-09-08 17:41:17 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:579:in `on_notify'
  2016-09-08 17:41:17 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:444:in `on_notify'
  2016-09-08 17:41:17 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_tail.rb:529:in `on_change'
  2016-09-08 17:41:17 +0000 [warn]: /var/lib/gems/2.3.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run_once'
  2016-09-08 17:41:17 +0000 [warn]: /var/lib/gems/2.3.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run'
  2016-09-08 17:41:17 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin_helper/event_loop.rb:71:in `block in start'
  2016-09-08 17:41:17 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin_helper/thread.rb:66:in `block in thread_create'
2016-09-08 17:41:17 +0000 [warn]: failed to write data into buffer by buffer overflow
2016-09-08 17:41:17 +0000 [warn]: emit transaction failed: error_class=Fluent::Plugin::Buffer::BufferOverflowError error="buffer space has too many data" tag="<tag_here>"

From that moment on, logs are filling up with those error/warns.

Regex is extracting around 36 uniq fields, and the stream flow is around 2-3k eps.

The flow is not stopped, and the process is running, however at this stage I'm unable to ascertain is there any data lost due to this behavior.

picture stachdude

Most helpful comment

At first, configure that plugin to have more buffer space by buffer_chunk_limit and buffer_queue_limit. Next, modify flush_interval to flush buffer more frequently.
Of course, authors of amqp plugin might know how to configure for high traffic.

Anyway, it's not bug or any kind of issue of Fluentd core.
It's good to know it.

picture tagomoris on 12 Sep 2016
👍4

All 14 comments

Regex is extracting around 36 uniq fields, and the stream flow is around 2-3k eps.

It seems normal traffic.
Does this happen with fluentd v0.12?
If so, your aggregator doesn't have a lack of capacity.
If this happens with only fluentd v0.14, we need to check buffer flush implementation.

repeatedly picture repeatedly on 8 Sep 2016

If the IO latecy is the problem, adding num_threads may help.

repeatedly picture repeatedly on 8 Sep 2016

My setup is run only on v 0.14.x

IO latency is kind of out of question, as I'm using storage array that is easily capable of reads over 80k.

I've try increasing num_threads up to 4, with the same effect.

@repeatedly I can try to setup v 0.12.x in my environment if that can be helpful.

stachdude picture stachdude on 8 Sep 2016

IO latency is kind of out of question,

This indicates network releated IO of out_forward, not in_tail.

I've try increasing num_threads up to 4, with the same effect.

Interesting. Flushing speed seems not the cause.

I can try to setup v 0.12.x in my environment if that can be helpful.

It would be helpful.

repeatedly picture repeatedly on 9 Sep 2016

@repeatedly I've repeated the tests on v. 0.12.29, unfortunately this is the result of a the stream

2016-09-11 08:05:19 +0000 [warn]: emit transaction failed: error_class=Fluent::BufferQueueLimitError error="queue size exceeds limit" tag="<tag_here>"
  2016-09-11 08:05:19 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/buffer.rb:204:in `block in emit'
  2016-09-11 08:05:19 +0000 [warn]: /usr/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'
  2016-09-11 08:05:19 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/buffer.rb:193:in `emit'
  2016-09-11 08:05:19 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/output.rb:457:in `emit'
  2016-09-11 08:05:19 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/event_router.rb:90:in `emit_stream'
  2016-09-11 08:05:19 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/plugin/in_tail.rb:291:in `receive_lines'
  2016-09-11 08:05:19 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/plugin/in_tail.rb:401:in `wrap_receive_lines'
  2016-09-11 08:05:19 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/plugin/in_tail.rb:596:in `on_notify'
  2016-09-11 08:05:19 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/plugin/in_tail.rb:427:in `on_notify'
  2016-09-11 08:05:19 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/plugin/in_tail.rb:528:in `on_change'
  2016-09-11 08:05:19 +0000 [warn]: /var/lib/gems/2.3.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run_once'
  2016-09-11 08:05:19 +0000 [warn]: /var/lib/gems/2.3.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run'
  2016-09-11 08:05:19 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/plugin/in_tail.rb:275:in `run'

So it seems that, at least in my environment, both versions are affected.

stachdude picture stachdude on 11 Sep 2016

@stachdude do you have log messages just before starting to show "failed to emit fluentd's log event"?
I think that your forward plugin is failing to connect the destination server, and we can see the root cause from logs.

tagomoris picture tagomoris on 12 Sep 2016

@tagomoris actually "failed to emit fluentd's log event" is the first log after normal startup log series.

stachdude picture stachdude on 12 Sep 2016

Please paste the almost entire logs, from "starting fluentd" to the first "failed to emit fluentd's log event".

tagomoris picture tagomoris on 12 Sep 2016 
2016-09-12 08:09:59 +0000 [info]: reading config file path="/fluentd/etc/fluent-forward.conf"
2016-09-12 08:09:59 +0000 [info]: starting fluentd-0.12.29
2016-09-12 08:09:59 +0000 [info]: gem 'fluent-mixin-rewrite-tag-name' version '0.1.0'
2016-09-12 08:09:59 +0000 [info]: gem 'fluent-plugin-amqp' version '0.9.1'
2016-09-12 08:09:59 +0000 [info]: gem 'fluent-plugin-geoip' version '0.6.1'
2016-09-12 08:09:59 +0000 [info]: gem 'fluent-plugin-kafka' version '0.3.1'
2016-09-12 08:09:59 +0000 [info]: gem 'fluent-plugin-multiprocess' version '0.2.1'
2016-09-12 08:09:59 +0000 [info]: gem 'fluentd' version '0.12.29'
2016-09-12 08:09:59 +0000 [info]: adding match pattern="**" type="forward"
2016-09-12 08:09:59 +0000 [info]: adding forwarding server 'IP:24224' host="IP" port=24224 weight=60 plugin_id="object:18a798c"
2016-09-12 08:09:59 +0000 [info]: adding source type="tail"
2016-09-12 08:09:59 +0000 [warn]: 'pos_file PATH' parameter is not set to a 'tail' source.
2016-09-12 08:09:59 +0000 [warn]: this parameter is highly recommended to save the position to resume tailing.
2016-09-12 08:09:59 +0000 [info]: using configuration file: <ROOT>
  <source>
    @type tail
    read_from_head true
    format /REGEX_HERE/
    tag http.*
    path /data/data.log
  </source>
  <match **>
    @type forward
    num_threads 4
    <server>
      host IP
      port 24224
      weight 60
    </server>
  </match>
</ROOT>
2016-09-12 08:09:59 +0000 [info]: following tail of /data/data.log
2016-09-12 08:12:11 +0000 [warn]: emit transaction failed: error_class=Fluent::BufferQueueLimitError error="queue size exceeds limit" tag="<tag_here>"
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/buffer.rb:204:in `block in emit'
  2016-09-12 08:12:11 +0000 [warn]: /usr/lib/ruby/2.3.0/monitor.rb:214:in `mon_synchronize'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/buffer.rb:193:in `emit'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/output.rb:457:in `emit'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/event_router.rb:90:in `emit_stream'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/plugin/in_tail.rb:291:in `receive_lines'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/plugin/in_tail.rb:401:in `wrap_receive_lines'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/plugin/in_tail.rb:596:in `on_notify'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/plugin/in_tail.rb:427:in `on_notify'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/plugin/in_tail.rb:407:in `attach'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/plugin/in_tail.rb:188:in `setup_watcher'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/plugin/in_tail.rb:206:in `block in start_watchers'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/plugin/in_tail.rb:193:in `each'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/plugin/in_tail.rb:193:in `start_watchers'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/plugin/in_tail.rb:182:in `refresh_watchers'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/plugin/in_tail.rb:129:in `start'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/root_agent.rb:115:in `block in start'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/root_agent.rb:114:in `each'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/root_agent.rb:114:in `start'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/engine.rb:237:in `start'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/engine.rb:187:in `run'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:570:in `run_engine'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:162:in `block in start'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:366:in `main_process'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:339:in `block in supervise'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:338:in `fork'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:338:in `supervise'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/supervisor.rb:156:in `start'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/lib/fluent/command/fluentd.rb:173:in `<top (required)>'
  2016-09-12 08:12:11 +0000 [warn]: /usr/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb:55:in `require'
  2016-09-12 08:12:11 +0000 [warn]: /usr/lib/ruby/2.3.0/rubygems/core_ext/kernel_require.rb:55:in `require'
  2016-09-12 08:12:11 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.12.29/bin/fluentd:5:in `<top (required)>'
  2016-09-12 08:12:11 +0000 [warn]: /usr/local/bin/fluentd:23:in `load'
  2016-09-12 08:12:11 +0000 [warn]: /usr/local/bin/fluentd:23:in `<main>'
stachdude picture stachdude on 12 Sep 2016

Is it Fluentd process which is listening the specified IP address and port 24224?
Is it producing output events?

tagomoris picture tagomoris on 12 Sep 2016

Yes, fluentd v 0.14.6.

2016-09-12 08:09:46 +0000 [info]: reading config file path="/fluentd/etc/fluent.conf"
2016-09-12 08:09:46 +0000 [info]: starting fluentd-0.14.6
2016-09-12 08:09:46 +0000 [info]: spawn command to main: /usr/bin/ruby2.3 -Eascii-8bit:ascii-8bit /usr/local/bin/fluentd -c /fluentd/etc/fluent.conf -p /fluentd/plugins --under-supervisor
2016-09-12 08:09:46 +0000 [info]: reading config file path="/fluentd/etc/fluent.conf"
2016-09-12 08:09:46 +0000 [info]: starting fluentd-0.14.6 without supervision
2016-09-12 08:09:46 +0000 [info]: gem 'fluent-plugin-amqp' version '0.9.1'
2016-09-12 08:09:46 +0000 [info]: gem 'fluent-plugin-filter-geoip' version '0.3.0'
2016-09-12 08:09:46 +0000 [info]: gem 'fluent-plugin-kafka' version '0.3.1'
2016-09-12 08:09:46 +0000 [info]: gem 'fluent-plugin-multiprocess' version '0.2.1'
2016-09-12 08:09:46 +0000 [info]: gem 'fluentd' version '0.14.6'
2016-09-12 08:09:46 +0000 [info]: gem 'fluentd' version '0.14.3'
2016-09-12 08:09:46 +0000 [info]: gem 'fluentd' version '0.12.29'
2016-09-12 08:09:46 +0000 [info]: adding filter pattern="**.**" type="geoip"
2016-09-12 08:09:54 +0000 [info]: adding match pattern="**.**" type="amqp"
2016-09-12 08:09:54 +0000 [info]: adding source type="forward"
2016-09-12 08:09:54 +0000 [info]: using configuration file: <ROOT>
  <source>
    @type forward
    port 24224
  </source>
  <filter **.**>
    @type geoip
    enable_auto_download "false"
    database_path "/usr/share/GeoIP/GeoIP2-City.mmdb"
    lookup_field "ipField"
    field_delimiter "."
    flatten true
    locale "en"
    continent true
    country true
    city true
    location true
    postal true
    registered_country true
    represented_country true
    subdivisions true
    traits true
    connection_type true
    @log_level "warn"
  </filter>
  <match **.**>
    buffer_type "memory"
    flush_interval 1s
    @type amqp
    host "amqp.host"
    port 5672
    user "fluent"
    pass xxxxxx
    vhost "/"
    exchange "fluent.receiver"
    exchange_type "topic"
    durable true
    tag_key true
    tag_header "Tag"
    time_header "ts"
    tls true
    tls_key ""
    tls_cert ""
    tls_ca_certificates [""]
    tls_verify_peer true
    @log_level "warn"
    <buffer>
      flush_mode interval
      retry_type exponential_backoff
      @type memory
      flush_interval 1s
    </buffer>
    <inject>
      tag_key true
    </inject>
  </match>
</ROOT>
2016-09-12 08:09:55 +0000 [info]: listening fluent socket on 0.0.0.0:24224
stachdude picture stachdude on 12 Sep 2016

@stachdude Can you monitor the CPU usage status of the node of receiver Fluentd process?
I suppose that the Fluentd process consumes much CPU time to process geoip filter plugin for much many fields.
The filter plugin works in the thread of in_forward, and too heavy filter processing makes the performance worse.

tagomoris picture tagomoris on 12 Sep 2016

@tagomoris you were right...

I've disabled the geoip plugin, and sending side is working fine now... however on receiving side, where I have now only amqp plugin enabled:

2016-09-12 11:06:27 +0000 [info]: reading config file path="/fluentd/etc/fluent.conf"
2016-09-12 11:06:27 +0000 [info]: starting fluentd-0.14.6
2016-09-12 11:06:27 +0000 [info]: spawn command to main: /usr/bin/ruby2.3 -Eascii-8bit:ascii-8bit /usr/local/bin/fluentd -c /fluentd/etc/fluent.conf -p /fluentd/plugins --under-supervisor
2016-09-12 11:06:27 +0000 [info]: reading config file path="/fluentd/etc/fluent.conf"
2016-09-12 11:06:27 +0000 [info]: starting fluentd-0.14.6 without supervision
2016-09-12 11:06:27 +0000 [info]: gem 'fluent-plugin-amqp' version '0.9.1'
2016-09-12 11:06:27 +0000 [info]: gem 'fluent-plugin-filter-geoip' version '0.3.0'
2016-09-12 11:06:27 +0000 [info]: gem 'fluent-plugin-kafka' version '0.3.1'
2016-09-12 11:06:27 +0000 [info]: gem 'fluent-plugin-multiprocess' version '0.2.1'
2016-09-12 11:06:27 +0000 [info]: gem 'fluentd' version '0.14.6'
2016-09-12 11:06:27 +0000 [info]: gem 'fluentd' version '0.14.3'
2016-09-12 11:06:27 +0000 [info]: gem 'fluentd' version '0.12.29'
2016-09-12 11:06:27 +0000 [info]: adding match pattern="**.**" type="amqp"
2016-09-12 11:06:27 +0000 [info]: adding source type="forward"
2016-09-12 11:06:27 +0000 [info]: using configuration file: <ROOT>
  <source>
    @type forward
    port 24224
  </source>
  <match **.**>
    @type amqp
    host "amqp.host"
    port 5672
    user "fluent"
    pass xxxxxx
    vhost "/"
    exchange "fluent.receiver"
    exchange_type "topic"
    durable true
    tag_key true
    tag_header "Tag"
    time_header "ts"
    tls true
    tls_key ""
    tls_cert ""
    tls_ca_certificates [""]
    tls_verify_peer true
    num_threads 4
    @log_level "warn"
    <buffer>
      flush_mode interval
      retry_type exponential_backoff
      flush_thread_count 4
    </buffer>
    <inject>
      tag_key true
    </inject>
  </match>
</ROOT>
2016-09-12 11:06:27 +0000 [info]: listening fluent socket on 0.0.0.0:24224
2016-09-12 11:09:43 +0000 [warn]: [Fluent::AMQPOutput] failed to write data into buffer by buffer overflow
2016-09-12 11:09:43 +0000 [warn]: emit transaction failed: error_class=Fluent::Plugin::Buffer::BufferOverflowError error="buffer space has too many data" tag="<tag_here>"
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/buffer.rb:186:in `write'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/compat/output.rb:369:in `block in handle_stream_simple'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/output.rb:610:in `write_guard'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/compat/output.rb:368:in `handle_stream_simple'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/output.rb:600:in `execute_chunking'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/output.rb:544:in `emit_buffered'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/event_router.rb:90:in `emit_stream'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_forward.rb:344:in `on_message'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_forward.rb:231:in `block in handle_connection'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_forward.rb:272:in `block (3 levels) in read_messages'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_forward.rb:271:in `feed_each'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_forward.rb:271:in `block (2 levels) in read_messages'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_forward.rb:280:in `block in read_messages'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_forward.rb:559:in `on_read'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/cool.io-1.4.5/lib/cool.io/io.rb:123:in `on_readable'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/cool.io-1.4.5/lib/cool.io/io.rb:186:in `on_readable'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run_once'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/cool.io-1.4.5/lib/cool.io/loop.rb:88:in `run'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/in_forward.rb:190:in `run'
2016-09-12 11:09:43 +0000 [error]: unexpected error on reading data from client address="172.20.1.10" error_class=Fluent::Plugin::Buffer::BufferOverflowError error="buffer space has too many data"
  2016-09-12 11:09:43 +0000 [error]: suppressed same stacktrace
2016-09-12 11:09:43 +0000 [warn]: [Fluent::AMQPOutput] failed to write data into buffer by buffer overflow
2016-09-12 11:09:43 +0000 [warn]: emit transaction failed: error_class=Fluent::Plugin::Buffer::BufferOverflowError error="buffer space has too many data" tag="fluent.warn"
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/buffer.rb:186:in `write'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/compat/output.rb:369:in `block in handle_stream_simple'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/output.rb:610:in `write_guard'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/compat/output.rb:368:in `handle_stream_simple'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/output.rb:600:in `execute_chunking'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/plugin/output.rb:544:in `emit_buffered'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/event_router.rb:90:in `emit_stream'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/event_router.rb:81:in `emit'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/engine.rb:165:in `block in log_event_loop'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/engine.rb:163:in `each'
  2016-09-12 11:09:43 +0000 [warn]: /var/lib/gems/2.3.0/gems/fluentd-0.14.6/lib/fluent/engine.rb:163:in `log_event_loop'
2016-09-12 11:09:43 +0000 [error]: failed to emit fluentd's log event tag="fluent.warn" event={"message"=>"[Fluent::AMQPOutput] failed to write data into buffer by buffer overflow"} error_class=Fluent::Plugin::Buffer::BufferOverflowError error="buffer space has too many data"
2016-09-12 11:09:43 +0000 [warn]: [Fluent::AMQPOutput] failed to write data into buffer by buffer overflow
2016-09-12 11:09:43 +0000 [warn]: emit transaction failed: error_class=Fluent::Plugin::Buffer::BufferOverflowError error="buffer space has too many data" tag="fluent.warn"

this happens... But I guess now it's an issue I should post on amqp plugin project site ? Tho this seems to be a strange behavior for a 3k eps.

stachdude picture stachdude on 12 Sep 2016

At first, configure that plugin to have more buffer space by buffer_chunk_limit and buffer_queue_limit. Next, modify flush_interval to flush buffer more frequently.
Of course, authors of amqp plugin might know how to configure for high traffic.

Anyway, it's not bug or any kind of issue of Fluentd core.
It's good to know it.

tagomoris picture tagomoris on 12 Sep 2016
👍4
Was this page helpful?
0 / 5 - 0 ratings

Related issues

rolindroy picture rolindroy  路  7Comments
epcim picture epcim  路  3Comments
pdecat picture pdecat  路  7Comments
dcvtruong picture dcvtruong  路  3Comments
amread picture amread  路  5Comments