Fluentd crashes #1098

perrin4869 · 2016-07-13T01:22:49Z

Running fluentd 0.14.1, installed with gem, on Arch Linux. I setup a simple fluent.conf demo like this:

<source>
  @type forward
  port 24224
</source>

<filter demo.temperature>
  @type record_transformer
  enable_ruby true
  <record>
    cpu_temp ${record["cpu_temp"] + 273.1}
  </record>
</filter>

<match demo.temperature>
  @type file
  path temperature
  flush_interval 1s
  append true
</match>

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

And I fed it data with a python script as follows:

#!/usr/bin/env python
import threading
from random import random
from fluent import event, sender


def set_interval(func, sec):
    def func_wrapper():
        set_interval(func, sec)
        func()
    t = threading.Timer(sec, func_wrapper)
    t.start()
    return t


def send_event():
    temp = 70 + random() * (120 - 70)  # 70 to 100
    e = {"hostname": "somehost", "cpu_temp": temp}
    event.Event("temperature", e)

    print(e)


if __name__ == "__main__":
    sender.setup('demo', host='localhost', port=24224)
    set_interval(send_event, 1)

However, fluentd goes crazy after a short while. The directory with the fluentd configuration file gets filled with buffer files:

demo.py
fluentd.conf
requirements.txt
temperature.20160713.log
temperature.b5377a1127d7372b0cce743309564537e.log
temperature.b5377a1127d7372b0cce743309564537e.log.meta
temperature.q5377a0ef3166873b918670336db4363b.log
temperature.q5377a0ef3166873b918670336db4363b.log.meta
temperature.q5377a0f0259024f31fbd332a6b46d5d0.log
temperature.q5377a0f0259024f31fbd332a6b46d5d0.log.meta
temperature.q5377a0f119b896c8c47a246b8c5beb3e.log
temperature.q5377a0f119b896c8c47a246b8c5beb3e.log.meta
temperature.q5377a0f20df0d19d406ccd7bfce1b7ac.log
temperature.q5377a0f20df0d19d406ccd7bfce1b7ac.log.meta
temperature.q5377a0f3023b750a28abbe69ad70814a.log
temperature.q5377a0f3023b750a28abbe69ad70814a.log.meta
temperature.q5377a0f3f65fa1859ba3e9d757e6c354.log
temperature.q5377a0f3f65fa1859ba3e9d757e6c354.log.meta
temperature.q5377a0f4ea975c703d1a09a1851b4941.log
temperature.q5377a0f4ea975c703d1a09a1851b4941.log.meta
temperature.q5377a0f5ded4e986152edef1f0ac5a25.log
temperature.q5377a0f5ded4e986152edef1f0ac5a25.log.meta
temperature.q5377a0f6d30d0540bc30e18159e6ba58.log
temperature.q5377a0f6d30d0540bc30e18159e6ba58.log.meta
temperature.q5377a0f7c7429d5f36b185742e212109.log
temperature.q5377a0f7c7429d5f36b185742e212109.log.meta
temperature.q5377a0f8bb79791d30682c34af3c1427.log
temperature.q5377a0f8bb79791d30682c34af3c1427.log.meta
temperature.q5377a0f9afbe277a9716c4c9d0665545.log
temperature.q5377a0f9afbe277a9716c4c9d0665545.log.meta
temperature.q5377a0faa422051a5e377990842dc252.log
temperature.q5377a0faa422051a5e377990842dc252.log.meta
temperature.q5377a0fb983431366edd54cb8ce22488.log
temperature.q5377a0fb983431366edd54cb8ce22488.log.meta
temperature.q5377a0fc8c6b774ffe008bf0c5f57037.log
temperature.q5377a0fc8c6b774ffe008bf0c5f57037.log.meta
temperature.q5377a0fd80a63a9cf2747d50ee657932.log
temperature.q5377a0fd80a63a9cf2747d50ee657932.log.meta
temperature.q5377a0fe74dc694dd158ad01cd33660e.log
temperature.q5377a0fe74dc694dd158ad01cd33660e.log.meta
temperature.q5377a0ff691f91a3e90fc0249bc90f73.log
temperature.q5377a0ff691f91a3e90fc0249bc90f73.log.meta
temperature.q5377a1005d45b5e1839042e134b95a4b.log
temperature.q5377a1005d45b5e1839042e134b95a4b.log.meta
temperature.q5377a101518dba28a4d1fa385cb81e67.log
# and many more like this

Trying to close fluentd with SIGINT or SIGTERM fails, so I killed it with SIGKILL:

2016-07-13 10:10:59 +0900 [info]: plugin/in_forward.rb:99:listen: listening fluent socket on 0.0.0.0:24224
2016-07-13 10:10:59 +0900 [trace]: plugin/in_forward.rb:246:initialize: accepted fluent socket from '127.0.0.1:49676': object_id=12974500
2016-07-13 10:10:59 +0900 fluent.trace: {"message":"accepted fluent socket from '127.0.0.1:49676': object_id=12974500"}
^C2016-07-13 10:11:36 +0900 [debug]: fluent/supervisor.rb:489:block in install_main_process_signal_handlers: fluentd main process get SIGINT
2016-07-13 10:11:36 +0900 [info]: serverengine/server.rb:43:stop: Received graceful stop
2016-07-13 10:11:36 +0900 fluent.debug: {"message":"fluentd main process get SIGINT"}
2016-07-13 10:11:37 +0900 [debug]: fluent/supervisor.rb:493:block in install_main_process_signal_handlers: fluentd main process get SIGTERM
2016-07-13 10:11:37 +0900 [debug]: fluent/supervisor.rb:496:block in install_main_process_signal_handlers: getting start to shutdown main process
2016-07-13 10:11:37 +0900 [info]: fluent/engine.rb:190:run: shutting down fluentd
2016-07-13 10:11:37 +0900 [debug]: fluent/root_agent.rb:170:block (2 levels) in shutdown: calling stop on input plugin type=:forward plugin_id="object:cb5700"
2016-07-13 10:11:37 +0900 [debug]: fluent/root_agent.rb:170:block (2 levels) in shutdown: calling stop on output plugin type=:file plugin_id="object:a9b154"
2016-07-13 10:11:37 +0900 [debug]: fluent/root_agent.rb:170:block (2 levels) in shutdown: calling stop on filter plugin type=:record_transformer plugin_id="object:edecac"
2016-07-13 10:11:37 +0900 [debug]: fluent/root_agent.rb:170:block (2 levels) in shutdown: calling stop on output plugin type=:stdout plugin_id="object:f683e4"
2016-07-13 10:11:37 +0900 fluent.debug: {"message":"fluentd main process get SIGTERM"}
2016-07-13 10:11:37 +0900 fluent.debug: {"message":"getting start to shutdown main process"}
2016-07-13 10:11:37 +0900 fluent.info: {"message":"shutting down fluentd"}
2016-07-13 10:11:37 +0900 fluent.debug: {"type":"forward","plugin_id":"object:cb5700","message":"calling stop on input plugin type=:forward plugin_id=\"object:cb5700\""}
2016-07-13 10:11:37 +0900 fluent.debug: {"type":"file","plugin_id":"object:a9b154","message":"calling stop on output plugin type=:file plugin_id=\"object:a9b154\""}
2016-07-13 10:11:37 +0900 [info]: fluent/root_agent.rb:196:block (3 levels) in shutdown: preparing shutdown input plugin type=:forward plugin_id="object:cb5700"
2016-07-13 10:11:37 +0900 [info]: fluent/root_agent.rb:196:block (3 levels) in shutdown: preparing shutdown output plugin type=:file plugin_id="object:a9b154"
2016-07-13 10:11:37 +0900 fluent.debug: {"type":"record_transformer","plugin_id":"object:edecac","message":"calling stop on filter plugin type=:record_transformer plugin_id=\"object:edecac\""}
2016-07-13 10:11:37 +0900 [info]: fluent/root_agent.rb:196:block (3 levels) in shutdown: preparing shutdown filter plugin type=:record_transformer plugin_id="object:edecac"
2016-07-13 10:11:37 +0900 fluent.debug: {"type":"stdout","plugin_id":"object:f683e4","message":"calling stop on output plugin type=:stdout plugin_id=\"object:f683e4\""}
2016-07-13 10:11:37 +0900 [info]: fluent/root_agent.rb:196:block (3 levels) in shutdown: preparing shutdown output plugin type=:stdout plugin_id="object:f683e4"
2016-07-13 10:11:37 +0900 [info]: fluent/root_agent.rb:196:block (3 levels) in shutdown: shutting down input plugin type=:forward plugin_id="object:cb5700"
2016-07-13 10:11:37 +0900 fluent.info: {"type":"forward","plugin_id":"object:cb5700","message":"preparing shutdown input plugin type=:forward plugin_id=\"object:cb5700\""}
2016-07-13 10:11:37 +0900 fluent.info: {"type":"file","plugin_id":"object:a9b154","message":"preparing shutdown output plugin type=:file plugin_id=\"object:a9b154\""}
2016-07-13 10:11:37 +0900 fluent.info: {"type":"record_transformer","plugin_id":"object:edecac","message":"preparing shutdown filter plugin type=:record_transformer plugin_id=\"object:edecac\""}
2016-07-13 10:11:37 +0900 fluent.info: {"type":"stdout","plugin_id":"object:f683e4","message":"preparing shutdown output plugin type=:stdout plugin_id=\"object:f683e4\""}
2016-07-13 10:11:37 +0900 fluent.info: {"type":"forward","plugin_id":"object:cb5700","message":"shutting down input plugin type=:forward plugin_id=\"object:cb5700\""}
2016-07-13 10:11:37 +0900 [info]: fluent/root_agent.rb:196:block (3 levels) in shutdown: shutting down output plugin type=:file plugin_id="object:a9b154"
2016-07-13 10:11:37 +0900 [info]: fluent/root_agent.rb:196:block (3 levels) in shutdown: shutting down filter plugin type=:record_transformer plugin_id="object:edecac"
2016-07-13 10:11:37 +0900 [info]: fluent/root_agent.rb:196:block (3 levels) in shutdown: shutting down output plugin type=:stdout plugin_id="object:f683e4"
2016-07-13 10:11:37 +0900 [debug]: fluent/root_agent.rb:170:block (2 levels) in shutdown: calling after_shutdown on input plugin type=:forward plugin_id="object:cb5700"
2016-07-13 10:11:37 +0900 [debug]: fluent/root_agent.rb:170:block (2 levels) in shutdown: calling after_shutdown on output plugin type=:file plugin_id="object:a9b154"
2016-07-13 10:11:37 +0900 fluent.info: {"type":"file","plugin_id":"object:a9b154","message":"shutting down output plugin type=:file plugin_id=\"object:a9b154\""}
2016-07-13 10:11:37 +0900 fluent.info: {"type":"record_transformer","plugin_id":"object:edecac","message":"shutting down filter plugin type=:record_transformer plugin_id=\"object:edecac\""}
2016-07-13 10:11:37 +0900 fluent.info: {"type":"stdout","plugin_id":"object:f683e4","message":"shutting down output plugin type=:stdout plugin_id=\"object:f683e4\""}
2016-07-13 10:11:37 +0900 fluent.debug: {"type":"forward","plugin_id":"object:cb5700","message":"calling after_shutdown on input plugin type=:forward plugin_id=\"object:cb5700\""}
2016-07-13 10:11:37 +0900 fluent.debug: {"type":"file","plugin_id":"object:a9b154","message":"calling after_shutdown on output plugin type=:file plugin_id=\"object:a9b154\""}
[1]    26900 killed     fluentd -c ./fluentd.conf -vv

If I let it keep running it crashes my computer.
Thanks!

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

repeatedly · 2016-07-14T00:05:02Z

I tested your configuration and it worked without problem in 25 minutes.
Is this problem reproducible?

buffer result

% wc -l buf/temperature.*
    1490 buf/temperature.20160713.log
       1 buf/temperature.b5378d282363305afcaf2199a7c31ffcc.log
       0 buf/temperature.b5378d282363305afcaf2199a7c31ffcc.log.meta
    1491 total

fluentd log

2016-07-14 08:33:04 +0900 [info]: reading config file path="fluent.conf"
2016-07-14 08:33:04 +0900 [info]: starting fluentd-0.14.1
2016-07-14 08:33:04 +0900 [info]: spawn command to main: /Users/repeatedly/.rbenv/versions/2.3.1/bin/ruby -Eascii-8bit:ascii-8bit /Users/repeatedly/.rbenv/versions/2.3.1/bin/fluentd -c fluent.conf --under-supervisor
2016-07-14 08:33:04 +0900 [info]: reading config file path="fluent.conf"
2016-07-14 08:33:04 +0900 [info]: starting fluentd-0.14.1 without supervision
[snip]
2016-07-14 08:33:05 +0900 [info]: adding filter pattern="demo.temperature" type="record_transformer"
2016-07-14 08:33:05 +0900 [info]: adding match pattern="demo.temperature" type="file"
2016-07-14 08:33:05 +0900 [info]: adding match pattern="**" type="stdout"
2016-07-14 08:33:05 +0900 [info]: adding source type="forward"
2016-07-14 08:33:05 +0900 [info]: using configuration file: <ROOT>
  <source>
    @type forward
    port 24224
  </source>
  <filter demo.temperature>
    @type record_transformer
    enable_ruby true
    <record>
      cpu_temp ${record["cpu_temp"] + 273.1}
    </record>
  </filter>
  <match demo.temperature>
    @type file
    path "/path/to/temperature"
    flush_interval 1s
    append true
    buffer_path /path/to/temperature.*
    <buffer time>
      flush_mode interval
      retry_type exponential_backoff
      path /path/to/temperature.*
      flush_interval 1s
      timekey 86400
    </buffer>
  </match>
  <match **>
    @type stdout
  </match>
</ROOT>
016-07-14 08:33:05 +0900 [info]: listening fluent socket on 0.0.0.0:24224
        ^C2016-07-14 08:58:06 +0900 [info]: Received graceful stop
2016-07-14 08:58:07 +0900 [info]: shutting down fluentd
2016-07-14 08:58:07 +0900 [info]: preparing shutdown input plugin type=:forward plugin_id="object:3fe25a1110d0"
2016-07-14 08:58:07 +0900 [info]: preparing shutdown output plugin type=:file plugin_id="object:3fe259099c84"
2016-07-14 08:58:07 +0900 [info]: preparing shutdown filter plugin type=:record_transformer plugin_id="object:3fe25985cde0"
2016-07-14 08:58:07 +0900 [info]: preparing shutdown output plugin type=:stdout plugin_id="object:3fe2594cb7bc"
2016-07-14 08:58:07 +0900 [info]: shutting down input plugin type=:forward plugin_id="object:3fe25a1110d0"
2016-07-14 08:58:07 +0900 [info]: shutting down output plugin type=:file plugin_id="object:3fe259099c84"
2016-07-14 08:58:07 +0900 [info]: shutting down filter plugin type=:record_transformer plugin_id="object:3fe25985cde0"
2016-07-14 08:58:07 +0900 [info]: shutting down output plugin type=:stdout plugin_id="object:3fe2594cb7bc"
2016-07-14 08:58:07 +0900 [info]: closing input plugin type=:forward plugin_id="object:3fe25a1110d0"
2016-07-14 08:58:07 +0900 [info]: closing output plugin type=:file plugin_id="object:3fe259099c84"
2016-07-14 08:58:07 +0900 fluent.info: {"message":"shutting down fluentd"}
2016-07-14 08:58:07 +0900 fluent.info: {"type":"forward","plugin_id":"object:3fe25a1110d0","message":"preparing shutdown input plugin type=:forward plugin_id=\"object:3fe25a1110d0\""}
2016-07-14 08:58:07 +0900 fluent.info: {"type":"file","plugin_id":"object:3fe259099c84","message":"preparing shutdown output plugin type=:file plugin_id=\"object:3fe259099c84\""}
2016-07-14 08:58:07 +0900 fluent.info: {"type":"record_transformer","plugin_id":"object:3fe25985cde0","message":"preparing shutdown filter plugin type=:record_transformer plugin_id=\"object:3fe25985cde0\""}
2016-07-14 08:58:07 +0900 fluent.info: {"type":"stdout","plugin_id":"object:3fe2594cb7bc","message":"preparing shutdown output plugin type=:stdout plugin_id=\"object:3fe2594cb7bc\""}
2016-07-14 08:58:07 +0900 fluent.info: {"type":"forward","plugin_id":"object:3fe25a1110d0","message":"shutting down input plugin type=:forward plugin_id=\"object:3fe25a1110d0\""}
2016-07-14 08:58:07 +0900 fluent.info: {"type":"file","plugin_id":"object:3fe259099c84","message":"shutting down output plugin type=:file plugin_id=\"object:3fe259099c84\""}
2016-07-14 08:58:07 +0900 fluent.info: {"type":"record_transformer","plugin_id":"object:3fe25985cde0","message":"shutting down filter plugin type=:record_transformer plugin_id=\"object:3fe25985cde0\""}
2016-07-14 08:58:07 +0900 fluent.info: {"type":"stdout","plugin_id":"object:3fe2594cb7bc","message":"shutting down output plugin type=:stdout plugin_id=\"object:3fe2594cb7bc\""}
2016-07-14 08:58:07 +0900 fluent.info: {"type":"forward","plugin_id":"object:3fe25a1110d0","message":"closing input plugin type=:forward plugin_id=\"object:3fe25a1110d0\""}
2016-07-14 08:58:07 +0900 fluent.info: {"type":"file","plugin_id":"object:3fe259099c84","message":"closing output plugin type=:file plugin_id=\"object:3fe259099c84\""}
2016-07-14 08:58:07 +0900 [info]: closing filter plugin type=:record_transformer plugin_id="object:3fe25985cde0"
2016-07-14 08:58:07 +0900 [info]: closing output plugin type=:stdout plugin_id="object:3fe2594cb7bc"
2016-07-14 08:58:07 +0900 [info]: Worker 0 finished with status 0

perrin4869 · 2016-07-14T06:05:58Z

Hi, thank you for your response! Actually, I have been able to reproduce it with the following steps:

Run fluentd with the config above
Run the python script.
Send SIGINT to fluentd
Start fluentd again

It will then do the behavior I described above. Maybe it has to do with buffer files not being cleaned up?

perrin4869 · 2016-07-20T07:06:22Z

@repeatedly could you reproduce this behavior? Just wondering :)

repeatedly · 2016-07-20T08:52:57Z

Yeah, I will try it.

nokute78 · 2016-07-20T09:28:50Z

I can reproduce similar issue without signal and python.
If the output file already exists before executing fluentd, this issue will be happened.

The issue is that fluentd generates very huge file.

How to reproduce

I strongly recommend to send Ctrl+Z ASAP after executing fluentd.

Generate output file .
Execute fluentd with perrin4869's config.

I generated like this.

$ echo "foobar" > temperature.`ruby -e 'puts Time.now.strftime("%Y%m%d")'`.log

Environment

ruby 2.2.4p230 (2015-12-16 revision 53155) [x86_64-linux]
fluentd 0.14.1 (installed with gem.)
CentOS 6.8

Result

[taka@localhost issue1098]$ ls
a.conf  test.py
[taka@localhost issue1098]$ echo "foobar" > temperature.`ruby -e 'puts Time.now.strftime("%Y%m%d")'`.log
[taka@localhost issue1098]$ ls
a.conf  temperature.20160720.log  test.py
[taka@localhost issue1098]$ fluentd -c a.conf -vv2016-07-20 18:22:35 +0900 [info]: fluent/supervisor.rb:557:read_config: reading config file path="a.conf"
2016-07-20 18:22:35 +0900 [info]: fluent/supervisor.rb:440:supervise: starting fluentd-0.14.1
2016-07-20 18:22:35 +0900 [info]: fluent/supervisor.rb:461:supervise: spawn command to main: /home/taka/.rvm/rubies/ruby-2.2.4/bin/ruby -Eascii-8bit:ascii-8bit /home/taka/.rvm/gems/ruby-2.2.4@fluentd014/bin/fluentd -c a.conf -vv --under-supervisor
2016-07-20 18:22:36 +0900 [info]: fluent/supervisor.rb:557:read_config: reading config file path="a.conf"
2016-07-20 18:22:36 +0900 [info]: fluent/supervisor.rb:383:run_worker: starting fluentd-0.14.1 without supervision
2016-07-20 18:22:36 +0900 [info]: fluent/engine.rb:116:block in configure: gem 'fluentd' version '0.14.1'
2016-07-20 18:22:36 +0900 [info]: fluent/agent.rb:143:add_filter: adding filter pattern="demo.temperature" type="record_transformer"
2016-07-20 18:22:36 +0900 [trace]: fluent/plugin.rb:140:register_impl: registered filter plugin 'record_transformer'
2016-07-20 18:22:36 +0900 [info]: fluent/agent.rb:131:add_match: adding match pattern="demo.temperature" type="file"
2016-07-20 18:22:36 +0900 [trace]: fluent/plugin.rb:140:register_impl: registered output plugin 'file'
2016-07-20 18:22:36 +0900 [trace]: fluent/plugin.rb:140:register_impl: registered buffer plugin 'file'
2016-07-20 18:22:36 +0900 [trace]: fluent/plugin.rb:140:register_impl: registered formatter plugin 'out_file'
2016-07-20 18:22:36 +0900 [info]: fluent/agent.rb:131:add_match: adding match pattern="**" type="stdout"
2016-07-20 18:22:36 +0900 [trace]: fluent/plugin.rb:140:register_impl: registered output plugin 'stdout'
2016-07-20 18:22:36 +0900 [trace]: fluent/plugin.rb:140:register_impl: registered formatter plugin 'json'
2016-07-20 18:22:36 +0900 [info]: fluent/root_agent.rb:227:add_source: adding source type="forward"
2016-07-20 18:22:36 +0900 [trace]: fluent/plugin.rb:140:register_impl: registered input plugin 'forward'
2016-07-20 18:22:36 +0900 [info]: fluent/engine.rb:123:configure: using configuration file: <ROOT>
  <source>
    @type forward
    port 24224
  </source>
  <filter demo.temperature>
    @type record_transformer
    enable_ruby true
    <record>
      cpu_temp ${record["cpu_temp"] + 273.1}
    </record>
  </filter>
  <match demo.temperature>
    @type file
    path "temperature"
    flush_interval 1s
    append true
    buffer_path temperature.*
    <buffer time>
      flush_mode interval
      retry_type exponential_backoff
      path temperature.*
      flush_interval 1s
      timekey 86400
    </buffer>
  </match>
  <match **>
    @type stdout
  </match>
</ROOT>
2016-07-20 18:22:36 +0900 [info]: plugin/in_forward.rb:99:listen: listening fluent socket on 0.0.0.0:24224
^C2016-07-20 18:22:37 +0900 [debug]: fluent/supervisor.rb:489:block in install_main_process_signal_handlers: fluentd main process get SIGINT
2016-07-20 18:22:37 +0900 [info]: serverengine/server.rb:43:stop: Received graceful stop
2016-07-20 18:22:37 +0900 fluent.debug: {"message":"fluentd main process get SIGINT"}
2016-07-20 18:22:38 +0900 [debug]: fluent/supervisor.rb:493:block in install_main_process_signal_handlers: fluentd main process get SIGTERM
2016-07-20 18:22:38 +0900 [debug]: fluent/supervisor.rb:496:block in install_main_process_signal_handlers: getting start to shutdown main process
2016-07-20 18:22:38 +0900 fluent.debug: {"message":"fluentd main process get SIGTERM"}
2016-07-20 18:22:38 +0900 fluent.debug: {"message":"getting start to shutdown main process"}
2016-07-20 18:22:38 +0900 [info]: fluent/engine.rb:190:run: shutting down fluentd
2016-07-20 18:22:38 +0900 [debug]: fluent/root_agent.rb:170:block (2 levels) in shutdown: calling stop on input plugin type=:forward plugin_id="object:d75af0"
2016-07-20 18:22:38 +0900 [debug]: fluent/root_agent.rb:170:block (2 levels) in shutdown: calling stop on output plugin type=:file plugin_id="object:e47ec4"
2016-07-20 18:22:38 +0900 [debug]: fluent/root_agent.rb:170:block (2 levels) in shutdown: calling stop on filter plugin type=:record_transformer plugin_id="object:6017ec"
2016-07-20 18:22:38 +0900 [debug]: fluent/root_agent.rb:170:block (2 levels) in shutdown: calling stop on output plugin type=:stdout plugin_id="object:dc16a8"
2016-07-20 18:22:38 +0900 [info]: fluent/root_agent.rb:196:block (3 levels) in shutdown: preparing shutdown input plugin type=:forward plugin_id="object:d75af0"
2016-07-20 18:22:38 +0900 [info]: fluent/root_agent.rb:196:block (3 levels) in shutdown: preparing shutdown output plugin type=:file plugin_id="object:e47ec4"
2016-07-20 18:22:38 +0900 [info]: fluent/root_agent.rb:196:block (3 levels) in shutdown: preparing shutdown filter plugin type=:record_transformer plugin_id="object:6017ec"
2016-07-20 18:22:38 +0900 [info]: fluent/root_agent.rb:196:block (3 levels) in shutdown: preparing shutdown output plugin type=:stdout plugin_id="object:dc16a8"
2016-07-20 18:22:38 +0900 fluent.info: {"message":"shutting down fluentd"}
2016-07-20 18:22:38 +0900 fluent.debug: {"type":"forward","plugin_id":"object:d75af0","message":"calling stop on input plugin type=:forward plugin_id=\"object:d75af0\""}
2016-07-20 18:22:38 +0900 fluent.debug: {"type":"file","plugin_id":"object:e47ec4","message":"calling stop on output plugin type=:file plugin_id=\"object:e47ec4\""}
2016-07-20 18:22:38 +0900 fluent.debug: {"type":"record_transformer","plugin_id":"object:6017ec","message":"calling stop on filter plugin type=:record_transformer plugin_id=\"object:6017ec\""}
2016-07-20 18:22:38 +0900 fluent.debug: {"type":"stdout","plugin_id":"object:dc16a8","message":"calling stop on output plugin type=:stdout plugin_id=\"object:dc16a8\""}
2016-07-20 18:22:38 +0900 fluent.info: {"type":"forward","plugin_id":"object:d75af0","message":"preparing shutdown input plugin type=:forward plugin_id=\"object:d75af0\""}
2016-07-20 18:22:38 +0900 fluent.info: {"type":"file","plugin_id":"object:e47ec4","message":"preparing shutdown output plugin type=:file plugin_id=\"object:e47ec4\""}
2016-07-20 18:22:38 +0900 fluent.info: {"type":"record_transformer","plugin_id":"object:6017ec","message":"preparing shutdown filter plugin type=:record_transformer plugin_id=\"object:6017ec\""}
2016-07-20 18:22:38 +0900 fluent.info: {"type":"stdout","plugin_id":"object:dc16a8","message":"preparing shutdown output plugin type=:stdout plugin_id=\"object:dc16a8\""}
2016-07-20 18:22:38 +0900 [info]: fluent/root_agent.rb:196:block (3 levels) in shutdown: shutting down input plugin type=:forward plugin_id="object:d75af0"
2016-07-20 18:22:38 +0900 fluent.info: {"type":"forward","plugin_id":"object:d75af0","message":"shutting down input plugin type=:forward plugin_id=\"object:d75af0\""}
^Z
[1]+  Stopped                  fluentd -c a.conf -vv
[taka@localhost issue1098]$ wc temperature.20160720.log 
 527548  527548 3692836 temperature.20160720.log
[taka@localhost issue1098]$

note

The file is written only "foobar" which is came from echo(1).

[taka@localhost issue1098]$ grep -v foobar temperature.20160720.log 
[taka@localhost issue1098]$

tagomoris · 2016-07-21T02:27:01Z

I'll fix this problem at next version (v0.14.2).
The workaround for this issue is to use different directly between path and buffer path.

perrin4869 · 2016-07-21T11:30:27Z

got it, looking forward to it! Thanks!

repeatedly · 2016-07-26T23:21:35Z

@perrin4869 Could you test #1124 patch?

perrin4869 · 2016-07-27T05:55:20Z

Sorry for the stupid question, but how do I install the patch? Can gem install from a github branch?
I'm not very proficient in ruby ><;;

tagomoris · 2016-07-27T10:22:01Z

Steps to build fluentd.gem with the patch above:

# ruby 2.1 or later required
git clone https://github.com/fluent/fluentd.git
cd fluentd
gem install bundler
git checkout -b ignore-non-buffer-chunk-files origin/ignore-non-buffer-chunk-files
bundle exec rake build
# install
gem install pkg/fluentd-0.14.1.gem

repeatedly · 2016-07-27T11:30:24Z

You can also test the patch without gem install.
After checkout, add fluentd library path to fluentd command like below.

$ RUBYLIB=/path/to/fluentd/lib fluentd -c ./fluentd.conf -vv

If you clone the repository to /home/user/fluentd, actual command is RUBYLIB=/home/user/fluentd/lib fluentd -c ./fluentd.conf

perrin4869 · 2016-07-28T01:05:52Z

I did the following, inside the

git clone https://github.com/fluent/fluentd
( cd fluentd && git checkout -b ignore-non-buffer-chunk-files origin/ignore-non-buffer-chunk-files )
RUBYLIB=fluentd/lib fluentd -c ./fluentd.conf -vv

I get these messages every second:

2016-07-28 10:04:41 +0900 [debug]: plugin/buffer.rb:336:enqueue_all: enqueueing all chunks in buffer instance=15614620
2016-07-28 10:04:41 +0900 [debug]: plugin/buffer.rb:336:enqueue_all: enqueueing all chunks in buffer instance=15614620
2016-07-28 10:04:41 +0900 fluent.debug: {"instance":15614620,"message":"enqueueing all chunks in buffer instance=15614620"}
2016-07-28 10:04:41 +0900 fluent.debug: {"instance":15614620,"message":"enqueueing all chunks in buffer instance=15614620"}
2016-07-28 10:04:42 +0900 [debug]: plugin/buffer.rb:336:enqueue_all: enqueueing all chunks in buffer instance=15614620
2016-07-28 10:04:42 +0900 [debug]: plugin/buffer.rb:336:enqueue_all: enqueueing all chunks in buffer instance=15614620
2016-07-28 10:04:42 +0900 fluent.debug: {"instance":15614620,"message":"enqueueing all chunks in buffer instance=15614620"}
2016-07-28 10:04:42 +0900 fluent.debug: {"instance":15614620,"message":"enqueueing all chunks in buffer instance=15614620"}
2016-07-28 10:04:43 +0900 [debug]: plugin/buffer.rb:336:enqueue_all: enqueueing all chunks in buffer instance=15614620
2016-07-28 10:04:43 +0900 [debug]: plugin/buffer.rb:336:enqueue_all: enqueueing all chunks in buffer instance=15614620
2016-07-28 10:04:43 +0900 fluent.debug: {"instance":15614620,"message":"enqueueing all chunks in buffer instance=15614620"}
2016-07-28 10:04:43 +0900 fluent.debug: {"instance":15614620,"message":"enqueueing all chunks in buffer instance=15614620"}
2016-07-28 10:04:44 +0900 [debug]: plugin/buffer.rb:336:enqueue_all: enqueueing all chunks in buffer instance=15614620
2016-07-28 10:04:44 +0900 [debug]: plugin/buffer.rb:336:enqueue_all: enqueueing all chunks in buffer instance=15614620
2016-07-28 10:04:44 +0900 fluent.debug: {"instance":15614620,"message":"enqueueing all chunks in buffer instance=15614620"}
2016-07-28 10:04:44 +0900 fluent.debug: {"instance":15614620,"message":"enqueueing all chunks in buffer instance=15614620"}
2016-07-28 10:04:45 +0900 [debug]: plugin/buffer.rb:336:enqueue_all: enqueueing all chunks in buffer instance=15614620
2016-07-28 10:04:45 +0900 [debug]: plugin/buffer.rb:336:enqueue_all: enqueueing all chunks in buffer instance=15614620

After starting the python script, I get:

2016-07-28 10:04:39 +0900 [trace]: plugin/in_forward.rb:246:initialize: accepted fluent socket from '127.0.0.1:42758': object_id=15013880
2016-07-28 10:04:39 +0900 [warn]: fluent/root_agent.rb:274:handle_emits_error: emit transaction failed: error_class=NoMethodError error="undefined method `emit_events' for #<Fluent::Plugin::RecordTransformerFilter:00000001ba3a78>" tag="demo.temperature"
  2016-07-28 10:04:39 +0900 [warn]: fluent/event_router.rb:81:emit: suppressed same stacktrace
2016-07-28 10:04:39 +0900 [error]: plugin/in_forward.rb:300:rescue in on_read_msgpack: forward error error=#<NoMethodError: undefined method `emit_events' for #<Fluent::Plugin::RecordTransformerFilter:00000001ba3a78>> error_class=NoMethodError
  2016-07-28 10:04:39 +0900 [error]: plugin/in_forward.rb:280:on_read: suppressed same stacktrace
2016-07-28 10:04:39 +0900 [trace]: plugin/in_forward.rb:314:on_close: closed socket
2016-07-28 10:04:39 +0900 fluent.trace: {"message":"accepted fluent socket from '127.0.0.1:42758': object_id=15013880"}
2016-07-28 10:04:39 +0900 fluent.warn: {"error":"#<NoMethodError: undefined method `emit_events' for #<Fluent::Plugin::RecordTransformerFilter:00000001ba3a78>>","tag":"demo.temperature","message":"emit transaction failed: error_class=NoMethodError error=\"undefined method `emit_events' for #<Fluent::Plugin::RecordTr
ansformerFilter:00000001ba3a78>\" tag=\"demo.temperature\""}
2016-07-28 10:04:39 +0900 fluent.error: {"error":"#<NoMethodError: undefined method `emit_events' for #<Fluent::Plugin::RecordTransformerFilter:00000001ba3a78>>","error_class":"NoMethodError","message":"forward error error=#<NoMethodError: undefined method `emit_events' for #<Fluent::Plugin::RecordTransformerFilter:
00000001ba3a78>> error_class=NoMethodError"}
2016-07-28 10:04:39 +0900 fluent.trace: {"message":"closed socket"}

Every time fluentd receives an event

tagomoris · 2016-07-28T01:30:27Z

@perrin4869 Could you please test it without <filter> section?
It causes another problem (and it was already fixed at #1118).

perrin4869 · 2016-07-28T02:10:21Z

ok, without the filter it's working like charm now :)
Looking forward to 0.14.2!

repeatedly · 2016-07-28T02:51:40Z

Thanks for the testing!

xingxing122 · 2017-03-09T03:06:32Z

我也遇到了这个问题，你们都是怎么解决的

pedromazala · 2017-11-05T00:55:32Z

Hello everyone. I'm having the same issue as listed on my Kibana:

Here is my config file:

# fluentd/conf/fluent.conf
<source>
  @type forward
  port 24224
  bind 0.0.0.0
</source>
<match *.**>
  @type copy
  <store>
    @type elasticsearch
    host elasticsearch
    port 9200
    logstash_format true
    logstash_prefix fluentd
    logstash_dateformat %Y%m%d
    include_tag_key true
    type_name access_log
    tag_key @log_name
    flush_interval 1s
  </store>
  <store>
    @type stdout
  </store>
</match>

Here is my Dockerfile:

# fluentd/Dockerfile
FROM fluent/fluentd:v0.12
RUN ["gem", "install", "fluent-plugin-elasticsearch", "--no-rdoc", "--no-ri", "--version", "1.9.5"]

Here is my docker-compose.yaml:

version: "3.0"
services:
    proxy:
        image: nginx:latest
        ports:
            - "8080:80"
        restart: always
        volumes:
            - ./nginx/conf.d/:/etc/nginx/conf.d/
            - ./nginx/log/:/var/log/nginx/

            - ./nginx/nginx.conf:/etc/nginx/nginx.conf
            - ./nginx/proxy.conf:/etc/nginx/proxy.conf

            - ./nginx/passwords/:/etc/nginx/passwords
        networks:
            - log

    elasticsearch:
        image: elasticsearch
        expose:
            - "9200"
        restart: always
        environment:
            ES_JAVA_OPTS: "-Xms750m -Xmx750m"
        volumes:
          - ./elasticsearch/data:/usr/share/elasticsearch/data
        networks:
            - log
    fluentd:
        build: ./fluentd
        volumes:
            - ./fluentd/conf:/fluentd/etc
        restart: always
        networks:
            - log
    kibana:
        image: kibana
        depends_on:
            - "elasticsearch"
        restart: always
        networks:
            - log
networks:
    log:

When I send some data to my logger (Fluent\Logger\FluentLogger) I'm getting this error. Can someone help me?

pedromazala · 2017-11-05T01:01:32Z

I'm having the same issue. Here is the error on my Kibana (I'm using EFK orchestration):

My config:

# fluentd/conf/fluent.conf
<source>
  @type forward
  port 24224
  bind 0.0.0.0
</source>
<match *.**>
  @type copy
  <store>
    @type elasticsearch
    host elasticsearch
    port 9200
    logstash_format true
    logstash_prefix fluentd
    logstash_dateformat %Y%m%d
    include_tag_key true
    type_name access_log
    tag_key @log_name
    flush_interval 1s
  </store>
  <store>
    @type stdout
  </store>
</match>

Here is my Dockerfile:

# fluentd/Dockerfile
FROM fluent/fluentd:v0.12
RUN ["gem", "install", "fluent-plugin-elasticsearch", "--no-rdoc", "--no-ri", "--version", "1.9.5"]

Here is my docker-compose.yaml:

version: "3.0"
services:
    proxy:
        image: nginx:latest
        ports:
            - "8080:80"
        restart: always
        volumes:
            - ./nginx/conf.d/:/etc/nginx/conf.d/
            - ./nginx/log/:/var/log/nginx/

            - ./nginx/nginx.conf:/etc/nginx/nginx.conf
            - ./nginx/proxy.conf:/etc/nginx/proxy.conf

            - ./nginx/passwords/:/etc/nginx/passwords
        networks:
            - log

    elasticsearch:
        image: elasticsearch
        expose:
            - "9200"
        restart: always
        environment:
            ES_JAVA_OPTS: "-Xms750m -Xmx750m"
        volumes:
          - ./elasticsearch/data:/usr/share/elasticsearch/data
        networks:
            - log
    fluentd:
        build: ./fluentd
        volumes:
            - ./fluentd/conf:/fluentd/etc
        restart: always
        networks:
            - log
    kibana:
        image: kibana
        depends_on:
            - "elasticsearch"
        restart: always
        networks:
            - log
networks:
    log:

When I try to log my data using fluentd (I'm using this package here) I'm getting the error. Can someone help me?

tagomoris added the v0.14 label Jul 20, 2016

tagomoris self-assigned this Jul 20, 2016

tagomoris mentioned this issue Jul 25, 2016

Ignore non buffer chunk files when resumed #1124

Merged

repeatedly closed this as completed Jul 28, 2016

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fluentd crashes #1098

Fluentd crashes #1098

perrin4869 commented Jul 13, 2016

repeatedly commented Jul 14, 2016

perrin4869 commented Jul 14, 2016

perrin4869 commented Jul 20, 2016

repeatedly commented Jul 20, 2016

nokute78 commented Jul 20, 2016 •

edited

Loading

tagomoris commented Jul 21, 2016

perrin4869 commented Jul 21, 2016

repeatedly commented Jul 26, 2016 •

edited

Loading

perrin4869 commented Jul 27, 2016 •

edited

Loading

tagomoris commented Jul 27, 2016

repeatedly commented Jul 27, 2016

perrin4869 commented Jul 28, 2016

tagomoris commented Jul 28, 2016

perrin4869 commented Jul 28, 2016

repeatedly commented Jul 28, 2016

xingxing122 commented Mar 9, 2017

pedromazala commented Nov 5, 2017

pedromazala commented Nov 5, 2017

Fluentd crashes #1098

Fluentd crashes #1098

Comments

perrin4869 commented Jul 13, 2016

repeatedly commented Jul 14, 2016

perrin4869 commented Jul 14, 2016

perrin4869 commented Jul 20, 2016

repeatedly commented Jul 20, 2016

nokute78 commented Jul 20, 2016 • edited Loading

How to reproduce

Environment

Result

note

tagomoris commented Jul 21, 2016

perrin4869 commented Jul 21, 2016

repeatedly commented Jul 26, 2016 • edited Loading

perrin4869 commented Jul 27, 2016 • edited Loading

tagomoris commented Jul 27, 2016

repeatedly commented Jul 27, 2016

perrin4869 commented Jul 28, 2016

tagomoris commented Jul 28, 2016

perrin4869 commented Jul 28, 2016

repeatedly commented Jul 28, 2016

xingxing122 commented Mar 9, 2017

pedromazala commented Nov 5, 2017

pedromazala commented Nov 5, 2017

nokute78 commented Jul 20, 2016 •

edited

Loading

repeatedly commented Jul 26, 2016 •

edited

Loading

perrin4869 commented Jul 27, 2016 •

edited

Loading