Logstash: Logstash will sometimes terminate with a lot of errors from Puma

Created on 24 Aug 2016 · 12Comments · Source: elastic/logstash

During termination, logstash can produce a lot of errors related to Puma.
For the purpose of demonstration, I could only reproduce this in connection with a logstash error, but I'm not sure if it is a necessary requirement to trigger the puma messages:

~/projects/logstash (git)-[master] % bin/logstash -e "input { generator { count => 10000 } } output { if [value] > 10 { stdout {} } }"
--- jar coordinate com.fasterxml.jackson.core:jackson-annotations already loaded with version 2.7.3 - omit version 2.7.0
Pipeline main started
An unexpected error occurred! {:error=>#<NoMethodError: undefined method `>' for nil:NilClass>, :backtrace=>["(eval):24:in `output_func'", "/Users/joaoduarte/projects/logstash/logstash-core/lib/logstash/pipeline.rb:295:in `output_batch'", "org/jruby/RubyProc.java:281:in `call'", "/Users/joaoduarte/projects/logstash/logstash-core/lib/logstash/util/wrapped_synchronous_queue.rb:171:in `each'", "org/jruby/RubyHash.java:1342:in `each'", "/Users/joaoduarte/projects/logstash/logstash-core/lib/logstash/util/wrapped_synchronous_queue.rb:170:in `each'", "/Users/joaoduarte/projects/logstash/logstash-core/lib/logstash/pipeline.rb:289:in `output_batch'", "/Users/joaoduarte/projects/logstash/logstash-core/lib/logstash/pipeline.rb:252:in `worker_loop'", "/Users/joaoduarte/projects/logstash/logstash-core/lib/logstash/pipeline.rb:225:in `start_workers'"], :level=>:fatal}
Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'
2016-08-24 15:35:34 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'
Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'
2016-08-24 15:35:34 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'
Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'
2016-08-24 15:35:34 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'
Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'
2016-08-24 15:35:34 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)

org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'
2016-08-24 15:35:34 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>
Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'
2016-08-24 15:35:34 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'
Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'
2016-08-24 15:35:34 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'
Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'
2016-08-24 15:35:34 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'
Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'
2016-08-24 15:35:34 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'
Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'
2016-08-24 15:35:34 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'
2016-08-24 15:35:34 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'
2016-08-24 15:35:34 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'
2016-08-24 15:35:34 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)

org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'
Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'
2016-08-24 15:35:34 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'
Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'
2016-08-24 15:35:34 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'

org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'
Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'
2016-08-24 15:35:34 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'
2016-08-24 15:35:34 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>
Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF)
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:322:in `handle_servers'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/server.rb:296:in `run'
org/jruby/RubyIO.java:3705:in `select'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:29:in `run_internal'
/Users/joaoduarte/projects/logstash/vendor/bundle/jruby/1.9/gems/puma-2.16.0-java/lib/puma/reactor.rb:138:in `run_in_thread'
2016-08-24 15:35:34 +0100: Listen loop error: #<Errno::EBADF: Bad file descriptor - Bad file descriptor>

bug monitoring v5.0.0-beta1

Source

jsvd

All 12 comments

This is a really a bummer, the only way to prevent that error or at least silent it is to monkey patch puma, this error is raise in an internal puma thread.

ph on 7 Sep 2016

I wonder if Puma 3.x still shows this behaviour..updating this would require also updating the http input, but I don't see why not.

jsvd on 7 Sep 2016

I can confirm also saw this behaviour, but while talking to @andrewvc was hard to debug the real reasons. In previous life, this issue was fixed by adding https://github.com/elastic/logstash/issues/4674 , but this was before @andrewvc did his refactoring, so not sure how to tackle this down the best right now. See https://github.com/elastic/logstash/pull/4782/commits/f171b49205c8516b5b3cfc893556c2050456f7f2 for more details.

purbon on 7 Sep 2016

Well I took a look at the implement in their master branch handle_server is the same code.

ph on 7 Sep 2016

Just to say that error is normal to have, if logstash is currently crashing, the server thread are doing IO.select and their FD get removed from their feet.

ph on 7 Sep 2016

The other problem, is they are using STDERR to report that error.

ph on 7 Sep 2016

I have found an elegant for silencing some of the errors from puma but sadly not all of them.

The Puma::Server accepts as a second argument a Puma::Events instance, this class is used under the hood to handle _some of the unknown errors_ and messaging , This class accepts 2 IO object, _stderr_ and _stdout_. I've created a small class IOWrappedLogger that make the logger acts as an _IO_ object but send all the writes to logger.debug. With this patch the Listen loop error are send to the logger in debug mode.

The other problem is with theses Error in reactor loop escaped: Bad file descriptor - Bad file descriptor (Errno::EBADF) errors, they are directly send to STDERR, I which we had refinements. ;)

ph on 7 Sep 2016

can't we just patch https://github.com/puma/puma/blob/2e9ee6d0fbed3315edc2097a05e1c5ed64ffbb41/lib/puma/reactor.rb#L150-L162
to use our logger instead of STDERR?

jsvd on 7 Sep 2016

Yes this is what I just end up doing, I wish they wouldn't use a constant for that.

ph on 7 Sep 2016

👍1

@jsvd The problem is its not the only place they are using it. ~~I guess I could alias it~~, its a really huge method to patch.

https://github.com/puma/puma/blob/2e9ee6d0fbed3315edc2097a05e1c5ed64ffbb41/lib/puma/reactor.rb#L32

ph on 7 Sep 2016

could we just patch it by defining something like:

module Puma
  class Reactor
    STDERR = Cabin::Channel.get(LogStash)
  end
end

essentially exploit namespacing..

jsvd on 7 Sep 2016

@jsvd stop reading my mind, I used ::Puma.const_set to achieve that. :P

ph on 7 Sep 2016

🎉1

Was this page helpful?

0 / 5 - 0 ratings

Related issues

Config compilation is still running after 1 hour

packetrevolt · 3Comments

logstash 2.3 and conditional filter broken?

dvic · 3Comments

Avoid class loader chaining in janino compilation

jsvd · 3Comments

Review plugin doc PRs

dedemorton · 3Comments

Mutate / Convert not working on nested fields

cschotke · 3Comments