Live streaming and JRuby - Puma stops responding

Rodrigo_Rosenfeld_R1 · September 10, 2014, 2:05pm

I'm posting this here because given the jstack output it seems to be more related to Rails than JRuby or Puma.

I'm attaching an output of jstack over the process so that you can see the full output.

The jvm-bridge.stack has a stack of an unresponsive server while the puma-jruby-rails.stack is for the current server which is still alives but will probably stop responding too after a while like it happens in our servers for a while already. The jvm-bridge one uses an older Rails release while the current one uses the latest stable but the result is about the same.

This is a simple Rails application with Live Streaming that will generate Excel outputs using the Apache POI library. I've also set up the Rack::Timeout middleware in this application but it doesn't seem to help fixing this bug:

require 'rack/timeout'
...
Rack::Timeout.timeout = 60 # seconds
config.middleware.use Rack::Timeout

Basically, as the time passes we get entries like this in the jstack output:

"Ruby-0-Thread-34: /var/www/apps/shared/bundle/jruby/1.9/gems/actionpack-4.1.5/lib/action_controller/metal/live.rb:220" #58 daemon prio=5 os_prio=0 tid=0x00007f3cd800d800 nid=0x6460 in Object.wait() [0x00007f3d91a18000]
    java.lang.Thread.State: WAITING (on object monitor)
         at java.lang.Object.wait(Native Method)
         at java.lang.Object.wait(Object.java:460)
         at org.jruby.RubyThread$SleepTask.run(RubyThread.java:1049)
         - locked <0x00000000f6ad7fe8> (a org.jruby.ext.thread.SizedQueue)
         at org.jruby.RubyThread.executeBlockingTask(RubyThread.java:1065)
         at org.jruby.RubyThread.wait_timeout(RubyThread.java:1413)
         at org.jruby.ext.thread.SizedQueue.push(SizedQueue.java:127)
         - locked <0x00000000f6ad7fe8> (a org.jruby.ext.thread.SizedQueue)
         at java.lang.invoke.LambdaForm$DMH/1223685984.invokeVirtual_LLL_L(LambdaForm$DMH)
         at java.lang.invoke.LambdaForm$MH/989355890.convert(LambdaForm$MH)
         at java.lang.invoke.LambdaForm$DMH/1007251739.invokeSpecial_LLLLL_L(LambdaForm$DMH)
         at java.lang.invoke.LambdaForm$MH/731960720.guard(LambdaForm$MH)
         at java.lang.invoke.LambdaForm$DMH/1007251739.invokeSpecial_LLLLL_L(LambdaForm$DMH)
         at java.lang.invoke.LambdaForm$MH/1709122943.guard(LambdaForm$MH)
         at java.lang.invoke.LambdaForm$MH/1014328909.linkToCallSite(LambdaForm$MH)
         at rubyjit.ActionDispatch::Response::Buffer$$write_05376424d13f339e8e84b2326e8269bca3b39ef3681842940.__file__(/var/www/apps/shared/bundle/jruby/1.9/gems/actionpack-4.1.5/lib/action_dispatch/http/response.rb:90)
         at rubyjit.ActionDispatch::Response::Buffer$$write_05376424d13f339e8e84b2326e8269bca3b39ef3681842940.__file__(/var/www/apps/shared/bundle/jruby/1.9/gems/actionpack-4.1.5/lib/action_dispatch/http/response.rb)
         at rubyjit.ActionDispatch::Response::Buffer$$write_05376424d13f339e8e84b2326e8269bca3b39ef3681842940.__file__(/var/www/apps/shared/bundle/jruby/1.9/gems/actionpack-4.1.5/lib/action_dispatch/http/response.rb)
         at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:101)
         at org.jruby.runtime.callsite.SuperCallSite.callBlock(SuperCallSite.java:68)
         at org.jruby.runtime.callsite.SuperCallSite.call(SuperCallSite.java:75)
         at rubyjit.ActionController::Live::Buffer$$write_2deb09bd276a73c856527692b6dbda52e3e08f6f681842940.__file__(/var/www/apps/shared/bundle/jruby/1.9/gems/actionpack-4.1.5/lib/action_controller/metal/live.rb:124)
         at rubyjit.ActionController::Live::Buffer$$write_2deb09bd276a73c856527692b6dbda52e3e08f6f681842940.__file__(/var/www/apps/shared/bundle/jruby/1.9/gems/actionpack-4.1.5/lib/action_controller/metal/live.rb)
         at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:181)
         at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168)
         at org.jruby.util.IOOutputStream.write(IOOutputStream.java:117)
         at org.jruby.util.IOOutputStream.write(IOOutputStream.java:109)
         at org.apache.poi.poifs.storage.BigBlock.doWriteData(BigBlock.java:67)
         at org.apache.poi.poifs.storage.DocumentBlock.writeData(DocumentBlock.java:195)
         at org.apache.poi.poifs.storage.BigBlock.writeBlocks(BigBlock.java:98)
         at org.apache.poi.poifs.storage.DocumentBlock.writeBlocks(DocumentBlock.java:34)
         at org.apache.poi.poifs.filesystem.POIFSDocument$BigBlockStore.writeBlocks(POIFSDocument.java:547)
         at org.apache.poi.poifs.filesystem.POIFSDocument.writeBlocks(POIFSDocument.java:303)
         at org.apache.poi.poifs.filesystem.POIFSFileSystem.writeFilesystem(POIFSFileSystem.java:375)
         at org.apache.poi.hssf.usermodel.HSSFWorkbook.write(HSSFWorkbook.java:1226)
         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
         at java.lang.reflect.Method.invoke(Method.java:483)
         at org.jruby.javasupport.JavaMethod.invokeDirectWithExceptionHandling(JavaMethod.java:455)
         at org.jruby.javasupport.JavaMethod.invokeDirect(JavaMethod.java:316)
         at org.jruby.java.invokers.InstanceMethodInvoker.call(InstanceMethodInvoker.java:61)
         at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168)
         at org.jruby.ast.CallOneArgNode.interpret(CallOneArgNode.java:57)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)
         at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:182)
         at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:198)
         at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:168)
         at org.jruby.ast.CallOneArgNode.interpret(CallOneArgNode.java:57)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)
         at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:161)
         at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:190)
         at org.jruby.RubyClass.finvoke(RubyClass.java:527)
         at org.jruby.RubyBasicObject.send19(RubyBasicObject.java:1501)
         at org.jruby.RubyKernel.send19(RubyKernel.java:2222)
         at org.jruby.RubyKernel$INVOKER$s$send19.call(RubyKernel$INVOKER$s$send19.gen)
         at org.jruby.internal.runtime.methods.AliasMethod.call(AliasMethod.java:86)
         at org.jruby.runtime.callsite.SuperCallSite.cacheAndCall(SuperCallSite.java:366)
         at org.jruby.runtime.callsite.SuperCallSite.callBlock(SuperCallSite.java:192)
         at org.jruby.runtime.callsite.SuperCallSite.call(SuperCallSite.java:197)
         at org.jruby.runtime.callsite.SuperCallSite.callVarargs(SuperCallSite.java:108)
         at org.jruby.ast.ZSuperNode.interpret(ZSuperNode.java:103)
         at org.jruby.ast.LocalAsgnNode.interpret(LocalAsgnNode.java:123)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)
         at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:182)
         at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:198)
         at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:326)
         at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:170)
         at org.jruby.ast.FCallSpecialArgNode.interpret(FCallSpecialArgNode.java:39)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)
         at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:204)
         at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:206)
         at org.jruby.runtime.callsite.SuperCallSite.cacheAndCall(SuperCallSite.java:366)
         at org.jruby.runtime.callsite.SuperCallSite.callBlock(SuperCallSite.java:192)
         at org.jruby.runtime.callsite.SuperCallSite.call(SuperCallSite.java:197)
         at org.jruby.runtime.callsite.SuperCallSite.callVarargs(SuperCallSite.java:108)
         at org.jruby.ast.ZSuperNode.interpret(ZSuperNode.java:103)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)
         at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:204)
         at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:206)
         at org.jruby.runtime.callsite.SuperCallSite.cacheAndCall(SuperCallSite.java:366)
         at org.jruby.runtime.callsite.SuperCallSite.callBlock(SuperCallSite.java:192)
         at org.jruby.runtime.callsite.SuperCallSite.call(SuperCallSite.java:197)
         at org.jruby.runtime.callsite.SuperCallSite.callVarargs(SuperCallSite.java:108)
         at org.jruby.ast.ZSuperNode.interpret(ZSuperNode.java:103)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112)
         at org.jruby.runtime.Interpreted19Block.evalBlockBody(Interpreted19Block.java:206)
         at org.jruby.runtime.Interpreted19Block.yield(Interpreted19Block.java:194)
         at org.jruby.runtime.Interpreted19Block.call(Interpreted19Block.java:125)
         at org.jruby.runtime.Block.call(Block.java:101)
         at org.jruby.RubyProc.call(RubyProc.java:290)
         at org.jruby.RubyProc.call19(RubyProc.java:271)
         at org.jruby.RubyProc$INVOKER$i$0$0$call19.call(RubyProc$INVOKER$i$0$0$call19.gen)
         at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:202)
         at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:198)
         at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:306)
         at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:136)
         at org.jruby.ast.CallNoArgNode.interpret(CallNoArgNode.java:60)
         at org.jruby.ast.OrNode.interpret(OrNode.java:100)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.AndNode.interpret(AndNode.java:97)
         at org.jruby.ast.AttrAssignOneArgNode.interpret(AttrAssignOneArgNode.java:33)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)
         at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:182)
         at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:198)
         at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:326)
         at org.jruby.ast.CallOneArgNode.interpret(CallOneArgNode.java:57)
         at org.jruby.ast.DAsgnNode.interpret(DAsgnNode.java:110)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112)
         at org.jruby.runtime.Interpreted19Block.evalBlockBody(Interpreted19Block.java:206)
         at org.jruby.runtime.Interpreted19Block.yield(Interpreted19Block.java:194)
         at org.jruby.runtime.Interpreted19Block.call(Interpreted19Block.java:125)
         at org.jruby.runtime.Block.call(Block.java:101)
         at org.jruby.RubyProc.call(RubyProc.java:290)
         at org.jruby.RubyProc.call19(RubyProc.java:271)
         at org.jruby.RubyProc$INVOKER$i$0$0$call19.call(RubyProc$INVOKER$i$0$0$call19.gen)
         at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:210)
         at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:206)
         at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:326)
         at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:170)
         at org.jruby.ast.CallOneArgNode.interpret(CallOneArgNode.java:57)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112)
         at org.jruby.runtime.Interpreted19Block.evalBlockBody(Interpreted19Block.java:206)
         at org.jruby.runtime.Interpreted19Block.yield(Interpreted19Block.java:194)
         at org.jruby.runtime.Interpreted19Block.call(Interpreted19Block.java:125)
         at org.jruby.runtime.Block.call(Block.java:101)
         at org.jruby.RubyProc.call(RubyProc.java:290)
         at org.jruby.RubyProc.call19(RubyProc.java:271)
         at org.jruby.RubyProc$INVOKER$i$0$0$call19.call(RubyProc$INVOKER$i$0$0$call19.gen)
         at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:210)
         at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:206)
         at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:326)
         at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:170)
         at org.jruby.ast.CallOneArgNode.interpret(CallOneArgNode.java:57)
         at org.jruby.ast.CallNoArgNode.interpret(CallNoArgNode.java:60)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
         at org.jruby.ast.IfNode.interpret(IfNode.java:118)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)
         at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:204)
         at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:206)
         at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:336)
         at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:179)
         at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:188)
         at org.jruby.ast.FCallOneArgBlockNode.interpret(FCallOneArgBlockNode.java:34)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)
         at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:204)
         at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:206)
         at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:336)
         at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:179)
         at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:188)
         at org.jruby.ast.FCallOneArgBlockNode.interpret(FCallOneArgBlockNode.java:34)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)
         at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:204)
         at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:206)
         at org.jruby.runtime.callsite.SuperCallSite.cacheAndCall(SuperCallSite.java:366)
         at org.jruby.runtime.callsite.SuperCallSite.callBlock(SuperCallSite.java:192)
         at org.jruby.runtime.callsite.SuperCallSite.call(SuperCallSite.java:197)
         at org.jruby.runtime.callsite.SuperCallSite.callVarargs(SuperCallSite.java:108)
         at org.jruby.ast.ZSuperNode.interpret(ZSuperNode.java:103)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.RescueNode.executeBody(RescueNode.java:221)
         at org.jruby.ast.RescueNode.interpret(RescueNode.java:116)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)
         at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:204)
         at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:206)
         at org.jruby.runtime.callsite.SuperCallSite.cacheAndCall(SuperCallSite.java:366)
         at org.jruby.runtime.callsite.SuperCallSite.callBlock(SuperCallSite.java:192)
         at org.jruby.runtime.callsite.SuperCallSite.call(SuperCallSite.java:197)
         at org.jruby.runtime.callsite.SuperCallSite.callVarargs(SuperCallSite.java:108)
         at org.jruby.ast.ZSuperNode.interpret(ZSuperNode.java:103)
         at org.jruby.ast.DAsgnNode.interpret(DAsgnNode.java:110)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112)
         at org.jruby.runtime.Interpreted19Block.evalBlockBody(Interpreted19Block.java:206)
         at org.jruby.runtime.Interpreted19Block.yield(Interpreted19Block.java:157)
         at org.jruby.runtime.Interpreted19Block.yieldSpecific(Interpreted19Block.java:135)
         at org.jruby.runtime.Block.yieldSpecific(Block.java:120)
         at org.jruby.ast.YieldOneNode.interpret(YieldOneNode.java:35)
         at org.jruby.ast.IfNode.interpret(IfNode.java:116)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112)
         at org.jruby.runtime.Interpreted19Block.evalBlockBody(Interpreted19Block.java:206)
         at org.jruby.runtime.Interpreted19Block.yield(Interpreted19Block.java:157)
         at org.jruby.runtime.Interpreted19Block.yieldSpecific(Interpreted19Block.java:135)

         at org.jruby.runtime.Block.yieldSpecific(Block.java:120)
         at org.jruby.ast.YieldOneNode.interpret(YieldOneNode.java:35)
         at org.jruby.ast.IfNode.interpret(IfNode.java:116)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112)
         at org.jruby.runtime.Interpreted19Block.evalBlockBody(Interpreted19Block.java:206)
         at org.jruby.runtime.Interpreted19Block.yield(Interpreted19Block.java:157)
         at org.jruby.runtime.Interpreted19Block.yieldSpecific(Interpreted19Block.java:135)
         at org.jruby.runtime.Block.yieldSpecific(Block.java:120)
         at org.jruby.ast.YieldOneNode.interpret(YieldOneNode.java:35)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.RescueNode.executeBody(RescueNode.java:221)
         at org.jruby.ast.RescueNode.interpret(RescueNode.java:116)
         at org.jruby.ast.EnsureNode.interpret(EnsureNode.java:96)
         at org.jruby.ast.BeginNode.interpret(BeginNode.java:83)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)
         at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:247)
         at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:222)
         at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:211)
         at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:222)
         at org.jruby.ast.CallTwoArgBlockNode.interpret(CallTwoArgBlockNode.java:62)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.IfNode.interpret(IfNode.java:116)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)
         at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:247)
         at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:222)
         at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:356)
         at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:213)
         at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:222)
         at org.jruby.ast.CallTwoArgBlockNode.interpret(CallTwoArgBlockNode.java:62)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)
         at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:204)
         at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:206)
         at org.jruby.runtime.callsite.SuperCallSite.cacheAndCall(SuperCallSite.java:366)
         at org.jruby.runtime.callsite.SuperCallSite.callBlock(SuperCallSite.java:192)
         at org.jruby.runtime.callsite.SuperCallSite.call(SuperCallSite.java:197)
         at org.jruby.runtime.callsite.SuperCallSite.callVarargs(SuperCallSite.java:108)
         at org.jruby.ast.ZSuperNode.interpret(ZSuperNode.java:103)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)
         at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:204)
         at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:206)
         at org.jruby.runtime.callsite.SuperCallSite.cacheAndCall(SuperCallSite.java:366)
         at org.jruby.runtime.callsite.SuperCallSite.callBlock(SuperCallSite.java:192)
         at org.jruby.runtime.callsite.SuperCallSite.call(SuperCallSite.java:197)
         at org.jruby.runtime.callsite.SuperCallSite.callVarargs(SuperCallSite.java:108)
         at org.jruby.ast.ZSuperNode.interpret(ZSuperNode.java:103)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)
         at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:182)
         at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:198)
         at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:326)
         at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:170)
         at org.jruby.ast.FCallSpecialArgNode.interpret(FCallSpecialArgNode.java:39)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)
         at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:204)
         at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:206)
         at org.jruby.runtime.callsite.SuperCallSite.cacheAndCall(SuperCallSite.java:366)
         at org.jruby.runtime.callsite.SuperCallSite.callBlock(SuperCallSite.java:192)
         at org.jruby.runtime.callsite.SuperCallSite.call(SuperCallSite.java:197)
         at org.jruby.runtime.callsite.SuperCallSite.callVarargs(SuperCallSite.java:108)
         at org.jruby.ast.ZSuperNode.interpret(ZSuperNode.java:103)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
         at org.jruby.ast.EnsureNode.interpret(EnsureNode.java:96)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_METHOD(ASTInterpreter.java:74)
         at org.jruby.internal.runtime.methods.InterpretedMethod.call(InterpretedMethod.java:204)
         at org.jruby.internal.runtime.methods.DefaultMethod.call(DefaultMethod.java:206)
         at org.jruby.runtime.callsite.SuperCallSite.cacheAndCall(SuperCallSite.java:366)
         at org.jruby.runtime.callsite.SuperCallSite.callBlock(SuperCallSite.java:192)
         at org.jruby.runtime.callsite.SuperCallSite.call(SuperCallSite.java:197)
         at org.jruby.runtime.callsite.SuperCallSite.callVarargs(SuperCallSite.java:108)
         at org.jruby.ast.SuperNode.interpret(SuperNode.java:115)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.RescueNode.executeBody(RescueNode.java:221)
         at org.jruby.ast.RescueNode.interpret(RescueNode.java:116)
         at org.jruby.ast.EnsureNode.interpret(EnsureNode.java:96)
         at org.jruby.ast.BeginNode.interpret(BeginNode.java:83)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.RescueNode.executeBody(RescueNode.java:221)
         at org.jruby.ast.RescueNode.interpret(RescueNode.java:116)
         at org.jruby.ast.EnsureNode.interpret(EnsureNode.java:96)
         at org.jruby.ast.BeginNode.interpret(BeginNode.java:83)
         at org.jruby.ast.NewlineNode.interpret(NewlineNode.java:105)
         at org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
         at org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:112)
         at org.jruby.runtime.Interpreted19Block.evalBlockBody(Interpreted19Block.java:206)
         at org.jruby.runtime.Interpreted19Block.yield(Interpreted19Block.java:194)
         at org.jruby.runtime.Interpreted19Block.call(Interpreted19Block.java:125)
         at org.jruby.runtime.Block.call(Block.java:101)
         at org.jruby.RubyProc.call(RubyProc.java:290)
         at org.jruby.RubyProc.call(RubyProc.java:228)
         at org.jruby.internal.runtime.RubyRunnable.run(RubyRunnable.java:99)
         at java.lang.Thread.run(Thread.java:745)

Yes, it's too big of a stacktrace, but this is the most relevant part to me:

         at rubyjit.ActionDispatch::Response::Buffer$$write_05376424d13f339e8e84b2326e8269bca3b39ef3681842940.__file__(/var/www/apps/shared/bundle/jruby/1.9/gems/actionpack-4.1.5/lib/action_dispatch/http/response.rb:90)
         at rubyjit.ActionDispatch::Response::Buffer$$write_05376424d13f339e8e84b2326e8269bca3b39ef3681842940.__file__(/var/www/apps/shared/bundle/jruby/1.9/gems/actionpack-4.1.5/lib/action_dispatch/http/response.rb)
         at rubyjit.ActionDispatch::Response::Buffer$$write_05376424d13f339e8e84b2326e8269bca3b39ef3681842940.__file__(/var/www/apps/shared/bundle/jruby/1.9/gems/actionpack-4.1.5/lib/action_dispatch/http/response.rb)
         at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:101)
         at org.jruby.runtime.callsite.SuperCallSite.callBlock(SuperCallSite.java:68)
         at org.jruby.runtime.callsite.SuperCallSite.call(SuperCallSite.java:75)
         at rubyjit.ActionController::Live::Buffer$$write_2deb09bd276a73c856527692b6dbda52e3e08f6f681842940.__file__(/var/www/apps/shared/bundle/jruby/1.9/gems/actionpack-4.1.5/lib/action_controller/metal/live.rb:124)
         at rubyjit.ActionController::Live::Buffer$$write_2deb09bd276a73c856527692b6dbda52e3e08f6f681842940.__file__(/var/www/apps/shared/bundle/jruby/1.9/gems/actionpack-4.1.5/lib/action_controller/metal/live.rb)

It blocks when attempting to push to the SizedQueue buffer:

def write(string)
raise IOError, "closed stream" if closed?

         @response.commit!
         @buf.push string
       end

This is a certification server (it also happens in production) and no requests were in place when I got the jstack output. Also, netstat didn't display any connection to the port the application was listening to.

For some reason some threads seem to block undefinitely and even Rack::Timeout won't kill such threads.

I have absolutely no idea why this is being blocked undefinitely but I'd like to suggest anyway that Rails uses some timeout mechanism while trying to write to the buffer (any ideas why Rack::Timeout won't kill such thread?) and allow developers to specify such timeout in seconds.

I'm using JRuby 1.7.12 (2.0.0p195) in case that helps. The jstack outputs use Puma 2.8.2 and 2.9.1.

Any ideas on what could be causing this?

The usual effect is that I'm notified by e-mail when this server stops responding and then I restart it but I'd like to understand exactly what's happening and fix it once and for all... Any help is appreciated.

jvm-bridge.stack (858 KB)

puma-jruby-rails.stack (99.3 KB)

Rodrigo_Rosenfeld_R1 · September 11, 2014, 2:55pm

Hi, I got more details about the issue and was able to replicate the issue. It happens both with JRuby and MRI and I'm not sure whether it's a Puma problem or not because I don't know other threaded server to test with...

I created a new very simple Rails 4.1.5 with actioncontroller/railties required in application.rb.

Basically, this is the controller:

main_controller.rb:

require 'timeout'
class MainController < ApplicationController
include ActionController::Live

   CHUNK = ('a' * 1_000_000).freeze
   def index
     logger.info 'outside timeout block'
     Timeout::timeout(5) do
       logger.info 'inside timeout block'
     10.times do |i|
       20.times{response.stream.write "#{CHUNK}\n"}
       sleep 1
     end
     logger.info 'timeout returned without errors'
   rescue
     logger.error "timeout rescue inside controller\n\n"
   ensure
     logger.error 'closing stream'
     Thread.current.exit
     # response.stream.close # this would block
     # logger.info 'stream closed'
   end
end

application_controller.rb:

require 'timeout'

class ApplicationController < ActionController::Base
   # Prevent CSRF attacks by raising an exception.
   # For APIs, you may want to use :null_session instead.
   protect_from_forgery with: :exception

   def process(*args)
     Timeout::timeout(5) do
       super
     end
   rescue
     logger.error "timeout happened!\n\n\n"
     raise 'error'
   end
end

Now, Rails will use a sized queue of size 10 for resonse.stream buffer. That's why I write 20 times.

Puma is used to serve the application in production mode with default settings (16 threads at most):

Now, I open an IRB session to simulate connections open by the client but then have been lost for any reason:

require 'socket'
20.times{s = TCPSocket.new 'localhost', 3000; s.puts "GET / HTTP/1.1\r\n\r\n";s.gets; s.close}

I can see 16 entries in the log and then the application stops responding. I can see all error logs but with JRuby I can see the threads still alive and waiting on object monitor inspecting a thread dump using the VisualVM tool. I'm not sure how to inspect threads in MRI but most probably the same happens with MRI as Puma also stops responding there too.

Any ideas on what is happening? Is this a Rails bug, a Rack bug or a Puma bug? How to handle such scenario? It seems the problem is that the connection is lost while the Rails app is trying to write to the buffer.

Maybe Rails should use another SizedQueue implementation that would accept some timeout if this is what's causing the issue (I tried to raise an error, terminate the current thread (Thread.current.exit) and to call close on the stream but none helped).

How can I debug this further to understand who is preventing the created threads from being terminated?

Thanks in advance,
Rodrigo.

Rodrigo_Rosenfeld_R1 · September 11, 2014, 6:34pm

I figured out what the problem is and just wanted to cross-link to the Rails and Puma issues I created:

https://github.com/rails/rails/issues/16878

https://github.com/puma/puma/issues/576