В данной статье я расскажу про жизненный цикл одной важной задачи - “Настроить сбор/парсер логов в Kubernetes”. Или “Почему мы решили написать свой оператор для сбора логов в Kubernetes”.

Оговорочка

Решений по логированию много. Скорее всего о каких-то я просто не знаю (а возможно даже не хочу знать). Эта статья - просто рассказ как я столкнулся с проблемой и к чему привела работа с ней.

Если у Вас есть “Лучшее” решение для логирования в Kubernetes - пишите о нем в комментариях.

Предистория

Как-то мне попался довольно важный и жирный кластер Kubernetes (фигово-сбаласнированный bare-metal, но работаем с тем, что имеем), в котором для сбора/парсинга логов использовался KFO и который абсолютно не справлялся с поставленной задачей. Однако с задачей отжирания ресурсов кластера Fluentd справлялся на ура.

Данный оператор поднимает одинаковые инстансы FluentD как DaemonSet на всех нодах кластера и собирает все, что указано в CRD fluentdconfigs или в ConfigMap fluentd-config.

Среднее потребление одного пода Fluentd - 800 mCPU (из-за того, что каждый инстанс стартовал с 1 worker’ом, который не умеет использовать больше 1 CPU) и 30 ГБ оперативы.

30 Гб оперативы - это много. В моменте можно было увидеть поды, которые кушают 50 Гб.

Происходит такое по довольно простой причине - буферы переполнены, FluetnD не справляется с нагрузкой.

Посмотреть как чувствуют себя буферы Fluentd можно с помощью метрик: fluentd_output_status_buffer_stage_length, fluentd_output_status_buffer_stage_byte_size - данные о Stage буфере

fluentd_output_status_buffer_queue_length, fluentd_output_status_queue_byte_size - данные о Queue буфере.

Почитать про буферы fluentd можно тут

Быстро решение - увеличить количество worker’ов в инстансах Fluentd и надеятся, что он справится. (Про workers можно почитать тут) Однако в итоговой конфигурации Fluentd используются плагины, которые не умеют в Worker’ы, а оператор KFO не умеет справляться с этой проблемой. Просить разработчиков переписывать их конфиги для сбора логов на новые, без уверенности, что это реально поможет - не очень хотелось.

Выбираем решение для логирования

В итоге было принято решение мигрировать на новую систему сбора и парсера логов.

Основные критерии:

1. Возможность настройки сбора логов не только приложений, запущенных в Kubernetes, но и c лог-файлов на нодах кластера Kubernetes. (Например kubernetes audit)

2. Возможность сбора логов journald (kubelet, crio/containerd и т.д.)

3. Разработчики, живущие в кластере, должны иметь возможность сами настраивать ОТКУДА собирать логи, КАК их обрабатывать и КУДА отправлять. Это необходимо, т.к. разработчики довольно часто деплоят новые приложения, у которых разные форматы логов. Идеально было бы внедрить единый формат логов для всех приложений, например json, но давайте на чистоту - такой идеал редко достижим и требует работы очень многих людей. (Так же, если необходимы логи каких-то готовых (опенсорсных) приложений, не факт, что эти приложения умеют в json, а если умеют, не факт, что делают это корректно. Даже сам kubernetes страдает от этого. Ну или попробуйте настроить nginx, чтобы все его логи были в валидном json). Все же были попытки быстро “перепилить” формат логов для продуктовых приложений, но при изменении формата логирования PHP с обычного текста на json словили нехилое падение производительности этого PHP приложения. К тому же такой функционал сильно разгрузит команду DevOps’ов, которым необходимо в ручном формате настраивать сбор и парсинг логов разработчиков.

4. Разработчик должен как-то видеть, когда задеплоенные им правила для логирования невалидны.

5. Система не должна иметь внешних вспомогательный систем. (Типа kafka). Это ограничение связано с тем, что у заказчика очень много кластеров Kubernetes (больших и маленьких) в разных ЦОДах. Если ли бы мы столкнулись с централизированной инфраструктурой, то, скорее всего, развернули классический стек EFK и гоняли бы логи через kafka.

(На данном этапе мы не учли другие важные критерии, из-за чего столкнулись с проблемами, но об этом ниже)

Возможно, это довольно специфические требования, но из них выходит, что нам точно нужен Kubernetes оператор (чтобы удовлетворить пункт #3). Был выбран - logging-operator. Хотелось бы сказать, что мы выбрали именно это решение, так как провели кучу тестов и именно этот оператор показал себя с наилучшей стороны, но увы все намного прозаичней. Logging operator был выбран тупо из-за отсутствия альтернатив. На рынке OpenSource решений просто нет ничего другого, что хотя бы приближенно нас устраивало.

Logging operator работает примерно следующим образом: На все ноды кластера с помощью DaemonSet’a устанавливается FluentBit, которые собирает указанные логи и отправляет их в “кластер”(Deployment) FluentD, который парсит и обрабатывает логи, а потом направляет куда нужно.

Хоть мне очень нравится функционал и реализация Logging Operator’a, у него есть ощутимые недостатки. Сначала они казались незначительными, но со временем эксплуатации оператора находились все более серьезные проблемы.

Поделю проблемы на 3 волны:

Первая волна проблем, которая была очевидна еще до начала внедрения Logging operator’а:

• FLuentD. Опять он. Да, в решении Logging operator’a можно распределить нагрузку на FluentD просто заскейлив StatefulSet. Но это все тот же Fluentd

• У Logging operator’a довольно странный механизм контроля и обновления управляемых компонентов. Рассмотрим на примере StatefulSet FluentD. Оператор генерирует StatefulSet и создает его, если его еще нет в кластере. При создании он в специальную аннотацию banzaicloud.com/last-applied запихивает сгенерированный StatefulSet в base64-формате. При следующей “проверке” StatefulSet’а, оператор будет сравнивать то, что он сгенерил с тем, что находится в аннотации, и если будут различия - обновит StatefulSet. То есть если кто-то что-то руками поменяет в StatefulSet’e - оператор этого даже не заметит и не восстановит правильное состояние. И так абсолютно со всеми компонентами, которые раскатывает и контролирует оператор. Подробнее о том, как это работает (написано в блоге BanzaiCloud.

• Если разработчик задеплоит в кластер невалидный конфиг для FluentD случится следующее: У CustomResource logging (который отвечает за разворачивание FluentBit и FluentD) в status’e пропишется, что формируемый конфиг невалидный. И пока ошибочная настройка не будет исправлена - новые настройки от других разработчиков не будут применяться. То есть конфигурация для сбора и парсинга логов “зависнет” в последнем “валидном” состоянии и никакие новые настройки применяться не будут. Так же у разработчика нет никаких инструментов, чтобы узнать, что его конфиг невалидный (кроме как увидеть глазами, что его логи не долетают куда надо). То есть пункт #4 из требований - не исполняется.

Мы решили смириться с этими недостатками и мигрировать нашу систему логгирования с KFO на Logging-operator.

Однако в процессе эксплуатации столкнулись со второй волной проблем:

• У logging-operator’а, точно так же как и у KFO, нет под капотом обработки конфига FluentD, если используется больше одного worker’а. То есть один pod FluentD не будет кушать больше 1 CPU. Вроде не так страшно, учитывая, что мы теперь можем скейлить Fluentd и размазывать нагрузку

• Если у вас слишком большой файл конфигурации для Fluentd - он не помещается в Secret (Лимит - 3Мб). А используемые компоненты, которые “подсовывают” файл конфигурации для FluentD не умеют его сжимать\разжимать, как это сделано, например, у Prometheus operator’а. Для решения этой проблемы пришлось пилить собственный Config-reloader и делать Pull Request в Logging operator.

• Если у вас ДЕЙСТВИТЕЛЬНО большой файл конфигурации, то даже заархивированный он не поместится в аннотацию banzaicloud.com/last-applied про которую я писал выше. Лимит размера аннотации в Kubernetes - 262144 байта.

Пока Pull Request не будет принят, приходится жить на собственном форке Logging Operator’a.

В итоге мы имеем небольшую кучу проблем, но некоторые решаемы, а некоторые терпимы. Однако в один прекрасный момент мы сталкиваемся с третьей волной проблем, которая уже стала критической:

• У нас в кластере Kubernetes много пользователей, которые хотят собираться свои логи. Как итог - сгенерированный конфиг для FluentD весит 300мб, На “прочитывание” такого файла у FluentD уходит 2 минуты. Эти 2 минуты FluentD перестает слушать порт и FluentBit получает постоянные ошибки:

  [2022/09/30 13:06:38] [ warn] [engine] failed to flush chunk '1-1664534047.977042867.flb', retry in 100 seconds: task_id=646, input=tail.0 > output=forward.0 (out_id=0)
  [2022/09/30 13:06:38] [ warn] [engine] failed to flush chunk '1-1664537319.791436589.flb', retry in 75 seconds: task_id=440, input=tail.0 > output=forward.0 (out_id=0)
  [2022/09/30 13:06:38] [ warn] [engine] failed to flush chunk '1-1664534482.915350881.flb', retry in 83 seconds: task_id=84, input=tail.0 > output=forward.0 (out_id=0)
  [2022/09/30 13:06:38] [ warn] [engine] failed to flush chunk '1-1664537526.483173846.flb', retry in 9 seconds: task_id=1308, input=tail.0 > output=forward.0 (out_id=0)
  [2022/09/30 13:06:38] [ warn] [engine] failed to flush chunk '1-1664534736.954314071.flb', retry in 111 seconds: task_id=1839, input=tail.0 > output=forward.0 (out_id=0)
  

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

• Вторая проблема нашлась в FluentBit. В Логах постоянно проскальзывают ошибки:

  [2022/10/26 12:58:58] [ warn] [input] tail.0 paused (mem buf overlimit)
  [2022/10/26 12:58:59] [ warn] [input] tail.0 paused (mem buf overlimit)
  [2022/10/26 12:59:04] [ warn] [input] tail.0 paused (mem buf overlimit)
  [2022/10/26 12:58:49] [ warn] [input] tail.0 paused (mem buf overlimit)
  

  Повышение размера буфера до 1Gb снизила частоту появления ошибок, но ошибки остались. Есть простой фикс - увеличить частоту отправки данных из буфера input в буфер output (Вот в этой статье неплохо об этом написано). Делается это с помощью поля Flush, который имеет формат seconds.nanoseconds. Однако у Logging-operator’a это поле в формате Integer. Соответственно мы не можем поставить меньше 1 секунды (дефолтного значения, который устанавливает Logging operator). То есть мы можем решить эту проблему, используя ванильный FluentBit, но раскатывая его через Logging-operator - хрен нам. (Pull Request на решение этой проблемы где-то в пути)

• Третья проблема связана с самой первой проблемой, описанной в первой волне недостатков logging-operator’a. Мы работаем с FluentD :) Не буду разглагольствовать. Суть в том, что FluentD тупо не вывозит нагрузку. Возможно это связано с тем, что генерируется СЛИШКОМ много логов (по мнению FluentD), возможно много ресурсов уходит на процессинг логов. Возможно проблема связана еще с чем-то. Но вот как выглядит картина, когда у нас “много” логов, и 40 подов FluentD:
  

  • FluentBit собирает логи с нод и отправляет в FluentD. В Логах FluentBit периодически проскальзывают ошибки:

    [2022/10/26 12:46:29] [ warn] [engine] failed to flush chunk '1-1666788378.238439157.flb', retry in 8 seconds: task_id=1004, input=tail.0 > output=forward.0 (out_id=0)
    [2022/10/26 12:46:29] [ warn] [engine] failed to flush chunk '1-1666788378.885702920.flb', retry in 10 seconds: task_id=916, input=tail.0 > output=forward.0 (out_id=0)
    [2022/10/26 12:46:29] [ warn] [engine] failed to flush chunk '1-1666788378.893210979.flb', retry in 7 seconds: task_id=943, input=tail.0 > output=forward.0 (out_id=0)
    [2022/10/26 12:46:29] [ warn] [engine] failed to flush chunk '1-1666788378.962421224.flb', retry in 10 seconds: task_id=994, input=tail.0 > output=forward.0 (out_id=0)
    [2022/10/26 12:46:29] [ warn] [engine] failed to flush chunk '1-1666788379.492231948.flb', retry in 8 seconds: task_id=1003, input=tail.0 > output=forward.0 (out_id=0)
    [2022/10/26 12:46:29] [ warn] [engine] failed to flush chunk '1-1666788356.895153182.flb', retry in 15 seconds: task_id=878, input=tail.0 > output=forward.0 (out_id=0)
    [2022/10/26 12:46:29] [ warn] [engine] failed to flush chunk '1-1666788357.885380444.flb', retry in 14 seconds: task_id=855, input=tail.0 > output=forward.0 (out_id=0)
    [2022/10/26 12:46:29] [ warn] [engine] failed to flush chunk '1-1666788362.277494203.flb', retry in 8 seconds: task_id=949, input=tail.0 > output=forward.0 (out_id=0)
    [2022/10/26 12:46:29] [ warn] [engine] failed to flush chunk '1-1666788361.891491363.flb', retry in 15 seconds: task_id=889, input=tail.0 > output=forward.0 (out_id=0)
    

    (Уточню, что на момент появления этих ошибок у Logging-operator’а выключен configcheck. Соответственно FluentD не обновляется каждые 10 минут и ошибка не связана с первой из 3 волны)

  • Ошибки эти связанны с тем, что FluentD тупо не успевает читать сообщения и у него накапливаются сообщения в сокете, который он слушает.

    $ netstat -ntpl
    Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name
    tcp        0      0 127.0.0.1:24444         0.0.0.0:*               LISTEN      7/ruby
    tcp        0      0 0.0.0.0:24231           0.0.0.0:*               LISTEN      166916/ruby
    tcp     1022      0 0.0.0.0:24240           0.0.0.0:*               LISTEN      166916/ruby
    tcp        0      0 :::9533                 :::*                    LISTEN      -
    

  Логично, что у нас кластер FluentD не справляется с нагрузкой. Что нужно сделать? Правильно - заскейлить. (Сначала посмотреть метрики работы FluentD и его буферов, увидеть ужас, и реально заскейлить). В Issue на эту тему сказали тоже самое. Окей. Скейлим кластер FluentD до 100 и видим, что у нас НИЧЕГО НЕ ИЗМЕНИЛОСЬ. Только ресурсов кластера теперь жрется в 2 раза больше. Я бы доскейлил количество подов FluentD до 200, но ресурсы в кластере K8s не резиновые.

Вывод

Вывод простой - “Мы в дерьме”.

А если смотреть позитивно, то мы сделали следующие выводы:

1. Необходимо более тщательно и разнообразно проверять технические решения, перед тем, как тащить их в прод и предлагать пользователям. Не стоит надеятся, что Опенсорс решение с 1к звезд сможет вас удовлетворить.

2. Необходимо другое решение. А поскольку других удовлетворяющих требованиям решений нет - необходимо создавать свое.

Вот именно по этому мы решили написать свой Оператор на базе Vector.