Efa 4.0.4 - 41 -
Efa 4.0.4 - 41 -
Hi ,
Afer install update to Efa 4.0.4- 41 i have problem witch 451 4.7.1 Service unavailable - try again later; Of course before working OK.
I check the logs :
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: connect from FQDN[X.X.X.X]
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: match_list_match: FQDN: no match
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: match_list_match: FQDN: no match
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: match_list_match: FQDN: no match
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: milter_macro_lookup: result "FQDN [X.X.X.X]"
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: milter8_conn_event: milter inet:127.0.0.1:8891: connect FQDN/X.X.X.X
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: event: SMFIC_CONNECT; macros: j=mx {daemon_name}=mx {daemon_addr}=10.10.1.24 v=Postfix 3.5.9 _=FQDN [X.X.X.X]
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: milter8_conn_event: milter inet:127.0.0.1:8893: connect FQDN/X.X.X.X
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: event: SMFIC_CONNECT; macros: j=mx {daemon_name}=mx {daemon_addr}=10.10.1.24 v=Postfix 3.5.9 _=FQDN [X.X.X.X]
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: milter8_conn_event: milter inet:127.0.0.1 connect FQDN/X.X.X.X
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: event: SMFIC_CONNECT; macros: j=mx {daemon_name}=mx {daemon_addr}=10.10.1.24 v=Postfix 3.5.9 _=FQDN [X.X.X.X]
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 220 mx ESMTP Postfix
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: < FQDN[X.X.X.X]: EHLO FQDN
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: milter8_helo_event: milter inet:127.0.0.1:8891: helo FQDN
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: milter8_helo_event: milter inet:127.0.0.1:8893: helo FQDN
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: milter8_helo_event: milter inet:127.0.0.1 helo FQDN
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: NOQUEUE: milter-reject: EHLO from FQDN[X.X.X.X]: 451 4.7.1 Service unavailable - try again later; proto=SMTP helo=<FQDN>
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: match_list_match: FQDN: no match
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 250-mx
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 250-PIPELINING
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 250-SIZE 133169152
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 250-ETRN
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 250-STARTTLS
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 250-ENHANCEDSTATUSCODES
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 250-8BITMIME
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 250-DSN
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 250 SMTPUTF8
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: < FQDN[X.X.X.X]: STARTTLS
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 454 4.3.0 Try again later
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: < FQDN[X.X.X.X]: MAIL FROM:<X@X.com>
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: NOQUEUE: milter-reject: MAIL from FQDN[X.X.X.X]: 451 4.7.1 Service unavailable - try again later; from=<X@X.com> proto=ESMTP helo=<FQDN>
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 451 4.7.1 Service unavailable - try again later
I search info about this and I find the problem in opendkim/opendmarc , but the version have fix this problem. I used :
libopendmarc-1.4.1.1-3.el7.x86_64
opendmarc-1.4.1.1-3.el7.x86_64
How I Can debug this problem and resolve this ?
Thanks for help
Afer install update to Efa 4.0.4- 41 i have problem witch 451 4.7.1 Service unavailable - try again later; Of course before working OK.
I check the logs :
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: connect from FQDN[X.X.X.X]
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: match_list_match: FQDN: no match
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: match_list_match: FQDN: no match
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: match_list_match: FQDN: no match
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: milter_macro_lookup: result "FQDN [X.X.X.X]"
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: milter8_conn_event: milter inet:127.0.0.1:8891: connect FQDN/X.X.X.X
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: event: SMFIC_CONNECT; macros: j=mx {daemon_name}=mx {daemon_addr}=10.10.1.24 v=Postfix 3.5.9 _=FQDN [X.X.X.X]
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: milter8_conn_event: milter inet:127.0.0.1:8893: connect FQDN/X.X.X.X
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: event: SMFIC_CONNECT; macros: j=mx {daemon_name}=mx {daemon_addr}=10.10.1.24 v=Postfix 3.5.9 _=FQDN [X.X.X.X]
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: milter8_conn_event: milter inet:127.0.0.1 connect FQDN/X.X.X.X
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: event: SMFIC_CONNECT; macros: j=mx {daemon_name}=mx {daemon_addr}=10.10.1.24 v=Postfix 3.5.9 _=FQDN [X.X.X.X]
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 220 mx ESMTP Postfix
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: < FQDN[X.X.X.X]: EHLO FQDN
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: milter8_helo_event: milter inet:127.0.0.1:8891: helo FQDN
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: milter8_helo_event: milter inet:127.0.0.1:8893: helo FQDN
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: milter8_helo_event: milter inet:127.0.0.1 helo FQDN
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: NOQUEUE: milter-reject: EHLO from FQDN[X.X.X.X]: 451 4.7.1 Service unavailable - try again later; proto=SMTP helo=<FQDN>
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: match_list_match: FQDN: no match
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 250-mx
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 250-PIPELINING
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 250-SIZE 133169152
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 250-ETRN
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 250-STARTTLS
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 250-ENHANCEDSTATUSCODES
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 250-8BITMIME
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 250-DSN
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 250 SMTPUTF8
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: < FQDN[X.X.X.X]: STARTTLS
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 454 4.3.0 Try again later
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: < FQDN[X.X.X.X]: MAIL FROM:<X@X.com>
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: NOQUEUE: milter-reject: MAIL from FQDN[X.X.X.X]: 451 4.7.1 Service unavailable - try again later; from=<X@X.com> proto=ESMTP helo=<FQDN>
Feb 2 19:20:14 mx4 postfix/smtpd[85109]: > FQDN[X.X.X.X]: 451 4.7.1 Service unavailable - try again later
I search info about this and I find the problem in opendkim/opendmarc , but the version have fix this problem. I used :
libopendmarc-1.4.1.1-3.el7.x86_64
opendmarc-1.4.1.1-3.el7.x86_64
How I Can debug this problem and resolve this ?
Thanks for help
- shawniverson
- Posts: 3650
- Joined: 13 Jan 2014 23:30
- Location: Indianapolis, Indiana USA
- Contact:
Re: Efa 4.0.4 - 41 -
Is opendmarc, opendkim, and msmilter running?
Re: Efa 4.0.4 - 41 -
yes, working OK.
Only 3-5 hosts have this problem - other connection working OK.
Only 3-5 hosts have this problem - other connection working OK.
- shawniverson
- Posts: 3650
- Joined: 13 Jan 2014 23:30
- Location: Indianapolis, Indiana USA
- Contact:
Re: Efa 4.0.4 - 41 -
Let's try isolating the problem:
Change the following lines in /etc/postfix/main.cf:
Change to:
Restart postfix and try again. This will test postfix without opendmarc and opendkim present.
Change the following lines in /etc/postfix/main.cf:
Code: Select all
smtpd_milters = inet:localhost:8891, inet:localhost:8893, inet:127.0.0.1:33333
non_smtpd_milters = inet:localhost:8891, inet:localhost:8893
Code: Select all
smtpd_milters = inet:127.0.0.1:33333
non_smtpd_milters =
Re: Efa 4.0.4 - 41 -
I have this setting and I have the same problem.
[root@mx4 log]# cat /etc/postfix/main.cf | grep smtpd_milters
smtpd_milters = inet:127.0.0.1:33333
This problem applies to 4 hosts. Other working ok..
[root@mx4 log]# cat /etc/postfix/main.cf | grep smtpd_milters
smtpd_milters = inet:127.0.0.1:33333
This problem applies to 4 hosts. Other working ok..
- shawniverson
- Posts: 3650
- Joined: 13 Jan 2014 23:30
- Location: Indianapolis, Indiana USA
- Contact:
Re: Efa 4.0.4 - 41 -
Okay the problem is not opendkim or opendmarc, then.
Enable debugging and restart msmilter:
/etc/MailScanner/MailScanner.conf
Report what you get in /var/log/maillog.
Enable debugging and restart msmilter:
/etc/MailScanner/MailScanner.conf
Code: Select all
Debug = yes
Code: Select all
sudo systemctl restart msmilter
Re: Efa 4.0.4 - 41 -
I enabled debug and the logs :
Mar 4 09:37:27 mx4 postfix/smtpd[7258]: connect from 5E988962.static.tld.pl[94.152.137.98]
Mar 4 09:37:27 mx4 MSMilter[7396]: connect_callback: ip = 94.152.137.98
Mar 4 09:37:27 mx4 MSMilter[7396]: Unexpected helo callback
Mar 4 09:37:27 mx4 MSMilter[7396]: eom_callback: incoming = /var/spool/MailScanner/milterin
Mar 4 09:37:27 mx4 postfix/smtpd[7258]: NOQUEUE: milter-reject: EHLO from 5E988962.static.tld.pl[94.152.137.98]: 451 4.7.1 Service unavailable - try again later; proto=SMTP helo=<smtp.60398.v.tld.pl>
Mar 4 09:37:27 mx4 postfix/smtpd[7258]: NOQUEUE: milter-reject: MAIL from 5E988962.static.tld.pl[94.152.137.98]: 451 4.7.1 Service unavailable - try again later; from=<X> proto=ESMTP helo=<smtp.60398.v.tld.pl>
Mar 4 09:37:27 mx4 postfix/smtpd[7258]: lost connection after MAIL from 5E988962.static.tld.pl[94.152.137.98]
Mar 4 09:37:27 mx4 postfix/smtpd[7258]: disconnect from 5E988962.static.tld.pl[94.152.137.98] ehlo=1 starttls=0/1 mail=0/1 commands=1/3
I search this code in MailScanner and in common/usr/sbin/MSMilter I find :
sub helo_callback
{
my $ctx = shift;
my $helohost = shift;
my $message_ref = $ctx->getpriv();
my $message = "Received: from $helohost";
# Check for unexpected helo
if ( ${$message_ref} =~ /^[0-9A-F]{7,20}|[0-9B-DF-HJ-NP-TV-Zb-df-hj-np-tv-z]{8,20}$/) {
MailScanner::Log::WarnLog("Unexpected helo callback");
return Sendmail::PMilter::SMFIS_TEMPFAIL;
}
This host have more dots in FQDN Maybe this is the problem ?
Mar 4 09:37:27 mx4 postfix/smtpd[7258]: connect from 5E988962.static.tld.pl[94.152.137.98]
Mar 4 09:37:27 mx4 MSMilter[7396]: connect_callback: ip = 94.152.137.98
Mar 4 09:37:27 mx4 MSMilter[7396]: Unexpected helo callback
Mar 4 09:37:27 mx4 MSMilter[7396]: eom_callback: incoming = /var/spool/MailScanner/milterin
Mar 4 09:37:27 mx4 postfix/smtpd[7258]: NOQUEUE: milter-reject: EHLO from 5E988962.static.tld.pl[94.152.137.98]: 451 4.7.1 Service unavailable - try again later; proto=SMTP helo=<smtp.60398.v.tld.pl>
Mar 4 09:37:27 mx4 postfix/smtpd[7258]: NOQUEUE: milter-reject: MAIL from 5E988962.static.tld.pl[94.152.137.98]: 451 4.7.1 Service unavailable - try again later; from=<X> proto=ESMTP helo=<smtp.60398.v.tld.pl>
Mar 4 09:37:27 mx4 postfix/smtpd[7258]: lost connection after MAIL from 5E988962.static.tld.pl[94.152.137.98]
Mar 4 09:37:27 mx4 postfix/smtpd[7258]: disconnect from 5E988962.static.tld.pl[94.152.137.98] ehlo=1 starttls=0/1 mail=0/1 commands=1/3
I search this code in MailScanner and in common/usr/sbin/MSMilter I find :
sub helo_callback
{
my $ctx = shift;
my $helohost = shift;
my $message_ref = $ctx->getpriv();
my $message = "Received: from $helohost";
# Check for unexpected helo
if ( ${$message_ref} =~ /^[0-9A-F]{7,20}|[0-9B-DF-HJ-NP-TV-Zb-df-hj-np-tv-z]{8,20}$/) {
MailScanner::Log::WarnLog("Unexpected helo callback");
return Sendmail::PMilter::SMFIS_TEMPFAIL;
}
This host have more dots in FQDN Maybe this is the problem ?
- shawniverson
- Posts: 3650
- Joined: 13 Jan 2014 23:30
- Location: Indianapolis, Indiana USA
- Contact:
Re: Efa 4.0.4 - 41 -
Looks like a race condition between the connect callback and helo callback. The connect callback is supposed to pass information along to the helo callback but that didn't happen, probably because the helo started before the connect callback completed.
The question is how to fix, because without the information from the connect callback the header cannot be properly populated.
The question is how to fix, because without the information from the connect callback the header cannot be properly populated.
Re: Efa 4.0.4 - 41 -
I comment this line and working OK.
#if ( ${$message_ref} =~ /^[0-9A-F]{7,20}|[0-9B-DF-HJ-NP-TV-Zb-df-hj-np-tv-z]{8,20}$/) {
#MailScanner::Log::WarnLog("Unexpected helo callback");
#return Sendmail::PMilter::SMFIS_TEMPFAIL;
#}
The hostname catches ragex and return this fail
#if ( ${$message_ref} =~ /^[0-9A-F]{7,20}|[0-9B-DF-HJ-NP-TV-Zb-df-hj-np-tv-z]{8,20}$/) {
#MailScanner::Log::WarnLog("Unexpected helo callback");
#return Sendmail::PMilter::SMFIS_TEMPFAIL;
#}
The hostname catches ragex and return this fail
-
- Posts: 1
- Joined: 04 Mar 2024 23:51
Re: Efa 4.0.4 - 41 -
Thanks - commented out same lines after email flow broke on weekend, appears to be all flowing again now
Re: Efa 4.0.4 - 41 -
This changes is added in MailScanner in December 2023
12/27/2023 Changes in v5.5.1-2
==================================
- Fix 7z/xz/bz2 etc. decompression
- Check for bad helo callback in msmilter
Maybe is the bug ? In my option the ragex is bad.
12/27/2023 Changes in v5.5.1-2
==================================
- Fix 7z/xz/bz2 etc. decompression
- Check for bad helo callback in msmilter
Maybe is the bug ? In my option the ragex is bad.
- shawniverson
- Posts: 3650
- Joined: 13 Jan 2014 23:30
- Location: Indianapolis, Indiana USA
- Contact:
Re: Efa 4.0.4 - 41 -
Yeah I see it now, there is a problem with the regex. I will fix in the next update.
Re: Efa 4.0.4 - 41 -
This bug is resolved ? I find information about new efa ver ?
- shawniverson
- Posts: 3650
- Joined: 13 Jan 2014 23:30
- Location: Indianapolis, Indiana USA
- Contact:
Re: Efa 4.0.4 - 41 -
Yes, resolved in 4.0.4-42.
Re: Efa 4.0.4 - 41 -
Thanks for you help @shawniverson !