Anomalie #4577
Redminbot s'emballe et paralyse le SI April
Début:
02/07/2020
Echéance:
% réalisé:
0%
Temps estimé:
Difficulté:
5 Difficile
Description
Ce mercredi soir, constat que :
- des services web du SI April ne sont plus joignables (pad…) ;
- des sauvegardes sont en cours mais leur suspension ne résout rien ;
- calamus a une grosse charge ( > 10) ;
- dans virtmanager le graphe cpu de la vm bot montre une activité certaine (pas les autres vm) ;
- sur la vm bots, le processus redminbot est à 100 % ;
- un systemctl restart redminbot débloque instantanément tout.
État du processus redminbot avant le restart :
top - 21:25:35 up 20 days, 16:20, 1 user, load average: 1,16, 1,16, 1,09
Tasks: 81 total, 2 running, 79 sleeping, 0 stopped, 0 zombie
%Cpu(s): 85,4 us, 14,6 sy, 0,0 ni, 0,0 id, 0,0 wa, 0,0 hi, 0,0 si, 0,0 st
MiB Mem : 483,2 total, 15,8 free, 141,0 used, 326,3 buff/cache
MiB Swap: 952,0 total, 904,7 free, 47,2 used. 324,7 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
11934 redmine+ 20 0 23300 13788 5700 R 99,9 2,8 133:26.43 redminebot.py
413 root 20 0 38628 13100 5256 S 0,3 2,6 23:44.23 python3
1 root 20 0 169724 7236 4620 S 0,0 1,5 2:17.79 systemd
2 root 20 0 0 0 0 S 0,0 0,0 0:00.17 kthreadd
3 root 0 -20 0 0 0 I 0,0 0,0 0:00.00 rcu_gp
4 root 0 -20 0 0 0 I 0,0 0,0 0:00.00 rcu_par_gp
Pas de trace particulière dans les logs…
Question :- que s'est-il passé ?
- cela est-il déjà arrivé ?
- cela arrive-t-il régulièrement ?
Demandes liées
Historique
Mis à jour par Christian P. Momon il y a presque 4 ans
Re :
top - 16:34:33 up 23 days, 11:29, 2 users, load average: 1,03, 1,06, 1,08
Tasks: 84 total, 2 running, 82 sleeping, 0 stopped, 0 zombie
%Cpu(s): 75,0 us, 25,0 sy, 0,0 ni, 0,0 id, 0,0 wa, 0,0 hi, 0,0 si, 0,0 st
MiB Mem : 483,2 total, 30,0 free, 140,3 used, 312,8 buff/cache
MiB Swap: 952,0 total, 898,0 free, 54,0 used. 325,3 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
16473 redmine+ 20 0 22900 14792 6628 R 93,3 3,0 958:20.90 redminebot.py
1 root 20 0 169764 7316 4668 S 0,0 1,5 2:35.09 systemd
2 root 20 0 0 0 0 S 0,0 0,0 0:00.19 kthreadd
Mis à jour par Christian P. Momon il y a presque 4 ans
- Statut changé de Nouveau à Attente d'information
- Assigné à mis à Christian P. Momon
Le problème semble se trouver par là :
(gdb) py-list
167 self.ircsock.send("PRIVMSG {} :Périodiquement, je vais afficher les actualités de http://agir.april.org/projects/{}.\n".format(channel,self.get_project(channel).name))
168
169 # Reads the messages from the server and adds them to the Queue and prints
170 # them to the console. This function will be run in a thread, see below.
171 def msg_handler(self): # pragma: no cover (this excludes this function from testing)
>172 new_msg = self.ircsock.recv(2048) # receive data from the server
173 new_msg = new_msg.strip('\n\r') # removing any unnecessary linebreaks
174
175 if new_msg != '' and new_msg.find("PING :") == -1:
176 print(datetime.datetime.now().isoformat() + " " + new_msg)
177 return new_msg
Ajout d'un test sur ce que retourne recv pour tenter d'avoir quelque chose dans les logs la prochaine fois :
def msg_handler(self): # pragma: no cover (this excludes this function from testing)
new_msg = self.ircsock.recv(2048) # receive data from the server
- new_msg = new_msg.strip('\n\r') # removing any unnecessary linebreaks
-
- if new_msg != '' and new_msg.find("PING :") == -1:
- print(datetime.datetime.now().isoformat() + " " + new_msg)
+ if not new_msg:
+ print "Empty recv."
+ new_msg=''
+ else:
+ new_msg = new_msg.strip('\n\r') # removing any unnecessary linebreaks
+ if new_msg != '' and new_msg.find("PING :") == -1:
+ print(datetime.datetime.now().isoformat() + " " + new_msg)
return new_msg
Mis à jour par Christian P. Momon il y a presque 4 ans
Nouveau départ en vrille ce 10/07/2020. La log ajoutée donne la ligne suivante et floode le journal :
juil. 10 21:16:00 bots redminebot.py[30734]: Empty recv. juil. 10 21:16:27 bots systemd-journald[230]: Suppressed 287214 messages from redminebot.service juil. 10 21:16:27 bots redminebot.py[30734]: Empty recv.
Modification du code quand ce cas arrive :
- print "Empty recv." - new_msg='' + print "Empty recv. It seems I’ve lost my mind. I stop to be reborn." + sys.exit(7)
Donc normalement, si ça arrive alors redminebot s'arrête tout seul et systemd le redémarre automatiquement.
Mis à jour par Christian P. Momon il y a presque 4 ans
- Statut changé de Attente d'information à Résolu
Le service systemd redminebot contient :
Restart=always RestartSec=10
Heureusement, le plantage n'arrive pas trop souvent, environ une ou deux fois par semaine.
Donc on peut dire que la solution de contournement tient la route pour l'instant.
Mis à jour par Christian P. Momon il y a presque 4 ans
- Lié à Anomalie #4592: /var vm bots plein ajouté