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

[Jorn Vernee]

On Mon, 8 May 2023 13:46:55 GMT, Maurizio Cimadamore <mcimadamore at openjdk.org> wrote:

> 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.

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

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

Marked as reviewed by jvernee (Reviewer).

PR Review: https://git.openjdk.org/jdk/pull/13866#pullrequestreview-1417085971