Test logging - with your own JUnit extension

Test logging

Logging is important. In some cases, it is even so important that you may want to test whether certain events are logged correctly by the application. There are different approaches for this. For example, you could replace the logger of a class with a mock, which is used to verify whether the desired log methods have been called. However, this changes the logging behavior of the tested class and the log messages generated during the test are "swallowed", i.e. they do not end up in the usual output medium (console, file, etc.). In addition, replacing a logger with a mock is often not possible or only possible with unsightly hacks, as loggers are often declared static and final.

We therefore choose a different approach. We simply add an appender to the root logger, which records all logged events. This can be used later to check whether the desired log events are present.

The JUnit extension

But first we want to create the basis, namely the JUnit extension. JUnit 5 provides us with a series of callback interfaces for this purpose:

• BeforeAllCallback
• BeforeEachCallback
• BeforeTestExecutionCallback
• AfterTestExecutionCallback
• AfterEachCallback
• AfterAllCallback
• TestInstancePreDestroyCallback

The experienced unit tester will of course immediately recognize the reference to the life cycle of a JUnit test. All we have to do is implement one or more of these interfaces in a class - and we have our JUnit 5 extension!

We use BeforeTestExecutionCallback and AfterTestExecutionCallback for our logging extension:

public class AssertLoggedExtension implements BeforeTestExecutionCallback, AfterTestExecutionCallback {
  
    @Override
    public void beforeTestExecution(ExtensionContext context) {
        // ...
    }

    @Override
    public void afterTestExecution(ExtensionContext context) {
        // ...
    }
}

As the name suggests, the method of the first interface, "beforeTestExecution(...)" is called before the test method is executed. Here we add our appender (for this we use the self-implemented class ListAppender, which stores all received events in an ArrayList):

    private final ListAppender listAppender = new ListAppender();

    @Override
    public void beforeTestExecution(ExtensionContext context) {
        Logger rootLogger = (Logger) LogManager.getRootLogger();
        rootLogger.addAppender(listAppender);
    }

After the test execution (method "afterTestExecution(...)"), we remove the appender again and also delete the logged events:

    @Override
    public void afterTestExecution(ExtensionContext context) {
        Logger rootLogger = (Logger) LogManager.getRootLogger();
        rootLogger.removeAppender(listAppender);
        listAppender.clearLogEvents();
    }

Finally, we add methods to our extension with which we can test whether the application has logged as desired:

    public void info(String expectedMessage) {
        assertLogged(expectedMessage, Level.INFO);
    }

    // more methods for the other log levels

    private void assertLogged(String message, Level level) {
        listAppender.getLoggedEvents().stream()
            .filter(e -> e.getLevel().equals(level))
            .filter(e -> e.getMessage().getFormattedMessage().equals(message))
            .findAny()
            .orElseThrow(() -> new AssertionFailedError("Log message '" + message + "' with level '" + level + 
                                                        "' was expected, but not logged."));
    }

Using the extension

Now to the use of our extension in the test. There are two options for this:

• With the annotation @ExtendWith above the test class definition
• Via @RegisterExtension within the test class

Since we want to interact directly with our extension by calling the check methods, we need variant no. 2:

public class AppTest {

    @RegisterExtension
    static final AssertLoggedExtension assertLogged = new AssertLoggedExtension();

    // ...
}

Now only the object to be tested and the test method are missing. Our test class now looks like this:

public class AppTest {

    @RegisterExtension
    static final AssertLoggedExtension assertLogged = new AssertLoggedExtension();

    // subject under test
    private final App app = new App();

    @Test
    public void shouldHaveLogged() {
        app.run();

        assertLogged.info("Running");
    }
}

Here you can see why the instance of our extension was called "assertLogged": This results in test code that is easy to read and understand.

And that's it already! We have our extension with which we can test logging. It wasn't difficult at all, was it?

The complete source code of the example can be found on GitHub at https://github.com/doubleSlashde/assert-log.

Two final remarks:

• For the sake of simplicity, I have limited myself to the logging framework Log4j2. With logunit, there is an extension that supports several log frameworks.
• The extension does not work when the tests are executed in parallel. This is because the log configuration is global and would be constantly overwritten by the extension. If parallel execution is absolutely necessary, the variant described above with the mocking of loggers must be used.

Learn more about software development