单元测试中验证日志

一般来说，日志是程序相当次要的副作用输出，很少需要专门的单元测试来保证它的行为。不过也不排除在某些情况下需要在单元测试中验证日志，比如：

• 某个场景下日志输出是下游模块的关键信息。一般出现在错误处理分支中。
• 某个模块除了日志没有显著的输出来检验它的行为。红灯，模块可测试性差的表现。

这里介绍以比较常用的logback和log4j2为例介绍验证日志的方法，以备不时之需。

被测试代码

public class SampleService {
    private static Logger LOG = LoggerFactory.getLogger(SampleService.class);
    @Autowired SampleDependency dependency;

    public String foo() {
        LOG.info("starting foo");
        String bar = "";
        try {
            bar = dependency.getExternalValue("bar");
        } catch (Exception e) {
            System.out.println(LOG.getClass().getTypeName());
            LOG.error("calling foo error", e);
        }
        return bar;
    }
}

因为两种框架外加slf4j中有很多同名的类，示例代码中全部带上完整包名以免混淆。

Logback

@Test
public void testLogback() {
    //given
    ch.qos.logback.core.Appender<ch.qos.logback.classic.spi.ILoggingEvent> appender = mock(ch.qos.logback.core.Appender.class);
    ((ch.qos.logback.classic.Logger) LoggerFactory.getLogger(SampleService.class)).addAppender(appender);
    doThrow(new RuntimeException("something wrong...")).when(dependency).getExternalValue(anyString());

    //when
    service.foo();

    //then
    ArgumentCaptor<ch.qos.logback.classic.spi.ILoggingEvent> logCaptor = ArgumentCaptor.forClass(ch.qos.logback.classic.spi.ILoggingEvent.class);
    //通过ArgumentCaptor捕获所有log,
    //verify默认是一次调用，改为atLeast(0)让任意次数记录log都能验证通过
    verify(appender, atLeast(0)).doAppend(logCaptor.capture()); 
    logCaptor.getAllValues().stream()
            .filter(event -> event.getFormattedMessage().equals("calling foo error"))
            .findFirst().orElseThrow(AssertionError::new);
}

Log4j2

@Test
public void testLog4J2() {
    //given
    org.apache.logging.log4j.core.Appender appender = mock(org.apache.logging.log4j.core.Appender.class);
    when(appender.getName()).thenReturn("mocked");  //加入appender时需要
    when(appender.isStarted()).thenReturn(true);  //使appender生效时需要
    ((org.apache.logging.log4j.core.Logger) org.apache.logging.log4j.LogManager.getRootLogger() ).addAppender(appender);
    doThrow(new RuntimeException("something wrong...")).when(dependency).getExternalValue(anyString());

    //when
    service.foo();

    //then
    ArgumentCaptor<org.apache.logging.log4j.core.LogEvent> logCaptor = ArgumentCaptor.forClass(org.apache.logging.log4j.core.LogEvent.class);
    verify(appender, atLeast(0)).append(logCaptor.capture());
    logCaptor.getAllValues().stream()
            .filter(event -> event.getMessage().getFormattedMessage().equals("calling foo error"))
            .findFirst().orElseThrow(AssertionError::new);
}