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:
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.
What methods do you use to find the bug in the code and locate uncommited transaction?