Bug 60764

Summary: SlowQueryReport causing connection leak
Product: Tomcat Modules Reporter: mark.housel
Component: jdbc-poolAssignee: Tomcat Developers Mailing List <dev>
Status: RESOLVED FIXED    
Severity: major    
Priority: P2    
Version: unspecified   
Target Milestone: ---   
Hardware: PC   
OS: All   

Description mark.housel 2017-02-22 01:40:58 UTC
Tomcat versions: 8.5.11, 7.0.75

I have a project that uses hibernate with optimistic locking and whenever it tries to do a rollback after an optimistic lock exception, the connection remains active and is not returned to the pool.  This only happens when I have the SlowQueryReport interceptor configured on my JDBC datasource in server.xml.  Here is the relevant stack trace:

20:06:59.566 level:DEBUG class:org.springframework.orm.jpa.EntityManagerFactoryUtils principal: Unexpected exception on closing JPA EntityManager
java.lang.reflect.UndeclaredThrowableException: null
	at com.sun.proxy.$Proxy40.hashCode(Unknown Source)
	at java.util.HashMap.hash(HashMap.java:338)
	at java.util.HashMap.get(HashMap.java:556)
	at org.hibernate.resource.jdbc.internal.ResourceRegistryStandardImpl.release(ResourceRegistryStandardImpl.java:76)
	at org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.releaseStatements(AbstractBatchImpl.java:157)
	at org.hibernate.engine.jdbc.batch.internal.AbstractBatchImpl.release(AbstractBatchImpl.java:195)
	at org.hibernate.engine.jdbc.internal.JdbcCoordinatorImpl.close(JdbcCoordinatorImpl.java:190)
	at org.hibernate.internal.SessionImpl.close(SessionImpl.java:424)
	at org.hibernate.jpa.internal.EntityManagerImpl.close(EntityManagerImpl.java:145)
	at org.springframework.orm.jpa.EntityManagerFactoryUtils.closeEntityManager(EntityManagerFactoryUtils.java:438)
	at org.springframework.orm.jpa.JpaTransactionManager.doCleanupAfterCompletion(JpaTransactionManager.java:602)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.cleanupAfterCompletion(AbstractPlatformTransactionManager.java:1016)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:811)
	at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:730)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.commitTransactionAfterReturning(TransactionAspectSupport.java:485)
	at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:291)
	at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:96)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:179)
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:208)
	at com.sun.proxy.$Proxy215.test(Unknown Source)
	at com.sony.snei.mm.quartz.job.AbstractCategoryLayoutJob$1.run(AbstractCategoryLayoutJob.java:71)
	at java.lang.Thread.run(Thread.java:745)
Caused by: java.sql.SQLException: Statement closed.
	at org.apache.tomcat.jdbc.pool.interceptor.AbstractQueryReport$StatementProxy.invoke(AbstractQueryReport.java:226)
	... 22 common frames omitted


The problem is that hashCode() is called on the connection after it has been closed and that causes StatementProxy to throw the "Statement closed" exception.  I think that it should allow hashCode() and equals() to be called on the delegate even after the connection is closed.

Thanks,
Mark
Comment 1 Keiichi Fujino 2017-03-01 09:20:00 UTC
Hi.

Does this problem affect only when using SlowQueryReport?
According to my initial investigation, the same problems seems to be occurred
even if StatementCache or StatementDecoratorInterceptor is used.
Comment 2 mark.housel 2017-03-01 18:58:04 UTC
(In reply to Keiichi Fujino from comment #1)
> Hi.
> 
> Does this problem affect only when using SlowQueryReport?
> According to my initial investigation, the same problems seems to be occurred
> even if StatementCache or StatementDecoratorInterceptor is used.

You are right, I just tested using StatementCache and got the same problem.

When I said it only happens with SlowQueryReport, I just meant that it didn't happen when I don't use SlowQueryReport.
Comment 3 Keiichi Fujino 2017-03-02 09:54:07 UTC
Thanks.

I am planning  to fix this problem as follows.
-Implement equals() and hashCode() in the StatementDecoratorInterceptor.
-Enable StatementDecoratorInterceptor by default.(mybe configuable)

As a result, Interceptor chain will be follows.
DisposableConnectionFacade -> StatementDecoratorInterceptor -> XXXInterceptor(1..n) -> ProxyConnection
Comment 4 Keiichi Fujino 2017-03-23 08:06:47 UTC
Fixed at r1788183

The fix will be in :
- 9.0.x for 9.0.0.M19 onwards
- 8.5.x for 8.5.13 onwards
- 8.0.x for 8.0.43 onwards
- 7.0.x for 7.0.77 onwards


The fix has changed to adding a facade on statement instead of modify StatementDecoratorInterceptor. 
As a result, Interceptor chain will be follows.
DisposableConnectionFacade -> StatementFacade -> XXXInterceptor(1..n) -> ProxyConnection