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.
SSLSessionthat has been invalidated here, not the cipher suite. You are attempting to rejoin an expired session. You may need to look at the peer logs for more information. – user207421