«За годы работы вспоминается множество проблем. Некоторые были сложными, трудными в решении, совершенно очевидными задним числом, а некоторые просто забавными.
Как-то приходилось мне поддерживать набор автотестов. Однажды один из них не прошел. Вроде бы ничего страшного, такое случается. При повторном запуске они проходят, и мы смотрим, что там с инфраструктурой, сетью, или просто случайность. Через пару дней этот тест снова красный. Потом еще раз. Стало ясно, что это закономерность. Мне нужно было выяснить, что происходит и как стабилизировать этот тест.
[Обратите внимание на слова. Моей целью не было сделать тест «зеленым». Можно было искать ошибку в самом тесте, или в продукте. Главной целью было понять проблему и убедиться, что тест надежно выдает один и тот же результат — будь то pass или fail].
Немного контекста. В этом наборе были только UI-тесты. Выполнение всех тестов заняло около часа. Они запускались в staging несколько раз в день. Красный тест проверял график с данными за последние 30 дней. Были и другие тесты, контролирующие графики, по другим интервалам. Во всех тестах на сайте использовался один и тот же общий компонент для графиков. Другие тесты никогда не падали.
Этот тест состоял из трех основных шагов: запрос данных за последние 30 дней с помощью API, чтение данных из графика на сайте и сравнение полученных данных. Тест считался красным, если между данными из этих двух источников имелась хоть какая-то разница. Для сравнения использовался Python-пакет deepdiff. Для этого данные из API локально преобразовались, чтобы соответствовать структуре, возвращаемой функцией, отвечающей за чтение данных из UI.
Тестовая инфраструктура состояла из нескольких частей. Сервер Jenkins, который запускал тестовый набор в определенное время суток. Исполнителями задач были контейнеры в Kubernetes-кластере. Для облегчения тестирования UI использовался сервер Selenium Grid с несколькими worker’ами, которые хостились как виртуальные машины на OpenStack. Тесты выполнялись в staging-окружении продукта, также в Kubernetes-кластере, но не там, где находились исполнители задач. Я полагаю, что все было разбросано по двум дата-центрам, причем большая часть тестовой инфраструктуры находилась в одном месте, а тестируемый продукт — в другом.
Теперь вернемся к истории.
Первым делом я заглянул в логи тестирования. К сожалению, различия между объектами, о которых сообщает deepdiff в каждом конкретном случае, не так-то просто разглядеть (см. ниже). Объем данных просто ошеломляет, а вывод всего в одной строке усугубляет. Из лога стало понятно, что списки, возвращаемые API и считываемые из UI — отличаются, но не сразу стало понятно, где эти различия.
> assert not deepdiff.DeepDiff(expected_graph_data, actual_graph_data)
E assert not {'values_changed': {"root[0]['Date']": {'new_value': '1970-01-01', 'old_value': '1970-01-02'}, "root[0]['Foo']": {'new_value': 46, 'old_value': 23}, "root[0]['Bar']": {'new_value': 60, 'old_value': 99}, "root[0]['Total']": {'new_value': 106, 'old_value': 122}, "root[1]['Date']": {'new_value': '1970-01-02', 'old_value': '1970-01-03'}, "root[1]['Foo']": {'new_value': 23, 'old_value': 26}, "root[1]['Bar']": {'new_value': 99, 'old_value': 92}, "root[1]['Total']": {'new_value': 122, 'old_value': 118}, "root[2]['Date']": {'new_value': '1970-01-03', 'old_value': '1970-01-04'}, "root[2]['Foo']": {'new_value': 26, 'old_value': 49}, "root[2]['Bar']": {'new_value': 92, 'old_value': 86}, "root[2]['Total']": {'new_value': 118, 'old_value': 135}, "root[3]['Date']": {'new_value': '1970-01-04', 'old_value': '1970-01-05'}, "root[3]['Foo']": {'new_value': 49, 'old_value': 68}, "root[3]['Bar']": {'new_value': 86, 'old_value': 60}, "root[3]['Total']": {'new_value': 135, 'old_value': 128}, "root[4]['Date']": {'new_value': '1970-01-05', 'old_value': '1970-01-06'}, "root[4]['Foo']": {'new_value': 68, 'old_value': 33}, "root[4]['Bar']": {'new_value': 60, 'old_value': 14}, "root[4]['Total']": {'new_value...ue': 25}, "root[24]['Bar']": {'new_value': 29, 'old_value': 78}, "root[24]['Total']": {'new_value': 106, 'old_value': 103}, "root[25]['Date']": {'new_value': '1970-01-26', 'old_value': '1970-01-27'}, "root[25]['Foo']": {'new_value': 25, 'old_value': 57}, "root[25]['Bar']": {'new_value': 78, 'old_value': 84}, "root[25]['Total']": {'new_value': 103, 'old_value': 141}, "root[26]['Date']": {'new_value': '1970-01-27', 'old_value': '1970-01-28'}, "root[26]['Foo']": {'new_value': 57, 'old_value': 48}, "root[26]['Bar']": {'new_value': 84, 'old_value': 18}, "root[26]['Total']": {'new_value': 141, 'old_value': 66}, "root[27]['Date']": {'new_value': '1970-01-28', 'old_value': '1970-01-29'}, "root[27]['Foo']": {'new_value': 48, 'old_value': 89}, "root[27]['Bar']": {'new_value': 18, 'old_value': 14}, "root[27]['Total']": {'new_value': 66, 'old_value': 103}, "root[28]['Date']": {'new_value': '1970-01-29', 'old_value': '1970-01-30'}, "root[28]['Foo']": {'new_value': 89, 'old_value': 61}, "root[28]['Bar']": {'new_value': 14, 'old_value': 66}, "root[28]['Total']": {'new_value': 103, 'old_value': 127}}, 'iterable_item_added': {'root[29]': {'Date': '1970-01-30', 'Foo': 61, 'Bar': 66, 'Total': 127}}}
Разобраться в этом логе, как видите, сложно, поэтому следующим шагом было выполнение упавшего теста локально, в изоляции. Предсказуемо, он прошел. Я не питал больших надежд на то, что смогу сразу же воспроизвести проблему, но это была простая вещь, которую можно было попробовать, поэтому я думал, что стоит попробовать.
На этом этапе я решил, что обойти проблему невозможно, и мне нужно понять, чем же отличаются ответы API и UI. Я скопировал строку лога в редактор и вставил символ новой строки после каждого },. Еще несколько действий, и у меня был формат, который было уже легче понять.
Deepdiff показывает различия между элементами с одним и тем же индексом в списках. Но если сфокусироваться на элементах с одинаковым значением даты, то окажется, что они в принципе одинаковы. Значения, появляющиеся под именем «old_value» в одном списке, появляются как «new_value» в другом списке, просто под другим индексом. Я наложил зеленый и желтый цвета на скриншот ниже, чтобы было легче увидеть. Можно считать, что эти списки в основном одинаковы, но один из них сдвинут по сравнению с другим; или можно сказать, что в одном списке лишний элемент добавлен в конце, а в другом — в самом начале. В частности, API считывает данные со 2 января по 1 февраля, а UI отображает данные с 1 января по 31 января. Данные сильно пересекаются, но специфический формат вывода в deepdiff затушёвывает этот ключевой момент.
На этом этапе у меня уже была догадка, в чем заключается проблема, но я не понимал ее причину, и почему она влияла только на этот единственный тест.
Поэтому на следующем этапе я хотел понять, есть ли какие-то закономерности в этом сбое. Я собрал результаты тестов за последние несколько недель и поместил их в таблицу. Добавил колонки для базовых вещей, таких как сам результат, далее сколько времени потребовалось для завершения теста, также дата и время запуска. Чтобы визуально выделить упавшие тесты, я добавил фоновый цвет для их выделения. В отдельном столбце я выделил все строки, где тест был запущен впервые в данный день. Затем я добавил столбцы, показывающие уже известные проблемы за предыдущие несколько недель, чтобы посмотреть, попадают ли все сбои в одну из них.
Хотя четкой предсказуемой закономерности не было, я заметил любопытную вещь: если тест не проходил, то он не проходил в первый же день. Последующие запуски в любой день никогда не показывали сбоя. А первый запуск в течение дня всегда начинался вскоре после полуночи по Гринвичу.
Это позволило мне построить рабочую гипотезу: проблема каким-то образом связана со временем, и есть небольшое временнОе окно, когда она может возникнуть, возможно, пару часов. Это окно начинается в районе полуночи по Гринвичу. Такая гипотеза объясняет, почему последующие запуски конвейера никогда не давали сбоев, и почему мне никогда не удавалось воспроизвести проблему локально — я нахожусь к востоку от линии UTC, и мне пришлось бы попробовать запустить тест в нерабочее время. Конечно, я не знал, выдумываю ли я что-то или создаю сложную adhoc-гипотезу, которая соответствует данным. Но она подсказала мне следующий шаг.
Чтобы подтвердить гипотезу, мне нужна была новая информация, которой у меня не было. Чтобы собрать ее, я добавил в тестовый набор расширенное протоколирование. Сначала я использовал Selenium JavaScript для получения даты и времени в том виде, в котором их «видит» браузер. Затем я сделал то же самое из Python, который одновременно управляет Selenium и запрашивает данные из API. Важно то, что Python-код выполняется непосредственно в тест-раннере (контейнер в Kubernetes), а код JavaScript — в браузере (VM Selenium Grid на OpenStack).
diff --git package/tests/ui/test_failing.py package/tests/ui/test_failing.py
index 1234567..abcdef0 100644
--- package/tests/ui/test_failing.py
+++ package/tests/ui/test_failing.py
@@ -10,6 +10,13 @@ def test_failing_test(user_app, some_fixture):
"""
view = navigate_to(user_app.some_app, "SomeViewName")
+ browser_time_string = view.browser.execute_script("return new Date().toTimeString()")
+ browser_utc_string = view.browser.execute_script("return new Date().toUTCString()")
+ view.logger.info(
+ "[JavaScript] Time right now: %s ; UTC time: %s",
+ browser_time_string,
+ browser_utc_string,
+ )
expected_x_axis = get_xaxis_values()
view.items.item_select(some_value)
view.graph.wait_displayed()
diff --git package/utils/utils.py package/utils/utils.py
index 1234567..abcdef0 100644
--- package/utils/utils.py
+++ package/utils/utils.py
@@ -10,6 +10,14 @@ METRIC_MAP = {
def _get_dates_range(some_param="Daily", date=None):
+ current_time = arrow.now()
+ log.info(
+ "[Python] Time right now: %s ; TZ name: %s ; TZ offset: %s ; UTC time: %s",
+ current_time,
+ current_time.strftime("%Z"),
+ current_time.strftime("%z"),
+ arrow.utcnow(),
+ )
try:
date = arrow.get(date)
except TypeError:
После применения и развертывания вышеуказанного патча мне оставалось ждать подтверждения — следующего сбоя. Я надеялся, что в новых логах появится больше информации.
Так и оказалось. JavaScript показывал дату на один день раньше, чем Python. На самом деле, время в JavaScript было примерно на 15 минут раньше, чем в Python. Так что если набор запускался около полуночи, и мы добирались до теста-виновника в течение 15 минут после запуска набора, то Python запрашивал данные через API для некоторых дат, но сайт в браузере думал, что это еще предыдущий день, и запрашивал другой набор дат. Это означает, что окно, в котором возникает проблема, крайне мало — всего около 15 минут каждый день.
[JavaScript] Time right now: Thu Jan 01 1970 23:58:17 GMT+0000 (Coordinated Universal Time) ; UTC time: Thu, 01 Jan 1970 23:58:17GMT [Python] Time right now: 1970-01-02T00:14:36.042473+00:00 ; TZ name: UTC ; TZ offset: +0000 ; UTC time: 1970-01-02T00:14:36.042473+00:00
На этом мы закончили основную часть дебага — мы уже знали, в чем дело, знали, что сбой не вызван ошибкой в тесте или продукте, и было ясно, что решение заключается в том, чтобы все машины, участвующие в тестировании, сверяли дату и время. Также казалось, что JavaScript показывает неправильную дату, что может означать, что проблема связана с виртуальными машинами Selenium Grid или экземпляром в OpenStack.
Я подключился ко всем машинам Selenium Grid с помощью SSH и проверил их локальное время с помощью команды date. Они все отставали от своего поясного времени примерно на 15 минут. Я предположил, что разница была вызвана обслуживанием инфраструктуры OpenStack, поэтому я просто использовал hwclock, чтобы заставить часы операционной системы жестко синхронизироваться с часами компьютера, и занялся своими делами.
Через пару дней я снова подключился к этим машинам и заметил, что локальное время снова отстает, но теперь примерно на 15 секунд. Выглядело так, будто местные часы «дрейфуют» примерно на 5 секунд в день. Может показаться, что это не так уж и много, но это также означало, что будет повторение описанной выше проблемы. Стало очевидно, что кто-то время от времени заходит на эти машины и сбрасывает часы — но это не лучшее долгосрочное решение, нам нужно было решение, автоматически синхронизирующее время.
Это «что-то» – называется NTP, и на всех машинах уже был установлен chrony. Однако, похоже что он у нас работал неправильно. Хотя команды выполнялись успешно, а в логах не было никаких проблем, часы просто не синхронизировались. После нескольких часов поисков я исключил все возможные причины на уровне операционной системы и пришел к выводу, что, возможно, NTP-трафик на публичные серверы блокируется брандмауэром дата-центра. Я обратился за помощью к администраторам OpenStack, и они сказали мне, что в дата-центре у них есть экземпляр NTP-сервера, который я могу использовать. Как только я настроил chrony на использование его в качестве источника, все наконец заработало.
После этого браузеры стали стабильно показывать то же время, что и исполнители задач. Это устранило проблему, и больше не было подобных сбоев.»
