Python: Явное лучше неявного
Приветствую, хабраюзер! Эта история началась со странного падения Python приложения. Сначала я не придал внимания данной проблеме: приложение запущено в Openshift и периодически падает. К такому поведению может приводить всякое, например, иногда ноды обновляют, а иногда случаются аварии и тогда одну или несколько нод выводят из эксплуатации. Однако со временем проблема стала регулярной и начала проявляться некоторая закономерность. При этом в Sentry не было каких-либо ошибок. Я был полностью уверен, что это какая-то типовая проблема и ее можно быстро решить, но как же я ошибался.
Как я уже сказал, в Sentry никаких ошибок не было, поэтому единственный способ что-то понять — это изучить логи. Долистав логи в ElasticSearch до нужного момента, я увидел странный traceback, который говорил, что упало не само приложение, а упал Python! Выглядел он примерно так:
Как проблема выглядит в логах. Traceback
Первая же мысль — скопировать ошибку, отправиться в Google и найти заветный ответ на Stackoverflow. Но не все так просто — выдача была достаточно скудной и все описанные проблемы никак не пересекались с моим стеком. После значительного количества времени, дойдя до десятой страницы поисковой выдачи, я потерял надежду на быстрое решение. Если коротко, то причина была в том, что в какой-то момент времени количество ссылок на None
становилось равным нулю и Python более не мог их удалять, что приводило к панике.
В обычной практике я не сталкивался с подобными проблемами и, честно говоря, не знал с какой стороны подойти к решению, поэтому в данной ситуации я предположил 3 потенциальные причины:
ошибка в самом Python, что крайне маловероятно, но возможно;
ошибка в приложении;
ошибка в какой-либо внешней библиотеке.
Изначально использовался Python 3.9, смены версии на 3.8 и 3.10 ни к каким изменениям не привели. Что с достаточно высокой вероятностью исключало проблему в Python, оставались два других подозреваемых — приложение и внешние библиотеки.
В чем суть самого приложения — все прозаично, это классический consumer, который читает топик Kafka и каким-либо образом обрабатывает полученные сообщения. Реализация приложения на момент первичного анализа была примерно следующая — подключаемся к Kafka, вычитываем N сообщений, запускаем N корутин на обработку, выполняя функцию _batch_processing
, и с помощью asyncio.gather
дожидаемся выполнения всех корутин, затем начинаем все сначала. При изучении traceback падения, можно увидеть, что используются несколько потоков, а само приложение падало на функции _batch_processing
. Исключив из подозреваемых сам Python, я сделал несколько предположений:
Где-то используется non-thread safe код, что маловероятно, ошибка нетипична.
Какая-то редкая проблема при использовании asyncio.gather.
Ошибка в какой-либо внешней библиотеке.
В самом приложении потоки не использовались, но использовался sentry_sdk
, который использует потоки для своей работы, и jaeger-client-python
, который, в свою очередь, использует threadloop
от Tornado. Были отключены sentry_sdk
и jaeger-client-python
, также был отключен prometheus-client
. К сожалению, это не привело к положительному результату. Приложение по-прежнему продолжало падать.
Исключив первый пункт, я перешел ко второму. Изначально мне не нравилась реализация приложения с периодическим запуском большого количества корутин и ожидания их c помощью asyncio.gather
. Поэтому код был значительно переработан и был удален asyncio.gather
, вместо этого были созданы фоновые задачи и очереди. Повторные тесты показали, что в такой конфигурации приложение стало падать еще чаще… Как выяснилось позже, производительность сильно выросла и поэтому приложение стало чаще падать. Отсюда был сделан вывод, что проблема напрямую зависит от количества потребляемых сообщений.
Следующее, что пришло на ум — нужно как-то локализовать проблему. Ничего проще, чем просто расставить в коде логгеры с выводом количества ссылок, в голову не пришло. Поэтому был создан простой класс, который позволял считать количество ссылок.
class ReferenceCounter:
def __init__(self):
self.count = sys.getrefcount(None)
self.previous_count = 0
def get_diff_count(self):
self.previous_count = self.count
self.count = sys.getrefcount(None)
return f'count: {self.count}, change: {self.count - self.previous_count}'
ref_counter = ReferenceCounter()
# Во всех важных местах был вставлен следующий код
logger.info(ref_counter.get_diff_count())
После того как были внесены изменения, в логах появились примерно следующие сообщения:
Пример лога со счетчиком ссылок
Как видно, из таких логов понятнее в чем причина падения не стало и на небольших объемах проблема не проявлялась. С другой стороны, хотелось видеть с какой скоростью и как часто ссылки убывают. Были добавлены Prometheus метрики и настроен вывод в Grafana. Теперь можно было увидеть, что количество ссылок монотонно убывает.
Отображение ситуации в Grafana
Яснее не становилось… Детальное изучение логов показало, что уменьшение количества ссылок происходило при обработке сообщений. Далее были предприняты шаги для локализации проблемы в функции _batch_processing
, однако даже пустая лямбда-функция приводила к уменьшению количества ссылок на None
объект. Стоит заметить, что перед обработкой сообщений использовалась внешняя библиотека marshmallow, которая применялась для валидации сообщений. В репозитории marshmallow
встречались тикеты с утечками памяти и похожими проблемами. Отключение абсолютно всех функций валидации и обработки не привело к какому-либо положительному эффекту.
for message in consumer:
pass
И даже больше — пустой цикл приводил к уменьшению количества ссылок!
В качестве клиентской библиотеки для работы с Kafka использовалась aiokafka
. Но эта библиотека была вне подозрений, ведь она используется в нескольких десятках проектов и жалоб на данную библиотеку не было. Я начал проверять все свои проекты, которые используют aiokafka
: в некоторых проектах версии библиотеки совпадали с версией проблемного проекта, но ни в одном проекте я не смог найти хоть что-то похожее на проблему, с которой столкнулся. Приложения работают месяцами без перезагрузки и все в порядке. Это заставило меня взять небольшую паузу и подумать, а в чем же может быть тогда проблема, если:
версии Python совпадают;
версии aiokafka совпадают;
версии Docker образов, на основе которых производится сборка, совпадают;
все контейнеры запускаются в единой среде.
Очевидно, что проблема как-то связана с aiokafka, но версии самой библиотеки не отличаются, поэтому я начал сравнивать версии библиотек, указанных в зависимостях и они также были идентичны. Сверку я производил следующим образом: взял список библиотек через pip freeze
из корректно работающего образа и из проблемного образа, нашел пересечения по именам библиотек и сравнил — все совпало. Я несколько раз сверил хеши базовых Docker образов и, на всякий случай, пересобрал работающий проект, после чего проверил его на предмет уменьшения количества ссылок и нет… утечка ссылок сохранилась.
В этот момент я совсем перестал понимать, что происходит. Но однозначно понимал, что магии не существует (и Деда Мороза тоже) и всему должно быть рациональное объяснение. Поэтому начал детальный анализ всей библиотеки aiokafka. Было понятно, что основная проблема возникает при чтении данных из топика. Как вообще происходит взаимодействие с Kafka — мы подключаемся к топику, здесь опустим как именно, дальше мы получаем набор байт, затем мы должны определить нужно ли декодировать последовательность байт или нет. Дело в том, что в большинстве случаев данные в Kafka передаются в сжатом состоянии в четырех возможных форматах — GZip, Snappy, LZ, Zstd. Изначально в топик передавались данные в Zstd формате, затем было принято решение перейти на LZ.
При детальном изучении логики работы aiokafka
я дошел до библиотеки kafka-python
. Если быть точнее, то до файла codec.py
. В этом файле описаны все кодеки, которые используются для декодирования сообщений.
Метод декодирования последовательности байт в kafka-python
Как видно, все достаточно просто и понятно — определяем тип кодека и используем конкретный. Однако если спуститься ниже, то можно увидеть следующий код:
Выбор первой из доступных библиотек для декодирования LZ4
Три флага lz4
, lz4f
, lz4framed
соответствуют трем различным библиотекам — lz4, lz4tools и py-lz4framed. В рекомендациях aiokafka
указана библиотека lz4 и во всех мною созданных проектах использовалась именно эта библиотека. Однако проверив проблемный проект, я обнаружил, что в действительности используется lz4tools
. Тут же заменил библиотеку на lz4
, пошел проверять баг и, как вы уже, наверное, догадались, проблема исчезла! Затем я попробовал обновить версию lz4tools
c 1.2 до 1.3 (latest) и использовать ее, но, к сожалению, это не привело к положительному результату. Поэтому я оставил lz4
и на этом задача была закрыта.
Итак, проблема была решена. Проект получил требуемую стабильность и работает по сей день без каких-либо зависаний и самопроизвольных перезапусков. Но мне как инженеру было интересно, в чем же конкретно проблема в lz4tools
?
Для этого я скачал исходники lz4tools
, пересобрал библиотеку и написал простой тест на проверку утечки ссылок.
import sys
import unittest
import lz4f
class TestLZ4File(unittest.TestCase):
def test_refcount(self):
start = sys.getrefcount(None)
ctx = lz4f.createDecompContext()
lz4f.freeDecompContext(ctx)
self.assertEqual(start, sys.getrefcount(None))
if __name__ == '__main__':
unittest.main()
Внезапно для меня тест был пройден. Сначала подумал, что я неправильно написал тест, но затем я переключился на ветку библиотеки с master
на тег 1.3 (latest) и тест был успешно провален. Кто-то из разработчиков уже внес изменения, но мне хотелось найти первопричину проблемы. Поэтому я проверил некоторый объем коммитов для того, чтобы найти нужный. Как оказалось, это был последний коммит и все изменения были лишь в трех строках кода, в которых возвращались только ссылки без изменения счетчика ссылока.
Коммит, который исправляет проблему с утечкой ссылок
Для себя лично я лишь в очередной раз подтвердил один из пунктов The Python Zen
Explicit is better than implicit.