#606 NPE in JtdsStatement.close() v1.2.5

[Anonymous]

When used in conjunction with Atomikos v.3.5.9 (and probably the newly released 3.6.0), you can cause a NPE when in Atomikos' AbstractConnectionProxy.forceCloseAllPendingStatements() method. Here's the stack trace:

WARN atomikos - Error closing pending statement:
java.lang.NullPointerException
at net.sourceforge.jtds.jdbc.JtdsStatement.close(JtdsStatement.java:868)
at net.sourceforge.jtds.jdbc.JtdsPreparedStatement.close(JtdsPreparedStatement.java:486)
at com.atomikos.jdbc.AbstractConnectionProxy.forceCloseAllPendingStatements(AbstractConnectionProxy.java:35)
at com.atomikos.jdbc.nonxa.AtomikosThreadLocalConnection.transactionTerminated(AtomikosThreadLocalConnection.java:367)
at com.atomikos.jdbc.nonxa.AtomikosNonXAParticipant.rollback(AtomikosNonXAParticipant.java:133)
at com.atomikos.icatch.imp.RollbackMessage.send(RollbackMessage.java:90)
at com.atomikos.icatch.imp.PropagationMessage.submit(PropagationMessage.java:86)
at com.atomikos.icatch.imp.Propagator$PropagatorThread.run(Propagator.java:62)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
at java.lang.Thread.run(Unknown Source)

A simple "if (null != connection)" check fixes the NPE, but not being real familiar with the JTDS code base, I don't know if there is an underlying issue being exposed here (either in JTDS or Atomikos). It may just be that Atomikos is doing something unusual.

[momo]

Thank you for reporting this issue. After taking a look I think this >MAY< be caused by Atomikos accessing the Statement object by multiple threads concurrently, which is not supported by jTDS. Since I don't know anything about Atomikos I also don't know if that really makes any sense.

If the problem can be safely reproduced, maybe you could provide a simple test case showing the error?

Cheers,
momo

[Anonymous]

The multiple thread issue explanation is plausible; I know that Atomikos maintains a list of statements associated with a connection so that it can make sure they're closed if a transaction times out (and in other situations, like the connection closing). I think there are situations where this can happen on another thread, but it's not the case all the time.

We have seen a couple other NPEs in the statement obj, caused by either a null connection or null tds var. I suspect the root cause is the same as this issue.

A test case is difficult because this only happens if a transaction times out while under load, in production, dealing with a partitioned table with 22M rows or so. This also coincided with an upgrade to ASE 15 from 12.5, so there are lots of variables in play here. I'll see if I can come up with something a little simpler.

[momo]

Assuming the problem being caused by multiple threads invoking Statement.close() concurrently, the error has been fixed in CVS.

[Carmelo Piccione]

I've seen this happen with several middleware applications, such as quickfixj and hibernate 3.4. Here is an example with hibernate of another thread actually causing the connection object to be nullified after the prepared statement acquires a lock on it but before it gets a chance to use the object:

java.lang.NullPointerException
367 at net.sourceforge.jtds.jdbc.JtdsPreparedStatement.executeQuery(JtdsPreparedStatement.java:775)
368 at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96)
369 at org.apache.commons.dbcp.DelegatingPreparedStatement.executeQuery(DelegatingPreparedStatement.java:96)
370 at org.hibernate.jdbc.AbstractBatcher.getResultSet(AbstractBatcher.java:208)
371 at org.hibernate.loader.Loader.getResultSet(Loader.java:1812)
372 at org.hibernate.loader.Loader.doQuery(Loader.java:697)
373 at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:259)
374 at org.hibernate.loader.Loader.doList(Loader.java:2232)
375 at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2129)
376 at org.hibernate.loader.Loader.list(Loader.java:2124)
377 at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:401)
378 at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:363)
379 at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:196)
380 at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1149)
381 at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102)
382 at org.hibernate.ejb.QueryImpl.getSingleResult(QueryImpl.java:88)

And here is an example of concurrent closes with quickfixj:

Mar 01, !08:21:20 WARN [!HouseKeeper] (!HouseKeeper.java:149) - !#0001 was active for 13399 milliseconds and has been removed automaticaly. The Thread responsible was named 'QFJ Timer', but the last SQL it performed is unknown because the trace property is not enabled.
Mar 01, !08:21:20 ERROR [QFJ Timer] (!SessionConnector.java:255) - Error during timer processing
java.lang.NullPointerException
at net.sourceforge.jtds.jdbc.JtdsStatement.close(!JtdsStatement.java:868)
at net.sourceforge.jtds.jdbc.!tdsPreparedStatement.close(!JtdsPreparedStatement.java:486)
at org.logicalcobwebs.proxool.AbstractProxyStatement.close(!AbstractProxyStatement.java:115)
at org.logicalcobwebs.proxool.ProxyStatement.invoke(!ProxyStatement.java:93)
at org.logicalcobwebs.proxool.ProxyStatement.intercept(!ProxyStatement.java:57)
at $java.sql.Statement$$EnhancerByCGLIB$$9cdbee37.close(<generated>)
at quickfix.!JdbcUtil.close(!JdbcUtil.java:143)
at quickfix.!JdbcStore.set(!JdbcStore.java:259)
at quickfix.!SessionState.set(!SessionState.java:299)
at quickfix.Session.sendRaw(!Session.java:1736)
at quickfix.Session.generateHeartbeat(!Session.java:1400)
at quickfix.Session.next(!Session.java:1392)
at quickfix.mina.!SessionConnector$SessionTimerTask.run(!SessionConnector.java:248)
at java.util.concurrent.Executors$RunnableAdapter.call(!Executors.java:441)
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(!FutureTask.java:317)
at java.util.concurrent.FutureTask.runAndReset(!FutureTask.java:150)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(!ScheduledThreadPoolExecutor.java:98)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(!ScheduledThreadPoolExecutor.java:181)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(!ScheduledThreadPoolExecutor.java:205)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:885)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
at java.lang.Thread.run(Thread.java:619) </generated>

Also, revision 1105 is only partially correct. It does not guard the use of the connection within the try block on line 852. Eg.

try {
                if (!connection.isClosed()) {
                    connection.releaseTds(tds);
                }
                // Check for server side errors
                tds.getMessages().checkErrors();
            } catch (SQLException ex) {
            ...
           } finally {}

should be

try {
                if (connection != null && !connection.isClosed()) {
                    connection.releaseTds(tds);
                }
                // Check for server side errors
                tds.getMessages().checkErrors();
            } catch (SQLException ex) {
            ...
           } finally {}

[momo]

Thank you for the hint. I have to admit the "fix" in revision 1105 was brainless, but even the solution you proposed isn't completely secure. I've chosen a more radical but 100% safe approach by catching all NPEs. After checking the code I'm quite sure all possible NPEs are caused by multiple threads closing the statement concurrently.

Nevertheless, the jTDS Connection implementation is still not thread-safe in general. You will keep getting the other NPEs caused by multi-threded access.

Cheers,
momo

[Carmelo Piccione]

Momo,

Thanks for the fast response concerning this. Assuming it is committed to the repository, can you point to the change set where you are catching all NPEs?

[momo]

The fix has been committed in revision 1108: http://jtds.svn.sourceforge.net/viewvc/jtds/branches/jTDS%201.2%20(stable)/src/main/net/sourceforge/jtds/jdbc/JtdsStatement.java?pathrev=1108&view=diff&r1=1108&r2=1107&diff_format=h

I recently switched from CVS to Subversion, maybe you have been looking in the CVS repository.

Cheers,
momo