JDK-8159416 : javax/net/ssl/DTLS/CipherSuite.java failed on timeout
  • Type: Enhancement
  • Component: security-libs
  • Sub-Component: javax.net.ssl
  • Affected Version: 9
  • Priority: P4
  • Status: Closed
  • Resolution: Not an Issue
  • OS: os_x
  • CPU: x86_64
  • Submitted: 2016-06-14
  • Updated: 2019-02-11
  • Resolved: 2016-12-05
Related Reports
Blocks :  
JDK-8163419 - Final CCS and Finished DTLS messages can't be re-transmitted
Blocks :  
JDK-8161086 - DTLS handshaking fails if some messages were lost
Duplicate :  
JDK-8159936 - javax/net/ssl/DTLS/WeakCipherSuite.java failed with timeout
Relates :  
JDK-8129389 - javax/net/ssl/DTLS tests fail intermittently
Relates :  
JDK-8138877 - [TEST] Intermittent test failure: javax/net/ssl/DTLS/WeakCipherSuite.java
Relates :  
JDK-8174072 - javax/net/ssl/DTLS/CipherSuite.java timed out intermittently
Relates :  
JDK-8176197 - javax/net/ssl/DTLS/CipherSuite.java failed on timeout
Relates :  
JDK-8159936 - javax/net/ssl/DTLS/WeakCipherSuite.java failed with timeout
Relates :  
JDK-8159936 - javax/net/ssl/DTLS/WeakCipherSuite.java failed with timeout
Description
javax/net/ssl/DTLS/CipherSuite.java failed on timeout
A part of log as the below:
result: Error. Program `/scratch/jenkins/workspace/9-dev/jdk/bin/java' timed out (timeout set to 600000ms, elapsed time was 601068ms).
test result: Error. Program `/scratch/jenkins/workspace/9-dev/jdk/bin/java' timed out (timeout set to 600000ms, elapsed time was 601068ms).
Comments
JDK-8161086 and JDK-8163419 have been fixed. I am closing this bug.
05-12-2016
It doesn't look like a test issue anymore. Instead, there are two bugs in DTLS implementation which cause intermittent test failures: JDK-8161086: DTLS handshaking fails if some messages were lost JDK-8163419: Final CCS and Finished DTLS messages can't be re-transmitted While working on this issue, I made DTLS tests to drop packets more aggressively which allow to cover more cases. I also added a regression tests for the bugs above: http://cr.openjdk.java.net/~asmotrak/8159416/webrev.08/ DTLS tests should stop failing intermittently after these two bugs are fixed, so this issues can be considered as an enhancement now which is blocked by the bugs above.
11-08-2016
One more issue was found while discussing this fix with Xuelei: JDK-8163419: Final CCS and Finished DTLS messages can't be re-transmitted
08-08-2016
I also noticed that ByteBuffer.flip() sometimes doesn't set position to zero which is strange. http://download.java.net/java/jdk9/docs/api/java/nio/ByteBuffer.html#flip-- As a result, the test may fail when client check received application data.
16-07-2016
JDK-8161086 was found while updating DTLS tests to be able to drop packets randomly. This fix depends on JDK-8161086 since existing DTLS tests are going to fail without JDK-8161086.
15-07-2016
Code review: http://mail.openjdk.java.net/pipermail/security-dev/2016-June/014242.html
28-06-2016
The tests use UDP to transfer packets. It looks like both server and client tries to receive packets. But the client tries to re-send packets. When the client gets SocketTimeoutException, it goes to onReceiveTimeout() which calls SSLEngine.wrap() to produce handshaking data. http://hg.openjdk.java.net/jdk9/dev/jdk/file/40dc66a99bcc/test/javax/net/ssl/DTLS/DTLSOverDatagram.java#l173 Then, the client re-send those packets to the server. Here are messages on client side: ... pool-1-thread-2, WRITE: DTLSv1.2 Handshake, length = 184 Client: Receive DTLS records, handshake status is NEED_UNWRAP Client: Warning: java.net.SocketTimeoutException: Receive timed out pool-1-thread-2, WRITE: DTLSv1.2 Handshake, length = 184 Client: New handshake status is NEED_UNWRAP Client: Receive DTLS records, handshake status is NEED_UNWRAP Client: Warning: java.net.SocketTimeoutException: Receive timed out pool-1-thread-2, WRITE: DTLSv1.2 Handshake, length = 184 Client: New handshake status is NEED_UNWRAP Client: Receive DTLS records, handshake status is NEED_UNWRAP Client: Warning: java.net.SocketTimeoutException: Receive timed out pool-1-thread-2, WRITE: DTLSv1.2 Handshake, length = 184 ... But the server doesn't re-send any packet, and fails to receive any (even if the client re-sends them). Here are messages on server side: ... Server: Receive DTLS records, handshake status is NEED_UNWRAP Server: Warning: java.net.SocketTimeoutException: Receive timed out Server: New handshake status is NEED_UNWRAP Server: Receive DTLS records, handshake status is NEED_UNWRAP Server: Warning: java.net.SocketTimeoutException: Receive timed out Server: New handshake status is NEED_UNWRAP Server: Receive DTLS records, handshake status is NEED_UNWRAP Server: Warning: java.net.SocketTimeoutException: Receive timed out Server: New handshake status is NEED_UNWRAP Server: Receive DTLS records, handshake status is NEED_UNWRAP Server: Warning: java.net.SocketTimeoutException: Receive timed out Server: New handshake status is NEED_UNWRAP Server: Receive DTLS records, handshake status is NEED_UNWRAP ... According to logs, it looks fine that the server doesn't re-send anything because it is beginning of handshaking, and the client tries to send ClientHello. The spec for DatagramSocket says that the socket is still valid if SocketTimeoutException occurred. http://download.java.net/java/jdk9/docs/api/java/net/DatagramSocket.html#setSoTimeout-int- At first glance, the test looks correct. I am wondering if it may be caused by some networking issues, or a bug in net-libs, or in system libs.
28-06-2016
The tests use UDP to transfer handshake data. But UDP doesn't gurantee packets delivery, so theoretically it would be always possible that handshaking fails if UDP is used. It is also possible that some packets can be dropped because of test environment (network issues, configuration issue, firewall settings, etc). At the moment, it is not clear why server can't receive packets with DatagramSocket.receive() method even if client tries to re-send them. Since the tests are for DTLS, we can use any transport. But to avoid changing test logic much, we can use custom DatagramSocketImpl and DatagramSocketImplFactory implementations to replace system UDP implementation.
28-06-2016
I finally was able to reproduce it on Mac. According to previously reported bugs about those failures, it seems to be Mac specific (see JDK-8138877, JDK-8129389, JDK-8159936).
23-06-2016
javax/net/ssl/DTLS/WeakCipherSuite.java test fails intermittently with the similar output: *** ClientHello, DTLSv1.2 RandomCookie: random_bytes = {39 C3 14 A5 B7 B9 2B 2F 28 25 53 B2 04 AC 05 5E 02 83 E8 CD 5D CE 45 DA EF 63 42 61 29 01 C8 5F} Session ID: {} cookie: { } Cipher Suites: [TLS_DH_anon_WITH_AES_128_GCM_SHA256] Compression Methods: { 0 } Extension signature_algorithms, signature_algorithms: SHA512withECDSA, SHA512withRSA, SHA384withECDSA, SHA384withRSA, SHA256withECDSA, SHA256withRSA, SHA256withDSA, SHA224withECDSA, SHA224withRSA, SHA224withDSA, SHA1withECDSA, SHA1withRSA, SHA1withDSA, MD5withRSA Extension status_request_v2 CertStatusReqItemV2: ocsp_multi, OCSPStatusRequest ResponderIds: <EMPTY> Extensions: <EMPTY> CertStatusReqItemV2: ocsp, OCSPStatusRequest ResponderIds: <EMPTY> Extensions: <EMPTY> Extension status_request: ocsp, OCSPStatusRequest ResponderIds: <EMPTY> Extensions: <EMPTY> Extension renegotiation_info, renegotiated_connection: <empty> *** pool-1-thread-2, WRITE: DTLSv1.2 Handshake, length = 124 Client: Receive DTLS records, handshake status is NEED_UNWRAP Server: Receive DTLS records, handshake status is NEED_UNWRAP Server: Warning: java.net.SocketTimeoutException: Receive timed out Client: Warning: java.net.SocketTimeoutException: Receive timed out pool-1-thread-2, WRITE: DTLSv1.2 Handshake, length = 124 Server: New handshake status is NEED_UNWRAP Server: Receive DTLS records, handshake status is NEED_UNWRAP Client: New handshake status is NEED_UNWRAP Client: Receive DTLS records, handshake status is NEED_UNWRAP Client: Warning: java.net.SocketTimeoutException: Receive timed out Server: Warning: java.net.SocketTimeoutException: Receive timed out Server: New handshake status is NEED_UNWRAP pool-1-thread-2, WRITE: DTLSv1.2 Handshake, length = 124 Server: Receive DTLS records, handshake status is NEED_UNWRAP Client: New handshake status is NEED_UNWRAP Client: Receive DTLS records, handshake status is NEED_UNWRAP Server: Warning: java.net.SocketTimeoutException: Receive timed out Server: New handshake status is NEED_UNWRAP Server: Receive DTLS records, handshake status is NEED_UNWRAP Client: Warning: java.net.SocketTimeoutException: Receive timed out pool-1-thread-2, WRITE: DTLSv1.2 Handshake, length = 124 Client: New handshake status is NEED_UNWRAP Client: Receive DTLS records, handshake status is NEED_UNWRAP Server: Warning: java.net.SocketTimeoutException: Receive timed out Server: New handshake status is NEED_UNWRAP Server: Receive DTLS records, handshake status is NEED_UNWRAP Client: Warning: java.net.SocketTimeoutException: Receive timed out pool-1-thread-2, WRITE: DTLSv1.2 Handshake, length = 124 Client: New handshake status is NEED_UNWRAP Client: Receive DTLS records, handshake status is NEED_UNWRAP Server: Warning: java.net.SocketTimeoutException: Receive timed out Client: Warning: java.net.SocketTimeoutException: Receive timed out Server: New handshake status is NEED_UNWRAP Server: Receive DTLS records, handshake status is NEED_UNWRAP pool-1-thread-2, WRITE: DTLSv1.2 Handshake, length = 124 Client: New handshake status is NEED_UNWRAP Client: Receive DTLS records, handshake status is NEED_UNWRAP Server: Warning: java.net.SocketTimeoutException: Receive timed out Client: Warning: java.net.SocketTimeoutException: Receive timed out Server: New handshake status is NEED_UNWRAP Server: Receive DTLS records, handshake status is NEED_UNWRAP pool-1-thread-2, WRITE: DTLSv1.2 Handshake, length = 124 Client: New handshake status is NEED_UNWRAP Client: Receive DTLS records, handshake status is NEED_UNWRAP Client: Warning: java.net.SocketTimeoutException: Receive timed out Server: Warning: java.net.SocketTimeoutException: Receive timed out pool-1-thread-2, WRITE: DTLSv1.2 Handshake, length = 124 Server: New handshake status is NEED_UNWRAP Server: Receive DTLS records, handshake status is NEED_UNWRAP Client: New handshake status is NEED_UNWRAP Client: Receive DTLS records, handshake status is NEED_UNWRAP Server: Warning: java.net.SocketTimeoutException: Receive timed out Client: Warning: java.net.SocketTimeoutException: Receive timed out Server: New handshake status is NEED_UNWRAP pool-1-thread-2, WRITE: DTLSv1.2 Handshake, length = 124 Server: Receive DTLS records, handshake status is NEED_UNWRAP Client: New handshake status is NEED_UNWRAP Client: Receive DTLS records, handshake status is NEED_UNWRAP Server: Warning: java.net.SocketTimeoutException: Receive timed out Client: Warning: java.net.SocketTimeoutException: Receive timed out
23-06-2016
According to logs, both client and server get SocketTimeoutException while trying to receive packets: ... *** ClientHello, DTLSv1.2 RandomCookie: random_bytes = {30 B0 FF 2A BE FF 1B 3A 26 C7 85 8C B1 D5 3D 17 A0 0D 65 83 A8 BD A0 D2 FB ED 62 6C 20 83 B3 38} Session ID: {} cookie: { } Cipher Suites: [TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256] Compression Methods: { 0 } Extension elliptic_curves, curve names: {secp256r1, sect163k1, sect163r2, secp192r1, secp224r1, sect233k1, sect233r1, sect283k1, sect283r1, secp384r1, sect409k1, sect409r1, secp521r1, sect571k1, sect571r1, secp160k1, secp160r1, secp160r2, sect163r1, secp192k1, sect193r1, sect193r2, secp224k1, sect239k1, secp256k1} Extension ec_point_formats, formats: [uncompressed] Extension signature_algorithms, signature_algorithms: SHA512withECDSA, SHA512withRSA, SHA384withECDSA, SHA384withRSA, SHA256withECDSA, SHA256withRSA, SHA256withDSA, SHA224withECDSA, SHA224withRSA, SHA224withDSA, SHA1withECDSA, SHA1withRSA, SHA1withDSA Extension status_request_v2 CertStatusReqItemV2: ocsp_multi, OCSPStatusRequest ResponderIds: <EMPTY> Extensions: <EMPTY> CertStatusReqItemV2: ocsp, OCSPStatusRequest ResponderIds: <EMPTY> Extensions: <EMPTY> Extension status_request: ocsp, OCSPStatusRequest ResponderIds: <EMPTY> Extensions: <EMPTY> Extension renegotiation_info, renegotiated_connection: <empty> *** pool-1-thread-2, WRITE: DTLSv1.2 Handshake, length = 184 Server: Receive DTLS records, handshake status is NEED_UNWRAP Client: Receive DTLS records, handshake status is NEED_UNWRAP Server: Warning: java.net.SocketTimeoutException: Receive timed out Client: Warning: java.net.SocketTimeoutException: Receive timed out pool-1-thread-2, WRITE: DTLSv1.2 Handshake, length = 184 Server: New handshake status is NEED_UNWRAP Server: Receive DTLS records, handshake status is NEED_UNWRAP Client: New handshake status is NEED_UNWRAP Client: Receive DTLS records, handshake status is NEED_UNWRAP Server: Warning: java.net.SocketTimeoutException: Receive timed out Client: Warning: java.net.SocketTimeoutException: Receive timed out ... Messages for successful handshake look like the following (see logs for successful connections): ... *** pool-1-thread-2, WRITE: DTLSv1.2 Handshake, length = 184 Server: Receive DTLS records, handshake status is NEED_UNWRAP pool-1-thread-1, READ: DTLSv1.2 Handshake, length = 184 Client: Receive DTLS records, handshake status is NEED_UNWRAP check handshake state: client_hello[1] update handshake state: client_hello[1] upcoming handshake states: hello_verify_request[3] *** ClientHello, DTLSv1.2 ... "pool-1-thread-1" is a name of thread where the server runs, and "pool-1-thread-2" is a name of thread where the client runs. See jstack output in logs: ... "pool-1-thread-2" #16 prio=5 os_prio=31 tid=0x00007fdf1d003000 nid=0x7d03 runnable [0x0000000132d3c000] java.lang.Thread.State: RUNNABLE at java.net.PlainDatagramSocketImpl.receive0(java.base@9-ea/Native Method) - locked <0x00000007afa0b078> (a java.net.PlainDatagramSocketImpl) at java.net.AbstractPlainDatagramSocketImpl.receive(java.base@9-ea/AbstractPlainDatagramSocketImpl.java:180) - locked <0x00000007afa0b078> (a java.net.PlainDatagramSocketImpl) at java.net.DatagramSocket.receive(java.base@9-ea/DatagramSocket.java:814) - locked <0x00000007aeedb1a8> (a java.net.DatagramPacket) - locked <0x00000007afa0b010> (a java.net.DatagramSocket) at DTLSOverDatagram.handshake(DTLSOverDatagram.java:174) at DTLSOverDatagram.doClientSide(DTLSOverDatagram.java:121) at DTLSOverDatagram$ClientCallable.call(DTLSOverDatagram.java:629) at DTLSOverDatagram$ClientCallable.call(DTLSOverDatagram.java:612) at java.util.concurrent.FutureTask.run(java.base@9-ea/FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@9-ea/ThreadPoolExecutor.java:1158) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@9-ea/ThreadPoolExecutor.java:632) at java.lang.Thread.run(java.base@9-ea/Thread.java:843) "pool-1-thread-1" #15 prio=5 os_prio=31 tid=0x00007fdf1d812000 nid=0x7c07 runnable [0x0000000132c39000] java.lang.Thread.State: RUNNABLE at java.net.PlainDatagramSocketImpl.receive0(java.base@9-ea/Native Method) - locked <0x00000007afa09910> (a java.net.PlainDatagramSocketImpl) at java.net.AbstractPlainDatagramSocketImpl.receive(java.base@9-ea/AbstractPlainDatagramSocketImpl.java:180) - locked <0x00000007afa09910> (a java.net.PlainDatagramSocketImpl) at java.net.DatagramSocket.receive(java.base@9-ea/DatagramSocket.java:814) - locked <0x00000007aee68ba0> (a java.net.DatagramPacket) - locked <0x00000007afa01bf8> (a java.net.DatagramSocket) at DTLSOverDatagram.handshake(DTLSOverDatagram.java:174) at DTLSOverDatagram.doServerSide(DTLSOverDatagram.java:102) at DTLSOverDatagram$ServerCallable.call(DTLSOverDatagram.java:591) at DTLSOverDatagram$ServerCallable.call(DTLSOverDatagram.java:574) at java.util.concurrent.FutureTask.run(java.base@9-ea/FutureTask.java:266) at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@9-ea/ThreadPoolExecutor.java:1158) at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@9-ea/ThreadPoolExecutor.java:632) at java.lang.Thread.run(java.base@9-ea/Thread.java:843) ... In this particular case, jtreg killed the test while it was waiting for packets in DatagramSocket.receive() method. But the test also may fail with "Too much loops to produce handshake packets".
22-06-2016
Attached CipherSuite.java.txt with logs.
14-06-2016