0

I had this problem and it happened to lose the connection to database after a day. After some research, I added these properties (I understood that Spring Boot uses HikariPool as default datasource).

spring.datasource.hikari.username=***
spring.datasource.hikari.password=***
spring.datasource.hikari.connection-timeout=3000
spring.datasource.hikari.auto-commit=true
spring.datasource.hikari.connection-init-sql=SELECT 1
spring.datasource.hikari.connection-test-query=SELECT 1
spring.datasource.hikari.idle-timeout=600000
spring.datasource.hikari.max-lifetime=1800000
spring.datasource.hikari.validation-timeout=5000
spring.datasource.hikari.maximum-pool-size=10
spring.datasource.hikari.leak-detection-threshold=45000
spring.datasource.platform=mysql
spring.jpa.hibernate.ddl-auto=update
spring.datasource.hikari.data-source-properties.cachePrepStmts=true
spring.datasource.hikari.data-source-properties.useServerPrepStmts=true

Running show processlist on MySQL gives 10 sleeping processes created by my application.

This is the error I'm getting from Spring Boot

    Feb 01 09:46:21 movxx java[7550]: 2021-02-01 09:46:21.107  INFO 7550 --- [MessageBroker-1] o.s.w.s.c.WebSocketMessageBrokerStats    : WebSocketSession[0 current WS(0)-HttpStream(0)-HttpPoll(0), 69 total, 0 closed abnormally (0 connect failure, 0 send limit, 10 transport error)], stompSubProtocol[processed CONNECT(36)-CONNECTED(36)-DISCONNECT(0)], stompBrokerRelay[null], inboundChannel[pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 639], outboundChannel[pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 108], sockJsScheduler[pool size = 1, active threads = 1, queued tasks = 2, completed tasks = 96783]
    Feb 01 10:16:21 movxx java[7550]: 2021-02-01 10:16:21.108  INFO 7550 --- [MessageBroker-1] o.s.w.s.c.WebSocketMessageBrokerStats    : WebSocketSession[0 current WS(0)-HttpStream(0)-HttpPoll(0), 69 total, 0 closed abnormally (0 connect failure, 0 send limit, 10 transport error)], stompSubProtocol[processed CONNECT(36)-CONNECTED(36)-DISCONNECT(0)], stompBrokerRelay[null], inboundChannel[pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 639], outboundChannel[pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 108], sockJsScheduler[pool size = 1, active threads = 1, queued tasks = 2, completed tasks = 97144]
    Feb 01 10:46:21 movxx java[7550]: 2021-02-01 10:46:21.109  INFO 7550 --- [MessageBroker-1] o.s.w.s.c.WebSocketMessageBrokerStats    : WebSocketSession[0 current WS(0)-HttpStream(0)-HttpPoll(0), 69 total, 0 closed abnormally (0 connect failure, 0 send limit, 10 transport error)], stompSubProtocol[processed CONNECT(36)-CONNECTED(36)-DISCONNECT(0)], stompBrokerRelay[null], inboundChannel[pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 639], outboundChannel[pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 108], sockJsScheduler[pool size = 1, active threads = 1, queued tasks = 2, completed tasks = 97505]
    Feb 01 11:16:21 movxx java[7550]: 2021-02-01 11:16:21.111  INFO 7550 --- [MessageBroker-1] o.s.w.s.c.WebSocketMessageBrokerStats    : WebSocketSession[0 current WS(0)-HttpStream(0)-HttpPoll(0), 69 total, 0 closed abnormally (0 connect failure, 0 send limit, 10 transport error)], stompSubProtocol[processed CONNECT(36)-CONNECTED(36)-DISCONNECT(0)], stompBrokerRelay[null], inboundChannel[pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 639], outboundChannel[pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 108], sockJsScheduler[pool size = 1, active threads = 1, queued tasks = 2, completed tasks = 97866]
    
Feb 01 11:24:19 movxx java[7550]: 2021-02-01 11:24:19.090  WARN 7550 --- [io-5000-exec-10] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: 08001
Feb 01 11:24:19 movxx java[7550]: 2021-02-01 11:24:19.091 ERROR 7550 --- [io-5000-exec-10] 

o.h.engine.jdbc.spi.SqlExceptionHelper   : HikariPool-1 - Connection is not available, request timed out after 3000ms.
    Feb 01 11:24:19 movxx java[7550]: 2021-02-01 11:24:19.091 ERROR 7550 --- [io-5000-exec-10] o.h.engine.jdbc.spi.SqlExceptionHelper   : Could not create connection to database server. Attempted reconnect 3 times. Giving up.
    Feb 01 11:24:19 movxx java[7550]: 2021-02-01 11:24:19.091  WARN 7550 --- [nio-5000-exec-7] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: 08001
    Feb 01 11:24:19 movxx java[7550]: 2021-02-01 11:24:19.092 ERROR 7550 --- [nio-5000-exec-7] o.h.engine.jdbc.spi.SqlExceptionHelper   : HikariPool-1 - Connection is not available, request timed out after 3001ms.
    Feb 01 11:24:19 movxx java[7550]: 2021-02-01 11:24:19.092 ERROR 7550 --- [nio-5000-exec-7] o.h.engine.jdbc.spi.SqlExceptionHelper   : Could not create connection to database server. Attempted reconnect 3 times. Giving up.
    Feb 01 11:24:19 movxx java[7550]: 2021-02-01 11:24:19.091  WARN 7550 --- [nio-5000-exec-4] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: 08001
    Feb 01 11:24:19 movxx java[7550]: 2021-02-01 11:24:19.093 ERROR 7550 --- [nio-5000-exec-4] o.h.engine.jdbc.spi.SqlExceptionHelper   : HikariPool-1 - Connection is not available, request timed out after 3000ms.
    Feb 01 11:24:19 movxx java[7550]: 2021-02-01 11:24:19.094 ERROR 7550 --- [nio-5000-exec-4] o.h.engine.jdbc.spi.SqlExceptionHelper   : Could not create connection to database server. Attempted reconnect 3 times. Giving up.
    Feb 01 11:24:19 movxx java[7550]: 2021-02-01 11:24:19.091  WARN 7550 --- [nio-5000-exec-5] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: 08001
    Feb 01 11:24:19 movxx java[7550]: 2021-02-01 11:24:19.095 ERROR 7550 --- [nio-5000-exec-5] o.h.engine.jdbc.spi.SqlExceptionHelper   : HikariPool-1 - Connection is not available, request timed out after 3000ms.
    Feb 01 11:24:19 movxx java[7550]: 2021-02-01 11:24:19.095 ERROR 7550 --- [nio-5000-exec-5] o.h.engine.jdbc.spi.SqlExceptionHelper   : Could not create connection to database server. Attempted reconnect 3 times. Giving up.
    Feb 01 11:24:19 movxx java[7550]: 2021-02-01 11:24:19.173 ERROR 7550 --- [nio-5000-exec-5] c.p.S.security.jwt.AuthTokenFilter       : Cannot set user authentication: {}
    Feb 01 11:24:19 movxx java[7550]: org.springframework.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transaction; nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection
    Feb 01 11:24:19 movxx java[7550]:         at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:448) ~[spring-orm-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]

However, the strange this is if I kill one of these processes, the backend reconnects and everything works fine.

The backend/frontend was not used in that period (or I connected 2-3 times to see if it's still working), but no high traffic or load on database.

I have no idea what to try to do next.

Backend: Spring Boot Database: MySQL

Edit: Could this be because of MySQL wait_timeout, as it has the default value (8h)? Would It be better to set it to one minute more than max-lifetime of hikari?

Edit2: Changed the database wait_timeout to 31 minutes, and so far the connection is still alive. Could this be the problem?

Another update: The backend seemed unresponsive for 1 hour (I don't understand how, maybe I had problems with my internet connection) and the logs show nothing. The problem solved by itself.

However, I found this error that appeared 1h before the connectivity issues, I had a method to delete some entries from the database at 1AM.

Feb 07 00:59:09 movxx java[133298]: 2021-02-07 00:59:09.832 DEBUG 133298 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)
Feb 07 00:59:09 movxx java[133298]: 2021-02-07 00:59:09.844 DEBUG 133298 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Fill pool skipped, pool is at sufficient level.
Feb 07 00:59:39 movxx java[133298]: 2021-02-07 00:59:39.871 DEBUG 133298 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)
Feb 07 00:59:40 movxx java[133298]: 2021-02-07 00:59:39.885 DEBUG 133298 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Fill pool skipped, pool is at sufficient level.
Feb 07 01:00:02 movxx java[133298]: 2021-02-07 01:00:02.829 ERROR 133298 --- [MessageBroker-1] o.s.s.s.TaskUtils$LoggingErrorHandler    : Unexpected error occurred in scheduled task
Feb 07 01:00:02 movxx java[133298]: org.springframework.dao.InvalidDataAccessApiUsageException: No EntityManager with actual transaction available for current thread - cannot reliably process 'remove' call; nested exception is javax.persistence.TransactionRequiredException: No EntityManager with actual transaction available for current thread - cannot reliably process 'remove' call
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.orm.jpa.EntityManagerFactoryUtils.convertJpaAccessExceptionIfPossible(EntityManagerFactoryUtils.java:403) ~[spring-orm-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.orm.jpa.vendor.HibernateJpaDialect.translateExceptionIfPossible(HibernateJpaDialect.java:257) ~[spring-orm-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.orm.jpa.AbstractEntityManagerFactoryBean.translateExceptionIfPossible(AbstractEntityManagerFactoryBean.java:528) ~[spring-orm-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.dao.support.ChainedPersistenceExceptionTranslator.translateExceptionIfPossible(ChainedPersistenceExceptionTranslator.java:61) ~[spring-tx-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.dao.support.DataAccessUtils.translateIfNecessary(DataAccessUtils.java:242) ~[spring-tx-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:153) ~[spring-tx-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:149) ~[spring-data-jpa-2.3.0.RELEASE.jar!/:2.3.0.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:95) ~[spring-aop-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) ~[spring-aop-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at com.sun.proxy.$Proxy178.deleteAllByDateBefore(Unknown Source) ~[na:na]
Feb 07 01:00:02 movxx java[133298]:         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
Feb 07 01:00:02 movxx java[133298]:         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]
Feb 07 01:00:02 movxx java[133298]:         at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
Feb 07 01:00:02 movxx java[133298]:         at java.base/java.lang.reflect.Method.invoke(Method.java:564) ~[na:na]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344) ~[spring-aop-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:205) ~[spring-aop-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at com.sun.proxy.$Proxy142.deleteAllByDateBefore(Unknown Source) ~[na:na]
Feb 07 01:00:02 movxx java[133298]:         at com.project.SpringREST.security.ScheduleDeletions.deleteOldNotifications(ScheduleDeletions.java:25) ~[classes!/:0.0.1-SNAPSHOT]
Feb 07 01:00:02 movxx java[133298]:         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
Feb 07 01:00:02 movxx java[133298]:         at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]
Feb 07 01:00:02 movxx java[133298]:         at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
Feb 07 01:00:02 movxx java[133298]:         at java.base/java.lang.reflect.Method.invoke(Method.java:564) ~[na:na]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.scheduling.support.ScheduledMethodRunnable.run(ScheduledMethodRunnable.java:84) ~[spring-context-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:93) ~[spring-context-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) ~[na:na]
Feb 07 01:00:02 movxx java[133298]:         at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[na:na]
Feb 07 01:00:02 movxx java[133298]:         at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[na:na]
Feb 07 01:00:02 movxx java[133298]:         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) ~[na:na]
Feb 07 01:00:02 movxx java[133298]:         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) ~[na:na]
Feb 07 01:00:02 movxx java[133298]:         at java.base/java.lang.Thread.run(Thread.java:832) ~[na:na]
Feb 07 01:00:02 movxx java[133298]: Caused by: javax.persistence.TransactionRequiredException: No EntityManager with actual transaction available for current thread - cannot reliably process 'remove' call
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.orm.jpa.SharedEntityManagerCreator$SharedEntityManagerInvocationHandler.invoke(SharedEntityManagerCreator.java:298) ~[spring-orm-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at com.sun.proxy.$Proxy130.remove(Unknown Source) ~[na:na]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.data.jpa.repository.query.JpaQueryExecution$DeleteExecution.doExecute(JpaQueryExecution.java:274) ~[spring-data-jpa-2.3.0.RELEASE.jar!/:2.3.0.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.data.jpa.repository.query.JpaQueryExecution.execute(JpaQueryExecution.java:88) ~[spring-data-jpa-2.3.0.RELEASE.jar!/:2.3.0.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.data.jpa.repository.query.AbstractJpaQuery.doExecute(AbstractJpaQuery.java:154) ~[spring-data-jpa-2.3.0.RELEASE.jar!/:2.3.0.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.data.jpa.repository.query.AbstractJpaQuery.execute(AbstractJpaQuery.java:142) ~[spring-data-jpa-2.3.0.RELEASE.jar!/:2.3.0.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor$QueryMethodInvoker.invoke(QueryExecutorMethodInterceptor.java:195) ~[spring-data-commons-2.3.0.RELEASE.jar!/:2.3.0.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.doInvoke(QueryExecutorMethodInterceptor.java:152) ~[spring-data-commons-2.3.0.RELEASE.jar!/:2.3.0.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.data.repository.core.support.QueryExecutorMethodInterceptor.invoke(QueryExecutorMethodInterceptor.java:130) ~[spring-data-commons-2.3.0.RELEASE.jar!/:2.3.0.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.data.projection.DefaultMethodInvokingMethodInterceptor.invoke(DefaultMethodInvokingMethodInterceptor.java:80) ~[spring-data-commons-2.3.0.RELEASE.jar!/:2.3.0.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:366) ~[spring-tx-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:118) ~[spring-tx-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:139) ~[spring-tx-5.2.6.RELEASE.jar!/:5.2.6.RELEASE]
Feb 07 01:00:02 movxx java[133298]:         ... 28 common frames omitted

.... HikariPool logs..


Feb 07 01:17:48 movxx java[133298]: 2021-02-07 01:17:45.800 ERROR 133298 --- [nio-5000-exec-9] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.web.socket.sockjs.SockJsException: Uncaught failure in SockJS request, uri=http://www.moviark.com/notifications/277/mhyg3p2g/xhr_streaming?t=1612660664363; nested exception is org.springframework.web.socket.sockjs.SockJsTransportFailureException: Failed to open session; nested exception is org.springframework.web.socket.sockjs.SockJsTransportFailureException: Failed to write SockJsFrame content='o'; nested exception is org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe] with root cause
Feb 07 01:17:48 movxx java[133298]: java.io.IOException: Broken pipe
Feb 07 01:17:48 movxx java[133298]:         at java.base/sun.nio.ch.FileDispatcherImpl.write0(Native Method) ~[na:na]
Feb 07 01:17:48 movxx java[133298]:         at java.base/sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:62) ~[na:na]
Feb 07 01:17:48 movxx java[133298]:         at java.base/sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:113) ~[na:na]
Feb 07 01:17:48 movxx java[133298]:         at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:79) ~[na:na]
Feb 07 01:17:48 movxx java[133298]:         at java.base/sun.nio.ch.IOUtil.write(IOUtil.java:50) ~[na:na]
Feb 07 01:17:48 movxx java[133298]:         at java.base/sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:484) ~[na:na]

Edit3: MySQL is not connected via SSL with the backend, so no more Public Key retrieval error (safest option), but now I am getting this error, at random times, and the backend restarts and the problem disappears. Could this be because of high load of CPU / Low RAM memory?

Feb 09 20:57:28 movxx java[24771]: 2021-02-09 20:57:27.647 DEBUG 24771 --- [io-5000-exec-12] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Timeout failure stats (total=10, active=10, idle=0, waiting=0)                           
Feb 09 20:57:29 movxx java[24771]: 2021-02-09 20:57:29.815 DEBUG 24771 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Pool stats (total=10, active=10, idle=0, waiting=0)                                      
Feb 09 20:57:29 movxx java[24771]: 2021-02-09 20:57:29.822 DEBUG 24771 --- [l-1 housekeeper] com.zaxxer.hikari.pool.HikariPool        : HikariPool-1 - Fill pool skipped, pool is at sufficient level.                                          
Feb 09 20:57:31 movxx java[24771]: 2021-02-09 20:57:31.533  WARN 24771 --- [io-5000-exec-12] o.h.engine.jdbc.spi.SqlExceptionHelper   : SQL Error: 0, SQLState: null                                                                            
Feb 09 20:57:31 movxx java[24771]: 2021-02-09 20:57:31.565 ERROR 24771 --- [io-5000-exec-12] o.h.engine.jdbc.spi.SqlExceptionHelper   : HikariPool-1 - Connection is not available, request timed out after 5956ms.                                                                                                     
Feb 09 20:57:34 movxx java[24771]: 2021-02-09 20:57:34.605 ERROR 24771 --- [io-5000-exec-12] c.p.S.security.jwt.AuthTokenFilter       : Cannot set user authentication: {}    
Feb 09 20:57:34 movxx java[24771]: org.springframework.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transaction; 
nested exception is org.hibernate.exception.JDBCConnectionException: Unable to acquire JDBC Connection

This is what ScheduleDeletions look like

@Configuration
@EnableAsync
@EnableScheduling
public class ScheduleDeletions {
    @Autowired
    NotificationsRepository notificationsRepository;

    @Scheduled(cron = "0 0 1 * * ?")
    public void deleteOldNotifications() {
        final Calendar cal = Calendar.getInstance();
        cal.setTimeInMillis(new Date().getTime());
        cal.add(Calendar.DATE, -7);
        notificationsRepository.deleteAllByDateBefore(cal.getTime());
    }

}
Kannon
  • 81
  • 3
  • 10

2 Answers2

1

Since following error appears in error log

com.mysql.cj.exceptions.UnableToConnectException: Public Key Retrieval is not allowed

you should try adding allowPublicKeyRetrieval=true to your JDBC connection string. Something like this:

jdbc:mysql://HOST:PORT/DBNAME?allowPublicKeyRetrieval=true

More details here https://community.atlassian.com/t5/Confluence-questions/MySQL-Public-Key-Retrieval-is-not-allowed/qaq-p/778956

Nikolai Shevchenko
  • 7,083
  • 8
  • 33
  • 42
  • Hello, I changed that section, but it is not advised to use it, as it is not secure. I am now using SSL for the database connection, but after some time I get another error: "SQL Error: 0, SQLState: null". I really have no ideea what to do anymore as this problem doesn't seem to dissapear. It restarts by itself, and the database is live again, but this is not really a solution because there is a problem causing that. – Kannon Feb 09 '21 at 21:02
  • @Kannon ok... maybe there is an issue with your code? Probably db connection leaks, that are hard to detect. If it's possible attach some code samples to your Question. At least the section related to scheduled invocation (`com.project.SpringREST.security.ScheduleDeletions.deleteOldNotifications`) – Nikolai Shevchenko Feb 10 '21 at 05:06
  • Thank you for your response! I edited my question and added that method. – Kannon Feb 10 '21 at 11:05
0

I solved the problem.

For the public key retrieval, I chose to use SSL for the database connection, and I followed this tutorial

Now on the main failure, I was because of ScheduledDeletions class. I solved the problem with 3 steps. I will add numbers to the code to explain it after [like this].

@Configuration
@EnableAsync
@EnableScheduling
@EnableTransactionManagement [1]
public class ScheduleDeletions {

    @Autowired
    NotificationsRepository notificationsRepository;

    @Scheduled(cron = "0 0 0 * * ?")
    @Transactional [2]
    public void deleteOldNotifications() {
        System.out.println("Running scheduled deletion: " + notificationsRepository.count());
        final Calendar cal = Calendar.getInstance();
        cal.setTimeInMillis(new Date().getTime());
        cal.add(Calendar.DAY_OF_MONTH, -7); [3]
        notificationsRepository.deleteAllByDateBefore(cal.getTime());
        System.out.println("Run successful on scheduled deletion: " + notificationsRepository.count());
    }
}

So (1) is optional, as It is enabled by default. Number (2) was necessary, because, in case of errors, it will revert the changes to the database. This post helped me a lot on this

(3) was strange, as I wanted to delete notifications older than 7 days, changing from Calendar.DATE to Calendar.DAY_OF_MONTH helped me to get rid of errors.

Just an advice for everyone who is at his first big project (as this is my first big project and I am learning from it). Even if your code is working on your local machine, you have no idea what behavior it will have on another machine, running for 5-6 days. Get a host and let it run, enable the loggers and if you are using Spring Boot, enable Garbage Collector logs, it will save your life.

Kannon
  • 81
  • 3
  • 10