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

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

Triaged July 3, 2009: Assigned normal urgency.

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

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)

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.

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..

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...

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).

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.

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...

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.

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.

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)

//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)

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())

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

else {
+ if (!gcDuringGetMetaData.equals(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.

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.

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).

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)

else

} else

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++)

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

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

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

catch(Exception ex)

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");
}
}

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.

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?

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.

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)

else

} else

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++)

}
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.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())

rs.close();
}
}
}

Btw, regressions ran ok with the patch.

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.

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.

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

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

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

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

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.

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.

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

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

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.

temp assign to mikem for backport.

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

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