Derby
  1. Derby
  2. DERBY-3823

NullPointerException in stress.multi test

    Details

    • Urgency:
      Normal
    • Bug behavior facts:
      Regression Test Failure

      Description

      I saw the following NPE in stress.multi running on 10.3 with derbyclient.
      java.lang.NullPointerException
      at org.apache.derby.impl.jdbc.EmbedPreparedStatement.getMetaData(Unknown
      Source)
      at org.apache.derby.impl.drda.DRDAConnThread.writeSQLDARD(Unknown Source
      )
      at org.apache.derby.impl.drda.DRDAConnThread.processCommands(Unknown Sou
      rce)
      at org.apache.derby.impl.drda.DRDAConnThread.run(Unknown Source)
      Cleanup action completed

      1. derby.log
        5 kB
        Knut Anders Hatlen
      2. d3823-1.diff
        4 kB
        Dag H. Wanvik

        Issue Links

          Activity

          Hide
          Kathey Marsden added a comment -

          Saw this again on trunk with IBM 1.5 on 1/4/2009 (722718)

          Show
          Kathey Marsden added a comment - Saw this again on trunk with IBM 1.5 on 1/4/2009 (722718)
          Hide
          Knut Anders Hatlen added a comment -

          The same stack trace (with line numbers) is mentioned in DERBY-1635.

          Show
          Knut Anders Hatlen added a comment - The same stack trace (with line numbers) is mentioned in DERBY-1635 .
          Hide
          Kristian Waagan added a comment -

          Triaged July 3, 2009: Assigned normal urgency.

          Show
          Kristian Waagan added a comment - Triaged July 3, 2009: Assigned normal urgency.
          Hide
          Kristian Waagan added a comment -

          Changed title to reflect that the issue has been seen on other JVMs than IBM.

          The error appeared in a tinderbox test run [1] on JVM Sun Microsystems Inc. 1.6.0_18 with the same stack trace as earlier, in the JUnit stress multi test.

          [1] http://dbtg.foundry.sun.com/derby/test/tinderbox_trunk16/jvm1.6/testing/Limited/testSummary-956615.html

          Show
          Kristian Waagan added a comment - Changed title to reflect that the issue has been seen on other JVMs than IBM. The error appeared in a tinderbox test run [1] on JVM Sun Microsystems Inc. 1.6.0_18 with the same stack trace as earlier, in the JUnit stress multi test. [1] http://dbtg.foundry.sun.com/derby/test/tinderbox_trunk16/jvm1.6/testing/Limited/testSummary-956615.html
          Hide
          Knut Anders Hatlen added a comment -

          Seen again in the tinderbox: http://dbtg.foundry.sun.com/derby/test/tinderbox_trunk16/jvm1.6/testing/testlog/SunOS-5.10_i86pc-i386/1176669-org.apache.derbyTesting.functionTests.suites.All_diff.txt

          The stack trace in the test output is different because it's the client-side trace. The stack trace on the server is the same as the one in the original report (see also the attached derby.log):

          java.lang.NullPointerException
          at org.apache.derby.impl.jdbc.EmbedPreparedStatement.getMetaData(Unknown Source)
          at org.apache.derby.impl.drda.DRDAConnThread.writeSQLDARD(Unknown Source)
          at org.apache.derby.impl.drda.DRDAConnThread.processCommands(Unknown Source)
          at org.apache.derby.impl.drda.DRDAConnThread.run(Unknown Source)

          Show
          Knut Anders Hatlen added a comment - Seen again in the tinderbox: http://dbtg.foundry.sun.com/derby/test/tinderbox_trunk16/jvm1.6/testing/testlog/SunOS-5.10_i86pc-i386/1176669-org.apache.derbyTesting.functionTests.suites.All_diff.txt The stack trace in the test output is different because it's the client-side trace. The stack trace on the server is the same as the one in the original report (see also the attached derby.log): java.lang.NullPointerException at org.apache.derby.impl.jdbc.EmbedPreparedStatement.getMetaData(Unknown Source) at org.apache.derby.impl.drda.DRDAConnThread.writeSQLDARD(Unknown Source) at org.apache.derby.impl.drda.DRDAConnThread.processCommands(Unknown Source) at org.apache.derby.impl.drda.DRDAConnThread.run(Unknown Source)
          Hide
          Dag H. Wanvik added a comment -

          The most likely way we could get NPE in this method is if the variable preparedStatement is null. That only happens if EmbedPreparedStatement was closed prior to calling getMetaData on it, I think.
          PreparedStatement#close calls EmbedPreparedStatement#closeActions which nulls out EmbedPreparedStatement#preparedStatement (line 244).
          That variable is first consulted in line 1081:

          //bug 4579 - if the statement is invalid, regenerate the metadata info
          if (preparedStatement.isValid() == false)

          { //need to revalidate the statement here, otherwise getResultDescription would //still have info from previous valid statement preparedStatement.rePrepare(lcc); rMetaData = null; }

          No idea yet how this can happen.

          Show
          Dag H. Wanvik added a comment - The most likely way we could get NPE in this method is if the variable preparedStatement is null. That only happens if EmbedPreparedStatement was closed prior to calling getMetaData on it, I think. PreparedStatement#close calls EmbedPreparedStatement#closeActions which nulls out EmbedPreparedStatement#preparedStatement (line 244). That variable is first consulted in line 1081: //bug 4579 - if the statement is invalid, regenerate the metadata info if (preparedStatement.isValid() == false) { //need to revalidate the statement here, otherwise getResultDescription would //still have info from previous valid statement preparedStatement.rePrepare(lcc); rMetaData = null; } No idea yet how this can happen.
          Hide
          Dag H. Wanvik added a comment -

          I have managed to reproduce this (the DERBY-5435 variant which is marked as a duplicate of this) four of times in three days. On the server side in all four cases I see the error printed from DRDA_Conn_Thread: "agentError("Why am I getting another SQLException?")" when an exception (NPE?) is thrown from the call to writeSQLDARD (line 1026). Now, some instrumentation..

          Show
          Dag H. Wanvik added a comment - I have managed to reproduce this (the DERBY-5435 variant which is marked as a duplicate of this) four of times in three days. On the server side in all four cases I see the error printed from DRDA_Conn_Thread: "agentError("Why am I getting another SQLException?")" when an exception (NPE?) is thrown from the call to writeSQLDARD (line 1026). Now, some instrumentation..
          Hide
          Dag H. Wanvik added a comment -

          Here is the NPE with line numbers:

          java.lang.NullPointerException
          at org.apache.derby.impl.jdbc.EmbedPreparedStatement.getMetaData(EmbedPreparedStatement.java:1095)
          at org.apache.derby.impl.drda.DRDAConnThread.writeSQLDARD(DRDAConnThread.java:6608)
          at org.apache.derby.impl.drda.DRDAConnThread.processCommands(DRDAConnThread.java:1018)
          at org.apache.derby.impl.drda.DRDAConnThread.run(DRDAConnThread.java:295)

          this is the line in question in getMetaData:

          if (gcDuringGetMetaData == null || gcDuringGetMetaData.equals(execp.getActivationClass().getName()) == false)
          {
          rMetaData = null;
          gcDuringGetMetaData = execp.getActivationClass().getName(); // <*******************

          execp is just a cast of preparedStatement which has been accessed earlier in the method, e.g. preparedStatement.isValid()
          so either it has changed under our feet, or it is its activationClass that's null...

          Show
          Dag H. Wanvik added a comment - Here is the NPE with line numbers: java.lang.NullPointerException at org.apache.derby.impl.jdbc.EmbedPreparedStatement.getMetaData(EmbedPreparedStatement.java:1095) at org.apache.derby.impl.drda.DRDAConnThread.writeSQLDARD(DRDAConnThread.java:6608) at org.apache.derby.impl.drda.DRDAConnThread.processCommands(DRDAConnThread.java:1018) at org.apache.derby.impl.drda.DRDAConnThread.run(DRDAConnThread.java:295) this is the line in question in getMetaData: if (gcDuringGetMetaData == null || gcDuringGetMetaData.equals(execp.getActivationClass().getName()) == false) { rMetaData = null; gcDuringGetMetaData = execp.getActivationClass().getName(); // <******************* execp is just a cast of preparedStatement which has been accessed earlier in the method, e.g. preparedStatement.isValid() so either it has changed under our feet, or it is its activationClass that's null...
          Hide
          Dag H. Wanvik added a comment -

          As for activation class, while preparing a statement, the activation class can be null for a while, cf. code in GenericStatement#prepMinion, ca line 207: and then set again line 502. If the above code tries to access the prepared statement's metadata while the statement is being recompiled (many threads, cached ps), getActivationClass could return null. I am not sure that's what's happening, though, since I can't see why the statement should become invalidated in the test (update of main/main2).

          Show
          Dag H. Wanvik added a comment - As for activation class, while preparing a statement, the activation class can be null for a while, cf. code in GenericStatement#prepMinion, ca line 207: and then set again line 502. If the above code tries to access the prepared statement's metadata while the statement is being recompiled (many threads, cached ps), getActivationClass could return null. I am not sure that's what's happening, though, since I can't see why the statement should become invalidated in the test (update of main/main2).
          Hide
          Dag H. Wanvik added a comment -

          I split that line in two and reran till I hit the error again. It was indeed the returned activation class that was null. So, I think we can conclude that this is not thread safe and is a bug in Derby.

          Show
          Dag H. Wanvik added a comment - I split that line in two and reran till I hit the error again. It was indeed the returned activation class that was null. So, I think we can conclude that this is not thread safe and is a bug in Derby.
          Hide
          Dag H. Wanvik added a comment -

          Uploading a trial patch to EmbedPreparedStatement#getMetaData which changes the logic to detect if a prepared statement has been/is the the process of being recompiled as we are trying to get the metadata. It should avoid the race condition in the existign code where it can happen that we try to get the ps's activation class while it is being recompiled (hence is null temporarily).

          Even if with the patch, we get a consistent picture of the ps's current activation class and result description (my hope), I am not sure I understand how this approach is always correct: We are trying to get metadata for a result set. If the prepared statement has been invalidated (i.e. recompiled), I wonder if the ResultDescription will still necessarily be correct for that result set? Perhaps it will, since if the some change were to occur to the table that would change the column information, presumably, such changes would block on the fact that the result set was still open . At least on embedded that seems reasonable assumption. On client/server I think we can possible close the result set as a result of prefetching rows, so I am not sure if this always holds. But maybe the retrieval of the metadata happens before the time the result set is closed.. Can anyone shed light on this?

          In any case, I will try to run the test for some time with the new patch and see what happens...

          Show
          Dag H. Wanvik added a comment - Uploading a trial patch to EmbedPreparedStatement#getMetaData which changes the logic to detect if a prepared statement has been/is the the process of being recompiled as we are trying to get the metadata. It should avoid the race condition in the existign code where it can happen that we try to get the ps's activation class while it is being recompiled (hence is null temporarily). Even if with the patch, we get a consistent picture of the ps's current activation class and result description (my hope), I am not sure I understand how this approach is always correct: We are trying to get metadata for a result set. If the prepared statement has been invalidated (i.e. recompiled), I wonder if the ResultDescription will still necessarily be correct for that result set? Perhaps it will, since if the some change were to occur to the table that would change the column information, presumably, such changes would block on the fact that the result set was still open . At least on embedded that seems reasonable assumption. On client/server I think we can possible close the result set as a result of prefetching rows, so I am not sure if this always holds. But maybe the retrieval of the metadata happens before the time the result set is closed.. Can anyone shed light on this? In any case, I will try to run the test for some time with the new patch and see what happens...
          Hide
          Dag H. Wanvik added a comment -

          For what it's worth, I haven't seen the error again after I applied the patch, i.e. during the last 30-40 hours running time since yesterday (2 machines) - I'll leave it running for some time before concluding, though.

          Show
          Dag H. Wanvik added a comment - For what it's worth, I haven't seen the error again after I applied the patch, i.e. during the last 30-40 hours running time since yesterday (2 machines) - I'll leave it running for some time before concluding, though.
          Hide
          Dag H. Wanvik added a comment -

          Another night, no recurrences of the bug. In light of the frequency with which I used to see it, this makes me believe the patch does fix this particular race condition (and hence the test instability). I'll run ordinary regressions before I consider committing it. Please review.

          Show
          Dag H. Wanvik added a comment - Another night, no recurrences of the bug. In light of the frequency with which I used to see it, this makes me believe the patch does fix this particular race condition (and hence the test instability). I'll run ordinary regressions before I consider committing it. Please review.
          Hide
          Mamta A. Satoor added a comment -

          Hi Dag, Thanks for working on this jira. I spent some time on it and your patch. I want to first recap my understanding of the issue and then share my thoughts on result set descriptor. Please let me know if my understanding of the jira or your concern about result set descriptor is incorrect

          The problem seems to be that while getting the metadata by calling EmbedPreparedStatement.getMetaData(),we can run into NPE because activation class assoicated with the prepared statement might be NULL. Activation class is temporarily set to null while the prepared statement is getting recompiled(GenericStatement.prepMinion) and it is possible that during that temporary NULL activation stage, metadata code is trying to use the activation class.

          The proposed fix is to synchronize part of the logic in EmbedPreparedStatement.getMetaData(). The code that will be synchronized will be in a loop which will repreare the invalid prepared statement and get it's activation class. If the activation class is null, then we will stay in the while loop until we can grab a non-null activation class for the prepared statement. When we get out of the synchronization code, we can rest assured that activation is not null. After that, we pretty much follow the existing logic(with some code rework but the logic stays the same) in EmbedPreparedStatement.getMetaData()

          The existing code in EmbedPreparedStatement.getMetaData() code is as follows
          if (preparedStatement.isValid() == false)

          { //need to revalidate the statement here, otherwise getResultDescription would //still have info from previous valid statement preparedStatement.rePrepare(lcc); rMetaData = null; }

          //bug 4579 - gcDuringGetMetaData will be null if this is the first time
          //getMetaData call is made.
          //Second check - if the statement was revalidated since last getMetaData call,
          //then gcDuringGetMetaData wouldn't match with current generated class name
          if (gcDuringGetMetaData == null || gcDuringGetMetaData.equals(execp.getActivationClass().getName()) == false)

          { rMetaData = null; gcDuringGetMetaData = execp.getActivationClass().getName(); }

          The code above can run into npe in "gcDuringGetMetaData = execp.getActivationClass().getName();" because getActivationClass() can be NULL.

          Part of the new suggested code is as follows
          + synchronized(execp) {
          + // DERBY-3823 Some other thread may be repreparing
          + do {
          + while (!execp.upToDate())

          { + execp.rePrepare(lcc); + }


          +
          + currAc = execp.getActivationClass();
          + resd = execp.getResultDescription();
          + } while (currAc == null);
          + }
          +
          + if (gcDuringGetMetaData == null)

          { + gcDuringGetMetaData = currAc.getName(); + rMetaData = null; + }

          else {
          + if (!gcDuringGetMetaData.equals(currAc.getName()))

          { + rMetaData = null; + gcDuringGetMetaData = currAc.getName(); + }


          + }
          +
          With the new code, we can be certain that currAC is not null once we are outside the synchronized code and hence we should not run into NPE later when we are accessing currAC

          Later on, EmbedPreparedStatement.getMetaData() gets the resultDescription(existing code to get the resultDescription is as follows ResultDescription resd = preparedStatement.getResultDescription() and new code from Dag is as follows (resd = execp.getResultDescription()

          The concern raised here by Dag is that the resultDescription may not match the newly reprepared statement's result description. I spent some time looking at the supporting code for getResultDescription and I think we might be ok with the result description being in sync with preapred statement. Following is what I found. Let me know if I might have missed something.

          getResultDescription() call from EmbedPreparedStatement.getMetaData() results into a call to GenericPreparedStatement.getResultDescription() which simply return local variable resultDesc. The resultDesc variable gets set by another method in the same class namely, GenericPreparedStatement.completeCompile.

          The completeCompile method has following comment
          // get the result description (null for non-cursor statements)
          // would we want to reuse an old resultDesc?
          // or do we need to always replace in case this was select *?
          resultDesc = qt.makeResultDescription();
          It appears from the comment in completeCompile above that we don't simply return the existing cached resultDesc(if it is not null). Instead, we actually reload the resultDesc everytime by calling qt.makeResultDescription(). Based on this, I think result description and prepared statement will not get out of sync.

          Show
          Mamta A. Satoor added a comment - Hi Dag, Thanks for working on this jira. I spent some time on it and your patch. I want to first recap my understanding of the issue and then share my thoughts on result set descriptor. Please let me know if my understanding of the jira or your concern about result set descriptor is incorrect The problem seems to be that while getting the metadata by calling EmbedPreparedStatement.getMetaData(),we can run into NPE because activation class assoicated with the prepared statement might be NULL. Activation class is temporarily set to null while the prepared statement is getting recompiled(GenericStatement.prepMinion) and it is possible that during that temporary NULL activation stage, metadata code is trying to use the activation class. The proposed fix is to synchronize part of the logic in EmbedPreparedStatement.getMetaData(). The code that will be synchronized will be in a loop which will repreare the invalid prepared statement and get it's activation class. If the activation class is null, then we will stay in the while loop until we can grab a non-null activation class for the prepared statement. When we get out of the synchronization code, we can rest assured that activation is not null. After that, we pretty much follow the existing logic(with some code rework but the logic stays the same) in EmbedPreparedStatement.getMetaData() The existing code in EmbedPreparedStatement.getMetaData() code is as follows if (preparedStatement.isValid() == false) { //need to revalidate the statement here, otherwise getResultDescription would //still have info from previous valid statement preparedStatement.rePrepare(lcc); rMetaData = null; } //bug 4579 - gcDuringGetMetaData will be null if this is the first time //getMetaData call is made. //Second check - if the statement was revalidated since last getMetaData call, //then gcDuringGetMetaData wouldn't match with current generated class name if (gcDuringGetMetaData == null || gcDuringGetMetaData.equals(execp.getActivationClass().getName()) == false) { rMetaData = null; gcDuringGetMetaData = execp.getActivationClass().getName(); } The code above can run into npe in "gcDuringGetMetaData = execp.getActivationClass().getName();" because getActivationClass() can be NULL. Part of the new suggested code is as follows + synchronized(execp) { + // DERBY-3823 Some other thread may be repreparing + do { + while (!execp.upToDate()) { + execp.rePrepare(lcc); + } + + currAc = execp.getActivationClass(); + resd = execp.getResultDescription(); + } while (currAc == null); + } + + if (gcDuringGetMetaData == null) { + gcDuringGetMetaData = currAc.getName(); + rMetaData = null; + } else { + if (!gcDuringGetMetaData.equals(currAc.getName())) { + rMetaData = null; + gcDuringGetMetaData = currAc.getName(); + } + } + With the new code, we can be certain that currAC is not null once we are outside the synchronized code and hence we should not run into NPE later when we are accessing currAC Later on, EmbedPreparedStatement.getMetaData() gets the resultDescription(existing code to get the resultDescription is as follows ResultDescription resd = preparedStatement.getResultDescription() and new code from Dag is as follows (resd = execp.getResultDescription() The concern raised here by Dag is that the resultDescription may not match the newly reprepared statement's result description. I spent some time looking at the supporting code for getResultDescription and I think we might be ok with the result description being in sync with preapred statement. Following is what I found. Let me know if I might have missed something. getResultDescription() call from EmbedPreparedStatement.getMetaData() results into a call to GenericPreparedStatement.getResultDescription() which simply return local variable resultDesc. The resultDesc variable gets set by another method in the same class namely, GenericPreparedStatement.completeCompile. The completeCompile method has following comment // get the result description (null for non-cursor statements) // would we want to reuse an old resultDesc? // or do we need to always replace in case this was select *? resultDesc = qt.makeResultDescription(); It appears from the comment in completeCompile above that we don't simply return the existing cached resultDesc(if it is not null). Instead, we actually reload the resultDesc everytime by calling qt.makeResultDescription(). Based on this, I think result description and prepared statement will not get out of sync.
          Hide
          Mamta A. Satoor added a comment -

          I am leaning more towards NOT backporting the changes to 10.8. I realize that in our regression tests, we have run into this intermittent NPE in stress test for quite a few releases now but we have not heard of this specific NPE from a user as of yet.

          The Derby code we are planning to change is traversed heavily and since the suggested code change would not have gone through enough testing, I am hesitant about having it in 10.8 release. In future, if we do come across users who run into this problem, it will be easy to track this jira down since the NPE stack trace is clear about where things are going wrong. At that point, we can consider backporting these changes as needed. Just my 2cents.

          Show
          Mamta A. Satoor added a comment - I am leaning more towards NOT backporting the changes to 10.8. I realize that in our regression tests, we have run into this intermittent NPE in stress test for quite a few releases now but we have not heard of this specific NPE from a user as of yet. The Derby code we are planning to change is traversed heavily and since the suggested code change would not have gone through enough testing, I am hesitant about having it in 10.8 release. In future, if we do come across users who run into this problem, it will be easy to track this jira down since the NPE stack trace is clear about where things are going wrong. At that point, we can consider backporting these changes as needed. Just my 2cents.
          Hide
          Dag H. Wanvik added a comment -

          Thanks, Mamta. I agree with you opinion concerning 10.8. Your understanding of my patch is sorrect. As for the correctness of the resultset description my concern was slightly different: I was wondering if the retrieved result set description actually still describes the result set (for which we are retrieving the metadata), if the ps has been invalidated and recompiled (presumably after the result set was generated).

          Show
          Dag H. Wanvik added a comment - Thanks, Mamta. I agree with you opinion concerning 10.8. Your understanding of my patch is sorrect. As for the correctness of the resultset description my concern was slightly different: I was wondering if the retrieved result set description actually still describes the result set (for which we are retrieving the metadata), if the ps has been invalidated and recompiled (presumably after the result set was generated).
          Hide
          Mamta A. Satoor added a comment -

          Dag, I wrote a program to see what happens to the resultset's metadata description when it gets changed underneath while a resultset is still open. (I ran this program with the current trunk codeline, ie without Dag;s suggested changes)

          As you suspected, embedded version throws an error because the resultset is still open but netwrok server goes ahead and allows the metadata change but this change does not get reflected in the resultset's metadata descriptor even after a fresh fetch of resultset's metadata descriptor after the metadata change.

          To run in the embedded mode, run the program with no parameters or with '1'. To run it in network server mode, have the network server running and then run the program with any value other than '1' for the parameter. eg
          embedded mode
          java DERBY3824StressTestNPE 1
          or
          java DERBY3824StressTestNPE
          For Network server mode
          java DERBY3824StressTestNPE 0

          The test results for embedded mode looks as follows
          *************
          Done loading data
          char column length is 5
          should get error for inserting too large of a data
          Error is A truncation error was encountered trying to shrink VARCHAR '12345678'to length 5.
          Exception in thread "main" java.sql.SQLException: Operation 'ALTER TABLE' cannot be performed on object 'T1' because there is an open ResultSet dependent on tha
          t object.
          *************

          The test results for network server mode looks as follows
          *************
          Done loading data
          char column length is 5
          should get error for inserting too large of a data
          Error is A truncation error was encountered trying to shrink VARCHAR '12345678'to length 5.
          char column length after alter table is 5
          was able to insert large data
          *************

          Following is the program.
          import java.sql.*;

          public class DERBY3824StressTestNPE extends Thread {
          public static void main(String[] args) throws Exception {

          Connection conn = null;
          if (args.length == 1) {
          int embedded = Integer.parseInt(args[0]);
          if (embedded == 1)

          { Class.forName("org.apache.derby.jdbc.EmbeddedDriver"); conn = DriverManager.getConnection( "jdbc:derby:DERBY4437DB;create=true"); }

          else

          { Class.forName("org.apache.derby.jdbc.ClientDriver"); String url = "jdbc:derby://localhost:1527/DERBY4437DB;create=true"; conn = DriverManager.getConnection(url); }

          } else

          { Class.forName("org.apache.derby.jdbc.EmbeddedDriver"); conn = DriverManager.getConnection( "jdbc:derby:DERBY4437DB;create=true"); }

          conn.setAutoCommit(false);
          Statement st = conn.createStatement();
          st.executeUpdate("create table t1(c11 int, "+
          "c12 varchar(5))");
          PreparedStatement ps =
          conn.prepareStatement("insert into t1 values(?,'aaaaa')");
          for (int i = 0; i < 1000; i++)

          { ps.setInt(1, i); ps.executeUpdate(); }

          System.out.println("Done loading data");
          conn.commit();

          ResultSet rs = st.executeQuery("select * from t1");
          for (int i = 0; i < 100; i++)

          { rs.next(); }

          ResultSetMetaData rsmd = rs.getMetaData();
          int charLength = rsmd.getColumnDisplaySize(2);
          System.out.println("char column length is " + charLength);
          Statement st2 = conn.createStatement();
          try

          { st2.executeUpdate("insert into t1 values(99,'12345678')"); }

          catch(Exception ex)

          { System.out.println("should get error for inserting too large of a data"); System.out.println("Error is " + ex.getMessage()); }

          st2.execute("alter table t1 alter column c12 set data type varchar(8)");
          rsmd = rs.getMetaData();
          charLength = rsmd.getColumnDisplaySize(2);
          System.out.println("char column length after alter table is " + charLength);
          st2.executeUpdate("insert into t1 values(99,'12345678')");
          System.out.println("was able to insert large data");
          }
          }

          Show
          Mamta A. Satoor added a comment - Dag, I wrote a program to see what happens to the resultset's metadata description when it gets changed underneath while a resultset is still open. (I ran this program with the current trunk codeline, ie without Dag;s suggested changes) As you suspected, embedded version throws an error because the resultset is still open but netwrok server goes ahead and allows the metadata change but this change does not get reflected in the resultset's metadata descriptor even after a fresh fetch of resultset's metadata descriptor after the metadata change. To run in the embedded mode, run the program with no parameters or with '1'. To run it in network server mode, have the network server running and then run the program with any value other than '1' for the parameter. eg embedded mode java DERBY3824StressTestNPE 1 or java DERBY3824StressTestNPE For Network server mode java DERBY3824StressTestNPE 0 The test results for embedded mode looks as follows ************* Done loading data char column length is 5 should get error for inserting too large of a data Error is A truncation error was encountered trying to shrink VARCHAR '12345678'to length 5. Exception in thread "main" java.sql.SQLException: Operation 'ALTER TABLE' cannot be performed on object 'T1' because there is an open ResultSet dependent on tha t object. ************* The test results for network server mode looks as follows ************* Done loading data char column length is 5 should get error for inserting too large of a data Error is A truncation error was encountered trying to shrink VARCHAR '12345678'to length 5. char column length after alter table is 5 was able to insert large data ************* Following is the program. import java.sql.*; public class DERBY3824StressTestNPE extends Thread { public static void main(String[] args) throws Exception { Connection conn = null; if (args.length == 1) { int embedded = Integer.parseInt(args [0] ); if (embedded == 1) { Class.forName("org.apache.derby.jdbc.EmbeddedDriver"); conn = DriverManager.getConnection( "jdbc:derby:DERBY4437DB;create=true"); } else { Class.forName("org.apache.derby.jdbc.ClientDriver"); String url = "jdbc:derby://localhost:1527/DERBY4437DB;create=true"; conn = DriverManager.getConnection(url); } } else { Class.forName("org.apache.derby.jdbc.EmbeddedDriver"); conn = DriverManager.getConnection( "jdbc:derby:DERBY4437DB;create=true"); } conn.setAutoCommit(false); Statement st = conn.createStatement(); st.executeUpdate("create table t1(c11 int, "+ "c12 varchar(5))"); PreparedStatement ps = conn.prepareStatement("insert into t1 values(?,'aaaaa')"); for (int i = 0; i < 1000; i++) { ps.setInt(1, i); ps.executeUpdate(); } System.out.println("Done loading data"); conn.commit(); ResultSet rs = st.executeQuery("select * from t1"); for (int i = 0; i < 100; i++) { rs.next(); } ResultSetMetaData rsmd = rs.getMetaData(); int charLength = rsmd.getColumnDisplaySize(2); System.out.println("char column length is " + charLength); Statement st2 = conn.createStatement(); try { st2.executeUpdate("insert into t1 values(99,'12345678')"); } catch(Exception ex) { System.out.println("should get error for inserting too large of a data"); System.out.println("Error is " + ex.getMessage()); } st2.execute("alter table t1 alter column c12 set data type varchar(8)"); rsmd = rs.getMetaData(); charLength = rsmd.getColumnDisplaySize(2); System.out.println("char column length after alter table is " + charLength); st2.executeUpdate("insert into t1 values(99,'12345678')"); System.out.println("was able to insert large data"); } }
          Hide
          Mamta A. Satoor added a comment - - edited

          I applied Dag's changes to trunk and saw the same behavior from my test program, ie embedded gave an error for metadata change while the resultset is still open but network server allowed the metadata change but didn't reflect those changes in resultset's metadada descriptor.

          Show
          Mamta A. Satoor added a comment - - edited I applied Dag's changes to trunk and saw the same behavior from my test program, ie embedded gave an error for metadata change while the resultset is still open but network server allowed the metadata change but didn't reflect those changes in resultset's metadada descriptor.
          Hide
          Mamta A. Satoor added a comment -

          I am thinking if we should create a new jira for resultset meta data getting out of sync with the underlying system metadata in case of network server.

          We already have 2 jiras, DERBY-3839(Convert "org.apache.derbyTesting.functionTests.tests.store.holdCursorJDBC30.sql" to junit. ) and DERBY-4373 (different results with network server vs. embedded on select from a temporary table with resultset cursor hold over commit) in which we see difference in behavior between client-server and embedded mode with how resultsets are handled because of server pre-fetching of the rows. I think in our specific case, we do want the resultset metadata to correctly reflect the metadata assoicated with underlying columns. Dag, do you think we should create a new jira for this mismatch of metadata and associate the new jira with the other 2 jiras related to resulset behavior?

          Show
          Mamta A. Satoor added a comment - I am thinking if we should create a new jira for resultset meta data getting out of sync with the underlying system metadata in case of network server. We already have 2 jiras, DERBY-3839 (Convert "org.apache.derbyTesting.functionTests.tests.store.holdCursorJDBC30.sql" to junit. ) and DERBY-4373 (different results with network server vs. embedded on select from a temporary table with resultset cursor hold over commit) in which we see difference in behavior between client-server and embedded mode with how resultsets are handled because of server pre-fetching of the rows. I think in our specific case, we do want the resultset metadata to correctly reflect the metadata assoicated with underlying columns. Dag, do you think we should create a new jira for this mismatch of metadata and associate the new jira with the other 2 jiras related to resulset behavior?
          Hide
          Dag H. Wanvik added a comment -

          Thanks for helping me understand this, Mamta! From you test program it appears that the metadata returned even in the client case is still correct (i.e. c12's size is still 5) . Since that's the result set we are processing (still), I think that is correct even though the underlying table now has length 8. I was worried we might somehow be able to retrieve the new values, 8, while still reading the "old" style result set on the client. Isn't metadata cached on the client also? If so the second call to "rsmd = rs.getMetaData();" may not even visit the server, unless you trace it to determine that it did.. I will try to tweak your program and debug to see if I can provoke it to return "8" while we are still reading the result set that has 5 as max lenght for c12... If that were possible it would be an error, I think. That fact that we are able to insert longer data than 5 is not wrong, since the underlying database has changed. I believe database metadata would correctly reflect that? But the result set metadata should stick to the actual data in the (old) result set I believe.

          Show
          Dag H. Wanvik added a comment - Thanks for helping me understand this, Mamta! From you test program it appears that the metadata returned even in the client case is still correct (i.e. c12's size is still 5) . Since that's the result set we are processing (still), I think that is correct even though the underlying table now has length 8. I was worried we might somehow be able to retrieve the new values, 8, while still reading the "old" style result set on the client. Isn't metadata cached on the client also? If so the second call to "rsmd = rs.getMetaData();" may not even visit the server, unless you trace it to determine that it did.. I will try to tweak your program and debug to see if I can provoke it to return "8" while we are still reading the result set that has 5 as max lenght for c12... If that were possible it would be an error, I think. That fact that we are able to insert longer data than 5 is not wrong, since the underlying database has changed. I believe database metadata would correctly reflect that? But the result set metadata should stick to the actual data in the (old) result set I believe.
          Hide
          Dag H. Wanvik added a comment -

          Fiddling with your program I think the actual result set's getMetaData
          is is correct (ResultSet#getMetaData) in the case I was worried about,
          it appears it is read early on while processing the rs. (Sorry, I was
          a bit mixed up here).

          But your concern is also correct I changed the program to use an
          explicit prepared statement (since the method for which we made the
          patch is PreparedStatement#getMetaData) to retrieve metadata from
          there, as well as getting the metadata from the actual result set.

          The PreparedStatement's getMetaData method is described in this way in
          the Javadoc:

          "getMetaData() Retrieves a ResultSetMetaData object
          that contains information about the columns of the ResultSet
          object that will be returned when this PreparedStatement object
          is executed." ("will be": my emphasis, not "just was"..

          here is my run result (incl some trace from EmbedPreparedStatement#getMetaData)

          Client/server:

          $ java -cp .:$CLASSPATH DERBY3823StressTestNPE 2
          execp.getResultDescription: insert into t1 values(?,'aaaaa')
          execp.getResultDescription: insert into t1 values(?,'aaaaa')
          Done loading data
          execp.getResultDescription: select * from t1
          execp.getResultDescription: select * from t1
          executing alter
          2. PS#getMetaData: char column length is 5
          Reexecuting ps on changed table...
          3. RS#getMetadata: char column length is 5
          data:1 12345678

          As we can see we are getting a value 8 long, but both ps's metadata
          and rs's metadata are both out of date. Note that there is no new call
          to execp.getResultDescription after we alter the table...

          On embedded it is correct:

          $ java -cp .:$CLASSPATH DERBY3823StressTestNPE
          Done loading data
          executing alter
          execp.getResultDescription: select * from t1
          2. PS#getMetaData: char column length is 8
          Reexecuting ps on changed table...
          3. RS#getMetadata: char column length is 8
          data:1 12345678

          As you observed, it should return 8. Maybe because it's cached on the
          client side, but should have been invalidated. This looks like a bug
          to me.

          In any case, I think the patch improves the situation in that we now
          will wait if the underlying prepared statement is being re-prepared. I
          think we should file a new bug for this and relate it to the two you
          mentioned. I can do it if you like. The current patch as least assures we get a consistent
          "snapshot" at the time metadata is attempted retrieved.

          ---------------------------------------------------
          import java.sql.*;

          public class DERBY3823StressTestNPE extends Thread {
          public static void main(String[] args) throws Exception {

          Connection conn = null;
          if (args.length == 1) {
          int embedded = Integer.parseInt(args[0]);
          if (embedded == 1)

          { Class.forName("org.apache.derby.jdbc.EmbeddedDriver"); conn = DriverManager.getConnection( "jdbc:derby:DERBY3823DB;create=true"); }

          else

          { Class.forName("org.apache.derby.jdbc.ClientDriver"); String url = "jdbc:derby://localhost:1527/DERBY3823DB;create=true"; conn = DriverManager.getConnection(url); }

          } else

          { Class.forName("org.apache.derby.jdbc.EmbeddedDriver"); conn = DriverManager.getConnection( "jdbc:derby:DERBY3823DB;create=true"); }

          conn.setAutoCommit(false);
          Statement st = conn.createStatement();
          st.executeUpdate("create table t1(c11 int, "+
          "c12 varchar(5))");
          {
          PreparedStatement ps =
          conn.prepareStatement("insert into t1 values(?,'aaaaa')");
          for (int i = 0; i < 1000; i++)

          { ps.setInt(1, i); ps.executeUpdate(); }

          }
          System.out.println("Done loading data");
          conn.commit();

          PreparedStatement ps = conn.prepareStatement("select * from t1");
          ResultSet rs = ps.executeQuery();

          for (int i = 0; i < 990; i++)

          { rs.next(); }

          rs.close();

          Statement st2 = conn.createStatement();
          System.err.println("executing " + "alter");
          st2.execute("alter table t1 alter column c12 set data type varchar(8)");
          st2.execute("delete from t1");
          st2.execute("insert into t1 values (1, '12345678')");

          {

          // Ps' javadoc: getMetaData() Retrieves a ResultSetMetaData object
          // that contains information about the columns of the ResultSet
          // object that will be returned when this PreparedStatement object
          // is executed. (my emphasis)

          ResultSetMetaData rsmd = ps.getMetaData();
          int charLength = rsmd.getColumnDisplaySize(2);
          System.out.println("2. PS#getMetaData: char column length is " + charLength);
          System.out.println("Reexecuting ps on changed table...");
          rs = ps.executeQuery();
          ResultSetMetaData rsmd2 = rs.getMetaData();
          charLength = rsmd2.getColumnDisplaySize(2);
          System.out.println("3. RS#getMetadata: char column length is " + charLength);
          while (rs.next())

          { System.out.println("data:" + rs.getString(1) + " " + rs.getString(2)); }

          rs.close();
          }
          }
          }

          Show
          Dag H. Wanvik added a comment - Fiddling with your program I think the actual result set's getMetaData is is correct (ResultSet#getMetaData) in the case I was worried about, it appears it is read early on while processing the rs. (Sorry, I was a bit mixed up here). But your concern is also correct I changed the program to use an explicit prepared statement (since the method for which we made the patch is PreparedStatement#getMetaData) to retrieve metadata from there, as well as getting the metadata from the actual result set. The PreparedStatement's getMetaData method is described in this way in the Javadoc: "getMetaData() Retrieves a ResultSetMetaData object that contains information about the columns of the ResultSet object that will be returned when this PreparedStatement object is executed." ("will be": my emphasis, not "just was".. here is my run result (incl some trace from EmbedPreparedStatement#getMetaData) Client/server: $ java -cp .:$CLASSPATH DERBY3823StressTestNPE 2 execp.getResultDescription: insert into t1 values(?,'aaaaa') execp.getResultDescription: insert into t1 values(?,'aaaaa') Done loading data execp.getResultDescription: select * from t1 execp.getResultDescription: select * from t1 executing alter 2. PS#getMetaData: char column length is 5 Reexecuting ps on changed table... 3. RS#getMetadata: char column length is 5 data:1 12345678 As we can see we are getting a value 8 long, but both ps's metadata and rs's metadata are both out of date. Note that there is no new call to execp.getResultDescription after we alter the table... On embedded it is correct: $ java -cp .:$CLASSPATH DERBY3823StressTestNPE Done loading data executing alter execp.getResultDescription: select * from t1 2. PS#getMetaData: char column length is 8 Reexecuting ps on changed table... 3. RS#getMetadata: char column length is 8 data:1 12345678 As you observed, it should return 8. Maybe because it's cached on the client side, but should have been invalidated. This looks like a bug to me. In any case, I think the patch improves the situation in that we now will wait if the underlying prepared statement is being re-prepared. I think we should file a new bug for this and relate it to the two you mentioned. I can do it if you like. The current patch as least assures we get a consistent "snapshot" at the time metadata is attempted retrieved. --------------------------------------------------- import java.sql.*; public class DERBY3823StressTestNPE extends Thread { public static void main(String[] args) throws Exception { Connection conn = null; if (args.length == 1) { int embedded = Integer.parseInt(args [0] ); if (embedded == 1) { Class.forName("org.apache.derby.jdbc.EmbeddedDriver"); conn = DriverManager.getConnection( "jdbc:derby:DERBY3823DB;create=true"); } else { Class.forName("org.apache.derby.jdbc.ClientDriver"); String url = "jdbc:derby://localhost:1527/DERBY3823DB;create=true"; conn = DriverManager.getConnection(url); } } else { Class.forName("org.apache.derby.jdbc.EmbeddedDriver"); conn = DriverManager.getConnection( "jdbc:derby:DERBY3823DB;create=true"); } conn.setAutoCommit(false); Statement st = conn.createStatement(); st.executeUpdate("create table t1(c11 int, "+ "c12 varchar(5))"); { PreparedStatement ps = conn.prepareStatement("insert into t1 values(?,'aaaaa')"); for (int i = 0; i < 1000; i++) { ps.setInt(1, i); ps.executeUpdate(); } } System.out.println("Done loading data"); conn.commit(); PreparedStatement ps = conn.prepareStatement("select * from t1"); ResultSet rs = ps.executeQuery(); for (int i = 0; i < 990; i++) { rs.next(); } rs.close(); Statement st2 = conn.createStatement(); System.err.println("executing " + "alter"); st2.execute("alter table t1 alter column c12 set data type varchar(8)"); st2.execute("delete from t1"); st2.execute("insert into t1 values (1, '12345678')"); { // Ps' javadoc: getMetaData() Retrieves a ResultSetMetaData object // that contains information about the columns of the ResultSet // object that will be returned when this PreparedStatement object // is executed. (my emphasis) ResultSetMetaData rsmd = ps.getMetaData(); int charLength = rsmd.getColumnDisplaySize(2); System.out.println("2. PS#getMetaData: char column length is " + charLength); System.out.println("Reexecuting ps on changed table..."); rs = ps.executeQuery(); ResultSetMetaData rsmd2 = rs.getMetaData(); charLength = rsmd2.getColumnDisplaySize(2); System.out.println("3. RS#getMetadata: char column length is " + charLength); while (rs.next()) { System.out.println("data:" + rs.getString(1) + " " + rs.getString(2)); } rs.close(); } } }
          Hide
          Dag H. Wanvik added a comment -

          Btw, regressions ran ok with the patch.

          Show
          Dag H. Wanvik added a comment - Btw, regressions ran ok with the patch.
          Hide
          Dag H. Wanvik added a comment -

          Mamta, I filed DERBY-5459 for the out-of-date metadata issue on client. If you are otherwise OK with the patch, I'll commit it soon.

          Show
          Dag H. Wanvik added a comment - Mamta, I filed DERBY-5459 for the out-of-date metadata issue on client. If you are otherwise OK with the patch, I'll commit it soon.
          Hide
          Mamta A. Satoor added a comment -

          Earlier today, I added(in trunk) a test case to AlterTableTest showing that in case of a network server, an open resulset's metadata can get changed underneath it but it is not reflected in the metadata.

          Show
          Mamta A. Satoor added a comment - Earlier today, I added(in trunk) a test case to AlterTableTest showing that in case of a network server, an open resulset's metadata can get changed underneath it but it is not reflected in the metadata.
          Hide
          Mamta A. Satoor added a comment -

          Dag, I think we should go ahead and commit your patch into trunk. The metadata stuff can be handled under DERBY-5459.Thanks for filing that jira

          Show
          Mamta A. Satoor added a comment - Dag, I think we should go ahead and commit your patch into trunk. The metadata stuff can be handled under DERBY-5459 .Thanks for filing that jira
          Hide
          Dag H. Wanvik added a comment -

          Committed patch as svn 1183192, resolving. As we have discussed, it would probably not be wise to back-port at this point.

          Show
          Dag H. Wanvik added a comment - Committed patch as svn 1183192, resolving. As we have discussed, it would probably not be wise to back-port at this point.
          Hide
          Dag H. Wanvik added a comment -

          Marking "affects version" back to the first seen by Kathey: 10.3.3.1, but it's probably even older.

          Show
          Dag H. Wanvik added a comment - Marking "affects version" back to the first seen by Kathey: 10.3.3.1, but it's probably even older.
          Hide
          Mike Matrigali added a comment -

          I am wondering if the consensus is still that we should not backport this fix to 10.8? It has run successfully for some time now in trunk. The fix looks localized to me. I understand that it does not fix everything, but seems to be better than no fix. What is the risk of the fix?

          For some reason we seem to be seeing the stressmulti error quite a lot in 10.8 nightly runs, tracked under
          DERBY-5435

          Show
          Mike Matrigali added a comment - I am wondering if the consensus is still that we should not backport this fix to 10.8? It has run successfully for some time now in trunk. The fix looks localized to me. I understand that it does not fix everything, but seems to be better than no fix. What is the risk of the fix? For some reason we seem to be seeing the stressmulti error quite a lot in 10.8 nightly runs, tracked under DERBY-5435
          Hide
          Dag H. Wanvik added a comment -

          I'm OK with it now I think. Mamta had concerns that this (new) code path isn't exercised often enough for us to trust it an update release yet.That is a valid concern of course. The related DERBY-5459 could also be backported I think.

          Show
          Dag H. Wanvik added a comment - I'm OK with it now I think. Mamta had concerns that this (new) code path isn't exercised often enough for us to trust it an update release yet.That is a valid concern of course. The related DERBY-5459 could also be backported I think.
          Hide
          Mamta A. Satoor added a comment -

          We have the fix for this jira in for a long time now so I feel comfortable backporting it to 10.8. My worry was that we were touching a highly traversed code but the fix approach sounds correct so it will be ok to backport this fix.

          Show
          Mamta A. Satoor added a comment - We have the fix for this jira in for a long time now so I feel comfortable backporting it to 10.8. My worry was that we were touching a highly traversed code but the fix approach sounds correct so it will be ok to backport this fix.
          Hide
          Mike Matrigali added a comment -

          i am temporarily assigning this to myself and plan on backporting it to 10.8.

          Show
          Mike Matrigali added a comment - i am temporarily assigning this to myself and plan on backporting it to 10.8.
          Hide
          Mike Matrigali added a comment -

          back ported fix from trunk to 10.8 and setting original owner back. Change can be backported farther if necessary.

          Show
          Mike Matrigali added a comment - back ported fix from trunk to 10.8 and setting original owner back. Change can be backported farther if necessary.
          Hide
          Kathey Marsden added a comment -

          Reopen for 10.5 backport consideration. If working on the backport for this issue. Temporarily assign yourself and add a comment that you are working on it. When finished, reresolve with the new fix versions or label backport_reject_10_x as appropriate.

          Show
          Kathey Marsden added a comment - Reopen for 10.5 backport consideration. If working on the backport for this issue. Temporarily assign yourself and add a comment that you are working on it. When finished, reresolve with the new fix versions or label backport_reject_10_x as appropriate.
          Hide
          Mike Matrigali added a comment -

          temp assign to mikem for backport.

          Show
          Mike Matrigali added a comment - temp assign to mikem for backport.
          Hide
          Mike Matrigali added a comment -

          backported to 10.5, 10.6 and 10.7. resetting to original owner. Don't plan on backporting to any other branches now.

          Show
          Mike Matrigali added a comment - backported to 10.5, 10.6 and 10.7. resetting to original owner. Don't plan on backporting to any other branches now.
          Hide
          Knut Anders Hatlen added a comment -

          [bulk update: close all resolved issues that haven't had any activity the last year]

          Show
          Knut Anders Hatlen added a comment - [bulk update: close all resolved issues that haven't had any activity the last year]

            People

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

              Dates

              • Created:
                Updated:
                Resolved:

                Development