🥇Fluentd: Warum es wichtig ist, den Ausgangspuffer zu konfigurieren

Heute ist es unvorstellbar, ein Projekt auf Basis von Kubernetes ohne den ELK-Stack zu gestalten, der Logdaten sowohl von Anwendungen als auch von Systemkomponenten des Clusters speichert. In unserer Praxis verwenden wir den EFK-Stack mit Fluentd anstelle von Logstash.

Fluentd ist ein moderner, universeller Log-Collector, der zunehmend an Beliebtheit gewinnt und der Cloud Native Computing Foundation beigetreten ist, wodurch sein Entwicklungsschwerpunkt auf der Nutzung in Verbindung mit Kubernetes liegt.

Die Verwendung von Fluentd anstelle von Logstash ändert nichts an der allgemeinen Funktionsweise des Softwarekomplexes, jedoch weist Fluentd eigene spezifische Nuancen auf, die aus seiner Multifunktionalität resultieren.

Zum Beispiel haben wir, als wir EFK in einem stark belasteten Projekt mit hoher Log-Schreibintensität einsetzten, festgestellt, dass in Kibana einige Nachrichten mehrmals wiederholt angezeigt werden. In diesem Artikel erläutern wir, warum dieses Phänomen auftritt und wie man das Problem löst.

Das Problem der Dokumentenduplizierung

In unseren Projekten wird Fluentd als DaemonSet bereitgestellt (automatisch als Einzelinstanz auf jedem Knoten des Kubernetes-Clusters gestartet) und überwacht die stdout-Logs der Container in /var/log/containers. Nach dem Sammeln und der Verarbeitung werden die Logs in Form von JSON-Dokumenten an ElasticSearch übermittelt, das entweder im Cluster- oder im Standalone-Betrieb hängt, abhängig von den Anforderungen des Projekts in Bezug auf Performance und Redundanz.

Bei der Verwendung von Fluentd mit einem Puffer-Plugin sind wir auf eine Situation gestoßen, in der einige Dokumente in ElasticSearch vollständig identischen Inhalt aufweisen, sich jedoch nur durch die ID unterscheiden. Um sicherzustellen, dass dies tatsächlich doppelte Einträge sind, kann man das Beispiel eines Nginx-Logs betrachten. In der Log-Datei kommt diese Nachricht nur einmal vor:

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

In ElasticSearch hingegen gibt es mehrere Dokumente, die diese Nachricht enthalten:

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

Es können mehr als zwei Wiederholungen auftreten.

Beim Festhalten dieses Problems können in den Fluentd-Logs eine Vielzahl von Warnungen beobachtet werden, die folgendes Muster aufweisen:

2020-01-16 01:46:46 +0000 [warn]: [test-prod] konnte den Puffer nicht leeren. retry_time=4 next_retry_seconds=2020-01-16 01:46:53 +0000 chunk="59c37fc3fb320608692c352802b973ce" error_class=Fluent::Plugin::ElasticsearchOutput::RecoverableRequestFailure error="Logs konnten nicht an den Elasticsearch-Cluster ({:host="elasticsearch", :port=9200, :scheme="http", :user="elastic", :password="verblasst"}): Lesezeitüberschreitung erreicht"

Diese Warnmeldungen treten auf, wenn ElasticSearch innerhalb der festgelegten request_timeout Zeit keine Antwort auf die Anfrage zurückgeben kann, wodurch der übertragene Pufferfragment nicht gelöscht werden kann. Daraufhin versucht Fluentd, das Pufferfragment erneut an ElasticSearch zu senden, und nach einer beliebigen Anzahl von Versuchen wird die Operation erfolgreich abgeschlossen:

2020-01-16 01:47:05 +0000 [warn]: [test-prod] Wiederholung erfolgreich. chunk_id="59c37fc3fb320608692c352802b973ce" 
2020-01-16 01:47:05 +0000 [warn]: [test-prod] Wiederholung erfolgreich. chunk_id="59c37fad241ab300518b936e27200747" 
2020-01-16 01:47:05 +0000 [warn]: [test-dev] Wiederholung erfolgreich. chunk_id="59c37fc11f7ab707ca5de72a88321cc2" 
2020-01-16 01:47:05 +0000 [warn]: [test-dev] Wiederholung erfolgreich. chunk_id="59c37fb5adb70c06e649d8c108318c9b" 
2020-01-16 01:47:15 +0000 [warn]: [kube-system] Wiederholung erfolgreich. chunk_id="59c37f63a9046e6dff7e9987729be66f"

ElasticSearch betrachtet jedoch jedes der übertragenen Pufferfragmente als einzigartig und weist ihnen bei der Indizierung eindeutige Werte für die _id-Felder zu. So entstehen Kopien der Nachrichten.

In Kibana sieht das so aus:

Problem lösen

Es gibt mehrere Ansätze zur Lösung dieses Problems. Eine Möglichkeit ist der in das Plugin fluent-plugin-elasticsearch integrierte Mechanismus zur Generierung eines einzigartigen Hashes für jedes Dokument. Wenn dieser Mechanismus verwendet wird, kann ElasticSearch Duplikate bereits beim Versand erkennen und verhindert somit die Erstellung doppelter Dokumente. Allerdings muss man bedenken, dass dieser Lösungsansatz nur die Symptome bekämpft und das Problem mit dem Timeout nicht behebt, weshalb wir von seiner Verwendung absehen mussten.

Wir verwenden ein Puffer-Plugin an der Ausgabe von Fluentd, um den Verlust von Logs bei vorübergehenden Netzwerkproblemen oder erhöhter Logschreibintensität zu verhindern. Wenn ElasticSearch aus irgendeinem Grund das Dokument nicht sofort im Index speichern kann, gelangt das Dokument in eine Warteschlange, die auf der Festplatte gespeichert wird. Um die Ursache des Problems zu beheben, das zu dem oben beschriebenen Fehler führt, müssen die Pufferparameter so festgelegt werden, dass der Ausgangspuffer von Fluentd ausreichend groß ist und sich innerhalb der vorgegebenen Zeit leeren kann.

Es ist wichtig zu erwähnen, dass die Parameterwerte, die im Folgenden behandelt werden, in jedem einzelnen Anwendungsfall der Pufferung in den Ausgangs-Plugins individuell sind, da sie von einer Vielzahl von Faktoren abhängen: der Intensität der Protokollierung von Nachrichten durch die Dienste, der Leistung des Speichersystems, der Auslastung des Netzwerkkanals und seiner Bandbreite. Daher können Sie, um für jeden speziellen Fall geeignete, aber nicht übermäßige Puffer-Einstellungen zu erhalten und langwieriges blindes Ausprobieren zu vermeiden, die Debugging-Informationen nutzen, die Fluentd während des Betriebs in sein Protokoll schreibt, um relativ schnell korrekte Werte zu erhalten.

Zum Zeitpunkt der Problemerkennung sah die Konfiguration wie folgt aus:

 @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

Im Laufe der Problemlösung wurden die Werte der folgenden Parameter manuell ausgewählt:
chunk_limit_size — die Größe der Chunks, in die die Nachrichten im Puffer aufgeteilt werden.

flush_interval — der Zeitintervall, nach dem der Puffer geleert wird.
queue_limit_length — die maximale Anzahl von Chunks in der Warteschlange.
request_timeout — die Zeit, die für die Verbindung zwischen Fluentd und ElasticSearch festgelegt wird.

Die gesamte Pufferspeicherkapazität kann berechnet werden, indem die Parameter queue_limit_length und chunk_limit_size multipliziert werden, was als "maximale Anzahl von Chunks in der Warteschlange, wobei jeder einen festgelegten Umfang hat" interpretiert werden kann. Bei unzureichender Pufferkapazität wird die folgende Warnung in den Protokollen angezeigt:

2020-01-21 10:22:57 +0000 [warn]: [test-prod] konnte Daten aufgrund einer Pufferüberlaufaktion nicht in den Puffer schreiben action=:block

Das bedeutet, dass der Puffer nicht rechtzeitig geleert werden kann und die Daten, die in den gefüllten Puffer eintreffen, blockiert werden, was zu einem Verlust von Protokolldaten führen kann.

Der Puffer kann auf zwei Arten vergrößert werden: entweder durch Erhöhung der Größe jedes Chunks in der Warteschlange oder durch Erhöhung der Anzahl der Chunks, die in der Warteschlange sein können.

Wenn die Chunk-Größe chunk_limit_size auf mehr als 32 Megabyte eingestellt wird, akzeptiert ElasticSearch dies nicht, da das eingehende Paket zu groß wird. Daher ist es besser, die maximale Warteschlangenlänge queue_limit_length zu erhöhen, wenn es notwendig ist, den Puffer weiter zu vergrößern.

Wenn der Puffer nicht mehr überläuft und nur noch die Meldung über den fehlenden Timeout bleibt, kann der Wert für request_timeout erhöht werden. Allerdings erscheinen beim Festlegen eines Wertes über 20 Sekunden folgende Warnungen in den Fluentd-Logs:

2020-01-21 09:55:33 +0000 [warn]: [test-dev] das Pufferspülen dauerte länger als slow_flush_log_threshold: elapsed_time=20.85753920301795 slow_flush_log_threshold=20.0 plugin_id="postgresql-dev"

Diese Meldung hat keinen Einfluss auf den Betrieb des Systems und bedeutet, dass die Zeit für das Leeren des Puffers die im Parameter slow_flush_log_threshold festgelegte Zeit überschreitet. Dies ist Debug-Information und wir verwenden sie, um den Wert des Parameters request_timeout anzupassen.

Der allgemeine Algorithmus zur Anpassung sieht wie folgt aus:

Setzen Sie den Wert für request_timeout auf sicher höher als notwendig (Hunderte von Sekunden). Während der Anpassung ist das Hauptkriterium für die Richtigkeit der Einstellung dieses Parameters das Verschwinden von Warnungen über den fehlenden Timeout.
Warten Sie auf Meldungen, die den Schwellenwert slow_flush_log_threshold überschreiten. Im Text der Warnung wird im Feld elapsed_time die tatsächliche Zeit für das Leeren des Puffers angegeben.
Setzen Sie den Wert für request_timeout höher als den maximalen Wert für elapsed_time, der im Beobachtungszeitraum ermittelt wurde. Wir berechnen den Wert für request_timeout als elapsed_time + 50%.
Um Warnmeldungen über lange Puffersäuberungen aus dem Protokoll zu entfernen, kann der Wert für slow_flush_log_threshold erhöht werden. Wir berechnen diesen Wert als elapsed_time + 25%.

Die endgültigen Werte dieser Parameter sind, wie bereits erwähnt, individuell für jeden Fall. Durch die Befolgung des oben angegebenen Algorithmus garantieren wir, dass der Fehler, der zu wiederholten Meldungen führt, behoben wird.

In der folgenden Tabelle wird gezeigt, wie sich die Anzahl der Fehler pro Tag, die zu doppelten Meldungen führen, bei der Anpassung der oben beschriebenen Parameter verändert:

node-1
node-2
node-3
node-4

Vor/Nachher
Vor/Nachher
Vor/Nachher
Vor/Nachher

Fehler beim Leeren des Puffers
1749/2
694/2
47/0
1121/2

Wiederholungsversuch erfolgreich
410/2
205/1
24/0
241/2

Es ist wichtig zu beachten, dass die erhaltenen Einstellungen während des Wachstums des Projekts und damit der Zunahme der Protokolle ihre Relevanz verlieren können. Ein erstes Anzeichen für das Fehlen eines festgelegten Timeouts sind Meldungen im Fluentd-Log über eine lange Pufferbereinigung, was bedeutet, dass der Schwellenwert slow_flush_log_threshold überschritten wurde. Ab diesem Zeitpunkt gibt es noch einen kleinen Puffer, bevor der Parameter request_timeout überschritten wird, weshalb es notwendig ist, rechtzeitig auf diese Meldungen zu reagieren und den Prozess zur Ermittlung optimaler Einstellungen, der oben beschrieben wurde, erneut durchzuführen.

Fazit

Die Feinabstimmung des Ausgangspuffers von Fluentd ist einer der wichtigsten Schritte bei der Konfiguration des EFK-Stacks, der die Stabilität seines Betriebs und die korrekte Ablage von Dokumenten in den Indizes bestimmt. Anhand des beschriebenen Einstellungsalgorithmus kann man sicher sein, dass alle Protokolle in der richtigen Reihenfolge, ohne Wiederholungen und Verluste, in den ElasticSearch-Index geschrieben werden.