hiero-ledger / hiero-ledger/hiero-consensus-node

Unit tests still have Virtual Map related confusing exceptions in the logs

Open
#21,027 0 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Platform Test Development
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

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. 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

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.