Tracing incorrect when command execute timeout

[lianghuang]

Bug Report

Current Behavior

1. When sync command reached timeout params where set in RedisURI, the tracing still show the request is success. I don't understand this is a bug or by design.
2. how to trace async command, when async use .get(100, TimeUnit.MILLISECONDS) , it also won't show timeout in tracing.

Here is the way to reproduce:
Running Input Code blew , because I set “.withTimeout(Duration.ofMillis(10))” , it runs into AsyncCommand

    @Override
    public boolean cancel(boolean mayInterruptIfRunning) {
        try {
            command.cancel();
            return super.cancel(mayInterruptIfRunning);
        } finally {
            COUNT_UPDATER.set(this, 0);
        }
    }

when command execute cancel method, callback set in default BraveTracing does not been executed.

  if (command instanceof CompleteableCommand) {
                CompleteableCommand<?> completeableCommand = (CompleteableCommand<?>) command;
                completeableCommand.onComplete((o, throwable) -> {

                    if (command.getOutput() != null) {

                        String error = command.getOutput().getError();
                        if (error != null) {
                            span.tag("error", error);
                        } else if (throwable != null) {
                            span.tag("exception", throwable.toString());
                            span.error(throwable);
                        }
                    }

                    span.finish();
                });
            }

The code above will execute when netty channel read data. but this command already timeout.

Stack trace

lambda$start$0:350, BraveTracing$BraveSpan (io.lettuce.core.tracing)
accept:-1, 242663346 (io.lettuce.core.tracing.BraveTracing$BraveSpan$$Lambda$107)
notifyConsumers:96, CommandWrapper (io.lettuce.core.protocol)
complete:66, CommandWrapper (io.lettuce.core.protocol)
complete:63, CommandWrapper (io.lettuce.core.protocol)
complete:742, CommandHandler (io.lettuce.core.protocol)
decode:677, CommandHandler (io.lettuce.core.protocol)
channelRead:594, CommandHandler (io.lettuce.core.protocol)
invokeChannelRead:379, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:365, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:357, AbstractChannelHandlerContext (io.netty.channel)
channelRead:1410, DefaultChannelPipeline$HeadContext (io.netty.channel)
invokeChannelRead:379, AbstractChannelHandlerContext (io.netty.channel)
invokeChannelRead:365, AbstractChannelHandlerContext (io.netty.channel)
fireChannelRead:919, DefaultChannelPipeline (io.netty.channel)
readReady:544, AbstractKQueueStreamChannel$KQueueStreamUnsafe (io.netty.channel.kqueue)
readReady:381, AbstractKQueueChannel$AbstractKQueueUnsafe (io.netty.channel.kqueue)
processReady:211, KQueueEventLoop (io.netty.channel.kqueue)
run:289, KQueueEventLoop (io.netty.channel.kqueue)
run:986, SingleThreadEventExecutor$4 (io.netty.util.concurrent)
run:74, ThreadExecutorMap$2 (io.netty.util.internal)
run:30, FastThreadLocalRunnable (io.netty.util.concurrent)
run:748, Thread (java.lang)

Input Code

Input Code

public class LettuceTest extends TestSupport2 {
    private static RedisClient client;
    private static StatefulRedisConnection<String, String> connect;

    @Before
    public void beforeClass() {

        // create or use an existent brave Tracing instance
        brave.Tracing clientTracing = Tracing.newBuilder()
                .localServiceName("test")
                .supportsJoin(Boolean.parseBoolean(System.getProperty("brave.supportsJoin", "true")))
                .supportsJoin(Boolean.parseBoolean(System.getProperty("brave.traceId128Bit", "false")))
                .build();
// create an instance of `BraveTracing`
        io.lettuce.core.tracing.Tracing tracing = BraveTracing.create(clientTracing);
// build the ClientResources with tracing support.
        ClientResources clientResources = DefaultClientResources.builder().tracing(tracing).build();
        client = RedisClient.create(clientResources, RedisURI.Builder.redis(proxyHost, port)
                .withTimeout(Duration.ofMillis(10))
                .withPassword(passwd.toCharArray()).build());
        connect = client.connect();
    }

    @After
    public void afterClass() {
        client.shutdown();
    }

    @Test
    public void _sync_test() throws Exception {
        try {
            String tes1 = connect.sync().get("test1");
        } catch (Exception e) {
            log.error("error ", e);
        }
        Thread.sleep(60 * 1000);
    }

Expected behavior/code

1. tracing can show correctly when sync command executed timeout.
2. suggest async command tracing way. thanks.

Environment

• Lettuce version(s): 6.0.x
• Redis version: 5.0

Possible Solution

add command callback in CommandWrapper

    @Override
    public void onComplete(BiConsumer<? super T, Throwable> action) {
        addOnComplete(action);
        if(command instanceof CompleteableCommand){
            ((CompleteableCommand<T>) command).onComplete(action);
        }
    }

ignore finished command in CommandHandler line 642.
if command is done(cancelled), skip complete command.

     if (canComplete(command)) {
                        stack.poll();
                        if(command!=null&&!command.isDone()){
                            try {
                                if (debugEnabled) {
                                    logger.debug("{} Completing command {}", logPrefix(), command);
                                }
                                complete(command);
                            } catch (Exception e) {
                                logger.warn("{} Unexpected exception during request: {}", logPrefix, e.toString(), e);
                            }
                        }
                    }

Additional context

[mp911de]

I wonder why the completion BiConsumer isn't called with an exception when the synchronous call facade cancels the command. Sounds like a bug to me.

[lianghuang]

I wonder why the completion BiConsumer isn't called with an exception when the synchronous call facade cancels the command. Sounds like a bug to me.

When the synchronous call, it execute the AsyncCommand cancel method. but the tracing command registered CommandWrapper's onComplete() method. it's not the same one.

[lianghuang]

And another problem is how to tracing user's async call such as

connect.async().get("test1").get(10,TimeUnit.MILLISECONDS);

do we have to call cancel() method explicitly? any better suggestion, thanks!

    try {
             feature= connect.async().get("test1");
           String result = feature.get(10,TimeUnit.MILLISECONDS);
        }catch (TimeoutException e){
            feature.cancel(true);
        }

[mp911de]

Imperative programming (connect.sync().get("test1")) anticipates cancellation of the command in some sense. It is for the purpose of interruptions so that if the connection gets disconnected then the command does not get retried anymore.

[mp911de]

I think using command callback delegation, attaching the callbacks to the inner-most command (command instanceof CompleteableCommand) makes sense to catch such cases like the one reported here.

[mp911de]

That's fixed now.