Redis Connection Factory Earlier Graceful Shutdown after Spring 3.2 Upgrade - LettuceConnectionFactory SmartLifecycle Backward Compatibility

[emindeniz99]

Hi, I have opened the issue to spring-boot, spring-projects/spring-boot#39501, They pointed me to this repository.

@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.

I looked into the related commits and pull requests, but I could not find any solution to support the old behavior spring bean lifecycle.

#2503

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 spring-boot#39469

Thanks

[mp911de]

We migrated our connection factories to Lifecycle to delay the start of the connection resources opened by the connection factory and to have control over the shutdown. This migration comes clearly with behavioral changes as the connection is no longer available to @PreDestroy/DisposableBean phases.

Please implement SmartLifecycle instead of using @PreDestroy.

[emindeniz99]

We migrated our connection factories to Lifecycle to delay the start of the connection resources opened by the connection factory and to have control over the shutdown. This migration comes clearly with behavioral changes as the connection is no longer available to @PreDestroy/DisposableBean phases.

Please implement SmartLifecycle instead of using @PreDestroy.

Thank you @mp911de and @wilkinsona , we will implement SmartLifecycle, we missed this point when upgrading the spring boot version. Our use case for redis connection in predestroy is rare in the development environment, so we noticed it after a few days.