Allow Customizing Redis Session Mapper

[gp0014]

Describe the bug
We are using redis to save sessions in spring cloud gateway, and see some missing key errors in the log.

Versions:
spring-session-data-redis:2.3.3.RELEASE

2022-02-08 01:04:07.219,ERROR,[lettuce-epollEventLoop-5-11] com.xxx.gateway.GatewayErrorHandler ,, - handle error for calling GET status:https://xxx.xxx.com/xxx/languages?lang=en_US downstream:500 INTERNAL_SERVER_ERROR http://172.24.149.220:10240/languages?lang=en_US
java.lang.IllegalStateException: creationTime key must not be null
	at org.springframework.session.data.redis.RedisSessionMapper.handleMissingKey(RedisSessionMapper.java:94)
	Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: 
Error has been observed at the following site(s):
	|_ checkpoint ⇢ org.springframework.web.cors.reactive.CorsWebFilter [DefaultWebFilterChain]
	|_ checkpoint ⇢ org.springframework.cloud.gateway.filter.WeightCalculatorWebFilter [DefaultWebFilterChain]
	|_ checkpoint ⇢ org.springframework.boot.actuate.metrics.web.reactive.server.MetricsWebFilter [DefaultWebFilterChain]
	|_ checkpoint ⇢ HTTP GET "/xxx/languages?lang=en_US" [ExceptionHandlingWebHandler]
Stack trace:
		at org.springframework.session.data.redis.RedisSessionMapper.handleMissingKey(RedisSessionMapper.java:94)
		at org.springframework.session.data.redis.RedisSessionMapper.apply(RedisSessionMapper.java:72)
		at org.springframework.session.data.redis.RedisSessionMapper.apply(RedisSessionMapper.java:35)
		at reactor.core.publisher.FluxMapFuseable$MapFuseableConditionalSubscriber.onNext(FluxMapFuseable.java:273)
		at reactor.core.publisher.FluxFilterFuseable$FilterFuseableConditionalSubscriber.onNext(FluxFilterFuseable.java:330)
		at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1812)
		at reactor.core.publisher.MonoCollect$CollectSubscriber.onComplete(MonoCollect.java:152)
		at reactor.core.publisher.FluxUsingWhen$UsingWhenSubscriber.deferredComplete(FluxUsingWhen.java:402)
		at reactor.core.publisher.FluxUsingWhen$CommitInner.onComplete(FluxUsingWhen.java:536)
		at reactor.core.publisher.MonoIgnoreElements$IgnoreElementsSubscriber.onComplete(MonoIgnoreElements.java:81)
		at reactor.core.publisher.FluxFlatMap$FlatMapMain.checkTerminated(FluxFlatMap.java:816)
		at reactor.core.publisher.FluxFlatMap$FlatMapMain.drainLoop(FluxFlatMap.java:600)
		at reactor.core.publisher.FluxFlatMap$FlatMapMain.drain(FluxFlatMap.java:580)
		at reactor.core.publisher.FluxFlatMap$FlatMapMain.onComplete(FluxFlatMap.java:457)
		at reactor.core.publisher.FluxArray$ArraySubscription.slowPath(FluxArray.java:137)
		at reactor.core.publisher.FluxArray$ArraySubscription.request(FluxArray.java:99)
		at reactor.core.publisher.FluxFlatMap$FlatMapMain.onSubscribe(FluxFlatMap.java:363)
		at reactor.core.publisher.FluxMerge.subscribe(FluxMerge.java:69)
		at reactor.core.publisher.Mono.subscribe(Mono.java:4252)
		at reactor.core.publisher.FluxUsingWhen$UsingWhenSubscriber.onComplete(FluxUsingWhen.java:394)
		at reactor.core.publisher.FluxMap$MapSubscriber.onComplete(FluxMap.java:136)
		at reactor.core.publisher.FluxFlatMap$FlatMapMain.checkTerminated(FluxFlatMap.java:838)
		at reactor.core.publisher.FluxFlatMap$FlatMapMain.drainLoop(FluxFlatMap.java:600)
		at reactor.core.publisher.FluxFlatMap$FlatMapMain.innerComplete(FluxFlatMap.java:909)
		at reactor.core.publisher.FluxFlatMap$FlatMapInner.onComplete(FluxFlatMap.java:1013)
		at reactor.core.publisher.MonoFlatMapMany$FlatMapManyInner.onComplete(MonoFlatMapMany.java:252)
		at reactor.core.publisher.FluxIterable$IterableSubscription.slowPath(FluxIterable.java:289)
		at reactor.core.publisher.FluxIterable$IterableSubscription.request(FluxIterable.java:225)
		at reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onSubscribeInner(MonoFlatMapMany.java:143)
		at reactor.core.publisher.MonoFlatMapMany$FlatMapManyInner.onSubscribe(MonoFlatMapMany.java:237)
		at reactor.core.publisher.FluxIterable.subscribe(FluxIterable.java:161)
		at reactor.core.publisher.FluxStream.subscribe(FluxStream.java:71)
		at reactor.core.publisher.Flux.subscribe(Flux.java:8357)
		at reactor.core.publisher.MonoFlatMapMany$FlatMapManyMain.onNext(MonoFlatMapMany.java:188)
		at reactor.core.publisher.MonoNext$NextSubscriber.onNext(MonoNext.java:76)
		at reactor.core.publisher.MonoNext$NextSubscriber.onNext(MonoNext.java:76)
		at io.lettuce.core.RedisPublisher$ImmediateSubscriber.onNext(RedisPublisher.java:917)
		at io.lettuce.core.RedisPublisher$RedisSubscription.onNext(RedisPublisher.java:290)
		at io.lettuce.core.RedisPublisher$SubscriptionCommand.complete(RedisPublisher.java:781)
		at io.lettuce.core.protocol.CommandWrapper.complete(CommandWrapper.java:59)
		at io.lettuce.core.cluster.ClusterCommand.complete(ClusterCommand.java:66)
		at io.lettuce.core.protocol.CommandWrapper.complete(CommandWrapper.java:59)
		at io.lettuce.core.protocol.CommandHandler.complete(CommandHandler.java:680)
		at io.lettuce.core.protocol.CommandHandler.decode(CommandHandler.java:640)
		at io.lettuce.core.protocol.CommandHandler.channelRead(CommandHandler.java:591)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
		at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
		at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
		at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
		at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
		at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:795)
		at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:480)
		at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:378)
		at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
		at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
		at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
		at java.base/java.lang.Thread.run(Thread.java:832)

To Reproduce

We can not find the reproduce steps.

Expected behavior
No error

[eleftherias]

Thanks for reaching out @gp0014.
Note the Spring Session Redis 2.3.x is no longer supported.
You can see the currently supported versions here.

I will keep this issue open for now in case someone is able to provide a sample, but without knowing how to reproduce it we won't be able to verify whether we have a fix.

[jobinvjohn]

Same issue is happening for us as well.

2022-03-02T08:23:26.685+05:30Copyjava.lang.IllegalStateException: creationTime key must not be null	java.lang.IllegalStateException: creationTime key must not be null
	2022-03-02T08:23:26.685+05:30
	2022-03-02T08:23:26.685+05:30
	2022-03-02T08:23:26.685+05:30
	2022-03-02T08:23:26.685+05:30
	2022-03-02T08:23:26.685+05:30
	2022-03-02T08:23:26.685+05:30
	2022-03-02T08:23:26.685+05:30
	2022-03-02T08:23:26.685+05:30
	2022-03-02T08:23:26.685+05:30
	2022-03-02T08:23:26.685+05:30Copy |_ checkpoint ⇢ org.springframework.security.web.server.context.ReactorContextWebFilter [DefaultWebFilterChain]
	2022-03-02T08:23:26.685+05:30
	2022-03-02T08:23:26.685+05:30
	2022-03-02T08:23:26.685+05:30
	2022-03-02T08:23:26.685+05:30
	2022-03-02T08:23:26.685+05:30
	2022-03-02T08:23:26.685+05:30Copy |_ checkpoint ⇢ org.springframework.boot.actuate.metrics.web.reactive.server.MetricsWebFilter [DefaultWebFilterChain]

[eleftherias]

Thanks @jobinvjohn, do you have a minimal sample that reproduces the issue?

[jo-schi]

We experience the same issue after updating to Spring Boot 2.6.6 and spring-session-data-redis 2.6.1.
The exceptions occurred after stopping the previous version on prod with active sessions and starting the new version.
Unfortunately I am not able to reproduce it on staging. Only obvious difference is that staging does not have spring.session.timeout set, and the prod version got that removed along with the update, before the update it was set to 4h.
Spring session is used by the Spring Cloud Gateway "SaveSession" Filter

[Topher999]

I I have the same problem, no creationTime in "spring-session" cache.
Most sessions do exist，just a few sessioin has the problem.

version：spring-session-data-redis:2.3.3.RELEASE

[LepikhinEgor]

I met this problem too. I can't reproduce this error, but I suspect it is caused by session invalidation via WebSession.invalidate

spring-session-data-redis version 2.7.0

[vpavic]

Looking at this, session stored in data store without a creation time looks like a potential issue due to concurrent requests. For example, a request that attempts to invalidate the session while at the same time some other request attempts to update it - delete happens first, and after that update writes only those session attributes that have changed (delta).

@LepikhinEgor, would this scenario be something like what you meant when saying:

but I suspect it is caused by session invalidation via WebSession.invalidate

[vikram-chaitanya]

@vpavic - We also noticed something similar(not exact) scenario. That is we had two concurrent requests(from angular code) and both of them are processed properly. But since each request changes the session Id (guess to avoid session fixation) in jdbc store the session id in cookies returned by each of them is different and this resulted in the next requests to fail since the cookie from the one of them is valid session id and other one is invalid and the due to the return time difference the invalid won and got stored. So basically we lost the session and had to authenticate again.

Is there some solution to this kind of issue during concurrent requests?