JRuby

Net::Http does not close socket when open_timeout is exceeded

Details

  • Number of attachments :
    0

Description

When open_timeout is exceeded the connection is still established even though it throws Timeout::Error, and the socket is left open. The following code will leave an established connection that you can see in netstat. Trying to call finish throws an IO error.

  begin
    puts 'STARTING CONNECTION'
    @conn = Net::HTTP.new("www.google.com",80)
    @conn.open_timeout = 0.001
    @conn.start
  rescue Timeout::Error => e
    puts 'CONNECTION TIMEOUT'
    #@conn.finish
    puts "CONNECTION FINISHED"
  end
  sleep 1000

Issue Links

is duplicated by

Bug - A problem which impairs or prevents the functions of the product. JRUBY-6607 TCPSocket connect failure inside Timeout leaves orphaned sockets

  • Major - Major loss of function.
  • Resolved - A resolution has been taken, and it is awaiting verification by reporter. From here issues are either reopened, or are closed.

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Chris Ochs added a comment -

FYI cruby 1.8.7 works correctly and does not leave an open connection.

Show
Chris Ochs added a comment - FYI cruby 1.8.7 works correctly and does not leave an open connection.
Hide
Permalink
Chris Ochs added a comment -

This is really strange. So the line in Net::HTTP that makes the socket connection is wrapped in a timeout like so:

s = timeout(@open_timeout)

{ TCPSocket.open(conn_address(), conn_port()) }

Timeout::Error is being thrown, but the socket still gets connected?

Show
Chris Ochs added a comment - This is really strange. So the line in Net::HTTP that makes the socket connection is wrapped in a timeout like so: s = timeout(@open_timeout) { TCPSocket.open(conn_address(), conn_port()) } Timeout::Error is being thrown, but the socket still gets connected?
Hide
Permalink
Charles Oliver Nutter added a comment -

If I'm reading this right, here's the netstat entry:

tcp4       0      0  192.168.0.4.52299      74.125.225.114.80      TIME_WAIT

On UNIX, sockets that are closed go into TIME_WAIT state to ensure all data has been sent, so it looks like this has been closed ok. Do you get something different?

I also get the same error message with MRI 1.8.7 when I uncomment the "finish" line:

system ~/projects/jruby $ jruby -rtimeout -rnet/http timeout_thing.rb 
STARTING CONNECTION
CONNECTION TIMEOUT
IOError: HTTP session not yet started
  finish at /Users/headius/projects/jruby/lib/ruby/1.9/net/http.rb:820
  (root) at timeout_thing.rb:5

system ~/projects/jruby $ ruby -rtimeout -rnet/http timeout_thing.rb 
STARTING CONNECTION
CONNECTION TIMEOUT
/System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/lib/ruby/1.8/net/http.rb:602:in `finish': HTTP session not yet started (IOError)
	from timeout_thing.rb:8

I do not see the netstat entry, but it's possible your timeout is so short MRI hasn't even attempted to make the connection yet...

Show
Charles Oliver Nutter added a comment - If I'm reading this right, here's the netstat entry: tcp4 0 0 192.168.0.4.52299 74.125.225.114.80 TIME_WAIT On UNIX, sockets that are closed go into TIME_WAIT state to ensure all data has been sent, so it looks like this has been closed ok. Do you get something different? I also get the same error message with MRI 1.8.7 when I uncomment the "finish" line: system ~/projects/jruby $ jruby -rtimeout -rnet/http timeout_thing.rb STARTING CONNECTION CONNECTION TIMEOUT IOError: HTTP session not yet started finish at /Users/headius/projects/jruby/lib/ruby/1.9/net/http.rb:820 (root) at timeout_thing.rb:5 system ~/projects/jruby $ ruby -rtimeout -rnet/http timeout_thing.rb STARTING CONNECTION CONNECTION TIMEOUT /System/Library/Frameworks/Ruby.framework/Versions/1.8/usr/lib/ruby/1.8/net/http.rb:602:in `finish': HTTP session not yet started (IOError) from timeout_thing.rb:8 I do not see the netstat entry, but it's possible your timeout is so short MRI hasn't even attempted to make the connection yet...
Hide
Permalink
Charles Oliver Nutter added a comment -

More eyes on this one (rather than JRUBY-6607) so I'm commenting here on the evenings explorations.

JRuby 1.6 or 1.7 both appear to drop the connection just fine with no lingering TIME_WAIT state when running on Java 7. I'm starting to think there's some JVM bug or improvement at play.

TIME_WAIT is the state that a socket goes into when closed if there's a possibility of packets still on the wire. It holds the socket in place to handle those rogue packets if they show up, and prevents additional connections that might be confused by those roque packets.

The length of time a socket will be in TIME_WAIT is determined at the kernel or system-global level.

I have read through MRI code again, and can't find anything they're doing to allow incomplete connections to disappear completely without TIME_WAIT. Evidence seems to be leading me to the conclusion that something OpenJDK/Sun JDK/Oracle JDK versions 1.6.x and lower are doing is causing these connections to hang around for a while.

FWIW, I see the following line in rbx for the script from JRUBY-6607, which is also very confusing:

vm      69644 headius    5u  IPv4 0xffffff8018dfb5e8        0t0      TCP 192.168.0.8:60211->10.255.255.1:http (SYN_SENT)

I'm not sure how to proceed with either this one or JRUBY-6607 at this point. I have tried various combinations of socket flags, and nothing appears to change behavior. I've added additional layers of closing and finishing in RubyTCPSocket.initialize, and not had any luck. The only thing that works for me seems to be using Java 7.

Can anyone else confirm this bug or JRUBY-6607 work as expected for them on Java 7 builds?

Show
Charles Oliver Nutter added a comment - More eyes on this one (rather than JRUBY-6607 ) so I'm commenting here on the evenings explorations. JRuby 1.6 or 1.7 both appear to drop the connection just fine with no lingering TIME_WAIT state when running on Java 7. I'm starting to think there's some JVM bug or improvement at play. TIME_WAIT is the state that a socket goes into when closed if there's a possibility of packets still on the wire. It holds the socket in place to handle those rogue packets if they show up, and prevents additional connections that might be confused by those roque packets. The length of time a socket will be in TIME_WAIT is determined at the kernel or system-global level. I have read through MRI code again, and can't find anything they're doing to allow incomplete connections to disappear completely without TIME_WAIT. Evidence seems to be leading me to the conclusion that something OpenJDK/Sun JDK/Oracle JDK versions 1.6.x and lower are doing is causing these connections to hang around for a while. FWIW, I see the following line in rbx for the script from JRUBY-6607 , which is also very confusing: vm 69644 headius 5u IPv4 0xffffff8018dfb5e8 0t0 TCP 192.168.0.8:60211->10.255.255.1:http (SYN_SENT) I'm not sure how to proceed with either this one or JRUBY-6607 at this point. I have tried various combinations of socket flags, and nothing appears to change behavior. I've added additional layers of closing and finishing in RubyTCPSocket.initialize, and not had any luck. The only thing that works for me seems to be using Java 7. Can anyone else confirm this bug or JRUBY-6607 work as expected for them on Java 7 builds?
Hide
Permalink
Charles Oliver Nutter added a comment -

The fixes for JRUBY-6607 appear to have fixed this as well.

Show
Charles Oliver Nutter added a comment - The fixes for JRUBY-6607 appear to have fixed this as well.

People

  • Assignee:
    Charles Oliver Nutter
    Reporter:
    Chris Ochs
Vote (0)
Watch (1)

Dates

  • Created:
    Updated:
    Resolved: