Derby
  1. Derby
  2. DERBY-4676

NullPointerException on SELECT on INNER JOIN

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 10.5.3.0, 10.6.1.0
    • Fix Version/s: 10.5.3.1, 10.6.2.1, 10.7.1.1
    • Component/s: Store
    • Environment:

      Description

      Running into a NullPointerException error in the Apache Derby database over multiple versions of the derby jars. From testing, this issue intermittently occurs during moderate load test scenarios, but has never occurred in production. This is using Derby as embedded and always occurs on the same statement as shown below and in the attachment. Following the error, hibernate throws an exception which results in the code attempting to rollback the transaction. The rollback fails as the NullPointerException appears to kill the connection.

          • derby.log

      2010-04-27 16:05:22.429 GMT Thread[SNMPDelayedStoreRunnable2Thread,5,main] (XID = 244546), (SESSIONID = 17), (DATABASE = db), (DRDAID = null), Cleanup action starting
      2010-04-27 16:05:22.429 GMT Thread[SNMPDelayedStoreRunnable2Thread,5,main] (XID = 244546), (SESSIONID = 17), (DATABASE = db), (DRDAID = null), Failed Statement is: select nonprimary0_.componentid as componen1_1_, nonprimary0_.deviceid as deviceid1_, device1_.deviceid as deviceid0_, device1_.name as name3_0_, device1_.description as descript3_3_0_, device1_.device_type as device4_3_0_, device1_.managed_address as managed5_3_0_, device1_.csid as csid3_0_, device1_.url as url3_0_, device1_.date_written_to_db as date8_3_0_, device1_.valid as valid3_0_, device1_.invalid_reason as invalid10_3_0_, device1_.version as version3_0_ from subsystem_callserver_map nonprimary0_ inner join device_data device1_ on nonprimary0_.deviceid=device1_.deviceid where nonprimary0_.componentid=? with 1 parameters begin parameter #1: 86b5b069-ca5c-4c38-9643-d9308c246100 :end parameter
      java.lang.NullPointerException
      at org.apache.derby.impl.store.access.conglomerate.GenericConglomerateController.fetch(Unknown Source)
      at org.apache.derby.impl.sql.execute.IndexRowToBaseRowResultSet.getNextRowCore(Unknown Source)
      at org.apache.derby.impl.sql.execute.NestedLoopJoinResultSet.getNextRowCore(Unknown Source)
      at org.apache.derby.impl.sql.execute.BasicNoPutResultSetImpl.getNextRow(Unknown Source)
      at org.apache.derby.impl.jdbc.EmbedResultSet.movePosition(Unknown Source)
      at org.apache.derby.impl.jdbc.EmbedResultSet.next(Unknown Source)
      at com.mchange.v2.c3p0.impl.NewProxyResultSet.next(NewProxyResultSet.java:2859)
      at org.hibernate.loader.Loader.doQuery(Loader.java:408)
      at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:218)
      at org.hibernate.loader.Loader.loadCollection(Loader.java:1434)
      at org.hibernate.loader.collection.CollectionLoader.initialize(CollectionLoader.java:99)
      at org.hibernate.persister.collection.AbstractCollectionPersister.initialize(AbstractCollectionPersister.java:488)
      at org.hibernate.event.def.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:60)
      at org.hibernate.impl.SessionImpl.initializeCollection(SessionImpl.java:1430)
      at org.hibernate.collection.AbstractPersistentCollection.forceInitialization(AbstractPersistentCollection.java:280)
      at org.hibernate.engine.PersistenceContext.initializeNonLazyCollections(PersistenceContext.java:796)
      at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:223)
      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)
      at ooad.p.ga(p.java:288)
      at ooad.p.ga(p.java:117)
      at oo.c.gdc(c.java:119)
      at oo.d.c(d.java:805)
      at oo.d.c(d.java:785)
      at oo.d.c(d.java:766)
      at oodb.s.run(s.java:82)
      at java.lang.Thread.run(Thread.java:595)

          • application log

      Apr 27 2010 12:05:22.476 -0400: %_JDBCExceptionReporter-3-org.hibernate.util.JDBCExceptionReporter: Java exception: ': java.lang.NullPointerException'.
      Apr 27 2010 12:05:22.492 -0400: %_JDBCTransaction-3-org.hibernate.transaction.JDBCTransaction: JDBC rollback failed
      java.sql.SQLException: No current connection.
      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.newEmbedSQLException(Unknown Source)
      at org.apache.derby.impl.jdbc.Util.noCurrentConnection(Unknown Source)
      at org.apache.derby.impl.jdbc.EmbedConnection.checkIfClosed(Unknown Source)
      at org.apache.derby.impl.jdbc.EmbedConnection.setupContextStack(Unknown Source)
      at org.apache.derby.impl.jdbc.EmbedConnection.rollback(Unknown Source)
      at com.mchange.v2.c3p0.impl.NewProxyConnection.rollback(NewProxyConnection.java:755)
      at org.hibernate.transaction.JDBCTransaction.rollbackAndResetAutoCommit(JDBCTransaction.java:163)
      at org.hibernate.transaction.JDBCTransaction.rollback(JDBCTransaction.java:142)
      at ooad.p.r(p.java:888)
      at ooad.p.ga(p.java:310)
      at ooad.p.ga(p.java:117)
      at oa.c.gdc(c.java:119)
      at oa.d.c(d.java:805)
      at oa.d.c(d.java:785)
      at oa.d.c(d.java:766)
      at ooad.s.run(s.java:82)
      at java.lang.Thread.run(Thread.java:595)

      1. junit.diff
        6 kB
        Knut Anders Hatlen
      2. error.log
        1 kB
        Seth Katzman
      3. derbyerror.log
        3 kB
        Seth Katzman
      4. derbyall.sum
        94 kB
        Mamta A. Satoor
      5. derbyall_fail.txt
        0.1 kB
        Mamta A. Satoor
      6. derbyall_diff.txt
        26 kB
        Mamta A. Satoor
      7. derby-4676-1a.diff
        12 kB
        Knut Anders Hatlen
      8. D4676.java
        2 kB
        Knut Anders Hatlen
      9. 2010-05-25-derbyerror.log
        17 kB
        Seth Katzman
      10. 2010-05-25-applicationerror.log
        36 kB
        Seth Katzman

        Issue Links

          Activity

          Hide
          Knut Anders Hatlen added a comment -

          [bulk update] Close all resolved issues that haven't been updated for more than one year.

          Show
          Knut Anders Hatlen added a comment - [bulk update] Close all resolved issues that haven't been updated for more than one year.
          Hide
          Mamta A. Satoor added a comment -

          Backport to 10.5 done

          Show
          Mamta A. Satoor added a comment - Backport to 10.5 done
          Hide
          Mamta A. Satoor added a comment -

          junit suite ran fine too on 10.5 after the merge. Will go ahead and checkin the changes into 10.5 this morning

          Show
          Mamta A. Satoor added a comment - junit suite ran fine too on 10.5 after the merge. Will go ahead and checkin the changes into 10.5 this morning
          Hide
          Mamta A. Satoor added a comment - - edited

          A rerun of derbyall didn't show any NPE. Running the junit suite now

          Show
          Mamta A. Satoor added a comment - - edited A rerun of derbyall didn't show any NPE. Running the junit suite now
          Hide
          Mamta A. Satoor added a comment -

          When I ran derbyall after the merge on 10.5 codeline, I saw a NPE for
          derbyall/derbynetclientmats/derbynetmats.fail:derbynet/dblook_test_net.java

          Not sure if it is indeed that test ran into NPE because I don't see one under that actual test directory. The derbyall.sum file has following

              • End: dblook_test_net jdk1.6.0 DerbyNetClient derbynetmats:derbynetmats 2010-07-06 16:34:52 ***
                Server Process did not complete in time. Destroying...
                java.lang.NullPointerException
                at org.apache.derbyTesting.functionTests.harness.RunTest.execTestProcess(RunTest.java:2609)
                at org.apache.derbyTesting.functionTests.harness.RunTest.testRun(RunTest.java:504)
                at org.apache.derbyTesting.functionTests.harness.RunTest.main(RunTest.java:372)
                derby.infolog.append=true
                derby.database.sqlAuthorization=true
                derby.connection.requireAuthentication=true
                derby.user.app=apppw
              • Start: dblook_test_net_territory jdk1.6.0 DerbyNetClient derbynetmats:derbynetmats 2010-07-06 16:34:53 ***
                Initialize for framework: DerbyNetClient
                java -Duser.language=en -Duser.country=US -Dderby.system.home=C:\p4clients\svn10.5\client1\10.5\systest\out142\derbyall\derbynetclientmats\DerbyNetClient\derbynetmats\derbynetmats\dblook_test_net_territory -Djava.security.manager -Djava.security.policy=C:\p4clients\svn10.5\client1\10.5\systest\out142\derby_tests.policy -DderbyTesting.codeclasses=file:/C:/p4clients/svn10.5/client1/10.5/classes/ -DderbyTesting.junit=file:/C:/p4clients/svn10.5/client1/10.5/tools/java/junit.jar -DderbyTesting.codedir=C:\p4clients\svn10.5\client1\10.5\classes -DderbyTesting.serverhost=localhost -DderbyTesting.clienthost=localhost org.apache.derby.drda.NetworkServerControl start
            • SecurityManager not installed –
              Attempt to shutdown framework: DerbyNetClient
              • End: dblook_test_net_territory jdk1.6.0 DerbyNetClient derbynetmats:derbynetmats 2010-07-06 16:35:55 ***
                Warning: Cleanup failed on baseDir: C:\p4clients\svn10.5\client1\10.5\systest\out142\derbyall\derbynetclientmats\DerbyNetClient\derbynetmats\derbynetmats\dblook_test_net_territory

          When I look directly under C:\p4clients\svn10.5\client1\10.5\systest\out142\derbyall\derbynetclientmats\DerbyNetClient\derbynetmats\derbynetmats, I don't see NPE in the files created for dblook_test_net

          I have attached the top level derbyall suite report files for reference.

          Show
          Mamta A. Satoor added a comment - When I ran derbyall after the merge on 10.5 codeline, I saw a NPE for derbyall/derbynetclientmats/derbynetmats.fail:derbynet/dblook_test_net.java Not sure if it is indeed that test ran into NPE because I don't see one under that actual test directory. The derbyall.sum file has following End: dblook_test_net jdk1.6.0 DerbyNetClient derbynetmats:derbynetmats 2010-07-06 16:34:52 *** Server Process did not complete in time. Destroying... java.lang.NullPointerException at org.apache.derbyTesting.functionTests.harness.RunTest.execTestProcess(RunTest.java:2609) at org.apache.derbyTesting.functionTests.harness.RunTest.testRun(RunTest.java:504) at org.apache.derbyTesting.functionTests.harness.RunTest.main(RunTest.java:372) derby.infolog.append=true derby.database.sqlAuthorization=true derby.connection.requireAuthentication=true derby.user.app=apppw Start: dblook_test_net_territory jdk1.6.0 DerbyNetClient derbynetmats:derbynetmats 2010-07-06 16:34:53 *** Initialize for framework: DerbyNetClient java -Duser.language=en -Duser.country=US -Dderby.system.home=C:\p4clients\svn10.5\client1\10.5\systest\out142\derbyall\derbynetclientmats\DerbyNetClient\derbynetmats\derbynetmats\dblook_test_net_territory -Djava.security.manager -Djava.security.policy=C:\p4clients\svn10.5\client1\10.5\systest\out142\derby_tests.policy -DderbyTesting.codeclasses= file:/C:/p4clients/svn10.5/client1/10.5/classes/ -DderbyTesting.junit= file:/C:/p4clients/svn10.5/client1/10.5/tools/java/junit.jar -DderbyTesting.codedir=C:\p4clients\svn10.5\client1\10.5\classes -DderbyTesting.serverhost=localhost -DderbyTesting.clienthost=localhost org.apache.derby.drda.NetworkServerControl start SecurityManager not installed – Attempt to shutdown framework: DerbyNetClient End: dblook_test_net_territory jdk1.6.0 DerbyNetClient derbynetmats:derbynetmats 2010-07-06 16:35:55 *** Warning: Cleanup failed on baseDir: C:\p4clients\svn10.5\client1\10.5\systest\out142\derbyall\derbynetclientmats\DerbyNetClient\derbynetmats\derbynetmats\dblook_test_net_territory When I look directly under C:\p4clients\svn10.5\client1\10.5\systest\out142\derbyall\derbynetclientmats\DerbyNetClient\derbynetmats\derbynetmats, I don't see NPE in the files created for dblook_test_net I have attached the top level derbyall suite report files for reference.
          Hide
          Mamta A. Satoor added a comment -

          I will backport this to 10.5

          Show
          Mamta A. Satoor added a comment - I will backport this to 10.5
          Hide
          Kathey Marsden added a comment -

          reopen for 10.5 back port

          Show
          Kathey Marsden added a comment - reopen for 10.5 back port
          Hide
          Knut Anders Hatlen added a comment -

          Thanks for testing the fix, Seth! I'm closing the issue based on your feedback.

          Show
          Knut Anders Hatlen added a comment - Thanks for testing the fix, Seth! I'm closing the issue based on your feedback.
          Hide
          Seth Katzman added a comment -

          I ran several hours of load against the 952726 nightly build jars with no errors. Previously, I was hitting this issue within 5-10 minutes on every run, so this appears to be a good fix. Looks good. Thanks.

          Show
          Seth Katzman added a comment - I ran several hours of load against the 952726 nightly build jars with no errors. Previously, I was hitting this issue within 5-10 minutes on every run, so this appears to be a good fix. Looks good. Thanks.
          Hide
          Seth Katzman added a comment -

          Hi Knut,

          I'll test the revised jar and get back to you with the results this coming week. Thanks again.

          Show
          Seth Katzman added a comment - Hi Knut, I'll test the revised jar and get back to you with the results this coming week. Thanks again.
          Hide
          Knut Anders Hatlen added a comment -

          Merged fix to 10.6 and committed revision 952585.
          Marking the issue as resolved.

          Seth, if you want to verify the fix in your environment, you can either check out the 10.6 branch and build your own jars, or you can wait until the fix has been picked up by the nightly build of the 10.6 branch at http://dbtg.foundry.sun.com/derby/bits/10.6/ (download one with SVN revision number at or above 952585 when available). Please let us know how the testing goes.

          Show
          Knut Anders Hatlen added a comment - Merged fix to 10.6 and committed revision 952585. Marking the issue as resolved. Seth, if you want to verify the fix in your environment, you can either check out the 10.6 branch and build your own jars, or you can wait until the fix has been picked up by the nightly build of the 10.6 branch at http://dbtg.foundry.sun.com/derby/bits/10.6/ (download one with SVN revision number at or above 952585 when available). Please let us know how the testing goes.
          Hide
          Knut Anders Hatlen added a comment -

          Committed revision 952138.

          I'll look into back-porting the fix to 10.6 before I resolve the issue.

          Show
          Knut Anders Hatlen added a comment - Committed revision 952138. I'll look into back-porting the fix to 10.6 before I resolve the issue.
          Hide
          Knut Anders Hatlen added a comment -

          Uploading a patch for this issue (derby-4676-1a.diff) with the following changes:

          M java/engine/org/apache/derby/impl/store/access/conglomerate/OpenConglomerate.java

          Updated javadoc for latchPage(), lockPositionForRead() and lockPositionForWrite() with info about the expected state upon return if the row has been removed.

          M java/engine/org/apache/derby/impl/store/access/conglomerate/GenericConglomerateController.java

          Added a check to see if the row had been removed after calling lockPositionForRead/Write. If so, return false from fetch(), as specified by the ConglomerateController#fetch javadoc.

          M java/testing/org/apache/derbyTesting/functionTests/tests/store/_Suite.java
          A java/testing/org/apache/derbyTesting/functionTests/tests/store/Derby4676Test.java

          Added a regression test that fails (intermittently) if the bug is present.

          Derbyall and suites.All ran cleanly with the patch. I've also run the new regression test 500 times without seeing any errors.

          Show
          Knut Anders Hatlen added a comment - Uploading a patch for this issue (derby-4676-1a.diff) with the following changes: M java/engine/org/apache/derby/impl/store/access/conglomerate/OpenConglomerate.java Updated javadoc for latchPage(), lockPositionForRead() and lockPositionForWrite() with info about the expected state upon return if the row has been removed. M java/engine/org/apache/derby/impl/store/access/conglomerate/GenericConglomerateController.java Added a check to see if the row had been removed after calling lockPositionForRead/Write. If so, return false from fetch(), as specified by the ConglomerateController#fetch javadoc. M java/testing/org/apache/derbyTesting/functionTests/tests/store/_Suite.java A java/testing/org/apache/derbyTesting/functionTests/tests/store/Derby4676Test.java Added a regression test that fails (intermittently) if the bug is present. Derbyall and suites.All ran cleanly with the patch. I've also run the new regression test 500 times without seeing any errors.
          Hide
          Knut Anders Hatlen added a comment -

          I'm attaching a JUnit regression test case for the bug. It doesn't always fail, since the bug is highly dependent on the timing, but it triggers the NPE in about every other run in my environment.

          Show
          Knut Anders Hatlen added a comment - I'm attaching a JUnit regression test case for the bug. It doesn't always fail, since the bug is highly dependent on the timing, but it triggers the NPE in about every other run in my environment.
          Hide
          Knut Anders Hatlen added a comment -

          Thanks Bryan. I'll go ahead with adding the null check and updating the comment, as well as adding a store test that exposes the problem. I'll wait for DERBY-4678 to go in first, so that we only have one fetch() method to fix in GenericConglomerateController.

          Show
          Knut Anders Hatlen added a comment - Thanks Bryan. I'll go ahead with adding the null check and updating the comment, as well as adding a store test that exposes the problem. I'll wait for DERBY-4678 to go in first, so that we only have one fetch() method to fix in GenericConglomerateController.
          Hide
          Bryan Pendleton added a comment -

          Given a choice between changing the code, or changing the comments,
          I usually choose to change the comments.

          I think you have isolated and explained the problem clearly; either of
          your proposed fixes seems reasonable to me.

          Show
          Bryan Pendleton added a comment - Given a choice between changing the code, or changing the comments, I usually choose to change the comments. I think you have isolated and explained the problem clearly; either of your proposed fixes seems reasonable to me.
          Hide
          Knut Anders Hatlen added a comment -

          Hi Bryan,

          'Yes' is the answer to all you questions above.

          fetch() first latches the heap page on which the indexed row is supposed to be found. Then it attempts to lock the row.

          If the row cannot be locked immediately, the latch is released before the thread is suspended while it waits for the lock to be obtained. Once it wakes up again, it will re-obtain the latch on the heap page. OpenConglomerate.latchPage() additionally checks if the row is still present on the page, and if it isn't, it will release the latch again and return false. OpenConglomerate.lockPositionForRead/Write however doesn't check the return value from latchPage() and doesn't distinguish between the case where the latch was successfully re-obtained and the case where it was not.

          Another simpler fix than what I suggested above, would be to check if pos.current_page is null after the attempt to lock the row, and assume that this means the row (or the entire page) is gone. In that case we should update the javadoc comment for lockPositionForRead() to state that this is how it behaves, and remove the sentence that incorrectly states that it raises an exception.

          Show
          Knut Anders Hatlen added a comment - Hi Bryan, 'Yes' is the answer to all you questions above. fetch() first latches the heap page on which the indexed row is supposed to be found. Then it attempts to lock the row. If the row cannot be locked immediately, the latch is released before the thread is suspended while it waits for the lock to be obtained. Once it wakes up again, it will re-obtain the latch on the heap page. OpenConglomerate.latchPage() additionally checks if the row is still present on the page, and if it isn't, it will release the latch again and return false. OpenConglomerate.lockPositionForRead/Write however doesn't check the return value from latchPage() and doesn't distinguish between the case where the latch was successfully re-obtained and the case where it was not. Another simpler fix than what I suggested above, would be to check if pos.current_page is null after the attempt to lock the row, and assume that this means the row (or the entire page) is gone. In that case we should update the javadoc comment for lockPositionForRead() to state that this is how it behaves, and remove the sentence that incorrectly states that it raises an exception.
          Hide
          Bryan Pendleton added a comment -

          Doesn't GenericConglomerateController.fetch latch the page just before
          it calls lockPositionForRead? Is the patch latch being given up inside the
          lock call, and then re-acquired? Is that why this only shows up under very
          high concurrency and lock contention scenarios?

          Show
          Bryan Pendleton added a comment - Doesn't GenericConglomerateController.fetch latch the page just before it calls lockPositionForRead? Is the patch latch being given up inside the lock call, and then re-acquired? Is that why this only shows up under very high concurrency and lock contention scenarios?
          Hide
          Knut Anders Hatlen added a comment -

          I looked at this in a debugger, and it seems like it's pos.current_page that's null in this code in GenericConglomerateController.fetch():

          boolean ret_val =
          (pos.current_page.fetchFromSlot(
          pos.current_rh, pos.current_slot,
          row,
          new FetchDescriptor(
          row.length, validColumns, (Qualifier[][]) null),
          false) != null);

          It is set to null by OpenConglomerate.latchPage() (called from fetch() via OpenConglomerate.lockPositionForRead()) when it discovers that the record was deleted by another transaction before the row was locked.

          One thing to note is that lockPositionForRead()'s javadoc says:

          • @param moveForwardIfRowDisappears
          • If true, then this routine must handle the case where
          • the row id we are waiting on disappears when the latch
          • is released. If false an exception will be thrown if
          • the row disappears.

          However, there is no exception thrown by this method when the row has disappeared, even though fetch() calls it with moveForwardIfRowDisappears=false.

          I think one possible fix is to make lockPositionForRead() raise an exception in this situation (can be detected by checking the return value from latchPage(), which is currently not checked). The javadoc for fetch() says that it should return false if the row has disappeared, so it could catch that exception and return false.

          fetch() is the only method that calls lockPositionForRead() with moveForwardIfRowDisappears=false, so such a change should only affect the case where we currently see a NullPointerException.

          Show
          Knut Anders Hatlen added a comment - I looked at this in a debugger, and it seems like it's pos.current_page that's null in this code in GenericConglomerateController.fetch(): boolean ret_val = (pos.current_page.fetchFromSlot( pos.current_rh, pos.current_slot, row, new FetchDescriptor( row.length, validColumns, (Qualifier[][]) null), false) != null); It is set to null by OpenConglomerate.latchPage() (called from fetch() via OpenConglomerate.lockPositionForRead()) when it discovers that the record was deleted by another transaction before the row was locked. One thing to note is that lockPositionForRead()'s javadoc says: @param moveForwardIfRowDisappears If true, then this routine must handle the case where the row id we are waiting on disappears when the latch is released. If false an exception will be thrown if the row disappears. However, there is no exception thrown by this method when the row has disappeared, even though fetch() calls it with moveForwardIfRowDisappears=false. I think one possible fix is to make lockPositionForRead() raise an exception in this situation (can be detected by checking the return value from latchPage(), which is currently not checked). The javadoc for fetch() says that it should return false if the row has disappeared, so it could catch that exception and return false. fetch() is the only method that calls lockPositionForRead() with moveForwardIfRowDisappears=false, so such a change should only affect the case where we currently see a NullPointerException.
          Hide
          Knut Anders Hatlen added a comment -

          Thanks, Seth.

          I am able to reproduce the bug with the attached java class. The repro has two threads running. One of them repeatedly inserts and deletes a record in a table. The other thread repeatedly reads rows from the same table, using an index on one of the columns.

          Here's the exception I see on trunk:

          $ java D4676
          java.sql.SQLException: Java exception: ': java.lang.NullPointerException'.
          at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:95)
          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.TransactionResourceImpl.wrapInSQLException(TransactionResourceImpl.java:403)
          at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(TransactionResourceImpl.java:346)
          at org.apache.derby.impl.jdbc.EmbedConnection.handleException(EmbedConnection.java:2269)
          at org.apache.derby.impl.jdbc.ConnectionChild.handleException(ConnectionChild.java:81)
          at org.apache.derby.impl.jdbc.EmbedResultSet.closeOnTransactionError(EmbedResultSet.java:4321)
          at org.apache.derby.impl.jdbc.EmbedResultSet.movePosition(EmbedResultSet.java:469)
          at org.apache.derby.impl.jdbc.EmbedResultSet.next(EmbedResultSet.java:373)
          at D4676$Reader.run(D4676.java:53)
          Caused by: java.sql.SQLException: Java exception: ': java.lang.NullPointerException'.
          at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:45)
          at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(SQLExceptionFactory40.java:119)
          at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:70)
          ... 10 more
          Caused by: java.lang.NullPointerException
          at org.apache.derby.impl.store.access.conglomerate.GenericConglomerateController.fetch(GenericConglomerateController.java:291)
          at org.apache.derby.impl.sql.execute.IndexRowToBaseRowResultSet.getNextRowCore(IndexRowToBaseRowResultSet.java:389)
          at org.apache.derby.impl.sql.execute.BasicNoPutResultSetImpl.getNextRow(BasicNoPutResultSetImpl.java:477)
          at org.apache.derby.impl.jdbc.EmbedResultSet.movePosition(EmbedResultSet.java:429)
          ... 2 more

          Show
          Knut Anders Hatlen added a comment - Thanks, Seth. I am able to reproduce the bug with the attached java class. The repro has two threads running. One of them repeatedly inserts and deletes a record in a table. The other thread repeatedly reads rows from the same table, using an index on one of the columns. Here's the exception I see on trunk: $ java D4676 java.sql.SQLException: Java exception: ': java.lang.NullPointerException'. at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:95) 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.TransactionResourceImpl.wrapInSQLException(TransactionResourceImpl.java:403) at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(TransactionResourceImpl.java:346) at org.apache.derby.impl.jdbc.EmbedConnection.handleException(EmbedConnection.java:2269) at org.apache.derby.impl.jdbc.ConnectionChild.handleException(ConnectionChild.java:81) at org.apache.derby.impl.jdbc.EmbedResultSet.closeOnTransactionError(EmbedResultSet.java:4321) at org.apache.derby.impl.jdbc.EmbedResultSet.movePosition(EmbedResultSet.java:469) at org.apache.derby.impl.jdbc.EmbedResultSet.next(EmbedResultSet.java:373) at D4676$Reader.run(D4676.java:53) Caused by: java.sql.SQLException: Java exception: ': java.lang.NullPointerException'. at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(SQLExceptionFactory.java:45) at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(SQLExceptionFactory40.java:119) at org.apache.derby.impl.jdbc.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:70) ... 10 more Caused by: java.lang.NullPointerException at org.apache.derby.impl.store.access.conglomerate.GenericConglomerateController.fetch(GenericConglomerateController.java:291) at org.apache.derby.impl.sql.execute.IndexRowToBaseRowResultSet.getNextRowCore(IndexRowToBaseRowResultSet.java:389) at org.apache.derby.impl.sql.execute.BasicNoPutResultSetImpl.getNextRow(BasicNoPutResultSetImpl.java:477) at org.apache.derby.impl.jdbc.EmbedResultSet.movePosition(EmbedResultSet.java:429) ... 2 more
          Hide
          Seth Katzman added a comment -

          I have attached the new logs (derby and application) using the 10.6.1.0 debug jars. The derby log file shows the initial NullPointerException with source line numbers. The application log file shows the debug dump of thread states with an assert failure.

          I also double checked the transaction isolation level of the connection being used. The transaction isolation level is always returning 2 which looks to be TRANSACTION_READ_COMMITTED.

          Show
          Seth Katzman added a comment - I have attached the new logs (derby and application) using the 10.6.1.0 debug jars. The derby log file shows the initial NullPointerException with source line numbers. The application log file shows the debug dump of thread states with an assert failure. I also double checked the transaction isolation level of the connection being used. The transaction isolation level is always returning 2 which looks to be TRANSACTION_READ_COMMITTED.
          Hide
          Seth Katzman added a comment -

          derby.log and application error log attachment using Derby 10.6.1.0 debug jars.

          Show
          Seth Katzman added a comment - derby.log and application error log attachment using Derby 10.6.1.0 debug jars.
          Hide
          Seth Katzman added a comment -

          Hi Knut,

          Thanks for the quick reply. I'll grab the debug jars and attempt to recreate the exception condition. I'll add further comments/enclosures as I find out more (connection transaction isolation and debug logs).

          Show
          Seth Katzman added a comment - Hi Knut, Thanks for the quick reply. I'll grab the debug jars and attempt to recreate the exception condition. I'll add further comments/enclosures as I find out more (connection transaction isolation and debug logs).
          Hide
          Knut Anders Hatlen added a comment -

          Hi Seth,

          If you have the chance, it would be great if you could try to run with a debug version of Derby (available from the download page, look for the lib-debug tarball) so that we get line numbers in the stack trace and perhaps an assert failure with more information.

          Another thing that came to mind: What's the transaction isolation level for the connection? I was wondering if this could be caused by another thread deleting a row right after it was found in the index and before it was read from the heap, which I think may happen if the isolation level is read uncommitted.

          Show
          Knut Anders Hatlen added a comment - Hi Seth, If you have the chance, it would be great if you could try to run with a debug version of Derby (available from the download page, look for the lib-debug tarball) so that we get line numbers in the stack trace and perhaps an assert failure with more information. Another thing that came to mind: What's the transaction isolation level for the connection? I was wondering if this could be caused by another thread deleting a row right after it was found in the index and before it was read from the heap, which I think may happen if the isolation level is read uncommitted.
          Hide
          Seth Katzman added a comment -

          Apache Derby log stacktrace and application error stacktrace.

          Show
          Seth Katzman added a comment - Apache Derby log stacktrace and application error stacktrace.

            People

            • Assignee:
              Knut Anders Hatlen
              Reporter:
              Seth Katzman
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development