ERR no such key when RedisOperationsSessionRepository.saveChangeSessionId called

[wangzw]

Hi all

I got the following exception and seems the session is already gone before rename. Should we ignore such exception?

Version: spring-session-data-redis-2.1.2.RELEASE

I guess that #1137 d3134ad did not fix all issues.

org.springframework.data.redis.RedisSystemException: Error in execution; nested exception is io.lettuce.core.RedisCommandExecutionException: ERR no such key
	at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:54) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
	at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:52) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
	at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:41) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
	at org.springframework.data.redis.PassThroughExceptionTranslationStrategy.translate(PassThroughExceptionTranslationStrategy.java:44) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
	at org.springframework.data.redis.FallbackExceptionTranslationStrategy.translate(FallbackExceptionTranslationStrategy.java:42) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
	at org.springframework.data.redis.connection.lettuce.LettuceConnection.convertLettuceAccessException(LettuceConnection.java:268) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
	at org.springframework.data.redis.connection.lettuce.LettuceKeyCommands.convertLettuceAccessException(LettuceKeyCommands.java:817) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
	at org.springframework.data.redis.connection.lettuce.LettuceKeyCommands.rename(LettuceKeyCommands.java:325) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
	at org.springframework.data.redis.connection.DefaultedRedisConnection.rename(DefaultedRedisConnection.java:118) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
	at org.springframework.data.redis.core.RedisTemplate.lambda$rename$16(RedisTemplate.java:932) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
	at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:224) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
	at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:184) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
	at org.springframework.data.redis.core.RedisTemplate.rename(RedisTemplate.java:931) ~[spring-data-redis-2.1.3.RELEASE.jar!/:2.1.3.RELEASE]
	at org.springframework.session.data.redis.RedisOperationsSessionRepository$RedisSession.saveChangeSessionId(RedisOperationsSessionRepository.java:867) ~[spring-session-data-redis-2.1.2.RELEASE.jar!/:2.1.2.RELEASE]
	at org.springframework.session.data.redis.RedisOperationsSessionRepository$RedisSession.saveDelta(RedisOperationsSessionRepository.java:826) ~[spring-session-data-redis-2.1.2.RELEASE.jar!/:2.1.2.RELEASE]
	at org.springframework.session.data.redis.RedisOperationsSessionRepository$RedisSession.access$000(RedisOperationsSessionRepository.java:703) ~[spring-session-data-redis-2.1.2.RELEASE.jar!/:2.1.2.RELEASE]
	at org.springframework.session.data.redis.RedisOperationsSessionRepository.save(RedisOperationsSessionRepository.java:421) ~[spring-session-data-redis-2.1.2.RELEASE.jar!/:2.1.2.RELEASE]
	at org.springframework.session.data.redis.RedisOperationsSessionRepository.save(RedisOperationsSessionRepository.java:247) ~[spring-session-data-redis-2.1.2.RELEASE.jar!/:2.1.2.RELEASE]
	at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.commitSession(SessionRepositoryFilter.java:240) ~[spring-session-core-2.1.2.RELEASE.jar!/:2.1.2.RELEASE]
	at org.springframework.session.web.http.SessionRepositoryFilter$SessionRepositoryRequestWrapper.access$100(SessionRepositoryFilter.java:201) ~[spring-session-core-2.1.2.RELEASE.jar!/:2.1.2.RELEASE]
	at org.springframework.session.web.http.SessionRepositoryFilter.doFilterInternal(SessionRepositoryFilter.java:154) ~[spring-session-core-2.1.2.RELEASE.jar!/:2.1.2.RELEASE]
	at org.springframework.session.web.http.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:81) ~[spring-session-core-2.1.2.RELEASE.jar!/:2.1.2.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.13.jar!/:9.0.13]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.13.jar!/:9.0.13]
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:117) ~[spring-boot-actuator-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
	at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:106) ~[spring-boot-actuator-2.1.1.RELEASE.jar!/:2.1.1.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.1.3.RELEASE.jar!/:5.1.3.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.13.jar!/:9.0.13]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.13.jar!/:9.0.13]
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:200) ~[spring-web-5.1.3.RELEASE.jar!/:5.1.3.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.1.3.RELEASE.jar!/:5.1.3.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.13.jar!/:9.0.13]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.13.jar!/:9.0.13]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199) ~[tomcat-embed-core-9.0.13.jar!/:9.0.13]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:490) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:408) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:791) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1417) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_191]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_191]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-9.0.13.jar!/:9.0.13]
	at java.lang.Thread.run(Thread.java:748) [na:1.8.0_191]
Caused by: io.lettuce.core.RedisCommandExecutionException: ERR no such key
	at io.lettuce.core.ExceptionFactory.createExecutionException(ExceptionFactory.java:135) ~[lettuce-core-5.1.3.RELEASE.jar!/:na]
	at io.lettuce.core.ExceptionFactory.createExecutionException(ExceptionFactory.java:108) ~[lettuce-core-5.1.3.RELEASE.jar!/:na]
	at io.lettuce.core.protocol.AsyncCommand.completeResult(AsyncCommand.java:120) ~[lettuce-core-5.1.3.RELEASE.jar!/:na]
	at io.lettuce.core.protocol.AsyncCommand.complete(AsyncCommand.java:111) ~[lettuce-core-5.1.3.RELEASE.jar!/:na]
	at io.lettuce.core.protocol.CommandWrapper.complete(CommandWrapper.java:59) ~[lettuce-core-5.1.3.RELEASE.jar!/:na]
	at io.lettuce.core.protocol.CommandHandler.complete(CommandHandler.java:646) ~[lettuce-core-5.1.3.RELEASE.jar!/:na]
	at io.lettuce.core.protocol.CommandHandler.decode(CommandHandler.java:604) ~[lettuce-core-5.1.3.RELEASE.jar!/:na]
	at io.lettuce.core.protocol.CommandHandler.channelRead(CommandHandler.java:556) ~[lettuce-core-5.1.3.RELEASE.jar!/:na]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1434) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:965) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:648) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:583) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:500) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:462) ~[netty-transport-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897) ~[netty-common-4.1.31.Final.jar!/:4.1.31.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.31.Final.jar!/:4.1.31.Final]
	... 1 common frames omitted

[vpavic]

Thanks for the report @wangzw - can you describe how to reproduce this? A minimal sample would be the most helpful.

[wangzw]

It is hard to reproduce since it happened on our online production. Customer reported a 500 error and from the logs, we found above exception.

From #1137 , there are two rename operations and only one ignore "ERR no such key" exception. Is it intentional？The exception we got was thrown from the other one, just as I commented in d3134ad.

[vpavic]

Thanks for following up. Yes, at the time it was intentional to only handle ERR no such key for expiration key. However, the session key itself should be there 5 minutes after the session was deleted (see reference manual section on handling expirations) so this truly looks like an exceptional situation.

Therefore I think it's important to understand under which circumstances the error occurs.

[wangzw]

Thanks for your feedback, I'm currently working on the investigation. The session is definitely not expired in 5 minutes. It happened just after I login.

It is a restful api, and I set session policy to SessionCreationPolicy.STATELESS. I do not know if it is related.

[wangzw]

If SessionCreationPolicy.STATELESS is set in HttpSecurity, session will be eagerly destroyed and "rename" will throw "ERR no such key".

That is the case we should catch when rename a session.

Temporary workaround is to change session policy to NEVER.

[wangzw]

@vpavic What is your opinion to fix this issue?

[vpavic]

It's still not clear to me how to reproduce the problem @wangzw. Can you provide a minimal sample application that reproduces the problem? It's unclear to me what's your use case with Spring Session and SessionCreationPolicy.STATELESS.

[wangzw]

I have a project to manage user account, it handle user authentication with spring-security (endpoint /login), user authorization with oauth2 (endpoint /token)and several restful API to do user management such as add/delete user (endpoint /users).

The project should support HA some two instances is running at the same time. So I use redis based distributed session for spring-security to handle login process.

User management API is restful, so it is configured as SessionCreationPolicy.STATELESS.

I do not know if there is a simply way to reproduce this issue. From my investigation, there is a race condition between session clean and session rename if SessionCreationPolicy.STATELESS is set.

In the previous comments you mentioned that the session key itself should be there 5 minutes after the session was deleted, but it is not true from my investigation.

[vpavic]

In the previous comments you mentioned that the session key itself should be there 5 minutes after the session was deleted, but it is not true from my investigation.

Since I've been unable to reproduce this, I'm afraid we really need a sample app to be able to move forward with this.

[wanwaner]

@wangzw
add HttpSecurity Config code:
http.sessionManagement().sessionFixation().none();

[vpavic]

Closing due to lack of feedback. Please comment back if you can provide more details and we can re-open the issue.