company_banner

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 в правильном порядке, без повторений и потерь.


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


    Nixys
    Эксперты в DevOps и Kubernetes

    Комментарии 0

    Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

    Самое читаемое