[Bug] The lettuce log appears in rocketmq_client.log, although rocketmq does not use this package, but why lettuce logs will be output to rocketmq_client.log? lettuce package when redis topology features a dependency.

[FrankCy]

Before Creating the Bug Report

• I found a bug, not just asking a question, which should be created in GitHub Discussions.

• I have searched the GitHub Issues and GitHub Discussions of this repository and believe that this is not a duplicate.

• I have confirmed that this bug belongs to the current repository, not other repositories of RocketMQ.

Runtime platform environment

Darwin frank 21.3.0 Darwin Kernel Version 21.3.0: Wed Jan 5 21:37:58 PST 2022; root:xnu-8019.80.24~20/RELEASE_ARM64_T8101 arm64

RocketMQ version

4.6.0

JDK Version

JDK:java version "1.8.0_321"

Describe the Bug

The lettuce log appears in rocketmq_client.log, although rocketmq does not use this package, but why lettuce logs will be output to rocketmq_client.log? lettuce package when redis topology features a dependency.

This instance of rocketmq acts as both a provider and a consumer.

Steps to Reproduce

1. rocketmq acts as a provider as well as a consumer.
2. redis has topology refresh enabled and checks for 30 seconds.
3. logs are entered into rocketmq_client.log while redis is checking.

lettuce-core：5.1.7.RELEASE
spring-boot-starter-data-redis：2.4.1
spring-data-redis：2.1.9.RELEASE

What Did You Expect to See?

Hopefully the log about lettuce doesn't hit rocketmq_client.log

What Did You See Instead?

The lettuce log is output in rocketmq_client.log which is not correct.

Additional Context

There is the following log in rocketmq-client.log:
2024-05-06 16:25:23,023 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7773456, /10.8.0.27:57227 -> 172.17.48.140/172.17.48.140:6379, last known addr=172.17.48.140/172.17.48.140:6379] channelActive()
2024-05-06 16:25:23,023 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7773456, /10.8.0.27:57227 -> 172.17.48.140/172.17.48.140:6379, last known addr=172.17.48.140/172.17.48.140:6379] channelActive()
2024-05-06 16:25:23,023 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7773456, /10.8.0.27:57227 -> 172.17.48.140/172.17.48.140:6379, last known addr=172.17.48.140/172.17.48.140:6379] channelActive()
2024-05-06 16:25:23,023 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7773456, /10.8.0.27:57227 -> 172.17.48.140/172.17.48.140:6379, last known addr=172.17.48.140/172.17.48.140:6379] channelActive()
2024-05-06 16:25:23,023 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7773456, /10.8.0.27:57227 -> 172.17.48.140/172.17.48.140:6379, last known addr=172.17.48.140/172.17.48.140:6379] channelActive()
2024-05-06 16:25:23,023 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7773456, /10.8.0.27:57227 -> 172.17.48.140/172.17.48.140:6379, last known addr=172.17.48.140/172.17.48.140:6379] channelActive()
2024-05-06 16:25:23,023 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7773456, /10.8.0.27:57227 -> 172.17.48.140/172.17.48.140:6379, last known addr=172.17.48.140/172.17.48.140:6379] userEventTriggered(ctx, io.lettuce.core.ConnectionEvents$Activated@1358e27d)
2024-05-06 16:25:23,023 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7773456, /10.8.0.27:57227 -> 172.17.48.140/172.17.48.140:6379, last known addr=172.17.48.140/172.17.48.140:6379] userEventTriggered(ctx, io.lettuce.core.ConnectionEvents$Activated@1358e27d)
2024-05-06 16:25:23,023 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7773456, /10.8.0.27:57227 -> 172.17.48.140/172.17.48.140:6379, last known addr=172.17.48.140/172.17.48.140:6379] userEventTriggered(ctx, io.lettuce.core.ConnectionEvents$Activated@1358e27d)
2024-05-06 16:25:23,023 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7773456, /10.8.0.27:57227 -> 172.17.48.140/172.17.48.140:6379, last known addr=172.17.48.140/172.17.48.140:6379] userEventTriggered(ctx, io.lettuce.core.ConnectionEvents$Activated@1358e27d)
2024-05-06 16:25:23,023 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7773456, /10.8.0.27:57227 -> 172.17.48.140/172.17.48.140:6379, last known addr=172.17.48.140/172.17.48.140:6379] userEventTriggered(ctx, io.lettuce.core.ConnectionEvents$Activated@1358e27d)
2024-05-06 16:25:23,023 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7773456, /10.8.0.27:57227 -> 172.17.48.140/172.17.48.140:6379, last known addr=172.17.48.140/172.17.48.140:6379] userEventTriggered(ctx, io.lettuce.core.ConnectionEvents$Activated@1358e27d)
2024-05-06 16:25:24,024 DEBUG io.lettuce.core.cluster.PooledClusterConnectionProvider$DefaultClusterNodeConnectionFactory - Resolved SocketAddress 172.17.48.40:6379 using for Cluster node at 172.17.48.40:6379
2024-05-06 16:25:24,024 DEBUG io.lettuce.core.cluster.PooledClusterConnectionProvider$DefaultClusterNodeConnectionFactory - Resolved SocketAddress 172.17.48.40:6379 using for Cluster node at 172.17.48.40:6379
2024-05-06 16:25:24,024 DEBUG io.lettuce.core.cluster.PooledClusterConnectionProvider$DefaultClusterNodeConnectionFactory - Resolved SocketAddress 172.17.48.40:6379 using for Cluster node at 172.17.48.40:6379
2024-05-06 16:25:24,024 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x504f668d, /10.8.0.27:57228 -> 172.17.48.40/172.17.48.40:6379, last known addr=172.17.48.40/172.17.48.40:6379] channelActive()
2024-05-06 16:25:24,024 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x504f668d, /10.8.0.27:57228 -> 172.17.48.40/172.17.48.40:6379, last known addr=172.17.48.40/172.17.48.40:6379] channelActive()
2024-05-06 16:25:24,024 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x504f668d, /10.8.0.27:57228 -> 172.17.48.40/172.17.48.40:6379, last known addr=172.17.48.40/172.17.48.40:6379] channelActive()
2024-05-06 16:25:24,024 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x504f668d, /10.8.0.27:57228 -> 172.17.48.40/172.17.48.40:6379, last known addr=172.17.48.40/172.17.48.40:6379] channelActive()
2024-05-06 16:25:24,024 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x504f668d, /10.8.0.27:57228 -> 172.17.48.40/172.17.48.40:6379, last known addr=172.17.48.40/172.17.48.40:6379] channelActive()

[humkum]

RocketMQ client use Slf4j Log architecture，if you want to split the log output file, you can customize the log configuration file by yourself.

[FrankCy]

RocketMQ client use Slf4j Log architecture，if you want to split the log output file, you can customize the log configuration file by yourself.

Hello, is this caused by lettuce and rocketmq using slf4j at the same time? Looking at the source code for both components does indeed use slf4j as a logging facade, and would like to analyse why this issue occurs. After setting lettuce's log output level to ERROR and rocketmq's log.level to debug, lettuce's logs are still being fed into rocketmq_client.log, I'm having trouble locating and resolving the issue here.

[leizhiyuan]

org.apache.rocketmq.client.log.ClientLogger

set
-Drocketmq.client.logUseSlf4j=true

and try again

[FrankCy]

org.apache.rocketmq.client.log.ClientLogger

set -Drocketmq.client.logUseSlf4j=true

and try again

Thank you. I'll try it later.

[FrankCy]

org.apache.rocketmq.client.log.ClientLogger

set -Drocketmq.client.logUseSlf4j=true

and try again

It's not correct, it won't even output the following INFO record after setting it up
INFO RocketmqClient - [persistAll] Group:

[FrankCy]

rocketmq startup parameters:
-Drocketmq.client.logRoot=/data/logs/ -Drocketmq.client.logLevel=DEBUG

A snippet of the rockemq_client.log output:
2024-05-09 17:30:44,832 DEBUG io.lettuce.core.cluster.PooledClusterConnectionProvider$DefaultClusterNodeConnectionFactory - Resolved SocketAddress 172.17.48.40:6379 using for Cluster node at 172.17.48.40:6379
2024-05-09 17:30:44,832 DEBUG io.lettuce.core.cluster.PooledClusterConnectionProvider$DefaultClusterNodeConnectionFactory - Resolved SocketAddress 172.17.48.40:6379 using for Cluster node at 172.17.48.40:6379
2024-05-09 17:30:44,832 DEBUG io.lettuce.core.cluster.PooledClusterConnectionProvider$DefaultClusterNodeConnectionFactory - Resolved SocketAddress 172.17.48.40:6379 using for Cluster node at 172.17.48.40:6379
2024-05-09 17:30:44,897 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x74b549ee, /10.8.0.70:59425 -> 172.17.48.40/172.17.48.40:6379, last known addr=172.17.48.40/172.17.48.40:6379] channelActive()
2024-05-09 17:30:44,897 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x74b549ee, /10.8.0.70:59425 -> 172.17.48.40/172.17.48.40:6379, last known addr=172.17.48.40/172.17.48.40:6379] channelActive()
2024-05-09 17:30:44,897 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x74b549ee, /10.8.0.70:59425 -> 172.17.48.40/172.17.48.40:6379, last known addr=172.17.48.40/172.17.48.40:6379] channelActive()
2024-05-09 17:30:44,898 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x74b549ee, /10.8.0.70:59425 -> 172.17.48.40/172.17.48.40:6379, last known addr=172.17.48.40/172.17.48.40:6379] channelActive()
2024-05-09 17:30:44,898 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x74b549ee, /10.8.0.70:59425 -> 172.17.48.40/172.17.48.40:6379, last known addr=172.17.48.40/172.17.48.40:6379] channelActive()
2024-05-09 17:30:44,898 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x74b549ee, /10.8.0.70:59425 -> 172.17.48.40/172.17.48.40:6379, last known addr=172.17.48.40/172.17.48.40:6379] channelActive()
2024-05-09 17:30:44,899 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x74b549ee, /10.8.0.70:59425 -> 172.17.48.40/172.17.48.40:6379, last known addr=172.17.48.40/172.17.48.40:6379] userEventTriggered(ctx, io.lettuce.core.ConnectionEvents$Activated@34fe5c90)
2024-05-09 17:30:44,899 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x74b549ee, /10.8.0.70:59425 -> 172.17.48.40/172.17.48.40:6379, last known addr=172.17.48.40/172.17.48.40:6379] userEventTriggered(ctx, io.lettuce.core.ConnectionEvents$Activated@34fe5c90)
2024-05-09 17:30:44,899 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x74b549ee, /10.8.0.70:59425 -> 172.17.48.40/172.17.48.40:6379, last known addr=172.17.48.40/172.17.48.40:6379] userEventTriggered(ctx, io.lettuce.core.ConnectionEvents$Activated@34fe5c90)
2024-05-09 17:30:44,899 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x74b549ee, /10.8.0.70:59425 -> 172.17.48.40/172.17.48.40:6379, last known addr=172.17.48.40/172.17.48.40:6379] userEventTriggered(ctx, io.lettuce.core.ConnectionEvents$Activated@34fe5c90)
2024-05-09 17:30:44,899 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x74b549ee, /10.8.0.70:59425 -> 172.17.48.40/172.17.48.40:6379, last known addr=172.17.48.40/172.17.48.40:6379] userEventTriggered(ctx, io.lettuce.core.ConnectionEvents$Activated@34fe5c90)
2024-05-09 17:30:44,899 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x74b549ee, /10.8.0.70:59425 -> 172.17.48.40/172.17.48.40:6379, last known addr=172.17.48.40/172.17.48.40:6379] userEventTriggered(ctx, io.lettuce.core.ConnectionEvents$Activated@34fe5c90)
2024-05-09 17:30:47,644 INFO RocketmqClient - [persistAll] Group: frank-rocketmq-demo ClientId: 10.8.0.70@172.17.48.88:9876@26015 updateConsumeOffsetToBroker MessageQueue [topic=%RETRY%frank-rocketmq-demo-group, brokerName=broker-a, queueId=0] 1655
2024-05-09 17:30:47,646 INFO RocketmqClient - [persistAll] Group: frank-rocketmq-demo ClientId: 10.8.0.70@172.17.48.88:9876@26015 updateConsumeOffsetToBroker MessageQueue [topic=ARCH_CACHE_MIDDLEWARE_FRANK, brokerName=broker-a, queueId=0] 3960
2024-05-09 17:30:47,647 INFO RocketmqClient - [persistAll] Group: frank-rocketmq-demo ClientId: 10.8.0.70@172.17.48.88:9876@26015 updateConsumeOffsetToBroker MessageQueue [topic=ARCH_CACHE_MIDDLEWARE_FRANK, brokerName=broker-a, queueId=1] 3963
2024-05-09 17:30:47,647 INFO RocketmqClient - [persistAll] Group: frank-rocketmq-demo ClientId: 10.8.0.70@172.17.48.88:9876@26015 updateConsumeOffsetToBroker MessageQueue [topic=ARCH_CACHE_MIDDLEWARE_FRANK, brokerName=broker-a, queueId=2] 3957
2024-05-09 17:30:47,647 INFO RocketmqClient - [persistAll] Group: frank-rocketmq-demo ClientId: 10.8.0.70@172.17.48.88:9876@26015 updateConsumeOffsetToBroker MessageQueue [topic=ARCH_CACHE_MIDDLEWARE_FRANK, brokerName=broker-a, queueId=3] 3955

If logLevel is set to ERROR or if -Drocketmq.client.logUseSlf4j=true is used, no logs are output to rocketmq_client.log.

The question is why is the lettuce log output to rocketmq_client.log? Though I know it doesn't use the lettuce-core dependency, but rather a dependency referenced by the redis topology refresh feature used in the program.

[FrankCy]

Why does setting -Drocketmq.client.logUseSlf4j=true not output the -Drocketmq.client.logFileName file?

[FrankCy]

Hello, is this issue related to #5347? The situation feels the same as this one, it's because logback is bound by default, so components that use log4j don't work correctly. Is this the reason for this? And how can I solve this problem?