Project

General

Profile

Anomalie #14152

Script de notification en erreur (relais SMTP)

Added by Henri QUENEAU over 2 years ago. Updated over 1 year ago.

Status:
Développé / Analysé (S)
Priority:
1-Majeur
Assignee:
Guillaume HEURTIER
Target version:
20.10 (Actif)
Start date:
06/05/2020
Due date:
Tags Courrier:
20.03.6 (Publié)

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

Capture d’écran de 2020-06-05 13-16-28.png (28.2 KB) Capture d’écran de 2020-06-05 13-16-28.png Robin SALDINGER, 06/05/2020 01:16 PM
Capture d’écran de 2020-06-12 17-18-40.png (9.15 KB) Capture d’écran de 2020-06-12 17-18-40.png Robin SALDINGER, 06/12/2020 05:19 PM
Capture d’écran de 2020-06-12 17-20-28.png (13.8 KB) Capture d’écran de 2020-06-12 17-20-28.png Robin SALDINGER, 06/12/2020 05:21 PM
5383
5384
5385

Related issues

Related to Backlog Courrier - Fonctionnalité #14158: Refactoring des classes et fichiers pour l'envoi des notificationsDéveloppé / Analysé (S)2020-06-16

History

#2 Updated by Emmanuel DILLARD over 2 years ago

  • Status changed from A qualifier to A traiter

#3 Updated by Emmanuel DILLARD over 2 years ago

  • Status changed from A traiter to Prêt à embarquer

#4 Updated by Alex ORLUC over 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 over 2 years ago

Les informations d'envois de mail depuis maarch sont les mêmes et ça marche.

#6 Updated by Laurent GIOVANNONI over 2 years ago

Vous avez essayé cette piste :

https://serverfault.com/questions/712903/503-5-5-1-error-authentication-not-enabled-when-trying-to-connect-to-my-postf

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 :

https://stackoverflow.com/questions/50659028/postfix-php-mail-issue-client-503-5-5-1-error-authentication-not-enabled-smtp

#7 Updated by Emmanuel DILLARD over 2 years ago

  • Status changed from Prêt à embarquer to Complément d'Informations
  • Assignee changed from EDI PO to Henri QUENEAU

#8 Updated by Emmanuel DILLARD over 2 years ago

#9 Updated by Henri QUENEAU over 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 :

https://labs.maarch.org/maarch/MaarchCourrier/blob/20.03/modules/notifications/batch/process_email_stack.php

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 over 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 over 2 years ago

  • Status changed from Etude planifiée to Prêt à embarquer
  • Priority changed from 0-Bloquant to 1-Majeur

#12 Updated by Emmanuel DILLARD over 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 over 2 years ago

  • Project changed from Backlog to CURRENT SPRINT
  • Status changed from Prêt à embarquer to En cours de dev (S)

#14 Updated by Florian AZIZIAN over 2 years ago

  • Assignee deleted (EDI PO)

#15 Updated by Guillaume HEURTIER over 2 years ago

  • Assignee set to Guillaume HEURTIER

#16 Updated by Guillaume HEURTIER over 2 years ago

  • Status changed from En cours de dev (S) to Développé / Analysé (S)

#17 Updated by Emmanuel DILLARD over 2 years ago

  • Project changed from CURRENT SPRINT to Backlog

#18 Updated by Emmanuel DILLARD over 2 years ago

  • Tags Courrier 20.03.6 (Publié) added
  • Tags Courrier deleted (20.03.6 (15/07))

#20 Updated by Emmanuel DILLARD over 1 year ago

  • Project changed from Backlog to Backlog Courrier
  • Target version changed from 20.10 Develop to 20.10 (Actif)

Also available in: Atom PDF