8368625: com/sun/net/httpserver/ServerStopTerminationTest.java fails intermittently in tier7

[myankelev]

I believe that increasing the timeout might help, as it seems to be happening due to the machine load. I'm going to make a pr increasing the timeout to 20 from 5 (similar to what it was when timeout factor was 4).

---

Progress

• Change must be properly reviewed (1 review required, with at least 1 Reviewer)
• Change must not contain extraneous whitespace
• Commit message must refer to an issue

Issue

• JDK-8368625: com/sun/net/httpserver/ServerStopTerminationTest.java fails intermittently in tier7 (Bug - P4)

Reviewing

Using git

Checkout this PR locally:
$ git fetch https://git.openjdk.org/jdk.git pull/27670/head:pull/27670
$ git checkout pull/27670

Update a local copy of the PR:
$ git checkout pull/27670
$ git pull https://git.openjdk.org/jdk.git pull/27670/head

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 27670

View PR using the GUI difftool:
$ git pr show -t 27670

Using diff file

Download this PR as a diff file:
https://git.openjdk.org/jdk/pull/27670.diff

Using Webrev

Link to Webrev Comment

[bridgekeeper]

👋 Welcome back myankelevich! A progress list of the required criteria for merging this PR into master will be added to the body of your pull request. There are additional pull request commands available for use with this pull request.

[openjdk]

❗ This change is not yet ready to be integrated.
See the Progress checklist in the description for automated requirements.

[openjdk]

@myankelev The following label will be automatically applied to this pull request:

• net

When this pull request is ready to be reviewed, an "RFR" email will be sent to the corresponding mailing list. If you would like to change these labels, use the /label pull request command.

[mlbridge]

Webrevs

• 01: Full - Incremental (d272f961)
• 00: Full (7ace98c1)

[msheppar]

The extending of the stop duration may not have the desired effect of eliminating what appears to be a race condition in the test

One of the recorded failures is for the temporal condition

    // The shutdown should take at least as long as the exchange duration
    if (elapsed < exchangeDuration.toNanos()) {
        fail("HttpServer.stop terminated before exchange completed");
    }

This is a somewhat dubious constraint and can’t always be met

The test assumes that the participating threads are all actively executing simultaneously, which may not be true
They may be scheduled to run rather than actually running.

Restating the objective of the test
Objective: to ensure that the stop request is not processed while there are extant exchanges

Potential race scenario:

Server started creates exchange which waits for a signal to complete

Exchange completion thread starts waits for 1 seconds before it can signal exchange to compete — the complete signal will be thus invoked sometime after 1 second depending on OS thread scheduling

Main thread continues and invokes a stop which has a max wait time of 5 seconds for extant exchanges to complete — so max completion time of stop is 5 seconds ++ i.e. could be slightly longer than 5 seconds again subject to OS scheduling

Temporal condition imposed by test

    // The shutdown should take at least as long as the exchange duration
    if (elapsed < exchangeDuration.toNanos()) {
        fail("HttpServer.stop terminated before exchange completed");
    }

    // The delay should not have expired
    if (elapsed >= delayDuration.toNanos()) { 
        fail("HttpServer.stop terminated after delay expired");
    }

1. States elapsed time of stop should be less than the duration of the exchange exchangeDuration. BUT exchangeDuration is not the
   duration of the exchange completion. Rather, it is the time delay before the exchange thread is signalled to complete.
   The actual completion of the exchange may be sometime later, again depending on OS thread scheduling.

Second condition is that the elapsed time of the stop should be less than or equal to the stop delay. BUT if the full timeout for the
stop expires as per

server.stop will wait a max of N (5) seconds before terminating as per

    try {
        // waiting for the duration of the delay, unless released before
        finishedLatch.await(delay, TimeUnit.SECONDS);

    } catch (InterruptedException e) {
        logger.log(Level.TRACE, "Error in awaiting the delay");

    } finally {

Then this infers that the extant exchanges have taken longer than the expected or allowed time. This in turn infers that
the exchange is still executing or waiting to execute at the time of the stop request.

All in all the temporal conditions are not exact and they are subject to variability depending on the scheduling of threads by the OS.

BUT extending of the delayDuration doesn’t necessarily impact the first condition, which has failed, because the elapsed time may be less than the exchange duration due to OS scheduling

[dfuch]

I believe Mark is right - there is an issue with the timing logic in this method. The virtual thread that sleeps before calling complete.countDown() may finish sleeping and call countDown() before server.stop() is called. Good analysis @msheppar !

[myankelev]

@msheppar @dfuch thanks for the review! I believe it should be fixed in the latest commit

[dfuch]

Suggested change

	final long startTime = System.nanoTime(); // taking custom start time just in case
	// taking start time before entering completeExchange to account for possible
	// delays in reaching server.stop().
	final long startTime = System.nanoTime();

[dfuch]

Looks good, but if this test fail we could envisage bumping that delay though. A better implementation could be to complete the exchange after exiting from server.stop() - without using any virtual thread, and just verifying that the server.stop() waited at least for 1s.