| Recently, our team embarked on the task of migrating applications to Spring Boot 3.x and Java 17. However, during this transition, we encountered an unusual SSL handshake error affecting a subset of our applications. The issue exhibited a sporadic nature, with approximately a 20% reproduction rate, and intriguingly, a retry attempt consistently resolved it. Eager to delve deeper into this anomaly, we opted to enable comprehensive network logging by leveraging Java VM arguments, specifically -Djavax.net.debug=all. This enabled us to gather detailed logs from the client-side. "Alert": { "level" : "fatal", "description": "internal_error" } ) javax.net.ssl|ERROR|92|http-nio-9000-exec-3|2024-04-15 15:33:55.009 UTC|TransportContext.java:363|Fatal (INTERNAL_ERROR): Received fatal alert: internal_error ( "throwable" : { javax.net.ssl.SSLException: Received fatal alert: internal_error at java.base/sun.security.ssl.Alert.createSSLException(Alert.java:133)
Upon analysis, we uncovered a corresponding stack trace originating from the server-side, indicating an inability to interpret the SSL message sent by the client. javax.net.ssl|ERROR|13|https-jsse-nio-9000-exec-10|2024-04-15 10:33:55.004 CDT|TransportContext.java:363|Fatal (INTERNAL_ERROR): problem unwrapping net record ( "throwable" : { javax.net.ssl.SSLException: Unrecognized SSL message, plaintext connection? at java.base/sun.security.ssl.SSLEngineInputRecord.bytesInCompletePacket(SSLEngineInputRecord.java:145) at java.base/sun.security.ssl.SSLEngineInputRecord.bytesInCompletePacket(SSLEngineInputRecord.java:64) at java.base/sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:612) at java.base/sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:506) at java.base/sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:482) at java.base/javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:679) at org.apache.tomcat.util.net.SecureNioChannel.handshakeUnwrap(SecureNioChannel.java:481) at org.apache.tomcat.util.net.SecureNioChannel.handshake(SecureNioChannel.java:213) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1715) at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:52) at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191) at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.base/java.lang.Thread.run(Thread.java:833)}
Notably, the issue consistently occurred when the client attempted to resume a session, resulting in an immediate fatal error. Further investigation revealed that the sessions attempting to resume were negotiated with TLSv1.3. Try resuming session ( Session(1713195048209|TLS_AES_256_GCM_SHA384) ) javax.net.ssl|INFO|92|http-nio-9000-exec-3|2024-04-15 15:33:54.954 UTC|AlpnExtension.java:182|No available application protocols javax.net.ssl|DEBUG|92|http-nio-9000-exec-3|2024-04-15 15:33:54.954 UTC|SSLExtensions.java:272|Ignore, context unavailable extension: application_layer_protocol_negotiation javax.net.ssl|ALL|92|http-nio-9000-exec-3|2024-04-15 15:33:54.954 UTC|SignatureScheme.java:412|Ignore disabled signature scheme: dsa_sha256 javax.net.ssl|ALL|92|http-nio-9000-exec-3|2024-04-15 15:33:54.954 UTC|SignatureScheme.java:412|Ignore disabled signature scheme: dsa_sha224 javax.net.ssl|ALL|92|http-nio-9000-exec-3|2024-04-15 15:33:54.954 UTC|SignatureScheme.java:412|Ignore disabled signature scheme: dsa_sha1 javax.net.ssl|ALL|92|http-nio-9000-exec-3|2024-04-15 15:33:54.954 UTC|SignatureScheme.java:412|Ignore disabled signature scheme: rsa_md5 javax.net.ssl|DEBUG|92|http-nio-9000-exec-3|2024-04-15 15:33:54.954 UTC|SSLExtensions.java:272|Ignore, context unavailable extension: cookie javax.net.ssl|DEBUG|92|http-nio-9000-exec-3|2024-04-15 15:33:54.955 UTC|SSLExtensions.java:272|Ignore, context unavailable extension: renegotiation_info javax.net.ssl|DEBUG|92|http-nio-9000-exec-3|2024-04-15 15:33:54.955 UTC|PreSharedKeyExtension.java:707|Found resumable session. Preparing PSK message. javax.net.ssl|DEBUG|92|http-nio-9000-exec-3|2024-04-15 15:33:54.990 UTC|ClientHello.java:641|Produced ClientHello handshake message ( "ClientHello": { "client version" : "TLSv1.2", "random" : "11BEE3F305C4048B9BA2BB2E4F8D1E124E9C75CA038F5F64805658218628B90A", "session id" : "",
The session trying to resuming was negotiated with TLSv1.3: Negotiated protocol version: TLSv1.3 javax.net.ssl|DEBUG|D2|http-nio-9000-exec-7|2024-04-15 15:30:48.209 UTC|SSLExtensions.java:175|Ignore unsupported extension: server_name javax.net.ssl|DEBUG|D2|http-nio-9000-exec-7|2024-04-15 15:30:48.209 UTC|SSLExtensions.java:175|Ignore unsupported extension: max_fragment_length javax.net.ssl|DEBUG|D2|http-nio-9000-exec-7|2024-04-15 15:30:48.209 UTC|SSLExtensions.java:175|Ignore unsupported extension: status_request javax.net.ssl|DEBUG|D2|http-nio-9000-exec-7|2024-04-15 15:30:48.209 UTC|SSLExtensions.java:175|Ignore unsupported extension: ec_point_formats javax.net.ssl|DEBUG|D2|http-nio-9000-exec-7|2024-04-15 15:30:48.209 UTC|SSLExtensions.java:175|Ignore unsupported extension: application_layer_protocol_negotiation javax.net.ssl|DEBUG|D2|http-nio-9000-exec-7|2024-04-15 15:30:48.209 UTC|SSLExtensions.java:175|Ignore unsupported extension: status_request_v2 javax.net.ssl|DEBUG|D2|http-nio-9000-exec-7|2024-04-15 15:30:48.209 UTC|SSLExtensions.java:175|Ignore unsupported extension: extended_master_secret javax.net.ssl|DEBUG|D2|http-nio-9000-exec-7|2024-04-15 15:30:48.209 UTC|SSLExtensions.java:175|Ignore unsupported extension: session_ticket javax.net.ssl|DEBUG|D2|http-nio-9000-exec-7|2024-04-15 15:30:48.209 UTC|SSLExtensions.java:204|Consumed extension: supported_versions javax.net.ssl|DEBUG|D2|http-nio-9000-exec-7|2024-04-15 15:30:48.209 UTC|SSLExtensions.java:204|Consumed extension: key_share javax.net.ssl|DEBUG|D2|http-nio-9000-exec-7|2024-04-15 15:30:48.209 UTC|SSLExtensions.java:175|Ignore unsupported extension: renegotiation_info javax.net.ssl|DEBUG|D2|http-nio-9000-exec-7|2024-04-15 15:30:48.209 UTC|PreSharedKeyExtension.java:924|Handling pre_shared_key absence. javax.net.ssl|ALL|D2|http-nio-9000-exec-7|2024-04-15 15:30:48.209 UTC|SSLSessionImpl.java:219|Session initialized: Session(1713195048209|TLS_AES_256_GCM_SHA384) javax.net.ssl|DEBUG|D2|http-nio-9000-exec-7|2024-04-15 15:30:48.209 UTC|SSLExtensions.java:219|Ignore unavailable extension: server_name
Interestingly, we encountered a similar pattern of issues during a previous upgrade to Java 11 and Spring Boot 2.6.x. At that time, we addressed the issue by implementing a retry mechanism for SSLExceptions, particularly for API calls to SOAP endpoints. However, this time around, our focus lies in identifying the root cause of the issue. Extensive research, both internal and external, led us to discover similar issues reported by others, notably documented as JDK-8277307. https://bugs.openjdk.org/browse/JDK-8277307 Fortunately, our findings provided potential solutions, suggesting an upgrade to Java 17.0.10 or alternatively applying a workaround by configuring the JVM argument -Djdk.tls.client.enableSessionTicketExtension=false on the client side. Armed with this information, we are eager to implement Java 17.0.10 and assess its effectiveness in resolving the SSL handshake issue. In conclusion, our journey toward migrating to Spring Boot 3.x and Java 17 has presented us with unforeseen challenges. Yet, each obstacle serves as an opportunity for growth and learning. By diligently investigating and applying solutions, we aim not only to resolve immediate issues but also to fortify our systems for the future. Through collaboration and perseverance, we are confident in our ability to navigate these complexities and emerge stronger than before. We eagerly anticipate the outcome of implementing Java 17.0.10 and remain committed to addressing any challenges that may arise along the way. | 
Comments
Post a Comment