[sympa-fr] erreur lors d'un envoi : Spool::unmarshal_metadata

[Luc Veillon <adresse@cachée>]

Bonjour,

Nous rencontrons un problème bloquant encore inexpliqué sur une liste de 800000 abonnés environ. Le courrier reste sur sympa/spool/msg, avec un lock, sympa_msp s'emballe et le message ne part jamais.  Nous avons 13 serveurs sympa, chacun comprenant des listes de tailles équivalentes, avec les mêmes structures, mêmes versions, scénarios identiques aux noms autorisés  près. Les envois sur ces listes se passent sans problème, avec demande d'authkey, puis une demi heure environ de préparation et 22h d'envoi.

Vous trouverez un descriptif de l'incident. Quelqu'un a t-il déjà vu le message d'erreur ? Il semble que des fonctionnalités ont été modifiées depuis la v6.2 autour de ce mot "unmarshal". De quoi s'agit-il exactement ?

Merci pour votre aide,

1/ sympa en version 6.2.12

2/ scénario nécessitant le retour en authkey du posteur

3/ le message est reçu et déposé par sympa dans

adresse@cachée

4/ Dès que sympa_msg.pl traite le message, il créée le fichier

adresse@cachée,lock

5/ Le processus effectue des requêtes sql comme le montre strace :

write(5, "\203\3\0\0\3SELECT bounce_subscriber AS"..., 903) = 903

La commande top montre un usage 80/20 de sympa_msg vs mysql

 8447 sympa     20   0  999m 782m 3456 S 80.4  6.6   3:52.01 sympa_msg.pl
 2020 mysql     20   0 1423m 339m 6408 S 21.6  2.8 129:14.78 mysqld

puis, boucle sans fin sur 

stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2945, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2945, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2945, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2945, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2945, ...}) = 0
stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=2945, ...}) = 0

6/ A ce moment là, il est passé en 100% de CPU

 8447 sympa     20   0 1820m 1.6g 3456 R 99.6 13.5  21:05.34 sympa_msg.pl

7/ Le log indique :

 Nov 22 16:41:51 sy-ari-sympa04.ariel.in.phm.education.gouv.fr sympa_msg[5978]: err main::#281 > Sympa::Spool::next#123 > Sympa::Spool::unmarshal_metadata#382 > Sympa::List::new#607 >

8/ En mode debug 2, on a :
La première passe, avec requête mysql
Nov 22 17:00:16 sy-ari-sympa04.ariel.in.phm.education.gouv.fr sympa_msg[8447]: debug2 Sympa::List::get_next_list_member()
Nov 22 17:00:16 sy-ari-sympa04.ariel.in.phm.education.gouv.fr sympa_msg[8447]: debug2 Sympa::List::get_next_list_member(email = xxxxx@ac-nancy-
metz.fr)
Nov 22 17:00:16 sy-ari-sympa04.ariel.in.phm.education.gouv.fr sympa_msg[8447]: debug2 Sympa::List::get_list_member_no_object(liste.fnec-fp-fo.agents_men, adresse@cachée, fo.syndicat.education.gouv.fr)
Nov 22 17:00:16 sy-ari-sympa04.ariel.in.phm.education.gouv.fr sympa_msg[8447]: debug Sympa::DatabaseDriver::MySQL::get_formatted_date() Building SQL date formatting
Nov 22 17:00:16 sy-ari-sympa04.ariel.in.phm.education.gouv.fr sympa_msg[8447]: debug Sympa::DatabaseDriver::MySQL::get_formatted_date() Building SQL date formatting
Nov 22 17:00:16 sy-ari-sympa04.ariel.in.phm.education.gouv.fr sympa_msg[8447]: debug2 Sympa::List::get_list_member_no_object() Custom_attribute = ()


puis, au moment des appels à /etc/localtime :
Nov 22 17:17:26 sy-ari-sympa04.ariel.in.phm.education.gouv.fr sympa_msg[8447]: debug2 Sympa::List::get_list_member(adresse@cachée)
Nov 22 17:17:26 sy-ari-sympa04.ariel.in.phm.education.gouv.fr sympa_msg[8447]: debug2 Sympa::List::get_list_member(adresse@cachée)
Nov 22 17:17:27 sy-ari-sympa04.ariel.in.phm.education.gouv.fr sympa_msg[8447]: debug2 Sympa::List::get_list_member(adresse@cachée)
Nov 22 17:17:27 sy-ari-sympa04.ariel.in.phm.education.gouv.fr sympa_msg[8447]: debug2 Sympa::List::get_list_member(adresse@cachée)
Nov 22 17:17:27 sy-ari-sympa04.ariel.in.phm.education.gouv.fr sympa_msg[8447]: debug2 Sympa::List::get_list_member(adresse@cachée)
Nov 22 17:17:27 sy-ari-sympa04.ariel.in.phm.education.gouv.fr sympa_msg[8447]: debug2 Sympa::List::get_list_member(adresse@cachée)

Il parcourt apparemment la totalité des abonnés. Nous l'avons laissé tourner plus de deux heures sans résultat.


Essais effectués :
- même message renommé au nom d'une liste clone avec 2 abonnés :
    1/ passe en sympa/spool/msg/bad si l'auteur ne fait pas partie des sender autorisées
    2/ passe en sympa/spool/msg/auth si l'auteur fait partie des sender autorisés, puis est distribué une fois reçue l'authkey
=> le message n'est pas en cause

- suppression des tâches
1479832090.ACTION.eval_bouncers._global
1479832090.ACTION.expire_bounce._global
1479832090.ACTION.purge_one_time_ticket_table._global
1479832090.ACTION.purge_session_table._global
1479832090.ACTION.purge_tables._global
puis relance du serveur sympa : même lenteur.

-- 
Luc VEILLON
Pôle IH2M Equipe "Hub - Hébergement - Messagerie"
DSI - Rectorat d'Orléans-Tours
10 Rue Molière
45 000 Orléans
Tél: 02 38 79 45 20/ 02 38 79 45 51
Fax: 02 38 79 45 29
Mel : adresse@cachée