Log Custom JSON with Log4J2

Podés leer este post en español aquí.

This post is the outcome of my own experience when trying to log JSON objects on a Spring boot Java app using Log4J2. It was hard to accomplish since there is little documentation properly written about it. So, hopefully, this post will help if you ever have to deal with such a situation.
I implemented a small application that serves as an example. You can find the code here.

I'm using *2.1.6.RELEASE* Spring Boot Starter dependencies which, in turn, uses *2.11.2* Log4J2.

Adding Log4J2 to Spring Boot

The first step is excluding from every Spring boot starter, the spring-boot-starter-logging, since it imports Logback, and we don't want it to be the one logging.

<dependency>
   <groupId>org.springframework.boot</groupId>
   <artifactId>spring-boot-starter-web</artifactId>
   <version>2.1.6.RELEASE</version>
   <exclusions>
       <exclusion>
           <groupId>org.springframework.boot</groupId>
           <artifactId>spring-boot-starter-logging</artifactId>
       </exclusion>
   </exclusions>
</dependency>

Then, we add spring-boot-starter-log4j2 dependency:

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

That's it. We've got Log4J2 up and running on our app.

Setting up Log4J2

So, just by adding Log4J2 dependency, when the app runs, it loads its default configuration, using PatternLayout outcome by terminal. According to the documentation, if we want our own custom loggers, appenders and/or layouts we must create our own config file. The name should be log4j2.*  (* stands as YAML, JSON, properties or xml).

For this app I tried using .properties but it failed and we couldn't understand exactly why. The documentation explicitly declares it could be used without problems.

I decided on log4j2.yml , which I added to resources.For Log4J2 to be able to understand YAML I also had to import Jackson dependency.

<dependency>
   <groupId>com.fasterxml.jackson.dataformat</groupId>
   <artifactId>jackson-dataformat-yaml</artifactId>
   <version>2.9.0</version>
</dependency>

My first iteration of a config file ended up being like this:

Configuration:
 status: error

 Appenders:
   Console:
     - name: CONSOLE_ROOT
       target: SYSTEM_OUT
       PatternLayout:
         alwaysWriteExceptions: true
         pattern: "[%threadName] %-5level %logger{36} - %message{nolookups} %ex{separator(|)} %n"

 Loggers:
   Root:
     level: info
     AppenderRef:
       ref: CONSOLE_ROOT

This way, the app logs to the terminal using PatternLayout on a single line. The only logger being the root.

JSONLayout (and why I decided against it)

Log4J2 comes with a layout to print JSONs. This is JSONLayout.

We just have to add a new appender with the layout, and a new logger (In fact, just the appender would do, but I want to show both to emphasize the differences). Our config file looks like this.

Configuration:
 status: error

 Appenders:
   Console:
     - name: JSON_LAYOUT_APPENDER
       target: SYSTEM_OUT
       JSONLayout:
         compact: true
         complete: false
         objectMessageAsJsonObject: true

     - name: CONSOLE_ROOT
       target: SYSTEM_OUT
       PatternLayout:
         alwaysWriteExceptions: true
         pattern: "[%threadName] %-5level %logger{36} - %message{nolookups} %ex{separator(|)} %n"

 Loggers:
   logger:
     - name: LOGGER_WITH_JSON_LAYOUT
       level: info
       additivity: false
       AppenderRef:
         ref: JSON_LAYOUT_APPENDER

   Root:
     level: info
     AppenderRef:
       ref: CONSOLE_ROOT

Ok, now we've got a logger set and ready to use. The problem is that it comes with a set of predefined fields, and even some of them can't be edited. Next I'll leave an example where, using this logger on the repository, I send the following JSON in the body.

{
    "field": "value"
}

The output is:

{"thread":"http-nio-8080-exec-2","level":"INFO","loggerName":"LOGGER_WITH_JSON_LAYOUT","message":{"field":"value"},"endOfBatch":false,"loggerFqcn":"org.apache.logging.log4j.spi.AbstractLogger","instant":{"epochSecond":1564775298,"nanoOfSecond":516000000},"threadId":25,"threadPriority":5}

The actual log is just what we get on the message field, the rest being layout data which we don't actually need. It adds noise to the outcome and takes up space.

Note: The message field doesn’t log JSON by default, but a String. For it to log JSON we have to add objectMessageAsJsonObject: true (as you can see here on the config YAML). Even so, this feature will not be available on every Log4J2 version. Only 2.11.0 forward. Here's the link for the resolved issue https://issues.apache.org/jira/browse/LOG4J2-2190. You won’t find documentation for this issue.

Using Log4J2 API instead of SLF4J

So, to log out our own custom JSONs we need to stop using SLF4J as a logger, and change it to Log4J2 API, which provides a better bundle of features. We're most interested in the one which will allow us to create the JSON: [Message](https://logging.apache.org/log4j/2.x/manual/messages.html) object. To instantiate the logger, we have to use the LogManager in the yaml file (With the actual logger name we want).

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
...
private static Logger loggerWithJsonLayout = LogManager.getLogger(LOGGER_WITH_JSON_LAYOUT);

CustomLayout and CustomMessage

To generate the CustomLayout we just refer to the documentation. It ends up looking like this:

@Plugin(name = "CustomLayout", category = "Core", elementType = "layout", printObject = true)
public class CustomLayout extends AbstractStringLayout {

   private static final String DEFAULT_EOL = "\r\n";

   protected CustomLayout(Charset charset) {
       super(charset);
   }

   @PluginFactory
   public static CustomLayout createLayout(@PluginAttribute(value = "charset", defaultString = "UTF-8") Charset charset) {
       return new CustomLayout(charset);
   }

   @Override
   public String toSerializable(LogEvent logEvent) {
       return logEvent.getMessage().getFormattedMessage() + DEFAULT_EOL;
   }
}

What's significant here is #toSerializable, which comes with its LogEvent param. We get the Message object from there and format it to return a string. Note the use of EOL to allow multiline.

To use this new layout, we add a new logger and a new appender to our config YAML.

Configuration:
 status: error

 Appenders:
   Console:
     - name: CUSTOM_LAYOUT_APPENDER
       target: SYSTEM_OUT
       CustomLayout: {}

     - name: JSON_LAYOUT_APPENDER
       target: SYSTEM_OUT
       JSONLayout:
         compact: true
         complete: false
         objectMessageAsJsonObject: true

     - name: CONSOLE_ROOT
       target: SYSTEM_OUT
       PatternLayout:
         alwaysWriteExceptions: true
         pattern: "[%threadName] %-5level %logger{36} - %message{nolookups} %ex{separator(|)} %n"

 Loggers:
   logger:
     - name: LOGGER_WITH_CUSTOM_LAYOUT
       level: info
       additivity: false
       AppenderRef:
         ref: CUSTOM_LAYOUT_APPENDER

     - name: LOGGER_WITH_JSON_LAYOUT
       level: info
       additivity: false
       AppenderRef:
         ref: JSON_LAYOUT_APPENDER

   Root:
     level: info
     AppenderRef:
       ref: CONSOLE_ROOT

We also need to instantiate the new logger on the controller:

private static final String LOGGER_WITH_CUSTOM_LAYOUT = "LOGGER_WITH_CUSTOM_LAYOUT";
private static Logger loggerWithCustomLayout = LogManager.getLogger(LOGGER_WITH_CUSTOM_LAYOUT);

Then we need to generate our Message object:

public class CustomMessage implements Message {
   private static final String TYPE = "type";
   private static final String BODY = "body";

   private final Map<String, Object> requestBody;

   public CustomMessage(Map<String, Object> requestBody) {
       this.requestBody = requestBody;
   }

   @Override
   public String getFormattedMessage() {
       JSONObject jsonBody = new JSONObject(requestBody);
       JSONObject jsonToLog = new JSONObject(new HashMap<String, Object>() {{
           put(TYPE, "custom");
           put(BODY, jsonBody);
       }});

       return jsonToLog.toString();
   }

   @Override
   public String getFormat() {
       return requestBody.toString();
   }

   @Override
   public Object[] getParameters() {
       return new Object[0];
   }

   @Override
   public Throwable getThrowable() {
       return null;
   }
}

What's essential here is the constructor that takes the JSON we send on the request. Also the #getFormattedMessage method where we generate the JSON the way we want, and with the params we want, to later return it as string.

Finally, in the controller we just log the JSON.

@PostMapping()
@ResponseStatus(HttpStatus.OK)
void toLogWithTheCustomLayout(@RequestBody Map<String, Object> requestBody) {
   loggerWithCustomLayout.info(new CustomMessage(requestBody));
}

So, if we send a JSON like the following:

{
    "key1": "value1",
    "key2: 123
}

We get this log:

{"type":"custom","body":{"key1":"value1","key2":123}}

That's the JSON we've built in CustomMessage.

What would happen if we didn't use the CustomMessage, just printing the map we get on the request body?

I mean, like this:

@PostMapping()
@ResponseStatus(HttpStatus.OK)
void toLogWithTheCustomLayout(@RequestBody Map<String, Object> requestBody) {
   loggerWithCustomLayout.info(requestBody);
}

If we did that, we'd get this:

{
  key1=value1,
  key2=123
}

Summing up

Logs are a very important part of our applications. Being able to have our own custom logs with a particular structure to fit our needs is mandatory. I think Log4J2 provides a simple, easy-to-integrate and implement, way to achieve this.

Hopefully, you've found this post useful, or maybe you've got an easier or more fitting way to generate these types of logs. We'd love to hear from you. Feel free to comment.