ProHoster > Блог > адміністрування > Fluentd: чому важливо налаштувати вихідний буфер

Fluentd: чому важливо налаштувати вихідний буфер

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 це виглядає так:

Fluentd: чому важливо налаштувати вихідний буфер

Рішення проблеми

Існує кілька варіантів вирішення цієї проблеми. Один з них - вбудований в плагін 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%.

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

У таблиці нижче показано, як змінюється кількість помилок за добу, що призводять до дублювання повідомлень, у процесі добору значень описаних вище параметрів:

вузол-1
вузол-2
вузол-3
вузол-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

Додати коментар або відгук