Anomalie #1176
ferméredmine est a 100% de CPU depuis plusieurs heures
Description
Hypothèse : il y a une URL dans redmine qui provoque un bug qui conduit à une boucle d'allocation infinie:
# strace -p 29712 Process 29712 attached - interrupt to quit brk(0x505e9000) = 0x505e9000 brk(0x505e7000) = 0x505e7000 brk(0x50608000) = 0x50608000 brk(0x50606000) = 0x50606000 ...
et donc un process qui utilise de plus en plus de RAM et 100% d'un CPU.
ssh -t -A root@pavot.april.org vserver amphetamine enter # redmine 29712 www-data 20 0 1047m 882m 2692 R 101 3.7 242:44.56 Rails: /usr/share/redmine
C'est arrivé au moment ou google a décidé de crawl tout le site. Il parait difficile de trouver quelle requete exactement a déclenché ce comportement. Les logs ne montrent pas d'erreurs portant sur une requete ayant duré plusieurs heures:
grep '^Completed' /var/log/redmine/default/production.log | grep -v '200 OK'
et la granularité de munin ne permet pas de situer l'apparition du comportement de façon précise : il y a des centaines de requetes qui ont été faites entre 6am et 7am le 27 janvier 2013 ( voir les logs attaché au ticket )
Fichiers
Mis à jour par Loïc Dachary il y a presque 12 ans
- Catégorie mis à Task
- Statut changé de Nouveau à Confirmé
- Assigné à mis à Loïc Dachary
- Priorité changé de Normale à Immédiate
- Version cible mis à Janvier 2013
Mis à jour par Loïc Dachary il y a presque 12 ans
tail -f /var/log/redmine/default/production.log
Processing IssuesController#index (for 66.249.76.56 at 2013-01-27 10:32:20) [GET]
Parameters: {"action"=>"index", "page"=>"3", "controller"=>"issues", "per_page"=>"xmsqozgry", "sort"=>"priority,assigned_to,tracker"}
Rendering template within layouts/base
Rendering issues/index.rhtml
Completed in 378ms (View: 118, DB: 46) | 200 OK [https://agir.april.org/issues?page=3&per_page=xmsqozgry&sort=priority%2Cassigned_to%2Ctracker]
Processing TimelogController#details (for 66.249.76.56 at 2013-01-27 10:32:32) [GET]
Parameters: {"project_id"=>"admins", "action"=>"details", "page"=>"11", "controller"=>"timelog", "per_page"=>"100", "sort"=>"project,spent_on:desc,issue:desc"}
Rendering template within layouts/base
Rendering timelog/details
Completed in 583ms (View: 366, DB: 28) | 200 OK [https://agir.april.org/projects/admins/time_entries?page=11&per_page=100&sort=project%2Cspent_on%3Adesc%2Cissue%3Adesc]
Processing ProjectsController#activity (for 66.249.76.56 at 2013-01-27 10:32:33) [GET]
Parameters: {"show_documents"=>"1", "from"=>"2012-10-24", "action"=>"activity", "id"=>"aprilcamp", "controller"=>"projects"}
Rendering template within layouts/base
Rendering projects/activity
Completed in 60ms (View: 33, DB: 7) | 200 OK [https://agir.april.org/projects/aprilcamp/activity?from=2012-10-24&show_documents=1]
Mis à jour par Loïc Dachary il y a presque 12 ans
On dirait bien que c'est google qui crawl.
# host 66.249.76.56 56.76.249.66.in-addr.arpa domain name pointer crawl-66-249-76-56.googlebot.com.
Mis à jour par Loïc Dachary il y a presque 12 ans
- Sujet changé de redmine est a 100% de CPU à redmine est a 100% de CPU depuis plusieurs heures
Mis à jour par Loïc Dachary il y a presque 12 ans
apache2 stop et il reste un process ruby qui prend 100% de la CPU
root@amphetamine:/# strace -p 29712 Process 29712 attached - interrupt to quit brk(0x505e9000) = 0x505e9000 brk(0x505e7000) = 0x505e7000 brk(0x50608000) = 0x50608000 brk(0x50606000) = 0x50606000 brk(0x50627000) = 0x50627000 brk(0x50625000) = 0x50625000 brk(0x50646000) = 0x50646000 brk(0x50644000) = 0x50644000 brk(0x50665000) = 0x50665000 brk(0x50663000) = 0x50663000 brk(0x50684000) = 0x50684000 brk(0x50682000) = 0x50682000 brk(0x506a3000) = 0x506a3000 brk(0x506a1000) = 0x506a1000 brk(0x506c2000) = 0x506c2000 brk(0x506c0000) = 0x506c0000 brk(0x506e1000) = 0x506e1000 ...
Je le kill -15 et je relance apache
Mis à jour par Loïc Dachary il y a presque 12 ans
Les requetes google ne pouvaient pas générer cette consomation CPU : les logs disent qu'elle prennent au plus 500ms et les requetes google se font a plusieurs secondes d'intervalle. Donc ça ne peut pas manger 100% d'un cpu.
Mis à jour par Loïc Dachary il y a presque 12 ans
- Fichier production.log.1.gz production.log.1.gz ajouté
Mis à jour par Loïc Dachary il y a presque 12 ans
- Fichier production.log.gz production.log.gz ajouté
Mis à jour par Loïc Dachary il y a presque 12 ans
- Statut changé de Confirmé à Résolu
- % réalisé changé de 0 à 100
la remonté d'alerte se fait via munin-node qui est installé sur amphetamine et qui préviendra la prochaine fois que cela se produit