Oggi è impensabile avere un progetto basato su Kubernetes senza la stack ELK, che consente di conservare i log sia delle applicazioni che dei componenti di sistema del cluster. Nella nostra pratica utilizziamo la stack EFK con Fluentd al posto di Logstash.
Fluentd è un moderno collettore di log versatile, sempre più popolare e recentemente entrato a far parte della Cloud Native Computing Foundation, il che implica che la sua direzione di sviluppo è orientata all'uso in combinazione con Kubernetes.
L'uso di Fluentd al posto di Logstash non cambia la sostanza del pacchetto software, tuttavia, Fluentd presenta delle specifiche peculiarità, derivate dalla sua multifunzionalità.
Ad esempio, iniziando a utilizzare EFK in un progetto ad alta intensità di scrittura dei log, ci siamo trovati di fronte a alcuni messaggi visualizzati ripetutamente in Kibana. In questo articolo spiegheremo la causa di questo fenomeno e come risolvere il problema.
Il problema della duplicazione dei documenti
Nei nostri progetti, Fluentd è implementato come DaemonSet (avviato automaticamente in un'istanza su ogni nodo del cluster Kubernetes) e monitora i log stdout dei contenitori in /var/log/containers. Dopo la raccolta e l'elaborazione, i log vengono inviati come documenti JSON a ElasticSearch, eseguito in modalità cluster o standalone, a seconda delle dimensioni del progetto e dei requisiti di prestazioni e resilienza. Viene utilizzata Kibana come interfaccia grafica.
Durante l'uso di Fluentd con un plugin di buffering in uscita, ci siamo imbattuti in una situazione in cui alcuni documenti in ElasticSearch avevano contenuti identici e differivano solo per l'identificatore. È possibile verificare che si tratta di messaggi ripetuti prendendo come esempio il log di Nginx. Nel file di log, questo messaggio esiste in un'unica istanza:
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 ci sono 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, le ripetizioni possono essere più di due.
Durante la registrazione di questo problema nei log di Fluentd, si possono osservare numerosi avvisi del seguente tenore:
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 riesce a restituire una risposta alla richiesta entro il tempo impostato da request_timeout, il che impedisce il caricamento del frammento di buffer. Dopo di ciò, Fluentd tenta di inviare nuovamente il frammento di buffer a ElasticSearch, e dopo un numero arbitrario di tentativi, l'operazione ha 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 percepisce ciascuno dei frammenti di buffer ripetuti come unici e assegna loro valori unici per il campo _id durante l'indicizzazione. Così, si creano copie dei messaggi.
In Kibana questo appare così:
Soluzione del problema
Esistono diverse soluzioni a questo problema. Una di queste è il meccanismo integrato nel plugin fluent-plugin-elasticsearch che genera un hash unico per ogni documento. Utilizzando questo meccanismo, ElasticSearch riconoscerà i duplicati durante la fase di invio e eviterà la duplicazione dei documenti. Tuttavia, bisogna considerare che questa soluzione affronta solo le conseguenze e non risolve il problema dell'assenza di timeout, quindi abbiamo deciso di non utilizzarla.
Utilizziamo un plugin di buffer in uscita di Fluentd per evitare la perdita di log in caso di brevi interruzioni di rete o di un aumentato tasso di scrittura dei log. Se per qualche motivo ElasticSearch non riesce a scrivere immediatamente un documento nell'indice, il documento viene messo in coda, che viene archiviata su disco. Pertanto, nel nostro caso, per eliminare la causa del problema che porta all'errore sopra descritto, è necessario impostare valori di configurazione corretti per il buffering, in modo che il buffer di output di Fluentd sia di dimensioni sufficienti e riesca a svuotarsi nel tempo stabilito.
È importante notare che i valori dei parametri di cui si parlerà di seguito sono individuali per ogni specifico caso di utilizzo del buffering nei plugin di uscita, poiché dipendono da molti fattori: l'intensità della registrazione dei messaggi di log da parte dei servizi, le prestazioni del sistema di archiviazione, il carico della rete e la sua capacità di banda. Pertanto, per ottenere impostazioni di buffer appropriate per ogni singolo caso, ma non eccessive, evitando lunghe sperimentazioni alla cieca, si può utilizzare le informazioni di debug che Fluentd scrive nel proprio log durante il funzionamento per ottenere rapidamente valori corretti.
Al momento della registrazione del problema, la configurazione appariva come segue:
@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 blockDurante la risoluzione del problema, i valori dei seguenti parametri sono stati selezionati manualmente:
chunk_limit_size — la dimensione dei chunk in cui vengono suddivisi i messaggi nel buffer.
- flush_interval — intervallo di tempo dopo il quale avviene lo svuotamento del buffer.
- queue_limit_length — numero massimo di chunk nella coda.
- request_timeout — tempo di connessione tra Fluentd ed ElasticSearch.
La dimensione totale del buffer può essere calcolata moltiplicando i parametri queue_limit_length e chunk_limit_size, che può essere interpretata come "numero massimo di chunk nella coda, ognuno dei quali ha una dimensione specificata". Se la dimensione del buffer è insufficiente, apparirà il seguente avviso nei log:
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 riesce a svuotarsi nel tempo stabilito e i dati che vengono inviati al buffer pieno vengono bloccati, il che porterà alla perdita di parte dei log.
È possibile aumentare il buffer in due modi: aumentando la dimensione di ogni chunk in coda o il numero di chunk che possono essere nella coda.
Se si imposta la dimensione del chunk chunk_limit_size superiore a 32 megabyte, ElasticSearch non lo accetterà, poiché il pacchetto in arrivo risulterebbe troppo grande. Pertanto, se è necessario aumentare ulteriormente il buffer, è meglio incrementare la lunghezza massima della coda queue_limit_length.
Quando il buffer smetterà di sovraccaricarsi e rimarrà solo il messaggio riguardante la mancanza di timeout, si potrà procedere ad aumentare il parametro request_timeout. Tuttavia, impostando un valore superiore a 20 secondi, nei log di Fluentd appariranno 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 sul funzionamento del sistema e indica che il tempo di svuotamento del buffer è stato superiore a quanto stabilito dal parametro slow_flush_log_threshold. Questa è informazione di debug che utilizziamo nella selezione del valore del parametro request_timeout.
L'algoritmo generale di selezione appare come segue:
- Impostare il valore di request_timeout garantito superiore a quello necessario (diverse centinaia di secondi). Durante la configurazione, il criterio principale per la correttezza di impostazione di questo parametro sarà la scomparsa degli avvisi riguardanti la mancanza di timeout.
- Attendere i messaggi che superano la soglia slow_flush_log_threshold. Nel testo dell'avviso, nel campo elapsed_time verrà indicato il tempo effettivo di svuotamento del buffer.
- Impostare il valore di request_timeout superiore al valore massimo elapsed_time ottenuto durante il periodo di osservazione. Calcoliamo il valore di request_timeout come elapsed_time + 50%.
- Per rimuovere dagli log gli avvisi riguardanti lo svuotamento lungo del buffer, si può aumentare il valore di slow_flush_log_threshold. Calcoliamo questo valore come elapsed_time + 25%.
I valori finali di questi parametri, come accennato in precedenza, risultano individuali per ogni caso. Seguendo l'algoritmo fornito sopra, ci assicuriamo di eliminare l'errore che causa il ripetersi dei messaggi.
Nella tabella sottostante viene mostrato come il numero di errori durante il giorno, che porta alla duplicazione dei messaggi, varia nel processo di ottimizzazione dei valori dei parametri sopra descritti:
node-1
node-2
node-3
node-4
Prima/Dopo
Prima/Dopo
Prima/Dopo
Prima/Dopo
impossibile svuotare il buffer
1749/2
694/2
47/0
1121/2
tentativo riuscito
410/2
205/1
24/0
241/2
Vale la pena notare che le impostazioni ottenute possono perdere la loro validità con la crescita del progetto e, di conseguenza, l'aumento del numero di log. Un segnale primario di insufficienza del timeout impostato è il ritorno nel log di Fluentd di messaggi riguardanti la lunga pulizia del buffer, vale a dire il superamento della soglia slow_flush_log_threshold. Da questo momento c'è ancora un piccolo margine prima di superare il parametro request_timeout, pertanto è necessario reagire tempestivamente a questi messaggi e ripetere il processo di ottimizzazione delle impostazioni descritto sopra.
Conclusione
La regolazione fine del buffer di uscita di Fluentd è uno dei principali passaggi nella configurazione dello stack EFK, determinando la stabilità del suo funzionamento e la correttezza dell'archiviazione dei documenti negli indici. Seguendo l'algoritmo di configurazione descritto, si può essere certi che tutti i log verranno archiviati in ElasticSearch nell'ordine corretto, senza duplicazioni o perdite.
Leggi anche altri articoli nel nostro blog:
Fonte: habr.com
