Re: Pathological messages causing long scan times
John Hardin, 2010-03-21 01:01: The offending rule is FILL_THIS_FORM_LONG from 72_active.cf. I'll look into it. Fix is in local masscheck testing. Fix committed. But not online yet? At least not with 3.3.1's sa-update, it still takes nearly 5 minutes to scan this message (last hit is TIME_LIMIT_EXCEEDED). Btw, shouldn't --timeout-child on spamd limit the time spent? I have set it to 30, but that does not seem to work.
Re: Pathological messages causing long scan times
On Monday March 22 2010 11:49:22 Jakob Hirsch wrote: Btw, shouldn't --timeout-child on spamd limit the time spent? I have set it to 30, but that does not seem to work. The signal handling in 3.3 is left at perl default of 'safe handling', which means that alarm signal cannot interrupt evaluation of a single regular expression, which is what is happening here. If there is a series of slow rules, or some other non-CPU bound slow rule, the time limit works alright. It is possible to run SA with unsafe signal handling by setting a PERL_SIGNALS environment variable to the string 'unsafe'. This was considered too risky for the distribution, but you can do it if runaway rules occur frequently and perl crashes rarely :- Dynamically switching between two modes was considered to be implemented in module Mail::SpamAssassin::Timeout, but didn't work as desired, it needs more investigation. Mark
Re: Pathological messages causing long scan times
On Thu, 18 Mar 2010, John Hardin wrote: On Thu, 18 Mar 2010, John Hardin wrote: On Fri, 19 Mar 2010, Mark Martinec wrote: The offending rule is FILL_THIS_FORM_LONG from 72_active.cf. I'll look into it. Fix is in local masscheck testing. Fix committed. -- John Hardin KA7OHZhttp://www.impsec.org/~jhardin/ jhar...@impsec.orgFALaholic #11174 pgpk -a jhar...@impsec.org key: 0xB8732E79 -- 2D8C 34F4 6411 F507 136C AF76 D822 E6E6 B873 2E79 --- An AR-15 in civilian hands used to defend a home or business: a High Velocity Assault Weapon with High Capacity Magazines An AR-15 in Law Enforcement Officer hands used to murder six kids: a Police-Style Patrol Rifle --- 162 days since President Obama won the Nobel Not George W. Bush prize
Re: Pathological messages causing long scan times
Gary Smith wrote: I'm not seeing your 130 sec CPU issue on my end. Are as mentioned by Matt, are you running into some DNS issue? These are stock rule + other house rules in place. I'm not getting any type of DNS hit, this might because you modified the headers. Either way, 5 seconds for me. Wow. O_o What version of SA, and what version of the stock rules? I don't regularly update everything, but I *do* update JM's sought rules daily via cron, and with local rules distributed via sa-update I usually do a complete sa-update on all the rules channels (scripted) a couple of times a week. I'm all but certain it's not a DNS issue; even default timeouts for DNS should give up and return after ~15 seconds. And that wouldn't cause a CPU core to be pegged for the entire time. -kgd
Pathological messages causing long scan times
Every so often I get nudged to check into a message stuck on one of our inbound MXes. So far, every one of them has been spam, but a few have cause some odd behaviour with spamc/spamd. Here's one pretty much guaranteed to peg a CPU core for ~130 seconds (or more): http://pastebin.com/2ssy2YEk Is there a way to determine which specific rule is likely to be causing the excessive scan times? I've already tried flipping rulesets around and adding some of the timing header report bits; the slowdowns so far have always happened with the stock rules, and the timing report doesn't break down nearly far enough. -kgd
Re: Pathological messages causing long scan times
On 3/18/2010 5:15 PM, Kris Deugau wrote: Here's one pretty much guaranteed to peg a CPU core for ~130 seconds (or more): http://pastebin.com/2ssy2YEk Interesting. I see the same thing as you on that message. There's a two-minute gap between these two debug lines: rules: ran body rule __F_LARGE_MONEY_2 == got hit: 00 million rules: ran body rule __SEEK_FRAUD_JFMEJI == got hit: Insurance premium and Clearance Certificate Fee One CPU is mostly pegged during that period. Thinking it had something to do with JM_SOUGHT_FRAUD_3, I removed that and __SEEK_FRAUD_JFMEJI, with no improvement. I don't know where else to look, aside from trial-and-error disabling of rules.
Re: Pathological messages causing long scan times
On Thu, Mar 18, 2010 at 21:56, Matt Garretson ma...@assembly.state.ny.us wrote: On 3/18/2010 5:15 PM, Kris Deugau wrote: Here's one pretty much guaranteed to peg a CPU core for ~130 seconds (or more): http://pastebin.com/2ssy2YEk Interesting. I see the same thing as you on that message. There's a two-minute gap between these two debug lines: rules: ran body rule __F_LARGE_MONEY_2 == got hit: 00 million rules: ran body rule __SEEK_FRAUD_JFMEJI == got hit: Insurance premium and Clearance Certificate Fee One CPU is mostly pegged during that period. Thinking it had something to do with JM_SOUGHT_FRAUD_3, I removed that and __SEEK_FRAUD_JFMEJI, with no improvement. I don't know where else to look, aside from trial-and-error disabling of rules. binary search of the ruleset is the easiest way to find this. It's most often a rawbody rule. Please let us know which one it is, particularly if it's in the core ruleset rather than a third-party one... -- --j.
Re: Pathological messages causing long scan times
On 3/18/2010 5:56 PM, Matt Garretson wrote: On 3/18/2010 5:15 PM, Kris Deugau wrote: Here's one pretty much guaranteed to peg a CPU core for ~130 seconds (or http://pastebin.com/2ssy2YEk Interesting. I see the same thing as you on that message. There's a two-minute gap between these two debug lines: Looking in more detail at the debug output, I see this towards the end (after the delay): async: select found 2 responses ready (t.o.=0.0) async: completed in 120.380 s: URI-A, A:ns1.refactoring.lt. dns: providing a callback for id: 39923/147.36.61.92.zen.spamhaus.org/A/IN async: starting: URI-DNSBL, DNSBL:zen.spamhaus.org.:147.36.61.92 (timeout 15.0s, min 3.0s) async: completed in 120.380 s: URI-A, A:ns4.aleja.lt. dns: providing a callback for id: 34683/6.12.79.77.zen.spamhaus.org/A/IN async: starting: URI-DNSBL, DNSBL:zen.spamhaus.org.:6.12.79.77 (timeout 15.0s, min 3.0s) async: queries completed: 2, started: 2 async: queries active: URI-DNSBL=2 at Thu Mar 18 17:22:45 2010 dns: harvested completed queries It looks like a dns call (or two?) for URI-A took 120 seconds to return. Is that a mere coincdence, or could that be causing a spin of some sort? I can understand a delay caused by slow DNS, but consuming a core seems strange. -Matt
Re: Pathological messages causing long scan times
On 3/18/2010 6:06 PM, Matt Garretson wrote: It looks like a dns call (or two?) for URI-A took 120 seconds to return. Is that a mere coincdence, or could that be causing a spin of some sort? FWIW, strace shows spamassassin doing this about twice a second (with varying arguments) during the two-minute delay: brk(0x69df000) = 0x69df000 mremap(0x7fc9756db000, 1298432, 1302528, MREMAP_MAYMOVE) = 0x7fc9756db000 mremap(0x7fc9756db000, 1302528, 1306624, MREMAP_MAYMOVE) = 0x7fc9756db000 []
Re: Pathological messages causing long scan times
that's CPU-bound, no system calls = regexp matching. body, rawbody or full rules. On Thu, Mar 18, 2010 at 22:16, Matt Garretson ma...@assembly.state.ny.us wrote: On 3/18/2010 6:06 PM, Matt Garretson wrote: It looks like a dns call (or two?) for URI-A took 120 seconds to return. Is that a mere coincdence, or could that be causing a spin of some sort? FWIW, strace shows spamassassin doing this about twice a second (with varying arguments) during the two-minute delay: brk(0x69df000) = 0x69df000 mremap(0x7fc9756db000, 1298432, 1302528, MREMAP_MAYMOVE) = 0x7fc9756db000 mremap(0x7fc9756db000, 1302528, 1306624, MREMAP_MAYMOVE) = 0x7fc9756db000 [] -- --j.
RE: Pathological messages causing long scan times
Here's one pretty much guaranteed to peg a CPU core for ~130 seconds (or more): http://pastebin.com/2ssy2YEk I'm not seeing your 130 sec CPU issue on my end. Are as mentioned by Matt, are you running into some DNS issue? These are stock rule + other house rules in place. I'm not getting any type of DNS hit, this might because you modified the headers. Either way, 5 seconds for me. [r...@hsoakmsa01 ~]# time cat bad.msg | spamc -R -p -u filter 10.8/0.0 Spam detection software, running on the system hsoakmsa01.holdstead.local, has identified this incoming email as possible spam. The original message has been attached to this so you can view it (if it isn't spam) or label similar future email. If you have any questions, see the administrator of that system for details. Content preview: Attention Freind, How are you today? I pray this mail gets to you in a perfect health condition. My Name is Mrs Laura Pedro General Secretary Compensation Award House inconjunction with the online lottery organization.I have been waiting for you to contact me for your Confirmable Bank Draft worth $14.6,000.00 million United States Dollars which is still valid for payment, but I have not hear from you. [...] Content analysis details: (10.8 points, 0.0 required) pts rule name description -- -- 2.1 SUBJ_ALL_CAPS Subject is all capitals 1.5 MILLION_USDBODY: Talks about millions of dollars 0.0 BAYES_50 BODY: Bayesian spam probability is 40 to 60% [score: 0.5000] 1.2 ADVANCE_FEE_2 Appears to be advance fee fraud (Nigerian 419) 1.4 ADVANCE_FEE_3 Appears to be advance fee fraud (Nigerian 419) 0.8 MSOE_MID_WRONG_CASEMSOE_MID_WRONG_CASE 0.6 ADVANCE_FEE_4 Appears to be advance fee fraud (Nigerian 419) 3.1 FORGED_MUA_OUTLOOK Forged mail pretending to be from MS Outlook real0m5.038s user0m0.017s sys 0m0.061s
Re: Pathological messages causing long scan times
On Fri, 19 Mar 2010, Mark Martinec wrote: On Thursday March 18 2010 23:18:56 Justin Mason wrote: that's CPU-bound, no system calls = regexp matching. body, rawbody or full rules. Yes, it's terrible, takes 4 minutes here (SA 3.3, perl 5.10.1). The offending rule is FILL_THIS_FORM_LONG from 72_active.cf. I'll look into it. -- John Hardin KA7OHZhttp://www.impsec.org/~jhardin/ jhar...@impsec.orgFALaholic #11174 pgpk -a jhar...@impsec.org key: 0xB8732E79 -- 2D8C 34F4 6411 F507 136C AF76 D822 E6E6 B873 2E79 --- Judicial Activism (n): interpreting the Constitution to grant the government powers that are popularly felt to be needed but that are not explicitly provided for therein (common definition); interpreting the Constitution as it is written (Brady definition) --- 160 days since President Obama won the Nobel Not George W. Bush prize
Re: Pathological messages causing long scan times
On Thu, 18 Mar 2010, John Hardin wrote: On Fri, 19 Mar 2010, Mark Martinec wrote: On Thursday March 18 2010 23:18:56 Justin Mason wrote: that's CPU-bound, no system calls = regexp matching. body, rawbody or full rules. Yes, it's terrible, takes 4 minutes here (SA 3.3, perl 5.10.1). The offending rule is FILL_THIS_FORM_LONG from 72_active.cf. I'll look into it. Fix is in local masscheck testing. -- John Hardin KA7OHZhttp://www.impsec.org/~jhardin/ jhar...@impsec.orgFALaholic #11174 pgpk -a jhar...@impsec.org key: 0xB8732E79 -- 2D8C 34F4 6411 F507 136C AF76 D822 E6E6 B873 2E79 --- Judicial Activism (n): interpreting the Constitution to grant the government powers that are popularly felt to be needed but that are not explicitly provided for therein (common definition); interpreting the Constitution as it is written (Brady definition) --- 160 days since President Obama won the Nobel Not George W. Bush prize
