Spring-Retry doesn't get a new database connection from HikariCP

Question

I know that spring-retry doesn't grab database connections.

We've wrapped a REST endpoint with @Retryable in an attempt to enact retry functionality but its not quite working as expected. I had anticipated that when a SQLException is thrown due to a com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure that the next attempt would grab a new connection from the pool. I'm facing an issue whereby if we take down the MySQL database part way through processing, spring-retry retries the method call, but does not get a new database connection. As a result all retries fail but new requests to the REST endpoint work successfully. Is there a way I can force a new connection from the datasource.?

I know that Spring-retry knows nothing about the code being run, but I'm bewildered why the connection, having just thrown an exception, isn't ditched and a new one pulled from the pool given the datasource configuration. (Its a simple Spring datasource)

I appreciate that Spring-retry and HikariCP are separate things but I had envisioned that if the database failed for some reason, the Spring-retry would allow us to re-attempt the same processing?

Versions

Mysql connector version: 8.0.18  
HikariCP version: 3.4.5  
SpringBoot version: 2.1.9.RELEASE

application.yml

spring:
  main: 
    allow-bean-definition-overriding: true
  jpa:
    database-platform: org.hibernate.dialect.MySQL5Dialect   
    hibernate:
      use-new-id-generator-mappings: false 
  boot:
    admin:
      url: http://127.0.0.1:8022
      username: admin
      password: *****
      client:
        name: ${spring.application.name}
  application:
    name: Usage Aggregation
  datasource:
    type: com.zaxxer.hikari.HikariDataSource
    url: jdbc:mysql://localhost:3308/db?createDatabaseIfNotExist=false&autoReconnect=true&autoReconnectForPools=true&socketTimeout=5000&connectTimeout=1000&useSSL=false
    hikari:
      jdbcUrl: jdbc:mysql://localhost:3308/db?createDatabaseIfNotExist=false&autoReconnect=true&autoReconnectForPools=true&socketTimeout=5000&connectTimeout=1000&useSSL=false
      username: root
      password: ****
      register-mbeans: true
      connectionInitSql: SELECT 1 FROM DUAL
      connectionTestQuery: SELECT 1 FROM DUAL
      socketTimeout: 3000
      validationTimeout: 500
      maximumPoolSize: 5
      idleTimeout: 3000
      poolName: SpringBootJPAHikariCP
      maxLifetime: 60000
      connectionTimeout: 1000

Controller

    @Retryable(exclude = {IllegalStateException.class},
    maxAttemptsExpression = 3,
    backoff = @Backoff(
        delayExpression = 30000,
        maxDelayExpression = 2,
        multiplierExpression = 500000
    ))
@RequestMapping("usageData/load/")
public void usageDataFromSource() {
    log.info("Running usage data live service end point for: usageData");
    //Sets status of aggregation disabled to false.
    aggregationService.updateAggregationDisabledFlag("usageData", false);

    usageService.copyUsageDataFromSourceToDestination();

}

Logs:

[2020-12-11 16:03:00,933] [http-nio-8095-exec-1] INFO u.b.c.RestController [] -    Running usage data live service end point for: usageData
[2020-12-11 16:03:09,099] [http-nio-8095-exec-1] DEBUG o.s.retry.support.RetryTemplate [] -    Retry: count=0
[2020-12-11 16:03:09,099] [http-nio-8095-exec-1] INFO u.b.config.RetryableDataSource [] -    ***************************** Getting a new Database connection *****************************
[2020-12-11 16:03:09,811] [http-nio-8095-exec-1] INFO u.b.service.UsageDataServiceImpl [] -    aggregation switch is false
[2020-12-11 16:03:19,906] [http-nio-8095-exec-1] ERROR u.b.service.UsageDataServiceImpl [] -    No usage data file available to process. Setting aggregationDisabled flag to true.

The database has already queried for the state of a flag at this point, showing the database connection is working. The database is stopped at this point in order to simulate a database failure in order to test the fail/retry/recover scenario.

 [2020-12-11 16:03:19,929] [http-nio-8095-exec-1] WARN c.zaxxer.hikari.pool.ProxyConnection [] -    SpringBootJPAHikariCP - Connection com.mysql.cj.jdbc.ConnectionImpl@184c1740 marked as broken because of SQLSTATE(08S01), ErrorCode(0) 
com.mysql.cj.jdbc.exceptions.CommunicationsException: Communications link failure  

The last packet successfully received from the server was 10,738 milliseconds ago. The last packet sent successfully to the server was 10,738 milliseconds ago.  
    at com.mysql.cj.jdbc.exceptions.SQLError.createCommunicationsException(SQLError.java:174)  
    at com.mysql.cj.jdbc.exceptions.SQLExceptionsMapping.translateException(SQLExceptionsMapping.java:64)  
    at com.mysql.cj.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:2056)  
    at com.zaxxer.hikari.pool.ProxyConnection.setAutoCommit(ProxyConnection.java:414)  
    at com.zaxxer.hikari.pool.HikariProxyConnection.setAutoCommit(HikariProxyConnection.java)  
    at org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor.begin(AbstractLogicalConnectionImplementor.java:67)  
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:263)  
    at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:236)  
    at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:86)  
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:184)   
    at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:402)  
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:378)  
    at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:475)  
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:289)  
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:98)  
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)  
    at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:139)  
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)  
    at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:144)  
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)  
    at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$ExposeRepositoryInvocationInterceptor.invoke(CrudMethodMetadataPostProcessor.java:364)  
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)  
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93)  
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)  
    at org.springframework.data.repository.core.support.SurroundingTransactionDetectorMethodInterceptor.invoke(SurroundingTransactionDetectorMethodInterceptor.java:61)  
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)  
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)  
    at com.sun.proxy.$Proxy133.updateAggregationDisabledFlag(Unknown Source)  
    at uk.bobbins.service.AggregationServiceImpl.updateAggregationDisabledFlag(AggregationServiceImpl.java:457)  
    at uk.bobbins.service.UsageDataServiceImpl.copyUsageDataFromSourceToDestination(UsageDataServiceImpl.java:94)  
    at uk.bobbins.UsageServiceImpl.copyUsageDataFromSourceToDestination(UsageServiceImpl.java:94)  
    at uk.bobbins.controller.RestController.UsageDataFromSource(RestController.java:152)  
    at uk.bobbins.controller.RestController$$FastClassBySpringCGLIB$$ae255ac.invoke(<generated>)  
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)  
    ...
    
    ...  
    at java.lang.Thread.run(Thread.java:748)  
Caused by: com.mysql.cj.exceptions.CJCommunicationsException: Communications link failure

The last packet successfully received from the server was 10,738 milliseconds ago. The last packet sent successfully to the server was 10,738 milliseconds ago.
    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.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:61)  
    at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:105)  
    at com.mysql.cj.exceptions.ExceptionFactory.createException(ExceptionFactory.java:151)  
    at com.mysql.cj.exceptions.ExceptionFactory.createCommunicationsException(ExceptionFactory.java:167)  
    at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:539)  
    at com.mysql.cj.protocol.a.NativeProtocol.checkErrorMessage(NativeProtocol.java:703)  
    at com.mysql.cj.protocol.a.NativeProtocol.sendCommand(NativeProtocol.java:642)  
    at com.mysql.cj.protocol.a.NativeProtocol.sendQueryPacket(NativeProtocol.java:941)  
    at com.mysql.cj.protocol.a.NativeProtocol.sendQueryString(NativeProtocol.java:887)  
    at com.mysql.cj.NativeSession.execSQL(NativeSession.java:1073)  
    at com.mysql.cj.jdbc.ConnectionImpl.setAutoCommit(ConnectionImpl.java:2046)  
    ... 104 common frames omitted  
Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.  
    at com.mysql.cj.protocol.FullReadInputStream.readFully(FullReadInputStream.java:67)  
    at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:63)  
    at com.mysql.cj.protocol.a.SimplePacketReader.readHeader(SimplePacketReader.java:45)  
    at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:52)  
    at com.mysql.cj.protocol.a.TimeTrackingPacketReader.readHeader(TimeTrackingPacketReader.java:41)  
    at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:54)  
    at com.mysql.cj.protocol.a.MultiPacketReader.readHeader(MultiPacketReader.java:44)  
    at com.mysql.cj.protocol.a.NativeProtocol.readMessage(NativeProtocol.java:533)  
    ... 110 common frames omitted  
[2020-12-11 16:03:19,947] [http-nio-8095-exec-1] DEBUG o.s.r.b.ExponentialBackOffPolicy [] -    Sleeping for 30000

The database is restarted at this point. We were hoping that the Spring-retry would grab a new connection and carry on. This is not the case. Instead the same dead connection is used for subsequent retries and the process fails accordingly.

[2020-12-11 16:03:49,948] [http-nio-8095-exec-1] DEBUG o.s.retry.support.RetryTemplate [] -    Checking for rethrow: count=1
[2020-12-11 16:03:49,948] [http-nio-8095-exec-1] DEBUG o.s.retry.support.RetryTemplate [] -    Retry: count=1
[2020-12-11 16:03:49,948] [http-nio-8095-exec-1] INFO u.b.c.RestController [] -    Running usage data live service end point for: usageData
[2020-12-11 16:03:53,752] [http-nio-8095-exec-1] DEBUG o.s.r.b.ExponentialBackOffPolicy [] -    Sleeping for 60000
[2020-12-11 16:04:53,753] [http-nio-8095-exec-1] DEBUG o.s.retry.support.RetryTemplate [] -    Checking for rethrow: count=2
[2020-12-11 16:04:53,753] [http-nio-8095-exec-1] DEBUG o.s.retry.support.RetryTemplate [] -    Retry: count=2
[2020-12-11 16:04:53,753] [http-nio-8095-exec-1] INFO u.b.c.RestController [] -    Running usage data live service end point for: usageData
[2020-12-11 16:06:53,609] [SpringBootJPAHikariCP housekeeper] WARN com.zaxxer.hikari.pool.HikariPool [] -    SpringBootJPAHikariCP - Thread starvation or clock leap detected (housekeeper delta=2m3s700ms974µs274ns).
[2020-12-11 16:06:53,608] [http-nio-8095-exec-1] DEBUG o.s.retry.support.RetryTemplate [] -    Checking for rethrow: count=3
[2020-12-11 16:06:53,612] [http-nio-8095-exec-1] DEBUG o.s.retry.support.RetryTemplate [] -    Retry failed last attempt: count=3
[2020-12-11 16:06:53,640] [http-nio-8095-exec-1] ERROR 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.transaction.CannotCreateTransactionException: Could not open JPA EntityManager for transaction; nested exception is org.hibernate.TransactionException: JDBC begin transaction failed: ] with root cause
java.sql.SQLException: Connection is closed
    at com.zaxxer.hikari.pool.ProxyConnection$ClosedConnection.lambda$getClosedConnection$0(ProxyConnection.java:515)
    at com.sun.proxy.$Proxy98.setAutoCommit(Unknown Source)
    at com.zaxxer.hikari.pool.ProxyConnection.setAutoCommit(ProxyConnection.java:414)
    at com.zaxxer.hikari.pool.HikariProxyConnection.setAutoCommit(HikariProxyConnection.java)
    at org.hibernate.resource.jdbc.internal.AbstractLogicalConnectionImplementor.begin(AbstractLogicalConnectionImplementor.java:67)
    at org.hibernate.resource.jdbc.internal.LogicalConnectionManagedImpl.begin(LogicalConnectionManagedImpl.java:263)
    at org.hibernate.resource.transaction.backend.jdbc.internal.JdbcResourceLocalTransactionCoordinatorImpl$TransactionDriverControlImpl.begin(JdbcResourceLocalTransactionCoordinatorImpl.java:236)
    at org.hibernate.engine.transaction.internal.TransactionImpl.begin(TransactionImpl.java:86)
    at org.springframework.orm.jpa.vendor.HibernateJpaDialect.beginTransaction(HibernateJpaDialect.java:184)
    at org.springframework.orm.jpa.JpaTransactionManager.doBegin(JpaTransactionManager.java:402)
    at org.springframework.transaction.support.AbstractPlatformTransactionManager.getTransaction(AbstractPlatformTransactionManager.java:378)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.createTransactionIfNecessary(TransactionAspectSupport.java:475)
    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:289)
    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:98)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.dao.support.PersistenceExceptionTranslationInterceptor.invoke(PersistenceExceptionTranslationInterceptor.java:139)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$CrudMethodMetadataPopulatingMethodInterceptor.invoke(CrudMethodMetadataPostProcessor.java:144)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.data.jpa.repository.support.CrudMethodMetadataPostProcessor$ExposeRepositoryInvocationInterceptor.invoke(CrudMethodMetadataPostProcessor.java:364)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:93)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.data.repository.core.support.SurroundingTransactionDetectorMethodInterceptor.invoke(SurroundingTransactionDetectorMethodInterceptor.java:61)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212)
    at com.sun.proxy.$Proxy133.updateAggregationDisabledFlag(Unknown Source)
    at uk.bobbins.service.AggregationServiceImpl.updateAggregationDisabledFlag(AggregationServiceImpl.java:457)
    at uk.bobbins.controller.RestController.usageDataFromSource(RestController.java:149)
    at uk.bobbins.controller.RestController$$FastClassBySpringCGLIB$$ae255ac.invoke(<generated>)
    at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
    at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:750)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
    at org.springframework.retry.interceptor.RetryOperationsInterceptor$1.doWithRetry(RetryOperationsInterceptor.java:91)
    at org.springframework.retry.support.RetryTemplate.doExecute(RetryTemplate.java:287)
    at org.springframework.retry.support.RetryTemplate.execute(RetryTemplate.java:164)
    at org.springframework.retry.interceptor.RetryOperationsInterceptor.invoke(RetryOperationsInterceptor.java:118)
    at org.springframework.retry.annotation.AnnotationAwareRetryOperationsInterceptor.invoke(AnnotationAwareRetryOperationsInterceptor.java:153)
    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
    at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689)
    at uk.bobbins.controller.RestController$$EnhancerBySpringCGLIB$$574fc03d.usageDataFromSource(<generated>)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
    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:190)
    at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138)
    at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:105)
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:893)
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:798)
    at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1040)
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943)
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
    at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:634)
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:741)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.boot.actuate.web.trace.servlet.HttpTraceFilter.doFilterInternal(HttpTraceFilter.java:88)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:94)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:114)
    at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:104)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:526)
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:408)
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:860)
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1589)
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
    at java.lang.Thread.run(Thread.java:748)

If anyone could shine a light on how I can make the spring-retry functionality acquire a new database connection (even from the pool) I would appreciate the knowledge.

Edited for a little more clarity.

Answer 1

Ok, after a bit of head scratching I finally think I've managed to figure out what's going on. It appears that at a failed database connection, the exception is thrown and reported upwards but the Spring retry prevents something happening and a new database connection is not acquired on the subsequent retry through the code.

The only solution I could find for this was to replace the Spring-Retry with my own @Retry annotation and aspect for handling the annotation.

That is to say:

@Retry
@RequestMapping("usageData/load/")
public void usageDataFromSource() {
    log.info("Running usage data live service end point for: usageData");
    //Sets status of aggregation disabled to false.
    aggregationService.updateAggregationDisabledFlag("usageData", false);

    usageService.copyUsageDataFromSourceToDestination();

}

And the Annotation:

@Documented
@Target(ElementType.METHOD)
@Inherited
@Retention(RetentionPolicy.RUNTIME)
public @interface Retry {
    int initialDelay() default 30000;
    int multiplier() default 2;
    int maxInterval() default 500000;
}

And the Aspect:

@Around(value = "@annotation(retry)")
public Object performMethodCallWithRetry(ProceedingJoinPoint joinPoint, Retry retry) throws Throwable {

    log.debug("About to try checking the Connection");
    int initialDelay = retry.initialDelay();
    int multiplier = retry.multiplier();
    int maxInterval = retry.maxInterval();

    int count = 0;
    long startTime = System.currentTimeMillis();
    int delay = 0;
    Object object = null;
    Throwable throwable;
    do {
        try {
            // Create the future call and wait for the response
            object = CompletableFuture.supplyAsync(() -> {
                try {
                    return joinPoint.proceed();
                } catch (Throwable e) {
                    throw new IllegalStateException(e);
                }
            }).join();

            throwable = null;
        } catch (Exception e) {
            // catch everything.  If the method has been wrapped in this aspect, we want to catch
            // and retry for all exceptions.
            throwable = e.getCause();

            log.error(
                "Failed to process {} on attempt {}",
                joinPoint.getSignature().getName(),
                count + 1,
                e);

            delay = count == 0 ? initialDelay : count * multiplier * initialDelay;
            log.info("Sleeping for {} seconds", delay);
            Thread.sleep(delay);
        }
        count++;
    } while (Objects.nonNull(throwable) && count < multiplier
        && System.currentTimeMillis() - startTime < maxInterval);
    log.debug("About to exit with success {}, count {} and delay {}ms", Objects.isNull(throwable),  count, delay);

    // if we have been through the retry loop and still have an exception, throw it.
    if (throwable != null) {
        throw throwable;
    }
    return object;
}

I hope that this may help someone who comes across the a similar problem

Answer 2

Reading the solution that uses a separate thread by Andrew Harrison is fantastic. It provided different perspective to the problem and made me dig up more on the issue.

Apparently the issue is because of spring.jpa.open-in-view by default is enabled. The transaction actually is created much earlier, at the interceptor layer, than what is annotated at the controller or service level method.

You will notice this debugging line

o.j.s.OpenEntityManagerInViewInterceptor : Opening JPA EntityManager in OpenEntityManagerInViewInterceptor

As such when the annotated method either controller or service is retried, the transaction did not cease despite the database connection has been interrupted.

This debugging line was never printed

o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(1649520370<open>)] after transaction

Hence the spring-retry just keep repeating the method attempt to revive the transaction.

Disabling spring.jpa.open-in-view ensure no transaction has started before the spring-retry point-cut, thus ending of the spring-retry point-cut would result in the transaction ending along with the annotated method and each new iteration of the method would be also a new transaction open hence getting a new connection from the entity manager.

If spring.jpa.open-in-view is enabled, spring-retry will keep iterating the annotated method and end with the debugging line

o.j.s.OpenEntityManagerInViewInterceptor : Closing JPA EntityManager in OpenEntityManagerInViewInterceptor

If it spring.jpa.open-in-view is disabled, each iteration while spring-retry is retrying the method would shows

o.s.orm.jpa.JpaTransactionManager        : Closing JPA EntityManager [SessionImpl(1633589911<open>)] after transaction

and on start of each iteration would shows

o.s.orm.jpa.JpaTransactionManager        : Creating new transaction with name [....]: PROPAGATION....

I hope this helps to shed light into why it may not be necessary to use Andrew Harrison method. Spring-retry works.

Andrew Harrison method may have created another problem should your View still requires access to the database. His method created new database connections in the new thread via the thread local EntityManager, but once the original request thread is resumed, the EntityManager in it will still be holding on to a defunct database connection. While I may not have tested, I highly suspect attempting to access the database in the View would result in JDBC errors too.