Depuis le début de la semaine, j'étais confronté à un problème que je n'avais jamais eu jusque là (ça fait 4 ans 1/2 que je m'auto-héberge) : plusieurs fois dans la journée (aléatoirement), mon serveur ne répondait plus du tout, la seule chose que je voyais c'était que la LED correspondante aux écritures sur le disque dur était en permanence allumée. La seule solution à ce problème était de couper l'alimentation du serveur et de le relancer. Cela corrigeait le problème pendant quelques heures (parfois moins) puis ça recommençait. Voici les différentes étapes qui m'ont permis de comprendre ce qui se passait et comment j'ai corrigé ce problème.
Le premier symptôme n'a pas été difficile à voir : le voyant du DD de mon serveur restait en permanence allumé. J'ai trouvé ça étrange en plein milieu de la journée, du coup, j'ai essayé de me connecter sur un service web de mon serveur : impossible. Ensuite, j'ai essayé de me connecter en SSH : plus de 5 minutes à attendre un prompt qui ne venait pas. On voyait clairement que le serveur en avait par dessus la RAM de toutes ces écritures et ne pouvait traiter de nouvelles requêtes. Seule solution : reboot hard (bouton reset de mon serveur).
Analyse des logs
Premier réflexe pour essayer de comprendre ce qui s'est passé : l'analyse des logs. J'ai trié les logs par date de dernière modification et les ai tous consultés (ceux du /var/log) : rien à signaler. J'ai ensuite regardé du côté de mes logs apache. La seule chose que j'ai trouvé c'était cette ligne dans le error.log d'apache :
[Sun Jul 05 19:21:12 2015] [error] server reached MaxClients setting, consider raising the MaxClients setting
Ça devait être la conséquence du ralentissement de la machine. Quand mon serveur était à genoux, les requêtes continuaient à arriver, il ne pouvait pas les traiter rapidement ; de ce fait, elles s'empilaient et le serveur crashait. La première chose que j'ai faite a été d'augmenter cette valeur et d'attendre. Comme prévu, le problème est revenu, peu importait la valeur que je mettais. Rien à voir de plus de ce côté-là donc.
J'ai ensuite "analysé" mes logs apache grâce à goaccess (que je vous recommande !). Pas de grosse attaque là non plus. Par exemple, la capture ci-dessous indique le nombre de hits par IP pour un fichier de log d'access passé en paramètre (j'ai un fichier différent par vhost). J'ai vérifié les plus gros consommateurs, c'était des requêtes légitimes :
J'ai ensuite regardé mes graphes de supervision Munin, rien à signaler côté RAM, CPU, IO, etc. On voyait bien une coupure mais rien avant cette coupure. C'était, pour faire simple, "tout nickel" et "tout cassé" d'un check à l'autre...
Désactivation des services consommateurs
Pour essayer de délimiter les risques, j'ai désactivé les services qui sont les plus consommateurs sur mon serveur et non-indispensables. J'ai donc désactivé Subsonic, Transmission et Munin. Le serveur continuait à planter, j'en ai donc déduit que cela devait venir de MySQL ou/et apache.
Génération d'un fichier d'analyse
Sachant que le problème reviendrait assez rapidement, j'ai mis en place un script qui m'a permis de stocker certains indicateurs (les requêtes HTTP, les processus en cours, la taille des disques, l'utilisation du swap, etc.). Je passais ce script toutes les 4 minutes et stockais le résultat dans un fichier. Voici un rendu d'exemple (que j'ai épuré) :
On voit bien ici qu'à 21h24, j'avais 11 processus apache et qu'à 21h28, j'étais passé à 212 mais que mon script n'a pas réussi à calculer d'autres infos (le disque était déjà trop occupé). Les infos intéressantes ici sont que l'incident s'est produit très rapidement entre 21h24 (où tout allait bien) et 21h28 où le serveur ne répondait plus à rien.
On voit également que mysql commence à swapper. J'ai donc creusé de ce côté.
La piste MySQL
Je n'avais auparavant activé aucun log sur mon serveur MySQL, j'ai donc dû les activer vers 15h30 (dernier crash avant celui-ci) pour analyser le futur problème. Pour info, voici les lignes ajoutées dans mon fichier my.cnf :
log_error = /var/log/mysql/mysql.log
log_warnings = 2
slow_query_log = /var/log/mysql/mysql-slow.log
long_query_time = 4
Les requêtes de plus de 4 secondes sont désormais logguées. Après le crash de 21h24, j'ai trouvé des entrées intéressantes dans mon fichier mysql-slow.log :
Ces requêtes (toutes sur le même vhost) sont apparues à 21h26 (entre 24 et 28, comme vu ci-dessus). Je décide donc d'aller voir dans les logs d'accès de ce vhost (les logs d'erreur ne montrant absolument rien). Et là, voici ce que je découvre :
J'ai noté toutes les heures de plantage de mon serveur, systématiquement, cela correspond avec ce type de requête de Googlebot vers la page xmlrpc.php de mon vhost (qui est un site Wordpress). Je n'ai pas réussi à détecter cela automatiquement car les requêtes ne sont pas très nombreuses et les IP des Googlebots ne sont jamais les mêmes.
Conclusion
Du coup, un tour rapide sur un moteur de recherche en tapant les mots-clé "wordpress xmlrpc dos" et j'ai eu confirmation de ma découverte : c'est un problème bien connu d'attaque par déni de service sur les CMS Wordpress même pour les plus à jour (le mien était en dernière version du core et des plugins installés).
Pour corriger cela, j'ai installé le plugin Wordress Disable XML-RPC Pingback. Depuis, plus aucun problème : je ne vois même plus aucune entrée de ce type dans les logs. Je ne pense pas qu'il s'agisse d'une coïncidence mais que c'est ce plugin qui empêche les requêtes des bots (j'avoue ne pas avoir trop creuser cette partie là)...
Voilà pour ce petit compte rendu, il vous sera peut-être utile si un jour vous êtes confronté à ce problème :) Si vous avez d'autres astuces ou des choses auxquelles je n'ai pas pensé, n'hésitez pas ! À bientôt
Jeu de briques
Snake
Pacman
Bubble