0

I need help troubleshooting a problem that has been recurring for years. It is about a web application, running on Tomcat 9. I am using Hibernate, Postgresql and Tomcat JDBC Connection Pool. The application is running in autocommit=false and CURRENT_SESSION_CONTEXT_CLASS=thread mode.

These are the settings of Tomcat data source (JDBC connection pool):

  <Resource name="xxx" auth="Container"
          type="javax.sql.DataSource" driverClassName="org.postgresql.Driver" factory="org.apache.tomcat.jdbc.pool.DataSourceFactory"
          url="jdbc:postgresql://localhost:5432/db"
          username="xxx" password="xxx" maxActive="200" maxIdle="50" minIdle="30"
          defaultAutoCommit="false" jmxEnabled="false"
          jdbcInterceptors="org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReport"
            removeAbandoned="true"
            removeAbandonedTimeout="30"
            logAbandoned="true"
            suspectTimeout="20"
            validationQuery="SELECT 1"
            testWhileIdle="true"
            timeBetweenEvictionRunsMillis="5000"
            minEvictableIdleTimeMillis="60000"
            testOnBorrow="true"
            validationInterval="10000"
            closeMethod="close"

/>

and Hibernate sessionFactory:

ServiceRegistry serviceRegistry = new StandardServiceRegistryBuilder().applySettings(...)
.applySetting( AvailableSettings.TRANSACTION_COORDINATOR_STRATEGY, "jdbc" )
.applySetting( AvailableSettings.CURRENT_SESSION_CONTEXT_CLASS, "thread" )
.applySetting( AvailableSettings.USE_NEW_ID_GENERATOR_MAPPINGS, false )
.applySetting( AvailableSettings.DIALECT, "org.hibernate.dialect.PostgreSQL10Dialect" )
.applySetting( AvailableSettings.DEFAULT_SCHEMA, "public" )
.applySetting( AvailableSettings.DRIVER, "org.postgresql.Driver" )
.applySetting( "hibernate.temp.use_jdbc_metadata_defaults", false )
.build();
Metadata metadata = new MetadataSources(serviceRegistry)
            .addAnnotatedClass(…).getMetadataBuilder().build();
sessionFactory = metadata.getSessionFactoryBuilder().build();

The pattern of executing commands to the database looks like this:

Session s = sessionFactory.getCurrentSession();
s.beginTransaction();
try {
  …
  …
  s.getTransaction().commit();
} catch (Exception x) {
  x.printStackTrace();
  s.getTransaction().rollback();
}

Once in a while it happens that an operation in a try-catch takes a very long time to execute or there is a transaction leak due to a bug in the code and the transaction is not completed by either commit() or rollback(). These are obviously code bugs that need to be corrected. However, they are very costly, because they cause Tomcat to mark these transactions as "abandoned" after some time and remove them from the pool. The problem is that Hibernate reacts badly to this, and in such a situation dozens of exceptions suddenly start being thrown:

org.apache.catalina.core.StandardWrapperValve.invoke Servlet.service() for servlet [dispatcher] in context with path
 [] threw exception [Request processing failed; nested exception is org.hibernate.TransactionException: JDBC begin transaction failed: ] with root cause
        java.sql.SQLException: Connection has already been closed.
                at org.apache.tomcat.jdbc.pool.ProxyConnection.invoke(ProxyConnection.java:121)
                at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
                at org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:79)
                at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
                at org.apache.tomcat.jdbc.pool.TrapException.invoke(TrapException.java:39)
                at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
                at org.apache.tomcat.jdbc.pool.interceptor.AbstractCreateStatementInterceptor.invoke(AbstractCreateStatementInterceptor.java:79)
                at org.apache.tomcat.jdbc.pool.JdbcInterceptor.invoke(JdbcInterceptor.java:109)
                at org.apache.tomcat.jdbc.pool.DisposableConnectionFacade.invoke(DisposableConnectionFacade.java:81)
                at jdk.proxy2/jdk.proxy2.$Proxy92.setAutoCommit(Unknown Source)
                at org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor.begin(AbstractLogicalConnectionImplementor.java:72)
                at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:285)
                at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:246)
                at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:83)
                at org.hibernate.internal.AbstractSharedSessionContract.beginTransaction(AbstractSharedSessionContract.java:503)
                at jdk.internal.reflect.GeneratedMethodAccessor191.invoke(Unknown Source)
                at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
                at java.base/java.lang.reflect.Method.invoke(Method.java:568)
                at org.hibernate.context.internal.ThreadLocalSessionContext$TransactionProtectionWrapper.invoke(ThreadLocalSessionContext.java:351)
                at jdk.proxy3/jdk.proxy3.$Proxy91.beginTransaction(Unknown Source)

This exception is thrown at Session.beginTransaction.

I have two questions:

  1. How to force Hibernate to simply take a new open connection from the Tomcat JDBC connection pool in such a situation? And report some kind of warning to System.out or log file.

  2. What methods do you use to find the bug in the code and locate uncommited transaction?

1 Answers1

0

Advice No 1

According to Tomcat documentation:

removeAbandonedTimeout - (int) Timeout in seconds before an abandoned(in use) connection can be removed. The default value is 60 (60 seconds). The value should be set to the longest running query your applications might have.

Your setting is (only) 30 seconds. Set it to the longest running query your applications might have.

Advice No 2

The code shared in the post can be improved:

  1. Call of session.beginTransaction() should be inside of the try/catch block.
  2. Exception must be re-thrown and not just logged.
  3. Session must be closed immediately when an exception occurred and transaction has been rolled back. In your code session is not closed at all. Add finally block like here:
Session session = sessionFactory.getCurrentSession();
Transaction tx = null;
try {
    tx = session.beginTransaction();
    // …
    tx.commit();
} catch (Exception ex) {
    if (tx != null) tx.rollback();
    throw ex;
}
finally {
    session.close();
}
Mar-Z
  • 2,660
  • 2
  • 4
  • 16
  • I believe that increasing _removeAbandonedTimeout_ parameter does not solve the issue and that is not what I asked. I am looking for a way to make `getCurrentSession` always take an active connection. In the second advice you are wrong. Closing the session is required when I would do `openSession` on _sessionFactory_. When I use `getCurrentSession` the session should not be closed. This is well explained [here](https://stackoverflow.com/questions/8046662/hibernate-opensession-vs-getcurrentsession). The other comments are comments on code style and do not address my questions. – Jakub Królikowski Jun 13 '23 at 11:38