I am not sure where the problem is, or if there is one: Spring, Hibernate, c3p0, my bug? Or not a bug?
I am using c3p0 (0.9.0.4 or 0.9.1-pre5) with Spring and Hibernate EntityManager's annotations features.
Versions: Spring 2.0 M3, latest versions of Hibernate, Hibernate Annotations, and Entity Manager, as of 8-Mar-2006.
When I set the Log4J log Level=DEBUG, I get the stack trace below when I close my Spring application's context -- which invokes the spring service beans' destory methods.
SEE: java.lang.Exception: DEBUG STACK TRACE for PoolBackedDataSource.close()
When I set the Log4J log Level=INFO, I do not get the stack trace.
If I do not programatically close my Spring application context -- and do not invoke destroy methods -- I do not see the stack trace no matter what Log4J log Level is set.
The problem may have something to do with the EHCache (see "Expiry thread interrupted on Disk Store" in log).
Or the problem may have something to do with the order of spring bean destruction. Estou "boiando" -- a little lost -- on this one.
Or maybe there is no problem. The c3p0 PoolBackedDataSource.close() method is just logging junk, and I should not worry.
Has anyone seen this before? I haven't seen any posts on the Hibernate or Spring forums that describe this weird problem.
Regards,
Stan
##################
##################
##################
2006-Mar-08 23:31:22 - INFO [com.povosoftware.base.BaseExceptionServiceImpl] dispose
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'entityManagerFactory'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'authenticatedUserManagerTarget'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'transactionManager'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'transactionInterceptor'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'povoSoftwareUserManagerTarget'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'personManagerTarget'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Invoking destroy() on bean with name 'entityManagerFactory'
2006-Mar-08 23:31:22 - INFO [org.springframework.orm.jpa.LocalEntityManagerFactoryBean] Closing JPA EntityManagerFactory
2006-Mar-08 23:31:22 - INFO [org.hibernate.impl.SessionFactoryImpl] closing
2006-Mar-08 23:31:22 - DEBUG [net.sf.ehcache.CacheManager] Attempting to create an existing instance. Existing instance returned.
2006-Mar-08 23:31:22 - DEBUG [net.sf.ehcache.store.DiskStore] mailarchive.org.hibernate.cache.StandardQueryCacheCache: Expiry thread interrupted on Disk Store.
2006-Mar-08 23:31:22 - DEBUG [net.sf.ehcache.store.DiskStore] Deleting file mailarchive.org.hibernate.cache.StandardQueryCache.data
2006-Mar-08 23:31:22 - DEBUG [net.sf.ehcache.CacheManager] Attempting to create an existing instance. Existing instance returned.
2006-Mar-08 23:31:22 - DEBUG [net.sf.ehcache.store.DiskStore] mailarchive.org.hibernate.cache.UpdateTimestampsCacheCache: Expiry thread interrupted on Disk Store.
2006-Mar-08 23:31:22 - DEBUG [net.sf.ehcache.store.DiskStore] Deleting file mailarchive.org.hibernate.cache.UpdateTimestampsCache.data
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.resourcepool.BasicResourcePool] Preparing to destroy resource: com.mchange.v2.c3p0.impl.NewPooledConnection@b2311b
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] Preparing to destroy PooledConnection: com.mchange.v2.c3p0.impl.NewPooledConnection@b2311b
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] Successfully destroyed PooledConnection: com.mchange.v2.c3p0.impl.NewPooledConnection@b2311b. Currently open Connections: 4; Failed close count: 0; Total processed by this pool: 5
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.resourcepool.BasicResourcePool] Successfully destroyed resource: com.mchange.v2.c3p0.impl.NewPooledConnection@b2311b
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.resourcepool.BasicResourcePool] Preparing to destroy resource: com.mchange.v2.c3p0.impl.NewPooledConnection@4aa085
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] Preparing to destroy PooledConnection: com.mchange.v2.c3p0.impl.NewPooledConnection@4aa085
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] Successfully destroyed PooledConnection: com.mchange.v2.c3p0.impl.NewPooledConnection@4aa085. Currently open Connections: 3; Failed close count: 0; Total processed by this pool: 5
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.resourcepool.BasicResourcePool] Successfully destroyed resource: com.mchange.v2.c3p0.impl.NewPooledConnection@4aa085
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.resourcepool.BasicResourcePool] Preparing to destroy resource: com.mchange.v2.c3p0.impl.NewPooledConnection@ccbb35
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] Preparing to destroy PooledConnection: com.mchange.v2.c3p0.impl.NewPooledConnection@ccbb35
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] Successfully destroyed PooledConnection: com.mchange.v2.c3p0.impl.NewPooledConnection@ccbb35. Currently open Connections: 2; Failed close count: 0; Total processed by this pool: 5
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.resourcepool.BasicResourcePool] Successfully destroyed resource: com.mchange.v2.c3p0.impl.NewPooledConnection@ccbb35
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.resourcepool.BasicResourcePool] Preparing to destroy resource: com.mchange.v2.c3p0.impl.NewPooledConnection@72add8
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] Preparing to destroy PooledConnection: com.mchange.v2.c3p0.impl.NewPooledConnection@72add8
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] Successfully destroyed PooledConnection: com.mchange.v2.c3p0.impl.NewPooledConnection@72add8. Currently open Connections: 1; Failed close count: 0; Total processed by this pool: 5
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.resourcepool.BasicResourcePool] Successfully destroyed resource: com.mchange.v2.c3p0.impl.NewPooledConnection@72add8
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.resourcepool.BasicResourcePool] Preparing to destroy resource: com.mchange.v2.c3p0.impl.NewPooledConnection@bf83ad
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] Preparing to destroy PooledConnection: com.mchange.v2.c3p0.impl.NewPooledConnection@bf83ad
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.c3p0.impl.C3P0PooledConnectionPool] Successfully destroyed PooledConnection: com.mchange.v2.c3p0.impl.NewPooledConnection@bf83ad. Currently open Connections: 0; Failed close count: 0; Total processed by this pool: 5
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.resourcepool.BasicResourcePool] Successfully destroyed resource: com.mchange.v2.c3p0.impl.NewPooledConnection@bf83ad
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.async.ThreadPoolAsynchronousRunner] Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#1,5,main] interrupted. Shutting down.
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.async.ThreadPoolAsynchronousRunner] Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#0,5,main] interrupted. Shutting down.
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.async.ThreadPoolAsynchronousRunner] Thread[com.mchange.v2.async.ThreadPoolAsynchronousRunner$PoolThread-#2,5,main] interrupted. Shutting down.
2006-Mar-08 23:31:22 - DEBUG [com.mchange.v2.c3p0.PoolBackedDataSource] com.mchange.v2.c3p0.PoolBackedDataSource@71d6fa has been closed.
java.lang.Exception: DEBUG STACK TRACE for PoolBackedDataSource.close().
at com.mchange.v2.c3p0.PoolBackedDataSource.close(PoolBackedDataSource.java:224)
at com.mchange.v2.c3p0.PoolBackedDataSource.close(PoolBackedDataSource.java:236)
at com.mchange.v2.c3p0.DataSources.destroy(DataSources.java:333)
at com.mchange.v2.c3p0.DataSources.destroy(DataSources.java:309)
at org.hibernate.connection.C3P0ConnectionProvider.close(C3P0ConnectionProvider.java:118)
at org.hibernate.impl.SessionFactoryImpl.close(SessionFactoryImpl.java:764)
at org.hibernate.ejb.EntityManagerFactoryImpl.close(EntityManagerFactoryImpl.java:36)
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:585)
at org.springframework.orm.jpa.LocalEntityManagerFactoryBean$TransactionAwareInvocationHandler.invoke(LocalEntityManagerFactoryBean.java:282)
at $Proxy23.close(Unknown Source)
at org.springframework.orm.jpa.LocalEntityManagerFactoryBean.destroy(LocalEntityManagerFactoryBean.java:233)
at org.springframework.beans.factory.support.AbstractBeanFactory$1.destroy(AbstractBeanFactory.java:971)
at org.springframework.beans.factory.support.AbstractBeanFactory.destroyBean(AbstractBeanFactory.java:1067)
at org.springframework.beans.factory.support.AbstractBeanFactory.destroyDisposableBean(AbstractBeanFactory.java:1039)
at org.springframework.beans.factory.support.AbstractBeanFactory.destroySingletons(AbstractBeanFactory.java:574)
at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:593)
at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:562)
at com.povosoftware.base.BaseApplication.dispose(BaseApplication.java:165)
at com.povosoftware.mailarchive.server.Application.main(Application.java:106)
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'downloadConfiguration1'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'mockAccountStan'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Invoking custom destroy method on bean with name 'mockAccountStan'
2006-Mar-08 23:31:22 - INFO [com.povosoftware.base.domain.mock.MailAccountImpl] dispose
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Invoking custom destroy method on bean with name 'downloadConfiguration1'
2006-Mar-08 23:31:22 - INFO [com.povosoftware.base.domain.mock.DownloadConfigurationImpl] dispose
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'mockAccountStan'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'downloadConfiguration2'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'mockAccountChiauly'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Invoking custom destroy method on bean with name 'mockAccountChiauly'
2006-Mar-08 23:31:22 - INFO [com.povosoftware.base.domain.mock.MailAccountImpl] dispose
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Invoking custom destroy method on bean with name 'downloadConfiguration2'
2006-Mar-08 23:31:22 - INFO [com.povosoftware.base.domain.mock.DownloadConfigurationImpl] dispose
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'mockAccountChiauly'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'downloadConfiguration3'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'mockAccountAdmin'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Invoking custom destroy method on bean with name 'mockAccountAdmin'
2006-Mar-08 23:31:22 - INFO [com.povosoftware.base.domain.mock.MailAccountImpl] dispose
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Invoking custom destroy method on bean with name 'downloadConfiguration3'
2006-Mar-08 23:31:22 - INFO [com.povosoftware.base.domain.mock.DownloadConfigurationImpl] dispose
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'mockAccountAdmin'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'downloadConfiguration4'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'mockAccountSpiro'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Invoking custom destroy method on bean with name 'mockAccountSpiro'
2006-Mar-08 23:31:22 - INFO [com.povosoftware.base.domain.mock.MailAccountImpl] dispose
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Invoking custom destroy method on bean with name 'downloadConfiguration4'
2006-Mar-08 23:31:22 - INFO [com.povosoftware.base.domain.mock.DownloadConfigurationImpl] dispose
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'mockAccountSpiro'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'archiveServiceTarget'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'archiveService'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Invoking custom destroy method on bean with name 'archiveServiceTarget'
2006-Mar-08 23:31:22 - INFO [com.povosoftware.mailarchive.server.service.ArchiveServiceImpl] dispose
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'archiveSetupServiceTarget'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Retrieving dependent beans for bean 'archiveSetupService'
2006-Mar-08 23:31:22 - DEBUG [org.springframework.beans.factory.support.DefaultListableBeanFactory] Invoking custom destroy method on bean with name 'archiveSetupServiceTarget'
2006-Mar-08 23:31:22 - INFO [com.povosoftware.mailarchive.server.service.ArchiveSetupServiceImpl] dispose
Process finished with exit code 0
##################
##################
##################
### Spring applicationContext.xml -- Hibernate EntityManager Definition
Code:
...
<!-- Hibernate EntityManager - EJB3 Configuration Beans -->
<bean id="entityManagerFactory"
class="org.springframework.orm.jpa.LocalEntityManagerFactoryBean">
<property name="entityManagerName" value="DefaultEntityManager" />
<!-- Overrides any other hibernate.properties -->
<property name="jpaProperties">
<props>
<prop key="hibernate.dialect">${db.dialect}</prop>
<prop key="hibernate.connection.driver_class">${db.driver}</prop>
<prop key="hibernate.connection.username">${db.user}</prop>
<prop key="hibernate.connection.password">${db.password}</prop>
<prop key="hibernate.connection.url">${db.url}</prop>
<prop key="hibernate.show_sql">${hibernate.show_sql}</prop>
<prop key="hibernate.format_sql">${hibernate.format_sql}</prop>
<!-- Use only w/ jdbc3 driver! -->
<prop key="hibernate.jdbc.use_get_generated_keys">${hibernate.jdbc.use_get_generated_keys}</prop>
<prop key="hibernate.cache.provider_class">${hibernate.cache.provider_class}</prop>
<prop key="hibernate.cache.use_query_cache">${hibernate.cache.use_query_cache}</prop>
<prop key="hibernate.cache.use_second_level_cache">${hibernate.cache.use_second_level_cache}</prop>
<prop key="hibernate.cache.region_prefix">${hibernate.cache.region_prefix}</prop>
<prop key="hibernate.cache.generate_statistics">${hibernate.cache.generate_statistics}</prop>
<!-- c3p0 DataSource config -->
<prop key="hibernate.c3p0.idle_test_period">${hibernate.c3p0.idle_test_period}</prop>
<prop key="hibernate.c3p0.acquire_increment">${hibernate.c3p0.acquire_increment}</prop>
<prop key="hibernate.c3p0.min_size">${hibernate.c3p0.min_size}</prop>
<prop key="hibernate.c3p0.max_size">${hibernate.c3p0.max_size}</prop>
<prop key="hibernate.c3p0.timeout">${hibernate.c3p0.timeout}</prop>
<prop key="hibernate.c3p0.max_statements">${hibernate.c3p0.max_statements}</prop>
<prop key="hibernate.c3p0.validate">${hibernate.c3p0.validate}</prop>
</props>
</property>
<property name="persistenceProviderClass">
<value>org.hibernate.ejb.HibernatePersistence</value>
</property>
</bean>
<bean id="transactionManager"
class="org.springframework.orm.jpa.JpaTransactionManager">
<property name="entityManagerFactory" ref="entityManagerFactory" />
</bean>
<bean id="transactionInterceptor"
class="org.springframework.transaction.interceptor.TransactionInterceptor">
<property name="transactionManager" ref="transactionManager" />
<property name="transactionAttributeSource">
<bean class="org.springframework.transaction.annotation.AnnotationTransactionAttributeSource" />
</property>
</bean>
...
##################
##################
##################
### Externalized Data Source, c3p0, and Hibernate properties
###
###
### HSQLDB properties
###
###
db.url=jdbc:hsqldb:hsql://localhost:9001/povodb
db.driver=org.hsqldb.jdbcDriver
db.user=*****
db.password=*******
db.dialect=org.hibernate.dialect.HSQLDialect
###
###
### hibernate properties
###
###
hibernate.show_sql=true
hibernate.format_sql=true
hibernate.cache.provider_class=org.hibernate.cache.EhCacheProvider
hibernate.cache.use_query_cache=true
hibernate.cache.use_second_level_cache=true
hibernate.cache.region_prefix=mailarchive
hibernate.cache.generate_statistics=true
###
###
### c3p0 /hibernate data-source properties
###
###
hibernate.c3p0.idle_test_period=100
hibernate.c3p0.acquire_increment=1
hibernate.c3p0.min_size=5
hibernate.c3p0.max_size=25
hibernate.c3p0.timeout=100
hibernate.c3p0.max_statements=50
hibernate.c3p0.validate=true
# Not really hibernate.c3p0 props, but use naming convention for dataSource bean config.
hibernate.c3p0.acquire_retry_attempts=3
##################
##################
##################