Springboot with log4j2, structured JSON logging

Question

Small question regarding how to achieve structured logging with a SpringBoot app, but using log4j2 (working with logback, but not log4j).

I have a super simple SpringBoot app:

@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);
        }
    }

}

with a simple 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>

with a logback.xml (not 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>

And this is working fine, very happy, I am seeing the logs in JSON format, structured, very happy.

I am trying to get the same result, using log4j2. I thought it will "work out of the box" but when switching to log4j2.xml, the logs are back to non JSON.

Please note, in the pom.xml I have:

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

And the log4j2.xml with I am trying:

<?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>

I am very puzzled why this would not yield a structured JSON logging, but lost the structured JSON.

What went wrong please?

Answer 1

To use log4j2 for logging in spring boot, the spring-boot-starter-logging dependency needs to be excluded. Once I did that, I got the error Console contains an invalid element or attribute "JsonTemplateLayout", which is due to the missing log4j-layout-template-json dependency that Olivier mentioned. After adding that dependency also, I got the expected JSON logs from log4j2 that looked like below:

{"@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"}

Below is the pom.xml I ended up with though the logstash-logback-encoder dependency is unused now:

    <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>
            <exclusions>
                <exclusion>
                    <groupId>org.springframework.boot</groupId>
                    <artifactId>spring-boot-starter-logging</artifactId>
                </exclusion>
            </exclusions>
        </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>org.apache.logging.log4j</groupId>
            <artifactId>log4j-layout-template-json</artifactId>
            <version>2.14.1</version>
        </dependency>
        <dependency>
            <groupId>net.logstash.logback</groupId>
            <artifactId>logstash-logback-encoder</artifactId>
            <version>6.6</version>
        </dependency>
    </dependencies>