Extending Log4j2

Creating Custom Log4j2 Plugins

2015-02-20

As you probably know, the differences between Log4j 1.x and Log4j2 are quite significant, and unless you're doing the most simple usage of Log4j you might have to make quite a few changes to support the version upgrade.

This article will give two simple examples of creating Log4j2 plugins, for those who need to do so for the first time, or those who need to see how they might rewrite existing Log4j1.x plugins. I'll also demonstrate how to write tests for the loggers with the use of a custom built String Appender.

The accompanying source code is available here:

/rewolf/blog-extending-log4j2

Table Mountain, Cape Town, South Africa. Taken from Lion's Head

Logging Request Ids

Most implementations of API services have some way of tracking the flow of individual requests. The common way to do this is with globally unique identifiers that identify individual requests and are logged with every log message and eventually returned to the customer with the response.

I'll demonstrate how one might provide logging support for a request Id in a system using Log4j2. Of course a possible solution would be to prepend the request Id every time you log something, but that is a seriously unreasonable approach. You could also have a wrapper log method that prepends it for you. But a nicer solution would be to have a new conversion pattern that could be used in PatternLayouts. If we call it %requestId a pattern might look as follows:

<Pattern>%-5p %d [%requestId] %c: %m%n</Pattern>

Producing logs something like the following:

INFO  2015-02-20 12:34,567 [abcd-efgh-1234] com.andrew_flower.example.Log4ConverterTest: This is a log!

In the following section you'll see how to add functionality to interpret the new code.

A new Pattern Converter

There are a few different types of Log4j2 plugins. In this case we will be creating a Converter. Converters are used in Patterns such as in the pattern of a PatternLayouts or the filename of a RollingFileAppender. The converter specifies a coverter key/pattern and also defines how that key should be replaced when contained in a pattern string.

We will be creating a converter for PatternLayouts as opposed to for filenames. All Log4j2 plugins must have the @Plugin annotation, but on top of that, each plugin type has additional requirements. I'll list what is needed for a PatternLayout converter:

Must have the @Plugin annotation.
The @Plugin annotation must have a name and specify "Converter" as the category. If this were for filename patterns it would be "FileConverter".
Converters should have the @ConverterKeysannotation and including a list of keys that it should match in a pattern string. You might have a short or long name for the key. For example, the existing ThrowablePatternConverter specifies { "ex", "throwable", "exception" }
A converter for log patterns (like we're creating) must extend LogEventPatternConverter.
It must have a newInstance static method taking a String array and returning an instance of the converter.
It must override the format method. It is this method that must contain the functionality to provide a replacement value for the pattern key.

So now we'll take a look at one way of writing the converter class. Take a look at the code below

package com.andrew_flower.demo.logging;

import com.andrew_flower.demo.HypotheticalApplicationRequestHandler;
import org.apache.logging.log4j.core.LogEvent;
import org.apache.logging.log4j.core.config.plugins.Plugin;
import org.apache.logging.log4j.core.pattern.*;

/**
 * Converter for Log strings that replaces the format token %requestId with current request Id from RequestHandler
 *
 * @author rewolf
 */
@Plugin(name = "RequestIdConverter", category = "Converter")
@ConverterKeys({"requestId"})
public class RequestIdConverter extends LogEventPatternConverter {

    private RequestIdConverter(final String name, final String style) {
        super(name, style);
    }

    public static RequestIdConverter newInstance(final String[] options) {
        return new RequestIdConverter("requestId", "requestId");
    }

    @Override
    public void format(final LogEvent event, final StringBuilder toAppendTo) {
        toAppendTo.append(getRequestId());
    }

    private String getRequestId() {
        String requestId = HypotheticalApplicationRequestHandler.getInstance().getCurrentRequestId();

        if (requestId == null) {
            requestId = "-";
        }

        return requestId;
    }
}

The example is very straight forward and you can see that the class obeys all the rules we enumerated above. Note that where the constructor calls the superclass it passes two strings. The first is the name of the converter, and the second is a CSS classname. Although we don't use CSS here, I've just used the same name. The format method receives a LogEvent object containing information like the message and level, and a StringBuilder which contains the evaluated log pattern up to the point of encountering this converter key. So all the format method must do is append the appropriate value to insert.

Configuration File

In order to use this file we can create a simple config file that makes use of our converter key.

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="ERROR">
  <Appenders>
    <Console name="STDOUT" target="SYSTEM_OUT">
      <PatternLayout pattern="%-5p %d [%requestId] %c: %m%n"/>
    </Console>
  </Appenders>
  <Loggers>
    <Root level="INFO">
      <AppenderRef ref="STDOUT"/>
    </Root>
  </Loggers>
</Configuration>

And that's all there is to creating a custom converter! Really simple and easy. I'm sure there many more imaginative things that can be inserted into pattern strings, but I'll leave that up to you guys. Thought I'd be interested to hear what other people have implemented. In the next section I'll run through how we might test this converter.

NOTE: When using such a converter as a maven dependency, I've had the case where it is not automatically registered as a converter and the converter key is not replaced.

In that case you should explicitly add your package to the Configuration tag:

<Configuration status="INFO" name="log-test" packages="com.andrew_flower.demo">

Testing the Converter

In my opinion code is not finished without tests, so let's complete this example by trying to write some JUnit tests for this. I'll just write two tests but you should obviously think of as many test conditions as you can. Let's write the following two tests:

A unit test to test the format method, that given our RequestIdConverter object, when calling format with a StringBuilder containing a message at the key point, then it will return the StringBuilder with the current requestId appended.
A component test to test that the Log4j2 configuration logs the request Id. So given a log configuration with PatternLayout containing a %requestId, when we call log(), then the log line contains the request Id. For this we'll create a special Appender that allows us to log to a String.

Write the tests

So this is the simple part, let's write the outline for what we want tests to do. The first test formatAppendsRequestId is really easy. We create an instance of our converter and test that it appends the request Id to the StringBuilder that we pass to it. Note that for completeness I've stubbed out the mythical request Id provider. Because our converter doesn't depend on anything from the log message itself, we pass null as the log event parameter. Have a look at the code:

package com.andrew_flower.demo;


import com.andrew_flower.demo.logging.RequestIdConverter;
import com.andrew_flower.demo.util.StringAppender;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.junit.Before;
import org.junit.Test;

import static org.junit.Assert.assertEquals;

/**
 * @author rewolf
 */
public class LogConverterTest {
    private final static String STUB_REQUEST_ID = "this-is-a-request-id";

    @Before
    public void setup() {
        HypotheticalApplicationRequestHandler stub = new HypotheticalApplicationRequestHandler() {
            @Override
            public String getCurrentRequestId() {
                return STUB_REQUEST_ID;
            }
        };
        HypotheticalApplicationRequestHandler.setInstance(stub);
    }

    @Test
    public void formatAppendsRequestId() {
        RequestIdConverter converter = RequestIdConverter.newInstance(new String[]{});
        StringBuilder message = new StringBuilder().append("BEFORE_");

        converter.format(null, message);

        assertEquals("BEFORE_" + STUB_REQUEST_ID, message.toString());
    }

    @Test
    public void logReplacesKeyWithRequestId() {
        // Get the RootLogger which, if you don't have log4j2-test.xml defined, will only log ERRORs
        Logger logger = LogManager.getRootLogger();
        // Create a String Appender to capture log output
        StringAppender appender = StringAppender.createStringAppender("[%requestId] %m");
        appender.addToLogger(logger.getName(), Level.INFO);
        appender.start();

        // Log to the string appender
        logger.error("Test");

        assertEquals("[" + STUB_REQUEST_ID + "] Test", appender.getOutput());
        appender.removeFromLogger(LogManager.getRootLogger().getName());
    }
}

The second test logReplacesKeyWithRequestId makes use of an imaginary appender type called StringAppender. In Log4j 1.x a similar appender existed, but it's not so easy in Log4j2. We can, however, quite easily create our own StringAppender and we do so in the next section. Note above that we assume there is no log4j2-test.xml defined, so the default configuration is to log ERROR logs only. For the test we therefore call error() on the RootLogger.

A String Appender

Our goal here is to create a means by which we can log to an in-memory String, or String stream. The Log4j2 Manual mentions an OutputStreamAppender that many Appenders actually extend. It is a very powerful class and also depends on a OutputStreamManager to handle the IO. We will just use the bare minimum of these classes to provide the functionality that is needed for our test.

Truly we should be writing a test for this class too, but I will skip that for conciseness' sake.

package com.andrew_flower.demo.util;

import org.apache.logging.log4j.*;
import org.apache.logging.log4j.core.*;
import org.apache.logging.log4j.core.appender.*;
import org.apache.logging.log4j.core.config.*;
import org.apache.logging.log4j.core.config.plugins.PluginFactory;
import org.apache.logging.log4j.core.layout.PatternLayout;

import java.io.*;

/**
 * A Custom Appender for Log4j2 that logs to a String. This is useful for testing logging.
 *
 * @author rewolf
 */
public class StringAppender extends AbstractOutputStreamAppender<StringAppender.StringOutputStreamManager> {
    private static LoggerContext context = (LoggerContext) LogManager.getContext(false);
    private static Configuration configuration = context.getConfiguration();
    private StringOutputStreamManager manager;

    private StringAppender(String name, Layout<? extends Serializable> layout, StringOutputStreamManager manager, boolean ignoreExceptions, boolean immediateFlush) {
        super(name, layout, null, ignoreExceptions, immediateFlush, null,manager);
        this.manager = manager;
    }

    /**
     * Create a StringAppender with a given output format
     * @param nullablePatternString Can be {@code null}. The PatternLayout string for log output.
     * @return a new StringAppender
     */
    @PluginFactory
    public static StringAppender createStringAppender(final String nullablePatternString) {
        final ByteArrayOutputStream outputStream = new ByteArrayOutputStream();
        final PatternLayout layout;

        if (nullablePatternString == null) {
            layout = PatternLayout.createDefaultLayout();
        } else {
            layout = PatternLayout.newBuilder()
                                  .withPattern(nullablePatternString)
                                  .build();
        }

        return new StringAppender(
                "StringAppender",
                layout,
                new StringOutputStreamManager(outputStream, "StringStream", layout),
                false,
                true);
    }

    public void addToLogger(final String loggerName, final Level level) {
        LoggerConfig loggerConfig = configuration.getLoggerConfig(loggerName);
        loggerConfig.addAppender(this, level, null);
        context.updateLoggers();
    }

    public void removeFromLogger(final String loggerName) {
        LoggerConfig loggerConfig = configuration.getLoggerConfig(loggerName);
        loggerConfig.removeAppender("StringAppender");
        context.updateLoggers();
    }

    public String getOutput() {
        manager.flush();
        return new String(manager.getStream().toByteArray());
    }

    /**
     * StringOutputStreamManager to manage an in memory byte-stream representing our stream
     */
    static class StringOutputStreamManager extends OutputStreamManager {
        ByteArrayOutputStream stream;

        StringOutputStreamManager(ByteArrayOutputStream os, String streamName, Layout<?> layout) {
            super(os, streamName, layout, false);
            stream = os;
        }

        ByteArrayOutputStream getStream() {
            return stream;
        }
    }
}

The interesting parts are the methods createStringAppender, addToLogger and getOutput. createStringAppender returns our StringAppender class after setting up a StringOutputStreamManager with a ByteArrayOutputStream that will be used for writing log data. addToLogger will add this StringAppender object to the list of appenders of the provided Logger. Finally getOutput returns the string that was created by the logger. You can lookup PatternLayout.create* methods in the javadoc as well as the superclass constructors for AbstractOutputStreamAppender and OutputStreamManager.

This demonstrates how we might create an in-memory StringAppender to test Loggers in JUnit, or even for other purposes. In production you would want to better check for errors, and probably let it be more customizable, but this serves as an easy example for now.

The accompanying source code is available here:

/rewolf/blog-extending-log4j2