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

A problem with an abnormal log output location. #2582

Closed
FrankCy opened this issue May 15, 2024 · 11 comments
Closed

A problem with an abnormal log output location. #2582

FrankCy opened this issue May 15, 2024 · 11 comments
Labels
invalid

Comments

@FrankCy
Copy link

FrankCy commented May 15, 2024

Description

The rocketmq-client.log outputs lettuce logs and the rocketmq log level is ERROR and the output lettuce log is DEBUG.

Configuration

Version:
Log4j:2.18.0
lettuce-core：5.1.7.RELEASE
spring-boot-starter-data-redis：2.4.1
spring-data-redis：2.1.9.RELEASE
rocketmq:4.6.0

Operating system: [OS and version]

JDK: [JDK distribution and version]
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

Logs

2024-05-15 14:46:41,131 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7d250fc, /10.8.0.74:64037 -> 172.17.48.180/172.17.48.180:6379, last known addr=172.17.48.180/172.17.48.180:6379] channelInactive()
2024-05-15 14:46:41,131 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7d250fc, /10.8.0.74:64037 -> 172.17.48.180/172.17.48.180:6379, last known addr=172.17.48.180/172.17.48.180:6379] channelInactive()
2024-05-15 14:46:41,131 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7d250fc, /10.8.0.74:64037 -> 172.17.48.180/172.17.48.180:6379, last known addr=172.17.48.180/172.17.48.180:6379] channelInactive()
2024-05-15 14:46:41,135 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7d250fc, /10.8.0.74:64037 -> 172.17.48.180/172.17.48.180:6379, last known addr=172.17.48.180/172.17.48.180:6379] Reconnect scheduling disabled
2024-05-15 14:46:41,135 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7d250fc, /10.8.0.74:64037 -> 172.17.48.180/172.17.48.180:6379, last known addr=172.17.48.180/172.17.48.180:6379] channelInactive()
2024-05-15 14:46:41,135 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7d250fc, /10.8.0.74:64037 -> 172.17.48.180/172.17.48.180:6379, last known addr=172.17.48.180/172.17.48.180:6379] Reconnect scheduling disabled
2024-05-15 14:46:41,135 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7d250fc, /10.8.0.74:64037 -> 172.17.48.180/172.17.48.180:6379, last known addr=172.17.48.180/172.17.48.180:6379] Reconnect scheduling disabled
2024-05-15 14:46:41,135 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7d250fc, /10.8.0.74:64037 -> 172.17.48.180/172.17.48.180:6379, last known addr=172.17.48.180/172.17.48.180:6379] Reconnect scheduling disabled
2024-05-15 14:46:41,135 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7d250fc, /10.8.0.74:64037 -> 172.17.48.180/172.17.48.180:6379, last known addr=172.17.48.180/172.17.48.180:6379] channelInactive()
2024-05-15 14:46:41,135 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7d250fc, /10.8.0.74:64037 -> 172.17.48.180/172.17.48.180:6379, last known addr=172.17.48.180/172.17.48.180:6379] channelInactive()
2024-05-15 14:46:41,135 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7d250fc, /10.8.0.74:64037 -> 172.17.48.180/172.17.48.180:6379, last known addr=172.17.48.180/172.17.48.180:6379] Reconnect scheduling disabled
2024-05-15 14:46:41,135 DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0xe7d250fc, /10.8.0.74:64037 -> 172.17.48.180/172.17.48.180:6379, last known addr=172.17.48.180/172.17.48.180:6379] Reconnect scheduling disabled
2024-05-15 14:46:51,441 INFO RocketmqClient - [persistAll] Group: frank-check ClientId: 10.8.0.74@172.17.48.88:9876@41288 updateConsumeOffsetToBroker MessageQueue [topic=%RETRY%check-middleware-group, brokerName=broker-a, queueId=0] 1655
2024-05-15 14:46:51,441 INFO RocketmqClient - [persistAll] Group: frank-check ClientId: 10.8.0.74@172.17.48.88:9876@41288 updateConsumeOffsetToBroker MessageQueue [topic=ARCH_CACHE_MIDDLEWARE_FRANK, brokerName=broker-a, queueId=0] 4698
2024-05-15 14:46:51,442 INFO RocketmqClient - [persistAll] Group: frank-check ClientId: 10.8.0.74@172.17.48.88:9876@41288 updateConsumeOffsetToBroker MessageQueue [topic=ARCH_CACHE_MIDDLEWARE_FRANK, brokerName=broker-a, queueId=1] 4704
2024-05-15 14:46:51,442 INFO RocketmqClient - [persistAll] Group: frank-check ClientId: 10.8.0.74@172.17.48.88:9876@41288 updateConsumeOffsetToBroker MessageQueue [topic=ARCH_CACHE_MIDDLEWARE_FRANK, brokerName=broker-a, queueId=2] 4699
2024-05-15 14:46:51,442 INFO RocketmqClient - [persistAll] Group: frank-check ClientId: 10.8.0.74@172.17.48.88:9876@41288 updateConsumeOffsetToBroker MessageQueue [topic=ARCH_CACHE_MIDDLEWARE_FRANK, brokerName=broker-a, queueId=3] 4696
2024-05-15 14:46:51,444 INFO RocketmqClient - [persistAll] Group: frank-check ClientId: 10.8.0.74@172.17.48.88:9876@41288 updateConsumeOffsetToBroker MessageQueue [topic=%RETRY%check-middleware-group, brokerName=broker-a, queueId=0] 1655
2024-05-15 14:46:51,444 INFO RocketmqClient - [persistAll] Group: frank-check ClientId: 10.8.0.74@172.17.48.88:9876@41288 updateConsumeOffsetToBroker MessageQueue [topic=ARCH_CACHE_MIDDLEWARE_FRANK, brokerName=broker-a, queueId=0] 4698
2024-05-15 14:46:51,444 INFO RocketmqClient - [persistAll] Group: frank-check ClientId: 10.8.0.74@172.17.48.88:9876@41288 updateConsumeOffsetToBroker MessageQueue [topic=ARCH_CACHE_MIDDLEWARE_FRANK, brokerName=broker-a, queueId=1] 4704
2024-05-15 14:46:51,444 INFO RocketmqClient - [persistAll] Group: frank-check ClientId: 10.8.0.74@172.17.48.88:9876@41288 updateConsumeOffsetToBroker MessageQueue [topic=ARCH_CACHE_MIDDLEWARE_FRANK, brokerName=broker-a, queueId=2] 4699
2024-05-15 14:46:51,444 INFO RocketmqClient - [persistAll] Group: frank-check ClientId: 10.8.0.74@172.17.48.88:9876@41288 updateConsumeOffsetToBroker MessageQueue [topic=ARCH_CACHE_MIDDLEWARE_FRANK, brokerName=broker-a, queueId=3] 4696
@rgoers
Copy link
Member

rgoers commented May 15, 2024

I don't actually see a problem being stated anywhere here. What exactly is wrong?

@FrankCy
Copy link
Author

FrankCy commented May 15, 2024

I don't actually see a problem being stated anywhere here. What exactly is wrong?

Hello, the program uses both rocketmq and redis and uses the topology refresh feature of redis, which has a dependency on lettuce-core, and the program is using log4j as the log collection output. We set ERROR in the log output of rocketmq component and output the logs to rocketmq-client.log, because we set the rocketmq log output level to ERROR, normally rocketmq-client.log will only print ERROR about rocketmq's logs, but the real Normally, rocketmq-client.log would only print ERROR logs for rocketmq, but in reality, it outputs DEBUG logs for lettuce-core, which is a dependency of spring-boot-stater-data-redis. It should not be in this log file. It's not clear why it arises, is it something to do with the order in which the component's logging dependencies are loaded?

@ppkarwasz
Copy link
Contributor

@FrankCy,

Can you check if your application is using Log4j for all logging: many RocketMQ artifacts have a dependency on logback-classic, which smuggles Logback into an application classpath. See apache/rocketmq#5347 for details. You can do it by adding some prefix to your PatternLayout (e.g. Log4j: ).

If your runtime dependencies are configured correctly (no Logback, an appropriate log4j-slf4j2-impl bridge), please add the contents of your configuration file to this question.

@FrankCy
Copy link
Author

FrankCy commented May 16, 2024

@FrankCy,

Can you check if your application is using Log4j for all logging: many RocketMQ artifacts have a dependency on logback-classic, which smuggles Logback into an application classpath. See apache/rocketmq#5347 for details. You can do it by adding some prefix to your PatternLayout (e.g. Log4j: ).

If your runtime dependencies are configured correctly (no Logback, an appropriate log4j-slf4j2-impl bridge), please add the contents of your configuration file to this question.

Okay, thanks. I'll double-check.

@FrankCy FrankCy closed this as completed May 17, 2024
@FrankCy
Copy link
Author

FrankCy commented May 17, 2024

@FrankCy,

Can you check if your application is using Log4j for all logging: many RocketMQ artifacts have a dependency on logback-classic, which smuggles Logback into an application classpath. See apache/rocketmq#5347 for details. You can do it by adding some prefix to your PatternLayout (e.g. Log4j: ).

If your runtime dependencies are configured correctly (no Logback, an appropriate log4j-slf4j2-impl bridge), please add the contents of your configuration file to this question.

Hi, this is not a problem, I am using rocketmq-client, not rocketmq-tools, rocketmq-client is using log4j-api 2.7 for log management.

@FrankCy FrankCy reopened this May 17, 2024
@vy
Copy link
Member

vy commented May 17, 2024

@FrankCy, could you share with us a minimal1 pom.xml and a Java file containing a main() method that we can run to reproduce the problem, please?

1 Minimal as in including a dependency if and only it is related with the problem; no other dependencies, plugins, properties, etc. that are irrelevant with the problem.

@FrankCy
Copy link
Author

FrankCy commented May 20, 2024

@FrankCy, could you share with us a _minimal_1 pom.xml and a Java file containing a main() method that we can run to reproduce the problem, please?

1 Minimal as in including a dependency if and only it is related with the problem; no other dependencies, plugins, properties, etc. that are irrelevant with the problem.

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <parent>
        <artifactId>frank-check-middleware</artifactId>
        <groupId>org.example</groupId>
        <version>1.0-SNAPSHOT</version>
        <relativePath>../../pom.xml</relativePath>
    </parent>
    <modelVersion>4.0.0</modelVersion>

    <artifactId>rocketmq-producer-and-consumer</artifactId>


    <properties>
        <maven.compiler.source>8</maven.compiler.source>
        <maven.compiler.target>8</maven.compiler.target>
        <netty-version>4.1.38.Final</netty-version>
    </properties>

    <dependencies>
        <dependency>
            <groupId>org.apache.rocketmq</groupId>
            <artifactId>rocketmq-spring-boot-starter</artifactId>
        </dependency>

        <!-- https://mvnrepository.com/artifact/com.google.guava/guava -->
        <dependency>
            <groupId>com.google.guava</groupId>
            <artifactId>guava</artifactId>
        </dependency>
        <!-- https://mvnrepository.com/artifact/dnsjava/dnsjava -->
        <dependency>
            <groupId>dnsjava</groupId>
            <artifactId>dnsjava</artifactId>
            <version>2.1.1</version>
        </dependency>
        
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-data-redis</artifactId>
            <version>2.2.13.RELEASE</version>
            <exclusions>
                <exclusion>
                    <groupId>ch.qos.logback</groupId>
                    <artifactId>logback-classic</artifactId>
                </exclusion>
            </exclusions>
        </dependency>
        <dependency>
            <groupId>org.apache.commons</groupId>
            <artifactId>commons-pool2</artifactId>
        </dependency>

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
        </dependency>

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-test</artifactId>
        </dependency>

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-log4j2</artifactId>
        </dependency>

        <!-- apollo -->
        <dependency>
            <groupId>com.ctrip.framework.apollo</groupId>
            <artifactId>apollo-client</artifactId>
            <version>1.4.1</version>
        </dependency>

        <dependency>
            <groupId>org.projectlombok</groupId>
            <artifactId>lombok</artifactId>
        </dependency>

        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-actuator</artifactId>
        </dependency>
    </dependencies>

    <build>
        <plugins>
            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-compiler-plugin</artifactId>
                <version>${maven-compiler-plugin.version}</version>
                <configuration>
                    <source>${maven-compiler-source.version}</source>
                    <target>${maven-compiler-target.version}</target>
                </configuration>
            </plugin>
            <plugin>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-maven-plugin</artifactId>
                <executions>
                    <execution>
                        <goals>
                            <goal>repackage</goal>
                        </goals>
                    </execution>
                </executions>
            </plugin>
        </plugins>
    </build>

</project>

@tcmot
Copy link

tcmot commented May 20, 2024

@FrankCy 你回复这些，@vy 能看懂吗？ 他想让你提供一个最小依赖的demo项目。包含 rocketmq依赖，并能复现出你出现的问题。

@FrankCy
Copy link
Author

FrankCy commented May 20, 2024

@FrankCy 你回复这些，@vy 能看懂吗？ 他想让你提供一个最小依赖的demo项目。包含 rocketmq依赖，并能复现出你出现的问题。

@tcmot 好，稍晚点

@vy vy added the waiting-for-user More information is needed from the user label May 21, 2024
@FrankCy
Copy link
Author

FrankCy commented May 22, 2024

This problem may be due to the rocketmq component implementation of the default binding logback, lettuce-core output logs using netty-common, also bound to the logback, so the application of the log4j2.xml can not control them, so far it seems that may be the reason, I'll watch again!

@vy
Copy link
Member

vy commented May 22, 2024

@FrankCy, thanks for the update. I am closing the issue. Feel free to re-open it when you manage to create the minimal reproduction code that I asked for.

@vy vy closed this as completed May 22, 2024
@vy vy added invalid and removed waiting-for-user More information is needed from the user labels May 22, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
invalid
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@vy @rgoers @FrankCy @ppkarwasz @tcmot