Issue
My application in tomcat (version 9.0.26) is interacting with a third party HTTPS webservice. In the proces of SSL negotiation, the handshake fails and I am looking for help with the debug.
Tomcat startup parameters are:
INFO: Command line argument: -Djavax.net.ssl.trustStore=C:\tomcat32\9.0.26\conf\MyTrustStore.p12 Dec 08, 2019 8:56:08 AM org.apache.catalina.startup.VersionLoggerListener log INFO: Command line argument: -Djavax.net.ssl.trustStorePassword=MyPass Dec 08, 2019 8:56:08 AM org.apache.catalina.startup.VersionLoggerListener log INFO: Command line argument: -Djavax.net.ssl.trustStoreType=PKCS12 Dec 08, 2019 8:56:08 AM org.apache.catalina.startup.VersionLoggerListener log INFO: Command line argument: -Djavax.net.debug=ssl:handshake:verbose:keymanager:trustmanager Dec 08, 2019 8:56:08 AM org.apache.catalina.core.AprLifecycleListener lifecycleEvent INFO: Loaded APR based Apache Tomcat Native library [1.2.23] using APR version [1.7.0]. Dec 08, 2019 8:56:08 AM org.apache.catalina.core.AprLifecycleListener lifecycleEvent INFO: APR capabilities: IPv6 [true], sendfile [true], accept filters [false], random [true]. Dec 08, 2019 8:56:08 AM org.apache.catalina.core.AprLifecycleListener lifecycleEvent INFO: APR/OpenSSL configuration: useAprConnector [false], useOpenSSL [true] Dec 08, 2019 8:56:08 AM org.apache.catalina.core.AprLifecycleListener initializeSSL INFO: OpenSSL successfully initialized [OpenSSL 1.1.1c 28 May 2019] Dec 08, 2019 8:56:09 AM org.apache.coyote.AbstractProtocol init INFO: Initializing ProtocolHandler ["http-nio-8080"] Dec 08, 2019 8:56:10 AM org.apache.coyote.AbstractProtocol init INFO: Initializing ProtocolHandler ["ajp-nio-8009"] Dec 08, 2019 8:56:10 AM org.apache.catalina.startup.Catalina load INFO: Server initialization in [2,592] milliseconds Dec 08, 2019 8:56:10 AM org.apache.catalina.core.StandardService startInternal INFO: Starting service [Catalina]
On enabling SSL debug logs, I captured below on the logs
Allow unsafe renegotiation: false Allow legacy hello messages: true Is initial handshake: true Is secure renegotiation: false Ignoring unsupported cipher suite: TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384 for TLSv1 Ignoring unsupported cipher suite: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384 for TLSv1 Ignoring unsupported cipher suite: TLS_RSA_WITH_AES_256_CBC_SHA256 for TLSv1 Ignoring unsupported cipher suite: TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384 for TLSv1 Ignoring unsupported cipher suite: TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384 for TLSv1 Ignoring unsupported cipher suite: TLS_DHE_RSA_WITH_AES_256_CBC_SHA256 for TLSv1 Ignoring unsupported cipher suite: TLS_DHE_DSS_WITH_AES_256_CBC_SHA256 for TLSv1 Ignoring unsupported cipher suite: TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384 for TLSv1.1 Ignoring unsupported cipher suite: TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384 for TLSv1.1 Ignoring unsupported cipher suite: TLS_RSA_WITH_AES_256_CBC_SHA256 for TLSv1.1 Ignoring unsupported cipher suite: TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384 for TLSv1.1 Ignoring unsupported cipher suite: TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384 for TLSv1.1 Ignoring unsupported cipher suite: TLS_DHE_RSA_WITH_AES_256_CBC_SHA256 for TLSv1.1 Ignoring unsupported cipher suite: TLS_DHE_DSS_WITH_AES_256_CBC_SHA256 for TLSv1.1 %% No cached client session update handshake state: client_hello1 upcoming handshake states: server_hello[2] * ClientHello, TLSv1.2 RandomCookie: GMT: 1558998647 bytes = { 181, 223, 221, 91, 197, 4, 57, 190, 202, 50, 65, 37, 54, 151, 211, 23, 88, 35, 181, 111, 187, 68, 160, 166, 229, 25, 76, 123 } Session ID: {} Cipher Suites: [TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA384, TLS_RSA_WITH_AES_256_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA384, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA384, TLS_DHE_RSA_WITH_AES_256_CBC_SHA256, TLS_DHE_DSS_WITH_AES_256_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_256_CBC_SHA, TLS_ECDH_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_RSA_WITH_AES_256_CBC_SHA, TLS_DHE_DSS_WITH_AES_256_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA256, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_RSA_WITH_AES_128_CBC_SHA256, TLS_DHE_DSS_WITH_AES_128_CBC_SHA256, TLS_ECDHE_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_ECDH_ECDSA_WITH_AES_128_CBC_SHA, TLS_ECDH_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDH_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_RSA_WITH_AES_256_GCM_SHA384, TLS_DHE_DSS_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDH_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_RSA_WITH_AES_128_GCM_SHA256, TLS_DHE_DSS_WITH_AES_128_GCM_SHA256, TLS_EMPTY_RENEGOTIATION_INFO_SCSV] Compression Methods: { 0 } Extension elliptic_curves, curve names: {secp256r1, secp384r1, secp521r1, sect283k1, sect283r1, sect409k1, sect409r1, sect571k1, sect571r1, secp256k1} Extension ec_point_formats, formats: [uncompressed] Extension signature_algorithms, signature_algorithms: SHA512withECDSA, SHA512withRSA, SHA384withECDSA, SHA384withRSA, SHA256withECDSA, SHA256withRSA, SHA256withDSA, SHA1withECDSA, SHA1withRSA, SHA1withDSA Extension extended_master_secret Extension server_name, server_name: [type=host_name (0), value=certservicesgateway.Bingonline.com] http-nio-8080-exec-3, WRITE: TLSv1.2 Handshake, length = 236 http-nio-8080-exec-3, READ: TLSv1.2 Handshake, length = 89 check handshake state: server_hello[2] ServerHello, TLSv1.2 RandomCookie: GMT: 1119462208 bytes = { 96, 236, 134, 31, 185, 89, 247, 95, 189, 217, 105, 127, 42, 183, 115, 120, 142, 31, 103, 111, 54, 50, 166, 58, 130, 107, 63, 128 } Session ID: {15, 155, 163, 64, 244, 187, 119, 250, 40, 154, 103, 47, 201, 208, 211, 136, 114, 116, 248, 159, 173, 34, 212, 74, 194, 65, 71, 17, 39, 181, 196, 228} Cipher Suite: TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384 Compression Method: 0 Extension renegotiation_info, renegotiated_connection: Extension ec_point_formats, formats: [uncompressed, ansiX962_compressed_prime, ansiX962_compressed_char2] * %% Initialized: [Session-6, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384] ** TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
And towards the end of the handshake failure find the 'Invalidated' logger:
update handshake state: change_cipher_spec upcoming handshake states: client finished[20] upcoming handshake states: server change_cipher_spec[-1] upcoming handshake states: server finished[20] http-nio-8080-exec-3, WRITE: TLSv1.2 Change Cipher Spec, length = 1 * Finished verify_data: { 124, 94, 237, 141, 218, 48, 210, 88, 98, 142, 112, 197 } * update handshake state: finished[20] upcoming handshake states: server change_cipher_spec[-1] upcoming handshake states: server finished[20] http-nio-8080-exec-3, WRITE: TLSv1.2 Handshake, length = 40 http-nio-8080-exec-3, READ: TLSv1.2 Alert, length = 2 http-nio-8080-exec-3, RECV TLSv1.2 ALERT: fatal, handshake_failure %% Invalidated: [Session-6, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384] http-nio-8080-exec-3, called closeSocket() http-nio-8080-exec-3, handling exception: javax.net.ssl.SSLHandshakeException: Received fatal alert: handshake_failure 2019-12-07 23:00:43.732 INFO --- [nio-8080-exec-3] .v.w.t.MyServiceHandler : @@@@@@@@@ Other Exception happened in MyServiceHandler.execute():com.sun.xml.internal.ws.client.ClientTransportException: HTTP transport error: javax.net.ssl.SSLHandshakeException: Received fatal alert: handshake_failure, and the cause is:javax.net.ssl.SSLHandshakeException: Received fatal alert: handshake_failure com.sun.xml.internal.ws.client.ClientTransportException: HTTP transport error: javax.net.ssl.SSLHandshakeException: Received fatal alert: handshake_failure at com.sun.xml.internal.ws.transport.http.client.HttpClientTransport.getOutput(Unknown Source) at com.sun.xml.internal.ws.transport.http.client.HttpTransportPipe.process(Unknown Source) at com.sun.xml.internal.ws.transport.http.client.HttpTransportPipe.processRequest(Unknown Source) at com.sun.xml.internal.ws.transport.DeferredTransportPipe.processRequest(Unknown Source) at com.sun.xml.internal.ws.api.pipe.Fiber.__doRun(Unknown Source) at com.sun.xml.internal.ws.api.pipe.Fiber._doRun(Unknown Source) at com.sun.xml.internal.ws.api.pipe.Fiber.doRun(Unknown Source) at com.sun.xml.internal.ws.api.pipe.Fiber.runSync(Unknown Source)
From the loggers, I think the SSL protocol version used is TLS1.2 and that looks good. It looks like the Cipher is not matching - but unsure if I am overlooking something and how to remediate this.
On inspecting the logs further, found this one error:
Unparseable certificate extensions: 1 1: ObjectId: 2.5.29.31 Criticality=false Unparseable CRLDistributionPoints extension due to java.io.IOException: invalid URI name:ldap://Enroll.visaca.com:389/cn=Visa Information Delivery External CA,c=US,ou=Visa International Service Association,o=VISA?certificateRevocationList
Update - 09-Dec -- In consultation with our middleware support team who indicate that the above CRL exception could be a false alarm.
So with that assumption, looking closely at the log and comparing with the steps outlined in TLS handshake steps wiki.
upcoming handshake states: client finished[20]
upcoming handshake states: server change_cipher_spec[-1]
upcoming handshake states: server finished[20]
http-nio-8080-exec-15, WRITE: TLSv1.2 Change Cipher Spec, length = 1
*** Finished verify_data: { 27, 249, 167, 252, 151, 220, 110, 252, 113, 134, 248, 228 }
*** update handshake state: finished[20]
upcoming handshake states: server change_cipher_spec[-1]
upcoming handshake states: server finished[20]
http-nio-8080-exec-15, WRITE: TLSv1.2 Handshake, length = 40
http-nio-8080-exec-15, READ: TLSv1.2 Alert, length = 2
http-nio-8080-exec-15, RECV TLSv1.2 ALERT: fatal, handshake_failure
%% Invalidated: [Session-6, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384]
http-nio-8080-exec-15, called closeSocket() http-nio-8080-exec-15,
handling exception: javax.net.ssl.SSLHandshakeException: Received
fatal alert: handshake_failure
The step 'server change_cipher_spec' is where I am suspecting something has gone wrong - though unsure how to debug this further. Appreciate any pointers.
Solution
Finally the issue is resolved.
As expected, 'Unparseable certificate extensions' turned out to be a false alarm.
Finally setting both trust store and key store helped resolve. The key store was also require for client authentication during the SSL Handshake.
-Djavax.net.ssl.trustStore=C:\Users\cert\visatomcat.p12 -Djavax.net.ssl.trustStorePassword=pass123 -Djavax.net.ssl.trustStoreType=PKCS12 -Djavax.net.ssl.keyStore=C:\Users\cert\visatomcat.p12 -Djavax.net.ssl.keyStorePassword=pass123
Answered By - Srini M
