3.2.4 needless warning about unclosed resultset

[davidmboon]

Here is the scenario

we have <track-statements>true</track-statements> for our datasource. We also have code that wraps Connections and statements and closes resultsets when you close statements, and the same for statements when you close connections. This is code that has been working for quite some time, under jboss 3.2.3 as well as weblogic 5.1 and 7.0.

Since we upgraded to jboss 3.2.4 we started seeing:
2004.07.13 08:54:08.734 EDT WARN [WrappedConnection]
Closing a result set you left open! Please close it
yourself.

and a corresponding stacktrace.

Two things are strange about this:
1. We are closing our resultsets
2. Even if I wasn't, that would be ok, becuase I'm closing my statements.

Now if you say something like 'you should close your RestultSet', which I don't disagree with and I am actaully doing, I'm going to have to refer you to the jdbc spec which pretty clearly states that the resources opened by statements will be closed when the statement is closed. If you're now saying that I have to take extra steps, then this seems like you're not conforming to the spec.

Regarding the statment caching, I don't think that this applies since I am actually closing my resultsets.

In summary, there seems to be a bug that is causing WrappedConnection to think that I have not closed resultsets when I actually have.

[davidmboon]

This post is regarding http://sourceforge.net/tracker/index.php?func=detail&aid=990142&group_id=22866&atid=376685

[davidmboon]

Okay, so I'm not the only one to run into this:
http://www.jboss.org/index.html?module=bb&op=viewtopic&t=49695

[adrian.brock]

Glad you found the search function :-)

On your specifc problem:
Show the complete stacktrace (it shows where the ResultSet was created)
and the code where you create and then close it.
Statements and Connections are important (as are line numbers)!

[davidmboon]

Ok, smarty pants, here's the full stack:

2004.07.10 00:34:15.153 GMT WARN [org.jboss.resource.adapter.jdbc.WrappedConnection] Closing a result set you left open! Please close i
t yourself.
java.lang.Exception: STACKTRACE
 at org.jboss.resource.adapter.jdbc.WrappedStatement.registerResultSet(WrappedStatement.java:843)
 at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:315)
 at com.elementk.service.jdbc.audit.AuditedPreparedStatement.executeQuery(AuditedPreparedStatement.java:84)
 at com.elementk.service.jdbc.audit.AuditedPreparedStatement.invoke(AuditedPreparedStatement.java:43)
 at $Proxy466.executeQuery(Unknown Source)
 at sun.reflect.GeneratedMethodAccessor117.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:324)
 at com.elementk.service.jdbc.impl.LmnkStatementImpl.invoke(LmnkStatementImpl.java:142)
 at $Proxy468.executeQuery(Unknown Source)
 at com.elementk.lms.khub.sys.email.dao.EmailDao.getEmailsToSend(EmailDao.java:70)
 at com.elementk.lms.khub.sys.email.MailSystem.sendMail(MailSystem.java:66)
 at com.elementk.lms.khub.sys.email.EmailDaemon.wakeUpAndSendMail(EmailDaemon.java:84)
 at com.elementk.lms.khub.sys.email.EmailDaemon.process(EmailDaemon.java:68)
 at com.elementk.service.scheduler.ProcessSchedulerAdapter.runIfEnabled(ProcessSchedulerAdapter.java:65)
 at sun.reflect.GeneratedMethodAccessor311.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:324)
 at org.jboss.mx.server.ReflectedDispatcher.dispatch(ReflectedDispatcher.java:60)
 at org.jboss.mx.server.Invocation.dispatch(Invocation.java:61)
 at org.jboss.mx.server.Invocation.dispatch(Invocation.java:53)
 at org.jboss.mx.server.Invocation.invoke(Invocation.java:86)
 at org.jboss.mx.server.AbstractMBeanInvoker.invoke(AbstractMBeanInvoker.java:185)
 at org.jboss.mx.server.MBeanServerImpl.invoke(MBeanServerImpl.java:473)
 at org.jboss.varia.scheduler.ScheduleManager$MBeanListener.handleNotification(ScheduleManager.java:528)
 at sun.reflect.GeneratedMethodAccessor5.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:324)
 at org.jboss.mx.notification.NotificationListenerProxy.invoke(NotificationListenerProxy.java:138)
 at $Proxy8.handleNotification(Unknown Source)
 at javax.management.NotificationBroadcasterSupport.handleNotification(NotificationBroadcasterSupport.java:98)
 at javax.management.NotificationBroadcasterSupport.sendNotification(NotificationBroadcasterSupport.java:83)
 at javax.management.timer.Timer.sendNotifications(Timer.java:441)
 at javax.management.timer.Timer.access$000(Timer.java:31)
 at javax.management.timer.Timer$RegisteredNotification.doRun(Timer.java:612)
 at org.jboss.mx.util.SchedulableRunnable.run(SchedulableRunnable.java:164)
 at org.jboss.mx.util.ThreadPool$Worker.run(ThreadPool.java:240)

[adrian.brock]

And the code that closes that specific ResultSet?

[davidmboon]

the resultset is close when the statement is closed, which is close when the connection is closed. Here is the code that we use to close the resultsets:

 /**
 * free up resources opened from this statement.
 */
 public void close() {
 if ( resources.size() == 0 ){
 log.debug("nothing to close for this statement. " + toString());
 }

 for (Iterator i = resources.iterator(); i.hasNext(); ) {
 Object obj = i.next();
 // since the list of resources is not typesafe make sure
 // the object returned is a resource that can be closed.
 if (obj != null && obj instanceof ResultSet) {
 try {
 log.debug("closing resoruce " + obj.toString());
 ((ResultSet)obj).close();
 i.remove();// be extra clear, not really neccessary but robust.
 }
 catch (SQLException e) {
 log.warn("Failed to close ResultSet " + e.getMessage(), e);
 }
 }
 else if ( obj != null ){
 log.warn("Could not close resultset, not an instance of ResultSet: " + obj.getClass().getName());
 }
 }
 }

[davidmboon]

This might be more what you were after though:

 /**
 * Get the emails that have not been sent yet. This email contains
 * a recipient list of 1 IndividualRecipient.
 *
 * @param since the time to look for new emails since, this
 * is a performance optimization, witout it
 * the query would need to look at all message
 * records, with it the query only needs to look
 * at message records in a range.
 */
 public Email[] getEmailsToSend(long since) {


 String sql =
 " SELECT m.msg_id, "
 + " m.subject, m.return_address, m.body_text, m.delivery_date, m.msg_category_id "
 + " FROM message m "
 + " WHERE m.notification_type_id = " + MessagingConstants.NOTIF_TYPE_EMAIL
 + " and m.status_id not in ( "
 + MessagingConstants.MESSAGE_STATUS_DRAFT + ","
 + MessagingConstants.MESSAGE_STATUS_SENT + ", "
 + MessagingConstants.MESSAGE_STATUS_INACTIVE + ", "
 + MessagingConstants.MESSAGE_STATUS_QUEUING + " ) "
 + " and m.delivery_date between (? -(1/24)) and sysdate "; //check between the last hour the email daemon ran
 //and the current time for the case where emails
 //are created at midnight. mhc 11/12/03

 LmnkConnection conn = null;

 try {
 conn = ConnectionFactory.createLmnkConnection();

 Object[] args = new Object[]{ new Timestamp(since) };
 LmnkStatement stmt = conn.prepareStatement(sql, args);
 //PreparedStatement stmt = conn.prepareStatement(sql);

 ResultSet rs = stmt.executeQuery();

 ArrayList result = new ArrayList(64);
 while (rs.next()) {
 //recipients will be filled in later
 Email email = new Email(null, rs.getString(2), rs.getString(3));
 email.setMessageId(rs.getLong(1));
 email.setBodyText(rs.getString(4));
 email.setDeliveryDate(rs.getTimestamp(5));
 email.setType( MessageType.createFromConstant(rs.getInt(6)));
 result.add(email);
 }

 Email[] emailsToSend = (Email[])result.toArray(new Email[result.size()]);

 /*
 * print out the emails being sent.
 */
 if ( log.isDebugEnabled() ) {
 if ( emailsToSend.length > 0 ) {
 StringBuffer sb = new StringBuffer();
 for ( int i = 0; i < emailsToSend.length; i++){
 sb.append( emailsToSend.getMessageId() );
 if ( i < emailsToSend.length ){
 sb.append(",");
 }
 }
 log.debug( "sending [" + sb.toString() + "]" );
 }
 }

 return emailsToSend;

 } catch ( SQLException e ){
 log.error("Failed to execute sql:\n" + sql , e);
 throw new DalRuntimeException(e.getMessage());
 } finally {
 if ( conn != null) conn.close();
 }
 }

[adrian.brock]

That's part of the code.

The rest is just assertion:

The resultset is close when the statement is closed, which is close when the connection is closed. Here is the code that we use to close the resultsets:

and you don't show where the ResultSet is added to the "resources" collection
or even where it is located.

If you don't want to post your code, post an example that reproduces the problem.

[adrian.brock]

This is the jboss code:
http://cvs.sourceforge.net/viewcvs.py/jboss/jbosscx/src/main/org/jboss/resource/adapter/jdbc/Attic/WrappedPreparedStatement.jpp?rev=1.1.2.5&only_with_tag=Branch_3_2&view=markup
http://cvs.sourceforge.net/viewcvs.py/jboss/jbosscx/src/main/org/jboss/resource/adapter/jdbc/Attic/WrappedStatement.jpp?rev=1.2.2.7&only_with_tag=Branch_3_2&view=markup

One thing occurs to me. Are you closing the statement before closing the resultsets?
That would obviously give you a warning since it is the statement.close() that
checks for unclosed resultsets.

[davidmboon]

LmnkStatementImpl is a InvocationHandler, and in the ivoke method we do this:

else if (method.getName().equals("close")) {
 this.close();
 realStatement.close();
 }

So we intercept the the close of the statement and first close the resultsets, then the real 'wrapped' statement.

According to the stack trace we are getting the warning from 'WrappedPreparedStatement.executeQuery'
here's the stack that is relevant:

at org.jboss.resource.adapter.jdbc.WrappedStatement.registerResultSet(WrappedStatement.java:843)
 at org.jboss.resource.adapter.jdbc.WrappedPreparedStatement.executeQuery(WrappedPreparedStatement.java:315)
 at com.elementk.service.jdbc.audit.AuditedPreparedStatement.executeQuery(AuditedPreparedStatement.java:84)
 at com.elementk.service.jdbc.audit.AuditedPreparedStatement.invoke(AuditedPreparedStatement.java:43)
 at $Proxy466.executeQuery(Unknown Source)
 at sun.reflect.GeneratedMethodAccessor117.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:324)
 at com.elementk.service.jdbc.impl.LmnkStatementImpl.invoke(LmnkStatementImpl.java:142)

It seems to be check the resultset when the query is executed, not when the statement is being closed.

[adrian.brock]

No, read the source.

It remembers where you allocated the ResultSet in a

HashMap<ResultSet, Exception> resultSets;

The STACKTRACE is only logged if you haven't closed the ResultSet when you
execute Statement.close()

The stacktrace of the statement.close() wouldn't be very revealing if you had
two results sets from the same statement.