Derby
  1. Derby
  2. DERBY-4312

SQLException XJ215 on insert with setCharacterStream() and autocommit off in mailjdbc test

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 10.4.2.0, 10.5.1.1, 10.5.2.0, 10.6.1.0
    • Fix Version/s: 10.4.2.1, 10.5.3.0, 10.6.1.0
    • Component/s: JDBC, Network Client
    • Labels:
      None
    • Environment:
      SuSE Linux IBM 1.6 SR4
    • Urgency:
      Urgent
    • Issue & fix info:
      High Value Fix, Patch Available, Release Note Needed, Repro attached
    • Bug behavior facts:
      Embedded/Client difference, Regression

      Description

      I am running the 10.5 maildbc test on Linux with network server and the 10.5.2.0 release candidate and an updated derbyTesting.jar to have just Lily's change to change the backup user: I see in the test output early and often, this error inserting data into the table:

      SQLState: XJ215
      Severity: 20000
      Message: You cannot invoke other java.sql.Clob/java.sql.Blob methods after calling the free() method or after
      Clob's transaction has been committed or rolled back.
      java.sql.SQLException: You cannot invoke other java.sql.Clob/java.sql.Blob methods after calling the free() m
      ter the Blob/Clob's transaction has been committed or rolled back.
      at org.apache.derby.client.am.SQLExceptionFactory40.getSQLException(Unknown Source)
      at org.apache.derby.client.am.SqlException.getSQLException(Unknown Source)
      at org.apache.derby.client.am.Lob.checkValidity(Unknown Source)
      at org.apache.derby.client.am.Clob.length(Unknown Source)
      at org.apache.derby.client.net.NetStatementRequest.computeProtocolTypesAndLengths(Unknown Source)
      at org.apache.derby.client.net.NetStatementRequest.buildSQLDTAcommandData(Unknown Source)
      at org.apache.derby.client.net.NetStatementRequest.writeExecute(Unknown Source)
      at org.apache.derby.client.net.NetPreparedStatement.writeExecute_(Unknown Source)
      at org.apache.derby.client.am.PreparedStatement.writeExecute(Unknown Source)
      at org.apache.derby.client.am.PreparedStatement.flowExecute(Unknown Source)
      at org.apache.derby.client.am.PreparedStatement.executeUpdateX(Unknown Source)
      at org.apache.derby.client.am.PreparedStatement.executeUpdate(Unknown Source)
      at org.apache.derbyTesting.system.mailjdbc.utils.DbTasks.insertMail(DbTasks.java:447)
      at org.apache.derbyTesting.system.mailjdbc.tasks.Refresh.insertMail(Refresh.java:99)
      at org.apache.derbyTesting.system.mailjdbc.tasks.Refresh.doWork(Refresh.java:75)
      at org.apache.derbyTesting.system.mailjdbc.tasks.Refresh.run(Refresh.java:51)
      Caused by: org.apache.derby.client.am.SqlException: You cannot invoke other java.sql.Clob/java.sql.Blob metho
      lling the free() method or after the Blob/Clob's transaction has been committed or rolled back.

      The interesting thing is that the test itself is not using any Clob methods it uses setCharacterStream and also autocommit is off.
      Below is a code excerpt and
      conn.setAutoCommit(false);
      PreparedStatement insertFirst = conn.prepareStatement(
      Statements.insertStr, Statement.RETURN_GENERATED_KEYS);
      String name = new String("ABCD");
      String l_name = new String("WXYZ");
      long s_insert = System.currentTimeMillis();
      for (int i = 0; i < num; i++) {
      String new_name = new String(increment(name, 60));
      String new_lname = new String(decrement(l_name, 60));
      insertFirst.setString(1, new_name);
      insertFirst.setString(2, new_lname);
      insertFirst.setTimestamp(3, new Timestamp(System
      .currentTimeMillis()));
      name = new_name;
      l_name = new_lname;
      try

      { // to create a stream of random length between 200 bytes and 3MB int clobLength = Rn.nextInt(3078000 - 200 + 1) + 200; streamReader = new LoopingAlphabetReader(clobLength, CharAlphabet.modernLatinLowercase()); insertFirst.setCharacterStream(4, streamReader, clobLength); }

      catch (Exception e)

      { MailJdbc.logAct.logMsg(LogFile.ERROR + thread_name + " : " + "File not found Exception : " + e.getMessage()); errorPrint(e); throw e; }

      int rand_num = Rn.nextInt(10 - 1);
      if (i == rand_num) {
      ResultSet rs = stmt
      .executeQuery("select count from REFRESH.INBOX where attach_id>0");
      while (rs.next())

      { id_count = rs.getInt(1); insertFirst.setInt(5, rs.getInt(1) + 1); }

      rs.close();
      conn.setTransactionIsolation(Connection.TRANSACTION_READ_COMMITTED);
      } else
      insertFirst.setInt(5, 0);
      insertFirst
      .setString(
      6,
      "This column is used only to by pass the space problem. If the problem still exists, then we are going to "
      + "have a serious issue here.*****************************************************************************************************");
      int result = insertFirst.executeUpdate();

      if I connect with ij I do see some rows in the INBOX, so some inserts do seem to be happening.

      Kristian pointed out that this looks similar to DERBY-4224 with setAsciiStream() but this looks far more serious as autocommit is off and there does not appear to be a commit, so there is no obvious workaround. I assume this is also a regression. We shouldn't be throwing this error if the user did not use any Clob methods. I will try to narrow down the reproduction and track down where the issue was introduced. Knut said DERBY-4224 goes all the way back to 10.3.1.4 with DERBY-208. I don't know if it is the same case with this one.

      1. releaseNote.html
        4 kB
        Rick Hillegas
      2. releaseNote.html
        5 kB
        Kathey Marsden
      3. derby-4312_diff.txt
        5 kB
        Kathey Marsden
      4. derby-4312_diff.txt
        2 kB
        Kathey Marsden
      5. create.sql
        1 kB
        Kathey Marsden
      6. ReproDerby4312.java
        2 kB
        Kathey Marsden

        Issue Links

          Activity

          Hide
          Kathey Marsden added a comment -

          This issue may be related to the implementation of DERBY-208 which introduced use of Clob/Blob objects with setCharacterStream.

          Show
          Kathey Marsden added a comment - This issue may be related to the implementation of DERBY-208 which introduced use of Clob/Blob objects with setCharacterStream.
          Hide
          Kathey Marsden added a comment -

          DERBY-4224 is a similar issue with setAsciiStream but in that case commit is required.

          Show
          Kathey Marsden added a comment - DERBY-4224 is a similar issue with setAsciiStream but in that case commit is required.
          Hide
          Myrna van Lunteren added a comment -

          I checked and I still had the 10.5.1.1 results files cluttering up my disk...And the error is in there too...I had apparently assumed it was expected.

          Judging from the platform testing wiki pages, the mailjdbc test was not run with network server for either 10.3* nor 10.4*.

          Show
          Myrna van Lunteren added a comment - I checked and I still had the 10.5.1.1 results files cluttering up my disk...And the error is in there too...I had apparently assumed it was expected. Judging from the platform testing wiki pages, the mailjdbc test was not run with network server for either 10.3* nor 10.4*.
          Hide
          Kathey Marsden added a comment -

          Attached is a reproduction for this issue outside of the maildbc test.
          To reproduce
          1) Start network server with java org.apache.derby.drda.NetworkServerControl start
          2) Create the table java org.apache.derby.tools.ij create.sql
          3) Run the program with
          java ReproDerby4312

          It appears there is a commit occurring with:
          conn.setTransactionIsolation(Connection.TRANSACTION_READ_COMMITTED);

          I had thought that setTransactionIsolation didn't commit if the isolation level remained the same, but I guess at least for network server it does.

          Show
          Kathey Marsden added a comment - Attached is a reproduction for this issue outside of the maildbc test. To reproduce 1) Start network server with java org.apache.derby.drda.NetworkServerControl start 2) Create the table java org.apache.derby.tools.ij create.sql 3) Run the program with java ReproDerby4312 It appears there is a commit occurring with: conn.setTransactionIsolation(Connection.TRANSACTION_READ_COMMITTED); I had thought that setTransactionIsolation didn't commit if the isolation level remained the same, but I guess at least for network server it does.
          Hide
          Kathey Marsden added a comment -

          The small test case passes with 10.4.1.3 and earlier and fails with 10.4.2.0 and later. Hopefully, since the offending change went in as part of a maintenance release it will be easier to deal with than the DERBY-208 side effect we suspected. I will track down the exact change that caused the problem.

          Show
          Kathey Marsden added a comment - The small test case passes with 10.4.1.3 and earlier and fails with 10.4.2.0 and later. Hopefully, since the offending change went in as part of a maintenance release it will be easier to deal with than the DERBY-208 side effect we suspected. I will track down the exact change that caused the problem.
          Hide
          Kathey Marsden added a comment -

          This issue was introduced with the fix for DERBY-3574 which throws an error when lobs are accessed after commit. Somehow we will need to detect when derby client is using its CLOB representation for setAsciiStream and setCharacterStream and keep them valid past the commit.

          I assume there is a similar issue for BLOB/getBinaryStream but have not verified this.

          Show
          Kathey Marsden added a comment - This issue was introduced with the fix for DERBY-3574 which throws an error when lobs are accessed after commit. Somehow we will need to detect when derby client is using its CLOB representation for setAsciiStream and setCharacterStream and keep them valid past the commit. I assume there is a similar issue for BLOB/getBinaryStream but have not verified this.
          Hide
          Kathey Marsden added a comment -

          Lob.java has:
          protected int dataType_ = 0; // data type(s) the LOB instance currently contains

          which can include:
          public static final int STRING = 2;
          public static final int ASCII_STREAM = 4;
          public static final int UNICODE_STREAM = 8;
          public static final int CHARACTER_STREAM = 16;
          public static final int BINARY_STREAM = 32;
          public static final int BINARY_STRING = 64;
          public static final int LOCATOR = 128;

          A quick change to only do the transaction check in Lob.checkValidity() if isLocator() is true seems to resolve the issue and jdbcapi.BlobClob4BlobTest passes so the intended DERBY-3574 check seems to still work since a test was added for that. I am not totally sure if this is too liberal though and would appreciate input. Meanwhile I will add a test and run the rest of regressions with this simple fix.

          Show
          Kathey Marsden added a comment - Lob.java has: protected int dataType_ = 0; // data type(s) the LOB instance currently contains which can include: public static final int STRING = 2; public static final int ASCII_STREAM = 4; public static final int UNICODE_STREAM = 8; public static final int CHARACTER_STREAM = 16; public static final int BINARY_STREAM = 32; public static final int BINARY_STRING = 64; public static final int LOCATOR = 128; A quick change to only do the transaction check in Lob.checkValidity() if isLocator() is true seems to resolve the issue and jdbcapi.BlobClob4BlobTest passes so the intended DERBY-3574 check seems to still work since a test was added for that. I am not totally sure if this is too liberal though and would appreciate input. Meanwhile I will add a test and run the rest of regressions with this simple fix.
          Hide
          Kathey Marsden added a comment -

          Attached is a patch for this issue, which also fixes DERBY-4224 for setAsciiStream and also setBinaryStream which I confirmed had the same issue. We now only throw the transaction related error if the Lob is a locator. I also added three commits to existing test cases after the three calls and confirmed that the three tests failed for network server without the code fix.

          I am running tests now.

          Show
          Kathey Marsden added a comment - Attached is a patch for this issue, which also fixes DERBY-4224 for setAsciiStream and also setBinaryStream which I confirmed had the same issue. We now only throw the transaction related error if the Lob is a locator. I also added three commits to existing test cases after the three calls and confirmed that the three tests failed for network server without the code fix. I am running tests now.
          Hide
          Kathey Marsden added a comment -

          There seems to be a problem with the patch. I am getting two instances of:
          1) testDerby500(org.apache.derbyTesting.functionTests.tests.store.StreamingColumnTest)junit.framework.ComparisonFailure:
          Unexpected SQL state. expected:<...J215> but was:<...N017>
          2) testDerby500_verifyVarcharStreams(org.apache.derbyTesting.functionTests.tests.store.StreamingColumnTest)junit.framewo
          rk.ComparisonFailure: Unexpected SQL state. expected:<...J215> but was:<...N017>

          with the nested exception of:
          Caused by: java.sql.SQLException: Network protocol error: end of stream prematurely reached, parameter #5. Remaining da
          ta has been padded with 0x0.
          at org.apache.derby.client.am.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:96)
          at org.apache.derby.client.am.SqlException.getSQLException(SqlException.java:358)
          at org.apache.derby.client.am.SqlException.getSQLException(SqlException.java:367)
          at org.apache.derby.client.am.PreparedStatement.executeUpdate(PreparedStatement.java:399)
          at org.apache.derbyTesting.functionTests.tests.store.StreamingColumnTest.testDerby500(StreamingColumnTest.java:1
          484)
          ... 53 more

          I'll take a look.

          Show
          Kathey Marsden added a comment - There seems to be a problem with the patch. I am getting two instances of: 1) testDerby500(org.apache.derbyTesting.functionTests.tests.store.StreamingColumnTest)junit.framework.ComparisonFailure: Unexpected SQL state. expected:<...J215> but was:<...N017> 2) testDerby500_verifyVarcharStreams(org.apache.derbyTesting.functionTests.tests.store.StreamingColumnTest)junit.framewo rk.ComparisonFailure: Unexpected SQL state. expected:<...J215> but was:<...N017> with the nested exception of: Caused by: java.sql.SQLException: Network protocol error: end of stream prematurely reached, parameter #5. Remaining da ta has been padded with 0x0. at org.apache.derby.client.am.SQLExceptionFactory40.getSQLException(SQLExceptionFactory40.java:96) at org.apache.derby.client.am.SqlException.getSQLException(SqlException.java:358) at org.apache.derby.client.am.SqlException.getSQLException(SqlException.java:367) at org.apache.derby.client.am.PreparedStatement.executeUpdate(PreparedStatement.java:399) at org.apache.derbyTesting.functionTests.tests.store.StreamingColumnTest.testDerby500(StreamingColumnTest.java:1 484) ... 53 more I'll take a look.
          Hide
          Kathey Marsden added a comment -

          The problem with the tests might be just exposing another issue. The test is preparing a statement and setting streams for the parameters. It executes, commits, and then tries to execute again using the same parameters. On the second execution the test has this:

          try

          { ps.setInt(1, 11); rowCount += ps.executeUpdate(); fail("Attempting to reuse stream should have thrown an exception!"); }

          catch (SQLException sqle) {
          if (usingDerbyNetClient())

          { assertSQLState("XJ215", sqle); println("Expected Exception: You cannot invoke other " + "java.sql.Clob/java.sql.Blob methods after calling the " + "free() method or after the Blob/Clob's transaction has" + " been committed or rolled back."); }

          else

          { assertSQLState("XJ001", sqle); println("EXPECTED EXCEPTION - streams cannot be re-used"); }

          The XJ215 was happening on the client, because of the commit in the test. That commit should not be preventing the statement execution (this bug). The client should be throwing an XJ001 like embedded but is getting the protocol error instead. I think I should be able to reproduce this without this patch if there is no commit. I'll try that next week and file another issue for the protocol error.

          Show
          Kathey Marsden added a comment - The problem with the tests might be just exposing another issue. The test is preparing a statement and setting streams for the parameters. It executes, commits, and then tries to execute again using the same parameters. On the second execution the test has this: try { ps.setInt(1, 11); rowCount += ps.executeUpdate(); fail("Attempting to reuse stream should have thrown an exception!"); } catch (SQLException sqle) { if (usingDerbyNetClient()) { assertSQLState("XJ215", sqle); println("Expected Exception: You cannot invoke other " + "java.sql.Clob/java.sql.Blob methods after calling the " + "free() method or after the Blob/Clob's transaction has" + " been committed or rolled back."); } else { assertSQLState("XJ001", sqle); println("EXPECTED EXCEPTION - streams cannot be re-used"); } The XJ215 was happening on the client, because of the commit in the test. That commit should not be preventing the statement execution (this bug). The client should be throwing an XJ001 like embedded but is getting the protocol error instead. I think I should be able to reproduce this without this patch if there is no commit. I'll try that next week and file another issue for the protocol error.
          Hide
          Kathey Marsden added a comment -

          All other tests passed. I would like input on whether I should go ahead and check this in and disable the failing tests until DERBY-4315 is fixed. The tests were checking for the wrong error code anyway but the new behavior would be worse than a wrong error code since it might potentially insert wrong data. Checking this fix in would 1) Solve this regression 2) revert to the pre-DERBY-3574 behavior for users attempting to reuse streams, so they would see DERBY-4315 even if they commit between statement executions.

          Thoughts?

          Show
          Kathey Marsden added a comment - All other tests passed. I would like input on whether I should go ahead and check this in and disable the failing tests until DERBY-4315 is fixed. The tests were checking for the wrong error code anyway but the new behavior would be worse than a wrong error code since it might potentially insert wrong data. Checking this fix in would 1) Solve this regression 2) revert to the pre- DERBY-3574 behavior for users attempting to reuse streams, so they would see DERBY-4315 even if they commit between statement executions. Thoughts?
          Hide
          Lily Wei added a comment -

          My 2 cents will be check in the fix. We have DERBY-4315. We should document this behavior and provide the workaround for users who try to do this so they can go forward. Do you think any existing product is doing reuse streams in client on insert?

          Show
          Lily Wei added a comment - My 2 cents will be check in the fix. We have DERBY-4315 . We should document this behavior and provide the workaround for users who try to do this so they can go forward. Do you think any existing product is doing reuse streams in client on insert?
          Hide
          Kathey Marsden added a comment -

          Thanks Lily. I tend to agree we should go ahead and check it in. I don't think any existing product is doing reuse of streams because it could never be done successfully. For 10.4.2.0 and 10.5.5.1 the potential for data corruption went away if they tried this after commit, but the error message became nonsensical. I think reusing streams is the type of user error that would be found in development where the better error message (even with the potential bad insert) would be easier to manage. Regarding documentation, I could add a releaseNote to this issue that explains the behavior change and points to DERBY-4315.

          Show
          Kathey Marsden added a comment - Thanks Lily. I tend to agree we should go ahead and check it in. I don't think any existing product is doing reuse of streams because it could never be done successfully. For 10.4.2.0 and 10.5.5.1 the potential for data corruption went away if they tried this after commit, but the error message became nonsensical. I think reusing streams is the type of user error that would be found in development where the better error message (even with the potential bad insert) would be easier to manage. Regarding documentation, I could add a releaseNote to this issue that explains the behavior change and points to DERBY-4315 .
          Hide
          Kathey Marsden added a comment -

          Here is an updated patch for this issue that changes StreamingColumnTest to look for the XN017 error when the stream is reused after commit instead of XJ215. suites.All and derbyall ran fine. I will test with the mailjdbc network server test and then commit to trunk, 10.5 and 10.4 Monday or Tuesday if there are no comments.

          Show
          Kathey Marsden added a comment - Here is an updated patch for this issue that changes StreamingColumnTest to look for the XN017 error when the stream is reused after commit instead of XJ215. suites.All and derbyall ran fine. I will test with the mailjdbc network server test and then commit to trunk, 10.5 and 10.4 Monday or Tuesday if there are no comments.
          Hide
          Kathey Marsden added a comment -

          Marking patch available and release note needed. The release note will say that now users who reuse streams after commit will get XN017 error instead of XJ215 and wrong data can be inserted until the DERBY-4315 fix is in place.

          Show
          Kathey Marsden added a comment - Marking patch available and release note needed. The release note will say that now users who reuse streams after commit will get XN017 error instead of XJ215 and wrong data can be inserted until the DERBY-4315 fix is in place.
          Hide
          Kathey Marsden added a comment -

          Adding release note warning about increased exposure to DERBY-4315.

          Show
          Kathey Marsden added a comment - Adding release note warning about increased exposure to DERBY-4315 .
          Hide
          Kathey Marsden added a comment -

          Submitted fix to trunk 10.5 and 10.4 and added release note.

          Show
          Kathey Marsden added a comment - Submitted fix to trunk 10.5 and 10.4 and added release note.
          Hide
          Dag H. Wanvik added a comment -

          This issue is marked as blocked by DERBY-4315 (open), but this issue is now closed. Should that link be changed now?

          Show
          Dag H. Wanvik added a comment - This issue is marked as blocked by DERBY-4315 (open), but this issue is now closed. Should that link be changed now?
          Hide
          Kathey Marsden added a comment -

          Change DERBY-4315 link to is related to since that issue might be exposed more often after this fix.

          Show
          Kathey Marsden added a comment - Change DERBY-4315 link to is related to since that issue might be exposed more often after this fix.
          Hide
          Rick Hillegas added a comment -

          Shortened the summary line in the release note in order to make the 10.6 release notes more readable.

          Show
          Rick Hillegas added a comment - Shortened the summary line in the release note in order to make the 10.6 release notes more readable.

            People

            • Assignee:
              Kathey Marsden
              Reporter:
              Kathey Marsden
            • Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development