Project

General

Profile

Anomalie #4577

Redminbot s'emballe et paralyse le SI April

Added by Christian P. Momon 10 months ago. Updated 8 months ago.

Status:
Fermé
Priority:
Élevée
Category:
-
Target version:
Start date:
07/02/2020
Due date:
% Done:

0%

Estimated time:
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 ?

Related issues

Related to Admins - Anomalie #4592: /var vm bots pleinFermé07/12/2020

Actions

History

#1

Updated by Christian P. Momon 10 months ago

  • Description updated (diff)
#2

Updated by Christian P. Momon 10 months ago

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                                                                                                                                                                           

#3

Updated by Christian P. Momon 10 months ago

  • Status changed from Nouveau to Attente d'information
  • Assignee set to 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

#4

Updated by Christian P. Momon 9 months ago

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.

#5

Updated by Christian P. Momon 9 months ago

  • Status changed from Attente d'information to 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.

#6

Updated by Christian P. Momon 9 months ago

#7

Updated by Quentin Gibeaux 8 months ago

  • Status changed from Résolu to Fermé

Also available in: Atom PDF