Log4j2：并行测试时的空日志文件

Question

我的测试自动化项目中有日志记录问题。我正在使用带有 FileAppender 的 log4j2 记录器。我的使用方式是：

Logger logger = (Logger) LogManager.getLogger(loggerName);
Appender appender = FileAppender.newBuilder()
            .withAppend(false)
            .withBufferedIo(true)
            .withFileName(DIR_NAME + File.separator + loggerName + ".log")
            .withIgnoreExceptions(false)
            .withImmediateFlush(true)
            .withLocking(false)
            .withLayout(PatternLayout.newBuilder().withPattern("%d{HH:mm:ss.SSS}  [%-5level] %msg%n").withCharset(Charset.forName("UTF-8")).build())
            .withName(loggerName)
            .build();

    appender.start();
    logger.addAppender(appender);

它在我运行单个测试时有效。所有数据都在控制台中可见，创建文件并将测试日志写入文件。如果测试在不同的线程中并行运行，则会出现问题。

在这种情况下，会创建两个不同的记录器和文件追加器。来自两个文件附加器的日志文件也被创建，来自两个测试的日志都在控制台中可见。一切似乎都很好，但每次这些日志文件之一都是空的。空日志属于稍后开始的测试。

我怀疑缓存有问题。第一个文件附加程序保存所有缓存以供写入，因此第二个文件无法写入。我对吗？解决方案是什么？

谢谢。

Answer 1

您应该能够在不使用编程配置的情况下实现您想要的。不以编程方式配置 log4j2 的原因有很多，但在我看来，最好的一个原因是这样做会使您的代码依赖于 log4j2 的不公共 API 一部分的方面。这意味着如果 log4j2 的实现发生更改，您的代码也必须更改。从长远来看，这会为您创造更多的工作。

因此，考虑到这一点，我将提供一个演示，说明如何使用 XML 配置文件设置 log4j2，以便为每个测试生成单独的日志。我假设，因为您的问题中没有指定，您的目标是为每个带有 Test 注释的方法创建一个日志，并且这些方法中的每一个都是并行执行的。

首先，这是我的 TestNG 课程：

package testpkg;

import java.lang.reflect.Method;

import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.ThreadContext;
import org.testng.annotations.BeforeMethod;
import org.testng.annotations.Test;

public class NewTest {
    private static final Logger log = LogManager.getLogger();

    @BeforeMethod
    public void setThreadName(Method method){
        ThreadContext.put("threadName", method.getName());
    }

    @Test
    public void test1() {
        log.info("This is the first test!");
        log.warn("Something may be wrong, better take a look.");
    }

    @Test
    public void test2() {
        log.info("Here's the second test!");
        log.error("There's a problem, better fix it");
    }
}

正如您在此处看到的，我有两个 Test 方法和一个名为 setThreadName 的 BeforeMethod。显然，setThreadName 方法在每个Test 方法之前执行。它使用即将运行的方法的名称将一个名为 threadName 的键放入 log4j2 ThreadContext。这将用作 log4j2 配置文件中日志文件名的一部分。

这里是 log4j2.xml 文件：

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
    <Appenders>
        <Routing name="MyRoutingAppender">
            <Routes pattern="$${ctx:threadName}">
                <Route>
                    <File
                        fileName="logs/${ctx:threadName}.log"
                        name="appender-${ctx:threadName}"
                        append="false">
                        <PatternLayout>
                            <Pattern>[%date{ISO8601}][%-5level][%t] %m%n</Pattern>
                        </PatternLayout>
                    </File>
                </Route>
            </Routes>
        </Routing>
        <Console name="STDOUT" target="SYSTEM_OUT">
            <PatternLayout pattern="[%date{ISO8601}][%-5level][%t] %m%n" />
        </Console>
    </Appenders>
    <Loggers>
        <Logger name="testpkg" level="TRACE" additivity="false">
            <AppenderRef ref="STDOUT" />
            <AppenderRef ref="MyRoutingAppender" />
        </Logger>
        <Root level="WARN">
            <AppenderRef ref="STDOUT" />
        </Root>
    </Loggers>
</Configuration>

如您所见，我已将配置文件设置为使用RoutingAppender 在运行时根据ThreadContext 键threadName 动态生成附加程序，并且threadName 也用于fileName FileAppender 的属性。

这是我的 testNG 配置文件：

<!DOCTYPE suite SYSTEM "http://testng.org/testng-1.0.dtd" >

<suite name="My suite" parallel="methods" thread-count="5" verbose="1">
  <test name="testpkg" >
    <classes>
       <class name="testpkg.NewTest" />
    </classes>
  </test>
</suite>

正如您在此处看到的，我已对其进行了设置，以便我的类中的每个 Test 方法并行运行。

执行时会产生以下控制台输出：

[RemoteTestNG] detected TestNG version 6.14.3
[2018-05-04T21:54:54,703][INFO ][TestNG-test=testpkg-2] Here's the second test!
[2018-05-04T21:54:54,703][INFO ][TestNG-test=testpkg-1] This is the first test!
[2018-05-04T21:54:54,709][WARN ][TestNG-test=testpkg-1] Something may be wrong, better take a look.
[2018-05-04T21:54:54,709][ERROR][TestNG-test=testpkg-2] There's a problem, better fix it

===============================================
My suite
Total tests run: 2, Failures: 0, Skips: 0
===============================================

可以清楚的看到两个方法的输出是交错的，所以我们知道这些方法确实是并行运行的。

测试类的执行还按预期创建了两个日志文件。它们被命名为 test1.log 和 test2.log

这是他们的内容：

test1.log：

[2018-05-04T21:54:54,703][INFO ][TestNG-test=testpkg-1] This is the first test!
[2018-05-04T21:54:54,709][WARN ][TestNG-test=testpkg-1] Something may be wrong, better take a look.

test2.log：

[2018-05-04T21:54:54,703][INFO ][TestNG-test=testpkg-2] Here's the second test!
[2018-05-04T21:54:54,709][ERROR][TestNG-test=testpkg-2] There's a problem, better fix it

所以我们在这里看到，正如预期的那样，第一种方法的日志进入了 test1.log，而第二种方法的日志进入了 test2.log

享受吧！