Что такое flaky тесты
Нестабильные(Flaky) тесты — одна из основных проблем автоматизированного тестирования
Умение разбираться с нестабильными тестами критически важно в тестировании, потому что автотесты с плавающими результатами замедляют скорость всей разработки.
Если вы не сталкивались с нестабильными тестами, обязательно прочтите эту статью, поскольку в ней делается попытка систематизировать причины возникновения нестабильности в тестах. Если вы сталкивались с нестабильными тестами, посмотрите сколько из них попадает в перечисленные области.
Данная статья призвана рассказать как бороться с каждой из причин.
За прошедшие годы я не раз сталкивался с нестабильными тестами, но вместо того чтобы рассматривать конкретные случаи, давайте попробуем сгруппировать причины возникновения нестабильности по задействованным при выполнении автотестов компонентам:
Фреймворк для запуска тестов;
Сервисы и библиотеки, от которых зависит тестируемая система и тестовый фреймворк;
Операционная система и устройство с которым взаимодействует фреймворк автотестирования.
Однако в распределенной системе каждая служба приложения и службы, от которых она зависит, могут находиться в другом аппаратном / программном стеке, как и служба, выполняющая тест. Это проиллюстрировано на рисунке 2 как полная среда выполнения теста
Как обсуждалось выше, каждый из этих компонентов является потенциальной областью нестабильных тестов
Сами тесты
Сами тесты могут вызвать нестабильность. Типичные причины:
Неправильная инциализация или очистка;
Неправильно подобранные тестовые данные;
Неправильное предположение о состоянии системы. Примером может служить системное время;
Зависимость от асинхроных действий;
Зависимость от порядка запуска тестов.
Фреймворк для запуска тестов
Ненадежный фреймворк для запуска тестов может привести к нестабильности. Типичные причины:
Неспособность выделить достаточно ресурсов для тестируемой системы, что приводит к ее сбою;
Неправильное планирование тестов, поэтому они «противоречат» и приводят к сбою друг друга;
Недостаточно системных ресурсов для выполнения требований тестирования.
Сервисы и библиотеки, от которых зависит тестируемая система и тестовый фреймворк
Приложение (или тестируемая система) может быть источником нестабильности
Приложение также может иметь множество зависимостей от других служб, и каждая из этих служб может иметь свои собственные зависимости.
В этой цепочки каждый сервис может послужить причиной возникновения нестабильных тестов.
Медленный ответ или отсутствие ответа при запросе от теста;
Избыточная подписка на ресурсы;
Изменения в приложении и в тестах происходят с разной скоростью.
Среды тестирования называются герметичными, если они содержат всё, что необходимо для запуска тестов (т.е. нет внешних зависимостей, таких как серверы, работающие в прод окружении).
Герметичная среда менее подвержена нестабильности.
Операционная система и устройство с которым взаимодействует фреймворк автотестирования
Наконец, оборудование и операционная система могут быть источником нестабильности тестов. Типичные причины включают:
Сбои или нестабильность сети;
Ресурсы, потребляемые другими задачами / службами, не связанными с выполняемыми тестами.
Как видно из большого разнообразия сбоев, снижение нестабильности при автоматизированном тестировании может быть довольно сложной задачей. В этой статье описаны области и типы нестабильности, которые могут возникать в этих областях, поэтому она может служить шпаргалкой при локализации причины нестабильных тестов.
В следующих статьях мы рассмотрим способы решения этих проблем.
Ссылки на источники
Нестабильные тесты в Google и как мы их исправляем (оригинал)
Мои тесты на Selenium не стабильны! (оригинал)
Как бороться с flaky тестами в opensource-сообществе
С проблемой flaky-тестов сталкиваются многие проекты, и тема эта уже не раз поднималась на Хабре. Тесты, не определившиеся со своим состоянием, постоянно отнимают не только машинное время, но и время разработчиков и тестировщиков. И если в коммерческой компании можно выделить некий ресурс для решения этой проблемы и назначить ответственных лиц, то в opensource-сообществе все не так просто. Особенно когда речь идет о крупных проектах — например, таких как Apache Ignite, где насчитывается почти 60 тысяч различных тестов.
В этом посте мы, собственно, и расскажем, как решали эту проблему в Apache Ignite. Мы — это Дмитрий Павлов, lead software engineer/community manager в GridGain, и Николай Кулагин, IT-инженер Сбербанк-Технологий.
Все написанное ниже не представляет позицию какой-либо компании, в том числе Сбербанка. Это рассказ исключительно от участников сообщества Apache Ignite.
Apache Ignite и тесты
История Apache Ignite начинается в 2014 году, когда компанией GridGain была пожертвована в Apache Software Foundation первая версия внутреннего продукта. С того момента прошло уже более 4 лет, и за это время количество тестов приблизилось к отметке в 60 тысяч.
В качестве сервера непрерывной интеграции мы используем JetBrains TeamCity — спасибо ребятам из JetBrains за то, что поддерживают opensource-движение. Все наши тесты распределены по сьютам, количество которых для ветки master приблизилось к 140. В сьютах тесты сгруппированы по какому-либо признаку. Это может быть тестирования только функциональности Machine Learning [RunMl], только кэша [RunCache], или всего [RunAll]. В дальнейшем под прогоном тестов будет подразумеваться именно [RunAll] – полная проверка. Она занимает примерно 55 часов машинного времени.
В качестве основной библиотеки используется Junit, но модульных тестов встречается мало. По большей части все наши тесты интеграционные, так как содержат запуск одной и более нод (а это занимает несколько секунд). Конечно, интеграционные тесты удобны тем, что один такой тест покрывает множество аспектов и взаимодействий, чего довольно сложно добиться одним модульным тестом. Но есть и недостатки: в нашем случае это довольно долгое время выполнения, а также сложность поиска возникшей проблемы.
Проблемы с flaky
В части этих тестов возникают сложности с flaky. Сейчас по классификации TeamCity примерно 1700 тестов отмечены как flaky — то есть с изменением состояния без изменения кода или конфигурации. Такие тесты нельзя игнорировать, так как есть риск получение бага в продакшене. Поэтому их приходится перепроверять и перезапускать, иногда несколько раз, анализировать результаты падений – и на это тратится драгоценное время и силы. И если уже существующие участники сообщества справляются с этой задачей, то для новых контрибьюторов это может стать настоящим барьером. Согласитесь, что, делая правку Java Doc, никак не ожидаешь столкнуться с падением, да не с одним, а с несколькими десятками.
Кто виноват?
Половина проблем с flaky-тестами возникает из-за конфигурации оборудования, из-за размеров инсталляции. А вторая половина напрямую связана с людьми, пропустившими и не исправившими свой баг.
Условно всех членов сообщества можно разделить на две группы:
Кто будет фиксить?
Если мы говорим о людях, покинувших сообщество, то их баги, естественно, достаются текущим контрибьюторам. Стоит заметить, что за правку, которая привела к багу, также несет ответственность и ревьюер, но и он может оказаться энтузиастом — то есть будет доступен далеко не всегда.
Бывает, что получается достучаться до человека, сообщить ему: вот здесь проблема. Но он говорит: нет, это не мой фикс внес баг. Так как полный прогон ветки master автоматически выполняется при относительно свободной очереди, то чаще всего это происходит ночью. Перед этим за весь день в ветку может быть влито несколько коммитов.
В TeamCity любая модификация кода расценивается как чейндж. Если после трех чейнджей у нас случается новое падение, то три человека будут говорить, что это связано не с их коммитом. Если пять чейнджей — то мы услышим это от пяти человек.
Другая проблема: донести до контрибьютора, что тесты необходимо запускать перед каждым ревью. Некоторые не знают, где, что и как запускать. Или тесты были запущены, но контрибьютор не написал об этом в тикете. На этом этапе тоже возникают проблемы.
Идем дальше. Представим, что тесты прогнаны, и в тикете есть ссылка на результаты. Но, как оказалось, это не дает никаких гарантий анализа прогнанных тестов. Контрибьютор может посмотреть на свой прогон, увидеть там какие-то падения, но написать «TeamCity Looks Good». Ревьюер — особенно если он знаком с контрибьютором или успешно ревьюил его раньше — может толком и не посмотреть результат. И мы получим вот такой «TeamCity Looks Good»:
Где здесь «Good» — непонятно. Но судя по всему, авторы хотя бы знают, что тесты нужно запускать.
Как мы с этим боролись
Метод 1. Разделение тестов
Мы разделили тесты на две группы. В первой, «чистой» — стабильные тесты. Во второй — нестабильные. Подход достаточно очевидный, но он не оправдался даже с двух попыток. Почему? Потому что сьют с нестабильными тестами превращается в такое гетто, где что-то начинает обязательно тайм-аутить, крэшится и т.д. В итоге все начинают просто игнорировать эти вечно проблемные тесты. В общем, никакого смысла делить тесты по сортам.
Метод 2. Разделение и нотификация
Второй вариант похож на первый — выделить более стабильные тесты, а остальные тесты по PR прогонять ночью. Если в стабильной группе что-то ломается, то контрибьютору стандартными средствами TeamCity отправляется сообщение о том, что нужно что-то пофиксить.
На эти сообщения отреагировало… 0 человек. Все их проигнорировали.
Метод 3. Ежедневный мониторинг
Мы поделили сьюты на несколько «наблюдателей», самых ответственных членов сообщества и подписали их на оповещения о падениях. В результате на практике подтвердили, что энтузиазм имеет свойство заканчиваться. Контрибьюторы бросают эту затею и перестают регулярно проверять. Тут пропустил, там просмотрел — и вот опять что-то пролезло в master.
Метод 4. Автоматизация
После очередного неудачного метода ребята из GridGain вспомнили о ранее разработанной утилите, добавляющей отсутствующий на тот момент функционал на TeamCity. А именно возможность просмотра общей статистики по количеству падений: сколько и чего упало, ухудшился или улучшился результат на следующий день. Эту утилиту начали постепенно развивать, добавили репорты, переименовали. Потом добавили нотификации, снова переименовали. Так получился TeamСity Bot. Сейчас в нем почти 500 коммитов и 7 контрибьюторов и он есть в supplementary репозитории Apache.
Что делает бот? Его возможности можно объединить в две группы:
Схема работы TeamСity Bot
До появления Apache Ignite Teamcity Bot процесс «внесения вклада» в сообщество выглядел следующим образом:
Выглядит просто, но на деле третий пункт может стать барьером для некоторых контрибьюторов. Например: новичок в коммьюнити решает внести свой первый вклад, выбирая максимально простой тикет. Это может быть правка Java Doc или обновление версий зависимостей maven. Анализируя результаты прогона по своему небольшому фиксу, он вдруг обнаруживает, что упало около 30 тестов. Откуда такое количество не пройденных тестов и как их анализировать — он не знает. Вполне ожидаемым последствием может стать то, что контрибьютор больше никогда сюда не вернется.
Более опытные участники коммьюнити также страдают от flaky — тратят время на анализ тестов, упавших по воле случая, и тем самым тормозят разработку продукта.
Схема контрибьюшна с TeamCity Bot
С появлением бота шагов в контрибьюшне прибавилось, но время, потраченное на анализ упавших тестов, существенно сократилось. Теперь достаточно запустить проверку и после ее прохождения заглянуть на соответствующую страницу бота. При наличии возможных блокеров (упавших тестов, не считающихся flaky) достаточно запустить перепроверку, по итогу которой получить визу в виде комментария в JIRA с результатами тестирования.
Обзор возможностей
Inspect Contribution – список всех незакрытых PR с выводом краткой информации по каждому: дата последнего обновления, номер PR, название, автор и тикет в JIRA.
Для каждого pull request’a доступна вкладка с более подробной информацией: правильное название PR, без которого бот не сможет найти нужный тикет в JIRA; были ли запущены тесты; готов ли результат проверки; оставлен ли комментарий в JIRA.
Анализ результатов тестирования:
Перед вами два отчета по тестированию одного и того же PR. Первый — от бота. Второй — стандартный отчет на Teamcity. Разница в объеме информации очевидна, и это без учета того, что для просмотра истории прогонов теста на TC необходимо будет также сделать несколько переходов на смежные страницы.
Вернемся к отчету бота. Этот отчет визуально разделен на две таблицы: возможные блокеры и все падения. К блокерам относятся тесты, которые:
Чтобы окончательно разобраться, что же является flaky тестом, а что багом, рассмотрим картинку выше. Горизонтальная полоса — это 100 прогонов. Вертикальная зеленая полоса — успешное прохождение теста, красная — падение. В случае бага история прогона выглядит естественно: однотонная зеленая полоса под конец меняет цвет на красный. Это означает, что именно в этом месте появился баг и тест стал постоянно падать. Если же перед нами flaky-тест, то его история прогонов — это сплошное чередование зеленого и красного цветов.
Анализ результатов тестирования
Для примера проанализируем результаты прохождения тестов на скриншоте выше. По версии бота падений из-за бага может быть два — они указаны в таблице Possible Blockers. Но это вполне могут быть flaky-тесты с низким fail rate’ом. Чтобы исключить этот вариант, достаточно нажать кнопку Re-run possible blockers, и эти две сьюты уйдут на перепроверку. Чтобы еще больше облегчить задачу, можно нажать Re-run possible blockers & comment JIRA, и получить комментарий (а с ним и уведомление на почту) от бота после окончания проверки. Потом зайти и посмотреть, есть ли проблема или нет.
Для ревьюеров это очень здорово. Можно забыть о правках, которые не прошли какие-то проверки, а просто покликать по ряду правок, нажать большую зеленую кнопку Re-run и ждать письма.
Идеальный отчет: блокеры не обнаружены
Зеленая виза (комментарий) бота. Блокеров не обнаружено.
Красная виза — требуется перепроверка и/или правка багов
Бывает, что в «мастер» все-таки просачиваются некоторые баги. Как мы уже сказали, раньше с этим боролись через личные нотификации. Или какой-то человек следил за тем, чтобы ничего не упало. Сейчас мы используем более простое решение:
При обнаружении нового бага на dev-лист отправляется сообщение, в котором указаны контрибьюторы и их чейнджи, которые могут быть причиной ошибки. Так все сообщество узнает, из-за кого все произошло.
Таким образом нам удалось увеличить количество хот-фиксов и сильно сократить время, которое тратится на устранение проблемы.
Мониторинг состояния мастера
Еще одна из функций бота — мониторинг состояния мастера с выводом статистики по последним запускам.
На странице Master trends сравнивается две выборки «мастера» за определенные промежутки времени. По каждому пункту в таблице выводится максимальное, минимальное значение и медиана.
Кроме общих результатов по всей выборке, в таблице присутствуют графики для каждого показателя с отображением значений каждого билда. Кликнув по точке, можно перейти к результатам прогона на TeamCity. Кроме того, есть возможно удалить результат из статистики. Это полезно, когда возникают совсем аномальные значения, из-за серьезных поломок, в которых наверняка виноват не контрибьютор. Такие результаты стоит исключать, чтобы они не учитывались при расчете тех же flaky-тестов. Кроме того, билд также можно выделить, чтобы проследить за результатами по каждому показателю.
В Apache Ignite Teamcity Bot сейчас зарегистрировано более 65 человек. За все время использования бота визы получили более 400 pull request’ов, а в среднем выдается пять виз в день.
Структура TeamCity Bot
Бот размещен на отдельном сервере, ходит на ignite.apache.org за данными, публично оповещает всех на dev-листе — это наша основная площадка для разработчиков Ignite — и пишет визы в тикеты через JIRA API.
Используется сервер Jetty, Jersey сервлеты, ряд сервисов со сложной бизнес логикой самого бота, в том числе сервисы Teamcity, JIRA и GitHub, обращающиеся в Ignited Integration сервис. Поверх этого Pure Integration для http-запросов. В качестве хранилища — собственный продукт Apache Ignite в конфигурации Single Node embedded-режим с активным persistence. Помимо очевидных плюсов использования Ignite в качестве БД, это также помогает нам найти различные сферы применения Ignite и понять, что удобно, а что нет.
Первый вариант реализации бота был вдохновлен одной статьей о REST-кэшировании и представлял собой REST-кэш и сервисы GitHub и Teamcity. Возвращаемые с сервера Teamcity xml и json разбирались в Pure Java Objects, которые затем складывались в кэш. Поначалу это работало, причем довольно быстро. Но с увеличением количества данных результаты стали ухудшаться.
Тут стоит заметить, что TeamCity удаляет историю старше
2 недель, а бот — нет. В конечном итоге при таком подходе появлялись тонны данных, которыми очень сложно управлять.
Развитие TeamCity Bot
В новом подходе реализован вариант компактного хранения данных и сделан выбор в пользу малого количество партиций кэша. Большое количество партиций на одной ноде негативно сказывается на скорости синхронизации данных на диск и увеличивает время старта кластера.
Все основные обновления данных выполняются асинхронно, так как в противном случае мы рискуем получить плохой UX из-за медленной отдачи данных TeamCity.
Для строк, редко меняющих свои значения (например, названия тестов) сделан простой маппинг в id, который генерируется Atomic Sequence’ом. Вот пример такой Entry:
Длинному имени теста соответствует int-овое число, которое хранится во всех билдах. Это экономит огромное количество ресурсов. Поверх методов, которые возвращают эту строчку, стоит Guava in-memory cache interceptor. Благодаря аннотации cache, мы даже в heap’е не выделяем строчки, прочитав их из Ignite по id. И по id мы всегда получаем одну и ту же строку, что хорошо для производительности.
Для «непредсказуемых» строк, например, stack trace лога, используются различные виды сжатия — gzip-компрессия, snappy-компрессия или uncompressed, в зависимости от того, что окажется лучше. Все эти способы помогают уместить максимум данных в in-memory и быстро отдавать ответ клиенту.
Почему с TeamCity Bot лучше
Нельзя сказать, что в TeamСity нет перечисленных выше возможностей. Они есть, но разбросаны по куче разных мест. В боте же все собрано на одной странице и можно быстро понять, в чем проблема.
Приятное дополнение — это письмо, которое бот отправляет на dev-листе при обнаружении проблемы. Сразу же в комьюнити появляется повод начать дискуссию: «Давайте, может, сейчас ревертнем?». Это добавляет уверенности ревьюерам.
С ботом новым контрибьюторам намного проще влиться в процесс разработки. Делая свой первый фикс, не всегда знаешь, что могут за собой повлечь внесенные изменения. И ныряя с головой в анализ результатов тестирования на TeamCity, можно запросто потерять энтузиазм к дальнейшей разработке. Apache Ignite TeamCity Bot же поможет быстро понять, есть ли проблема, и сохранить энтузиазм.
Надеемся, что бот упростит жизнь текущим контрибьюторам и привлечет новых людей в коммьюнити. Напоследок советуем, конечно, не допускать появления огромного количество flaky-тестов, потому что с ними сложно бороться. И доверяйте роботам — у них нет предпочтений и они не верят людям на слово.
Flaky tests
Что неприятнее «красного теста»? Тест, который то зелёный, то красный, и непонятно, почему. На нашей конференции Heisenbug 2017 Moscow Андрей Солнцев (Codeborne) рассказывал, из-за чего они могут возникать и как снижать их число. Примеры в его докладе такие, что прямо-таки кожей ощущаешь боль, возникавшую при столкновении с ними. А советы полезные — причём ознакомиться с ними стоит как тестировщикам, так и разработчикам. Есть и неожиданное: можно узнать, как порой можно разобраться в проблеме, если оторваться от экрана и поиграть с дочкой в кубики.
В итоге зрители высоко оценили доклад, и мы решили не просто опубликовать видеозапись, а ещё и сделать для Хабра текстовую версию доклада.
На мой взгляд, flaky-тесты — это самая актуальная тема в мире автоматизации. Потому что на вопрос «что вообще в мире делается, как у вас дела с автоматизацией?» все отвечают: «Стабильности нет! Падают наши тесты периодически».
Ты запустил у себя тест, он зелёный, ещё два дня зелёный, а потом раз и внезапно упал на Jenkins. Ты пытаешься это повторить, запускаешь, а он снова зелёный. И в итоге никогда не знаешь: это баг или это просто тест глюканул? И каждый раз надо разбираться.
Зачастую после ночного запуска тестов на Jenkins тестировщик сначала видит «30 тестов упало, надо изучить», но все знают, что происходит дальше…
Вы, конечно, догадались, какое неприличное слово замаскировано: «перезапущу». Мол, «сегодня неохота разбираться…» Вот так это обычно происходит, и это прямо беда.
Точной статистики нет, но я часто слышал от разных людей, что у них примерно 30% тестов — flaky. Грубо говоря, запускают тысячу, из них 300 периодически красные, и дальше руками проверяют, а на самом ли деле они упали.
Google пару лет выпустил статью: там сообщается, что у них 1,5% процента flaky-тестов, и рассказано, как они бьются за снижение их числа. Я могу чуть похвастаться и сказать, что в моём проекте в Codeborne сейчас 0,1%. Но на самом деле всё это плохо, даже 0,1%. Почему?
Возьмём 1,5%, это число кажется маленьким, но что оно значит на практике? Допустим, в проекте тысяча тестов. Это может значить, что в одном билде упало 15 тестов, в следующем 12, затем 18. И это ужасно плохо, потому что в этом случае почти все билды красные, и постоянно нужно проверять руками, правда это или нет.
И даже наш один промилле (0,1%) — всё равно плохо. Допустим, у нас 1000 тестов, тогда 0,1% означает, что регулярно один билд из десяти валится с 1-2 красными тестами. Вот реальная картина с нашего Jenkins, так и получается: при одном запуске упал один flaky-тест, при другом запуске другой.
Получается, ни дня без красного билда у нас не проходит. Так как много зелёного, вроде бы всё хорошо, но клиент вправе спросить нас: «Ребята, мы вам платим деньги, а вы нам постоянно красноту поставляете! Что за дела?»
Я бы на месте клиента был недоволен, и объяснять «вообще-то по отрасли это нормально, у всех всё красное» нехорошо, да? Поэтому, на мой взгляд, это очень актуальная проблема, и давайте вместе разбираться, как же с ней бороться.
Пример 1: классика
Для затравки — классический Selenium-скрипт:
Правильно, мы все хорошо знаем, что любая! Может сломаться абсолютно любая строчка, по совершенно разным причинам:
Первая строчка — медленный интернет, сервис упал, админы что-то не настроили.
Вторая строчка — элемент еще не успел отрисоваться, если он динамически отрисовывается.
Что может сломаться в третьей строчке? Тут для меня было неожиданно: я написал это тест для конференции, запустил локально, и он именно на третьей строчке свалился с вот такой ошибкой:
Это говорит, что элемент в этой точке некликабельный. Казалось бы, простая элементарная Google-форма. Секрет оказался в том, что во второй строке мы вбили слово, и пока мы его вводили, Google уже нашёл первые результаты, показал несколько первых результатов в таком поп-апчике, и они закрыли следующую кнопку. И это происходит не во всех браузерах и не всегда. У меня с этим скриптом такое происходило примерно один раз из пяти.
Четвёртая же строчка может упасть, например, потому что этот элемент отрисовывается динамически и еще не успел отрисоваться.
На этом примере хочу сказать, что, по моему опыту, 90% flaky-тестов имеют в основе одни и те же причины:
Вот этот тест проходит всегда. За счёт того, что методы setValue(), click() и shouldHave() — умные: если что-то не успело подрисоваться, они чуть-чуть ждут и пробуют ещё (это называется «умные ожидания»).
Если посмотреть чуть подробнее, то все эти should*-методы умные:
Пример 2: nbob
Итак, 90% проблем с flaky-тестами решаются с помощью Selenide. Но остаются 10% гораздо более изощрённых случаев со сложными запутанными причинами. Вот именно о них я и хочу сегодня поговорить, потому что это такая «серая область». Приведу один из примеров: flaky-тест, на который я сразу же наткнулся в новом проекте. На первый взгляд, этого просто не может случиться, вот это-то и интересно.
Тестировали приложение-клавиатуру для логина в киосках. Тест хотел залогиниться как юзер «bob», то есть в поле «логин» ввести три буквы: b-o-b. Для этого использовались кнопки на экране. Как правило, это срабатывало, но иногда тест падал, и в поле «логин» оставалось значение «nbob»:
Естественно, ломишься искать по коду, где у нас могло быть написано «nbob» — но в целом проекте этого вообще нет (ни в базе данных, ни в коде, ни даже в Excel-файлах). Как это возможно?
Смотрим подробнее код — казалось бы, всё просто, никаких загадок:
Так получилось, что буква N находилась посередине экрана, а функция click() как минимум в Chrome работает так: высчитывает центральную координату элемента и кликает в неё. Поскольку body — это большой элемент, она кликала в центр всего экрана.
И это падало не всегда. Кто знает, почему? На самом деле, я сам не до конца знаю. Возможно, из-за того, что окно браузера всё время открывалось разного размера, и это не всегда попадало в букву N.
В итоге расширяем список причин нестабильных тестов:
Пример 3: фантомные счета
Пример интересен тем, что тут совпало сразу всё, что только может совпасть.
Был тест, который проверял, что на этом экране должно быть 5 счетов.
Он, как правило, был зелёный, но иногда при непонятно каких условиях падал и говорил, что на экране не пять, а шесть счетов.
Я стал исследовать, откуда берётся лишний счёт. Абсолютно непонятно. Возник вопрос: может быть, у нас есть другой тест, который в ходе теста создает новый счёт? Оказалось, что да, есть такой LoansTest. А между ним и падающим AccountsTest (который ожидает пять счетов) может оказываться миллион каких-то других тестов.
Пытаемся понять, как же так: разве LoansTest, который создаёт счёт, не должен его удалять в конце? Смотрим его код — да, должен, в конце для этого есть функция After. Тогда, по идее, всё должно быть хорошо, в чём же проблема?
Может, тест его удаляет, но он остаётся где-то закэшированным? Смотрим продакшн-код, который грузит счета — в нём действительно есть аннотация @CacheFor, он кэширует счета на пять минут.
Возникает вопрос: но разве тест не должен был очистить этот кэш? Было бы логично, не может же быть такой косяк? Смотрим его код — да, он действительно очищает кэш перед каждым тестом. Что за дела? Тут уже теряешься, потому что гипотезы закончились: объект удаляется, кэш очищается, ёлки-палки, что же ещё может быть проблемой? Дальше стал уже просто лазать по коду, это заняло некоторое время, возможно, даже несколько дней. Пока я наконец не посмотрел в этот класс и суперкласс, и не нашёл там одну подозрительную вещь:
Кто-то уже заметил, да? Совершенно верно: и в дочернем, и в родительском классе есть метод с одним и тем же названием, и он не вызывает super.
И в Java это очень легко сделать: нажимаешь в IntelliJ IDEA или Eclipse сочетание Alt+Enter или Ctrl+Insert, он по умолчанию создаёт тебе метод setUp(), и не замечаешь, что он оверрайдит метод в суперклассе. То есть кэш все-таки не вызывался. Когда я увидел это, я был дико зол. Это сейчас мне радостно.
Давайте подытожим ещё раз: как это получилось, почему тест падал не всегда? Во-первых, он зависел от порядка этих двух тестов, они же всегда запускаются в случайном порядке. Ещё тест зависел от того, сколько времени прошло между ними. Счета кэшируются пять минут, если проходило больше, то тест был зелёный, а если меньше — падал, и такое случалось редко.
Расширяем список того, почему тесты могут быть нестабильны:
Пример 4: Время Java
Был тест, который работал на всех наших компьютерах и на нашем Jenkins, но иногда падал на Jenkins заказчика. Смотрим в тест, разбираемся, почему. Оказывается, падал, потому что при проверке «дата платежа должна быть сейчас или в прошлом» она оказывалась «в будущем».
Смотрим в код, вдруг при каких-то условиях мы можем поставить дату в будущем? Не можем: в единственном месте, где инициализируется время платежа, используется new Date(), а это всегда текущее время (в крайнем случае оно может оказаться в прошлом, если вдруг тест был очень медленным). Как такое вообще возможно? Долго бились головой, не могли понять.
А однажды заглянули в лог приложения. Отсюда первая мораль — очень полезно при исследовании тестов заглядывать в лог самого приложения. Поднимите руки, кто это делает. В общем, не большинство, увы. А там есть полезная информация: к примеру, request log, такой-то URL в такое время выполнился, выдал такой-то ответ.
Здесь есть кое-что подозрительное, заметили? Смотрим время: этот запрос обрабатывался минус три секунды. Как такое может быть? Долго бились, не могли понять. Наконец, когда у нас кончились теории, сделали тупое решение: в Jenkins написали простенький скрипт, который в цикле раз в секунду логирует текущее время. Запустили его. На следующий день, когда этот flaky-тест один раз ночью упал, стали смотреть выдержку из этого файла за то время, когда он упал:
Итак: 34 секунды, 35, 36, 37, 35, 39… Круто, что мы это нашли, но как это вообще возможно? Снова теории закончились, ещё два дня чесали голову. Это реально тот случай, когда Матрица шутит над тобой, да?
Пока наконец не стукнула в голову одна идея… И вот, что оказалось. В Linux есть сервис для синхронизации времени, который бегает на центральный сервер и спрашивает «а столько сейчас милисекунд?» И оказывается, на этом конкретном Jenkins было запущено два разных сервиса. Тест начал падать, когда на этом сервере обновили Ubuntu.
Там раньше был сконфигурирован ntp-сервис, который обращался на специальный банковский сервер и брал время оттуда. А с новой версией Ubuntu по умолчанию включался новый легковесный сервис, к примеру, systemd-timesyncd. И работали оба. Никто этого не заметил. Почему-то центральный банковский сервер и какой-то центральный Ubuntu-сервер выдавали ответ с разницей в 3 секунды. Естественно, эти два сервиса друг другу мешали. Где-то глубоко в документации Ubuntu сказано, что, конечно, не допускайте такой ситуации… Ну, спасибо за информацию 🙂
Кстати, заодно я узнал один интересный нюанс Java, который до этого, несмотря на мой многолетний опыт, не знал. Один из самых базовых методов в Java называется System.currentTimeMillis(), с помощью него обычно засекают время вызова чего-то, многие писали такой код:
На самом деле, в документации методов это написано, я же просто никогда не читал её. Я всю жизнь думал, что System.currentTimeMillis() и System.nanoTime() — одно и то же, только с разницей в миллион раз. А оказалось, что это принципиально разные вещи.
System.currentTimeMillis() возвращает реально текущую дату — сколько сейчас миллисекунд прошло с 1 января 1970-го. А System.nanoTime() — некий абстрактный счётчик, который не привязан к реальному времени: да, он гарантированно растёт каждую наносекунду на единичку, но он не связан с текущим временем, он может быть даже отрицательным. При старте JVM как-то случайным образом выбирается момент времени, и он начинает расти. Это для меня был сюрприз. Для вас тоже? Вот, не зря приехал.
Пример 5: Проклятие зелёной кнопки
Тут у нас тест заполняет некую форму, нажимает зелёную кнопку Confirm, и иногда не идёт дальше. Почему не идёт — непонятно.
Вбиваем четыре нуля и висим, не идём на следующую страничку. Клик происходит без ошибок. Я посмотрел всё: Ajaх-запросы, ожидание, таймауты, логи приложений, кэш — ничего не нашёл. Пока не появилась библиотека Video Recorder, написанная Сергеем Пироговым. Она позволяет, добавив в код одну аннотацию, записывать видео. Тогда я смог снять видео этого теста, посмотреть его в замедленном виде, и это наконец-то прояснило ситуацию, которую до видео я не мог разгадать несколько месяцев.
Прогресс-бар перекрыл кнопку на доли секунды, а клик сработал ровно в этот момент и попал по этому прогресс-бару. То есть прогресс-бар схавал клик и пропал! И его не будет видно ни на одном скриншоте, ни в одном логе, никогда не узнаешь, что произошло.
В принципе, это в каком-то смысле баг приложения: прогресс-бар появился, потому что приложение реально вылезает за край экрана, и если прокрутить, там оказывается куча полезных данных. Но пользователи на это не жаловались, потому что на большом экране всё помещалось, не помещалось только на маленьком.
Пример 6: почему зависает Chrome?
Детективное расследование длиной в два года, абсолютно реальный случай. Ситуация такая: наши тесты довольно часто были flaky и падали, и в стек-трейсах было видно, что Chrome зависает: не тест наш, а именно Chrome. В логах было видно «Build is running 36 hours. » Стали снимать тред-дампы и стак-трейсы — они показывают, что в тестах всё хорошо, зависает обращение к Chromedriver и, как правило, в момент закрытия (вызываем метод close, и этот метод ничего не делает, висит 36 часов). Если интресно, то стек-трейс выглядел так:
Пытались сделать всё, что только может прийти в голову:
Пытаемся повторить проблему: пишем цикл от 1 до 1000, в цикле просто открываем браузер, первую страничку в нашем приложении и закрываем. Написали такой цикл, и… бинго! Результат: проблема стала повторяться стабильно (правда, примерно через каждые 80 итераций)! Круто! Правда, это достижение долго ничего не давало. Запустил ты, дождался 80-й итерации, завис Chrome… а дальше что делать? Смотришь в стак-трейсы, дампы, логи — ничего полезного там нет. Developer Tools в Chrome, возможно, помог бы, но до сентября 2017-го вместе с Selenium эти тулы не работали (конфликтовали порты: запускаешь Chrome из Selenium, и DevTools не открываются). Долгое время не мог придумать, что сделать.
И тут в этой истории начинается сказочный момент. Однажды, после бесконечного количества попыток, я снова запустил эти тесты, он у меня снова на какой-то итерации вроде 56-й завис, я думаю «давай ещё что-нибудь покопаю» (правда, не знаю, куда ещё брейкпойнт поставить или какой-то лог добавить). В этот момент дочка предлагает поиграть в кубики, а у меня тут как раз тест завис. Я говорю «Подожди», она мне: «Ты что, не понял, у меня тут к у б и к и!»
Что поделать, с грустью оставил компьютер, пошёл играть в кубики… И вдруг, примерно через 20 минут, случайно бросаю взгляд на экран, и вижу совершенно неожиданную картину:
Что получается: идёт отсчёт, через сколько минут истечёт сессия, а я строю башню из кубиков, остаётся две, одна… сессия истекает, тест продолжается, бежит до конца и падает (элемента уже нет, сессия истекла).
Что получается: Chrome на самом деле не зависал, как мы думали всё это время, он всё это время что-то ждал. Когда сессия истекала, дожидался, шёл дальше. Чего именно ждал Chrome — абсолютно непонятно, чтобы это понять, пришлось перелопатить весь код методом бинарного поиска: выкидываешь половину JavaScript и HTML, снова пытаешься повторить 80 итераций — не зависло, о, значит, где-то там… В общем, экспериментальным путем поняли, что проблема вот здесь:
Был на всех наших страницах JavaScript — тот самый, который показывает окошко, что сессия истекает. Наверно, все JavaScript-программисты знают, что так делать не очень правильно: всё, что запускается в тегах