H2 Corrupted DB

[Svetlin Zarev]

Hello!

I stumbled across an error that should have been fixed according to [1]. The issue happens during import of  quite big jira backup. (Unfortunately I cannot send you the database as it's quite big and contains confidential data) Here is the issue:

2016-04-11 15:33:11,774 active-objects-init-JiraTenantImpl{id='system'}-0 ERROR anonymous 926x10x1 12xtipa 0:0:0:0:0:0:0:1 /secure/SetupImport.jspa [n.java.ao.sql] Exception executing SQL update <ALTER TABLE PUBLIC.AO_60DB71_ISSUERANKING ALTER COLUMN ISSUE_ID BIGINT DEFAULT 0 NOT NULL>

org.h2.jdbc.JdbcSQLException: General error: "java.lang.IllegalStateException: Reading from cache:nio:C:/Users/XXX/Downloads/atlassian-jira-software-7.1.4-jira-7.1.4/jira-home/database/h2db.mv.db failed; file length -1 read length 384 at 2782475972 [1.4.191/1]" [50000-191]
    at org.h2.message.DbException.getJdbcSQLException(DbException.java:345)
    at org.h2.message.DbException.get(DbException.java:168)
    at org.h2.message.DbException.convert(DbException.java:295)
    at org.h2.message.DbException.toSQLException(DbException.java:268)
    at org.h2.message.TraceObject.logAndConvert(TraceObject.java:352)
    at org.h2.jdbc.JdbcStatement.executeUpdate(JdbcStatement.java:117)
    at org.apache.commons.dbcp2.DelegatingStatement.executeUpdate(DelegatingStatement.java:234)
    at org.apache.commons.dbcp2.DelegatingStatement.executeUpdate(DelegatingStatement.java:234)
    at net.java.ao.DatabaseProvider.executeUpdate(DatabaseProvider.java:2246)
    at net.java.ao.DatabaseProvider.executeUpdateForAction(DatabaseProvider.java:2302)
    at net.java.ao.DatabaseProvider.executeUpdatesForActions(DatabaseProvider.java:2274)
    at net.java.ao.schema.SchemaGenerator.migrate(SchemaGenerator.java:91)
    at net.java.ao.EntityManager.migrate(EntityManager.java:128)
    at com.atlassian.activeobjects.internal.EntityManagedActiveObjects.migrate(EntityManagedActiveObjects.java:45)
    at com.atlassian.activeobjects.internal.AbstractActiveObjectsFactory$1.doInTransaction(AbstractActiveObjectsFactory.java:77)
    at com.atlassian.activeobjects.internal.AbstractActiveObjectsFactory$1.doInTransaction(AbstractActiveObjectsFactory.java:72)
    at com.atlassian.sal.core.transaction.HostContextTransactionTemplate$1.doInTransaction(HostContextTransactionTemplate.java:25)
    at com.atlassian.jira.DefaultHostContextAccessor.doInTransaction(DefaultHostContextAccessor.java:34)
    ... 2 filtered
    at java.lang.reflect.Method.invoke(Method.java:497)
    at com.atlassian.plugin.util.ContextClassLoaderSettingInvocationHandler.invoke(ContextClassLoaderSettingInvocationHandler.java:26)
    at com.sun.proxy.$Proxy26.doInTransaction(Unknown Source)
    ... 2 filtered
    at java.lang.reflect.Method.invoke(Method.java:497)
    at com.atlassian.plugin.osgi.bridge.external.HostComponentFactoryBean$DynamicServiceInvocationHandler.invoke(HostComponentFactoryBean.java:136)
    at com.sun.proxy.$Proxy26.doInTransaction(Unknown Source)
    at com.atlassian.sal.core.transaction.HostContextTransactionTemplate.execute(HostContextTransactionTemplate.java:21)
    ... 2 filtered
    at java.lang.reflect.Method.invoke(Method.java:497)
    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)
    at org.eclipse.gemini.blueprint.service.importer.support.internal.aop.ServiceInvoker.doInvoke(ServiceInvoker.java:56)
    at org.eclipse.gemini.blueprint.service.importer.support.internal.aop.ServiceInvoker.invoke(ServiceInvoker.java:60)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:133)
    at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:121)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.eclipse.gemini.blueprint.service.util.internal.aop.ServiceTCCLInterceptor.invokeUnprivileged(ServiceTCCLInterceptor.java:70)
    at org.eclipse.gemini.blueprint.service.util.internal.aop.ServiceTCCLInterceptor.invoke(ServiceTCCLInterceptor.java:53)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.eclipse.gemini.blueprint.service.importer.support.LocalBundleContextAdvice.invoke(LocalBundleContextAdvice.java:57)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.springframework.aop.support.DelegatingIntroductionInterceptor.doProceed(DelegatingIntroductionInterceptor.java:133)
    at org.springframework.aop.support.DelegatingIntroductionInterceptor.invoke(DelegatingIntroductionInterceptor.java:121)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:207)
    at com.sun.proxy.$Proxy1017.execute(Unknown Source)
    at com.atlassian.activeobjects.internal.AbstractActiveObjectsFactory.create(AbstractActiveObjectsFactory.java:72)
    at com.atlassian.activeobjects.internal.DelegatingActiveObjectsFactory.create(DelegatingActiveObjectsFactory.java:32)
    at com.atlassian.activeobjects.osgi.TenantAwareActiveObjects$1$1$1.call(TenantAwareActiveObjects.java:91)
    at com.atlassian.activeobjects.osgi.TenantAwareActiveObjects$1$1$1.call(TenantAwareActiveObjects.java:86)
    at com.atlassian.sal.core.executor.ThreadLocalDelegateCallable.call(ThreadLocalDelegateCallable.java:42)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.IllegalStateException: Reading from cache:nio:C:/Users/XXX/Downloads/atlassian-jira-software-7.1.4-jira-7.1.4/jira-home/database/h2db.mv.db failed; file length -1 read length 384 at 2782475972 [1.4.191/1]
    at org.h2.mvstore.DataUtils.newIllegalStateException(DataUtils.java:773)
    at org.h2.mvstore.DataUtils.readFully(DataUtils.java:443)
    at org.h2.mvstore.FileStore.readFully(FileStore.java:98)
    at org.h2.mvstore.Page.read(Page.java:190)
    at org.h2.mvstore.MVStore.readPage(MVStore.java:1939)
    at org.h2.mvstore.Page.getChildPage(Page.java:217)
    at org.h2.mvstore.MVMap.binarySearch(MVMap.java:468)
    at org.h2.mvstore.MVMap.binarySearch(MVMap.java:469)
    at org.h2.mvstore.MVMap.binarySearch(MVMap.java:469)
    at org.h2.mvstore.MVMap.get(MVMap.java:450)
    at org.h2.mvstore.db.TransactionStore.commit(TransactionStore.java:332)
    at org.h2.mvstore.db.TransactionStore$Transaction.commit(TransactionStore.java:779)
    at org.h2.engine.Session.commit(Session.java:611)
    at org.h2.command.Command.stop(Command.java:154)
    at org.h2.command.Command.executeUpdate(Command.java:288)
    at org.h2.jdbc.JdbcStatement.executeUpdateInternal(JdbcStatement.java:130)
    at org.h2.jdbc.JdbcStatement.executeUpdate(JdbcStatement.java:115)
    ... 52 more
Caused by: java.nio.channels.ClosedChannelException
    at sun.nio.ch.FileChannelImpl.ensureOpen(FileChannelImpl.java:109)
    at sun.nio.ch.FileChannelImpl.read(FileChannelImpl.java:688)
    at org.h2.store.fs.FileNio.read(FilePathNio.java:74)
    at org.h2.mvstore.cache.FilePathCache$FileCache.read(FilePathCache.java:87)
    at org.h2.mvstore.DataUtils.readFully(DataUtils.java:429)



[1] https://groups.google.com/d/msg/h2-database/GVNb3GgJJEs/CTtuPdreCQAJ

Best regards,
Svetlin

[Noel Grandin]

Hi

The root exception there is "ClosedChannelException", which means one of two things
(1) something else happened before this exception, and we'd need to see that earlier exception to know what the problem was
(2) something else called interrupt() on that thread, which is very very bad

Regards, Noel

[Svetlin Zarev]

This seems to be the first exception (except for some NPEs in jira code that don;t seem relevant to me). After that exception the whole jira instance is trashed.
Why ` interrupt() ` is bad ? Shouldn't H2 be able to recover (ACID?) ?

PS: This question is not about jira. I'm using it just as a test tool to evaluate H2 and jira 7 turned out to use H2 as demo DB.

[Svetlin Zarev]

Update: I connected to the DB via the H2 console without issues and executed the SQL statement from the exception and it finished successfully. Maybe the issue is in jira.

[Noel Grandin]

I agree, I don't see anything obvious in that log. You could try checking the H2 .trace.log file which lives next to the DB file, sometimes that manages to capture exceptions that the application ignores.

interrupt() closes the NIO FileChannel object, which means the whole DB is effectively shutdown. The data is fine, but you'd need to reconnect to the DB.

To work around this, you could try running the DB in TCP server mode. Then interrupt() will just close the java.sql.Connection object that that Thread is using, instead of shutting down the DB.

​