Русский
Русский
English
Статистика
Реклама

Fluentd почему важно настроить выходной буфер


В наше время невозможно представить проект на базе Kubernetes без стека ELK, с помощью которого сохраняются логи как приложений, так и системных компонентов кластера. В своей практике мы используем стек EFK с Fluentd вместо Logstash.


Fluentd это современный универсальный коллектор логов, набирающий всё большую популярность и присоединившийся к Cloud Native Computing Foundation, из-за чего вектор его разработки ориентирован на использование совместно с Kubernetes.


Факт использования Fluentd вместо Logstash не изменяет общую суть программного комплекса, однако, для Fluentd характерны свои специфические нюансы, следующие из его многофункциональности.


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


Проблема дублирования документов


В наших проектах Fluentd развернут как DaemonSet (автоматически запускается в одном экземпляре на каждом узле кластера Kubernetes) и отслеживает stdout логи контейнеров в /var/log/containers. После сбора и обработки логи в виде JSON-документов поступают в ElasticSearch, поднятый в кластерном либо standalone виде, в зависимости от масштабов проекта и требований к производительности и отказоустойчивости. В качестве графического интерфейса используется Kibana.


При использовании Fluentd с буферизирующим плагином на выходе мы столкнулись с ситуацией, когда некоторые документы в ElasticSearch имеют полностью одинаковое содержание и отличаются лишь идентификатором. Убедиться, что это именно повтор сообщения можно на примере лога Nginx. В файле лога данное сообщение существует в единственном экземпляре:


127.0.0.1 192.168.0.1 - [28/Feb/2013:12:00:00 +0900] "GET / HTTP/1.1" 200 777 "-" "Opera/12.0" -

Однако, в ElasticSearch существует несколько документов, содержащих данное сообщение:


{  "_index": "test-custom-prod-example-2020.01.02",  "_type": "_doc",  "_id": "HgGl_nIBR8C-2_33RlQV",  "_version": 1,  "_score": 0,  "_source": {    "service": "test-custom-prod-example",    "container_name": "nginx",    "namespace": "test-prod",    "@timestamp": "2020-01-14T05:29:47.599052886 00:00",    "log": "127.0.0.1 192.168.0.1 - [28/Feb/2013:12:00:00  0900] \"GET / HTTP/1.1\" 200 777 \"-\" \"Opera/12.0\" -",    "tag": "custom-log"  }}{  "_index": "test-custom-prod-example-2020.01.02",  "_type": "_doc",  "_id": "IgGm_nIBR8C-2_33e2ST",  "_version": 1,  "_score": 0,  "_source": {    "service": "test-custom-prod-example",    "container_name": "nginx",    "namespace": "test-prod",    "@timestamp": "2020-01-14T05:29:47.599052886 00:00",    "log": "127.0.0.1 192.168.0.1 - [28/Feb/2013:12:00:00  0900] \"GET / HTTP/1.1\" 200 777 \"-\" \"Opera/12.0\" -",    "tag": "custom-log"  }}

Притом, повторов может быть больше двух.


Во время фиксации данной проблемы в логах Fluentd можно наблюдать большое количество предупреждений следующего содержания:


2020-01-16 01:46:46 +0000 [warn]: [test-prod] failed to flush the buffer. retry_time=4 next_retry_seconds=2020-01-16 01:46:53 +0000 chunk="59c37fc3fb320608692c352802b973ce" error_class=Fluent::Plugin::ElasticsearchOutput::RecoverableRequestFailure error="could not push logs to Elasticsearch cluster ({:host=>\"elasticsearch\", :port=>9200, :scheme=>\"http\", :user=>\"elastic\", :password=>\"obfuscated\"}): read timeout reached"

Данные предупреждения возникают когда ElasticSearch не может вернуть ответ на запрос за установленное параметром request_timeout время, из-за чего пересылаемый фрагмент буфера не может быть очищен. После этого Fluentd пытается отправить фрагмент буфера в ElasticSearch повторно и через произвольное число попыток операция завершается успешно:


2020-01-16 01:47:05 +0000 [warn]: [test-prod] retry succeeded. chunk_id="59c37fc3fb320608692c352802b973ce" 2020-01-16 01:47:05 +0000 [warn]: [test-prod] retry succeeded. chunk_id="59c37fad241ab300518b936e27200747" 2020-01-16 01:47:05 +0000 [warn]: [test-dev] retry succeeded. chunk_id="59c37fc11f7ab707ca5de72a88321cc2" 2020-01-16 01:47:05 +0000 [warn]: [test-dev] retry succeeded. chunk_id="59c37fb5adb70c06e649d8c108318c9b" 2020-01-16 01:47:15 +0000 [warn]: [kube-system] retry succeeded. chunk_id="59c37f63a9046e6dff7e9987729be66f"

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


В Kibana это выглядит так:



Решение проблемы


Существует несколько вариантов решения данной проблемы. Один из них встроенный в плагин fluent-plugin-elasticsearch механизм генерации уникального хеша для каждого документа. Если использовать данный механизм, ElasticSearch будет распознавать повторы на стадии пересылки и не допускать дублирования документов. Но нельзя не учитывать, что данный способ решения проблемы борется со следствием и не устраняет ошибку с нехваткой тайм-аута, поэтому мы отказались от его применения.


Мы используем буферизирующий плагин на выходе Fluentd, чтобы не допустить потери логов в случае кратковременных неполадок с сетью или возросшей интенсивности записи логов. Если по какой-либо причине ElasticSearch не может мгновенно записать документ в индекс, документ попадает в очередь, которая хранится на диске. Поэтому, в нашем случае, чтобы устранить источник проблемы, которая приводит к возникновению описанной выше ошибки, необходимо задать корректные значения параметров буферизации, при которых выходной буфер Fluentd будет достаточного объема и при этом успевать очищаться за отведенное время.


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


На момент фиксации проблемы конфигурация выглядела следующим образом:


 <buffer>        @type file        path /var/log/fluentd-buffers/kubernetes.test.buffer        flush_mode interval        retry_type exponential_backoff        flush_thread_count 2        flush_interval 5s        retry_forever        retry_max_interval 30        chunk_limit_size 8M        queue_limit_length 8        overflow_action block      </buffer>

В ходе решения проблемы вручную подбирались значения следующих параметров:
chunk_limit_size размер чанков, на которые разбиваются сообщения в буфере.


  • flush_interval интервал времени, через который происходит очистка буфера.
  • queue_limit_length максимальное количество чанков в очереди.
  • request_timeout время, на которое устанавливается соединение между Fluentd и ElasticSearch.

Общий размер буфера можно вычислить, перемножив параметры queue_limit_length и chunk_limit_size, что можно толковать как максимальное количество чанков в очереди, каждый из которых имеет заданный объем. При недостаточном размере буфера в логах будет появляться следующее предупреждение:


2020-01-21 10:22:57 +0000 [warn]: [test-prod] failed to write data into buffer by buffer overflow action=:block

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


Увеличить буфер можно двумя способами: увеличив либо размер каждого чанка в очереди, либо количество чанков, которые могут находиться в очереди.


Если установить размер чанка chunk_limit_size более 32 мегабайт, то ElasticSeacrh не примет его, так как входящий пакет получится слишком большим. Поэтому, если необходимо увеличить буфер дополнительно, лучше увеличивать максимальную длину очереди queue_limit_length.


Когда буфер перестанет переполняться и останется только сообщение о нехватке тайм-аута, можно приступить к увеличению параметра request_timeout. Однако, при установке значения больше 20 секунд, в логах Fluentd начнут появляться следующие предупреждения:


2020-01-21 09:55:33 +0000 [warn]: [test-dev] buffer flush took longer time than slow_flush_log_threshold: elapsed_time=20.85753920301795 slow_flush_log_threshold=20.0 plugin_id="postgresql-dev" 

Данное сообщение никак не влияет на работу системы и означает, что время очистки буфера заняло больше, чем установлено параметром slow_flush_log_threshold. Это отладочная информация и мы используем её при подборе значения параметра request_timeout.


Обобщенный алгоритм подбора выглядит следующим образом:


  1. Установить значение request_timeout гарантированно большим, чем необходимо (сотни секунд). На время настройки основным критерием правильности установки данного параметра будет являться исчезновение предупреждений у нехватке тайм-аута.
  2. Дождаться сообщений о превышении порога slow_flush_log_threshold. В тексте предупреждения в поле elapsed_time будет написано реальное время очистки буфера.
  3. Установить значение request_timeout больше, чем максимальное значение elapsed_time, полученное за период наблюдения. Мы рассчитываем значение request_timeout как elapsed_time + 50%.
  4. Чтобы убрать из лога предупреждения о долгой очистке буфера, можно поднять значение slow_flush_log_threshold. Мы рассчитываем данное значение как elapsed_time + 25%.

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


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


node-1 node-2 node-3 node-4
До/После До/После До/После До/После
failed to flush the buffer 1749/2 694/2 47/0 1121/2
retry succeeded 410/2 205/1 24/0 241/2

Стоит дополнительно отметить, что полученные настройки могут потерять свою актуальность в процессе роста проекта и, соответственно, увеличения количества логов. Первичным признаком нехватки установленного тайм-аута является возвращение в лог Fluentd сообщений о долгой очистке буфера, то есть превышение порога slow_flush_log_threshold. С этого момента есть ещё небольшой запас до превышения параметра request_timeout, поэтому необходимо своевременно отреагировать на данные сообщения и повторно выполнить процесс подбора оптимальных настроек, описанный выше.


Заключение


Тонкая настройка выходного буфера Fluentd является одним из главных этапов настройки EFK стека, определяющим стабильность его работы и корректность размещения документов в индексах. Ориентируясь на описанный алгоритм настройки, можно быть уверенным, что все логи будут записаны в индекс ElasticSearch в правильном порядке, без повторений и потерь.


Также читайте другие статьи в нашем блоге:


Источник: habr.com
К списку статей
Опубликовано: 13.07.2020 14:10:08
0

Сейчас читают

Комментариев (0)
Имя
Электронная почта

Блог компании nixys

Devops

Kubernetes

Серверное администрирование

Системное администрирование

Fluentd

Elk

Категории

Последние комментарии

© 2006-2020, personeltest.ru