JDK-8265228 : java/foreign/TestHandshake.java failed with "test TestHandshake.testHandshake("SegmentCopyAccessor", TestHandshake$$Lambda$33/0x0000000800c22220@70055f59): failure"
  • Type: Bug
  • Component: core-libs
  • Affected Version: 17
  • Priority: P2
  • Status: Closed
  • Resolution: Duplicate
  • OS: windows
  • CPU: x86_64
  • Submitted: 2021-04-14
  • Updated: 2021-07-27
  • Resolved: 2021-07-27
Related Reports
Duplicate :  
JDK-8264774 - Implementation of Foreign Function and Memory API (Incubator)
Relates :  
JDK-8260869 - Test java/foreign/TestHandshake.java fails intermittently
Description
The following test failed in the JDK17 CI:

java/foreign/TestHandshake.java

Here's a snippet from the log file:

ITERATION 3
Starting handshaker with delay set to 39 millis
test TestHandshake.testHandshake("SegmentCopyAccessor", TestHandshake$$Lambda$33/0x0000000800c22220@70055f59): failure
java.lang.AssertionError: expected [true] but found [false]
	at org.testng.Assert.fail(Assert.java:94)
	at org.testng.Assert.failNotEquals(Assert.java:496)
	at org.testng.Assert.assertTrue(Assert.java:42)
	at org.testng.Assert.assertTrue(Assert.java:52)
	at TestHandshake.testHandshake(TestHandshake.java:78)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:78)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:85)
	at org.testng.internal.Invoker.invokeMethod(Invoker.java:639)
	at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:821)
	at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1131)
	at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:124)
	at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:108)
	at org.testng.TestRunner.privateRun(TestRunner.java:773)
	at org.testng.TestRunner.run(TestRunner.java:623)
	at org.testng.SuiteRunner.runTest(SuiteRunner.java:357)
	at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:352)
	at org.testng.SuiteRunner.privateRun(SuiteRunner.java:310)
	at org.testng.SuiteRunner.run(SuiteRunner.java:259)
	at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
	at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:86)
	at org.testng.TestNG.runSuitesSequentially(TestNG.java:1185)
	at org.testng.TestNG.runSuitesLocally(TestNG.java:1110)
	at org.testng.TestNG.run(TestNG.java:1018)
	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:94)
	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:54)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:78)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.base/java.lang.Thread.run(Thread.java:831)

Starting this bug as a P2 since this is an intermittent Tier1 failure.

Found a very similar bug that was previously fixed:

JDK-8260869 Test java/foreign/TestHandshake.java fails intermittently
Comments
Only bugs associated with changesets should be closed as "Fixed". If this bug is fixed by another issue, then please close this bug as a duplicate of the other issue.
19-07-2021
Resolved as part of integration of JEP 412
13-07-2021
Addressed in panama-repo: https://github.com/openjdk/panama-foreign/pull/517 I will close this issue when the changes in panama will be upstreamed.
23-04-2021
This is telling: ITERATION 0 Starting handshaker with delay set to 254 millis Accessor #2 suspending - delay (ms): 8717 Accessor #1 suspending - delay (ms): 8719 Accessor #7 suspending - delay (ms): 8719 Accessor #6 suspending - delay (ms): 8717 Accessor #4 suspending - delay (ms): 8783 Accessor #9 suspending - delay (ms): 8717 Accessor #3 suspending - delay (ms): 8783 Basically, the first thread from the pool starts 8 seconds (!!) after it has been scheduled. The total tolerance is set to 10 seconds, which means that, in some runs, we get dangerously close to that. There is no explanation as to why threads are delayed so much (note that it cannot be related to the handshaker trying to close, since that hasn't started yet). It's probably a pause caused by some other external factor (antivirus - this being on Windows?). I'll considering upping the threshold for this test.
23-04-2021
Assigning to Maurizio for now. Please re-assign as appropriate.
23-04-2021