De nos jours, il est impossible d'imaginer un projet basé sur Kubernetes sans la pile ELK, qui enregistre les journaux des applications et des composants système du cluster. Dans notre pratique, nous utilisons la pile EFK avec Fluentd au lieu de Logstash.
Fluentd est un collecteur de journaux moderne et universel qui gagne de plus en plus en popularité et a rejoint la Cloud Native Computing Foundation, c'est pourquoi son vecteur de développement est axé sur une utilisation en conjonction avec Kubernetes.
Le fait d'utiliser Fluentd au lieu de Logstash ne change pas l'essence générale du progiciel, cependant, Fluentd se caractérise par ses propres nuances spécifiques résultant de sa polyvalence.
Par exemple, lorsque nous avons commencé à utiliser EFK dans un projet chargé avec une forte intensité de journalisation, nous avons été confrontés au fait que dans Kibana, certains messages étaient affichés plusieurs fois de manière répétée. Dans cet article nous vous expliquerons pourquoi ce phénomène se produit et comment résoudre le problème.
Le problème de la duplication de documents
Dans nos projets, Fluentd est déployé en tant que DaemonSet (lancé automatiquement dans une instance sur chaque nœud du cluster Kubernetes) et surveille les journaux du conteneur stdout dans /var/log/containers. Après collecte et traitement, les logs sous forme de documents JSON sont envoyés à ElasticSearch, élevés sous forme de cluster ou autonome, en fonction de l'ampleur du projet et des exigences de performances et de tolérance aux pannes. Kibana est utilisé comme interface graphique.
Lors de l'utilisation de Fluentd avec un plugin de mise en mémoire tampon de sortie, nous avons rencontré une situation dans laquelle certains documents dans ElasticSearch avaient exactement le même contenu et ne différaient que par l'identifiant. Vous pouvez vérifier qu'il s'agit d'une répétition de message en utilisant le journal Nginx comme exemple. Dans le fichier journal, ce message existe en une seule copie :
127.0.0.1 192.168.0.1 - [28/Feb/2013:12:00:00 +0900] "GET / HTTP/1.1" 200 777 "-" "Opera/12.0" -Cependant, plusieurs documents dans ElasticSearch contiennent ce message :
{
"_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"
}
}De plus, il peut y avoir plus de deux répétitions.
Lors de la résolution de ce problème dans les journaux Fluentd, vous pouvez voir un grand nombre d'avertissements avec le contenu suivant :
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"Ces avertissements se produisent lorsqu'ElasticSearch ne peut pas renvoyer de réponse à une requête dans le délai spécifié par le paramètre request_timeout, raison pour laquelle le fragment de tampon transféré ne peut pas être effacé. Après cela, Fluentd tente d'envoyer à nouveau le fragment de tampon à ElasticSearch et après un nombre arbitraire de tentatives, l'opération se termine avec succès :
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"Cependant, ElasticSearch traite chacun des fragments de tampon transférés comme uniques et leur attribue des valeurs de champ _id uniques lors de l'indexation. C'est ainsi que les copies des messages apparaissent.
Dans Kibana, cela ressemble à ceci :
La solution
Il existe plusieurs options pour résoudre ce problème. L'un d'eux est le mécanisme intégré au plugin fluent-plugin-elasticsearch pour générer un hachage unique pour chaque document. Si vous utilisez ce mécanisme, ElasticSearch reconnaîtra les répétitions au stade du transfert et empêchera les documents en double. Mais il faut garder à l'esprit que cette méthode de résolution du problème peine à l'enquête et n'élimine pas l'erreur faute de délai d'attente, nous avons donc abandonné son utilisation.
Nous utilisons un plugin de mise en mémoire tampon sur la sortie Fluentd pour éviter la perte de journaux en cas de problèmes de réseau à court terme ou d'intensité de journalisation accrue. Si, pour une raison quelconque, ElasticSearch ne parvient pas à écrire instantanément un document dans l'index, le document est mis en file d'attente et stocké sur le disque. Par conséquent, dans notre cas, afin d'éliminer la source du problème qui conduit à l'erreur décrite ci-dessus, il est nécessaire de définir les valeurs correctes pour les paramètres de mise en mémoire tampon, auxquelles le tampon de sortie Fluentd sera de taille suffisante et en même temps réussir à être dégagé dans le temps imparti.
Il convient de noter que les valeurs des paramètres discutés ci-dessous sont individuelles dans chaque cas spécifique d'utilisation de la mise en mémoire tampon dans les plugins de sortie, car elles dépendent de nombreux facteurs : l'intensité de l'écriture des messages dans le journal par les services, les performances du système de disque, le réseau. la charge du canal et sa bande passante. Par conséquent, afin d'obtenir des paramètres de tampon adaptés à chaque cas individuel, mais non redondants, en évitant de longues recherches aveugles, vous pouvez utiliser les informations de débogage que Fluentd écrit dans son journal pendant le fonctionnement et obtenir relativement rapidement les valeurs correctes.
Au moment où le problème a été enregistré, la configuration ressemblait à ceci :
<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>Lors de la résolution du problème, les valeurs des paramètres suivants ont été sélectionnées manuellement :
chunk_limit_size — la taille des morceaux dans lesquels les messages dans le tampon sont divisés.
- flush_interval — intervalle de temps après lequel le tampon est vidé.
- queue_limit_length — le nombre maximum de morceaux dans la file d'attente.
- request_timeout est l'heure pendant laquelle la connexion entre Fluentd et ElasticSearch est établie.
La taille totale du tampon peut être calculée en multipliant les paramètres queue_limit_length et chunk_limit_size, qui peuvent être interprétés comme « le nombre maximum de morceaux dans la file d'attente, chacun ayant une taille donnée ». Si la taille du tampon est insuffisante, l'avertissement suivant apparaîtra dans les journaux :
2020-01-21 10:22:57 +0000 [warn]: [test-prod] failed to write data into buffer by buffer overflow action=:blockCela signifie que le tampon n'a pas le temps d'être vidé dans le temps imparti et que les données qui entrent dans le tampon plein sont bloquées, ce qui entraînera la perte d'une partie des journaux.
Vous pouvez augmenter la mémoire tampon de deux manières : en augmentant soit la taille de chaque morceau dans la file d'attente, soit le nombre de morceaux pouvant être dans la file d'attente.
Si vous définissez la taille du bloc chunk_limit_size sur plus de 32 mégaoctets, ElasticSeacrh ne l'acceptera pas, car le paquet entrant sera trop volumineux. Par conséquent, si vous devez augmenter davantage la mémoire tampon, il est préférable d'augmenter la longueur maximale de la file d'attente queue_limit_length.
Lorsque le tampon cesse de déborder et que seul le message de délai d'attente insuffisant reste, vous pouvez commencer à augmenter le paramètre request_timeout. Cependant, si vous définissez la valeur sur plus de 20 secondes, les avertissements suivants commenceront à apparaître dans les journaux Fluentd :
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" Ce message n'affecte en rien le fonctionnement du système et signifie que le temps de vidage du tampon a pris plus de temps que celui défini par le paramètre slow_flush_log_threshold. Il s'agit d'informations de débogage et nous les utilisons lors du choix de la valeur du paramètre request_timeout.
L'algorithme de sélection généralisé est le suivant :
- Définissez request_timeout sur une valeur garantie supérieure à celle nécessaire (centaines de secondes). Lors de la configuration, le critère principal pour le réglage correct de ce paramètre sera la disparition des avertissements pour manque de timeout.
- Attendez les messages concernant le dépassement du seuil slow_flush_log_threshold. Le texte d'avertissement dans le champ elapsed_time indiquera l'heure réelle à laquelle le tampon a été vidé.
- Définissez request_timeout sur une valeur supérieure à la valeur elapsed_time maximale obtenue pendant la période d'observation. Nous calculons la valeur request_timeout comme elapsed_time + 50 %.
- Pour supprimer du journal les avertissements concernant les longs vidages de tampon, vous pouvez augmenter la valeur de slow_flush_log_threshold. Nous calculons cette valeur comme elapsed_time + 25 %.
Les valeurs finales de ces paramètres, comme indiqué précédemment, sont obtenues individuellement pour chaque cas. En suivant l'algorithme ci-dessus, nous sommes assurés d'éliminer l'erreur qui conduit à des messages répétés.
Le tableau ci-dessous montre comment le nombre d'erreurs par jour, conduisant à la duplication de messages, évolue dans le processus de sélection des valeurs des paramètres décrits ci-dessus :
nœud-1
nœud-2
nœud-3
nœud-4
Avant après
Avant après
Avant après
Avant après
n'a pas réussi à vider le tampon
1749/2
694/2
47/0
1121/2
nouvelle tentative réussie
410/2
205/1
24/0
241/2
Il convient en outre de noter que les paramètres résultants peuvent perdre de leur pertinence à mesure que le projet se développe et, par conséquent, le nombre de journaux augmente. Le principal signe d'un délai d'attente insuffisant est le retour de messages concernant un long vidage de la mémoire tampon dans le journal Fluentd, c'est-à-dire un dépassement du seuil slow_flush_log_threshold. À partir de ce moment, il reste encore une petite marge avant que le paramètre request_timeout ne soit dépassé, il est donc nécessaire de répondre à ces messages en temps opportun et de répéter le processus de sélection des paramètres optimaux décrit ci-dessus.
Conclusion
Le réglage fin du tampon de sortie Fluentd est l'une des principales étapes de configuration de la pile EFK, déterminant la stabilité de son fonctionnement et le placement correct des documents dans les index. Sur la base de l'algorithme de configuration décrit, vous pouvez être sûr que tous les journaux seront écrits dans l'index ElasticSearch dans le bon ordre, sans répétitions ni pertes.
Lisez également d'autres articles sur notre blog:
Source: habr.com