-
1. Re: SSLHandshakeException at consumer endpoint
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
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
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
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
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
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.