Efa 4.0.4 - 41 -

General eFa discussion
Post Reply
michaswr
Posts: 10
Joined: 11 Jan 2018 08:40

Efa 4.0.4 - 41 -

Post by 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:33333: 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:33333: 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
User avatar
shawniverson
Posts: 3684
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: Efa 4.0.4 - 41 -

Post by shawniverson »

Is opendmarc, opendkim, and msmilter running?
michaswr
Posts: 10
Joined: 11 Jan 2018 08:40

Re: Efa 4.0.4 - 41 -

Post by michaswr »

yes, working OK.

Only 3-5 hosts have this problem - other connection working OK.
User avatar
shawniverson
Posts: 3684
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: Efa 4.0.4 - 41 -

Post by 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
Posts: 10
Joined: 11 Jan 2018 08:40

Re: Efa 4.0.4 - 41 -

Post by 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..
User avatar
shawniverson
Posts: 3684
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: Efa 4.0.4 - 41 -

Post by 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
Posts: 10
Joined: 11 Jan 2018 08:40

Re: Efa 4.0.4 - 41 -

Post by 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 ?
User avatar
shawniverson
Posts: 3684
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: Efa 4.0.4 - 41 -

Post by 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
Posts: 10
Joined: 11 Jan 2018 08:40

Re: Efa 4.0.4 - 41 -

Post by 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
Posts: 1
Joined: 04 Mar 2024 23:51

Re: Efa 4.0.4 - 41 -

Post by bureauserv »

Thanks - commented out same lines after email flow broke on weekend, appears to be all flowing again now
michaswr
Posts: 10
Joined: 11 Jan 2018 08:40

Re: Efa 4.0.4 - 41 -

Post by 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.
User avatar
shawniverson
Posts: 3684
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: Efa 4.0.4 - 41 -

Post by shawniverson »

Yeah I see it now, there is a problem with the regex. I will fix in the next update.
michaswr
Posts: 10
Joined: 11 Jan 2018 08:40

Re: Efa 4.0.4 - 41 -

Post by michaswr »

This bug is resolved ? I find information about new efa ver ?
User avatar
shawniverson
Posts: 3684
Joined: 13 Jan 2014 23:30
Location: Indianapolis, Indiana USA
Contact:

Re: Efa 4.0.4 - 41 -

Post by shawniverson »

Yes, resolved in 4.0.4-42.
michaswr
Posts: 10
Joined: 11 Jan 2018 08:40

Re: Efa 4.0.4 - 41 -

Post by michaswr »

Thanks for you help @shawniverson !
Post Reply