Writing clean logging code using Java 8 lambdas

In this article, I will show you how to clean up your logging code using Apache Log4j 2.4 and Java 8 lambdas.

Log4j is a great logging framework, and the upcoming version — 2.4 — includes support for Java 8 lambdas. Lambda expressions are new to Java 8 and provide a simple and compact way to represent a method interface using an expression.

Let’s get started; I’ve seen a lot of logging code that looks like this:

final String that = "that";

// Creates logger
final Logger logger = LogManager.getLogger();

// Builds a String
logger.debug("This " + this + " and " + that + "with " + compute());

Why do I use the final keyword? See my previous post The final KISS in Java.

The string building is pretty nasty, so for the first clean, we’ll irefactor the log message construction into something more palatable using Log4j parameter markers:

logger.debug("This {} and {} with {} ", this, that, compute());

The "{}" is called a parameter marker and defines the spot where an argument will replace these characters. In this example, we have three "{}" parameter markers and three parameters (this, that, and compute()) in addition to the message template.

This is all neat and prettier than the previous incarnation but there is still a problem. The call to compute() may be expensive. Ideally, we want logging calls to be as inexpensive as possible when logging at that call site’s level is disable.

In plain logging, you must guard the logging call like this:

// Guards against calling compute
if (logger.isDebugEnabled()) {
  logger.debug("This {} and {} with {} ", this, that, compute());
}

So that more code (three lines vs. one) and one golden opportunity to shoot yourself in the foot? Can you see how? Yes, by mismatching the “is” method to the log method, in this case isDebugEnabled() must match debug() to get the desired behavior.

This is the kind of implosion I’ve seen:

// No logging takes place here!
if (logger.isDebugEnabled()) {
  logger.trace("This {} and {} with {} ", this, that, compute());
}

Mission invisible: You have debug logging enabled for your logger but you get no logging output because the logging call is at the TRACE level.

With Java 8 and Log4j 2.4, we can go back to writing a one-liner:

// Uses Java 8 lambdas to build arguments on demand
logger.debug("I am logging that {} happened.", () -> compute());

The key expression is worth repeating:

() -> compute()

In simple terms, this tells Java: “Build me an object that refers to the compute() method and pass that as a method argument.” Log4j will ask this magic object to call the compute() method only when it decides that the log level is enabled for the logger and it is time to build the full log message from the message template.

This is so powerful! You can now express in one line a potentially expensive logging call and keep it succinct.

The only ugly part here is that when you use this technique, you must specific all arguments with lambdas:

logger.debug("This {} and {} with {} ", 
  () -> this, () -> that, () -> compute());

Not great, granted, but hopefully better than before.

Under the hood

A lambda expression is a method that does not have a name. This is not like any other kind of method and it’s new to Java 8. You use this to pass behavior around your system, as if it were a piece of data. The idea of behavior as data is the take away here. Very powerful concept folks!

As you saw above, a lambda expression (with 0 arguments) looks like this:

() -> compute()

More generally, the pattern is:

(x, y) -> x + y

A lambda expression can take more than one argument, in this case two. This example creates a function that adds two numbers together.

If we wanted to assign this function, we would use a BinaryOperator:

BinaryOperator<Integer> adder = (x, y) -> x + y;

The compiler infers types for us in this example, which we could also write to explicitely declare its types:

BinaryOperator<Integer> adder = (Integer x, Integer y) -> x + y;

The last item in this brief walkthrough of note is the functional interface, which is an interface with a single method used as the type of a lambda expression. In the case of Log4j, this interface is:

package org.apache.logging.log4j.util;

public interface Supplier<T> {

    /**
     * Gets a value.
     *
     * @return a value
     */
    T get();
}

The only reason this class exists in Log4j 2.4 is to still be able to run with Java 7 as a requirement instead of Java 8. If you are using Java 8, you can use Java 8’s stock java.util.function.Supplier interface.

Log4j defines some methods with Supplier arguments instead of used Object or a generic type. For example, here is a fragment from the org.apache.logging.log4j.Logger interface:

/**
  * Logs a message with parameters which are only to be constructed if the logging level is the {@link Level#DEBUG
  * DEBUG} level.
  *
  * @param message the message to log; the format depends on the message factory.
  * @param paramSuppliers An array of functions, which when called, produce the desired log message parameters.
  * @since 2.4
  */
void debug(String message, Supplier<?>... paramSuppliers);

This article showed you how to combine Log4j with Java 8 lambdas and also serves a gentle introduction to the Log4j API and lambda basics.

Happy Coding,
Gary Gregory