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