JRuby (please use github issues at http://bugs.jruby.org)
  1. JRuby (please use github issues at http://bugs.jruby.org)
  2. JRUBY-6346

Error establishing SSL connections: OpenSSL::SSL::SSLError: Socket closed

    Details

    • Type: Bug Bug
    • Status: Resolved Resolved
    • Priority: Critical Critical
    • Resolution: Not A Bug
    • Affects Version/s: JRuby 1.6.5
    • Fix Version/s: JRuby 1.7.1
    • Component/s: OpenSSL
    • Labels:
      None
    • Environment:
      Mac OSX Lion, jruby 1.6.5.1, jruby-openssl 0.7.5.dev
    • Number of attachments :
      1

      Description

      I have been intermittently seeing "SSLError: Socket closed" upon `connect`, trying to establish an SSL socket connection. Hard to tell whether it was just my connection or not. Then I noticed that it happens without fail upon `accept` when running WEBrick in https mode--except from Safari. I mean, Webrick starts up okay, but when I navigate to https://localhost:3000 in my browser (though, strangely, Safari works fine), it fails with the following backtrace:

      #<OpenSSL::SSL::SSLError: Socket closed>
      org/jruby/ext/openssl/SSLSocket.java:227:in `accept'
      /Users/mhauck/.rvm/gems/jruby-1.6.5.1/gems/jruby-openssl-0.7.5.1.dev.ibm/lib/1.9/openssl/ssl-internal.rb:164:in `accept'
      /Users/mhauck/.rvm/rubies/jruby-1.6.5.1/lib/ruby/1.9/webrick/server.rb:159:in `accept_client'
      /Users/mhauck/.rvm/rubies/jruby-1.6.5.1/lib/ruby/1.9/webrick/server.rb:94:in `start'
      org/jruby/RubyArray.java:1612:in `each'
      /Users/mhauck/.rvm/rubies/jruby-1.6.5.1/lib/ruby/1.9/webrick/server.rb:91:in `start'
      /Users/mhauck/.rvm/rubies/jruby-1.6.5.1/lib/ruby/1.9/webrick/server.rb:22:in `start'
      /Users/mhauck/.rvm/rubies/jruby-1.6.5.1/lib/ruby/1.9/webrick/server.rb:81:in `start'
      /Users/mhauck/.rvm/gems/jruby-1.6.5.1/gems/rack-1.2.4/lib/rack/handler/webrick.rb:13:in `run'
      /Users/mhauck/.rvm/gems/jruby-1.6.5.1/gems/rack-1.2.4/lib/rack/server.rb:217:in `start'
      /Users/mhauck/.rvm/gems/jruby-1.6.5.1/gems/railties-3.0.10/lib/rails/commands/server.rb:65:in `start'
      /Users/mhauck/.rvm/gems/jruby-1.6.5.1/gems/railties-3.0.10/lib/rails/commands.rb:30:in `(root)'
      org/jruby/RubyKernel.java:1804:in `tap'
      /Users/mhauck/.rvm/gems/jruby-1.6.5.1/gems/railties-3.0.10/lib/rails/commands.rb:27:in `(root)'
      org/jruby/RubyKernel.java:1047:in `require'
      script/rails:59:in `(root)'

      The failure in `connect` comes from the following code (from jtv-apns gem):

      context = OpenSSL::SSL::SSLContext.new
      context.cert = cert
      context.key = pem
      sock = TCPSocket.new(host, port)
      ssl = OpenSSL::SSL::SSLSocket.new(sock, context)
      ssl.connect

      PS. I configured webrick to use SSL as detailed here: http://www.nearinfinity.com/blogs/chris_rohr/configuring_webrick_to_use_ssl.html

        Activity

        Hide
        Matt Hauck added a comment -

        Forgot to say I am in 1.9 mode.

        Show
        Matt Hauck added a comment - Forgot to say I am in 1.9 mode.
        Hide
        Matt Hauck added a comment - - edited

        It appears that in both places, the problem is happening in doHandshake() – it is expecting there to be more data from the client / server (readAndUnwrap()) but there is none.

        if(readAndUnwrap() == -1 && hsStatus != SSLEngineResult.HandshakeStatus.FINISHED) {
          throw new SSLHandshakeException("Socket closed");
        }

        Show
        Matt Hauck added a comment - - edited It appears that in both places, the problem is happening in doHandshake() – it is expecting there to be more data from the client / server ( readAndUnwrap() ) but there is none. if(readAndUnwrap() == -1 && hsStatus != SSLEngineResult.HandshakeStatus.FINISHED) {   throw new SSLHandshakeException("Socket closed"); }
        Hide
        Matt Hauck added a comment - - edited

        Okay, got jdb up and working. It is exiting here from lines 464-466 in readAndUnwrap():

        if(status == SSLEngineResult.Status.CLOSED) {
          doShutdown();
          return -1;
        }

        hsStatus = "NEED_WRAP"
        peerNetData.hasRemaining() = false
        peerAppData.hasRemaining() = true

        Reading peerAppData gives me a 96-long "0000<...>" string. Is there anything I can inspect here that might be of interest?

        Show
        Matt Hauck added a comment - - edited Okay, got jdb up and working. It is exiting here from lines 464-466 in readAndUnwrap(): if(status == SSLEngineResult.Status.CLOSED) {   doShutdown();   return -1; } hsStatus = "NEED_WRAP" peerNetData.hasRemaining() = false peerAppData.hasRemaining() = true Reading peerAppData gives me a 96-long "0000<...>" string. Is there anything I can inspect here that might be of interest?
        Hide
        Matt Hauck added a comment -

        I hooked up log4j, and interestingly got some other log messages that weren't coming through in the standard Rails logger:

        2012-01-20 13:54:06.407::WARN: EXCEPTION
        javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:849)
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1170)
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1197)
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1181)
        at org.mortbay.jetty.security.SslSocketConnector$SslConnection.run(SslSocketConnector.java:632)
        at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582)
        Caused by: java.io.EOFException: SSL peer shut down incorrectly
        at com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:333)
        at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:830)
        ... 5 more

        Show
        Matt Hauck added a comment - I hooked up log4j, and interestingly got some other log messages that weren't coming through in the standard Rails logger: 2012-01-20 13:54:06.407::WARN: EXCEPTION javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:849) at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1170) at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1197) at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1181) at org.mortbay.jetty.security.SslSocketConnector$SslConnection.run(SslSocketConnector.java:632) at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582) Caused by: java.io.EOFException: SSL peer shut down incorrectly at com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:333) at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:830) ... 5 more
        Hide
        Matt Hauck added a comment -

        Some more interesting data:

        (rdb:1) sock.closed?
        false
        (rdb:1) ssl.closed?
        false
        (rdb:1) ssl.connect
        OpenSSL::SSL::SSLError Exception: Socket closed
        (rdb:1) ssl.closed?
        false
        (rdb:1) sock.closed?
        false

        where `sock` is a TCPSocket object passed off to SSLSocket and `ssl` is an SSLSocket object.

        Show
        Matt Hauck added a comment - Some more interesting data: (rdb:1) sock.closed? false (rdb:1) ssl.closed? false (rdb:1) ssl.connect OpenSSL::SSL::SSLError Exception: Socket closed (rdb:1) ssl.closed? false (rdb:1) sock.closed? false where `sock` is a TCPSocket object passed off to SSLSocket and `ssl` is an SSLSocket object.
        Hide
        Pedro Teixeira added a comment -

        Can reproduce the problem running 'rake cert:request' in the puppet-dashboard project:
        https://github.com/puppetlabs/puppet-dashboard/blob/master/lib/tasks/install.rake

        Works fine under MRI.

        Show
        Pedro Teixeira added a comment - Can reproduce the problem running 'rake cert:request' in the puppet-dashboard project: https://github.com/puppetlabs/puppet-dashboard/blob/master/lib/tasks/install.rake Works fine under MRI.
        Hide
        Pedro Teixeira added a comment -

        Not much info in the stack trace, but here it goes:

        Socket closed
        org/jruby/ext/openssl/SSLSocket.java:179:in `connect'
        /home/pedro/.rvm/rubies/jruby-1.6.5/lib/ruby/1.8/net/http.rb:586:in `connect'
        /home/pedro/.rvm/rubies/jruby-1.6.5/lib/ruby/1.8/net/http.rb:553:in `do_start'
        /home/pedro/.rvm/rubies/jruby-1.6.5/lib/ruby/1.8/net/http.rb:542:in `start'

        Show
        Pedro Teixeira added a comment - Not much info in the stack trace, but here it goes: Socket closed org/jruby/ext/openssl/SSLSocket.java:179:in `connect' /home/pedro/.rvm/rubies/jruby-1.6.5/lib/ruby/1.8/net/http.rb:586:in `connect' /home/pedro/.rvm/rubies/jruby-1.6.5/lib/ruby/1.8/net/http.rb:553:in `do_start' /home/pedro/.rvm/rubies/jruby-1.6.5/lib/ruby/1.8/net/http.rb:542:in `start'
        Hide
        Pedro Teixeira added a comment -

        Error occurs in jruby 1.6.5 and 1.6.6 with gem jruby-openssl 0.7.5. Environment: Linux (Linux Mint), x64.

        Show
        Pedro Teixeira added a comment - Error occurs in jruby 1.6.5 and 1.6.6 with gem jruby-openssl 0.7.5. Environment: Linux (Linux Mint), x64.
        Hide
        Pedro Teixeira added a comment -

        What's weirder: it doesn't work on the first attempt, but a second attempt to connect in the same process, works find.

        Show
        Pedro Teixeira added a comment - What's weirder: it doesn't work on the first attempt, but a second attempt to connect in the same process, works find.
        Hide
        Ben Porterfield added a comment -

        I also see this consistently. Server still seems to respond fine, so I've silenced it for now, but would love to have it fixed. Occurs for me in jruby 1.6.5 on OS X.

        Show
        Ben Porterfield added a comment - I also see this consistently. Server still seems to respond fine, so I've silenced it for now, but would love to have it fixed. Occurs for me in jruby 1.6.5 on OS X.
        Hide
        Ben Porterfield added a comment -

        I take that back - using SSL does appear to make the server break in a strange way. Some page load properly, others appear to be missing data mid-string, as if a packet was lost. The same server works with TCPServer fine, breaks when wrapping it in SSLServer.

        Show
        Ben Porterfield added a comment - I take that back - using SSL does appear to make the server break in a strange way. Some page load properly, others appear to be missing data mid-string, as if a packet was lost. The same server works with TCPServer fine, breaks when wrapping it in SSLServer.
        Hide
        Ben Porterfield added a comment - - edited

        It turns out that the issues I was seeing appear related to JRUBY-6515. I still see this error consistently, but does not appear to break ability to respond.

        Show
        Ben Porterfield added a comment - - edited It turns out that the issues I was seeing appear related to JRUBY-6515 . I still see this error consistently, but does not appear to break ability to respond.
        Hide
        Hiroshi Nakamura added a comment -

        I confirmed the same error on my end.

        • both 1.8 mode and 1.9 mode raise the error.
          javax.net.ssl.SSLHandshakeException: Socket closed
          	at org.jruby.ext.openssl.SSLSocket.doHandshake(SSLSocket.java:339)
          	at org.jruby.ext.openssl.SSLSocket.accept(SSLSocket.java:225)
          	at org.jruby.ext.openssl.SSLSocket$i$0$0$accept.call(SSLSocket$i$0$0$accept.gen:65535)
          	at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:292)
          
        • Above error happens three times for a connection, and it hangs (100% CPU usage)
        • Firefox and OpenSSL clients (Ruby, curl and wget) works fine. It happens for Google Chrome.

        It's like time to learn Google's False Start and Snap Start.

        Show
        Hiroshi Nakamura added a comment - I confirmed the same error on my end. both 1.8 mode and 1.9 mode raise the error. javax.net.ssl.SSLHandshakeException: Socket closed at org.jruby.ext.openssl.SSLSocket.doHandshake(SSLSocket.java:339) at org.jruby.ext.openssl.SSLSocket.accept(SSLSocket.java:225) at org.jruby.ext.openssl.SSLSocket$i$0$0$accept.call(SSLSocket$i$0$0$accept.gen:65535) at org.jruby.runtime.callsite.CachingCallSite.cacheAndCall(CachingCallSite.java:292) Above error happens three times for a connection, and it hangs (100% CPU usage) Firefox and OpenSSL clients (Ruby, curl and wget) works fine. It happens for Google Chrome. It's like time to learn Google's False Start and Snap Start.
        Hide
        Matt Hauck added a comment -

        If this is still unresolved, why is it marked as fixed for jruby-1.7rc1?

        Show
        Matt Hauck added a comment - If this is still unresolved, why is it marked as fixed for jruby-1.7rc1?
        Hide
        Charles Oliver Nutter added a comment -

        Is there a trivial reproduction here somewhere? I'd like to fix this.

        Show
        Charles Oliver Nutter added a comment - Is there a trivial reproduction here somewhere? I'd like to fix this.
        Hide
        Matt Hauck added a comment -

        Here is a simple ssl server that might to do the trick. I'm not sure if this is the exact same error or not...but whenever I try to connect in chrome, it gives me this:

        IOError: Broken pipe
        syswrite at org/jruby/ext/openssl/SSLSocket.java:621
        do_write at /Users/matt/.rvm/rubies/jruby-1.7.0/lib/ruby/1.9/openssl/buffering.rb:317
        puts at /Users/matt/.rvm/rubies/jruby-1.7.0/lib/ruby/1.9/openssl/buffering.rb:402
        (root) at sslserver.rb:20
        loop at org/jruby/RubyKernel.java:1390
        (root) at sslserver.rb:16

        Show
        Matt Hauck added a comment - Here is a simple ssl server that might to do the trick. I'm not sure if this is the exact same error or not...but whenever I try to connect in chrome, it gives me this: IOError: Broken pipe syswrite at org/jruby/ext/openssl/SSLSocket.java:621 do_write at /Users/matt/.rvm/rubies/jruby-1.7.0/lib/ruby/1.9/openssl/buffering.rb:317 puts at /Users/matt/.rvm/rubies/jruby-1.7.0/lib/ruby/1.9/openssl/buffering.rb:402 (root) at sslserver.rb:20 loop at org/jruby/RubyKernel.java:1390 (root) at sslserver.rb:16
        Hide
        Charles Oliver Nutter added a comment -

        Reproduced here with Matt's server script using a cert + key from our openssl tests. Investigating.

        Show
        Charles Oliver Nutter added a comment - Reproduced here with Matt's server script using a cert + key from our openssl tests. Investigating.
        Hide
        Charles Oliver Nutter added a comment -

        Oddly enough it also fails with 1.9.3 when I hit the server with a browser:

        system ~/projects/jruby $ ruby-1.9.3 ssl-server.rb 
        
        Waiting...
        
        Waiting...
        
        Waiting...
        
        Waiting...
        /usr/local/lib/ruby/1.9.1/openssl/buffering.rb:318:in `syswrite': Broken pipe (Errno::EPIPE)
        	from /usr/local/lib/ruby/1.9.1/openssl/buffering.rb:318:in `do_write'
        	from /usr/local/lib/ruby/1.9.1/openssl/buffering.rb:403:in `puts'
        	from ssl-server.rb:20:in `block in <main>'
        	from ssl-server.rb:16:in `loop'
        	from ssl-server.rb:16:in `<main>'
        

        In the MRI case, the two strings do get sent to the browser, but that could just be buffering/flushing behavior difference. JRuby does fail during the second write.

        Show
        Charles Oliver Nutter added a comment - Oddly enough it also fails with 1.9.3 when I hit the server with a browser: system ~/projects/jruby $ ruby-1.9.3 ssl-server.rb Waiting... Waiting... Waiting... Waiting... /usr/local/lib/ruby/1.9.1/openssl/buffering.rb:318:in `syswrite': Broken pipe (Errno::EPIPE) from /usr/local/lib/ruby/1.9.1/openssl/buffering.rb:318:in `do_write' from /usr/local/lib/ruby/1.9.1/openssl/buffering.rb:403:in `puts' from ssl-server.rb:20:in `block in <main>' from ssl-server.rb:16:in `loop' from ssl-server.rb:16:in `<main>' In the MRI case, the two strings do get sent to the browser, but that could just be buffering/flushing behavior difference. JRuby does fail during the second write.
        Hide
        Charles Oliver Nutter added a comment -

        Ok, even more confusing...one time I got the above output from JRuby too, indicating that it was able to send all the data but closed earlier than expected?

        Show
        Charles Oliver Nutter added a comment - Ok, even more confusing...one time I got the above output from JRuby too, indicating that it was able to send all the data but closed earlier than expected?
        Hide
        Charles Oliver Nutter added a comment -

        Ok, I think this is actually a browser interaction issue and not a bug in SSL.

        Because I was sometimes getting successful responses using MRI, I started to question whether the server was the problem. So, on a hunch, I added a one-second sleep to the server after accepting the incoming socket. With that sleep, MRI fails every time.

        I think what we're seeing here is an interaction between the SSL server wanting to immediately write content and the browser sending its HTTP request. If the request starts before the server's write begins (and perhaps also during) the browser appears to shut down the connection. This causes the "broken pipe" error, since the client side has gone away and the server is still up.

        It works sometimes because some browsers will sometimes show what the server wrote, even if it's not a proper HTTP response. It seems to be all about timing.

        JRuby fails it more frequently than MRI probably because at startup we're a bit slower to get to the writing.

        I would recommend attempting to reproduce this with an SSL client that is not a browser. If you can do that, and there's still a problem, please reopen.

        Show
        Charles Oliver Nutter added a comment - Ok, I think this is actually a browser interaction issue and not a bug in SSL. Because I was sometimes getting successful responses using MRI, I started to question whether the server was the problem. So, on a hunch, I added a one-second sleep to the server after accepting the incoming socket. With that sleep, MRI fails every time. I think what we're seeing here is an interaction between the SSL server wanting to immediately write content and the browser sending its HTTP request. If the request starts before the server's write begins (and perhaps also during) the browser appears to shut down the connection. This causes the "broken pipe" error, since the client side has gone away and the server is still up. It works sometimes because some browsers will sometimes show what the server wrote, even if it's not a proper HTTP response. It seems to be all about timing. JRuby fails it more frequently than MRI probably because at startup we're a bit slower to get to the writing. I would recommend attempting to reproduce this with an SSL client that is not a browser. If you can do that, and there's still a problem, please reopen.

          People

          • Assignee:
            Charles Oliver Nutter
            Reporter:
            Matt Hauck
          • Votes:
            3 Vote for this issue
            Watchers:
            6 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: