Writing Log4J 2.x Plugins

Originally published: 2020-04-05

Last updated: 2020-04-05

I recently implemented Log4J 2.0 support for my AWS appenders project. When I started, I was hoping to find some sort of “here's how to implement a Log4J2 appender” posting, either in the project docs or elsewhere on the Internet. But either my Googling skills are getting worse, or there aren't any independent postings on the subject. And as for the project documentation … well, Apache projects aren't exactly known for the quality of their docs.

So, like you do, I turned to the source code, to see how the in-project appenders were written. And I wrote a simple appender, progressively adding features. This article covers the things that I learned at each stage. If you want to follow along with code, there's a project on GitHub.

So let's get started.

Configuration

This was the first place that I stumbled when working with Log4J 2.x, because its XML configuration format looks almost, but not quite, like that used by Logback. In Logback, you have an <appender> element and have to specify the fully-qualified classname of your appender. With Log4J2, the docs seem to indicate the same, although the “type” attribute isn't a fully-qualified classname, which is a clue that it's not.

It took me a while to realize that, with its plugin architecture, Log4J2 requires you to specify a packages attribute at the top of the configuration file, which indicates where to search for plugins (the documentation of that attribute appears above the section titled “Configuration with XML", and like most developers I jumped right to the section that I thought I needed).

With that misunderstanding resolved, here's my initial configuration file, referencing my appender:

<Configuration status="warn" packages="com.kdgregory.sandbox.log4j2"> 
    <Appenders> 
        <MyAppender name="STDOUT"> 
            <PatternLayout pattern="%d [%t] %-5p %c{1} - %m" /> 
        </MyAppender> 
    </Appenders> 
    <Loggers> 
        <Root level="debug"> 
            <AppenderRef ref="STDOUT" /> 
        </Root> 
    </Loggers> 
</Configuration> 

A Basic Appender

My first thought, as I looked at the various factories, builders, and managers involved with a Log4J2 appender, was “this is why people make fun of ‘enterprise’ Java!” However, a very basic appender doesn't need builders or managers. But you do need a factory.

@Plugin(name = "MyAppender", category = Core.CATEGORY_NAME, elementType = Appender.ELEMENT_TYPE)
public class MyAppender
extends AbstractAppender
{
    @PluginFactory
    public static MyAppender createAppender(
        @PluginAttribute("name") String name,
        @PluginElement("Layout") Layout<String> layout,
        @PluginElement("Filters") Filter filter)
    {
        return new MyAppender(name, filter, layout);
    }


    @SuppressWarnings("deprecation")
    private MyAppender(String name, Filter filter, Layout<String> layout)
    {
        super(name, filter, layout);
        System.err.println("MyAppender constructed as " + name);
    }


    @Override
    public void append(LogEvent event)
    {
        System.out.println(getLayout().toSerializable(event));
    }
}

Like many plugin architectures, Log4J2 uses Java annotations to identify the things that are relevant to the framework. However, unlike, say, Spring, which uses different annotations for different types of plugins, Log4J uses a single @Plugin annotation, with attributes that identify the type of plugin.

Here I use constants for the category and elementType attribute values. However, they are relatively recent introductions: version 2.6 for Appender.ELEMENT_TYPE, and version 2.8 for Core.CATEGORY_NAME. The documentation uses literal values, and if you plan to support older versions of the library, you will need to do the same (although be aware that non-backwards-compatible changes won't let you go beyond 2.7 without providing multiple implementations).

The plugin's factory method is separately annotated, with @PluginFactory. Its parameters are the appender's configuration values, and they're annotated with either @PluginAttribute or @PluginElement: the former for “simple” values, the latter for values that are themselves plugins.

All appenders take a name, a layout object, and a filter object; the names of these attributes are defined by Log4J. This version of the example doesn't add anything else.

MyAppender subclasses AbstractAppender, which provides basic appender functionality such as life-cycle management. As a result, I just need to implement append() (although as we'll see later, you typically override some of the life-cycle methods).

Because Log4J uses a factory method to create the appender, it can have a private constructor. Note the @SuppressWarnings annotation: for this example I'm calling a simplified AbstractAppender constructor that has been deprecated since 2.11. Again, if you need to support older versions of the library, you'll need to pay attention to these details.

Moving on to the append() method, and more particularly, the Layout it uses to format log events. Other logging frameworks assume that they'll be writing strings; their appenders are responsible for translating those strings to other formats (such as byte arrays) if needed. Log4J 2.x, however, allows a layout to produce anything that implements Serializable, and also requires the layout to produce a byte array.

This latter requirement means that appenders can just write the layout output to an OutputStream. It also enables two optimizations: one that quickly transforms strings that use only the USO-8859-1 character set, and another (the “zero garbage” optimization) in which the layout fills a pre-allocated buffer.

The downside of this approach is that end-users can easily configure a non-string-producing layout with a string-expecting appender. Even though my appender's class signature specifies that it takes a Layout<String>, Java's type erasure makes that only useful for documentation. And although Layout defines a getContentType() method, that's intended for consumption by the ultimate destination; most appenders don't check its response.

Before finishing this section, I want to comment on my use of System.err in the constructor. When I write an experimental program, I often use System.err for log output: it's unbuffered, so I can see the output right away, and Eclipse highlights its output in red. For a “real” appender, however, any internal logging should go through the Log4J “status logger,” which is controlled by the configuration file.

Configuration Properties

Maybe your developers aren't paying attention to log messages, and you think it would be a good idea if each message were repeated several times. This is a perfect use for a custom appender! Please don't take that seriously, but it is a good way to demonstrate appender configuration.

Let's start with the configuration update: I added a repeats property that will control how often the appender writes each log message.

<MyAppender name="STDOUT"> 
    <PatternLayout pattern="%d [%t] %-5p %c{1} - %m" /> 
    <repeats>3</repeats> 
</MyAppender> 

Now it's time to make that work. With Logback or Log4J 1.x, you would add an instance variable to the appender and a setter method to configure it. With Log4J 2.x, you add a parameter to the factory method, tagged with @PluginAttribute:

@PluginFactory
public static MyAppender createAppender(
    @PluginAttribute("name") String name,
    @PluginElement("Layout") Layout<String> layout,
    @PluginElement("Filters") Filter filter),
    @PluginAttribute("repeats") int repeats
{
    return new MyAppender(name, filter, layout, repeats);
}

That argument then gets passed on to the constructor. This is where things get a little tricky. With the setter-based injection of other logging frameworks, you can specify a default value for a configuration parameter; if the setter isn't called, the appender will use the default value.

However, with Log4J2, if the configuration doesn't specify a value, you'll get the “default” value for the argument's type: zero or null. Which means that the constructor needs to check all of its arguments for these values, and replace with an appropriate default (or use a recent version of Log4J2, which allows you to specify default values in the parameter annotation). In my case, I don't allow you to turn off repeats entirely, so can code that 0 (the default) actually means 1.

private int repeats;

@SuppressWarnings("deprecation")
private MyAppender(String name, Filter filter, Layout<String> layout, int repeats)
{
    super(name, filter, layout);
    this.repeats = (repeats != 0) ? repeats : 1;
}

With this in place, we can now put a loop in append(). If I was writing a production appender, I would apply the layout once, save the result in a variable, and print the saved value in the loop.

@Override
public void append(LogEvent event)
{
    for (int ii = 0 ; ii < repeats ; ii++)
    {
        System.out.println(getLayout().toSerializable(event));
    }
}

Builders

In addition to the problem of default values, an appender with a lot of configuration parameters is unwieldy to construct. This is not so much a problem when you configure with a file, but some people still configure things in code. The solution to both issues is to introduce a builder: an object that you can configure incrementally using setter methods, and which provides a build() method that constructs the actual appender.

Introducing a builder does not change the appender proper. Instead, it replaces the existing factory method (annotated with @PluginFactory) by a nested builder class and a factory method (annotated with @PluginBuilderFactory) that instantiates that class. There's a lot of code that follows; I'll dig into it below.

@Plugin(name = "MyAppender", category = Core.CATEGORY_NAME, elementType = Appender.ELEMENT_TYPE)
public class MyAppender extends AbstractAppender
{
    @PluginBuilderFactory
    public static MyAppenderBuilder newBuilder() {
        return new MyAppenderBuilder();
    }


    public static class MyAppenderBuilder
    implements org.apache.logging.log4j.core.util.Builder<MyAppender> 
    {
        @PluginBuilderAttribute("name")
        @Required(message = "MyAppender: no name provided")
        private String name;

        @PluginElement("Layout")
        private Layout<String> layout;

        @PluginElement("Filter")
        private Filter filter;

        @PluginBuilderAttribute("repeats")
        private int repeats = 1;

        public MyAppenderBuilder setName(String value)
        {
            this.name = value;
            return this;
        }

        public MyAppenderBuilder setLayout(Layout<String> value)
        {
            this.layout = value;
            return this;
        }

        public MyAppenderBuilder setFilter(Filter value)
        {
            this.filter = value;
            return this;
        }

        public MyAppenderBuilder setRepeats(int value)
        {
            this.repeats = value;
            return this;
        }

        @Override
        public MyAppender build()
        {
            return new MyAppender(name, filter, layout, repeats);
        }
    }

Let's start with the builder's implements clause, which uses a fully-qualified classname. This is required because org.apache.logging.log4j.core.appender.AbstractAppender has its own nested Builder class. And while the built-in class gives you boilerplate for the name, layout, and filter attributes, I found that getting the parameterization right was challenging. As a result, I adopted the practice of many of the built-in appenders and directly implemented core.util.Builder.

The appender's configuration properties are now instance variables of the builder class. The annotation names for these variables have changed: @PluginBuilderAttribute for simple strings, @PluginElement is for properties that are themselves plugins. For most appenders, layout and filter are the only injected plugins, but you will find others amongst the built-in appenders (for example, SocketAppender uses a plugin to provide SSL configuration).

You'll notice that the name attribute is marked with the @Required annotation. Log4J provides a very limited set of validation operations, and allows you to define your own. My preference is to handle validation in the build() method.

As a final note on the builder, I've followed the practice of built-in appenders by providing only setter methods, and having them return the builder object. There's no need for getters: builder objects only live for a short time, even with manual configuration. And there's nothing magic about the method name; you could follow the modern convention of withXXX() for chainable methods.

The last thing to note is that the appender's constructor has changed: since the builder has a default value for repeats, we don't need the ternary expression.

private MyAppender(String name, Filter filter, Layout<String> layout, int repeats)
{
    super(name, filter, layout);
    this.repeats = repeats;
}

Introducing a Configuration Interface

In my view, one of the drawbacks of the Log4J2 builder approach — at least as implemented in the built-in appenders — is that you have to define all of the configuration variables in the builder, and then again in the appender. Plus you have the boilerplate of passing those variables to the constructor and assigning them there. That's maybe not a problem with a simple appender like the one I'm showing, but real-world appenders might have a dozen or more configuration parameters.

My approach to this is to add getters to the builder object, and create an interface that defines them. The builder implements this interface, and passes itself to the appender's constructor.

So, first step is to define an interface with all of the getters. Since this is a private interface, I don't feel a strong need to document the interface or its methods.

private interface MyAppenderConfig
{
    String getName();
    Layout<String> getLayout();
    Filter getFilter();
    int getRepeats();
}

Next, the builder object has to implement this interface, and define the actual getters. I've cut down the actual code for the sake of space.

public static class MyAppenderBuilder
implements org.apache.logging.log4j.core.util.Builder<MyAppender>, MyAppenderConfig
{
    @PluginBuilderAttribute("name")
    @Required(message = "MyAppender: no name provided")
    private String name;

    @Override
    public String getName()
    {
        return this.name;
    }

    public MyAppenderBuilder setName(String value)
    {
        this.name = value;
        return this;
    }

    // other variables, setters, getters

    @Override
    public MyAppender build()
    {
        return new MyAppender(this);
    }
}

And lastly, the changes to the appender proper:

private MyAppenderConfig config;


@SuppressWarnings("deprecation")
private MyAppender(MyAppenderConfig config)
{
    super(config.getName(), config.getFilter(), config.getLayout());
    this.config = config;
}


@Override
public void append(LogEvent event)
{
    for (int ii = 0 ; ii < config.getRepeats() ; ii++)
    {
        System.out.println(getLayout().toSerializable(event));
    }
}

Appender Life-Cycle

The simple appender in this article is ready to use as soon as it's constructed, because it writes all output to standard out. However, a more complex appender might need some initialization: for example, opening a network connection to a log aggregator. And every appender should be able to support layouts that have a header and footer — for example, HtmlLayout, which emits the boilerplate structure of an HTML page as header and footer for the table rows that are emitted by append().

To support these abilities, every Log4J2 appender follows a life-cycle:

Construction
The framework creates a new appender instance every time configuration is changed.
Initialization
After all appenders have been constructed, the framework will call start() on each of them. This is when the appender should retrieve and output the layout's header (if it exists).
Operation
The framework calls append() for each log message.
Shutdown
The appender calls stop() on each appender. This is when it should retrieve and output the layout's footer, if any.

For this example, I've changed the Main program to write debug messages to standard error, and also to reconfigure the logger between the first and second messages:

public static void main(String[] argv)
throws Exception
{
    System.err.println("main started, getting logger");
    Logger logger = LogManager.getLogger(Main.class);

    logger.info("Hello, World");

    // this simulates changes to the configuration file during runtime
    System.err.println("reconfiguring logging context");
    final LoggerContext context = (LoggerContext) LogManager.getContext(false);
    context.reconfigure();

    logger.info("Did you hear me? Was it on a separate line?");

    System.err.println("end of main()");
}

I've also added the various life-cycle methods to the appender, similarly writing debug messages to standard error. The append() method does the same, and doesn't actually do any appending. Furthermore, I use the identity hashcode of the appender object as a unique-ish ID, and add that to each of the messages.

@SuppressWarnings("deprecation")
private LifecycleReportingAppender(String name, Filter filter, Layout<String> layout)
{
    super(name, filter, layout);
    System.err.println("LifecycleReportingAppender constructed; id = " + System.identityHashCode(this));
}


@Override
public void initialize()
{
    // note: this does not appear to be called
    System.err.println("initialize() called on " + System.identityHashCode(this));
    super.initialize();
}


@Override
public void start()
{
    System.err.println("start() called on " + System.identityHashCode(this));
    super.start();
}


@Override
public void stop()
{
    // this will not be called for Log4J version 2.7 or later
    System.err.println("stop() called on " + System.identityHashCode(this));
    super.stop();
}


@Override
public boolean stop(long timeout, TimeUnit timeUnit)
{
    System.err.println("stop(" + timeout + "," + timeUnit + ") called on " + System.identityHashCode(this));
    return super.stop(timeout, timeUnit);
}


@Override
public void append(LogEvent event)
{
    System.err.println("append() called on " + System.identityHashCode(this));
}

When you run this, this is what you'll see for output (actually, you'll see a lot of messages from the framework, because I've also enabled debug-level internal logging):

main started, getting logger
LifecycleReportingAppender constructed; id = 141289226
start() called on 141289226
append() called on 141289226
reconfiguring logging context
LifecycleReportingAppender constructed; id = 668210649
start() called on 668210649
stop(0,MILLISECONDS) called on 141289226
append() called on 668210649
end of main()
stop(2500,MILLISECONDS) called on 668210649

I want to wrap up this section by delving into stop(timeout,timeUnit).

Depending on the destination for your custom appender, you might benefit from writing a batch of messages, rather than individual messages. For example, if you're writing to an Amazon Kinesis stream, you have the choice of using the PutRecord API call with a single record, or PutRecords with up to 500. Both calls take about the same time to execute: the overhead inherent in a network request is a significant part of request time. So if you were writing an appender with Kinesis as a destination, you might decide to gather message into batches and write them asynchronously.

Even if you don't batch records for efficiency, you might still want to write them using a background thread, to avoid blocking the application's thread. However, once you introduce asynchronous writes and queuing, you have the problem that you'll lose messages if the appender shuts down as soon as it's told to. This is a particular problem with programs that don't take a long time to run: once the JVM exits, queued-but-unsent messages are gone.

If you're writing such an appender, you might (like I did) add in a JVM shutdown hook to give the appender time to send its queued messages. Sure, there are no guarantees that shutdown hooks will run; someone can always kill -9 your JVM. But in the normal case, they do run.

Log4J2 provides its own shutdown hook, controlled by the top-level configuration values shutdownHook (by default enabled) and shutdownTimeout (by default zero). The latter value is passed to your appender's stop() method.

Except when it isn't. As the previous output shows, reconfiguring the logging context will tell the appender that it has zero milliseconds in which to shut down.

And even when Log4J passes a value to the appender, that value is “a hint and not an absolute guarantee.” The appender can wait longer and it won't be interrupted. And if your stop() method takes less time, the logging framework won't delay shutting down just because you gave it a long shutdownTimeout.

So, bottom line, take as much time as you need to properly shut down your appender. If you want to give the user the feeling of control, you can look at the provided value. But don't shut down early if it's zero.

Headers and Footers

As I mentioned above, some layouts provide optional headers and footers; you retrieve them with the layout's getHeader() and getFooter() methods. These methods both return a byte[], but have absolutely no constraints on what that array might contain.

In practice, layouts that derive from AbstractStringLayout create that byte[] using the layout's charset property. The built-in appenders that support headers and footers take a rather cavalier attitude toward this: WriterAppender assumes that it will only be given a StringLayout, while ConsoleAppender and FileAppender both subclass AbstractOutputStreamAppender, which is perfectly happy to be given a byte[].

When writing an appender that requires a string-based layout, I think it's best to at least check to see if you've been given a StringLayout, and if yes to apply its character set conversion. Otherwise, either you should allow your users to specify a character set as part of the appender's configuration … or just punt and use UTF-8.

My approach is to retrieve the layout's character set in my appender's constructor, with a default of UTF-8:

// this is the default character set, if the layout doesn't tell us different
private Charset layoutCharset = StandardCharsets.UTF_8;


@SuppressWarnings("deprecation")
private MyAppender(MyAppenderConfig config)
{
    super(config.getName(), config.getFilter(), config.getLayout());
    this.config = config;

    if (config.getLayout() instanceof StringLayout)
    {
        layoutCharset = ((StringLayout)config.getLayout()).getCharset();
    }
}

The next question is where you should write the header and footer. In the built-in appenders, this is handled by a “manager” class (see below): the header is written when the manager is constructed, the footer when it is explicitly closed.

You could follow this same practice — perhaps adding a start() method to your manager so that you separate construction from operation. Or, if you're like me and don't see the point of managers, write the header in your appender's start() method, the footer in its stop() method.

@Override
public void start()
{
    byte[] header = getLayout().getHeader();
    if ((header != null) &amp;&amp; (header.length > 0))
    {
        System.out.println(new String(header, layoutCharset));
    }
    super.start();
}

@Override
public boolean stop(long timeout, TimeUnit timeUnit)
{
    byte[] footer = getLayout().getFooter();
    if ((footer != null) &amp;&amp; (footer.length > 0))
    {
        System.out.println(new String(footer, layoutCharset));
    }
    return super.stop(timeout, timeUnit);
}

Note the these methods also call their superclass implementations: while that's a generally good idea for overridden methods, here it's required to properly set flags managed by the AbstractLifeCycle class. Note also that in stop() I return the result of calling the super implementation. I should actually be AND-ing that with the success or failure of my implementation.

Managers

Here we get to a part of appender implementation that I don't understand — or at least don't agree with. The docs seem clear:

Most Appenders use Managers. A manager actually “owns” the resources, such as an OutputStream or socket. When a reconfiguration occurs a new Appender will be created. However, if nothing significant in the previous Manager has changed, the new Appender will simply reference it instead of creating a new one.

This makes a lot of sense. If your logging destination requires an expensive setup or teardown, you don't want to re-create it whenever the configuration changes (even if it doesn't change often). However, Log4J doesn't differentiate between reconfiguring and shutting down. As a result, the built-in appenders don't try to preserve their managers, they just shut them down from within the appender's stop() method.

One place that managers may be helpful is in unit testing. See below.

What do I do with that Filter object?

Log4J2 allows you to configure a Filter as a child of an Appender, so different appenders attached to the same logger can independently choose to write the event or not. For example, you might write debug-level events to a filesystem, but only info or above to a database.

As a consequence, the filter object (if it exists) will be passed to your appender via its configuration. However (assuming your appender inherits from AbstactAppender), you don't have to touch that object other than pass it to your superclass. The Log4J framework invokes the filter before calling append().

Implementing a Layout

A layout is a plugin that transforms a LogEvent into a format that can be usable by the destination. The Log4J2 library comes with a variety of layouts, supporting transforms into JSON, or XML, or even a line of comma-separated values. Probably the best-known and most-used is PatternLayout, which allows the user to translate different parts of the event into a string using pattern codes. For example, "%d{HH:mm:ss.SSS} %-5p - %m%n" outputs the timestamp when the event was created, followed by the event's level, and finishing with the actual message that the user logged (plus a newline).

There aren't a lot of reasons that you might write your own layout: the built-in layouts cover most common use-cases. But no treatment of Log4J2 would be complete without looking at layouts. So as an example I created RedactingLayout, which takes a list of regular expressions (regexes) and uses them to replace message text with the word "REDACTED". This is useful to “sanitize” logs, removing credit card and social security numbers. And it's already implemented in PatternLayout, but that layout only supports a single regex.

With other logging frameworks, I'd implement this layout as an extension of PatternLayout, but Log4J2 made that class final, so it can't be extended (Log4J2 wants you to implement a PatternConverter instead). Since this is just an example, I instead subclasssed AbstractStringLayout with a hardcoded output format.

Let's start with how the configuration for this layout looks:

<Appenders> 
    <MyAppender name="STDOUT"> 
        <RedactingLayout redactionPatterns="[Ww]orld,separate"/> 
    </MyAppender> 
</Appenders> 

Pretty straightforward: a comma-separated list of regexes. This one will replace the words "World", "world", and "separate". And note that, since this is an example, you can't use a comma in the redaction pattern.

OK, on to the code.

@Plugin(name = "RedactingLayout", category = Core.CATEGORY_NAME, elementType = Layout.ELEMENT_TYPE)
public class RedactingLayout
extends AbstractStringLayout
{
    @PluginFactory
    public static RedactingLayout factory(
        @PluginAttribute("redactionPatterns") String redactionPatterns)
    {
        return new RedactingLayout(redactionPatterns);
    }


    private List<Pattern> redactionPatterns = new ArrayList<>();


    private RedactingLayout(String redactionPatterns)
    {
        super(StandardCharsets.UTF_8);
        for (String pattern : redactionPatterns.split(","))
        {
            this.redactionPatterns.add(Pattern.compile(pattern));
        }
    }

    @Override
    public String toSerializable(LogEvent event)
    {
        String message = event.getMessage().getFormattedMessage();
        for (Pattern pattern : redactionPatterns)
        {
            Matcher matcher = pattern.matcher(message);
            message = matcher.replaceAll("REDACTED");
        }
        return message;
    }
}

As I said above, layouts are plugins and must be annotated as such. Like appenders, layouts can have builders, and many of the “built-in” layouts are implemented that way. However, to minimize code size for the example, I've used a simple factory method.

Perhaps the biggest difference between Log4J2 and other logging frameworks is that the others assume layouts will produce a String, but Log4J2 layouts can produce anything that implements java.io.Serializable. This gives a custom appender lots of flexibility: you could, for example, create an appender that writes POJOs over an ObjectOutputStream. However, it also means that your layout and appender have to agree on the format, and there's nothing that prevents a user from combining incompatible layouts and appenders.

For my example I'm extending AbstractStringLayout, which implements StringLayout, which in turn means that the toSerializable() method returns String.

AbstractStringLayout exposes methods that will convert the string value to byte arrays, but requires the subclass to specify a Charset object to control this conversion. For this iteration, I hardcode UTF-8 (I strongly believe in UTF-8 Everywhere), but in a real-world layout you should allow the configuration to specify the charset.

One feature of AbstractStringLayout that I don't use but most layouts should is the built-in StringBuilder object. One of the goals of Log4J2 is to minimize load on the garbage collector, and this object is one of the ways they do that: it's a pre-allocated thread-local StringBuilder that can be reused by the layout.

In this example, however, I don't use it because Matcher doesn't integrate closely with StringBuilder (amazingly, for a class that was introduced in JDK 1.5, it does have methods that use the long-out-of-favor StringBuffer). If I were writing a production layout I would put in a little more effort, re-implementing the functionality of Matcher.appendReplacement() and Matcher.appendTail().

Using Lookups

Lookups are one of the more useful features of Log4J2: they let you retrieve runtime information and use it in your configuration. This information ranges from the environment variables and system properties, to details about the Docker container the application is running in (assuming it's running in a container).

Lookups are referenced in the configuration using ${key}, where key is the name of the lookup. For example, you could configure a PatternLayout to pull the username out of the environment:

<PatternLayout pattern="%d{HH:mm:ss.SSS}  %-5p - %t - ${env:USER} - %m%n" /> 

Lookups prefixed with a single dollar-sign (${key}) are replaced when Log4J reads the configuration file. Prefixing with a double dollar-sign ($${key}) preserves the lookup until runtime, allowing you to substitute up-to-date values.

As a layout author, you gain access to lookups by letting Log4J inject a Configuration object into your layout.

@PluginFactory
public static RedactingLayout factory(
    @PluginConfiguration Configuration config,
    @PluginAttribute("redactionPatterns") String redactionPatterns)
{
    return new RedactingLayout(config, redactionPatterns);
}

But all you really care about from that configuration object is its StrSubstitutor:

private StrSubstitutor subs;
private List<Pattern> redactionPatterns = new ArrayList<>();


private RedactingLayout(Configuration config, String redactionPatterns)
{
    super(StandardCharsets.UTF_8);
    subs = config.getStrSubstitutor();
    for (String pattern : redactionPatterns.split(","))
    {
        this.redactionPatterns.add(Pattern.compile(pattern));
    }
}

Then, in your toSerializable() method (or when creating the header or footer), you use that StrSubstitutor to replace lookups in arbitrary strings. Here I've updated RedactingLayout to use a hardcoded substitution so that I can have a timestamp in my output.

@Override
public String toSerializable(LogEvent event)
{
    String raw_message = event.getMessage().getFormattedMessage();
    String message = subs.replace("${date:yyyy-MM-dd HH:mm:ss.SSS} - " + raw_message);
    for (Pattern pattern : redactionPatterns)
    {
        Matcher matcher = pattern.matcher(message);
        message = matcher.replaceAll("REDACTED");
    }
    return message;
}

Note that I also apply the substitution to the pre-redacted message. This leads to some interesting behavior: if you look at the main program, you'll see that I changed one of the log messages to include another lookup, which will be substituted by the layout. I don't know if this works with all built-in layouts; it does work with PatternLayout, but it's probably a better habit to either perform substitutions in the layout configuration, or store whatever you need in the context map.

Implementing a Lookup

While you probably won't write your own layout, you might find it useful to write custom lookups. For example, in the Log4J and Logback versions of my AWS logging library I implemented a layout that produces JSON with the ability to retrieve information such as the EC2 instance ID. For Log4J2, it was easier to rely on the built-in JsonLayout and implement lookups that would retrieve the same information.

For an example lookup, I retrieve the JVM process ID and hostname; both are available from the JVM's RuntimeMXBean. I find this information extremely useful in an environment where applications are scaled horizontally and log to a single destination. Here's how it looks with a PatternLayout:

<Appenders> 
    <Console name="STDOUT"> 
        <PatternLayout pattern="%d{HH:mm:ss.SSS}  %-5p - ${example:HOSTNAME} ${example:PID} %t - %m%n" /> 
    </Console> 
</Appenders> 

In this case, the single dollar-sign indicates that resolution happens during configuration; the process ID and hostname aren't going to change while the program is running. The lookup key has two parts: example identifies the plugin, while HOSTNAME and PID identify the lookups provided by that plugin.

Lookups are plugins, and like other plugins, their implementation class must be identified with the @Plugin annotation. The plugin type is "Lookup" (there's no convenient constant). The name attribute is the prefix used to reference the plugin's lookups.

@Plugin(category = "Lookup", name = "example")
public class ExampleLookup
implements StrLookup
{

There's no abstract superclass for lookups: you are responsible for implementing the methods in StrLookup. However, all of the work of resolving lookups is done by StrSubstitutor, so an abstract superclass wouldn't provide much benefit.

Unlike other plugins, lookups don't allow configuration via builder or factory method. In fact, they don't allow any configuration at all, and you must provide a no-arguments constructor.

In this example, since hostname and process ID won't change, I retrieve them in that constructor. If the VM name returned by RuntimeMxBean doesn't follow the OpenJDK format of pid@hostname, then these variables will be left as null. That's OK: StrSubstitutor will skip the lookup (and the user will see the original key, so can identify and fix invalid values).

private String processId;
private String hostname;

public ExampleLookup()
{
    RuntimeMXBean runtimeMx = ManagementFactory.getRuntimeMXBean();
    String vmName = runtimeMx.getName();
    int sepIdx = vmName.indexOf('@');

    if (sepIdx > 0)
    {
        processId = vmName.substring(0, sepIdx);
        hostname = vmName.substring(sepIdx + 1, vmName.length());
    }
}

The last part of a lookup is the lookup() method. There are two variants: the first takes the key alone, while the second takes both key and a LogEvent. The latter is only called from within a Layout, and is permitted to retrieve information from the event. Since I don't need to do that, my version delegates the key-only variant of the method.

@Override
public String lookup(String key)
{
    if ("HOSTNAME".equalsIgnoreCase(key)) return hostname;
    if ("PID".equalsIgnoreCase(key)) return processId;
    return null;
}

@Override
public String lookup(LogEvent event, String key)
{
    return lookup(key);
}

As I noted above: if lookup() returns null then the original reference will remain in the output. This is useful to highlight a case where the key was misspelled, or where the lookup could not retrieve a value.

Testing Your Appender

The Log4J2 architecture, with its plugins, builders, and annotation-driven operation, is not very friendly toward testing. Sure, you can do a “unit” test, where you construct an instance of your appender (using the builder) and then invoke its public methods. But I don't think that really tells you much. To properly test an appender, you need to let the framework create and invoke it.

When I developed my library for Log4J 1.x, I adopted the practice of creating “testable” appenders: a subclass with hooks that would expose the internal appender state and allow me to inject mock objects, while leaving most of the appender's logic untouched. This worked well because Log4J 1.x (and Logback) lets you pick an appender implementation by referencing its classname in the configuration file. If I needed slightly different behavior, I could use a different subclass.

With Log4J2, the tight coupling between configuration, builder, and appender makes such testable classes a challenge. Simply subclassing the appender isn't sufficient: you must also subclass the builder. And change your configuration file to look for your testable classes. For the most part this works, but leaves several gaps, one of which is that you don't know that your non-testable appender will actually be found by the framework; for this you need integration tests.

An alternative approach, and one used by the “built-in” appenders, is to use a manager object, and mock it for testing. In this approach, the appender itself becomes very thin: all I/O is delegated to the manager. To create the manager, the appender invokes a factory method that's referenced as a static variable, and to mock the manager the test assigns a different factory method as part of a @Before action.

For my example, I'm taking a halfway approach: rather than the appender writing all output to System.out, it takes a java.io.PrintStream as a constructor parameter. In normal usage, the builder injects System.out. For testing, the testable subclass passes a wrapped ByteArrayOutputStream, and makes that stream available for later examination.

The first changes, therefore, happen to MyAppender and its builder:

@Plugin(name = "MyAppender", category = Core.CATEGORY_NAME, elementType = Appender.ELEMENT_TYPE)
public class MyAppender extends AbstractAppender
{
    // MyAppenderConfig is now "protected" so that it's visible to TestableAppender
    // newBuilder() hasn't changed (it won't be called in testing)

    public static class MyAppenderBuilder
    implements org.apache.logging.log4j.core.util.Builder<MyAppender>, MyAppenderConfig
    {
        // none of the attributes have changed

        @Override
        public MyAppender build()
        {
            return new MyAppender(this, System.out);
        }
    }

//----------------------------------------------------------------------------
//  Appender implementation
//----------------------------------------------------------------------------

    private MyAppenderConfig config;

    // this is the destination for logging; it's passed in by the builder
    private PrintStream out;

    // this is the default character set, if the layout doesn't tell us different
    private Charset layoutCharset = StandardCharsets.UTF_8;

    @SuppressWarnings("deprecation")
    protected MyAppender(MyAppenderConfig config, PrintStream out)
    {
        super(config.getName(), config.getFilter(), config.getLayout());
        this.config = config;
        this.out = out;

        if (config.getLayout() instanceof StringLayout)
        {
            layoutCharset = ((StringLayout)config.getLayout()).getCharset();
        }
    }

    @Override
    public void append(LogEvent event)
    {
        for (int ii = 0 ; ii < config.getRepeats() ; ii++)
        {
            out.println(getLayout().toSerializable(event));
        }
    }

    // start() and stop() similarly use "out" when writing the header and footer
}

The next step to create TestableAppender. Note that, while it defines a nested builder class, that builder can inherit most functionality from MyAppender.Builder: Log4J is smart enough to follow the inheritance tree to identify configuration variables. The one thing that it can't inherit is the build() method, because it's passing in the output stream.

The TestableAppender constructor wraps that stream in a PrintStream in order to invoke the superclass constructor, then saves it for use by the getOutput() method.

@Plugin(name = "TestableAppender", category = Core.CATEGORY_NAME, elementType = Appender.ELEMENT_TYPE)
public class TestableAppender extends MyAppender
{
    @PluginBuilderFactory
    public static TestableAppenderBuilder newBuilder() {
        return new TestableAppenderBuilder();
    }


    public static class TestableAppenderBuilder
    extends MyAppender.MyAppenderBuilder
    {
        @Override
        public TestableAppender build()
        {
            return new TestableAppender(this, new ByteArrayOutputStream());
        }
    }

    private ByteArrayOutputStream bos;

    private TestableAppender(MyAppenderConfig config, ByteArrayOutputStream bos)
    {
        super(config, new PrintStream(bos, true));
        this.bos = bos;
    }

    public String getOutput()
    {
        byte[] bytes = bos.toByteArray();
        return new String(bytes);
    }
}

I stored this class in src/main/test, because I don't want it to be bundled with the actual appender. I also changed the package to com.kdgregory.sandbox.log4j2.helpers, so I'll need to update the configuration file to search there. Configuration for tests is actually a big deal, so let's look at the entire file:

<Configuration status="warn" packages="com.kdgregory.sandbox.log4j2.helpers"> 
    <Appenders> 
        <Console name="STDOUT"> 
            <PatternLayout pattern="%d{HH:mm:ss.SSS}  %-5p - %m%n" /> 
        </Console> 
        <TestableAppender name="TEST"> 
            <PatternLayout pattern="%p - %m" /> 
            <repeats>2</repeats> 
        </TestableAppender> 
    </Appenders> 
    <Loggers> 
        <Root level="debug"> 
            <AppenderRef ref="STDOUT" /> 
        </Root> 
        <Logger name="TEST" level="debug" additivity="false"> 
            <AppenderRef ref="TEST" /> 
        </Logger> 
    </Loggers> 
</Configuration> 

You'll note that I define two appenders: a “normal” console appender and my test appender. This is more relevant to integration tests than unit tests, but I found it really useful if the tests logged their own operation. However, I don't want those operational logs to be mixed in with the output of the appender under test, so I configure an explicit logger for that appender. Note that I have to set additivity to false so that the test messages don't also get written to the console.

OK, what does a test look like?

@Test
public void testBasicOperation() throws Exception
{
    initialize("testBasicOperation");

    logger.debug("line 1");
    logger.info("line 2");

    String[] output = appender.getOutput().split("\n");
    assertEquals(Arrays.asList(
                    "DEBUG - line 1",
                    "DEBUG - line 1",
                    "INFO - line 2",
                    "INFO - line 2"),
                 Arrays.asList(output));
}

That seems simple enough: write two log messages and verify that each has been repeated the expected number of time. That initialize() function, however, seems like it does something interesting.

private Logger logger;
private TestableAppender appender;

protected void initialize(String testName)
throws Exception
{
    URI config = ClassLoader.getSystemResource(testName + ".xml").toURI();
    assertNotNull("was able to retrieve config", config);

    LoggerContext context = LoggerContext.getContext();
    context.setConfigLocation(config);

    logger = context.getLogger("TEST");

    appender = (TestableAppender)logger.getAppenders().get("TEST");
    assertNotNull("was able to retrieve appender", appender);
}

A test “suite” does not mean a single test. And one configuration file isn't enough for all tests. So the role of the initialize() function is to reconfigure Log4J using a named file. I store each of the test configurations in src/main/resources, named after the test. This method finds the named configuration (with an early failure if it can't), uses it to re-initialize Log4J, then extracts the test logger and its appender.

If you look at the example project, you'll see that it actually contains several tests: the basic operation test shown here, a test that verifies default configuration (so no repeats), and one that uses a header and footer. For a real-world appender, you may have dozens of tests, exploring how different configuration options interact.

Internal Logging

Log4J2 provides several ways of reporting information from within an appender. There's a static getStatusLogger() method on AbstractLifeCycle, which is the superclass of AbstractAppender. The Appender interface exposes the getErrorHandler() method, but as its name implies this is only intended to report errors. And finally, there's StatusLogger, which is a singleton object that's defined by the Log4J API (not the implementation!).

Digging into the code, AbstractLifeCycle.getStatusLogger() simply returns the singleton object, while DefaultErrorHandler also delegates to the singleton but adds some (not at all thread-safe) code to limit the number of times an exception is reported. The built-in appenders seem mixed in their approach to logging: most rely on the logger defined by AbstractLifeCycle (and most access it directly, without using getStatusLogger()), while some use a mix of status logger and error handler.

I find it difficult to recommend ErrorHandler, although if you expect repeated errors during runtime it will avoid overwhelming your users with spurious error messages.

Troubleshooting

Troubleshooting appender problems can be a challenge, because the reported error messages may not indicate the actual error. This section is a listing of “errors I have known” and what their actual causes were.

ERROR Unable to invoke factory method ... No factory method found

This message might indeed mean that your factory method doesn't exist — or that it doesn't have the right signature. I ran into it at one point because I was returning the wrong — but compatible — type from the builder factory. That one confounded me because the unit tests passed because they subclassed the builder, but the integration tests didn't. I ended up single-stepping through the PluginBuilder class to find the problem.

The other cause of this message is that the builder threw an exception. Look for a prior reported error (such as the one below), or put a breakpoint in the build() method.

ERROR Unable to inject fields into builder class

This could be reported because the configuration specifies a value that's incompatible with the field type. However, it's also reported if there's an error in the appender's constructor or initialization code (ie, long after fields are injected).

Look carefully at the stack trace, to see if your appender class is near the throw point, or if the trace consists entirely of internal Log4J framework methods. If the former, fix your error. If the latter, turn on debug output in the configuration, and look for the “Building Plugin” messages. Log4J will report the builder's configuration just before its build() method is called; here's a real-world example, from one of my “minimal configuration” tests:

2020-01-28 07:55:29,909 main DEBUG Building Plugin[name=appender, class=com.kdgregory.log4j2.testhelpers.TestableCloudWatchAppender].
2020-01-28 07:55:29,919 main DEBUG TestableCloudWatchAppender$TestableCloudWatchAppenderBuilder(useDefaultThreadFactory="null", name="CLOUDWATCH", logGroup="null", logStream="null", retentionPeriod="null", rotationMode="null", rotationInterval="null", sequence="null", dedicatedWriter="null", PatternLayout(%m), Filter=null, batchDelay="null", discardThreshold="null", discardAction="null", clientFactory="null", clientRegion="null", clientEndpoint="null", synchronous="null", useShutdownHook="null")

A Parting Thought

After implementing a real-world Log4J 2.x appender, and digging into the Log4J source code to figure out problems, I'm reminded of Sir Anthony Hoare's adage that a system can either be so simple that it obviously has no bugs, or so complex that it has no obvious bugs. In my opinion, Log4J2 is firmly in the second group.

Beyond complexity, which can be unavoidable, I think the Log4J2 developers try too hard to be clever. Sometimes this is relatively harmless, such as using the simple classname in the configuration file (hopefully you won't try to use two appenders with the same name). But in other cases it's downright dangerous, such as directly injecting values into builder fields. Not only does this go against two decades of JavaBean practice, it will fail if you run your application in a sandbox that doesn't allow setAccessible().

I realize, however, that Log4J 2.x isn't going away, and there are a lot of people that will use it. Either because it's newer than the alternatives, or because they think they need an asynchronous appender that can pass 18,000,000 messages per second (even though there's no destination I know of that can accept that rate). Which is why I added Log4J support to my library.

But for my own application development work, I'll be sticking with Logback or even Log4J 1.x: it may be old, but that means that it's been thoroughly tested.

For More Information

The example project implements a simple appender, layout, and lookup. This project is structured such that each commit corresponds to one of the sections of this article.

The Log4J2 manual just touches the surface of implementing new features, but it's helpful as a reference.

Log4J2 divides up its JavaDoc into several sections. I found the core docs useful, the others not so much.

The source code was far more useful: I could look to see how the in-project appenders did things. It was also valuable to load into my IDE so that I could step through examples. However, it's on an Apache managed server with a very limited UI; if you're used to GitHub you'll hate it. Instead, clone from https://git-wip-us.apache.org/repos/asf/logging-log4j2.git and use your own tools to examine.

I hesitate to include my appenders library, because it was primarily an exercise in making Log4J2 work with the structure that I'd already created for Log4J1 and Logback. But you might find it useful anyway (especially in how I dealt with the real-world concerns of startup and shutdown).

Copyright © Keith D Gregory, all rights reserved

This site does not intentionally use tracking cookies. Any cookies have been added by my hosting provider (InMotion Hosting), and I have no ability to remove them. I do, however, have access to the site's access logs with source IP addresses.