Own `RedisCredentialsProvider` causes issue with protocol handshake on Redis 5

[jiantosca]

Bug Report

Current Behavior

Howdy - I get a RedisConnectionException when using a RedisCredentialsProvider trying to connect over SSL. If I use an ImmediateRedisCredentialsProvider instead, the ssl connection works fine.

Also, the same RedisCredentialsProvider instance that fails with ssl connection, works fine for non-ssl connection.

I included some simple code that i used to recreate the issue.

Stack trace

// your stack trace here;
io.lettuce.core.RedisConnectionException:  my.redis.server/<unresolved>:443
     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:350)
     at io.lettuce.core.RedisClient.connect(RedisClient.java:216)
     at io.lettuce.core.RedisClient.connect(RedisClient.java:201)
     at RedisCredentialsProviderTest.testIt(RedisCredentialsProviderTest.java:49)
     at RedisCredentialsProviderTest.main(RedisCredentialsProviderTest.java:27)
Caused by: io.lettuce.core.RedisCommandExecutionException: ERR unknown command 'HELLO'
     at io.lettuce.core.internal.ExceptionFactory.createExecutionException(ExceptionFactory.java:147)
     at io.lettuce.core.internal.ExceptionFactory.createExecutionException(ExceptionFactory.java:116)
     at io.lettuce.core.protocol.AsyncCommand.completeResult(AsyncCommand.java:120)
     at io.lettuce.core.protocol.AsyncCommand.complete(AsyncCommand.java:111)
     at io.lettuce.core.protocol.CommandHandler.complete(CommandHandler.java:747)
     at io.lettuce.core.protocol.CommandHandler.decode(CommandHandler.java:682)
     at io.lettuce.core.protocol.CommandHandler.channelRead(CommandHandler.java:599)
     at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
     at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
     at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
     at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1373)
     at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1236)
     at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1285)
     at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:519)
     at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:458)
     at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:280)
     at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:444)
     at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
     at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
     at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
     at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
     at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
     at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
     at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
     at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
     at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
     at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
     at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
     at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
     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:833)

Input Code

Input Code

import io.lettuce.core.RedisClient;
import io.lettuce.core.RedisCredentials;
import io.lettuce.core.RedisCredentialsProvider;
import io.lettuce.core.RedisCredentialsProvider.ImmediateRedisCredentialsProvider;
import io.lettuce.core.RedisURI;
import reactor.core.publisher.Mono;

public class RedisCredentialsProviderTest {

	public static void main(String[] args) {

		var sslServer = "ssl server";
		var sslPort = 443;
		
		var notSslServer = "no ssl server";
		var notSslPort = 6379;
		
		var provider = new MyRedisCredentialsProvider("username", "password");
		var immediateProvider = new MyImmediateRedisCredentialsProvider("username", "password");
		
                // this first one fails
                testIt(sslServer, sslPort, true, provider, "SSL with MyRedisCredentialsProvider");
		testIt(sslServer, sslPort, true, immediateProvider, "SSL with MyImmediateRedisCredentialsProvider");

		testIt(notSslServer, notSslPort, false, provider, "No SSL with MyRedisCredentialsProvider");
		testIt(notSslServer, notSslPort, false, immediateProvider, "No SSL with MyImmediateRedisCredentialsProvider");
	}
	
	static void testIt(String server, int port, boolean withSsl, RedisCredentialsProvider provider, String testMsg) {
		
		var redisUri = RedisURI.Builder
				.redis(server, port)
				.withAuthentication(provider)
				.withSsl(withSsl)
				.build();
		
		try(var client = RedisClient.create(redisUri)) {
			var commands = client.connect().sync();
			System.out.println(String.format("%s - Ping: %s", testMsg, commands.ping()));
		} catch (Exception e) {
			System.out.println(testMsg + " - Ping failed:");
			e.printStackTrace();
		}
	}
	
	static class MyRedisCredentialsProvider implements RedisCredentialsProvider {
		
                String username;
	        String password;
		
                public MyRedisCredentialsProvider(String username, String password) {
			this.username = username;
			this.password = password;
		}

		@Override
		public Mono<RedisCredentials> resolveCredentials() {
			return Mono.just(RedisCredentials.just(username, password));
		}
	}
	
	static class MyImmediateRedisCredentialsProvider implements ImmediateRedisCredentialsProvider {
		
                String username;
		String password;

		public MyImmediateRedisCredentialsProvider(String username, String password) {
			this.username = username;
			this.password = password;
		}
		
		@Override
		public RedisCredentials resolveCredentialsNow() {
			return RedisCredentials.just(username, password);
		}
	}		
}

Expected behavior/code

I would expect connectivity to work equally well whether I use a RedisCredentialsProvider that returns a Mono<RedisCredentials>, or an ImmediateRedisCredentialsProvider that return a RedisCredentials

Environment

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

Possible Solution

Additional context

[mp911de]

ERR unknown command 'HELLO' is a typical response if the server does not match the Redis protocol or the Redis version is less than Redis v5. Can you capture please the handshake sequence by setting the logger category io.lettuce.core.protocol to TRACE?

You should see something like:

2022-10-31 08:56:28 [DEBUG] [lettuce-kqueueEventLoop-4-3] [channel=0xe7a575cf, /127.0.0.1:55770 -> 127.0.0.1/127.0.0.1:6443] writing command AsyncCommand [type=HELLO, output=GenericMapOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command] (CommandEncoder:101)
2022-10-31 08:56:28 [TRACE] [lettuce-kqueueEventLoop-4-3] [channel=0xe7a575cf, /127.0.0.1:55770 -> 127.0.0.1/127.0.0.1:6443] Sent: *5
$5
HELLO
$1
3
$4
AUTH
$11
lettuceTest
$17
lettuceTestPasswd (CommandEncoder:103)
2022-10-31 08:56:28 [DEBUG] [lettuce-kqueueEventLoop-4-3] [channel=0xe7a575cf, /127.0.0.1:55770 -> 127.0.0.1/127.0.0.1:6443, epid=0x3, chid=0x3] Received: 152 bytes, 1 commands in the stack (CommandHandler:578)
2022-10-31 08:56:28 [TRACE] [lettuce-kqueueEventLoop-4-3] [channel=0xe7a575cf, /127.0.0.1:55770 -> 127.0.0.1/127.0.0.1:6443, epid=0x3, chid=0x3] Buffer: %7
$6
server
$5
redis
$7
version
$11
255.255.255
$5
proto
:3
$2
id
:26
$4
mode
$10
standalone
$4
role
$6
master
$7
modules
*0 (CommandHandler:593)

[jiantosca]

Sure, I included two below ...both for the same redis db. The first one is the trace when using RedisCredentialsProvider that returns a Mono<RedisCredentials>. The second one works using a ImmediateRedisCredentialsProvider

Note i also logged a call to info in the working/second trace below showing the redis version (6.2.5). I figured HELLO should be available in 6+ but our admins saying it's not supported. My locally running redis (non ssl/also 6.2.5) does have HELLO cmd.... so my bad for thinking it had something to do with ssl. When I disable HELLO from my local redis i can recreate the issue.

01-11-2022 09:16:45.351 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0x135c5646, [id: 0x76ea9180] (inactive), epid=0x1, chid=0x1] channelRegistered()
01-11-2022 09:16:45.506 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0x135c5646, /XX.X.XXX.XX:58150 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] write(ctx, AsyncCommand [type=HELLO, output=GenericMapOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], promise)
01-11-2022 09:16:45.507 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandEncoder - [channel=0x135c5646, /XX.X.XXX.XX:58150 -> our.redis.server.org/XX.XXX.XX.XX:443] writing command AsyncCommand [type=HELLO, output=GenericMapOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
01-11-2022 09:16:45.507 [lettuce-nioEventLoop-4-1] TRACE i.l.core.protocol.CommandEncoder - [channel=0x135c5646, /XX.X.XXX.XX:58150 -> our.redis.server.org/XX.XXX.XX.XX:443] Sent: *5
$5
HELLO
$1
3
$4
AUTH
$25
topSecretUser
$11
topSecretPas
01-11-2022 09:16:45.677 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0x135c5646, /XX.X.XXX.XX:58150 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] Received: 30 bytes, 1 commands in the stack
01-11-2022 09:16:45.677 [lettuce-nioEventLoop-4-1] TRACE i.l.core.protocol.CommandHandler - [channel=0x135c5646, /XX.X.XXX.XX:58150 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] Buffer: -ERR unknown command 'HELLO'
01-11-2022 09:16:45.677 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0x135c5646, /XX.X.XXX.XX:58150 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] Stack contains: 1 commands
01-11-2022 09:16:45.680 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.RedisStateMachine - Decode done, empty stack: true
01-11-2022 09:16:45.680 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0x135c5646, /XX.X.XXX.XX:58150 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] Completing command AsyncCommand [type=HELLO, output=GenericMapOutput [output=null, error='ERR unknown command 'HELLO''], commandType=io.lettuce.core.protocol.Command]
01-11-2022 09:16:45.686 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [unknown, epid=0x1] closeAsync()
01-11-2022 09:16:45.690 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0x135c5646, /XX.X.XXX.XX:58150 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] channelInactive()
01-11-2022 09:16:45.690 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [unknown, epid=0x1] deactivating endpoint handler
01-11-2022 09:16:45.691 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0x135c5646, /XX.X.XXX.XX:58150 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] channelInactive() done
01-11-2022 09:16:45.692 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.ConnectionWatchdog - [unknown, last known addr=null] channelInactive()
01-11-2022 09:16:45.692 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.ConnectionWatchdog - [unknown, last known addr=null] ConnectionWatchdog not armed
01-11-2022 09:16:45.692 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0x135c5646, /XX.X.XXX.XX:58150 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] channelUnregistered()

ImmediateRedisCredentialsProvider:

01-11-2022 09:52:13.729 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0xa90b7a3d, [id: 0x7d9f76ef] (inactive), epid=0x1, chid=0x1] channelRegistered()
01-11-2022 09:52:13.878 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] write(ctx, AsyncCommand [type=HELLO, output=GenericMapOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], promise)
01-11-2022 09:52:13.881 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandEncoder - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443] writing command AsyncCommand [type=HELLO, output=GenericMapOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
01-11-2022 09:52:13.881 [lettuce-nioEventLoop-4-1] TRACE i.l.core.protocol.CommandEncoder - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443] Sent: *5
$5
HELLO
$1
3
$4
AUTH
$25
topSecretUser
$11
topSecretPass
01-11-2022 09:52:14.043 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] Received: 30 bytes, 1 commands in the stack
01-11-2022 09:52:14.043 [lettuce-nioEventLoop-4-1] TRACE i.l.core.protocol.CommandHandler - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] Buffer: -ERR unknown command 'HELLO'
01-11-2022 09:52:14.043 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] Stack contains: 1 commands
01-11-2022 09:52:14.046 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.RedisStateMachine - Decode done, empty stack: true
01-11-2022 09:52:14.046 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] Completing command AsyncCommand [type=HELLO, output=GenericMapOutput [output=null, error='ERR unknown command 'HELLO''], commandType=io.lettuce.core.protocol.Command]
01-11-2022 09:52:14.048 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] write(ctx, AsyncCommand [type=AUTH, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], promise)
01-11-2022 09:52:14.049 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandEncoder - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443] writing command AsyncCommand [type=AUTH, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
01-11-2022 09:52:14.049 [lettuce-nioEventLoop-4-1] TRACE i.l.core.protocol.CommandEncoder - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443] Sent: *3
$4
AUTH
$25
topSecretUser
$11
topSecretPass
01-11-2022 09:52:14.099 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] Received: 5 bytes, 1 commands in the stack
01-11-2022 09:52:14.099 [lettuce-nioEventLoop-4-1] TRACE i.l.core.protocol.CommandHandler - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] Buffer: +OK
01-11-2022 09:52:14.099 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] Stack contains: 1 commands
01-11-2022 09:52:14.099 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.RedisStateMachine - Decode done, empty stack: true
01-11-2022 09:52:14.099 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] Completing command AsyncCommand [type=AUTH, output=StatusOutput [output=OK, error='null'], commandType=io.lettuce.core.protocol.Command]
01-11-2022 09:52:14.100 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] channelActive()
01-11-2022 09:52:14.100 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
01-11-2022 09:52:14.100 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1] activating endpoint
01-11-2022 09:52:14.100 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1] flushCommands()
01-11-2022 09:52:14.101 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1] flushCommands() Flushing 0 commands
01-11-2022 09:52:14.102 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.ConnectionWatchdog - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, last known addr=our.redis.server.org/XX.XXX.XX.XX:443] channelActive()
01-11-2022 09:52:14.102 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] channelActive() done
01-11-2022 09:52:14.103 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1] write() writeAndFlush command AsyncCommand [type=INFO, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
01-11-2022 09:52:14.104 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] write(ctx, AsyncCommand [type=INFO, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], promise)
01-11-2022 09:52:14.104 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandEncoder - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443] writing command AsyncCommand [type=INFO, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
01-11-2022 09:52:14.104 [lettuce-nioEventLoop-4-1] TRACE i.l.core.protocol.CommandEncoder - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443] Sent: *1
$4
INFO
01-11-2022 09:52:14.105 [main] DEBUG i.l.core.protocol.DefaultEndpoint - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1] write() done
01-11-2022 09:52:14.154 [lettuce-nioEventLoop-4-1] DEBUG i.l.core.protocol.CommandHandler - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] Received: 976 bytes, 1 commands in the stack
01-11-2022 09:52:14.154 [lettuce-nioEventLoop-4-1] TRACE i.l.core.protocol.CommandHandler - [channel=0xa90b7a3d, /XX.X.XXX.XX:59557 -> our.redis.server.org/XX.XXX.XX.XX:443, epid=0x1, chid=0x1] Buffer: $2192
# Server
redis_version:6.2.5
redis_git_sha1:00000000
redis_git_dirty:0
redis_build_id:0000000000000000000000000000000000000000
redis_mode:standalone
os:Linux 4.18.0-305.57.1.el8_4.x86_64 x86_64
....

[jiantosca]

I did a little more digging.... When RedisHandshake's initiateHandshakeResp3 uses a CompletableFuture<RedisCredentials> and an unknown command happens, an instance of CompletionException (with a cause of RedisException) is passed to isUnknownCommand(Throwable error) which will always return false and prevent a call to fallbackToResp2(channel, handshake).

This of course isn't a problem when using an ImmediateRedisCredentialsProvider since isUnknownCommand would get the RedisException instead of a CompletionException.

Would it make sense to update isUnknownCommand(Throwable error) with something like below so it looks for a RedisException cause?

    private static boolean isUnknownCommand(Throwable error) {
    	if(!isRedisException(error) && error.getCause() != null) {
    		return isUnknownCommand(error.getCause());
    	}
        return isRedisException(error) && LettuceStrings.isNotEmpty(error.getMessage())
                && ((error.getMessage().startsWith("ERR") && error.getMessage().contains("unknown")));
    }
    
    private static boolean isRedisException(Throwable error) {
    	return error instanceof RedisException;
    }

ava.util.concurrent.CompletionException: io.lettuce.core.RedisCommandExecutionException: ERR unknown command `HELLO`, with args beginning with: `3`, `AUTH`, `testUser`, `testUserPassword`, 
	at java.base/java.util.concurrent.CompletableFuture.encodeRelay(CompletableFuture.java:368)
	at java.base/java.util.concurrent.CompletableFuture.completeRelay(CompletableFuture.java:377)
	at java.base/java.util.concurrent.CompletableFuture$UniRelay.tryFire(CompletableFuture.java:1097)
	at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:510)
	at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2162)
	at io.lettuce.core.protocol.AsyncCommand.doCompleteExceptionally(AsyncCommand.java:139)
	at io.lettuce.core.protocol.AsyncCommand.completeResult(AsyncCommand.java:120)
	at io.lettuce.core.protocol.AsyncCommand.complete(AsyncCommand.java:111)
	at io.lettuce.core.protocol.CommandWrapper.complete(CommandWrapper.java:63)
	at io.lettuce.core.protocol.CommandHandler.complete(CommandHandler.java:747)
	at io.lettuce.core.protocol.CommandHandler.decode(CommandHandler.java:682)
	at io.lettuce.core.protocol.CommandHandler.channelRead(CommandHandler.java:599)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:442)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:412)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:440)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:420)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:788)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:724)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:650)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:562)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
	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:833)
Caused by: io.lettuce.core.RedisCommandExecutionException: ERR unknown command `HELLO`, with args beginning with: `3`, `AUTH`, `testUser`, `testUserPassword`, 
	at io.lettuce.core.internal.ExceptionFactory.createExecutionException(ExceptionFactory.java:147)
	at io.lettuce.core.internal.ExceptionFactory.createExecutionException(ExceptionFactory.java:116)
	... 22 more

[mp911de]

Thanks a lot for investigating. I wonder why -ERR unknown command 'HELLO' happens in the first place, but anyways, that's a bug in the protocol handshake.

For the time being, please configure to use the RESP2 protocol as workaround.

[jiantosca]

Thanks a lot for investigating. I wonder why -ERR unknown command 'HELLO' happens in the first place, but anyways, that's a bug in the protocol handshake.

For the time being, please configure to use the RESP2 protocol as workaround.

Thanks, will do. And I'll see if I can understand more on why our 6.2.5 redis doesn't support HELLO command.

[mp911de]

That's fixed now.