Project

General

Profile

Tâche #11161

Scénario #10982: Assistance aux utilisateurs (14-16)

Plantage du service Zéphir à intervalles réguliers

Added by Bruno Boiget about 6 years ago. Updated about 6 years ago.

Status:
Fermé
Priority:
Normal
Assigned To:
Target version:
Start date:
12/17/2014
Due date:
% Done:

100%

Estimated time:
4.00 h
Spent time:
Remaining (hours):
0.0

Description

des problèmes d'arrêt des services de Zéphir ont été remontés par plusieurs personnes (Karim Ayari et Thierry Bertrand).

en étudiant les logs, il est apparu que la rotation des logs du service ne se fait pas correctement (après rotation des logs, le backend se met à logger directement dans syslog, et il semble que les disfonctionnements/plantages se produisent à ce moment).

Voir si la configuration logrotate des logs de zephir et zephir_web n'est pas mauvaise (il doit manquer une relance du service rsyslog).

History

#1 Updated by Bruno Boiget about 6 years ago

  • Distribution changed from EOLE 2.5 to EOLE 2.3

informations remontées par Karim à ce sujet (et au sujet de problèmes avec zephir-client) :

petit info sur le plantage du service Zéphir qui semble sévir sur quelques serveurs si je ne me trompe pas.

comme tu le sais j'ai 2 serveurs Zéphir, ce matin j'ai trouvé l'un des 2 avec zéphir planté et comme je m'en doutais depuis le départ c'est au moment de la rotation des logs qu'il ne se relance pas.

j'ai donc jeté un oeil à l'autre zéphir :

la rotation s'était effectuée j'avais bien les fichiers zephir_backend.info.log.1 et zephir_backend.info.log
le service s'était relancé :

root     20611 22.1 30.0 2540500 1836240 ?     Sl   06:26  53:46 /usr/bin/python /usr/bin/twistd --syslog --pidfile /var/run/zephir_backend.pid --reactor epoll -no zephir_backend
nobody   20968  0.0  0.6 142924 38972 ?        S    06:26   0:07 /usr/bin/python /usr/bin/twistd --syslog --pidfile /var/run/zephir_web.pid --reactor epoll -no zephir_web

et pourtant le service écrivait encore dans le fichier zephir_backend.info.log.1 !!

je décide de relancer zephir, et la 1ère fois j'ai un échec :

root@zephir23-1:/var/log/rsyslog/local/zephir_backend# service zephir restart
 * Arret du système Zephir...                                                                                   [ OK ]
 * Demarrage du système Zephir...                                                                                    
 Le système Zephir est déja lancé                                                                                [fail]

le pid est toujours présent dans /var/run/

je relance encore une fois zéphir, cette fois-ci cela fonctionne :

root@zephir23-1:/var/log/rsyslog/local/zephir_backend# service zephir restart
 * Arret du système Zephir...                                                                                          Le système Zephir est déjà arreté                                                                               [ OK ]
 * Demarrage du système Zephir...                                                                               [ OK ]

je regarde les logs, et je m'aperçoit qu'il continue de loguer dans zephir_backend.info.log.1.

root@zephir23-1:/var/log/rsyslog/local/zephir_backend# tailf zephir_backend.info.log.1
Mar  1 10:45:15 zephir23-1 zephir_backend: [HTTPChannel,39383,109.0.146.117] connexion du serveur 1025
Mar  1 10:45:16 zephir23-1 zephir_backend: [-] Received SIGTERM, shutting down.
Mar  1 10:45:16 zephir23-1 zephir_backend: [-] (Port 7081 Closed)
Mar  1 10:45:16 zephir23-1 zephir_backend: [-] (Port 8090 Closed)
Mar  1 10:45:16 zephir23-1 zephir_backend: [-] Stopping factory <twisted.web.server.Site instance at 0x30fdea8>
Mar  1 10:45:16 zephir23-1 zephir_backend: [twisted.web.server.Site] (Port 7080 Closed)
Mar  1 10:45:16 zephir23-1 zephir_backend: [twisted.web.server.Site] Stopping factory <twisted.web.server.Site instance at 0x30fae60>
Mar  1 10:45:16 zephir23-1 zephir_backend: [-] Main loop terminated.
Mar  1 10:45:16 zephir23-1 zephir_backend: [-] Server Shut Down.
Mar  1 10:45:21 zephir23-1 zephir_backend: [HTTPChannel,1,194.199.77.31] connexion du serveur 813
Mar  1 10:45:22 zephir23-1 zephir_backend: [-] debsums : pas de dernière mesure disponible.
Mar  1 10:45:22 zephir23-1 zephir_backend: [-] RootDebsums : pas de dernière mesure disponible.
Mar  1 10:45:22 zephir23-1 zephir_backend: [-] RRDtool warning: This RRD was created on another architecture
Mar  1 10:45:22 zephir23-1 zephir_backend: last message repeated 3 times
Mar  1 10:45:22 zephir23-1 zephir_backend: [HTTPChannel,8,193.51.226.119] connexion du serveur 12

Mar  1 10:45:23 zephir23-1 zephir_backend: [HTTPChannel,9,194.199.117.101] connexion du serveur 651
Mar  1 10:45:25 zephir23-1 zephir_backend: [HTTPChannel,13,80.14.44.202] connexion du serveur 938

je décide alors de relancer rsyslog :

root@zephir23-1:/var/log/rsyslog/local/zephir_backend# service rsyslog restart
rsyslog start/running, process 6404
root@zephir23-1:/var/log/rsyslog/local/zephir_backend#

et là il log bien dans le nouveau log zephir_backend.info.log

root@zephir23-1:/var/log/rsyslog/local/zephir_backend# tailf zephir_backend.info.log
Mar  1 10:48:07 zephir23-1 zephir_backend: last message repeated 3 times
Mar  1 10:48:07 zephir23-1 zephir_backend: [HTTPChannel,160,193.51.226.125] connexion du serveur 530
Mar  1 10:48:07 zephir23-1 zephir_backend: [HTTPChannel,161,88.173.76.197] connexion du serveur 911
Mar  1 10:48:07 zephir23-1 zephir_backend: [HTTPChannel,162,194.199.77.57] connexion du serveur 909
Mar  1 10:48:08 zephir23-1 zephir_backend: [HTTPChannel,166,194.199.77.45] connexion du serveur 868
Mar  1 10:48:10 zephir23-1 zephir_backend: [HTTPChannel,170,193.51.226.81] connexion du serveur 673
Mar  1 10:48:10 zephir23-1 zephir_backend: [HTTPChannel,171,194.199.117.113] connexion du serveur 462
Mar  1 10:48:11 zephir23-1 zephir_backend: [HTTPChannel,172,194.199.117.20] connexion du serveur 296
Mar  1 10:48:12 zephir23-1 zephir_backend: [HTTPChannel,173,194.199.75.71] connexion du serveur 57
Mar  1 10:48:14 zephir23-1 zephir_backend: [HTTPChannel,176,193.51.226.101] connexion du serveur 733
Mar  1 10:48:18 zephir23-1 zephir_backend: [-] Mise en cache des configurations : 150/872 effectué
Mar  1 10:48:21 zephir23-1 zephir_backend: [HTTPChannel,199,194.57.173.197] connexion du serveur 271
^C
root@zephir23-1:/var/log/rsyslog/local/zephir_backend#

pour ce problème je pense qu'il faudrait peut-être recharger rsyslog après la rotation.

------------------

pour le problème du service zephir qui ne se relance pas, je pense qu'il y a un soucis avec la suppression du .pid par moment il ne parvient pas à le supprimer.

d'ailleurs j'ai remarqué que le numéro de process présent dans le .pid et celui renvoyé par un ps n'est pas toujours identique d'où le test dans le script d'init :

/bin/kill -SIGTERM $pid >/dev/null 2>&1 || rm -f $PIDFILE

root@zephir23-1:/var/log/rsyslog/local/zephir_backend# cat /var/run/zephir_backend.pid ; echo "" 
18082

root@zephir23-1:/var/log/rsyslog/local/zephir_backend# ps aux |grep zephir_backend
root      8982  105 23.1 2050348 1414112 pts/19 Sl  11:31   6:27 /usr/bin/python /usr/bin/twistd --syslog --pidfile /var/run/zephir_backend.pid --reactor epoll -no zephir_backend

dans le script d'init :

quand les numéros de process sont diffèrents :

 printf ' '
 + '[' -f /var/run/zephir_backend.pid ']'
++ cat /var/run/zephir_backend.pid
+ pid=25070
+ /bin/kill -SIGTERM 25070
+ rm -f /var/run/zephir_backend.pid  #ici il est supprimé à la bourrin car le numéro de process est diffèrent
+ rm -f /var/lock/zephir_backend
+ rm -f /var/spool/uucp/lock

dans ce cas de figure cela fonctionne très bien.

par contre ce qui ne marche pas à tous les coups :

 printf ' '
 + '[' -f /var/run/zephir_backend.pid ']'
++ cat /var/run/zephir_backend.pid
+ pid=10423
+ /bin/kill -SIGTERM 10423
+ rm -f /var/lock/zephir_backend
+ rm -f /var/spool/uucp/lock

je pense que lorsque les numéros de process sont identiques le kill -SIGTERM ne fait pas toujours son taf de supprimer le zephir_backend.pid

#2 Updated by Bruno Boiget about 6 years ago

  • Assigned To set to Bruno Boiget

Après étude avec Benjamin, j'ai envoyé un patch à Karim avec les modifications pour recharger rsyslog après rotation des logs.

#3 Updated by Bruno Boiget about 6 years ago

  • Status changed from Nouveau to En cours

#4 Updated by Bruno Boiget about 6 years ago

  • Description updated (diff)
  • Remaining (hours) changed from 4.0 to 2.0

#5 Updated by Karim Ayari about 6 years ago

patch déposé sur 1 de nos serveurs zéphir, je n'ai pas patché le second comme cela on pourra comparer.

#6 Updated by Bruno Boiget about 6 years ago

A priori le patch semble résoudre le problème pour Karim (un serveur autre non patché a bien planté lundi, mais pas celui ayant le patch).

Il y a toujours des plantages sur le Zéphir du medee, mais à priori liés à d'autres problèmes. (zeronimo remonte des problèmes de type 'too many open files' depuis une semaine).

#7 Updated by Fabrice Barconnière about 6 years ago

  • Status changed from En cours to Fermé
  • % Done changed from 0 to 100
  • Remaining (hours) changed from 2.0 to 0.0

Pour les autres pb, il y aura d'autres demandes.

Also available in: Atom PDF