hiero-ledger / hiero-ledger/hiero-consensus-node
Unit tests still have Virtual Map related confusing exceptions in the logs
Nobody has claimed this yet.
- Dominant language
- Java
- Stars
- 407
- Forks
- 226
- Avg merge
- 3d 4h
- Merged PRs (30d)
- 210
Description
Unit tests still have Virtual Map-related confusing exceptions in the logs (see this GH run for example).
Something bad on the DB! is an exception thrown by the test classes to simulate disk/network failures on the teacher or learner side. It should've been fixed with #19942, but worth revisiting, as maybe a different log4j2 config caused the exceptions to re-appear:
18:48:49.075 262358 <work group test-learning-synchronizer: learner-task #2> Error while flushing VirtualMap
java.io.IOException: Something bad on the DB!
at com.swirlds.virtualmap@0.65.0-SNAPSHOT/com.swirlds.virtualmap.internal.reconnect.VirtualMapReconnectTestBase$BreakableDataSource.saveRecords(VirtualMapReconnectTestBase.java:259)
at com.swirlds.virtualmap@0.65.0-SNAPSHOT/com.swirlds.virtualmap.datasource.VirtualDataSource.saveRecords(VirtualDataSource.java:83)
at com.swirlds.virtualmap@0.65.0-SNAPSHOT/com.swirlds.virtualmap.VirtualMap.flush(VirtualMap.java:965)
at com.swirlds.virtualmap@0.65.0-SNAPSHOT/com.swirlds.virtualmap.VirtualMap.lambda$setupWithOriginalNode$0(VirtualMap.java:1256)
at com.swirlds.virtualmap@0.65.0-SNAPSHOT/com.swirlds.virtualmap.internal.pipeline.VirtualPipeline.pausePipelineAndExecute(VirtualPipeline.java:613)
at com.swirlds.virtualmap@0.65.0-SNAPSHOT/com.swirlds.virtualmap.internal.pipeline.VirtualPipeline.pausePipelineAndRun(VirtualPipeline.java:360)
at com.swirlds.virtualmap@0.65.0-SNAPSHOT/com.swirlds.virtualmap.VirtualMap.setupWithOriginalNode(VirtualMap.java:1242)
at com.swirlds.common@0.65.0-SNAPSHOT/com.swirlds.common.merkle.synchronization.task.LearnerPushTask.handleCustomRootInitialLesson(LearnerPushTask.java:115)
at com.swirlds.common@0.65.0-SNAPSHOT/com.swirlds.common.merkle.synchronization.task.LearnerPushTask.extractNodeFromLesson(LearnerPushTask.java:139)
at com.swirlds.common@0.65.0-SNAPSHOT/com.swirlds.common.merkle.synchronization.task.LearnerPushTask.run(LearnerPushTask.java:247)
at com.swirlds.common@0.65.0-SNAPSHOT/com.swirlds.common.threading.pool.StandardWorkGroup.lambda$execute$1(StandardWorkGroup.java:138)
at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
at java.base/java.lang.Thread.run(Thread.java:1583)
NPE in DataFileCollection is something new, though:
<merkledb: Store hashes #0> ERROR MerkleDbDataSource [closeFlushTest] Uncaught exception during storing hashes
java.lang.NullPointerException: Cannot invoke "java.util.concurrent.ConcurrentSkipListSet.remove(Object)" because "this.setOfNewFileIndexes" is null
at com.swirlds.merkledb@0.65.0-SNAPSHOT/com.swirlds.merkledb.files.DataFileCollection.endWriting(DataFileCollection.java:403)
at com.swirlds.merkledb@0.65.0-SNAPSHOT/com.swirlds.merkledb.files.MemoryIndexDiskKeyValueStore.endWriting(MemoryIndexDiskKeyValueStore.java:126)
at com.swirlds.merkledb@0.65.0-SNAPSHOT/com.swirlds.merkledb.MerkleDbDataSource.writeHashes(MerkleDbDataSource.java:1093)
at com.swirlds.merkledb@0.65.0-SNAPSHOT/com.swirlds.merkledb.MerkleDbDataSource.lambda$saveRecords$6(MerkleDbDataSource.java:473)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
at java.base/java.lang.Thread.run(Thread.java:1583)
<merkledb: Store hashes #0> ERROR MerkleDbDataSource [closeFlushTest] Uncaught exception during storing hashes
java.lang.NullPointerException: Cannot invoke "java.util.concurrent.ConcurrentSkipListSet.add(Object)" because "this.setOfNewFileIndexes" is null
at com.swirlds.merkledb@0.65.0-SNAPSHOT/com.swirlds.merkledb.files.DataFileCollection.newDataFile(DataFileCollection.java:665)
at com.swirlds.merkledb@0.65.0-SNAPSHOT/com.swirlds.merkledb.files.DataFileCollection.startWriting(DataFileCollection.java:345)
at com.swirlds.merkledb@0.65.0-SNAPSHOT/com.swirlds.merkledb.files.MemoryIndexDiskKeyValueStore.startWriting(MemoryIndexDiskKeyValueStore.java:97)
at com.swirlds.merkledb@0.65.0-SNAPSHOT/com.swirlds.merkledb.MerkleDbDataSource.writeHashes(MerkleDbDataSource.java:1075)
at com.swirlds.merkledb@0.65.0-SNAPSHOT/com.swirlds.merkledb.MerkleDbDataSource.lambda$saveRecords$6(MerkleDbDataSource.java:473)
at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
This field, setOfNewFileIndexes, is only used when TRACE logging level is enabled. The field is final, it’s initialized as:
private final ConcurrentSkipListSet<Integer> setOfNewFileIndexes = logger.isTraceEnabled() ? new ConcurrentSkipListSet<>() : null;
...and never changed after. All field access is guarded with isTraceEnabled() checks, too. For example, here is where the NPE is thrown:
if (logger.isTraceEnabled()) {
final DataFileMetadata metadata = dataReader.getMetadata();
setOfNewFileIndexes.remove(metadata.getIndex());
}
The only scenario how this NPE may be thrown is that logger level is changed on the fly. That is, when the DataFileCollection object is created, tracing is disabled, but then it gets enabled at some point.
The fix, if needed, can be trivial: just replace isTracingEnabled() with setOfNewFileIndexes checks for null.
Contributor guide
First steps
- Read the whole issue, then the project's contributing guide.
- Comment on the issue to say you are picking it up — it saves two people doing the same work.
- Fork the repository and make your change on a branch.
- Open a pull request that references the issue number.
Research direction
Inspect #19942 and the linked GitHub Actions run first. Trace DataFileCollection's setOfNewFileIndexes initialization and guarded accesses, then review the VirtualMapReconnectTestBase failure path and relevant log4j2 configuration. Done means the simulated failures and closeFlushTest no longer emit confusing or unexpected exceptions under the tested logging settings.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- java
- Domain
- databases, testing-qa
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 48/100