Blog

Unit testing log statements

In this blog, our collegue Niels Kuiper writes about unit testing log statements. You can find his blog, where Niels covers topics related to java development,  by following the link below.
http://3ldn.nl/2017/02/18/unit-testing-log-statements/

Usually logging is not considered when writing tests. This is often because logging is not the primary purpose of a class and will, in terms of line coverage, usually be covered automatically. There are however situations when logging is the primary purpose of a class and as such it requires more thorough testing. When using a logging framework such as SLF4J however, the difficulty is in how to determine that the logging actually happening and that is has the correct level and content: the logging framework is usually not very test-orientated.

There are several posts on stackoverflow that deal with unit testing logging in java, so for a broader overview, check there. This post will give single, straightforward method of testing log statements.

The code for this example can be found at https://github.com/kuipercm/test-logging

Situation

Let’s assume that we are writing a component that handles sending and receiving messages to an external source. For traceability and auditability purposes it is a business requirement to log all incoming and outgoing messages. This makes the logging an essential part of the application and it should therefore be verified in tests.

To facilitate the logging, a separate class is created such the details of what to log and how are still abstracted from the main, more functional, program flow. It has the added benefit that the logging class can be more easily tested.

public class FruitMachine {
    private final FruitLogger logger = FruitLogger.INSTANCE;
 
    private final String remoteUrl;
 
    public FruitMachine(String remoteUrl) {
        this.remoteUrl = remoteUrl;
    }
 
    public void sendMessage(FruityMessage message) {
        logger.logAllFruitMessages(message);
        //do some remote call
    }
 
}

In the code sample above, the logging of the FruitMachine class is handled by the FruitLogger instance. The logger is called for all FruitMessages.

The FruitLogger itself it not special:

public class FruitLogger {
    public static final FruitLogger INSTANCE = new FruitLogger();
 
    static final Logger log = LoggerFactory.getLogger(FruitLogger.class);
 
    private FruitLogger() {
        //don't instatiate outside this class
    }
 
    public void logAllFruitMessages(FruityMessage message) {
        if (message != null) {
            log.info("Outgoing message body: {}", message.getBody());
        }
    }
}

It logs the message body at INFO level. The Logger is an SLF4j component.

Since the primary purpose of the FruitLogger is to log the message (albeit a little bit simplistic in this example), it is good to have (at least) a unit test for it.

The Test

In the FruitLogger class above, there are two important things to note:

  1. The Logger “log” field has package private (or “default”) visibility. This is to facilitate easier interaction in the unit test.
  2. Of all non-null messages, the message body is logged.

The difficult part is how to test that the “log” will actually contain the message body, because even though we can access the “log” field in the unit test, there are no methods on it such that we can examine what has been sent to it.

To solve this, we can create a test in the following way

public class FruitLoggerTest {
    private static Logger fruityLogger;
    private static ListAppender<ILoggingEvent> fruityLoggerAppender;

    @BeforeClass
    public static void setupBeforeClass() {
        LoggerContext context = (LoggerContext)LoggerFactory.getILoggerFactory();
        fruityLogger = context.getLogger(log.getName());
        fruityLoggerAppender = new ListAppender<>();
        fruityLoggerAppender.start();
        fruityLogger.addAppender(fruityLoggerAppender);
    }

    @Before
    public void setup() {
        fruityLogger.setLevel(Level.ALL);
        fruityLoggerAppender.clearAllFilters();
        fruityLoggerAppender.list.clear();
    }

    @Test
    public void verify_that_the_fruity_message_content_is_logged_at_info_level() {
        assertThat(fruityLoggerAppender.list).hasSize(0);

        FruityMessage fruityMessage = new FruityMessage("apples", "oranges");
        INSTANCE.logAllFruitMessages(fruityMessage);

        assertThat(fruityLoggerAppender.list).hasSize(1);

        ILoggingEvent loggedEvent = fruityLoggerAppender.list.get(0);
        assertThat(loggedEvent.getLevel()).isEqualTo(Level.INFO);
        assertThat(loggedEvent.getFormattedMessage()).contains("body");
        assertThat(loggedEvent.getFormattedMessage()).contains("oranges");
    }
}

This test extracts the fruityLogger from the logging context based on the name of the logger. Subsequently it adds a ListAppender to this logger. The ListAppender is a type of Appender that has an internal list of the ILoggingEvents sent to it and this list can be accessed. This makes usage of this Appender in the test context very useful, as can be seen in this test class.

There are a few things to note with respect to the setup() method:

  • the log level of the fruityLogger is reset to Level.ALL: in unit tests you can change the log level of the logger, to verify that when a certain log level is set, certain messages will no longer be logged. For example, if the log level were to be set to WARN, then the FruitLogger should no longer log the message body. Although it can be considered testing of the logging framework to execute such a test, there are situations in which it can be crucial to verify the behavior.
  • the Appender is cleared of all filters: filters can interfere with which messages are accepted in the appender. It is a good idea to start each test with a clean slate.
  • the ListAppender.list field is also cleared to make sure that each test will only put its own messages in the Appender and will not be influenced by other tests.

The test itself is not difficult to understand. It should be noted that the FruityMessage consists of a header and body field. In this example, the header is “apples”, the body is “oranges”.

Final remarks

As demonstrated above, it is possible to test the logging of classes in unit tests. This is particularly useful in situations where logging becomes a primary purpose of a class due to business requirements.

The code of this example can be found on https://github.com/kuipercm/test-logging. What is not shown in the code samples above is which dependencies are required for this code to work. These are in the pom.xml of the project in Github.

Happy testing!

Van Controle naar Contact: Cavero helpt ROC Midden Nederland met digitaal samenwerken door adoptie Office365
Introductie tot Front-end Development (deel I)