[DERBY-5248] Java Process Crash Causes Corrupt DB

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 10.8.1.2
• Fix Version/s: 10.8.2.2
• Component/s: Store
• Environment: Red Hat Enterprise Linux ES release 4 (Nahant Update 7); java version "1.6.0_01"; Java(TM) SE Runtime Environment (build 1.6.0_01-b06); Java HotSpot(TM) Server VM (build 1.6.0_01-b06, mixed mode); Derby 10.8.1.2
• Urgency: Normal
• Issue & fix info: Repro attached
• Bug behavior facts: Crash, Data corruption, Seen in production
• Assignee: Mike Matrigali
• Reporter: Tim Wu
• Created: 26/May/11 23:17
• Updated: 17/Jun/13 09:19
• Resolved: 16/Feb/12 14:07

Description

During some crash tests on our product, we hit an issue where after a crash, the derby db is stuck in a corrupted state. The db fails to boot with the following error when started up with the debug jar:

org.apache.derby.shared.common.sanity.AssertFailure: ASSERT FAILED incorrect deleted row count. Should be: 903, instead got: 902, maxSlot = 1255, recordCount = 1255
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.data.BasePage.internalNonDeletedRecordCount(BasePage.java:1432)
at org.apache.derby.impl.store.raw.data.CachedPage.releaseExclusive(CachedPage.java:488)
at org.apache.derby.impl.store.raw.data.StoredPage.releaseExclusive(StoredPage.java:1066)
at org.apache.derby.impl.store.raw.data.BasePage.unlatch(BasePage.java:1370)
at org.apache.derby.impl.store.raw.data.PageBasicOperation.releaseResource(PageBasicOperation.java:195)
at org.apache.derby.impl.store.raw.data.PhysicalUndoOperation.releaseResource(PhysicalUndoOperation.java:177)
at org.apache.derby.impl.store.raw.log.FileLogger.undo(FileLogger.java:1055)
at org.apache.derby.impl.store.raw.xact.Xact.abort(Xact.java:952)
at org.apache.derby.impl.store.raw.xact.XactFactory.rollbackAllTransactions(XactFactory.java:547)
at org.apache.derby.impl.store.raw.log.LogToFile.recover(LogToFile.java:1229)
at org.apache.derby.impl.store.raw.RawStore.boot(RawStore.java:339)
at org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1982)
at org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:334)
at org.apache.derby.impl.services.monitor.BaseMonitor.startModule(BaseMonitor.java:531)
at org.apache.derby.iapi.services.monitor.Monitor.bootServiceModule(Monitor.java:427)
at org.apache.derby.impl.store.access.RAMAccessManager.boot(RAMAccessManager.java:1019)
at org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1982)
at org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:334)
at org.apache.derby.impl.services.monitor.BaseMonitor.startModule(BaseMonitor.java:531)
at org.apache.derby.iapi.services.monitor.Monitor.bootServiceModule(Monitor.java:427)
at org.apache.derby.impl.db.BasicDatabase.bootStore(BasicDatabase.java:749)
at org.apache.derby.impl.db.BasicDatabase.boot(BasicDatabase.java:177)
at org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1982)
at org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:334)
at org.apache.derby.impl.services.monitor.BaseMonitor.bootService(BaseMonitor.java:1816)
at org.apache.derby.impl.services.monitor.BaseMonitor.startProviderService(BaseMonitor.java:1682)
at org.apache.derby.impl.services.monitor.BaseMonitor.findProviderAndStartService(BaseMonitor.java:1560)
at org.apache.derby.impl.services.monitor.BaseMonitor.startPersistentService(BaseMonitor.java:979)
at org.apache.derby.iapi.services.monitor.Monitor.startPersistentService(Monitor.java:550)
at org.apache.derby.impl.jdbc.EmbedConnection.bootDatabase(EmbedConnection.java:2697)
at org.apache.derby.impl.jdbc.EmbedConnection.<init>(EmbedConnection.java:385)
at org.apache.derby.impl.jdbc.EmbedConnection30.<init>(EmbedConnection30.java:73)
at org.apache.derby.impl.jdbc.EmbedConnection40.<init>(EmbedConnection40.java:51)
at org.apache.derby.jdbc.Driver40.getNewEmbedConnection(Driver40.java:70)
at org.apache.derby.jdbc.InternalDriver.connect(InternalDriver.java:248)
at org.apache.derby.jdbc.AutoloadedDriver.connect(AutoloadedDriver.java:144)
at java.sql.DriverManager.getConnection(DriverManager.java:582)
at java.sql.DriverManager.getConnection(DriverManager.java:154)
at OpenDerby.main(OpenDerby.java:17)
---------------
Stack traces for all live threads:
Thread name=main id=1 priority=5 state=RUNNABLE isdaemon=false
java.lang.Thread.dumpThreads(Native Method)
java.lang.Thread.getAllStackTraces(Thread.java:1554)
org.apache.derby.shared.common.sanity.ThreadDump.getStackDumpString(ThreadDump.java:34)
sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
java.lang.reflect.Method.invoke(Method.java:597)
org.apache.derby.shared.common.sanity.AssertFailure$1.run(AssertFailure.java:165)
java.security.AccessController.doPrivileged(Native Method)
org.apache.derby.shared.common.sanity.AssertFailure.dumpThreads(AssertFailure.java:159)
org.apache.derby.shared.common.sanity.AssertFailure.<init>(AssertFailure.java:72)
org.apache.derby.shared.common.sanity.SanityManager.THROWASSERT(SanityManager.java:162)
org.apache.derby.shared.common.sanity.SanityManager.THROWASSERT(SanityManager.java:147)
org.apache.derby.impl.store.raw.data.BasePage.internalNonDeletedRecordCount(BasePage.java:1432)
org.apache.derby.impl.store.raw.data.CachedPage.releaseExclusive(CachedPage.java:488)
org.apache.derby.impl.store.raw.data.StoredPage.releaseExclusive(StoredPage.java:1066)
org.apache.derby.impl.store.raw.data.BasePage.unlatch(BasePage.java:1370)
org.apache.derby.impl.store.raw.data.PageBasicOperation.releaseResource(PageBasicOperation.java:195)
org.apache.derby.impl.store.raw.data.PhysicalUndoOperation.releaseResource(PhysicalUndoOperation.java:177)
org.apache.derby.impl.store.raw.log.FileLogger.undo(FileLogger.java:1055)
org.apache.derby.impl.store.raw.xact.Xact.abort(Xact.java:952)
org.apache.derby.impl.store.raw.xact.XactFactory.rollbackAllTransactions(XactFactory.java:547)
org.apache.derby.impl.store.raw.log.LogToFile.recover(LogToFile.java:1229)
org.apache.derby.impl.store.raw.RawStore.boot(RawStore.java:339)
org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1982)
org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:334)
org.apache.derby.impl.services.monitor.BaseMonitor.startModule(BaseMonitor.java:531)
org.apache.derby.iapi.services.monitor.Monitor.bootServiceModule(Monitor.java:427)
org.apache.derby.impl.store.access.RAMAccessManager.boot(RAMAccessManager.java:1019)
org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1982)
org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:334)
org.apache.derby.impl.services.monitor.BaseMonitor.startModule(BaseMonitor.java:531)
org.apache.derby.iapi.services.monitor.Monitor.bootServiceModule(Monitor.java:427)
org.apache.derby.impl.db.BasicDatabase.bootStore(BasicDatabase.java:749)
org.apache.derby.impl.db.BasicDatabase.boot(BasicDatabase.java:177)
org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1982)
org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:334)
org.apache.derby.impl.services.monitor.BaseMonitor.bootService(BaseMonitor.java:1816)
org.apache.derby.impl.services.monitor.BaseMonitor.startProviderService(BaseMonitor.java:1682)
org.apache.derby.impl.services.monitor.BaseMonitor.findProviderAndStartService(BaseMonitor.java:1560)
org.apache.derby.impl.services.monitor.BaseMonitor.startPersistentService(BaseMonitor.java:979)
org.apache.derby.iapi.services.monitor.Monitor.startPersistentService(Monitor.java:550)
org.apache.derby.impl.jdbc.EmbedConnection.bootDatabase(EmbedConnection.java:2697)
org.apache.derby.impl.jdbc.EmbedConnection.<init>(EmbedConnection.java:385)
org.apache.derby.impl.jdbc.EmbedConnection30.<init>(EmbedConnection30.java:73)
org.apache.derby.impl.jdbc.EmbedConnection40.<init>(EmbedConnection40.java:51)
org.apache.derby.jdbc.Driver40.getNewEmbedConnection(Driver40.java:70)
org.apache.derby.jdbc.InternalDriver.connect(InternalDriver.java:248)
org.apache.derby.jdbc.AutoloadedDriver.connect(AutoloadedDriver.java:144)
java.sql.DriverManager.getConnection(DriverManager.java:582)
java.sql.DriverManager.getConnection(DriverManager.java:154)
OpenDerby.main(OpenDerby.java:17)

Thread name=derby.rawStoreDaemon id=12 priority=5 state=TIMED_WAITING isdaemon=true
java.lang.Object.wait(Native Method)
org.apache.derby.impl.services.daemon.BasicDaemon.rest(BasicDaemon.java:576)
org.apache.derby.impl.services.daemon.BasicDaemon.run(BasicDaemon.java:390)
java.lang.Thread.run(Thread.java:680)

Thread name=Finalizer id=3 priority=8 state=WAITING isdaemon=true
java.lang.Object.wait(Native Method)
java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

Thread name=Reference Handler id=2 priority=10 state=WAITING isdaemon=true
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:485)
java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)

Thread name=Signal Dispatcher id=6 priority=9 state=RUNNABLE isdaemon=true

Thread name=Timer-0 id=10 priority=5 state=WAITING isdaemon=true
java.lang.Object.wait(Native Method)
java.lang.Object.wait(Object.java:485)
java.util.TimerThread.mainLoop(Timer.java:483)
java.util.TimerThread.run(Timer.java:462)

---------------

Exception in thread "main" java.sql.SQLException: Failed to start database '/Users/tim/Downloads/LinkedBlockingQueueCrashTest/objectdb/datadb' with class loader sun.misc.Launcher$AppClassLoader@40affc70, see the next exception for details.
at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:98)
at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Util.java:142)
at org.apache.derby.impl.jdbc.Util.seeNextException(Util.java:278)
at org.apache.derby.impl.jdbc.EmbedConnection.bootDatabase(EmbedConnection.java:2736)
at org.apache.derby.impl.jdbc.EmbedConnection.<init>(EmbedConnection.java:385)
at org.apache.derby.impl.jdbc.EmbedConnection30.<init>(EmbedConnection30.java:73)
at org.apache.derby.impl.jdbc.EmbedConnection40.<init>(EmbedConnection40.java:51)
at org.apache.derby.jdbc.Driver40.getNewEmbedConnection(Driver40.java:70)
at org.apache.derby.jdbc.InternalDriver.connect(InternalDriver.java:248)
at org.apache.derby.jdbc.AutoloadedDriver.connect(AutoloadedDriver.java:144)
at java.sql.DriverManager.getConnection(DriverManager.java:582)
at java.sql.DriverManager.getConnection(DriverManager.java:154)
at OpenDerby.main(OpenDerby.java:17)
Caused by: java.sql.SQLException: Failed to start database '/Users/tim/Downloads/LinkedBlockingQueueCrashTest/objectdb/datadb' with class loader sun.misc.Launcher$AppClassLoader@40affc70, see the next exception for details.
at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:45)
at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(SQLExceptionFactory40.java:122)
at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:71)
... 12 more
Caused by: java.sql.SQLException: Java exception: 'ASSERT FAILED incorrect deleted row count. Should be: 903, instead got: 902, maxSlot = 1255, recordCount = 1255: org.apache.derby.shared.common.sanity.AssertFailure'.
at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:45)
at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(SQLExceptionFactory40.java:122)
at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:71)
at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Util.java:142)
at org.apache.derby.impl.jdbc.Util.javaException(Util.java:299)
at org.apache.derby.impl.jdbc.EmbedConnection.bootDatabase(EmbedConnection.java:2732)
... 9 more
Caused by: org.apache.derby.shared.common.sanity.AssertFailure: ASSERT FAILED incorrect deleted row count. Should be: 903, instead got: 902, maxSlot = 1255, recordCount = 1255
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.data.BasePage.internalNonDeletedRecordCount(BasePage.java:1432)
at org.apache.derby.impl.store.raw.data.CachedPage.releaseExclusive(CachedPage.java:488)
at org.apache.derby.impl.store.raw.data.StoredPage.releaseExclusive(StoredPage.java:1066)
at org.apache.derby.impl.store.raw.data.BasePage.unlatch(BasePage.java:1370)
at org.apache.derby.impl.store.raw.data.PageBasicOperation.releaseResource(PageBasicOperation.java:195)
at org.apache.derby.impl.store.raw.data.PhysicalUndoOperation.releaseResource(PhysicalUndoOperation.java:177)
at org.apache.derby.impl.store.raw.log.FileLogger.undo(FileLogger.java:1055)
at org.apache.derby.impl.store.raw.xact.Xact.abort(Xact.java:952)
at org.apache.derby.impl.store.raw.xact.XactFactory.rollbackAllTransactions(XactFactory.java:547)
at org.apache.derby.impl.store.raw.log.LogToFile.recover(LogToFile.java:1229)
at org.apache.derby.impl.store.raw.RawStore.boot(RawStore.java:339)
at org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1982)
at org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:334)
at org.apache.derby.impl.services.monitor.BaseMonitor.startModule(BaseMonitor.java:531)
at org.apache.derby.iapi.services.monitor.Monitor.bootServiceModule(Monitor.java:427)
at org.apache.derby.impl.store.access.RAMAccessManager.boot(RAMAccessManager.java:1019)
at org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1982)
at org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:334)
at org.apache.derby.impl.services.monitor.BaseMonitor.startModule(BaseMonitor.java:531)
at org.apache.derby.iapi.services.monitor.Monitor.bootServiceModule(Monitor.java:427)
at org.apache.derby.impl.db.BasicDatabase.bootStore(BasicDatabase.java:749)
at org.apache.derby.impl.db.BasicDatabase.boot(BasicDatabase.java:177)
at org.apache.derby.impl.services.monitor.BaseMonitor.boot(BaseMonitor.java:1982)
at org.apache.derby.impl.services.monitor.TopService.bootModule(TopService.java:334)
at org.apache.derby.impl.services.monitor.BaseMonitor.bootService(BaseMonitor.java:1816)
at org.apache.derby.impl.services.monitor.BaseMonitor.startProviderService(BaseMonitor.java:1682)
at org.apache.derby.impl.services.monitor.BaseMonitor.findProviderAndStartService(BaseMonitor.java:1560)
at org.apache.derby.impl.services.monitor.BaseMonitor.startPersistentService(BaseMonitor.java:979)
at org.apache.derby.iapi.services.monitor.Monitor.startPersistentService(Monitor.java:550)
at org.apache.derby.impl.jdbc.EmbedConnection.bootDatabase(EmbedConnection.java:2697)
... 9 more

It also fails with a slightly different error using the non-debug jar:

Exception in thread "main" java.sql.SQLException: Failed to start database '/Users/tim/Downloads/LinkedBlockingQueueCrashTest/objectdb/datadb' with class loader sun.misc.Launcher$AppClassLoader@40affc70, see the next exception for details.
at org.apache.derby.impl.jdbc.SQLExceptionFactory40.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.impl.jdbc.EmbedConnection40.<init>(Unknown Source)
at org.apache.derby.jdbc.Driver40.getNewEmbedConnection(Unknown Source)
at org.apache.derby.jdbc.InternalDriver.connect(Unknown Source)
at org.apache.derby.jdbc.AutoloadedDriver.connect(Unknown Source)
at java.sql.DriverManager.getConnection(DriverManager.java:582)
at java.sql.DriverManager.getConnection(DriverManager.java:154)
at OpenDerby.main(OpenDerby.java:16)
Caused by: java.sql.SQLException: Failed to start database '/Users/tim/Downloads/LinkedBlockingQueueCrashTest/objectdb/datadb' with class loader sun.misc.Launcher$AppClassLoader@40affc70, see the next exception for details.
at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(Unknown Source)
... 13 more
Caused by: java.sql.SQLException: An exception was thrown during transaction abort.
at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(Unknown Source)
at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(Unknown Source)
at org.apache.derby.impl.jdbc.Util.generateCsSQLException(Unknown Source)
... 10 more
Caused by: ERROR XSTB0: An exception was thrown during transaction abort.
at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
at org.apache.derby.impl.store.raw.xact.Xact.abort(Unknown Source)
at org.apache.derby.impl.store.raw.xact.XactFactory.rollbackAllTransactions(Unknown Source)
at org.apache.derby.impl.store.raw.log.LogToFile.recover(Unknown Source)
at org.apache.derby.impl.store.raw.RawStore.boot(Unknown Source)
at org.apache.derby.impl.services.monitor.BaseMonitor.boot(Unknown Source)
at org.apache.derby.impl.services.monitor.TopService.bootModule(Unknown Source)
at org.apache.derby.impl.services.monitor.BaseMonitor.startModule(Unknown Source)
at org.apache.derby.iapi.services.monitor.Monitor.bootServiceModule(Unknown Source)
at org.apache.derby.impl.store.access.RAMAccessManager.boot(Unknown Source)
at org.apache.derby.impl.services.monitor.BaseMonitor.boot(Unknown Source)
at org.apache.derby.impl.services.monitor.TopService.bootModule(Unknown Source)
at org.apache.derby.impl.services.monitor.BaseMonitor.startModule(Unknown Source)
at org.apache.derby.iapi.services.monitor.Monitor.bootServiceModule(Unknown Source)
at org.apache.derby.impl.db.BasicDatabase.bootStore(Unknown Source)
at org.apache.derby.impl.db.BasicDatabase.boot(Unknown Source)
at org.apache.derby.impl.services.monitor.BaseMonitor.boot(Unknown Source)
at org.apache.derby.impl.services.monitor.TopService.bootModule(Unknown Source)
at org.apache.derby.impl.services.monitor.BaseMonitor.bootService(Unknown Source)
at org.apache.derby.impl.services.monitor.BaseMonitor.startProviderService(Unknown Source)
at org.apache.derby.impl.services.monitor.BaseMonitor.findProviderAndStartService(Unknown Source)
at org.apache.derby.impl.services.monitor.BaseMonitor.startPersistentService(Unknown Source)
at org.apache.derby.iapi.services.monitor.Monitor.startPersistentService(Unknown Source)
... 10 more
Caused by: ERROR XSLA8: Cannot rollback transaction 10946, trying to compensate null operation with null
at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
at org.apache.derby.impl.store.raw.log.FileLogger.undo(Unknown Source)
... 32 more
Caused by: ERROR XSLA1: Log Record has been sent to the stream, but it cannot be applied to the store (Object null). This may cause recovery problems also.
at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
at org.apache.derby.impl.store.raw.log.FileLogger.logAndUndo(Unknown Source)
at org.apache.derby.impl.store.raw.xact.Xact.logAndUndo(Unknown Source)
... 33 more
Caused by: ERROR XSDB0: Unexpected exception on in-memory page Page(1,Container(0, 1409))
at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
at org.apache.derby.impl.store.raw.data.StoredPage.storeRecordForInsert(Unknown Source)
at org.apache.derby.impl.store.raw.data.StoredPage.storeRecord(Unknown Source)
at org.apache.derby.impl.store.raw.data.PurgeOperation.undoMe(Unknown Source)
at org.apache.derby.impl.store.raw.data.PhysicalUndoOperation.doMe(Unknown Source)
... 35 more

I have the zipped up db that causes the problem. Will attach it to this bug report.

Issue Links

• blocks: DERBY-5258 btree post commit releases latch before committing/aborting purges, possibly allowing other operation on page
• is related to: DERBY-5281 Derby DB Corrupt After Crash
• relates to: DERBY-5258 btree post commit releases latch before committing/aborting purges, possibly allowing other operation on page
• relates to: DERBY-5284 A derby crash at exactly right time during a btree split can cause a corrupt db which can not be booted.