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.

Sign up for GitHub

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

Jump to bottom

Auto reconnect do not work if command timeout #1727

Closed
aamrute-idnow opened this issue Apr 14, 2021 · 19 comments
Closed

Auto reconnect do not work if command timeout #1727

aamrute-idnow opened this issue Apr 14, 2021 · 19 comments
Labels
status: invalid An issue that we don't feel is valid

Comments

@aamrute-idnow
Copy link

aamrute-idnow commented Apr 14, 2021 •
edited
Loading

Bug Report

Current Behavior

Redis instance : 3 Sentinel, 2 Redis node ( 1 master, 1 replica)

Scenario :
During application runtime, Redis Master node + 1 Sentinel node not responding (port accept connection but do not respond)

Client Behavior :
Redis command throws timeout exception (which is okay). But it should also make reconnect. If application open new connection at this point, then first sentinel node fail, but application pick the second sentinel and able to establish connection to new redis master.

On server side sentinel able to detect such unhealthy node and elect new master immoderately.

Stack trace 
io.lettuce.core.RedisCommandTimeoutException: Command timed out after 5 second(s)
        at io.lettuce.core.internal.ExceptionFactory.createTimeoutException(ExceptionFactory.java:53)
        at io.lettuce.core.protocol.CommandExpiryWriter.lambda$potentiallyExpire$0(CommandExpiryWriter.java:172)
        at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
        at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)
        at io.netty.util.concurrent.DefaultEventExecutor.run(DefaultEventExecutor.java:66)
        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:834)
Further DEBUG Log 
DEBUG - i.l.c.p.DefaultEndpoint - [channel=0x676b1852, /127.0.0.1:47118 -> /127.0.0.1:6379, epid=0x1] write() writeAndFlush command AsyncCommand [type=EXPIRE, output=BooleanOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
DEBUG - i.l.c.p.DefaultEndpoint - [channel=0x676b1852, /127.0.0.1:47118 -> /127.0.0.1:6379, epid=0x1] write() done
DEBUG - i.l.c.p.CommandHandler - [channel=0x676b1852, /127.0.0.1:47118 -> /127.0.0.1:6379, epid=0x1, chid=0x2] write(ctx, AsyncCommand [type=EXPIRE, output=BooleanOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], promise)
DEBUG - i.l.c.p.CommandEncoder - [channel=0x676b1852, /127.0.0.1:47118 -> /127.0.0.1:6379] writing command AsyncCommand [type=EXPIRE, output=BooleanOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]

Further client do make reconnect but only after 10 min when netty throw below exception

DEBUG - i.l.c.p.CommandHandler - [channel=0x676b1852, /127.0.0.1:47118 -> /127.0.0.1:6379, epid=0x1, chid=0x2] Unexpected exception during request: java.io.IOException: Connection reset by peer
java.io.IOException: Connection reset by peer
        at java.base/sun.nio.ch.FileDispatcherImpl.read0(Native Method)
        at java.base/sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
        at java.base/sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:276)
        at java.base/sun.nio.ch.IOUtil.read(IOUtil.java:233)
        at java.base/sun.nio.ch.IOUtil.read(IOUtil.java:223)
        at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:358)
        at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:253)
        at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132)
        at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:350)
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151)
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
        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:834)

Input Code

Input Code 
                final RedisURI redisUri = getRedisURI(redisConfig, withSsl);
		RedisClient redisClient = RedisClient.create(redisUri);
		final SocketOptions socketOptions = SocketOptions.builder()
				.connectTimeout(Duration.ofMillis(200))
				.build();
		final ClientOptions.Builder builder = ClientOptions.builder()
				.pingBeforeActivateConnection(true)
				.socketOptions(socketOptions)
				.autoReconnect(true).timeoutOptions(TimeoutOptions.enabled(Duration.ofSeconds(5)));
		redisClient.setOptions(builder.build());
		redisClient.setDefaultTimeout(Duration.ofSeconds(5));

Expected behavior/code

When command throw timeout exception, client should trigger autoreconnect immediately and try again with new connection.

Environment

  • Lettuce version(s): 6.1.1.RELEASE
  • Redis version: 6.2.1
@aamrute-idnow aamrute-idnow changed the title Redis reconnect do not work if command timeout Auto reconnect do not work if command timeout Apr 14, 2021
@mp911de
Copy link
Collaborator

mp911de commented Apr 14, 2021

java.io.IOException: Connection reset by peer isn't something that a client can do something about. Can you provide a bit more context such as the logs, whether specifically there are reconnect attempts and what happens during reconnect attemps=

@mp911de mp911de added the status: waiting-for-feedback We need additional information before we can continue label Apr 14, 2021
@aamrute-idnow
Copy link
Author

aamrute-idnow commented Apr 14, 2021 •
edited
Loading

@mp911de Reconnect attempt happens only after java.io.IOException: Connection reset by peer and reconnect itself worked fine, as it is able to find working sentinel and establish new connection.

My issue is, Reconnect happened too late.

Here is sequence of operation

Step 1 : Application create healthy connection with redis (i.e. when all sentinel and redis nodes up and running). I have only one StatefulRedisConnection in application, shared between multiple thread.

Step 2: Master nodes goes into strange state (port do not respond). At this point application makes multiple RedisCommand calls, and all command call return into timeout exception.

Step 3: After ~10 min, I could see exception java.io.IOException: Connection reset by peer, after this io.lettuce.core.protocol.ConnectionWatchdog establish a reconnect scheduler and its finished successfully (first sentinel node timeout, but second node work and able to return new redis master).

If there is Reconnect at step 2 then application do not have downtime for ~ 10 min.

Hope it is clear, otherwise will share logs for each step with you.

@datagitlies
Copy link

datagitlies commented May 12, 2021 •
edited
Loading

@mp911de I'm having a similar issue as @aamrute-idnow where it appears that lettuce is sometimes having problems reconnecting to the server after a connection is closed. The client application will have problems for ~ 10 min and then finally reconnect to the server (during that period all commands except for PING will timeout). In my case, I know why the connection is being closed - it's because our server has timeout 300 in redis.conf which will close the connection after a client is idle for 300 seconds. Our client application sits idle most of the day but runs batches of work at night. I'm using lettuce-core : 6.0.4.RELEASE and our server is version 5.0.6 - I'm happy to share more / provide logs etc. Right now I'm working to repeat this on my local machine but so far not having a ton of luck.

Below is what the stack trace looks like when the connection is closed by the server after 300 seconds of idle time.

INFO - io.lettuce.core.protocol.CommandHandler  : [channel=0x47606e1c, /127.0.0.1:58198 -> localhost/127.0.0.1:6379, chid=0x8] Unexpected exception during request: java.io.IOException: An existing connection was forcibly closed by the remote host
java.io.IOException: An existing connection was forcibly closed by the remote host
	at sun.nio.ch.SocketDispatcher.read0(Native Method)
	at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:43)
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
	at sun.nio.ch.IOUtil.read(IOUtil.java:192)
	at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:377)
	at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:253)
	at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132)
	at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:350)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
	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.lang.Thread.run(Thread.java:748)

EDIT: one thing I have observed is that all of the PING commands return successfully (we have pingBeforeActivateConnection set to true) even while all of the other commands like GET / SET / INFO timeout. We have the following settings in our client application:

spring:
  redis:
    connect-timeout: PT0.3S
    timeout: PT0.5S

@datagitlies
Copy link

@mp911de I've managed to capture the events which are allowing my client application to recover its Redis connection after ~10 minutes of timeouts. I think it's when the CommandHandler.exceptionCaught method is being invoked. Once the two events below are logged, everything returns to normal. My thought is ... why did it take so long for this method to be invoked and the connection recovered?

DEBUG io.lettuce.core.protocol.CommandHandler [channel=0xf8804f21, /###.###.###.###:49594 -> redis.acme.co/###.###.###.###:6379, chid=0xc3] Storing exception in LatencyMeteredCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.TracedCommand]	
DEBUG io.lettuce.core.protocol.CommandHandler [channel=0xf8804f21, /###.###.###.###:49594 -> redis.acme.co/###.###.###.###:6379, chid=0xc3] Unexpected exception during request: java.io.IOException: Connection timed out	java.io.IOException: Connection timed out
	at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
	at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
	at sun.nio.ch.IOUtil.read(IOUtil.java:192)
	at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:379)
	at io.netty.buffer.UnpooledDirectByteBuf.setBytes(UnpooledDirectByteBuf.java:570)
	at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132)
	at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:350)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
	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.lang.Thread.run(Thread.java:748)

Expand the section below to see the the full series of events that occurred:

events in context 
2021-05-14T00:46:05.549Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xf8804f21, /###.###.###.###:49594 -> redis.acme.co/###.###.###.###:6379, chid=0xc3] write(ctx, TracedCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.AsyncCommand], promise)	
2021-05-14T00:46:06.050Z	http-nio-8080-exec-7			WARN	co.acme.RedisCacheErrorHandler						Redis command timed out	org.springframework.dao.QueryTimeoutException: Redis command timed out; nested exception is io.lettuce.core.RedisCommandTimeoutException: Command timed out after 500 millisecond(s)
	at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:70)
	at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:41)
	at org.springframework.data.redis.PassThroughExceptionTranslationStrategy.translate(PassThroughExceptionTranslationStrategy.java:44)
	at org.springframework.data.redis.FallbackExceptionTranslationStrategy.translate(FallbackExceptionTranslationStrategy.java:42)
	at org.springframework.data.redis.connection.lettuce.LettuceConnection.convertLettuceAccessException(LettuceConnection.java:274)
	at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.convertLettuceAccessException(LettuceStringCommands.java:800)
	at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.get(LettuceStringCommands.java:70)
	at org.springframework.data.redis.connection.DefaultedRedisConnection.get(DefaultedRedisConnection.java:267)
	at org.springframework.data.redis.cache.DefaultRedisCacheWriter.lambda$get$1(DefaultRedisCacheWriter.java:126)
	at org.springframework.data.redis.cache.DefaultRedisCacheWriter.execute(DefaultRedisCacheWriter.java:304)
	at org.springframework.data.redis.cache.DefaultRedisCacheWriter.get(DefaultRedisCacheWriter.java:126)
	at org.springframework.data.redis.cache.RedisCache.lookup(RedisCache.java:88)
	at org.springframework.cache.support.AbstractValueAdaptingCache.get(AbstractValueAdaptingCache.java:58)
	at org.springframework.cache.interceptor.AbstractCacheInvoker.doGet(AbstractCacheInvoker.java:73)
	at org.springframework.cache.interceptor.CacheAspectSupport.findInCaches(CacheAspectSupport.java:571)
	at org.springframework.cache.interceptor.CacheAspectSupport.findCachedItem(CacheAspectSupport.java:536)
	at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:402)
	at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:345)
	at org.springframework.cache.interceptor.CacheInterceptor.invoke(CacheInterceptor.java:64)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692)
	at co.acme.data.ValueCache$$EnhancerBySpringCGLIB$$419be9df.retrieveAllowedValues(<generated>)
	at ommitted.for.Brevity.foo(Brevity.java:55)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
	at net.rakugakibox.spring.boot.logback.access.tomcat.LogbackAccessTomcatValve.invoke(LogbackAccessTomcatValve.java:91)
	at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:764)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:893)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1707)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:748)
Caused by: io.lettuce.core.RedisCommandTimeoutException: Command timed out after 500 millisecond(s)
	at io.lettuce.core.internal.ExceptionFactory.createTimeoutException(ExceptionFactory.java:53)
	at io.lettuce.core.protocol.CommandExpiryWriter.lambda$potentiallyExpire$0(CommandExpiryWriter.java:172)
	at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
	at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)
	at io.netty.util.concurrent.DefaultEventExecutor.run(DefaultEventExecutor.java:66)
	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)
	... 1 common frames omitted

2021-05-14T00:46:06.056Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xf8804f21, /###.###.###.###:49594 -> redis.acme.co/###.###.###.###:6379, chid=0xc3] write(ctx, TracedCommand [type=SET, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.AsyncCommand], promise)	
2021-05-14T00:46:06.558Z	http-nio-8080-exec-7			WARN	co.acme.RedisCacheErrorHandler						Redis command timed out	org.springframework.dao.QueryTimeoutException: Redis command timed out; nested exception is io.lettuce.core.RedisCommandTimeoutException: Command timed out after 500 millisecond(s)
	at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:70)
	at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:41)
	at org.springframework.data.redis.PassThroughExceptionTranslationStrategy.translate(PassThroughExceptionTranslationStrategy.java:44)
	at org.springframework.data.redis.FallbackExceptionTranslationStrategy.translate(FallbackExceptionTranslationStrategy.java:42)
	at org.springframework.data.redis.connection.lettuce.LettuceConnection.convertLettuceAccessException(LettuceConnection.java:274)
	at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.convertLettuceAccessException(LettuceStringCommands.java:800)
	at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.set(LettuceStringCommands.java:182)
	at org.springframework.data.redis.connection.DefaultedRedisConnection.set(DefaultedRedisConnection.java:295)
	at org.springframework.data.redis.cache.DefaultRedisCacheWriter.lambda$put$0(DefaultRedisCacheWriter.java:105)
	at org.springframework.data.redis.cache.DefaultRedisCacheWriter.execute(DefaultRedisCacheWriter.java:304)
	at org.springframework.data.redis.cache.DefaultRedisCacheWriter.put(DefaultRedisCacheWriter.java:102)
	at org.springframework.data.redis.cache.RedisCache.put(RedisCache.java:150)
	at org.springframework.cache.interceptor.AbstractCacheInvoker.doPut(AbstractCacheInvoker.java:87)
	at org.springframework.cache.interceptor.CacheAspectSupport$CachePutRequest.apply(CacheAspectSupport.java:837)
	at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:430)
	at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:345)
	at org.springframework.cache.interceptor.CacheInterceptor.invoke(CacheInterceptor.java:64)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692)
	at co.acme.data.ValueCache$$EnhancerBySpringCGLIB$$419be9df.retrieveAllowedValues(<generated>)
	at ommitted.for.Brevity.foo(Brevity.java:55)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
	at net.rakugakibox.spring.boot.logback.access.tomcat.LogbackAccessTomcatValve.invoke(LogbackAccessTomcatValve.java:91)
	at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:764)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:893)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1707)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:748)
Caused by: io.lettuce.core.RedisCommandTimeoutException: Command timed out after 500 millisecond(s)
	at io.lettuce.core.internal.ExceptionFactory.createTimeoutException(ExceptionFactory.java:53)
	at io.lettuce.core.protocol.CommandExpiryWriter.lambda$potentiallyExpire$0(CommandExpiryWriter.java:172)
	at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
	at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)
	at io.netty.util.concurrent.DefaultEventExecutor.run(DefaultEventExecutor.java:66)
	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)
	... 1 common frames omitted

2021-05-14T00:46:13.095Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xf8804f21, /###.###.###.###:49594 -> redis.acme.co/###.###.###.###:6379, chid=0xc3] Storing exception in LatencyMeteredCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.TracedCommand]	
2021-05-14T00:46:13.096Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xf8804f21, /###.###.###.###:49594 -> redis.acme.co/###.###.###.###:6379, chid=0xc3] channelInactive()	
2021-05-14T00:46:13.096Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xf8804f21, /###.###.###.###:49594 -> redis.acme.co/###.###.###.###:6379, chid=0xc3] channelInactive() done	
2021-05-14T00:46:13.096Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xf8804f21, /###.###.###.###:49594 -> redis.acme.co/###.###.###.###:6379, chid=0xc3] channelUnregistered()	
2021-05-14T00:46:13.096Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.ConnectionWatchdog				[channel=0xf8804f21, /###.###.###.###:49594 -> redis.acme.co/###.###.###.###:6379, last known addr=redis.acme.co/###.###.###.###:6379] Reconnect attempt 1, delay 1ms	
2021-05-14T00:46:13.096Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.ConnectionWatchdog				[channel=0xf8804f21, /###.###.###.###:49594 -> redis.acme.co/###.###.###.###:6379, last known addr=redis.acme.co/###.###.###.###:6379] scheduleReconnect()	
2021-05-14T00:46:13.096Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xf8804f21, /###.###.###.###:49594 -> redis.acme.co/###.###.###.###:6379, chid=0xc3] Unexpected exception during request: java.io.IOException: Connection timed out	java.io.IOException: Connection timed out
	at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
	at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
	at sun.nio.ch.IOUtil.read(IOUtil.java:192)
	at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:379)
	at io.netty.buffer.UnpooledDirectByteBuf.setBytes(UnpooledDirectByteBuf.java:570)
	at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132)
	at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:350)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:151)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
	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.lang.Thread.run(Thread.java:748)

2021-05-14T00:46:13.096Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.ConnectionWatchdog				[channel=0xf8804f21, /###.###.###.###:49594 -> redis.acme.co/###.###.###.###:6379, last known addr=redis.acme.co/###.###.###.###:6379] channelInactive()	
2021-05-14T00:46:13.137Z	lettuce-eventExecutorLoop-1-8		INFO	io.lettuce.core.protocol.ConnectionWatchdog				Reconnecting, last destination was redis.acme.co/###.###.###.###:6379	
2021-05-14T00:46:13.139Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, [id: 0x14361459] (inactive), chid=0x194] channelRegistered()	
2021-05-14T00:46:13.140Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] write(ctx, AsyncCommand [type=HELLO, output=GenericMapOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], promise)	
2021-05-14T00:46:13.141Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] Received: 63 bytes, 1 commands in the stack	
2021-05-14T00:46:13.141Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] Stack contains: 1 commands	
2021-05-14T00:46:13.141Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] Completing command LatencyMeteredCommand [type=HELLO, output=GenericMapOutput [output=null, error='ERR unknown command `HELLO`, with args beginning with: `3`, '], commandType=io.lettuce.core.protocol.AsyncCommand]	
2021-05-14T00:46:13.141Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] write(ctx, AsyncCommand [type=PING, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], promise)	
2021-05-14T00:46:13.142Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] channelActive()	
2021-05-14T00:46:13.142Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] Received: 7 bytes, 1 commands in the stack	
2021-05-14T00:46:13.142Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] Completing command LatencyMeteredCommand [type=PING, output=StatusOutput [output=PONG, error='null'], commandType=io.lettuce.core.protocol.AsyncCommand]	
2021-05-14T00:46:13.142Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] Stack contains: 1 commands	
2021-05-14T00:46:13.143Z	lettuce-nioEventLoop-4-4		INFO	io.lettuce.core.protocol.ReconnectionHandler				Reconnected to redis.acme.co:6379	
2021-05-14T00:46:13.143Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] channelActive() done	
2021-05-14T00:46:13.143Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.ConnectionWatchdog				[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, last known addr=redis.acme.co/###.###.###.###:6379] channelActive()	
2021-05-14T00:46:13.157Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] Received: 188 bytes, 1 commands in the stack	
2021-05-14T00:46:13.157Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] Stack contains: 1 commands	
2021-05-14T00:46:13.157Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] Completing command LatencyMeteredCommand [type=GET, output=ValueOutput [output=[B@5cd6a20b, error='null'], commandType=io.lettuce.core.protocol.TracedCommand]	
2021-05-14T00:46:13.157Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] write(ctx, TracedCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.AsyncCommand], promise)	
2021-05-14T00:46:21.146Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] write(ctx, TracedCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.AsyncCommand], promise)	
2021-05-14T00:46:21.147Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] Stack contains: 1 commands	
2021-05-14T00:46:21.147Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] Completing command LatencyMeteredCommand [type=GET, output=ValueOutput [output=[B@bfcfb71, error='null'], commandType=io.lettuce.core.protocol.TracedCommand]	
2021-05-14T00:46:21.147Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] Received: 188 bytes, 1 commands in the stack	
2021-05-14T00:46:29.111Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] write(ctx, TracedCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.AsyncCommand], promise)	
2021-05-14T00:46:29.112Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] Received: 188 bytes, 1 commands in the stack	
2021-05-14T00:46:29.112Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] Completing command LatencyMeteredCommand [type=GET, output=ValueOutput [output=[B@15b2c38f, error='null'], commandType=io.lettuce.core.protocol.TracedCommand]	
2021-05-14T00:46:29.112Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] Stack contains: 1 commands	
2021-05-14T00:46:31.660Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] write(ctx, TracedCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.AsyncCommand], promise)	
2021-05-14T00:46:31.661Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] Stack contains: 1 commands	
2021-05-14T00:46:31.661Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] Completing command LatencyMeteredCommand [type=GET, output=ValueOutput [output=[B@7b5a97f3, error='null'], commandType=io.lettuce.core.protocol.TracedCommand]	
2021-05-14T00:46:31.661Z	lettuce-nioEventLoop-4-4		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xa9ee0a54, /###.###.###.###:38804 -> redis.acme.co/###.###.###.###:6379, chid=0x194] Received: 188 bytes, 1 commands in the stack

@mp911de
Copy link
Collaborator

mp911de commented May 17, 2021

java.io.IOException: Connection timed out means that the remote peer didn't acknowledge TCP packets within the TCP timeout which is OS-specific. There's nothing Lettuce can do because everything is just a consequence of the TCP flow.

Reconnect happens within a few ms which is a good sign that the connection could be re-established rather quickly.

Since this ticket's isn't actionable, I'm closing it.

@mp911de mp911de closed this as completed May 17, 2021
@mp911de mp911de added status: invalid An issue that we don't feel is valid and removed status: waiting-for-feedback We need additional information before we can continue labels May 17, 2021
@datagitlies
Copy link

java.io.IOException: Connection timed out means that the remote peer didn't acknowledge TCP packets within the TCP timeout which is OS-specific. There's nothing Lettuce can do because everything is just a consequence of the TCP flow.

Reconnect happens within a few ms which is a good sign that the connection could be re-established rather quickly.

Since this ticket's isn't actionable, I'm closing it.

Is that to imply that I am missing a timeout setting somewhere @mp911de? Because I wouldn't expect it to take 10 - 15 MINUTES to reach this timeout condition given that I have the below configuration in my application:

spring:
  redis:
    connect-timeout: PT0.3S
    timeout: PT0.5S

If you know which timeout setting I am missing, please do share as I'm considering moving to Jedis to see if it fares any better.

@mp911de
Copy link
Collaborator

mp911de commented May 17, 2021

The timeout isn't configurable. Check out https://stackoverflow.com/questions/25490451/meaning-of-java-io-ioexception-connection-timed-out-after-connect-phase for further details.

@datagitlies
Copy link

datagitlies commented May 17, 2021 •
edited
Loading

Ugh... thanks @mp911de - I started thinking my issue was network related, then moved to looking deeper at lettuce-core, and now I'm right back where I started (network). Do you think setting keepAlive=true via SocketOptions would help at all? These disconnects must be happening in a rather crude way (leaving my connection(s) in an odd state - waiting for that OS level timeout to finally hit). I'm starting to think that something within our network is killing my connections after they sit idle for 20 + hours. But the odd thing is I can see connections being dropped and reestablished in the logs every 5 min (300s) because our Redis server has timeout 300 in the redis.conf which I would think would prevent this situation completely. It's all just not adding up.

EDIT: it's almost as if the application is using the wrong connection / event loop thread if I look deeper at which threads are doing the logging:

  • lettuce-nioEventLoop-4-1
  • lettuce-nioEventLoop-4-2
  • lettuce-nioEventLoop-4-3
  • lettuce-nioEventLoop-4-4
  • etc.
  • etc.

@datagitlies
Copy link

I believe I have confirmed my suspicion above @mp911de - I can see that my application is stuck using the same channel (channel=0xf8804f21) and port (49594) over and over when it's having the timeout issues even though there are logs detailing that connections are being reestablished every 5 minutes on a different channel (channel=0x6d886c48) and port (34596) but then these new connections are never picked up or used. Something isn't right. My application has "good" connections to Redis (I even see successful HELLO and PING commands going over the new channel / port) but for some reason the application is not using these.

@mp911de
Copy link
Collaborator

mp911de commented May 17, 2021

Enabling keep-alive helps for sure with dead peer detection to detect outages earlier. IMO Redis inactivity disconnects are a bad fix for an unrelated problem so disabling the inactivity timeout on Redis would remove at least some reconnects.

Note that netty uses typically a different thread for each new connection.

@datagitlies
Copy link

Expand the section further below to see this series of events in my logs:

  1. timeouts occurring via channel 0xf8804f21 and port 49594
  2. a new channel 0xff302421 establishing a new connection via port 38120
  3. successful commands HELLO and PING being sent via the new channel / port
  4. timeouts continuing to occur via the old channel / port

This pattern repeats for 10 to 15 minutes before the application finally snaps out of it and starts using a good connection. Any idea why lettuce is continuing to use the old channel / port @mp911de?

exand to see the pattern / logs 
2021-05-14T00:45:08.023Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xf8804f21, /###.###.###.###:49594 -> redis.acme.co/###.###.###.###:6379, chid=0xc3] write(ctx, TracedCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.AsyncCommand], promise)	
2021-05-14T00:45:08.525Z	http-nio-8080-exec-6			WARN	co.acme.RedisCacheErrorHandler						Redis command timed out	org.springframework.dao.QueryTimeoutException: Redis command timed out; nested exception is io.lettuce.core.RedisCommandTimeoutException: Command timed out after 500 millisecond(s)
	at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:70)
	at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:41)
	at org.springframework.data.redis.PassThroughExceptionTranslationStrategy.translate(PassThroughExceptionTranslationStrategy.java:44)
	at org.springframework.data.redis.FallbackExceptionTranslationStrategy.translate(FallbackExceptionTranslationStrategy.java:42)
	at org.springframework.data.redis.connection.lettuce.LettuceConnection.convertLettuceAccessException(LettuceConnection.java:274)
	at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.convertLettuceAccessException(LettuceStringCommands.java:800)
	at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.get(LettuceStringCommands.java:70)
	at org.springframework.data.redis.connection.DefaultedRedisConnection.get(DefaultedRedisConnection.java:267)
	at org.springframework.data.redis.cache.DefaultRedisCacheWriter.lambda$get$1(DefaultRedisCacheWriter.java:126)
	at org.springframework.data.redis.cache.DefaultRedisCacheWriter.execute(DefaultRedisCacheWriter.java:304)
	at org.springframework.data.redis.cache.DefaultRedisCacheWriter.get(DefaultRedisCacheWriter.java:126)
	at org.springframework.data.redis.cache.RedisCache.lookup(RedisCache.java:88)
	at org.springframework.cache.support.AbstractValueAdaptingCache.get(AbstractValueAdaptingCache.java:58)
	at org.springframework.cache.interceptor.AbstractCacheInvoker.doGet(AbstractCacheInvoker.java:73)
	at org.springframework.cache.interceptor.CacheAspectSupport.findInCaches(CacheAspectSupport.java:571)
	at org.springframework.cache.interceptor.CacheAspectSupport.findCachedItem(CacheAspectSupport.java:536)
	at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:402)
	at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:345)
	at org.springframework.cache.interceptor.CacheInterceptor.invoke(CacheInterceptor.java:64)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692)
	at co.acme.data.ValueCache$$EnhancerBySpringCGLIB$$419be9df.retrieveAllowedValues(<generated>)
	at ommitted.for.Brevity.foo(Brevity.java:55)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
	at net.rakugakibox.spring.boot.logback.access.tomcat.LogbackAccessTomcatValve.invoke(LogbackAccessTomcatValve.java:91)
	at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:764)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:893)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1707)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:748)
Caused by: io.lettuce.core.RedisCommandTimeoutException: Command timed out after 500 millisecond(s)
	at io.lettuce.core.internal.ExceptionFactory.createTimeoutException(ExceptionFactory.java:53)
	at io.lettuce.core.internal.Futures.awaitOrCancel(Futures.java:246)
	at io.lettuce.core.FutureSyncInvocationHandler.handleInvocation(FutureSyncInvocationHandler.java:75)
	at io.lettuce.core.internal.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:80)
	at com.sun.proxy.$Proxy275.get(Unknown Source)
	at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.get(LettuceStringCommands.java:68)
	... 137 common frames omitted

2021-05-14T00:45:08.530Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xf8804f21, /###.###.###.###:49594 -> redis.acme.co/###.###.###.###:6379, chid=0xc3] write(ctx, TracedCommand [type=SET, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.AsyncCommand], promise)	
2021-05-14T00:45:09.032Z	http-nio-8080-exec-6			WARN	co.acme.RedisCacheErrorHandler						Redis command timed out	org.springframework.dao.QueryTimeoutException: Redis command timed out; nested exception is io.lettuce.core.RedisCommandTimeoutException: Command timed out after 500 millisecond(s)
	at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:70)
	at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:41)
	at org.springframework.data.redis.PassThroughExceptionTranslationStrategy.translate(PassThroughExceptionTranslationStrategy.java:44)
	at org.springframework.data.redis.FallbackExceptionTranslationStrategy.translate(FallbackExceptionTranslationStrategy.java:42)
	at org.springframework.data.redis.connection.lettuce.LettuceConnection.convertLettuceAccessException(LettuceConnection.java:274)
	at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.convertLettuceAccessException(LettuceStringCommands.java:800)
	at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.set(LettuceStringCommands.java:182)
	at org.springframework.data.redis.connection.DefaultedRedisConnection.set(DefaultedRedisConnection.java:295)
	at org.springframework.data.redis.cache.DefaultRedisCacheWriter.lambda$put$0(DefaultRedisCacheWriter.java:105)
	at org.springframework.data.redis.cache.DefaultRedisCacheWriter.execute(DefaultRedisCacheWriter.java:304)
	at org.springframework.data.redis.cache.DefaultRedisCacheWriter.put(DefaultRedisCacheWriter.java:102)
	at org.springframework.data.redis.cache.RedisCache.put(RedisCache.java:150)
	at org.springframework.cache.interceptor.AbstractCacheInvoker.doPut(AbstractCacheInvoker.java:87)
	at org.springframework.cache.interceptor.CacheAspectSupport$CachePutRequest.apply(CacheAspectSupport.java:837)
	at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:430)
	at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:345)
	at org.springframework.cache.interceptor.CacheInterceptor.invoke(CacheInterceptor.java:64)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692)
	at co.acme.data.ValueCache$$EnhancerBySpringCGLIB$$419be9df.retrieveAllowedValues(<generated>)
	at ommitted.for.Brevity.foo(Brevity.java:55)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
	at net.rakugakibox.spring.boot.logback.access.tomcat.LogbackAccessTomcatValve.invoke(LogbackAccessTomcatValve.java:91)
	at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:764)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:893)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1707)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:748)
Caused by: io.lettuce.core.RedisCommandTimeoutException: Command timed out after 500 millisecond(s)
	at io.lettuce.core.internal.ExceptionFactory.createTimeoutException(ExceptionFactory.java:53)
	at io.lettuce.core.protocol.CommandExpiryWriter.lambda$potentiallyExpire$0(CommandExpiryWriter.java:172)
	at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
	at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:170)
	at io.netty.util.concurrent.DefaultEventExecutor.run(DefaultEventExecutor.java:66)
	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)
	... 1 common frames omitted

2021-05-14T00:45:12.537Z	lettuce-nioEventLoop-4-2		DEBUG	io.lettuce.core.protocol.ConnectionWatchdog				[channel=0x6d886c48, /###.###.###.###:34596 -> redis.acme.co/###.###.###.###:6379, last known addr=redis.acme.co/###.###.###.###:6379] Reconnect attempt 1, delay 1ms	
2021-05-14T00:45:12.537Z	lettuce-nioEventLoop-4-2		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0x6d886c48, /###.###.###.###:34596 -> redis.acme.co/###.###.###.###:6379, chid=0x192] channelInactive()	
2021-05-14T00:45:12.537Z	lettuce-nioEventLoop-4-2		DEBUG	io.lettuce.core.protocol.ConnectionWatchdog				[channel=0x6d886c48, /###.###.###.###:34596 -> redis.acme.co/###.###.###.###:6379, last known addr=redis.acme.co/###.###.###.###:6379] scheduleReconnect()	
2021-05-14T00:45:12.537Z	lettuce-nioEventLoop-4-2		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0x6d886c48, /###.###.###.###:34596 -> redis.acme.co/###.###.###.###:6379, chid=0x192] channelUnregistered()	
2021-05-14T00:45:12.537Z	lettuce-nioEventLoop-4-2		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0x6d886c48, /###.###.###.###:34596 -> redis.acme.co/###.###.###.###:6379, chid=0x192] channelInactive() done	
2021-05-14T00:45:12.537Z	lettuce-nioEventLoop-4-2		DEBUG	io.lettuce.core.protocol.ConnectionWatchdog				[channel=0x6d886c48, /###.###.###.###:34596 -> redis.acme.co/###.###.###.###:6379, last known addr=redis.acme.co/###.###.###.###:6379] channelInactive()	
2021-05-14T00:45:12.638Z	lettuce-eventExecutorLoop-1-5		INFO	io.lettuce.core.protocol.ConnectionWatchdog				Reconnecting, last destination was redis.acme.co/###.###.###.###:6379	
2021-05-14T00:45:12.641Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xff302421, [id: 0xa54f2545] (inactive), chid=0x193] channelRegistered()	
2021-05-14T00:45:12.642Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xff302421, /###.###.###.###:38120 -> redis.acme.co/###.###.###.###:6379, chid=0x193] write(ctx, AsyncCommand [type=HELLO, output=GenericMapOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], promise)	
2021-05-14T00:45:12.643Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xff302421, /###.###.###.###:38120 -> redis.acme.co/###.###.###.###:6379, chid=0x193] Received: 63 bytes, 1 commands in the stack	
2021-05-14T00:45:12.643Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xff302421, /###.###.###.###:38120 -> redis.acme.co/###.###.###.###:6379, chid=0x193] write(ctx, AsyncCommand [type=PING, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], promise)	
2021-05-14T00:45:12.643Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xff302421, /###.###.###.###:38120 -> redis.acme.co/###.###.###.###:6379, chid=0x193] Stack contains: 1 commands	
2021-05-14T00:45:12.643Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xff302421, /###.###.###.###:38120 -> redis.acme.co/###.###.###.###:6379, chid=0x193] Completing command LatencyMeteredCommand [type=HELLO, output=GenericMapOutput [output=null, error='ERR unknown command `HELLO`, with args beginning with: `3`, '], commandType=io.lettuce.core.protocol.AsyncCommand]	
2021-05-14T00:45:12.644Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xff302421, /###.###.###.###:38120 -> redis.acme.co/###.###.###.###:6379, chid=0x193] channelActive()	
2021-05-14T00:45:12.644Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xff302421, /###.###.###.###:38120 -> redis.acme.co/###.###.###.###:6379, chid=0x193] channelActive() done	
2021-05-14T00:45:12.644Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xff302421, /###.###.###.###:38120 -> redis.acme.co/###.###.###.###:6379, chid=0x193] Received: 7 bytes, 1 commands in the stack	
2021-05-14T00:45:12.644Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xff302421, /###.###.###.###:38120 -> redis.acme.co/###.###.###.###:6379, chid=0x193] Completing command LatencyMeteredCommand [type=PING, output=StatusOutput [output=PONG, error='null'], commandType=io.lettuce.core.protocol.AsyncCommand]	
2021-05-14T00:45:12.644Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xff302421, /###.###.###.###:38120 -> redis.acme.co/###.###.###.###:6379, chid=0x193] Stack contains: 1 commands	
2021-05-14T00:45:12.644Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.ConnectionWatchdog				[channel=0xff302421, /###.###.###.###:38120 -> redis.acme.co/###.###.###.###:6379, last known addr=redis.acme.co/###.###.###.###:6379] channelActive()	
2021-05-14T00:45:12.644Z	lettuce-nioEventLoop-4-3		INFO	io.lettuce.core.protocol.ReconnectionHandler			Reconnected to redis.acme.co:6379	
2021-05-14T00:45:13.847Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xf8804f21, /###.###.###.###:49594 -> redis.acme.co/###.###.###.###:6379, chid=0xc3] write(ctx, TracedCommand [type=GET, output=ValueOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.AsyncCommand], promise)	
2021-05-14T00:45:14.348Z	http-nio-8080-exec-10			WARN	co.acme.RedisCacheErrorHandler						Redis command timed out	org.springframework.dao.QueryTimeoutException: Redis command timed out; nested exception is io.lettuce.core.RedisCommandTimeoutException: Command timed out after 500 millisecond(s)
	at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:70)
	at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:41)
	at org.springframework.data.redis.PassThroughExceptionTranslationStrategy.translate(PassThroughExceptionTranslationStrategy.java:44)
	at org.springframework.data.redis.FallbackExceptionTranslationStrategy.translate(FallbackExceptionTranslationStrategy.java:42)
	at org.springframework.data.redis.connection.lettuce.LettuceConnection.convertLettuceAccessException(LettuceConnection.java:274)
	at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.convertLettuceAccessException(LettuceStringCommands.java:800)
	at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.get(LettuceStringCommands.java:70)
	at org.springframework.data.redis.connection.DefaultedRedisConnection.get(DefaultedRedisConnection.java:267)
	at org.springframework.data.redis.cache.DefaultRedisCacheWriter.lambda$get$1(DefaultRedisCacheWriter.java:126)
	at org.springframework.data.redis.cache.DefaultRedisCacheWriter.execute(DefaultRedisCacheWriter.java:304)
	at org.springframework.data.redis.cache.DefaultRedisCacheWriter.get(DefaultRedisCacheWriter.java:126)
	at org.springframework.data.redis.cache.RedisCache.lookup(RedisCache.java:88)
	at org.springframework.cache.support.AbstractValueAdaptingCache.get(AbstractValueAdaptingCache.java:58)
	at org.springframework.cache.interceptor.AbstractCacheInvoker.doGet(AbstractCacheInvoker.java:73)
	at org.springframework.cache.interceptor.CacheAspectSupport.findInCaches(CacheAspectSupport.java:571)
	at org.springframework.cache.interceptor.CacheAspectSupport.findCachedItem(CacheAspectSupport.java:536)
	at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:402)
	at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:345)
	at org.springframework.cache.interceptor.CacheInterceptor.invoke(CacheInterceptor.java:64)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692)
	at co.acme.data.ValueCache$$EnhancerBySpringCGLIB$$419be9df.retrieveAllowedValues(<generated>)
	at ommitted.for.Brevity.foo(Brevity.java:55)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
	at net.rakugakibox.spring.boot.logback.access.tomcat.LogbackAccessTomcatValve.invoke(LogbackAccessTomcatValve.java:91)
	at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:764)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:893)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1707)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:748)
Caused by: io.lettuce.core.RedisCommandTimeoutException: Command timed out after 500 millisecond(s)
	at io.lettuce.core.internal.ExceptionFactory.createTimeoutException(ExceptionFactory.java:53)
	at io.lettuce.core.internal.Futures.awaitOrCancel(Futures.java:246)
	at io.lettuce.core.FutureSyncInvocationHandler.handleInvocation(FutureSyncInvocationHandler.java:75)
	at io.lettuce.core.internal.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:80)
	at com.sun.proxy.$Proxy275.get(Unknown Source)
	at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.get(LettuceStringCommands.java:68)
	... 137 common frames omitted

2021-05-14T00:45:14.373Z	lettuce-nioEventLoop-4-3		DEBUG	io.lettuce.core.protocol.CommandHandler					[channel=0xf8804f21, /###.###.###.###:49594 -> redis.acme.co/###.###.###.###:6379, chid=0xc3] write(ctx, TracedCommand [type=SET, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.AsyncCommand], promise)	
2021-05-14T00:45:14.875Z	http-nio-8080-exec-10			WARN	co.acme.RedisCacheErrorHandler						Redis command timed out	org.springframework.dao.QueryTimeoutException: Redis command timed out; nested exception is io.lettuce.core.RedisCommandTimeoutException: Command timed out after 500 millisecond(s)
	at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:70)
	at org.springframework.data.redis.connection.lettuce.LettuceExceptionConverter.convert(LettuceExceptionConverter.java:41)
	at org.springframework.data.redis.PassThroughExceptionTranslationStrategy.translate(PassThroughExceptionTranslationStrategy.java:44)
	at org.springframework.data.redis.FallbackExceptionTranslationStrategy.translate(FallbackExceptionTranslationStrategy.java:42)
	at org.springframework.data.redis.connection.lettuce.LettuceConnection.convertLettuceAccessException(LettuceConnection.java:274)
	at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.convertLettuceAccessException(LettuceStringCommands.java:800)
	at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.set(LettuceStringCommands.java:182)
	at org.springframework.data.redis.connection.DefaultedRedisConnection.set(DefaultedRedisConnection.java:295)
	at org.springframework.data.redis.cache.DefaultRedisCacheWriter.lambda$put$0(DefaultRedisCacheWriter.java:105)
	at org.springframework.data.redis.cache.DefaultRedisCacheWriter.execute(DefaultRedisCacheWriter.java:304)
	at org.springframework.data.redis.cache.DefaultRedisCacheWriter.put(DefaultRedisCacheWriter.java:102)
	at org.springframework.data.redis.cache.RedisCache.put(RedisCache.java:150)
	at org.springframework.cache.interceptor.AbstractCacheInvoker.doPut(AbstractCacheInvoker.java:87)
	at org.springframework.cache.interceptor.CacheAspectSupport$CachePutRequest.apply(CacheAspectSupport.java:837)
	at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:430)
	at org.springframework.cache.interceptor.CacheAspectSupport.execute(CacheAspectSupport.java:345)
	at org.springframework.cache.interceptor.CacheInterceptor.invoke(CacheInterceptor.java:64)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
	at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:750)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:692)
	at co.acme.data.ValueCache$$EnhancerBySpringCGLIB$$419be9df.retrieveAllowedValues(<generated>)
	at ommitted.for.Brevity.foo(Brevity.java:55)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
	at net.rakugakibox.spring.boot.logback.access.tomcat.LogbackAccessTomcatValve.invoke(LogbackAccessTomcatValve.java:91)
	at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:764)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:893)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1707)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:748)
Caused by: io.lettuce.core.RedisCommandTimeoutException: Command timed out after 500 millisecond(s)
	at io.lettuce.core.internal.ExceptionFactory.createTimeoutException(ExceptionFactory.java:53)
	at io.lettuce.core.internal.Futures.awaitOrCancel(Futures.java:246)
	at io.lettuce.core.FutureSyncInvocationHandler.handleInvocation(FutureSyncInvocationHandler.java:75)
	at io.lettuce.core.internal.AbstractInvocationHandler.invoke(AbstractInvocationHandler.java:80)
	at com.sun.proxy.$Proxy275.set(Unknown Source)
	at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.set(LettuceStringCommands.java:180)
	... 135 common frames omitted

@datagitlies
Copy link

I'm finding it hard to believe that lettuce / netty won't allow me to set some sort of higher level timeout and that I'm beholden to the OS level (i.e. not configurable) timeout. What I'm trying to understand now is what exactly netty was doing when it finally encountered the IOException and got things back in working order by calling the CommandHandler.exceptionCaught method . Was it trying to close an already closed connection? Was it trying to open a new connection? Was it sending a Redis command? This just seems like bad design if I can't control the timeout and my application has to wait 10 - 15 minutes for the TCP timeout at the OS level. That's unconscionable!

@mp911de
Copy link
Collaborator

mp911de commented May 19, 2021

Check out the configurable channel options at https://github.com/netty/netty/blob/d34212439068091bcec29a8fad4df82f0a82c638/transport/src/main/java/io/netty/channel/ChannelOption.java#L34.

CommandHandler.exceptionCaught(…) handles exceptions in a way that it propagates the failure to the currently active command without closing the connection.

@datagitlies
Copy link

@mp911de I am using spring-data-redis : 2.4.8 and providing the following configuration:

spring:
  redis:
    connect-timeout: PT0.3S
    timeout: PT0.5S

which (as I'm sure you already know) results in SocketOptions with a connectTimeout that eventually is turned into a ChannelOption via the AbstractRedisClient (I'm using version 6.0.4) see link below:

https://github.com/lettuce-io/lettuce-core/blob/6.0.x/src/main/java/io/lettuce/core/AbstractRedisClient.java#L227

I want to understand why my configured timeouts are not being honored by lettuce or netty.

@mp911de
Copy link
Collaborator

mp911de commented May 19, 2021

The connect timeout applies to the connection phase where the TCP connection gets established. spring.redis.timeout maps to the command timeout (i.e. how long commands are permitted to remain not completed). There's no other timeout to apply.

The general SO_TIMEOUT which is used in blocking arrangements (how long SocketInputStream.read(…) is allowed to block) isn't applicable because we're using non-blocking I/O. From that perspective, which timeouts do seem to you not being honored?

@datagitlies
Copy link

The reason I believe that timeouts are not being honored is because my application's Redis connection is in this bad state for 10-15 minutes which only ends when CommandHandler.exceptionCaught(…) is called with that java.io.IOException: Connection timed out exception I provided above. If the timeouts were being honored everywhere that wouldn't take so long to occur, would it? My application recovers every time after that point and I think it has something to do with what's occurring in DefaultEndpoint.notifyException(...) which is called by CommandHandler.exceptionCaught(…). My goal is to understand why it's taking so long for lettuce to execute that code.

@mp911de
Copy link
Collaborator

mp911de commented May 19, 2021

What do you expect Lettuce/Netty should do? I mean, if there's no reset signal from the remote side and you're not using keep-alive, there's no way to detect the remote peer is down. From the report above commands time out properly at 500ms.

@datagitlies
Copy link

datagitlies commented May 19, 2021 •
edited
Loading

Yes, the commands timeout properly after 500ms (i.e. the timeout is honored). But ALL the commands timeout after 500ms for 10-15 minutes straight. That's pretty strange considering what lettuce / netty are doing in the mean time on another channel / port (issuing HELLO and PING commands - successfully - with no timeout). Did you see my post above with those logs?

EDIT: it's like lettuce / netty know that it has a bad channel / port / connection so it's creating a new one, but cannot use it for some reason. It's waiting for CommandHandler.exceptionCaught(…) to be called. Once that finally happens after 10-15 minutes, all is well again.

@datagitlies
Copy link

@mp911de I ended up setting keepAlive=true via SocketOptions which seems to have helped but I still think something strange is going on when looking at the sequence of events in the debug logs I shared above. But... I'll leave well enough alone now that things are "better" for my application.

@shelltea shelltea mentioned this issue Nov 18, 2022
Closed
4 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
status: invalid An issue that we don't feel is valid
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@mp911de @datagitlies @aamrute-idnow