H2 2.3.232 database corruption #322
Description
Opening this issue here to track the H2 corruption analysis progress.
Upon analyzing issue #306, it appears that during the batch insertion of data into the OwlPlug FileStat or Plugin tables, the data can disappear during the process. This behavior is non-deterministic, as with the same data, it fails at a different step during the insertion. With a large number of lines to insert (+5.000 in FileStat table), the issue can be reproduced almost every time during OwlPLug execution.
The H2 database is an embedded file-based SQL store. Hibernate manages the opening and closing of connections to the database. The issue seems to appear between 2 connections (between the closing and opening of a new one)
The data is inserted without any issues, and the connection is successfully closed.
When a connection is reopened, the table where data was previously inserted is empty. The table is still here, but appears empty. Sometimes, the table is not empty, but some rows are missing. As the FileStat table contains a FK to itself, it often leads to a Referential integrity constraint violation as the parent data has been deleted when inserting the child data.
The problem does not seem OS-dependent as it has been reproduced and reported on Windows 10, macOS, and Ubuntu.
H2 Logs TRACE=2
2025-05-28 00:40:03.878943+02:00 database: opening C:/Users/Arthur/.owlplug/owlplug (build 232)
2025-05-28 00:40:03.883942+02:00 database: opened C:/Users/Arthur/.owlplug/owlplug
2025-05-28 00:40:03.884943+02:00 database: connecting session #3 to C:/Users/Arthur/.owlplug/owlplug
2025-05-28 00:40:03.884943+02:00 jdbc[3]:
/*SQL */SET TRACE_LEVEL_FILE 2;
2025-05-28 00:40:03.884943+02:00 jdbc[3]:
/**/Connection conn1670 = DriverManager.getConnection("jdbc:h2:file:~/.owlplug/owlplug;TRACE_LEVEL_FILE=2", "SA", "");
2025-05-28 00:40:03.884943+02:00 jdbc[3]:
/*SQL l:354 #:1*/select fs1_0.id,c1_0.parent_id,c1_0.id,c1_0.length,c1_0.name,c1_0.parent_path,c1_0.path,fs1_0.length,fs1_0.name,p1_0.id,p1_0.length,p1_0.name,p1_0.parent_id,p1_0.parent_path,p1_0.path,fs1_0.parent_path,fs1_0.path from file_stat fs1_0 left join file_stat c1_0 on fs1_0.id=c1_0.parent_id left join file_stat p1_0 on p1_0.id=fs1_0.parent_id where fs1_0.id=? {1: CAST(12299 AS BIGINT)};
2025-05-28 00:40:03.884943+02:00 jdbc[3]:
/*SQL l:354 #:1*/select fs1_0.id,c1_0.parent_id,c1_0.id,c1_0.length,c1_0.name,c1_0.parent_path,c1_0.path,fs1_0.length,fs1_0.name,p1_0.id,p1_0.length,p1_0.name,p1_0.parent_id,p1_0.parent_path,p1_0.path,fs1_0.parent_path,fs1_0.path from file_stat fs1_0 left join file_stat c1_0 on fs1_0.id=c1_0.parent_id left join file_stat p1_0 on p1_0.id=fs1_0.parent_id where fs1_0.id=? {1: CAST(2391 AS BIGINT)};
2025-05-28 00:40:03.884943+02:00 jdbc[3]:
/*SQL l:354 #:2*/select fs1_0.id,c1_0.parent_id,c1_0.id,c1_0.length,c1_0.name,c1_0.parent_path,c1_0.path,fs1_0.length,fs1_0.name,p1_0.id,p1_0.length,p1_0.name,p1_0.parent_id,p1_0.parent_path,p1_0.path,fs1_0.parent_path,fs1_0.path from file_stat fs1_0 left join file_stat c1_0 on fs1_0.id=c1_0.parent_id left join file_stat p1_0 on p1_0.id=fs1_0.parent_id where fs1_0.id=? {1: CAST(1 AS BIGINT)};
2025-05-28 00:40:03.885943+02:00 jdbc[3]:
/*SQL l:74 #:1*/SELECT SETTING_VALUE FROM INFORMATION_SCHEMA.SETTINGS WHERE SETTING_NAME=? {1: 'QUERY_TIMEOUT'};
2025-05-28 00:40:03.885943+02:00 jdbc[3]:
/*SQL l:121 #:13*/select c1_0.parent_id,c1_0.id,c1_0.length,c1_0.name,c1_0.parent_path,c1_0.path from file_stat c1_0 where c1_0.parent_id=? {1: CAST(2 AS BIGINT)};
2025-05-28 00:40:03.885943+02:00 jdbc[3]:
/*SQL l:121 #:5*/select c1_0.parent_id,c1_0.id,c1_0.length,c1_0.name,c1_0.parent_path,c1_0.path from file_stat c1_0 where c1_0.parent_id=? {1: CAST(293 AS BIGINT)};
2025-05-28 00:40:03.888942+02:00 jdbc[3]:
/*SQL l:121 #:67 t:2*/select c1_0.parent_id,c1_0.id,c1_0.length,c1_0.name,c1_0.parent_path,c1_0.path from file_stat c1_0 where c1_0.parent_id=? {1: CAST(2392 AS BIGINT)};
2025-05-28 00:40:03.888942+02:00 jdbc[3]:
/*SQL #:1*/select next value for file_stat_seq;
2025-05-28 00:40:03.890942+02:00 jdbc[3]:
/*SQL l:86 #:1*/insert into file_stat (length,name,parent_id,parent_path,path,id) values (?,?,?,?,?,?) {1: CAST(3570 AS BIGINT), 2: 'Bio Soup.nmsv', 3: CAST(12299 AS BIGINT), 4: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences', 5: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences/Bio Soup.nmsv', 6: CAST(12300 AS BIGINT)};
2025-05-28 00:40:03.890942+02:00 jdbc[3]:
/*SQL l:86 #:1*/insert into file_stat (length,name,parent_id,parent_path,path,id) values (?,?,?,?,?,?) {1: CAST(3780 AS BIGINT), 2: 'Long story.nmsv', 3: CAST(12299 AS BIGINT), 4: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences', 5: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences/Long story.nmsv', 6: CAST(12301 AS BIGINT)};
2025-05-28 00:40:03.890942+02:00 jdbc[3]:
/*SQL l:86 #:1*/insert into file_stat (length,name,parent_id,parent_path,path,id) values (?,?,?,?,?,?) {1: CAST(3984 AS BIGINT), 2: 'Shakin Monster.nmsv', 3: CAST(12299 AS BIGINT), 4: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences', 5: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences/Shakin Monster.nmsv', 6: CAST(12302 AS BIGINT)};
2025-05-28 00:40:03.890942+02:00 jdbc[3]:
/*SQL l:86 #:1*/insert into file_stat (length,name,parent_id,parent_path,path,id) values (?,?,?,?,?,?) {1: CAST(2038 AS BIGINT), 2: 'Long story.ksd', 3: CAST(12299 AS BIGINT), 4: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences', 5: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences/Long story.ksd', 6: CAST(12303 AS BIGINT)};
2025-05-28 00:40:03.890942+02:00 jdbc[3]:
/*SQL l:86 #:1*/insert into file_stat (length,name,parent_id,parent_path,path,id) values (?,?,?,?,?,?) {1: CAST(2200 AS BIGINT), 2: 'Shakin Monster.ksd', 3: CAST(12299 AS BIGINT), 4: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences', 5: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences/Shakin Monster.ksd', 6: CAST(12304 AS BIGINT)};
2025-05-28 00:40:03.890942+02:00 jdbc[3]:
/*SQL l:86 #:1*/insert into file_stat (length,name,parent_id,parent_path,path,id) values (?,?,?,?,?,?) {1: CAST(3618 AS BIGINT), 2: '3 Elements.nmsv', 3: CAST(12299 AS BIGINT), 4: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences', 5: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences/3 Elements.nmsv', 6: CAST(12305 AS BIGINT)};
2025-05-28 00:40:03.890942+02:00 jdbc[3]:
/*SQL l:86 #:1*/insert into file_stat (length,name,parent_id,parent_path,path,id) values (?,?,?,?,?,?) {1: CAST(3898 AS BIGINT), 2: 'Metal Parts.nmsv', 3: CAST(12299 AS BIGINT), 4: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences', 5: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences/Metal Parts.nmsv', 6: CAST(12306 AS BIGINT)};
2025-05-28 00:40:03.890942+02:00 jdbc[3]:
/*SQL l:86 #:1*/insert into file_stat (length,name,parent_id,parent_path,path,id) values (?,?,?,?,?,?) {1: CAST(3735 AS BIGINT), 2: 'Space Fluter.nmsv', 3: CAST(12299 AS BIGINT), 4: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences', 5: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences/Space Fluter.nmsv', 6: CAST(12307 AS BIGINT)};
2025-05-28 00:40:03.891943+02:00 jdbc[3]:
/*SQL l:86 #:1*/insert into file_stat (length,name,parent_id,parent_path,path,id) values (?,?,?,?,?,?) {1: CAST(3770 AS BIGINT), 2: 'Birth of the robo 2.nmsv', 3: CAST(12299 AS BIGINT), 4: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences', 5: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences/Birth of the robo 2.nmsv', 6: CAST(12308 AS BIGINT)};
2025-05-28 00:40:03.891943+02:00 jdbc[3]:
/*SQL l:86 #:1*/insert into file_stat (length,name,parent_id,parent_path,path,id) values (?,?,?,?,?,?) {1: CAST(1869 AS BIGINT), 2: 'Bio Soup.ksd', 3: CAST(12299 AS BIGINT), 4: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences', 5: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences/Bio Soup.ksd', 6: CAST(12309 AS BIGINT)};
2025-05-28 00:40:03.891943+02:00 jdbc[3]:
/*SQL l:86 #:1*/insert into file_stat (length,name,parent_id,parent_path,path,id) values (?,?,?,?,?,?) {1: CAST(2127 AS BIGINT), 2: 'Metal Parts.ksd', 3: CAST(12299 AS BIGINT), 4: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences', 5: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences/Metal Parts.ksd', 6: CAST(12310 AS BIGINT)};
2025-05-28 00:40:03.891943+02:00 jdbc[3]:
/*SQL l:86 #:1*/insert into file_stat (length,name,parent_id,parent_path,path,id) values (?,?,?,?,?,?) {1: CAST(1927 AS BIGINT), 2: '3 Elements.ksd', 3: CAST(12299 AS BIGINT), 4: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences', 5: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences/3 Elements.ksd', 6: CAST(12311 AS BIGINT)};
2025-05-28 00:40:03.891943+02:00 jdbc[3]:
/*SQL l:86 #:1*/insert into file_stat (length,name,parent_id,parent_path,path,id) values (?,?,?,?,?,?) {1: CAST(2020 AS BIGINT), 2: 'Birth of the robo 2.ksd', 3: CAST(12299 AS BIGINT), 4: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences', 5: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences/Birth of the robo 2.ksd', 6: CAST(12312 AS BIGINT)};
2025-05-28 00:40:03.891943+02:00 jdbc[3]:
/*SQL l:86 #:1*/insert into file_stat (length,name,parent_id,parent_path,path,id) values (?,?,?,?,?,?) {1: CAST(2000 AS BIGINT), 2: 'Space Fluter.ksd', 3: CAST(12299 AS BIGINT), 4: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences', 5: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences/Space Fluter.ksd', 6: CAST(12313 AS BIGINT)};
2025-05-28 00:40:03.891943+02:00 jdbc[3]:
/*SQL l:80 #:1*/update file_stat set length=?,name=?,parent_id=?,parent_path=?,path=? where id=? {1: CAST(40536 AS BIGINT), 2: 'Micemincer Sequences', 3: CAST(2392 AS BIGINT), 4: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome', 5: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Micemincer Sequences', 6: CAST(12299 AS BIGINT)};
2025-05-28 00:40:03.892943+02:00 jdbc[3]:
/*SQL */COMMIT;
2025-05-28 00:40:03.892943+02:00 jdbc[3]:
/*SQL */COMMIT;
2025-05-28 00:40:03.892943+02:00 database: disconnecting session #3
2025-05-28 00:40:03.892943+02:00 database: closing C:/Users/Arthur/.owlplug/owlplug
2025-05-28 00:40:03.900945+02:00 database: closed
2025-05-28 00:40:03.900945+02:00 database: disconnected session #3
2025-05-28 00:40:03.902943+02:00 database: opening C:/Users/Arthur/.owlplug/owlplug (build 232)
2025-05-28 00:40:03.908943+02:00 database: opened C:/Users/Arthur/.owlplug/owlplug
2025-05-28 00:40:03.908943+02:00 database: connecting session #3 to C:/Users/Arthur/.owlplug/owlplug
2025-05-28 00:40:03.908943+02:00 jdbc[3]:
/*SQL */SET TRACE_LEVEL_FILE 2;
2025-05-28 00:40:03.908943+02:00 jdbc[3]:
/**/Connection conn1671 = DriverManager.getConnection("jdbc:h2:file:~/.owlplug/owlplug;TRACE_LEVEL_FILE=2", "SA", "");
2025-05-28 00:40:03.947942+02:00 jdbc[3]:
/*SQL l:124 t:38*/select fs1_0.id,fs1_0.length,fs1_0.name,fs1_0.parent_id,fs1_0.parent_path,fs1_0.path from file_stat fs1_0 where fs1_0.path=? {1: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/MS_MASSIVE 1.3+'};
2025-05-28 00:40:03.948942+02:00 jdbc[3]:
/*SQL l:74 #:1*/SELECT SETTING_VALUE FROM INFORMATION_SCHEMA.SETTINGS WHERE SETTING_NAME=? {1: 'QUERY_TIMEOUT'};
2025-05-28 00:40:03.948942+02:00 jdbc[3]:
/*SQL */COMMIT;
2025-05-28 00:40:03.948942+02:00 jdbc[3]:
/*SQL */COMMIT;
2025-05-28 00:40:03.948942+02:00 database: disconnecting session #3
2025-05-28 00:40:03.948942+02:00 database: closing C:/Users/Arthur/.owlplug/owlplug
2025-05-28 00:40:04.196469+02:00 database: closed
2025-05-28 00:40:04.196469+02:00 database: disconnected session #3
2025-05-28 00:40:04.199470+02:00 database: opening C:/Users/Arthur/.owlplug/owlplug (build 232)
2025-05-28 00:40:04.205469+02:00 database: opened C:/Users/Arthur/.owlplug/owlplug
2025-05-28 00:40:04.205469+02:00 database: connecting session #3 to C:/Users/Arthur/.owlplug/owlplug
2025-05-28 00:40:04.206470+02:00 jdbc[3]:
/*SQL */SET TRACE_LEVEL_FILE 2;
2025-05-28 00:40:04.206470+02:00 jdbc[3]:
/**/Connection conn1672 = DriverManager.getConnection("jdbc:h2:file:~/.owlplug/owlplug;TRACE_LEVEL_FILE=2", "SA", "");
2025-05-28 00:40:04.206470+02:00 jdbc[3]:
/*SQL */COMMIT;
2025-05-28 00:40:04.206470+02:00 jdbc[3]:
/*SQL */COMMIT;
2025-05-28 00:40:04.206470+02:00 database: disconnecting session #3
2025-05-28 00:40:04.206470+02:00 database: closing C:/Users/Arthur/.owlplug/owlplug
2025-05-28 00:40:04.380469+02:00 database: closed
2025-05-28 00:40:04.380469+02:00 database: disconnected session #3
2025-05-28 00:40:04.383470+02:00 database: opening C:/Users/Arthur/.owlplug/owlplug (build 232)
2025-05-28 00:40:04.390469+02:00 database: opened C:/Users/Arthur/.owlplug/owlplug
2025-05-28 00:40:04.390469+02:00 database: connecting session #3 to C:/Users/Arthur/.owlplug/owlplug
2025-05-28 00:40:04.390469+02:00 jdbc[3]:
/*SQL */SET TRACE_LEVEL_FILE 2;
2025-05-28 00:40:04.390469+02:00 jdbc[3]:
/**/Connection conn1673 = DriverManager.getConnection("jdbc:h2:file:~/.owlplug/owlplug;TRACE_LEVEL_FILE=2", "SA", "");
2025-05-28 00:40:04.395470+02:00 jdbc[3]: exception
org.h2.jdbc.JdbcSQLIntegrityConstraintViolationException: Intégrité référentielle violation de contrainte: "FKPTCXSPE0E9WAUQIVFK6F6OPGW: PUBLIC.FILE_STAT FOREIGN KEY(PARENT_ID) REFERENCES PUBLIC.FILE_STAT(ID) (CAST(2392 AS BIGINT))"
Referential integrity constraint violation: "FKPTCXSPE0E9WAUQIVFK6F6OPGW: PUBLIC.FILE_STAT FOREIGN KEY(PARENT_ID) REFERENCES PUBLIC.FILE_STAT(ID) (CAST(2392 AS BIGINT))"; SQL statement:
insert into file_stat (length,name,parent_id,parent_path,path,id) values (?,?,?,?,?,?) [23506-232]
at org.h2.message.DbException.getJdbcSQLException(DbException.java:520)
at org.h2.message.DbException.getJdbcSQLException(DbException.java:489)
at org.h2.message.DbException.get(DbException.java:223)
at org.h2.message.DbException.get(DbException.java:199)
at org.h2.constraint.ConstraintReferential.checkRowOwnTable(ConstraintReferential.java:308)
at org.h2.constraint.ConstraintReferential.checkRow(ConstraintReferential.java:249)
at org.h2.table.Table.fireConstraints(Table.java:1227)
at org.h2.table.Table.fireAfterRow(Table.java:1245)
at org.h2.command.dml.Insert.insertRows(Insert.java:188)
at org.h2.command.dml.Insert.update(Insert.java:135)
at org.h2.command.dml.DataChangeStatement.update(DataChangeStatement.java:74)
at org.h2.command.CommandContainer.update(CommandContainer.java:139)
at org.h2.command.Command.executeUpdate(Command.java:304)
at org.h2.command.Command.executeUpdate(Command.java:248)
at org.h2.jdbc.JdbcPreparedStatement.executeUpdateInternal(JdbcPreparedStatement.java:213)
at org.h2.jdbc.JdbcPreparedStatement.executeUpdate(JdbcPreparedStatement.java:172)
at com.p6spy.engine.wrapper.PreparedStatementWrapper.executeUpdate(PreparedStatementWrapper.java:94)
at org.hibernate.engine.jdbc.internal.ResultSetReturnImpl.executeUpdate(ResultSetReturnImpl.java:194)
at org.hibernate.engine.jdbc.mutation.internal.AbstractMutationExecutor.performNonBatchedMutation(AbstractMutationExecutor.java:134)
at org.hibernate.engine.jdbc.mutation.internal.MutationExecutorSingleNonBatched.performNonBatchedOperations(MutationExecutorSingleNonBatched.java:55)
at org.hibernate.engine.jdbc.mutation.internal.AbstractMutationExecutor.execute(AbstractMutationExecutor.java:55)
at org.hibernate.persister.entity.mutation.InsertCoordinatorStandard.doStaticInserts(InsertCoordinatorStandard.java:194)
at org.hibernate.persister.entity.mutation.InsertCoordinatorStandard.coordinateInsert(InsertCoordinatorStandard.java:132)
at org.hibernate.persister.entity.mutation.InsertCoordinatorStandard.insert(InsertCoordinatorStandard.java:104)
at org.hibernate.action.internal.EntityInsertAction.execute(EntityInsertAction.java:110)
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:644)
at org.hibernate.engine.spi.ActionQueue.executeActions(ActionQueue.java:511)
at org.hibernate.event.internal.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:414)
at org.hibernate.event.internal.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:41)
at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:127)
at org.hibernate.internal.SessionImpl.doFlush(SessionImpl.java:1429)
at org.hibernate.internal.SessionImpl.managedFlush(SessionImpl.java:491)
at org.hibernate.internal.SessionImpl.flushBeforeTransactionCompletion(SessionImpl.java:2354)
at org.hibernate.internal.SessionImpl.beforeTransactionCompletion(SessionImpl.java:1978)
at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.beforeTransactionCompletion(JdbcCoordinatorImpl.java:439)
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl.beforeCompletionCallback(JdbcResourceLocalTransactionCoordinatorImpl.java:169)
at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.commit(JdbcResourceLocalTransactionCoordinatorImpl.java:267)
at org.hibernate.engine.transaction.internal.TransactionImpl.commit(TransactionImpl.java:101)
at org.springframework.orm.jpa.JpaTransactionManager.doCommit(JpaTransactionManager.java:562)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:795)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:758)
at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:698)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:416)
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:119)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:138)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:165)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:184)
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:223)
at jdk.proxy2/jdk.proxy2.$Proxy144.save(Unknown Source)
at com.owlplug.core.tasks.FileSyncTask.extractFolderSize(FileSyncTask.java:95)
at com.owlplug.core.tasks.FileSyncTask.extractFolderSize(FileSyncTask.java:111)
at com.owlplug.core.tasks.FileSyncTask.extractFolderSize(FileSyncTask.java:111)
at com.owlplug.core.tasks.FileSyncTask.extractFolderSize(FileSyncTask.java:111)
at com.owlplug.core.tasks.FileSyncTask.extractFolderSize(FileSyncTask.java:111)
at com.owlplug.core.tasks.FileSyncTask.start(FileSyncTask.java:62)
at com.owlplug.core.tasks.AbstractTask.call(AbstractTask.java:51)
at com.owlplug.core.tasks.AbstractTask.call(AbstractTask.java:28)
at javafx.concurrent.Task$TaskCallable.call(Task.java:1399)
at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:317)
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.lang.Thread.run(Thread.java:1583)
2025-05-28 00:40:04.400472+02:00 jdbc[3]:
/*SQL l:74 #:1*/SELECT SETTING_VALUE FROM INFORMATION_SCHEMA.SETTINGS WHERE SETTING_NAME=? {1: 'QUERY_TIMEOUT'};
2025-05-28 00:40:04.404472+02:00 jdbc[3]:
/*SQL */ROLLBACK;
2025-05-28 00:40:04.404472+02:00 jdbc[3]:
/*SQL */COMMIT;
2025-05-28 00:40:04.406471+02:00 database: disconnecting session #3
2025-05-28 00:40:04.406471+02:00 database: closing C:/Users/Arthur/.owlplug/owlplug
2025-05-28 00:40:04.411470+02:00 database: closed
2025-05-28 00:40:04.411470+02:00 database: disconnected session #3
A similar issue has been reported to H2, but reproduction is difficult:
Suspect : The database compaction
Database compaction is executed after the connection is closed. The issue could be related to the compaction algorithm as:
- Only tables where data has been recently inserted are impacted.
- The problem cannot be reproduced with h2 2.3.230. In that version, the compaction does not complete in time (infinite loop). Using the version, the database grows continuously without a manual call to
SHUTDOWN COMPACT. - A bug fix has been introduced in h2 2.3.232 that fixed the infinite loop problem, and by the same time allowed the compaction to complete.
- Disabling auto-compaction on closing with
AUTO_COMPACT_FILL_RATE=0removed the issue completely.
[⏩Cancelled] Attempts to create an SSCCE
Trying to create an SSCCE without Hibernate and OwlPlug code: https://github.com/DropSnorz/h2-corrupt-sscce
Cancelling as re-creating an isolated use cache just with H2 and Java 11 seems complicated.
[❌ Unsuccessful ] Build H2 master to run without double compaction
Check if the problem can be reproduced without the double-compaction Store/MvStore fixed in h2database/h2database#4168.
Rebuild h2 from master / 56c0b70 version 2.3.239-SNASPHOT, but the issue can still be reproduced.
[❌ Unsuccessful] Synchronization / or race condition?
The disk speed and/or driver seem to impact the occurrence. On the same physical host:
- 🔴 Reproduced if database stored in NVME SSD PCIe 3.0 x4 (S.M.A.R.T., TRIM, VolatileWriteCache)
🟢 Cannot be reproduced if stored in HDD SATA/600 7200 RPM (S.M.A.R.T., APM, NCQ)- 🔴 Reproduced if database stored in a Virtual Box VM disk but backed by HDD SATA/600 7200 RPM (S.M.A.R.T., APM, NCQ)
Initially, I thought that the disk driver or speed might have an impact, it's just that the issue takes more time to appear on slower drives.
[✅ Confirmed] Build/Run H2 master with debug points on compaction logic
After adding some logs, every failure occurs upon closing after a shrink or truncate operation. It was very very strange as this seems to happen after any compaction loop execution on the RandomAccessStore.
2025-06-22 13:38:43.913594+02:00 database: disconnecting session #3
2025-06-22 13:38:43.913594+02:00 database: closing C:/Users/Arthur/.owlplug/owlplug
2025-06-22 13:38:43.914594+02:00 user: FileStore : dropUnusedChunks.toBeFreedChunks 0
2025-06-22 13:38:43.914594+02:00 database: RAS : writeChunk->shrinkStoreIfPossible()
2025-06-22 13:38:43.914594+02:00 database: RAS : shrinkIfPossible->truncate()
2025-06-22 13:38:43.916593+02:00 user: MVStore: Closing MVStore
2025-06-22 13:38:43.916593+02:00 user: MVStore : Stopping FileStore
2025-06-22 20:44:56.792193+02:00 user: RAS : compactStore
2025-06-22 20:44:56.792193+02:00 user: RAS : compaction loop 0
I was suspecting the shrink/truncate to malfunction, but the database was shrunk during closing because some chunks cannot be recovered during the database opening phase. Then the database recovery logic starts irremediably: https://github.com/h2database/h2database/blob/56c0b70ba19114b2fdab40637348a56bee0b5cc1/h2/src/main/org/h2/mvstore/RandomAccessStore.java#L303
/*SQL l:80 #:1*/update file_stat set length=?,name=?,parent_id=?,parent_path=?,path=? where id=? {1: CAST(23969 AS BIGINT), 2: 'LME_MIDI', 3: CAST(11573 AS BIGINT), 4: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Loopmasters Presents Electro Synths Massive Presets', 5: 'C:/AudioPlugins/VST-Presets/MASSIVE Ultimate/You''re Welcome/Loopmasters Presents Electro Synths Massive Presets/LME_MIDI', 6: CAST(11648 AS BIGINT)};
2025-06-22 20:44:56.605399+02:00 jdbc[3]:
/*SQL */COMMIT;
2025-06-22 20:44:56.605399+02:00 jdbc[3]:
/*SQL */COMMIT;
2025-06-22 20:44:56.605399+02:00 database: disconnecting session #3
2025-06-22 20:44:56.605399+02:00 database: closing C:/Users/Arthur/.owlplug/owlplug
2025-06-22 20:44:56.605399+02:00 database: MVStore: Increase current version to 8655
2025-06-22 20:44:56.605399+02:00 database: MVStore: store->FileStore.dropUnusedChunks()
2025-06-22 20:44:56.605399+02:00 user: FileStore : dropUnusedChunks.toBeFreedChunks 0
2025-06-22 20:44:56.606402+02:00 database: FileStore : serializeAndStore() c.id=8655 lastChunkId=8655
2025-06-22 20:44:56.606402+02:00 database: FileStore: storeBuffer() c.id=8655
2025-06-22 20:44:56.606402+02:00 database: RAS : writeChunk->writeStoreHeader()
2025-06-22 20:44:56.606402+02:00 database: RAS : writeStoreHeader()
2025-06-22 20:44:56.606402+02:00 database: RAS header: H:2,block:41,blockSize:1000,chunk:21cf,created:19798f30e74,format:3,version:21cf,fletcher:71a310ae
2025-06-22 20:44:56.606402+02:00 database: RAS : writeChunk->shrinkStoreIfPossible()
2025-06-22 20:44:56.607400+02:00 user: MVStore: Closing MVStore
2025-06-22 20:44:56.607400+02:00 user: MVStore : Stopping FileStore
2025-06-22 20:44:56.607400+02:00 user: RAS : compactStore
// ----------------------- Beginning of the issue
// ----------------------- Chunk and version 8656 will be unrecoverable on next database opening
2025-06-22 20:44:56.647401+02:00 database: MVStore: Increase current version to 8656
2025-06-22 20:44:56.647401+02:00 database: MVStore: store->FileStore.dropUnusedChunks()
2025-06-22 20:44:56.647401+02:00 user: FileStore : dropUnusedChunks.toBeFreedChunks 1
2025-06-22 20:44:56.689403+02:00 database: FileStore : serializeAndStore() c.id=8656 lastChunkId=8656
2025-06-22 20:44:56.689403+02:00 database: FileStore: storeBuffer() c.id=8656
2025-06-22 20:44:56.697399+02:00 user: FileStore : dropUnusedChunks.toBeFreedChunks 6
2025-06-22 20:44:56.698401+02:00 user: RAS : compactMoveChunks
2025-06-22 20:44:56.698401+02:00 database: RAS : writeStoreHeader()
2025-06-22 20:44:56.698401+02:00 database: RAS header: H:2,block:8be,blockSize:1000,chunk:21d0,created:19798f30e74,format:3,version:21d0,fletcher:c297f4f9
2025-06-22 20:44:56.707399+02:00 database: FileStore : serializeAndStore() c.id=8657 lastChunkId=8657
2025-06-22 20:44:56.707399+02:00 database: FileStore: storeBuffer() c.id=8657
2025-06-22 20:44:56.707399+02:00 database: RAS : writeChunk->writeStoreHeader()
2025-06-22 20:44:56.707399+02:00 database: RAS : writeStoreHeader()
2025-06-22 20:44:56.707399+02:00 database: RAS header: H:2,block:459,blockSize:1000,chunk:21d1,created:19798f30e74,format:3,version:21d1,fletcher:3f3dc6cc
2025-06-22 20:44:56.707399+02:00 database: RAS : writeChunk->shrinkStoreIfPossible()
2025-06-22 20:44:56.717001+02:00 database: FileStore : serializeAndStore() c.id=8658 lastChunkId=8658
2025-06-22 20:44:56.717001+02:00 database: FileStore: storeBuffer() c.id=8658
2025-06-22 20:44:56.717001+02:00 database: RAS : writeChunk->writeStoreHeader()
2025-06-22 20:44:56.717001+02:00 database: RAS : writeStoreHeader()
2025-06-22 20:44:56.717001+02:00 database: RAS header: H:2,block:870,blockSize:1000,chunk:21d2,created:19798f30e74,format:3,version:21d2,fletcher:ab84c3ce
2025-06-22 20:44:56.717001+02:00 database: RAS : writeChunk->shrinkStoreIfPossible()
2025-06-22 20:44:56.717001+02:00 database: RAS : shrinkIfPossible->truncate() end=8851456 size=17711104
2025-06-22 20:44:56.720998+02:00 database: RAS : compactMoveChunks->shrinkIfPossible()
2025-06-22 20:44:56.725998+02:00 database: MVStore: Increase current version to 8659
2025-06-22 20:44:56.725998+02:00 database: MVStore: store->FileStore.dropUnusedChunks()
2025-06-22 20:44:56.726998+02:00 user: FileStore : dropUnusedChunks.toBeFreedChunks 2
2025-06-22 20:44:56.758192+02:00 database: FileStore : serializeAndStore() c.id=8659 lastChunkId=8659
2025-06-22 20:44:56.758192+02:00 database: FileStore: storeBuffer() c.id=8659
2025-06-22 20:44:56.760193+02:00 database: RAS : writeChunk->writeStoreHeader()
2025-06-22 20:44:56.760193+02:00 database: RAS : writeStoreHeader()
2025-06-22 20:44:56.760193+02:00 database: RAS header: H:2,block:46,blockSize:1000,chunk:21d3,created:19798f30e74,format:3,version:21d3,fletcher:84bd124d
2025-06-22 20:44:56.760193+02:00 database: RAS : writeChunk->shrinkStoreIfPossible()
2025-06-22 20:44:56.763192+02:00 user: FileStore : dropUnusedChunks.toBeFreedChunks 2
2025-06-22 20:44:56.764193+02:00 user: RAS : compaction loop 2
2025-06-22 20:44:56.764193+02:00 database: RAS : writeCleanShutdownMark->shrinkStoreIfPossible()
2025-06-22 20:44:56.764193+02:00 database: RAS : shrinkIfPossible->truncate() end=4575232 size=8851456
2025-06-22 20:44:56.764193+02:00 database: RAS : writeStoreHeader()
2025-06-22 20:44:56.764193+02:00 database: RAS header: H:2,block:46,blockSize:1000,chunk:21d3,clean:1,created:19798f30e74,format:3,version:21d3,fletcher:6fed46b5
2025-06-22 20:44:56.765193+02:00 user: MVStore : Maps closed
2025-06-22 20:44:56.766193+02:00 database: closed
2025-06-22 20:44:56.766193+02:00 database: disconnected session #3
2025-06-22 20:44:56.769192+02:00 database: opening C:/Users/Arthur/.owlplug/owlplug (build 239)
2025-06-22 20:44:56.772192+02:00 database: MVStore : setCurrentVersion 0
2025-06-22 20:44:56.773192+02:00 database: 2135232579 RAS : readStoreHeader()
2025-06-22 20:44:56.773192+02:00 database: RAS : ---- created=19798f30e74
2025-06-22 20:44:56.773192+02:00 database: RAS : ---- H=2
2025-06-22 20:44:56.773192+02:00 database: RAS : ---- format=3
2025-06-22 20:44:56.773192+02:00 database: RAS : ---- chunk=21d3
2025-06-22 20:44:56.773192+02:00 database: RAS : ---- block=46
2025-06-22 20:44:56.773192+02:00 database: RAS : ---- clean=1
2025-06-22 20:44:56.773192+02:00 database: RAS : ---- version=21d3
2025-06-22 20:44:56.773192+02:00 database: RAS : ---- blockSize=1000
2025-06-22 20:44:56.773192+02:00 database: RAS : ---- created=19798f30e74
2025-06-22 20:44:56.773192+02:00 database: RAS : ---- H=2
2025-06-22 20:44:56.773192+02:00 database: RAS : ---- format=3
2025-06-22 20:44:56.773192+02:00 database: RAS : ---- chunk=21d3
2025-06-22 20:44:56.773192+02:00 database: RAS : ---- block=46
2025-06-22 20:44:56.773192+02:00 database: RAS : ---- clean=1
2025-06-22 20:44:56.773192+02:00 database: RAS : ---- version=21d3
2025-06-22 20:44:56.773192+02:00 database: RAS : ---- blockSize=1000
2025-06-22 20:44:56.773192+02:00 database: RAS : readStoreHeader() assumeCleanShutdown=true newest.id=8659 newest.version=8659
2025-06-22 20:44:56.773192+02:00 database: FileStore : setLastChunk() last.id=8659
2025-06-22 20:44:56.773192+02:00 database: RAS : readStoreHeader()->readChunkHeaderAndFooter() = chunk:d4a,block:2,len:d,pages:33,max:d590,map:2b9,next:29,root:35280002eda54,time:d0eb,version:d4a,toc:becc
2025-06-22 20:44:56.773192+02:00 database: RAS : readStoreHeader()->readChunkHeaderAndFooter() = chunk:1035,block:f,len:f,pages:3c,max:fc40,map:371,next:3c,root:40d4000367416,time:ea78,version:1035,toc:ddf7
2025-06-22 20:44:56.773192+02:00 database: RAS : readStoreHeader()->readChunkHeaderAndFooter() = chunk:1c0e,block:1e,len:1a,pages:70,max:1d3b0,map:753,next:6c,root:703800061ed16,time:1686c,version:1c0e,toc:18d05
2025-06-22 20:44:56.773192+02:00 database: RAS : readStoreHeader()->readChunkHeaderAndFooter() = chunk:21ce,block:38,len:9,pages:19,max:8fd0,map:e41,next:479,root:87380001c0ac3,time:22785,version:21ce,toc:7f13
2025-06-22 20:44:56.773192+02:00 database: RAS : readStoreHeader()->readChunkHeaderAndFooter() = chunk:21cf,block:41,len:5,pages:12,max:5590,map:e43,next:457,root:873c0000f5283,time:22829,version:21cf,toc:4cef
// ----------------------- Here chunks chunk:8656 (21cf) cannot be retrieved from the file
// ----------------------- This causes the database to rollback from version 8656 to 7182
2025-06-22 20:44:56.774192+02:00 database: FileStore : readChunkHeaderOptionally() Exception:Reading from file sun.nio.ch.FileChannelImpl@1de83efb failed at 4575232 (length 4575232), read 0, remaining 1024 [2.3.239/1]
2025-06-22 20:44:56.779195+02:00 database: Header cannot be found block=1117,expectedId=8656
2025-06-22 20:44:56.779195+02:00 database: RAS : readStoreHeader()->readChunkHeaderAndFooter() = null
2025-06-22 20:44:56.779195+02:00 database: RAS : readStoreHeader() assumeCleanShutdown=false
2025-06-22 20:44:56.779195+02:00 database: FileStore : setLastChunk() last.id=8655
2025-06-22 20:44:56.779195+02:00 database: FileStore : setLastChunk() last.id=8654
2025-06-22 20:44:56.779195+02:00 database: FileStore : setLastChunk() last.id=7182
2025-06-22 20:44:56.779195+02:00 database: Header cannot be found block=30expectedId=7178
2025-06-22 20:44:56.779195+02:00 database: FileStore : readChunkHeaderOptionally() Exception:File corrupt reading chunk at position 135168 [2.3.239/6]
2025-06-22 20:44:56.779195+02:00 database: Header cannot be found block=33,expectedId=7179
2025-06-22 20:44:56.779195+02:00 database: Header cannot be found block=56,expectedId=7181
2025-06-22 20:44:56.779195+02:00 database: RAS : readStoreHeader() completed
2025-06-22 20:44:56.779195+02:00 database: FileStore : start() lastChunkVersion=7182
2025-06-22 20:44:56.779195+02:00 database: MVStore : setCurrentVersion 7182
2025-06-22 20:44:56.782193+02:00 database: opened C:/Users/Arthur/.owlplug/owlplug
2025-06-22 20:44:56.782193+02:00 database: connecting session #3 to C:/Users/Arthur/.owlplug/owlplug
After adding more logs, it appears the chunk 8656 is dropped upon compaction during map/database closure and flagged as FileStore : dropUnusedChunks.toBeFreedChunks. The recovery execution must be tracked by checking the occurrences of RAS : readStoreHeader() assumeCleanShutdown=false. It always follows a database closure if a chunk gets freed during compaction, while this particular chunk was also created during the database closure compaction loop. This is a consistent behavior during my test: "If a chunk is created and freed during the compaction process, the recovery mode will be executed on next database opening"
There are several possibilities:
-
The chunk shouldn't be freed; the change is correctly reflected in metadata, and the startup recovery behaves correctly.
Chunk is added to thedeadChunklist by theacceptChunkOccupancyChangescall. This decision appears valid as the page was evicted from the map. This could be checked again as I'm not sure to fully get the page eviction detection logic behindChunk.accountForRemovedPage(). -
The chunk should be freed; the change is not correctly reflected in metadata, and the startup recovery behaves correctly.
This seems to be the most likely issue based on (2) and (3). -
The chunk should be freed; the change is correctly reflected in metadata, but the startup recovery mode is not working correctly.
The startup recovery seems to behave well by falling back to the most recent chunks and validating the layout. This causes the database to roll back in time as the latest chunk will be considered as corrupted. Sometimes, multiple chunks cannot be recovered, and the database can be rolled back for hundreds of versions, sometimes leaving an empty table.
I've added more logs to check compaction loop execution and verify markMetaChanged is called upon chunk deletion, and how compactMoveChunk is executed.
/*SQL */COMMIT;
2025-07-09 22:48:04.506193+02:00 database: disconnecting session #3
2025-07-09 22:48:04.506193+02:00 database: closing D:/temp/owlplug/owlplug
2025-07-09 22:48:04.506193+02:00 database: MVStore: store() -> Increase current version to 6240
2025-07-09 22:48:04.506193+02:00 database: MVStore: store() -> FileStore.dropUnusedChunks()
2025-07-09 22:48:04.506193+02:00 database: FileStore : dropUnusedChunks.toBeFreedChunks 0
2025-07-09 22:48:04.506193+02:00 database: MVStore: store() -> FileStore.storeNow()
2025-07-09 22:48:04.507190+02:00 database: FileStore : StoreIt version=6240,syncWrite=true
2025-07-09 22:48:04.507190+02:00 database: FileStore : serializeAndStore() c.id=6240 lastChunkId=6240
2025-07-09 22:48:04.508191+02:00 database: FileStore: storeBuffer() c.id=6240
2025-07-09 22:48:04.508191+02:00 database: RAS : writeStoreHeader()
2025-07-09 22:48:04.508191+02:00 database: RAS header: H:2,block:9a3,blockSize:1000,chunk:1860,created:197f0cfd8aa,format:3,version:1860,fletcher:e773fd22
2025-07-09 22:48:04.508191+02:00 database: RAS : writeChunk->shrinkStoreIfPossible()
2025-07-09 22:48:04.508191+02:00 user: MVStore: Closing MVStore
2025-07-09 22:48:04.508191+02:00 user: MVStore : Stopping FileStore
2025-07-09 22:48:04.508191+02:00 database: RAS : compactStore()
2025-07-09 22:48:04.508191+02:00 database: FileStore : rewriteChunks()
2025-07-09 22:48:04.525190+02:00 database: RAS : compactStore() -> Starting compaction loop 1
2025-07-09 22:48:04.636190+02:00 database: RAS : compactMoveChunks() -> dropUnusedChunks()
2025-07-09 22:48:04.636190+02:00 database: FileStore : dropUnusedChunk -> mvStore.markMetaChanged() for chunkId=6233
2025-07-09 22:48:04.636190+02:00 database: FileStore : dropUnusedChunk -> mvStore.markMetaChanged() for chunkId=6238
2025-07-09 22:48:04.636190+02:00 database: FileStore : dropUnusedChunks.toBeFreedChunks 2
2025-07-09 22:48:04.636190+02:00 database: FileStore : dropUnusedChunks free chunk space for : 6233,6238
2025-07-09 22:48:04.636190+02:00 database: RAS : compactMoveChunks() -> compactMoveChunks skipped getFillRate=94,targetFillRate=90
2025-07-09 22:48:04.636190+02:00 database: FileStore : rewriteChunks()
2025-07-09 22:48:04.638190+02:00 database: RAS : compaction loop completed 1
2025-07-09 22:48:04.638190+02:00 database: RAS : writeCleanShutdownMark->shrinkStoreIfPossible()
2025-07-09 22:48:04.638190+02:00 database: RAS : shrinkIfPossible->truncate() end=14659584 size=14671872
2025-07-09 22:48:04.638190+02:00 database: RAS : writeStoreHeader()
2025-07-09 22:48:04.638190+02:00 database: RAS header: H:2,block:9a3,blockSize:1000,chunk:1860,clean:1,created:197f0cfd8aa,format:3,version:1860,fletcher:1b706557
2025-07-09 22:48:04.713191+02:00 user: MVStore : Maps closed
2025-07-09 22:48:04.714191+02:00 database: closed
2025-07-09 22:48:04.714191+02:00 database: disconnected session #3
2025-07-09 22:48:04.716191+02:00 database: opening D:/temp/owlplug/owlplug (build 239)
2025-07-09 22:48:04.718194+02:00 database: MVStore : setCurrentVersion 0
2025-07-09 22:48:04.718194+02:00 database: 284535385 RAS : readStoreHeader()
2025-07-09 22:48:04.718194+02:00 database: RAS : ---- created=197f0cfd8aa
2025-07-09 22:48:04.718194+02:00 database: RAS : ---- H=2
2025-07-09 22:48:04.718194+02:00 database: RAS : ---- format=3
2025-07-09 22:48:04.718194+02:00 database: RAS : ---- chunk=1860
2025-07-09 22:48:04.718194+02:00 database: RAS : ---- block=9a3
2025-07-09 22:48:04.718194+02:00 database: RAS : ---- clean=1
2025-07-09 22:48:04.718194+02:00 database: RAS : ---- version=1860
2025-07-09 22:48:04.718194+02:00 database: RAS : ---- blockSize=1000
2025-07-09 22:48:04.718194+02:00 database: RAS : ---- created=197f0cfd8aa
2025-07-09 22:48:04.718194+02:00 database: RAS : ---- H=2
2025-07-09 22:48:04.718194+02:00 database: RAS : ---- format=3
2025-07-09 22:48:04.718194+02:00 database: RAS : ---- chunk=1860
2025-07-09 22:48:04.718194+02:00 database: RAS : ---- block=9a3
2025-07-09 22:48:04.718194+02:00 database: RAS : ---- clean=1
2025-07-09 22:48:04.718194+02:00 database: RAS : ---- version=1860
2025-07-09 22:48:04.718194+02:00 database: RAS : ---- blockSize=1000
2025-07-09 22:48:04.718194+02:00 database: RAS : readStoreHeader() assumeCleanShutdown=true newest.id=6240 newest.version=6240
2025-07-09 22:48:04.718194+02:00 database: FileStore : setLastChunk() last.id=6240
2025-07-09 22:48:04.718194+02:00 database: RAS : readStoreHeader()->readChunkHeaderAndFooter() = chunk:17cc,block:2,len:465,pages:a7d,max:5556a0,map:fe5,next:a0b,root:5f300117c55d8,time:216c11,version:17cc,toc:45f86a
2025-07-09 22:48:04.719206+02:00 database: RAS : readStoreHeader()->readChunkHeaderAndFooter() = chunk:1859,block:467,len:da,pages:3fc,max:107340,map:104f,next:ded,root:61640035a749c,time:222d1b,version:1859,toc:d76c9
2025-07-09 22:48:04.719206+02:00 database: RAS : readStoreHeader()->readChunkHeaderAndFooter() = chunk:185b,block:9aa,len:451,pages:a85,max:53e820,map:1051,next:1240,root:616c011288d1a,time:222ea8,version:185b,toc:44ad88
2025-07-09 22:48:04.719206+02:00 database: RAS : readStoreHeader()->readChunkHeaderAndFooter() = chunk:185c,block:543,len:f,pages:23,max:11000,map:1051,next:552,root:617000034b9dc,time:222faa,version:185c,toc:e0c5
2025-07-09 22:48:04.719206+02:00 database: FileStore : readChunkHeaderOptionally() Exception:Reading from file sun.nio.ch.FileChannelImpl@30616993 failed at 14663680 (length 14659584), read 0, remaining 1024 [2.3.239/1]
2025-07-09 22:48:04.719206+02:00 database: Header cannot be found block=3580expectedId=6238
2025-07-09 22:48:04.719206+02:00 database: RAS : readStoreHeader()->readChunkHeaderAndFooter() = null
2025-07-09 22:48:04.719206+02:00 database: RAS : readStoreHeader() assumeCleanShutdown=false
2025-07-09 22:48:04.719206+02:00 database: FileStore : setLastChunk() last.id=6236
2025-07-09 22:48:04.719206+02:00 database: FileStore : readChunkHeaderOptionally() Exception:Reading from file sun.nio.ch.FileChannelImpl@30616993 failed at 19136512 (length 14659584), read 0, remaining 1024 [2.3.239/1]
2025-07-09 22:48:04.719206+02:00 database: Header cannot be found block=4672expectedId=6232
2025-07-09 22:48:04.719206+02:00 database: RAS : readStoreHeader() completed
2025-07-09 22:48:04.719206+02:00 database: FileStore : start() lastChunkVersion=6236
2025-07-09 22:48:04.719206+02:00 database: MVStore : setCurrentVersion 6236
2025-07-09 22:48:04.722192+02:00 database: opened D:/temp/owlplug/owlplug
2025-07-09 22:48:04.722192+02:00 database: connecting session #3 to D:/temp/owlplug/owlplug
So here is my understanding of the problem. Within the compaction loop in RandomAccessStore.compactMoveChunk there is a call to dropUnusedChunks(). This call is flagging chunks, which are removed from the layout, added to the deadChunk list and freed from the freeSpace.
Later in compactMoveChunks, an overloaded method is called compactMoveChunks(moveSize), but only if the current store file rate is beyond the targetFillRate. If we want to persist the chunks deletion, this method is the "last chance" to call the store() to create a new version and a Chunk. If this method is not called, the chunk will remain but it's as they are still stored on the file.
When the compaction loop completes, either because max compaction time is exceeded or the expected rate has been reached. The shrinkStoreIfPossible() method is called from the last database closure operation in writeCleanShutdownMark() method. As the shrink logic is based on the freeSpace, the database file might be truncated dropping the chunks flagged as deleted but still referenced in last chunk layout on the file.
When the database is re-opened, last chunk is loaded but the referenced chunk cannot be retrieved as the chunk location is now out of the file boundaries. The recovery process and and roll-back is starting.
Possible solutions
-
I've tried to force execution of
compactMoveChunksif chunks are dropped. This fixes the bug I was facing, usually it appears after ~1-2 minutes of batch insertions, with this change any issue occurs within 1h.
Force chunk space reallocation if chunks are dropped h2database#2 -
Maybe rework the shrink/free space logic or prevent some chunks to join the
deadChunklist to early.
Metadata
Metadata
Assignees
Labels
Projects
Status