Описание проблемы
Дано
кластер 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
Подробнее можно почитать по ссылкам
В релизных образах 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
Иногда документации недостаточно и полезно искать анонсы по релизам и читать исходники
Estagus
Не появилась ли у вас проблема при многопоточности с out of order?