Fluentd: Varför det är viktigt att konfigurera utgångsbufferten

Nuförtiden är det omöjligt att föreställa sig ett Kubernetes-baserat projekt utan ELK-stacken, som sparar loggar av både applikationer och systemkomponenter i klustret. I vår praktik använder vi EFK-stacken med Fluentd istället för Logstash.

Fluentd är en modern, universell loggsamlare som vinner mer och mer popularitet och har anslutit sig till Cloud Native Computing Foundation, vilket är anledningen till att dess utvecklingsvektor är fokuserad på användning i samband med Kubernetes.

Faktumet att använda Fluentd istället för Logstash ändrar inte den allmänna essensen av mjukvarupaketet, men Fluentd kännetecknas av sina egna specifika nyanser som ett resultat av dess mångsidighet.

När vi till exempel började använda EFK i ett hektiskt projekt med hög loggningsintensitet, ställdes vi inför det faktum att i Kibana visades vissa meddelanden upprepade gånger flera gånger. I den här artikeln kommer vi att berätta varför detta fenomen uppstår och hur du löser problemet.

Problemet med dubbelarbete

I våra projekt distribueras Fluentd som ett DaemonSet (startas automatiskt i en instans på varje nod i Kubernetes-klustret) och övervakar stdout-behållareloggar i /var/log/containers. Efter insamling och bearbetning skickas loggarna i form av JSON-dokument till ElasticSearch, upptagna i kluster eller fristående form, beroende på projektets omfattning och kraven på prestanda och feltolerans. Kibana används som grafiskt gränssnitt.

När vi använde Fluentd med ett plugin för outputbuffring, stötte vi på en situation där vissa dokument i ElasticSearch hade exakt samma innehåll och endast skilde sig i identifieraren. Du kan verifiera att detta är en meddelandeupprepning med hjälp av Nginx-loggen som exempel. I loggfilen finns detta meddelande i en enda kopia:

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

Det finns dock flera dokument i ElasticSearch som innehåller detta meddelande:

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

Dessutom kan det vara mer än två repetitioner.

När du åtgärdar det här problemet i Fluentd-loggarna kan du se ett stort antal varningar med följande innehåll:

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"

Dessa varningar inträffar när ElasticSearch inte kan returnera ett svar på en begäran inom den tid som anges av parametern request_timeout, vilket är anledningen till att det vidarebefordrade buffertfragmentet inte kan rensas. Efter detta försöker Fluentd skicka buffertfragmentet till ElasticSearch igen och efter ett godtyckligt antal försök slutförs operationen framgångsrikt:

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 behandlar dock vart och ett av de överförda buffertfragmenten som unika och tilldelar dem unika _id-fältvärden under indexering. Så här visas kopior av meddelanden.

I Kibana ser det ut så här:

Lösning

Det finns flera alternativ för att lösa detta problem. En av dem är mekanismen inbyggd i plugin-programmet fluent-plugin-elasticsearch för att generera en unik hash för varje dokument. Om du använder den här mekanismen kommer ElasticSearch att känna igen upprepningar vid vidarebefordran och förhindra dubbletter av dokument. Men vi måste ta hänsyn till att denna metod för att lösa problemet kämpar med utredningen och inte eliminerar felet med brist på timeout, så vi övergav användningen.

Vi använder en buffertplugin på Fluentd-utgången för att förhindra loggförlust i händelse av kortvariga nätverksproblem eller ökad loggningsintensitet. Om ElasticSearch av någon anledning inte kan skriva ett dokument direkt till indexet, ställs dokumentet i kö och lagras på disk. Därför, i vårt fall, för att eliminera källan till problemet som leder till felet som beskrivs ovan, är det nödvändigt att ställa in de korrekta värdena för buffringsparametrarna, där Fluentd-utgångsbufferten kommer att vara av tillräcklig storlek och samtidigt klara av att bli rensad på utsatt tid.

Det är värt att notera att värdena för parametrarna som diskuteras nedan är individuella i varje specifikt fall av användning av buffring i utdataplugins, eftersom de beror på många faktorer: intensiteten av att skriva meddelanden till loggen av tjänster, disksystemprestanda, nätverk kanalbelastning och dess bandbredd. Därför, för att få buffertinställningar som är lämpliga för varje enskilt fall, men inte redundanta, för att undvika långa sökningar i blindo, kan du använda den felsökningsinformation som Fluentd skriver till sin logg under drift och relativt snabbt få fram de korrekta värdena.

När problemet registrerades såg konfigurationen ut så här:

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

När du löste problemet valdes värdena för följande parametrar manuellt:
chunk_limit_size — storleken på de bitar som meddelanden i bufferten är uppdelade i.

• flush_interval — tidsintervall efter vilket bufferten rensas.
• queue_limit_length — det maximala antalet bitar i kön.
• request_timeout är den tid under vilken anslutningen mellan Fluentd och ElasticSearch upprättas.

Den totala buffertstorleken kan beräknas genom att multiplicera parametrarna queue_limit_length och chunk_limit_size, vilket kan tolkas som "det maximala antalet bitar i kön, som var och en har en given storlek." Om buffertstorleken är otillräcklig visas följande varning i loggarna:

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

Det betyder att bufferten inte hinner tömmas på den tilldelade tiden och data som kommer in i hela bufferten blockeras, vilket kommer att leda till att en del av loggarna går förlorade.

Du kan öka bufferten på två sätt: genom att antingen öka storleken på varje bit i kön eller antalet bitar som kan finnas i kön.

Om du ställer in chunk size chunk_limit_size till mer än 32 megabyte, kommer ElasticSeacrh inte att acceptera det, eftersom det inkommande paketet blir för stort. Därför, om du behöver öka bufferten ytterligare, är det bättre att öka den maximala kölängden queue_limit_length.

När bufferten slutar flöda över och endast meddelandet om timeout otillräcklig återstår, kan du börja öka parametern request_timeout. Men om du ställer in värdet på mer än 20 sekunder kommer följande varningar att börja visas i Fluentd-loggarna:

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" 

Detta meddelande påverkar inte systemets funktion på något sätt och betyder att buffertspolningstiden tog längre tid än vad som ställts in av parametern slow_flush_log_threshold. Detta är felsökningsinformation och vi använder den när vi väljer värdet för parametern request_timeout.

Den generaliserade urvalsalgoritmen är som följer:

1. Ställ in request_timeout till ett värde som garanterat är större än nödvändigt (hundratals sekunder). Under inställningen kommer huvudkriteriet för korrekt inställning av denna parameter att vara försvinnandet av varningar för bristande timeout.
2. Vänta på meddelanden om överskridande av tröskelvärdet slow_flush_log_threshold. Varningstexten i elapsed_time-fältet visar den reala tiden som bufferten rensades.
3. Ställ in request_timeout till ett värde som är större än det maximala elapsed_time-värdet som erhållits under observationsperioden. Vi beräknar request_timeout-värdet som elapsed_time + 50 %.
4. För att ta bort varningar om långa buffertspolningar från loggen kan du höja värdet på slow_flush_log_threshold. Vi beräknar detta värde som förfluten_tid + 25 %.

De slutliga värdena för dessa parametrar, som nämnts tidigare, erhålls individuellt för varje fall. Genom att följa ovanstående algoritm kommer vi garanterat att eliminera felet som leder till upprepade meddelanden.

Tabellen nedan visar hur antalet fel per dag, vilket leder till duplicering av meddelanden, ändras i processen för att välja värdena för parametrarna som beskrivs ovan:

nod-1
nod-2
nod-3
nod-4

Före efter
Före efter
Före efter
Före efter

misslyckades med att spola bufferten
1749/2
694/2
47/0
1121/2

försök igen lyckades
410/2
205/1
24/0
241/2

Det är också värt att notera att de resulterande inställningarna kan förlora sin relevans när projektet växer och följaktligen antalet loggar ökar. Det primära tecknet på otillräcklig timeout är returen av meddelanden om en lång buffertspolning till Fluentd-loggen, det vill säga överskridande tröskelvärdet slow_flush_log_threshold. Från och med denna tidpunkt finns det fortfarande en liten marginal innan parametern request_timeout överskrids, så det är nödvändigt att svara på dessa meddelanden i tid och upprepa processen för att välja de optimala inställningarna som beskrivs ovan.

Slutsats

Att finjustera Fluentd-utgångsbufferten är ett av huvudstegen för att konfigurera EFK-stacken, bestämma stabiliteten för dess funktion och korrekt placering av dokument i index. Baserat på den beskrivna konfigurationsalgoritmen kan du vara säker på att alla loggar kommer att skrivas till ElasticSearch-indexet i rätt ordning, utan upprepningar eller förluster.

Läs även andra artiklar på vår blogg:

• Go och Zabbix 5.0 blev vänner
• Uppgradera ett Kubernetes-kluster utan driftstopp
• Kubernetes: varför är det så viktigt att ställa in systemresurshantering?
• Tre enkla knep för att krympa Docker-bilder
• Backup av ett stort antal heterogena webbprojekt

Källa: will.com