Details
-
Type:
Bug
-
Status:
Resolved
-
Priority:
Major
-
Resolution: Incomplete
-
Affects Version/s: JRuby 1.2
-
Fix Version/s: JRuby 1.5
-
Component/s: Core Classes/Modules
-
Labels:None
-
Environment:Hide# java -version
java version "1.6.0_13"
Java(TM) SE Runtime Environment (build 1.6.0_13-b03)
Java HotSpot(TM) 64-Bit Server VM (build 11.3-b02, mixed mode)
# uname -a
Linux host1 2.6.18-6-amd64 #1 SMP Fri Jun 6 05:24:08 UTC 2008 x86_64 GNU/Linux
The machine has 4 cores totalShow# java -version java version "1.6.0_13" Java(TM) SE Runtime Environment (build 1.6.0_13-b03) Java HotSpot(TM) 64-Bit Server VM (build 11.3-b02, mixed mode) # uname -a Linux host1 2.6.18-6-amd64 #1 SMP Fri Jun 6 05:24:08 UTC 2008 x86_64 GNU/Linux The machine has 4 cores total
-
Patch Submitted:Yes
Description
In a long running, multi-threaded JRuby on Rails application, it happened that suddenly, no request was servable, because every "puts" call created this type of exception:
[#|2009-05-19T15:15:49.516+0200|WARNING|glassfish|javax.enterprise.system.core|_ThreadID=13;_ThreadName=Thread-1;|The log message is null.
java.nio.BufferOverflowException
at java.nio.HeapByteBuffer.put(HeapByteBuffer.java:165)
at org.jruby.util.io.ChannelStream.bufferedWrite(ChannelStream.java:781)
at org.jruby.util.io.ChannelStream.fwrite(ChannelStream.java:925)
at org.jruby.RubyIO.fwrite(RubyIO.java:1255)
at org.jruby.RubyIO.write(RubyIO.java:1066)
at org.jruby.RubyIO$i_method_1_0$RUBYINVOKER$write.call(org/jruby/RubyIO$i_method_1_0$RUBYINVOKER$write.gen)
at org.jruby.RubyClass.finvoke(RubyClass.java:468)
at org.jruby.javasupport.util.RuntimeHelpers.invoke(RuntimeHelpers.java:392)
at org.jruby.RubyBasicObject.callMethod(RubyBasicObject.java:321)
at org.jruby.RubyIO.write(RubyIO.java:2000)
at org.jruby.RubyIO.puts(RubyIO.java:1990)
at org.jruby.RubyIO$i_method_0_0$RUBYINVOKER$puts.call(org/jruby/RubyIO$i_method_0_0$RUBYINVOKER$puts.gen)
at org.jruby.RubyClass.finvoke(RubyClass.java:449)
at org.jruby.javasupport.util.RuntimeHelpers.invoke(RuntimeHelpers.java:401)
at org.jruby.RubyBasicObject.callMethod(RubyBasicObject.java:329)
at org.jruby.RubyKernel.puts(RubyKernel.java:349)
at org.jruby.RubyKernel$s_method_0_0$RUBYINVOKER$puts.call(org/jruby/RubyKernel$s_method_0_0$RUBYINVOKER$puts.gen)
at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodN.call(JavaMethod.java:620)
at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:15
... (sourcecode where a "puts" call happens)
This bug seems to be a regression of JRUBY-2285
Activity
Well, I can (presumably), however, the server ran for about 4 weeks really busily using JRuby 1.2.0 until this bug appeared. Thus, it is unlikely that a further apparent non-appearance of the bug in the next months implies that the problem is fixed.
Xuan: Well let's call it resolved for now then. If it shows up again, try to capture as much information as you can and reopen the bug.
Well, it happened again, now with this configuration:
- jruby --version
jruby 1.3.1 (ruby 1.8.6p287) (2009-06-15 2fd6c3d) (Java HotSpot(TM) 64-Bit Server VM 1.6.0_13) [amd64-java]
#
and this stack trace:
java.nio.BufferOverflowException
at java.nio.HeapByteBuffer.put(HeapByteBuffer.java:165)
at org.jruby.util.io.ChannelStream.bufferedWrite(ChannelStream.java:781)
at org.jruby.util.io.ChannelStream.fwrite(ChannelStream.java:925)
at org.jruby.RubyIO.fwrite(RubyIO.java:1354)
at org.jruby.RubyIO.write(RubyIO.java:1165)
at org.jruby.RubyIO$i_method_1_0$RUBYINVOKER$write.call(org/jruby/RubyIO$i_method_1_0$RUBYINVOKER$write.gen)
at org.jruby.RubyClass.finvoke(RubyClass.java:530)
at org.jruby.javasupport.util.RuntimeHelpers.invoke(RuntimeHelpers.java:410)
at org.jruby.RubyBasicObject.callMethod(RubyBasicObject.java:315)
at org.jruby.RubyIO.write(RubyIO.java:2142)
at org.jruby.RubyIO.puts(RubyIO.java:2128)
at org.jruby.RubyKernel.puts(RubyKernel.java:417)
at org.jruby.RubyKernel$s_method_0_0$RUBYINVOKER$puts.call(org/jruby/RubyKernel$s_method_0_0$RUBYINVOKER$puts.gen)
at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodN.call(JavaMethod.java:620)
at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:164)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:115)
- jruby --version jruby 1.3.1 (ruby 1.8.6p287) (2009-06-15 2fd6c3d) (Java HotSpot(TM) 64-Bit Server VM 1.6.0_13) [amd64-java] #
Ok...after looking at the logic in ChannelStream, I can't see how it would blow up if all things are equal. It checks lengths, splits up writes, flushes if necessary, and so on. So the only possibility I can see would be a concurrency issue.
ChannelStream itself should be synchronized for all operations, so I don't think the problem is there. But the ByteList that's passed into this particular path comes directly from the argument to IO#write. If the associated string is being modified concurrently, it could potentially blow up an in-progress write.
This is also very difficult to prove. We would need a demo script that uses a given string object for writing while simultaneously growing the string, and the growing of the string needs to cause it to become larger than the remaining buffer size after that size has already been checked and ok.
A simple partial fix for this is as follows:
diff --git a/src/org/jruby/RubyIO.java b/src/org/jruby/RubyIO.java
index 752e88d..abe8a15 100644
--- a/src/org/jruby/RubyIO.java
+++ b/src/org/jruby/RubyIO.java
@@ -1162,7 +1162,7 @@ public class RubyIO extends RubyObject {
myOpenFile.checkWritable(runtime);
- int written = fwrite(str.getByteList());
+ int written = fwrite(str.getByteList().shallowDup());
if (written == -1) {
// TODO: sys fail
But of course this doesn't fix all consumers of ChannelStream. It may solve the issues that Xuân is seeing, however, and it may be possible to generalize it into a more complete patch pretty easily by tracking callers of ChannelStream.write and fwrite.
diff --git a/src/org/jruby/RubyIO.java b/src/org/jruby/RubyIO.java
index 752e88d..abe8a15 100644
--- a/src/org/jruby/RubyIO.java
+++ b/src/org/jruby/RubyIO.java
@@ -1162,7 +1162,7 @@ public class RubyIO extends RubyObject {
myOpenFile.checkWritable(runtime);
- int written = fwrite(str.getByteList());
+ int written = fwrite(str.getByteList().shallowDup());
if (written == -1) {
// TODO: sys fail
As serious as this problem appears to be it is too risky at this point to land a fix for it in 1.4. We will need to land any solution we have for it in 1.5.
I am seeing the same thing in a script that is called from a tomcat servlet container - it takes six to twelve hours to show up.
jruby 1.4.0 (ruby 1.8.7 patchlevel 174) (2009-11-03 6586) (Java HotSpot(TM) 64-Bit Server VM 1.6.0_06) [amd64-java]
puts call is on this line from the log listing below:
ruby.jit.ruby.home.explorer.legacyBridge.c2_strata_home.lib.connector.param_helper.add_params_to_state1224198347_1963380425.block_0$RUBY$q_block_(param_helper.rb:51)
java.nio.BufferOverflowException
at java.nio.HeapByteBuffer.put(HeapByteBuffer.java:165)
at org.jruby.util.io.ChannelStream.bufferedWrite(ChannelStream.java:1012)
at org.jruby.util.io.ChannelStream.fwrite(ChannelStream.java:1156)
at org.jruby.RubyIO.fwrite(RubyIO.java:1445)
at org.jruby.RubyIO.write(RubyIO.java:1249)
at org.jruby.RubyIO$i_method_1_0$RUBYINVOKER$write.call(org/jruby/RubyIO$i_method_1_0$RUBYINVOKER$write.gen)
at org.jruby.RubyClass.finvoke(RubyClass.java:568)
at org.jruby.javasupport.util.RuntimeHelpers.invoke(RuntimeHelpers.java:409)
at org.jruby.RubyBasicObject.callMethod(RubyBasicObject.java:317)
at org.jruby.RubyIO.write(RubyIO.java:2294)
at org.jruby.RubyIO.putsArray(RubyIO.java:2280)
at org.jruby.RubyIO.puts(RubyIO.java:2249)
at org.jruby.RubyKernel.puts(RubyKernel.java:435)
at org.jruby.RubyKernel$s_method_0_0$RUBYINVOKER$puts.call(org/jruby/RubyKernel$s_method_0_0$RUBYINVOKER$puts.gen)
at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodN.call(JavaMethod.java:623)
at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:176)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:147)
at ruby.jit.ruby.home.explorer.legacyBridge.c2_strata_home.lib.connector.param_helper.add_params_to_state1224198347_1963380425.block_0$RUBY$q_block_(param_helper.rb:51)
at ruby.jit.ruby.home.explorer.legacyBridge.c2_strata_home.lib.connector.param_helper.add_params_to_state1224198347_1963380425BlockCallback$block_0$RUBY$_block_xx1.call
(Unknown Source)
at org.jruby.runtime.CompiledBlock.yield(CompiledBlock.java:125)
at org.jruby.runtime.CompiledBlock.yieldSpecific(CompiledBlock.java:88)
at org.jruby.runtime.Block.yieldSpecific(Block.java:117)
at org.jruby.RubyHash$10.visit(RubyHash.java:1071)
at org.jruby.RubyHash.visitAll(RubyHash.java:576)
at org.jruby.RubyHash.iteratorVisitAll(RubyHash.java:1058)
at org.jruby.RubyHash.each(RubyHash.java:1069)
at org.jruby.RubyHash.each19(RubyHash.java:1089)
at org.jruby.RubyHash$i_method_0_0$RUBYFRAMEDINVOKER$each19.call(org/jruby/RubyHash$i_method_0_0$RUBYFRAMEDINVOKER$each19.gen)
at org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:116)
at org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:133)
at ruby.jit.ruby.home.explorer.legacyBridge.c2_strata_home.lib.connector.param_helper.add_params_to_state1224198347_1963380425._file_(param_helper.rb:49)
at ruby.jit.ruby.home.explorer.legacyBridge.c2_strata_home.lib.connector.param_helper.add_params_to_state1224198347_1963380425._file_(param_helper.rb)
at org.jruby.internal.runtime.methods.JittedMethod.call(JittedMethod.java:187)
at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:187)
at ruby.jit.ruby.home.explorer.legacyBridge.c2_strata_home.lib.connector.request_processor_base.preprocess1431620097_1963380425._file_(request_processor_base.rb:58)
at ruby.jit.ruby.home.explorer.legacyBridge.c2_strata_home.lib.connector.request_processor_base.preprocess1431620097_1963380425._file_(request_processor_base.rb)
I've been able to replicate this problem in JRuby 1.4.0 in an 8-core machine (where the JRuby application had a CPU load of more than 100% (=more than 1 core)).
Consider this output of this http://github.com/xbaldauf/jruby/tree/943d51c017648edd54b747281b30911835117c23 JRuby-1.4.0-fork (with enhanced debugging)
SCHWERWIEGEND: caught while buffer=java.nio.HeapByteBuffer[pos=0 lim=1 cap=4096], buf="obfuscatedobfusc", buf.begin()=0,buf.length()=16 (clearing buffer afterwards):
SCHWERWIEGEND: java.nio.BufferOverflowException
SCHWERWIEGEND: at java.nio.HeapByteBuffer.put(HeapByteBuffer.java:165)
SCHWERWIEGEND: at org.jruby.util.io.ChannelStream.bufferedWrite(ChannelStream.java:1013)
SCHWERWIEGEND: at org.jruby.util.io.ChannelStream.fwrite(ChannelStream.java:1162)
SCHWERWIEGEND: at org.jruby.RubyIO.fwrite(RubyIO.java:144
When the java.nio.HeapByteBuffer.put() call happens, buffer.position==0 and buffer.limit==1. Thus, in statement
if (buf.length() > buffer.remaining()) flushWrite();
flushWrite() will be called. One would expect that flushWrite() makes the buffer ready to be written. However, flushWrite()'s very first line of source code is
if (reading || !modes.isWritable() || buffer.position() == 0) return; // Don't bother
which means that flushWrite() becomes a no-operation in this case, and flushWrite() does not do anything to the buffer. Hence, the 16 bytes to be written do not fit in the 1 byte left (which should actually be 4096 bytes left), and buffer.put() fails.
Please have a look at http://github.com/xbaldauf/jruby/commit/73045a15fdd7f8c3c32314b5ff8d4ca35fdaab87
I've fixed two bugs which may be the cause for this bug.
The changes look good to me; I'm testing them now (full ant test spec-short run).
Xuan: Sorry to not get back to this sooner.
I applied your change, which looked ok...but it causes a failure in at least one Ruby test:
tmp = open("while_tmp", "w")
tmp.print "tvi925\n";
tmp.print "tvi920\n";
tmp.print "vt100\n";
tmp.print "Amiga\n";
tmp.print "paper\n";
tmp.close
# test break
tmp = open("while_tmp", "r")
test_ok(tmp.kind_of?(File))
while line = tmp.gets()
break if /vt100/ =~ line
end
test_ok(!tmp.eof? && /vt100/ =~ line)
tmp.close
The last test_ok line fails. This is from test/mri/sample/test.rb. Can you try to run that script on your copy of JRuby and see if you get the same failure?
tmp = open("while_tmp", "w")
tmp.print "tvi925\n";
tmp.print "tvi920\n";
tmp.print "vt100\n";
tmp.print "Amiga\n";
tmp.print "paper\n";
tmp.close
# test break
tmp = open("while_tmp", "r")
test_ok(tmp.kind_of?(File))
while line = tmp.gets()
break if /vt100/ =~ line
end
test_ok(!tmp.eof? && /vt100/ =~ line)
tmp.close
More info: With the patch applied, lots of stuff seems to break. I have not investigated.
Well, I'm running JRuby 1.5 now, and the bug is still there, albeit in a slightly different form
[Jun 24, 2010 10:29:42 PM] Interrupting idle Thread: http-thread-pool-1234-(26)
/!\ FAILSAFE /!\ Thu Jun 24 22:29:42 +0200 2010
Status: 500 Internal Server Error
Bad file descriptor - Bad file descriptor
/obfuscated/app/specific.rb:58:in `call'
/usr/local/lib/jruby-1.5.0/lib/ruby/gems/1.8/gems/rails-2.3.8/lib/rails/rack/metal.rb:44:in `call'
/usr/local/lib/jruby-1.5.0/lib/ruby/gems/1.8/gems/rails-2.3.8/lib/rails/rack/metal.rb:43:in `each'
/usr/local/lib/jruby-1.5.0/lib/ruby/gems/1.8/gems/rails-2.3.8/lib/rails/rack/metal.rb:43:in `call'
/usr/local/lib/jruby-1.5.0/lib/ruby/gems/1.8/gems/actionpack-2.3.8/lib/action_controller/failsafe.rb:26:in `call'
/usr/local/lib/jruby-1.5.0/lib/ruby/gems/1.8/gems/actionpack-2.3.8/lib/action_controller/dispatcher.rb:106:in `call'
/usr/local/lib/jruby-1.5.0/lib/ruby/gems/1.8/gems/glassfish-1.0.3.dev-universal-java/lib/rack/adapter/rails.rb:133:in `call'
/usr/local/lib/jruby-1.5.0/lib/ruby/gems/1.8/gems/glassfish-1.0.3.dev-universal-java/lib/rack/handler/grizzly.rb:55:in `call'
:1
/!\ FAILSAFE /!\ Thu Jun 24 22:29:42 +0200 2010
Status: 500 Internal Server Error
#<Java::JavaNio::BufferOverflowException:0x227d5382>
java.nio.HeapByteBuffer.put(HeapByteBuffer.java:165)
org.jruby.util.io.ChannelStream.bufferedWrite(ChannelStream.java:1045)
org.jruby.util.io.ChannelStream.fwrite(ChannelStream.java:1222)
org.jruby.RubyIO.fwrite(RubyIO.java:1482)
org.jruby.RubyIO.write(RubyIO.java:1286)
org.jruby.RubyIO$i_method_1_0$RUBYINVOKER$write.call(org/jruby/RubyIO$i_method_1_0$RUBYINVOKER$write.gen:65535)
org.jruby.RubyClass.finvoke(RubyClass.java:663)
org.jruby.javasupport.util.RuntimeHelpers.invoke(RuntimeHelpers.java:452)
org.jruby.RubyBasicObject.callMethod(RubyBasicObject.java:332)
org.jruby.RubyIO.write(RubyIO.java:2330)
org.jruby.RubyIO.putsArray(RubyIO.java:2316)
org.jruby.RubyIO.puts(RubyIO.java:2285)
org.jruby.RubyKernel.puts(RubyKernel.java:483)
org.jruby.RubyKernel$s_method_0_0$RUBYINVOKER$puts.call(org/jruby/RubyKernel$s_method_0_0$RUBYINVOKER$puts.gen:65535)
org.jruby.internal.runtime.methods.JavaMethod$JavaMethodN.call(JavaMethod.java:630)
org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:186)
org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:309)
org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:148)
As usual, the filedescriptor #1 (stdout) is set to /dev/null.
This JRuby on Rails instance runs rails 2.3.8 with the glassfish gem 1.0.2 on "jruby 1.5.0 (ruby 1.8.7 patchlevel 249) (2010-05-12 6769999) (Java HotSpot(TM) 64-Bit Server VM 1.6.0_20) [amd64-java]".
My current theory is that this bug is actually a side effect of another bug: Maybe someone calls freopen("/dev/null",...,STDOUT) and thus overwrites the filedescriptor #1. However, I monkey-patched IO::reopen to catch any reopen-attempts, but this did not seem to have an effect. Nevertheless, if STDOUT is /dev/null, why actually is there a buffer overflow? Does writing to stdout fail?
[Jun 24, 2010 10:29:42 PM] Interrupting idle Thread: http-thread-pool-1234-(26)
/!\ FAILSAFE /!\ Thu Jun 24 22:29:42 +0200 2010
Status: 500 Internal Server Error
Bad file descriptor - Bad file descriptor
/obfuscated/app/specific.rb:58:in `call'
/usr/local/lib/jruby-1.5.0/lib/ruby/gems/1.8/gems/rails-2.3.8/lib/rails/rack/metal.rb:44:in `call'
/usr/local/lib/jruby-1.5.0/lib/ruby/gems/1.8/gems/rails-2.3.8/lib/rails/rack/metal.rb:43:in `each'
/usr/local/lib/jruby-1.5.0/lib/ruby/gems/1.8/gems/rails-2.3.8/lib/rails/rack/metal.rb:43:in `call'
/usr/local/lib/jruby-1.5.0/lib/ruby/gems/1.8/gems/actionpack-2.3.8/lib/action_controller/failsafe.rb:26:in `call'
/usr/local/lib/jruby-1.5.0/lib/ruby/gems/1.8/gems/actionpack-2.3.8/lib/action_controller/dispatcher.rb:106:in `call'
/usr/local/lib/jruby-1.5.0/lib/ruby/gems/1.8/gems/glassfish-1.0.3.dev-universal-java/lib/rack/adapter/rails.rb:133:in `call'
/usr/local/lib/jruby-1.5.0/lib/ruby/gems/1.8/gems/glassfish-1.0.3.dev-universal-java/lib/rack/handler/grizzly.rb:55:in `call'
:1
/!\ FAILSAFE /!\ Thu Jun 24 22:29:42 +0200 2010
Status: 500 Internal Server Error
#<Java::JavaNio::BufferOverflowException:0x227d5382>
java.nio.HeapByteBuffer.put(HeapByteBuffer.java:165)
org.jruby.util.io.ChannelStream.bufferedWrite(ChannelStream.java:1045)
org.jruby.util.io.ChannelStream.fwrite(ChannelStream.java:1222)
org.jruby.RubyIO.fwrite(RubyIO.java:1482)
org.jruby.RubyIO.write(RubyIO.java:1286)
org.jruby.RubyIO$i_method_1_0$RUBYINVOKER$write.call(org/jruby/RubyIO$i_method_1_0$RUBYINVOKER$write.gen:65535)
org.jruby.RubyClass.finvoke(RubyClass.java:663)
org.jruby.javasupport.util.RuntimeHelpers.invoke(RuntimeHelpers.java:452)
org.jruby.RubyBasicObject.callMethod(RubyBasicObject.java:332)
org.jruby.RubyIO.write(RubyIO.java:2330)
org.jruby.RubyIO.putsArray(RubyIO.java:2316)
org.jruby.RubyIO.puts(RubyIO.java:2285)
org.jruby.RubyKernel.puts(RubyKernel.java:483)
org.jruby.RubyKernel$s_method_0_0$RUBYINVOKER$puts.call(org/jruby/RubyKernel$s_method_0_0$RUBYINVOKER$puts.gen:65535)
org.jruby.internal.runtime.methods.JavaMethod$JavaMethodN.call(JavaMethod.java:630)
org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:186)
org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:309)
org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:148)
I'm going to mark this incomplete. A lot of work has happened in the past year, since this bug was last updated. And as far as I know we have seen no similar bugs for late 1.5.x versions or for 1.6.x versions. Reopen if it is still a problem.
I'm running on JRuby1.6.1 with GlassFishv3 (jruby 1.6.1 (ruby-1.8.7-p330) (2011-04-12 85838f6) (Java HotSpot(TM) 64-Bit Server VM 1.6.0_25) [linux-amd64-java]), and found a similar bug. This is the stack trace:
Errno::EBADF (Bad file descriptor - Bad file descriptor):
org/jruby/RubyIO.java:1327:in `write'
/home/admin/glassfishv3/glassfish/domains/domain1/generated/jsp/game_server/loader_11516509/META-INF/jruby.home/lib/ruby/1.8/logge
r.rb:504:in `write'
/home/admin/glassfishv3/glassfish/domains/domain1/generated/jsp/game_server/loader_11516509/META-INF/jruby.home/lib/ruby/1.8/monit
or.rb:191:in `mon_synchronize'
/home/admin/glassfishv3/glassfish/domains/domain1/generated/jsp/game_server/loader_11516509/META-INF/jruby.home/lib/ruby/1.8/logge
r.rb:496:in `write'
/home/admin/glassfishv3/glassfish/domains/domain1/generated/jsp/game_server/loader_11516509/META-INF/jruby.home/lib/ruby/1.8/logge
r.rb:326:in `add'
/home/admin/glassfishv3/glassfish/domains/domain1/generated/jsp/game_server/loader_11516509/META-INF/jruby.home/lib/ruby/1.8/logge
r.rb:383:in `warn'
app/controllers/application_controller.rb:156:in `user_status_filter'
org/jruby/RubyKernel.java:2052:in `send'
gems/gems/activesupport-2.3.9/lib/active_support/callbacks.rb:178:in `evaluate_method'
gems/gems/actionpack-2.3.9/lib/action_controller/filters.rb:186:in `call'
gems/gems/actionpack-2.3.9/lib/action_controller/filters.rb:635:in `run_before_filters'
gems/gems/actionpack-2.3.9/lib/action_controller/filters.rb:615:in `call_filters'
gems/gems/actionpack-2.3.9/lib/action_controller/filters.rb:610:in `perform_action_with_filters'
gems/gems/actionpack-2.3.9/lib/action_controller/benchmarking.rb:68:in `perform_action_with_benchmark'
gems/gems/actionpack-2.3.9/lib/action_controller/benchmarking.rb:68:in `perform_action_with_benchmark'
gems/gems/actionpack-2.3.9/lib/action_controller/rescue.rb:160:in `perform_action_with_rescue'
gems/gems/actionpack-2.3.9/lib/action_controller/flash.rb:151:in `perform_action_with_flash'
org/jruby/RubyKernel.java:2052:in `send'
gems/gems/actionpack-2.3.9/lib/action_controller/base.rb:532:in `process'
gems/gems/actionpack-2.3.9/lib/action_controller/filters.rb:606:in `process_with_filters'
gems/gems/actionpack-2.3.9/lib/action_controller/base.rb:391:in `process'
gems/gems/actionpack-2.3.9/lib/action_controller/base.rb:386:in `call'
gems/gems/actionpack-2.3.9/lib/action_controller/routing/route_set.rb:438:in `call'
gems/gems/actionpack-2.3.9/lib/action_controller/dispatcher.rb:87:in `dispatch'
gems/gems/actionpack-2.3.9/lib/action_controller/dispatcher.rb:121:in `_call'
gems/gems/actionpack-2.3.9/lib/action_controller/dispatcher.rb:130:in `build_middleware_stack'
org/jruby/RubyProc.java:268:in `call'
org/jruby/RubyProc.java:228:in `call'
gems/gems/actionpack-2.3.9/lib/action_controller/string_coercion.rb:25:in `call'
/home/admin/glassfishv3/glassfish/domains/domain1/generated/jsp/game_server/loader_11516509/vendor/rack-1.2.2/rack/head.rb:9:in `c
all'
/home/admin/glassfishv3/glassfish/domains/domain1/generated/jsp/game_server/loader_11516509/vendor/rack-1.2.2/rack/methodoverride.
rb:24:in `call'
gems/gems/actionpack-2.3.9/lib/action_controller/params_parser.rb:15:in `call'
gems/gems/actionpack-2.3.9/lib/action_controller/session/cookie_store.rb:100:in `call'
gems/gems/actionpack-2.3.9/lib/action_controller/failsafe.rb:26:in `call'
/home/admin/glassfishv3/glassfish/domains/domain1/generated/jsp/game_server/loader_11516509/vendor/rack-1.2.2/rack/lock.rb:11:in `
call'
/home/admin/glassfishv3/glassfish/domains/domain1/generated/jsp/game_server/loader_11516509/vendor/rack-1.2.2/rack/lock.rb:11:in `
call'
gems/gems/actionpack-2.3.9/lib/action_controller/dispatcher.rb:106:in `call'
/home/admin/glassfishv3/glassfish/domains/domain1/generated/jsp/game_server/loader_11516509/rack/adapter/rails.rb:36:in `serve_rai
ls'
/home/admin/glassfishv3/glassfish/domains/domain1/generated/jsp/game_server/loader_11516509/rack/adapter/rails.rb:41:in `call'
/home/admin/glassfishv3/glassfish/domains/domain1/generated/jsp/game_server/loader_11516509/jruby/rack/rails.rb:187:in `call'
/home/admin/glassfishv3/glassfish/domains/domain1/generated/jsp/game_server/loader_11516509/rack/handler/servlet.rb:19:in `call'
Java::JavaNio::BufferOverflowException ():
java.nio.HeapByteBuffer.put(HeapByteBuffer.java:165)
org.jruby.util.io.ChannelStream.bufferedWrite(ChannelStream.java:1054)
org.jruby.util.io.ChannelStream.fwrite(ChannelStream.java:1233)
org.jruby.RubyIO.fwrite(RubyIO.java:1445)
org.jruby.RubyIO.write(RubyIO.java:1327)
org.jruby.RubyIO$i$1$0$write.call(RubyIO$i$1$0$write.gen:65535)
org.jruby.RubyClass.finvoke(RubyClass.java:685)
org.jruby.javasupport.util.RuntimeHelpers.invoke(RuntimeHelpers.java:548)
org.jruby.RubyBasicObject.callMethod(RubyBasicObject.java:358)
org.jruby.RubyIO.write(RubyIO.java:2305)
org.jruby.RubyIO.putsArray(RubyIO.java:2291)
org.jruby.RubyIO.puts(RubyIO.java:2260)
org.jruby.RubyIO.puts(RubyIO.java:2252)
org.jruby.RubyIO$i$0$0$puts.call(RubyIO$i$0$0$puts.gen:65535)
org.jruby.internal.runtime.methods.JavaMethod$JavaMethodN.call(JavaMethod.java:630)
org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:205)
org.jruby.RubyClass.finvoke(RubyClass.java:685)
org.jruby.javasupport.util.RuntimeHelpers.invoke(RuntimeHelpers.java:548)
org.jruby.RubyKernel.warn(RubyKernel.java:1300)
org.jruby.RubyKernel$s$1$0$warn.call(RubyKernel$s$1$0$warn.gen:65535)
org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:137)
org.jruby.ast.FCallOneArgNode.interpret(FCallOneArgNode.java:36)
org.jruby.ast.NewlineNode.interpret(NewlineNode.java:103)
org.jruby.ast.BlockNode.interpret(BlockNode.java:71)
org.jruby.ast.RescueBodyNode.interpret(RescueBodyNode.java:108)
org.jruby.ast.RescueNode.handleException(RescueNode.java:181)
org.jruby.ast.RescueNode.interpretWithJavaExceptions(RescueNode.java:124)
org.jruby.ast.RescueNode.interpret(RescueNode.java:110)
org.jruby.ast.BeginNode.interpret(BeginNode.java:83)
org.jruby.ast.NewlineNode.interpret(NewlineNode.java:103)
org.jruby.evaluator.ASTInterpreter.INTERPRET_BLOCK(ASTInterpreter.java:111)
org.jruby.runtime.InterpretedBlock.evalBlockBody(InterpretedBlock.java:374)
org.jruby.runtime.InterpretedBlock.yield(InterpretedBlock.java:347)
org.jruby.runtime.InterpretedBlock.yield(InterpretedBlock.java:304)
org.jruby.runtime.Block.yield(Block.java:130)
org.jruby.RubyArray.eachCommon(RubyArray.java:1595)
org.jruby.RubyArray.each(RubyArray.java:1602)
org.jruby.RubyArray$i$0$0$each.call(RubyArray$i$0$0$each.gen:65535)
org.jruby.runtime.callsite.CachingCallSite.callBlock(CachingCallSite.java:112)
org.jruby.runtime.callsite.CachingCallSite.callIter(CachingCallSite.java:123)
org.jruby.ast.CallNoArgBlockNode.interpret(CallNoArgBlockNode.java:64)
org.jruby.ast.NewlineNode.interpret(NewlineNode.java:103)
.........................
The ruby code in 'app/controllers/application_controller.rb' is:
155: logger = Logger.new(STDOUT)
156: logger.warn("blablabla.....") <= error occurred
Alex: The issue in GlassFish is a separate one...network streams getting closed prematurely. We have added features to JRuby 1.6 and jruby-rack to prevent this, but the GlassFish gem is unlikely to ever be updated for these changes. We recommend looking at Trinidad for small server purposes and Torquebox for full EE server support.
Try it again using the lastest jruby source (rev 61a0d45a0af9c648a9374df9122a9ee3bdd13127 or later).
ChannelStream#sync was unsynchronized, and directly modified the write buffer, which possibly could have caused it.
If it still persists, can you try and create a small ruby script that reproduces the problem?