JDO : Beware when closing PreparedStatement Objects

Once you are done with a PreparedStatement, it is good practice to close it. But pain awaits you in unexpected moments, if you close a statement one too many times.

In standard code using JDO, it is not uncommon to find ResultSet and PreparedStatement objects that do not get closed. Things will work for a while before memory issues force developers to clean these up. This is what happened on our production systems recently. Unfortunately, we were somewhat overzealous and at one point, closed a statement twice. It ran on Q/A without a problem, so unnoticed to the gatekeepers, it slipped into production.

And there it crashed and burned, not in the close statement as one would imagine, but in stmt.get call with the following stack trace:

Processor.processFile: problem 
processing data from filename: /path/to/something.csv on:
com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after statement closed.
        at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
        at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:39)
        at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:27)
        at java.lang.reflect.Constructor.newInstance(Constructor.java:513)
        at com.mysql.jdbc.Util.handleNewInstance(Util.java:409)
        at com.mysql.jdbc.Util.getInstance(Util.java:384)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:1015)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:989)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:984)
        at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:929)
        at com.mysql.jdbc.StatementImpl.checkClosed(StatementImpl.java:406)
        at com.mysql.jdbc.ServerPreparedStatement.checkClosed(ServerPreparedStatement.java:546)
        at com.mysql.jdbc.ServerPreparedStatement.setLong(ServerPreparedStatement.java:2037)
        at com.solarmetric.jdbc.DelegatingPreparedStatement.setLong(DelegatingPreparedStatement.java:397)
        at com.solarmetric.jdbc.PoolConnection$PoolPreparedStatement.setLong(PoolConnection.java:448)
        at com.solarmetric.jdbc.DelegatingPreparedStatement.setLong(DelegatingPreparedStatement.java:397)
        at com.solarmetric.jdbc.DelegatingPreparedStatement.setLong(DelegatingPreparedStatement.java:397)
        at com.solarmetric.jdbc.DelegatingPreparedStatement.setLong(DelegatingPreparedStatement.java:397)
        at com.solarmetric.jdbc.LoggingConnectionDecorator$LoggingConnection$LoggingPreparedStatement.setLong(LoggingCo
nnectionDecorator.java:1265)
        at com.solarmetric.jdbc.DelegatingPreparedStatement.setLong(DelegatingPreparedStatement.java:397)
        at com.solarmetric.jdbc.DelegatingPreparedStatement.setLong(DelegatingPreparedStatement.java:397)
        at ourcode.getData(Manager.java:5435)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at ourcode.JDOProxy.invoke(JDOProxy.java:198)
        at $Proxy5.getData(Unknown Source)
        at ourcode.Processor.writeData(Processor.java:3185)
 

This is due to a bug in the mysql connector where if a statement is closed twice, and we create another statement (PreparedStatement) again with the same sql string, it retrieves the closed PreparedStatement object from an internal cache. Then any attempt to use that statement results in an exception. Here are the details of the mysql bug

Here is a bit of code showing the double close. If this function is called twice, it will throw the exception on the second call :

    private static void badsql(PersistenceManager pm) {
        Connection conn=null;
        ResultSet results =null;
        PreparedStatement stmt=null;

        try {
            conn = QUtil.getConn(pm);

            String[] urls = new String[] {"blingbling.com", "singsing.com", "soso.com"};

            stmt = conn.prepareStatement("select numhits from facttable where name = ?");

            for (String url : urls) {
                stmt.setString(1, url);
                results = stmt.executeQuery();
                if (results.next()) {
                    int numTerms = results.getInt(1);
                    System.out.println(url + "=>" + numTerms);
                }
                results.close();
            }
            //first close
            stmt.close();
            conn.close();

        } catch (Exception e) {

        } finally {
            CloseUtil.closeAndIgnore(results);
            //Here is the second close
            CloseUtil.closeAndIgnore(stmt);
            CloseUtil.closeAndIgnore(conn);
        }
    }

The problematic function was being called once for a large batch of records. Since there was not enough records in the Q/A environment, it was called just once and thus we never found the bug in Q/A.