We are trying to implement connection pooling using c3p0. The issue is when there are no transactions on our server for long time, the very first next transaction have connection timeout issue.
Exception stacktrace:
Could not open JPA EntityManager for transaction; nested exception is javax.persistence.Pers
istenceException: org.hibernate.TransactionException: JDBC begin transaction failed:
org.springframework.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transacti
on; nested exception is javax.persistence.PersistenceException: org.hibernate.TransactionException: JDBC begin t
ransaction failed:
at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:431)
at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPla
tformTransactionManager.java:373)
at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(Tra
nsactionAspectSupport.java:427)
at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(Transact
ionAspectSupport.java:276)
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:207)
at com.sun.proxy.$Proxy559.getMerchantById(Unknown Source)
at com.ag.controller.MerchantController.getMerchantById(MerchantController.java:1111)
at com.ag.controller.MerchantController.checkoutMerchant(MerchantController.java:226)
at sun.reflect.GeneratedMethodAccessor1766.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:22
1)
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod
.java:137)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(S
ervletInvocableHandlerMethod.java:111)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMetho
d(RequestMappingHandlerAdapter.java:806)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(Req
uestMappingHandlerAdapter.java:729)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodA
dapter.java:85)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:959)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:893)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:648)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:292)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:
85)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
at com.ag.configuration.XSSFilter.doFilter(XSSFilter.java:27)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:212)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:106)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:502)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:141)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:616)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:88)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:522)
at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1095)
at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:672)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
Caused by: javax.persistence.PersistenceException: org.hibernate.TransactionException: JDBC begin transaction fa
iled:
at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1763)
at org.hibernate.jpa.spi.AbstractEntityManagerImpl.convert(AbstractEntityManagerImpl.java:1677)
at org.hibernate.jpa.spi.AbstractEntityManagerImpl.throwPersistenceException(AbstractEntityManagerImpl.j
ava:1771)
at org.hibernate.jpa.internal.TransactionImpl.begin(TransactionImpl.java:64)
at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:166)
at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:380)
... 53 more
Caused by: org.hibernate.TransactionException: JDBC begin transaction failed:
at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:76)
at org.hibernate.engine.transaction.spi.AbstractTransactionImpl.begin(AbstractTransactionImpl.java:162)
at org.hibernate.internal.SessionImpl.beginTransaction(SessionImpl.java:1435)
at org.hibernate.jpa.internal.TransactionImpl.begin(TransactionImpl.java:61)
... 55 more
Caused by: com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: The last packet successfully received from t
he server was 54,078,423 milliseconds ago. The last packet sent successfully to the server was 54,078,423 milli
seconds ago. is longer than the server configured value of 'wait_timeout'. You should consider either expiring a
nd/or testing connection validity before use in your application, increasing the server configured values for cl
ient timeouts, or using the Connector/J connection property 'autoReconnect=true' to avoid this problem.
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at com.mysql.jdbc.Util.handleNewInstance(Util.java:400)
at com.mysql.jdbc.SQLError.createCommunicationsException(SQLError.java:1038)
at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3621)
at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:2429)
at com.mysql.jdbc.MysqlIO.sqlQueryDirect(MysqlIO.java:2594)
at com.mysql.jdbc.ConnectionImpl.execSQL(ConnectionImpl.java:2541)
at com.mysql.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:4882)
at com.mchange.v2.c3p0.impl.NewProxyConnection.setAutoCommit(NewProxyConnection.java:912)
at org.hibernate.engine.transaction.internal.jdbc.JdbcTransaction.doBegin(JdbcTransaction.java:72)
... 58 more
Caused by: java.net.SocketException: Connection timed out
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:109)
at java.net.SocketOutputStream.write(SocketOutputStream.java:153)
at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
at com.mysql.jdbc.MysqlIO.send(MysqlIO.java:3603)
... 64 more
DataSource Configuration:
@Primary
@Bean
public DataSource agDataSource() {
ComboPooledDataSource dataSource = new ComboPooledDataSource();
try {
dataSource.setDriverClass(Preconditions.checkNotNull(environment.getRequiredProperty("hibernate.connection.driver_class")));
} catch (IllegalStateException | PropertyVetoException e) {
e.printStackTrace();
}
dataSource.setJdbcUrl(Preconditions.checkNotNull(environment.getRequiredProperty("hibernate.connection.url")));
dataSource.setUser(Preconditions.checkNotNull(environment.getRequiredProperty("hibernate.connection.username")));
dataSource.setPassword(Preconditions.checkNotNull("hibernate.connection.password"));
}
@Primary
@Bean(name="agEntityManagerFactory")
public LocalContainerEntityManagerFactoryBean agEntityManagerFactory() throws ClassNotFoundException {
final LocalContainerEntityManagerFactoryBean entityManagerFactoryBean = new LocalContainerEntityManagerFactoryBean();
entityManagerFactoryBean.setDataSource(agDataSource());
entityManagerFactoryBean.setPackagesToScan(new String[] { "com.ag.entities" });
entityManagerFactoryBean.setPersistenceProviderClass(HibernatePersistenceProvider.class);
final HibernateJpaVendorAdapter vendorAdapter = new HibernateJpaVendorAdapter();
vendorAdapter.setShowSql(true);
entityManagerFactoryBean.setJpaVendorAdapter(vendorAdapter);
//entityManagerFactoryBean.setJpaVendorAdapter(vendorAdapter);
entityManagerFactoryBean.setJpaProperties(hibernateProperties());
entityManagerFactoryBean.afterPropertiesSet();
entityManagerFactoryBean.setLoadTimeWeaver(new InstrumentationLoadTimeWeaver());
return entityManagerFactoryBean;
}
@Primary
@Bean(name = "agTransactionManager")
public PlatformTransactionManager agTransactionManager() {
final JpaTransactionManager transactionManager = new JpaTransactionManager();
try {
transactionManager.setEntityManagerFactory(agEntityManagerFactory().getObject());
transactionManager.setDataSource(agDataSource());
transactionManager.setJpaDialect(new HibernateJpaDialect());
//transactionManager.setNestedTransactionAllowed(true);
} catch (ClassNotFoundException e) {
e.printStackTrace();
}
return transactionManager;
}
I am able to solve the issue by setting the connection pooling properties on datasource object itself. I think the hibernate properties are not able to reflect the pooling setting. I am able to replicate the issue on dev environment by setting wait_timeout=60, interactive_timeout=60 ( i.e. 1 min) in my.ini file of mysql. Then After server started I tried first transaction, waited for 1 min, then tried the txn which failed. Then I enabled the query log(by setting two more properties in my.ini:
general_log = 1
general_log_file = "C:/xampp/mysql/data/mysql.log"
I enabled above settings to check whether my select 1 validation query is getting executed or not.I tried the pooling setting on datasource object itself it starts working. The query log was also showing the selec 1 execution every hibernate.c3p0.idle_test_period seconds.
@Primary
@Bean
public DataSource agDataSource() {
ComboPooledDataSource dataSource = new ComboPooledDataSource();
try {
dataSource.setDriverClass(environment.getRequiredProperty("hibernate.connection.driver_class"));
} catch (IllegalStateException | PropertyVetoException e) {
e.printStackTrace();
}
dataSource.setJdbcUrl(environment.getRequiredProperty("hibernate.connection.url"));
dataSource.setUser(environment.getRequiredProperty("hibernate.connection.username"));
dataSource.setPassword(environment.getRequiredProperty("hibernate.connection.password"));
dataSource.setMaxPoolSize(Integer.parseInt(environment.getRequiredProperty("hibernate.c3p0.max_size")));
dataSource.setMinPoolSize(Integer.parseInt(environment.getRequiredProperty("hibernate.c3p0.min_size")));
dataSource.setMaxIdleTime(Integer.parseInt(environment.getRequiredProperty("hibernate.c3p0.timeout")));
dataSource.setMaxStatements(Integer.parseInt(environment.getRequiredProperty("hibernate.c3p0.max_statements")));
dataSource.setIdleConnectionTestPeriod(Integer.parseInt(environment.getRequiredProperty("hibernate.c3p0.idle_test_period")));
dataSource.setAcquireIncrement(Integer.parseInt(environment.getRequiredProperty("hibernate.c3p0.acquire_increment")));
dataSource.setPreferredTestQuery(environment.getRequiredProperty("hibernate.c3p0.preferredTestQuery"));
dataSource.setTestConnectionOnCheckin(true);
dataSource.setTestConnectionOnCheckout(true);
return dataSource;
}
now it works fine. happy. I posted the answer and the steps i did to validate my setting so that it may help somebody else.