Projet

Général

Profil

Anomalie #14152

Script de notification en erreur (relais SMTP)

Ajouté par Henri QUENEAU il y a presque 4 ans. Mis à jour il y a presque 3 ans.

Statut:
R&D - Terminé
Priorité:
1-Majeur
Assigné à:
Version cible:
Début:
05/06/2020
Echéance:
Version applicable MC:
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


Demandes liées

Lié à Backlog Courrier - Fonctionnalité #14158: Refactoring des classes et fichiers pour l'envoi des notificationsR&D - Terminé2020-06-16

Historique

#2 Mis à jour par Emmanuel DILLARD il y a presque 4 ans

  • Statut changé de A qualifier à A traiter

#3 Mis à jour par Emmanuel DILLARD il y a presque 4 ans

  • Statut changé de A traiter à R&D - A planifier

#4 Mis à jour par Alex ORLUC il y a presque 4 ans

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 Mis à jour par Henri QUENEAU il y a presque 4 ans

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

#6 Mis à jour par Laurent GIOVANNONI il y a presque 4 ans

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 Mis à jour par Emmanuel DILLARD il y a presque 4 ans

  • Statut changé de R&D - A planifier à Complément d'Informations
  • Assigné à changé de EDI PO à Henri QUENEAU

#8 Mis à jour par Emmanuel DILLARD il y a presque 4 ans

#9 Mis à jour par Henri QUENEAU il y a presque 4 ans

  • Statut changé de Complément d'Informations à A traiter
  • Assigné à changé de Henri QUENEAU à 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 Mis à jour par Emmanuel DILLARD il y a presque 4 ans

  • Sujet changé de Impossible d'envoyer les notifications à Script de notification en erreur (relais SMTP)
  • Statut changé de A traiter à Etude planifiée

#11 Mis à jour par Emmanuel DILLARD il y a plus de 3 ans

  • Statut changé de Etude planifiée à R&D - A planifier
  • Priorité changé de 0-Bloquant à 1-Majeur

#12 Mis à jour par Emmanuel DILLARD il y a plus de 3 ans

  • Version cible changé de 20.03 (Fin de vie) à 20.10 Develop
  • Tags Courrier 20.03.6 (15/07) ajouté

#13 Mis à jour par Emmanuel DILLARD il y a plus de 3 ans

  • Projet changé de Backlog à CURRENT SPRINT
  • Statut changé de R&D - A planifier à R&D - En cours

#14 Mis à jour par Florian AZIZIAN il y a plus de 3 ans

  • Assigné à EDI PO supprimé

#15 Mis à jour par Guillaume HEURTIER il y a plus de 3 ans

  • Assigné à mis à Guillaume HEURTIER

#16 Mis à jour par Guillaume HEURTIER il y a plus de 3 ans

  • Statut changé de R&D - En cours à R&D - Terminé

#17 Mis à jour par Emmanuel DILLARD il y a plus de 3 ans

  • Projet changé de CURRENT SPRINT à Backlog

#18 Mis à jour par Emmanuel DILLARD il y a plus de 3 ans

  • Tags Courrier 20.03.6 (Publié) ajouté
  • Tags Courrier 20.03.6 (15/07) supprimé

#20 Mis à jour par Emmanuel DILLARD il y a presque 3 ans

  • Projet changé de Backlog à Backlog Courrier
  • Version cible changé de 20.10 Develop à 20.10

Formats disponibles : Atom PDF