search

nahi / httpclient

'httpclient' gives something like the functionality of libwww-perl (LWP) in Ruby.
https://github.com/nahi/httpclient
703 stars 290 forks source link

Connection closed by remote host #368

Open dmnelson opened 7 years ago

dmnelson commented 7 years ago

Hi,

I'm currently using httpclient on an application with version 2.6.0.1 and that has been working well for a long time. Recently, I have been trying to upgrade to 2.8.3 but I'm facing an issue. I'm getting intermittent Java::JavaNet::SocketException: Connection closed by remote host (I'm using JRuby).

I've found a way to (almost) consistently replicate it:

> client = HTTPClient.new
> 5.times { puts client.get("https://url_to_another_app").status; sleep 7 }

It's the interval between calls that's causing the issue error to happen. In other words, I can make 100 calls in sequence if there is no delay between them, but if I wait few seconds the next call fails.

I've tried that against some other websites (Google, Twitter, etc. ) and the error didn't happen, so it's something more specific to our app that I haven't figured out yet. But in another hand, it works completely fine on 2.6.0.1 against our app. So it's also related to some change that has happened on this gem since then.

The stacktrace:

Java::JavaNet::SocketException: Connection closed by remote host
    from sun.security.ssl.SSLSocketImpl.checkWrite(sun/security/ssl/SSLSocketImpl.java:1523)
    from sun.security.ssl.AppOutputStream.write(sun/security/ssl/AppOutputStream.java:71)
    from java.io.OutputStream.write(java/io/OutputStream.java:75)
    from java.lang.reflect.Method.invoke(java/lang/reflect/Method.java:483)
    from org.jruby.javasupport.JavaMethod.invokeDirectWithExceptionHandling(org/jruby/javasupport/JavaMethod.java:453)
    from org.jruby.javasupport.JavaMethod.invokeDirect(org/jruby/javasupport/JavaMethod.java:314)
    from RUBY.<<(/Users/david/.rvm/gems/jruby-9.1.10.0/gems/httpclient-2.8.3/lib/httpclient/jruby_ssl_socket.rb:99)
    from RUBY.dump(/Users/david/.rvm/gems/jruby-9.1.10.0/gems/httpclient-2.8.3/lib/httpclient/http.rb:510)
    from RUBY.dump(/Users/david/.rvm/gems/jruby-9.1.10.0/gems/httpclient-2.8.3/lib/httpclient/http.rb:962)
    from RUBY.block in query(/Users/david/.rvm/gems/jruby-9.1.10.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:517)
    from org.jruby.ext.timeout.Timeout.yieldWithTimeout(org/jruby/ext/timeout/Timeout.java:177)
    from org.jruby.ext.timeout.Timeout.timeout(org/jruby/ext/timeout/Timeout.java:149)
    from org.jruby.ext.timeout.Timeout$INVOKER$s$timeout.call(org/jruby/ext/timeout/Timeout$INVOKER$s$timeout.gen)
    from RUBY.query(/Users/david/.rvm/gems/jruby-9.1.10.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:515)
    from RUBY.query(/Users/david/.rvm/gems/jruby-9.1.10.0/gems/httpclient-2.8.3/lib/httpclient/session.rb:177)
    from RUBY.do_get_block(/Users/david/.rvm/gems/jruby-9.1.10.0/gems/httpclient-2.8.3/lib/httpclient.rb:1242)
... 40 levels...
    from org.jruby.RubyKernel$INVOKER$s$0$1$load19.call(org/jruby/RubyKernel$INVOKER$s$0$1$load19.gen)
    from RUBY.<eval>(/Users/david/.rvm/gems/jruby-9.1.10.0/bin/bundle:1)
    from org.jruby.RubyKernel.evalCommon(org/jruby/RubyKernel.java:1033)
    from org.jruby.RubyKernel.eval(org/jruby/RubyKernel.java:1000)
    from org.jruby.RubyKernel$INVOKER$s$0$3$eval19.call(org/jruby/RubyKernel$INVOKER$s$0$3$eval19.gen)
    from Users.david.$_dot_rvm.gems.jruby_minus_9_dot_1_dot_10_dot_0.bin.jruby_executable_hooks.invokeOther17:eval(Users/david/$_dot_rvm/gems/jruby_minus_9_dot_1_dot_10_dot_0/bin//Users/david/.rvm/gems/jruby-9.1.10.0/bin/jruby_executable_hooks:15)
    from Users.david.$_dot_rvm.gems.jruby_minus_9_dot_1_dot_10_dot_0.bin.jruby_executable_hooks.<main>(/Users/david/.rvm/gems/jruby-9.1.10.0/bin/jruby_executable_hooks:15)
    from java.lang.invoke.MethodHandle.invokeWithArguments(java/lang/invoke/MethodHandle.java:636)
    from org.jruby.Ruby.runScript(org/jruby/Ruby.java:827)
    from org.jruby.Ruby.runNormally(org/jruby/Ruby.java:746)
    from org.jruby.Ruby.runNormally(org/jruby/Ruby.java:764)
    from org.jruby.Ruby.runFromMain(org/jruby/Ruby.java:577)
    from org.jruby.Main.doRunFromMain(org/jruby/Main.java:417)
    from org.jruby.Main.internalRun(org/jruby/Main.java:305)
    from org.jruby.Main.run(org/jruby/Main.java:232)
    from org.jruby.Main.main(org/jruby/Main.java:204)

Any words of wisdom on this one?

mejackreed commented 6 years ago

Seeing the same errors as you. Seems to be related to the SSL Socket jruby implementation.

jrochkind commented 6 years ago

Could this be an issue where HTTPClient was trying to keep open a persistent connection, but the server closed the connection?

This is NOT the usual failure mode when that happens, I don't think. There may be a bug specifically in JRuby SSL paths related to this.

Ordinarily, if this happened, the NEXT request you made would be good again. @dmnelson, after the exception if you make a request again, does it fail with the same exception?

I wonder if something in JRuby SSL path is keeping HTTPClient from realizing it's got to throw out the connection and create a new one, cause server has closed the persistent HTTP connection.

This is all kind of a wild guess. This is pretty hard to figure out how to debug.

jrochkind commented 6 years ago

Following up this idea, still just kinda random guessing here without running code....

I notice MRI SSLSocket#close does a @ssl_socket.close and a @socket.close. https://github.com/nahi/httpclient/blob/59c9590a576286c130a63d62bd55c2e1afe98faf/lib/httpclient/ssl_socket.rb#L48-L51

But JRuby SSLSocket#close just does a @socket.close. Could it be missing the @ssl_socket.close? There is a separate @ssl_socket ivar in the JRuby version too and the implementations seem otherwise pretty parallel in these parts.... https://github.com/nahi/httpclient/blob/master/lib/httpclient/jruby_ssl_socket.rb#L44-L46

brianvans commented 6 years ago

I consistently hit this issue if the client's keep_alive_timeout exceeds that of the server (for instance, keepalive_timeout 5s; under nginx, which is shorter than httpclient's default of 15s). In the below example, it is particularly strange that the second response fails to raise an exception, but rather passes back empty values for parts of the response object.

I haven't been able to debug much further, but I hope this helps narrow the issue down a bit.

irb(main):001:0> puts JRUBY_VERSION
9.2.0.0
=>
irb(main):002:0> puts HTTPClient::VERSION
2.8.3
=>
irb(main):003:0> client = HTTPClient.new
=> #<HTTPClient:0x1046d517>
irb(main):004:0> client.keep_alive_timeout = 120
=> 120
irb(main):005:0> 5.times do |i|
irb(main):006:1*   puts "REQUEST: #{i}"
irb(main):007:1>   resp = client.get('https://api.github.com/status')
irb(main):008:1>   puts "STATUS: #{resp.status}"
irb(main):009:1>   puts "BODY: #{resp.body}"
irb(main):010:1>   sleep 62
irb(main):011:1> end
REQUEST: 0
STATUS: 200
BODY: {"message":"GitHub lives! (2018-10-30 20:13:18 -0700) (1)"}
REQUEST: 1
STATUS: 
BODY: 
REQUEST: 2
Traceback (most recent call last):
       16: from RUBY.query(/home/user/.rbenv/versions/jruby-9.2.0.0/lib/ruby/gems/shared/gems/httpclient-2.8.3/lib/httpclient/session.rb:177)
       15: from RUBY.query(/home/user/.rbenv/versions/jruby-9.2.0.0/lib/ruby/gems/shared/gems/httpclient-2.8.3/lib/httpclient/session.rb:515)
       14: from org.jruby.ext.timeout.Timeout$INVOKER$s$timeout.call(org/jruby/ext/timeout/Timeout$INVOKER$s$timeout.gen)
       13: from org.jruby.ext.timeout.Timeout.timeout(org/jruby/ext/timeout/Timeout.java:122)
       12: from org.jruby.ext.timeout.Timeout.timeout(org/jruby/ext/timeout/Timeout.java:149)
       11: from org.jruby.ext.timeout.Timeout.yieldWithTimeout(org/jruby/ext/timeout/Timeout.java:177)
       10: from RUBY.block in query(/home/user/.rbenv/versions/jruby-9.2.0.0/lib/ruby/gems/shared/gems/httpclient-2.8.3/lib/httpclient/session.rb:517)
        9: from RUBY.dump(/home/user/.rbenv/versions/jruby-9.2.0.0/lib/ruby/gems/shared/gems/httpclient-2.8.3/lib/httpclient/http.rb:962)
        8: from RUBY.dump(/home/user/.rbenv/versions/jruby-9.2.0.0/lib/ruby/gems/shared/gems/httpclient-2.8.3/lib/httpclient/http.rb:510)
        7: from RUBY.<<(/home/user/.rbenv/versions/jruby-9.2.0.0/lib/ruby/gems/shared/gems/httpclient-2.8.3/lib/httpclient/jruby_ssl_socket.rb:99)
        6: from org.jruby.javasupport.JavaMethod.invokeDirect(org/jruby/javasupport/JavaMethod.java:316)
        5: from org.jruby.javasupport.JavaMethod.invokeDirectWithExceptionHandling(org/jruby/javasupport/JavaMethod.java:455)
        4: from java.lang.reflect.Method.invoke(java/lang/reflect/Method.java:498)
        3: from java.io.OutputStream.write(java/io/OutputStream.java:75)
        2: from sun.security.ssl.AppOutputStream.write(sun/security/ssl/AppOutputStream.java:71)
        1: from sun.security.ssl.SSLSocketImpl.checkWrite(sun/security/ssl/SSLSocketImpl.java:1547)
Java::JavaNet::SocketException (Connection closed by remote host)