Identifying the set of events to be logged

Recently one of the talented engineers I work with submitted a pull request for review where he wanted to temporarily capture more diagnostic information in the service he was working on. The information he was trying to capture would normally be classified as debug information but he had coded it to log at the info level so that the logging configuration would still match our policy of logging informational messages. His intention was to change them all to debug messages at some later time (which, as we all know, rarely happens). Obviously, this kind of defeats the point of having a policy to log at the info level.

The interesting thing is that Log4j 2 has built in support for these kinds of use cases so there really is no need to deviate from from standard practices. In this article I will discuss various ways the result that is desired can be achieved.

Use Appropriate Logger Declarations

The first approach is perhaps the most obvious one - just write the code to log the events at the debug level and then filter based on the classes. So assuming all the classes were in a package named com.acme.someservice we would write our log events using

logger.debug("Some log message");

and then cause them to be logged by adding

<Logger name="com.acme.someservice" level="debug"/>

to the logging configuration. The downside to this approach is that it will cause all debug messages to appear from the specified package, not just the new ones being added.

Custom Logging Levels

Log4j supports defining and using custom logging levels. This would allow associating the new messages with their own custom level so they could be logged without affecting other debug level messages. This would be accomplished by first defining a new Level either in the code or the configuration.

public static final Level DIAG = Level.forName("DIAG", 450);

and then using this level when logging events

logger.log(DIAG, "Some log message");

or, using the Log4j API's fluent logger syntax

logger.atLevel(DIAG).log("Some log message");

As another alternative, you can use the code generation tool to create a custom Logger class that would allow the slightly more convenient syntax

logger.diag("Some log message");

to be used. In all of these cases the configuration would be the same. The logging configuration would need to be changed to use the "DIAG" level wherever it is needed. For example, one could do

<Logger name="com.acme.someservice" level="diag"/>

which would yield the same results as the previous example using debug, except in this case only the new diagnostic messages would be logged and not the debug messages. Setting the level in the configuration to the standard "info" level on the logger would result in the new diagnostic messages not being logged. As another alternative, the root logger could be modified

<Root level="diag">
  <AppenderRef ref="file"/>
</Root>

which will cause anything using the custom level to be logged.

Markers

Markers are a very under-utilized feature of Log4j 2. Invented by Ceki Gülcü, markers can be described as being orthogonal to log levels. Levels typically classify the log events by their importance or severity while markers provide a way to categorize them. In our example, we are really trying to provide a way to delineate a set of debug log events in a way that we can cause them to be logged without enabling other log events. This is an almost perfect use case for markers.

To implement this we first need to create a Marker.

public final Marker DIAG = MarkerManager.getMarker("DIAG");

Next the Marker is used in the logging statement as

logger.debug(DIAG, "Some log message");

or

logger.atDebug.withMarker(DIAG).log("Some log message");

Finally, in the Log4j configuration a filter needs to be added to cause any log event with this Marker to be logged.

<Configuration status="error">
  <MarkerFilter marker="DIAG" onMatch="ACCEPT" onMisMatch="NEUTRAL"/>
  <Appenders>
    <Console name="console">
      <PatternLayout pattern="%d %-5level - %msg%n"/>
    </Console>
  </Appenders>
  <Loggers>
    <Root level="INFO">
      <AppenderRef ref="console"/>
    </Root>
  </Loggers>
</Configuration>  

This configuration uses a global filter to evaluate the log events. If the event contains a Marker named "DIAG" then the event will be logged regardless of its logging level. So even if the events are logged at debug, as is shown in the examples above, they will still appear in the output.

Log4j allows Filters to be used in different locations in the configuration. As was stated above, global filters evaluate every log event. In addition, filters can be configured on Loggers, AppenderRefs and Appenders. So another possible configuration would be

<Configuration status="error">
 
  <Appenders>
    <Console name="console">
      <PatternLayout pattern="%d %-5level - %msg%n"/>
    </Console>
  </Appenders>
  <Loggers>
    <Logger name="com.acme.someservice" level="debug">
      <MarkerFilter marker="DIAG" onMatch="ACCEPT" onMisMatch="NEUTRAL"/>
      <AppenderRef ref="console" level="info"/>
    </Logger>
    <Root level="INFO">
      <AppenderRef ref="console"/>
    </Root>
  </Loggers>
</Configuration> 

In this case all log events coming from the com.acme.someservice package will be handled by the Logger with the same name and will continue to be evaluated if their logging level is debug or more specific. The Marker filter will then accept any events with the DIAG marker causing further evaluation of logging levels to be ignored for those events. Events without the marker will then be rejected if their level is debug since only info events and above will be processed. This has the benefit of limiting the diagnostic events to the single package but it comes at a cost. Log4j supports logging the class name, method name and line number of the logging event. The only way to capture that information in Java is to walk the stack at run time to find the caller of the logging method. This is fairly slow. In many cases Log4j normally will only evaluate the callers information if it is used somewhere in the configuration, such as in the PatternLayout. In the case above it is not referenced so there will be almost no extra overhead. But in the case where location information is referenced Log4j will detect this and try to obtain the caller information as soon as it can, which will happen before the Marker filter is evaluated. This means that all log events at debug level will have their location information obtained including the ones rejected by the AppenderRef's logging level. To avoid this overhead when using this pattern specify the configuration as

<Configuration status="error"> 
  <Appenders>
    <Console name="console">
      <PatternLayout pattern="%d %-5level %C{1.}.%M:%L %msg%n"/>
    </Console>
  </Appenders>
  <Loggers>
    <Logger name="com.acme.someservice" level="debug" includeLocation="false">
      <MarkerFilter marker="DIAG" onMatch="ACCEPT" onMisMatch="NEUTRAL"/>
      <AppenderRef ref="console" level="info"/>
    </Logger>
    <Root level="INFO">
      <AppenderRef ref="console"/>
    </Root>
  </Loggers>
</Configuration>

Adding the includeLocation attribute with a value of false will cause Log4j to not try to optimize the caller location that passes through the com.acme.someservice Logger. However, caller information will still be included in events. It just won't be calculated until the PatternLayout requires it.

Summary

We have looked at 3 options for causing "special" log events to be included. In the vast majority of the cases just using the appropriate Logger configuration with the appropriate logger names will do the trick. Generally, when that option doesn't work using a Marker will be the best option as it best fits what is trying to be accomplished. If for some reason Markers don't meet the requirements a custom logging level might just do the trick.