Sommaire
Premier diagnostic
Le serveur répond au ping et permet les connexions TCP port 22, mais pas le SSH. Et les services web ne répondent plus. Souci matériel ? Noyau en vrac ? Attaque en cours ? Les spéculations vont bon train.
La connexion au serveur revient par intermittence, permettant à un moment d’exécuter quelques commandes, à d’autres d’attendre longuement pour l’affichage d’un caractère ou l’exécution de la commande tapée.
Le premier contact réétabli avec le serveur est assez clair (une forte charge) :
$ uptime
15:06:59 up 2 days, 2:54, 1 user, load average: 50,00, 205,21, 260,83
(dernier redémarrage le week-end précédent, mais surtout une charge système moyenne respectivement de 50, 205 et 261 sur les 1, 5 et 15 dernières minutes)
Initialement on suppose qu’il s’agit d’un trop grand nombre de requêtes ou de certaines requêtes tentant des injections de code sur le site (bref le trafic de fond plutôt habituel et permanent), et on ajoute des règles de filtrage péniblement et lentement pour bloquer les IP qui ressortent le plus dans nos logs.
Le site est alors inaccessible pendant plusieurs périodes. On arrête et relance ensuite plusieurs fois les services en pensant avoir ajouté suffisamment de filtrage, mais rapidement le serveur se retrouve englué. Les services sont alors arrêtés plus longuement le temps d’analyser les logs au calme. Au calme inclut notamment ne pas juste disposer d’une connexion ssh depuis un smartphone, mais plutôt d’un clavier et d’un grand écran par exemple, de l’accès à tous les secrets et toute la documentation aussi.
Finalement le trafic n’est pas énorme (en volume total) et si les requêtes hostiles sont bien présentes, rien ne semble inhabituel. Par contre les processus de coloration syntaxique partent en vrille, consommant chacun un processeur et aspirant allègrement la mémoire disponible. Avant d’être éliminés par le noyau Linux.
La console est remplie d’élimination de processus de ce type :
Mais si rien n’a changé niveau logiciel sur le conteneur LXC de production et si les requêtes ne sont pas inhabituelles, qu’est-ce qui peut bien écrouler le serveur et créer ces processus gourmands ?
Eh bien des requêtes habituelles…
Pendant les phases d’attente lorsque le serveur ne répondait plus vraiment, nous avons noté qu'une nouvelle entrée de suivi a été créée (merci BAud et merci RSS/Atom pour nous avoir permis de la voir alors que le serveur ne répondait déjà plus). Elle indique que la coloration syntaxique ne marche plus sur le site. Notamment l’exemple donné dans la documentation.
Pourtant le rendu fonctionne en testant en ligne de commande avec pygmentize.
Mais oui en testant l’exemple donné via le site, il est créé un processus Python2 pygment qui commence à se gaver de ressources.
Et en regardant les différents contenus et commentaires créés sur le site autour de l’incident, en filtrant sur ceux contenant des blocs avec de la coloration syntaxique, la dépêche (alors en préparation) sur G'MIC 3.6 apparaît. Et en testant cette dépêche, il est bien créé quatre processus Python2 pygment qui se gavent de ressources et ne semblent jamais vouloir se terminer. À rapprocher par exemple d’une page qui a été servie en 6785.9978s.
OK, le souci vient de requêtes tout à fait habituelles de coloration syntaxique, reste à comprendre pourquoi ces processus tournent mal.
La boucle sans fin
Un petit strace pour suivre les appels système en cours sur un des processus infernaux relève une boucle assez violente :
(...)
close(623199355) = -1 EBADF (Bad file descriptor)
close(623199356) = -1 EBADF (Bad file descriptor)
close(623199357) = -1 EBADF (Bad file descriptor)
(...)
Il semble y avoir une immense itération sur des descripteurs de fichiers, en vue de les fermer, mais à l’aveugle, sans savoir s’ils existent réellement.
En regardant le code du composant utilisé (pygments), il semble n'y avoir qu'un seul appel à close() :
# close fd's inherited from the ruby parent
import resource
maxfd = resource.getrlimit(resource.RLIMIT_NOFILE)[1]
if maxfd == resource.RLIM_INFINITY:
maxfd = 65536
for fd in range(3, maxfd):
try:
os.close(fd)
except:
pass
Donc on itère sur tous les descripteurs entre 3 et le maximum déterminé…
>>> import resource
>>> print(resource.getrlimit(resource.RLIMIT_NOFILE)[1])
524288
>>> print(resource.RLIM_INFINITY)
-1
Un demi-million de fois ici donc. L’objectif initial de la boucle est de fermer les descripteurs de fichiers provenant du processus Ruby père, issue du fork via Open3.popen3. La version suivante du composant la remplace d’ailleurs par un ajout de l'option :close_others, qui précisément « modifie l’héritage [des descripteurs de fichiers du processus parent] en fermant les non-standards (numéros 3 et plus grands) ».
Sur une Debian 12, la limite du nombre de fichiers par défaut, c’est 1 048 576. C’est déjà probablement bien plus que la valeur qui prévalait à l’époque où a été écrit la boucle Python (on avait des limitations à 4096 à une époque reculée). Mais il s’avère que durant le week-end l’hôte du conteneur de production a été migré en Debian 13. Sans modification du conteneur de production pensions-nous. Sans modification directe du conteneur de production. Mais quid d’une modification indirecte ? Par exemple si la limite par défaut des « Max open files » était passée à 1 073 741 816 sur l’hôte, soit 1024 fois plus que quelques jours auparavant. Et donc des boucles nettement plus longues voire sans fin, sans libération de mémoire.
On ne peut mettre à jour le composant pygments dans l’immédiat, mais on peut limiter les dégâts en abaissant la limite du nombre de descripteurs de fichiers à quelque chose de raisonnable (i.e. on va gaspiller raisonnablement des cycles CPU dans une boucle un peu inutile mais brève…). Une édition de /etc/security/limits.conf, un redémarrage du conteneur de production et on peut vérifier que cela va nettement mieux avec cette réparation de fortune.
Une dernière page d’epub ?
Le conteneur LXC portant le service epub de production a assez mal pris la surcharge du serveur, et vers 20h08, systemd-networkd sifflera la fin de la récré avec un eth0: The interface entered the failed state frequently, refusing to reconfigure it automatically (quelque chose comme « ça n’arrête pas d’échouer, débrouillez-vous sans moi »). Le service epub est resté en carafe jusqu’au 27 août vers 13h31 (merci pour l’entrée de suivi).
Voir ce commentaire sur la dépêche de l’incident précédent expliquant la séparation du service epub et du conteneur principal de production (en bref : dette technique et migration en cours).
Retour en graphiques sur la journée
Le serveur était très occupé. Au point de n’avoir pas le temps de mettre à jour les graphiques de temps en temps.
Rétrospectivement les processeurs du serveur ont travaillé dur : 140 de charge sur le graphique (mais avec des pics jusque 260 d’après la commande uptime), contre moins de 5 en temps normal (un petit facteur de 28 à 52 ô_Ô)
Et l’utilisation de la mémoire montre aussi de brutaux changements de comportement : libération intempestive de mémoire (Free, en vert), utilisation mémoire plus importante que d’habitude (Used, en jaune), là où le comportement normal est d’avoir le maximum en cache (Cached, en orange) et des processus tellement peu consommateurs en RAM que cela n’apparaît normalement pas.
Mesures préventives et correctives
Dans les actions en cours ou à prévoir :
- mettre à jour la documentation pour disposer facilement et rapidement des informations pour les connexions aux cartes d’administration ou les procédures de blocages d’IP
- faire la montée des versions des composants (yapuka, épineux sujet de la dette technique à éponger)
- vérifier l’efficacité des limitations CPU/mémoire mises sur certains conteneurs LXC et les étendre aux autres
- mettre des limites sur des processus particuliers (comme ceux de pygments)
- ajouter le déploiement des limites par utilisateur dans le code Ansible
- corriger la collecte
rrd des métriques concernant les interfaces réseau
- remonter les alertes OOM qui ne sont pas normales
- comprendre la surconsommation mémoire ? (les boucles actives expliquent la consommation processeur, mais pour la mémoire ?)
Bonus inattendu pour l’incident précédent du 26 juin 2025
De façon cocasse, ce nouvel incident et le temps passé à parcourir les différents logs ont permis de retrouver les infos de la carte d’administration distante et d’expliciter l’origine du redémarrage serveur intempestif. À quelque chose malheur est bon, si on peut dire. Ceci n’est pas une invitation pour un prochain incident.
Connexion
