Судный день: К чему приводят скрытые ошибки асинхронной обработки данных при росте нагрузки
В нашем блоге мы рассказываем не только о развитии своего продукта — биллинга для операторов связи «Гидра», но и описываем сложности и проблемы, с которыми сталкиваемся на этом пути. Ранее мы уже описывали ситуацию, в которой бесконтрольный рост таблиц в базе данных одной компании-пользователя нашей системы привел к настоящему DoS.
Сегодня речь пойдет о еще одном интересном случае внезапного сбоя, который сделал «день смеха» 1 апреля этого года совсем не смешным для службы поддержки «Латеры».
Все пропало
Один из операторов связи и, по совместительству, клиентов нашей компании, пользовался биллингом «Гидра» на протяжении нескольких лет. Изначально все было хорошо, однако со временем стали возникать проблемы — к примеру, различные элементы системы могли работать медленнее положенного.
Однако утром первого апреля спокойный ход событий был нарушен. Что-то пошло не так — в техподдержку обратились крайне возбужденные представители клиента. Оказалось, что часть абонентов, не оплативших доступ в интернет, получила его (что не самое страшное), а пользователям, которые все оплачивали вовремя, доступ был заблокирован — и вот это уже вызвало просто бурю недовольства.
Служба поддержки была поднята по тревоге. Предстояло максимально быстро найти и устранить проблему.
Горячий день
Зайдя на биллинговый сервер, инженеры техподдержки первым делом обнаружили, что полтора часа назад закончилось место в основном табличном пространстве рабочей БД. В результате этого остановилось несколько системных процессов биллинга — в частности, обновление профилей в модуле provisioning (отвечает за управление доступов абонентов к услугам). Техподдержка выдохнула и, предвкушая скорый обед, быстро увеличила табличное пространство и запустила процессы.
Это не помогло — абонентам легче не стало. Клиент тем временем начал паниковать: поток возмущенных звонков «я заплатил, но ничего не работает» начал заваливать его колл-центр. Разбирательство продолжилось.
На сервере RADIUS-авторизации, который за несколько дней до этого переехал на новое «железо», инженеры обнаружили сильнейшее замедление работы. Быстро выяснилось, что оно приводило к тому, что в БД сервера авторизации содержались неактуальные данные о пользовательских профилях — именно поэтому биллинг ошибочно открывал доступ в интернет одним абонентам и закрывал его тем, кто оплачивал услуги вовремя. Однако причина столь драматического падения производительности оставалась неясной.
Для избавления от неактуальных данных было решено повторно отправить в RADIUS-сервер из провиженинга правильные данные, по сути дела реплицировать всю информацию заново. Эта операция изначально задумывалась как средство, которое применяется в отчаянном положении при разрушении БД.
Через несколько минут стало понятно, что повторная отправка данных не просто не помогла, но существенно ухудшила ситуацию. Задержка от оплаты до включения доступа у абонентов выросла, по нашим расчетам, до нескольких часов.
Единственное, что можно было сделать дополнительно — предварительно очистить данные в кэше перед репликацией, но это привело бы к отказам в обслуживании для абонентов, у которых все было хорошо (а их было большинство), и на это пойти мы не могли.
В итоге решено было разбирать проблему по шагам, поделив ее на этапы и проверяя элементы системы на каждом из них. Это позволило реконструировать ход событий того дня, в конце концов понять причину и устранить проблему.
Лирическое отступление: Когда город засыпает
Итак, в ночь на 1 апреля биллинг начал генерировать новые данные для абонентских профилей на замену старым — если абонент не оплатил услугу, то нужно было отобрать у него доступ к ней. На этом шаге модуль provisioning сгенерировал большое количество новых профилей и асинхронно отправил их во внутреннюю очередь сообщений Oracle. Поскольку напрямую с очередями Oracle работать извне с нашим стеком технологий неудобно, для их дальнейшей передачи используется «прослойка» в виде брокера сообщений Apache ActiveMQ, к которому подключается RADIUS-сервер, записывающий данные в MongoDB.
Биллинг должен отправлять данные об измененных абонентских профилях в строгом порядке. Чтобы порядок соблюдался и не происходило «путаницы» профилей на отключение и подключение, в системе реализован специальный процесс, который выбирает данные из очереди ActiveMQ и записывает их в MongoDB.
Приходит понимание
Система была развернута таким образом, что ActiveMQ и MongoDB находились на разных серверах, при этом в используемой конфигурации ActiveMQ не требовалось подтверждения получения сообщений — все отправленное из очереди считалось по умолчанию принятым. Нужно было лишь входящее соединение, затем данные отправлялись до исчерпания лимитов буферов ОС принимающей стороны.
Ранее иногда случались случаи потери связи RADIUS-сервера с ActiveMQ — на такой случай мы предусмотрели функциональность восстановления соединений. Для детектирования случаев потери связи был реализован специальный механизм, использующий протокол STOMP — в нем есть настройка передачи heartbeat-пакетов. Если такой сигнал не получен, то соединение считается утерянным и принудительно переустанавливается.
Когда мы все это осознали, причина проблемы стала сразу понятна.
Сообщения из ActiveMQ всегда извлекаются в том же потоке исполнения, который записывает данные в профили абонентов. Извлечение и запись — то, что он делает по порядку, и если запись задержалась, то поток не может «достать» следующий пакет. И если в нем содержался heartbeat, то он не будет получен — и другой поток, который проверяет наличие таких пакетов, будет считать соединение потерянным и попытается его переустановить.
Когда соединение переустанавливается, тот сокет и его буфер, которые использовались, закрываются, и все данные, которые там лежали и еще не были разобраны приложением, оказываются потерянными. При этом ActiveMQ пребывает в уверенности относительно успешности отправки, поскольку подтверждения получений не требуется, а принимающая сторона регулярно переустанавливает соединение.
Получается, что часть обновлений профилей остается потерянной, но дальнейшая работа системы продолжается. В итоге реплицированный кэш базы данных оказывается частично невалидным, хотя многие обновления все же доходили.
Вывести проблему из острой фазы удалось с помощью увеличения heartbeat-таймаута до большего числа — это позволило потоку, обрабатывающему данные, дождаться записи и успешно обработать все сообщения. После этого работоспособность системы была полностью восстановлена, а в базу данных авторизационного сервера попала корректная информация. В общей сложности с момента поступления заявки от клиента до завершения разбирательств прошло шесть часов.
Кризис миновал, можно было выдохнуть, однако теперь требовалось понять, что послужило причиной такой некорректной работы, и предотвратить возможность повторения подобных сбоев.
Поиск причин
Как всегда бывает в моменты масштабных аварий, друг на друга наложились сразу несколько факторов — каждый по отдельности не привел бы к столь плачевным последствиям, но сработал эффект «снежного кома».
Одной из причин стало желание руководства нашего клиента, видеть все платежи от всех клиентов в один день. Именно поэтому система была настроена таким образом, чтобы все списания и зачисления происходили в первый день нового месяца.
Этот процесс устроен так: в биллинге по каждому абоненту ведется электронный документ, в котором учитывается факт оказания услуги. Каждый месяц такой документ создается заново. За несколько часов до окончания месяца происходит проверка баланса — документы анализируются, и на основании этого анализа абоненты после полуночи либо вновь получают доступ к услугам, либо теряют его.
Поскольку такие проверки баланса у этого клиента происходят одномоментно в начале нового месяца, то первого числа каждого месяца нагрузка на систему всегда возрастает. Этому способствует не только необходимость проанализировать всех клиентов и отключить неплательщиков — тех из них, кто сразу же решит оплатить услуги, нужно быстро «допустить» к услугам снова и корректно этот факт учесть.
Все это работает благодаря двум важным системным процессам. Один из них отвечает за выполнение команд на отключение абонентов. Когда биллинг понимает, что абонента нужно отключить, он через встроенный модуль provisioning отправляет команду на прерывание его сессии доступа.
Второй процесс — предотвращение установления новой сессии отключенным абонентом. Для этого в независимую базу данных авторизационного сервера с пользовательскими конфигурациями нужно реплицировать данные из provisioning-модуля «Гидры». Это позволяет всем частям системы знать о том, что определенных абонентов обслуживать сейчас не нужно.
Важное замечание: очевидно, что подобное желание видеть все деньги от всех абонентов в один день не способствует равномерному распределению нагрузки на систему. Напротив, в ходе «судного дня» для абонентов она вырастает в разы — причем, как на биллинг, так и на сервисы приема платежей. Кроме того, такая конфигурация способствует увеличению оттока пользователей (о том, как с ним бороться, мы рассказывали здесь и здесь).
Вторая причина — желание сэкономить на инфраструктуре и отказ от разумного разнесения сервисов. Для биллинга был закуплен менее мощный сервер, чем было необходимо. Четыре года он отработал без проблем, однако объём данных в БД рос, кроме того, на сервер постепенно «навешивались» требовательные к ресурсам дополнительные сервисы (внешняя отчетная система на Java-машине, новый модуль provisioning также с использованием Java-машины и т.д.), а рекомендации инженеров, говоривших о необходимости разнесения сервисов, откладывались в долгий ящик с аргументом «работает же».
Две из четырех предпосылок будущего сбоя уже были в наличии. Но даже в этом случае масштабных проблем удалось бы избежать, если бы не две трагических случайности, которые случились одновременно в самый неподходящий момент.
Незадолго до 1 апреля наконец удалось получить отдельный сервер для авторизационной БД с профилями абонентов. Как выяснилось позже, RAID-массив на этом сервере оказался дефектным, и на нем авторизация при определенном уровне нагрузки тормозила еще сильнее, чем на старом «железе». Ни на одной из более чем 100 других инсталляций «Гидры» эта ошибка не проявлялась из-за того, что в нормальных условиях сервис авторизации работает быстро и ресурсов хватает с большим запасом.
Непосредственным триггером аварии, вероятно, следует считать закончившееся место в табличном пространстве, которое привело к тому, что начали накапливаться изменения профилей. Как только свободное место вновь появилось, все эти изменения были обработаны и в дефектный RADIUS-сервер через системные очереди устремился поток репликационных сообщений, которые не смогли примениться.
Определенные подозрения о возможном баге возникали и до описываемой ситуации — периодически у некоторых единичных абонентов в базе сохранялись неправильные профили. Однако вычислить проблему до первого числа нового месяца не удалось — событие было очень редким и расширенное логирование не помогло вовремя «отловить» ошибку (в том числе по причине переезда на новый сервер).
Предотвращение проблем в будущем
Устранив сбой и разобравшись в его причинах, уже в спокойной обстановке мы внесли корректировки, призванные исключить повторение ситуации в будущем. Вот, что мы сделали:
- Прежде всего, в ActiveMQ была добавлена функциональность требования подтверждения доставки отправленных данных. При этом подобное подтверждение работает в кумулятивном режиме — сервер подтверждает получение не каждого сообщения, а некоторой их пачки (раз в пять секунд). Логика обработки сообщений поддерживает повторную обработку очереди начиная с определенного момента, даже если какие-то из данных уже попали в БД.
- Кроме того была увеличена частота отправки heartbeat-пакетов — вместо пяти секунд время увеличилось до нескольких минут. В дополнение к механизму heartbeat соединение к брокеру сообщений стало устанавливаться с опцией keepalive с небольшими интервалами проверки активности соединения (несколько десятков секунд против пары часов, устанавливаемой операционной системой по умолчанию).
- Также производились тесты, в ходе которых при отправке сообщений случайным образом перезапускались разные модули системы. В ходе одного из таких тестов какая-то часть данных все равно оказывалась потерянной. Тогда был заменен сам «движок» базы данных MongoDB — перешли на использование WiredTiger. Мы планировали сделать это раньше, но по случаю тестов решили совместить переезд.
Внесенные изменения позволили свести число потерянных пакетов к нулю и предотвратить возникновение подобных проблем в будущем даже в условиях очень «агрессивной среды».
Кроме того, по рекомендациям инженеров техподдержки «Латеры» сервисы системы были разнесены на разные серверы (деньги на них быстро нашлись). Это удалось успеть сделать до 1 мая — следующего дня массовых биллинговых операций.
Главный урок
Тревожные «звоночки», сигнализирующие о возможных проблемах, звучали и в марте, но выявить их до наступления планового всплеска активности не удалось. Если бы этого всплеска не было, или он произошел бы в другом месте — не на «тормозящем» RADIUS-сервере с максимальной скоростью последовательной записи 5 МБ/сек, то с высокой долей вероятности инженерам удалось бы локализовать проблему в апреле. Им не хватило буквально нескольких дней.
Все это подводит к выводу о том, что в том случае, если существуют подозрения на наличие не до конца понятных проблем с работоспособностью систем, а также ожидается всплеск активности, то стоит также быть готовым, что именно в этот момент все пойдет по максимально неблагоприятному сценарию. При наличии таких подозрений необходимо интенсивнее проводить поиск возможных проблем, чтобы успеть разобраться с ними до серьезного повышения нагрузки.
Другие технические статьи от «Латеры»:
