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) && (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) && (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