Startup failure after upgrading

[mchesler]

• fluentd version 0.14.23
• Ubuntu 14.04

After upgrading from 0.14.15 to 0.14.23, fluentd will no longer start up. In the logs, I see the following error continuously:

2017-11-20 19:19:00 +0000 [error]: #0 unexpected error error_class=Errno::EPERM error="Operation not permitted"
  2017-11-20 19:19:00 +0000 [error]: #0 /var/lib/gems/2.2.0/gems/serverengine-2.0.5/lib/serverengine/privilege.rb:50:in `groups='
  2017-11-20 19:19:00 +0000 [error]: #0 /var/lib/gems/2.2.0/gems/serverengine-2.0.5/lib/serverengine/privilege.rb:50:in `change'
  2017-11-20 19:19:00 +0000 [error]: #0 /var/lib/gems/2.2.0/gems/fluentd-0.14.15/lib/fluent/supervisor.rb:714:in `change_privilege'
  2017-11-20 19:19:00 +0000 [error]: #0 /var/lib/gems/2.2.0/gems/fluentd-0.14.15/lib/fluent/supervisor.rb:500:in `block in run_worker'
  2017-11-20 19:19:00 +0000 [error]: #0 /var/lib/gems/2.2.0/gems/fluentd-0.14.15/lib/fluent/supervisor.rb:661:in `call'
  2017-11-20 19:19:00 +0000 [error]: #0 /var/lib/gems/2.2.0/gems/fluentd-0.14.15/lib/fluent/supervisor.rb:661:in `main_process'
  2017-11-20 19:19:00 +0000 [error]: #0 /var/lib/gems/2.2.0/gems/fluentd-0.14.15/lib/fluent/supervisor.rb:498:in `run_worker'
  2017-11-20 19:19:00 +0000 [error]: #0 /var/lib/gems/2.2.0/gems/fluentd-0.14.15/lib/fluent/command/fluentd.rb:316:in `<top (required)>'
  2017-11-20 19:19:00 +0000 [error]: #0 /usr/lib/ruby/2.2.0/rubygems/core_ext/kernel_require.rb:54:in `require'
  2017-11-20 19:19:00 +0000 [error]: #0 /usr/lib/ruby/2.2.0/rubygems/core_ext/kernel_require.rb:54:in `require'
  2017-11-20 19:19:00 +0000 [error]: #0 /var/lib/gems/2.2.0/gems/fluentd-0.14.15/bin/fluentd:5:in `<top (required)>'
  2017-11-20 19:19:00 +0000 [error]: #0 /usr/local/bin/fluentd:23:in `load'
  2017-11-20 19:19:00 +0000 [error]: #0 /usr/local/bin/fluentd:23:in `<main>'
2017-11-20 19:19:00 +0000 [info]: Worker 0 finished unexpectedly with status 1

[mchesler]

I should mention that we start fluentd with upstart using the below command, which we have not changed for a very long time:

exec start-stop-daemon --start --make-pidfile --pidfile /var/run/fluentd.pid --exec /usr/local/bin/fluentd -- --user fluentd --group fluentd --log /var/log/fluentd.log --config /etc/fluentd/fluentd.conf

[repeatedly]

2017-11-20 19:19:00 +0000 [error]: #0 /var/lib/gems/2.2.0/gems/fluentd-0.14.15/lib/fluent/command/fluentd.rb:316:in `<top (required)>'

Hmm... you said "After upgrading from 0.14.15 to 0.14.23" but log said fluentd is still v0.14.15.
How to upgrade fluentd?

[mchesler]

That's an excellent point. I hadn't noticed that before. I upgraded by installing the new gem version, but I did not explicitly remove the old gem. I'll give that a try.

[mchesler]

Same issue after cleanup:

2017-11-20 21:18:01 +0000 [error]: #0 unexpected error error_class=Errno::EPERM error="Operation not permitted"
  2017-11-20 21:18:01 +0000 [error]: #0 /var/lib/gems/2.2.0/gems/serverengine-2.0.5/lib/serverengine/privilege.rb:50:in `groups='
  2017-11-20 21:18:01 +0000 [error]: #0 /var/lib/gems/2.2.0/gems/serverengine-2.0.5/lib/serverengine/privilege.rb:50:in `change'
  2017-11-20 21:18:01 +0000 [error]: #0 /var/lib/gems/2.2.0/gems/fluentd-0.14.23/lib/fluent/supervisor.rb:751:in `change_privilege'
  2017-11-20 21:18:01 +0000 [error]: #0 /var/lib/gems/2.2.0/gems/fluentd-0.14.23/lib/fluent/supervisor.rb:520:in `block in run_worker'
  2017-11-20 21:18:01 +0000 [error]: #0 /var/lib/gems/2.2.0/gems/fluentd-0.14.23/lib/fluent/supervisor.rb:699:in `call'
  2017-11-20 21:18:01 +0000 [error]: #0 /var/lib/gems/2.2.0/gems/fluentd-0.14.23/lib/fluent/supervisor.rb:699:in `main_process'
  2017-11-20 21:18:01 +0000 [error]: #0 /var/lib/gems/2.2.0/gems/fluentd-0.14.23/lib/fluent/supervisor.rb:518:in `run_worker'
  2017-11-20 21:18:01 +0000 [error]: #0 /var/lib/gems/2.2.0/gems/fluentd-0.14.23/lib/fluent/command/fluentd.rb:316:in `<top (required)>'
  2017-11-20 21:18:01 +0000 [error]: #0 /usr/lib/ruby/2.2.0/rubygems/core_ext/kernel_require.rb:54:in `require'
  2017-11-20 21:18:01 +0000 [error]: #0 /usr/lib/ruby/2.2.0/rubygems/core_ext/kernel_require.rb:54:in `require'
  2017-11-20 21:18:01 +0000 [error]: #0 /var/lib/gems/2.2.0/gems/fluentd-0.14.23/bin/fluentd:5:in `<top (required)>'
  2017-11-20 21:18:01 +0000 [error]: #0 /usr/local/bin/fluentd:23:in `load'
  2017-11-20 21:18:01 +0000 [error]: #0 /usr/local/bin/fluentd:23:in `<main>'
2017-11-20 21:18:01 +0000 [info]: Worker 0 finished unexpectedly with status 1

[repeatedly]

Hmm... the weird point is you hit this error with v0.14.15 and v0.14.23.
So it seems the external factor causes it.

Did you change other settings in the OS?
And does fresh installation also have same problem?

[mchesler]

A fresh installation does have the same problem. Also, if I go back to 0.14.15, it starts working again.

[mchesler]

Going version by version, the issue seems to appear in 0.14.17

[repeatedly]

I see. One possible patch is #1580
Could you test fluentd v0.14.23 after removes

fluentd/lib/fluent/supervisor.rb

Line 571 in 4ccb485

dry_run

this line?

[mchesler]

Starts up just fine with that line removed.

[repeatedly]

Thanks!
It seems double change_privilege call causes it.
We will fix it soon.

[repeatedly]

Patch for this issue: #1758

[repeatedly]

If you have a time, could you test #1758 on your environment?

[mchesler]

@repeatedly Works fine with #1758 Any idea when the patch will be released?

[repeatedly]

Released v0.14.24.