java/lang/ref/CleanerTest.java

Observed this test fails intermittently with:

test CleanerTest.testRefSubtypes(): failure
java.lang.AssertionError: The reference to the Cleanable should have been freed expected [true] but found [false]

Tested with JDK9 promotion build 100:
java version "9-ea"
Java(TM) SE Runtime Environment (build 9-ea+100-2016-01-07-021452.javare.4235)
Java HotSpot(TM) 64-Bit Server VM (build 9-ea+100-2016-01-07-021452.javare.4235, mixed mode)


See log:
#section:testng
----------messages:(3/295)----------
command: testng -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -Xbootclasspath/a:. -verbose:gc -Xmx4m CleanerTest
reason: User specified action: run testng/othervm -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -Xbootclasspath/a:. -verbose:gc -Xmx4m CleanerTest
elapsed time (seconds): 1.186
----------System.out:(117/7004)----------
#0: [GC pause (G1 Evacuation Pause) (young) 1024K->763K(4096K), 0.0026955 secs]
#1: [GC pause (G1 Evacuation Pause) (young) 1787K->967K(4096K), 0.0067572 secs]
#2: [GC pause (G1 Evacuation Pause) (young) 1991K->1122K(4096K), 0.0021678 secs]
#3: [GC pause (G1 Evacuation Pause) (young) 2146K->1105K(4096K), 0.0019537 secs]
#4: [GC pause (G1 Evacuation Pause) (young) 2129K->1173K(4096K), 0.0512073 secs]
#5: [GC pause (G1 Evacuation Pause) (young) 2197K->1311K(4096K), 0.0016903 secs]
#6: [GC pause (G1 Evacuation Pause) (young) 2335K->1496K(4096K), 0.0028746 secs]
#7: [GC pause (G1 Evacuation Pause) (young) 2520K->1546K(4096K), 0.0016530 secs]
#8: [GC pause (G1 Evacuation Pause) (young)-- 2570K->2231K(4096K), 0.0026848 secs]
[TestNG] Running:
  java/lang/ref/CleanerTest.java

#9: [GC pause (G1 Evacuation Pause) (young) (initial-mark)-- 3255K->3255K(4096K), 0.0045818 secs]
#10: [GC concurrent-mark-start]
#11: [GC pause (G1 Evacuation Pause) (young) 3255K->3255K(4096K), 0.0020492 secs]
#12: [Full GC (Allocation Failure) 3255K->1438K(4096K), 0.0099214 secs]
#10: [GC concurrent-mark-abort]
Case: java.lang.ref.PhantomReference, expect: EV_CLEAN, events: [EV_UNREF], throwEx: false
#13: [Full GC (Last ditch collection) 2007K->1386K(4096K), 0.0228410 secs]
 Cleanable cleaned in cycle: 1
#14: [Full GC (Last ditch collection) 1484K->1352K(4096K), 0.0093812 secs]
 Cleanable cleaned in cycle: 1
Case: java.lang.ref.PhantomReference, expect: EV_CLEAN, events: [EV_CLEAN], throwEx: false
 Cleanable cleaned in cycle: 0
#15: [Full GC (Last ditch collection) 1397K->1334K(4096K), 0.0091754 secs]
 Cleanable cleaned in cycle: 1
Case: java.lang.ref.PhantomReference, expect: EV_CLEAN, events: [EV_CLEAN, EV_UNREF], throwEx: false
 Cleanable cleaned in cycle: 0
#16: [Full GC (Last ditch collection) 1365K->1333K(4096K), 0.0093547 secs]
 Cleanable cleaned in cycle: 1
Case: java.lang.ref.PhantomReference, expect: EV_CLEAN, events: [EV_UNREF, EV_CLEAN], throwEx: false
 Cleanable cleaned in cycle: 0
#17: [Full GC (Last ditch collection) 1338K->1333K(4096K), 0.0132911 secs]
 Cleanable cleaned in cycle: 1
#18: [Full GC (Last ditch collection) 1337K->1333K(4096K), 0.0119658 secs]
 Cleanable cleaned in cycle: 1
test CleanerTest.testCleanableActions(): success
#19: [Full GC (System.gc()) 1371K->1341K(4096K), 0.0088952 secs]
#20: [Full GC (System.gc()) 1341K->1341K(4096K), 0.0093265 secs]
test CleanerTest.testCleanerTermination(): success
Case: java.lang.ref.PhantomReference, expect: EV_CLEAN, events: [EV_UNREF], throwEx: false
#21: [Full GC (Last ditch collection) 1426K->1338K(4096K), 0.0090826 secs]
 Cleanable cleaned in cycle: 1
#22: [Full GC (Last ditch collection) 1340K->1337K(4096K), 0.0093840 secs]
 Cleanable cleaned in cycle: 1
Case: java.lang.ref.WeakReference, expect: EV_CLEAN, events: [EV_UNREF], throwEx: false
#23: [Full GC (Last ditch collection) 1396K->1338K(4096K), 0.0117849 secs]
 Cleanable cleaned in cycle: 1
#24: [Full GC (Last ditch collection) 1340K->1338K(4096K), 0.0087296 secs]
 Cleanable cleaned in cycle: 1
Case: java.lang.ref.SoftReference, expect: EV_CLEAN, events: [EV_UNREF], throwEx: false
#25: [Full GC (Last ditch collection) 1399K->1339K(4096K), 0.0083857 secs]
 Cleanable cleaned in cycle: 1
#26: [Full GC (Last ditch collection) 1341K->1339K(4096K), 0.0075489 secs]
 Cleanable cleaned in cycle: 1
Case: java.lang.ref.PhantomReference, expect: EV_CLEAN, events: [EV_CLEAN], throwEx: false
 Cleanable cleaned in cycle: 0
#27: [Full GC (Last ditch collection) 1359K->1340K(4096K), 0.0097007 secs]
#28: [Full GC (Last ditch collection) 1342K->1339K(4096K), 0.0084111 secs]
#29: [Full GC (Last ditch collection) 1342K->1339K(4096K), 0.0105368 secs]
 Cleanable not cleaned
test CleanerTest.testRefSubtypes(): failure
java.lang.AssertionError: The reference to the Cleanable should have been freed expected [true] but found [false]
at org.testng.Assert.fail(Assert.java:94)
at org.testng.Assert.failNotEquals(Assert.java:494)
at org.testng.Assert.assertTrue(Assert.java:42)
at CleanerTest.verify(CleanerTest.java:223)
at CleanerTest.generateCases(CleanerTest.java:181)
at CleanerTest.generateCasesInternal(CleanerTest.java:143)
at CleanerTest.testRefSubtypes(CleanerTest.java:111)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:520)
at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:84)
at org.testng.internal.Invoker.invokeMethod(Invoker.java:714)
at org.testng.internal.Invoker.invokeTestMethod(Invoker.java:901)
at org.testng.internal.Invoker.invokeTestMethods(Invoker.java:1231)
at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:127)
at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:111)
at org.testng.TestRunner.privateRun(TestRunner.java:767)
at org.testng.TestRunner.run(TestRunner.java:617)
at org.testng.SuiteRunner.runTest(SuiteRunner.java:334)
at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:329)
at org.testng.SuiteRunner.privateRun(SuiteRunner.java:291)
at org.testng.SuiteRunner.run(SuiteRunner.java:240)
at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:52)
at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:86)
at org.testng.TestNG.runSuitesSequentially(TestNG.java:1224)
at org.testng.TestNG.runSuitesLocally(TestNG.java:1149)
at org.testng.TestNG.run(TestNG.java:1057)
at com.sun.javatest.regtest.TestNGAction$TestNGRunner.main(TestNGAction.java:163)
at com.sun.javatest.regtest.TestNGAction$TestNGRunner.main(TestNGAction.java:147)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:520)
at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:92)
at java.lang.Thread.run(Thread.java:804)
#30: [Full GC (Last ditch collection) 1466K->1352K(4096K), 0.0103050 secs]
 Cleanable cleaned in cycle: 1
test CleanerTest.testReferentNotAvailable(): success
#31: [Full GC (System.gc()) 1406K->1352K(4096K), 0.0095465 secs]
test CleanerTest.testWeakKey(): success

===============================================
java/lang/ref/CleanerTest.java
Total tests run: 5, Failures: 1, Skips: 0
===============================================

#32: [GC pause (G1 Evacuation Pause) (young) (initial-mark) 2376K->1822K(4096K), 0.0023782 secs]
#33: [GC concurrent-root-region-scan-start]
#33: [GC concurrent-root-region-scan-end, 0.0005729 secs]
#33: [GC concurrent-mark-start]
#33: [GC concurrent-mark-end, 0.0020209 secs]
#33: [GC remark, 0.0018800 secs]
#33: [GC cleanup 1944K->1944K(4096K), 0.0002697 secs]
----------System.err:(14/796)----------
java.lang.Exception: failures: 1
at com.sun.javatest.regtest.TestNGAction$TestNGRunner.main(TestNGAction.java:166)
at com.sun.javatest.regtest.TestNGAction$TestNGRunner.main(TestNGAction.java:147)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:520)
at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:92)
at java.lang.Thread.run(Thread.java:804)

JavaTest Message: Test threw exception: java.lang.Exception: failures: 1