Anomalie #14152
Script de notification en erreur (relais SMTP)
Description
Impossible d'envoyer les notifications :
lors du lancement du script des notifications, les mails ne sont pas délivrés. on obtient les logs:
[2020-06-15 15:02:32] INFO 0 'Load xml config file:/var/www/html/MaarchCourrier/custom/cs_courrier/modules/notifications/batch/config/config.xml' [2020-06-15 15:02:32] INFO 0 'Load xml config file:/var/www/html/MaarchCourrier/custom/cs_courrier/modules/notifications/batch/config/config.xml' [2020-06-15 15:02:32] INFO 0 'STATE:LOAD_EMAILS' [2020-06-15 15:02:32] INFO 0 '11 notification(s) to send.' [2020-06-15 15:02:32] INFO 0 'STATE:SEND_AN_EMAIL' [2020-06-15 15:02:32] INFO 0 'sending notification 1/11 (TO => robin.saldinger@maarch.org, SUBJECT => Avis : Avis à émettre ) ...' [2020-06-15 15:02:32] ERROR 0 'SENDING EMAIL ERROR ! (AUTH command failed: 5.5.1 Error: authentication not enabled)' [2020-06-15 15:02:32] INFO 0 'STATE:SEND_AN_EMAIL' [2020-06-15 15:02:32] INFO 0 'sending notification 2/11 (TO => fxlyonnetdumoutier@vincennes.fr, SUBJECT => Courriers à traiter ) ...' [2020-06-15 15:02:32] ERROR 0 'SENDING EMAIL ERROR ! (AUTH command failed: 5.5.1 Error: authentication not enabled)' [2020-06-15 15:02:32] INFO 0 'STATE:SEND_AN_EMAIL' [2020-06-15 15:02:32] INFO 0 'sending notification 3/11 (TO => jdegouy@vincennes.fr, SUBJECT => Courriers à viser ) ...' [2020-06-15 15:02:32] ERROR 0 'SENDING EMAIL ERROR ! (AUTH command failed: 5.5.1 Error: authentication not enabled)' [2020-06-15 15:02:32] INFO 0 'STATE:SEND_AN_EMAIL' [2020-06-15 15:02:32] INFO 0 'sending notification 4/11 (TO => stang@vincennes.fr, SUBJECT => Courriers à traiter ) ...' [2020-06-15 15:02:32] ERROR 0 'SENDING EMAIL ERROR ! (AUTH command failed: 5.5.1 Error: authentication not enabled)' [2020-06-15 15:02:32] INFO 0 'STATE:SEND_AN_EMAIL' [2020-06-15 15:02:32] INFO 0 'sending notification 5/11 (TO => jdegouy@vincennes.fr, SUBJECT => Courriers à viser ) ...' [2020-06-15 15:02:32] ERROR 0 'SENDING EMAIL ERROR ! (AUTH command failed: 5.5.1 Error: authentication not enabled)' [2020-06-15 15:02:32] INFO 0 'STATE:SEND_AN_EMAIL' [2020-06-15 15:02:32] INFO 0 'sending notification 6/11 (TO => fraymond@vincennes.fr, SUBJECT => Courriers à traiter ) ...' [2020-06-15 15:02:32] ERROR 0 'SENDING EMAIL ERROR ! (AUTH command failed: 5.5.1 Error: authentication not enabled)' [2020-06-15 15:02:32] INFO 0 'STATE:SEND_AN_EMAIL' [2020-06-15 15:02:32] INFO 0 'sending notification 7/11 (TO => rmubiayi@vincennes.fr, SUBJECT => Courriers à traiter ) ...' [2020-06-15 15:02:32] ERROR 0 'SENDING EMAIL ERROR ! (AUTH command failed: 5.5.1 Error: authentication not enabled)' [2020-06-15 15:02:32] INFO 0 'STATE:SEND_AN_EMAIL' [2020-06-15 15:02:32] INFO 0 'sending notification 8/11 (TO => fsmaali@vincennes.fr, SUBJECT => Courriers à viser ) ...' [2020-06-15 15:02:32] ERROR 0 'SENDING EMAIL ERROR ! (AUTH command failed: 5.5.1 Error: authentication not enabled)' [2020-06-15 15:02:32] INFO 0 'STATE:SEND_AN_EMAIL' [2020-06-15 15:02:32] INFO 0 'sending notification 9/11 (TO => fguesdon@vincennes.fr, SUBJECT => Courriers à traiter ) ...' [2020-06-15 15:02:32] ERROR 0 'SENDING EMAIL ERROR ! (AUTH command failed: 5.5.1 Error: authentication not enabled)' [2020-06-15 15:02:32] INFO 0 'STATE:SEND_AN_EMAIL' [2020-06-15 15:02:32] INFO 0 'sending notification 10/11 (TO => fraymond@vincennes.fr, SUBJECT => Courriers à traiter ) ...' [2020-06-15 15:02:32] ERROR 0 'SENDING EMAIL ERROR ! (AUTH command failed: 5.5.1 Error: authentication not enabled)' [2020-06-15 15:02:32] INFO 0 'STATE:SEND_AN_EMAIL' [2020-06-15 15:02:32] INFO 0 'sending notification 11/11 (TO => robin.saldinger@maarch.org, SUBJECT => Avis : Avis à émettre ) ...' [2020-06-15 15:02:32] ERROR 0 'SENDING EMAIL ERROR ! (AUTH command failed: 5.5.1 Error: authentication not enabled)' [2020-06-15 15:02:32] INFO 0 'STATE:SEND_AN_EMAIL' [2020-06-15 15:02:32] INFO 0 '0 notification(s) sent' [2020-06-15 15:02:32] INFO 0 'End of process'
log du serveur smtp:
Jun 15 14:57:37 sp62 postfix/submission/smtpd[30766]: connect from unknown[192.168.201.34] Jun 15 14:57:37 sp62 postfix/submission/smtpd[30766]: lost connection after AUTH from unknown[192.168.201.34] Jun 15 14:57:37 sp62 postfix/submission/smtpd[30766]: disconnect from unknown[192.168.201.34] ehlo=1 auth=0/1 commands=1/2 Jun 15 14:57:37 sp62 postfix/submission/smtpd[30766]: connect from unknown[192.168.201.34] Jun 15 14:57:37 sp62 postfix/submission/smtpd[30766]: lost connection after AUTH from unknown[192.168.201.34] Jun 15 14:57:37 sp62 postfix/submission/smtpd[30766]: disconnect from unknown[192.168.201.34] ehlo=1 auth=0/1 commands=1/2 Jun 15 14:57:37 sp62 postfix/submission/smtpd[30766]: connect from unknown[192.168.201.34] Jun 15 14:57:37 sp62 postfix/submission/smtpd[30766]: lost connection after AUTH from unknown[192.168.201.34] Jun 15 14:57:37 sp62 postfix/submission/smtpd[30766]: disconnect from unknown[192.168.201.34] ehlo=1 auth=0/1 commands=1/2 Jun 15 14:57:37 sp62 postfix/submission/smtpd[30766]: connect from unknown[192.168.201.34] Jun 15 14:57:37 sp62 postfix/submission/smtpd[30766]: lost connection after AUTH from unknown[192.168.201.34] Jun 15 14:57:37 sp62 postfix/submission/smtpd[30766]: disconnect from unknown[192.168.201.34] ehlo=1 auth=0/1 commands=1/2 Jun 15 14:57:37 sp62 postfix/submission/smtpd[30766]: connect from unknown[192.168.201.34] Jun 15 14:57:37 sp62 postfix/submission/smtpd[30766]: lost connection after AUTH from unknown[192.168.201.34] Jun 15 14:57:37 sp62 postfix/submission/smtpd[30766]: disconnect from unknown[192.168.201.34] ehlo=1 auth=0/1 commands=1/2 Jun 15 15:01:26 sp62 postfix/postscreen[21031]: CONNECT from [192.168.201.34]:37142 to [172.27.0.8]:25 Jun 15 15:01:32 sp62 postfix/postscreen[21031]: PASS NEW [192.168.201.34]:37142 Jun 15 15:01:32 sp62 postfix/smtpd[17330]: connect from unknown[192.168.201.34] Jun 15 15:01:32 sp62 postfix/smtpd[17330]: Anonymous TLS connection established from unknown[192.168.201.34]: TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits) Jun 15 15:01:32 sp62 postfix/smtpd[17330]: NOQUEUE: filter: RCPT from unknown[192.168.201.34]: <ne-pas-repondre@vincennes.fr>: Sender address triggers FILTER smtp-amavis:[127.0.0.1]:10026; from=<ne-pas-repondre@vincennes.fr> to=<henri.queneau@maarch.org> proto=ESMTP helo=<courrier.vincennes.fr> Jun 15 15:01:32 sp62 postfix/smtpd[17330]: BA0A8760365: client=unknown[192.168.201.34], sasl_method=LOGIN, sasl_username=ne-pas-repondre@vincennes.fr Jun 15 15:01:32 sp62 postfix/smtpd[17330]: disconnect from unknown[192.168.201.34] ehlo=2 starttls=1 auth=1 mail=1 rcpt=1 data=1 quit=1 commands=8 Jun 15 15:01:32 sp62 amavis[31969]: (31969-09) Checking: P8vU6Y-eG_V9 ORIGINATING/MYNETS [192.168.201.34] <ne-pas-repondre@vincennes.fr> -> <henri.queneau@maarch.org> Jun 15 15:01:32 sp62 amavis[31969]: (31969-09) Passed CLEAN {RelayedOutbound}, ORIGINATING/MYNETS LOCAL [192.168.201.34]:37142 <ne-pas-repondre@vincennes.fr> -> <henri.queneau@maarch.org>, Queue-ID: BA0A8760365, Message-ID: <u9pgmB5HbCX2gGBws4FEOYfP0wqYjFvnc4dvESyWCnw@courrier.vincennes.fr>, mail_id: P8vU6Y-eG_V9, Hits: -, size: 649, queued_as: D8CFD760366, 118 ms Jun 15 15:02:32 sp62 postfix/postscreen[21031]: CONNECT from [192.168.201.34]:37166 to [172.27.0.8]:25 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: PASS OLD [192.168.201.34]:37166 Jun 15 15:02:32 sp62 postfix/smtpd[17335]: connect from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: lost connection after AUTH from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: disconnect from unknown[192.168.201.34] ehlo=1 auth=0/1 commands=1/2 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: CONNECT from [192.168.201.34]:37168 to [172.27.0.8]:25 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: PASS OLD [192.168.201.34]:37168 Jun 15 15:02:32 sp62 postfix/smtpd[17335]: connect from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: lost connection after AUTH from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: disconnect from unknown[192.168.201.34] ehlo=1 auth=0/1 commands=1/2 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: CONNECT from [192.168.201.34]:37170 to [172.27.0.8]:25 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: PASS OLD [192.168.201.34]:37170 Jun 15 15:02:32 sp62 postfix/smtpd[17335]: connect from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: lost connection after AUTH from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: disconnect from unknown[192.168.201.34] ehlo=1 auth=0/1 commands=1/2 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: CONNECT from [192.168.201.34]:37172 to [172.27.0.8]:25 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: PASS OLD [192.168.201.34]:37172 Jun 15 15:02:32 sp62 postfix/smtpd[17335]: connect from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: lost connection after AUTH from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: disconnect from unknown[192.168.201.34] ehlo=1 auth=0/1 commands=1/2 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: CONNECT from [192.168.201.34]:37174 to [172.27.0.8]:25 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: PASS OLD [192.168.201.34]:37174 Jun 15 15:02:32 sp62 postfix/smtpd[17335]: connect from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: lost connection after AUTH from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: disconnect from unknown[192.168.201.34] ehlo=1 auth=0/1 commands=1/2 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: CONNECT from [192.168.201.34]:37176 to [172.27.0.8]:25 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: PASS OLD [192.168.201.34]:37176 Jun 15 15:02:32 sp62 postfix/smtpd[17335]: connect from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: lost connection after AUTH from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: disconnect from unknown[192.168.201.34] ehlo=1 auth=0/1 commands=1/2 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: CONNECT from [192.168.201.34]:37178 to [172.27.0.8]:25 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: PASS OLD [192.168.201.34]:37178 Jun 15 15:02:32 sp62 postfix/smtpd[17335]: connect from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: lost connection after AUTH from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: disconnect from unknown[192.168.201.34] ehlo=1 auth=0/1 commands=1/2 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: CONNECT from [192.168.201.34]:37180 to [172.27.0.8]:25 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: PASS OLD [192.168.201.34]:37180 Jun 15 15:02:32 sp62 postfix/smtpd[17335]: connect from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: lost connection after AUTH from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: disconnect from unknown[192.168.201.34] ehlo=1 auth=0/1 commands=1/2 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: CONNECT from [192.168.201.34]:37182 to [172.27.0.8]:25 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: PASS OLD [192.168.201.34]:37182 Jun 15 15:02:32 sp62 postfix/smtpd[17335]: connect from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: lost connection after AUTH from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: disconnect from unknown[192.168.201.34] ehlo=1 auth=0/1 commands=1/2 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: CONNECT from [192.168.201.34]:37184 to [172.27.0.8]:25 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: PASS OLD [192.168.201.34]:37184 Jun 15 15:02:32 sp62 postfix/smtpd[17335]: connect from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: lost connection after AUTH from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: disconnect from unknown[192.168.201.34] ehlo=1 auth=0/1 commands=1/2 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: CONNECT from [192.168.201.34]:37186 to [172.27.0.8]:25 Jun 15 15:02:32 sp62 postfix/postscreen[21031]: PASS OLD [192.168.201.34]:37186 Jun 15 15:02:32 sp62 postfix/smtpd[17335]: connect from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: lost connection after AUTH from unknown[192.168.201.34] Jun 15 15:02:32 sp62 postfix/smtpd[17335]: disconnect from unknown[192.168.201.34] ehlo=1 auth=0/1 commands=1/2
Pourtant l'envoi de mail depuis l'application fonctonne bien
Related issues
History
#2 Updated by Emmanuel DILLARD almost 2 years ago
- Status changed from A qualifier to A traiter
#3 Updated by Emmanuel DILLARD almost 2 years ago
- Status changed from A traiter to Prêt à développer
#4 Updated by Alex ORLUC almost 2 years ago
Cela semble plutôt clair,
les infos serveur de mail ne semblent pas être bonnes :
AUTH command failed: 5.5.1 Error: authentication not enabled
et
lost connection after AUTH from unknown[192.168.201.34]
#5 Updated by Henri QUENEAU almost 2 years ago
Les informations d'envois de mail depuis maarch sont les mêmes et ça marche.
#6 Updated by Laurent GIOVANNONI almost 2 years ago
Vous avez essayé cette piste :
d'après les logs, je comprends que vous utilisez smtpd via un relais postfix ?
si c'est le cas, modifiez postconf :
For enable SASL when receiving email via smtpd, you need to put this parameter
smtpd_sasl_auth_enable = yes
sinon autre piste si souci avec phpmailer :
#7 Updated by Emmanuel DILLARD almost 2 years ago
- Status changed from Prêt à développer to Complément d'Informations
- Assignee changed from EDI PO to Henri QUENEAU
#8 Updated by Emmanuel DILLARD almost 2 years ago
- Related to Fonctionnalité #14158: Refactoring des classes et fichiers pour l'envoi des notifications added
#9 Updated by Henri QUENEAU almost 2 years ago
- Status changed from Complément d'Informations to A traiter
- Assignee changed from Henri QUENEAU to EDI PO
Ajout d'un relai smtp.
activation du mode sendmail (dans la conf du batch des notifications).
obtention de l'erreur:
root@sp78:/var/www/html/MaarchCourrier/custom/cs_courrier/modules/notifications/batch/scripts# php /var/www/html/MaarchCourrier/modules/notifications/batch/process_email_stack.php -c /var/www/html/MaarchCourrier/custom/cs_courrier/modules/notifications/batch/config/config.xml sh: 1: Syntax error: end of file unexpected sh: 1: Syntax error: end of file unexpected sh: 1: Syntax error: end of file unexpected sh: 1: Syntax error: end of file unexpected sh: 1: Syntax error: end of file unexpected sh: 1: Syntax error: end of file unexpected sh: 1: Syntax error: end of file unexpected
les envois de mail fonctionnent lorsqu'on envoi un mail en ligne de commande.
le problème vient de maarch :
Il faut modifier le code en supprimant/commentant les conditions:
if (empty($email->sender) && !empty((string)$mailerParams->mailfrom)) { $email->sender = (string)$mailerParams->mailfrom; } if (substr($email->sender, 0, 1) != '<') { $email->sender = '<' . $email->sender; } if (substr($email->sender, -1) != '>') { $email->sender .= '>'; }
En commentant ça, les mails partent!
Attention, cet ajout a été fait pour corriger l'envoi de mail d'un autre client.
Le client de vincennes utilise le mode sendmail car ils sont en startTLS.
L'autre client utilise le mode smtp tout simplement.
Il faut ajouter une condition dans le code disant de passer sur les conditions listés ci dessus lorsqu'on n'est pas en mode sendmail
#10 Updated by Emmanuel DILLARD almost 2 years ago
- Subject changed from Impossible d'envoyer les notifications to Script de notification en erreur (relais SMTP)
- Status changed from A traiter to Etude planifiée
#11 Updated by Emmanuel DILLARD almost 2 years ago
- Status changed from Etude planifiée to Prêt à développer
- Priority changed from 0-Bloquant to 1-Majeur
#12 Updated by Emmanuel DILLARD almost 2 years ago
- Target version changed from 20.03 (Support restreint) to 20.10 Develop
- Tags Courrier 20.03.6 (15/07) added
#13 Updated by Emmanuel DILLARD almost 2 years ago
- Project changed from Backlog to CURRENT SPRINT
- Status changed from Prêt à développer to En cours de dev (S)
#14 Updated by Florian AZIZIAN almost 2 years ago
- Assignee deleted (
EDI PO)
#15 Updated by Guillaume HEURTIER almost 2 years ago
- Assignee set to Guillaume HEURTIER
#16 Updated by Guillaume HEURTIER almost 2 years ago
- Status changed from En cours de dev (S) to Développé / Analysé (S)
#17 Updated by Emmanuel DILLARD almost 2 years ago
- Project changed from CURRENT SPRINT to Backlog
#18 Updated by Emmanuel DILLARD almost 2 years ago
- Tags Courrier 20.03.6 (Publié) added
- Tags Courrier deleted (
20.03.6 (15/07))
#20 Updated by Emmanuel DILLARD 11 months ago
- Project changed from Backlog to Backlog Courrier
- Target version changed from 20.10 Develop to 20.10 (Actif)