Verify logback log statements

The basic idea behind unittests is that they prove that the code does what it’s expected to do. That means you have to prove that the code is executed in the first place. But sometimes the only way to prove that the code is executed, is to verify that something is logged. With the recent Log4Shell exploit in mind, we’re going to use a different framework: logback.

Initial setup

Because we want to use this technique in multiple tests, we’re going to create a separate class. This class should capture all logging events for a specific class under test, and store them for later retrieval. So let’s start

public class TestUtils {

  private final Object objectUnderTest;
  
  private final List<ILoggingEvent> loggingEvents = new ArrayList<>();
  
  public TestUtils(Object objectUnderTest){
    this.objectUnderTest = objectUnderTest;
  }
}

Notice that we set this up with an actual object instead of a class. We could just use the class instead. I have chosen to include the actual object under test, so the TestUtils class can include some reflection helpers. But that is beyond the scope of this post.

Setup logging

To start capturing the logging statements, we need to create an appender. Once the appender is created, we need to start it and configure the logger to use it. The appender has one important method: append. In our case, this method should add the loggingEvent to the list of loggingEvents. The code for setting up the logging becomes as follows:

    public void setupLogging(){
        AppenderBase<ILoggingEvent> appender = new AppenderBase<ILoggingEvent>() {
            @Override
            protected void append(ILoggingEvent iLoggingEvent) {
                loggingEvents.add(iLoggingEvent);
            }
        };
        appender.start();

        ch.qos.logback.classic.Logger logger = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(objectUnderTest.getClass());
        logger.addAppender(appender);
        logger.setLevel(Level.ALL);
    }

Find logging statements

Since we’re using this for unittests, we only expect one statement with a specific message. To get the loggingEvent, if it’s there, we check all logging events:

    public Optional<ILoggingEvent> getLoggingEventWithMessage(String message){
        return loggingEvents.stream()
                .filter(iLoggingEvent -> iLoggingEvent.getMessage().equals(message))
                .findAny();
    }

How to use

Immagine you need to test the following snippet:

public class MessageLogger {
	public void logMessage(boolean bool, String message){
		if(bool){
			LOG.info("Message is {}", message);
		}
	}
}

The test we can write is the following:

public class MessageLoggerTest {
	
	@Test
	public void logMessage(){
		MessageLogger messageLogger = new MessageLogger();
		TestUtils testUtils = new TestUtils(messageLogger);
		testUtils.setupLogging();
		
		messageLogger.logMessage(true, "Hello World!");
		
		Optional<ILoggingEvent> loggingEvent = testUtils.getLoggingEventWithMessage("Message is {}");
		assertTrue(loggingEvent.isPresent());
	}
}

Note that we query for the unformatted message. The arguments can be retrieved using ILoggingEvent.getArgumentArray().

Conclusion

Sometimes we need to verify whether a logging statements has been logged in order to prove that the code under test does what it’s supposed to do. This utility class makes it easy to do so.
We’ve seen how to add a custom appender to a logback logger that stores the received loggingEvents in a list. We have created a method to query the list for an event with a specific message.
Next we have seen an example of how to use this functionality.

Leave a Reply

Your email address will not be published.