[Mimedefang] New errors following update to 2.85

Fri Nov 12 15:36:51 EST 2021

Replies...

> On Nov 12, 2021, at 1:48 AM, Giovanni Bechis <giovanni at paclan.it> wrote:
> 
> more inline comments.
> On Thu, Nov 11, 2021 at 08:35:47PM -0700, Philip Prindeville wrote:
>> Inline.
>> 
>>> On Nov 11, 2021, at 1:01 AM, Giovanni Bechis <giovanni at paclan.it> wrote:
>>> 
>>> On Wed, Nov 10, 2021 at 03:23:25PM -0700, Philip Prindeville via MIMEDefang wrote:
>>>> Hi,
>>>> 
>>>> I just updated my mail server from Fedora 33 to Fedora 34, and I noticed right away seeing these messages:
>>>> 
>>>> Nov 10 14:37:17 localhost mimedefang.pl[9141]: 1AALbHB8009400: relay: vger.kernel.org (23.128.96.18:56344 => 192.168.4.3:25)
>>>> Nov 10 14:37:22 localhost mimedefang.pl[7873]: 1AALbHB8009400: helo: vger.kernel.org (23.128.96.18:56344) said "helo vger.kernel.org"
>>>> Nov 10 14:37:22 localhost sendmail[9400]: 1AALbHB8009400: from=<netdev-owner at vger.kernel.org>, size=400289, class=-60, nrcpts=1, msgid=<20211110063928.GB30217 at xsang-OptiPlex-9020>, bodytype=8BITMIME, proto=ESMTP, daemon=MTA-v4, relay=vger.kernel.org [23.128.96.18]
>>>> Nov 10 14:39:22 localhost sendmail[9400]: 1AALbHB8009400: Milter (mimedefang): timeout before data read, where=eom
>>>> Nov 10 14:39:22 localhost sendmail[9400]: 1AALbHB8009400: Milter (mimedefang): to error state
>>>> Nov 10 14:39:22 localhost sendmail[9400]: 1AALbHB8009400: Milter: data, reject=451 4.3.2 Please try again later
>>>> Nov 10 14:39:22 localhost sendmail[9400]: 1AALbHB8009400: to=<foo at bar.com>, delay=00:02:00, pri=538289, stat=Please try again later
>>>> Nov 10 14:43:38 localhost mimedefang.pl[8384]: 1AALbHB8009400: MDLOG,1AALbHB8009400,mail_in,,,<netdev-owner at vger.kernel.org>,<philipp_subx at redfish-solutions.com>,[af_unix]  95e381b609: WARNING:possible_recursive_locking_detected
>>>> Nov 10 14:43:38 localhost mimedefang[1258]: 1AALbHB8009400: smfi_addheader returned MI_FAILURE
>>>> 
>>>> Looking through the logs, this happens over and over, and only with the delivery of this one message.  Since it can't be delivered for some reason, I looked it up on MARC:
>>>> 
>>>> https://marc.info/?l=linux-netdev&m=163652637632433&w=2
>>>> 
>>>> Anyone have an idea what's going on?  Is there a timeout I need to increase?
>>>> 
>>> you are hitting R=2m timeout while milter is sending data to mimedefang,
>>> this may happen when some code inside mimedefang.pl times out for a
>>> reason (antispam, antivirus ?).
>>> The code that triggers the problem may be near a call to
>>> action_add_header or action_change_header in your mimedefang-filter.
>> 
>> 
>> Why is it the R=2m timeout and not the E=10m timeout?
>> 
> because the timeout did not hit in filter_end but it was a timeout
> generated by something else (SpamAssassin in this case)

In our case we enable the SpamAssassin feature and it gets called from within filter_end().

> 
>> I took the message, copied it to a flat file on the mail server, and did a test:
>> 
>> % spamassassin -t < /tmp/test.eml
>> 
>> Content analysis details:   (-2.3 points, 5.0 required)
>> 
>> pts rule name              description
>> ---- ---------------------- --------------------------------------------------
>> -2.3 RCVD_IN_DNSWL_MED      RBL: Sender listed at https://www.dnswl.org/,
>>                            medium trust
>>                            [134.134.136.100 listed in list.dnswl.org]
>> 0.0 SPF_HELO_NONE          SPF: HELO does not publish an SPF Record
>> 0.0 TIME_LIMIT_EXCEEDED    Exceeded time limit / deadline
>> 
>> 
>> real	6m37.324s
>> user	0m6.569s
>> sys	0m0.250s
>> % 
>> 
>> Which seems like a really long time to run over the message.
>> 
>> This is a 2 core VM running on a 2.3GHz Xeon-D with Qemu/KVM.  I'd think that spamassassin would be quicker than that for a barely 400K message...
>> 
>> I must have some rules that are painfully expensive.  Any suggestions on which ones to watch out for?
>> 
>> I'm guessing the 60 or so "body" or "rawbody" rules are killing me...
>> 
>> Nope, just checked.  Commented about half of them out (that haven't had hits in 5 years or more) and it took almost exactly the same amount of time...
>> 
> you can run "spamassassin -D rules -t <file.eml" to have an idea of
> which rule takes that much.

Okay, seeing this:

...
Nov 12 11:43:37.936 [36367] dbg: rules: ran eval rule __UPPERCASE_25_50 ======> got hit (1)
Nov 12 11:45:38.048 [36367] dbg: rules: ran eval rule __ANY_TEXT_ATTACH_DOC ======> got hit (1)
...
Nov 12 11:45:38.063 [36367] dbg: rules: ran eval rule __ANY_TEXT_ATTACH ======> got hit (1)
Nov 12 11:49:58.565 [36367] info: check: exceeded time limit in Mail::SpamAssassin::Plugin::Check::_eval_tests_type11_pri0_set1, skipping further tests

Wait, what???  Why is this taking 4:30s to execute???

And how to dig into this further?  Googling the error message doesn't return much that's useful...

> 
> 
>> 
>> 
>>> 
>>>> Looking at:
>>>> 
>>>> Xmimedefang, S=unix:/var/spool/MIMEDefang/mimedefang.sock, F=T, T=S:2m;R:2m;E:10m
>>>> 
>>>> That looks like plenty...  
>>>> 
>>>> Other than that, everything seems to be working fine (well, I did have to change the $qid variable to filter_relay() and filter_helo() as that changed, but that was relatively minor).
>>>> 
>>>> BTW: who now owns the direction of development of MimeDefang?  Who is the designer-in-chief?
>>>> 
>>> MIMEDefang development now happens on https://github.com/The-McGrail-Foundation/MIMEDefang
>>> You can find some info about MIMEDefang project management at https://mimedefang.org/mimedefang-project-charter/
>>> 
>>> Giovanni
>> 
>> 
>> Okay, thanks.  I had suggested to Dianne some time ago that we include extra functionality (like DKIM checking, etc.) but leave the invocation commented out, and she was opposed to that because it cluttered the code.
>> 
>> I don't see it that way, and the time to parse code that doesn't get executed seems to be negligible in Perl, especially if the same instance gets run 300 times before being terminated...
>> 
> I am trying to split mimedefang.pl code into modules without breaking
> current mimedefang-filter code, this way it will be possible to load
> some more code (like DKIM checking) only if a user needs it.

I've done some customization that might be generically useful that I'd like to contribute:

* we pay attention to $SendmailMacros{daemon_port} and only apply certain checks when the port is 25... for internal clients using 587 w/ authentication, we skip certain rules;

* skip running a scanner on email sent to abuse at ourdomain.com;

* if we find a virus, we elide the attachment and replace it with a warning saying it was deleted;

* certain types of spam/phishing get converted into ARF complaints and put into a drafts folder;

* skip running SpamAssassin if the submitting host is 127.0.0.1;

* skip running SpamAssassin if the server port isn't 25;

* in filter_relay(), allow blocking based on:

  + country-code from a GeoIP database;

  + ISP from a GeoIP database;

  + country-code TLD;

* log connections with client IP address and client port (many ISP's won't accept reports without the client port number, since they can't trace it through NATting without it);

* in filter_helo(), allow blocking on:

  + blacklist of client name in HELO message;

  + block hosts lying about their [n.n.n.n] in HELO messages;

  + blacklist of TLD's from rDNS on client IP;

  + blacklist of client IP in CIDR list;

  + spamhaus.org RBL blacklisting (not for 127.0.0.10 or 127.0.0.11);

  + block a HELO n.n.n.n that isn't enclosed in brackets, per RFC-2821;

  + block a HELO [n.n.n.n] that isn't a valid dotted quad;

  + block a HELO [n.n.n.n] that claims to be any of my addresses;

  + block a HELO [n.n.n.n] that disagrees with the actual $hostip;

  + block a HELO that's "localhost", "localhost.localdomain", or any of my own FQDNs;

  + block HELO names from a list of strings known to be baked into malware/ratware;

  + block HELO names that aren't FQDN's (i.e. hostname only);

  + block external hosts whose IP address doesn't have a matching rDNS record to their greeting;

* in filter_sender(), block based on a blacklist of domain names;

* in filter_recipient(), block based on:

  + a list of falsified addresses that harvesters padded their lists with (otherwise the Postmaster mailbox fills up with bounces);

  + a pattern to match Message-Id's that have been mistakenly harvested as addresses (WTH?);

All of our IP handling is IPv4-based, since our ISP doesn't offer IPv6...  some assembly required.

> 
> 
> 
>> Kevin: Maybe we could revisit the issue under different direction?
>> 
>> -Philip