Springboot 与 log4j2、结构化 JSON 日志记录

Question

关于如何使用 SpringBoot 应用程序实现结构化日志记录的小问题，但使用 log4j2（使用 logback，但不使用 log4j）。

我有一个超级简单的 SpringBoot 应用程序：

@RestController
@SpringBootApplication
public class Application {

    public static void main(String[] args) {
        SpringApplication.run(Application.class, args);
    }

    @RequestMapping("/")
    public String index(@RequestHeader("accept") String acceptHeader) {
        MDC.put("acceptHeader", acceptHeader);
        LoggerFactory.getLogger(getClass()).info("Hello");
        return "Greetings from Spring Boot!";
    }

    @Bean
    public CommandLineRunner commandLineRunner(ApplicationContext ctx) {
        return args -> function(ctx);
    }

    private void function(ApplicationContext ctx) {
        System.out.println("Let's inspect the beans provided by Spring Boot:");
        String[] beanNames = ctx.getBeanDefinitionNames();
        Arrays.sort(beanNames);
        for (String beanName : beanNames) {
            System.out.println(beanName);
        }
    }

}

用一个简单的 pom：

    <properties>
        <java.version>11</java.version>
        <maven.compiler.source>11</maven.compiler.source>
        <maven.compiler.target>11</maven.compiler.target>
    </properties>

    <dependencies>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
            <version>2.5.5</version>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-actuator</artifactId>
            <version>2.5.5</version>
        </dependency>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-log4j2</artifactId>
            <version>2.5.5</version>
        </dependency>
        <dependency>
            <groupId>net.logstash.logback</groupId>
            <artifactId>logstash-logback-encoder</artifactId>
            <version>6.6</version>
        </dependency>
    </dependencies>

使用 logback.xml （不是 log4j2.xml）

<configuration>
    <appender name="jsonConsoleAppender" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="net.logstash.logback.encoder.LogstashEncoder"/>
    </appender>
    <root level="INFO">
        <appender-ref ref="jsonConsoleAppender"/>
    </root>
</configuration>

这工作正常，非常高兴，我看到 JSON 格式的日志，结构化，非常高兴。

我试图使用 log4j2 获得相同的结果。我认为它会“开箱即用”，但是当切换到 log4j2.xml 时，日志又回到非 JSON。

请注意，在 pom.xml 中我有：

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

我正在尝试的 log4j2.xml ：

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="info">
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT" follow="true">
            <JsonTemplateLayout>
                <EventTemplateAdditionalField key="HOME_DIR" value="${env:HOME}"/>
            </JsonTemplateLayout>
        </Console>
    </Appenders>
    <Loggers>
        <Root level="info">
            <AppenderRef ref="Console" />
        </Root>
    </Loggers>
</Configuration>

我很困惑为什么这不会产生结构化的 JSON 日志记录，而是丢失了结构化的 JSON。

请问出了什么问题？

Answer 1

要在 Spring Boot 中使用 log4j2 进行日志记录，spring-boot-starter-logging需要排除依赖。一旦我这样做了，我就得到了错误Console contains an invalid element or attribute "JsonTemplateLayout"，这是由于log4j-layout-template-json奥利维尔提到的缺少依赖项造成的。添加该依赖项后，我从 log4j2 获得了预期的 JSON 日志，如下所示：

{"@timestamp":"2021-10-16T19:39:28.199Z","log.level":"INFO","message":"No active profile set, falling back to default profiles: default","process.thread.name":"main","log.logger":"com.example.demo.Application","HOME_DIR":"/some/path"}
{"@timestamp":"2021-10-16T19:39:28.791Z","log.level":"INFO","message":"Tomcat initialized with port(s): 8080 (http)","process.thread.name":"main","log.logger":"org.springframework.boot.web.embedded.tomcat.TomcatWebServer","HOME_DIR":"/some/path"}
{"@timestamp":"2021-10-16T19:39:28.801Z","log.level":"INFO","message":"Initializing ProtocolHandler [\"http-nio-8080\"]","process.thread.name":"main","log.logger":"org.apache.coyote.http11.Http11NioProtocol","HOME_DIR":"/some/path"}
{"@timestamp":"2021-10-16T19:39:28.802Z","log.level":"INFO","message":"Starting service [Tomcat]","process.thread.name":"main","log.logger":"org.apache.catalina.core.StandardService","HOME_DIR":"/some/path"}
{"@timestamp":"2021-10-16T19:39:28.802Z","log.level":"INFO","message":"Starting Servlet engine: [Apache Tomcat/9.0.53]","process.thread.name":"main","log.logger":"org.apache.catalina.core.StandardEngine","HOME_DIR":"/some/path"}
{"@timestamp":"2021-10-16T19:39:28.842Z","log.level":"INFO","message":"Initializing Spring embedded WebApplicationContext","process.thread.name":"main","log.logger":"org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/]","HOME_DIR":"/some/path"}
{"@timestamp":"2021-10-16T19:39:28.842Z","log.level":"INFO","message":"Root WebApplicationContext: initialization completed in 616 ms","process.thread.name":"main","log.logger":"org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext","HOME_DIR":"/some/path"}
{"@timestamp":"2021-10-16T19:39:29.149Z","log.level":"INFO","message":"Exposing 1 endpoint(s) beneath base path '/actuator'","process.thread.name":"main","log.logger":"org.springframework.boot.actuate.endpoint.web.EndpointLinksResolver","HOME_DIR":"/some/path"}
{"@timestamp":"2021-10-16T19:39:29.165Z","log.level":"INFO","message":"Starting ProtocolHandler [\"http-nio-8080\"]","process.thread.name":"main","log.logger":"org.apache.coyote.http11.Http11NioProtocol","HOME_DIR":"/some/path"}
{"@timestamp":"2021-10-16T19:39:29.175Z","log.level":"INFO","message":"Tomcat started on port(s): 8080 (http) with context path ''","process.thread.name":"main","log.logger":"org.springframework.boot.web.embedded.tomcat.TomcatWebServer","HOME_DIR":"/some/path"}
{"@timestamp":"2021-10-16T19:39:29.188Z","log.level":"INFO","message":"Started Application in 1.193 seconds (JVM running for 1.723)","process.thread.name":"main","log.logger":"com.example.demo.Application","HOME_DIR":"/some/path"}

以下是pom.xml我最终得到的结果，尽管logstash-logback-encoder现在未使用依赖项：

{"@timestamp":"2021-10-16T19:39:28.199Z","log.level":"INFO","message":"No active profile set, falling back to default profiles: default","process.thread.name":"main","log.logger":"com.example.demo.Application","HOME_DIR":"/some/path"}
{"@timestamp":"2021-10-16T19:39:28.791Z","log.level":"INFO","message":"Tomcat initialized with port(s): 8080 (http)","process.thread.name":"main","log.logger":"org.springframework.boot.web.embedded.tomcat.TomcatWebServer","HOME_DIR":"/some/path"}
{"@timestamp":"2021-10-16T19:39:28.801Z","log.level":"INFO","message":"Initializing ProtocolHandler [\"http-nio-8080\"]","process.thread.name":"main","log.logger":"org.apache.coyote.http11.Http11NioProtocol","HOME_DIR":"/some/path"}
{"@timestamp":"2021-10-16T19:39:28.802Z","log.level":"INFO","message":"Starting service [Tomcat]","process.thread.name":"main","log.logger":"org.apache.catalina.core.StandardService","HOME_DIR":"/some/path"}
{"@timestamp":"2021-10-16T19:39:28.802Z","log.level":"INFO","message":"Starting Servlet engine: [Apache Tomcat/9.0.53]","process.thread.name":"main","log.logger":"org.apache.catalina.core.StandardEngine","HOME_DIR":"/some/path"}
{"@timestamp":"2021-10-16T19:39:28.842Z","log.level":"INFO","message":"Initializing Spring embedded WebApplicationContext","process.thread.name":"main","log.logger":"org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/]","HOME_DIR":"/some/path"}
{"@timestamp":"2021-10-16T19:39:28.842Z","log.level":"INFO","message":"Root WebApplicationContext: initialization completed in 616 ms","process.thread.name":"main","log.logger":"org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext","HOME_DIR":"/some/path"}
{"@timestamp":"2021-10-16T19:39:29.149Z","log.level":"INFO","message":"Exposing 1 endpoint(s) beneath base path '/actuator'","process.thread.name":"main","log.logger":"org.springframework.boot.actuate.endpoint.web.EndpointLinksResolver","HOME_DIR":"/some/path"}
{"@timestamp":"2021-10-16T19:39:29.165Z","log.level":"INFO","message":"Starting ProtocolHandler [\"http-nio-8080\"]","process.thread.name":"main","log.logger":"org.apache.coyote.http11.Http11NioProtocol","HOME_DIR":"/some/path"}
{"@timestamp":"2021-10-16T19:39:29.175Z","log.level":"INFO","message":"Tomcat started on port(s): 8080 (http) with context path ''","process.thread.name":"main","log.logger":"org.springframework.boot.web.embedded.tomcat.TomcatWebServer","HOME_DIR":"/some/path"}
{"@timestamp":"2021-10-16T19:39:29.188Z","log.level":"INFO","message":"Started Application in 1.193 seconds (JVM running for 1.723)","process.thread.name":"main","log.logger":"com.example.demo.Application","HOME_DIR":"/some/path"}