Derby
  1. Derby
  2. DERBY-5422

IndexOutOfBoundsException followed by NullPointerException in cleanup during system.nstest

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Critical Critical
    • Resolution: Cannot Reproduce
    • Affects Version/s: 10.9.1.0
    • Fix Version/s: None
    • Component/s: Test
    • Labels:
      None
    • Environment:
      Windows XP, with ibm 1.6 SR9 FP1
    • Urgency:
      Blocker
    • Bug behavior facts:
      Regression

      Description

      During the embedded NsTest system test on windows XP I saw the following in derby.log:

      Tue Sep 13 16:25:03 PDT 2011:
      Booting Derby version The Apache Software Foundation - Apache Derby - 10.8.2.1 - (1170221): instance b779ce27-0132-6516-81e1-000000312348
      on database directory D:\10.8.2.1\tst\restoredir\nstestdb with class loader sun.misc.Launcher$AppClassLoader@40504050
      Loaded from file:/D:/10.8.2.1/jars/derby.jar
      java.vendor=IBM Corporation
      java.runtime.version=jvmwi3260sr9-20110203_74623
      java.fullversion=JRE 1.6.0 IBM J9 2.4 Windows Server 2003 x86-32 jvmwi3260sr9-20110203_74623 (JIT enabled, AOT enabled)
      J9VM - 20110203_074623
      JIT - r9_20101028_17488ifx3
      GC - 20101027_AA
      user.dir=D:\10.8.2.1\tst
      derby.system.home=null
      New exception raised during cleanup Index: -1, Size: 15
      java.lang.IndexOutOfBoundsException: Index: -1, Size: 15
      at java.util.ArrayList.remove(ArrayList.java:552)
      at org.apache.derby.iapi.services.context.ContextManager.popContext(Unknown Source)
      at org.apache.derby.iapi.services.context.ContextImpl.popMe(Unknown Source)
      at org.apache.derby.impl.store.access.RAMTransaction.destroy(Unknown Source)
      at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.doRollback(Unknown Source)
      at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.internalRollback(Unknown Source)
      at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.cleanupOnError(Unknown Source)
      at org.apache.derby.iapi.services.context.ContextManager.cleanupOnError(Unknown Source)
      at org.apache.derby.impl.sql.catalog.SequenceUpdater.clearIdentity(Unknown Source)
      at org.apache.derby.impl.services.cache.ConcurrentCache.removeEntry(Unknown Source)
      at org.apache.derby.impl.services.cache.ConcurrentCache.ageOut(Unknown Source)
      at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearSequenceCaches(Unknown Source)
      at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearCaches(Unknown Source)
      at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.doneReading(Unknown Source)
      at org.apache.derby.impl.sql.GenericStatement.prepMinion(Unknown Source)
      at org.apache.derby.impl.sql.GenericStatement.prepareStorable(Unknown Source)
      at org.apache.derby.iapi.sql.dictionary.SPSDescriptor.compileStatement(Unknown Source)
      at org.apache.derby.iapi.sql.dictionary.SPSDescriptor.prepareAndRelease(Unknown Source)
      at org.apache.derby.iapi.sql.dictionary.SPSDescriptor.getPreparedStatement(Unknown Source)
      at org.apache.derby.iapi.sql.dictionary.SPSDescriptor.getPreparedStatement(Unknown Source)
      at org.apache.derby.impl.sql.execute.GenericTriggerExecutor.executeSPS(Unknown Source)
      at org.apache.derby.impl.sql.execute.RowTriggerExecutor.fireTrigger(Unknown Source)
      at org.apache.derby.impl.sql.execute.TriggerEventActivator.notifyEvent(Unknown Source)
      at org.apache.derby.impl.sql.execute.DeleteResultSet.fireAfterTriggers(Unknown Source)
      at org.apache.derby.impl.sql.execute.DeleteResultSet.open(Unknown Source)
      at org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(Unknown Source)
      at org.apache.derby.impl.sql.GenericPreparedStatement.execute(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.executeUpdate(Unknown Source)
      at org.apache.derbyTesting.system.nstest.utils.DbUtil.delete_one_row(DbUtil.java:452)
      at org.apache.derbyTesting.system.nstest.tester.TesterObject.doIUDOperation(TesterObject.java:175)
      at org.apache.derbyTesting.system.nstest.tester.Tester1.startTesting(Tester1.java:118)
      at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:551)
      Cleanup action completed
      New exception raised during cleanup null
      java.lang.NullPointerException
      at org.apache.derby.impl.sql.compile.CompilerContextImpl.initRequiredPriv(Unknown Source)
      at org.apache.derby.impl.sql.compile.CompilerContextImpl.resetContext(Unknown Source)
      at org.apache.derby.impl.sql.compile.CompilerContextImpl.cleanupOnError(Unknown Source)
      at org.apache.derby.iapi.services.context.ContextManager.cleanupOnError(Unknown Source)
      at org.apache.derby.impl.jdbc.TransactionResourceImpl.cleanupOnError(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.executeUpdate(Unknown Source)
      at org.apache.derbyTesting.system.nstest.utils.DbUtil.delete_one_row(DbUtil.java:452)
      at org.apache.derbyTesting.system.nstest.tester.TesterObject.doIUDOperation(TesterObject.java:175)
      at org.apache.derbyTesting.system.nstest.tester.Tester1.startTesting(Tester1.java:118)
      at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:551)
      Tue Sep 13 16:25:12 PDT 2011 Thread[Thread 1,5,main] Equally severe exception raised during cleanup (ignored) null
      java.lang.NullPointerException
      at org.apache.derby.impl.sql.compile.CompilerContextImpl.initRequiredPriv(Unknown Source)
      at org.apache.derby.impl.sql.compile.CompilerContextImpl.resetContext(Unknown Source)
      at org.apache.derby.impl.sql.compile.CompilerContextImpl.cleanupOnError(Unknown Source)
      at org.apache.derby.iapi.services.context.ContextManager.cleanupOnError(Unknown Source)
      at org.apache.derby.impl.jdbc.TransactionResourceImpl.cleanupOnError(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.executeUpdate(Unknown Source)
      at org.apache.derbyTesting.system.nstest.utils.DbUtil.delete_one_row(DbUtil.java:452)
      at org.apache.derbyTesting.system.nstest.tester.TesterObject.doIUDOperation(TesterObject.java:175)
      at org.apache.derbyTesting.system.nstest.tester.Tester1.startTesting(Tester1.java:118)
      at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:551)
      Cleanup action completed

      It appears this caused the Tester1 thread to loose the connection:
      ---------------------
      Tester1Thread 1 dbUtil ----> During failure to execute delete stmt, exception thrown was : java.sql.SQLTransactionRollbackException: An internal error was identified by RawStore module.
      TObj -->At this point - executing delete_one_row(), exception thrown was : No current connection.
      java.sql.SQLNonTransientConnectionException: No current connection.
      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.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.prepareStatement(Unknown Source)
      at org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(Unknown Source)
      at org.apache.derbyTesting.system.nstest.utils.DbUtil.add_one_row(DbUtil.java:96)
      at org.apache.derbyTesting.system.nstest.tester.TesterObject.doIUDOperation(TesterObject.java:148)
      at org.apache.derbyTesting.system.nstest.tester.Tester1.startTesting(Tester1.java:118)
      at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:551)
      Caused by: java.sql.SQLException: No current connection.
      at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
      at org.apache.derby.impl.jdbc.SQLExceptionFactory40.wrapArgsForTransportAcrossDRDA(Unknown Source)
      ... 12 more
      -------------------------------

      1. run7.jar
        17 kB
        Myrna van Lunteren
      2. run2.jar
        194 kB
        Myrna van Lunteren
      3. DERBY5422_diff_patch1.txt
        2 kB
        Mamta A. Satoor
      4. derby2.log
        507 kB
        Mamta A. Satoor
      5. derby1.log
        754 kB
        Mamta A. Satoor

        Issue Links

          Activity

          Hide
          Rick Hillegas added a comment -

          I agree with Kathey that this error may be fallout from an ungraceful recovery after the error seen in DERBY-5423. Setting derby.language.sequence.preallocator=200 may help this test run longer before it stumbles over too much contention on the identity column. That is not to say that we shouldn't add defensive logic to the test so that it recovers more gracefully.

          Show
          Rick Hillegas added a comment - I agree with Kathey that this error may be fallout from an ungraceful recovery after the error seen in DERBY-5423 . Setting derby.language.sequence.preallocator=200 may help this test run longer before it stumbles over too much contention on the identity column. That is not to say that we shouldn't add defensive logic to the test so that it recovers more gracefully.
          Hide
          Myrna van Lunteren added a comment -

          I still see this issue show up, even after the changes for DERBY-5423/5426.

          Even before, Rick, I wonder how you deduced this was fall out from the error seen in DERBY-5423? Even in my first report, the first error X0Y84 showed up later and in another Tester objects threads (and, well, the Tester object that sees the IndexOutOfBoundsException lost the connection, so could not do anything to get any X0Y84 errors).

          I have only once run with derby.language.sequence.preallocator=200, and that time I didn't see the error, but I've also run it without any properties for a couple of days and not seen the error also.
          My most recent run was to experiment with another variation of modification to the tests, and I saw the error again.
          So, it's quite intermittent.

          The bothersome part about this is that the connection gets dropped for the Tester who gets this error.
          I think that is worrying.

          I can modify the test to make the Tester object stop processing once this error is seen, or perhaps, only perform the offending task (it seems to be any of the methods DbUtil.update_one_row, DbUtil.add_one_row, DbUtil.delete_one_row, called from TesterObject.doIUDOperation can run into the 'no current connection' trouble. We get more of a stack trace with DbUtil.add_one_row.

          But the problem remains...

          Show
          Myrna van Lunteren added a comment - I still see this issue show up, even after the changes for DERBY-5423 /5426. Even before, Rick, I wonder how you deduced this was fall out from the error seen in DERBY-5423 ? Even in my first report, the first error X0Y84 showed up later and in another Tester objects threads (and, well, the Tester object that sees the IndexOutOfBoundsException lost the connection, so could not do anything to get any X0Y84 errors). I have only once run with derby.language.sequence.preallocator=200, and that time I didn't see the error, but I've also run it without any properties for a couple of days and not seen the error also. My most recent run was to experiment with another variation of modification to the tests, and I saw the error again. So, it's quite intermittent. The bothersome part about this is that the connection gets dropped for the Tester who gets this error. I think that is worrying. I can modify the test to make the Tester object stop processing once this error is seen, or perhaps, only perform the offending task (it seems to be any of the methods DbUtil.update_one_row, DbUtil.add_one_row, DbUtil.delete_one_row, called from TesterObject.doIUDOperation can run into the 'no current connection' trouble. We get more of a stack trace with DbUtil.add_one_row. But the problem remains...
          Hide
          Myrna van Lunteren added a comment -

          My expirements so far:

          (Notes:

          • iiobe = IndexOutOfBoundsException
          • all test runs were with Embedded except 1.
          • 0, 1, and 2 were normal QA Cycle runs )

          0. original 10.8.1.2 QA Cycle Windows Embedded; insane; no properties: no ioobe, ran for 8 days.
          0b. new run with original 10.8.1.2.RC2 sane jars; Windows Embedded; no properties: no ioobe. ran for 2 days, 2 hours.
          (purpose: check 10.8.1.2 with sane jars)
          1. original 10.8.2.1.RC2 QA Cycle run: Linux networkServer; insane; no properties: No ioobe, ran for 4 days, 18 hours.
          2. original 10.8.2.1.RC2 QA Cycle run: Windows Embedded; insane; no properties: ioobe within 1 minute.
          3. original 10.8.2.1.RC2 Windows Embedded; sane; properties incl. derby.language.sequence.preallocator=200: no ioobe, ran for 2 days, 19

          hours
          (purpose: experiment with preallocator setting, looking for X0Y84 error; stopped after encountered.)
          4. original 10.8.2.1.RC2 Linux Embedded; insane; no properties: no ioobe, ran for 12 hours.
          (purpose: verify Embedded on Linux; looking for X0Y84 error; stopped after encountered).
          5. 10.8.2.2 - (1174879M) (with DERBY-5421_1.diff patch); Windows Embedded
          sane jars; some derby.properties (logStatementText, logSeverityLevel=0): ioobe after 2 days, 7 hours.
          (purpose: pick up changes for DERBY-5423/5426 with sane)
          6. 10.8.2.2 - (1174879M) (with DERBY-5421_1.diff patch); Linux Embedded; insane jars, no properties: no ioobe, ran for 3 days, 15 hours
          (purpose: pick up changes for DERBY-5423/5426 with insane)
          7. 10.8.2.2 - (1174879M) (with DERBY-5421_2.diff patch); Linux Embedded; insane jars; no properties: ioobe after ca. 13 hours
          (purpose: check patch DERBY-5421_2.diff)

          I'll attach jar-ed up derby.log files for runs (numbered here 2, 5, 7.
          Each jar file also contains a section of the console output around the time of the problem showing the result of the dropped connection.

          Show
          Myrna van Lunteren added a comment - My expirements so far: (Notes: iiobe = IndexOutOfBoundsException all test runs were with Embedded except 1. 0, 1, and 2 were normal QA Cycle runs ) 0. original 10.8.1.2 QA Cycle Windows Embedded; insane; no properties: no ioobe, ran for 8 days. 0b. new run with original 10.8.1.2.RC2 sane jars; Windows Embedded; no properties: no ioobe. ran for 2 days, 2 hours. (purpose: check 10.8.1.2 with sane jars) 1. original 10.8.2.1.RC2 QA Cycle run: Linux networkServer; insane; no properties: No ioobe, ran for 4 days, 18 hours. 2. original 10.8.2.1.RC2 QA Cycle run: Windows Embedded; insane; no properties: ioobe within 1 minute. 3. original 10.8.2.1.RC2 Windows Embedded; sane; properties incl. derby.language.sequence.preallocator=200: no ioobe, ran for 2 days, 19 hours (purpose: experiment with preallocator setting, looking for X0Y84 error; stopped after encountered.) 4. original 10.8.2.1.RC2 Linux Embedded; insane; no properties: no ioobe, ran for 12 hours. (purpose: verify Embedded on Linux; looking for X0Y84 error; stopped after encountered). 5. 10.8.2.2 - (1174879M) (with DERBY-5421 _1.diff patch); Windows Embedded sane jars; some derby.properties (logStatementText, logSeverityLevel=0): ioobe after 2 days, 7 hours. (purpose: pick up changes for DERBY-5423 /5426 with sane) 6. 10.8.2.2 - (1174879M) (with DERBY-5421 _1.diff patch); Linux Embedded; insane jars, no properties: no ioobe, ran for 3 days, 15 hours (purpose: pick up changes for DERBY-5423 /5426 with insane) 7. 10.8.2.2 - (1174879M) (with DERBY-5421 _2.diff patch); Linux Embedded; insane jars; no properties: ioobe after ca. 13 hours (purpose: check patch DERBY-5421 _2.diff) I'll attach jar-ed up derby.log files for runs (numbered here 2, 5, 7. Each jar file also contains a section of the console output around the time of the problem showing the result of the dropped connection.
          Hide
          Myrna van Lunteren added a comment -

          unfortunately the derby.log from run5 is too large to get attached. But perhaps 2 runs worth gives enough info.

          Show
          Myrna van Lunteren added a comment - unfortunately the derby.log from run5 is too large to get attached. But perhaps 2 runs worth gives enough info.
          Hide
          Mike Matrigali added a comment - - edited

          Without a good reproducible test case it hard to be sure, but it seems likely that this bug is caused by DERBY-4477. Given that Sequence cache cleanup is in the error stack, seems likely that using the sequence cache for identity generation is the problem. I don't think there are any sequences currently in the nstest.

          I assume the problem is some bad error handling after some other error.

          Show
          Mike Matrigali added a comment - - edited Without a good reproducible test case it hard to be sure, but it seems likely that this bug is caused by DERBY-4477 . Given that Sequence cache cleanup is in the error stack, seems likely that using the sequence cache for identity generation is the problem. I don't think there are any sequences currently in the nstest. I assume the problem is some bad error handling after some other error.
          Hide
          Mike Matrigali added a comment -

          from looking at the run2.jar:
          o I think derby.log is saying that the problem is that we got an error in SequenceUpdater.clearIdentity and then while
          handling that error we got an java.lang.IndexOutOfBoundsException. Unfortunately it looks like the original error gets lost
          when we get the IndexOutOfBoundsException.

          My initial question is whose job should it be to catch and report the nested exception so that we could see what error is causing
          cleanupOnError to be called and fail?

          So the interesting piece of code is SequenceUpdater.java, with some sort of failure in clean:

          public void clearIdentity()
          {
          try

          { clean( false ); }

          catch (StandardException se)
          {
          //Doing check for lcc and db to be certain
          LanguageConnectionContext lcc = getLCC();
          if (lcc != null)

          { Database db = lcc.getDatabase(); boolean isactive = (db != null ? db.isActive() : false); lcc.getContextManager().cleanupOnError(se, isactive); }

          }
          }

          Show
          Mike Matrigali added a comment - from looking at the run2.jar: o I think derby.log is saying that the problem is that we got an error in SequenceUpdater.clearIdentity and then while handling that error we got an java.lang.IndexOutOfBoundsException. Unfortunately it looks like the original error gets lost when we get the IndexOutOfBoundsException. My initial question is whose job should it be to catch and report the nested exception so that we could see what error is causing cleanupOnError to be called and fail? So the interesting piece of code is SequenceUpdater.java, with some sort of failure in clean: public void clearIdentity() { try { clean( false ); } catch (StandardException se) { //Doing check for lcc and db to be certain LanguageConnectionContext lcc = getLCC(); if (lcc != null) { Database db = lcc.getDatabase(); boolean isactive = (db != null ? db.isActive() : false); lcc.getContextManager().cleanupOnError(se, isactive); } } }
          Hide
          Myrna van Lunteren added a comment -

          I did not see this error with nstest runs on the 10.8 branch after backing out as per DERBY-5448.

          Show
          Myrna van Lunteren added a comment - I did not see this error with nstest runs on the 10.8 branch after backing out as per DERBY-5448 .
          Hide
          Mamta A. Satoor added a comment -

          I followed up on Mike's comment to this jira(on 03/Oct/11).

          derby.log shows IndexOutOfBoundsException followed by NullPointerException during the cleanup of exception received by SequenceUpdater.clearIdentity. But the original exception encountered by org.apache.derby.impl.sql.catalog.SequenceUpdater.clearIdentity never gets reported.

          The SequenceUpdater.clearIdentity has a try catch which calls org.apache.derby.iapi.services.context.ContextManager.cleanupOnError if an exception is caught. It looks like cleanupOnError only conditionally logs the information about the original exception. cleanupOnError has following check before it prints original exeption info in derby.log
          boolean reportError = reportError(error);
          If reportError is false, cleanupOnError does not log any information about the original exception.
          reportError() method returns false
          1)if the exception is ShutdownException or
          2)if the exception is a StandardException and for some reason, it's reporting type is set to StandardException.REPORT_NEVER or
          3)if the exception is a StandardException and it's reporting type is set to StandardException.REPORT_DEFAULT but it's severity level is not as expected

          I am not sure why do we not log all kinds of exceptions while cleaning up the context on that exception. Having the information about the original exception will definitely help us figure out why SequenceUpdate.clearIdentity failed.

          I can think of two options at this point(there might be other ways to handle this too)
          1)Log all kinds of exceptions in ContextManager.cleanupOnError irrespective of what reportError says or
          2)Check in SequenceUpdate.clearIdentity if the exception caught has reportError set to false. If so, then go ahead and log it before calling ContextManager.cleanupOnError

          For now, I will go ahead and work on a temporary patch based on option 2). We can then rerun nstest using that patch and hope that it runs into IndexOutOfBoundsException again but this time, we will log the original error in derby.log

          In order to make sure that my changes do work, in my codeline, I will force trace my code changes to make sure that we log the exception received by clearIdentity.

          Show
          Mamta A. Satoor added a comment - I followed up on Mike's comment to this jira(on 03/Oct/11). derby.log shows IndexOutOfBoundsException followed by NullPointerException during the cleanup of exception received by SequenceUpdater.clearIdentity. But the original exception encountered by org.apache.derby.impl.sql.catalog.SequenceUpdater.clearIdentity never gets reported. The SequenceUpdater.clearIdentity has a try catch which calls org.apache.derby.iapi.services.context.ContextManager.cleanupOnError if an exception is caught. It looks like cleanupOnError only conditionally logs the information about the original exception. cleanupOnError has following check before it prints original exeption info in derby.log boolean reportError = reportError(error); If reportError is false, cleanupOnError does not log any information about the original exception. reportError() method returns false 1)if the exception is ShutdownException or 2)if the exception is a StandardException and for some reason, it's reporting type is set to StandardException.REPORT_NEVER or 3)if the exception is a StandardException and it's reporting type is set to StandardException.REPORT_DEFAULT but it's severity level is not as expected I am not sure why do we not log all kinds of exceptions while cleaning up the context on that exception. Having the information about the original exception will definitely help us figure out why SequenceUpdate.clearIdentity failed. I can think of two options at this point(there might be other ways to handle this too) 1)Log all kinds of exceptions in ContextManager.cleanupOnError irrespective of what reportError says or 2)Check in SequenceUpdate.clearIdentity if the exception caught has reportError set to false. If so, then go ahead and log it before calling ContextManager.cleanupOnError For now, I will go ahead and work on a temporary patch based on option 2). We can then rerun nstest using that patch and hope that it runs into IndexOutOfBoundsException again but this time, we will log the original error in derby.log In order to make sure that my changes do work, in my codeline, I will force trace my code changes to make sure that we log the exception received by clearIdentity.
          Hide
          Mamta A. Satoor added a comment -

          IndexOutOfBoundException is raised during the clean up of the StandardException raised by SequenceUpdate.clearIdentity. The clearIdentity method has a try catch block and the catch block, calls ContextManager.cleanupOnError to handle the StandardException it received. But ContextManager.cleanupOnError will NOT log the passed StandardException only if the passed exception's reporting value is set to StandardException.REPORT_NEVER or if it's reporting value is set to StandardException.REPORT_DEFAULT but it's severity level is not high enough. We found in this jira that this can make us loose information about the StandardException if ContextManager.cleanupOnError itself runs into a Runtime Exception like IndexOutOfBoundsException. To avoid such a situation, we will log the StandardException in SeuqneceUpdate if ContextManager.cleanupOnError is not going to log it. It will be good to run the nstest again hoping that we will run IndexOutOfBoundException but this time around, we will know the root cause of the problem in clearIdentity.

          There might be other ways of handling this problem. Would love to know what community thinks. It will also be interesting to know why ContextManager,cleanupOnError does not log all kinds of StandardExceptions. It will definitely be very useful to have the information for debugging purposes.

          Show
          Mamta A. Satoor added a comment - IndexOutOfBoundException is raised during the clean up of the StandardException raised by SequenceUpdate.clearIdentity. The clearIdentity method has a try catch block and the catch block, calls ContextManager.cleanupOnError to handle the StandardException it received. But ContextManager.cleanupOnError will NOT log the passed StandardException only if the passed exception's reporting value is set to StandardException.REPORT_NEVER or if it's reporting value is set to StandardException.REPORT_DEFAULT but it's severity level is not high enough. We found in this jira that this can make us loose information about the StandardException if ContextManager.cleanupOnError itself runs into a Runtime Exception like IndexOutOfBoundsException. To avoid such a situation, we will log the StandardException in SeuqneceUpdate if ContextManager.cleanupOnError is not going to log it. It will be good to run the nstest again hoping that we will run IndexOutOfBoundException but this time around, we will know the root cause of the problem in clearIdentity. There might be other ways of handling this problem. Would love to know what community thinks. It will also be interesting to know why ContextManager,cleanupOnError does not log all kinds of StandardExceptions. It will definitely be very useful to have the information for debugging purposes.
          Hide
          Knut Anders Hatlen added a comment -

          Would setting derby.stream.error.logSeverityLevel=0 make ContextManager log the exception, or would it still ignore some StandardExceptions? (Myrna's comments from 30/Sep/11 indicate that this was attempted in run #5, but the log was too big to attach, and I don't think the contents from that log have been analyzed.)

          Show
          Knut Anders Hatlen added a comment - Would setting derby.stream.error.logSeverityLevel=0 make ContextManager log the exception, or would it still ignore some StandardExceptions? (Myrna's comments from 30/Sep/11 indicate that this was attempted in run #5, but the log was too big to attach, and I don't think the contents from that log have been analyzed.)
          Hide
          Mamta A. Satoor added a comment -

          Knut, this is how ContextManager.cleanipOnError decides what to report
          private boolean reportError(Throwable t) {

          if (t instanceof StandardException) {

          StandardException se = (StandardException) t;

          switch (se.report())

          { case StandardException.REPORT_DEFAULT: int level = se.getSeverity(); return (level >= logSeverityLevel) || (level == ExceptionSeverity.NO_APPLICABLE_SEVERITY); case StandardException.REPORT_NEVER: return false; case StandardException.REPORT_ALWAYS: default: return true; }

          }

          return !(t instanceof ShutdownException);

          }

          So, it looks like setting derby.stream.error.logSeverityLevel=0 would make ContextManager log the exception,

          Show
          Mamta A. Satoor added a comment - Knut, this is how ContextManager.cleanipOnError decides what to report private boolean reportError(Throwable t) { if (t instanceof StandardException) { StandardException se = (StandardException) t; switch (se.report()) { case StandardException.REPORT_DEFAULT: int level = se.getSeverity(); return (level >= logSeverityLevel) || (level == ExceptionSeverity.NO_APPLICABLE_SEVERITY); case StandardException.REPORT_NEVER: return false; case StandardException.REPORT_ALWAYS: default: return true; } } return !(t instanceof ShutdownException); } So, it looks like setting derby.stream.error.logSeverityLevel=0 would make ContextManager log the exception,
          Hide
          Mamta A. Satoor added a comment -

          I ran nstest few times on a windows machine with ibm jdk 6 using trunk insane jars with my patch included in the jar and was able to run into IndexOutOfBoundsException 2 times. Both the times it took over 10hrs to run into IndexOutOfBoundsException. I have attached the derby.log for both the times as derby1.log and derby2.log. With my patch, now the original standard exception is getting logged before IndexOutOfBoundsException.
          Following is the relevant log from derby1.log
          Cleanup action completed
          ERROR 40001: A lock could not be obtained due to a deadlock, cycle of locks and waiters is:
          Lock : ROW, SYSCOLUMNS, (5,16)
          Waiting XID :

          {438038, X}

          , NSTEST, update nstesttab set t_numeric_large = ? where serialkey = 111243
          Granted XID :

          {438142, S}
          Lock : ROW, NSTESTTAB, (1828,13)
          Waiting XID : {438142, S}

          , NSTEST, select max(serialkey) from nstesttab where serialkey > ?
          Granted XID :

          {438000, X}


          Lock : ROW, SYSCOLUMNS, (5,16)
          Waiting XID :

          {438000, S}

          , NSTEST, delete from nstesttab where serialkey = ?
          . The selected victim is XID : 438038.
          at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
          at org.apache.derby.impl.services.locks.Deadlock.buildException(Unknown Source)
          at org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(Unknown Source)
          at org.apache.derby.impl.services.locks.AbstractPool.lockObject(Unknown Source)
          at org.apache.derby.impl.services.locks.ConcurrentPool.lockObject(Unknown Source)
          at org.apache.derby.impl.store.raw.xact.RowLocking3.lockRecordForWrite(Unknown Source)
          at org.apache.derby.impl.store.access.conglomerate.OpenConglomerate.lockPositionForWrite(Unknown Source)
          at org.apache.derby.impl.store.access.conglomerate.GenericConglomerateController.fetch(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.updateCurrentSeqValue(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.updateCurrentIdentityValue(Unknown Source)
          at org.apache.derby.impl.sql.catalog.SequenceUpdater$SyscolumnsUpdater.updateCurrentValueOnDisk(Unknown Source)
          at org.apache.derby.impl.sql.catalog.SequenceUpdater.updateCurrentValueOnDisk(Unknown Source)
          at org.apache.derby.impl.sql.catalog.SequenceUpdater.clean(Unknown Source)
          at org.apache.derby.impl.sql.catalog.SequenceUpdater.clearIdentity(Unknown Source)
          at org.apache.derby.impl.services.cache.ConcurrentCache.removeEntry(Unknown Source)
          at org.apache.derby.impl.services.cache.ConcurrentCache.ageOut(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearSequenceCaches(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearCaches(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.doneReading(Unknown Source)
          at org.apache.derby.impl.sql.GenericStatement.prepMinion(Unknown Source)
          at org.apache.derby.impl.sql.GenericStatement.prepare(Unknown Source)
          at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(Unknown Source)
          at org.apache.derby.impl.jdbc.EmbedPreparedStatement.<init>(Unknown Source)
          at org.apache.derby.jdbc.Driver40.newEmbedPreparedStatement(Unknown Source)
          at org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(Unknown Source)
          at org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(Unknown Source)
          at org.apache.derbyTesting.system.nstest.utils.DbUtil.update_one_row(DbUtil.java:260)
          at org.apache.derbyTesting.system.nstest.tester.TesterObject.doIUDOperation(TesterObject.java:162)
          at org.apache.derbyTesting.system.nstest.tester.Tester2.startTesting(Tester2.java:109)
          at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:555)

          New exception raised during cleanup Index: -1, Size: 14
          java.lang.IndexOutOfBoundsException: Index: -1, Size: 14
          at java.util.ArrayList.remove(ArrayList.java:552)
          at org.apache.derby.iapi.services.context.ContextManager.popContext(Unknown Source)
          at org.apache.derby.iapi.services.context.ContextImpl.popMe(Unknown Source)
          at org.apache.derby.impl.store.access.RAMTransaction.destroy(Unknown Source)
          at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.doRollback(Unknown Source)
          at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.internalRollback(Unknown Source)
          at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.cleanupOnError(Unknown Source)
          at org.apache.derby.iapi.services.context.ContextManager.cleanupOnError(Unknown Source)
          at org.apache.derby.impl.sql.catalog.SequenceUpdater.clearIdentity(Unknown Source)
          at org.apache.derby.impl.services.cache.ConcurrentCache.removeEntry(Unknown Source)
          at org.apache.derby.impl.services.cache.ConcurrentCache.ageOut(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearSequenceCaches(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearCaches(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.doneReading(Unknown Source)
          at org.apache.derby.impl.sql.GenericStatement.prepMinion(Unknown Source)
          at org.apache.derby.impl.sql.GenericStatement.prepare(Unknown Source)
          at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(Unknown Source)
          at org.apache.derby.impl.jdbc.EmbedPreparedStatement.<init>(Unknown Source)
          at org.apache.derby.jdbc.Driver40.newEmbedPreparedStatement(Unknown Source)
          at org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(Unknown Source)
          at org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(Unknown Source)
          at org.apache.derbyTesting.system.nstest.utils.DbUtil.update_one_row(DbUtil.java:260)
          at org.apache.derbyTesting.system.nstest.tester.TesterObject.doIUDOperation(TesterObject.java:162)
          at org.apache.derbyTesting.system.nstest.tester.Tester2.startTesting(Tester2.java:109)
          at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:555)
          Cleanup action completed

          Following is the relevant log from derby2.log
          Tue Nov 01 20:20:20 PDT 2011:
          Booting Derby version The Apache Software Foundation - Apache Derby - 10.9.0.0 alpha - (1185351M): instance 5a3828f5-0133-600f-f7c8-0000001345f0
          on database directory D:\mamta\derby5422\anotherrun\restoredir\nstestdb with class loader sun.misc.Launcher$AppClassLoader@44ef44ef
          Loaded from file:/D:/mamta/trunkInsane5422Trace/derby.jar
          java.vendor=IBM Corporation
          java.runtime.version=jvmwi3260sr9-20110203_74623
          java.fullversion=JRE 1.6.0 IBM J9 2.4 Windows Server 2003 x86-32 jvmwi3260sr9-20110203_74623 (JIT enabled, AOT enabled)
          J9VM - 20110203_074623
          JIT - r9_20101028_17488ifx3
          GC - 20101027_AA
          user.dir=D:\mamta\derby5422\anotherrun
          derby.system.home=null
          Database Class Loader started - derby.database.classpath=''
          ERROR 40XL1: A lock could not be obtained within the time requested
          at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
          at org.apache.derby.impl.services.locks.AbstractPool.lockObject(Unknown Source)
          at org.apache.derby.impl.services.locks.ConcurrentPool.lockObject(Unknown Source)
          at org.apache.derby.impl.store.raw.xact.RowLocking3.lockRecordForWrite(Unknown Source)
          at org.apache.derby.impl.store.access.conglomerate.OpenConglomerate.lockPositionForWrite(Unknown Source)
          at org.apache.derby.impl.store.access.conglomerate.GenericConglomerateController.fetch(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.updateCurrentSeqValue(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.updateCurrentIdentityValue(Unknown Source)
          at org.apache.derby.impl.sql.catalog.SequenceUpdater$SyscolumnsUpdater.updateCurrentValueOnDisk(Unknown Source)
          at org.apache.derby.impl.sql.catalog.SequenceUpdater.updateCurrentValueOnDisk(Unknown Source)
          at org.apache.derby.impl.sql.catalog.SequenceUpdater.clean(Unknown Source)
          at org.apache.derby.impl.sql.catalog.SequenceUpdater.clearIdentity(Unknown Source)
          at org.apache.derby.impl.services.cache.ConcurrentCache.removeEntry(Unknown Source)
          at org.apache.derby.impl.services.cache.ConcurrentCache.ageOut(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearSequenceCaches(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearCaches(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.startWriting(Unknown Source)
          at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.invalidateStatements(Unknown Source)
          at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.writeUpdatedStats(Unknown Source)
          at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.updateIndexStatsMinion(Unknown Source)
          at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.generateStatistics(Unknown Source)
          at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.processingLoop(Unknown Source)
          at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.run(Unknown Source)
          at java.lang.Thread.run(Thread.java:736)

          ERROR 40XL1: A lock could not be obtained within the time requested
          at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
          at org.apache.derby.impl.services.locks.AbstractPool.lockObject(Unknown Source)
          at org.apache.derby.impl.services.locks.ConcurrentPool.lockObject(Unknown Source)
          at org.apache.derby.impl.store.raw.xact.RowLocking3.lockRecordForWrite(Unknown Source)
          at org.apache.derby.impl.store.access.conglomerate.OpenConglomerate.lockPositionForWrite(Unknown Source)
          at org.apache.derby.impl.store.access.conglomerate.GenericConglomerateController.fetch(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.updateCurrentSeqValue(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.updateCurrentIdentityValue(Unknown Source)
          at org.apache.derby.impl.sql.catalog.SequenceUpdater$SyscolumnsUpdater.updateCurrentValueOnDisk(Unknown Source)
          at org.apache.derby.impl.sql.catalog.SequenceUpdater.updateCurrentValueOnDisk(Unknown Source)
          at org.apache.derby.impl.sql.catalog.SequenceUpdater.clean(Unknown Source)
          at org.apache.derby.impl.sql.catalog.SequenceUpdater.clearIdentity(Unknown Source)
          at org.apache.derby.impl.services.cache.ConcurrentCache.removeEntry(Unknown Source)
          at org.apache.derby.impl.services.cache.ConcurrentCache.ageOut(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearSequenceCaches(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearCaches(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.transactionFinished(Unknown Source)
          at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.finishDDTransaction(Unknown Source)
          at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.doRollback(Unknown Source)
          at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.internalRollback(Unknown Source)
          at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.invalidateStatements(Unknown Source)
          at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.writeUpdatedStats(Unknown Source)
          at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.updateIndexStatsMinion(Unknown Source)
          at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.generateStatistics(Unknown Source)
          at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.processingLoop(Unknown Source)
          at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.run(Unknown Source)
          at java.lang.Thread.run(Thread.java:736)

          ERROR 40XL1: A lock could not be obtained within the time requested
          at org.apache.derby.iapi.error.StandardException.newException(Unknown Source)
          at org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(Unknown Source)
          at org.apache.derby.impl.services.locks.AbstractPool.lockObject(Unknown Source)
          at org.apache.derby.impl.services.locks.ConcurrentPool.lockObject(Unknown Source)
          at org.apache.derby.impl.store.raw.xact.RowLocking3.lockRecordForWrite(Unknown Source)
          at org.apache.derby.impl.store.access.conglomerate.OpenConglomerate.lockPositionForWrite(Unknown Source)
          at org.apache.derby.impl.store.access.conglomerate.GenericConglomerateController.fetch(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.updateCurrentSeqValue(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.updateCurrentIdentityValue(Unknown Source)
          at org.apache.derby.impl.sql.catalog.SequenceUpdater$SyscolumnsUpdater.updateCurrentValueOnDisk(Unknown Source)
          at org.apache.derby.impl.sql.catalog.SequenceUpdater.updateCurrentValueOnDisk(Unknown Source)
          at org.apache.derby.impl.sql.catalog.SequenceUpdater.clean(Unknown Source)
          at org.apache.derby.impl.sql.catalog.SequenceUpdater.clearIdentity(Unknown Source)
          at org.apache.derby.impl.services.cache.ConcurrentCache.removeEntry(Unknown Source)
          at org.apache.derby.impl.services.cache.ConcurrentCache.ageOut(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearSequenceCaches(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearCaches(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.doneReading(Unknown Source)
          at org.apache.derby.impl.sql.GenericStatement.prepMinion(Unknown Source)
          at org.apache.derby.impl.sql.GenericStatement.prepare(Unknown Source)
          at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(Unknown Source)
          at org.apache.derby.impl.jdbc.EmbedPreparedStatement.<init>(Unknown Source)
          at org.apache.derby.jdbc.Driver40.newEmbedPreparedStatement(Unknown Source)
          at org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(Unknown Source)
          at org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(Unknown Source)
          at org.apache.derbyTesting.system.nstest.utils.DbUtil.update_one_row(DbUtil.java:260)
          at org.apache.derbyTesting.system.nstest.tester.TesterObject.doIUDOperation(TesterObject.java:162)
          at org.apache.derbyTesting.system.nstest.tester.Tester1.startTesting(Tester1.java:118)
          at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:551)

          New exception raised during cleanup Index: -1, Size: 14
          java.lang.IndexOutOfBoundsException: Index: -1, Size: 14
          at java.util.ArrayList.remove(ArrayList.java:552)
          at org.apache.derby.iapi.services.context.ContextManager.popContext(Unknown Source)
          at org.apache.derby.iapi.services.context.ContextImpl.popMe(Unknown Source)
          at org.apache.derby.impl.store.access.RAMTransaction.destroy(Unknown Source)
          at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.doRollback(Unknown Source)
          at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.internalRollback(Unknown Source)
          at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.cleanupOnError(Unknown Source)
          at org.apache.derby.iapi.services.context.ContextManager.cleanupOnError(Unknown Source)
          at org.apache.derby.impl.sql.catalog.SequenceUpdater.clearIdentity(Unknown Source)
          at org.apache.derby.impl.services.cache.ConcurrentCache.removeEntry(Unknown Source)
          at org.apache.derby.impl.services.cache.ConcurrentCache.ageOut(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearSequenceCaches(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearCaches(Unknown Source)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.doneReading(Unknown Source)
          at org.apache.derby.impl.sql.GenericStatement.prepMinion(Unknown Source)
          at org.apache.derby.impl.sql.GenericStatement.prepare(Unknown Source)
          at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(Unknown Source)
          at org.apache.derby.impl.jdbc.EmbedPreparedStatement.<init>(Unknown Source)
          at org.apache.derby.jdbc.Driver40.newEmbedPreparedStatement(Unknown Source)
          at org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(Unknown Source)
          at org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(Unknown Source)
          at org.apache.derbyTesting.system.nstest.utils.DbUtil.update_one_row(DbUtil.java:260)
          at org.apache.derbyTesting.system.nstest.tester.TesterObject.doIUDOperation(TesterObject.java:162)
          at org.apache.derbyTesting.system.nstest.tester.Tester1.startTesting(Tester1.java:118)
          at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:551)
          Cleanup action completed

          Show
          Mamta A. Satoor added a comment - I ran nstest few times on a windows machine with ibm jdk 6 using trunk insane jars with my patch included in the jar and was able to run into IndexOutOfBoundsException 2 times. Both the times it took over 10hrs to run into IndexOutOfBoundsException. I have attached the derby.log for both the times as derby1.log and derby2.log. With my patch, now the original standard exception is getting logged before IndexOutOfBoundsException. Following is the relevant log from derby1.log Cleanup action completed ERROR 40001: A lock could not be obtained due to a deadlock, cycle of locks and waiters is: Lock : ROW, SYSCOLUMNS, (5,16) Waiting XID : {438038, X} , NSTEST, update nstesttab set t_numeric_large = ? where serialkey = 111243 Granted XID : {438142, S} Lock : ROW, NSTESTTAB, (1828,13) Waiting XID : {438142, S} , NSTEST, select max(serialkey) from nstesttab where serialkey > ? Granted XID : {438000, X} Lock : ROW, SYSCOLUMNS, (5,16) Waiting XID : {438000, S} , NSTEST, delete from nstesttab where serialkey = ? . The selected victim is XID : 438038. at org.apache.derby.iapi.error.StandardException.newException(Unknown Source) at org.apache.derby.impl.services.locks.Deadlock.buildException(Unknown Source) at org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(Unknown Source) at org.apache.derby.impl.services.locks.AbstractPool.lockObject(Unknown Source) at org.apache.derby.impl.services.locks.ConcurrentPool.lockObject(Unknown Source) at org.apache.derby.impl.store.raw.xact.RowLocking3.lockRecordForWrite(Unknown Source) at org.apache.derby.impl.store.access.conglomerate.OpenConglomerate.lockPositionForWrite(Unknown Source) at org.apache.derby.impl.store.access.conglomerate.GenericConglomerateController.fetch(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.updateCurrentSeqValue(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.updateCurrentIdentityValue(Unknown Source) at org.apache.derby.impl.sql.catalog.SequenceUpdater$SyscolumnsUpdater.updateCurrentValueOnDisk(Unknown Source) at org.apache.derby.impl.sql.catalog.SequenceUpdater.updateCurrentValueOnDisk(Unknown Source) at org.apache.derby.impl.sql.catalog.SequenceUpdater.clean(Unknown Source) at org.apache.derby.impl.sql.catalog.SequenceUpdater.clearIdentity(Unknown Source) at org.apache.derby.impl.services.cache.ConcurrentCache.removeEntry(Unknown Source) at org.apache.derby.impl.services.cache.ConcurrentCache.ageOut(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearSequenceCaches(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearCaches(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.doneReading(Unknown Source) at org.apache.derby.impl.sql.GenericStatement.prepMinion(Unknown Source) at org.apache.derby.impl.sql.GenericStatement.prepare(Unknown Source) at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(Unknown Source) at org.apache.derby.impl.jdbc.EmbedPreparedStatement.<init>(Unknown Source) at org.apache.derby.jdbc.Driver40.newEmbedPreparedStatement(Unknown Source) at org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(Unknown Source) at org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(Unknown Source) at org.apache.derbyTesting.system.nstest.utils.DbUtil.update_one_row(DbUtil.java:260) at org.apache.derbyTesting.system.nstest.tester.TesterObject.doIUDOperation(TesterObject.java:162) at org.apache.derbyTesting.system.nstest.tester.Tester2.startTesting(Tester2.java:109) at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:555) New exception raised during cleanup Index: -1, Size: 14 java.lang.IndexOutOfBoundsException: Index: -1, Size: 14 at java.util.ArrayList.remove(ArrayList.java:552) at org.apache.derby.iapi.services.context.ContextManager.popContext(Unknown Source) at org.apache.derby.iapi.services.context.ContextImpl.popMe(Unknown Source) at org.apache.derby.impl.store.access.RAMTransaction.destroy(Unknown Source) at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.doRollback(Unknown Source) at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.internalRollback(Unknown Source) at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.cleanupOnError(Unknown Source) at org.apache.derby.iapi.services.context.ContextManager.cleanupOnError(Unknown Source) at org.apache.derby.impl.sql.catalog.SequenceUpdater.clearIdentity(Unknown Source) at org.apache.derby.impl.services.cache.ConcurrentCache.removeEntry(Unknown Source) at org.apache.derby.impl.services.cache.ConcurrentCache.ageOut(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearSequenceCaches(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearCaches(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.doneReading(Unknown Source) at org.apache.derby.impl.sql.GenericStatement.prepMinion(Unknown Source) at org.apache.derby.impl.sql.GenericStatement.prepare(Unknown Source) at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(Unknown Source) at org.apache.derby.impl.jdbc.EmbedPreparedStatement.<init>(Unknown Source) at org.apache.derby.jdbc.Driver40.newEmbedPreparedStatement(Unknown Source) at org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(Unknown Source) at org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(Unknown Source) at org.apache.derbyTesting.system.nstest.utils.DbUtil.update_one_row(DbUtil.java:260) at org.apache.derbyTesting.system.nstest.tester.TesterObject.doIUDOperation(TesterObject.java:162) at org.apache.derbyTesting.system.nstest.tester.Tester2.startTesting(Tester2.java:109) at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:555) Cleanup action completed Following is the relevant log from derby2.log Tue Nov 01 20:20:20 PDT 2011: Booting Derby version The Apache Software Foundation - Apache Derby - 10.9.0.0 alpha - (1185351M): instance 5a3828f5-0133-600f-f7c8-0000001345f0 on database directory D:\mamta\derby5422\anotherrun\restoredir\nstestdb with class loader sun.misc.Launcher$AppClassLoader@44ef44ef Loaded from file:/D:/mamta/trunkInsane5422Trace/derby.jar java.vendor=IBM Corporation java.runtime.version=jvmwi3260sr9-20110203_74623 java.fullversion=JRE 1.6.0 IBM J9 2.4 Windows Server 2003 x86-32 jvmwi3260sr9-20110203_74623 (JIT enabled, AOT enabled) J9VM - 20110203_074623 JIT - r9_20101028_17488ifx3 GC - 20101027_AA user.dir=D:\mamta\derby5422\anotherrun derby.system.home=null Database Class Loader started - derby.database.classpath='' ERROR 40XL1: A lock could not be obtained within the time requested at org.apache.derby.iapi.error.StandardException.newException(Unknown Source) at org.apache.derby.impl.services.locks.AbstractPool.lockObject(Unknown Source) at org.apache.derby.impl.services.locks.ConcurrentPool.lockObject(Unknown Source) at org.apache.derby.impl.store.raw.xact.RowLocking3.lockRecordForWrite(Unknown Source) at org.apache.derby.impl.store.access.conglomerate.OpenConglomerate.lockPositionForWrite(Unknown Source) at org.apache.derby.impl.store.access.conglomerate.GenericConglomerateController.fetch(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.updateCurrentSeqValue(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.updateCurrentIdentityValue(Unknown Source) at org.apache.derby.impl.sql.catalog.SequenceUpdater$SyscolumnsUpdater.updateCurrentValueOnDisk(Unknown Source) at org.apache.derby.impl.sql.catalog.SequenceUpdater.updateCurrentValueOnDisk(Unknown Source) at org.apache.derby.impl.sql.catalog.SequenceUpdater.clean(Unknown Source) at org.apache.derby.impl.sql.catalog.SequenceUpdater.clearIdentity(Unknown Source) at org.apache.derby.impl.services.cache.ConcurrentCache.removeEntry(Unknown Source) at org.apache.derby.impl.services.cache.ConcurrentCache.ageOut(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearSequenceCaches(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearCaches(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.startWriting(Unknown Source) at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.invalidateStatements(Unknown Source) at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.writeUpdatedStats(Unknown Source) at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.updateIndexStatsMinion(Unknown Source) at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.generateStatistics(Unknown Source) at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.processingLoop(Unknown Source) at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.run(Unknown Source) at java.lang.Thread.run(Thread.java:736) ERROR 40XL1: A lock could not be obtained within the time requested at org.apache.derby.iapi.error.StandardException.newException(Unknown Source) at org.apache.derby.impl.services.locks.AbstractPool.lockObject(Unknown Source) at org.apache.derby.impl.services.locks.ConcurrentPool.lockObject(Unknown Source) at org.apache.derby.impl.store.raw.xact.RowLocking3.lockRecordForWrite(Unknown Source) at org.apache.derby.impl.store.access.conglomerate.OpenConglomerate.lockPositionForWrite(Unknown Source) at org.apache.derby.impl.store.access.conglomerate.GenericConglomerateController.fetch(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.updateCurrentSeqValue(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.updateCurrentIdentityValue(Unknown Source) at org.apache.derby.impl.sql.catalog.SequenceUpdater$SyscolumnsUpdater.updateCurrentValueOnDisk(Unknown Source) at org.apache.derby.impl.sql.catalog.SequenceUpdater.updateCurrentValueOnDisk(Unknown Source) at org.apache.derby.impl.sql.catalog.SequenceUpdater.clean(Unknown Source) at org.apache.derby.impl.sql.catalog.SequenceUpdater.clearIdentity(Unknown Source) at org.apache.derby.impl.services.cache.ConcurrentCache.removeEntry(Unknown Source) at org.apache.derby.impl.services.cache.ConcurrentCache.ageOut(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearSequenceCaches(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearCaches(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.transactionFinished(Unknown Source) at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.finishDDTransaction(Unknown Source) at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.doRollback(Unknown Source) at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.internalRollback(Unknown Source) at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.invalidateStatements(Unknown Source) at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.writeUpdatedStats(Unknown Source) at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.updateIndexStatsMinion(Unknown Source) at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.generateStatistics(Unknown Source) at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.processingLoop(Unknown Source) at org.apache.derby.impl.services.daemon.IndexStatisticsDaemonImpl.run(Unknown Source) at java.lang.Thread.run(Thread.java:736) ERROR 40XL1: A lock could not be obtained within the time requested at org.apache.derby.iapi.error.StandardException.newException(Unknown Source) at org.apache.derby.impl.services.locks.ConcurrentLockSet.lockObject(Unknown Source) at org.apache.derby.impl.services.locks.AbstractPool.lockObject(Unknown Source) at org.apache.derby.impl.services.locks.ConcurrentPool.lockObject(Unknown Source) at org.apache.derby.impl.store.raw.xact.RowLocking3.lockRecordForWrite(Unknown Source) at org.apache.derby.impl.store.access.conglomerate.OpenConglomerate.lockPositionForWrite(Unknown Source) at org.apache.derby.impl.store.access.conglomerate.GenericConglomerateController.fetch(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.updateCurrentSeqValue(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.updateCurrentIdentityValue(Unknown Source) at org.apache.derby.impl.sql.catalog.SequenceUpdater$SyscolumnsUpdater.updateCurrentValueOnDisk(Unknown Source) at org.apache.derby.impl.sql.catalog.SequenceUpdater.updateCurrentValueOnDisk(Unknown Source) at org.apache.derby.impl.sql.catalog.SequenceUpdater.clean(Unknown Source) at org.apache.derby.impl.sql.catalog.SequenceUpdater.clearIdentity(Unknown Source) at org.apache.derby.impl.services.cache.ConcurrentCache.removeEntry(Unknown Source) at org.apache.derby.impl.services.cache.ConcurrentCache.ageOut(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearSequenceCaches(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearCaches(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.doneReading(Unknown Source) at org.apache.derby.impl.sql.GenericStatement.prepMinion(Unknown Source) at org.apache.derby.impl.sql.GenericStatement.prepare(Unknown Source) at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(Unknown Source) at org.apache.derby.impl.jdbc.EmbedPreparedStatement.<init>(Unknown Source) at org.apache.derby.jdbc.Driver40.newEmbedPreparedStatement(Unknown Source) at org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(Unknown Source) at org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(Unknown Source) at org.apache.derbyTesting.system.nstest.utils.DbUtil.update_one_row(DbUtil.java:260) at org.apache.derbyTesting.system.nstest.tester.TesterObject.doIUDOperation(TesterObject.java:162) at org.apache.derbyTesting.system.nstest.tester.Tester1.startTesting(Tester1.java:118) at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:551) New exception raised during cleanup Index: -1, Size: 14 java.lang.IndexOutOfBoundsException: Index: -1, Size: 14 at java.util.ArrayList.remove(ArrayList.java:552) at org.apache.derby.iapi.services.context.ContextManager.popContext(Unknown Source) at org.apache.derby.iapi.services.context.ContextImpl.popMe(Unknown Source) at org.apache.derby.impl.store.access.RAMTransaction.destroy(Unknown Source) at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.doRollback(Unknown Source) at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.internalRollback(Unknown Source) at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.cleanupOnError(Unknown Source) at org.apache.derby.iapi.services.context.ContextManager.cleanupOnError(Unknown Source) at org.apache.derby.impl.sql.catalog.SequenceUpdater.clearIdentity(Unknown Source) at org.apache.derby.impl.services.cache.ConcurrentCache.removeEntry(Unknown Source) at org.apache.derby.impl.services.cache.ConcurrentCache.ageOut(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearSequenceCaches(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.clearCaches(Unknown Source) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.doneReading(Unknown Source) at org.apache.derby.impl.sql.GenericStatement.prepMinion(Unknown Source) at org.apache.derby.impl.sql.GenericStatement.prepare(Unknown Source) at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.prepareInternalStatement(Unknown Source) at org.apache.derby.impl.jdbc.EmbedPreparedStatement.<init>(Unknown Source) at org.apache.derby.jdbc.Driver40.newEmbedPreparedStatement(Unknown Source) at org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(Unknown Source) at org.apache.derby.impl.jdbc.EmbedConnection.prepareStatement(Unknown Source) at org.apache.derbyTesting.system.nstest.utils.DbUtil.update_one_row(DbUtil.java:260) at org.apache.derbyTesting.system.nstest.tester.TesterObject.doIUDOperation(TesterObject.java:162) at org.apache.derbyTesting.system.nstest.tester.Tester1.startTesting(Tester1.java:118) at org.apache.derbyTesting.system.nstest.NsTest.run(NsTest.java:551) Cleanup action completed
          Hide
          Myrna van Lunteren added a comment -

          This happened in 10.8.2.1, but not 10.8.2.2 after back-out of DERBY-4437 changes. But version 10.8.2.1 got merged to released version 10.8.2.2, making the found-in version incorrect.
          So marking this as found in 10.9.

          Show
          Myrna van Lunteren added a comment - This happened in 10.8.2.1, but not 10.8.2.2 after back-out of DERBY-4437 changes. But version 10.8.2.1 got merged to released version 10.8.2.2, making the found-in version incorrect. So marking this as found in 10.9.
          Hide
          Myrna van Lunteren added a comment -

          I'm increasing the urgency of this issue.
          I ran nstest small configuration (see DERBY-5649) with insane jars with the tree sync-ed to 1295990, and saw this again.

          If I understand Mamta's research correctly, there's a lock time out underlying the IndexOutOfBoundsException and NullPointerException, but the result of this is that the connection to the database is lost, which is a pretty serious result from a lock timeout.

          Show
          Myrna van Lunteren added a comment - I'm increasing the urgency of this issue. I ran nstest small configuration (see DERBY-5649 ) with insane jars with the tree sync-ed to 1295990, and saw this again. If I understand Mamta's research correctly, there's a lock time out underlying the IndexOutOfBoundsException and NullPointerException, but the result of this is that the connection to the database is lost, which is a pretty serious result from a lock timeout.
          Hide
          Myrna van Lunteren added a comment -

          I've attached the output to DERBY-5661 of a test run (nstest.out6) to on a slow windows (XP) machine with sane trunk jars and ibm 1.6 SR9 FP1 which show the connection lost trouble.

          For that run, I had sync-ed up my build to include the changes to the nstest from DERBY-5649 and ran with the following test details:
          java -Dderby.nstest.backupRestore=false org.apache.derbyTesting.system.nstest.NsTest Embedded small > nstest.out6 2>&1

          and with a derby.properties in the directory where I started derby with the following contents:
          ---------------------------------------
          derby.infolog.append=true
          derby.stream.errorlogSeverity=0
          derby.language.logStatementText=true
          #derby.language.logQueryPlan=true
          derby.locks.monitor=true
          derby.locks.deadlockTrace=true
          #derby.locks.waitTimeout=300
          #derby.locks.deadlockTimeout=300
          ---------------------------------------

          This was on my slower 1 CPU system. The test ran into DERBY-5661, DERBY-5428, DERBY-5454, DERBY-5430, DERBY-5422. Also a strange ArrayIndexOutOfBounds error is visible in derby.log (renamed to derby.log6 to differentiate).

          Show
          Myrna van Lunteren added a comment - I've attached the output to DERBY-5661 of a test run (nstest.out6) to on a slow windows (XP) machine with sane trunk jars and ibm 1.6 SR9 FP1 which show the connection lost trouble. For that run, I had sync-ed up my build to include the changes to the nstest from DERBY-5649 and ran with the following test details: java -Dderby.nstest.backupRestore=false org.apache.derbyTesting.system.nstest.NsTest Embedded small > nstest.out6 2>&1 and with a derby.properties in the directory where I started derby with the following contents: --------------------------------------- derby.infolog.append=true derby.stream.errorlogSeverity=0 derby.language.logStatementText=true #derby.language.logQueryPlan=true derby.locks.monitor=true derby.locks.deadlockTrace=true #derby.locks.waitTimeout=300 #derby.locks.deadlockTimeout=300 --------------------------------------- This was on my slower 1 CPU system. The test ran into DERBY-5661 , DERBY-5428 , DERBY-5454 , DERBY-5430 , DERBY-5422 . Also a strange ArrayIndexOutOfBounds error is visible in derby.log (renamed to derby.log6 to differentiate).
          Hide
          Rick Hillegas added a comment -

          Hi Myrna,

          Now that derby-4437 has been backed out, it might make sense to check whether these IndexOutOfBoundsExceptions have been affected. Thanks.

          Show
          Rick Hillegas added a comment - Hi Myrna, Now that derby-4437 has been backed out, it might make sense to check whether these IndexOutOfBoundsExceptions have been affected. Thanks.
          Hide
          Myrna van Lunteren added a comment -

          I have run the test a number of times since the fix for DERBY-4437 was backed out and have not seen this again.

          I'm closing this issue as Cannot Reproduce, because this behavior was always somewhat elusive.

          Show
          Myrna van Lunteren added a comment - I have run the test a number of times since the fix for DERBY-4437 was backed out and have not seen this again. I'm closing this issue as Cannot Reproduce, because this behavior was always somewhat elusive.

            People

            • Assignee:
              Unassigned
              Reporter:
              Myrna van Lunteren
            • Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development