NullpointerException while posting requests

[Ricardo Estafan]

Hello all,

i have a struts application in which i use hibernate together with a mysql database. Everything works great, BUT i keep getting the following exception in the tomcat 5.0.28 console :

  
Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0,5,main] - 
caught unexpected Exception while executing posted task
java.lang.NullPointerException
at com.mysql.jdbc.ServerPreparedStatement.realClose(ServerPreparedStatement.java:1092)
at com.mchange.v1.db.sql.StatementUtils.attemptClose(StatementUtils.java:711)
at com.mchange.v2.c3p0.stmt.GooGooStatementCache$1.run(GooGooStatementCache.java:38)
at com.mchange.v2.async.stmt.ThreadPoolAsynchronousRunner$PoolThread.run(ThreadPoolAsynchronousRunner.java:354)

Does anyone have an idea how to solve this issue?

Thanks a lot!!

[Mark Spritzler]

Is there a bigger stack trace? Maybe in your Tomcat log or console.

Maybe you have a required field that isn't being filled in that you get your NullPointer from.

Mark

[David Harkness]

It looks like the com.mchange package is the connection pool you're using, and the ThreadPoolAsynchronousRunner is its thread pool. One way to set up connection pools is to have connections really closed after they have been open for x number of minutes as a sort of preemptive house-keeping. Perhaps that's what this is doing, and it's having a problem closing one of the statements referenced by the connection.

Total guess, but if you supply more information (e.g. when does it happen? during a request, at the end, or at random times?), maybe we can provide better guesses. Another option would be to see if that package has a forum or support site.

[Ricardo Estafan]

Ok a ressume, it seems that it's not consistent, but here's what happens. Uppon starting the app, at first the following request is performed :

  
public Collection getGenres()
    {
        String sql = "from Genre order by ranking asc";
 
        Collection genres = find(sql);
 
        closeSession();
 
        return genres;
    }

This doesn't result in an exception.

After this the following request is performed :

  
public Collection getLastUpdatedProducts()
    {
        String sql = "from Product where ownRelease != 1 and amount != 0 order by instockdate asc";
 
        Collection products = find(sql);
 
        closeSession();
 
        Collection lastUpdatedProducts = new HashSet();
 
        if (products != null)
        {
            int count = 0;
 
            Iterator iter = products.iterator();
 
            while (iter.hasNext() && count < AntenneConstants.NUMBER_OF_UPDATED_PRODUCTS)
            {
                Product product = (Product) iter.next();
 
                lastUpdatedProducts.add(product);
 
                count++;
            }
        }
 
        return lastUpdatedProducts;
    }

I've checked the database as far as null values go. In one case i have a p[roduct where the ownRelease value is null, the amount is null and the instockdate is null. The first two are used in order to obtain the appropriate products. The latter is used to order the products. Could this perhaps result in a nullpointerexception?

I don't have any additional stack trace, it seems like when i set show_sql to false. It doesn't show the exception anymore. Could it have something to do with when writing to a logger or showing sql takes some amount of time which gives enough time for a new connection to be setup.

It seems quite awkward i cannot pinpoint when it occurs and at this moment it doesn't seem to occur at all...

[David Harkness]

Spurious exceptions are notoriously difficult to track down. Here are some more questions for you:

What is the environment? OS, JDK version, container (servlet/EJB), JDBC driver, Hibernate version, logging library

Is the MySQL database on the same machine? I doubt this makes a difference, but any info can help.

What connection pool are you using? What others have you tried?

Does the log show anything else with that exception like the logging class / logger name or the error level? Looking at it again, it looks like Java's default output when it catches an exception from Thread.run().

What other side effects are there to this exception? Does the request go to an error page or not work in other ways? Or do you just see an exception in the log.

Does disabling show_sql solve the problem consistantly? That seems really odd.*

And here are some suggestions to try:

Try out a different connection pool, e.g. C3P0 (sounds toyish but used by tons of production sites) and Apache DBCP

Try out a different JDBC driver. I don't use MySQL, so you'll have to search for yourself, but there must be others out there.

Search MySQL forums since it's their driver. (I assume so from the package name)

Try to isolate it in a small application that creates many threads and calls the same operation that usually results in the exception. Make the number of threads a parameter so you can kick up the number until you hit the problem. Actually, next tip is probably better (actual vs. contrived environment) and definitely easier.

Since that might be a bit time-consuming to code up, write a simple app that will create multiple threads that make HTTP calls to your webapp. Make the number of threads and the URL configurable. Play with it until you can narrow down which URLs cause the problem and how many threads. If you find a lot of URLs cause the issue, this is yet more evidence that it isn't related to a single request but to some system service (pool, Hibernate, etc).

Okay, here's one possibility that seems to fit the evidence. If SQL logging in Hibernate is performed by a separate thread, perhaps it's still in the process of inspecting the Statement (for what I don't know since I assume it would use the SQL generated before creating the Statement, but who knows) when the connection pool tries to close it.

Actually, that doesn't quite seem to match because if that were occuring, Hibernate should be affected -- not the JDBC driver. Wow, this one's tricky!

[Ricardo Estafan]

Hello this is a response on the hibernate forum i don't want to keep for myself ;-)
-------------------------------
Hi. There are two issues here:

1) Perhaps you don't like where the messages are going, i.e. to Tomcat console. If this is the issue, upgrade to c3p0-0.9.0-pre5, which will log to log4j or jdk14logging.

2) Perhaps you don't like that Exceptions keep occuring in your application. Though I don't know for sure, here is what I think is going on: Your pool, for whatever reason, decides to close and discard a Connection. The Connection has cached Statements associated with it. At Connection close, tasks are posted nearly simultaneously to asynchronously close all cached Statements belonging to the Connection as well as the Connection itself. BUT, some drivers are a bit buggy, and can't handle the unusual ordering where a Connection and its child Statement are closed simultaneously, or in an unusual order. When a Statement tries to close() after its parent Connection has already closed, your JDBC driver throws a NullPointerException. (Oracle seems also to have a problem -- an occasional deadlock -- with the simultaneous close of a Connection and its child Statements.

I've implemented a change in the Statement pooling to ensure all cached Statements close prior to the call to Connection close(), which should resolve these problems. This change isn't yet in any public release, because I'd like to test it a bit more. If you'd like to try a development version with the change, write me directly ([e-mail]), and I'll send you a development snapshot, which should, if I'm right about the problem, prevent these Exceptions from occurring at all.

smiles,
Steve (c3p0 guy)

[David Harkness]

That's got my vote. Nice one, Ricardo!