如何在日志记录器中对消息进行JUnit断言

310

我有一些测试代码,它调用Java记录器来报告其状态。 在JUnit测试代码中,我想验证是否已经在记录器中正确地生成了日志条目。以下是大致的代码:

methodUnderTest(bool x){
    if(x)
        logger.info("x happened")
}

@Test tester(){
    // perhaps setup a logger first.
    methodUnderTest(true);
    assertXXXXXX(loggedLevel(),Level.INFO);
}

我认为可以通过一个特别适应的日志记录器(或处理程序,或格式化程序)来实现这一点,但我更希望重用已经存在的解决方案。(而且,说实话,我不清楚如何从日志记录器获取logRecord,但假设那是可能的。)

33个回答

1

Log4J2的API略有不同。此外,您可能正在使用其异步appender。我为此创建了一个锁定的appender:

    public static class LatchedAppender extends AbstractAppender implements AutoCloseable {

    private final List<LogEvent> messages = new ArrayList<>();
    private final CountDownLatch latch;
    private final LoggerConfig loggerConfig;

    public LatchedAppender(Class<?> classThatLogs, int expectedMessages) {
        this(classThatLogs, null, null, expectedMessages);
    }
    public LatchedAppender(Class<?> classThatLogs, Filter filter, Layout<? extends Serializable> layout, int expectedMessages) {
        super(classThatLogs.getName()+"."+"LatchedAppender", filter, layout);
        latch = new CountDownLatch(expectedMessages);
        final LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
        final Configuration config = ctx.getConfiguration();
        loggerConfig = config.getLoggerConfig(LogManager.getLogger(classThatLogs).getName());
        loggerConfig.addAppender(this, Level.ALL, ThresholdFilter.createFilter(Level.ALL, null, null));
        start();
    }

    @Override
    public void append(LogEvent event) {
        messages.add(event);
        latch.countDown();
    }

    public List<LogEvent> awaitMessages() throws InterruptedException {
        assertTrue(latch.await(10, TimeUnit.SECONDS));
        return messages;
    }

    @Override
    public void close() {
        stop();
        loggerConfig.removeAppender(this.getName());
    }
}

像这样使用它:
        try (LatchedAppender appender = new LatchedAppender(ClassUnderTest.class, 1)) {

        ClassUnderTest.methodThatLogs();
        List<LogEvent> events = appender.awaitMessages();
        assertEquals(1, events.size());
        //more assertions here

    }//appender removed

1
如果我只想查看某个字符串是否被记录(而不是验证确切的日志语句,这太容易出错了),我所做的就是将StdOut重定向到一个缓冲区,进行包含操作,然后重新设置StdOut:
PrintStream original = System.out;
ByteArrayOutputStream buffer = new ByteArrayOutputStream();
System.setOut(new PrintStream(buffer));

// Do something that logs

assertTrue(buffer.toString().contains(myMessage));
System.setOut(original);

3
我尝试使用java.util.logging进行记录(尽管我使用了System.setErr(new PrintStream(buffer));,因为它将日志记录到stderr),但它不起作用(缓冲区保持为空)。如果我直接使用System.err.println("foo"),它就可以工作,因此我认为日志系统会保留自己的输出流引用,并从System.err中获取该引用,因此对System.setErr(..)的调用不会影响日志输出,因为它是在日志系统初始化之后发生的。 - hoijui

0

你可能想要测试两件事情。

  • 当我的程序有一个操作员感兴趣的事件时,我的程序是否执行了适当的日志记录操作,以便通知操作员该事件。
  • 当我的程序执行日志记录操作时,它生成的日志消息是否具有正确的文本。

这两件事实际上是不同的事情,因此可以分别进行测试。然而,由于测试第二个(消息文本)存在问题,我建议根本不要这样做。对消息文本的测试最终将包括检查一个文本字符串(预期的消息文本)是否与用于日志记录代码中的文本字符串相同或可以轻松派生自该字符串。

  • 这些测试根本不测试程序逻辑,它们只测试一个资源(字符串)是否等同于另一个资源。
  • 这些测试很脆弱;即使对日志消息格式的微小调整也会破坏你的测试。
  • 这些测试与你的日志界面的国际化(翻译)不兼容。这些测试假定只有一种可能的消息文本,因此只有一种可能的人类语言。
请注意,直接调用文本日志记录接口的程序代码(实现某些业务逻辑)是不良设计(但不幸的是非常常见)。负责业务逻辑的代码还决定了一些日志策略和日志消息的文本。它将业务逻辑与用户界面代码混合在一起(是的,日志消息是您程序的用户界面的一部分)。这些东西应该是分开的。
因此,我建议业务逻辑不直接生成日志消息的文本。而是让它委托给一个日志记录对象。
  • 日志对象的类应该提供一个合适的内部API,你的业务对象可以使用你的领域模型的对象来表达发生的事件,而不是文本字符串。
  • 你的日志类的实现负责生成这些领域对象的文本表示,并呈现一个合适的文本描述事件,然后将该文本消息转发给低级别的日志框架(如JUL、log4j或slf4j)。
  • 你的业务逻辑只负责调用你的日志记录器类的正确方法,传递正确的领域对象,以描述实际发生的事件。
  • 你的具体日志记录器类实现了一个接口,该接口描述了你的业务逻辑可能使用的内部API。
  • 实现业务逻辑并必须执行日志记录的类引用日志记录对象进行委托。引用的类是抽象的接口。
  • 使用依赖注入来设置对日志记录器的引用。

然后,你可以通过创建一个模拟日志记录器来测试你的业务逻辑类是否正确地告诉日志记录接口有关事件,并在测试的设置阶段中使用依赖注入。

就像这样:

 public class MyService {// The class we want to test
    private final MyLogger logger;

    public MyService(MyLogger logger) {
       this.logger = Objects.requireNonNull(logger);
    }

    public void performTwiddleOperation(Foo foo) {// The method we want to test
       ...// The business logic
       logger.performedTwiddleOperation(foo);
    }
 };

 public interface MyLogger {
    public void performedTwiddleOperation(Foo foo);
    ...
 };

 public final class MySl4jLogger: implements MyLogger {
    ...

    @Override
    public void performedTwiddleOperation(Foo foo) {
       logger.info("twiddled foo " + foo.getId());
    }
 }

 public final void MyProgram {
    public static void main(String[] argv) {
       ...
       MyLogger logger = new MySl4jLogger(...);
       MyService service = new MyService(logger);
       startService(service);// or whatever you must do
       ...
    }
 }

 public class MyServiceTest {
    ...

    static final class MyMockLogger: implements MyLogger {
       private Food.id id;
       private int nCallsPerformedTwiddleOperation;
       ...

       @Override
       public void performedTwiddleOperation(Foo foo) {
          id = foo.id;
          ++nCallsPerformedTwiddleOperation;
       }

       void assertCalledPerformedTwiddleOperation(Foo.id id) {
          assertEquals("Called performedTwiddleOperation", 1, nCallsPerformedTwiddleOperation);
          assertEquals("Called performedTwiddleOperation with correct ID", id, this.id);
       }
    };

    @Test
    public void testPerformTwiddleOperation_1() {
       // Setup
       MyMockLogger logger = new MyMockLogger();
       MyService service = new MyService(logger);
       Foo.Id id = new Foo.Id(...);
       Foo foo = new Foo(id, 1);

       // Execute
       service.performedTwiddleOperation(foo);

       // Verify
       ...
       logger.assertCalledPerformedTwiddleOperation(id);
    }
 }

0
使用Jmockit(1.21),我能够编写这个简单的测试。 该测试确保特定的ERROR消息仅被调用一次。
@Test
public void testErrorMessage() {
    final org.slf4j.Logger logger = org.slf4j.LoggerFactory.getLogger( MyConfig.class );

    new Expectations(logger) {{
        //make sure this error is happens just once.
        logger.error( "Something went wrong..." );
        times = 1;
    }};

    new MyTestObject().runSomethingWrong( "aaa" ); //SUT that eventually cause the error in the log.    
}

0

通过添加Appender进行单元测试并不能真正测试Logger的配置。因此,我认为这是一种独特的情况,其中单元测试带来的价值并不是那么高,但是集成测试带来了很多价值(尤其是如果您的日志记录具有某些审计目的)。

为了为其创建集成测试,假设您正在使用简单的ConsoleAppender并且想要测试其输出。然后,您应该测试消息如何从System.out写入其自己的ByteArrayOutputStream

在这个意义上,我会按照以下步骤进行(我使用JUnit 5):

public class Slf4jAuditLoggerTest {

    private final ByteArrayOutputStream outContent = new ByteArrayOutputStream();

    @BeforeEach
    public void beforeEach() {
        System.setOut(new PrintStream(outContent));
    }

这样,您只需简单地测试其输出:

    @Test
    public void myTest() {
        // Given...
        // When...
        // Then
        assertTrue(outContent.toString().contains("[INFO] My formatted string from Logger"));
    }

如果您这样做,将会为您的项目带来更多的价值,并且不需要使用内存实现、创建新的Appender或其他任何操作。

0
最近我发布了一个新的日志测试选项,名为"flogger-testing"库(https://github.com/hagbard/flogger-testing)。不要被名称所迷惑,它可以与Log4J和JDK日志一起使用(功能略有降级)。它支持JUnit4规则和JUnit5扩展,两者都具有完全相同的断言API。
它不需要强制您将模拟的日志记录器注入到代码中等可能有害的做法,并且通过拦截正在发出的日志(使您的测试更接近于测试日志文件中出现的内容),可以完美地与static final日志记录器实例配合使用。
为类添加日志记录测试非常简单(JUnit5):
  @RegisterExtension
  public final FloggerTestExtension logs = FloggerTestExtension.forClassUnderTest(INFO);

而且强大的流畅API的使用方式如下:

@Test
public void testLoadData_missingFile() {
  // Do normal assertion about returned values.
  var result = ClassUnderTest.loadData(MISSING_FILE);
  assertThat(result).isEmpty();

  // Assert that we saw the expected warning ...
  LogEntry firstWarning = logs.assertLogs().withLevel(WARNING).getMatch(0);
  assertThat(firstWarning).hasMessageContaining("No such file", MISSING_FILE);
  assertThat(firstWarning).hasCause(IOException.class);
  // ... and assert that nothing seemed to go wrong before the first warning.
  logs.assertLogs(before(firstWarning)).never().haveCause();
}

它具有其他日志测试API中没有的许多功能,这些功能在本主题中提到:

  • 结构化元数据测试
  • 为所有测试设置常见断言,以强制执行日志策略
  • 在单个测试中覆盖日志级别(例如,确保启用最详细的日志记录不会引起任何问题)
  • 在测试中绕过速率限制(仅适用于Flogger)
  • 使用每个线程的元数据,以确保日志测试可以可靠地并行运行(仅适用于Flogger)

使用可读性强、功能强大的API编写更健壮的日志测试。


0
另一个值得一提的想法,虽然它是一个老话题,就是创建一个CDI生产者来注入您的记录器,这样模拟变得容易。 (它还具有不再需要声明“整个记录器语句”的优点,但这是离题了)

示例:

创建要注入的记录器:

public class CdiResources {
  @Produces @LoggerType
  public Logger createLogger(final InjectionPoint ip) {
      return Logger.getLogger(ip.getMember().getDeclaringClass());
  }
}

限定词:

@Qualifier
@Retention(RetentionPolicy.RUNTIME)
@Target({TYPE, METHOD, FIELD, PARAMETER})
public @interface LoggerType {
}

在你的生产代码中使用日志记录器:

public class ProductionCode {
    @Inject
    @LoggerType
    private Logger logger;

    public void logSomething() {
        logger.info("something");
    }
}

在测试代码中测试日志记录器(以easyMock为例):

@TestSubject
private ProductionCode productionCode = new ProductionCode();

@Mock
private Logger logger;

@Test
public void testTheLogger() {
   logger.info("something");
   replayAll();
   productionCode.logSomething();
}

0

模拟Appender可以帮助捕获日志行。 在http://clearqa.blogspot.co.uk/2016/12/test-log-lines.html上找到示例。

// Fully working test at: https://github.com/njaiswal/logLineTester/blob/master/src/test/java/com/nj/Utils/UtilsTest.java

@Test
public void testUtilsLog() throws InterruptedException {

    Logger utilsLogger = (Logger) LoggerFactory.getLogger("com.nj.utils");

    final Appender mockAppender = mock(Appender.class);
    when(mockAppender.getName()).thenReturn("MOCK");
    utilsLogger.addAppender(mockAppender);

    final List<String> capturedLogs = Collections.synchronizedList(new ArrayList<>());
    final CountDownLatch latch = new CountDownLatch(3);

    //Capture logs
    doAnswer((invocation) -> {
        LoggingEvent loggingEvent = invocation.getArgumentAt(0, LoggingEvent.class);
        capturedLogs.add(loggingEvent.getFormattedMessage());
        latch.countDown();
        return null;
    }).when(mockAppender).doAppend(any());

    //Call method which will do logging to be tested
    Application.main(null);

    //Wait 5 seconds for latch to be true. That means 3 log lines were logged
    assertThat(latch.await(5L, TimeUnit.SECONDS), is(true));

    //Now assert the captured logs
    assertThat(capturedLogs, hasItem(containsString("One")));
    assertThat(capturedLogs, hasItem(containsString("Two")));
    assertThat(capturedLogs, hasItem(containsString("Three")));
}

0

在我的情况下,我解决了与以下相同的问题:

Logger root = (Logger) LoggerFactory.getLogger(CSVTasklet.class); //CSVTasklet is my target class
    final Appender mockAppender = mock(Appender.class);
    root.addAppender(mockAppender); 

verify(mockAppender).doAppend(argThat((ArgumentMatcher) argument -> ((LoggingEvent) argument).getMessage().contains("No projects."))); // I checked "No projects." in the log

0

我之前回答了一个关于log4j的类似问题,请参考how-can-i-test-with-junit-that-a-warning-was-logged-with-log4

这是一个使用Log4j2(已测试2.11.2版本)和junit 5的新示例;

    package com.whatever.log;

    import org.apache.logging.log4j.Level;
    import org.apache.logging.log4j.LogManager;
    import org.apache.logging.log4j.core.Logger;
    import org.apache.logging.log4j.core.*;
    import org.apache.logging.log4j.core.appender.AbstractAppender;
    import org.apache.logging.log4j.core.config.Configuration;
    import org.apache.logging.log4j.core.config.LoggerConfig;
    import org.apache.logging.log4j.core.config.plugins.Plugin;
    import org.apache.logging.log4j.core.config.plugins.PluginAttribute;
    import org.apache.logging.log4j.core.config.plugins.PluginElement;
    import org.apache.logging.log4j.core.config.plugins.PluginFactory;
    import org.junit.jupiter.api.AfterEach;
    import org.junit.jupiter.api.BeforeEach;
    import org.junit.jupiter.api.DisplayName;
    import org.junit.jupiter.api.Test;

    import java.util.ArrayList;
    import java.util.List;
    import static org.junit.Assert.*;

class TestLogger {

    private TestAppender testAppender;
    private LoggerConfig loggerConfig;
    private final Logger logger = (Logger)
            LogManager.getLogger(ClassUnderTest.class);

    @Test
    @DisplayName("Test Log Junit5 and log4j2")
    void test() {
        ClassUnderTest.logMessage();
        final LogEvent loggingEvent = testAppender.events.get(0);
        //asset equals 1 because log level is info, change it to debug and
        //the test will fail
        assertTrue(testAppender.events.size()==1,"Unexpected empty log");
        assertEquals(Level.INFO,loggingEvent.getLevel(),"Unexpected log level");
        assertEquals(loggingEvent.getMessage().toString()
                ,"Hello Test","Unexpected log message");
    }

    @BeforeEach
    private void setup() {
        testAppender = new TestAppender("TestAppender", null);

        final LoggerContext context = logger.getContext();
        final Configuration configuration = context.getConfiguration();

        loggerConfig = configuration.getLoggerConfig(logger.getName());
        loggerConfig.setLevel(Level.INFO);
        loggerConfig.addAppender(testAppender,Level.INFO,null);
        testAppender.start();
        context.updateLoggers();
    }

    @AfterEach
    void after(){
        testAppender.stop();
        loggerConfig.removeAppender("TestAppender");
        final LoggerContext context = logger.getContext();
        context.updateLoggers();
    }

    @Plugin( name = "TestAppender", category = Core.CATEGORY_NAME, elementType = Appender.ELEMENT_TYPE)
    static class TestAppender extends AbstractAppender {

        List<LogEvent> events = new ArrayList();

        protected TestAppender(String name, Filter filter) {
            super(name, filter, null);
        }

        @PluginFactory
        public static TestAppender createAppender(
                @PluginAttribute("name") String name,
                @PluginElement("Filter") Filter filter) {
            return new TestAppender(name, filter);
        }

        @Override
        public void append(LogEvent event) {
            events.add(event);
        }
    }

    static class ClassUnderTest {
        private static final Logger LOGGER =  (Logger) LogManager.getLogger(ClassUnderTest.class);
        public static void logMessage(){
            LOGGER.info("Hello Test");
            LOGGER.debug("Hello Test");
        }
    }
}

使用以下 Maven 依赖项:
 <dependency>
 <artifactId>log4j-core</artifactId>
  <packaging>jar</packaging>
  <version>2.11.2</version>
</dependency>
<dependency>
    <groupId>org.junit.jupiter</groupId>
    <artifactId>junit-jupiter-api</artifactId>
    <version>5.5.0</version>
    <scope>test</scope>
</dependency>

我尝试了这个,但在setup方法中的loggerConfig = configuration.getLoggerConfig(logger.getName());这一行出现了错误。错误是无法访问org.apache.logging.log4j.spi.LoggerContextShutdownEnabled类文件,因为找不到org.apache.logging.log4j.spi.LoggerContextShutdownEnabled。 - carlos palma
我已经审查了代码并进行了一些小的更改,但对我来说它是有效的。我建议您检查依赖项并确保所有导入都是正确的。 - Haim Raman
你好,海姆。最终我采用了logback的解决方案……但我认为你是对的,为了实现这个解决方案,我必须清除我所导入的另一个log4j版本的import。 - carlos palma

网页内容由stack overflow 提供, 点击上面的
可以查看英文原文,
原文链接