I tried to reinstall MIME::Tools, but the issue remains. No space issues root@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@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 ' [email protected]' in 'mfrom' identity (mechanism 'mx' matched)*34.193.196.229*<[email protected]>*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=< [email protected]>, size=2719, class=0, nrcpts=1, msgid=<172494053.52128.1637250479567@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),,,<[email protected]>,< [email protected]>,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:[email protected]; ruf=mailto:[email protected]; 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: <[email protected]> | 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=< [email protected]>, 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 < [email protected]> wrote: > On 2021-11-18 at 08:05:11 UTC-0500 (Thu, 18 Nov 2021 15:05:11 +0200) > Ernst du Plooy via MIMEDefang <[email protected]> > 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=<[email protected]>, 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=<[email protected]>, 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 <[email protected]> > > 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 <[email protected]> > > 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=<[email protected]>, 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 > [email protected] or [email protected] > (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 [email protected] > > https://lists.mimedefang.org/mailman/listinfo/mimedefang_lists.mimedefang.org >
_______________________________________________ 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 [email protected] https://lists.mimedefang.org/mailman/listinfo/mimedefang_lists.mimedefang.org
