8307411: Test java/foreign/channels/TestAsyncSocketChannels.java failed: IllegalStateException: Already closed

[mcimadamore]

This is a tricky intermittent failure on one of our async file channel test.

While the logic of the test is a bit hard to follow, I believe the test is supposed to work as follows:

• in the main thread, we submit an initial async write on a buffer
• the completion handler of the async op will submit another async write after one completes
• before/after each write we increment/decrement an atomic counter
• in the main thread waits 20 secs, to make sure the write buffers are full and that there are some async writes actually awaiting for OS to serve them
• we then try to close the test arena - this would fail as there are pending OS writes, and we keep the arena locked to prevent JVM crashes
• then the main test will set the continueWriting flag to false (which will cause the handler to stop submitting new write requests).
• the main thread will then read what's left (so that the buffers will empty and the OS can serve the outstanding writes)
• when there's no outstanding writes left, the main thread will close the test scope.

I think, after many hours spent staring the test that, when working as intended, the test logic is correct. Each write is only submitted after the previous one finished, and the test can only end when we see the number of outstanding write to reach 0. For this to happen, we need to execute the handler once when continueWriting is set to false (which will cause an asymmetric decrement of the counter from the handler, which will match the asymmetric increment outside the handler, in the main test thread).

When trying to reduce the timeout which ensures that write buffers are full, I started hitting the same exception as the one described in the bug report. After some digging, I found that the exception was not caused (as I thought) by some bad synchronization logic which allowed the main test to close the arena before the handlers were actually finished with it. Instead, the failure is caused by the test assertion which checks that the test arena cannot be closed:

assertMessage(expectThrows(ISE, () -> drop.close()), "Session is acquired by"); 

This check is bogus: it assumes that the buffers are indeed full, and that some OS write operation cannot progress. In that case, the underlying arena will be kept alive (as the implementation wants to avoid a JVM crash triggered by an OS write on an already freed region of memory).

But, if the buffer is not full at this stage, there is nothing keeping the test arena alive: note that the completion handler executes after the arena acquire/release in IOUtils. So, if all write operations complete normally, drop::close will actually succeed!

At this point it's a coint toss as to whether we'll see a message because the copletion handler tries to allocate on an already closed arena, or if we see a message complaining about drop::close not failing as expected.

While there are other ways to fix this, I think a simple fix is to actually remove the assertion on drop::close. Note that if there's a bug in the keepalive logic of the arena, the test would still fail (but with a JVM crash). And, by avoiding a spurious call to drop::close we make sure that the test always runs as intended whether or not the OS buffers are full.

---

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-8307411: Test java/foreign/channels/TestAsyncSocketChannels.java failed: IllegalStateException: Already closed

Reviewers

• Jorn Vernee (@JornVernee - Reviewer)

Reviewing

Using git

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

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

Using Skara CLI tools

Checkout this PR locally:
$ git pr checkout 13866

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

Using diff file

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

Webrev

Link to Webrev Comment

[bridgekeeper]

👋 Welcome back mcimadamore! 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]

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

• core-libs

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

• 00: Full (f3b8e384)

[JornVernee]

Great detective work, thanks! I think the fix is good. We already have other tests that try to detect acquire/release issue.

[openjdk]

@mcimadamore This change now passes all automated pre-integration checks.

ℹ️ This project also has non-automated pre-integration requirements. Please see the file CONTRIBUTING.md for details.

After integration, the commit message for the final commit will be:

8307411: Test java/foreign/channels/TestAsyncSocketChannels.java failed: IllegalStateException: Already closed

Reviewed-by: jvernee

You can use pull request commands such as /summary, /contributor and /issue to adjust it as needed.

At the time when this comment was updated there had been 11 new commits pushed to the master branch:

• 4116b10: 8306461: ObjectInputStream::readObject() should handle negative array sizes without throwing NegativeArraySizeExceptions
• 93ee19f: 8305486: Add split() variants that keep the delimiters to String and j.u.r.Pattern
• ad90fb6: 8293786: HttpClient will not send more than 64 kb of data from the 2nd request in http2
• 5a259d8: 8303153: Native interpreter frame missing mirror
• 4b02956: 8054022: HttpURLConnection timeouts with Expect: 100-Continue and no chunking
• 9f34e4f: 8304434: [AIX] Update minimum xlclang version
• d2e0e53: 8307604: gcc12 based Alpine build broken build after JDK-8307301
• e91f0d3: 8307571: Remove unused SomeConstants in WatcherThread class
• 26755a9: 8306408: Fix the format of several tables in building.md
• 64c0962: 8307569: Build with gcc8 is broken after JDK-8307301
• ... and 1 more: https://git.openjdk.org/jdk/compare/5c7ede94ae59b46c12d40a38bf5b7e15319cc7e2...master

As there are no conflicts, your changes will automatically be rebased on top of these commits when integrating. If you prefer to avoid this automatic rebasing, please check the documentation for the /integrate command for further details.

➡️ To integrate this PR with the above commit message to the master branch, type /integrate in a new comment.

[mcimadamore]

/integrate

[openjdk]

Going to push as commit f92d095.
Since your change was applied there have been 19 commits pushed to the master branch:

• 7a3bea1: 8307629: FunctionDescriptor::toMethodType should allow sequence layouts (mainline)
• d2b3eef: 8307131: C2: assert(false) failed: malformed control flow
• cd5d0ff: 8304031: Classfile API cannot encode Primitive Class as Condy
• 07f55c5: 8305950: Have -XshowSettings option display tzdata version
• d9052b9: 8307130: Open source few Swing JMenu tests
• 5e1fe43: 8299229: [JVMCI] add support for UseZGC
• 14df5c1: 8307165: java/awt/dnd/NoFormatsDropTest/NoFormatsDropTest.java timed out
• 7f6358a: 8291555: Implement alternative fast-locking scheme
• 4116b10: 8306461: ObjectInputStream::readObject() should handle negative array sizes without throwing NegativeArraySizeExceptions
• 93ee19f: 8305486: Add split() variants that keep the delimiters to String and j.u.r.Pattern
• ... and 9 more: https://git.openjdk.org/jdk/compare/5c7ede94ae59b46c12d40a38bf5b7e15319cc7e2...master

Your commit was automatically rebased without conflicts.

[openjdk]

@mcimadamore Pushed as commit f92d095.

💡 You may see a message that your pull request was closed with unmerged commits. This can be safely ignored.