Testing Logging Output in Java

Testing that the logged output is as expected seems to be on the cusp of a good/bad idea. Is the logged output the intended behavior of the application? or is it an implementation detail that you’re just mirroring in a test?

Arguably, it’s sometimes the former… logging is the sort of thing that matters when it matters.

I’d argue that it’s often too low level a thing to be testing, but it’s a critical thing to test when:

◉ You’re writing a logging framework that centralises the logging logic

◉ You have some exceptional case that MUST be logged differently and need to lock down the behaviour

◉ Logging IS the logic for some reason

Note, I like to think of tests as locking down the logic – we wrote the code this way today, hopefully using TDD, to achieve something observable by a test. The test keeps that observable behaviour from disappearing by going red if someone breaks it. So the test locks down some spec.

Logging in the Modern World

These days we deliberately log to the System console, rather than log files. This works well when we’re containerising our application, or writing an AWS Lambda, and we want the hosting environment’s log scraper to pull the logs from stdout rather than mine log files as we write them.

Spooling log messages to the console, while once thought of as a no-no, is essentially a lot cleaner than telling a logging agent to go and read a file as we write it.

Can’t We Just Watch System.out Then?

Well, indeed we can. No need to register a listener into the logging framework. Let’s just look at what appears on the console. We can configure our logger to write to the console – in fact it probably does already!

Enter System Stubs

I will write more about it in due course, but System Stubs is a testing library I’ve worked hard on in recent weeks. It started life as a different project that I forked, and then I essentially reworked it to fit in with the sort of tests I’ve been writing. As such, it’s available as a JUnit 5 extension (as well as in other forms).

Let’s imagine we have some code under test that’s going to do some logging, and we want to see if a certain message appears.

Here’s a test:

@ExtendWith(SystemStubsExtension.class)

class TheOneAboutTheLoggingTest {

    @SystemStub

    private SystemOut systemOut;

    @Test

    void youKnow_ForLogging() {

         doTheThingThatShouldLog();

         assertThat(systemOut.getLines())

             .anyMatch(line -> line.contains("ERROR This is bad!"));

    }

}

Let’s just unpack a few of the elements in the above.

There’s the JUnit 5 extension – SystemStubsExtension. No big deal. Then there’s a SystemOut object, which is used to capture System.out while the object is active. The object is created by the extension and is activated just before the test, then cleared up afterwards.

While the test is running, System.out is not appearing in the console, it’s being stored in the memory of the SystemOut object’s TapStream.

At any point we can expect the lines of text that have appeared on System.out. The getLines function provides a Stream<String> which we inspect here using AssertJ.

Given logging output usually contains timestamps, this method requires us to do some sort of substring checking to avoid having to predict the timestamp. Perhaps a future library might help parse the output a little more.

It’s also worth noting that NOT seeing the logging output on the console is a little annoying during this sort of test. In due course, I’m planning to release version 1.2.0 of SystemStubs which will allow a multiplex where the output appears on the console AND is also tapped.

So is Tapping System.out the Future of Log Testing?

Yes and no.

It’s enormously convenient and easy to do. So, I’m inclined to default to it.

However, for fine-grained testing of exactly what is being sent to the logging library, the reading of strings from a console is a bit messy.

Source: javacodegeeks.com