Log4j 2 JSON pattern layout + Logging JSON payload

Question

I am using ELK stack along with log4j 2 via sl4j with json pattern layout to log messages. All my logs are logged as json messages.Also in one of my logs I am trying to log the json response received from the third party service. But this response json body is not appended to the json structure. But it rather appended as a string including the escape characters.

how the ultimate logs being logged out.

 {
    "timeMillis": 1471862316416,
    "thread": "FioranoMQ Pubsub Session Thread",
    "level": "INFO",
    "loggerName": "com.mlp.eventing.bridge.fiorano.TopicMessageListener",
    "message": "{\"Msgtype\":\"SentToRabbitMqTest\",\"MessageData\":\"10\",\"opration\":\"devide\"}",
    "endOfBatch": false,
    "loggerFqcn": "org.apache.logging.slf4j.Log4jLogger",
    "threadId": 28,
    "threadPriority": 5
}

In above message segment is appended as escaped strings rather than the entire json structure. My expected out put should be

{
    "timeMillis": 1471862316416,
    "thread": "FioranoMQ Pubsub Session Thread",
    "level": "INFO",
    "loggerName": "com.mlp.eventing.bridge.fiorano.TopicMessageListener",
    "message": {
        "Msgtype": "SentToRabbitMqTest",
        "MessageData": "10",
        "opration": "devide"
    },
    "endOfBatch": false,
    "loggerFqcn": "org.apache.logging.slf4j.Log4jLogger",
    "threadId": 28,
    "threadPriority": 5
}

I am expecting to extract the fields in the message segment using the grok filters for json in shipper.conf

Below are my configurations :- log4j2.xml

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="info"> <!-- log4j internals tracing -->
    <properties>
        <property name="pattern">%d{yyyy-MM-dd HH:mm:ss.SSS} | %-5.5p | %-20.20C:%-5.5L | %msg%n</property>
        <property name="filePath">/opt/mlp/logs</property> 
        <property name="fileName">logs</property>
    </properties>
    <Appenders>
        <RollingFile name="RollingFile" fileName="${filePath}/${fileName}.log"
                     filePattern="${filePath}/${fileName}-%d{yyyy-MM-dd}-%i.log" append="true">
            <JSONLayout complete="false" compact="true" eventEol="true" />  
            <PatternLayout>
                <pattern>${pattern}</pattern>
            </PatternLayout>
            <Policies>
                <SizeBasedTriggeringPolicy size="1000 KB"/> 
            </Policies>l
        </RollingFile>
        <Console name="STDOUT" target="SYSTEM_OUT">
            <PatternLayout>
                <pattern>${pattern}</pattern>
            </PatternLayout>
        </Console>
    </Appenders>
    <Loggers>
        <Root level="debug">
            <AppenderRef ref="RollingFile"/>
            <AppenderRef ref="STDOUT"/>
        </Root>
    </Loggers>
</Configuration>

sample code snippet

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

class A {
private static final Logger LOG = LoggerFactory.getLogger(Main.class);

public void testMethod()  {

JSONObject responseJson = callService();// json simple object
LOG.info(responseJson);

}

}

maven dependencies

<dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>slf4j-api</artifactId>
            <version>1.7.21</version>
        </dependency>

        <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-slf4j-impl</artifactId>
            <version>2.6.2</version>
        </dependency>

        <!-- end adding sl4j 2 for the message bridge -->

        <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-api</artifactId>
            <version>2.6.2</version>
        </dependency>

        <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-core</artifactId>
            <version>2.6.2</version>
        </dependency>

        <!--
        to enable json support for log4j enable following libraries
        -->

        <dependency>
            <groupId>com.fasterxml.jackson.core</groupId>
            <artifactId>jackson-core</artifactId>
            <version>2.7.5</version>
        </dependency>

        <dependency>
            <groupId>com.fasterxml.jackson.core</groupId>
            <artifactId>jackson-databind</artifactId>
            <version>2.7.5</version>
        </dependency>

        <dependency>
            <groupId>com.fasterxml.jackson.core</groupId>
            <artifactId>jackson-annotations</artifactId>
            <version>2.7.5</version>
        </dependency>

Reconcilable

Did you end up solving your issue? – Franny

This might seem like a dumb question, but isn't the third party response a string and not an Object? Because if so, then everything was perfect with the logging and you just needed to parse the response. – Dit

I have a similar issue. The Log4J Json Layout escapes the string so the output printed to file is not a valid json. The pattern layout prints without escaping. – Knotty

Answer 1

To be able to log JSON unescaped, you should use Log4j2 logger instead of Slf4j. This feature is available starting from Log4j 2.11.

Log4j logger is able to log ObjectMessage, which will be converted to a nested JSON. ObjectMessage constructor accepts Map, so JSONObject have to be converted to map (e.g. with help of Jackson ObjectMapper).

In the layout configuration add objectMessageAsJsonObject="true":

<JSONLayout complete="false" compact="true" eventEol="true" objectMessageAsJsonObject="true" />

Full working example:

import com.fasterxml.jackson.core.type.TypeReference;
import com.fasterxml.jackson.databind.ObjectMapper;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.message.ObjectMessage;
import org.json.JSONObject;

import java.io.IOException;
import java.util.HashMap;
import java.util.Map;

public class test {

    public static void main(String[] args) throws IOException {
        HashMap<Object, Object> map = new HashMap<>();
        map.put("foo", "bar");
        JSONObject jsonObject = new JSONObject(map);

        Map<String, Object> newMap = new ObjectMapper().readValue(jsonObject.toString(), new TypeReference<Map<String, Object>>() {});

        Logger log4jLogger = LogManager.getLogger("mainLogger");
        log4jLogger.info(new ObjectMessage(newMap));
    }
}

This will produce:

{"thread":"main","level":"INFO","loggerName":"mainLogger","message":{"foo":"bar"},"endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","instant":{"epochSecond":1548434758,"nanoOfSecond":572000000},"threadId":1,"threadPriority":5}

Impi

not happening for me the it is logged as {"timeMillis":1615981656315,"thread":"main","level":"INFO","loggerName":"com.ServiceApplication","message":"{foo=bar}"} – Holocaine

Me to when using log4j2 version 2.13.3 :( – Mondrian