Soyez le bienvenu! Je n'ai pas tout lu, juste la fin et le début :-) Jo
2014-07-25 18:54 GMT+02:00 Jean-Philippe Camguilhem <jp.camguil...@gmail.com >: > 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_...@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. > > > > > > _______________________________________________ > Talk-fr mailing list > Talk-fr@openstreetmap.org > https://lists.openstreetmap.org/listinfo/talk-fr > >
_______________________________________________ Talk-fr mailing list Talk-fr@openstreetmap.org https://lists.openstreetmap.org/listinfo/talk-fr
