Issue Details (XML | Word | Printable)

Key: NUCRDBMS-615
Type: Bug Bug
Status: Closed Closed
Resolution: Cannot Reproduce
Priority: No Testcase No Testcase
Assignee: Unassigned
Reporter: Vito Impagliazzo
Votes: 0
Watchers: 0
Operations

If you were logged in you would be able to see more operations.
DataNucleus Store RDBMS

NPE in ForwardQueryResult.closingConnection(ForwardQueryResult.java:273)

Created: 24/Sep/12 11:48 AM   Updated: 26/Oct/12 05:15 PM   Resolved: 02/Oct/12 03:40 PM
Component/s: Connection
Affects Version/s: 3.1.1
Fix Version/s: None

File Attachments: 1. Zip Archive testcase.zip (4 kB)

Environment: linux ubuntu, mysql

Datastore: MySQL
Severity: Development


 Description  « Hide
Queries do randomly fail with NullPointerException at ForwardQueryResult.java:273. Debuggin code for revision 15483 (release 3.1.1) it turns out that the variable query is null, however query was not null a few lines before otherwise NPE would have been generated at line 256. Full stacktrace:

java.lang.NullPointerException
at org.datanucleus.store.rdbms.query.ForwardQueryResult.closingConnection(ForwardQueryResult.java:273)
at org.datanucleus.store.query.AbstractQueryResult.disconnect(AbstractQueryResult.java:108)
at org.datanucleus.store.rdbms.query.AbstractRDBMSQueryResult.disconnect(AbstractRDBMSQueryResult.java:69)
at org.datanucleus.store.rdbms.query.JDOQLQuery$2.managedConnectionPreClose(JDOQLQuery.java:705)
at org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl.close(ConnectionFactoryImpl.java:475)
at org.datanucleus.store.connection.AbstractManagedConnection.release(AbstractManagedConnection.java:75)
at org.datanucleus.store.rdbms.ConnectionFactoryImpl$ManagedConnectionImpl.release(ConnectionFactoryImpl.java:305)
at org.datanucleus.store.rdbms.query.JDOQLQuery.performExecute(JDOQLQuery.java:795)
at org.datanucleus.store.query.Query.executeQuery(Query.java:1789)
at org.datanucleus.store.query.Query.executeWithArray(Query.java:1666)
at org.datanucleus.store.query.Query.execute(Query.java:1639)
at org.datanucleus.api.jdo.JDOQuery.execute(JDOQuery.java:221)
...
...

libs:

datanucleus-core-3.1.1.jar
datanucleus-rdbms-3.1.1.jar


Sort Order: Ascending order - Click to sort in descending order
Andy Jefferson added a comment - 24/Sep/12 02:45 PM
Thanks for the report ... but if something "fails" then it will always fail based on some order of events (after all programming is logic). Consequently you can easily define how you use transactions, queries and how you close them. Which leads on to the testcase that we ask for

Vito Impagliazzo added a comment - 24/Sep/12 06:16 PM
Thanks for the answer. Yes you are right, by random I however meant that the same code does work sometime, and does not other times. When dealing with multiple threads it is a normality I would add. I have set a breakpoint with eclipse at ForwardQueryResult.java:273 and I can see variable 'query' being null, however a few lines before (line 256) 'query' has been used, so most likely another thread has set it to null in the mean while.
This is how my code looks like

Extent e = tx.first.getExtent(clazz, false);
String sq = "authId=='session:NK9qxWllZKije7qXBoWxYyuTYkvMtP'"; //an example
Query q = tx.first.newQuery(e, sq);
q.setRange(0, 100);
List res = new LinkedList();
res.addAll((List)q.execute());
q.closeAll();
q = null;

I have to add, I run the same query 4 times in a row on 4 different classes (somehow I can't make query on subclasses work well, so I manually query each individual subclass for now)

Thanks for your time

Vito Impagliazzo added a comment - 24/Sep/12 06:20 PM
For completeness, this is how I setup:

Map<String, String> props = new HashMap<String, String>();
props.put("javax.jdo.PersistenceManagerFactoryClass", "org.datanucleus.api.jdo.JDOPersistenceManagerFactory");
props.put("datanucleus.metadata.validate", "false");
// hsqldb driver works for both hsql and mysql
props.put("javax.jdo.option.ConnectionDriverName", "org.hsqldb.jdbcDriver");
props.put("javax.jdo.option.ConnectionURL", "jdbc:" +
cfg.engine.value() + ":" + cfg.url.value());
props.put("javax.jdo.option.ConnectionUserName", cfg.user.value());
props.put("javax.jdo.option.ConnectionPassword", cfg.pwd.value());
props.put("javax.jdo.option.Mapping", "hsql");
props.put("datanucleus.autoCreateSchema", "true");
props.put("datanucleus.validateTables", "false");
props.put("datanucleus.validateConstraints", "false");
pmf = JDOHelper.getPersistenceManagerFactory(props);

Andy Jefferson added a comment - 24/Sep/12 06:42 PM
But how can multiple threads come in there ? PM is not thread-safe and never has been. Consequently a query is not thread-safe either (and if accessing as multithreaded then you're asking for problems). A connection is related to a PM and hence to a thread, and is "released" when the txn is committed or pm is closed.

FWIW Test cases are defined by http://www.datanucleus.org/project/problem_jdo_testcase.html
as per the front page of JIRA, and I can't see how "query" can be null at that second point unless you provide a (valid) testcase

Vito Impagliazzo added a comment - 24/Sep/12 07:42 PM
Dear Andy
thanks again for your answer, sorry my fault I did not notice the link on jira front page, I looked straight at the register function after I got in jira from some google link...
I am now attaching a test case with very few classes, A, B, B1, B2. B is abstract, B1 and B2 are subclasses of B. I actually have problems running even the test case as the database gets locked and it does not go over the Main.store() method. After killing the java process, the pending mysql operation gets actually executed. (After killing a couple of times, it does not try to modify the table anymore and eventually goes on, but then other problems arise, so I won't mention them yet).

mysqladmin -uroot processlist
+-----+------+-----------------+----------+---------+------+---------------------------------+--------------------------------------------------------------------+
| Id | User | Host | db | Command | Time | State | Info |
+-----+------+-----------------+----------+---------+------+---------------------------------+--------------------------------------------------------------------+
| 9 | root | localhost | sc2_test | Sleep | 9 | | |
| 127 | sc | localhost:41041 | sc2_test | Query | 2 | Waiting for table metadata lock | ALTER TABLE `USERAUTH` ADD COLUMN `EMAIL` VARCHAR(255) BINARY NULL |
| 128 | sc | localhost:41042 | sc2_test | Sleep | 2 | | |
| 129 | root | localhost | | Query | 0 | | show processlist |
+-----+------+-----------------+----------+---------+------+---------------------------------+--------------------------------------------------------------------+

Tested against mysql 5.5.24 and 5.1.63 (in the latter mysqladmin says as status "copy to tmp table")

This is the stacktrace where the test case gets stuck for ever:

Thread [main] (Suspended)
owns: ReadAheadInputStream (id=38)
owns: JDBC4Connection (id=39)
owns: StatementImpl (id=40)
owns: StoreDataManager (id=41)
SocketInputStream.socketRead0(FileDescriptor, byte[], int, int, int) line: not available [native method]
SocketInputStream.read(byte[], int, int, int) line: 150
SocketInputStream.read(byte[], int, int) line: 121
ReadAheadInputStream.fill(int) line: 114
ReadAheadInputStream.readFromUnderlyingStreamIfNecessary(byte[], int, int) line: 161
ReadAheadInputStream.read(byte[], int, int) line: 189
MysqlIO.readFully(InputStream, byte[], int, int) line: 2537
MysqlIO.reuseAndReadPacket(Buffer, int) line: 2990
MysqlIO.reuseAndReadPacket(Buffer) line: 2979
MysqlIO.checkErrorPacket(int) line: 3520
MysqlIO.sendCommand(int, String, Buffer, boolean, String, int) line: 1990
MysqlIO.sqlQueryDirect(StatementImpl, String, String, Buffer, int, int, int, boolean, String, Field[]) line: 2151
JDBC4Connection(ConnectionImpl).execSQL(StatementImpl, String, int, Buffer, int, int, boolean, String, Field[], boolean) line: 2619
JDBC4Connection(ConnectionImpl).execSQL(StatementImpl, String, int, Buffer, int, int, boolean, String, Field[]) line: 2569
StatementImpl.execute(String, boolean) line: 813
StatementImpl.execute(String) line: 656
DelegatingStatement.execute(String) line: 264
DelegatingStatement.execute(String) line: 264
ClassTable(AbstractTable).executeDdlStatement(Statement, String) line: 761
ClassTable(AbstractTable).executeDdlStatementList(List, Connection) line: 712
ClassTable(TableImpl).validateColumns(Connection, boolean, boolean, Collection) line: 261
RDBMSStoreManager$ClassAdder.performTablesValidation(List<DatastoreContainerObject>, ClassLoaderResolver) line: 2612
RDBMSStoreManager$ClassAdder.addClassTablesAndValidate(String[], ClassLoaderResolver) line: 2411
RDBMSStoreManager$ClassAdder.run(ClassLoaderResolver) line: 2050
RDBMSStoreManager$ClassAdder(AbstractSchemaTransaction).execute(ClassLoaderResolver) line: 113
RDBMSStoreManager.addClasses(String[], ClassLoaderResolver) line: 823
RDBMSStoreManager(AbstractStoreManager).addClass(String, ClassLoaderResolver) line: 1157
RDBMSStoreManager(MappedStoreManager).getDatastoreClass(String, ClassLoaderResolver) line: 407
RDBMSPersistenceHandler.insertObject(ObjectProvider) line: 126
JDOStateManager.internalMakePersistent() line: 2377
JDOStateManager.makePersistent() line: 2353
ObjectManagerImpl.persistObjectInternal(Object, FieldValues, ObjectProvider, int, int) line: 1896
ObjectManagerImpl.persistObjectWork(Object) line: 1745
ObjectManagerImpl.persistObjects(Object[]) line: 1685
JDOPersistenceManager.makePersistentAll(Collection) line: 780
JDOPersistenceManager.makePersistentAll(Object...) line: 765
Main.store() line: 51
Main.main(String[]) line: 38

Testfile zip following

Andy Jefferson added a comment - 24/Sep/12 08:02 PM
.. which has got nothing at all to do with the alleged issue, and everything to do with you attempting to create schema at runtime when docs say run SchemaTool up-front (so it knows about ALL classes when generating schema). And when you run SchemaTool up front then run the test it demonstrates no such problem.

Andy Jefferson added a comment - 02/Oct/12 11:04 AM
Any update on providing a testcase that reproduces this?

Vito Impagliazzo added a comment - 02/Oct/12 11:18 AM
Still not able to reproduce it in a simple test case. Will maybe later on consider asking for professional help from your organisation if that proves faster. You might close the issue in my opinion, I will eventually come back only in case of further evidence. Thanks for your time.