Избавляемся от Flaky тестов в CI/CD при помощи JMina

Представьте: вы написали код, покрыли его тестами, запустили их локально — тесты успешно прошли. Вы загрузили изменения в репозиторий, пайплайн успешно завершился. Самое время расслабиться и приступить к новым задачам. Но не тут-то было!

Спустя некоторое время в CI/CD падает тест. Вы запускаете тесты локально — они проходят успешно. Вы снова запускаете пайплайн в CI/CD — и тесты снова проходят. Однако через какое-то время ситуация повторяется.

Знакомая картина? Значит, вы уже сталкивались с flaky-тестами.

Flaky-тесты — это тесты, которые могут как успешно пройти, так и упасть без каких-либо изменений в коде.

По работе я довольно часто сталкиваюсь с flaky-тестами. Иногда удаётся поймать падение при локальном прогоне тестов. Иногда причина становится ясной по полученной ошибке. Иногда мы можем проанализировать логи и найти источник проблемы.

Но бывает, что тесты падают только в CI/CD: ошибка ничего не объясняет, а логи превышают лимиты и не сохраняются полностью. Такая ситуация особенно часто возникает при написании интеграционных тестов для сложных многошаговых процессов, работающих с большим объёмом данных.

«Ах, если бы можно было вставить assert прямо в код, чтобы ловить ошибки там, где они возникают», — подумал я. В принципе, мы иногда действительно добавляем проверки (assertions) в сам код — например, для проверки параметров методов на null.

Но, конечно, мы не знаем заранее, какое конкретное значение должна иметь переменная в конкретный момент времени. Кроме того, добавление множества assertions сделало бы код практически нечитаемым.

Тогда мне пришла в голову идея: а что если сделать небольшую утилиту, которая позволяла бы вставлять в код лямбду из теста? Как-бы, заминировать код. Это могло бы выглядеть примерно так:

В коде:

inlineAssert("step1", i, status);

В тесте:

on("step1").check((int i, Status status) -> { // проверки }); myClass.myMethod();

Конечно, для этого придётся добавить в код несколько дополнительных строк, которые сами по себе никак не будут влиять на выполнение программы — они нужны будут только для тестов. Но ничего страшного: мы ведь уже добавляем в код логи!

Минуточку…

Для логирования мы используем SLF4J, который сам по себе ничего не логирует, а делегирует вызовы методов, например, в Logback. Точно так же он может делегировать вызовы любому другому провайдеру — например, нашей утилите, в которой мы сможем выполнять необходимые проверки.

Это примерно аналогично тому, как если бы мы использовали Mockito, чтобы создать Spy для логгера.

Так у меня и родилась идея утилиты JMina.

Возможности JMina:

• Перехватывать вызовы методов логирования SLF4J по имени логгера, уровню логирования, маркеру и сообщению — в любых комбинациях.

• Проверять передаваемые параметры на равенство заданным значениям.

• Использовать лямбду для проверки параметров.

• Вызывать исключения при выполнении определённых логов.

• Проверять, что все ожидаемые логи были вызваны.

Рассмотрим, как это работает на простейшем примере — вычислении корней квадратного уравнения.

Алгоритм состоит из двух шагов: сначала вычисляется дискриминант, затем, на основе дискриминанта, находятся сами корни. Ошибка может произойти на любом из этих шагов. Чтобы понять, на каком именно этапе возникла проблема, добавим в код логирование значения дискриминанта.

public class QuadraticEquation {     private final Logger log = LoggerFactory.getLogger(QuadraticEquation.class);      public List<Double> solve(double a, double b, double c) {         double discriminant = b * b - 4 * a * c;          log.debug("discriminant: {}", discriminant);    // Log the discriminant value to verify it during test execution          if (discriminant < 0) {             return Collections.emptyList();         } else {             List<Double> roots = new ArrayList<>();              if (discriminant > 0) {                 roots.add((-b - sqrt(discriminant)) / (2 * a));                 roots.add((-b + sqrt(discriminant)) / (2 * a));             } else {                 roots.add(-b / (2 * a));             }              return roots;         }     } } 

А в тесте добавим проверку его значения.

public class QuadraticEquationTest {     @Test     public void testSolve() {         // Verify discriminant value inside the solve method         Mina                 .on(QuadraticEquation.class, DEBUG, "discriminant: {}")                 .check((Double discriminant) -> assertEquals(9, discriminant));          // Run our code         List<Double> roots = new QuadraticEquation().solve(1, -1, -2);          // Verify that all logs were called         Mina.assertAllCalled();          // Verify roots         assertEquals(-1, roots.get(0));         assertEquals(2, roots.get(1));     }      @AfterEach     public void clean() {         // Don't forget to clean-up context after each test         Mina.clean();     } } 

Теперь, если на этапе вычисления дискриминанта будет получено неправильное значение, тест упадёт с ошибкой. Причём stack trace укажет именно на то место в коде, где произошла ошибка. Таким образом мы сможем быстро найти проблему и исправить её.

На что ещё способна JMina?

Если мы тестируем успешный сценарий (success path), то, скорее всего, не ожидаем появления сообщений об ошибках. И если такое сообщение будет залогировано, мы можем сразу остановить выполнение теста и выбросить исключение.

Mina.on(ERROR).exception();

Flaky-тесты могут отнимать массу времени и сил, особенно когда ошибки проявляются только в CI/CD, а логи оказываются неполными или бесполезными. Чтобы упростить отладку и повысить надёжность тестов, я разработал утилиту JMina — лёгкое, но мощное решение для перехвата и проверки логов прямо в процессе выполнения кода.

С помощью JMina можно оперативно находить ошибки там, где они возникают, проверять ключевые этапы работы системы и мгновенно останавливать тесты при появлении неожиданных проблем. Эта утилита уже помогает мне делать тестирование стабильнее и эффективнее — надеюсь, она будет полезна и вам.

P.S. Наиболее частые причины flaky-тестов (по моему опыту):

• Влияние других тестов в Pipeline.
  Некоторые тесты могут переопределять Bean’ы с помощью Mock’ов, менять настройки или оставлять грязные данные. И далеко не все тесты корректно очищают изменения после себя.

• Scheduled tasks.
  Задачи, запускаемые по расписанию, могут начать выполняться во время прохождения тестов и повлиять на результат. Рекомендую отключать планировщики в тестовой среде.

• Неправильная работа со временем.
  Некоторые тесты могут проходить или падать в зависимости от текущего времени. Чаще всего проблемы возникают около полуночи, в первый и последний день месяца или года.

• Race condition.
  Неприятная проблема: иногда крайне сложно понять, что именно произошло. Но лучше, чтобы у вас падали тесты, а не продакшн.

• Отсутствие сортировки там, где она требуется. При работе с небольшими таблицами в базе данных строки часто возвращаются в порядке вставки или в порядке материального индекса. Но если явная сортировка не указана в запросе, СУБД не гарантирует порядок строк.