db-derby-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Mike Matrigali (JIRA)" <j...@apache.org>
Subject [jira] [Issue Comment Edited] (DERBY-5248) Java Process Crash Causes Corrupt DB
Date Wed, 01 Jun 2011 18:43:47 GMT

    [ https://issues.apache.org/jira/browse/DERBY-5248?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13042354#comment-13042354
] 

Mike Matrigali edited comment on DERBY-5248 at 6/1/11 6:42 PM:
---------------------------------------------------------------

After pouring through the log records and what runs during recovery I have found at the following
problem.  

The problem occurs while backing a purge on a btree.  The normal place for this to happen
would be by the background daemon doing post commit work,
although this work can fall back on the actual user thread for various reasons.  I can't tell
from what I have exactly where the purges came from.  I do know
the purges are space reclamation and not splits because they are all one row at a time.  
The actual problem is proper undo requires that the system always
insure that there will be enough space to do the undo.  In this case there is not enough space
and the application of the undo actually trashes the page by
the data of the row which grows from the front of page backward overwriting the slot table
which grows from the back of the page toward the top.  

The problem set of log records is evident from the last few records in the log:

... many records leading to the end
 10946 : Page Op: Page(1,C(0, 1409)) pv 27734 : Purge : 1 slots  1 (recordId=8038) instant
= (1,30696447) logEnd = (1,30696511)
 10944 : Page Op: Page(1,C(0, 1409)) pv 27735 : Insert :  Slot=352 recordId=9452 instant =
(1,30696511) logEnd = (1,30696580)
 10944 : Page Op: Page(2,C(0, 1168)) pv 6403 : Update  Slot=5 recordId=11 instant = (1,30696580)
logEnd = (1,30696713)
 10944 : EndXact null Committed : transactionStatus =  Committed instant = (1,30696713) logEnd
= (1,30696746)
DEBUG LogTrace OUTPUT: detected zapped log end on log file 1 end marker at 30696746 real end
at 134217728^M
DEBUG LogTrace OUTPUT: C:\tmp\_t\objectdb\log\log2.dat does not exist^M

The problem is that transaction 10946 purges a row from page 1 which actually removes the
bytes from the page and then before that transaction
commits and or aborts transaction 10944 inserts a row on page 1 and commits.  There never
is an abort or commit in the log for the purge indicating
that the test crash happened before the commit could be made.  Because undo always requires
space be available purges should always be 
committed/aborted before allowing any other access to page.  Note the heap code does this
correctly by not releasing the latch explicitly but instead
leaving it latched and letting commit unlatch it with the following code segment, it may
be a little harder in btree due to the datastructures:
 // If no purge happened on the page and the page is not
 // removed, feel free to unlatch it.  Otherwise, let
 // transaction commit take care of it.
 if (!purgingDone)
 {
     page.unlatch();
     page = null;
 }

By code inspection I looked at btree post commit and there is a problem there which I logged
as DERBY-5258.   I have been trying to reproduce this
with a real system but have not been able to so far.  The "distance" from the time the latch
on page1 is released by the purge and the commit happens
is only a few instructions so I was surprised that it could be made to happen.  I did note
however that for the bug to happen as we see in this
database we don't need the crash to happen exactly in these few instructions, only that another
thread gets the latch on the page and does an insert
on the page before the commit.  This is because the internal transaction does a "no sync"
commit for performance reasons, which only puts the
log record into the buffer.  A crash anytime before that buffer is written to disk by filling
or by a real commit would leave the db in the state that it is.

Some things that may be making this application more likely to hit this are:
o the btree index row is small so there are a lot of rows on page 1 of the index
o there seems to be a LOT of inserts and deletes on page 1 of the index
o The application has set a very large log buffer size - I didn't even know people were playing
with this tuning option

      was (Author: mikem):
    After pouring through the log records and what runs during recovery I have found at the
following problem.  

The problem occurs while backing a purge on a btree.  The normal place for this to happen
would be by the background daemon doing post commit work,
although this work can fall back on the actual user thread for various reasons.  I can't tell
from what I have exactly where the purges came from.  I do know
the purges are space reclamation and not splits because they are all one row at a time.  
The actual problem is proper undo requires that the system always
insure that there will be enough space to do the undo.  In this case there is not enough space
and the application of the undo actually trashes the page by
the data of the row which grows from the front of page backward overwriting the slot table
which grows from the back of the page toward the top.  

The problem set of log records is evident from the last few records in the log:

... many records leading to the end
 10946 : Page Op: Page(1,C(0, 1409)) pv 27734 : Purge : 1 slots  1 (recordId=8038) instant
= (1,30696447) logEnd = (1,30696511)
 10944 : Page Op: Page(1,C(0, 1409)) pv 27735 : Insert :  Slot=352 recordId=9452 instant =
(1,30696511) logEnd = (1,30696580)
 10944 : Page Op: Page(2,C(0, 1168)) pv 6403 : Update  Slot=5 recordId=11 instant = (1,30696580)
logEnd = (1,30696713)
 10944 : EndXact null Committed : transactionStatus =  Committed instant = (1,30696713) logEnd
= (1,30696746)
DEBUG LogTrace OUTPUT: detected zapped log end on log file 1 end marker at 30696746 real end
at 134217728^M
DEBUG LogTrace OUTPUT: C:\tmp\_t\objectdb\log\log2.dat does not exist^M

The problem is that transaction 10946 purges a row from page 1 which actually removes the
bytes from the page and then before that transaction
commits and or aborts transaction 10944 inserts a row on page 1 and commits.  There never
is an abort or commit in the log for the purge indicating
that the test crash happened before the commit could be made.  Because undo always requires
space be available purges should always be 
committed/aborted before allowing any other access to page.  Note the heap code does this
correctly by not releasing the latch explicitly but instead
leaving it latched and letting commit unlatch it with the following code segment, it may
be a little harder in btree due to the datastructures:
 // If no purge happened on the page and the page is not
 // removed, feel free to unlatch it.  Otherwise, let
 // transaction commit take care of it.
 if (!purgingDone)
 {
     page.unlatch();
     page = null;
 }

By code inspection I looked at btree post commit and there is a problem there which I logged
as DERBY-5358.   I have been trying to reproduce this
with a real system but have not been able to so far.  The "distance" from the time the latch
on page1 is released by the purge and the commit happens
is only a few instructions so I was surprised that it could be made to happen.  I did note
however that for the bug to happen as we see in this
database we don't need the crash to happen exactly in these few instructions, only that another
thread gets the latch on the page and does an insert
on the page before the commit.  This is because the internal transaction does a "no sync"
commit for performance reasons, which only puts the
log record into the buffer.  A crash anytime before that buffer is written to disk by filling
or by a real commit would leave the db in the state that it is.

Some things that may be making this application more likely to hit this are:
o the btree index row is small so there are a lot of rows on page 1 of the index
o there seems to be a LOT of inserts and deletes on page 1 of the index
o The application has set a very large log buffer size - I didn't even know people were playing
with this tuning option
  
> Java Process Crash Causes Corrupt DB
> ------------------------------------
>
>                 Key: DERBY-5248
>                 URL: https://issues.apache.org/jira/browse/DERBY-5248
>             Project: Derby
>          Issue Type: Bug
>          Components: Store
>    Affects Versions: 10.8.1.2
>         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
>            Reporter: Tim Wu
>             Fix For: 10.8.1.3
>
>         Attachments: c581.dat.xml.gz, ij_recovery_log_trace.log.gz, log.ctrl.xml, log1.dat.xml.gz,
objectdb.zip
>
>
> 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.
>  

--
This message is automatically generated by JIRA.
For more information on JIRA, see: http://www.atlassian.com/software/jira

Mime
View raw message