Log4j2: пустой файл журнала в случае параллельных тестов - PullRequest
Новая
       38

Log4j2: пустой файл журнала в случае параллельных тестов

0 голосов
/ 24 апреля 2018

У меня в проекте тестирования автоматизации проблема с ведением журнала.Я использую log4j2 logger с FileAppender.Я использую его так: 

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);

Это работает, когда я запускаю одиночный тест.Все данные отображаются в консоли, файл создается, и в файл записывается журнал испытаний.Проблема возникает в том случае, если тесты выполняются параллельно - в разных потоках.

В этом случае создаются два разных регистратора и файловых аппендера.Файлы журналов из обоих файловых аппендеров также создаются, и журналы обоих тестов видны в консоли.Кажется, все в порядке, но каждый раз, когда один из этих файлов журнала пуст.Пустой журнал принадлежит тесту, который начался позже.

Я подозреваю, что проблема с кэшированием.Первый файл appender содержит весь кэш для записи, поэтому второй не может писать.Я прав?Какое решение для этого?

Спасибо.

1 Ответ

0 голосов
/ 05 мая 2018

Вы должны быть в состоянии достичь того, что вы хотите, без использования программной конфигурации.Есть много причин не настраивать log4j2 программно, но, на мой взгляд, лучшая из них заключается в том, что при этом вы сделаете свой код зависимым от аспектов log4j2, которые являются , а не частью общедоступного API.Это означает, что если реализация log4j2 изменится, ваш код также должен измениться.Это создает больше работы для вас в долгосрочной перспективе.

Итак, имея в виду, я предоставлю демонстрацию того, как настроить log4j2 с помощью файла конфигурации XML, чтобы он генерировал отдельные журналы для каждого теста.Я предполагаю, что поскольку в вашем вопросе не было указано, что ваша цель - создать журнал для каждого метода с аннотацией 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 метода и BeforeMethod с именем setThreadName.Метод 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

Наслаждайтесь!

...