[DERBY-4697] After an abnormal shutdown, cannot connect to derby DB.

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Not A Problem
• Affects Version/s: 10.3.3.0
• Component/s: Store
• Environment: Linux RHEL5. 64 bit. Embedded DERBY.
• Urgency: Urgent
• Bug behavior facts: Data corruption
• Assignee: Unassigned
• Reporter: Michael Closson
• Created: 11/Jun/10 18:12
• Updated: 16/Nov/10 19:39
• Resolved: 16/Nov/10 19:39

Description

My company uses embedded derby DB for persistence (w/ hibernate) in one of our server products. We have been using it for several years now.

We are using derby version 10.3. (Bundle-Version: 10.3.1000004.561794)

Recently at a customer site, the server couldn't start because it could not connect to the database. It happened after the server shutdown abnormally. The error message reported in the log file is:

Caused by: java.sql.SQLException: Failed to start database 'db', see the next exception for details.
at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Unknown Source)
at org.apache.derby.impl.jdbc.Util.seeNextException(Unknown Source)
at org.apache.derby.impl.jdbc.EmbedConnection.bootDatabase(Unknown Source)
at org.apache.derby.impl.jdbc.EmbedConnection.<init>(Unknown Source)
at org.apache.derby.impl.jdbc.EmbedConnection30.<init>(Unknown Source)
at org.apache.derby.jdbc.Driver30.getNewEmbedConnection(Unknown Source)
at org.apache.derby.jdbc.InternalDriver.connect(Unknown Source)
at org.apache.derby.jdbc.AutoloadedDriver.connect(Unknown Source)
at com.mchange.v2.c3p0.DriverManagerDataSource.getConnection(DriverManagerDataSource.java:65)
at com.mchange.v2.c3p0.WrapperConnectionPoolDataSource.getPooledConnection(WrapperConnectionPoolDataSource.java:66)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPoolManager.initializeAutomaticTestTable(C3P0PooledConnectionPoolManager.java:472)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPoolManager.createPooledConnectionPool(C3P0PooledConnectionPoolManager.java:406)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPoolManager.getPool(C3P0PooledConnectionPoolManager.java:327)
at com.mchange.v2.c3p0.impl.C3P0PooledConnectionPoolManager.getPool(C3P0PooledConnectionPoolManager.java:345)
at com.mchange.v2.c3p0.PoolBackedDataSource.getConnection(PoolBackedDataSource.java:64)
at org.hibernate.connection.C3P0ConnectionProvider.getConnection(C3P0ConnectionProvider.java:35)
at org.hibernate.jdbc.ConnectionManager.openConnection(ConnectionManager.java:298)
at org.hibernate.jdbc.ConnectionManager.getConnection(ConnectionManager.java:110)
at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:88)
at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1162)
at org.hibernate.loader.Loader.doQuery(Loader.java:390)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:218)
at org.hibernate.loader.Loader.doList(Loader.java:1593)
at org.hibernate.loader.Loader.list(Loader.java:1577)
at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:395)
at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:271)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:844)
at org.hibernate.impl.QueryImpl.list(QueryImpl.java:74)
... 11 more
Caused by: java.sql.SQLException: Java exception: ': java.lang.IndexOutOfBoundsException'.
at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Unknown Source)
at org.apache.derby.impl.jdbc.Util.javaException(Unknown Source)
... 37 more

Indeed, if I try to connect to the database with IJ, I get the same error.

If I connect with jars that I built from derby source (10.6, latest) I get a different error:

[mclosson@magrath work]$ java org.apache.derby.tools.ij
ij version 10.6
ij> connect 'jdbc:derby:db';
org.apache.derby.shared.common.sanity.AssertFailure: ASSERT FAILED Wrong LogInstant on log record (1392542017,37698) version real position (392,719194)
at org.apache.derby.shared.common.sanity.SanityManager.THROWASSERT(SanityManager.java:162)
at org.apache.derby.shared.common.sanity.SanityManager.THROWASSERT(SanityManager.java:147)
at org.apache.derby.impl.store.raw.log.Scan.getNextRecordForward(Scan.java:810)
at org.apache.derby.impl.store.raw.log.Scan.getNextRecord(Scan.java:206)
at org.apache.derby.impl.store.raw.log.FileLogger.readLogRecord(FileLogger.java:1612)
at org.apache.derby.impl.store.raw.log.LogToFile.findCheckpoint(LogToFile.java:2806)
at org.apache.derby.impl.store.raw.log.LogToFile.recover(LogToFile.java:756)
at org.apache.derby.impl.store.raw.RawStore.boot(RawStore.java:339)
...

Perhaps derby wrote an incomplete log record, and now cannot recover? Also, if I delete the log control file (log.ctrl) then I can connect OK. But if I do this, is there risk that some transactions will be lost? (I think so).

I have the database that causes this error, but I prefer to not post it to the bug log or mailing list. But if someone emails me directly, I will supply it.