Assertion error in shrinkStoreIfPossible

[adelel1]

Hello,

We have a customer of ours that when they run integration tests using h2 database, they get the following assertion error intermittently,

Caused by: java.lang.AssertionError: 95203328 != 65208320
at org.h2.mvstore.RandomAccessStore.shrinkStoreIfPossible(RandomAccessStore.java:679) ~[h2-2.2.224.jar:2.2.224]

Presumably this should never happen? Are you able to tell us what could give rise to this assertion error,

Thanks,

Full stack trace....

org.h2.jdbc.JdbcSQLNonTransientConnectionException: The database has been closed [90098-224]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:690) ~[h2-2.2.224.jar:2.2.224]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:489) ~[h2-2.2.224.jar:2.2.224]
at org.h2.message.DbException.get(DbException.java:212) ~[h2-2.2.224.jar:2.2.224]
at org.h2.engine.SessionLocal.getTransaction(SessionLocal.java:1610) ~[h2-2.2.224.jar:2.2.224]
at org.h2.engine.SessionLocal.getStatementSavepoint(SessionLocal.java:1620) ~[h2-2.2.224.jar:2.2.224]
at org.h2.engine.SessionLocal.setSavepoint(SessionLocal.java:858) ~[h2-2.2.224.jar:2.2.224]
at org.h2.command.Command.executeUpdate(Command.java:248) ~[h2-2.2.224.jar:2.2.224]
at org.h2.jdbc.JdbcConnection.rollbackInternal(JdbcConnection.java:1441) ~[h2-2.2.224.jar:2.2.224]
at org.h2.jdbc.JdbcConnection.rollback(JdbcConnection.java:516) ~[h2-2.2.224.jar:2.2.224]
at com.zaxxer.hikari.pool.ProxyConnection.rollback(ProxyConnection.java:374) ~[HikariCP-3.3.1.jar:?]
at com.zaxxer.hikari.pool.HikariProxyConnection.rollback(HikariProxyConnection.java) ~[HikariCP-3.3.1.jar:?]
at net.corda.nodeapi.internal.persistence.DatabaseTransaction.rollback(DatabaseTransaction.kt:105) ~[corda-node-api-4.11.3.jar:?]
at net.corda.node.services.statemachine.ActionExecutorImpl.executeRollbackTransaction(ActionExecutorImpl.kt:233) ~[corda-node-4.11.3.jar:?]
at net.corda.node.services.statemachine.ActionExecutorImpl.executeAction(ActionExecutorImpl.kt:67) ~[corda-node-4.11.3.jar:?]
at net.corda.node.services.statemachine.TransitionExecutorImpl.executeTransition(TransitionExecutorImpl.kt:47) ~[corda-node-4.11.3.jar:?]
at net.corda.node.services.statemachine.interceptors.HospitalisingInterceptor.executeTransition(HospitalisingInterceptor.kt:39) ~[corda-node-4.11.3.jar:?]
at net.corda.node.services.statemachine.interceptors.DumpHistoryOnErrorInterceptor.executeTransition(DumpHistoryOnErrorInterceptor.kt:38) ~[corda-node-4.11.3.jar:?]
at net.corda.node.services.statemachine.FlowStateMachineImpl.processEvent(FlowStateMachineImpl.kt:195) ~[corda-node-4.11.3.jar:?]
at net.corda.node.services.statemachine.FlowStateMachineImpl.processEventImmediately(FlowStateMachineImpl.kt:301) ~[corda-node-4.11.3.jar:?]
at net.corda.node.services.statemachine.FlowStateMachineImpl.run(FlowStateMachineImpl.kt:390) ~[corda-node-4.11.3.jar:?]
at net.corda.node.services.statemachine.FlowStateMachineImpl.run(FlowStateMachineImpl.kt:79) ~[corda-node-4.11.3.jar:?]
at co.paralleluniverse.fibers.Fiber.run1(Fiber.java:1110) ~[quasar-core-0.7.16_r3.jar:0.7.16_r3]
at co.paralleluniverse.fibers.Fiber.exec(Fiber.java:806) ~[quasar-core-0.7.16_r3.jar:0.7.16_r3]
at co.paralleluniverse.fibers.RunnableFiberTask.doExec(RunnableFiberTask.java:103) ~[quasar-core-0.7.16_r3.jar:0.7.16_r3]
at co.paralleluniverse.fibers.RunnableFiberTask.run(RunnableFiberTask.java:94) ~[quasar-core-0.7.16_r3.jar:0.7.16_r3]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_382]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_382]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[?:1.8.0_382]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[?:1.8.0_382]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_382]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_382]
at net.corda.node.utilities.AffinityExecutor$ServiceAffinityExecutor$1$thread$1.run(AffinityExecutor.kt:63) ~[corda-node-4.11.3.jar:?]
Caused by: org.h2.mvstore.MVStoreException: java.lang.AssertionError: 95203328 != 65208320 [2.2.224/3]
at org.h2.mvstore.DataUtils.newMVStoreException(DataUtils.java:996) ~[h2-2.2.224.jar:2.2.224]
at org.h2.mvstore.FileStore.storeBuffer(FileStore.java:1529) ~[h2-2.2.224.jar:2.2.224]
at org.h2.mvstore.FileStore.lambda$serializeAndStore$3(FileStore.java:1432) ~[h2-2.2.224.jar:2.2.224]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_382]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_382]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_382]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_382]
at java.lang.Thread.run(Thread.java:750) [?:1.8.0_382]
Caused by: java.lang.AssertionError: 95203328 != 65208320
at org.h2.mvstore.RandomAccessStore.shrinkStoreIfPossible(RandomAccessStore.java:679) ~[h2-2.2.224.jar:2.2.224]
at org.h2.mvstore.RandomAccessStore.writeChunk(RandomAccessStore.java:377) ~[h2-2.2.224.jar:2.2.224]
at org.h2.mvstore.RandomAccessStore.writeChunk(RandomAccessStore.java:28) ~[h2-2.2.224.jar:2.2.224]
at org.h2.mvstore.FileStore.storeBuffer(FileStore.java:1524) ~[h2-2.2.224.jar:2.2.224]
at org.h2.mvstore.FileStore.lambda$serializeAndStore$3(FileStore.java:1432) ~[h2-2.2.224.jar:2.2.224]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[?:1.8.0_382]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[?:1.8.0_382]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_382]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_382]
at java.lang.Thread.run(Thread.java:750) ~[?:1.8.0_382]

[akellens]

I encountered the exact same issue, but I could not find a consistently reproducible scenario.
During our test runs, we do frequently reset the database, and my hunch is that this causes the exception to be thrown.

As a workaround I added AUTO_COMPACT_FILL_RATE=0 to our database configuration when executing the tests, and have not encountered the issue since.

[grandinj]

what is the full H2 URL you are using?

[akellens]

what is the full H2 URL you are using?

In our case it is MODE=MySQL;DATABASE_TO_UPPER=false;CASE_INSENSITIVE_IDENTIFIERS=TRUE;CIPHER=AES;AUTO_SERVER=TRUE;AUTO_COMPACT_FILL_RATE=0

[grandinj]

What kind of filesystem is this running against? And what platform?

Because it looks a little like maybe two things are trying to access that file at once.

[akellens]

What kind of filesystem is this running against? And what platform?
I encountered the issue when running the tests locally on my Mac (14.4.1).
The filesystem is APFS (Encrypted).

Because it looks a little like maybe two things are trying to access that file at once.
While I wouldn't exclude this option immediately, it seems rather unlikely in the case I encountered.

[hanohrs]

I'm facing the same issue too.

I've created a simple program with a high chance (~10%) to reproduce this issue.
My environment is MacBook Air (M1, 2020) 8GB RAM + 512GB SSD (encrypted APFS).
https://gist.github.com/hanohrs/10f25d621f18d00b697cda51e887cf0c

I saw the same issue on a EC2 Red Hat 8 instance.
I don't remember the filesystem right now.

I've seen this issue with H2 2.2.222 too, but never seen it with H2 2.2.220.

[grandinj]

Could one of you build from github source and check if the problem still occurs? we have made some recent fixes in this area.

[hanohrs]

The build from the master branch, 8115ca9, runs 100 times without this error.
I can say that this is practically fixed and acceptable to me.
(I can't upgrade to Java 11, though.)

But when I manually revert the change to RandomAccessStore made by 0cc81db (diff),
the error is thrown again.

I think the changeset 0cc81db fixes a performance problem, but does not fix a logical bug.
So I doubt that the head, 3115ca9, still has this bug.

[rPraml]

I see the same here (H2.2.224) since a few days
filesystem is ext4 (Ubuntu on Windows/WSL)
with OPTIMIZE_REUSE_RESULTS=0 (due bug #3894)