Derby
  1. Derby
  2. DERBY-5223

Thread's interrupted flag not always preserved after Derby returns from JDBC API call

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 10.8.1.2
    • Fix Version/s: 10.8.2.2, 10.9.1.0
    • Component/s: JDBC
    • Labels:
      None
    • Bug behavior facts:
      Regression Test Failure

      Description

      Sometimes we have this this stack trace on the log from SuitesAll:

      .Exception in thread "WorkerThread. Thread#5" junit.framework.AssertionFailedError
      at junit.framework.Assert.fail(Assert.java:47)
      at junit.framework.Assert.assertTrue(Assert.java:20)
      at junit.framework.Assert.assertTrue(Assert.java:27)
      at org.apache.derbyTesting.functionTests.tests.store.InterruptResilienceTest$WorkerThread.run(InterruptResilienceTest.java:430)

      This happens sometimes when the application thread's interrupt flag is set before we enter a Derby API call, but the flag is cleared on return contrary to our specified behavior.

      Cf mention on https://issues.apache.org/jira/browse/DERBY-5081?focusedCommentId=13030155&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-13030155

      I can reproduce this every 20 runs or so on Linux with JDK7, but it has been seen also on Windows, so it is not VM specific.

      1. derby-5223.diff
        3 kB
        Dag H. Wanvik
      2. derby-5223.stat
        0.2 kB
        Dag H. Wanvik
      3. derby-5223b.diff
        3 kB
        Dag H. Wanvik
      4. derby-5223b.stat
        0.2 kB
        Dag H. Wanvik

        Issue Links

          Activity

          Dag H. Wanvik created issue -
          Dag H. Wanvik made changes -
          Field Original Value New Value
          Bug behavior facts [Regression Test Failure]
          Affects Version/s 10.8.1.2 [ 12316362 ]
          Component/s JDBC [ 11407 ]
          Hide
          Dag H. Wanvik added a comment -

          I instrumented this and retrieved the following stack trace which shows where Derby detected the interrupt, but failed to preserve the flag.
          Notice that on the stack we have the frame:

          GenericLanguageConnectionContext.initialize(GenericLanguageConnectionContext.java:401)

          The variable interruptedException is set to null just after that call, which is clearly wrong: the null initialization happens too late since, in this case, the connection has seen an interrupt in the line above, i.e. "setDefaultSchema(initDefaultSchemaDescriptor());".

          Hence, we lose the information that Derby has seen an interrupt and temporarily proceeded with the flag cleared (so that NIO can complete ok). On return from
          the connect call, the flag is thus never set back on again.

          ..java.lang.Exception: Stack trace
          at java.lang.Thread.dumpStack(Thread.java:1342)
          at org.apache.derby.iapi.util.InterruptStatus.setInterrupted(InterruptStatus.java:83)
          at org.apache.derby.impl.store.raw.data.BasePage.setExclusive(BasePage.java:1689)
          at org.apache.derby.impl.store.raw.data.BaseContainer.latchPage(BaseContainer.java:527)
          at org.apache.derby.impl.store.raw.data.FileContainer.latchPage(FileContainer.java:3530)
          at org.apache.derby.impl.store.raw.data.FileContainer.getUserPage(FileContainer.java:2549)
          at org.apache.derby.impl.store.raw.data.FileContainer.getPage(FileContainer.java:2591)
          at org.apache.derby.impl.store.raw.data.BaseContainerHandle.getPage(BaseContainerHandle.java:319)
          at org.apache.derby.impl.store.access.btree.ControlRow.get(ControlRow.java:833)
          at org.apache.derby.impl.store.access.btree.ControlRow.get(ControlRow.java:820)
          at org.apache.derby.impl.store.access.btree.BTreeScan.positionAtStartForForwardScan(BTreeScan.java:361)
          at org.apache.derby.impl.store.access.btree.BTreeForwardScan.positionAtStartPosition(BTreeForwardScan.java:70)
          at org.apache.derby.impl.store.access.btree.BTreeForwardScan.fetchRows(BTreeForwardScan.java:122)
          at org.apache.derby.impl.store.access.btree.BTreeScan.fetchNext(BTreeScan.java:1599)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getDescriptorViaIndexMinion(DataDictionaryImpl.java:9288)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getDescriptorViaIndex(DataDictionaryImpl.java:9212)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.locateSchemaRow(DataDictionaryImpl.java:1722)
          at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getSchemaDescriptor(DataDictionaryImpl.java:1589)
          at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.initDefaultSchemaDescriptor(GenericLanguageConnectionContext.java:426)
          at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.initialize(GenericLanguageConnectionContext.java:401)
          at org.apache.derby.impl.db.BasicDatabase.setupConnection(BasicDatabase.java:295)
          at org.apache.derby.impl.jdbc.TransactionResourceImpl.startTransaction(TransactionResourceImpl.java:189)
          at org.apache.derby.impl.jdbc.EmbedConnection.<init>(EmbedConnection.java:441)
          at org.apache.derby.impl.jdbc.EmbedConnection30.<init>(EmbedConnection30.java:73)
          at org.apache.derby.impl.jdbc.EmbedConnection40.<init>(EmbedConnection40.java:51)
          at org.apache.derby.jdbc.Driver40.getNewEmbedConnection(Driver40.java:70)
          at org.apache.derby.jdbc.InternalDriver.connect(InternalDriver.java:248)
          at org.apache.derby.jdbc.AutoloadedDriver.connect(AutoloadedDriver.java:146)
          at java.sql.DriverManager.getConnection(DriverManager.java:579)
          at java.sql.DriverManager.getConnection(DriverManager.java:190)
          at org.apache.derbyTesting.junit.DriverManagerConnector.openConnection(DriverManagerConnector.java:81)
          at org.apache.derbyTesting.junit.DriverManagerConnector.openConnection(DriverManagerConnector.java:43)
          at org.apache.derbyTesting.junit.TestConfiguration.openDefaultConnection(TestConfiguration.java:1574)
          at org.apache.derbyTesting.functionTests.tests.store.InterruptResilienceTest$WorkerThread.run(InterruptResilienceTest.java:432)
          Exception in thread "WorkerThread. Thread#4" junit.framework.AssertionFailedError
          at junit.framework.Assert.fail(Assert.java:47)
          at junit.framework.Assert.assertTrue(Assert.java:20)
          at junit.framework.Assert.assertTrue(Assert.java:27)
          at org.apache.derbyTesting.functionTests.tests.store.InterruptResilienceTest$WorkerThread.run(InterruptResilienceTest.java:435)
          ........
          Time: 175.745

          Show
          Dag H. Wanvik added a comment - I instrumented this and retrieved the following stack trace which shows where Derby detected the interrupt, but failed to preserve the flag. Notice that on the stack we have the frame: GenericLanguageConnectionContext.initialize(GenericLanguageConnectionContext.java:401) The variable interruptedException is set to null just after that call, which is clearly wrong: the null initialization happens too late since, in this case, the connection has seen an interrupt in the line above, i.e. "setDefaultSchema(initDefaultSchemaDescriptor());". Hence, we lose the information that Derby has seen an interrupt and temporarily proceeded with the flag cleared (so that NIO can complete ok). On return from the connect call, the flag is thus never set back on again. ..java.lang.Exception: Stack trace at java.lang.Thread.dumpStack(Thread.java:1342) at org.apache.derby.iapi.util.InterruptStatus.setInterrupted(InterruptStatus.java:83) at org.apache.derby.impl.store.raw.data.BasePage.setExclusive(BasePage.java:1689) at org.apache.derby.impl.store.raw.data.BaseContainer.latchPage(BaseContainer.java:527) at org.apache.derby.impl.store.raw.data.FileContainer.latchPage(FileContainer.java:3530) at org.apache.derby.impl.store.raw.data.FileContainer.getUserPage(FileContainer.java:2549) at org.apache.derby.impl.store.raw.data.FileContainer.getPage(FileContainer.java:2591) at org.apache.derby.impl.store.raw.data.BaseContainerHandle.getPage(BaseContainerHandle.java:319) at org.apache.derby.impl.store.access.btree.ControlRow.get(ControlRow.java:833) at org.apache.derby.impl.store.access.btree.ControlRow.get(ControlRow.java:820) at org.apache.derby.impl.store.access.btree.BTreeScan.positionAtStartForForwardScan(BTreeScan.java:361) at org.apache.derby.impl.store.access.btree.BTreeForwardScan.positionAtStartPosition(BTreeForwardScan.java:70) at org.apache.derby.impl.store.access.btree.BTreeForwardScan.fetchRows(BTreeForwardScan.java:122) at org.apache.derby.impl.store.access.btree.BTreeScan.fetchNext(BTreeScan.java:1599) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getDescriptorViaIndexMinion(DataDictionaryImpl.java:9288) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getDescriptorViaIndex(DataDictionaryImpl.java:9212) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.locateSchemaRow(DataDictionaryImpl.java:1722) at org.apache.derby.impl.sql.catalog.DataDictionaryImpl.getSchemaDescriptor(DataDictionaryImpl.java:1589) at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.initDefaultSchemaDescriptor(GenericLanguageConnectionContext.java:426) at org.apache.derby.impl.sql.conn.GenericLanguageConnectionContext.initialize(GenericLanguageConnectionContext.java:401) at org.apache.derby.impl.db.BasicDatabase.setupConnection(BasicDatabase.java:295) at org.apache.derby.impl.jdbc.TransactionResourceImpl.startTransaction(TransactionResourceImpl.java:189) at org.apache.derby.impl.jdbc.EmbedConnection.<init>(EmbedConnection.java:441) at org.apache.derby.impl.jdbc.EmbedConnection30.<init>(EmbedConnection30.java:73) at org.apache.derby.impl.jdbc.EmbedConnection40.<init>(EmbedConnection40.java:51) at org.apache.derby.jdbc.Driver40.getNewEmbedConnection(Driver40.java:70) at org.apache.derby.jdbc.InternalDriver.connect(InternalDriver.java:248) at org.apache.derby.jdbc.AutoloadedDriver.connect(AutoloadedDriver.java:146) at java.sql.DriverManager.getConnection(DriverManager.java:579) at java.sql.DriverManager.getConnection(DriverManager.java:190) at org.apache.derbyTesting.junit.DriverManagerConnector.openConnection(DriverManagerConnector.java:81) at org.apache.derbyTesting.junit.DriverManagerConnector.openConnection(DriverManagerConnector.java:43) at org.apache.derbyTesting.junit.TestConfiguration.openDefaultConnection(TestConfiguration.java:1574) at org.apache.derbyTesting.functionTests.tests.store.InterruptResilienceTest$WorkerThread.run(InterruptResilienceTest.java:432) Exception in thread "WorkerThread. Thread#4" junit.framework.AssertionFailedError at junit.framework.Assert.fail(Assert.java:47) at junit.framework.Assert.assertTrue(Assert.java:20) at junit.framework.Assert.assertTrue(Assert.java:27) at org.apache.derbyTesting.functionTests.tests.store.InterruptResilienceTest$WorkerThread.run(InterruptResilienceTest.java:435) ........ Time: 175.745
          Hide
          Dag H. Wanvik added a comment -

          Attaching patch derby-5223. This fix moves the initialization of the variable "interruptedException" earlier in GenerciLanguageConnectionContext#initialize and also changes the asserts in the minion threads in InterruptResilienceTest into explicit exception "throw"s instead, so any future errors in these invariants do not get overlooked

          Running regressions.

          Show
          Dag H. Wanvik added a comment - Attaching patch derby-5223. This fix moves the initialization of the variable "interruptedException" earlier in GenerciLanguageConnectionContext#initialize and also changes the asserts in the minion threads in InterruptResilienceTest into explicit exception "throw"s instead, so any future errors in these invariants do not get overlooked Running regressions.
          Dag H. Wanvik made changes -
          Attachment derby-5223.diff [ 12478651 ]
          Attachment derby-5223.stat [ 12478652 ]
          Dag H. Wanvik made changes -
          Issue & fix info [Patch Available]
          Hide
          Knut Anders Hatlen added a comment -

          That's a good catch! The fix looks fine to me. Resetting the flag in resetFromPool() sounds like a good precaution, but just to verify that I haven't misunderstood: If the flag is non-null when resetFromPool() is called, the (physical) connection has been interrupted and closed, so it's not likely that it's possible to reuse it? In any case, resetting it sounds like the right thing to do.

          As to the changes in InterruptResilienceTest, would it be better to make WorkerThread preserve all Throwables? It sounds useful to be allowed to use asserts there, and I could easily imagine that someone later adds an assert call there without realizing that it won't be detected. Just to prove my point: There's still an assertEquals() call left in WorkerThread after the patch...

          Show
          Knut Anders Hatlen added a comment - That's a good catch! The fix looks fine to me. Resetting the flag in resetFromPool() sounds like a good precaution, but just to verify that I haven't misunderstood: If the flag is non-null when resetFromPool() is called, the (physical) connection has been interrupted and closed, so it's not likely that it's possible to reuse it? In any case, resetting it sounds like the right thing to do. As to the changes in InterruptResilienceTest, would it be better to make WorkerThread preserve all Throwables? It sounds useful to be allowed to use asserts there, and I could easily imagine that someone later adds an assert call there without realizing that it won't be detected. Just to prove my point: There's still an assertEquals() call left in WorkerThread after the patch...
          Hide
          Dag H. Wanvik added a comment -

          Thanks for looking at this, Knut. Yes, you are right, I just added it to resetFromPool as a precaution, I'll add a comment to prevent wrong conclusions being drawn, though.

          Thanks for catching that remaining assert in the thread. Catching and passing back to the main thread any Throwable (which would include the JUnit exception from an assert) may be a better approach, though. I'll try that out.

          Show
          Dag H. Wanvik added a comment - Thanks for looking at this, Knut. Yes, you are right, I just added it to resetFromPool as a precaution, I'll add a comment to prevent wrong conclusions being drawn, though. Thanks for catching that remaining assert in the thread. Catching and passing back to the main thread any Throwable (which would include the JUnit exception from an assert) may be a better approach, though. I'll try that out.
          Hide
          Dag H. Wanvik added a comment -

          Uploading verssion "b" of this patch, which implements the catching of Throwable (not just Exception) inside the worker thread's run method, idea as suggested by Knut. This lets us keep/revert to the JUnit asserts inside threads. This makes the code more readable. Regressions ran ok with this change.

          Show
          Dag H. Wanvik added a comment - Uploading verssion "b" of this patch, which implements the catching of Throwable (not just Exception) inside the worker thread's run method, idea as suggested by Knut. This lets us keep/revert to the JUnit asserts inside threads. This makes the code more readable. Regressions ran ok with this change.
          Dag H. Wanvik made changes -
          Attachment derby-5223b.diff [ 12478839 ]
          Attachment derby-5223b.stat [ 12478840 ]
          Hide
          Dag H. Wanvik added a comment -

          Committed patch version "b" to trunk as svn 1102826.

          Show
          Dag H. Wanvik added a comment - Committed patch version "b" to trunk as svn 1102826.
          Dag H. Wanvik made changes -
          Fix Version/s 10.8.1.3 [ 12316378 ]
          Fix Version/s 10.9.0.0 [ 12316344 ]
          Issue & fix info [Patch Available]
          Hide
          Dag H. Wanvik added a comment -

          Backported to 10.8 branch as svn 1102836, closing.

          Show
          Dag H. Wanvik added a comment - Backported to 10.8 branch as svn 1102836, closing.
          Rick Hillegas made changes -
          Fix Version/s 10.8.1.4 [ 12316500 ]
          Fix Version/s 10.8.1.3 [ 12316378 ]
          Knut Anders Hatlen made changes -
          Fix Version/s 10.8.1.5 [ 12316676 ]
          Fix Version/s 10.8.1.4 [ 12316500 ]
          Dag H. Wanvik made changes -
          Assignee Dag H. Wanvik [ dagw ]
          Dag H. Wanvik made changes -
          Link This issue is part of DERBY-4741 [ DERBY-4741 ]
          Dag H. Wanvik made changes -
          Status Open [ 1 ] Resolved [ 5 ]
          Resolution Fixed [ 1 ]
          Dag H. Wanvik made changes -
          Status Resolved [ 5 ] Closed [ 6 ]
          Myrna van Lunteren made changes -
          Fix Version/s 10.8.2.0 [ 12317955 ]
          Fix Version/s 10.8.1.6 [ 12316676 ]
          Myrna van Lunteren made changes -
          Fix Version/s 10.8.2.2 [ 12317968 ]
          Fix Version/s 10.8.2.0 [ 12317955 ]
          Gavin made changes -
          Workflow jira [ 12612910 ] Default workflow, editable Closed status [ 12801075 ]

            People

            • Assignee:
              Dag H. Wanvik
              Reporter:
              Dag H. Wanvik
            • Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development