> 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?
>
>> 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?
>
> If you want to send me that message zipped up I can try it here with those
> changes and see if it's a base rule running away.
>
Sent out-of-band.
Doh. Forgot to zip it.
