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

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

Как проблема выглядит в логах. Traceback
Как проблема выглядит в логах. 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, я сделал несколько предположений:

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

Отображение ситуации в 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
Метод декодирования последовательности байт в kafka-python

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

Выбор первой из доступных библиотек для декодирования LZ4
Выбор первой из доступных библиотек для декодирования 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.

Комментарии (11)


  1. kryvichh
    13.01.2022 13:44

    Интересное расследование.

    Получается, простой командой можно положить любую Python-программу. А почему return Py_NONE; не инкрементирует количество ссылок?


    1. LevZaplatin Автор
      13.01.2022 14:32
      +2

      В документации написано, что если вы возвращаете Py_none, то самостоятельно должны следить за ссылками либо использовать Py_RETURN_NONE.

      Все это описано в оф. документации, к сожалению, я не работаю с модулями на С и не могу более детально прокомментировать.


      1. kryvichh
        13.01.2022 22:53

        Да, я сразу глянул документацию, перед тем как спросить.


  1. MentalBlood
    13.01.2022 16:03

    Наверное самая легкосовершаемая ошибка при биндинге C-кода к Python


  1. enkryptor
    14.01.2022 00:37

    А почему пустой цикл приводил к уменьшению количества ссылок?


    1. LevZaplatin Автор
      14.01.2022 09:34

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


  1. soymiguel
    14.01.2022 00:45
    +10

    Спасибо большое, читается с удовольствием. Хабр, как известно, давно уже не торт, а нытье про токсичность с абузерами (что бы это ни значило), и вот такие исчезающие пироженки с вишенками - это прям ностальгия, как на десять лет назад вернуться. Реальная - без драм масштабов вселенной - проблема, грамотное изложение, настоящее решение, ничей хрупкий дивный внутренний мир не пострадал, никто не расплакался и не выгорел по дороге от кофе-машины до офисного пинг-понга - и все это в одном посте на хабре в 2022 году. Идеально.


  1. quarckster
    14.01.2022 10:01
    +1

    Большое спасибо за статью. Я посмотрел на PR, и получается что он висел 5 лет! Сколько же крови эта библиотека выпила у людей, которые ей пользовались?


  1. amakhrov
    14.01.2022 21:51

    Статья - огонь!

    Я только не совсем понял мораль басни. Что в описанном случае было нарушением принципа "явное лучше неявного" (с которым я, конечно же, согласен целиком и полностью)?


    1. LevZaplatin Автор
      14.01.2022 21:55

      Неявным является выбор конкретной реализации. Было бы лучше, если при использовании мы могли бы выбрать конкретную библиотеку.
      Например, если бы был метод setCodec() или useLZ4fCodec()


      1. amakhrov
        14.01.2022 22:04

        Ааа. Понял! По статье я решил, что тип кодека динамически определяется, потому что так надо. Но сейчас заглянул в исходник - и код там просто пробует импортировать разные библиотеки и для декодирования использует то, что нашлось в наличии. Согласен - очень неочевидно.