Efa 4.0.4 - 41 -

[michaswr]

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

[shawniverson]

Is opendmarc, opendkim, and msmilter running?

[michaswr]

yes, working OK.

Only 3-5 hosts have this problem - other connection working OK.

[shawniverson]

Let's try isolating the problem:

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 

Change to:

Code: Select all

smtpd_milters = inet:127.0.0.1:33333
non_smtpd_milters =

Restart postfix and try again. This will test postfix without opendmarc and opendkim present.

[michaswr]

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..

[shawniverson]

Okay the problem is not opendkim or opendmarc, then.

Enable debugging and restart msmilter:

/etc/MailScanner/MailScanner.conf

Code: Select all

Debug = yes

Code: Select all

sudo systemctl restart msmilter

Report what you get in /var/log/maillog.

[michaswr]

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 ?

[shawniverson]

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.

[michaswr]

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

[bureauserv]

Thanks - commented out same lines after email flow broke on weekend, appears to be all flowing again now

[michaswr]

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.

[shawniverson]

Yeah I see it now, there is a problem with the regex. I will fix in the next update.

[michaswr]

This bug is resolved ? I find information about new efa ver ?

[shawniverson]

Yes, resolved in 4.0.4-42.

[michaswr]

Thanks for you help @shawniverson !