Closed
Description
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.
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