Details
-
Bug
-
Status: Resolved
-
Normal
-
Resolution: Fixed
-
None
-
Code - Bug - Unclear Impact
-
Normal
-
Normal
-
Unit Test
-
All
-
None
-
Description
An internal CI system is failing BinLogTest somewhat frequently under JDK11. Configuration was recently changed to reduce the number of cores the tests run with, however it is reproducible on an 8 core laptop.
[junit-timeout] OpenJDK 64-Bit Server VM warning: Option UseConcMarkSweepGC was deprecated in version 9.0 and will likely be removed in a future release. [junit-timeout] Testsuite: org.apache.cassandra.utils.binlog.BinLogTest [Junit-timeout] WARNING: An illegal reflective access operation has occurred [junit-timeout] WARNING: Illegal reflective access by net.openhft.chronicle.core.Jvm (file:/.../lib/chronicle-core-1.16.4.jar) to field java.nio.Bits.RESERVED_MEMORY [junit-timeout] WARNING: Please consider reporting this to the maintainers of net.openhft.chronicle.core.Jvm [junit-timeout] WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations [junit-timeout] WARNING: All illegal access operations will be denied in a future release [junit-timeout] Testsuite: org.apache.cassandra.utils.binlog.BinLogTest Tests run: 13, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 13.895 sec [junit-timeout] [junit-timeout] Testcase: testPutAfterStop(org.apache.cassandra.utils.binlog.BinLogTest): FAILED [junit-timeout] expected:<null> but was:<org.apache.cassandra.utils.binlog.BinLog$1@5ed190be> [junit-timeout] junit.framework.AssertionFailedError: expected:<null> but was:<org.apache.cassandra.utils.binlog.BinLog$1@5ed190be> [junit-timeout] at org.apache.cassandra.utils.binlog.BinLogTest.testPutAfterStop(BinLogTest.java:431) [junit-timeout] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [junit-timeout] at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) [junit-timeout] at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [junit-timeout] [junit-timeout] [junit-timeout] Test org.apache.cassandra.utils.binlog.BinLogTest FAILED
There's also a different failure under JDK8
junit-timeout] Testsuite: org.apache.cassandra.utils.binlog.BinLogTest [junit-timeout] Testsuite: org.apache.cassandra.utils.binlog.BinLogTest Tests run: 13, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 15.273 sec [junit-timeout] [junit-timeout] Testcase: testBinLogStartStop(org.apache.cassandra.utils.binlog.BinLogTest): FAILED [junit-timeout] expected:<2> but was:<0> [junit-timeout] junit.framework.AssertionFailedError: expected:<2> but was:<0> [junit-timeout] at org.apache.cassandra.utils.binlog.BinLogTest.testBinLogStartStop(BinLogTest.java:172) [junit-timeout] [junit-timeout] [junit-timeout] Test org.apache.cassandra.utils.binlog.BinLogTest FAILED
Reproducer
PASSED=0; time { while ant testclasslist -Dtest.classlistprefix=unit -Dtest.classlistfile=<(echo org/apache/cassandra/utils/binlog/BinLogTest.java); do PASSED=$((PASSED+1)); echo PASSED $PASSED; done }; echo FAILED after $PASSED runs.
In the last four attempts it has taken 31, 38, 27 and 10 rounds respectively under JDK11 and took 51 under JDK8 (about 15 minutes).
I have not tried running in a cpu-limited container or anything like that yet.
Additionally, this went past in the logs a few times (under JDK11). No idea if it's just an artifact of weird test setup, or something more serious.
[junit-timeout] WARNING: Please consider reporting this to the maintainers of net.openhft.chronicle.core.Jvm [junit-timeout] WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations [junit-timeout] WARNING: All illegal access operations will be denied in a future release [junit-timeout] Testsuite: org.apache.cassandra.utils.binlog.BinLogTest Tests run: 13, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 12.839 sec [junit-timeout] [junit-timeout] java.lang.Throwable: 1e53135d-main creation ref-count=1 [junit-timeout] at net.openhft.chronicle.core.ReferenceCounter.newRefCountHistory(ReferenceCounter.java:45) [junit-timeout] at net.openhft.chronicle.core.ReferenceCounter.<init>(ReferenceCounter.java:35) [junit-timeout] at net.openhft.chronicle.core.ReferenceCounter.onReleased(ReferenceCounter.java:40) [junit-timeout] at net.openhft.chronicle.bytes.AbstractBytes.<init>(AbstractBytes.java:38) [junit-timeout] at net.openhft.chronicle.bytes.MappedBytes.<init>(MappedBytes.java:59) [junit-timeout] at net.openhft.chronicle.bytes.MappedBytes.<init>(MappedBytes.java:55) [junit-timeout] at net.openhft.chronicle.bytes.MappedBytes.mappedBytes(MappedBytes.java:113) [junit-timeout] at net.openhft.chronicle.queue.impl.single.SingleChronicleQueueStore.bytes(SingleChronicleQueueStore.java:358) [junit-timeout] at net.openhft.chronicle.queue.impl.single.SingleChronicleQueueExcerpts$StoreTailer.resetWires(SingleChronicleQueueExcerpts.java:1702) [junit-timeout] at net.openhft.chronicle.queue.impl.single.SingleChronicleQueueExcerpts$StoreTailer.cycle(SingleChronicleQueueExcerpts.java:1907) [junit-timeout] at net.openhft.chronicle.queue.impl.single.SingleChronicleQueueExcerpts$StoreTailer.toStart(SingleChronicleQueueExcerpts.java:1614) [junit-timeout] at net.openhft.chronicle.queue.impl.single.SingleChronicleQueue.createTailer(SingleChronicleQueue.java:401) [junit-timeout] at org.apache.cassandra.utils.binlog.BinLogTest.readBinLogRecords(BinLogTest.java:495) [junit-timeout] at org.apache.cassandra.utils.binlog.BinLogTest.testCleanupOnOversize(BinLogTest.java:407) ... [junit-timeout] java.lang.Throwable: 1e53135d-main Reserve ref-count=2 [junit-timeout] at net.openhft.chronicle.core.ReferenceCounter.recordResevation(ReferenceCounter.java:66) [junit-timeout] at net.openhft.chronicle.core.ReferenceCounter.reserve(ReferenceCounter.java:59) [junit-timeout] at net.openhft.chronicle.bytes.AbstractBytes.reserve(AbstractBytes.java:464) [junit-timeout] at net.openhft.chronicle.core.ReferenceCounted.tryReserve(ReferenceCounted.java:81) [junit-timeout] at net.openhft.chronicle.queue.impl.single.SingleChronicleQueueStore.writeEOF(SingleChronicleQueueStore.java:461) [junit-timeout] at net.openhft.chronicle.queue.impl.single.SingleChronicleQueueExcerpts$StoreTailer.checkMoveToNextCycle(SingleChronicleQueueExcerpts.java:1437) [junit-timeout] at net.openhft.chronicle.queue.impl.single.SingleChronicleQueueExcerpts$StoreTailer.inACycleNone(SingleChronicleQueueExcerpts.java:1416) [junit-timeout] at net.openhft.chronicle.queue.impl.single.SingleChronicleQueueExcerpts$StoreTailer.inACycle(SingleChronicleQueueExcerpts.java:1356) [junit-timeout] at net.openhft.chronicle.queue.impl.single.SingleChronicleQueueExcerpts$StoreTailer.readingDocument(SingleChronicleQueueExcerpts.java:1168) [junit-timeout] at net.openhft.chronicle.queue.impl.single.SingleChronicleQueueExcerpts$StoreTailer.readDocument(SingleChronicleQueueExcerpts.java:1096) [junit-timeout] at org.apache.cassandra.utils.binlog.BinLogTest.readBinLogRecords(BinLogTest.java:498) [junit-timeout] at org.apache.cassandra.utils.binlog.BinLogTest.testCleanupOnOversize(BinLogTest.java:407) ... [junit-timeout] java.lang.Throwable: 1e53135d-main Release ref-count=1 [junit-timeout] at net.openhft.chronicle.core.ReferenceCounter.recordRelease(ReferenceCounter.java:88) [junit-timeout] at net.openhft.chronicle.core.ReferenceCounter.release(ReferenceCounter.java:79) [junit-timeout] at net.openhft.chronicle.bytes.AbstractBytes.release(AbstractBytes.java:469) [junit-timeout] at net.openhft.chronicle.queue.impl.single.SingleChronicleQueueStore.writeEOF(SingleChronicleQueueStore.java:463) [junit-timeout] at net.openhft.chronicle.queue.impl.single.SingleChronicleQueueExcerpts$StoreTailer.checkMoveToNextCycle(SingleChronicleQueueExcerpts.java:1437) [junit-timeout] at net.openhft.chronicle.queue.impl.single.SingleChronicleQueueExcerpts$StoreTailer.inACycleNone(SingleChronicleQueueExcerpts.java:1416) [junit-timeout] at net.openhft.chronicle.queue.impl.single.SingleChronicleQueueExcerpts$StoreTailer.inACycle(SingleChronicleQueueExcerpts.java:1356) [junit-timeout] at net.openhft.chronicle.queue.impl.single.SingleChronicleQueueExcerpts$StoreTailer.readingDocument(SingleChronicleQueueExcerpts.java:1168) [junit-timeout] at net.openhft.chronicle.queue.impl.single.SingleChronicleQueueExcerpts$StoreTailer.readDocument(SingleChronicleQueueExcerpts.java:1096) [junit-timeout] at org.apache.cassandra.utils.binlog.BinLogTest.readBinLogRecords(BinLogTest.java:498) [junit-timeout] at org.apache.cassandra.utils.binlog.BinLogTest.testCleanupOnOversize(BinLogTest.java:407) ... [junit-timeout] java.lang.Throwable: 1e53135d-main Release ref-count=0 [junit-timeout] at net.openhft.chronicle.core.ReferenceCounter.recordRelease(ReferenceCounter.java:88) [junit-timeout] at net.openhft.chronicle.core.ReferenceCounter.release(ReferenceCounter.java:79) [junit-timeout] at net.openhft.chronicle.bytes.AbstractBytes.release(AbstractBytes.java:469) [junit-timeout] at net.openhft.chronicle.queue.impl.single.SingleChronicleQueueExcerpts$StoreTailer.close(SingleChronicleQueueExcerpts.java:1117) [junit-timeout] at net.openhft.chronicle.queue.impl.single.SingleChronicleQueue.lambda$close$4(SingleChronicleQueue.java:537) [junit-timeout] at java.base/java.util.WeakHashMap.forEach(WeakHashMap.java:1026) [junit-timeout] at net.openhft.chronicle.queue.impl.single.SingleChronicleQueue.close(SingleChronicleQueue.java:537) [junit-timeout] at org.apache.cassandra.utils.binlog.BinLogTest.readBinLogRecords(BinLogTest.java:506) [junit-timeout] at org.apache.cassandra.utils.binlog.BinLogTest.testCleanupOnOversize(BinLogTest.java:407) ... [junit-timeout] java.lang.Throwable: 1e53135d-main/queue-thread-local-cleaner-daemon Release ref-count=0 [junit-timeout] at net.openhft.chronicle.core.ReferenceCounter.recordRelease(ReferenceCounter.java:88) [junit-timeout] at net.openhft.chronicle.core.ReferenceCounter.release(ReferenceCounter.java:74) [junit-timeout] at net.openhft.chronicle.bytes.AbstractBytes.release(AbstractBytes.java:469) [junit-timeout] at net.openhft.chronicle.queue.impl.single.StoreComponentReferenceHandler.processWireQueue(StoreComponentReferenceHandler.java:74) [junit-timeout] at net.openhft.chronicle.queue.impl.single.StoreComponentReferenceHandler.lambda$static$0(StoreComponentReferenceHandler.java:43) [junit-timeout] at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [junit-timeout] at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) [junit-timeout] at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [junit-timeout] at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [junit-timeout] at java.base/java.lang.Thread.run(Thread.java:834)
