Inconsistency with connection timeouts

[perlun]

Hi,

We discovered a bug in our code related to connection timeouts. We intended to use them but apparently have failed to do so; we only set the command timeout using an approach like this:

StatefulRedisConnection<String, byte[]> redisConnection = redisClient.connect( StringByteArrayCodec.INSTANCE, redisUri );
redisConnection.setTimeout( Duration.ofMillis( redisServer.getCommandTimeout() ) );

While fixing this, I attempted to set the default timeout for the RedisClient (to override the connection timeout) in this way:

RedisClient redisClient = RedisClient.create( clientResourcesBuilder.build() );
redisClient.setDefaultTimeout( Duration.ofMillis( 5000 ) );

But, interestingly enough, a default timeout of 60 seconds is still being used in this case. 😲 This can be seen by the exception details:

DEBUG 2021-09-29 10:11:10.332 [i.l.c.RedisClient] :: Trying to get a Redis connection for: redis://********************************@localhost:52345
DEBUG 2021-09-29 10:11:10.602 [i.l.c.RedisClient] :: Resolved SocketAddress localhost:52345 using redis://********************************@localhost:52345
DEBUG 2021-09-29 10:11:10.603 [i.l.c.AbstractRedisClient] :: Connecting to Redis at localhost:52345
INFO  2021-09-29 10:11:10.693 [f.h.c.c.r.R.Toxiproxy] :: STDOUT: time="2021-09-29T07:11:10Z" level="info" msg="Accepted client" proxy="[::]:8666" upstream="redis:6379" name="redis:6379" client=172.31.66.1:49756 
INFO  2021-09-29 10:12:10.710 [f.h.c.c.r.R.Toxiproxy] :: STDOUT: time="2021-09-29T07:12:10Z" level="warning" msg="Source terminated" name="redis:6379" bytes=123 err=read tcp 172.31.66.3:43788->172.31.66.2:6379: use of closed network connection 
DEBUG 2021-09-29 10:12:10.712 [i.l.c.AbstractRedisClient] :: Connecting to Redis at localhost:52345, initialization: localhost:52345
io.lettuce.core.RedisCommandTimeoutException: Connection initialization timed out. Command timed out after 1 minute(s)
	at io.lettuce.core.internal.ExceptionFactory.createTimeoutException(ExceptionFactory.java:65)
	at io.lettuce.core.protocol.RedisHandshakeHandler.lambda$channelRegistered$0(RedisHandshakeHandler.java:62)
	at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
	at io.netty.util.concurrent.PromiseTask.run(PromiseTask.java:106)
	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:829)
DEBUG 2021-09-29 10:12:10.713 [i.l.c.RedisChannelHandler] :: close()
DEBUG 2021-09-29 10:12:10.713 [i.l.c.RedisChannelHandler] :: closeAsync()
ERROR 2021-09-29 10:12:10.716 [f.h.c.c.r.RedisServiceRepository] :: Failed connecting to Redis
io.lettuce.core.RedisConnectionException: Unable to connect to localhost:52345
	at io.lettuce.core.RedisConnectionException.create(RedisConnectionException.java:78)
	at io.lettuce.core.RedisConnectionException.create(RedisConnectionException.java:56)
	at io.lettuce.core.AbstractRedisClient.getConnection(AbstractRedisClient.java:320)
	at io.lettuce.core.RedisClient.connect(RedisClient.java:241)
	at fi.hibox.centre.protocol.redis.RedisConnectionProvider.getRedisConnectionForServer(RedisConnectionProvider.java:173)

I looked briefly at the Lettuce code and the RedisHandshakeHandler timeout gets initialized like this:

https://github.com/lettuce-io/lettuce-core/blob/43843bf4bdfb09c492efbcf14667da4293452479/src/main/java/io/lettuce/core/protocol/RedisHandshakeHandler.java#L46-L50

The RedisHandshakeHandler is initialized here:

https://github.com/lettuce-io/lettuce-core/blob/43843bf4bdfb09c492efbcf14667da4293452479/src/main/java/io/lettuce/core/ConnectionBuilder.java#L135-L137

The timeout gets set here:

https://github.com/lettuce-io/lettuce-core/blob/43843bf4bdfb09c492efbcf14667da4293452479/src/main/java/io/lettuce/core/ConnectionBuilder.java#L96-L106

TL;DR: The RedisHandshakeHandler ignores the timeout defined on the RedisClient completely, but overriding it via the RedisURI works fine (tested locally).

Is this by design or should this be considered a bug? What wouuld be the correct semantics here? 🤔 The current behavior feels a bit unexpected, at least to me.

[mp911de]

The RedisURI has precedence over the default timeout. I'm not sure how to think about it since RedisURI.timeout and the default timeout on the client create ambiguity over what shall happen. That method comes from a time where RedisClient could be constructed with host and port. There, a default timeout made sense, nowadays not anymore.

The only place that makes actually sense from the default timeout is the cluster client as Redis Cluster can be configured from multiple URI's and we need a single timeout. RedisClient internally uses the default timeout for URI-less connects (that is when a RedisClient is created for a URI and then calling RedisClient.connect() or connect(RedisCodec)).

I think it makes sense to deprecate the timeout methods and fall back to the URI timeout.

[perlun]

Thanks for the writeup and explaining there history here a bit more in depth. 👍 Deprecating the timeout methods sounds reasonable, but I wanted to also pinpoint another thing:

The current approach (RedisClient.setDefaultTimeout() and RedisURI.Builder.withTimeout()) sets both the connection timeout and the command timeout at the moment. If you want these to have different values, you need to do set either one of these (preferably the URI timeout) to the connection timeout and then, once connected, call the StatefulRedisConnection<K, V>.setTimeout() method to set the default command timeout for the connection in question.

I wonder if it would make sense to distinguish things a bit, something like this:

• RedisURI.Builder.withConnectionTimeout()
• RedisURI.Builder.withCommandTimeout() - these would do what you would expect, set only one of these timeouts
• RedisURI.Builder.withDefaultTimeout() - sets both of these timeouts, for scenarios where you want them to be the same

RedisURI.Builder.withTimeout() could then be deprecated and refer to the .withDefaultTimeout() method instead. I think this would be perhaps most clear. We could also consider just keeping withTimeout() as a method that sets both timeouts, but the API becomes perhaps somewhat less clear that way.

WDYT? I might be able to put some effort into fixing this if you agree it would be good, but would be interesting to hear your thoughts first.

[mp911de]

The timeout on a RedisURI respective connection always concerns the command timeout. We have dedicated other timeouts (connect timeout on SocketOptions, TimeoutOptions for more fine-grained timeout control) as in a lot of cases (e.g. Redis Cluster topology discovery) we need to have a timeout before connecting actually to the cluster.

[perlun]

Ah, thanks! 🙏 This was an incorrect assumption on my part.

[mp911de]

I created #1868 to follow up.

[slovdahl]

The timeout on a RedisURI respective connection always concerns the command timeout. We have dedicated other timeouts (connect timeout on SocketOptions, TimeoutOptions for more fine-grained timeout control)

Does this hold up? 🤔 AFAICT, just setting connect timeout with SocketOptions.Builder#connectTimeout() doesn't have any effect. Setting the default timeout with RedisClient#setDefaultTimeout does not have any effect either. The only way to get the connect timeout overridden seems to be by setting the (supposed command) timeout with RedisURI.Builder#withTimeout.

[wmxl]

@mp911de
What is the nuanced difference between setting a timeout in RedisURI and using TimeoutOptions, especially when no specific command type is given?

Even after setting timeouts on both RedisURI and TimeoutOptions, I've noticed that actual command execution times can exceed these values. Why might this be happening?