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

Own RedisCredentialsProvider causes issue with protocol handshake on Redis 5 #2234

Closed
jiantosca opened this issue Oct 28, 2022 · 6 comments
Closed

Own RedisCredentialsProvider causes issue with protocol handshake on Redis 5 #2234

jiantosca opened this issue Oct 28, 2022 · 6 comments
Assignees
@mp911de
Labels
type: bug A general bug
Milestone
6.2.2.RELEASE

Comments

@jiantosca
Copy link
Contributor

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
Copy link
Collaborator

mp911de commented Oct 31, 2022

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)

@mp911de mp911de added the status: waiting-for-feedback We need additional information before we can continue label Oct 31, 2022
@jiantosca
Copy link
Contributor Author

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
Copy link
Contributor Author

jiantosca commented Nov 2, 2022 •
edited
Loading

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
Copy link
Collaborator

mp911de commented Nov 2, 2022

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.

@mp911de mp911de added type: bug A general bug and removed status: waiting-for-feedback We need additional information before we can continue labels Nov 2, 2022
@mp911de mp911de self-assigned this Nov 2, 2022
@jiantosca jiantosca changed the title RedisCredentialsProvider not working with ssl connection RedisCredentialsProvider causes issue with protocol handshake Nov 2, 2022
@jiantosca
Copy link
Contributor Author

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 mp911de added this to the 6.2.2.RELEASE milestone Nov 14, 2022
@mp911de mp911de changed the title RedisCredentialsProvider causes issue with protocol handshake Own RedisCredentialsProvider causes issue with protocol handshake on Redis 5 Nov 22, 2022
mp911de added a commit that referenced this issue Nov 22, 2022
@mp911de
Unwrap completion exception in RedisHandshake #2234
a168148 
We now unwrap potentially wrapped exceptions to be able to inspect the cause. This can happen in an async flow when the HELLO command invocation fails.
mp911de added a commit that referenced this issue Nov 22, 2022
@mp911de
Unwrap completion exception in RedisHandshake #2234
4d07dfd 
We now unwrap potentially wrapped exceptions to be able to inspect the cause. This can happen in an async flow when the HELLO command invocation fails.
@mp911de
Copy link
Collaborator

mp911de commented Nov 22, 2022

That's fixed now.

@mp911de mp911de closed this as completed Nov 22, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@mp911de mp911de

Labels
type: bug A general bug
Projects
None yet
Milestone
6.2.2.RELEASE
Development

No branches or pull requests
2 participants
@jiantosca @mp911de