Oggigiorno è impensabile realizzare un progetto basato su Kubernetes senza la stack ELK, che consente di salvare i log sia delle applicazioni che dei componenti di sistema del cluster. Nella nostra pratica utilizziamo lo stack EFK con Fluentd invece di Logstash.
Fluentd è un moderno e versatile collettore di log, che sta acquisendo sempre più popolarità e si è unito alla Cloud Native Computing Foundation, il che ha orientato il suo sviluppo verso l'uso insieme a Kubernetes.
L'uso di Fluentd invece di Logstash non cambia l'essenza generale della suite software, tuttavia, Fluentd presenta alcune peculiarità derivanti dalla sua multifunzionalità.
Ad esempio, iniziando a utilizzare EFK in un progetto ad alto carico con una forte intensità di scrittura dei log, ci siamo trovati di fronte al fatto che in Kibana alcuni messaggi venivano visualizzati più volte. In questo articolo vi spiegheremo perché si verifica questo fenomeno e come risolvere il problema.
Problema di duplicazione dei documenti
Nei nostri progetti, Fluentd è distribuito come DaemonSet (viene avviato automaticamente in un'istanza su ogni nodo del cluster Kubernetes) e monitora i log stdout dei container in /var/log/containers. Dopo la raccolta e l'elaborazione, i log vengono inviati a ElasticSearch in forma di documenti JSON, che possono essere sollevati in modalità cluster o standalone, a seconda della dimensione del progetto e delle esigenze di prestazioni e tolleranza ai guasti. Come interfaccia grafica utilizziamo Kibana.
Utilizzando Fluentd con un plugin di buffering in uscita, ci siamo trovati di fronte a una situazione in cui alcuni documenti in ElasticSearch hanno contenuti completamente identici e si differenziano solo per l'identificatore. Si può verificare che si tratta effettivamente di duplicati del messaggio prendendo ad esempio il log di Nginx. Nel file di log, 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 esistono diversi documenti contenenti 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, i duplicati possono essere più di due.
Durante la registrazione di questo problema nei log di Fluentd, è possibile osservare un gran numero di avvisi del seguente tenore:
2020-01-16 01:46:46 +0000 [warn]: [test-prod] impossibile svuotare il buffer. retry_time=4 next_retry_seconds=2020-01-16 01:46:53 +0000 chunk="59c37fc3fb320608692c352802b973ce" error_class=Fluent::Plugin::ElasticsearchOutput::RecoverableRequestFailure error="impossibile inviare i log al cluster Elasticsearch ({:host=>"elasticsearch", :port=>9200, :scheme=>"http", :user=>"elastic", :password=>"offuscato"}): timeout di lettura raggiunto"Questi avvisi si verificano quando ElasticSearch non riesce a restituire una risposta alla richiesta entro il tempo stabilito dal parametro request_timeout, motivo per cui il frammento di buffer inviato non può essere svuotato. Successivamente, Fluentd cerca di inviare nuovamente il frammento di buffer a ElasticSearch e, dopo un numero arbitrario di tentativi, l'operazione termina con successo:
2020-01-16 01:47:05 +0000 [warn]: [test-prod] tentativo riuscito. chunk_id="59c37fc3fb320608692c352802b973ce"
2020-01-16 01:47:05 +0000 [warn]: [test-prod] tentativo riuscito. chunk_id="59c37fad241ab300518b936e27200747"
2020-01-16 01:47:05 +0000 [warn]: [test-dev] tentativo riuscito. chunk_id="59c37fc11f7ab707ca5de72a88321cc2"
2020-01-16 01:47:05 +0000 [warn]: [test-dev] tentativo riuscito. chunk_id="59c37fb5adb70c06e649d8c108318c9b"
2020-01-16 01:47:15 +0000 [warn]: [kube-system] tentativo riuscito. chunk_id="59c37f63a9046e6dff7e9987729be66f"Tuttavia, ElasticSearch percepisce ciascuno dei frammenti di buffer inviati come univoco e assegna loro valori unici nei campi _id durante l indicizzazione. In questo modo, si creano copie dei messaggi.
In Kibana appare così:
Soluzione del problema
Esistono diversi modi per affrontare questo problema. Uno di questi è il meccanismo di generazione di un hash unico per ogni documento, integrato nel plugin fluent-plugin-elasticsearch. Utilizzando questo meccanismo, ElasticSearch riconoscerà i duplicati durante la fase di invio e non permetterà la duplicazione dei documenti. Tuttavia, non si può ignorare che questo metodo affronta la conseguenza del problema e non risolve l'errore relativo alla mancanza di timeout, quindi abbiamo deciso di non applicarlo.
Utilizziamo un plugin di buffering all'uscita di Fluentd per evitare la perdita di log in caso di brevi problemi di rete o di un aumento dell'intensità della registrazione dei log. Se per qualche motivo ElasticSearch non riesce a scrivere immediatamente un documento nell'indice, il documento viene messo in coda, che viene memorizzata su disco. Pertanto, nel nostro caso, per eliminare la fonte del problema che porta all'errore sopra descritto, è necessario impostare valori corretti per i parametri di buffering, in modo che il buffer di output di Fluentd sia di dimensioni sufficienti e riesca a svuotarsi nel tempo assegnato.
Vale la pena notare che i valori dei parametri, di cui si parlerà più avanti, sono individuali in ciascun caso specifico di utilizzo del buffering nei plugin di output, poiché dipendono da numerosi fattori: l'intensità della registrazione nei 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 prove alla cieca, è possibile utilizzare le informazioni di debug che Fluentd scrive nel proprio log durante il funzionamento e ottenere valori corretti in modo relativamente rapido.
Al momento della segnalazione del problema, la configurazione era la seguente:
@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 sono stati manualmente selezionati i valori dei seguenti parametri:
chunk_limit_size — dimensione dei chunk in cui vengono suddivisi i messaggi nel buffer.
- flush_interval — l'intervallo di tempo dopo il quale avviene la pulizia del buffer.
- queue_limit_length — il numero massimo di chunk nella coda.
- request_timeout — il tempo per stabilire una connessione tra Fluentd ed ElasticSearch.
La dimensione totale del buffer può essere calcolata moltiplicando i parametri queue_limit_length e chunk_limit_size, il che può essere interpretato come «il numero massimo di chunk in coda, ognuno dei quali ha una dimensione specificata». Se la dimensione del buffer è insufficiente, nel log apparirà il seguente avviso:
2020-01-21 10:22:57 +0000 [warn]: [test-prod] impossibile scrivere i dati nel buffer a causa dell'overflow del buffer action=:blockQuesto significa che il buffer non riesce a svuotarsi nel tempo assegnato e i dati che arrivano in un buffer pieno vengono bloccati, il che porterà alla perdita di parte dei log.
Il buffer può essere aumentato in due modi: aumentando la dimensione di ogni chunk nella coda o il numero di chunk che possono essere presenti nella coda.
Se si imposta la dimensione del chunk chunk_limit_size a più di 32 megabyte, ElasticSearch non lo accetterà, poiché il pacchetto in arrivo risulterebbe troppo grande. Pertanto, se è necessario aumentare ulteriormente il buffer, è meglio aumentare la lunghezza massima della coda queue_limit_length.
Quando il buffer smetterà di traboccare e rimarrà solo un messaggio riguardante il timeout insufficiente, si potrà iniziare ad aumentare il parametro request_timeout. Tuttavia, impostando un valore superiore a 20 secondi, nel log di Fluentd inizieranno ad apparire i seguenti avvisi:
2020-01-21 09:55:33 +0000 [warn]: [test-dev] il flush del buffer ha impiegato più tempo del 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 indica che il tempo di pulizia del buffer ha superato quello impostato dal parametro slow_flush_log_threshold. Queste sono informazioni di debug e le utilizziamo per la scelta del valore del parametro request_timeout.
L'algoritmo generale per la scelta appare come segue:
- Impostare il valore di request_timeout garantito superiore a quello necessario (centinaia di secondi). Durante la fase di configurazione, il criterio principale per determinare la correttezza dell'impostazione di questo parametro sarà la scomparsa degli avvisi riguardanti il timeout insufficiente.
- Aspettare i messaggi relativi al superamento della soglia slow_flush_log_threshold. Nel testo dell'avviso, nel campo elapsed_time verrà visualizzato il tempo reale di pulizia del buffer.
- Impostare il valore di request_timeout superiore al valore massimo di elapsed_time ottenuto nel periodo di osservazione. Calcoliamo il valore di request_timeout come elapsed_time + 50%.
- Per rimuovere dal log gli avvisi su un lungo svuotamento 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 notato in precedenza, sono individuali per ciascun caso. Seguendo l'algoritmo sopra descritto, eliminiamo garantitamente l'errore che causa la ripetizione dei messaggi.
Nella tabella sottostante è mostrato come varia il numero di errori al giorno, che porta alla duplicazione dei messaggi, durante il tentativo di trovare i valori dei parametri descritti sopra:
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 potrebbero perdere la loro rilevanza durante la crescita del progetto e, di conseguenza, l'aumento del numero di log. Un segno principale della mancanza del timeout impostato è il ritorno nel log di Fluentd di messaggi riguardanti il lungo svuotamento del buffer, cioè il superamento della soglia di slow_flush_log_threshold. Da questo momento c'è un piccolo margine prima di superare il parametro request_timeout, quindi è necessario reagire tempestivamente a questi messaggi e ripetere il processo di ricerca delle impostazioni ottimali, come 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 della collocazione dei documenti negli indici. Seguendo l'algoritmo di configurazione descritto, si può essere certi che tutti i log saranno registrati nell'indice ElasticSearch nell'ordine corretto, senza ripetizioni e perdite.
Leggi anche altri articoli nel nostro blog:
Fonte: habr.com
