[TestNG + Log4j] Логирование тестов, запускаемых в параллели

база знаний
, ,
#1

В данном уроке я опишу свой опыт решения двух задач для Java тестов, написанных в формате фреймворка TestNG:

а) Подключение библиотеки log4j для детального логирования прохождения тестов.

б) Разделение логов при параллельном запуске тестов.

Запаситесь терпением, будет много примеров и текста. В качестве IDE я использую Eclipse (не забудьте подключить к нему TestNG). Скачайте библиотеку log4j (ссылка в конце урока).

Шаг№1. Пишем простую тестовую сиюту. В Eclipse: File -> New -> Java Project. В проекте: File->New->TestNG Class. Назовём его Sample_01 и методом copy-paste из нашего урока создадим в этом классе два теста:

package info.automatedtesting;

import org.testng.Assert;
import org.testng.annotations.Test;

public class Sample_01 {
    
    @Test
    public void test_01() {
        System.out.println("start test 01");
        Integer amount = 0;
        System.out.println("set amount to " + amount);
        Integer reportPrice = 20;
        System.out.println("set reportPrice to " + reportPrice);
        System.out.println("Checking the results");
        if (amount.compareTo(reportPrice) != 0) {
            Assert.fail("reportPrice != amount");
        }
        System.out.println("end test 01");
    }

    @Test
    public void test_02() {
        System.out.println("start test 02");
        Integer amount = 20;
        System.out.println("set amount to " + amount);
        Integer reportPrice = 20;
        System.out.println("set reportPrice to " + reportPrice);
        System.out.println("Checking the results");
        if (amount.compareTo(reportPrice) != 0) {
            Assert.fail("reportPrice != amount");
        }
        System.out.println("end test 02");
    }

}

Ctrl+F11 и смотрим консоль Eclipse. Сколько бы раз мы не запускали тесты, мы всегда получаем следующий текст:

start test 01
set amount to 0
set reportPrice to 20
Checking the results
start test 02
set amount to 20
set reportPrice to 20
Checking the results
end test 02
PASSED: test_02
FAILED: test_01
java.lang.AssertionError: reportPrice != amount
    at org.testng.Assert.fail(Assert.java:89)
...

В целом всё хорошо: тесты запускаются, а полезная информация выдаётся.

Но получать такой объём информации полезно лишь на этапе отладки или в случае падения теста. То есть в целом неплохо бы иметь возможность логирования по различным уровням. Например есть уровень INFO, когда выдаётся информация лишь о том, что запущен тест 01 или 02. И уровень DEBUG, когда можно получить все детали прохождения тестов. Для этого можно использовать библиотеку log4j.

Шаг№2. Подключаем библиотеку log4j

Создайте User Library в Eclipse, назовите её log4j, добавьте в неё  jar из скачанного бандла log4j и подключите эту библиотеку к вашему проекту. Теперь создайте новый класс Sample_02, в который добавьте следующий код:

package info.automatedtesting;

import org.apache.log4j.Logger;
import org.testng.Assert;
import org.testng.annotations.BeforeTest;
import org.testng.annotations.Test;

public class Sample_02 {

    private Logger logger;

    @BeforeTest
    public void setUp() {
        logger = Logger.getLogger("new logger");
    }

    @Test
    public void test_01() {
        logger.info("start test 01");
        Integer amount = 0;
        logger.debug("set amount to " + amount);
        Integer reportPrice = 20;
        logger.debug("set reportPrice to " + reportPrice);
        logger.info("Checking the results");
        if (amount.compareTo(reportPrice) != 0) {
            Assert.fail("reportPrice != amount");
        }
        logger.info("end test 01");
    }

    @Test
    public void test_02() {
        logger.info("start test 02");
        Integer amount = 20;
        logger.debug("set amount to " + amount);
        Integer reportPrice = 20;
        logger.debug("set reportPrice to " + reportPrice);
        logger.info("Checking the results");
        if (amount.compareTo(reportPrice) != 0) {
            Assert.fail("reportPrice != amount");
        }
        logger.info("end test 02");
    }
}

Логика тестов не изменена. Переписано логирование. Чтобы log4j заработал, нужно дописать к нему конфигурационный файл (log4j.xml) и поместить его в каталог src нашего проекта:

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
    <appender name="console" class="org.apache.log4j.ConsoleAppender">
        <param name="Target" value="System.out" />
        <param name="Threshold" value="INFO" />
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%p %c: %m%n" />
        </layout>
    </appender>
    <root>
        <level value="INFO" />
        <appender-ref ref="console" />
    </root>
</log4j:configuration>

Нажимаем Ctrl+F11 в файле Sample_02 и смотрим консоль Eclipse:

INFO new logger: start test 01
INFO new logger: Checking the results
INFO new logger: start test 02
INFO new logger: Checking the results
INFO new logger: end test 02
PASSED: test_02
FAILED: test_01
java.lang.AssertionError: reportPrice != amount
    at org.testng.Assert.fail(Assert.java:89)
...

То есть мы получили лишь ту информацию, которая добавляется в переменную logger через метод info. Если же в файле log4j.xml поменять INFO на DEBUG, то при запуске сюиты мы получим более детальный отчёт:

INFO new logger: start test 01
DEBUG new logger: set amount to 0
DEBUG new logger: set reportPrice to 20
INFO new logger: Checking the results
INFO new logger: start test 02
DEBUG new logger: set amount to 20
DEBUG new logger: set reportPrice to 20
INFO new logger: Checking the results
INFO new logger: end test 02
PASSED: test_02
FAILED: test_01
java.lang.AssertionError: reportPrice != amount
    at org.testng.Assert.fail(Assert.java:89)

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

Тут нам поможет Шаг№3, в котором мы добавим информацию о прохождении теста уровня DEBUG в методы Assertion.

В библиотеке log4j есть абстрактный класс AppenderSkeleton, который позволяет добавить свои фишечки в процесс логирования. Наша фишечка заключается в том, что мы желаем иметь метод, который бы выдавал всю информацию, добавленную в переменную logger. Поэтому создаём новый класс, расширяющий AppenderSkeleton и называем его CustomAppender:

package info.automatedtesting;

import java.util.ArrayList;
import java.util.Iterator;
import java.util.List;

import org.apache.log4j.AppenderSkeleton;
import org.apache.log4j.spi.LoggingEvent;

public class CustomAppender extends AppenderSkeleton {

    public CustomAppender() {
        this.name = "CustomAppender";
    }

    private final List<LoggingEvent> log = new ArrayList<LoggingEvent>();

    @Override
    public void close() {
        // TODO Auto-generated method stub

    }

    @Override
    public boolean requiresLayout() {
        // TODO Auto-generated method stub
        return false;
    }

    @Override
    protected void append(LoggingEvent event) {
        log.add(event);
    }

    public List<LoggingEvent> getLog() {
        return new ArrayList<LoggingEvent>(log);
    }

    public String getLogAsString() {
        String dataOut = "--- [Detailed Test Output] ---\n";
        Iterator<LoggingEvent> it = log.iterator();
        while (it.hasNext()) {
            LoggingEvent event = it.next();
            dataOut = dataOut + event.getRenderedMessage() + "\n";
        }
        dataOut = dataOut + "--- [END] ---";
        return dataOut;
    }
}

После этого изменяем файл log4j.xml, в который добавляем наш CustomAppender:

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">
 
    <appender name="console" class="org.apache.log4j.ConsoleAppender">
        <param name="Target" value="System.out" />
        <param name="Threshold" value="INFO" />
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="%p %c: %m%n" />
        </layout>
    </appender>
    <appender name="CustomAppender" class="info.automatedtesting.CustomAppender">
        <param name="Threshold" value="DEBUG" />
    </appender>
    <root>
        <level value="DEBUG" />
        <appender-ref ref="console" />
        <appender-ref ref="CustomAppender" />
    </root>
</log4j:configuration>

Теперь у нас есть два Appender, один срабатывает на уровне DEBUG, второй на уровне INFO. То есть при прохождении тестов в консоли всегда будет присутствовать информация уровня INFO, а при падении того или иного теста, мы получим полный DEBUG нашего теста. Да, чуть не забыл, тесты придётся немного изменить, создайте новый класс Sample_03:

package info.automatedtesting;

import org.apache.log4j.Logger;
import org.testng.Assert;
import org.testng.annotations.BeforeTest;
import org.testng.annotations.Test;

public class Sample_03 {
    private Logger logger;

    @BeforeTest
    public void setUp() {
        logger = Logger.getLogger("new logger");
    }

    @Test
    public void test_01() {
        try {
            CustomAppender appender = new CustomAppender();
            logger.addAppender(appender);
            logger.info("start test 01");
            Integer amount = 0;
            logger.debug("set amount to " + amount);
            Integer reportPrice = 20;
            logger.debug("set reportPrice to " + reportPrice);
            logger.info("Checking the results");
            if (amount.compareTo(reportPrice) != 0) {
                Assert.fail("reportPrice != amount\n"
                        + appender.getLogAsString());
            }
            logger.info("end test 01");
        } finally {
            logger.removeAllAppenders();
        }
    }

    @Test
    public void test_02() {
        try {
            CustomAppender appender = new CustomAppender();
            logger.addAppender(appender);
            logger.info("start test 02");
            Integer amount = 20;
            logger.debug("set amount to " + amount);
            Integer reportPrice = 20;
            logger.debug("set reportPrice to " + reportPrice);
            logger.info("Checking the results");
            if (amount.compareTo(reportPrice) != 0) {
                Assert.fail("reportPrice != amount\n"
                        + appender.getLogAsString());
            }
            logger.info("end test 02");
        } finally {
            logger.removeAllAppenders();
        }
    }
}

Жмём Ctrl+F11, смотрим в консоль:

INFO new logger: start test 01
INFO new logger: Checking the results
INFO new logger: start test 02
INFO new logger: Checking the results
INFO new logger: end test 02
PASSED: test_02
FAILED: test_01
java.lang.AssertionError: reportPrice != amount
--- [Detailed Test Output] ---
start test 01
set amount to 0
set reportPrice to 20
Checking the results
--- [END] ---
    at org.testng.Assert.fail(Assert.java:89)
...

В целом можно было обойтись и стандартными методами log4j. Например, логи уровня INFO выводить в консоль, а DEBUG писать в файл. Но мы не ищем простых путей. :slight_smile: И именно поэтому мы переходим к следующему шагу.

Шаг№4. Запускаем тесты в параллели.

Как известно любая тестовая сиюта хороша тем, что рано или поздно она выходит из рамок IDE и запускается в режиме stand-alone. Пусть мы решили, что наши два теста тоже готовы выйти в свободное плавание. Мы написали правильный build.xml и конфигурационный файл для сюиты, запускаем тесты, радуемся жизни. Через некоторое время заглядываем в документацию по TestNG и понимаем, что используя параметры parallel и thread-count мы можем уменьшить время прохождения тестов за счёт того, что они будут работать в параллели. Поэтому делаем магические пассы руками и… та-даааам получаем следущий выхлоп в консоли:

[testng] [ThreadUtil] Starting executor timeOut:2147483647ms workers:2 threadPoolSize:7
[testng] INFO new logger: start test 02
[testng] INFO new logger: start test 01
[testng] INFO new logger: Checking the results
[testng] INFO new logger: end test 02
[testng] INFO new logger: Checking the results
[testng] PASSED: test_02
[testng]
[testng] ===============================================
[testng]     Sample_03 test 02
[testng]     Tests run: 1, Failures: 0, Skips: 0
[testng] ===============================================
[testng]
[testng] FAILED: test_01
[testng] java.lang.AssertionError: reportPrice != amount
[testng] --- [Detailed Test Output] ---
[testng] start test 02
[testng] start test 01
[testng] set amount to 20
[testng] set reportPrice to 20
[testng] set amount to 0
[testng] Checking the results
[testng] set reportPrice to 20
[testng] end test 02
[testng] Checking the results
[testng] --- [END] ---
[testng]     at org.testng.Assert.fail(Assert.java:89)
...

Результат мягко говоря обескураживает. Как с этим бороться: для каждого теста нам нужен свой logger. Поэтому мы создаём новый класс Sample_04:

package info.automatedtesting;

import info.automatedtesting.CustomAppender;
import org.apache.log4j.Logger;
import org.testng.Assert;
import org.testng.annotations.Test;

public class Sample_04 {
    private Logger logger;

    private Logger setUp(String name) {
        logger = Logger.getLogger(name);
        CustomAppender appender = new CustomAppender();
        logger.addAppender(appender);
        return logger;
    }

    @Test
    public void test_01() {
        logger = setUp("simpleTest_01");
        try {
            CustomAppender appender = (CustomAppender) logger
                    .getAppender("CustomAppender");
            logger.info("start test 01");
            Integer amount = 0;
            logger.debug("set amount to " + amount);
            Integer reportPrice = 20;
            logger.debug("set reportPrice to " + reportPrice);
            logger.info("Checking the results");
            if (amount.compareTo(reportPrice) != 0) {
                Assert.fail("reportPrice != amount\n"
                        + appender.getLogAsString());
                
            }
            logger.info("end test 01");
        } finally {
            logger.removeAllAppenders();
        }
    }

    @Test
    public void test_02() {
        logger = setUp("simpleTest_02");
        try {
            CustomAppender appender = (CustomAppender) logger
                    .getAppender("CustomAppender");
            logger.info("start test 02");
            Integer amount = 20;
            logger.debug("set amount to " + amount);
            Integer reportPrice = 20;
            logger.debug("set reportPrice to " + reportPrice);
            logger.info("Checking the results");
            if (amount.compareTo(reportPrice) != 0) {
                Assert.fail("reportPrice != amount\n"
                        + appender.getLogAsString());
            }
            logger.info("end test 02");
        } finally {
            logger.removeAllAppenders();
        }
    }
}

Перезапускаем тесты и смотрим в консоль:

[testng] [ThreadUtil] Starting executor timeOut:2147483647ms workers:2 threadPoolSize:7
[testng] INFO simpleTest_01: start test 01
[testng] INFO simpleTest_02: start test 02
[testng] INFO simpleTest_02: Checking the results
[testng] INFO simpleTest_02: end test 02
[testng] INFO simpleTest_01: Checking the results
[testng] PASSED: test_02
[testng]
[testng] ===============================================
[testng]     Sample_04 test 02
[testng]     Tests run: 1, Failures: 0, Skips: 0
[testng] ===============================================
[testng]
[testng] FAILED: test_01
[testng] java.lang.AssertionError: reportPrice != amount
[testng] --- [Detailed Test Output] ---
[testng] start test 01
[testng] set amount to 0
[testng] set reportPrice to 20
[testng] Checking the results
[testng] --- [END] ---
[testng]     at org.testng.Assert.fail(Assert.java:89)
...

Теперь понятно какая строчка лога к какому тесту принадлежит и при падении мы получаем информацию по прохождению конкретного теста. Поставленные задачи выполнены. :slight_smile:

Пишите, отвечу на все вопросы.

1 лайк
#2

@polusok походу что-то не так с syntaxhighlighter

#3

Тема создавалась в 2012 году. Сейчас уже другой синтаксис подсветки кода. Так что многие старые топики нужно будет редактировать по надобности.

#4

форматирование поправил