[OSM-talk-fr] Doublon de mail Was: Edition des relations pour les transports en commun > (ville de Nantes) (JeanMichel FRANCOIS)

Ven 25 Juil 16:54:09 UTC 2014

Bonsoir,

Le 22/07/2014 02:44, Philippe Verdy a écrit :
> C'est tout de même dommage qu'une société qui se dit experte en solutions de "déploiement agile" ne sache pas configurer correctement une solution mail nécessaire à n'importe quel site hébergé pour ses clients et au moins isoler le système défaillant après plus d'une semaine.

Alors je vais répondre de deux façons :

+ La version courte:

Un bug sur le cache DNS d'un des fournisseurs d'OSM, engendrait un timeout lors de la vérification de notre signature DKIM, qui empêchait la réception de l'ACK du message à notre smtp, et donc ce dernier à remis le message en queue et  conformément aux RFC a tenté une politique de best-effort de livraison de ce message pendant 5 jours.

+ La version longue pour les plus curieux d'entre vous,  je sais qu'il y e n a qui vont lire jusqu'au bout.

===============================
traçage du message trublion
===============================

https://lists.openstreetmap.org/pipermail/talk-fr/2014-July/069617.html

message id 2A4FE8129D

In log veritas
==================

le mail traverse deux smtp sur notre infra: en premier lieux notre MX

root__at__proxy-smtp:/home/sysadmin/jpcw# grep --color 2A4FE8129D mail.log.1
Jul 16 08:19:59 proxy-smtp postfix/smtpd[5373]: 2A4FE8129D: client=mail.makina-corpus.com[212.83.188.243]
Jul 16 08:19:59 proxy-smtp postfix/cleanup[5558]: 2A4FE8129D: message-id=<53C6198E.4080001__at__makina-corpus.com>
Jul 16 08:19:59 proxy-smtp opendkim[5363]: 2A4FE8129D: DKIM-Signature field added (s=mail, d=makina-corpus.com)
Jul 16 08:19:59 proxy-smtp postfix/qmgr[21119]: 2A4FE8129D: from=<jeanmichel.francois__at__makina-corpus.com>, size=24700, nrcpt=1 (queue active)
Jul 16 08:20:00 proxy-smtp amavis[4568]: (04568-12) Passed CLEAN {RelayedOutbound}, MYNETS LOCAL [212.83.188.243]:35209 [128.79.238.165] <jeanmichel.francois__at__makina-corpus.com> -> <talk-fr__at__openstreetmap.org>, Queue-ID: 2A4FE8129D, Message-ID: <53C6198E.4080001__at__makina-corpus.com>, mail_id: vidMKJEXV1Wn, Hits: -1.999, size: 25123, queued_as: 104228131D, dkim_sd=mail:makina-corpus.com, 880 ms
Jul 16 08:20:00 proxy-smtp postfix/smtp[5559]: 2A4FE8129D: to=<talk-fr__at__openstreetmap.org>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.98, delays=0.09/0.01/0.01/0.88, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 104228131D)
Jul 16 08:20:00 proxy-smtp postfix/qmgr[21119]: 2A4FE8129D: removed

Le mail envoyé par Jean-Michel depuis son client de messagerie est accepté par notre MX, puis entête DKIM, puis le mail est scanné et finalement transmis
à notre relay (qui est donc notre smtp sortant) qui le mets en queue avec le queuid 104228131D

historique de ce mail dans nos logs
-------------------------------------------------

root__at__proxy-smtp:/home/sysadmin/jpcw# grep --color 104228131D mail.log.1 | grep -v "(queue active)" | wc -l
79
root__at__proxy-smtp:/home/sysadmin/jpcw# grep --color 104228131D mail.log | grep -v "(queue active)" | wc -l
23

Aggrégeons dans un fichier texte pour y voir plus clair
+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
grep --color 104228131D mail.log.1 | grep -v "(queue active)" >> report_104228131D.txt
grep --color 104228131D mail.log | grep -v "(queue active)" >> report_104228131D.txt

reprise du mail transmis par le MX, correspondant à la vision log du smtp sortant de l'échange au dessus

Jul 16 08:20:00 proxy-smtp postfix/smtpd[5562]: 104228131D: client=localhost.localdomain[127.0.0.1]
Jul 16 08:20:00 proxy-smtp postfix/cleanup[5558]: 104228131D: message-id=<53C6198E.4080001__at__makina-corpus.com>
Jul 16 08:20:00 proxy-smtp opendkim[5363]: 104228131D: DKIM-Signature field added (s=mail, d=makina-corpus.com)
Jul 16 08:20:00 proxy-smtp amavis[4568]: (04568-12) Passed CLEAN {RelayedOutbound}, MYNETS LOCAL [212.83.188.243]:35209 [128.79.238.165] <jeanmichel.francois__at__makina-corpus.com> -> <talk-fr__at__openstreetmap.org>, Queue-ID: 2A4FE8129D, Message-ID: <53C6198E.4080001__at__makina-corpus.com>, mail_id: vidMKJEXV1Wn, Hits: -1.999, size: 25123, queued_as: 104228131D, dkim_sd=mail:makina-corpus.com, 880 ms
Jul 16 08:20:00 proxy-smtp postfix/smtp[5559]: 2A4FE8129D: to=<talk-fr__at__openstreetmap.org>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.98, delays=0.09/0.01/0.01/0.88, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as 104228131D)

A partir d'ici smtp sortant va essayer maintenant de contacter le destinataire à savoir a.mx.openstreetmap.org, pour cela il met le message en queue sous le numéro 104228131D

Les différents décalages:

Jul 16 08:30:00 proxy-smtp postfix/smtp[5563]: 104228131D: to=<talk-fr__at__openstreetmap.org>, relay=a.mx.openstreetmap.org[89.16.179.150]:25, delay=600, delays=0.08/0.01/0.12/600, dsn=4.4.2, status=deferred (conversation with a.mx.openstreetmap.org[89.16.179.150] timed out while sending end of data -- message may be sent more than once)

décalage de ré-émission de 20 minutes

Jul 16 08:50:04 proxy-smtp postfix/smtp[7272]: 104228131D: to=<talk-fr__at__openstreetmap.org>, relay=a.mx.openstreetmap.org[89.16.179.150]:25, delay=1804, delays=1202/0.02/0.21/602, dsn=4.4.2, status=deferred (conversation with a.mx.openstreetmap.org[89.16.179.150] timed out while sending end of data -- message may be sent more than once)

puis 45 minutes

Jul 16 09:35:03 proxy-smtp postfix/smtp[10686]: 104228131D: to=<talk-fr__at__openstreetmap.org>, relay=a.mx.openstreetmap.org[89.16.179.150]:25, delay=4503, delays=3902/0.02/0.37/600, dsn=4.4.2, status=deferred (conversation with a.mx.openstreetmap.org[89.16.179.150] timed out while sending end of data -- message may be sent more than once)

Puis 1h20 minutes

Jul 16 10:55:02 proxy-smtp postfix/smtp[16367]: 104228131D: to=<talk-fr__at__openstreetmap.org>, relay=a.mx.openstreetmap.org[89.16.179.150]:25, delay=9303, delays=8702/0.02/0.08/600, dsn=4.4.2, status=deferred (conversation with a.mx.openstreetmap.org[89.16.179.150] timed out while sending end of data -- message may be sent more than once)

puis à ce même rythme de 1h20 durant les 5 jours recommandés dans les RFC
....
Jul 21 07:35:05 proxy-smtp postfix/smtp[30835]: 104228131D: to=<talk-fr__at__openstreetmap.org>, relay=a.mx.openstreetmap.org[212.110.172.32]:25, delay=429306, delays=428705/0.03/0.69/600, dsn=4.4.2, status=deferred (conversation with a.mx.openstreetmap.org[212.110.172.32] timed out while sending end of data -- message may be sent more than once)
Jul 21 08:55:04 proxy-smtp postfix/smtp[4562]: 104228131D: to=<talk-fr__at__openstreetmap.org>, relay=a.mx.openstreetmap.org[212.110.172.32]:25, delay=434105, delays=433504/0.01/0.4/600, dsn=4.4.2, status=deferred (conversation with a.mx.openstreetmap.org[212.110.172.32] timed out while sending end of data -- message may be sent more than once)
Jul 21 08:55:04 proxy-smtp postfix/qmgr[21119]: 104228131D: from=<jeanmichel.francois__at__makina-corpus.com>, status=expired, returned to sender

Au bout des 5 jours d'échecs, il retourne le mail à l'expéditeur.

Jul 21 08:55:04 proxy-smtp postfix/bounce[5292]: 104228131D: sender non-delivery notification: CA77581131
Jul 21 08:55:04 proxy-smtp postfix/qmgr[21119]: 104228131D: removed

En clair notre smtp n'a fait que son boulot de ré-émission du mail car  a.mx.openstreetmap.org "timeoutait" avant de renvoyer l'acknowledge du transfert complet.
Postfix considère ça comme un échec et remet le mail en queue en espaçant progressivement les tentatives de ré-émission.

In TCPDump veritas
===================

Maintenant que l'on sait qu'il y a un souci de l'autre côté il faut essayer de comprendre ce qui se passe, c'est pourquoi ce lundi midi un de mes collègues est venu demander un admin-sys sir le chan osm 
pour convenir d'un créneau pour tracer la connexion de part et d'autre.

Je vous paste ici la conversation entre kiorky (Makina), T(omH, Firefishy) OSM sur irc

Le début de la conversation n'est pas le plus intéressant, ça cause on se met d'accord pour s'envoyer un mail et on trace de part et d'autre la connexion
etc (plus que constat que notre ns2 ne répondait plus suite erreur salt du matin, mais indépendante du bug recensé, bref, que des choses hors diagnostic)

 lun. juil. 21 13:43:25 2014<kiorky> but at least all our ns will normally reply to the txt record.
 lun. juil. 21 13:48:24 2014<TomH> ok, so first problem is that UDP response is getting truncated so it falls back to TCP (doesn't happen on my bytemark VM)
 lun. juil. 21 13:48:53 2014<TomH> second problem is that tcp to that first server fails
 lun. juil. 21 13:48:58 2014<TomH> from my VM as well
 lun. juil. 21 13:50:21 2014<TomH> ah Fedora is enabling EDNS and ubuntu isn't
 lun. juil. 21 13:50:28 2014<TomH> that's why UDP works for my machine
 lun. juil. 21 13:50:41 2014>>>> Ab_fab (~Ab_fab at def92-12-88-177-250-146.fbx.proxad.net) has quit [Ping timeout: 480 seconds]

 Un ticket va être ouvert sur le fournisseur (bytemark) car le cache ne sait pas passer d'udp en tcp sur les requêtes dns verbeuses (ce qui est le cas de la véirf DKIM)

 lun. juil. 21 13:51:50 2014<Firefishy> TomH: I'll fire off an email to bytemark about their server rejecting TCP queries.
 lun. juil. 21 13:52:04 2014<TomH> oh was just about to do it
 lun. juil. 21 13:52:28 2014<Firefishy> TomH: ok, I'll leave it to you.

 lun. juil. 21 13:57:50 2014<TomH> it's weird - it lets you connect, but the query itself is never even ACKed
 lun. juil. 21 13:58:03 2014<TomH> the client just sits there retransmitting the data

Les admins-sys d'OSM constatent la même chose que de notre côté, le smtp d'osm ne renvoie jamais l'Aknowledge sur la bonne réception du mail, car il a timeouté sur la vérif DKIM à cause d'un bug du cache du prestataire.
la requête étant verbeuse (vérif DKIM), lors du passage d'UDP en TCP -> time out == boom.

Du coup notre smtp croit que le message n'a pas été reçu en entier, (car il n'a pas reçu l'ACK) de celui d'OSM, du coup il remet en queue, et ce pendant 5 jours comme expliqué au dessus.
c'est le fonctionnement normal du mail.

Petit topo ultra-simplifié de la conversation des 2 smtp
==========================================================

smtp-makian elho
smtp-osm elho
smtp-makina j'ai un mail pour toi
smtp-osm ok l'adresse est valide commence à envoyer la data, pendant ce temps je vérifie ta signature DKIM
smtp-makina -> transfer data
smtp-osm (timeout avec le cache DNS du fournisseur bytemark, ne peut pas vérifier signature)
smtp-makina en attente ACK du transfert de la data et de la prise en charge du message par le smtp d'osm
.... time out
smtp-makina remet en queue pour plus tard pendant 5 jours

Ce qui est surprenant et là où il reste potentiellement un souci, c'est que le smtp d'osm transmettait à chaque fois le messagge à la socket du mailman.
C'est pour cela que vous les avez reçu pour certains environ 90 fois).

Dans un monde idéal ce transfert ne devrait avoir lieu qu'après l'ACK de la prise en charge au smtp expéditeur, 
là il a lieu avant, enfin ça je ne sais plus besoin de vous l'expliquer, vous l'avez vécu /o\ :D

Comme vous le voyez l'introduction d'une sécurité supplémentaire ici le DKIM engendre des effets de bords là où on ne les attends pas forcément.
La vie d'admin-sys quoi.

Conclusion
==============

Nous sommes humains, nous aurions pu nous tromper,et nous l'aurions reconnu volontiers !

Vous comprendrez qu'ici pour nous il n'y a pas erreur de notre part.

Alors oui nous n'avons regardé que le lundi fin de matinée, un problème remonté par Jean-Michel le jeudi soir ou vendredi, pour nous rien ne laissait présager un dysfonctionment, car en plus comme
quelqu'un l'a constaté dans le fil, ce problème n'était présent que sur cette liste. Pour nous il n'y avait aucune urgence, aucun dysfonctionnment constaté sur notre mesagerie, et mois d'été oblige
on est pas en sur-effectif à l'admin-sys, sans compter la migration de notre infra sur Salt.

Donc oui on aurait pu plonger dans les logs plus tôt pour ce mail, tout autant que des gens d'ici auraient pu demander aux admin-sys (très compétents au demeurant) d'OSM pour le tracer aussi de leur côté.

Nous sommes vraiment désolés de la gène occasionnée, mais nous n'y sommes strictement pour rien.

Notre SMTP a fait son boulot, normalement et conformément aux standards, certains vont peut-être émettre des souhaits sur les délais de ré-émission, mais ça ne change rien au bug constaté.
Si le temps du delayed s'était allongé de façon plus conséquente vous n'auriez pu recevoir que 25 mails au lieu de 90 mais vous en auriez reçu 25 quand même.

Nous comprenons l'énervement de certains, nous comprenons aussi que les analyses et autres diagnostics plus ou moins "douteux"(très difficiles sans les logs ou sans tcpdumper la connexion),
ou autres solutions radicales proposées étaient proportionnelles à l'agacement engendré, et que de surcroît tout pouvait porter à croire que ça venait de chez nous.

Pourquoi diable cette ML qui sert des messages tous les jours se mettrait à bugguer pour un seul expéditeur, qui plus est récemment inscrit sur la liste. 
Donc non nous n'en voulons pas trop aux gens qui nous ont jeté des cailloux, 
enfin rien qui ne puisse se régler autour d'une bière quoi :D (on a quand même des principes !)

Last but not least
==============

Alors pourquoi je ne réponds ici qu'un vendredi ?

Non ce n'est pas permis parce que c'est vendredi,

c'est juste que parce qu'aujourd'hui c'est sysadmin-day et que je m'octroie le droit de partager avec vous ce qui est vécu par mes(vos) collègues ici ou ailleurs.

Donc n'oubliez pas qu'ils sont humains, et qu'il est facile de les accuser à tords chaque fois qu'il y a un problème, les admin-sys sont des hommes de l'ombre.
On ne parle d'eux, on ne pense à eux que quand ça ne fonctionne pas !

Happy sysadmin day à tous ceux qui le méritent, et je sais qu'il y en a sur cette liste.

Cordialement,

Jean-Philippe

admin-sys junior intermittent chez Makina-Corpus

P.S nous retenterons l'envoi d'un mail de Jean-Michel après son retour de congés, on surveillera en direct,
et nous brûlerons la queue si le bug n'est toujours pas résolu chez bytemark.

Je me suis isncrit avec un de mes mails perso, car je ne désespère pas de contribuer à OSM, ni pourquoi pas de poser un jour une question.

Je découvre et suis avec un certain intérêt les questions dont je ne supposais même pas l'existence depuis plusieurs jours.

Ce mail sert donc aussi de présentation.

-------------- section suivante --------------
Une pièce jointe HTML a été nettoyée...
URL: <http://lists.openstreetmap.org/pipermail/talk-fr/attachments/20140725/f6668f62/attachment.htm>