Derby
  1. Derby
  2. DERBY-5498

ClosedByInterruptException in AuthenticationTest

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 10.8.1.2, 10.8.2.2, 10.9.1.0
    • Fix Version/s: 10.9.1.0
    • Component/s: Store
    • Environment:
      Solaris 11, JDK 7u1
    • Bug behavior facts:
      Regression Test Failure

      Description

      AuthenticationTest failed with this error on trunk (intermittent error, passed when I reran suites.All):

      java.sql.SQLException: DERBY SQL error: SQLCODE: -1, SQLSTATE: XJ040, SQLERRMC: Failed to start database 'singleUse/oneuse2c' with class loader sun.misc.Launcher$AppClassLoader@1ff5ea7, see the next exception for details.::SQLSTATE: XJ001Java exception: 'ASSERT FAILED Unable to Acquire Exclusive Lock on /export/home/hudsond/.hudson/jobs/Derby-JUnit/workspace/test/system/singleUse/oneuse2c/dbex.lck: org.apache.derby.shared.common.sanity.AssertFailure'.::SQLSTATE: XJ001Java exception: ': java.nio.channels.ClosedByInterruptException'.
      at org.apache.derby.client.am.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:99)
      at org.apache.derby.client.am.SqlException.getSQLException(SqlException.java:364)
      at org.apache.derby.jdbc.ClientDriver.connect(ClientDriver.java:166)
      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.junit.BaseJDBCTestSetup.getConnection(BaseJDBCTestSetup.java:72)
      at org.apache.derbyTesting.junit.DatabasePropertyTestSetup.tearDown(DatabasePropertyTestSetup.java:280)
      at junit.extensions.TestSetup$1.protect(TestSetup.java:24)
      at junit.extensions.TestSetup.run(TestSetup.java:27)
      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:23)
      at junit.extensions.TestSetup.run(TestSetup.java:27)
      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:23)
      at junit.extensions.TestSetup.run(TestSetup.java:27)
      at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
      at junit.extensions.TestSetup$1.protect(TestSetup.java:23)
      at junit.extensions.TestSetup.run(TestSetup.java:27)
      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:23)
      at junit.extensions.TestSetup.run(TestSetup.java:27)
      at junit.extensions.TestDecorator.basicRun(TestDecorator.java:24)
      at junit.extensions.TestSetup$1.protect(TestSetup.java:23)
      at junit.extensions.TestSetup.run(TestSetup.java:27)
      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:23)
      at junit.extensions.TestSetup.run(TestSetup.java:27)
      Caused by: org.apache.derby.client.am.SqlException: DERBY SQL error: SQLCODE: -1, SQLSTATE: XJ040, SQLERRMC: Failed to start database 'singleUse/oneuse2c' with class loader sun.misc.Launcher$AppClassLoader@1ff5ea7, see the next exception for details.::SQLSTATE: XJ001Java exception: 'ASSERT FAILED Unable to Acquire Exclusive Lock on /export/home/hudsond/.hudson/jobs/Derby-JUnit/workspace/test/system/singleUse/oneuse2c/dbex.lck: org.apache.derby.shared.common.sanity.AssertFailure'.::SQLSTATE: XJ001Java exception: ': java.nio.channels.ClosedByInterruptException'.
      at org.apache.derby.client.am.Connection.completeSqlca(Connection.java:2125)
      at org.apache.derby.client.net.NetConnectionReply.parseRdbAccessFailed(NetConnectionReply.java:538)
      at org.apache.derby.client.net.NetConnectionReply.parseAccessRdbError(NetConnectionReply.java:431)
      at org.apache.derby.client.net.NetConnectionReply.parseACCRDBreply(NetConnectionReply.java:294)
      at org.apache.derby.client.net.NetConnectionReply.readAccessDatabase(NetConnectionReply.java:121)
      at org.apache.derby.client.net.NetConnection.readSecurityCheckAndAccessRdb(NetConnection.java:826)
      at org.apache.derby.client.net.NetConnection.flowSecurityCheckAndAccessRdb(NetConnection.java:762)
      at org.apache.derby.client.net.NetConnection.flowUSRIDPWDconnect(NetConnection.java:591)
      at org.apache.derby.client.net.NetConnection.flowConnect(NetConnection.java:406)
      at org.apache.derby.client.net.NetConnection.<init>(NetConnection.java:220)
      at org.apache.derby.client.net.NetConnection40.<init>(NetConnection40.java:74)
      at org.apache.derby.client.net.ClientJDBCObjectFactoryImpl40.newNetConnection(ClientJDBCObjectFactoryImpl40.java:269)
      at org.apache.derby.jdbc.ClientDriver.connect(ClientDriver.java:157)

      The server side log was not preserved because the failure happened inside a decorator.

      1. d5498a.diff
        12 kB
        Dag H. Wanvik
      2. d5498a.diff
        12 kB
        Dag H. Wanvik
      3. d5498a-debug.diff
        13 kB
        Dag H. Wanvik
      4. d5498a-debug.stat
        0.3 kB
        Dag H. Wanvik
      5. d5498b.diff
        12 kB
        Dag H. Wanvik
      6. d5498b.stat
        0.3 kB
        Dag H. Wanvik

        Activity

        Hide
        Kathey Marsden added a comment -

        Assigning back to Dag and marking backport reject. Merge is not automatic because of other DirFile4 changes so did not make an effort to merge manually. If really needed I think it could be merged manually, but won't do that now.

        Show
        Kathey Marsden added a comment - Assigning back to Dag and marking backport reject. Merge is not automatic because of other DirFile4 changes so did not make an effort to merge manually. If really needed I think it could be merged manually, but won't do that now.
        Hide
        Kathey Marsden added a comment -

        Assign to myself temporarily for backport.

        Show
        Kathey Marsden added a comment - Assign to myself temporarily for backport.
        Hide
        Knut Anders Hatlen added a comment -

        I saw this problem again today on the 10.8 branch, but this time in ResultSetMiscTest. Dag, from your last comment it sounded like you intended to backport the fix?

        Show
        Knut Anders Hatlen added a comment - I saw this problem again today on the 10.8 branch, but this time in ResultSetMiscTest. Dag, from your last comment it sounded like you intended to backport the fix?
        Hide
        Dag H. Wanvik added a comment -

        Committed patch b as svn 1200995, resolving. I'll backport this to the 10.8 branch, so please hold off closing for now.

        Show
        Dag H. Wanvik added a comment - Committed patch b as svn 1200995, resolving. I'll backport this to the 10.8 branch, so please hold off closing for now.
        Hide
        Dag H. Wanvik added a comment -

        Uploading version b addressing Knut's comments.

        Show
        Dag H. Wanvik added a comment - Uploading version b addressing Knut's comments.
        Hide
        Dag H. Wanvik added a comment -

        Thanks, Knut. All are good points, I'll re-spin the patch.

        Show
        Dag H. Wanvik added a comment - Thanks, Knut. All are good points, I'll re-spin the patch.
        Hide
        Knut Anders Hatlen added a comment -

        Perhaps the above mentioned code comment should also contain the JDK bug number. Then it will be easier to find all instances of this workaround when we decide that it's safe to remove it.

        Show
        Knut Anders Hatlen added a comment - Perhaps the above mentioned code comment should also contain the JDK bug number. Then it will be easier to find all instances of this workaround when we decide that it's safe to remove it.
        Hide
        Knut Anders Hatlen added a comment -

        Thanks, Dag. The patch looks good to me. Two questions:

        + } catch (ClosedChannelException e) {
        + // if (e instanceof ChannelInterruptedException) {
        + //
        + // JDK bug: use AsynchronousCloseException instead of
        + // the logically correct ChannelInterruptedException
        +
        + if (e instanceof AsynchronousCloseException)

        { + InterruptStatus.setInterrupted(); + }

        else

        { + throw e; // not expected + }

        Since we immediately re-throw all non-AsynchronousCloseExceptions, couldn't we change the catch block to catch AsynchronousCloseException only and unconditionally call InterruptStatus.setInterrupted()?

        The comment mentions ChannelInterruptedException. Did you mean ClosedByInterruptException?

        Show
        Knut Anders Hatlen added a comment - Thanks, Dag. The patch looks good to me. Two questions: + } catch (ClosedChannelException e) { + // if (e instanceof ChannelInterruptedException) { + // + // JDK bug: use AsynchronousCloseException instead of + // the logically correct ChannelInterruptedException + + if (e instanceof AsynchronousCloseException) { + InterruptStatus.setInterrupted(); + } else { + throw e; // not expected + } Since we immediately re-throw all non-AsynchronousCloseExceptions, couldn't we change the catch block to catch AsynchronousCloseException only and unconditionally call InterruptStatus.setInterrupted()? The comment mentions ChannelInterruptedException. Did you mean ClosedByInterruptException?
        Hide
        Dag H. Wanvik added a comment -

        Not sure where the interrupt comes from here. In any case, there is a small time-window inside DirFile4#getExclusiveFileLock where we use a NIO file channel and the code is not ready to handle interrupts.

        Enclosing a patch, d5498a, which plugs this hole by our usual approach when seeing interrupts: make a note, clear the thread's interrupt flag, and then retry the operation.

        The companion patch which I also upload contains additional instrumentation code to provoke an interrupt of the thread just before we attempt to get the exclusive lock as a test of the new logic. See code bewteen "test code being" and "test code end".

        Running regressions.

        Show
        Dag H. Wanvik added a comment - Not sure where the interrupt comes from here. In any case, there is a small time-window inside DirFile4#getExclusiveFileLock where we use a NIO file channel and the code is not ready to handle interrupts. Enclosing a patch, d5498a, which plugs this hole by our usual approach when seeing interrupts: make a note, clear the thread's interrupt flag, and then retry the operation. The companion patch which I also upload contains additional instrumentation code to provoke an interrupt of the thread just before we attempt to get the exclusive lock as a test of the new logic. See code bewteen "test code being" and "test code end". Running regressions.

          People

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

            Dates

            • Created:
              Updated:
              Resolved:

              Development