Приветствую, хабраюзер! Эта история началась со странного падения Python приложения. Сначала я не придал внимания данной проблеме: приложение запущено в Openshift и периодически падает. К такому поведению может приводить всякое, например, иногда ноды обновляют, а иногда случаются аварии и тогда одну или несколько нод выводят из эксплуатации. Однако со временем проблема стала регулярной и начала проявляться некоторая закономерность. При этом в Sentry не было каких-либо ошибок. Я был полностью уверен, что это какая-то типовая проблема и ее можно быстро решить, но как же я ошибался.

Как я уже сказал, в Sentry никаких ошибок не было, поэтому единственный способ что-то понять - это изучить логи. Долистав логи в ElasticSearch до нужного момента, я увидел странный traceback, который говорил, что упало не само приложение, а упал Python! Выглядел он примерно так:

Первая же мысль - скопировать ошибку, отправиться в 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, я сделал несколько предположений:

1. Где-то используется non-thread safe код, что маловероятно, ошибка нетипична.

2. Какая-то редкая проблема при использовании asyncio.gather.

3. Ошибка в какой-либо внешней библиотеке.

В самом приложении потоки не использовались, но использовался 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. Теперь можно было увидеть, что количество ссылок монотонно убывает.

Яснее не становилось... Детальное изучение логов показало, что уменьшение количества ссылок происходило при обработке сообщений. Далее были предприняты шаги для локализации проблемы в функции _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. В этом файле описаны все кодеки, которые используются для декодирования сообщений.

Как видно, все достаточно просто и понятно - определяем тип кодека и используем конкретный. Однако если спуститься ниже, то можно увидеть следующий код:

Три флага 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.