🥇Fluentd: por que é importante configurar o buffer de saída

Hoje em dia é impossível imaginar um projeto baseado em Kubernetes sem a pilha ELK, que salva logs de aplicações e componentes do sistema do cluster. Em nossa prática, usamos a pilha EFK com Fluentd em vez de Logstash.

Fluentd é um coletor de logs moderno e universal que está ganhando cada vez mais popularidade e se juntou à Cloud Native Computing Foundation, por isso seu vetor de desenvolvimento está focado no uso em conjunto com Kubernetes.

O fato de utilizar o Fluentd em vez do Logstash não altera a essência geral do pacote de software, porém, o Fluentd se caracteriza por nuances específicas decorrentes de sua versatilidade.

Por exemplo, quando começamos a usar o EFK em um projeto movimentado e com alta intensidade de registro, nos deparamos com o fato de que no Kibana algumas mensagens eram exibidas repetidamente várias vezes. Neste artigo explicaremos por que esse fenômeno ocorre e como resolver o problema.

O problema da duplicação de documentos

Em nossos projetos, o Fluentd é implantado como um DaemonSet (iniciado automaticamente em uma instância em cada nó do cluster Kubernetes) e monitora os logs do contêiner stdout em /var/log/containers. Após a coleta e processamento, os logs em forma de documentos JSON são enviados para o ElasticSearch, gerados em cluster ou de forma autônoma, dependendo da escala do projeto e dos requisitos de desempenho e tolerância a falhas. Kibana é usado como interface gráfica.

Ao usar o Fluentd com um plugin de buffer de saída, encontramos uma situação em que alguns documentos no ElasticSearch tinham exatamente o mesmo conteúdo e diferiam apenas no identificador. Você pode verificar se esta é uma repetição de mensagem usando o log do Nginx como exemplo. No arquivo de log, esta mensagem existe em uma única cópia:

127.0.0.1 192.168.0.1 - [28/Feb/2013:12:00:00 +0900] "GET / HTTP/1.1" 200 777 "-" "Opera/12.0" -

No entanto, existem vários documentos no ElasticSearch que contêm esta mensagem:

{
  "_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"
  }
}

Além disso, pode haver mais de duas repetições.

Ao corrigir esse problema nos logs do Fluentd, você pode ver um grande número de avisos com o seguinte conteúdo:

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"

Esses avisos ocorrem quando o ElasticSearch não consegue retornar uma resposta a uma solicitação dentro do tempo especificado pelo parâmetro request_timeout, razão pela qual o fragmento do buffer encaminhado não pode ser limpo. Depois disso, o Fluentd tenta enviar o fragmento do buffer para o ElasticSearch novamente e após um número arbitrário de tentativas, a operação é concluída com sucesso:

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"

No entanto, o ElasticSearch trata cada um dos fragmentos de buffer transferidos como únicos e atribui a eles valores de campo _id exclusivos durante a indexação. É assim que aparecem as cópias das mensagens.

No Kibana é assim:

A solução

Existem várias opções para resolver este problema. Um deles é o mecanismo embutido no plugin fluent-plugin-elasticsearch para gerar um hash exclusivo para cada documento. Se você usar esse mecanismo, o ElasticSearch reconhecerá repetições na fase de encaminhamento e evitará documentos duplicados. Mas devemos levar em consideração que este método de resolução do problema dificulta a investigação e não elimina o erro por falta de timeout, por isso abandonamos seu uso.

Usamos um plug-in de buffer na saída do Fluentd para evitar perda de log no caso de problemas de rede de curto prazo ou aumento da intensidade de registro. Se por algum motivo o ElasticSearch não conseguir gravar instantaneamente um documento no índice, o documento será enfileirado e armazenado no disco. Portanto, no nosso caso, para eliminar a origem do problema que leva ao erro descrito acima, é necessário definir os valores corretos para os parâmetros de buffer, nos quais o buffer de saída do Fluentd terá tamanho suficiente e ao mesmo tempo conseguem ser compensados no tempo previsto.

Vale ressaltar que os valores dos parâmetros discutidos a seguir são individuais em cada caso específico de utilização de buffer em plugins de saída, pois dependem de vários fatores: intensidade de gravação de mensagens no log por serviços, desempenho do sistema de disco, rede carga do canal e sua largura de banda. Portanto, para obter configurações de buffer adequadas para cada caso individual, mas não redundantes, evitando pesquisas cegas e demoradas, você pode usar as informações de depuração que o Fluentd grava em seu log durante a operação e obter os valores corretos de forma relativamente rápida.

No momento em que o problema foi registrado, a configuração estava assim:

 <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>

Na resolução do problema, foram selecionados manualmente os valores dos seguintes parâmetros:
chunk_limit_size — o tamanho dos pedaços em que as mensagens no buffer são divididas.

flush_interval — intervalo de tempo após o qual o buffer é limpo.
queue_limit_length — o número máximo de pedaços na fila.
request_timeout é o tempo para o qual a conexão entre Fluentd e ElasticSearch é estabelecida.

O tamanho total do buffer pode ser calculado multiplicando os parâmetros queue_limit_length e chunk_limit_size, que podem ser interpretados como “o número máximo de pedaços na fila, cada um com um determinado tamanho”. Se o tamanho do buffer for insuficiente, o seguinte aviso aparecerá nos logs:

2020-01-21 10:22:57 +0000 [warn]: [test-prod] failed to write data into buffer by buffer overflow action=:block

Isso significa que o buffer não tem tempo para ser limpo no tempo previsto e os dados que entram no buffer cheio são bloqueados, o que levará à perda de parte dos logs.

Você pode aumentar o buffer de duas maneiras: aumentando o tamanho de cada pedaço na fila ou o número de pedaços que podem estar na fila.

Se você definir o tamanho do bloco chunk_limit_size para mais de 32 megabytes, o ElasticSeacrh não o aceitará, pois o pacote recebido será muito grande. Portanto, se você precisar aumentar ainda mais o buffer, é melhor aumentar o comprimento máximo da fila queue_limit_length.

Quando o buffer parar de transbordar e apenas a mensagem de tempo limite insuficiente permanecer, você poderá começar a aumentar o parâmetro request_timeout. No entanto, se você definir o valor para mais de 20 segundos, os seguintes avisos começarão a aparecer nos logs do 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"

Esta mensagem não afeta de forma alguma a operação do sistema e significa que o tempo de liberação do buffer demorou mais do que o definido pelo parâmetro slow_flush_log_threshold. Estas são informações de depuração e as usamos ao escolher o valor do parâmetro request_timeout.

O algoritmo de seleção generalizado é o seguinte:

Defina request_timeout como um valor garantido como maior que o necessário (centenas de segundos). Durante a configuração, o principal critério para a correta configuração deste parâmetro será o desaparecimento dos avisos de falta de timeout.
Aguarde mensagens sobre exceder o limite slow_flush_log_threshold. O texto de aviso no campo elapsed_time mostrará o tempo real em que o buffer foi limpo.
Configure request_timeout para um valor maior que o valor máximo de elapsed_time obtido durante o período de observação. Calculamos o valor request_timeout como elapsed_time + 50%.
Para remover avisos sobre longas liberações de buffer do log, você pode aumentar o valor de slow_flush_log_threshold. Calculamos esse valor como tempo_decorrido + 25%.

Os valores finais desses parâmetros, conforme observado anteriormente, são obtidos individualmente para cada caso. Seguindo o algoritmo acima, garantimos a eliminação do erro que leva à repetição de mensagens.

A tabela abaixo mostra como a quantidade de erros por dia, levando à duplicação de mensagens, muda no processo de seleção dos valores dos parâmetros descritos acima:

nó-1
nó-2
nó-3
nó-4

Antes Depois
Antes Depois
Antes Depois
Antes Depois

falha ao liberar o buffer
1749/2
694/2
47/0
1121/2

tentativa novamente bem-sucedida
410/2
205/1
24/0
241/2

Vale ressaltar ainda que as configurações resultantes podem perder relevância à medida que o projeto cresce e, consequentemente, o número de logs aumenta. O principal sinal de tempo limite insuficiente é o retorno de mensagens sobre uma longa liberação de buffer para o log do Fluentd, ou seja, excedendo o limite slow_flush_log_threshold. Deste ponto em diante, ainda há uma pequena margem antes que o parâmetro request_timeout seja excedido, portanto é necessário responder a essas mensagens em tempo hábil e repetir o processo de seleção das configurações ideais descrito acima.

Conclusão

O ajuste fino do buffer de saída do Fluentd é uma das principais etapas da configuração da pilha EFK, determinando a estabilidade de seu funcionamento e o correto posicionamento dos documentos nos índices. Com base no algoritmo de configuração descrito, você pode ter certeza de que todos os logs serão gravados no índice ElasticSearch na ordem correta, sem repetições ou perdas.

Fluentd: Por que é importante configurar o buffer de saída

O problema da duplicação de documentos

A solução

Conclusão

Leia também outros artigos em nosso blog:

Adicionar um comentário cancelar resposta