🥇Fluentd: dlaczego ważne jest skonfigurowanie bufora wyjściowego

W dzisiejszych czasach trudno wyobrazić sobie projekt oparty na Kubernetes bez stosu ELK, który służy do przechowywania logów zarówno aplikacji, jak i komponentów systemowych klastra. W naszej praktyce używamy stosu EFK z Fluentd zamiast Logstash.

Fluentd to nowoczesny, uniwersalny kolektor logów, który zyskuje na popularności i dołączył do Cloud Native Computing Foundation, co sprawia, że jego rozwój jest ukierunkowany na współpracę z Kubernetes.

Fakt użycia Fluentd zamiast Logstash nie zmienia zasadniczej natury kompleksu oprogramowania, jednak Fluentd ma swoje specyficzne niuanse, wynikające z jego wszechstronności.

Na przykład, rozpoczynając korzystanie z EFK w obciążonym projekcie z wysoką intensywnością zapisu logów, napotkaliśmy sytuację, w której w Kibanie niektóre wiadomości były wyświetlane wielokrotnie. W tym artykule wyjaśnimy, dlaczego tak się dzieje i jak rozwiązać ten problem.

Problem duplikacji dokumentów

W naszych projektach Fluentd jest uruchamiany jako DaemonSet (automatycznie uruchamiany w jednym egzemplarzu na każdym węźle klastra Kubernetes) i śledzi logi stdout kontenerów w /var/log/containers. Po zebraniu i przetworzeniu, logi w postaci dokumentów JSON trafiają do ElasticSearch, uruchomionego w trybie klastrowym lub standalone, w zależności od skali projektu oraz wymagań dotyczących wydajności i odporności na awarie. Jako interfejs graficzny używamy Kibany.

Podczas korzystania z Fluentd z wtyczką buforującą napotkaliśmy sytuację, w której niektóre dokumenty w ElasticSearch mają identyczną treść, różniąc się jedynie identyfikatorem. Można to potwierdzić na przykładzie logu Nginx. W pliku logu dana wiadomość występuje w jedynym egzemplarzu:

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

Jednak w ElasticSearch istnieje kilka dokumentów zawierających tę wiadomość:

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

Jednakże, powtórzeń może być więcej niż dwa.

Podczas rejestrowania tego problemu w logach Fluentd można zauważyć dużą ilość ostrzeżeń o następującej treści:

2020-01-16 01:46:46 +0000 [warn]: [test-prod] nie udało się opróżnić bufora. retry_time=4 next_retry_seconds=2020-01-16 01:46:53 +0000 chunk="59c37fc3fb320608692c352802b973ce" error_class=Fluent::Plugin::ElasticsearchOutput::RecoverableRequestFailure error="nie można wysłać logów do klastra Elasticsearch ({:host=>"elasticsearch", :port=>9200, :scheme=>"http", :user=>"elastic", :password=>"obfuscated"}): osiągnięto limit czasu odczytu"

Te ostrzeżenia pojawiają się, gdy ElasticSearch nie może zwrócić odpowiedzi na zapytanie w ustalonym czasie parametrem request_timeout, co uniemożliwia opróżnienie przekazywanego fragmentu bufora. Następnie Fluentd próbuje ponownie wysłać fragment bufora do ElasticSearch, a po dowolnej liczbie prób operacja kończy się sukcesem:

2020-01-16 01:47:05 +0000 [warn]: [test-prod] próba się powiodła. chunk_id="59c37fc3fb320608692c352802b973ce" 
2020-01-16 01:47:05 +0000 [warn]: [test-prod] próba się powiodła. chunk_id="59c37fad241ab300518b936e27200747" 
2020-01-16 01:47:05 +0000 [warn]: [test-dev] próba się powiodła. chunk_id="59c37fc11f7ab707ca5de72a88321cc2" 
2020-01-16 01:47:05 +0000 [warn]: [test-dev] próba się powiodła. chunk_id="59c37fb5adb70c06e649d8c108318c9b" 
2020-01-16 01:47:15 +0000 [warn]: [kube-system] próba się powiodła. chunk_id="59c37f63a9046e6dff7e9987729be66f"

Jednakże, ElasticSearch traktuje każdy z przesyłanych fragmentów bufora jako unikalny i przypisuje im unikalne wartości pól _id podczas indeksowania. W ten sposób pojawiają się kopie wiadomości.

W Kibana wygląda to tak:

Rozwiązanie problemu

Istnieje kilka sposobów rozwiązania tego problemu. Jednym z nich jest wbudowany wtyczką fluent-plugin-elasticsearch mechanizm generowania unikalnego hasha dla każdego dokumentu. Jeśli użyjesz tego mechanizmu, ElasticSearch rozpozna powtórzenia na etapie przesyłania i nie dopuści do duplikacji dokumentów. Jednak należy wziąć pod uwagę, że ten sposób rozwiązania problemu zwalcza konsekwencje, a nie eliminuje błąd braku timeoutu, dlatego zrezygnowaliśmy z jego zastosowania.

Używamy wtyczki buforującej na wyjściu Fluentd, aby zapobiec utracie logów w przypadku chwilowych problemów z siecią lub zwiększonej intensywności zapisu logów. Jeśli z jakiegokolwiek powodu ElasticSearch nie może natychmiast zapisać dokumentu w indeksie, dokument trafia do kolejki, która jest przechowywana na dysku. Dlatego w naszym przypadku, aby wyeliminować źródło problemu, które prowadzi do wystąpienia opisanego powyżej błędu, konieczne jest ustawienie odpowiednich wartości parametrów buforowania, przy których bufor wyjściowy Fluentd będzie odpowiedniej wielkości i jednocześnie zdąży być opróżniony w wyznaczonym czasie.

Warto zauważyć, że wartości parametrów, o których mowa poniżej, są indywidualne w każdym przypadku użycia buforowania w wtyczkach wyjściowych, ponieważ zależą od wielu czynników: intensywności zapisu wiadomości w logach przez usługi, wydajności systemu dyskowego, obciążenia sieci i jej przepustowości. Dlatego, aby uzyskać odpowiednie dla każdego konkretnego przypadku, ale nie nadmierne ustawienia bufora, unikając długiego przeszukiwania na ślepo, można skorzystać z informacji debugowania, które Fluentd zapisuje w swoim logu podczas pracy i stosunkowo szybko uzyskać poprawne wartości.

W momencie stwierdzenia problemu konfiguracja wyglądała następująco:

 @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

Podczas ręcznego rozwiązywania problemu dobierano wartości następujących parametrów:
chunk_limit_size — rozmiar chunków, na które dzielone są wiadomości w buforze.

flush_interval — czas, po którym następuje czyszczenie bufora.
queue_limit_length — maksymalna liczba chunków w kolejce.
request_timeout — czas, na który ustanawiane jest połączenie między Fluentd a ElasticSearch.

Całkowity rozmiar bufora można obliczyć, mnożąc wartości queue_limit_length i chunk_limit_size, co można interpretować jako „maksymalną liczbę chunków w kolejce, z których każdy ma określony rozmiar”. W przypadku niewystarczającego rozmiaru bufora w logach pojawi się następujące ostrzeżenie:

2020-01-21 10:22:57 +0000 [warn]: [test-prod] nie udało się zapisać danych do bufora z powodu przepełnienia bufora action=:block

Oznacza to, że bufor nie może zostać oczyszczony w wyznaczonym czasie, a dane, które przychodzą do wypełnionego bufora, są blokowane, co prowadzi do utraty części logów.

Bufor można zwiększyć na dwa sposoby: zwiększając rozmiar każdego chunku w kolejce lub liczbę chunków, które mogą znajdować się w kolejce.

Jeśli ustawisz rozmiar chunku chunk_limit_size na więcej niż 32 megabajty, ElasticSearch go nie przyjmie, ponieważ пакiet wejściowy będzie zbyt duży. Dlatego, jeśli potrzebujesz dodatkowo zwiększyć bufor, lepiej zwiększyć maksymalną długość kolejki queue_limit_length.

Kiedy bufor przestanie być przepełniony i pozostanie tylko komunikat o braku czasu oczekiwania, można przystąpić do zwiększenia parametru request_timeout. Jednak przy ustawieniu wartości powyżej 20 sekund w logach Fluentd zaczną pojawiać się następujące ostrzeżenia:

2020-01-21 09:55:33 +0000 [warn]: [test-dev] czyszczenie bufora zajęło więcej czasu niż slow_flush_log_threshold: elapsed_time=20.85753920301795 slow_flush_log_threshold=20.0 plugin_id="postgresql-dev"

Ten komunikat nie wpływa na działanie systemu i oznacza, że czas czyszczenia bufora zajął więcej, niż ustalono w parametrze slow_flush_log_threshold. To informacje do debugowania i używamy ich przy dostosowywaniu wartości parametru request_timeout.

Ogólny algorytm dostosowywania wygląda następująco:

Ustanowić wartość request_timeout z gwarancją, że będzie większa niż potrzebna (setki sekund). W czasie konfigurowania głównym kryterium poprawności ustawienia tego parametru będzie zniknięcie ostrzeżeń o braku czasu oczekiwania.
Czekać na wiadomości o przekroczeniu progu slow_flush_log_threshold. W tekście ostrzeżenia w polu elapsed_time będzie podany rzeczywisty czas czyszczenia bufora.
Ustaw wartość request_timeout na wyższą niż maksymalna wartość elapsed_time uzyskana w okresie obserwacji. Obliczamy wartość request_timeout jako elapsed_time + 50%.
Aby usunąć z logu ostrzeżenia o długim czyszczeniu bufora, można podnieść wartość slow_flush_log_threshold. Obliczamy tę wartość jako elapsed_time + 25%.

Ostateczne wartości tych parametrów, jak wcześniej zauważono, są indywidualne dla każdego przypadku. Stosując powyższy algorytm, gwarantujemy wyeliminowanie błędu prowadzącego do powtórzenia komunikatów.

W poniższej tabeli pokazano, jak zmienia się liczba błędów dziennie, które prowadzą do duplikacji komunikatów, podczas dobierania wartości opisanych powyżej parametrów:

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

Przed/Po
Przed/Po
Przed/Po
Przed/Po

nie udało się opróżnić bufora
1749/2
694/2
47/0
1121/2

ponowne próbowanie zakończone sukcesem
410/2
205/1
24/0
241/2

Warto dodatkowo zauważyć, że uzyskane ustawienia mogą stracić swoją aktualność w miarę rozwoju projektu i, co za tym idzie, zwiększenia liczby logów. Pierwszym oznakiem braku ustalonego limitu czasu jest pojawienie się w logu Fluentd komunikatów o długim czyszczeniu bufora, czyli przekroczenie progu slow_flush_log_threshold. Od tego momentu istnieje jeszcze niewielki zapas przed przekroczeniem parametru request_timeout, dlatego konieczne jest terminowe zareagowanie na te komunikaty i ponowne przeprowadzenie procesu dobierania optymalnych ustawień opisanego powyżej.

Podsumowanie

Dopasowanie bufora wyjściowego Fluentd jest jednym z głównych etapów konfigurowania stosu EFK, determinującym stabilność jego działania i poprawność umieszczania dokumentów w indeksach. Opierając się na opisanym algorytmie formatujących, można być pewnym, że wszystkie logi będą zapisywane do indeksu ElasticSearch we właściwej kolejności, bez powtórzeń i strat.

Przeczytaj również inne artykuły na naszym blogu:

Źródło: habr.com