[Mimedefang] MsgID between sendmail and mimedefang issue

Ernst du Plooy eduplooy at gmail.com
Thu Nov 18 14:39:52 EST 2021


The error happens between filter_recipient and filter_begin.  See below.

I added two syslog messages as follows:

sub filter_recipient
{
  my($recipient, $sender, $ip, $hostname, $first, $helo, $rcpt_mailer,
$rcpt_host, $rcpt_addr) = @_;
  #rest of filter_recipient code
  ....
  *md_syslog('warning', "temptest FILTER_RECIPIENT end");*
  return ('CONTINUE', "ok");
}

sub filter_begin
{
  *md_syslog('warning', "temptest FILTER_BEGIN start");*
  #rest of filter_begin
  ...
}

The "temptest FILTER_RECIPIENT" message will display, but "temptest
FILTER_BEGIN start" does not.  This error only occurs for some messages.

Messages with error:
[root at relay2 mail]# cat /var/log/maillog |grep 1AIJNGr4016296
Nov 18 21:23:19 relay2 mimedefang.pl[15960]: 1AIJNGr4016296: SPF Result:
*pass*pass*pm.mtasv.net: Sender is authorized to use '
pm_bounces at pm.mtasv.net' in 'mfrom' identity (mechanism 'include:
spf.mtasv.net' matched)*50.31.156.120*<pm_bounces at pm.mtasv.net>*
sc-ord-mta120.mtasv.net
Nov 18 21:23:19 relay2 mimedefang.pl[15960]: 1AIJNGr4016296: NOTICE: All
Filter Recipient tests passed
*Nov 18 21:23:19 relay2 mimedefang.pl <http://mimedefang.pl>[15960]:
1AIJNGr4016296: temptest FILTER_RECIPIENT end*
Nov 18 21:23:20 relay2 sendmail[16296]: 1AIJNGr4016296: from=<
pm_bounces at pm.mtasv.net>, size=17978, class=0, nrcpts=1,
msgid=<6196a823b02b5_4e2b1b4e63c9981133341 at eba11ddb-cc25-491a-9283-cc2e3312fc11.mail>,
bodytype=8BITMIME, proto=ESMTP, daemon=MTA, relay=sc-ord-mta120.mtasv.net
[50.31.156.120]
Nov 18 21:23:20 relay2 mimedefang[15628]: 1AIJNGr4016296: Could not open
/var/spool/MIMEDefang/mdefang-1AIJNGr4016296/INPUTMSG: No such file or
directory
Nov 18 21:23:20 relay2 mimedefang[15628]: 1AIJNGr4016296:
lstat(/var/spool/MIMEDefang/mdefang-1AIJNGr4016296) failed: No such file or
directory
Nov 18 21:23:20 relay2 mimedefang[15628]: 1AIJNGr4016296: failed to clean
up /var/spool/MIMEDefang/mdefang-1AIJNGr4016296: No such file or directory
Nov 18 21:23:20 relay2 sendmail[16296]: 1AIJNGr4016296: Milter: data,
reject=451 4.3.2 Please try again later
Nov 18 21:23:20 relay2 sendmail[16296]: 1AIJNGr4016296: to=<rbotha at bfn.co.za>,
delay=00:00:01, pri=47978, stat=Please try again later

Message without error:
root at relay2 mail]# cat /var/log/maillog |grep 1AIJX2VT022358
Nov 18 21:33:04 relay2 mimedefang.pl[19551]: 1AIJX2VT022358: SPF Result:
Whitelisted SPF Cache 168.245.44.183 <bounces+13594577-8a58-nicolene=
roscher.bfnmcc.co.za at abmail.email.etsy.com> o2523.abmail.email.etsy.com
Nov 18 21:33:04 relay2 mimedefang.pl[19551]: 1AIJX2VT022358: NOTICE: All
Filter Recipient tests passed
*Nov 18 21:33:04 relay2 mimedefang.pl <http://mimedefang.pl>[19551]:
1AIJX2VT022358: temptest FILTER_RECIPIENT end*
Nov 18 21:33:05 relay2 sendmail[22358]: 1AIJX2VT022358:
from=<bounces+13594577-8a58-nicolene=
roscher.bfnmcc.co.za at abmail.email.etsy.com>, size=59859, class=0, nrcpts=1,
msgid=<bRqUVaKBSWScLutZDn1TAA at ismtpd0135p1iad2.sendgrid.net>,
bodytype=8BITMIME, proto=ESMTP, daemon=MTA, relay=
o2523.abmail.email.etsy.com [168.245.44.183]
*Nov 18 21:33:05 relay2 mimedefang.pl <http://mimedefang.pl>[19451]:
1AIJX2VT022358: temptest FILTER_BEGIN start*
Nov 18 21:33:05 relay2 mimedefang.pl[19451]: 1AIJX2VT022358:
MDLOG,1AIJX2VT022358,RECEIVE (sbn),,,<bounces+13594577-8a58-nicolene=
roscher.bfnmcc.co.za at abmail.email.etsy.com>,<nicolene at roscher.bfnmcc.co.za>,Exclusive:
Start Cyber Week early!
......

The server is running Centos:
[root at relay mail]# cat /etc/redhat-release
CentOS Linux release 7.9.2009 (Core)

And sendmail and mimedefang were installed using RPM's and were not
compiled.
[root at relay mail]# rpm -qa |grep sendmail
sendmail-milter-8.14.7-6.el7.x86_64
sendmail-8.14.7-6.el7.x86_64
sendmail-cf-8.14.7-6.el7.noarch
sendmail-doc-8.14.7-6.el7.noarch
sendmail-devel-8.14.7-6.el7.x86_6

[root at relay mail]# rpm -qa |grep mimedefang
mimedefang-2.85-1.el7.x86_64



On Thu, 18 Nov 2021 at 18:28, Ernst du Plooy <eduplooy at gmail.com> wrote:

> 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/078e406b/attachment-0001.html>


More information about the MIMEDefang mailing list