Timeout.rb is not working in special cases (Thread may block whole application).

Details

  • Type: Bug Bug
  • Status: Closed Closed
  • Priority: Major Major
  • Resolution: Fixed
  • Affects Version/s: JRuby 1.1.5
  • Fix Version/s: JRuby 1.2
  • Component/s: Core Classes/Modules
  • Labels:
    None
  • Environment:
    Microsoft Windows XP Professional SP3, JDK1.6.0_07, JRuby 1.1.5

Description

As already mentioned here (http://jira.codehaus.org/browse/JRUBY-2148), JRuby is not working correctly when using timeouts, whereas the original Ruby Interpreter is doing the job in the cases I tested. It would be very nice to somehow fix this bug, as other classes such as Net::Http are also affected by JRuby's erratic behaviour. In my example an Http-request to a slow responding server only throws the Timeout::Error after a response from the server is received, as Timeout's "Killer-Thread" is blocked by the main thread waiting for the server's response. A demonstrating script is attached. For executing the script, a server is required, that waits some seconds before sending the response (e.g. easy RoR app with sleep(10) in the index method).

  1. File
    http_test.rb
    03/Sep/08 8:10 AM
    1 kB
    Maximilian Walther

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Charles Oliver Nutter added a comment -

This particular case appears to work well now. We have made modifications over the past several months that should make most IO operations interruptible, which allows timeout to fire. If you see additional cases failing please file bugs.

Show
Charles Oliver Nutter added a comment - This particular case appears to work well now. We have made modifications over the past several months that should make most IO operations interruptible, which allows timeout to fire. If you see additional cases failing please file bugs.
Hide
Permalink
Christian Seiler added a comment -

Oh great to see this fixed. I got bitten by this one a couple of times (e.g. activemessaging blocked on non-responding ActiveMQ). Or currently a thread on my server is being locked since two days (importing a twitter timeline, running on JRuby 1.1.6):

at sun.nio.ch.FileDispatcher.read0(Native Method)
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21)
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233)
at sun.nio.ch.IOUtil.read(IOUtil.java:206)
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236)

  • locked <0x00002aaad70adcc0> (a java.lang.Object)
    at org.jruby.util.io.ChannelDescriptor.read(ChannelDescriptor.java:464)
    at org.jruby.util.io.ChannelDescriptor.read(ChannelDescriptor.java:438)
    at org.jruby.RubyIO.sysread(RubyIO.java:2119)
    at org.jruby.RubyIO$i_method_0_1$RUBYINVOKER$sysread.call(org/jruby/RubyIO$i_method_0_1$RUBYINVOKER$sysread.gen)
    at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodNoBlock.call(JavaMethod.java:62)
    at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:243)
    at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:152)
    at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:114)
    at ruby.jit.ruby.usr.local.jruby_minus_1_dot_1_dot_6.lib.ruby.$1_dot_8.net.protocol.rbuf_fill2136491728_1395225393.bloc
    k_0$RUBY$_block_(protocol.rb:133)
    at ruby.jit.ruby.usr.local.jruby_minus_1_dot_1_dot_6.lib.ruby.$1_dot_8.net.protocol.rbuf_fill2136491728_1395225393Block
    Callback$block_0$RUBY$_block_xx1.call(Unknown Source)
    at org.jruby.runtime.CompiledBlock.yield(CompiledBlock.java:120)

I find this a bit weird anyway. 'lsof' doesn't report any established TCP connection to Twitter (one should expect this after two days), so shouldn't the read somehow fail?

Show
Christian Seiler added a comment - Oh great to see this fixed. I got bitten by this one a couple of times (e.g. activemessaging blocked on non-responding ActiveMQ). Or currently a thread on my server is being locked since two days (importing a twitter timeline, running on JRuby 1.1.6): at sun.nio.ch.FileDispatcher.read0(Native Method) at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:21) at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:233) at sun.nio.ch.IOUtil.read(IOUtil.java:206) at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:236)
  • locked <0x00002aaad70adcc0> (a java.lang.Object) at org.jruby.util.io.ChannelDescriptor.read(ChannelDescriptor.java:464) at org.jruby.util.io.ChannelDescriptor.read(ChannelDescriptor.java:438) at org.jruby.RubyIO.sysread(RubyIO.java:2119) at org.jruby.RubyIO$i_method_0_1$RUBYINVOKER$sysread.call(org/jruby/RubyIO$i_method_0_1$RUBYINVOKER$sysread.gen) at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodNoBlock.call(JavaMethod.java:62) at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:243) at org.jruby.internal.runtime.methods.DynamicMethod.call(DynamicMethod.java:152) at org.jruby.runtime.callsite.CachingCallSite.call(CachingCallSite.java:114) at ruby.jit.ruby.usr.local.jruby_minus_1_dot_1_dot_6.lib.ruby.$1_dot_8.net.protocol.rbuf_fill2136491728_1395225393.bloc k_0$RUBY$_block_(protocol.rb:133) at ruby.jit.ruby.usr.local.jruby_minus_1_dot_1_dot_6.lib.ruby.$1_dot_8.net.protocol.rbuf_fill2136491728_1395225393Block Callback$block_0$RUBY$_block_xx1.call(Unknown Source) at org.jruby.runtime.CompiledBlock.yield(CompiledBlock.java:120)
I find this a bit weird anyway. 'lsof' doesn't report any established TCP connection to Twitter (one should expect this after two days), so shouldn't the read somehow fail?
Hide
Permalink
Maximilian Walther added a comment -

Thanks for taking care of that bug. I will make some tests in the application I created those days and give feedback asap.

Show
Maximilian Walther added a comment - Thanks for taking care of that bug. I will make some tests in the application I created those days and give feedback asap.
Hide
Permalink
Charles Oliver Nutter added a comment -

Christian: Yeah, that surprises me too. Can you file a separate bug with a full set of traces and we'll look it over?

Show
Charles Oliver Nutter added a comment - Christian: Yeah, that surprises me too. Can you file a separate bug with a full set of traces and we'll look it over?
Hide
Permalink
Wyatt Kapastin added a comment -

We are seeing this same problem running with both JRuby 1.1.5 and even 1.3.1. We send a request to a remote web service that runs beyond the timeout setting we have specified, very similar to this example, but we ultimately receive a "Timeout error occurred" exception several (9+) seconds after our specified timeout period. What's worse however, is that the request never ultimately makes it back to the calling application, event though our firewall indicates that the response was sent back. My hunch is that if the request time runs longer than the timeout, that the timeout code ultimately kills it before it makes it back through to us. The implication is that the calling application perceives the request as a failure, but the processing successfully completes on the remote server. This is a significant issue for us because we roll back the transaction on the calling server, which we should not do. Any further insights into this would be greatly appreciated - we can provide as much information as is necessary to further troubleshoot.

Show
Wyatt Kapastin added a comment - We are seeing this same problem running with both JRuby 1.1.5 and even 1.3.1. We send a request to a remote web service that runs beyond the timeout setting we have specified, very similar to this example, but we ultimately receive a "Timeout error occurred" exception several (9+) seconds after our specified timeout period. What's worse however, is that the request never ultimately makes it back to the calling application, event though our firewall indicates that the response was sent back. My hunch is that if the request time runs longer than the timeout, that the timeout code ultimately kills it before it makes it back through to us. The implication is that the calling application perceives the request as a failure, but the processing successfully completes on the remote server. This is a significant issue for us because we roll back the transaction on the calling server, which we should not do. Any further insights into this would be greatly appreciated - we can provide as much information as is necessary to further troubleshoot.
Hide
Permalink
Charles Oliver Nutter added a comment -

Wyatt: I'm guessing the issue is fixed on JRuby master. The new timeout implementation did not cover some key scenarios. Can you try a nightly build?

Show
Charles Oliver Nutter added a comment - Wyatt: I'm guessing the issue is fixed on JRuby master. The new timeout implementation did not cover some key scenarios. Can you try a nightly build?

People

  • Assignee:
    Charles Oliver Nutter
    Reporter:
    Maximilian Walther
Vote (1)
Watch (2)

Dates

  • Created:
    Updated:
    Resolved: