OwlPlug icon indicating copy to clipboard operation
OwlPlug copied to clipboard
verified publisher icon DropSnorz

H2 2.3.232 database corruption

Open DropSnorz opened this issue 6 months ago • 0 comments

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.

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:

  • https://github.com/h2database/h2database/issues/4123

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=0 removed the issue.

[⌛ In progress] Attempts to create an SSCCE

Trying to create an SSCCE without Hibernate and OwlPlug code : https://github.com/DropSnorz/h2-corrupt-sscce

[❌ Unsuccessful ] Build H2 master to run without double compaction

Check if the problem can be reproduced without the double-compaction Store/MvStore fixed in https://github.com/h2database/h2database/pull/4168.

Rebuild h2 from master / 56c0b70 version 2.3.239-SNASPHOT but the issue can still be reproduced.

[⌛ In progress] Build/Run H2 master with debug points on compaction logic

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

DropSnorz avatar Jun 21 '25 09:06 DropSnorz