RFR: 8339538: Wrong timeout computations in DnsClient [v8]

[Mark Sheppard]

On Wed, 2 Oct 2024 13:25:54 GMT, Aleksei Efimov <aefimov at openjdk.org> wrote:

> > I think that if there is a PortUnreachable thrown, during DnsClient.query processing from the doUdpQuery, then the timeout may expire early ... if I've interpreted the outer loop processing correctly
> 
> The `DnsClient.query` marks server as misconfigured (not suitable for further retries) in scenarios when `PortUnreachable` is caught (see `doNotRetry`). And since the timeout/retries are specified per server it is expected for the timeout to expire early. For scenarios with one server and `PortUnreachable` exception - the `DnsClient.query` will throw the `CommunicationException` with `PortUnreachable` set as its cause.

Here's two set of trace (pre your current change) for the main Timeout test. The second trace is a simulated receipt of an ICMP Host unreachable

normal successful execution of Timeout test

----------System.out:(19/715)----------
Skip local DNS Server creation 
DnsClient.query retry == 0
DnsClient.doUdpQuery pktTimeout == 250
DnsClient.blockingReceive: select with timeout == 250
DnsClient.query retry == 1
DnsClient.doUdpQuery pktTimeout == 500
DnsClient.blockingReceive: select with timeout == 500
DnsClient.query retry == 2
DnsClient.doUdpQuery pktTimeout == 1000
DnsClient.blockingReceive: select with timeout == 1000
DnsClient.query retry == 3
DnsClient.doUdpQuery pktTimeout == 2000
DnsClient.blockingReceive: select with timeout == 2000
DnsClient.query retry == 4
DnsClient.doUdpQuery pktTimeout == 4000
DnsClient.blockingReceive: select with timeout == 4000
Elapsed (ms):  7793
Expected (ms): 7750
elapsed time is as long as expected.
----------System.err:(18/768)----------
DNS: SEND ID (1): 29440
DNS: Trying RECEIVE(1) retry(1) for:29440    sock-timeout:250 ms.
DNS: Caught IOException:java.net.SocketTimeoutException
DNS: SEND ID (2): 29440
DNS: Trying RECEIVE(1) retry(2) for:29440    sock-timeout:500 ms.
DNS: Caught IOException:java.net.SocketTimeoutException
DNS: SEND ID (3): 29440
DNS: Trying RECEIVE(1) retry(3) for:29440    sock-timeout:1000 ms.
DNS: Caught IOException:java.net.SocketTimeoutException
DNS: SEND ID (4): 29440
DNS: Trying RECEIVE(1) retry(4) for:29440    sock-timeout:2000 ms.
DNS: Caught IOException:java.net.SocketTimeoutException
DNS: SEND ID (5): 29440
DNS: Trying RECEIVE(1) retry(5) for:29440    sock-timeout:4000 ms.
DNS: Caught IOException:java.net.SocketTimeoutException

--------------oOo----------------
timeout failure due to PortUnreachableException

----------System.out:(12/392)----------
Skip local DNS Server creation 
DnsClient.query retry == 0
DnsClient.doUdpQuery pktTimeout == 250
DnsClient.blockingReceive: select with timeout == 250
DnsClient.query retry == 1
DnsClient.doUdpQuery pktTimeout == 500
DnsClient.blockingReceive: select with timeout == 500
DnsClient.query retry == 2
DnsClient.query retry == 3
DnsClient.query retry == 4
Elapsed (ms):  777
Expected (ms): 7750
----------System.err:(21/1055)----------
DNS: SEND ID (1): 27504
DNS: Trying RECEIVE(1) retry(1) for:27504    sock-timeout:250 ms.
DNS: Caught IOException:java.net.SocketTimeoutException
DNS: SEND ID (2): 27504
DNS: Trying RECEIVE(1) retry(2) for:27504    sock-timeout:500 ms.
DNS: Caught IOException:java.net.SocketTimeoutException
DNS: SEND ID (3): 27504
DNS: Caught Exception:java.net.PortUnreachableException: simulated ICMP Host unreachable
java.lang.RuntimeException: Failed: timeout in 777 ms, expected7750ms
	at Timeout.handleException(Timeout.java:116)
	at TestBase.launch(TestBase.java:84)
	at TestBase.run(TestBase.java:50)
	at Timeout.main(Timeout.java:59)
	at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
	at java.base/java.lang.reflect.Method.invoke(Method.java:588)
	at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:333)
	at java.base/java.lang.Thread.run(Thread.java:1575)

JavaTest Message: Test threw exception: java.lang.RuntimeException
JavaTest Message: shutting down test

result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Failed: timeout in 777 ms, expected7750ms


test result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Failed: timeout in 777 ms, expected7750ms


So if a PortUnreachableException is thrown, which can happen for either a send or receive anytime after the first iteration through the retry loop, then there will be an early timeout. As such, your assertion does not appear to be true.

-------------

PR Comment: https://git.openjdk.org/jdk/pull/20892#issuecomment-2389979568