Описание проблемы

Дано

• кластер k8s

• много приложений, которые пишут свои логи в stdout/stderr, а контейнерный движок (в данном случае docker) складывает их в файлы

• fluent-bit, запущенный на каждой ноде k8s. Он собирает логи, фильтрует их и отправляет в Loki

• loki - хранилище логов от Grafana Labs

В чём заключается проблема

При просмотре логов через Grafana (источник - Loki) видно, что логи приходят с сильной задержкой или часть логов вообще отсутствует. При просмотре через kubectl logs все логи на месте

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

Ищем причину

Конфиг fluent-bit имеет примерно такой вид

[SERVICE]
  Flush                     1
  Daemon                    Off
  Log_Level                 info
  Parsers_File              parsers.conf
  Parsers_File              custom_parsers.conf
  HTTP_Server               On
  HTTP_Listen               0.0.0.0
  HTTP_Port                 2020
[INPUT]
  Name                      tail
  Path                      /var/log/containers/*.log
  Parser                    docker
  Tag                       kube.*
  Mem_Buf_Limit             4MB
  Skip_Long_Lines           On
  Skip_Empty_Lines          On
[FILTER]
  Name                      kubernetes
  Match                     kube.*
  Merge_Log                 On
  Keep_Log                  On
  K8S-Logging.Parser        On
  K8S-Logging.Exclude       On
[OUTPUT]
  Name                      loki
  Match                     kube.*
  Host                      loki.logging.svc.cluster.local
  Port                      3100
  Labels                    job=fluent, namespace=$kubernetes['namespace_name'], pod=$kubernetes['pod_name'], container=$kubernetes['container_name']
  Auto_kubernetes_labels    off
  Line_format               json

Первым делом смотрим логи самого fluent-bit

kubectl logs -l app.kubernetes.io/name=fluent-bit --max-log-requests=6 -f

и видим там много подобных сообщений

[2022/04/27 07:48:32] [ warn] [input] tail.0 paused (mem buf overlimit)
[2022/04/27 07:48:33] [ info] [input] tail.0 resume (storage buf overlimit 77/128)
[2022/04/27 07:48:33] [ warn] [input] tail.0 paused (mem buf overlimit)
[2022/04/27 07:48:34] [ info] [input] tail.0 resume (storage buf overlimit 77/128)                                           
[2022/04/27 07:48:34] [ warn] [input] tail.0 paused (mem buf overlimit)
[2022/04/27 07:48:35] [ info] [input] tail.0 resume (storage buf overlimit 78/128)

tail.0 paused (mem buf overlimit) говорит о том, что сбор логов через плагин tail был приостановлен из-за превышения лимита буфера в памяти Mem_Buf_Limit (если не задать, то в какой-то момент придёт ООМ). Как только логи из буфера сбрасываются в loki и в буфере появляется место, tail продолжает собирать логи, но тут же снова упирается в лимит буфера и останавливает сбор новых логов.

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

[SERVICE]
...
  storage.path              /fluent-bit/log/storage/
[INPUT]
...
  storage.type              filesystem

Логи будут отправляться на диск:

• при превышении Mem_Buf_Limit

• при превышении разрешённого количества чанков в памяти. Задаётся глобально параметром storage.max_chunks_up (по-умолчанию 128). Для конкретного input плагина размер чанка задаётся через Buffer_Chunk_Size и Buffer_Max_Size

Подробнее можно почитать по ссылкам

• https://docs.fluentbit.io/manual/administration/buffering-and-storage

• https://docs.fluentbit.io/manual/pipeline/inputs/tail

В релизных образах fluent-bit не содержится никаких дополнительных инструментов. Для дебага необходимо пользоваться специальными образами с суффиксом -debug
Например, 1.9.2-debug

Теперь можно понаблюдать, как растёт очередь логов на файловой системе

watch -n 5 "kubectl get po | grep flue | cut -d' ' -f1 | xargs -I{} sh -c 'kubectl exec -t {} -- du -hs /fluent-bit/log/storage'"

Итак, проблема в том, что логи в input плагине появляются быстрее, чем успевают отправляться в output плагине. Почему так происходит?

Первым предположением было то, что Loki не успевает принимать и обрабатывать логи, однако

отсутствие нагрузки на loki

и вывод дебаг-лога fluent-bit

[2022/04/27 10:11:31] [debug] [upstream] KA connection #94 to loki-headless.logging.svc.cluster.local:3100 has been assigned (recycled)
[2022/04/27 10:11:31] [debug] [output:loki:loki.0] loki-headless.logging.svc.cluster.local:3100, HTTP status=204
[2022/04/27 10:11:31] [debug] [upstream] KA connection #94 to loki-headless.logging.svc.cluster.local:3100 is now available
 
[2022/04/27 10:11:32] [debug] [upstream] KA connection #94 to loki-headless.logging.svc.cluster.local:3100 has been assigned (recycled)
[2022/04/27 10:11:32] [debug] [output:loki:loki.0] loki-headless.logging.svc.cluster.local:3100, HTTP status=204
[2022/04/27 10:11:32] [debug] [upstream] KA connection #94 to loki-headless.logging.svc.cluster.local:3100 is now available
 
[2022/04/27 10:11:33] [debug] [upstream] KA connection #94 to loki-headless.logging.svc.cluster.local:3100 has been assigned (recycled)
[2022/04/27 10:11:33] [debug] [output:loki:loki.0] loki-headless.logging.svc.cluster.local:3100, HTTP status=204
[2022/04/27 10:11:33] [debug] [upstream] KA connection #94 to loki-headless.logging.svc.cluster.local:3100 is now available
 
[2022/04/27 10:11:34] [debug] [upstream] KA connection #94 to loki-headless.logging.svc.cluster.local:3100 has been assigned (recycled)
[2022/04/27 10:11:34] [debug] [output:loki:loki.0] loki-headless.logging.svc.cluster.local:3100, HTTP status=204
[2022/04/27 10:11:34] [debug] [upstream] KA connection #94 to loki-headless.logging.svc.cluster.local:3100 is now available
 
[2022/04/27 10:11:35] [debug] [upstream] KA connection #94 to loki-headless.logging.svc.cluster.local:3100 has been assigned (recycled)
[2022/04/27 10:11:35] [debug] [output:loki:loki.0] loki-headless.logging.svc.cluster.local:3100, HTTP status=204
[2022/04/27 10:11:35] [debug] [upstream] KA connection #94 to loki-headless.logging.svc.cluster.local:3100 is now available
 
[2022/04/27 10:11:36] [debug] [upstream] KA connection #94 to loki-headless.logging.svc.cluster.local:3100 has been assigned (recycled)
[2022/04/27 10:11:36] [debug] [output:loki:loki.0] loki-headless.logging.svc.cluster.local:3100, HTTP status=204
[2022/04/27 10:11:36] [debug] [upstream] KA connection #94 to loki-headless.logging.svc.cluster.local:3100 is now available
 
[2022/04/27 10:11:37] [debug] [upstream] KA connection #94 to loki-headless.logging.svc.cluster.local:3100 has been assigned (recycled)
[2022/04/27 10:11:37] [debug] [output:loki:loki.0] loki-headless.logging.svc.cluster.local:3100, HTTP status=204
[2022/04/27 10:11:37] [debug] [upstream] KA connection #94 to loki-headless.logging.svc.cluster.local:3100 is now available

говорят о том, что Loki принимает все логи с той скоростью, с которой fluent-bit их отправляет

Значит проблему надо искать на стороне fluent-bit в том, как он отправляет логи

Как fluent-bit отправляет логи

Пора обратиться к документации

Fluent Bit has an Engine that helps to coordinate the data ingestion from input plugins and calls the Scheduler to decide when it is time to flush the data through one or multiple output plugins

Fluent-bit один раз в определённый интервал времени собирает данные из буфера input плагинов, прогоняет через фильтры и отправляет в output плагины. Это интервал задаётся глобально параметром Flush в секции [SERVICE]. Выходит, никакой тонкой настройки output плагинов и возможности отправлять некий буфер сразу после его накопления - нет, а единственный вариант - это просто чаще отправлять логи

Отправляем логи чаще

Что ж, попробуем отправлять логи каждые 100мс

[SERVICE]
  Flush                     0.1
...

Похоже, что теперь логи успевают отправляться, но неужели нет более элегантного способа, чем просто чаще отправлять данные? Тем более, что это всё происходит в одном потоке

Оказывается, есть способ лучше

Используем многопоточность

В fluent-bit 1.7.0 добавили многопоточность, которая позволяет output плагинам выполнять обработку и доставку логов в отдельных потоках. Количество потоков задаётся через параметр Workers

Что конкретно происходит при вынесении доставки в отдельный поток, в рамках этой статьи останется магией, потому что в документации об этом не говорится и надо пристально изучать код на C. Поэтому просто поэкспериментируем, выставив отправку логов каждые 5 секунд и один отдельный воркер для Loki output

Конфиг

[SERVICE]
  Flush                     5
...
[OUTPUT]
  Name                      loki
...
  Workers                   1

Файловый буфер

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

Дебаг лог

[2022/04/27 13:25:08] [debug] [output:loki:loki.0] task_id=0 assigned to thread #0
[2022/04/27 13:25:08] [debug] [upstream] KA connection #125 to loki-headless.logging.svc.cluster.local:3100 has been assigned (recycled)
[2022/04/27 13:25:08] [debug] [output:loki:loki.0] loki-headless.logging.svc.cluster.local:3100, HTTP status=204
[2022/04/27 13:25:08] [debug] [upstream] KA connection #125 to loki-headless.logging.svc.cluster.local:3100 is now available
 
[2022/04/27 13:25:13] [debug] [output:loki:loki.0] task_id=1 assigned to thread #0
[2022/04/27 13:25:13] [debug] [upstream] KA connection #122 to loki-headless.logging.svc.cluster.local:3100 has been assigned (recycled)
[2022/04/27 13:25:13] [debug] [output:loki:loki.0] loki-headless.logging.svc.cluster.local:3100, HTTP status=204
[2022/04/27 13:25:13] [debug] [upstream] KA connection #122 to loki-headless.logging.svc.cluster.local:3100 is now available
 
[2022/04/27 13:25:18] [debug] [output:loki:loki.0] task_id=2 assigned to thread #0
[2022/04/27 13:25:18] [debug] [upstream] KA connection #119 to loki-headless.logging.svc.cluster.local:3100 has been assigned (recycled)
[2022/04/27 13:25:18] [debug] [output:loki:loki.0] task_id=0 assigned to thread #0
[2022/04/27 13:25:18] [debug] [output:loki:loki.0] task_id=3 assigned to thread #0
[2022/04/27 13:25:18] [debug] [upstream] KA connection #114 to loki-headless.logging.svc.cluster.local:3100 has been assigned (recycled)
[2022/04/27 13:25:18] [debug] [output:loki:loki.0] task_id=1 assigned to thread #0
[2022/04/27 13:25:18] [debug] [output:loki:loki.0] task_id=4 assigned to thread #0
[2022/04/27 13:25:18] [debug] [output:loki:loki.0] loki-headless.logging.svc.cluster.local:3100, HTTP status=204
[2022/04/27 13:25:18] [debug] [upstream] KA connection #119 to loki-headless.logging.svc.cluster.local:3100 is now available
[2022/04/27 13:25:18] [debug] [upstream] KA connection #116 to loki-headless.logging.svc.cluster.local:3100 has been assigned (recycled)
[2022/04/27 13:25:18] [debug] [upstream] KA connection #118 to loki-headless.logging.svc.cluster.local:3100 has been assigned (recycled)
[2022/04/27 13:25:18] [debug] [output:loki:loki.0] loki-headless.logging.svc.cluster.local:3100, HTTP status=204
[2022/04/27 13:25:18] [debug] [upstream] KA connection #114 to loki-headless.logging.svc.cluster.local:3100 is now available
[2022/04/27 13:25:18] [debug] [output:loki:loki.0] loki-headless.logging.svc.cluster.local:3100, HTTP status=204
[2022/04/27 13:25:18] [debug] [upstream] KA connection #116 to loki-headless.logging.svc.cluster.local:3100 is now available
[2022/04/27 13:25:18] [debug] [upstream] KA connection #125 to loki-headless.logging.svc.cluster.local:3100 has been assigned (recycled)
[2022/04/27 13:25:18] [debug] [output:loki:loki.0] loki-headless.logging.svc.cluster.local:3100, HTTP status=204
[2022/04/27 13:25:18] [debug] [upstream] KA connection #125 to loki-headless.logging.svc.cluster.local:3100 is now available
[2022/04/27 13:25:18] [debug] [output:loki:loki.0] loki-headless.logging.svc.cluster.local:3100, HTTP status=204
[2022/04/27 13:25:18] [debug] [upstream] KA connection #118 to loki-headless.logging.svc.cluster.local:3100 is now available
 
[2022/04/27 13:25:23] [debug] [output:loki:loki.0] task_id=5 assigned to thread #0
[2022/04/27 13:25:23] [debug] [output:loki:loki.0] task_id=0 assigned to thread #0
[2022/04/27 13:25:23] [debug] [output:loki:loki.0] task_id=1 assigned to thread #0
[2022/04/27 13:25:23] [debug] [upstream] KA connection #122 to loki-headless.logging.svc.cluster.local:3100 has been assigned (recycled)
[2022/04/27 13:25:23] [debug] [upstream] KA connection #119 to loki-headless.logging.svc.cluster.local:3100 has been assigned (recycled)
[2022/04/27 13:25:23] [debug] [output:loki:loki.0] loki-headless.logging.svc.cluster.local:3100, HTTP status=204
[2022/04/27 13:25:23] [debug] [upstream] KA connection #122 to loki-headless.logging.svc.cluster.local:3100 is now available
[2022/04/27 13:25:23] [debug] [upstream] KA connection #114 to loki-headless.logging.svc.cluster.local:3100 has been assigned (recycled)
[2022/04/27 13:25:23] [debug] [output:loki:loki.0] loki-headless.logging.svc.cluster.local:3100, HTTP status=204
[2022/04/27 13:25:23] [debug] [upstream] KA connection #114 to loki-headless.logging.svc.cluster.local:3100 is now available
[2022/04/27 13:25:23] [debug] [output:loki:loki.0] loki-headless.logging.svc.cluster.local:3100, HTTP status=204
[2022/04/27 13:25:23] [debug] [upstream] KA connection #119 to loki-headless.logging.svc.cluster.local:3100 is now available

По дебаг логу видно, что событие отправки логов стартует каждые 5 секунд, однако за счёт использования отдельного потока в каждом событии одновременно запускается сразу несколько задач (task_id=#), которые отправляют в Loki накопившиеся чанки

Вывод

• При использовании fluent-bit данная проблема может воспроизводиться при отправке не только в Loki, но и в другие хранилища/форвардеры логов. Стоит заметить, что версия 1.7.0 с многопоточностью появилась в феврале 2021 года и с тех пор в некоторые output плагины уже были добавлены значения Workers по-умолчанию (например, в плагин elasticsearch с версии 1.8.13), так что при использовании более новых версий fluent-bit с этой проблемой можно не столкнуться

• Использование отдельных потоков - это отличное производительное решение и однозначно нужно использовать именно его вместо уменьшения интервала Flush

• Иногда документации недостаточно и полезно искать анонсы по релизам и читать исходники