Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Exception thrown on application shutdown when using redis with RedisIndexedWebSession enabled #3188

Open
ronniiii opened this issue Sep 5, 2024 · 1 comment
Labels
status: waiting-for-triage An issue we've not yet triaged type: bug A general bug

Comments

@ronniiii
Copy link

ronniiii commented Sep 5, 2024

Please Note I filed this bug in spring-projects/spring-data-redis#2983 but the comment I received was to file this over here.

Spring boot throws exception on application shutdown. It does not happen when I replace @EnableRedisIndexedWebSession with @EnableRedisWebSession. Something else I've also tried not specifying my own LettuceClientConfiguration in the RedisConfig below which also works.

I am using the following Spring dependencies:

org.springframework.session:spring-session-data-redis:3.31
org.springframework.boot:spring-boot-starter-data-redis-reactive:3.3.2

Exception Thrown:

`Disconnected from the target VM, address: '127.0.0.1:51013', transport: 'socket'
2024-09-05 12:04:03,671 destroy LettucePoolingConnectionProvider contains unreleased connections {}
2024-09-05 12:04:03,805 error Operator called default onErrorDropped {} reactor.core.Exceptions$ErrorCallbackNotImplemented: org.springframework.data.redis.connection.PoolException: Returned connection io.lettuce.core.pubsub.StatefulRedisPubSubConnectionImpl@40b6b5f3 was either previously returned or does not belong to this connection provider
Caused by: org.springframework.data.redis.connection.PoolException: Returned connection io.lettuce.core.pubsub.StatefulRedisPubSubConnectionImpl@40b6b5f3 was either previously returned or does not belong to this connection provider
at org.springframework.data.redis.connection.lettuce.LettucePoolingConnectionProvider.releaseAsync(LettucePoolingConnectionProvider.java:192)
at org.springframework.data.redis.connection.lettuce.LettuceConnectionFactory$ExceptionTranslatingConnectionProvider.releaseAsync(LettuceConnectionFactory.java:1834)
at org.springframework.data.redis.connection.lettuce.LettuceReactiveRedisConnection$AsyncConnect.lambda$close$3(LettuceReactiveRedisConnection.java:373)
at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:45)
at reactor.core.publisher.Mono.subscribe(Mono.java:4568)
at reactor.core.publisher.FluxFlatMap$FlatMapMain.onNext(FluxFlatMap.java:430)
at reactor.core.publisher.FluxArray$ArraySubscription.slowPath(FluxArray.java:126)
at reactor.core.publisher.FluxArray$ArraySubscription.request(FluxArray.java:99)
at reactor.core.publisher.FluxFlatMap$FlatMapMain.onSubscribe(FluxFlatMap.java:373)
at reactor.core.publisher.FluxMerge.subscribe(FluxMerge.java:73)
at reactor.core.publisher.MonoFromFluxOperator.subscribe(MonoFromFluxOperator.java:83)
at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:53)
at reactor.core.publisher.Mono.subscribe(Mono.java:4568)
at reactor.core.publisher.Mono.subscribeWith(Mono.java:4634)
at reactor.core.publisher.Mono.subscribe(Mono.java:4395)
at org.springframework.data.redis.core.ReactiveRedisTemplate.lambda$listenTo$4(ReactiveRedisTemplate.java:289)
at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.runFinally(FluxDoFinally.java:146)
at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.cancel(FluxDoFinally.java:135)
at reactor.core.publisher.FluxFlatMap$FlatMapMain.cancel(FluxFlatMap.java:361)
at reactor.core.publisher.LambdaSubscriber.dispose(LambdaSubscriber.java:191)
at org.springframework.session.data.redis.ReactiveRedisIndexedSessionRepository.destroy(ReactiveRedisIndexedSessionRepository.java:338)
at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:211)
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:1195)
at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1156)
at org.springframework.boot.web.reactive.context.ReactiveWebServerApplicationContext.doClose(ReactiveWebServerApplicationContext.java:149)
at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:1102)
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)

2024-09-05 12:04:03,806 error Operator called default onErrorDropped {} reactor.core.Exceptions$ErrorCallbackNotImplemented: org.springframework.data.redis.connection.PoolException: Returned connection io.lettuce.core.pubsub.StatefulRedisPubSubConnectionImpl@126a7e1b was either previously returned or does not belong to this connection provider
Caused by: org.springframework.data.redis.connection.PoolException: Returned connection io.lettuce.core.pubsub.StatefulRedisPubSubConnectionImpl@126a7e1b was either previously returned or does not belong to this connection provider
at org.springframework.data.redis.connection.lettuce.LettucePoolingConnectionProvider.releaseAsync(LettucePoolingConnectionProvider.java:192)
at org.springframework.data.redis.connection.lettuce.LettuceConnectionFactory$ExceptionTranslatingConnectionProvider.releaseAsync(LettuceConnectionFactory.java:1834)
at org.springframework.data.redis.connection.lettuce.LettuceReactiveRedisConnection$AsyncConnect.lambda$close$3(LettuceReactiveRedisConnection.java:373)
at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:45)
at reactor.core.publisher.Mono.subscribe(Mono.java:4568)
at reactor.core.publisher.FluxFlatMap$FlatMapMain.onNext(FluxFlatMap.java:430)
at reactor.core.publisher.FluxArray$ArraySubscription.slowPath(FluxArray.java:126)
at reactor.core.publisher.FluxArray$ArraySubscription.request(FluxArray.java:99)
at reactor.core.publisher.FluxFlatMap$FlatMapMain.onSubscribe(FluxFlatMap.java:373)
at reactor.core.publisher.FluxMerge.subscribe(FluxMerge.java:73)
at reactor.core.publisher.MonoFromFluxOperator.subscribe(MonoFromFluxOperator.java:83)
at reactor.core.publisher.MonoDefer.subscribe(MonoDefer.java:53)
at reactor.core.publisher.Mono.subscribe(Mono.java:4568)
at reactor.core.publisher.Mono.subscribeWith(Mono.java:4634)
at reactor.core.publisher.Mono.subscribe(Mono.java:4395)
at org.springframework.data.redis.core.ReactiveRedisTemplate.lambda$listenTo$4(ReactiveRedisTemplate.java:289)
at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.runFinally(FluxDoFinally.java:146)
at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.cancel(FluxDoFinally.java:135)
at reactor.core.publisher.FluxFlatMap$FlatMapMain.cancel(FluxFlatMap.java:361)
at reactor.core.publisher.LambdaSubscriber.dispose(LambdaSubscriber.java:191)
at org.springframework.session.data.redis.ReactiveRedisIndexedSessionRepository.destroy(ReactiveRedisIndexedSessionRepository.java:338)
at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:211)
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:1195)
at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1156)
at org.springframework.boot.web.reactive.context.ReactiveWebServerApplicationContext.doClose(ReactiveWebServerApplicationContext.java:149)
at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:1102)
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)`

My sample configuration below:

RedisConfig.java

`@Configuration
public class RedisConfig {

@Bean
public LettuceConnectionFactory redisConnectionFactory() {
    GenericObjectPoolConfig<?> genericObjectPoolConfig = new GenericObjectPoolConfig<>();
    genericObjectPoolConfig.setMaxTotal(10);
    genericObjectPoolConfig.setMaxIdle(5);
    genericObjectPoolConfig.setMinIdle(1);
    genericObjectPoolConfig.setTestOnBorrow(true);
    
    LettuceClientConfiguration clientConfig = LettucePoolingClientConfiguration.builder()
            .poolConfig(genericObjectPoolConfig)
            .build();

    RedisStandaloneConfiguration redisStandaloneConfiguration = new RedisStandaloneConfiguration();
    redisStandaloneConfiguration.setDatabase(0);
    redisStandaloneConfiguration.setHostName("localhost");
    redisStandaloneConfiguration.setPort(6379);
    return new LettuceConnectionFactory(redisStandaloneConfiguration, clientConfig);
}

}`

SessionConfig.java

@Configuration @EnableRedisIndexedWebSession public class SessionConfig { }

@ronniiii ronniiii added status: waiting-for-triage An issue we've not yet triaged type: bug A general bug labels Sep 5, 2024
@njuneau-coveo
Copy link

Hello,

This issue is also reproducible with the non-reactive version RedisIndexedSessionRepository, running with the following:

  • Spring Boot 3.3.7
  • spring-session-data-redis version 3.3.5
  • Jedis as the connection provider

To help reproduce and diagnose the issue, I have put up a sample project here: https://github.com/njuneau-coveo/spring-session-shutdown-demo . Upon shutdown, a stack trace similar to @ronniiii (but with Jedis instead of Lettuce) will appear in the logs at least once:

java.lang.IllegalStateException: JedisConnectionFactory has been STOPPED. Use start() to initialize it                                                                                                                                         
        at org.springframework.data.redis.connection.jedis.JedisConnectionFactory.assertInitialized(JedisConnectionFactory.java:1059) ~[spring-data-redis-3.3.7.jar!/:3.3.7]
        at org.springframework.data.redis.connection.jedis.JedisConnectionFactory.getConnection(JedisConnectionFactory.java:880) ~[spring-data-redis-3.3.7.jar!/:3.3.7]
        at org.springframework.data.redis.core.RedisConnectionUtils.fetchConnection(RedisConnectionUtils.java:195) ~[spring-data-redis-3.3.7.jar!/:3.3.7]
[...]
        at org.springframework.session.data.redis.RedisSessionExpirationPolicy.cleanExpiredSessions(RedisSessionExpirationPolicy.java:132) ~[spring-session-data-redis-3.3.5.jar!/:3.3.5]
        at org.springframework.session.data.redis.RedisIndexedSessionRepository.cleanUpExpiredSessions(RedisIndexedSessionRepository.java:489) ~[spring-session-data-redis-3.3.5.jar!/:3.3.5]
        at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54) ~[spring-context-6.1.16.jar!/:6.1.16]
        at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:96) ~[spring-context-6.1.16.jar!/:6.1.16]

As mentioned in spring-projects/spring-data-redis#2983 , RedisIndexedSessionRepository shuts down its cleanup job too late in the process since JedisConnectionFactory moved to SmartLifecycle.

The demo project provides an exaggerated cleanup cron and a Thread.sleep to make the issue consistently visible for debugging, but we have observed it in the wild in some of our actual projects.

Hopefully this will help out :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
status: waiting-for-triage An issue we've not yet triaged type: bug A general bug
Projects
None yet
Development

No branches or pull requests

2 participants