Hibernate Books

All times are UTC - 5 hours [ DST ]



Post new topic Reply to topic  [ 3 posts ] 
Author Message
 Post subject: Session.close leaks a JDBC Connection
PostPosted: Fri Jan 08, 2010 8:20 pm 
Newbie

Joined: Fri Jan 08, 2010 4:00 pm
Posts: 3
Session.close fails to close a JDBC Connection, I've found, if the first two calls to the connection (getAutoCommit and isClosed) throw SQLException and subsequent calls don't throw exceptions. This seems like a bug to me. Can you recommend a workaround?

That's unusual behavior for a Connection, but it happens. One example is a Spring TransactionAwareDataSourceProxy, with a connection pool that's temporarily exhausted. Spring attempts to get a connection from the pool on each call to a Connection method. The first two calls may fail because the pool is exhausted, but the third call may allocate a connection and succeed. Other connection pooling systems behave this way.

This creates a vicious cycle: if the pool is temporarily exhausted, Hibernate leaks a connection, which makes it more likely that the pool will become exhausted. If demand for connections doesn't stop, all the connections will leak and the pool will be permanently exhausted.

Here's a JUnit test case that shows the problem. First the output:
Code:
2010/01/08 16:17:56.242 INFO  [org.hibernate.cfg.Environment] Hibernate 3.3.2.GA
2010/01/08 16:17:56.245 INFO  [org.hibernate.cfg.Environment] loaded properties from resource hibernate.properties: {hibernate.dialect=org.hibernate.dialect.Oracle10gDialect, hibernate.temp.use_jdbc_metadata_defaults=false, hibernate.bytecode.use_reflection_optimizer=false, hibernate.transaction.factory_class=org.springframework.orm.hibernate3.SpringTransactionFactory, hibernate.connection.provider_class=com.linkedin.test.hibernate.MockConnectionProvider}
2010/01/08 16:17:56.247 INFO  [org.hibernate.cfg.Environment] Bytecode provider name : javassist
2010/01/08 16:17:56.250 INFO  [org.hibernate.cfg.Environment] using JDK 1.4 java.sql.Timestamp handling
2010/01/08 16:17:56.307 INFO  [org.hibernate.connection.ConnectionProviderFactory] Initializing connection provider: com.linkedin.test.hibernate.MockConnectionProvider
2010/01/08 16:17:56.334 INFO  [org.hibernate.dialect.Dialect] Using dialect: org.hibernate.dialect.Oracle10gDialect
2010/01/08 16:17:56.368 INFO  [org.hibernate.transaction.TransactionFactoryFactory] Transaction strategy: org.springframework.orm.hibernate3.SpringTransactionFactory
2010/01/08 16:17:56.379 INFO  [org.hibernate.transaction.TransactionManagerLookupFactory] No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended)
2010/01/08 16:17:56.381 INFO  [org.hibernate.hql.ast.ASTQueryTranslatorFactory] Using ASTQueryTranslatorFactory
2010/01/08 16:17:56.416 INFO  [org.hibernate.impl.SessionFactoryImpl] building session factory
2010/01/08 16:17:56.423 INFO  [org.hibernate.impl.SessionFactoryObjectFactory] Not binding factory to JNDI, no JNDI name configured
2010/01/08 16:17:56.454 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection
2010/01/08 16:17:56.488 ERROR [org.hibernate.transaction.JDBCTransaction] JDBC begin failed
java.sql.SQLException: pool exhausted
   at org.easymock.internal.MockInvocationHandler.invoke(MockInvocationHandler.java:34)
   at org.easymock.internal.ObjectMethodsFilter.invoke(ObjectMethodsFilter.java:61)
   at $Proxy0.getAutoCommit(Unknown Source)
   at org.hibernate.transaction.JDBCTransaction.begin(JDBCTransaction.java:85)
   at org.hibernate.impl.SessionImpl.beginTransaction(SessionImpl.java:1354)
   at com.linkedin.test.hibernate.TestConnectionManager.testBeginFailed(TestConnectionManager.java:31)
   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:592)
   at junit.framework.TestCase.runTest(TestCase.java:154)
   at junit.framework.TestCase.runBare(TestCase.java:127)
   at junit.framework.TestResult$1.protect(TestResult.java:106)
   at junit.framework.TestResult.runProtected(TestResult.java:124)
   at junit.framework.TestResult.run(TestResult.java:109)
   at junit.framework.TestCase.run(TestCase.java:118)
   at junit.framework.TestSuite.runTest(TestSuite.java:208)
   at junit.framework.TestSuite.run(TestSuite.java:203)
   at org.eclipse.jdt.internal.junit.runner.junit3.JUnit3TestReference.run(JUnit3TestReference.java:130)
   at org.eclipse.jdt.internal.junit.runner.TestExecution.run(TestExecution.java:38)
   at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:460)
   at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.runTests(RemoteTestRunner.java:673)
   at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.run(RemoteTestRunner.java:386)
   at org.eclipse.jdt.internal.junit.runner.RemoteTestRunner.main(RemoteTestRunner.java:196)
2010/01/08 16:17:56.489 TRACE [org.hibernate.jdbc.ConnectionManager] performing cleanup
2010/01/08 16:17:56.489 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)]
2010/01/08 16:17:56.490 WARN  [org.hibernate.util.JDBCExceptionReporter] SQL Error: 0, SQLState: null
2010/01/08 16:17:56.490 ERROR [org.hibernate.util.JDBCExceptionReporter] pool exhausted
2010/01/08 16:17:56.490 TRACE [org.hibernate.jdbc.JDBCContext] after transaction completion
2010/01/08 16:17:56.491 DEBUG [org.hibernate.jdbc.ConnectionManager] transaction completed on session with on_close connection release mode; be sure to close the session to release JDBC resources!
2010/01/08 16:17:56.494 ERROR [com.linkedin.test.hibernate.TestConnectionManager] java.lang.AssertionError:
  Expectation failure on verify:
    getAutoCommit(): expected: between 0 and 1, actual: 1
    close(): expected: 1, actual: 0
2010/01/08 16:17:56.494 INFO  [org.hibernate.impl.SessionFactoryImpl] closing

Here's the hibernate.properties file:
Code:
hibernate.connection.provider_class=com.linkedin.test.hibernate.MockConnectionProvider
hibernate.temp.use_jdbc_metadata_defaults=false
hibernate.dialect=org.hibernate.dialect.Oracle10gDialect
hibernate.transaction.factory_class=org.springframework.orm.hibernate3.SpringTransactionFactory

Here's the test driver:
Code:
package com.linkedin.test.hibernate;

import junit.framework.TestCase;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.hibernate.JDBCException;
import org.hibernate.SessionFactory;
import org.hibernate.Transaction;
import org.hibernate.TransactionException;
import org.hibernate.cfg.Configuration;
import org.hibernate.classic.Session;

/**
* Test org.hibernate.jdbc.ConnectionManager.
* @author <a href="mailto:jkristian@linkedin.com">John Kristian</a>
*/
public class TestConnectionManager extends TestCase {

    private static final Log log = LogFactory.getLog(TestConnectionManager.class);

    public TestConnectionManager(String name) {
        super(name);
    }

    /** Handle exceptions when beginTransaction can't get a database connection. */
    public void testBeginFailed() {
        SessionFactory sessionFactory = new Configuration().buildSessionFactory();
        try {
            Session session = sessionFactory.openSession();
            try {
                Transaction tx = session.beginTransaction();
                tx.commit();
                fail("expected TransactionException");
            } catch (TransactionException expected) {
                log.debug("session.beginTransaction", expected);
            } finally {
                try {
                    session.close();
                    fail("expected JDBCException");
                } catch (JDBCException expected) {
                    log.debug("session.close", expected);
                }
                MockConnectionProvider.verify();
            }
        } catch (AssertionError e) {
            log.error(e);
            throw e;
        } finally {
            sessionFactory.close();
        }
    }
}

And the mock ConnectionProvider:
Code:
package com.linkedin.test.hibernate;

import java.lang.reflect.InvocationHandler;
import java.lang.reflect.InvocationTargetException;
import java.lang.reflect.Method;
import java.lang.reflect.Proxy;
import java.sql.Connection;
import java.sql.SQLException;
import java.util.ArrayList;
import java.util.Collection;
import java.util.Properties;
import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.easymock.EasyMock;
import org.easymock.IAnswer;
import org.hibernate.HibernateException;
import org.hibernate.connection.ConnectionProvider;

/**
* Simulates a connection pool that's temporarily exhausted.
* @author <a href="mailto:jkristian@linkedin.com">John Kristian</a>
*/
public class MockConnectionProvider implements ConnectionProvider {

    private static final Log log = LogFactory.getLog(MockConnectionProvider.class);
    private static final Collection<Object> mocks = new ArrayList<Object>();

    public void configure(Properties props) throws HibernateException {
    }

    public boolean supportsAggressiveRelease() {
        return true;
    }

    public Connection getConnection() throws SQLException {
        SQLException poolExhausted = new SQLException("pool exhausted");
        Connection connection = EasyMock.createStrictMock(Connection.class);
        EasyMock.expect(connection.getAutoCommit()).andThrow(poolExhausted);
        {
            // This works: EasyMock.expect(connection.isClosed()).andReturn(true);
            // This works: EasyMock.expect(connection.isClosed()).andReturn(false);
            // But this causes a leak:
            EasyMock.expect(connection.isClosed()).andThrow(poolExhausted);
            EasyMock.expect(connection.isClosed()).andReturn(false);
        }
        EasyMock.expect(connection.getAutoCommit()).andAnswer(new LogStackAndReturn<Boolean>(false)).times(0, 1);
        // EasyMock.expect(connection.getWarnings()).andReturn(null).times(0, 1);
        // connection.clearWarnings(); EasyMock.expectLastCall().times(0, 1);
        connection.close(); EasyMock.expectLastCall();
        EasyMock.replay(connection);
        mocks.add(connection);
        if (log.isTraceEnabled()) {
            connection = (Connection) Proxy.newProxyInstance(connection.getClass().getClassLoader(),
                    new Class[] { Connection.class }, new LogCall(connection));
        }
        return connection;
    }

    public void closeConnection(Connection connection) throws SQLException {
        connection.close();
    }

    public void close() throws HibernateException {
        log.trace("close");
    }

    public static void verify() {
        EasyMock.verify(mocks.toArray());
    }

    /** Logs the current stack and then returns a given value. */
    private static class LogStackAndReturn<T> implements IAnswer<T> {

        private final T _answer;

        LogStackAndReturn(T answer) {
            _answer = answer;
        }

        public T answer() throws Throwable {
            log.debug("stack trace", new Exception());
            return _answer;
        }
    }

    /** Logs the method name and the returned value. */
    private static class LogCall implements InvocationHandler {

        private final Object _subject;

        LogCall(Object subject) {
            _subject = subject;
        }

        public Object invoke(Object proxy, Method method, Object[] args) throws Throwable {
            String name = method.getName();
            log.trace("-> " + name);
            String valediction = "<- " + name + " ";
            try {
                Object result = method.invoke(_subject, args);
                valediction += "returned " + result;
                return result;
            } catch (InvocationTargetException e) {
                Throwable t = e.getCause();
                valediction += "threw " + t;
                throw t;
            } catch (Throwable t) {
                valediction += "threw " + t;
                throw t;
            } finally {
                log.trace(valediction);
            }
        }
    }

}


Top
 Profile  
 
 Post subject: Re: Session.close leaks a JDBC Connection
PostPosted: Mon Jan 11, 2010 4:00 pm 
Newbie

Joined: Fri Jan 08, 2010 4:00 pm
Posts: 3
This problem can be prevented, I discovered, by setting hibernate.connection.release_mode=after_transaction. (on_close is the default, from SpringTransactionFactory.) Is this a good idea? Would after_transaction have undesirable side-effects? SPR-2022 suggests after_transaction would prevent using custom isolation levels or read-only connections, which seems bad.

By the way, here's a simplified version of MockConnectionProvider, and my log4j.xml file.
Code:
package com.linkedin.test.hibernate;

import java.sql.Connection;
import java.sql.SQLException;
import java.util.ArrayList;
import java.util.Collection;
import java.util.Properties;
import org.easymock.EasyMock;
import org.hibernate.HibernateException;
import org.hibernate.connection.ConnectionProvider;

/**
* Simulates a connection pool that's temporarily exhausted.
* @author <a href="mailto:jkristian@linkedin.com">John Kristian</a>
*/
public class MockConnectionProvider implements ConnectionProvider {

    private static final Collection<Object> mocks = new ArrayList<Object>();

    public void configure(Properties props) throws HibernateException {
    }

    public boolean supportsAggressiveRelease() {
        return true;
    }

    public Connection getConnection() throws SQLException {
        SQLException poolExhausted = new SQLException("pool exhausted");
        Connection connection = EasyMock.createStrictMock(Connection.class);
        EasyMock.expect(connection.getAutoCommit()).andThrow(poolExhausted);
        {
            // This works: EasyMock.expect(connection.isClosed()).andReturn(true);
            // This works: EasyMock.expect(connection.isClosed()).andReturn(false);
            // But this causes a leak:
            EasyMock.expect(connection.isClosed()).andThrow(poolExhausted);
            EasyMock.expect(connection.isClosed()).andReturn(false);
        }
        EasyMock.expect(connection.getAutoCommit()).andReturn(false);
        connection.close(); EasyMock.expectLastCall();
        EasyMock.replay(connection);
        mocks.add(connection);
        return connection;
    }

    public void closeConnection(Connection connection) throws SQLException {
        connection.close();
    }

    public void close() throws HibernateException {
    }

    public static void verify() {
        EasyMock.verify(mocks.toArray());
    }

}

Code:
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
  <appender name="ConsoleAppender" class="org.apache.log4j.ConsoleAppender">
    <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern" value="%d{yyyy/MM/dd HH:mm:ss.SSS} %-5p [%c] %m%n" />
    </layout>
  </appender>
  <logger name="org.hibernate.cfg.SettingsFactory">
    <level value="warn"/>
  </logger>
  <logger name="org.hibernate.jdbc">
    <level value="all"/>
  </logger>
  <root>
    <priority value="info"/>
    <appender-ref ref="ConsoleAppender"/>
  </root>
</log4j:configuration>


Top
 Profile  
 
 Post subject: Re: Session.close leaks a JDBC Connection
PostPosted: Fri Jan 15, 2010 12:56 am 
Newbie

Joined: Fri Jan 08, 2010 4:00 pm
Posts: 3
I opened a bug report HHH-4802. I'm still hoping for a good workaround. Anyone?


Top
 Profile  
 
Display posts from previous:  Sort by  
Post new topic Reply to topic  [ 3 posts ] 

All times are UTC - 5 hours [ DST ]


You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum

Search for:
© Copyright 2014, Red Hat Inc. All rights reserved. JBoss and Hibernate are registered trademarks and servicemarks of Red Hat, Inc.