W dzisiejszych czasach nie sposób wyobrazić sobie projektu opartego na Kubernetesie bez stosu ELK, na którym zapisywane są logi zarówno aplikacji, jak i komponentów systemowych klastra. W naszej praktyce używamy stosu EFK z Fluentd zamiast Logstash.
Fluentd to nowoczesny, uniwersalny moduł zbierający logi, który zyskuje coraz większą popularność i dołączył do Cloud Native Computing Foundation, dlatego jego wektor rozwoju skupia się na wykorzystaniu w połączeniu z Kubernetesem.
Fakt wykorzystania Fluentd zamiast Logstash nie zmienia ogólnej istoty pakietu oprogramowania, jednakże Fluentd charakteryzuje się swoimi specyficznymi niuansami wynikającymi z jego wszechstronności.
Przykładowo, gdy zaczęliśmy używać EFK w obciążonym projekcie o dużej intensywności logowania, stanęliśmy przed faktem, że w Kibanie niektóre komunikaty wyświetlały się wielokrotnie, kilka razy. W tym artykule dowiemy się, dlaczego występuje to zjawisko i jak rozwiązać problem.
Problem duplikacji dokumentów
W naszych projektach Fluentd jest wdrażany jako DaemonSet (automatycznie uruchamiany w jednej instancji na każdym węźle klastra Kubernetes) i monitoruje standardowe logi kontenerów w /var/log/containers. Po pobraniu i przetworzeniu logi w postaci dokumentów JSON przesyłane są do ElasticSearch, generowane w formie klastra lub samodzielnej, w zależności od skali projektu oraz wymagań dotyczących wydajności i odporności na błędy. Jako interfejs graficzny używana jest Kibana.
Używając Fluentd z wtyczką buforującą dane wyjściowe, napotkaliśmy sytuację, w której niektóre dokumenty w ElasticSearch miały dokładnie tę samą treść i różniły się jedynie identyfikatorem. Możesz sprawdzić, czy jest to powtórzenie komunikatu, korzystając z dziennika Nginx jako przykładu. W pliku dziennika ten komunikat występuje w jednej kopii:
127.0.0.1 192.168.0.1 - [28/Feb/2013:12:00:00 +0900] "GET / HTTP/1.1" 200 777 "-" "Opera/12.0" -Istnieje jednak kilka dokumentów w ElasticSearch, które zawierają ten komunikat:
{
"_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"
}
}Co więcej, powtórzeń może być więcej niż dwa.
Podczas naprawiania tego problemu w dziennikach Fluentd można zobaczyć dużą liczbę ostrzeżeń o następującej treści:
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"Ostrzeżenia te pojawiają się, gdy ElasticSearch nie może zwrócić odpowiedzi na żądanie w czasie określonym przez parametr request_timeout i dlatego nie można wyczyścić przekazanego fragmentu bufora. Następnie Fluentd ponownie próbuje wysłać fragment bufora do ElasticSearch i po dowolnej liczbie prób operacja kończy się pomyślnie:
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"Jednakże ElasticSearch traktuje każdy z przesłanych fragmentów bufora jako unikalny i przypisuje im unikalne wartości pola _id podczas indeksowania. Tak wyglądają kopie wiadomości.
W Kibanie wygląda to tak:
Roztwór
Istnieje kilka opcji rozwiązania tego problemu. Jednym z nich jest wbudowany we wtyczkę fluent-plugin-elasticsearch mechanizm generowania unikalnego skrótu dla każdego dokumentu. Jeśli skorzystasz z tego mechanizmu, ElasticSearch rozpozna powtórzenia na etapie przekazywania i zapobiegnie duplikowaniu dokumentów. Musimy jednak wziąć pod uwagę, że ta metoda rozwiązania problemu jest trudna w dochodzeniu i nie eliminuje błędu związanego z brakiem limitu czasu, dlatego zaprzestaliśmy jej stosowania.
Używamy wtyczki buforującej na wyjściu Fluentd, aby zapobiec utracie logów w przypadku krótkotrwałych problemów z siecią lub zwiększonej intensywności rejestrowania. Jeśli z jakiegoś powodu ElasticSearch nie jest w stanie natychmiast zapisać dokumentu do indeksu, dokument jest umieszczany w kolejce i przechowywany na dysku. Dlatego w naszym przypadku, aby wyeliminować źródło problemu prowadzącego do opisanego powyżej błędu, konieczne jest ustawienie prawidłowych wartości parametrów buforowania, przy których bufor wyjściowy Fluentd będzie miał wystarczającą wielkość i jednocześnie uda się je rozliczyć w wyznaczonym terminie.
Warto zaznaczyć, że wartości omówionych poniżej parametrów są indywidualne w każdym konkretnym przypadku stosowania buforowania we wtyczkach wyjściowych, gdyż zależą od wielu czynników: intensywności zapisywania komunikatów do logu przez usługi, wydajności systemu dyskowego, sieci obciążenie kanału i jego przepustowość. Dlatego też, aby uzyskać ustawienia bufora odpowiednie dla każdego indywidualnego przypadku, ale nie zbędne, unikając w ten sposób długich poszukiwań na ślepo, można wykorzystać informacje debugowania, które Fluentd zapisuje do swojego dziennika podczas działania i stosunkowo szybko uzyskać prawidłowe wartości.
W momencie zarejestrowania problemu konfiguracja wyglądała następująco:
<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>Podczas rozwiązywania problemu ręcznie dobierano wartości następujących parametrów:
chunk_limit_size — rozmiar fragmentów, na jakie podzielone są wiadomości w buforze.
- Flush_interval — przedział czasu, po którym bufor jest czyszczony.
- kolejka_limit_długość — maksymalna liczba fragmentów w kolejce.
- request_timeout to czas, przez jaki nawiązywane jest połączenie pomiędzy Fluentd a ElasticSearch.
Całkowity rozmiar bufora można obliczyć, mnożąc parametry kolejki_limit_długości i chunk_limit_size, co można zinterpretować jako „maksymalną liczbę fragmentów w kolejce, z których każdy ma określony rozmiar”. Jeżeli wielkość bufora będzie niewystarczająca, w logach pojawi się następujące ostrzeżenie:
2020-01-21 10:22:57 +0000 [warn]: [test-prod] failed to write data into buffer by buffer overflow action=:blockOznacza to, że bufor nie ma czasu na wyczyszczenie w wyznaczonym czasie i dane wchodzące do pełnego bufora są blokowane, co będzie skutkować utratą części logów.
Bufor można zwiększyć na dwa sposoby: zwiększając rozmiar każdej porcji w kolejce lub liczbę porcji, które mogą znajdować się w kolejce.
Jeśli ustawisz rozmiar porcji chunk_limit_size na więcej niż 32 megabajty, ElasticSeacrh go nie zaakceptuje, ponieważ przychodzący pakiet będzie za duży. Dlatego jeśli zajdzie potrzeba dalszego zwiększenia bufora, lepiej zwiększyć maksymalną długość kolejki długość_limitu_kolejki.
Gdy bufor przestanie się przepełniać i pozostanie jedynie komunikat o niewystarczającym przekroczeniu limitu czasu, można zacząć zwiększać parametr request_timeout. Jeśli jednak ustawisz wartość na więcej niż 20 sekund, w dziennikach Fluentd zaczną pojawiać się następujące ostrzeżenia:
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" Komunikat ten nie wpływa w żaden sposób na pracę systemu i oznacza, że czas opróżniania bufora trwał dłużej niż ustawiony parametrem slow_flush_log_threshold. Są to informacje debugujące i wykorzystujemy je przy wyborze wartości parametru request_timeout.
Uogólniony algorytm selekcji jest następujący:
- Ustaw request_timeout na wartość, która będzie większa niż to konieczne (setki sekund). Podczas konfiguracji głównym kryterium prawidłowego ustawienia tego parametru będzie zniknięcie ostrzeżeń o braku limitu czasu.
- Poczekaj na komunikaty o przekroczeniu progu slow_flush_log_threshold. Tekst ostrzegawczy w polu elapsed_time będzie wskazywał rzeczywisty czas wyczyszczenia bufora.
- Ustaw request_timeout na wartość większą niż maksymalna wartość, która upłynęła, uzyskana w okresie obserwacji. Obliczamy wartość request_timeout jako czas, który upłynął + 50%.
- Aby usunąć z dziennika ostrzeżenia dotyczące długiego opróżniania bufora, można podnieść wartość slow_flush_log_threshold. Obliczamy tę wartość jako czas, który upłynął + 25%.
Ostateczne wartości tych parametrów, jak wspomniano wcześniej, uzyskuje się indywidualnie dla każdego przypadku. Postępując zgodnie z powyższym algorytmem, mamy gwarancję wyeliminowania błędu prowadzącego do powtarzających się komunikatów.
Poniższa tabela pokazuje jak zmienia się dzienna liczba błędów prowadzących do powielania komunikatów w procesie doboru wartości parametrów opisanych powyżej:
węzeł-1
węzeł-2
węzeł-3
węzeł-4
Przed po
Przed po
Przed po
Przed po
nie udało się opróżnić bufora
1749/2
694/2
47/0
1121/2
ponowna próba powiodła się
410/2
205/1
24/0
241/2
Warto dodatkowo zauważyć, że powstałe ustawienia mogą tracić na znaczeniu wraz z rozwojem projektu i odpowiednio wzrostem liczby logów. Podstawową oznaką niewystarczającego limitu czasu jest powrót komunikatów o długim opróżnieniu bufora do dziennika Fluentd, czyli przekroczeniu progu slow_flush_log_threshold. Od tego momentu do przekroczenia parametru request_timeout pozostaje jeszcze niewielki margines, dlatego należy na te komunikaty reagować w odpowiednim czasie i powtarzać opisany powyżej proces doboru optymalnych ustawień.
wniosek
Dostrojenie bufora wyjściowego Fluentd to jeden z głównych etapów konfiguracji stosu EFK, określający stabilność jego działania i prawidłowe rozmieszczenie dokumentów w indeksach. Bazując na opisanym algorytmie konfiguracji można mieć pewność, że wszystkie logi zostaną zapisane do indeksu ElasticSearch w odpowiedniej kolejności, bez powtórzeń i strat.
Przeczytaj także inne artykuły na naszym blogu:
Źródło: www.habr.com