В данной статье я расскажу про жизненный цикл одной важной задачи - “Настроить сбор/парсер логов в 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 не умеет справляться с этой проблемой. Просить разработчиков переписывать их конфиги для сбора логов на новые, без уверенности, что это реально поможет - не очень хотелось.
Выбираем решение для логирования
В итоге было принято решение мигрировать на новую систему сбора и парсера логов.
Основные критерии:
Возможность настройки сбора логов не только приложений, запущенных в Kubernetes, но и c лог-файлов на нодах кластера Kubernetes. (Например kubernetes audit)
Возможность сбора логов journald (kubelet, crio/containerd и т.д.)
Разработчики, живущие в кластере, должны иметь возможность сами настраивать ОТКУДА собирать логи, КАК их обрабатывать и КУДА отправлять. Это необходимо, т.к. разработчики довольно часто деплоят новые приложения, у которых разные форматы логов. Идеально было бы внедрить единый формат логов для всех приложений, например json, но давайте на чистоту - такой идеал редко достижим и требует работы очень многих людей. (Так же, если необходимы логи каких-то готовых (опенсорсных) приложений, не факт, что эти приложения умеют в json, а если умеют, не факт, что делают это корректно. Даже сам kubernetes страдает от этого. Ну или попробуйте настроить nginx, чтобы все его логи были в валидном json). Все же были попытки быстро “перепилить” формат логов для продуктовых приложений, но при изменении формата логирования PHP с обычного текста на json словили нехилое падение производительности этого PHP приложения. К тому же такой функционал сильно разгрузит команду DevOps’ов, которым необходимо в ручном формате настраивать сбор и парсинг логов разработчиков.
Разработчик должен как-то видеть, когда задеплоенные им правила для логирования невалидны.
Система не должна иметь внешних вспомогательный систем. (Типа 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к звезд сможет вас удовлетворить.
Необходимо другое решение. А поскольку других удовлетворяющих требованиям решений нет - необходимо создавать свое.
Вот именно по этому мы решили написать свой Оператор на базе Vector.
Комментарии (9)
OkGoLove
11.11.2022 07:14promtail + loki - полет отличный
chemtech
12.11.2022 07:59А вы не решали такую задачу: добавление label из Detected Fields ?
zvlb Автор
12.11.2022 08:27Нет. Все проходящие логи либо не трансформировались, либо json, либо полностью разрезались регуляркой.
Из issue я не очень понимаю, что человек имеет в виду под
I have 2 field in log lines
Что значит «поля» в логах?
Звучит так, будто человеку нужна регулярка, но он “don’t want”
chemtech
12.11.2022 08:37Detected Fields обычно это key из json.
Вот картинка для примера.
https://stackoverflow.com/questions/65776393/grafana-explore-filtering-on-parsed-field
Иногда требуется найти лог определенного пользователя (username). А искать по всем логам очень долго. По идее можно username добавлять в label. По label поиск будет быстрее.zvlb Автор
12.11.2022 12:19Тогда тут, скорее всего, обсуждается как это сделать, работая именно с Loki.
С Loki у меня опыт работы близок к 0, по этому вряд ли смогу подсказать
zvlb Автор
12.11.2022 12:43А это и не ко мне вопрос был. Простите)
chemtech
12.11.2022 17:52Вопрос был всем. Похоже нашел как это сделать - https://stackoverflow.com/questions/58564836/how-to-promtail-parse-json-to-label-and-timestamp
chemtech
Спасибо! А установка с помощью helm чарта планируется?
zvlb Автор
Pull requests уже есть. Там дорабатываются мелочи