On 2021-11-15 at 18:08:20 UTC-0500 (Mon, 15 Nov 2021 16:08:20 -0700)
Philip Prindeville <philipp_s...@redfish-solutions.com>
is rumored to have said:
On Nov 12, 2021, at 8:49 PM, John Hardin <jhar...@impsec.org> wrote:
On Fri, 12 Nov 2021, Philip Prindeville wrote:
I got the message, saved it to a flat file, and ran "spamassassin -t
-D rules < netdev.eml" and saw:
...
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
...
Am I correct that __ANY_TEXT_ATTACH alone took 4:30s?
"ran ... got hit" is past tense. And it needs to complete the rule to
know whether it got a hit.
11:45:38.048 -> 11:45:38.063 = less than 20 msec.
The next rule, whatever that was, is the one that timed out after
4m20s.
Ah, the rule _eval_tests_type11_pri0_set1() took 4:20.
Why can't I even find the rule?
That "rule" is actually a subroutine that is assembled and named at
runtime in M:SA:Check from set 1 (probably the only set) of the "body
eval" (type 11) rules running at priority 0.
Which suggests a tough bit of troubleshooting.
Could there be rules that *aren't* matching but are taking a while?
It's timing out on a rule that's running away. The timeout triggers
before "hit/no hit" is known.
What would be helpful here would be logging of when a rule *starts*
evaluation. Normally that would be painful, but for tracking a
runaway it would be useful. Perhaps I can code up something to
capture that and log it on a timeout...
Whenever a rule gets started, you could save the name and start time,
and then burp that during timeout handling, right?
I like that idea. I have no idea how feasible it is.
--
Bill Cole
b...@scconsult.com or billc...@apache.org
(AKA @grumpybozo and many *@billmail.scconsult.com addresses)
Not Currently Available For Hire
