spring JPA with c3p0 is having connection timeout on first request

Question

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;
        }

Cowles

Configure connection checking while being idle (see #30451970 for more information, that is for spring boot but gives you an overview of what to configure). I would also suggest using another connection pool, like HikariCP instead of C3P0. Also you are aware that your Preconditions.checkNotNull are redundant? That is the whole point of using getRequiredProperty. Also you shouldn't be calling afterPropertiesSet in your code. Spring will do that for you. – Aldosterone

@M.Deinum Thanks for your suggestion. I will definitely do the correction in my code. I am able to replicate the same issue on dev machine by setting the some connection properties of mysql connection. – Cowles

Answer 1

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.

Cowles