Heutzutage ist ein Kubernetes-basiertes Projekt ohne den ELK-Stack nicht mehr vorstellbar, der Protokolle 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-Sammler, der sich immer größerer Beliebtheit erfreut und der Cloud Native Computing Foundation beigetreten ist, weshalb sein Entwicklungsvektor auf den Einsatz in Verbindung mit Kubernetes ausgerichtet ist.
Die Tatsache, Fluentd anstelle von Logstash zu verwenden, ändert nichts am allgemeinen Wesen des Softwarepakets, Fluentd zeichnet sich jedoch durch seine eigenen spezifischen Nuancen aus, die sich aus seiner Vielseitigkeit ergeben.
Als wir beispielsweise anfingen, EFK in einem geschäftigen Projekt mit hoher Protokollierungsintensität einzusetzen, wurden wir mit der Tatsache konfrontiert, dass in Kibana einige Meldungen mehrmals wiederholt angezeigt wurden. In diesem Artikel erklären wir Ihnen, warum dieses Phänomen auftritt und wie Sie das Problem lösen können.
Das Problem der Dokumentenvervielfältigung
In unseren Projekten wird Fluentd als DaemonSet bereitgestellt (automatisch in einer Instanz auf jedem Knoten des Kubernetes-Clusters gestartet) und überwacht stdout-Containerprotokolle in /var/log/containers. Nach der Erfassung und Verarbeitung werden die Protokolle in Form von JSON-Dokumenten an ElasticSearch gesendet und je nach Umfang des Projekts und Anforderungen an Leistung und Fehlertoleranz in Cluster- oder eigenständiger Form erstellt. Als grafische Oberfläche kommt Kibana zum Einsatz.
Bei der Verwendung von Fluentd mit einem Ausgabepuffer-Plugin stießen wir auf eine Situation, in der einige Dokumente in ElasticSearch genau den gleichen Inhalt hatten und sich nur in der Kennung unterschieden. Sie können anhand des Nginx-Protokolls als Beispiel überprüfen, ob es sich um eine Nachrichtenwiederholung handelt. In der Protokolldatei ist diese Meldung in einer einzigen Kopie vorhanden:
127.0.0.1 192.168.0.1 - [28/Feb/2013:12:00:00 +0900] "GET / HTTP/1.1" 200 777 "-" "Opera/12.0" -Es gibt jedoch mehrere Dokumente in ElasticSearch, die diese Meldung 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 Sie dieses Problem in den Fluentd-Protokollen beheben, können Sie eine große Anzahl von Warnungen mit folgendem Inhalt sehen:
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"Diese Warnungen treten auf, wenn ElasticSearch innerhalb der durch den Parameter „request_timeout“ angegebenen Zeit keine Antwort auf eine Anfrage zurückgeben kann, weshalb das weitergeleitete Pufferfragment nicht gelöscht werden kann. Danach versucht Fluentd erneut, das Pufferfragment 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] 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 behandelt jedoch jedes der übertragenen Pufferfragmente als einzigartig und weist ihnen während der Indizierung eindeutige _id-Feldwerte zu. So erscheinen Kopien von Nachrichten.
In Kibana sieht es so aus:
Die Lösung
Es gibt mehrere Möglichkeiten, dieses Problem zu lösen. Einer davon ist der im Plugin „fluent-plugin-elasticsearch“ integrierte Mechanismus zum Generieren eines eindeutigen Hashs für jedes Dokument. Wenn Sie diesen Mechanismus nutzen, erkennt ElasticSearch Wiederholungen bei der Weiterleitung und verhindert doppelte Dokumente. Wir müssen jedoch berücksichtigen, dass diese Methode zur Lösung des Problems Schwierigkeiten mit der Untersuchung hat und den Fehler aufgrund fehlender Zeitüberschreitung nicht beseitigt, weshalb wir auf ihre Verwendung verzichtet haben.
Wir verwenden ein Pufferungs-Plugin für die Fluentd-Ausgabe, um Protokollverluste bei kurzfristigen Netzwerkproblemen oder erhöhter Protokollierungsintensität zu verhindern. Wenn ElasticSearch aus irgendeinem Grund nicht in der Lage ist, ein Dokument sofort in den Index zu schreiben, wird das Dokument in die Warteschlange gestellt und auf der Festplatte gespeichert. Um die Ursache des Problems zu beseitigen, das zu dem oben beschriebenen Fehler führt, ist es in unserem Fall daher erforderlich, die richtigen Werte für die Pufferparameter festzulegen, bei denen der Fluentd-Ausgabepuffer ausreichend groß ist und Gleichzeitig schaffen Sie es, in der vorgegebenen Zeit gelöscht zu werden.
Es ist erwähnenswert, dass die Werte der unten besprochenen Parameter in jedem konkreten Fall der Verwendung der Pufferung in Ausgabe-Plugins individuell sind, da sie von vielen Faktoren abhängen: der Intensität des Schreibens von Nachrichten in das Protokoll durch Dienste, der Leistung des Festplattensystems und des Netzwerks Kanallast und seine Bandbreite. Um also für jeden Einzelfall passende, aber nicht redundante Puffereinstellungen zu erhalten und langwierige Blindsuchen zu vermeiden, kann man die Debugging-Informationen nutzen, die Fluentd im Betrieb in sein Protokoll schreibt, und relativ schnell an die richtigen Werte kommen.
Zum Zeitpunkt der Problemaufnahme sah die Konfiguration so aus:
<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>Bei der Lösung des Problems wurden die Werte der folgenden Parameter manuell ausgewählt:
chunk_limit_size – die Größe der Blöcke, in die Nachrichten im Puffer unterteilt werden.
- Flush_Interval – Zeitintervall, nach dem der Puffer geleert wird.
- queue_limit_length – die maximale Anzahl von Blöcken in der Warteschlange.
- request_timeout ist die Zeit, für die die Verbindung zwischen Fluentd und ElasticSearch hergestellt wird.
Die Gesamtpuffergröße kann durch Multiplikation der Parameter queue_limit_length und chunk_limit_size berechnet werden, was als „die maximale Anzahl von Chunks in der Warteschlange, von denen jeder eine bestimmte Größe hat“ interpretiert werden kann. Wenn die Puffergröße nicht ausreicht, wird in den Protokollen die folgende Warnung angezeigt:
2020-01-21 10:22:57 +0000 [warn]: [test-prod] failed to write data into buffer by buffer overflow action=:blockDies bedeutet, dass der Puffer nicht innerhalb der vorgesehenen Zeit gelöscht werden kann und die Daten, die in den vollen Puffer gelangen, blockiert werden, was zum Verlust eines Teils der Protokolle führt.
Sie können den Puffer auf zwei Arten vergrößern: entweder durch Erhöhen der Größe jedes Blocks in der Warteschlange oder durch Erhöhen der Anzahl der Blöcke, die sich in der Warteschlange befinden können.
Wenn Sie die Blockgröße chunk_limit_size auf mehr als 32 Megabyte festlegen, akzeptiert ElasticSeacrh dies nicht, da das eingehende Paket zu groß ist. Wenn Sie den Puffer weiter vergrößern müssen, ist es daher besser, die maximale Warteschlangenlänge queue_limit_length zu erhöhen.
Wenn der Puffer nicht mehr überläuft und nur noch die Meldung „Timeout unzureichend“ übrig bleibt, können Sie mit der Erhöhung des Parameters „request_timeout“ beginnen. Wenn Sie den Wert jedoch auf mehr als 20 Sekunden festlegen, werden in den Fluentd-Protokollen die folgenden Warnungen angezeigt:
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" Diese Meldung hat keinerlei Auswirkungen auf den Betrieb des Systems und bedeutet, dass die Pufferlöschzeit länger gedauert hat als durch den Parameter slow_flush_log_threshold festgelegt. Hierbei handelt es sich um Debugging-Informationen, die wir bei der Auswahl des Werts des Parameters „request_timeout“ verwenden.
Der verallgemeinerte Auswahlalgorithmus lautet wie folgt:
- Setzen Sie request_timeout auf einen Wert, der garantiert größer als nötig ist (Hunderte von Sekunden). Das Hauptkriterium für die korrekte Einstellung dieses Parameters beim Setup ist das Verschwinden der Warnungen wegen fehlender Zeitüberschreitung.
- Warten Sie auf Meldungen zum Überschreiten des slow_flush_log_threshold-Schwellenwerts. Der Warntext im Feld „elapsed_time“ zeigt die tatsächliche Zeit an, in der der Puffer gelöscht wurde.
- Setzen Sie „request_timeout“ auf einen Wert, der größer ist als der maximale Wert für „elapsed_time“, der während des Beobachtungszeitraums ermittelt wurde. Wir berechnen den request_timeout-Wert als verstrichene_Zeit + 50 %.
- Um Warnungen über lange Pufferleerungsvorgänge aus dem Protokoll zu entfernen, können Sie den Wert von slow_flush_log_threshold erhöhen. Wir berechnen diesen Wert als verstrichene_Zeit + 25 %.
Die endgültigen Werte dieser Parameter werden, wie bereits erwähnt, für jeden Fall individuell ermittelt. Durch die Befolgung des oben genannten Algorithmus können wir garantiert den Fehler beseitigen, der zu wiederholten Nachrichten führt.
Die folgende Tabelle zeigt, wie sich die Anzahl der Fehler pro Tag, die zu Duplikaten von Nachrichten führen, bei der Auswahl der Werte der oben beschriebenen Parameter ändert:
Knoten-1
Knoten-2
Knoten-3
Knoten-4
Vorher Nachher
Vorher Nachher
Vorher Nachher
Vorher Nachher
Der Puffer konnte nicht geleert werden
1749/2
694/2
47/0
1121/2
Wiederholungsversuch erfolgreich
410/2
205/1
24/0
241/2
Darüber hinaus ist zu beachten, dass die resultierenden Einstellungen mit zunehmendem Projektwachstum und entsprechend steigender Protokollanzahl an Relevanz verlieren können. Das primäre Anzeichen für eine unzureichende Zeitüberschreitung ist die Rückkehr von Meldungen über einen langen Pufferleerungsprozess im Fluentd-Protokoll, d. h. die Überschreitung des slow_flush_log_threshold-Schwellenwerts. Ab diesem Zeitpunkt verbleibt noch ein kleiner Spielraum, bevor der Parameter „request_timeout“ überschritten wird. Daher ist es erforderlich, rechtzeitig auf diese Nachrichten zu reagieren und den oben beschriebenen Vorgang zur Auswahl der optimalen Einstellungen zu wiederholen.
Abschluss
Die Feinabstimmung des Fluentd-Ausgabepuffers ist einer der Hauptschritte bei der Konfiguration des EFK-Stacks und bestimmt die Stabilität seines Betriebs und die korrekte Platzierung von Dokumenten in Indizes. Basierend auf dem beschriebenen Konfigurationsalgorithmus können Sie sicher sein, dass alle Protokolle in der richtigen Reihenfolge, ohne Wiederholungen oder Verluste, in den ElasticSearch-Index geschrieben werden.
Lesen Sie auch andere Artikel in unserem Blog:
Source: habr.com