[DevOps, Kubernetes, Серверное администрирование, Системное администрирование] Fluentd: почему важно настроить выходной буфер

Ответить на тему

Автор

Сообщение

news_bot ^®

Стаж: 6 лет 3 месяца
Сообщений: 27286

news_bot ^® написал(а)
13-Июл-2020 15:33

Цитировать

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

Установить значение request_timeout гарантированно большим, чем необходимо (сотни секунд). На время настройки основным критерием правильности установки данного параметра будет являться исчезновение предупреждений у нехватке тайм-аута.
Дождаться сообщений о превышении порога slow_flush_log_threshold. В тексте предупреждения в поле elapsed_time будет написано реальное время очистки буфера.
Установить значение request_timeout больше, чем максимальное значение elapsed_time, полученное за период наблюдения. Мы рассчитываем значение request_timeout как elapsed_time + 50%.
Чтобы убрать из лога предупреждения о долгой очистке буфера, можно поднять значение 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
===========
Похожие новости:

Теги для поиска: #_devops, #_kubernetes, #_servernoe_administrirovanie (Серверное администрирование), #_sistemnoe_administrirovanie (Системное администрирование), #_fluentd, #_elk, #_kubernetes, #_devops, #_blog_kompanii_nixys (
Блог компании Nixys
), #_devops, #_kubernetes, #_servernoe_administrirovanie (
Серверное администрирование
), #_sistemnoe_administrirovanie (
Системное администрирование
)

Профиль ЛС

Ответить на тему

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

Текущее время: 15-Май 14:51
Часовой пояс: UTC + 5