Adding custom field to log4j json layout breaks spring logging structure

Question

I have a Spring Boot (2.2.6) application that uses Log4j2 (with Slf4j). Log4j is configured to use the json layout and in the end I want to ingest the logs in Datadog. For that the 'serviceName' is important as a field in the json.

Now according to the log4j docu (https://logging.apache.org/log4j/2.x/manual/layouts.html#JSONLayout) one can add a custom field with the 'KeyValuePair' tags and that works. Unfortunately this breaks the normal structure of the spring logs.

Log4j2.xml config:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
    <Appenders>
        <!-- Write logs to stdout, JSON, one line per log event -->
        <Console name="Console" target="SYSTEM_OUT">
            <JSONLayout compact="true" eventEol="true" includeStacktrace="true" locationInfo="true"
                        stacktraceAsString="true" properties="true">
      <KeyValuePair key="serviceName" value="$${env:APPLICATION_NAME:-local}-sidecar"/> <!-- fine w/o this line -->
</JSONLayout>
        </Console>
    </Appenders>
    <Loggers>
        <Logger name="my.service" level="debug" additivity="false">
            <AppenderRef ref="Console"/>
        </Logger>
        <Logger name="org.springframework" level="info" additivity="false">
            <AppenderRef ref="Console"/>
        </Logger>
        <Logger name="org.apache" level="info" additivity="false">
            <AppenderRef ref="Console"/>
        </Logger>
        <Root level="info">
            <AppenderRef ref="Console"/>
        </Root>
    </Loggers>
</Configuration>

Log w/o custom field:

{
  "thread": "main",
  "level": "INFO",
  "loggerName": "com.nginxtrafficsidecar.ApplicationKt",
  "message": "Starting ApplicationKt on xxx with PID 17300 (C:\\Users\\Felix\\Documents\\code\\nginx-traffic-sidecar\\build\\classes\\kotlin\\main started by Felix in C:\\Users\\Felix\\Documents\\code\\nginx-traffic-sidecar)",
  "endOfBatch": false,
  "loggerFqcn": "org.apache.commons.logging.LogAdapter$Log4jLog",
  "threadId": 1,
  "instant": {
    "epochSecond": 1587975181,
    "nanoOfSecond": 331370300
  },
  "source": {
    "class": "org.springframework.boot.StartupInfoLogger",
    "method": "logStarting",
    "file": "StartupInfoLogger.java",
    "line": 55,
    "classLoaderName": "app"
  },
  "contextMap": {},
  "threadPriority": 5
}

log w/ custom field:

{
  "logEvent": "Starting ApplicationKt on xxx with PID 9732 (C:\\Users\\Felix\\Documents\\code\\nginx-traffic-sidecar\\build\\classes\\kotlin\\main started by Felix in C:\\Users\\Felix\\Documents\\code\\nginx-traffic-sidecar)",
  "serviceName": "local-sidecar"
}

Spring docu mentions how this might work with logback, but not log4j (https://docs.spring.io/spring-boot/docs/current/reference/html/spring-boot-features.html#boot-features-custom-log-configuration, end of chapter)

I've searched but couldn't find anything useful. Any ideas how i can add a custom field to the json log while still preserving all fields coming from Spring?

Thanks, Felix

Answer 1

1. download Jackson Annotations and import it because JsonLayout use Jackson Annotations internal code.
   • in my case, download and import these

jackson-annotations-2.10.3.jar
jackson-core-2.10.3.jar
jackson-databind-2.10.3.jar

2. add <JsonLayout>...</JsonLayout> in your config(in my case log4j2.xml) like below

<JsonLayout>
  <KeyValuePair key="testKey" value="testValue"/>
</JsonLayout>

Replace key and value to what you want to use. In my case key is "testKey" and value is "testValue"

3. run and check your log!

it it my full sample code and xml configuration info. code

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.ThreadContext;

public class LogTest{
    private static final Logger logger = LogManager.getLogger(LogTest.class.getName());


    public static void main(String[] args) {
        ThreadContext.put("logFileName", "testFile1" );
        logger.info("log printed! - testFile1");

        ThreadContext.put("logFileName", "testFile2" );
        logger.info("log printed! - testFile2");

        ThreadContext.remove("logFileName");
    }

}

log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
    <Appenders>
        <Routing name="RoutingAppender">
            <Routes pattern="${ctx:logFileName}">
                <Route>
                    <RollingFile name="Rolling-${ctx:logFileName}"
                                 fileName="./logs/${ctx:logFileName}.log"
                                 filePattern="./logs/${ctx:logFileName}.%i.log.gz">
                        <JsonLayout>
                            <KeyValuePair key="testKey" value="testValue"/>
                        </JsonLayout>
                        <SizeBasedTriggeringPolicy size="512" />
                    </RollingFile>
                </Route>
            </Routes>
        </Routing>
    </Appenders>

    <Loggers>
        <Root level="all">
            <AppenderRef ref="RoutingAppender" />
        </Root>
    </Loggers>
</Configuration>

output

{
  "instant" : {
    "epochSecond" : 1588590944,
    "nanoOfSecond" : 469000000
  },
  "thread" : "main",
  "level" : "INFO",
  "loggerName" : "com.test.LogTest",
  "message" : "log printed! - testFile2",
  "endOfBatch" : false,
  "loggerFqcn" : "org.apache.logging.log4j.spi.AbstractLogger",
  "threadId" : 1,
  "threadPriority" : 5,
  "testKey" : "testValue"
}