[prog.bugs] Не ходят сообщения? Отжирается память?

Через пару дней свалю в отпуск и заброшу блог на несколько недель. Напоследок расскажу поучительную, на мой взгляд, историю.

Некоторое время назад случилась не просто жопа, а просто охеренных рамеров жопа с большой буквы Ж. Утром телефонный звонок из нашей техподдержки (а это уже показатель чего-то из ряда вон). По словам дежурного наш комплекс работает как-то странно: в одну сторону сообщения ходят, в другую нет. Конкретной причины никто не знает, толком что происходит никто не знает, что делать не понятно и вообще полный ахтунг, особенно со стороны клиентов.

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

Первый лучик света проклюнулся когда дошла очередь до анализа консольных логов компонента – потоки stdout и stderr перехватываются и укладываются в отдельный файл. Размер этого файла был более 200Mb и постоянно увеличивался. Процентов 95% его содержимого составляли сообщения об ошибке о том, что не удалось сконвертировать текст из UCS-2 в UTF-8.

Нашли место программы, в котором эта ошибка фиксируется. Проанализировали конфигурацию компонента. Оказалось, что трафик одного из клиентов подвергается дополнительному анализу. И как раз сегодня этот клиент запустил новый поток данных, при обработке которых и диагностируется ошибка.

Выяснилось, что в этом фрагменте кода есть ошибка – префикс данных клиента выкусывается неправильно, после чего некорректный UCS-2 текст (в нем оказывалось нечетное количество байт) отдается внешней библиотеке на перекодировку. Та диагностирует проблему, мы эту диагностику посылаем в stderr. Отсюда и строки в консольном логе.

Сразу же вносятся правки, новая версия заливается на сервера, проблема исчезает, все работает шустро, память не течет. Возникает первая версия – внешняя библиотека при обработке некорректной UCS-2 последовательности портит память. Причем так, что мгновенного сбоя приложения не происходит, зато начинается утечка памяти.

Начинаются эксперименты по ее проверке. Но все они завершаются неудачно. Какие бы корявые строки не подсовывали внешней библиотеке, в каком бы количестве, в каком бы окружении… Нет ни растрела, ни утечки, все пучком.

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

Как ни стыдно в этом признаваться, но в течении трех или четырех дней даже намеков на какую-нибудь реальную версию не было. Первые наметки появились когда взгляд случайно зацепился за временные метки в сообщениях консольного лога. Они имели странное распределение – сначала с десяток записей в течении 3-5 миллисекунд, затем пауза в 200-300 миллисекунд, затем следующая пачка записей, вновь за 3-5 миллисекунд, потом опять пауза.

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

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

Почему так?

Оказалось потому, что программа-монитор, из-под которой запускается компонент, которая следит за его работой и, заодно перехватывает stdout/stderr, не может справиться с темпом записи в stderr порядка 100-150 строк в секунду. Она ловит десяток, записывает их в свой лог, берет паузу в несколько сотен миллисекунд, затем ловит еще десяток и т.д. А поскольку в нашем компоненте запись в stderr синхронная, то и наш компонент стал регулярно засыпать на несколько сотен миллисекунд.

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

Расход памяти так же объяснялся очень просто: поскольку тормозил только один агент, а в SObjectizer-4 нет средств для защиты агентов от перегрузки, то остальные агенты постоянно грузили его новыми сообщениями, которые копились в очереди тормознутого агента и именно они вызывали расход памяти.

Вот так мозаика и сложилась: клиент дал новый большой поток данных, сработало правило по его анализу, это правило спровоцировало древний баг в коде, что привело к диагностике о невозможности конвертации UCS-2, которая шла в stderr, который перехватывался программой, неспособной делать это достаточно быстро.

Что интересно: когда я писал обработку ошибок конвертации текста из одной кодировки в другую, у меня был выбор, отправлять ли сообщение об этом в лог приложения, либо в stderr. Я остановился на stderr чтобы не делать лишней зависимости для библиотеки, в которой эта конвертация делалась.

Что еще более интересно, так это то, что древний баг с неправильным вырезанием префикса из данных был даже покрыт unit-тестами, причем несколькими. Просто и unit-тесты я сам писал, поэтому и в них ошибся на ту самую –1 (как это обычно бывает у программистов с +1 и –1).

Ну а самых опытных читателей, я думаю, вовсе не удивит то, что злополучное правило, которое инициировало дополнительный анализ трафика клиента, было оставлено в конфигурации по недосмотру. Т.е. когда-то оно было актуально, но те времена давно прошли, а правило так и осталось. Может быть и срабатывало время от времени эпизодически, но на глаза не попадалось. Ну а в этот день звезды сложились.

PS. По некоторым причинам названия упомянутых в тексте компонентов, библиотек и программ огласить не могу.