test your logging

I have yet to work on a project where we have attempted to test the log statements in the software & I’ve recently found myself asking why.

Log statements added by different developers (sometimes guided by a woolly statement on logging in the project coding guidelines) vary in their number, style & usefulness. Logging ends up inconsistent in its level of detail, format & log level.

The logging of the same event could end up like any of the following:

1: Saving order...

2: Creating order for customer [123] for [5] items with value [£56.20]...

3: Adding order [
     customer: {
       ... // full details of customer
     },
     items: {
       ... // full details of all items
     },
     ...
   ]

In this environment, diagnosing the cause of production issues frequently involves tweaking the log level for certain packages in the hope that the application gives up its secrets and deploying patches with additional log statements when it doesn’t.

It seems clear that we do care about logging & it is an important part of what we deliver.

If we are using AOP to consistently apply logging at the boundary to certain layers and have no other logging, that’s great. Testing those log statements is probably less valuable. If not, we need a solution.

LogCaptor

LogCaptor is a simple library that allows us to capture logging from the system under test and make assertions about it. It looks like this:

class WidgetServiceTest {

    private final LogCaptor logCaptor = LogCaptor.forClass(WidgetService.class);
    ...

    @Test
    void testAdd() {
        String name = "My Widget";
        service.add(Widget.of(name));
        assertThat(logCaptor.getDebugLogs())
                .containsExactly(
                        String.format("Adding widget with name [%s]", name)
                );
    }
}

(this example is also using the awesome AssertJ)

The LogCaptor class provides methods for getting the logged messages as a list of LogEvent or strings. For the latter, these can be restricted to a particular logging level.

The full LogEvent is useful for more complex assertions. It provides access to arguments and any Throwable as well as the message & log level. The following example shows a test of a log statement that includes an exception.

@Test
void testRemoveWithIllegalId() {
    int illegalId = -1;

    assertThatIllegalArgumentException()
            .isThrownBy(() -> service.remove(illegalId));

    List<LogEvent> logEvents = logCaptor.getLogEvents();
    assertThat(logEvents)
            .hasOnlyOneElementSatisfying(
                    event -> {
                        assertThat(event.getMessage())
                            .isEqualTo("Error removing widget");
                        assertThat(event.getLevel())
                            .isEqualTo("ERROR");
                        assertThat(event.getThrowable())
                                .isPresent()
                                .get(as(InstanceOfAssertFactories.THROWABLE))
                                .hasMessage(
                                        String.format(
                                                "Widget id must be greater than 0 but was [%s]", 
                                                illegalId
                                        )
                                )
                                .isInstanceOf(IllegalArgumentException.class);
                    }
            );
}

It works with all common logging libraries and with the Lombok logging annotations.

That’s LogCaptor.

logcaptor.
assertj.
source.

LogCaptor#

LogCaptor