Observability. Часть 1, про логи

"Пираты журнального моря"

Автор — Игорь Овсянников, декабрь 2023 г. DevOps инженер в GFN.AM, преподаватель курса DevOps в OTUS.

Каждый раз, решая инцидент или аварию в инфраструктуре, я задумывался: а можно ли было это предусмотреть? Можно ли было быстрее узнать о проблеме, самостоятельно, а не от недовольных клиентов? Сейчас я считаю, что можно, с хорошо настроенным мониторингом и observability pipelines.

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

Про логи

Это диагностические данные в формате текста. Пожалуй, первый известный истории формат диагностических данных от систем, за исключением перегоревших ламп в ламповых ЭВМ и подобного.

Поскольку логи обычно пишутся в формате текста, конечного формата как такового нет: Да, есть отметка о времени, но это может быть как Unix timestamp, так и дата в ISO 8601 / RFC 3339. В квадратных скобках? Да, давайте так! А тут у нас будет имя потока. И затем сообщение. О, а давайте ошибки будем писать уже в другом формате! И ещё на несколько строк, ну, чтобы парсить было сложнее! ОК, есть syslog, есть Journald log. Но это лишь одни из десятка стандартов, и лучше ситуация вряд ли когда-либо станет (см. xkcd 927).

Можно задуматься, нужны ли вообще стандарты логов или какой-либо контракт в протоколах, если логами пользуются, как правило, только сами разработчики, авторы программ. Это, пожалуй, зависит индивидуально от команды. Кто у вас потребитель логов — разработчики или Ops-ы и SRE? Если разработчик написал лог через println, значит, ему так удобно. Если логами пользуются и другие инженеры, то рекомендую договориться с программистами о контракте логов. Чтобы если бэкенд таймаутился при подключении к внешней системе, то выводился бы и URL системы. Так будет понятно, биллинг это или авторизация :)

В любом случае, при стандартах и общих протоколах всегда живётся легче. Особенно при пересылке логов в системы и БД.

Ландшафт систем логирования, 2023 год

Холст, Open Source, масло

Современный стек мониторинга делится на три компонента: сборщики данных (коллекторы), хранилища (СУБД и полуСУБД), и системы визуализации и дашбордов, плюс опционально алертинг. Ниже представлены все такие инструменты из мира OSS, которые мне известны.

Сборщики логов:

• Logstash;

• Fluentd;

• Fluent bit;

• Vector;

• Filebeat;

• Elastic Agent;

• Promtail.

Хранилища:

• Elasticsearch

• Object storage (S3, minio, etc);

• Kafka;

• ClickHouse;

• Grafana Loki;

• Manticore Search;

• PostgreSQL;

• HDFS.

Визуализация:

• Kibana;

• Grafana;

• Metabase;

• Redash;

• Apache Superset;

• DataLens.

Материал, который вы читаете, лишь первая часть из цикла статей Observability. Здесь будет рассмотрены:

• Fluent bit;

• Vector;

• Elasticsearch и Kibana;

• Loki и Grafana.

В следующей будут показаны примеры работы и производительность:

• Promtail и Loki;

• Loki (бенчмарки запросов);

• Fluent bit/Vector/Promtail и Loki (JSON);

• Logstash + Elasticsearch;

• Fluentd + Elasticsearch;

• Filebeat и Elastic Agent + Elasticsearch.

А также есть особые гости: приложения, которые будут генерировать более-менее реальные данные.

1. Feeder, сервис на Go, который читает дамп галактики из игры Elite: Dangerous за авторством Spansh, и пересылает данные о системах в другие сервисы. В качестве фреймворка для логов использует log из встроенной библиотеки.

2. Statistics, веб-сервис на Ktor, Kotlin-фреймворке. Он получает JSON-ы и разбирает их, выдавая в логи общую статистику (сколько планет, сколько звёзд, и т.п.). В качестве подсистемы журналирования использует JVM-библиотеки SLF4J и Logback.

3. Storage, просто записывает полученные данные в Kafka. Написан на Flask, Python-фреймворке.

В почти каждом из сервисов присутствуют ошибки. Feeder, например, делает очень много параллельных подключений, и быстро упирается в лимиты HTTP-клиента. А сервис статистики иногда может кидать стектрейсы, и для разнообразия кидает Error-ы, если встречает в JSON упоминание чёрной дыры. И у storage-сервиса свои “приколы”. Это всё было сделано в целях разнообразия запросов.

Ссылки на конфигурации и исходный код приложений и тестов, а также Compose файлов, приведены в конце статьи.

Fluent bit

Один из самых популярных, если ещё не самый популярный, коллектор логов на сегодняшний день. Является потомком Fluentd, однако когда Fluentd написан на Ruby, Fluent bit написан на Си. Можно предположить, что у него отличная производительность и малое потребление ресурсов. Могут быть, в теории, баги и уязвимости, однако мне ничего не попадалось за всё время карьеры и изучения инструмента в рамках данного материала.

Кстати, я сказал “популярный коллектор логов”. Это отчасти верно и отчасти нет. Дело в том, что его знают как обработчик журналов систем. Но с версии 2.0 он уже поддерживает метрики и трейсы, что делает его агентом сбора телеметрии (не путать с пользовательской телеметрией, у нас здесь речь про телеметрию от систем).

Из других особенностей:

• Конфигурация в conf-файлах. Но в последних версиях появилась возможность писать конфиг на YAML, за исключением, по каким-то причинам, файла с парсерами.

• Можно писать кастомные обработчики данных через Lua и WASM.

• Интересный набор плагинов ввода: есть свой парсер nginx stats, который выдаёт метрики, OpenTelemetry input, встроенный node exporter и process exporter (не надо ставить дополнительно бинари от проекта Prometheus!), и поддерживается даже сбор из WASI-программ.

• Кстати про input-ы: это единственный известный мне коллектор, который “из коробки” умеет собирать не только логи с подов в Kubernetes, но и события ресурсов (которые kubectl get events).

• Есть интересные output-ы: можно писать метрики в Prometheus remote write, в OpenTelemetry protocol, PostgreSQL, Kafka, и Loki.

Личные впечатления от работы с “битом” у меня положительные. Несмотря на то, что его потребовалось дополнительно перенастроить под бенчмарки в плане буферов, после этих манипуляций он работает очень здорово.

Vector

Тоже коллектор телеметрии, однако когда цель Fluent bit это сбор, предварительная обработка и маршрутизация данных, и пересылка телеметрии в базы данных или другие системы, Vector сфокусирован на обработке в частности. Так, у него есть свой язык обработки, Vector Remap Language (VRL), с разными фильтрами и парсерами.

Из прикольных штук хочу выделить следующее:

• Написан на Rust. По идее, он должен быть безопаснее fluent bit и других инструментов, которые будут рассмотрены позже.

• Конфигурация на трёх языках на выбор: TOML, YAML и JSON.

• Продвинутые промежуточные обработчики: VRL-программы, агрегация и дедупликация, перевод логов в метрики и обратно, троттлинг событий, и не только.

• Умеет писать в ClickHouse! Это нам пригодится в следующих статьях цикла.

• Есть свой API (GraphQL), где, к примеру, можно мониторить производительность фреймворка.

Мне очень нравится Vector своими возможностями обработки. У него, в сравнении с “битом”, не так много input-ов, да и с производительностью дела похуже (как выяснится в бенчмарках), но VRL очень хороший язык парсинга в сравнении с Lua, и уже из-за этого у меня тает сердечко.

Elasticsearch

Документная база данных со своим языком запросов за авторством компании Elastic, поддерживает поиск по текстовым полям в JSON-документах. Нечёткий поиск, поиск по словам, по маске, и прочее, что предоставляет поисковой движок Apache Lucene.

Особенности “Эластика”:

• Работает с JSON-документами, которые находятся в отдельных индексах, а индексы объединяются в alias-ы. Так можно искать одновременно по нескольким индексам с общими полями.

• Клиенты общаются с сервером по HTTP REST API. Язык запросов основан на JSON и оттого весьма специфичен (мнение автора).

• Написана на Java. Это даёт высокую производительность ценой большого потребления памяти. Минимально рекомендуемый размер - 1 ГБ. Для наших тестов используется значение в 3 ГБ.

• Поддерживает кластеризацию и шардирование, масштабируется горизонтально, есть разные стратегии, например, гео-распределенная репликация (cross-datacenter replication).

• В связи со своей шардированной натурой поддерживает резервное копирование только на object storage (S3 и аналоги). Утилит типа pg_dump нет.

• Умеет делить хранилища на несколько категорий: hot, warm и cold. К примеру, горячее хранилище может быть файловой системой на SSD, а холодным будет выступать бакет object storage.

• Продвинутые настройки аутентификации, алертинг, и другое. Полный перечень здесь.

Я спокойно отношусь к Elasticsearch, даже несмотря на специфичную лицензию. Из грустного - система много “кушает” памяти, что делает её трудным инструментом для пет-проектов. Так, к примеру, минимальный кластер - это 3 узла, и каждому рекомендуется выдать по 4 ГБ памяти. Ещё меня смущает резервное копирование, где требуется иметь S3/Minio в инфраструктуре. Тем не менее, это самое взрослое и популярное решение на рынке, а значит, у него, по идее, мало болячек, про него много статей, документации и клиентских библиотек.

Про хранение данных: в ES по умолчанию используется сжатие LZ4, поэтому даже со всеми поисковыми индексами по логам с сервисов в ФС контейнера было всего 6.6 ГБ.

А при переключении на DEFLATE на файловой системе было уже… Столько же. Сначала я думал, это какая-то ошибка, и надо сделать индексу force merge. Но и это не поменяло размер индекса! И, похоже, смена кодека сжатия на DEFLATE действительно ничего не меняет.

Установка описана здесь, есть как tgz, так и deb/rpm, а также Docker-образы. Отмечу, что пакеты Elasticsearch, как и всего Elastic Stack, недоступны из России (HTTP 403). Но есть и обходные пути. Так, Elastic Stack есть на Docker Hub в открытом доступе.

Kibana

Продукт компании Elastic. В то время как другие системы визуализации могут работать с самыми разными системами, Kibana полностью завязана на Elasticsearch, до такой степени, что она хранит свои настройки и конфигурацию в том же Elasticsearch.

Kibana написана на Typescript, разработка ведётся достаточно активно и по сей день. Деплой аналогичен Elasticsearch.

Когда вы только запустите Kibana, она предложит настроить различные интеграции, но для всех этих интеграций понадобится Elastic Beats или Elastic Agent. Еее, вендор-лок!

И всё же, это достаточно крутой продукт, хотя бы потому что это не просто визуализация данных в ES, а целая IDE, где можно работать со всей конфигурацией и функционалом кластера.

Как следствие такого объёма фич, Kibana кажется перегруженной. Например, я загрузил логи через Fluent bit в Elasticsearch и хочу просто посмотреть их as is. Открываем меню:

Возможно, нам нужен Observability -> Logs? Нет!

Раздел с логами требует установки Filebeat или других Elastic-специфичных агентов. В данном случае остаётся работать с Analytics -> Discover.

Discover выглядит хорошо. Можно выставить простые и не очень фильтры, на выбор доступны два языка запросов, Kibana и Lucene, Выборка по времени, таблица с полями на выбор, и другое тоже есть.

Также в Kibana есть конструктор дашбордов. Можно не просто отсматривать логи, а делать целую статистику, визуализации с разбивками по полям.

Вот, какой можно сделать дашборд при наличии структурированных (JSON) логов:

Создание такого дашборда заняло около получаса. Впечатления от конструктора очень хорошие, пользоваться удобно.

Grafana

Grafana, универсальный конструктор дашбордов, сердце одноименного стека. Я познакомился с “Графаной” ещё в начале карьеры в 2016-м, когда Prometheus ещё не был так популярен, и все знали про метрики только по стеку Graphite. Уже тогда я был поражён возможностями Grafana в плане возможностей визуализации.

Это я “состряпал” за полчаса графики по HTTP-проверкам из Prometheus blackbox exporter.

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

Из другого вкусненького:

• Grafana это конструктор-полиглот: вы може в одном и том же дашборде отображать данные из Prometheus, Loki, PostgreSQL, и многих других доступных систем.

• В панелях визуализаций можно настроить всё. Абсолютно. Всё. Кроме шрифтов, наверное.

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

• Удобный раздел Explore для ad-hoc запросов, в который можно перейти из любой панели. На дашборде есть график с общей статистикой, и нужны детали? Нажимаете на Explore и попадаете в редактор со всеми поставленными переменными!

• Алертинг, отображение трейсов, тёмная тема, и много чего ещё.

Loki

Часть стека Grafana. Проект появился в 2018-м году и быстро набрал популярность, на данный момент у GitHub-репозитория 20 752 звезды.

Что о нём можно сказать, кроме того, что он просто хороший?

• В отличии от Elasticsearch, Локи не индексирует сами строки логов, он строит индексы только по ключевым полям (например, имя пода Kubernetes, или уровень лога, error/info). Это здорово снижает затраты инфраструктуру.

  

• Из этого вытекает особенность — Loki быстро и эффективно записывает данные, но запросы выполняет дольше того же Elasticsearch.

• Loki сделан с идеей “Prometheus для логов”, поэтому его язык запросов во многом похож на язык “прометея”.

• При этом, в отличии от Prometheus,  Loki изначально сделан с оглядкой на кластеризацию: можно писать данные в Object Storage, устанавливать в распределённом режиме, и так далее.

• Есть CLI (logcli), хорошая поддержка логов из Kubernetes, и нативный datasource в Grafana.

Бенчмарки

Запускать бенчмарки будем на pytest. Мы его будем использовать не совсем как фреймворк тестирования: дело в том, что на нём легко писать взаимосвязанные функции на базе фикстур, помечать их и выборочно запускать. Make или pyinvoke на такое просто не способны.

Ну ладно, сами бенчмарки тоже будем делать, но только запросов.

Методика такая (пример с Fluent bit и ES): Запускаем Elasticsearch, запускаем контейнер Fluent bit с правилом “завершись, как дочитаешь до конца”. Пока контейнеры выполняются, мы периодически дёргаем в фоне pidstat, парсим вывод через jc, и добавляем записи в массивы статистик. В конце тестов (когда Fluent bit завершится) выдаём средние и максимальные значения RSS памяти и CPU в процентах. На основе этих данных и будем строить сводную таблицу.

Из особенностей тестирования отдельных систем:

• Fluent bit: его можно настроить на завершение работы по окончанию чтения файла. Таким образом, мы сможем замерить время его работы просто сказав “exit_on_eof: yes” в input-е чтения самого большого лога, что я и сделал.

• Vector: У него такой опции нет. Но есть GraphQL API! Так, к нему можно подключиться по WebSocket и “подписаться” на статистику компонентов. Как только число проходящих через elasticsearch output станет нулевым, считаем работу сделанной и завершаем тестирование.

Тесты я запускал на своём ПК с Ryzen 5600X и 32ГБ памяти. SSD - NVMe Kingston NV2 2TB, в качестве операционной системы выступает KDE Neon. Признаю, обзор будет неточным. Но я сделал всё возможное, чтобы вы могли легко повторить тесты: в репозитории есть и readme, и ранее упомянутые pytest-функции.

Fluent bit и Elasticsearch (plaintext)

Конфигурация к fluent bit для ES выглядит так:

  outputs:
  - name: es
    match: app.*
    host: es01
    port: 9200
    compress: gzip
    suppress_type_name: on
    http_user: elastic
    http_passwd: changeme
    logstash_format: yes
    tls: on
    tls.ca_file: /ca/ca/ca.crt

Fluent bit с изначальной конфигурацией не смог дожить до конца: я выставил лимит памяти в его контейнере на 2 ГБ, и, к моему удивлению, спустя полторы минуты он упал с OOM-кодом (137).

В его логе красовалось следующее:

[2023/12/04 06:00:49] [error] [output:es:es.0] HTTP status=429 URI=/_bulk, response:
{"error":{"root_cause":[{"type":"es_rejected_execution_exception","reason":"rejected execution of coordinating operation [coordinating_and_primary_bytes=212260263, replica_bytes=0, all_bytes=212260263, coordinating_operation_bytes=4143309, max_coordinating_and_primary_bytes=214748364]"}],"type":"es_rejected_execution_exception","reason":"rejected execution of coordinating operation [coordinating_and_primary_bytes=212260263, replica_bytes=0, all_bytes=212260263, coordinating_operation_bytes=4143309, max_coordinating_and_primary_bytes=214748364]"},"status":429}

Почитав руководство, выставляем в output.es параметр buffer_size: 16M и во всех input.tail mem_buf_limit: 64M.
Получаем достаточно адекватные цифры:

Время загрузки: 484.5s (0:08:04). Поделив объём логов (79565209) на это число, получаем пропускную способность в 164 000 строк в секунду.
Объём данных в Elasticsearch составил 6.6 ГБ.

Fluent bit и Elasticsearch (JSON)

Если перенастроить сервисы на логирование в ndjson, то логов будет пропорционально больше:

У сервиса statistics объём логов вырос более, чем в два раза! Это связано с оверхедом JSON. В связи с тем, что тут нет одного единого поля (строки), а множество разных (timestamp, logger, message…), уже на одни названия полей будет оверхед. Взгляните:

А почему у feeder объём логов не изменился? Дело в том, что для логирования в Kotlin-сервисе statistics я использовал стандартный функционал фреймворка Logback, который пишет всё, что ни попадя. В случае с Go-утилитой feeder использовалась библиотека zerolog, которая пишет только timestamp, level, и то, что явно прикажешь. В результате логи получались вроде таких:

{"level":"info","service":"storage","bytes":3,"time":1701994489605,"message":"response readed"}

Ладно, довольно лирики. Давайте же спарсим эти логи и закинем в Elasticsearch!

Время: 13 минут и 49 секунд. Пропускная способность составила 80 921 событий в секунду. К слову, размер индекса Elasticsearch составляет 7.0 ГБ.

Имеем:

• JSON-логи в целом весят больше, а иногда и сильно больше, поскольку некоторые фреймворки могут логировать весьма большие JSON;

• Работа с логами в JSON требует для Fluent bit в полтора раза больше времени из-за предыдущего пункта;

• Elasticsearch-у легче “дышится” при работе с JSON-логами, он в 2 раза меньше требует CPU;

• А Fluent bit, в свою очередь, в 2 раза меньше кушает памяти.

Vector и Elasticsearch (plaintext)

Vector стремится быть оптимизированным и надёжным решением, как и Fluent bit. Тем не менее, его результат в полтора раза отличается от времени оного: 13 минут и 17 секунд. Соответственно, это 100 000 событий в секунду. Кроме того, он во время бенчмарка потреблял больше CPU и RAM, аж в два раза в сравнении с “битом”:

Вам может показаться, что Vector тут однозначный аутсайдер: и ресурсов потреблял больше, и работал дольше, а результат тот же. Но дело в том, что результат всё же иной. Размер индекса Vector составляет 8.4 ГБ.

Logstash это индекс Fluent bit в режиме совместимости с Logstash, Vector — ну, тут понятно, кто.

Сравните эти индексы. В одном 79 млн документов, в другом - 88 млн. Вчитавшись в логи, оказывается, что Fluent bit способен терять данные, если, например, Elasticsearch отвечает 429-м кодом (просит снизить обороты запросов), а буферы данных коллектора логов уже заполнены другими такими же запросами в очереди. Конечно, он умеет информировать нижестоящие источники данных о своём состоянии. В теории, tail input при заполненности своих буферов и вышестоящих output-ов должен был приостановить чтение, однако этого он не сделал, и в результате потерял 10% данных.

Безусловно, я чего-то недоглядел в документации и настройках “бита”. Но примечательно то, что Vector я вообще не тюнил. Судя по всему, Вектор динамически подстраивает размер буферов под ситуацию, ценой большего потребления ресурсов.

Vector и Elasticsearch (JSON)

16 минут и 10 секунд. 69 158 событий в секунду. Размер индекса составил 7.8 ГБ. В сравнении с Fluent bit на 800 МБ больше, что я связываю с объёмом метаданных, которые Vector добавляет к событиям.

Fluent bit и Loki (plaintext)

Когда я замерял производительность Fluent bit в связке с Loki, заметил одну странную особенность: процессор почти не был нагружен, по ядру на коллектор и БД.

Я это связываю с фиксированным числом воркеров. Кроме того, к “биту” есть аж два плагина Loki: встроенный “loki” и внешний “grafana-loki” от Grafana Labs. Второй постепенно пытаются вмёржить во встроенный, за обсуждением можно следить здесь.

У них есть существенные отличия: например, grafana-loki умеет работать на “нативном” для Loki Protobuf-е, есть буферизация и backoff запросов, и другое.

Я же решил продолжить тест “нативного” плагина. И вот результаты:

По времени: 14 минут и 37 секунд, или 877 секунд. Суммарно загружено 79.6 млн записей, это 90 тысяч записей в секунду. Использование ФС — 816.7 МБ, что в разы меньше, чем Elasticsearch! Всё благодаря собственным практикам сжатия логов в Loki.

Vector и loki (plaintext)

В отличии от Fluent bit, в Vector для Loki можно легко передавать логи по Protobuf. Как мы потом увидим, это сильно улучшает производительность. Также, при первом испытании оказалось, что Vector потерял 75% логов. После включения acknowledgements и буферизации на диск ситуация пришла в норму, результаты такие:

Тесты заняли всего 7 минут 15 секунд, или 435 секунд, или 180 тысяч событий в секунду. Это рекорд! В рамках этой статьи, конечно.

Производительность запросов БД

Для таких сценариев используется плагин pytest-benchmark. “Бенчить” запросы будем в двух вариантах: в обычном сценарии использования системы, и с предварительным сбросом page cache (echo 1 | suto tee /proc/sys/vm/drop_caches), чтобы продемонстрировать, как часто система работает с файловой системой.

Случайные страницы

offset=[1:5000], limit=[5001:10000]

Группировка по сервисам

(COUNT BY service)

Промежуточные выводы

О результатах производительности БД пока рано говорить, особенно с учётом того, что замеры были только Elasticsearch и я только сейчас, в финале статьи, осознал, что стоило замерять потребление памяти. Но Elasticsearch меня хорошо порадовал своей производительностью. То есть… Я много весёлого и немного грустного слышал про Elasticsearch, особенно, как весело его чинить при разваливающихся кластерах из >32 узлов и на 400 ТБ. И вы все знаете про интересную лицензию Elastic. И я видел своими глазами сложный интерфейс Kibana за пределами раздела Analytics. Но система хорошая, несмотря ни на что.

Моё личное предпочтение, при этом, отдаётся Grafana Loki. Он хорошо кластеризуетя, хранит данные в бакетах, и очень эффективно хранит логи. Низкое потребление ресурсов, особенно если вы много пишете и редко запрашиваете большие объёмы данных. Мощный интерфейс Grafana, очень приятный в использовании язык запросов, не то что JSON в Elasticsearch (извините). Главное не забывайте про комбинаторный взрыв меток, поскольку тут у Loki те же проблемы, что и у Prometheus. 

Из коллекторов логов… Сложно однозначно выбрать победителя. Fluent Bit хорош в целом по ресурсам и при первичном сборе метрик, Vector отлично показывает себя в сложных сценариях разбора данных. Мой совет? Собирайте логи на серверах Fluent bit-ом, и при необходимости пересылайте на отдельный сервер с Vector, который будет перемалывать и маршрутизировать данные в хранилища.

Как и обещал, ссылки на репозиторий и ветки:

• kamish/o11y — GitHub проект;

• Ветка с инструкцией по логам: habr/logging;

• Ветка с конфигами и тестами для JSON логов: habr/logging-json.

В завершение хочу порекомендовать курс "Observability: мониторинг, логирование, трейсинг". В рамках запуска курса мои коллеги из OTUS проведут бесплатный урок, где расскажут про способы отправки данных в систему мониторинга Zabbix без использования агентов и с помощью функциональности Discovery Trapper. Регистрируйтесь, будет интересно!