Сегодня мы, backend-команда личного кабинета МегаФона, хотим поделиться своим опытом в решении проблемы log shipping-процесса в централизованное хранилище Elasticsearch. Обновив ELK-стек, мы поняли, что старая тактика использования Filebeat больше не работает. А как мы с этим разобрались — вы узнаете в этой статье. Вас ожидает не только утомительная теория, но и реальные результаты стресс-тестирования всей системы доставки при больших нагрузках. Приятного чтения!

Что расскажу:

• Рассказать немного о Filebeat;

• Причины выбора Filebeat как log shipper инструмента;

• Краткое описание работы нашей системы backend - filesystem - filebeat - elasticsearch;

• Мониторинг FIlebeat;

• Детальное описание работы с Filebeat до версии 7.9.0;

• Новая тактика работы с Filebeat с версиями старше 7.9.0 и наши ожидания;

• Стресс-тестирование и анализ результатов.

Что такое Filebeat?

Начнем с небольшого погружения в теорию. Filebeat - это инструмент для считывания событий из источников и их последующей отправки в какой-либо источник. Источники могут быть разного характера, начиная от облака Elasticsearch service и заканчивая просто другим файлом или консолью. 

Вот полный список доступных output-точек:

• Elasticsearch Service

• Elasticsearch

• Logstash

• Kafka

• Redis

• File

• Console

Filebeat имеет две важные компоненты:

• inputs — это собственно источники, откуда Filebeat будет считывать события;

• harvesters — это сборщики (комбайны) событий, которые непосредственно "цепляются" за inputs компоненты, считывают информацию и отправляют их в output.

Каждые N времени (регулируется конфигурацией scan_frequency) производится research новых input-источников и при их нахождении Filebeat приставляет к ним harvesters.

Прогресс чтения отражается в так называемом registry, который представляет собой файлы, хранящие информацию о конкретной input-компоненте и offset (то есть точка смещения, до которой дочитал закрепленный за ней harvester). Такой подход позволяет продолжить чтение даже после рестарта Filebeat.

Более подробно можно почитать здесь: https://www.elastic.co/guide/en/beats/filebeat/current/how-filebeat-works.html

Почему Filebeat?

Конечно, главная причина выбора Filebeat — это один из инструментов экосистемы ELK. Такие фичи как Index Lifecycle Management, Data Streams уже доступны из коробки, ничего настраивать не надо. Ко всему прочему Filebeat обладает следующими полезностями:

1. Приложение написано на Go, а значит потребление ресурсов должно быть меньше;

2. Backpressure. В случае отказа output-точки, мы будем копить события и попытаемся как можно дольше сохранять их до момента восстановления output-компонента.

Но есть и минусы:

1. Во время внедрения старой версии и поддержания работы с более свежей версией нам очень не хватало API для получения информации о том, какие журналы уже были прочитаны и доставлены;

2. Есть кейсы, которые не очевидны, а в документации описание либо не встречается, либо его, на наш взгляд, недостаточно.

Краткое описание нашей системы доставки журналов в Elasticsearch

Расскажем немного о том, как события попадают на руки Filebeat, а уже после — в хранилище Elasticsearch.

Начнем с продюсера наших событий — это backend. Если кратко, наш backend пишет уже сформированные json-события в локальную очередь.  А по мере разгребания этой очереди, события пишутся в самый конец файла, предназначенного для Filebeat (например, beat.log). Файл beat.log находится там, где наш Filebeat уже ищет файлы для считывания, поэтому ему ничего не остается, кроме как приставить harvester к нашему журналу.

На этом работа нашего backend еще не завершается. Мы выделили маленький job-ресурс, который помогает нам заниматься ротацией наших журналов. Мы неслучайно написали про журналы во множественном числе: job-ресурс декомпозирует их по мере увеличения размера до N gb. Таким образом, журналы можно удобно ликвидировать в рамках работы Filebeat. Спустя некоторое время нашему Filebeat приходится работать уже не с одним, а с множеством журналов. Когда и какие журналы мы удаляем — расскажем ниже.

Сам Filebeat работает самостоятельно. Он считывает, что еще не считал, и отправляет то, что еще не отправил, если output-точка доступна для входящих событий. 

Отправка событий идет пачками по http протоколу. Ниже представлена упрощенная схема системы доставки журналов из изолированных нод нашего backend.

На этом знакомство с системой закончим и перейдем к мониторингу.

Мониторинг работы Filebeat

Из коробки нам доступен мониторинг через среду ELK. Его можно настроить благодаря следующей конфигурации:

monitoring: 
  enabled: true

После можно наблюдать за работой в Kibana:

Но так как все наши дашборды находятся в Grafana, мы решили отказаться от готового инструмента и сделали свой скреп метрик в Prometheus.

У Filebeat есть API, по которому он отдает подробно все свои показатели. Этим мы и воспользовались, предварительно включив в конфигурации следующее:

http: 
  enabled: true 
  host: localhost 
  port: 5066

Собственно само API curl -XGET 'localhost:5066/stats'

В ответе мы получили большущий Json с множеством параметров работы, что, вполне подходит для контроля.

На выходе получили следующую картину в Grafana:

А теперь время перейти к детальному описанию работы с инструментом.

Ротация журналов для Filebeat до версии 7.9.0

Самое первое решение по работе с Filebeat до версии 7.9 строилось на "подглядывании" за его внутренней работой. Registry в виде файла data.json имел примерно следующую структуру:

[ 
"soure":"/apps/logs/my_apps/file.log","offset":"308017933","timestamp":"2020-07-23T07:20:38.120400049+02:00","ttl":-1,"type";"log","meta":null,"FileStateOS":"{"inode":"271256140,"device":2081}}, 
"soure":"/apps/logs/my_apps1/file.log","offset":"7111033","timestamp":"2020-07-23T07:20:38.221412049+02:00","ttl":-1,"type";"log","meta":null,"FileStateOS":"{"inode":"213256140,"device":2081}}, 
... 
]

Каждый объект в массиве соответствовал найденному harvester log-файлу и имел важные атрибуты, такие как inode и offset. Далее, с этими атрибутами, работал job-ресурс нашего backend. 

Краткое описание работы log rotation job:

1. Парсили файл data.json для выявления текущего состояния отправки журналов Filebeat'ом;

2. Собирали информацию о журналах, которые на данный момент есть;

3. Производили декомпозицию, если это необходимо;

4. Соотносили информацию из data.json к текущим журналам из п.2 по inode;

5. Если offset из data.json был равен длине журнала, то мы удаляли журнал, так как это означало, что harvester считал и отправил все ивенты из этого журнала;

6. Если объем всех журналов после п.5 занимал уже критическую отметку (что означало недоступность output-точки или неработоспособность Filebeat), мы удаляли старые журналы, так как места хранить их больше не было.

Плюсы решения:

1. Мы могли "держать на пульсе" состояние отправки ивентов из журналов;

2. Мы вовремя избавлялись от отправленных журналов, тем самым не "захламляя" hard-пространство; 

Недостатки решения:

1. Был использован недокументированный аспект работы Filebeat;

2. Не были использованы ключевые аспекты Filebeat;

3. Связь log rotation и log shipper инструментов была слишком сильной.

Безотказная работа такого решения продолжалась до версии 7.9.0, пока ребята из команды разработки Filebeat не пересмотрели вид хранения registry.

Новое решение и ожидания от него

С версией 7.9.0 Filebeat принес новую структуру registry — файл data.json ушел, взамен пришли log.json и active.dat. Файл log.json представляет собой некий журнал операций, а active.dat — snapshot на базе log.json, который создается каждый раз по мере разрастания log.json до 10 Мб. 

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

К сожалению, команда Filebeat считает, что Filebeat как log shipper-инструмент должен отвечать только за доставку ивентов из файлов. А управлением этими файлами должны заниматься мы, ориентируясь на то, что  сами придумаем. 

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

Начав читать документацию, натыкаемся на интересный абзац:

A harvester is responsible for reading the content of a single file. The harvester reads each file, line by line, and sends the content to the output. One harvester is started for each file. The harvester is responsible for opening and closing the file, which means that the file descriptor remains open while the harvester is running. If a file is removed or renamed while it’s being harvested, Filebeat continues to read the file. This has the side effect that the space on your disk is reserved until the harvester closes. By default, Filebeat keeps the file open until close_inactive is reached.

То есть команда Filebeat дает нам гарантии: если harvester начал читать файл, то ни переименование, ни удаление не помешают ему дочитать и отправить ивенты в output collector.

Для достижения этих гарантий в рамках ротации журналов используем следующие конфигурации:

filebeat.inputs:
    clean_removed: false # не удаляем из реестра удаленные журналы 
    close_removed: false # не закрываем harverster для удаленного файла, если он еще считывает его
    clean_renamed: false # не удаляем из реестра переименованные файлы
    close_renamed: false # не заркываем harvester для переименованного файла, если он еще считывает его

Так как наши журналы не пополняются новыми ивентами (кроме основного, куда пишет наш backend), harvester'у нет нужды долго держать журнал и ожидать в нем новые события. Также нет необходимости при каждом сканировании приставлять новый harvester к уже прочитанным файлам. Поэтому в целях экономии ресурсов на холостой ход мы применили такие настройки:

filebeat.inputs:
    close_inactive: 30s # после N времени с момента окончания чтения файла закроем harvester
    clean_inactive: 90s # очищаем реестр по файлам, которые были дочитаны N времени назад (должно быть больше, чем ignore_older + scan_frecuency)
    ignore_older: 60s # игнорируем собранные файлы, которым уже N времени

С текущими настройками нам не страшно ни переименовать, ни удалить файл раньше времени. Поэтому job ротации теперь удаляет журналы, отталкиваясь только от того, сколько места они занимают. 

С эксплуатацией в обычном режиме все более менее ясно, но что будет в аварийной ситуации? Что если Elasticsearch или другая output-точка будет недоступна в течение нескольких часов? Мы потеряем логи или упадем от нехватки hard-памяти?

Да, команда Filebeat дала нам гарантии, что даже удаленные файлы будут удерживаться harvester'ом, если он еще "не закончил" с чтением. И вместе с тем любезно предупредила: 

This has the side effect that the space on your disk is reserved until the harvester closes. By default, Filebeat keeps the file open until close_inactive is reached.

Судя по документации, close_inactive  срабатывает только в том случае, если harvester считал последнюю строчку файла, что не совсем нам подходит. Если output-элемент будет недоступен в течение долгого времени (рассматриваем наихудшие варианты), то память на hard закончится и сервис для пользователей перестанет быть доступным. А это еще хуже, чем потеря журналов.

На помощь приходит следующая настройка:

filebeat.inputs:
    close_timeout: 30m #если в течение N времени harvester не смог дочитать файл, закроем аварийно, чтобы освободить ресурсы

Хорошо,  от нехватки hard-памяти мы спаслись, но что будет с логами, если журналы мы уже удалили? Что будет с логами, если output-точка успела восстановиться до close_timeout или по его истечении?

В теории, журналы, удерживаемые harvester'ами,  должны считываться, даже если output недоступен. Но логично предположить, что ему надо их где-то хранить. Либо в RAM-памяти, либо в hard. 

Так наша цель выстроить отказоустойчивую систему - хранение очереди на hard-диске поможет нам обзавестись backpressure - даже при отказе Filebeat или вообще всего контейнера, наши журналы сохранятся в volume и после рестарта Filebeat продолжит отправлять события. В этом помогла такая конфигурация:

queue.disk: 
  max_size: 200GB 
  path: "${path.data}/diskqueue"

Да, теперь есть небольшой запас времени для восстановления output-компонента. Пока будет свободно место в disk queue, Filebeat будет считывать события и бережно их складывать, периодически пытаясь их заслать куда надо. Но есть одно но: количество попыток отправки событий ограничено до трёх. Так как нам очень не хочется терять события, пока есть свободное место на диске, мы выключили следующую конфигурацию:

output.elasticsearch:
     max_retries: -1 # ограничение кол-ва попыток отправок событий. Если в течение этих попыток события не отправятся, они будут утеряны. Выключим это

Таким образом, при отказе output-компонента мы ожидаем следующее поведение:

1. Filebeat продолжит сканировать input.path для поиска новых журналов;

2. События из журналов будут считываться и бережно складываться в queue на hard-диске;

3. Периодически Filebeat будет пытаться отправить пачку ивентов из queue, но сколько бы попыток он ни сделал, он эту пачку событий не дропает;

4. По мере увеличения времени нахождения в аварийном состоянии output-компонента, hard-память будет расти, но до предела, который предусмотрен queue на hard-диске. Кроме того, в hard-памяти будет находиться N количество журналов, которые предусмотрены в рамках ротации. А также самим Filebeat'ом будут удерживаться удаленные файлы в течение close_timeout времени. Совокупность этих нагрузок не должна превышать пространственные ограничения нашей машины (в этом случае нам, конечно, надо время от времени пересматривать знание о том, как быстро и в каком количестве backend генерирует события);

5. Если output-точка недоступна дольше того времени, которое мы можем себе позволить копить события, в какой-то момент мы должны прекратить сбор новых событий. Filebeat должен перестать считывать новые файлы, если queue будет заполнена, а по мере окончания close_timeout отпускать ресурсы удаленных журналов;

6. Как только output-элемент станет доступен, все события из queue на hard-диске должны будут отправиться. По мере освобождения очереди Filebeat продолжит считывать доступные файлы, и процесс сбора и отправки событий перейдет в обычный режим.

От слов к делу. Стресс-тестирование и анализ результатов

В теории описанный сценарий звучит так, будто у нас все под контролем, но, на самом деле,  вопросов очень много. Будут ли по факту события за период недоступности, например, Elasticsearch, доставлены целыми и невредимыми? Не будет ли осложнений с hard-памятью? Не "откинется" ли Filebeat после N количества неудачных попыток достучаться до Elasticsearch или сможет ли он переварить доставку скопившейся очереди? Мы это проверили и сейчас покажем.

Мы считаем, самый простой способ инициировать аварию — это поменять пароль от учетной записи Elasticsearch. Мы им воспользовались и действительно получили ожидаемую аварию. Filebeat больше не отсылает события и начинается самое интересное.

Как видно из скриншота, количество событий output_acked падает, и появляются события pipeline_retry  (думаем, из названия понятно, что и почему). События pipeline_retry будут на протяжении всей аварии — оно и правильно. Другие же события, которые отвечают только за считывание и сохранение событий в очереди, остаются на том же уровне, что для нас является отличной новостью — back pressure работает!

Мы стабильно перекладываем события из файлов в очередь Filebeat, а события pipeline_retry все растут и растут (Filebeat уже не терпится их отправить):

В это время метрики hard-памяти так же показывают корреляцию с метриками Filebeat:

Дожидаться "полочки" по hard-памяти мы не стали, так как уверены, что получили бы её. Поэтому через два часа тестов мы вернули пароль от учетной записи и увидели такие результаты:

На графике Filebeat Events Delivery Stats сразу видно, что события наконец-то начали уходить. Ивенты output_acked возросли до сверхколичества в сравнении с обычным режимом работы. Вместе с тем подросло использование CPU и RAM-памяти. После того как Filebeat закончил отправлять в усиленном режиме свои "долги", он вернулся в обычный режим эксплуатации. 

Стоит также отметить, что на протяжении всей аварии harvesters продолжали работать в обычном режиме — искали новые файлы и считывали с них информацию. Это видно по графикам Filebeat Harvesters Stats и Filebeat Registrar Stats.

Это все хорошо, но что с хранилищем? Вернулись ли события? Да! Вернулись и не потерялись. Точного счета, конечно, нет, но можно судить по двум графикам — до и после:

Итоги

Что ж, Filebeat работает как мы ожидали. Наверняка есть множество других инструментов для доставки журналов событий в централизованное хранилище, но мы считаем, что наше решение принесло команде личного кабинета МегаФон хорошие результаты. А какие инструменты используете вы? Делитесь своим опытом в комментариях. 

Спасибо, что дочитали до конца и пусть ваши события бесперебойно доходят до хранилища.