5 Replies Latest reply on Mar 25, 2011 11:48 AM by Dan Valiga

    SSLHandshakeException at consumer endpoint

    Gaurav Nigam Newbie

      Hi,

      I have a consumer endpoint and I am getting an SSLHandshakeException every 5 seconds. Stacktrace is given below:

       

      javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake

      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(Unknown Source)

      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(Unknown Source)

      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(Unknown Source)

      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(Unknown Source)

      at org.mortbay.jetty.security.SslSocketConnector$SslConnection.run(SslSocketConnector.java:631)

      at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:522)

      Caused by: java.io.EOFException: SSL peer shut down incorrectly

      at com.sun.net.ssl.internal.ssl.InputRecord.read(Unknown Source)

      ... 6 more

       

      Can anyone please tell me what could be the reason for this exception to occur and why is it occurring every 5 seconds?

        • 1. Re: SSLHandshakeException at consumer endpoint
          Dave Stanley Novice

          Can you enable debug logging on the ssl handshake by adding the line below to your consumer's command line.

           

          -Djavax.net.debug=ssl,handshake

           

          This should tell you why the handshake is failing..

           

          /Dave

          • 2. Re: SSLHandshakeException at consumer endpoint
            Paul Olson Newbie

            Thanks Dave,

             

            I added -Djavax.new.debug=all into the servicemix startup shell script (3.4.0.2) but the output didn't show me much. I can see it reading the keystore ect., and the the following:

             

            -


            ...

            trigger seeding of SecureRandom

            done seeding SecureRandom

            DEBUG - JettyContextManager            - Dispatching job: org.mortbay.jetty.AbstractConnector$Acceptor@f53d61

            INFO  - jetty                          - Started SslSocketConnector@vzsjcsebp02.totality.com:8192

            matching alias: gateway.totality.com

            DEBUG - HttpComponent                  - Service unit initialized

            INFO  - ServiceUnitLifeCycle           - Initializing service unit: gif-gc-su

            DEBUG - CamelJbiComponent              - Initializing service unit

            DEBUG - CamelJbiComponent              - Looking for /opt/progress/fuse-esb/fuse-esb-3.4.0.2/data/smx/service-assemblies/http-to-gc-sa/version_1/sus/servicemix-camel/gif-gc-su/camel-context.xml: true

            12915102@qtp1-1 - Acceptor0 SslSocketConnector@vzsjcsebp02.totality.com:8192, setSoTimeout(65000) called

            DEBUG - JettyContextManager            - Dispatching job: org.mortbay.jetty.security.SslSocketConnector$SslConnection@1e0312b

            5060581@qtp1-0, received EOFException: error

            5060581@qtp1-0, handling exception: javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake

            5060581@qtp1-0, SEND TLSv1 ALERT:  fatal, description = handshake_failure

            5060581@qtp1-0, WRITE: TLSv1 Alert, length = 2

            : length = 7

            0000: 15 03 01 00 02 02 28                               ......(

            5060581@qtp1-0, called closeSocket()

            WARN  - jetty                          - EXCEPTION

            ...

            -


             

            The exception happens when servicemix is initalizing the service unit, so I know it's not an external client trying to connect to us.

             

            We have the "servicemix-http" with SSL successfully deployed on other servers. This particular server however sits behind a hardware load balancer. I have a feeling that the problem is related to the fact that the component can't bind to the IP of the external URL because that resolves to the front end of the load balancer. So we had to change the "locationURI" in the xbean to be the name of the actual server this is running on. But everything I've tried doesn't help.

             

            btw- the consumer endpoint actually works. It's an anoyance in the log files and it chews up unnecessary resources.

             

            paul

            • 3. Re: SSLHandshakeException at consumer endpoint
              Dan Valiga Newbie

              Was there any resolution on this?  I have EXACTLY the same situation running Fuse ESB 4.3.1. 

               

              It is setup the same way Paul described, with a server that is behind a load balancer.  The Fuse ESB server has a valid certificate for the public name that the load balancer resolves to (with the keystore and credentials for the cert defined in /etc/org.ops4j.pax.web.cfg).  Only connections via HTTPS are served (port 9443 with the load balancer forwarding from public-facing 443).

               

              The SSLHandshakeException happens every 4 to 5 seconds with a Jetty stack trace logged each time in servicemix.log.  This fills up all 10 rolling logs very quickly.  It starts the moment Fuse/ServiceMix is started and continues until stopped, even on servers that have no users hitting them.  I've tried removing all bundles I've installed to make sure it isn't some interaction I introduced, and there was no change; the errors continued. 

               

              What is making a call every 4 seconds and why is it failing?  Like mentioned by the others, this doesn't seem to affect the function of the server or any services exposed in CXF, but is very annoying the way the logs fill up. 

               

              Thanks,

               

              -Dan

               

              Example from servicemix.log:

               

              ...

              13:03:49,127 | DEBUG | heckpoint Worker | MessageDatabase                  | ?                                   ? | 43 - org.apache.activemq.activemq-core - 5.4.2.fuse-01-00 | Checkpoint started.

              13:03:49,136 | DEBUG | heckpoint Worker | MessageDatabase                  | ?                                   ? | 43 - org.apache.activemq.activemq-core - 5.4.2.fuse-01-00 | Checkpoint done.

              13:03:51,652 | WARN  | qtp-1690590946-2 | jetty                            | ?                                   ? | 104 - org.ops4j.pax.web.pax-web-jetty - 0.7.4 | EXCEPTION

              javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake

                      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:817)[:1.6]

                      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1138)[:1.6]

                      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1165)[:1.6]

                      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1149)[:1.6]

                      at org.mortbay.jetty.security.SslSocketConnector$SslConnection.run(SslSocketConnector.java:708)[100:org.apache.servicemix.bundles.jetty:6.1.26.1-fuse]

                      at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582)[100:org.apache.servicemix.bundles.jetty:6.1.26.1-fuse]

              Caused by: java.io.EOFException: SSL peer shut down incorrectly

                      at com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:333)[:1.6]

                      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:798)[:1.6]

                      ... 5 more

              13:03:52,718 | WARN  | qtp-1690590946-2 | jetty                            | ?                                   ? | 104 - org.ops4j.pax.web.pax-web-jetty - 0.7.4 | EXCEPTION

              javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake

                      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:817)[:1.6]

                      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1138)[:1.6]

                      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1165)[:1.6]

                      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1149)[:1.6]

                      at org.mortbay.jetty.security.SslSocketConnector$SslConnection.run(SslSocketConnector.java:708)[100:org.apache.servicemix.bundles.jetty:6.1.26.1-fuse]

                      at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582)[100:org.apache.servicemix.bundles.jetty:6.1.26.1-fuse]

              Caused by: java.io.EOFException: SSL peer shut down incorrectly

                      at com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:333)[:1.6]

                      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:798)[:1.6]

                      ... 5 more

              13:03:52,773 | DEBUG | nitor WriteCheck | InactivityMonitor                | ?                                   ? | 43 - org.apache.activemq.activemq-core - 5.4.2.fuse-01-00 | 10001 ms elapsed since last write check.

              13:03:52,776 | DEBUG | onitor ReadCheck | InactivityMonitor                | ?                                   ? | 43 - org.apache.activemq.activemq-core - 5.4.2.fuse-01-00 | 29999 ms elapsed since last read check.

              13:03:52,779 | DEBUG | nitor WriteCheck | InactivityMonitor                | ?                                   ? | 43 - org.apache.activemq.activemq-core - 5.4.2.fuse-01-00 | 10001 ms elapsed since last write check.

              13:03:52,779 | DEBUG | onitor ReadCheck | InactivityMonitor                | ?                                   ? | 43 - org.apache.activemq.activemq-core - 5.4.2.fuse-01-00 | 30000 ms elapsed since last read check.

              13:03:54,158 | DEBUG | heckpoint Worker | MessageDatabase                  | ?                                   ? | 43 - org.apache.activemq.activemq-core - 5.4.2.fuse-01-00 | Checkpoint started.

              13:03:54,167 | DEBUG | heckpoint Worker | MessageDatabase                  | ?                                   ? | 43 - org.apache.activemq.activemq-core - 5.4.2.fuse-01-00 | Checkpoint done.

              13:03:56,131 | DEBUG | nitor WriteCheck | InactivityMonitor                | ?                                   ? | 43 - org.apache.activemq.activemq-core - 5.4.2.fuse-01-00 | 10000 ms elapsed since last write check.

              13:03:56,131 | DEBUG | nitor WriteCheck | InactivityMonitor                | ?                                   ? | 43 - org.apache.activemq.activemq-core - 5.4.2.fuse-01-00 | 10000 ms elapsed since last write check.

              13:03:56,132 | DEBUG | onitor ReadCheck | InactivityMonitor                | ?                                   ? | 43 - org.apache.activemq.activemq-core - 5.4.2.fuse-01-00 | 30002 ms elapsed since last read check.

              13:03:56,132 | DEBUG | onitor ReadCheck | InactivityMonitor                | ?                                   ? | 43 - org.apache.activemq.activemq-core - 5.4.2.fuse-01-00 | 30002 ms elapsed since last read check.

              13:03:56,262 | DEBUG | onitor ReadCheck | InactivityMonitor                | ?                                   ? | 43 - org.apache.activemq.activemq-core - 5.4.2.fuse-01-00 | 30001 ms elapsed since last read check.

              13:03:56,262 | DEBUG | onitor ReadCheck | InactivityMonitor                | ?                                   ? | 43 - org.apache.activemq.activemq-core - 5.4.2.fuse-01-00 | 30001 ms elapsed since last read check.

              13:03:56,262 | DEBUG | nitor WriteCheck | InactivityMonitor                | ?                                   ? | 43 - org.apache.activemq.activemq-core - 5.4.2.fuse-01-00 | 10001 ms elapsed since last write check.

              13:03:56,262 | DEBUG | nitor WriteCheck | InactivityMonitor                | ?                                   ? | 43 - org.apache.activemq.activemq-core - 5.4.2.fuse-01-00 | 10001 ms elapsed since last write check.

              13:03:56,698 | WARN  | qtp-1690590946-2 | jetty                            | ?                                   ? | 104 - org.ops4j.pax.web.pax-web-jetty - 0.7.4 | EXCEPTION

              javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake

                      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:817)[:1.6]

                      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1138)[:1.6]

                      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1165)[:1.6]

                      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1149)[:1.6]

                      at org.mortbay.jetty.security.SslSocketConnector$SslConnection.run(SslSocketConnector.java:708)[100:org.apache.servicemix.bundles.jetty:6.1.26.1-fuse]

                      at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582)[100:org.apache.servicemix.bundles.jetty:6.1.26.1-fuse]

              Caused by: java.io.EOFException: SSL peer shut down incorrectly

                      at com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:333)[:1.6]

                      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:798)[:1.6]

                      ... 5 more

              13:03:57,809 | WARN  | qtp-1690590946-2 | jetty                            | ?                                   ? | 104 - org.ops4j.pax.web.pax-web-jetty - 0.7.4 | EXCEPTION

              javax.net.ssl.SSLHandshakeException: Remote host closed connection during handshake

                      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:817)[:1.6]

                      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1138)[:1.6]

                      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1165)[:1.6]

                      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(SSLSocketImpl.java:1149)[:1.6]

                      at org.mortbay.jetty.security.SslSocketConnector$SslConnection.run(SslSocketConnector.java:708)[100:org.apache.servicemix.bundles.jetty:6.1.26.1-fuse]

                      at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:582)[100:org.apache.servicemix.bundles.jetty:6.1.26.1-fuse]

              Caused by: java.io.EOFException: SSL peer shut down incorrectly

                      at com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:333)[:1.6]

                      at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:798)[:1.6]

                      ... 5 more

              13:03:58,373 | DEBUG | NioProcessor-1   | ServerSession                    | ?                                   ? | 30 - sshd-core - 0.4.0 | Received packet SSH_MSG_CHANNEL_DATA

              13:03:58,373 | DEBUG | NioProcessor-1   | ChannelSession                   | ?                                   ? | 30 - sshd-core - 0.4.0 | Received SSH_MSG_CHANNEL_DATA on channel 0

              13:03:58,373 | DEBUG | Thread-32        | ChannelSession                   | ?                                   ? | 30 - sshd-core - 0.4.0 | Send SSH_MSG_CHANNEL_DATA on channel 0

              13:03:58,804 | DEBUG | NioProcessor-1   | ServerSession                    | ?                                   ? | 30 - sshd-core - 0.4.0 | Received packet SSH_MSG_CHANNEL_DATA

              ...

              • 4. Re: SSLHandshakeException at consumer endpoint
                Freeman(Yue) Fang Master

                Hi,

                It seems that FUSE ESB do receive message from secure port 9443

                Is it possible that caused by your load balancer heart-beat ping every 4 second?

                 

                You can put some tool like tcpmon between your load balancer and FUSE ESB to dump the onwire message to get more concrete idea.

                 

                Freeman

                • 5. Re: SSLHandshakeException at consumer endpoint
                  Dan Valiga Newbie

                  D'Oh!  Of course you're right - just talked with the network guys and there was an internal 'ping' setup to the Jetty secure port every 5 seconds.  Thanks.