Derby
  1. Derby
  2. DERBY-5243

assert failure in test testRAFReadWriteMultipleThreads: interrupted flag cleared

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 10.8.1.2
    • Fix Version/s: 10.8.2.2, 10.9.1.0
    • Component/s: SQL, Test
    • Labels:
      None
    • Environment:
      Linux, Sun JDK 1.4.2u25 and JDK 5. Not seen or JDK 6 or 7, or other OS than Linux
    • Issue & fix info:
      Patch Available
    • Bug behavior facts:
      Regression Test Failure

      Description

      This is another instance of an interrupted thread losing its interrupted flag after calling Derby, but I believe this is distinct from other we have seen.

      1) testRAFReadWriteMultipleThreads(org.apache.derbyTesting.functionTests.tests.store.InterruptResilienceTest)java.sql.SQLException: The exception 'junit.framework.AssertionFailedError: WorkerThread 0' was thrown while evaluating an expression.
      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.seeNextException(Unknown Source)
      at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(Unknown Source)
      at org.apache.derby.impl.jdbc.TransactionResourceImpl.handleException(Unknown Source)
      at org.apache.derby.impl.jdbc.EmbedConnection.handleException(Unknown Source)
      at org.apache.derby.impl.jdbc.ConnectionChild.handleException(Unknown Source)
      at org.apache.derby.impl.jdbc.EmbedStatement.executeStatement(Unknown Source)
      at org.apache.derby.impl.jdbc.EmbedStatement.execute(Unknown Source)
      at org.apache.derby.impl.jdbc.EmbedStatement.executeUpdate(Unknown Source)
      at org.apache.derbyTesting.functionTests.tests.store.InterruptResilienceTest.testRAFReadWriteMultipleThreads(InterruptResilienceTest.java:532)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      at org.apache.derbyTesting.junit.BaseTestCase.runBare(BaseTestCase.java:112)
      at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
      at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
      at junit.extensions.TestSetup.run(TestSetup.java:25)
      at org.apache.derbyTesting.junit.BaseTestSetup.run(BaseTestSetup.java:57)
      at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
      at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
      at junit.extensions.TestSetup.run(TestSetup.java:25)
      at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
      at junit.extensions.TestSetup$1.protect(TestSetup.java:21)
      at junit.extensions.TestSetup.run(TestSetup.java:25)
      Caused by: java.sql.SQLException: Java exception: 'WorkerThread 0: junit.framework.AssertionFailedError'.
      at org.apache.derby.impl.jdbc.SQLExceptionFactory.getSQLException(Unknown Source)
      at org.apache.derby.impl.jdbc.Util.newEmbedSQLException(Unknown Source)
      at org.apache.derby.impl.jdbc.Util.javaException(Unknown Source)
      at org.apache.derby.impl.jdbc.TransactionResourceImpl.wrapInSQLException(Unknown Source)
      ... 45 more
      Caused by: junit.framework.AssertionFailedError: WorkerThread 0
      at org.apache.derbyTesting.junit.BaseTestCase.fail(BaseTestCase.java:771)
      at org.apache.derbyTesting.functionTests.tests.store.InterruptResilienceTest.tstRAFReadWriteMultipleThreads(InterruptResilienceTest.java:323)
      at org.apache.derby.exe.ac070a00b0x0130x06edxad12x000062ebfce90.g0(Unknown Source)
      at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
      at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
      at org.apache.derby.impl.services.reflect.ReflectMethod.invoke(Unknown Source)
      at org.apache.derby.impl.sql.execute.CallStatementResultSet.open(Unknown Source)
      at org.apache.derby.impl.sql.GenericPreparedStatement.executeStmt(Unknown Source)
      at org.apache.derby.impl.sql.GenericPreparedStatement.execute(Unknown Source)
      ... 41 more
      Caused by: junit.framework.AssertionFailedError
      at org.apache.derbyTesting.functionTests.tests.store.InterruptResilienceTest$WorkerThread.run(InterruptResilienceTest.java:430)

      1. nanotime.log
        2 kB
        Dag H. Wanvik
      2. DERBY-5243-instrument.stat
        0.2 kB
        Dag H. Wanvik
      3. DERBY-5243-instrument.diff
        6 kB
        Dag H. Wanvik
      4. DERBY-5243-1.stat
        0.3 kB
        Dag H. Wanvik
      5. DERBY-5243-1.diff
        3 kB
        Dag H. Wanvik

        Activity

        Dag H. Wanvik created issue -
        Hide
        Dag H. Wanvik added a comment - - edited

        [Edited: first analysis was slightly wrong]:

        I did some tracing of this, and I suspect to be a bug in the JDK (1.4.2 and 5). In this case, after we have seen an interrupt exception (08000) due seeing the thread interrupted in BasicNoPutResultSetImpl#checkCancellationFlag, we want to reestablish the connection and reprepare the statement test, the flag should still be set after the exception was received.

        In the test code, the assert is made after we have performed those two operations (reopen, prepare) have been performed, but by adding more trace I can see it already cleared when we start handling the exception: It gets cleared while the thread is still inside EmbedConnection.movePosition's call to handleException.

        While it is processing that (writing to derby.log among other things), I can see in my trace that another thread gets interrupted and throws in the same way, which may or may not be relevant. When i next see a trace from the first thread, its flag has been cleared. None of the threads have been involved in NIO during this time inside handleException, although both could have received yet another interrupt. But that shouldn't clear the flag, surely. The Thread#isInterrupted method is a native method, which could explain why we see this only on Linux.

        Show
        Dag H. Wanvik added a comment - - edited [Edited: first analysis was slightly wrong] : I did some tracing of this, and I suspect to be a bug in the JDK (1.4.2 and 5). In this case, after we have seen an interrupt exception (08000) due seeing the thread interrupted in BasicNoPutResultSetImpl#checkCancellationFlag, we want to reestablish the connection and reprepare the statement test, the flag should still be set after the exception was received. In the test code, the assert is made after we have performed those two operations (reopen, prepare) have been performed, but by adding more trace I can see it already cleared when we start handling the exception: It gets cleared while the thread is still inside EmbedConnection.movePosition's call to handleException. While it is processing that (writing to derby.log among other things), I can see in my trace that another thread gets interrupted and throws in the same way, which may or may not be relevant. When i next see a trace from the first thread, its flag has been cleared. None of the threads have been involved in NIO during this time inside handleException, although both could have received yet another interrupt. But that shouldn't clear the flag, surely. The Thread#isInterrupted method is a native method, which could explain why we see this only on Linux.
        Hide
        Dag H. Wanvik added a comment -

        Btw, it is easily easily reproduced on the indicated plaftforms, ca 20% of runs of InterruptResilienceTest on my box (Ubuntu on VirtualBox).

        Show
        Dag H. Wanvik added a comment - Btw, it is easily easily reproduced on the indicated plaftforms, ca 20% of runs of InterruptResilienceTest on my box (Ubuntu on VirtualBox).
        Hide
        Dag H. Wanvik added a comment - - edited

        Using DERBY-5243-instrument, a typical trace looks like this:

        Thread | code location | isInterrupted()
        -----------------------------------------------------------------------------
        ..
        ThreadWorkerThread. Thread#5,5,main CM.cleanuponerror 0 : true
        ThreadWorkerThread. Thread#5,5,main CM.cleanuponerror 0.1 : true
        ThreadWorkerThread. Thread#5,5,main CM.cleanuponerror 0.2 : true
        ThreadWorkerThread. Thread#5,5,main CM.cleanuponerror 0.3 : true
        ThreadWorkerThread. Thread#4,5,main CM.cleanuponerror 0 : true
        ThreadWorkerThread. Thread#4,5,main CM.cleanuponerror 0.1 : true
        ThreadWorkerThread. Thread#4,5,main CM.cleanuponerror 0.2 : true
        ThreadWorkerThread. Thread#4,5,main CM.cleanuponerror 0.3 : true
        ThreadWorkerThread. Thread#6,5,main CM.cleanuponerror 0 : true
        ThreadWorkerThread. Thread#6,5,main CM.cleanuponerror 0.1 : true
        ThreadWorkerThread. Thread#6,5,main CM.cleanuponerror 0.2 : true
        ThreadWorkerThread. Thread#6,5,main CM.cleanuponerror 0.3 : true
        ThreadWorkerThread. Thread#4,5,main CM.cleanuponerror 1 : true
        ThreadWorkerThread. Thread#4,5,main stackTrace 0 : true
        ThreadWorkerThread. Thread#4,5,main stackTrace 1 : true
        ThreadWorkerThread. Thread#6,5,main CM.cleanuponerror 1 : true
        ThreadWorkerThread. Thread#6,5,main stackTrace 0 : true
        ThreadWorkerThread. Thread#6,5,main stackTrace 1 : true Still OK

        >>>>>>>>>
        ThreadWorkerThread. Thread#5,5,main CM.cleanuponerror 1 : true
        ThreadWorkerThread. Thread#5,5,main stackTrace 0 : true
        ThreadWorkerThread. Thread#5,5,main stackTrace 1 : true
        <<<<<<<<<

        ThreadWorkerThread. Thread#6,5,main stackTrace 2 : false Cleared!
        ThreadWorkerThread. Thread#6,5,main CM.cleanuponerror 2 : false
        ThreadWorkerThread. Thread#6,5,main exitting!
        ThreadWorkerThread. Thread#5,5,main stackTrace 2 : false
        ThreadWorkerThread. Thread#5,5,main CM.cleanuponerror 2 : false
        ThreadWorkerThread. Thread#5,5,main exitting!
        ThreadWorkerThread. Thread#4,5,main stackTrace 2 : true
        ThreadWorkerThread. Thread#4,5,main CM.cleanuponerror 2 : true

        We see that the flag is cleared when the code for thread 6 reaches
        tracepoint "stackTrace 2". The only thing the thread has done in the
        meantime is call Throwable.printStackTrace(PrintWriter). So the
        ther eis a possibility that the interrupt on thread 5 must have
        led to thread 6's flag being cleared.

        Show
        Dag H. Wanvik added a comment - - edited Using DERBY-5243 -instrument, a typical trace looks like this: Thread | code location | isInterrupted() ----------------------------------------------------------------------------- .. Thread WorkerThread. Thread#5,5,main CM.cleanuponerror 0 : true Thread WorkerThread. Thread#5,5,main CM.cleanuponerror 0.1 : true Thread WorkerThread. Thread#5,5,main CM.cleanuponerror 0.2 : true Thread WorkerThread. Thread#5,5,main CM.cleanuponerror 0.3 : true Thread WorkerThread. Thread#4,5,main CM.cleanuponerror 0 : true Thread WorkerThread. Thread#4,5,main CM.cleanuponerror 0.1 : true Thread WorkerThread. Thread#4,5,main CM.cleanuponerror 0.2 : true Thread WorkerThread. Thread#4,5,main CM.cleanuponerror 0.3 : true Thread WorkerThread. Thread#6,5,main CM.cleanuponerror 0 : true Thread WorkerThread. Thread#6,5,main CM.cleanuponerror 0.1 : true Thread WorkerThread. Thread#6,5,main CM.cleanuponerror 0.2 : true Thread WorkerThread. Thread#6,5,main CM.cleanuponerror 0.3 : true Thread WorkerThread. Thread#4,5,main CM.cleanuponerror 1 : true Thread WorkerThread. Thread#4,5,main stackTrace 0 : true Thread WorkerThread. Thread#4,5,main stackTrace 1 : true Thread WorkerThread. Thread#6,5,main CM.cleanuponerror 1 : true Thread WorkerThread. Thread#6,5,main stackTrace 0 : true Thread WorkerThread. Thread#6,5,main stackTrace 1 : true Still OK >>>>>>>>> Thread WorkerThread. Thread#5,5,main CM.cleanuponerror 1 : true Thread WorkerThread. Thread#5,5,main stackTrace 0 : true Thread WorkerThread. Thread#5,5,main stackTrace 1 : true <<<<<<<<< Thread WorkerThread. Thread#6,5,main stackTrace 2 : false Cleared! Thread WorkerThread. Thread#6,5,main CM.cleanuponerror 2 : false Thread WorkerThread. Thread#6,5,main exitting! Thread WorkerThread. Thread#5,5,main stackTrace 2 : false Thread WorkerThread. Thread#5,5,main CM.cleanuponerror 2 : false Thread WorkerThread. Thread#5,5,main exitting! Thread WorkerThread. Thread#4,5,main stackTrace 2 : true Thread WorkerThread. Thread#4,5,main CM.cleanuponerror 2 : true We see that the flag is cleared when the code for thread 6 reaches tracepoint "stackTrace 2". The only thing the thread has done in the meantime is call Throwable.printStackTrace(PrintWriter). So the ther eis a possibility that the interrupt on thread 5 must have led to thread 6's flag being cleared.
        Dag H. Wanvik made changes -
        Field Original Value New Value
        Attachment DERBY-5243-instrument.diff [ 12480171 ]
        Attachment DERBY-5243-instrument.stat [ 12480172 ]
        Hide
        Dag H. Wanvik added a comment -

        Just to make sure I am not fooled by the way the threads print their traces, I made another run labelling each line with System.nanoTime and sorted the resulting lines. It conformed the interleaving see above, cf. attachement nanoTime.log

        Show
        Dag H. Wanvik added a comment - Just to make sure I am not fooled by the way the threads print their traces, I made another run labelling each line with System.nanoTime and sorted the resulting lines. It conformed the interleaving see above, cf. attachement nanoTime.log
        Dag H. Wanvik made changes -
        Attachment nanotime.log [ 12480349 ]
        Hide
        Dag H. Wanvik added a comment -

        Uploading a patch which moves the setting of the interrupted flag to just before CONN_INTERRUPT exception is thrown as an SQLException back to the user application. Previously, we set the interrupted flag when we first threw the internal StandardException. The new placement means we are done with IO to derby.log which may be behind the problem we are seeing. I ran this 100 times on Linux/JDK 5 without seeing the error.

        Running regressions.

        Show
        Dag H. Wanvik added a comment - Uploading a patch which moves the setting of the interrupted flag to just before CONN_INTERRUPT exception is thrown as an SQLException back to the user application. Previously, we set the interrupted flag when we first threw the internal StandardException. The new placement means we are done with IO to derby.log which may be behind the problem we are seeing. I ran this 100 times on Linux/JDK 5 without seeing the error. Running regressions.
        Dag H. Wanvik made changes -
        Attachment DERBY-5243-1.diff [ 12480718 ]
        Attachment DERBY-5243-1.stat [ 12480719 ]
        Dag H. Wanvik made changes -
        Issue & fix info [Patch Available]
        Component/s SQL [ 11408 ]
        Dag H. Wanvik made changes -
        Assignee Dag H. Wanvik [ dagw ]
        Dag H. Wanvik made changes -
        Status Open [ 1 ] In Progress [ 3 ]
        Hide
        Dag H. Wanvik added a comment -

        Regressions ran ok.

        Show
        Dag H. Wanvik added a comment - Regressions ran ok.
        Hide
        Dag H. Wanvik added a comment -

        Committed as svn 1129797.

        Show
        Dag H. Wanvik added a comment - Committed as svn 1129797.
        Hide
        Knut Anders Hatlen added a comment -

        Is there more work planned on this issue, or could it be resolved?

        Show
        Knut Anders Hatlen added a comment - Is there more work planned on this issue, or could it be resolved?
        Dag H. Wanvik made changes -
        Status In Progress [ 3 ] Resolved [ 5 ]
        Fix Version/s 10.9.0.0 [ 12316344 ]
        Resolution Fixed [ 1 ]
        Hide
        Dag H. Wanvik added a comment -

        No, so I am resolving it.

        Show
        Dag H. Wanvik added a comment - No, so I am resolving it.
        Hide
        Dag H. Wanvik added a comment -

        The patch was backported to the 10.8 branch as svn 1129799.

        Show
        Dag H. Wanvik added a comment - The patch was backported to the 10.8 branch as svn 1129799.
        Dag H. Wanvik made changes -
        Fix Version/s 10.8.1.6 [ 12316676 ]
        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 ]
        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.
        Knut Anders Hatlen made changes -
        Status Resolved [ 5 ] Closed [ 6 ]
        Gavin made changes -
        Workflow jira [ 12614355 ] Default workflow, editable Closed status [ 12802318 ]
        Transition Time In Source Status Execution Times Last Executer Last Execution Date
        Open Open In Progress In Progress
        7d 10h 48m 1 Dag H. Wanvik 31/May/11 02:57
        In Progress In Progress Resolved Resolved
        35d 10h 20m 1 Dag H. Wanvik 05/Jul/11 13:18
        Resolved Resolved Closed Closed
        712d 21h 1m 1 Knut Anders Hatlen 17/Jun/13 10:19

          People

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

            Dates

            • Created:
              Updated:
              Resolved:

              Development