НОВОСТИ Fluentd: почему важно настроить выходной буфер

Alvaros
Онлайн

Alvaros

Ветеран
.
Регистрация
14.05.16
Сообщения
21.461
Реакции
102
Репутация
204
zh-lp5gmaewbzhzsxlls1nxm0dc.png



В наше время невозможно представить проект на базе 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 это выглядит так:


aamher7mzvt27icosjqw1y-hv8c.png


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



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


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


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


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



@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



В ходе решения проблемы вручную подбирались значения следующих параметров:
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-1node-2node-3node-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 в правильном порядке, без повторений и потерь.

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


 
Сверху Снизу