[Mimedefang] MsgID between sendmail and mimedefang issue
Ernst du Plooy
eduplooy at gmail.com
Thu Nov 18 11:28:08 EST 2021
I tried to reinstall MIME::Tools, but the issue remains.
No space issues
root at relay2 ~]# df -h |grep MIMEDefang
tmpfs 4.0G 3.4M 4.0G 1% /var/spool/MIMEDefang/
The inital example I've sent is extremely confusing and I can't really wrap
my head around it. To make things easier and to first look at the
directory problem I extracted another example:
[root at relay2 ~]# cat /var/log/maillog |grep 1AIFm3xE022061
Nov 18 17:48:05 relay2 mimedefang.pl[17432]: 1AIFm3xE022061: SPF Result:
*pass*pass*nightsbridge.co.za: 34.193.196.229 is authorized to use '
xxx at nightsbridge.co.za' in 'mfrom' identity (mechanism 'mx'
matched)*34.193.196.229*<booking at nightsbridge.co.za>*mail.nightsbridge.com
Nov 18 17:48:05 relay2 mimedefang.pl[17432]: 1AIFm3xE022061: NOTICE: All
Filter Recipient tests passed
Nov 18 17:48:06 relay2 sendmail[22061]: 1AIFm3xE022061: from=<
booking at nightsbridge.co.za>, size=2719, class=0, nrcpts=1,
msgid=<172494053.52128.1637250479567 at localnode>, proto=ESMTP, daemon=MTA,
relay=mail1.nightsbridge.com [34.193.196.229]
Nov 18 17:48:06 relay2 mimedefang.pl[17375]: 1AIFm3xE022061:
MDLOG,1AIFm3xE022061,RECEIVE (sbn),,,<xxx at nightsbridge.co.za>,<
xxx at villabali.co.za>,Booking for Villa Bali Boutique Hotel (xxx) - xxxn%2C
arriving 15 Dec 2021
Nov 18 17:48:06 relay2 mimedefang.pl[17375]: 1AIFm3xE022061: Rules Used:
xxx.co.za
Nov 18 17:48:06 relay2 mimedefang.pl[17375]: 1AIFm3xE022061: DKIM Domain:
xxx.co.za
Nov 18 17:48:06 relay2 mimedefang.pl[17375]: 1AIFm3xE022061: Executing
DMARC for Domain (nightsbridge.co.za) and IP (34.193.196.229).
Nov 18 17:48:06 relay2 mimedefang.pl[17375]: 1AIFm3xE022061: DKIM pass
DMARC: v=DMARC1; p=reject; rua=mailto:mailmaster at nightsbridge.com;
ruf=mailto:mailmaster at nightsbridge.com; adkim=s; aspf=s
Nov 18 17:48:06 relay2 mimedefang.pl[17375]: 1AIFm3xE022061: Clamd returned
error: File path check failure: No such file or directory.
Nov 18 17:48:06 relay2 mimedefang.pl[17375]: 1AIFm3xE022061: Anti-Virus:
Running virus scanner
Nov 18 17:48:06 relay2 mimedefang.pl[17375]: 1AIFm3xE022061: Anti-Virus:
result: From: <xxx at nightsbridge.co.za> | Message: 999 swerr | Action:
tempfail | Virus-Name: | Complete-Message:
Nov 18 17:48:06 relay2 mimedefang.pl[17375]: 1AIFm3xE022061: Anti-Virus:
scanner tempfail!
Nov 18 17:48:06 relay2 mimedefang.pl[17375]: 1AIFm3xE022061: High Load
Server
Nov 18 17:48:06 relay2 mimedefang.pl[17375]: 1AIFm3xE022061: NOTICE: All
Filter tests passwd
Nov 18 17:48:06 relay2 mimedefang.pl[17375]: 1AIFm3xE022061: NOTICE: Scan
complete.
Nov 18 17:48:06 relay2 mimedefang[10998]: 1AIFm3xE022061: Filter did not
create RESULTS file
Nov 18 17:48:06 relay2 mimedefang[10998]: 1AIFm3xE022061:
lstat(/var/spool/MIMEDefang/mdefang-1AIFm3xE022061) failed: No such file or
directory
Nov 18 17:48:06 relay2 mimedefang[10998]: 1AIFm3xE022061: failed to clean
up /var/spool/MIMEDefang/mdefang-1AIFm3xE022061: No such file or directory
Nov 18 17:48:06 relay2 sendmail[22061]: 1AIFm3xE022061: Milter: data,
reject=451 4.3.2 Please try again later
Nov 18 17:48:06 relay2 sendmail[22061]: 1AIFm3xE022061: to=<
res at villabali.co.za>, delay=00:00:01, pri=32719, stat=Please try again later
Bill Cole wrote:
>1. Look for the log entries in the time gaps and before the first one
>above for any hints of what actually happened.
Agree, the time delay is weird, but it is not common. The new example do
not have these delays.
>2. Look at your mimedefang-filter where it is logging SPF results and
>figure out what it's doing with IPs and hostnames. It's getting
>something wrong in there...
if ($testspf)
{
my ($result, $code, $expl) = spf_query ($ip, $sender, $helo);
md_syslog('warning', "SPF Result:
*$result*$code*$expl*$ip*$sender*$helo");
if ($result ne "pass")
{
#deal with various result values. The above examples passwd SPF so not
relevant to the error.
....
}
}
sub spf_query ($$$) {
my $spf_server = Mail::SPF::Server->new();
my ($ip, $sender, $helo) = @_;
my $request = Mail::SPF::Request->new(
# versions => [1, 2],
scope => 'mfrom',
identity => $sender,
ip_address => $ip,
helo_identity => $helo
);
my $result = $spf_server->process($request);
my @res = split(' ', $result);
return ($res[0], $result->code, $result->local_explanation);
}
>3. Figure out why MD is remembering an old message's working directory
>almost 2 minutes after Sendmail believes it both (a) was told by a
>milter that the sending IP is bad and (b) lost the connection
>unceremoniously after DATA.
Maybe we should look at the new example to simplify things for now.
On Thu, 18 Nov 2021 at 17:49, Bill Cole via MIMEDefang <
mimedefang at lists.mimedefang.org> wrote:
> On 2021-11-18 at 08:05:11 UTC-0500 (Thu, 18 Nov 2021 15:05:11 +0200)
> Ernst du Plooy via MIMEDefang <mimedefang at lists.mimedefang.org>
> is rumored to have said:
>
> > I'm seeing weird errors on some instances on Mimedefang lately. This
> > only
> > happens once or twice a day. Notice the 3rd line from below. The
> > mgsid (
> > 1AH5u8x0021136) from sendmail is not the same as the id used for the
> > temporary directory created by mimedefang (1AH5sPfg019398). It seems
> > that
> > the message id between sendmail and mimedefang gets mixed up.
>
> Being intimately familiar with how Sendmail and MIMEDefang handle the
> queueID, I feel confident in saying that this is NOT what is happening.
>
> The Sendmail queueID is created by sendmail at runtime and is
> meaningful: it is composed of a timestamp in a sendmail-specific format
> and a sendmail process ID. MD cannot invent a queueID. 1AH5sPfg019398
> was created by the sendmail process with PID 19398. 1AH5u8x0021136 was
> created *almost 2 minutes later* by the sendmail process with PID 21136.
>
>
> > Nov 17 07:54:25 xxx01 sendmail[19398]: 1AH5sPfg019398: Milter:
> > to=<help at email.domain>, reject=554 5.7.1 Connection Refused: Relay
> > Server
> > (a.b.61.62) blacklisted
>
> There should be something about 1AH5sPfg019398 logged before this. The
> munging hurts here, as you've eliminated the relay host IP which might
> be useful.
>
> > Nov 17 07:54:25 xxx01 sendmail[19398]: 1AH5sPfg019398: lost input
> > channel
> > from mail-ct2zaf01lp2175.outbound.protection.outlook.com
> > [104.47.19.175] to
> > MTA after data
>
> That MS machine dropped the connection before getting a reply to the
> second step of the DATA command, i.e. after sending the message but
> before getting an acknowledgement or rejection. Maybe it never saw the
> rejection.
>
> > Nov 17 07:54:25 xxx01 sendmail[19398]: 1AH5sPfg019398:
> > from=<user at email.domain>, size=330137, class=0, nrcpts=0, proto=ESMTP,
> > daemon=MTA, relay=mail-ct2zaf01lp2175.outbound.protection.outlook.com
> > [104.47.19.175]
>
> 1:43 time gap... What happened here?
>
> > Nov 17 07:56:08 xxx01 mimedefang.pl[10411]: 1AH5sPfg019398:
> > filter_recipient tempfailed recipient <help at email.domain>
> > Nov 17 07:56:08 xxx01 mimedefang.pl[10411]: 1AH5sPfg019398: Cannot
> > open
> > COMMANDS file from mimedefang: No such file or directory
>
> Strange. Why does MD care about 1AH5sPfg019398 1:43 after Sendmail
> disposed of it?
>
> > Nov 17 07:56:08 xxx01 mimedefang.pl[10411]: 1AH5sPfg019398: SPF
> > Result:
> > Skip Greylist for ZAF01-CT2-obe.outbound.protection.outlook.com
>
> That's a new hostname!
>
> > Nov 17 07:56:08 xxx01 mimedefang.pl[10411]: 1AH5sPfg019398: SPF
> > Result:
> > Whitelisted SPF Cache 104.47.19.175 <aaronb at email.domain>
> > ZAF01-CT2-obe.outbound.protection.outlook.com
>
> ??? The IP and hostname are inconsistent here. What is the line in
> mimedefang-filter that it logging this?
>
> I suspect that you have some custom code in mimedefang-filter for SPF
> that is doing something slightly wrong and remembering a queueID for too
> long. No idea HOW it's managing that.
>
> > Nov 17 07:56:09 xxx01 sendmail[21136]: 1AH5u8x0021136: Milter:
> > to=<ne at email.domain>, reject=451 4.3.0 could not
> > chdir(/var/spool/MIMEDefang/mdefang-1AH5sPfg019398): No such file or
> > directory
>
> Here we have a new sendmail process with a new queueID and apparently a
> confusion inside MD, which is passing back a message referencing the
> working directory for the old, quite reasonably no longer existing,
> queueID.
>
> And another gap here. Only 14s but that's still oddly long. What
> happened here?
>
> > Nov 17 07:56:23 xxx01 mimedefang.pl[10411]: 1AH5sPfg019398: TEMPFAIL
> > Nov 17 07:56:23 xxx01 mimedefang.pl[10411]: 1AH5sPfg019398: NOTICE:
> > All
> > Filter Recipient tests passed
>
> Very weird. Whatever in your mimedefang-filter logged this thought it
> was still working inside filter_recipient() with 1AH5sPfg019398, 1:58
> after Sendmail itself finished working with that queueID, having gotten
> to the point of DATA before the client disappeared. And it seems
> confused about 'passing' whatever tests it is running in
> filter_recipient().
>
> > Any suggestions?
>
> 1. Look for the log entries in the time gaps and before the first one
> above for any hints of what actually happened.
> 2. Look at your mimedefang-filter where it is logging SPF results and
> figure out what it's doing with IPs and hostnames. It's getting
> something wrong in there...
> 3. Figure out why MD is remembering an old message's working directory
> almost 2 minutes after Sendmail believes it both (a) was told by a
> milter that the sending IP is bad and (b) lost the connection
> unceremoniously after DATA.
>
> I don't have a coherent theory of what happened here, but I suspect that
> it is hiding in the missing 1:43 and maybe the additional 0:14 later,
> and possibly in whatever was logged BEFORE the first line above.
>
> --
> Bill Cole
> bill at scconsult.com or billcole at apache.org
> (AKA @grumpybozo and many *@billmail.scconsult.com addresses)
> Not Currently Available For Hire
>
> _______________________________________________
> NOTE: If there is a disclaimer or other legal boilerplate in the above
> message, it is NULL AND VOID. You may ignore it.
>
> MIMEDefang mailing list MIMEDefang at lists.mimedefang.org
>
> https://lists.mimedefang.org/mailman/listinfo/mimedefang_lists.mimedefang.org
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.mimedefang.org/pipermail/mimedefang_lists.mimedefang.org/attachments/20211118/f77d9b3c/attachment-0001.html>
More information about the MIMEDefang
mailing list