[Mimedefang] New errors following update to 2.85

[Bill Cole]

On 2021-11-12 at 15:36:51 UTC-0500 (Fri, 12 Nov 2021 13:36:51 -0700)
Philip Prindeville via MIMEDefang <mimedefang at lists.mimedefang.org>
is rumored to have said:

[...]

> 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???

Because some rule that was in the compiled ruleset of the moment 
somewhere after __ANY_TEXT_ATTACH went insane. The most common cause of 
such insanity is a regex (i.e. body, rawbody, header or full) rule which 
causes O(n!) or similarly complex behavior, usually because it has to 
backtrack frequently when scanning for a match. The root cause is 
usually a greedy '.*' or '.+' in a rule where the initial '.' might 
match in many places that the full pattern doesn't match. It is a good 
idea to anchor rule patterns when possible, use {min,max} ranges where 
possible instead of * or +, and use specific character classes rather 
than '.' where possible.  A runaway regex in a SA rule usually requires 
the combination of a vulnerable rule with an uncommon sort of message.

> And how to dig into this further?

Unfortunately, we do not know which rule caused the problem because of 
how the rules are loaded and compiled. We only know what rules had hits 
before the one that caused the timeout. In this case we got a completely 
bizarre function name for where the bad rule lives 
(_eval_tests_type11_pri0_set1) which means that it is one of the many 
"body eval" rules that are registered . The order of rules should be the 
same between runs of spamassassin or spamd scanner processes using the 
same rules & config, but not so much between different systems. One 
identification trick is to run a similar but non-hanging message through 
a '-D all' scan and looking for what matches in the good message right 
after the last match in the bad message. Another approach is to 
temporarily raise the time_limit setting to something extreme to see if 
you can work through it and possibly get a hit on the bad rule 
(unlikely.) The more sure method is a bisecting approach, truncating the 
bad message at various lengths to find where the problematic content is 
in the message body. You can also work by eliminating/including rules 
(or whole files of rules such as local.cf) to find the problematic rule.

> Googling the error message doesn't return much that's useful...

Yeah, it won't. The method name "_eval_tests_type11_pri0_set1" 
identifies a block of code assembled at runtime from a subset (priority 
0, set 1) of the current "body eval" rules (type 11.)  It's not a 
function that exists in the SA code on disk and the only way to stumble 
across it is if SA breaks loudly while that ephemeral code runs (e.g. by 
timing out.)


-- 
Bill Cole
bill at scconsult.com or billcole at apache.org
(AKA @grumpybozo and many *@billmail.scconsult.com addresses)
Not Currently Available For Hire