🥇Fluentd: Warum ist die Konfiguration des Ausgabe-Puffers wichtig?

Heutzutage ist es unmöglich, ein Projekt auf Basis von Kubernetes ohne den ELK-Stack vorzustellen, mit dessen Hilfe die Protokolle sowohl der Anwendungen als auch der Systemkomponenten des Clusters gespeichert werden. In unserer Praxis verwenden wir den EFK-Stack mit Fluentd anstelle von Logstash.

Fluentd ist ein moderner, universeller Log-Collector, der zunehmend an Popularität gewinnt und der Cloud Native Computing Foundation beigetreten ist, weshalb sein Entwicklungsfokus auf der gemeinsamen Nutzung mit Kubernetes liegt.

Die Verwendung von Fluentd anstelle von Logstash ändert nicht die grundlegende Funktionsweise des Software-Komplexes, jedoch weist Fluentd seine eigenen spezifischen Nuancen auf, die sich aus seiner Multifunktionalität ergeben.

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

Das Problem der Duplikation von Dokumenten

In unseren Projekten wird Fluentd als DaemonSet bereitgestellt (wird automatisch in einer Instanz auf jedem Knoten des Kubernetes-Clusters gestartet) und überwacht stdout-Protokolle der Container in /var/log/containers. Nach der Sammlung und Verarbeitung gelangen die Protokolle in Form von JSON-Dokumenten in ElasticSearch, das je nach Umfang des Projekts und Anforderungen an Leistung und Ausfallsicherheit im Cluster- oder Standalone-Modus betrieben wird. Kibana wird als grafische Schnittstelle verwendet.

Bei der Verwendung von Fluentd mit einem Puffer-Plugin für den Ausgang sind wir auf eine Situation gestoßen, in der einige Dokumente in ElasticSearch inhaltlich identisch sind und sich nur in der Kennung unterscheiden. Um sicherzustellen, dass es sich tatsächlich um Duplikate handelt, kann man das Beispiel eines Nginx-Logs betrachten. In der Log-Datei existiert diese Nachricht nur einmal:

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 gibt es jedoch 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"
  }
}

Darüber hinaus kann es mehr als zwei Wiederholungen geben.

Während der Erfassung dieses Problems können in den Fluentd-Protokollen zahlreiche Warnungen des folgenden Inhalts beobachtet werden:

2020-01-16 01:46:46 +0000 [warn]: [test-prod] Puffer konnte nicht geleert werden. retry_time=4 next_retry_seconds=2020-01-16 01:46:53 +0000 chunk="59c37fc3fb320608692c352802b973ce" error_class=Fluent::Plugin::ElasticsearchOutput::RecoverableRequestFailure error="konnte keine Protokolle an den Elasticsearch-Cluster ({:host=>"elasticsearch", :port=>9200, :scheme=>"http", :user=>"elastic", :password=>"obfuscated"}): Lese-Timeout überschritten"

Diese Warnungen entstehen, wenn Elasticsearch innerhalb der festgelegten request_timeout-Zeit keine Antwort auf die Anfrage zurückgeben kann, wodurch der übermittelte Pufferabschnitt nicht geleert werden kann. Danach versucht Fluentd, den Pufferabschnitt erneut an Elasticsearch zu senden, und nach einer beliebigen Anzahl von Versuchen wird der Vorgang erfolgreich abgeschlossen:

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

Allerdings betrachtet Elasticsearch jeden der übermittelten Pufferabschnitte als einzigartig und weist ihm eindeutige Werte für die Felder _id bei der Indizierung zu. So entstehen Kopien von Nachrichten.

In Kibana sieht das so aus:

Lösung des Problems

Es gibt mehrere Möglichkeiten zur Lösung dieses Problems. Eine davon ist der in das Plugin fluent-plugin-elasticsearch integrierte Mechanismus zur Generierung eines einzigartigen Hashs für jedes Dokument. Wenn dieser Mechanismus verwendet wird, erkennt ElasticSearch Wiederholungen während der Übermittlung und verhindert die Duplizierung von Dokumenten. Allerdings sollte man nicht außer Acht lassen, dass diese Methode das Problem nur an der Wurzel bekämpft und den Fehler der fehlenden Timeout-Dauer nicht behebt, weshalb wir von ihrer Anwendung abgesehen haben.

Wir verwenden ein Puffern-Plugin am Ausgang von Fluentd, um einen Verlust von Protokollen bei kurzfristigen Netzwerkproblemen oder erhöhtem Protokollierungsaufkommen zu vermeiden. Wenn ElasticSearch aus irgendeinem Grund das Dokument nicht sofort im Index speichern kann, wird das Dokument in eine Warteschlange eingereiht, die auf der Festplatte gespeichert wird. Daher ist es in unserem Fall notwendig, um die Ursache des Problems, die zu dem oben beschriebenen Fehler führt, zu beheben, angemessene Werte für die Pufferparameter zu definieren, sodass der Ausgangspuffer von Fluentd ausreichend ist und in der Lage ist, in der vorgegebenen Zeit geleert zu werden.

Es ist zu beachten, dass die Werte der Parameter, über die wir im Folgenden sprechen werden, in jedem konkreten Fall der Verwendung des Pufferns in den Ausgangs-Plugins individuell sind, da sie von vielen Faktoren abhängig sind: der Intensität der Protokollnachrichten, die von den Diensten geschrieben werden, der Leistungsfähigkeit des Speichersystems, der Auslastung des Netzwerks und seiner Bandbreite. Daher kann man, um für jeden einzelnen Fall passende, aber nicht übermäßige Pufferkonfigurationen zu erhalten und ein langes blindes Ausprobieren zu vermeiden, die Debugging-Informationen nutzen, die Fluentd in sein Protokoll während des Betriebs schreibt, um relativ schnell die korrekten Werte zu erhalten.

Zum Zeitpunkt der Problemfeststellung war die Konfiguration wie folgt:

 @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 Rahmen der manuellen Problemlösung wurden die Werte der folgenden Parameter angepasst:
chunk_limit_size — die Größe der Chunks, in die die Protokollnachrichten im Puffer aufgeteilt werden.

flush_interval — der Zeitraum, 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 Gesamtspeichergröße des Puffers kann berechnet werden, indem die Parameter queue_limit_length und chunk_limit_size multipliziert werden, was interpretiert werden kann als „maximale Anzahl von Chunks in der Warteschlange, von denen jeder ein festgelegtes Volumen hat“. Bei unzureichender Puffergröße erscheint folgende Warnung in den Logs:

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

Das bedeutet, dass der Puffer nicht schnell genug geleert wird, und die Daten, die in den vollen Puffer gelangen, blockiert werden, was zu einem Verlust von Logeinträgen führen wird.

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

Wenn die Chunk-Größe chunk_limit_size mehr als 32 Megabyte beträgt, wird ElasticSearch diesen nicht akzeptieren, da das eingehende Paket zu groß ist. Daher ist es besser, bei einer zusätzlichen Vergrößerung des Puffers die maximale Warteschlangenlänge queue_limit_length zu erhöhen.

Wenn der Puffer nicht mehr überläuft und nur noch die Meldung über den Zeitüberschreitungsmangel verbleibt, kann mit der Erhöhung des Parameters request_timeout begonnen werden. Wenn jedoch der Wert über 20 Sekunden festgelegt wird, erscheinen folgende Warnungen in den Fluentd-Logs:

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

Diese Nachricht hat keinen Einfluss auf das System und bedeutet, dass die Zeit, die zum Leeren des Puffers benötigt wurde, länger war als der Wert, der durch slow_flush_log_threshold festgelegt wurde. Dies ist Debugging-Information und wird bei der Anpassung des Wertes des Parameters request_timeout verwendet.

Der allgemeine Algorithmus zur Anpassung sieht wie folgt aus:

Setzen Sie den Wert von request_timeout garantiert höher, als nötig (Hunderte von Sekunden). Während der Anpassung wird hauptsächlich darauf geachtet, dass die Warnungen über Zeitüberschreitung verschwinden.
Warten Sie auf Nachrichten, die die Schwelle 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.
Stellen Sie den Wert von request_timeout höher ein als den maximalen Wert von elapsed_time, der im Beobachtungszeitraum ermittelt wurde. Wir berechnen den Wert von request_timeout als elapsed_time + 50%.
Um Warnungen im Protokoll über langsame Pufferleerrungen zu entfernen, kann der Wert von slow_flush_log_threshold erhöht werden. Wir berechnen diesen Wert als elapsed_time + 25%.

Die endgültigen Werte dieser Parameter, wie zuvor erwähnt, ergeben sich individuell für jeden Fall. Wenn wir dem oben beschriebenen Algorithmus folgen, beseitigen wir garantiert den Fehler, der zu wiederholten Meldungen führt.

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

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

Vor/Nach
Vor/Nach
Vor/Nach
Vor/Nach

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

Wiederholter Versuch erfolgreich
410/2
205/1
24/0
241/2

Es ist außerdem erwähnenswert, dass die erhaltenen Einstellungen während des Wachstums des Projekts und der damit verbundenen Zunahme der Protokolle ihre Relevanz verlieren können. Ein erstes Anzeichen für einen Mangel an festgelegtem Timeout ist das Zurückkommen von Fluentd-Nachrichten im Protokoll über langsame Pufferleerrungen, d. h. das Überschreiten des Schwellenwerts slow_flush_log_threshold. Ab diesem Zeitpunkt gibt es noch einen kleinen Spielraum, bevor der Parameter request_timeout überschritten wird, weshalb rechtzeitig auf diese Nachrichten reagiert und der oben beschriebene Prozess zur Anpassung der optimalen Einstellungen erneut durchgeführt werden muss.

Fazit

Die Feineinstellung des Ausgabe-Puffers von Fluentd ist einer der Hauptschritte bei der Konfiguration des EFK-Stacks, der die Stabilität seiner Arbeit und die korrekte Platzierung von Dokumenten in den Indizes bestimmt. Basierend auf dem beschriebenen Konfigurationsalgorithmus kann man sicher sein, dass alle Protokolle in der richtigen Reihenfolge, ohne Wiederholungen und Verluste, im ElasticSearch-Index aufgezeichnet werden.