Wednesday, February 24, 2016

log4jdbc - Invalid operation: result set is closed - DB2 JCC Driver

While troubleshooting a "resultset is closed" issue, the immediate thing that came into mind is the DB2 JCC driver's default behavior of implicitly closing the ResultSet upon find that the cursor has been placed after the last row (ie the result set has exhausted). And calling ResultSet.next() on such a state will throw the exception stating "resultset is closed". As in my previous post, DB2 provides a workaround to tolerate the call next() on exhausted resultset by setting the property allowNextOnExhaustedResultSet = 1.  But in the current case, it is not the next() that was causing the problem and instead the call to ResultSet.getMetaData() after the ResultSet has been exhausted. But who calls this getMetaData on a already closed resultset? From the exception stack, we noticed the application has been plugged in with the log4jdbc for monitoring the JDBC operations and it is the log4jdbc invoking the getMetaData() at an in-appropriate time which the DB2 JCC driver does not like.

Further digging into log4jdbc, we discovered that the stack of log4jdbc might correspond to version 1.12 or less. And from version 1.13 and above they have a fix for this problem where they verify if the resultset is usable by calling rs.isClosed() check before invoking the getMetaData() call. And there seems to be an issue with the isClosed() API when DB2 implicitly closes the ResultSet which is addressed by a WebSphere datasource custom property resultSetUnusableWhenNoMoreResults="true". So the problem can be resolved by upgrading the log4jdbc to a higher version along with the WebSphere datasource custom property resultSetUnusableWhenNoMoreResults="true".

com.ibm.db2.jcc.am.SqlException: [jcc][t4][10120][10898][3.65.131] Invalid operation: result set is closed. ERRORCODE=-4470, SQLSTATE=null
    at com.ibm.db2.jcc.am.kd.a(Unknown Source)
    at com.ibm.db2.jcc.am.kd.a(Unknown Source)
    at com.ibm.db2.jcc.am.kd.a(Unknown Source)
    at com.ibm.db2.jcc.am.ResultSet.checkForClosedResultSet(Unknown Source)
    at com.ibm.db2.jcc.am.ResultSet.getMetaDataX(Unknown Source)
    at com.ibm.db2.jcc.am.ResultSet.getMetaData(Unknown Source)
    at com.ibm.ws.rsadapter.jdbc.WSJdbcResultSet.getMetaData(WSJdbcResultSet.java
    at net.sf.log4jdbc.DefaultResultSetCollector.getMetaDataIfNeeded(DefaultResultSetCo
    at net.sf.log4jdbc.DefaultResultSetCollector.methodReturned(DefaultResultSetCollecto

    at net.sf.log4jdbc.ResultSetSpy.reportAllReturns(ResultSetSpy.java:89)
    at net.sf.log4jdbc.ResultSetSpy.reportReturn(ResultSetSpy.java:159)
    at net.sf.log4jdbc.ResultSetSpy.next(ResultSetSpy.java:1998)

    at org.hibernate.loader.Loader.processResultSet(Loader.java:950)

Disclaimer: These are my personal views and does not reflect my employer in any way!!

No comments: