#0 thread doesn't exit correctly (killed or other reason) plugin=Fluent::Plugin::SystemdInput

[jdoss]

We are seeing this error happen on start up when using fluentd 0.14.16 and fluent-plugin-systemd 0.3.1. From what I can tell systemd events are getting processed as expected.

2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2017-10-19 16:55:58 +0000 [warn]: #0 killing existing thread thread=#<Thread:0x007f81502f9b48@/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.16/lib/fluent/plugin_helper/thread.rb:70 sleep>
2017-10-19 16:55:58 +0000 [warn]: #0 thread doesn't exit correctly (killed or other reason) plugin=Fluent::Plugin::SystemdInput title=:event_loop thread=#<Thread:0x007f81502f9b48@/opt/td-agent/embedded/lib/ruby/gems/2.4.0/gems/fluentd-0.14.16/lib/fluent/plugin_helper/thread.rb:70 aborting> error=nil
2017-10-19 16:55:58 +0000 [info]: Worker 0 finished unexpectedly with status 0
2017-10-19 16:55:59 +0000 [info]: gem 'fluent-plugin-elasticsearch' version '1.9.5'
2017-10-19 16:55:59 +0000 [info]: gem 'fluent-plugin-kafka' version '0.5.5'
2017-10-19 16:55:59 +0000 [info]: gem 'fluent-plugin-rewrite-tag-filter' version '1.5.5'
2017-10-19 16:55:59 +0000 [info]: gem 'fluent-plugin-s3' version '1.0.0.rc3'
2017-10-19 16:55:59 +0000 [info]: gem 'fluent-plugin-secure-forward' version '0.4.5'
2017-10-19 16:55:59 +0000 [info]: gem 'fluent-plugin-systemd' version '0.3.1'
2017-10-19 16:55:59 +0000 [info]: gem 'fluent-plugin-td' version '1.0.0.rc1'
2017-10-19 16:55:59 +0000 [info]: gem 'fluent-plugin-td-monitoring' version '0.2.2'
2017-10-19 16:55:59 +0000 [info]: gem 'fluent-plugin-webhdfs' version '1.1.1'
2017-10-19 16:55:59 +0000 [info]: gem 'fluentd' version '0.14.16'
2017-10-19 16:55:59 +0000 [info]: adding filter pattern="*.**" type="record_transformer"
2017-10-19 16:55:59 +0000 [info]: adding match pattern="*.**" type="forward"
2017-10-19 16:55:59 +0000 [info]: #0 'flush_interval' is configured at out side of <buffer>. 'flush_mode' is set to 'interval' to keep existing behaviour
2017-10-19 16:55:59 +0000 [warn]: #0 secondary type should be same with primary one primary="Fluent::Plugin::ForwardOutput" secondary="Fluent::Plugin::FileOutput"
2017-10-19 16:55:59 +0000 [info]: #0 adding forwarding server '10.*.*.*:24224' host="one" port=24224 weight=60 plugin_id="object:3f817d56f188"
2017-10-19 16:55:59 +0000 [info]: #0 adding forwarding server '10.*.*.*:24224' host="two" port=24224 weight=60 plugin_id="object:3f817d56f188"
2017-10-19 16:55:59 +0000 [info]: #0 adding forwarding server '10.*.*.*:24224' host="three" port=24224 weight=60 plugin_id="object:3f817d56f188"
2017-10-19 16:55:59 +0000 [info]: adding source type="systemd"
2017-10-19 16:55:59 +0000 [info]: adding source type="forward"
2017-10-19 16:55:59 +0000 [info]: using configuration file: <ROOT>
  <source>
    @type systemd
    tag "systemd"
    path "/var/log/journal"
    read_from_head true
    <storage>
      @type "local"
      persistent true
      path "/var/log/td-agent/systemd.pos"
    </storage>
    <entry>
      field_map {"MESSAGE":"log","_PID":["process","pid"],"_CMDLINE":"process","_COMM":"cmd"}
      fields_strip_underscores true
      fields_lowercase true
    </entry>
</source>

[errm]

Could you share your full configuration file ... I can't replicate this error.

[jdoss]

I will see if it is still happening and get you a config file on Monday.

[errm]

Thanks very much @jdoss ... sorry it took me so long to look at this ...

[jdoss]

@errm This isn't happening anymore. Here are the versions we have installed now and it must have been something funky with an older version of Fluentd.

2018-02-09 22:54:36 +0000 [info]: gem 'fluent-plugin-elasticsearch' version '2.4.1'
2018-02-09 22:54:36 +0000 [info]: gem 'fluent-plugin-kafka' version '0.6.5'
2018-02-09 22:54:36 +0000 [info]: gem 'fluent-plugin-s3' version '1.1.0'
2018-02-09 22:54:36 +0000 [info]: gem 'fluent-plugin-secure-forward' version '0.4.5'
2018-02-09 22:54:36 +0000 [info]: gem 'fluent-plugin-systemd' version '0.3.1'
2018-02-09 22:54:36 +0000 [info]: gem 'fluent-plugin-td' version '1.0.0'
2018-02-09 22:54:36 +0000 [info]: gem 'fluent-plugin-td-monitoring' version '0.2.3'
2018-02-09 22:54:36 +0000 [info]: gem 'fluent-plugin-webhdfs' version '1.2.2'
2018-02-09 22:54:36 +0000 [info]: gem 'fluentd' version '1.0.2'

[errm]

Thanks for the report @jdoss good to know...

[adie]

This is happening on my end as well when shutting down fluentd. As I understand the problematic line is that one: https://github.com/fluent-plugin-systemd/fluent-plugin-systemd/blob/master/lib/fluent/plugin/in_systemd.rb#L115 - router becomes nil on shutdown.

[errm]

@adie could you confirm the fluent version you are using?

[adie]

I use fluentd v1.5.2 and fluent-plugin-systemd v1.0.2

[adie]

@errm excerpt from my td-agent.log:

...
2019-07-08 09:27:32 +0000 [info]: #0 shutting down filter plugin type=:grep plugin_id="object:bc8f40"
2019-07-08 09:27:32 +0000 [info]: #0 shutting down filter plugin type=:grep plugin_id="object:ce700c"
2019-07-08 09:27:37 +0000 [warn]: #0 event loop does NOT exit until hard timeout.
2019-07-08 09:27:37 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2019-07-08 09:27:37 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
... (around 6500 of the same lines)
2019-07-08 09:27:38 +0000 [error]: #0 Exception emitting record: undefined method `emit' for nil:NilClass
2019-07-08 09:27:38 +0000 [warn]: #0 killing existing thread thread=#<Thread:0x0000000001a5c2c8@/my-project/vendor/bundle/ruby/2.5.0/gems/fluentd-1.5.2/lib/fluent/plugin_helper/thread.rb:70 sleep>
2019-07-08 09:27:38 +0000 [warn]: #0 thread doesn't exit correctly (killed or other reason) plugin=Fluent::Plugin::SystemdInput title=:event_loop thread=#<Thread:0x0000000001a5c2c8@/my-project/vendor/bundle/ruby/2.5.0/gems/fluentd-1.5.2/lib/fluent/plugin_helper/thread.rb:70 aborting> error=nil
2019-07-08 09:27:38 +0000 [info]: Worker 0 finished unexpectedly with status 0
2019-07-08 09:27:39 +0000 [info]: adding match ...
...
2019-07-08 09:27:39 +0000 [info]: #0 fluentd worker is now running worker=0

So while it does not seem to cause any issues, it spams the logs.

[errm]

Thanks for the info @adie ... sorry it's taken a long time to look at this!

Having had a hard look at the code it is clear we are not handling shutdown at all cleanly... I am going to take a look at this over the next week or so!

[errm]

I released a new version 1.0.4 with the fix for this issue!