model versions

spring boot: 3.0.0
openjdk: 17.0.2
kafka-server: 3.3.1

describe

I created a new spring boot project, using log4j2 to send logs through kafka, the project will be stuck when starting. This is the spring boot console log.it doesn't have any error message.

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::                (v3.0.0)

2023-05-03 15:57:31.473 INFO  --- [main] com.baozi.Main : Starting Main using Java 17.0.2 with PID 64882 (/Users/baoqingyang/study/test-log4j2-kafka/target/classes started by baoqingyang in /Users/baoqingyang/study/test-log4j2-kafka)
2023-05-03 15:57:31.658 INFO  --- [kafka-producer-network-thread | producer-1] org.apache.kafka.clients.Metadata : [Producer clientId=producer-1] Resetting the last seen epoch of partition test.log-0 to 0 since the associated topicId changed from null to 65urwbD-SsmtubvQ0-mXQw
2023-05-03 15:57:31.661 INFO  --- [kafka-producer-network-thread | producer-1] org.apache.kafka.clients.Metadata : [Producer clientId=producer-1] Cluster ID: C82zisl4QNe3-M5ukKRGXQ
2023-05-03 15:57:31.677 INFO  --- [kafka-producer-network-thread | producer-1] org.apache.kafka.clients.producer.internals.TransactionManager : [Producer clientId=producer-1] ProducerId set to 7 with epoch 0

Comment From: baozi-2019

This is the configuration file and log template file of log4j2

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="OFF" monitorInterval="3000">
    <Properties>
        <Property name="LOG_PATTERN">
            %d{yyyy-MM-dd HH:mm:ss.SSS} %highlight{%-5level}{FATAL=white, ERROR=red, WARN=yellow, INFO=green, DEBUG=cyan, TRACE=blue} --- [%t] %c : %m%ex{full}%n
        </Property>
    </Properties>
    <Appenders>
        <Console name="ConsoleAppender" target="SYSTEM_OUT">
            <PatternLayout pattern="${LOG_PATTERN}" disableAnsi="false" charset="UTF-8"/>
        </Console>
        <Kafka name="Kafka" topic="test.log">
<!--            <JsonTemplateLayout charset="UTF-8" eventTemplateUri="classpath:LogstashJsonEventLayoutV1.json">-->
            <JsonTemplateLayout charset="UTF-8" eventTemplateUri="classpath:CustomerLogTemplate.json">
                <EventTemplateAdditionalField key="serviceName" value="user"/>
            </JsonTemplateLayout>
            <Property name="bootstrap.servers">xxx:xxx</Property>
        </Kafka>
    </Appenders>
    <category name="org.apache.log4j.xml">

    </category>
    <Loggers>
        <Root level="INFO">
            <AppenderRef ref="ConsoleAppender"/>
            <AppenderRef ref="Kafka"/>
        </Root>
        <Logger name="org.apache.kafka" level="INFO" />
    </Loggers>
</Configuration>


{
  "exceptionClass": {
    "$resolver": "exception",
    "field": "className"
  },
  "exceptionMessage": {
    "$resolver": "exception",
    "field": "message",
    "stringified": true
  },
  "exceptionStacktrace": {
    "$resolver": "exception",
    "field": "stackTrace",
    "stackTrace": {
      "stringified": true
    }
  },
  "version": "1.0.0",
  "sourceHost": "${hostName}",
  "message": {
    "$resolver": "message",
    "stringified": true
  },
  "threadName": {
    "$resolver": "thread",
    "field": "name"
  },
  "timestamp": {
    "$resolver": "timestamp",
    "epoch": {
      "unit": "millis",
      "rounded": true
    }
  },
  "level": {
    "$resolver": "level",
    "field": "name"
  },
  "loggerName": {
    "$resolver": "logger",
    "field": "name"
  }
}

Comment From: baozi-2019

application.yaml

logging:
  config: classpath:log4j.xml

Comment From: wilkinsona

@baozi-2019 Thanks for the report. To help us to diagnose the problem, can you please turn those snippets into a complete yet minimal example that reproduces it? It's also not clear why you have reported this as a Spring Boot problem. If you've done some investigating of your own and identified that the problem only occurs when using Spring Boot then please share some details so that we can avoid duplicating effort.

Comment From: baozi-2019

@baozi-2019 Thanks for the report. To help us to diagnose the problem, can you please turn those snippets into a complete yet minimal example that reproduces it? It's also not clear why you have reported this as a Spring Boot problem. If you've done some investigating of your own and identified that the problem only occurs when using Spring Boot then please share some details so that we can avoid duplicating effort.

This is an example test-log4j2-kafka.zip

Comment From: wilkinsona

Thanks. This isn't a Spring Boot problem. With log4j.xml renamed to log4j2.xml so that it's found by default and the following main method:

package com.baozi;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class Main {

    private static final Logger log = LoggerFactory.getLogger(Main.class);

    public static void main(String[] args) {
        for (int i = 0; i < 10; i++) {
            log.info("Log message {}", i);
        }
    }
}

This output is produced:

2023-05-03 11:45:27.933 INFO  --- [main] com.baozi.Main : Log message 0
2023-05-03 11:45:28.140 INFO  --- [kafka-producer-network-thread | producer-1] org.apache.kafka.clients.Metadata : [Producer clientId=producer-1] Resetting the last seen epoch of partition test.log-0 to 0 since the associated topicId changed from null to 2VQ-1wA2R3SQZkkQgfgBpQ
2023-05-03 11:45:28.145 INFO  --- [kafka-producer-network-thread | producer-1] org.apache.kafka.clients.Metadata : [Producer clientId=producer-1] Cluster ID: mF0utEwkRyCb_0H-4RBkyA
2023-05-03 11:45:28.146 INFO  --- [kafka-producer-network-thread | producer-1] org.apache.kafka.clients.producer.internals.TransactionManager : [Producer clientId=producer-1] ProducerId set to 5 with epoch 0

Taking a thread dump shows that the main thread is in a Kafka call:

"main" #1 prio=5 os_prio=31 cpu=9524.80ms elapsed=9.80s tid=0x00007fd232809a00 nid=0x2203 runnable  [0x00007000026f9000]
   java.lang.Thread.State: RUNNABLE
    at org.apache.kafka.clients.producer.internals.RecordAccumulator.partitionChanged(RecordAccumulator.java:242)
    at org.apache.kafka.clients.producer.internals.RecordAccumulator.append(RecordAccumulator.java:315)
    - locked <0x00000006005f2338> (a java.util.ArrayDeque)
    at org.apache.kafka.clients.producer.KafkaProducer.doSend(KafkaProducer.java:1027)
    at org.apache.kafka.clients.producer.KafkaProducer.send(KafkaProducer.java:949)
    at org.apache.kafka.clients.producer.KafkaProducer.send(KafkaProducer.java:834)
    at org.apache.logging.log4j.core.appender.mom.kafka.KafkaManager.send(KafkaManager.java:122)
    at org.apache.logging.log4j.core.appender.mom.kafka.KafkaAppender.tryAppend(KafkaAppender.java:224)
    at org.apache.logging.log4j.core.appender.mom.kafka.KafkaAppender.append(KafkaAppender.java:172)
    at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:161)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:134)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:125)
    at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:89)
    at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:683)
    at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:641)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:624)
    at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:560)
    at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:82)
    at org.apache.logging.log4j.core.Logger.log(Logger.java:162)
    at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2205)
    at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2159)
    at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2142)
    at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2034)
    at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1899)
    at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:180)
    at com.baozi.Main.main(Main.java:12)

I'm not familiar with the Kafka Log4j appender so I'm afraid I can't offer any suggestions to resolve the problem.

Comment From: baozi-2019

Thanks. This isn't a Spring Boot problem. With log4j.xml renamed to log4j2.xml so that it's found by default and the following main method:

``` package com.baozi;

import org.slf4j.Logger; import org.slf4j.LoggerFactory;

public class Main {

private static final Logger log = LoggerFactory.getLogger(Main.class);

public static void main(String[] args) { for (int i = 0; i < 10; i++) { log.info("Log message {}", i); } } } ```

This output is produced:

2023-05-03 11:45:27.933 �[32mINFO �[m --- [main] com.baozi.Main : Log message 0 2023-05-03 11:45:28.140 �[32mINFO �[m --- [kafka-producer-network-thread | producer-1] org.apache.kafka.clients.Metadata : [Producer clientId=producer-1] Resetting the last seen epoch of partition test.log-0 to 0 since the associated topicId changed from null to 2VQ-1wA2R3SQZkkQgfgBpQ 2023-05-03 11:45:28.145 �[32mINFO �[m --- [kafka-producer-network-thread | producer-1] org.apache.kafka.clients.Metadata : [Producer clientId=producer-1] Cluster ID: mF0utEwkRyCb_0H-4RBkyA 2023-05-03 11:45:28.146 �[32mINFO �[m --- [kafka-producer-network-thread | producer-1] org.apache.kafka.clients.producer.internals.TransactionManager : [Producer clientId=producer-1] ProducerId set to 5 with epoch 0

Taking a thread dump shows that the main thread is in a Kafka call:

"main" #1 prio=5 os_prio=31 cpu=9524.80ms elapsed=9.80s tid=0x00007fd232809a00 nid=0x2203 runnable [0x00007000026f9000] java.lang.Thread.State: RUNNABLE at org.apache.kafka.clients.producer.internals.RecordAccumulator.partitionChanged(RecordAccumulator.java:242) at org.apache.kafka.clients.producer.internals.RecordAccumulator.append(RecordAccumulator.java:315) - locked <0x00000006005f2338> (a java.util.ArrayDeque) at org.apache.kafka.clients.producer.KafkaProducer.doSend(KafkaProducer.java:1027) at org.apache.kafka.clients.producer.KafkaProducer.send(KafkaProducer.java:949) at org.apache.kafka.clients.producer.KafkaProducer.send(KafkaProducer.java:834) at org.apache.logging.log4j.core.appender.mom.kafka.KafkaManager.send(KafkaManager.java:122) at org.apache.logging.log4j.core.appender.mom.kafka.KafkaAppender.tryAppend(KafkaAppender.java:224) at org.apache.logging.log4j.core.appender.mom.kafka.KafkaAppender.append(KafkaAppender.java:172) at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:161) at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:134) at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:125) at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:89) at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:683) at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:641) at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:624) at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:560) at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:82) at org.apache.logging.log4j.core.Logger.log(Logger.java:162) at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2205) at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2159) at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2142) at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:2034) at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1899) at org.apache.logging.slf4j.Log4jLogger.info(Log4jLogger.java:180) at com.baozi.Main.main(Main.java:12)

I'm not familiar with the Kafka Log4j appender so I'm afraid I can't offer any suggestions to resolve the problem.

I modified spring boot version 3.0.2 and it works fine, does the new version fix this issue?

Comment From: wilkinsona

As I said above, it's not a Spring Boot problem. The example I shared above shows it occurring without any Spring Boot code being involved. It could be that it's been fixed in a third-party dependency that's been upgraded in Spring Boot's dependency management.