La semaine dernière, j'ai eu un problème sur une infrastructure ELK de logs. Je vous propose de décortiquer içi ce qu'il en est ressorti. Spoiler : j'ai fait une erreur de débutant.

Dabord, un petit rappel de l'architecture de notre infrastructure pour parser et stocker les logs.

Symptômes

En arrivant le matin au bureau, j'ai eu une alerte de mon monitoring sur l'occupation RAM du serveur buffer.

Le scénario classique, quand la RAM monte sur le redis, qui sert de mémoire tampon pour lisser l'arrivées des logs dans notre infra, c'est :

• soit un gros pic de log. Comme nous connaissons les équipes qui nous envoi des logs, et surtout l'audience des appli qui nous envoient leurs logs, c'est souvent dû à un développeur qui active l'envoie de log en debug sur son instance de test/intégration/pré-prod/whatever qui subit des tests de perf/montée en charge. Ca se règle avec une petite gueulante parce qu'il "ne faut pas faire ça sur l'infra de prod". Ca se règle assez vite.
• soit un/plusieurs noeuds de parsing est tombé. Dans l'urgence en relancer des nouveaux, et voir pourquoi certains sont mort. Cela prend un peu plus de temps.

Notre monitoring nous montre aussi depuis quand ça monte : le matin à minuit.

Actions entreprises

Les logstash de parsing

Dans l'urgence, je me suis logué sur les serveurs de parsing et j'ai redémarré les logstash. Pendant qu'ils redémarraient, j'en ai profité pour lire les logs (du redémarrage et d'avant).

Et j'ai stoppé l'entrée de nouveau log dans le buffer redis. Histoire d'éviter que celui-là n'explose aussi.
Il n'y a rien a craindre pour les logs. Ceux qui sont sur le serveur de buffers seront traités quand tout sera remis en place et ceux qu'on empêche d'être envoyé restent bien au chaud sur les serveurs et rejoindront le buffer quand on rouvrira les vannes.

En attendant, les logs des logstash de parsing nous donnent : ils n'arrivent pas à envoyer les logs parsés au cluster elasticsearch. Eclair de génie (en vrai, j'ai honte, j'aurais dû le faire avant) : quel est l'état de notre cluster elasticsearch ?

Le cluster elasticsearch

Un petit coup de curl 'http://un_serveur_elasticsearch/_cluster/health?pretty=true' => "status" : "yellow",. Aïe ! Il y a des unassigned_shards.

Sortons notre script magique, inspiré de cette réponse sur Stackoverflow. Ce script nous permet de forcer l'assignation de shard sur un noeud donné du cluster. Ca surcharge temporairement ce noeud-là, le temps que la magie du cluster fasse son effet et ne redispatche la charge sur l'ensemble du cluster.

Réponse du script : Erreur. Il ne peut pas forcer parce que... parce que QUOI ??? il ne reste que 85% d'espace disque, alors Elasticsearch refuse la création d'un nouvel index. WTF ? Connexion sur un des noeud pour vérifier, effectivement, il reste un peu moins de 15% d'espace libre.

"Expected behavior". Bon, OK. Dans l'urgence, je supprime des vieux logs. On a normalement 30 jours de rétention, je n'en garderais que 28, ça devrait permettre de résorber temporairement cette situation.

Application de notre 2e script magique, largement inspiré de celui-ci. Résultat : l'occupation disque redescend à 55%. C'est à la fois cool, parce que tout repart, la machine se remet en branle, et à la fois pas cool, parce que 2 jours de rétention, ça ne fait pas 30% de notre capacité.

La suite

Fin de l'incident

A ce stade, je remets tout en route, j'attends que le buffer se vide un peu avant de rouvrir les vannes. En quelques minutes, tout est rentré dans l'ordre.

Fin de l'incident.

La vraie raison

A ce stade, tout est fonctionnel, mais je n'ai toujours pas la root cause, la raison première de cet incident.

Je creuse un peu du côté des 30% de capacité en 2 jours. C'est louche.

Nous avons un script qui tourne toutes les nuits qui supprime les logs trop vieux, au delà des 30 jours de rétention. En regardant les graph de notre solution de monitoring, on peut voir clairement que l'espace à commencé à grossir il y a 2 semaines. Ce script n'avait pas tourné depuis 2 semaines. Pourquoi ?

Il requêtait un serveur appartenant au cluster qui a été décommissionné il y a 2 mois et supprimé il y a 2 semaines. Vous le voyez, le pebkac ?

Comment faire pour que cela ne se reproduise plus ?

Plusieurs choses ont été faites pour que je ne rencontre plus ce problème dont je suis indirectement en partie la cause.

1. Descendre les seuils d'alerte pour l'espace disque du cluster elasticsearch, on est passé de 85-95 à 70-80.
2. Réfléchir à l'éventuelle modification du paramètre cluster.routing.allocation.disk.watermark.low
3. Superviser l'exécution du script de suppression des vieux enregistrements
4. Superviser le nombre de jour de log stockés dans elasticsearch

Les points 3. et 4. auraient déjà dû être fait bien avant, dès la mise en place de l'infra. C'est un gros oubli. C'est là qu'a été mon erreur.