Java thread exception with concurrent requests about puma

[evanphx]

@headius any thoughts on this?

• Evan // via iPhone

On Jan 6, 2012, at 7:56 PM, [email protected] wrote:

I'm trying to test out concurrent requests w/puma. I can successfully call each of the routes below individually. When I try to call the long one, then the short while the long is executing, one of two things seem to happen:

1. The short one never returns
2. The short one returns, then the long one (as I'd expect), but then I get a Java exception.

Code & exception below:

Ruby (w/RVM):

jruby 1.6.5 (ruby-1.9.2-p136) (2011-10-25 9dcd388) (Java HotSpot(TM) 64-Bit Server VM 1.6.0_29) [darwin-x86_64-java]

Gemfile:

gem 'rack'
gem 'jruby-rack'
gem 'puma'
gem 'sinatra'
gem 'jdbc-mysql'
gem 'sequel'

config.ru:

require 'tester'
Tester.run!

tester.rb:

require 'sinatra/base'
require 'sequel'

class Tester < Sinatra::Base
set :server, :puma

 get '/short' do
   db = Sequel.connect("jdbc:mysql://localhost/test?user=root")    
   db.run "select sleep(1)"
   "Hello!"
end

 get '/long' do
   db = Sequel.connect("jdbc:mysql://localhost/test?user=root")
   db.run "select sleep(20)"
   "Long Hello!"
 end

end

Exception:

Exception in thread "RubyThread-5: /Users/bporterfield/.rvm/gems/jruby-1.6.5@2j/gems/puma-0.9.2-java/lib/puma/thread_pool.rb:49" java.nio.channels.IllegalBlockingModeException

Full rackup to stacktrace here: http://pastebin.com/PZ22bhx2

---

Reply to this email directly or view it on GitHub:
https://github.com/evanphx/puma/issues/32

[dnagir]

I am not sure if that's related, but aren't you suppose to mange the sequel connection if you en it on every request?
http://sequel.rubyforge.org/rdoc/files/doc/opening_databases_rdoc.html

Is there a similar issue without using sequel at all?

[headius]

Poking at it now.

[nicksieger]

@bporterfield do you need jruby-rack in your gemfile?

[headius]

If you can add -Xbacktrace.style=raw to JRuby we might get more information. That exception is normally from the JDK's IO APIs...a either the IO channel in play can't be set back to blocking while it is still registered for "select", or it can't be set to nonblocking in the first place.

Need more input. Ideally you should reproduce this without Sequel involved, since the issue is unlikely to be related to Sequel (and if it is, it would be a Sequel bug).

[bporterfield]

Apologies for delay. You're correct, I do not need jruby-rack.

I'm still seeing similar issues with a much simpler case, although I'm not familiar with threading and Ruby so I may be off with this test. Please let me know.

Gemfile

source :rubygems

gem 'rack'
gem 'puma', :git => "https://github.com/evanphx/puma.git"
gem 'sinatra'

config.ru

require 'tester'
Tester.run!

tester.rb

require 'sinatra/base'

  class Tester < Sinatra::Base
    set :server, :puma

  get '/short' do
    sleep(1)
    "Hello!"
 end 

  get '/long' do
    sleep(10) 
    "Long Hello!"
  end
end

I start this with: bundle exec rackup, first calling /long and then /short. The result is that /short seems to wait for /long before returning. My expectation is that it would not?

I thought maybe my idea of how sleep & threading worked together could be wrong, so I tried to print out current thread during each request using Thread.current. It appears as though each request uses the same thread (which would explain the delay before the second request returns, but was not what I was expecting).

[bporterfield]

Testing again today, I did receive the thread exception again. I made a few long/short requests (from code above) and at some point (after probably 5 or 6 requests) the error occurred. The server did not seem to handle concurrent requests before the error either

bundle exec rackup
Puma 0.9.3 starting...

• Min threads: 0, max threads: 16
• Listening on tcp://0.0.0.0:3000
  == Sinatra/1.3.2 has taken the stage on 3000 for development with backup from Puma
  Exception in thread "RubyThread-7: /Users/bporterfield/.rvm/gems/jruby-1.6.5.1@puma2/bundler/gems/puma-c2e6206e599e/lib/puma/thread_pool.rb:49" java.nio.channels.IllegalBlockingModeException
  at java.nio.channels.spi.AbstractSelectableChannel.configureBlocking(AbstractSelectableChannel.java:257)

full stack trace: http://pastebin.com/1DKtdAU6

[bporterfield]

reproduced with -Xbacktrace.style=raw ->

jruby -Xbacktrace.style=raw -S bundle exec rackup
Puma 0.9.3 starting...

• Min threads: 0, max threads: 16
• Listening on tcp://0.0.0.0:3000
  == Sinatra/1.3.2 has taken the stage on 3000 for development with backup from Puma
  Exception in thread "RubyThread-11: /Users/bporterfield/.rvm/gems/jruby-1.6.5.1@puma2/bundler/gems/puma-c2e6206e599e/lib/puma/thread_pool.rb:49" java.nio.channels.IllegalBlockingModeException
  at java.nio.channels.spi.AbstractSelectableChannel.configureBlocking(AbstractSelectableChannel.java:257)
  at org.jruby.util.io.SelectBlob.tidyUp(SelectBlob.java:335)
  at org.jruby.util.io.SelectBlob.goForIt(SelectBlob.java:86)
  at org.jruby.RubyIO.select_static(RubyIO.java:3297)
  at org.jruby.RubyIO.select(RubyIO.java:3293)
  at org.jruby.RubyIO$s$0$3$select.call(RubyIO$s$0$3$select.gen:65535)
  at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:69)
  at org.jruby.ast.CallManyArgsNode.interpret(CallManyArgsNode.java:59)
  at org.jruby.ast.LocalAsgnNode.interpret(LocalAsgnNode.java:123)
  at org.jruby.ast.IfNode.interpret(IfNode.java:111)
  at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:104)

full stack trace: http://pastebin.com/TmgZrqJx

[bporterfield]

Using https://github.com/evanphx/puma/pull/39, the requests return as expected. However, I am still able to reproduce the exception (although it seems to take quite a bit more requesting for it to happen).

[bporterfield]

Just an update - I still consistently see this every time I start the server (within a few requests). It does not appear to affect the functionality, but is a little worrying :D

Also reproduced with jruby 1.6.6

[iconara]

I see this too in a basic pure-Rack app (run lambda { |env| [200, {}, []] }). I fire it up in Puma and hit reload as fast as I can in the browser, this error is printed quite a lot:

Exception in thread "RubyThread-3: /Users/theo/.rvm/gems/jruby-1.6.7@bomcl/gems/puma-0.9.5-java/lib/puma/thread_pool.rb:55" java.nio.channels.IllegalBlockingModeException
    at java.nio.channels.spi.AbstractSelectableChannel.configureBlocking(AbstractSelectableChannel.java:257)
    at org.jruby.util.io.SelectBlob.tidyUp(SelectBlob.java:348)
    at org.jruby.util.io.SelectBlob.goForIt(SelectBlob.java:87)
    at org.jruby.RubyIO.select_static(RubyIO.java:3366)
    at org.jruby.RubyIO.select(RubyIO.java:3362)
    at org.jruby.RubyIO$s$0$3$select.call(RubyIO$s$0$3$select.gen:65535)
    at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:69)
    at org.jruby.ast.CallManyArgsNode.interpret(CallManyArgsNode.java:59)
    at org.jruby.ast.LocalAsgnNode.interpret(LocalAsgnNode.java:123)
    at org.jruby.ast.IfNode.interpret(IfNode.java:111)
    at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:104)
    at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
    at org.jruby.ast.IfNode.interpret(IfNode.java:119)
    at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:104)
    at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
    at org.jruby.ast.IfNode.interpret(IfNode.java:117)
    at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:104)
    at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
    at org.jruby.ast.WhileNode.interpret(WhileNode.java:131)
    at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:104)

I see it both in Java 1.6 and 1.7u4 running JRuby 1.6.7

[Overbryd]

Same issue here. Seems to be not related to a specific requests, it just happens occasionally.
If there is anything I can help to fix this issue, I'd be happy to help you out!

@headius @evanphx Is this issue still on your radar? How can we help?

I was using 1.6.7 in 32bit mode:

jruby -v
jruby 1.6.7 (ruby-1.9.2-p312) (2012-02-22 3e82bc8) (Java HotSpot(TM) Client VM 1.6.0_31) [darwin-i386-java]

Stacktrace: https://gist.github.com/2658217

[scizo]

I'm also seeing this in my logs. I am running jruby 1.6.7 and puma 1.4.0. It has no effect on the functionality of my app.

[evanphx]

Stale, closing.

[dgies]

My app recently switched to puma and this exception is cropping up every time we run tests with cucumber/selenium, causing all tests to fail. Using puma 1.5.0 with jruby 1.6.7.2.
jruby 1.6.7.2 (ruby-1.8.7-p357) (2012-05-01 26e08ba) (Java HotSpot(TM) 64-Bit Server VM 1.6.0_45) [darwin-x86_64-java]