Redis Connection Factory Earlier Graceful Shutdown after Spring 3.2 Upgrade

[emindeniz99]

Problem

We have upgraded spring boot version from 3.0.5 to 3.2.2. After that, we experience a graceful shutdown issue with our predestroy logic that makes Redis calls.

The new spring version changes the order of destruction for RedisConnectionFactory , they are destroyed earlier than dependent services.

2024-02-09 14:59:16,243 - WARN - CommonAnnotationBeanPostProcessor - Destroy method on bean with name 'redisEarlyClosedDependencyIssueService' threw an exception java.lang.IllegalStateException: LettuceConnectionFactory has been STOPPED. Use start() to initialize it

Reproduce

package com.dreamgames.royalkingdomgameserver.service;

import jakarta.annotation.PreDestroy;
import lombok.RequiredArgsConstructor;
import lombok.extern.slf4j.Slf4j;
import org.springframework.data.redis.connection.RedisConnectionFactory;
import org.springframework.data.redis.core.RedisTemplate;
import org.springframework.data.redis.serializer.GenericToStringSerializer;
import org.springframework.stereotype.Service;

@Service
@Slf4j
@RequiredArgsConstructor
public class RedisEarlyClosedDependencyIssueService {

    final RedisConnectionFactory redisConnectionFactory;

    @PreDestroy
    public void preDestroy() {
        var template = generateGenericRedisTemplate(redisConnectionFactory, String.class);
        log.debug("Shutting down RedisEarlyClosedDependencyIssueService");
        var res = template.opsForValue().get("spring-3-2-test-key-123"); // throws  exception
        log.debug("RedisEarlyClosedDependencyIssueService redis value: {}", res);
    }

    public static <V> RedisTemplate<String, V> generateGenericRedisTemplate(RedisConnectionFactory redisConnectionFactory, Class<V> valueClass) {
        RedisTemplate<String, V> redisTemplate = new RedisTemplate<>();
        redisTemplate.setConnectionFactory(redisConnectionFactory);
        redisTemplate.setDefaultSerializer(new GenericToStringSerializer<>(valueClass));
        redisTemplate.afterPropertiesSet();
        return redisTemplate;
    }

}

Specs

Spring Boot spring-boot-starter-parent, spring-boot-starter-web, spring-boot-starter-data-redis 3.2.2

Graceful Shutdown Console Output (spring log level: trace)

...
2024-02-09 14:59:15,686 - DEBUG - ApplicationAvailabilityBean -  Application availability state ReadinessState changed from ACCEPTING_TRAFFIC to REFUSING_TRAFFIC 
2024-02-09 14:59:15,686 - DEBUG - AnnotationConfigServletWebServerApplicationContext -  Closing org.springframework.boot.web.servlet.context.AnnotationConfigServletWebServerApplicationContext@6f8f8a80, started on Fri Feb 09 11:59:00 UTC 2024 
2024-02-09 14:59:15,686 - TRACE - DefaultListableBeanFactory -  Returning cached instance of singleton bean 'org.springframework.context.annotation.internalScheduledAnnotationProcessor' 
2024-02-09 14:59:15,686 - TRACE - DefaultListableBeanFactory -  Returning cached instance of singleton bean 'meterRegistryCloser' 
2024-02-09 14:59:15,686 - TRACE - DefaultListableBeanFactory -  Returning cached instance of singleton bean 'refreshEventListener' 
2024-02-09 14:59:15,686 - TRACE - DefaultListableBeanFactory -  Returning cached instance of singleton bean 'startupTimeMetrics' 
2024-02-09 14:59:15,686 - TRACE - DefaultListableBeanFactory -  Returning cached instance of singleton bean 'taskScheduler' 
2024-02-09 14:59:15,686 - TRACE - DefaultListableBeanFactory -  Returning cached instance of singleton bean 'springApplicationAdminRegistrar' 
2024-02-09 14:59:15,687 - TRACE - DefaultListableBeanFactory -  Returning cached instance of singleton bean 'asyncExecutor' 
2024-02-09 14:59:15,687 - TRACE - DefaultListableBeanFactory -  Returning cached instance of singleton bean 'producerFactory' 
2024-02-09 14:59:15,687 - TRACE - DefaultListableBeanFactory -  Returning cached instance of singleton bean 'redisConnectionFactory' 
2024-02-09 14:59:15,687 - TRACE - DefaultListableBeanFactory -  Returning cached instance of singleton bean 'standaloneRedisConnectionFactory' 
2024-02-09 14:59:15,687 - TRACE - DefaultListableBeanFactory -  Returning cached instance of singleton bean 'refreshScopeLifecycle' 
2024-02-09 14:59:15,687 - TRACE - DefaultListableBeanFactory -  Returning cached instance of singleton bean 'taskScheduler' 
2024-02-09 14:59:15,687 - TRACE - DefaultListableBeanFactory -  Returning cached instance of singleton bean 'lifecycleProcessor' 
2024-02-09 14:59:15,687 - TRACE - DefaultListableBeanFactory -  Returning cached instance of singleton bean 'org.springframework.kafka.config.internalKafkaListenerEndpointRegistry' 
2024-02-09 14:59:15,687 - TRACE - DefaultListableBeanFactory -  Returning cached instance of singleton bean 'springBootLoggingLifecycle' 
2024-02-09 14:59:15,687 - TRACE - DefaultListableBeanFactory -  Returning cached instance of singleton bean 'webServerGracefulShutdown' 
2024-02-09 14:59:15,687 - TRACE - DefaultListableBeanFactory -  Returning cached instance of singleton bean 'webServerStartStop' 
2024-02-09 14:59:15,687 - DEBUG - DefaultLifecycleProcessor -  Stopping beans in phase 2147483647 
2024-02-09 14:59:15,688 - TRACE - DefaultLifecycleProcessor -  Asking bean 'taskScheduler' of type [org.springframework.scheduling.concurrent.ThreadPoolTaskScheduler] to stop 
2024-02-09 14:59:15,688 - DEBUG - DefaultLifecycleProcessor -  Bean 'taskScheduler' completed its stop procedure 
2024-02-09 14:59:15,688 - DEBUG - DefaultLifecycleProcessor -  Stopping beans in phase 2147483547 
2024-02-09 14:59:15,688 - TRACE - DefaultLifecycleProcessor -  Asking bean 'org.springframework.kafka.config.internalKafkaListenerEndpointRegistry' of type [org.springframework.kafka.config.KafkaListenerEndpointRegistry] to stop 
2024-02-09 14:59:15,688 - DEBUG - DefaultLifecycleProcessor -  Bean 'org.springframework.kafka.config.internalKafkaListenerEndpointRegistry' completed its stop procedure 
2024-02-09 14:59:15,688 - DEBUG - DefaultLifecycleProcessor -  Stopping beans in phase 2147482623 
2024-02-09 14:59:15,688 - TRACE - DefaultLifecycleProcessor -  Asking bean 'webServerGracefulShutdown' of type [org.springframework.boot.web.context.WebServerGracefulShutdownLifecycle] to stop 
2024-02-09 14:59:15,688 - INFO - GracefulShutdown -  Commencing graceful shutdown. Waiting for active requests to complete 
2024-02-09 14:59:15,693 - INFO - GracefulShutdown -  Graceful shutdown complete 
2024-02-09 14:59:15,693 - DEBUG - DefaultLifecycleProcessor -  Bean 'webServerGracefulShutdown' completed its stop procedure 
2024-02-09 14:59:15,693 - DEBUG - DefaultLifecycleProcessor -  Stopping beans in phase 2147481599 
2024-02-09 14:59:15,693 - TRACE - DefaultLifecycleProcessor -  Asking bean 'webServerStartStop' of type [org.springframework.boot.web.servlet.context.WebServerStartStopLifecycle] to stop 
2024-02-09 14:59:15,697 - DEBUG - DefaultLifecycleProcessor -  Bean 'webServerStartStop' completed its stop procedure 
2024-02-09 14:59:15,697 - DEBUG - DefaultLifecycleProcessor -  Stopping beans in phase 0 
2024-02-09 14:59:15,812 - TRACE - DefaultLifecycleProcessor -  Asking bean 'redisConnectionFactory' of type [org.springframework.data.redis.connection.lettuce.LettuceConnectionFactory] to stop 
2024-02-09 14:59:15,918 - DEBUG - DefaultLifecycleProcessor -  Bean 'redisConnectionFactory' completed its stop procedure 
2024-02-09 14:59:15,918 - TRACE - DefaultLifecycleProcessor -  Asking bean 'standaloneRedisConnectionFactory' of type [org.springframework.data.redis.connection.lettuce.LettuceConnectionFactory] to stop 
2024-02-09 14:59:16,024 - DEBUG - DefaultLifecycleProcessor -  Bean 'standaloneRedisConnectionFactory' completed its stop procedure 
2024-02-09 14:59:16,235 - TRACE - DefaultLifecycleProcessor -  Stopping bean 'refreshScopeLifecycle' of type [org.springframework.cloud.context.refresh.RefreshScopeLifecycle] 
2024-02-09 14:59:16,235 - DEBUG - DefaultLifecycleProcessor -  Successfully stopped bean 'refreshScopeLifecycle' 
2024-02-09 14:59:16,235 - DEBUG - DefaultLifecycleProcessor -  Stopping beans in phase -2147483647 
2024-02-09 14:59:16,235 - TRACE - DefaultLifecycleProcessor -  Asking bean 'springBootLoggingLifecycle' of type [org.springframework.boot.context.logging.LoggingApplicationListener$Lifecycle] to stop 
2024-02-09 14:59:16,235 - DEBUG - DefaultLifecycleProcessor -  Bean 'springBootLoggingLifecycle' completed its stop procedure 
2024-02-09 14:59:16,235 - DEBUG - DefaultLifecycleProcessor -  Stopping beans in phase -2147483648 
2024-02-09 14:59:16,235 - TRACE - DefaultLifecycleProcessor -  Asking bean 'producerFactory' of type [org.springframework.kafka.core.DefaultKafkaProducerFactory] to stop 
2024-02-09 14:59:16,235 - DEBUG - DefaultLifecycleProcessor -  Bean 'producerFactory' completed its stop procedure 
.....

2024-02-09 14:59:16,239 - TRACE - DefaultListableBeanFactory -  Retrieved dependent beans for bean 'discoveryClientHealthIndicator': [discoveryCompositeHealthContributor] 
2024-02-09 14:59:16,239 - TRACE - DefaultListableBeanFactory -  Retrieved dependent beans for bean 'discoveryCompositeHealthContributor': [healthContributorRegistry, reactiveHealthContributorRegistry] 
2024-02-09 14:59:16,239 - TRACE - DefaultListableBeanFactory -  Retrieved dependent beans for bean 'healthContributorRegistry': [healthEndpointGroupMembershipValidator, healthEndpoint, healthEndpointWebExtension] 
2024-02-09 14:59:16,239 - TRACE - DefaultListableBeanFactory -  Retrieved dependent beans for bean 'configurationPropertiesRebinder': [refreshScopeHealthIndicator] 
2024-02-09 14:59:16,240 - TRACE - DisposableBeanAdapter -  Invoking custom destroy method 'shutdown' on bean with name 'lettuceClientResources': public abstract io.netty.util.concurrent.Future io.lettuce.core.resource.ClientResources.shutdown() 
2024-02-09 14:59:16,242 - DEBUG - DisposableBeanAdapter -  Custom destroy method 'shutdown' on bean with name 'lettuceClientResources' completed asynchronously 
2024-02-09 14:59:16,242 - TRACE - DisposableBeanAdapter -  Invoking destroy() on bean with name 'redisKeyValueTemplate' 
2024-02-09 14:59:16,242 - TRACE - DisposableBeanAdapter -  Invoking destroy() on bean with name 'redisKeyValueAdapter' 
2024-02-09 14:59:16,242 - DEBUG - RedisMessageListenerContainer -  Stopped RedisMessageListenerContainer 
2024-02-09 14:59:16,242 - TRACE - DisposableBeanAdapter -  Invoking destroy() on bean with name 'asyncExecutor' 
2024-02-09 14:59:16,242 - DEBUG - ThreadPoolTaskExecutor -  Shutting down ExecutorService 'asyncExecutor' 
2024-02-09 14:59:16,242 - TRACE - CommonAnnotationBeanPostProcessor -  Invoking destroy method on bean 'redisEarlyClosedDependencyIssueService': public void com.dreamgames.royalkingdomgameserver.service.RedisEarlyClosedDependencyIssueService.preDestroy() 
2024-02-09 14:59:16,242 - DEBUG - RedisEarlyClosedDependencyIssueService -  Shutting down RedisEarlyClosedDependencyIssueService 
2024-02-09 14:59:16,242 - DEBUG - RedisConnectionUtils -  Fetching Redis Connection from RedisConnectionFactory 
2024-02-09 14:59:16,243 - WARN - CommonAnnotationBeanPostProcessor -  Destroy method on bean with name 'redisEarlyClosedDependencyIssueService' threw an exception java.lang.IllegalStateException: LettuceConnectionFactory has been STOPPED. Use start() to initialize it
	at org.springframework.data.redis.connection.lettuce.LettuceConnectionFactory.assertStarted(LettuceConnectionFactory.java:1401)
	at org.springframework.data.redis.connection.lettuce.LettuceConnectionFactory.getConnection(LettuceConnectionFactory.java:999)
	at org.springframework.data.redis.core.RedisConnectionUtils.fetchConnection(RedisConnectionUtils.java:194)
	at org.springframework.data.redis.core.RedisConnectionUtils.doGetConnection(RedisConnectionUtils.java:143)
	at org.springframework.data.redis.core.RedisConnectionUtils.getConnection(RedisConnectionUtils.java:104)
	at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:393)
	at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:373)
	at org.springframework.data.redis.core.AbstractOperations.execute(AbstractOperations.java:97)
	at org.springframework.data.redis.core.DefaultValueOperations.get(DefaultValueOperations.java:50)
	at com.dreamgames.royalkingdomgameserver.service.RedisEarlyClosedDependencyIssueService.preDestroy(RedisEarlyClosedDependencyIssueService.java:22)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:568)
	at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleMethod.invoke(InitDestroyAnnotationBeanPostProcessor.java:457)
	at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor$LifecycleMetadata.invokeDestroyMethods(InitDestroyAnnotationBeanPostProcessor.java:415)
	at org.springframework.beans.factory.annotation.InitDestroyAnnotationBeanPostProcessor.postProcessBeforeDestruction(InitDestroyAnnotationBeanPostProcessor.java:239)
	at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:202)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:587)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:559)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:1202)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:520)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:1195)
	at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:1183)
	at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1144)
	at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.doClose(ServletWebServerApplicationContext.java:174)
	at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:1090)
	at org.springframework.boot.SpringApplicationShutdownHook.closeAndWait(SpringApplicationShutdownHook.java:145)
	at java.base/java.lang.Iterable.forEach(Iterable.java:75)
	at org.springframework.boot.SpringApplicationShutdownHook.run(SpringApplicationShutdownHook.java:114)
	at java.base/java.lang.Thread.run(Thread.java:840)

...
Process finished with exit code 130 (interrupted by signal 2:SIGINT)

Related Issues

• ThreadPoolTaskExecutor rejecting tasks as soon as the context has been closed can lead to exceptions during web app shutdown
  ThreadPoolTaskExecutor rejecting tasks as soon as the context has been closed can lead to exceptions during web app shutdown spring-framework#32226
• WebFlux auto-configuration should only configure the blocking executor when virtual threads are enabled #39469

[wilkinsona]

Thanks for the report but this is out of Spring Boot's control. LettuceConnectionFactory now implements SmartLifecycle which results in it being closed before your RedisEarlyClosedDependencyIssueService. I'm not sure if the Spring Data Redis team expected Framework to destroy RedisEarlyClosedDependencyIssueService early due to its RedisConnectionFactory dependency or for users of the connection factory to also participate in the lifecycle.

@christophstrobl @mp911de can you please point @emindeniz99 in the right direction?

[emindeniz99]

@wilkinsona Thank you very much, I looked into the links that you mentioned, but I could not find any solution to support the old behavior spring bean lifecycle. I will open the issue at spring-data-redis repo.

spring-projects/spring-data-redis#2843

[wilkinsona]

Please be patient, @emindeniz99. The Spring Data team are very busy at the moment and I was hoping for some guidance from them before another issue was opened in potentially the wrong repository.