Эта статья написана в соавторстве с CCP Masterplan.

В этой статье мы расскажем, что происходило «за кулисами» 15 июля 2015 года, в момент самого длинного за последние годы периода отключения сервера EVE Online. Мы делимся с вами этой информацией, потому что знаем, что среди игроков есть много людей, занятых в сфере IT: им могут быть интересны истории из практики. Кроме того, в тексте есть детали о том, как работает уникальный игровой кластер. Если вам это интересно, то подробности о том, что же произошло 15 июля, ниже. Если вы не хотите загружать голову лишними мелочами, ознакомьтесь с этим текстом, написанным вскоре после инцидента.

Предварительные данные

Игроки-ветераны несомненно помнят моменты, когда сервер отключался на дни, а не на часы. В последние годы мы в основном избавились от столь длительных задержек. 15 июля сервер был недоступен для игроков в течение 699 минут, чуть дольше, чем 2 и 3 июня 2013 года, незадолго до выхода «Одиссеи» (что, в свою очередь, потребовало отключить сервер на 342 минуты в силу необходимости выполнить скрипты, обеспечивающие «тирцид», корректировку иерархии кораблей). Ещё раньше, в 2011, при выпуске «Инкарны», сервер отключался на 963 минуты; впрочем, после «Инкарны» выпуски полугодичных обновлений больше не требовали чрезмерно длительных перезагрузок. Сейчас, если речь идёт об автоматической перезагрузке без добавления кода, мы можем быть уверены, что перезагрузка займёт 7 минут; если мы загружаем код, то с запасом укладываемся в отведённые нам полчаса.

Запуск

Кластер «Транквилити» состоит из примерно 250 узловых серверов. Чтобы кластер включился, узлам необходимо выполнить согласованную последовательность действий. Каждый узел должен получить свой ID, создать соединение с каждым из прочих узлов, получить список планетных систем, размещённых на нём, и данные, необходимые для выполнения задачи (например, на узле может размещаться торговая система сектора, ряд корпораций или альянсов, или процесс освоения навыков для некоторой подгруппы пилотов).

При запуске кластер проходит несколько этапов. Кластер не перейдёт на следующий этап, пока все узлы не сообщат, что закончили все процедуры текущего этапа. Отсчёт начинается с -4 и ведётся до 0. Как только все узлы сообщат, что провели этап 0, кластер готов к старту. Управление этим процессом осуществляется с помощью центрального узла, называемого «Полярис». «Полярис» отвечает за проверку этапа, на котором находится каждый узел, и рассылает инструкции о переходе на новый этап по мере выполнения необходимых условий.

-4: Узел запустился, установлена связь с базой данных
-3: Узел установил сетевые соединения со всеми прочими узлами
-2: Подготовлен кэш адресов. По сути, это таблица маршрутизации, позволяющая каждому узлу узнать о назначениях соседних
-1: Все пусковые сервисы закончили инициализацию, началась предзагрузка данных (торговые системы, планетные системы, и так далее)
0: Узел сообщает кластеру, что готов к работе, все пусковые данные загружены, службы готовы принимать запросы

Инцидент

Когда мы отключили сервер 15 июля, чтобы установить первый дополнительный патч для «Эгиды-суверенитета», проблем не ожидалось: тест-серверы, на которых этот код уже был загружен, запустились обычным образом и вели себя нормально. Мы полагали, что этот запуск пройдёт как обычно, в течение 15-20 минут. Первый звонок прозвучал, когда загрузка кода на сервер продлилась чрезвычайно долго, а утилита загрузки выдала неисправимую ошибку и ушла в перезагрузку незадолго до 11:30. В этот момент мы сообщили о задержке при запуске, но не ожидали ничего необычного: иногда в утилитах случаются сбои, бывают просрочки по времени. Мы загрузили код вновь, на этот раз успешно. Запуск сервера начался в 11:42. В 11:46 12 узлов из примерно 250 сообщали, что они зависли (что не позволяло запуститься серверу). Не страшась, мы воспользовались древнейшим IT-трюком: «выключи его и включи снова».

В этот раз запуск прошёл быстрее, но 41 узел по-прежнему оставался на этапе «-1». Мы решили открыть сервер в режиме VIP-доступа (зайти на него в этом режиме могут только учётные записи с особыми полномочиями разработчика) и полностью проработать загрузку кода, чтобы исключить блокировки, конфликты или человеческий фактор. В этот момент мы считали, что причиной проблем является окружение, поскольку тот же код работал на тест-сервере без каких-либо проблем.

К сожалению, две перезагрузки спустя мы ни на шаг не приблизились к решению вопроса. Пришло время вызвать кавалерию. Программисты присоединились к системным администраторам и начали исследовать вопрос со стороны кода; другие разработчики обсуждали возможный откат на предыдущий день, и его последствия. До сих пор откат не рассматривался как вариант, поскольку не было никаких признаков, что проблема в коде, но теперь у нас было время, пока программисты вели следствие, и мы решили, что испытаем его.

Программисты читали логи запуска, пытаясь понять, какие ошибки являются причиной сбоев, администраторы проверяли аппаратное обеспечение и операционные системы: несколькими днями ранее в инфраструктуру были внесены различные изменения. Поскольку «Полярис» был ключевым элементом в системе запуска, мы убрали из системы компьютер, на котором располагался «Полярис», и разместили этот ключевой узел на другом физическом носителе. Этим шагом мы попытались отфильтровать аппаратные и программные проблемы, специфичные для конкретного компьютера в кластере, но очередной запуск вновь был безуспешен. Прогон возможного отката оказался успешным, но мы не считали, что проблема в коде — мы были твёрдо уверены, что речь о внесённом нами патче, о данных или об окружении. Далее мы решили установить первоначальную версию игры для «Транквилити» на тест-сервер «Сингьюлэрити», поскольку на «Сингьюлэрити» были данные и службы DUST, а на «Мультиплисити» (нашем сервере для хотфиксов/обновлений) их не было.

Мы сочли, что этот сценарий маловероятен, но стоит проверки: конечно же, «Сингьюлэрити» успешно заработал. Утилиты наблюдения отметили, что процесс EVE Online пытается установить связь через внешнюю сетевую карту, IBM USB Remote NDIS Network Device, входящую в состав блейд-серверов IBM. Этот сетевой интерфейс предназначен для управления сервером через IMM (Integrated Management Module, интегрированный модуль управления) или AMM (Advanced Management Module, усовершествованный модуль управления). Через этот интерфейс сервером можно управлять на низком уровне. Например, обновлять прошивку с помощью ОС, или передавать данные на сервер. Интерфейс получил IP-адрес, самоподписанный Windows, не входящий в пространство адресов IPv4, и не связанный с нашей внутренней сетью центра данных. Процесс EVE Online не должен был работать с этим интерфейсом, но мы решили устранить эту возможность и отключили интерфейс. Говоря о «Транквилити», мы отключили интерфейс CREST, переименовали обновление, устанавливаемое на сервер, чтобы исключить сбои при перезаписи и всё, что только возможно, и попробовали вновь. В 14:21 завершился очередной запуск: 53 узла остановились на этапе «-1».

В течение часа, пока разработчики вели расследование, мы проверили ещё несколько маловероятных идей. В 15:29 один из разработчиков предложил выгрузить из базы новые записи о системе владения космосом, сохранив их во временных таблицах, и проверить, не являются ли эти данные причиной сбоя. С точки зрения игры наибольшая разница между запуском в среду по сравнению с запуском во вторник состояла в том, что во вторник все сооружения системы суверенитетов были в «нулевом» состоянии, не было никаких связанных с ними боевых действий и окон уязвимости. В ответ на эту идею CCP Lebowski и другие сотрудники отдела контроля качества запустили на «Сингьюлэрити» множество энтоз-событий и попытались тем самым вызвать ошибки или сбои запуска. Несмотря на двойную (по сравнению с «Транквилити») нагрузку «Сингьюлэрити» такими событиями, тест-сервер продолжал загружаться как обычно. В 15:48 мы прогнали скрипт на «Дуалити», убедились, что он работает как задумано, и запустили его на «Транквилити». Скрипт отработал, записи обнулились, и в 16:33 мы с тревогой смотрели на то, как идёт запуск.

-4
-3
-2
-1
...
0
Работает!

Отлично! Теперь осталось понять, почему сброс данных об оборонном режиме и об окнах уязвимости привёл к успешному запуску сервера.

Открывать сервер в таком состоянии было нельзя — фактически мы свели к нулю целый день сражений за власть над «нулями». Мы продолжили исследование. К этому моменту в процессе участвовало 8 программистов, несколько системных администраторов и практически все сотрудники отдела контроля качества, пытавшиеся воспроизвести сбой на «Сингьюлэрити». В 17:10 мы внесли очередную правку: на «Транквилити» добавились данные об окнах уязвимости. Тогда следующий запуск помог бы нам определиться, что именно вызывает сбой: окна уязвимости, или сведения об оборонных режимах. Этот запуск тоже прошёл успешно: мы наконец-то поняли, что речь идёт именно об оборонных режимах. Разработчики начали копать в том же направлении. Затем мы вновь добавили в базу сведения о боевых действиях.

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

В нашей теории проблема выглядела так: если попытки узнать столицу альянса особым образом взаимодействуют с механизмом загрузки конфигурационных данных (с помощью которого «перекрывается» значение задержки по умолчанию), может возникнуть взаимная блокировка узлов. Узел, на котором размещена планетная система с идущими боевыми действиями, ожидает необходимые данные от узла, хранящего сведения об альянсе. Узел с данными об альянсе получил настройки столицы и посылает этой столице сообщение вида «ты столица, у тебя защитный коэффициент увеличен на 2». Теперь узел с данными об альянсе не отвечает на новые запросы, пока узел с данными о планетной системе не ответит, что принял сведения о столице, но узел с данными о планетной системе не отвечает на новые запросы, пока узел с даннымми об альянсе не ответит на сведения о боевых действиях. Мы загрузили патч, который устранил опцию по настройке задержки переноса столицы, и должен был убрать возможность подобной блокировки. При следующем запуске в 18:12 нас ждал 51 узел, зависший в «-1» — а значит, надо было думать дальше (после ещё одной быстрой перезагрузки на всякий случай).

Итак, что же мы знали?

• Запуск без данных о боях прошёл успешно как на «Транквилити», так и на всех тест-серверах.
• Запуск с данными о трёх сотнях боёв за суверенитет не удался на «Транквилити», но был успешен на всех тест-серверах.
• Удаление кросс-ссылок на узлы, связанных со столицами альянсов, не помогло.
• Пришло время экспериментировать с загрузкой данных о боях за суверенитет, чтобы найти источник проблемы.

Мы отказались от загрузки данных о боях. Как следствие, запасные командные пункты не появлялись, но в целом сооружения системы суверенитетов загрузились ожидаемым образом. Это было не решение проблемы, но ещё один кусочек паззла, приблизивший нас к пониманию, что именно отграничивает успешный запуск от неуспешного. Этот вариант (хотфикс № 2) привёл к успешному запуску в 19:15, и был продолжен третьим экспериментом: что получится, если теперь мы загрузим данные о боях, но после небольшой задержки, чтобы всё прочее успешно загрузилось до того?

Мы попробовали вновь включить загрузку этих данных (отключенную во втором хотфиксе), но с задержкой и в асинхронном режиме по сравнению с прочим ходом запуска сервера. К этому моменту мы столкнулись с некоторыми другими проблемами: задержки синхронизации «Перфорса», некоторые проблемы с хранением данных, но с каждым хотфиксом мы были всё ближе и ближе...

...к пицце, с благодарностью встреченной нами в 19:48 во время установки третьего хотфикса.

Третий хотфикс вновь уронил «Транквилити», что было особенно интересно. В этом случае мы загружали данные о боях независимо от прочих задач, осуществляемых при запуске, и тем не менее они каким-то образом роняли узлы кластера.

С новыми силами, приданными нам полным столом пиццы, мы вернулись к второму хотфиксу, чтобы продолжить эксперименты с помощью консоли на живом пациенте.

Как только все узлы запустились, и мы подтвердили, что планетные системы успешно загружены, мы открыли окно консоли на сервере и начали отдавать команды и наблюдать результаты в реальном времени. Мы провели несколько проверок и убедились, что ни на одном из узлов нет данных о боях. Как и ожидалось, они ответили, что данных о боях действительно нет. Мы потребовали от всех нод получить соответствующие данные о боях. Сразу после этого кластер начал «тормозить». Через несколько минут несколько узлов прекратило работу и покинуло кластер. По мере этого планетные системы на мёртвых узлах переносились на оставшиеся в живых. Теперь у нас было около 200 узлов из 250. Мы скомандовали кластеру повторно получить данные о боях. Ожидалось, что каждый узел сообщит об известном ему пакете этих данных, и ответит, что получение не требуется (так как данные есть в памяти). На самом деле кластер вновь перестал отвечать в течение нескольких минут, а когда всё успокоилось, умерло ещё несколько узлов. Это было очень странно: ожидалось, что узлы просто запишут в логи определённые данные, поскольку получать им нечего. Тогда мы подумали: может быть, речь не о самих данных о боях, а о связанных с ними записях в логи? Теперь кластер был в не очень хорошем состоянии, мы вновь перезапустили его (оставаясь на втором хотфиксе) и продолжили испытания.

С помощью консоли мы отключили логирование функции загрузки сведений о боях за суверенитет. Затем повторили тот же тест: попросили все узлы загрузить те же сведения. Команда выполнилась почти мгновенно, кластер остался работоспособным. Что за?.. Дальнейшие проверки подтвердили, что все сведения о боях за суверенитет действительно загрузились. Мы повторили этот эксперимент (с отключенным логированием). Он завершился мгновенно, сообщив, что загрузка данных о боях не требуется.

И наконец мы включили логирование процесса и выдали очередную команду загрузки данных о боях. Кластер вновь начал «тормозить», а узлы — «выпадать» из системы. Похоже, мы нашли виновника, хоть и не знали, почему он совершал преступление, и что было его орудием. По каким-то причинам канал логирования, используемой системой ведения боёв за суверенитет на «Транквилити», снижал производительность узлов до такой степени, что они отключались от кластера.

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

В 21:48 мы выпустили пятый хотфикс, предположительно решавший проблему. Мы удалили логирование системы ведения боёв за суверенитет, но в остальном практически не трогали код. Успех этого варианта означал бы, что мы почти готовы открывать «Транквилити». Он был выпущен на «Транквилити» в 22:07. В 22:22 сервер был запущен, и мы начали проверки в режиме VIP, чтобы убедиться, что эксперименты не повредили данные о суверенитете. Мы нашли одну проблему с боем-двойником, но легко устранили её. Интерфейс CREST был включен в 22:38, «Транквилити» вышел из VIP-режима и открылся для всех игроков в 22:41.

Послесловие: 20 июля, понедельник

Идя по следу падающих кластеров, нам надо было выяснить, почему один конкретный канал логирования (используемый для боёв за суверенитет) на одном конкретном сервере («Транквилити») приводит к чрезвычайным проблемам со стабильностью сервера. Мы запланировали определённое время VIP-режима на «Транквилити», в течение которого могли бы продолжить эксперименты. Требовалось найти наиболее простой код, который привёл бы к воспроизведению симптомов, что помогло бы в дальнейших исследованиях. Мы вошли в консоль на одной из нод «Транквилити»: отсюда можно было тыкать сервер палочкой и смотреть, что сломается. (До этого мы пробовали повторить ситуацию на «Сингьюлэрити» и «Дуалити»; испытания не привели к ошибкам).

Мы подготовили набор действий, которые следовало провести. Каждый следующий шаг последовательно добавлял факторы, пока проблему не удастся воспроизвести. Как выяснилось, далеко копать не пришлось. Вот как это было:

У нас было два канала логирования: обычный канал, и особый канал, который использовался в системе отслеживания боёв за суверенитет. Мы убедились, что оба канала работают, выполнив на одном узле следующий код:

1 # generic_logger is a reference to a generic log channel
2 # campaign_logger is a reference to the log channel used by sovereignty campaigns
3
4 # Step 1a: Assert that output to the generic logger works correctly
5 generic_logger.warn('The quick brown fox jumps over the lazy dog')
6
7 # Step 1b: Assert that output to the campaign logger works correctly
8 campaign_logger.warn('The quick brown fox jumps over the lazy dog')

С помощью Splunk мы в реальном времени наблюдали за логами. Да, каждая строка появилась один раз.

Дальше шаг 1а был повторён на 250 узлах параллельно. Splunk отобразил 250 строк. Потом мы повторили шаг 1b, и результат был тот же: каждый узел записывает одну строку, все строки проходят через канал суверенитета.

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

1 # Step 2a: Log the same line 500 times per node, on the generic log channel
2 [generic_logger.warn('The quick brown fox jumps over the lazy dog') for i in range(500)]
3
4 # Step 2b: Log the same line 500 times per node, on the campaign log channel
5 [campaign_logger.warn('The quick brown fox jumps over the lazy dog') for i in range(500)]

Для тех, кто не знаком с Python, вторая строка будет исполнена в цикле 500 раз, и каждый раз выдаст предупреждение через обычный канал. Пятая строка делает то же самое, но через канал суверенитета.

Сначала мы провели шаг 2а на всех узлах параллельно. Команда выполнилась мгновенно; на графике Splunk возник пик в 125 000 строк (250*500). Нагрузка не так велика, как может показаться: вполне приемлемые значения для системы, особенно в точечных пиках, наподобие нашего. Потом мы провели шаг 2b. Случилось кое-что любопытное. Splunk показал нам корректное число строк в логе (наши логи что-то показывают!), но команда выполнилась не так быстро, как в шаге 2а. На самом деле консоль начала реагировать на нас лишь через несколько минут, и полученные данные свидетельствовали, что несколько узлов не ответили. Статус кластера сообщил нам, что эти узлы отключены. Каким-то непонятным образом невинная строка логов смогла привести к отключению узлов из кластера по тайм-ауту.

Легче, чем мы думали! Чтобы воспроизвести мёртвый кластер, даже не понадобилось работать с базой данных или со сведениями о боях. Когда оказывается, что простое логирование данных может выключить работающий сервер, у разработчика определённо есть проблемы. Примерно такие же, как были у нас в среду, 15 июля. Определив проблему, мы перезапустили «Транквилити», и запустили на него игроков, отключив режим VIP.

Как было сказано ранее, такая реакция никогда не наблюдалась ни на одном тест-сервере. В работе «Транквилити» (или его конфигурации) есть нечто уникальное. Мы продолжаем искать причины, объясняющие, почему логирование системы приводит к таким сбоям именно и только на «Транквилити» и именно и только на определённых каналах логирования. Мы знаем, что «Транквилити» несомненно отличается от прочих серверов по масштабу, но пока что наши эксперименты говорят нам, что ответ не сводится к количеству узлов.

Загадка ещё не решена...