Информационный портал

В этот раз запуск прошёл быстрее, но 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 мы внесли очередную правку: на «Транквилити» добавились данные об окнах уязвимости. Тогда следующий запуск помог бы нам определиться, что именно вызывает сбой: окна уязвимости, или сведения об оборонных режимах. Этот запуск тоже прошёл успешно: мы наконец-то поняли, что речь идёт именно об оборонных режимах. Разработчики начали копать в том же направлении. Затем мы вновь добавили в базу сведения о боевых действиях.

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

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

Нормально, нет логов, нет наказания за использование уязвимостей в СОВе.

Собственно, все 250 узлов тормозят систему сбора логов или есть отдельные кусты?