Add fallback to RESP2 upon NOPROTO response

[lpellegr]

Bug Report

Current Behavior

Redis.com just upgraded all clusters to version 7.2.0. Since, any connection to the cluster fails with error NOPROTO unsupported protocol version from Lettuce client.

Stack trace

Caused by: io.lettuce.core.RedisConnectionException: Unable to connect to redis-11364.c124.us-central1-1.gce.cloud.redislabs.com/<unresolved>:11364
	at io.lettuce.core.RedisConnectionException.create(RedisConnectionException.java:78) ~[lettuce-core-6.2.5.RELEASE.jar:6.2.5.RELEASE]
	at io.lettuce.core.RedisConnectionException.create(RedisConnectionException.java:56) ~[lettuce-core-6.2.5.RELEASE.jar:6.2.5.RELEASE]
	at io.lettuce.core.AbstractRedisClient.getConnection(AbstractRedisClient.java:350) ~[lettuce-core-6.2.5.RELEASE.jar:6.2.5.RELEASE]
	at io.lettuce.core.RedisClient.connect(RedisClient.java:216) ~[lettuce-core-6.2.5.RELEASE.jar:6.2.5.RELEASE]
	at io.lettuce.core.RedisClient.connect(RedisClient.java:201) ~[lettuce-core-6.2.5.RELEASE.jar:6.2.5.RELEASE]
	at co.ipregistry.api.usage_handler.repository.RedisEventPublisher.<init>(RedisEventPublisher.java:29) ~[classes/:na]
	at java.base/jdk.internal.reflect.DirectConstructorHandleAccessor.newInstance(Unknown Source) ~[na:na]
	at java.base/java.lang.reflect.Constructor.newInstanceWithCaller(Unknown Source) ~[na:na]
	at java.base/java.lang.reflect.Constructor.newInstance(Unknown Source) ~[na:na]
	at org.springframework.beans.BeanUtils.instantiateClass(BeanUtils.java:211) ~[spring-beans-6.0.10.jar:6.0.10]
	... 60 common frames omitted
Caused by: io.lettuce.core.RedisCommandExecutionException: NOPROTO unsupported protocol version
	at io.lettuce.core.internal.ExceptionFactory.createExecutionException(ExceptionFactory.java:147) ~[lettuce-core-6.2.5.RELEASE.jar:6.2.5.RELEASE]
	at io.lettuce.core.internal.ExceptionFactory.createExecutionException(ExceptionFactory.java:116) ~[lettuce-core-6.2.5.RELEASE.jar:6.2.5.RELEASE]
	at io.lettuce.core.protocol.AsyncCommand.completeResult(AsyncCommand.java:120) ~[lettuce-core-6.2.5.RELEASE.jar:6.2.5.RELEASE]
	at io.lettuce.core.protocol.AsyncCommand.complete(AsyncCommand.java:111) ~[lettuce-core-6.2.5.RELEASE.jar:6.2.5.RELEASE]
	at io.lettuce.core.protocol.CommandHandler.complete(CommandHandler.java:747) ~[lettuce-core-6.2.5.RELEASE.jar:6.2.5.RELEASE]
	at io.lettuce.core.protocol.CommandHandler.decode(CommandHandler.java:682) ~[lettuce-core-6.2.5.RELEASE.jar:6.2.5.RELEASE]
	at io.lettuce.core.protocol.CommandHandler.channelRead(CommandHandler.java:599) ~[lettuce-core-6.2.5.RELEASE.jar:6.2.5.RELEASE]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442) ~[netty-transport-4.1.94.Final.jar:4.1.94.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[netty-transport-4.1.94.Final.jar:4.1.94.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412) ~[netty-transport-4.1.94.Final.jar:4.1.94.Final]
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) ~[netty-transport-4.1.94.Final.jar:4.1.94.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440) ~[netty-transport-4.1.94.Final.jar:4.1.94.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420) ~[netty-transport-4.1.94.Final.jar:4.1.94.Final]
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) ~[netty-transport-4.1.94.Final.jar:4.1.94.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) ~[netty-transport-4.1.94.Final.jar:4.1.94.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788) ~[netty-transport-4.1.94.Final.jar:4.1.94.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724) ~[netty-transport-4.1.94.Final.jar:4.1.94.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650) ~[netty-transport-4.1.94.Final.jar:4.1.94.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562) ~[netty-transport-4.1.94.Final.jar:4.1.94.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997) ~[netty-common-4.1.94.Final.jar:4.1.94.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.94.Final.jar:4.1.94.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) ~[netty-common-4.1.94.Final.jar:4.1.94.Final]

Input Code

Input Code

redisClient = RedisClient.create(environmentService.getRedisUri());
redisClient.setOptions(
    ClientOptions.builder().socketOptions(
        SocketOptions.builder().keepAlive(true).build()).build());
redisConnection = redisClient.connect();

redisPubSubConnection = redisClient.connectPubSub();
    redisPubSubConnection.sync().clientSetname("client-app");

Expected behavior/code

No connection error.

Environment

• Lettuce version(s): 6.2.5.RELEASE
• Redis version: 7.2.0

[lpellegr]

It was noticed that forcing RESP2 helps fix the issue:

redisClient.setOptions(
                ClientOptions.builder()
                        .protocolVersion(ProtocolVersion.RESP2).build());

[mp911de]

Please provide additional context. Setting the logger io.lettuce.core.protocol to TRACE logs the handshake sequence and should show something like:

2023-07-20 10:22:43 [DEBUG] [lettuce-nioEventLoop-4-1] [channel=0xc8a6b786, [id: 0xa022ce4e] (inactive), epid=0x1, chid=0x1] channelRegistered() (CommandHandler:206)
2023-07-20 10:22:43 [DEBUG] [lettuce-nioEventLoop-4-1] [channel=0xc8a6b786, /127.0.0.1:57830 -> /127.0.0.1:6479, epid=0x1, chid=0x1] write(ctx, AsyncCommand [type=HELLO, output=GenericMapOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], promise) (CommandHandler:383)
2023-07-20 10:22:43 [DEBUG] [lettuce-nioEventLoop-4-1] [channel=0xc8a6b786, /127.0.0.1:57830 -> /127.0.0.1:6479] writing command AsyncCommand [type=HELLO, output=GenericMapOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command] (CommandEncoder:101)
2023-07-20 10:22:43 [TRACE] [lettuce-nioEventLoop-4-1] [channel=0xc8a6b786, /127.0.0.1:57830 -> /127.0.0.1:6479] Sent: *2
$5
HELLO
$1
3 (CommandEncoder:103)
2023-07-20 10:22:43 [DEBUG] [lettuce-nioEventLoop-4-1] [channel=0xc8a6b786, /127.0.0.1:57830 -> /127.0.0.1:6479, epid=0x1, chid=0x1] Received: 146 bytes, 1 commands in the stack (CommandHandler:578)
2023-07-20 10:22:43 [TRACE] [lettuce-nioEventLoop-4-1] [channel=0xc8a6b786, /127.0.0.1:57830 -> /127.0.0.1:6479, epid=0x1, chid=0x1] Buffer: %7
$6
server
$5
redis
$7
version
$7
7.1.242
$5
proto
:3
$2
id
:3
$4
mode
$10
standalone
$4
role
$6
master
$7
modules
*0 (CommandHandler:593)

[lpellegr]

Thanks for your help. Here are the traces:

2023-07-20T10:36:08.118+02:00 DEBUG 9651 --- [ioEventLoop-4-1] i.lettuce.core.protocol.CommandHandler   : [channel=0x3330ede9, [id: 0x7a36ffea] (inactive), epid=0x1, chid=0x1] channelRegistered()
2023-07-20T10:36:08.250+02:00 DEBUG 9651 --- [ioEventLoop-4-1] i.lettuce.core.protocol.CommandHandler   : [channel=0x3330ede9, /192.168.1.44:55964 -> redis-22334.c124.us-central1-1.gce.cloud.redislabs.com/35.x.y.z:22334, epid=0x1, chid=0x1] write(ctx, AsyncCommand [type=HELLO, output=GenericMapOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], promise)
2023-07-20T10:36:08.252+02:00 DEBUG 9651 --- [ioEventLoop-4-1] i.lettuce.core.protocol.CommandEncoder   : [channel=0x3330ede9, /192.168.1.44:55964 -> redis-22334.c124.us-central1-1.gce.cloud.redislabs.com/35.x.y.z:22334] writing command AsyncCommand [type=HELLO, output=GenericMapOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
2023-07-20T10:36:08.252+02:00 TRACE 9651 --- [ioEventLoop-4-1] i.lettuce.core.protocol.CommandEncoder   : [channel=0x3330ede9, /192.168.1.44:55964 -> redis-22334.c124.us-central1-1.gce.cloud.redislabs.com/35.x.y.z:22334] Sent: *5
$5
HELLO
$1
3
$4
AUTH
$16
app-user
$32
my-app-password
2023-07-20T10:36:08.369+02:00 DEBUG 9651 --- [ioEventLoop-4-1] i.lettuce.core.protocol.CommandHandler   : [channel=0x3330ede9, /192.168.1.44:55964 -> redis-22334.c124.us-central1-1.gce.cloud.redislabs.com/35.x.y.z:22334, epid=0x1, chid=0x1] Received: 39 bytes, 1 commands in the stack
2023-07-20T10:36:08.369+02:00 TRACE 9651 --- [ioEventLoop-4-1] i.lettuce.core.protocol.CommandHandler   : [channel=0x3330ede9, /192.168.1.44:55964 -> redis-22334.c124.us-central1-1.gce.cloud.redislabs.com/35.x.y.z:22334, epid=0x1, chid=0x1] Buffer: -NOPROTO unsupported protocol version
2023-07-20T10:36:08.369+02:00 DEBUG 9651 --- [ioEventLoop-4-1] i.lettuce.core.protocol.CommandHandler   : [channel=0x3330ede9, /192.168.1.44:55964 -> redis-22334.c124.us-central1-1.gce.cloud.redislabs.com/35.x.y.z:22334, epid=0x1, chid=0x1] Stack contains: 1 commands
2023-07-20T10:36:08.370+02:00 DEBUG 9651 --- [ioEventLoop-4-1] i.l.core.protocol.RedisStateMachine      : Decode done, empty stack: true
2023-07-20T10:36:08.370+02:00 DEBUG 9651 --- [ioEventLoop-4-1] i.lettuce.core.protocol.CommandHandler   : [channel=0x3330ede9, /192.168.1.44:55964 -> redis-22334.c124.us-central1-1.gce.cloud.redislabs.com/35.x.y.z:22334, epid=0x1, chid=0x1] Completing command AsyncCommand [type=HELLO, output=GenericMapOutput [output=null, error='NOPROTO unsupported protocol version'], commandType=io.lettuce.core.protocol.Command]
2023-07-20T10:36:08.371+02:00 DEBUG 9651 --- [ioEventLoop-4-1] i.lettuce.core.protocol.DefaultEndpoint  : [unknown, epid=0x1] closeAsync()
2023-07-20T10:36:08.372+02:00 DEBUG 9651 --- [ioEventLoop-4-1] i.lettuce.core.protocol.CommandHandler   : [channel=0x3330ede9, /192.168.1.44:55964 -> redis-22334.c124.us-central1-1.gce.cloud.redislabs.com/35.x.y.z:22334, epid=0x1, chid=0x1] channelInactive()
2023-07-20T10:36:08.373+02:00 DEBUG 9651 --- [ioEventLoop-4-1] i.lettuce.core.protocol.DefaultEndpoint  : [unknown, epid=0x1] deactivating endpoint handler
2023-07-20T10:36:08.373+02:00 DEBUG 9651 --- [ioEventLoop-4-1] i.lettuce.core.protocol.CommandHandler   : [channel=0x3330ede9, /192.168.1.44:55964 -> redis-22334.c124.us-central1-1.gce.cloud.redislabs.com/35.x.y.z:22334, epid=0x1, chid=0x1] channelInactive() done
2023-07-20T10:36:08.374+02:00 DEBUG 9651 --- [ioEventLoop-4-1] i.l.core.protocol.ConnectionWatchdog     : [unknown, last known addr=null] channelInactive()
2023-07-20T10:36:08.374+02:00 DEBUG 9651 --- [ioEventLoop-4-1] i.l.core.protocol.ConnectionWatchdog     : [unknown, last known addr=null] ConnectionWatchdog not armed
2023-07-20T10:36:08.374+02:00 DEBUG 9651 --- [ioEventLoop-4-1] i.lettuce.core.protocol.CommandHandler   : [channel=0x3330ede9, /192.168.1.44:55964 -> redis-22334.c124.us-central1-1.gce.cloud.redislabs.com/35.x.y.z:22334, epid=0x1, chid=0x1] channelUnregistered()

[mp911de]

Interesting. This redis server doesn’t support RESP3, the spec used to send -ERR for servers that use lower versions. Can you discuss this issue with your redis provider, why suddenly this change is?

[lpellegr]

The provider is redis.com. I will ask them if they can comment here.

[thallredis]

Redis Inc. are in the process of preparing for a larger rollout of Redis 7.2, which will include support for RESP3, which has not been made available with previous Redis Enterprise or Redis Enterprise Cloud. As part of the preliminary rollout to selected regions, existing databases being upgraded to Redis 7.2 have RESP3 disabled. Effectively, when you create a new database, RESP2 and RESP3 will be available, but for existing databases, only RESP2 is available (preserving existing behavior, functionality, etc.) — in an attempt to avoid introducing inadvertent issues to our active customers.

However, while doing this, we inadvertently changed the server behavior.

Instead of responding with -ERR unknown command 'HELLO' the 7.2 server responds with -NOPROTO sorry this protocol version is not supported. While both responses are allowed in the RESP3 specification, we've identified that this is a breaking change for some client libraries, including Lettuce.

Redis Inc. is actively working to roll out an update to revert the change in behavior and pausing ANY additional rollout until this is addressed.

The workaround, in the meantime, is documented here: https://docs.redis.com/latest/rc/changelog/june-2023/#lettuce

[mp911de]

Thanks for the detail. We can easily add a protocol downgrade to RESP2 if the HELLO handshake results in NOPROTO. It was just not expected because the typical scenario for a protocol downgrade happens with older Redis versions that do not contain the HELLO command.

[mp911de]

Lettuce can now handle NOPROTO responses.