Today I want to show you a way how to implement lazy logging with SLF4J 1.x. Newer log libraries like Log4j2 support lazy logging with lambdas like this:

LOGGER.info("Expensive operation: {}", () -> expensiveOperation());

SLF4J 1.x doesn’t support this, trying this gives you a compiler error.

But we can leverage a behaviour of the logging frameworks: they call .toString() on the parameter objects. So let’s define a method like this:

static Object lazy(Callable<?> callable) {
    return new Object() {
        @Override
        public String toString() {
            try {
                Object result = callable.call();
                if (result == null) {
                    return "null";
                }

                return result.toString();
            } catch (Exception e) {
                throw new RuntimeException(e);
            }
        }
    };
}

This method takes a Callable, which is a SAM interface and can be used in a lambda expression. It then returns a new anonymous class with the toString() method overridden. This toString() calls the given Callable and delegates the toString() method to the returned object (and adds some null checks and exception handling).

The lazy method can then be used like this:

LOGGER.info("Expensive operation: {}", lazy(() -> expensiveOperation()));

It looks like the Log4j2 version, only the lazy method call is added.

Let’s test in a real program:

public static void main(String[] args) throws InterruptedException {
    LOGGER.info("Started");
    LOGGER.info("Expensive operation: {}", lazy(() -> expensiveOperation()));
    LOGGER.info("Stopped");
}

where expensiveOperation() is defined like this:

private static String expensiveOperation() throws InterruptedException {
    Thread.sleep(2000);
    return "foo";
}

When run, it prints

2021-12-23T17:33:57.719+01:00 [main] INFO  de.mkammerer.skeleton.Main - Started
2021-12-23T17:33:57.722+01:00 [main] INFO  de.mkammerer.skeleton.Main - Expensive operation: foo
2021-12-23T17:33:59.723+01:00 [main] INFO  de.mkammerer.skeleton.Main - Stopped

The “Stopped” message appears 2 seconds after the “Started” message, as the expensive operation is called and the thread slept for 2 seconds. Let’s change the logging level from the expensiveOperation() from INFO to TRACE. The logging backend is configured to only log DEBUG and higher, hence the log message is suppressed:

LOGGER.trace("Expensive operation: {}", lazy(() -> expensiveOperation()));

And run it again:

2021-12-23T17:35:56.678+01:00 [main] INFO  de.mkammerer.skeleton.Main - Started
2021-12-23T17:35:56.681+01:00 [main] INFO  de.mkammerer.skeleton.Main - Stopped

Now the “Stopped” message appears immediately after the “Started” message, which proves that expensiveMethod() has not been called and that the lazy method works as expected.

Back to posts