V dnešní době si nelze představit projekt založený na Kubernetes bez ELK stacku, který ukládá logy jak aplikací, tak systémových komponent clusteru. V naší praxi používáme EFK stack s Fluentd místo Logstashe.
Fluentd je moderní univerzální sběrač logů, který si získává stále větší oblibu a připojil se k Cloud Native Computing Foundation, a proto je jeho vývojový vektor zaměřen na použití ve spojení s Kubernetes.
Skutečnost, že místo Logstashe používáte Fluentd, nemění obecnou podstatu softwarového balíku, nicméně Fluentd se vyznačuje svými vlastními specifickými nuancemi vyplývajícími z jeho všestrannosti.
Když jsme například začali používat EFK v nabitém projektu s vysokou intenzitou logování, potýkali jsme se s tím, že v Kibaně se některé zprávy zobrazovaly opakovaně několikrát. V tomto článku vám řekneme, proč k tomuto jevu dochází a jak problém vyřešit.
Problém duplikace dokumentů
V našich projektech je Fluentd nasazen jako DaemonSet (automaticky spuštěný v jedné instanci na každém uzlu clusteru Kubernetes) a monitoruje protokoly kontejnerů stdout v /var/log/containers. Po shromáždění a zpracování jsou protokoly ve formě dokumentů JSON odeslány do ElasticSearch, vytvořeny v clusterové nebo samostatné podobě, v závislosti na rozsahu projektu a požadavcích na výkon a odolnost proti chybám. Jako grafické rozhraní se používá Kibana.
Při použití Fluentdu s pluginem pro vyrovnávací paměť výstupu jsme narazili na situaci, kdy některé dokumenty v ElasticSearch měly úplně stejný obsah a lišily se pouze identifikátorem. Jako příklad můžete ověřit, že se jedná o opakování zprávy, pomocí protokolu Nginx. V souboru protokolu tato zpráva existuje v jediné 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" -V ElasticSearch však existuje několik dokumentů, které obsahují tuto zprávu:
{
"_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"
}
}Navíc může být více než dvě opakování.
Při odstraňování tohoto problému v protokolech Fluentd můžete vidět velké množství varování s následujícím obsahem:
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"K těmto varováním dochází, když ElasticSearch nemůže vrátit odpověď na požadavek v době určené parametrem request_timeout, což je důvod, proč předaný fragment vyrovnávací paměti nelze vymazat. Poté se Fluentd znovu pokusí odeslat fragment vyrovnávací paměti do ElasticSearch a po libovolném počtu pokusů se operace úspěšně dokončí:
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 však s každým z přenesených fragmentů vyrovnávací paměti zachází jako s jedinečnými a během indexování jim přiřadí jedinečné hodnoty pole _id. Takto se zobrazují kopie zpráv.
V Kibaně to vypadá takto:
Řešení
Existuje několik možností, jak tento problém vyřešit. Jedním z nich je mechanismus zabudovaný do pluginu fluent-plugin-elasticsearch pro generování jedinečného hashe pro každý dokument. Pokud použijete tento mechanismus, ElasticSearch rozpozná opakování ve fázi předávání a zabrání duplicitním dokumentům. Musíme ale vzít v úvahu, že tento způsob řešení problému bojuje s vyšetřováním a neodstraňuje chybu s nedostatkem timeoutu, proto jsme od jeho používání upustili.
Na výstupu Fluentd používáme bufferovací plugin, abychom zabránili ztrátě logu v případě krátkodobých problémů se sítí nebo zvýšené intenzity logování. Pokud z nějakého důvodu ElasticSearch nemůže okamžitě zapsat dokument do indexu, dokument je zařazen do fronty a uložen na disk. Proto je v našem případě pro odstranění zdroje problému, který vede k výše popsané chybě, nutné nastavit správné hodnoty parametrů vyrovnávací paměti, při kterých bude mít výstupní vyrovnávací paměť Fluentd dostatečnou velikost a zároveň stihnout vyklidit ve stanoveném čase.
Stojí za zmínku, že hodnoty níže diskutovaných parametrů jsou v každém konkrétním případě použití ukládání do vyrovnávací paměti ve výstupních pluginech individuální, protože závisí na mnoha faktorech: intenzitě zápisu zpráv do protokolu podle služeb, výkonu systému disku, síti zatížení kanálu a jeho šířka pásma. Abyste tedy získali nastavení vyrovnávací paměti, která jsou vhodná pro každý jednotlivý případ, ale nejsou nadbytečná, abyste se vyhnuli zdlouhavému hledání naslepo, můžete využít informace o ladění, které si Fluentd během provozu zapisuje do svého protokolu, a poměrně rychle získat správné hodnoty.
V době, kdy byl problém zaznamenán, vypadala konfigurace takto:
<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>Při řešení problému byly ručně vybrány hodnoty následujících parametrů:
chunk_limit_size — velikost chunků, na které jsou zprávy ve vyrovnávací paměti rozděleny.
- flush_interval — časový interval, po kterém je vyrovnávací paměť vymazána.
- queue_limit_length — maximální počet bloků ve frontě.
- request_timeout je doba, po kterou je navázáno spojení mezi Fluentd a ElasticSearch.
Celkovou velikost vyrovnávací paměti lze vypočítat vynásobením parametrů queue_limit_length a chunk_limit_size, které lze interpretovat jako „maximální počet bloků ve frontě, z nichž každý má danou velikost“. Pokud je velikost vyrovnávací paměti nedostatečná, zobrazí se v protokolech následující varování:
2020-01-21 10:22:57 +0000 [warn]: [test-prod] failed to write data into buffer by buffer overflow action=:blockTo znamená, že buffer nestihne být vyčištěn ve stanoveném čase a data, která vstupují do plného bufferu, jsou zablokována, což povede ke ztrátě části logů.
Vyrovnávací paměť můžete zvětšit dvěma způsoby: buď zvýšením velikosti každého bloku ve frontě, nebo zvýšením počtu bloků, které mohou být ve frontě.
Pokud nastavíte velikost bloku chunk_limit_size na více než 32 megabajtů, ElasticSeacrh to nepřijme, protože příchozí paket bude příliš velký. Pokud tedy potřebujete dále zvýšit vyrovnávací paměť, je lepší zvýšit maximální délku fronty queue_limit_length.
Když vyrovnávací paměť přestane přetékat a zůstane pouze zpráva nedostatečný časový limit, můžete začít zvyšovat parametr request_timeout. Pokud však nastavíte hodnotu na více než 20 sekund, začnou se v protokolech Fluentd objevovat následující varování:
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" Tato zpráva nijak neovlivňuje činnost systému a znamená, že doba vyprázdnění vyrovnávací paměti trvala déle, než je nastaveno parametrem slow_flush_log_threshold. Jedná se o ladicí informace a používáme je při výběru hodnoty parametru request_timeout.
Algoritmus zobecněného výběru je následující:
- Nastavte request_timeout na hodnotu, která bude zaručeně větší, než je nutné (stovky sekund). Při nastavování bude hlavním kritériem pro správné nastavení tohoto parametru zmizení upozornění na nedostatek časového limitu.
- Počkejte na zprávy o překročení limitu slow_flush_log_threshold. Varovný text v poli elapsed_time bude ukazovat skutečný čas vymazání vyrovnávací paměti.
- Nastavte request_timeout na hodnotu větší, než je maximální hodnota elapsed_time získaná během sledovaného období. Hodnotu request_timeout vypočítáme jako elapsed_time + 50 %.
- Chcete-li z protokolu odstranit varování o dlouhých vyprázdněních vyrovnávací paměti, můžete zvýšit hodnotu slow_flush_log_threshold. Tuto hodnotu vypočítáme jako elapsed_time + 25 %.
Konečné hodnoty těchto parametrů, jak bylo uvedeno výše, se získají individuálně pro každý případ. Dodržením výše uvedeného algoritmu zaručeně odstraníme chybu, která vede k opakovaným zprávám.
Níže uvedená tabulka ukazuje, jak se počet chyb za den, vedoucí k duplikaci zpráv, mění v procesu výběru hodnot parametrů popsaných výše:
uzel-1
uzel-2
uzel-3
uzel-4
Před po
Před po
Před po
Před po
se nepodařilo vyprázdnit vyrovnávací paměť
1749/2
694/2
47/0
1121/2
opakovaný pokus byl úspěšný
410/2
205/1
24/0
241/2
Dále stojí za zmínku, že výsledná nastavení mohou ztratit svou relevanci, jak projekt roste, a v důsledku toho se zvyšuje počet protokolů. Primárním znakem nedostatečného časového limitu je návrat zpráv o dlouhém vyprázdnění vyrovnávací paměti do protokolu Fluentd, tedy překročení prahu slow_flush_log_threshold. Od tohoto okamžiku je ještě malá rezerva před překročením parametru request_timeout, proto je nutné na tyto zprávy včas reagovat a zopakovat výše popsaný proces výběru optimálního nastavení.
Závěr
Jemné doladění výstupní vyrovnávací paměti Fluentd je jednou z hlavních fází konfigurace zásobníku EFK, určení stability jeho provozu a správného umístění dokumentů do indexů. Na základě popsaného konfiguračního algoritmu si můžete být jisti, že všechny protokoly budou zapsány do indexu ElasticSearch ve správném pořadí, bez opakování nebo ztrát.
Přečtěte si také další články na našem blogu:
Zdroj: www.habr.com