As is well known, Log4j 1 combined its API with its implementation. It provided no help to users to determine which classes and methods they could safely rely on and which classes were considered private to the implementation. This led to a lot of issues when trying to fix bugs or provide enhancements. Ceki Gülcü learned from these mistakes when he created SLF4J and Logback by making Logback use the SLF4J API.
When developing Apache Log4j 2 I considered using SLF4J as the API. However, my main focus at the time was to develop an audit logging system for my employer so I had a need to log objects, while SLF4J only supports logging formatted Strings. While you can pass objects to SLF4J they are intended to be treated as data to be inserted into the format String, so using them for anything else is subject to what may happen to the log event while it is processed. For example, when an asynchronous appender is encountered the objects need to be converted to Strings as the objects cannot be safely accessed from another thread.
As a result of these factors it was decided that Log4j 2 should have an API that is separate from the implementation. The rest of this document discusses features of the Log4j 2 API that users can benefit from that aren't found in other logging APIs.
It is all about Messages
With all that in mind, the Log4j 2 API was developed to be a standalone logging API, similar to SLF4J, but with the ability to log Message objects instead of just Strings. Yes, logging Strings is by far the way most logging is done and the Log4j 2 API supports that. When you call one of the logging methods that accepts a String, the Log4j 2 API will use the MessageFactory that is associated with the Logger instance and convert the String to a Message appropriate for that MessageFactory. Out of the box Log4j 2 supports 3 different types of formatting types:
Parameterized - This is the mechanism that was introduced by SLF4J where '{}' is used to indicate where placeholders occur which are then replaced by the String values of the parameters passed on the logging call. logger.info("Name: {}, Locale: {}", name, locale);
StringFormatted - This format expects the format Strings to follow the format used by java.util.Formatter and printf calls. logger.info("Name: %s, Locale: %s", name, locale);
MessageFormatted - This format expects the format String to adhere to java.text.MessageFormat. logger.info("Name: {1}, Locale: {2)", name, locale);
Users can specify which of these formats they want to use by coding:
private static Logger LOGGER = LogManager.getLogger(StringFormatterMessageFactory.INSTANCE);Log4j 2 also provides FormattedMessageFactory which will inspect the contents of the format String and dynamically determine which Message formatter to use. Since common practice is to define a Logger per class it is not expected that it would be unusual to use this factory since it would be an unusual coding practice to have multiple format styles in the same class.
In my audit logging solution I wanted to use the RFC 5424 specification which allowed structured data to be written to syslog so Log4j 2 supports a StructuredDataMessage that allows data elements to be captured in a format that the RFC5424Layout can fully take advantage of. The StructuredDataMessage extends MapMessage, which means that it can also be handled by Layouts that perform special behavior on log events that pass a Map of data elements or taken advantage of Messages to format their own output.
The Log4j 2 API also supports other kinds of Messages. As an exercise to show the power of using Messages I developed ThreadDumpMessage. Creating a ThreadDumpMessage is cheap, but when a logging method is called with a ThreadDumpMessage and the ThreadDumpMessage's getFormattedMessage method is called it will take a thread dump of all running threads. This allows a user to put logging calls to take thread dumps during certain error conditions and only go through the overhead of taking the thread dump when whatever filter conditions are configured pass.
Of course, users can also create custom Messages. The simplest implementations only need to implement the four methods defined in the Message interface.
Building a Log Event
A typical use of the logging API is to do something like:
logger.error("Unable to create {} due to an unexpected error", thing, exception);The practice of having the Throwable be the last parameter started with Log4j 1 and was carried into SLF4J, so Log4j 2 kept the convention to make porting existing code easy. From time to time users have asked about the ambiguity of including the exception as the last argument. With the 2.13.0 release the API has been enhanced to include a set of "event builder" methods. Using this set of methods resolves the ambiguity as to whether the Throwable is separate or is a parameter. These methods allow Markers, the location, and Throwable to be provided separately from the format String and parameters. An example that logs all of these would look like:
logger.atWarn().withLocation().withThrowable(exception).log("Unable to process request due to {}", code);In the example above if warn logging is not enabled then a no-op event builder is returned. All the subsequent method calls do nothing. Note that the format string and parameters are still provided together in the log call, which will allow IDEs like IntelliJ to continue to warn when a parameter is missing or does not have a placeholder in the format String.
Location Performance
In some languages the current class, file name, and line number are available at compile time. Unfortunately, this is not true of Java which means these values have to be dynamically determined at run time. A benefit of using the event builder methods is that the withLocation method is able to calculate the caller's location by directly looking 2 stack frames up, which is much faster than the normal method have having to walk the stack trace to locate the caller.
The table below shows some of the results from the FileAppenderBenchmark and FileAppenderWithLocationBenchmark classes in the log4j-perf project when configured to use 4 threads. The Log4j2 File results show the performance of the "normal" logging calls when location information is and is not included and demonstrate that lazily including the location information is about 8 times slower than not including location information. The Log Builder results show that while using the withLocation method of LogBuilder is about 3 times faster than lazily calculating the location information it is still about 2.5 times slower than not including location information.
Flow Tracing
Flow tracing provides special methods to be used when a method is entered or exited. The SLF4J API provides these in the SLF4J extensions jar and the developer must use a different Logger implementation than normal. Log4j provides flow tracing API methods as part of the Logger API.
Markers
Flow tracing makes use of Markers when logging an event. When thinking about Markers it is useful to consider how Loggers are used. Typically, developers create a Logger in every class that will perform logging and name the logger with the class's name. Then when configuring what to log and at what level package names are used to filter the log events. One can think about this as "horizontal filtering". Markers, on the other hand, can be applied to any log event in any class, so including a MarkerFilter in the configuration can allow log events to be filtered across classes and packages, thus providing "vertical filtering".
As an example consider the following method:
public boolean checkStatus(String user) {
logger.traceEntry("User: {}", user);
boolean result = .....
return logger.traceExit(result);
}and this configuration:
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="ERROR" monitorInterval="180">
<MarkerFilter marker="FLOW" onMatch="ACCEPT" onMismatch="NEUTRAL"/>
<Appenders>
<Console name="Console" target="SYSTEM_OUT">
<PatternLayout>
<MarkerPatternSelector defaultPattern="%d [%t] %-5p - %m%n">
<PatternMatch key="FLOW" pattern="%d [%t] %-5p -------- %C{1.}.%M:%L %m --------%n"/>
</MarkerPatternSelector>
</PatternLayout>
</Console>
</Appenders>
<Loggers>
<Root level="debug">
<AppenderRef ref="Console"/>
</Root>
</Loggers>
</Configuration>
The configuration causes the log event to pass through the MarkerFilter first. Because traceEntry and traceExit implicitly include a FLOW marker the events will immediately be accepted and will be handled by the Root Logger even though its log level is set to debug. The entry and exit messages will then be passed to the Console appender and they will use the pattern that is associated with the FLOW Marker. Notice that in this case the logger name was only used to determine how to route the log events to the correct Appender.
It should be noted that the configuration and behavior described above are not part of the Log4J API. Other implementations will be passed the Markers but may choose to ignore them or handle them differently.
Lambda Expressions
The Log4j 2 API has supported Lambda expressions since release 2.4 in 2015. When logging an event such as
logger.debug("User Profile: {}", user.getProfile().toString());the call to the getProfile and toString methods will be called regardless of whether debug logging is enabled or not. In some cases these methods can incur quite a bit of overhead. Prior to the support for Lambda expressions the only way to avoid this would be to wrap this in a call to logger.isDebugEnabled(). With Lambdas this becomes:
logger.debug("User Profile: {}", () -> user.getProfile().toString());In this case the lambda function will not be called until after it is determined that debug logging is enabled.
Using the Log4j API as a general purpose Logging API
Like SLF4J, the Log4j 2 API can be used to route logging events to any logging framework that implements its binding and a number of adapters and bridges exist to allow logging to and from various APIs to all be funneled to a single implementation.
Due to this flexibility applications and libraries can feel comfortable in knowing that they can take advantage of the features of the Log4j 2 API listed above without being tied to a particular logging implementation. While I happen to believe that Log4j 2 also provides the best Java logging implementation it has always been recognized that there are times when that choice is out of the developers control and so compatibility with the chosen logging framework is required.