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.

Javadoc

In our current project there is a guideline that all of the public API must have Javadoc. I disagree with this guideline. Our project does not have a public API, since we’re the only team that works on this project and no other team is allowed to use the codebase. Public classes and methods are not the only criterium for a public API.

So I asked, how many times is the Javadoc actually read, versus looking at the actual code to see what the method does? Personally, I never look at the Javadoc, and I suspect I’m not alone in this practice.

So why don’t I read Javadoc in our project? I don’t trust it. We’re using IntelliJ Ultimate, and this IDE also finds errors in Javadoc. And there are lots and lots of errors. So I don’t trust it.

When you’re working on the code, you’re not updating the accompanying Javadoc. The reason for this is the same as why you don’t write unittests – unless you’re using TDD: you’re solving a problem, and you need your attention there.

Javadoc is useful when you’re writing a library, and actually want third parties to use it. They need this form of documentation.

As for our project, there are other ways of documenting the code. You can (and must, in my opinion) factor the code to be as clear as possible. Good naming practices are a good step towards self-documenting code.

Another way of documenting, is writing clear unittests. You don’t need to write them first, though that is often the easiest way to write them. As long as you run them, you have a form of documentation that fails if incorrect.

For the same reason, you can use the assert keyword. To enable this, you need a runtime JVM argument, by default it is disabled. This means assert statements are not executed in production, but neither is Javadoc. However, during development, asserts can provide a treasure of information and verify the correctness of your program. The assert keyword IS documentation.

A nice Stackoverflow thread about assert can be found here: https://stackoverflow.com/questions/1208404/do-you-use-assertions

No documentation is bad, wrong documentation is worse. Javadoc tends to turn wrong when the codebase changes, and should therefore be avoided if possible.