Tâche #11161
Scénario #10982: Assistance aux utilisateurs (14-16)
Plantage du service Zéphir à intervalles réguliers
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 over 8 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 over 8 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 over 8 years ago
- Status changed from Nouveau to En cours
#4 Updated by Bruno Boiget over 8 years ago
- Description updated (diff)
- Remaining (hours) changed from 4.0 to 2.0
#5 Updated by Karim Ayari over 8 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 over 8 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 over 8 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.