NullPointerException in ....B2IRowLocking3.searchLeftAndLockPreviousKey

• Key: DERBY-3244
• Type: Bug
• Status: Closed
• Resolution: Fixed
• Priority: Major
• Assignee: Mike Matrigali
• Reporter: Ole Solberg
• Component/s: Store
• Affects Version/s: 10.3.2.1, 10.4.1.3
• Fix Version/s: 10.3.3.0, 10.4.1.3

Description

The last week(48) we have seen a large number of this failure.

It was categorized as DERBY-2589 but these instances all have the NPE.


Exception while trying to insert row number: 52
ERROR XJ001: Java exception: ': java.lang.NullPointerException'.
java.sql.SQLException: Java exception: ': java.lang.NullPointerException'.
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)
at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(Unknown Source)
at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(Unknown Source)
at org.apache.derby.impl.jdbc.EmbedConnection.handleException(Unknown Source)
at org.apache.derby.impl.jdbc.ConnectionChild.handleException(Unknown Source)
at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(Unknown Source)
at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(Unknown Source)
at org.apache.derby.impl.jdbc.EmbedPreparedStatement.execute(Unknown Source)
at org.apache.derbyTesting.functionTests.tests.store.OnlineCompressTest.createAndLoadTable(OnlineCompressTest.java:140)
at org.apache.derbyTesting.functionTests.tests.store.OnlineCompressTest.deleteAllRows(OnlineCompressTest.java:494)
at org.apache.derbyTesting.functionTests.tests.store.OnlineCompressTest.test1(OnlineCompressTest.java:913)
at org.apache.derbyTesting.functionTests.tests.store.OnlineCompressTest.testList(OnlineCompressTest.java:1500)
at org.apache.derbyTesting.functionTests.tests.store.OnlineCompressTest.main(OnlineCompressTest.java:1520)
Caused by: java.lang.NullPointerException
at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.searchLeftAndLockPreviousKey(Unknown Source)
at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockNonScanPreviousRow(Unknown Source)
at org.apache.derby.impl.store.access.btree.BTreeController.doIns(Unknown Source)
at org.apache.derby.impl.store.access.btree.BTreeController.insert(Unknown Source)
at org.apache.derby.impl.store.access.btree.index.B2IController.insert(Unknown Source)
at org.apache.derby.impl.sql.execute.IndexChanger.insertAndCheckDups(Unknown Source)
at org.apache.derby.impl.sql.execute.IndexChanger.doInsert(Unknown Source)
at org.apache.derby.impl.sql.execute.IndexChanger.insert(Unknown Source)
at org.apache.derby.impl.sql.execute.IndexSetChanger.insert(Unknown Source)
at org.apache.derby.impl.sql.execute.RowChangerImpl.insertRow(Unknown Source)
at org.apache.derby.impl.sql.execute.InsertResultSet.normalInsertCore(Unknown Source)
at org.apache.derby.impl.sql.execute.InsertResultSet.open(Unknown Source)
at org.apache.derby.impl.sql.GenericPreparedStatement.execute(Unknown Source)
... 8 more


The error statistics shows the occurrences:
(http://dbtg.thresher.com/derby/test/stats_today.html / http://dbtg.thresher.com/derby/test/stats_newest.html )

http://dbtg.thresher.com/derby/test/statistics/2589_48.html :
JIRA: 2589, Week: 48 600335-598009
598009 Daily jvm1.4 vista
598009 Daily jvm1.6 lin
598341 Daily jvm1.6 solN+1
598341 Daily jvm1.6 sparc
598354 10.3Branch jvm1.5 lin
598376 trunk16 jvmAll JDK16Jvm1.5SunOS-5.10_i86pc-i386
598692 Daily jvm1.6 sol
598729 trunk16 jvmAll JDK16Jvm1.6SunOS-5.10_i86pc-i386
599062 Daily jvm1.5 lin
599088 trunk15 jvm1.5 SunOS-5.10_i86pc-i386
599088 trunk15 jvm1.5 SunOS-5.10_sun4u-sparc
599088 trunk16 jvmAll JDK16Jvm1.5SunOS-5.10_i86pc-i386
600335 Daily jvm1.4 lin
Mon Dec 3 09:36:11 CET 2007

http://dbtg.thresher.com/derby/test/statistics/2589_47.html seems to be the first occurence:
JIRA: 2589, Week: 47 597885-597885
597885 Daily jvm1.6 lin
Mon Dec 3 09:36:13 CET 2007

All are seen on trunk except one on the 10.3 branch (598354 10.3Branch jvm1.5 lin).

Comments

[Mike Matrigali]

Do you have any of these failures that include a line number for where the null pointer error happened. If so please post the stack with the line number.

[Ole Solberg]

Got one occurrence of the failure in ~10 attempts:


----------------------------------------------------------------
2007-12-10 13:16:02.173 GMT:
 Booting Derby version The Apache Software Foundation - Apache Derby - 10.4.0.0 alpha - (602814): instance c013800d-0116-c432-a688-00000d5a7df3
on database directory /export/home/tmp/os136789/myCleanSandbox/storemore/storemore/OnlineCompressTest/wombat

Database Class Loader started - derby.database.classpath=''
2007-12-10 13:16:23.867 GMT Thread[main,5,main] (XID = 24422), (SESSIONID = 0), (DATABASE = wombat), (DRDAID = null), Cleanup action starting
2007-12-10 13:16:23.867 GMT Thread[main,5,main] (XID = 24422), (SESSIONID = 0), (DATABASE = wombat), (DRDAID = null), Failed Statement is: insert into TEST1 values(?, ?, ?, ?, ?, ?) with 6 parameters begin parameter #1: 247 :end parameter begin parameter #2: 2470 :end parameter begin parameter #3: 24700 :end parameter begin parameter #4: -247 :end parameter begin parameter #5: aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa :end parameter begin parameter #6: bbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbbb :end parameter
java.lang.NullPointerException
at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.searchLeftAndLockPreviousKey(B2IRowLocking3.java:458)
at org.apache.derby.impl.store.access.btree.index.B2IRowLocking3.lockNonScanPreviousRow(B2IRowLocking3.java:964)
at org.apache.derby.impl.store.access.btree.BTreeController.doIns(BTreeController.java:444)
at org.apache.derby.impl.store.access.btree.BTreeController.insert(BTreeController.java:1035)
at org.apache.derby.impl.store.access.btree.index.B2IController.insert(B2IController.java:211)
at org.apache.derby.impl.sql.execute.IndexChanger.insertAndCheckDups(IndexChanger.java:439)
at org.apache.derby.impl.sql.execute.IndexChanger.doInsert(IndexChanger.java:383)
at org.apache.derby.impl.sql.execute.IndexChanger.insert(IndexChanger.java:589)
at org.apache.derby.impl.sql.execute.IndexSetChanger.insert(IndexSetChanger.java:268)
at org.apache.derby.impl.sql.execute.RowChangerImpl.insertRow(RowChangerImpl.java:453)
at org.apache.derby.impl.sql.execute.InsertResultSet.normalInsertCore(InsertResultSet.java:1011)
at org.apache.derby.impl.sql.execute.InsertResultSet.open(InsertResultSet.java:487)
at org.apache.derby.impl.sql.GenericPreparedStatement.execute(GenericPreparedStatement.java:370)
at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(EmbedStatement.java:1234)
at org.apache.derby.impl.jdbc.EmbedPreparedStatement.executeStatement(EmbedPreparedStatement.java:1650)
at org.apache.derby.impl.jdbc.EmbedPreparedStatement.execute(EmbedPreparedStatement.java:1305)
at org.apache.derbyTesting.functionTests.tests.store.OnlineCompressTest.createAndLoadTable(OnlineCompressTest.java:140)
at org.apache.derbyTesting.functionTests.tests.store.OnlineCompressTest.checkPurgePhase(OnlineCompressTest.java:780)
at org.apache.derbyTesting.functionTests.tests.store.OnlineCompressTest.test1(OnlineCompressTest.java:916)
at org.apache.derbyTesting.functionTests.tests.store.OnlineCompressTest.testList(OnlineCompressTest.java:1500)
at org.apache.derbyTesting.functionTests.tests.store.OnlineCompressTest.main(OnlineCompressTest.java:1520)
Cleanup action completed

[Mike Matrigali]

Thanks ole, that helps a lot. I wasn't having much success reproducing on my machine by just running the
test, but was able to force
a path through the code in the debuggger that got a null at the point in your stack trace. I will be checking in fix after tests pass.

checked in fix to trunk:
m2_ibm15:42>svn commit

Sending java\engine\org\apache\derby\impl\store\access\btree\BTreeLockingPolicy.java
Sending java\engine\org\apache\derby\impl\store\access\btree\index\B2IRowLocking3.java
Transmitting file data ..
Committed revision 603375.

I will wait awhile before closing as I never actually could make the bug happen by running the test on my laptop. The fix does stop the nullpointer at the line number that Ole reported, and that I caused by hand by forcing the code through the left latch wait error path.

[Ole Solberg]

I did 100 storemore test runs on 603375 without seeing the failure.
(On 603319 it hit after 11 runs.)

[Kathey Marsden]

Fixing the fix version. This went into the 10.3 branch at 603774 and the 10.3.2.1 release was at 599110.