[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 commented 6 months ago

Before Creating the Bug Report

[X] I found a bug, not just asking a question, which should be created in GitHub Discussions.
[X] I have searched the GitHub Issues and GitHub Discussions of this repository and believe that this is not a duplicate.
[X] 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

rocketmq acts as a provider as well as a consumer.
redis has topology refresh enabled and checks for 30 seconds.
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 commented 6 months ago

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 commented 6 months ago

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 commented 6 months ago

org.apache.rocketmq.client.log.ClientLogger

set -Drocketmq.client.logUseSlf4j=true

and try again

FrankCy commented 6 months ago

org.apache.rocketmq.client.log.ClientLogger

set -Drocketmq.client.logUseSlf4j=true

and try again

Thank you. I'll try it later.

FrankCy commented 6 months ago

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 commented 6 months ago

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 commented 6 months ago

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

FrankCy commented 6 months ago

Hello, is this issue related to https://github.com/apache/rocketmq/issues/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?

apache / rocketmq