Al giorno d'oggi è impossibile immaginare un progetto basato su Kubernetes senza lo stack ELK, che salva i log sia delle applicazioni che dei componenti di sistema del cluster. Nella nostra pratica utilizziamo lo stack EFK con Fluentd anziché Logstash.
Fluentd è un raccoglitore di log moderno e universale che sta guadagnando sempre più popolarità e ha aderito alla Cloud Native Computing Foundation, motivo per cui il suo vettore di sviluppo è focalizzato sull'uso insieme a Kubernetes.
Il fatto di utilizzare Fluentd invece di Logstash non cambia l'essenza generale del pacchetto software, tuttavia Fluentd è caratterizzato da sfumature specifiche derivanti dalla sua versatilità.
Ad esempio, quando abbiamo iniziato a utilizzare EFK in un progetto impegnativo con un'elevata intensità di registrazione, ci siamo trovati di fronte al fatto che in Kibana alcuni messaggi venivano visualizzati più volte. In questo articolo ti spiegheremo perché si verifica questo fenomeno e come risolvere il problema.
Il problema della duplicazione dei documenti
Nei nostri progetti, Fluentd viene distribuito come DaemonSet (avviato automaticamente in un'istanza su ciascun nodo del cluster Kubernetes) e monitora i log del contenitore stdout in /var/log/containers. Dopo la raccolta e l'elaborazione, i log sotto forma di documenti JSON vengono inviati a ElasticSearch, generati in forma cluster o standalone, a seconda della scala del progetto e dei requisiti di prestazioni e tolleranza agli errori. Kibana viene utilizzato come interfaccia grafica.
Quando si utilizza Fluentd con un plug-in di buffering dell'output, abbiamo riscontrato una situazione in cui alcuni documenti in ElasticSearch avevano esattamente lo stesso contenuto e differivano solo nell'identificatore. Puoi verificare che si tratti di una ripetizione del messaggio utilizzando il log Nginx come esempio. Nel file di registro, questo messaggio esiste in un'unica copia:
127.0.0.1 192.168.0.1 - [28/Feb/2013:12:00:00 +0900] "GET / HTTP/1.1" 200 777 "-" "Opera/12.0" -Tuttavia, in ElasticSearch sono presenti diversi documenti che contengono questo messaggio:
{
"_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"
}
}Inoltre, possono esserci più di due ripetizioni.
Durante la risoluzione di questo problema nei log di Fluentd, puoi visualizzare un gran numero di avvisi con il seguente contenuto:
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"Questi avvisi si verificano quando ElasticSearch non può restituire una risposta a una richiesta entro il tempo specificato dal parametro request_timeout, motivo per cui il frammento del buffer inoltrato non può essere cancellato. Successivamente, Fluentd tenta di inviare nuovamente il frammento del buffer a ElasticSearch e dopo un numero arbitrario di tentativi, l'operazione viene completata con successo:
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"Tuttavia, ElasticSearch tratta ciascuno dei frammenti del buffer trasferiti come unici e assegna loro valori di campo _id univoci durante l'indicizzazione. Ecco come appaiono le copie dei messaggi.
A Kibana assomiglia a questo:
La soluzione
Esistono diverse opzioni per risolvere questo problema. Uno di questi è il meccanismo integrato nel plugin fluente-plugin-elasticsearch per generare un hash univoco per ciascun documento. Se utilizzi questo meccanismo, ElasticSearch riconoscerà le ripetizioni in fase di inoltro e impedirà la duplicazione dei documenti. Ma dobbiamo tenere conto del fatto che questo metodo di risoluzione del problema ostacola l'indagine e non elimina l'errore per mancanza di timeout, quindi ne abbiamo abbandonato l'uso.
Utilizziamo un plug-in di buffering sull'output Fluentd per prevenire la perdita di log in caso di problemi di rete a breve termine o di maggiore intensità di registrazione. Se per qualche motivo ElasticSearch non è in grado di scrivere immediatamente un documento nell'indice, il documento viene accodato e archiviato su disco. Pertanto, nel nostro caso, per eliminare la fonte del problema che porta all'errore sopra descritto, è necessario impostare i valori corretti per i parametri di buffering, in cui il buffer di output di Fluentd avrà dimensioni sufficienti e allo stesso tempo riescono a essere cancellati nel tempo assegnato.
Vale la pena notare che i valori dei parametri discussi di seguito sono individuali in ogni caso specifico di utilizzo del buffering nei plugin di output, poiché dipendono da molti fattori: l'intensità della scrittura dei messaggi nel registro da parte dei servizi, le prestazioni del sistema del disco, la rete carico del canale e relativa larghezza di banda. Pertanto, per ottenere impostazioni del buffer adatte ad ogni singolo caso, ma non ridondanti, evitando lunghe ricerche alla cieca, è possibile utilizzare le informazioni di debug che Fluentd scrive nel suo log durante il funzionamento e ottenere in tempi relativamente brevi i valori corretti.
Al momento della registrazione del problema, la configurazione era simile a questa:
<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>Durante la risoluzione del problema, sono stati selezionati manualmente i valori dei seguenti parametri:
Chunk_limit_size — la dimensione dei blocchi in cui sono divisi i messaggi nel buffer.
- flush_interval — intervallo di tempo dopo il quale il buffer viene cancellato.
- coda_limit_lunghezza — il numero massimo di blocchi nella coda.
- request_timeout è il tempo durante il quale viene stabilita la connessione tra Fluentd ed ElasticSearch.
La dimensione totale del buffer può essere calcolata moltiplicando i parametri Queue_limit_length e Chunk_limit_size, che possono essere interpretati come “il numero massimo di blocchi nella coda, ciascuno dei quali ha una determinata dimensione”. Se la dimensione del buffer è insufficiente, nei log verrà visualizzato il seguente avviso:
2020-01-21 10:22:57 +0000 [warn]: [test-prod] failed to write data into buffer by buffer overflow action=:blockCiò significa che il buffer non ha tempo per essere svuotato nel tempo assegnato e i dati che entrano nel buffer pieno vengono bloccati, il che porterà alla perdita di parte dei registri.
Puoi aumentare il buffer in due modi: aumentando la dimensione di ciascun blocco nella coda o il numero di blocchi che possono trovarsi nella coda.
Se imposti la dimensione del blocco Chunk_limit_size su più di 32 megabyte, ElasticSeacrh non lo accetterà, poiché il pacchetto in arrivo sarà troppo grande. Pertanto, se è necessario aumentare ulteriormente il buffer, è meglio aumentare la lunghezza massima della coda tail_limit_length.
Quando il buffer smette di traboccare e rimane solo il messaggio di timeout insufficiente, puoi iniziare ad aumentare il parametro request_timeout. Tuttavia, se imposti il valore su più di 20 secondi, nei log di Fluentd inizieranno a comparire i seguenti avvisi:
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" Questo messaggio non influisce in alcun modo sul funzionamento del sistema e significa che il tempo di svuotamento del buffer ha richiesto più tempo di quanto impostato dal parametro slow_flush_log_threshold. Si tratta di informazioni di debug e le utilizziamo quando scegliamo il valore del parametro request_timeout.
L’algoritmo di selezione generalizzato è il seguente:
- Imposta request_timeout su un valore garantito maggiore del necessario (centinaia di secondi). In fase di setup il criterio principale per la corretta impostazione di questo parametro sarà la scomparsa degli avvisi per mancato timeout.
- Attendi i messaggi relativi al superamento della soglia slow_flush_log_threshold. Il testo di avviso nel campo elapsed_time mostrerà l'ora reale in cui il buffer è stato cancellato.
- Imposta request_timeout su un valore maggiore del valore massimo elapsed_time ottenuto durante il periodo di osservazione. Calcoliamo il valore request_timeout come tempo trascorso + 50%.
- Per rimuovere gli avvisi relativi agli svuotamenti prolungati del buffer dal log, è possibile aumentare il valore di slow_flush_log_threshold. Calcoliamo questo valore come tempo_trascorso + 25%.
I valori finali di questi parametri, come notato in precedenza, si ottengono individualmente per ciascun caso. Seguendo l'algoritmo di cui sopra, abbiamo la garanzia di eliminare l'errore che porta a messaggi ripetuti.
La tabella seguente mostra come il numero di errori giornalieri, che portano alla duplicazione dei messaggi, cambia nel processo di selezione dei valori dei parametri sopra descritti:
nodo-1
nodo-2
nodo-3
nodo-4
Prima dopo
Prima dopo
Prima dopo
Prima dopo
non è riuscito a svuotare il buffer
1749/2
694/2
47/0
1121/2
riprovare è riuscito
410/2
205/1
24/0
241/2
Vale inoltre la pena notare che le impostazioni risultanti potrebbero perdere la loro rilevanza man mano che il progetto cresce e, di conseguenza, aumenta il numero di registri. Il segno principale di timeout insufficiente è la restituzione di messaggi relativi a un lungo svuotamento del buffer nel log Fluentd, ovvero al superamento della soglia slow_flush_log_threshold. Da questo momento in poi c'è ancora un piccolo margine prima che il parametro request_timeout venga superato, quindi è necessario rispondere tempestivamente a questi messaggi e ripetere il processo di selezione delle impostazioni ottimali sopra descritto.
conclusione
La messa a punto del buffer di output di Fluentd è una delle fasi principali della configurazione dello stack EFK, determinando la stabilità del suo funzionamento e il corretto posizionamento dei documenti negli indici. In base all'algoritmo di configurazione descritto, puoi essere sicuro che tutti i log verranno scritti nell'indice ElasticSearch nell'ordine corretto, senza ripetizioni o perdite.
Leggi anche altri articoli sul nostro blog:
Fonte: habr.com