RE: [exim] Timeouts with Spamassassin 3.1.0 on particular ma…

Top Page
Delete this message
Reply to this message
Author: Martin Hepworth
Date:  
To: 'Geraint Edwards', 'Alan Thew'
CC: 'Exim List'
Subject: RE: [exim] Timeouts with Spamassassin 3.1.0 on particular mail items
Geraint

I'd --lint SA to make sure all the new plugins enable by default have their
proper perl dependencies

spamassassin -D --lint

Also check your not running ALL the RBLS as that can slow things down quite
a bit...


--
Martin Hepworth
Snr Systems Administrator
Solid State Logic
Tel: +44 (0)1865 842300

-----Original Message-----
From: exim-users-bounces@??? [mailto:exim-users-bounces@exim.org] On
Behalf Of Geraint Edwards
Sent: 10 October 2005 19:18
To: Alan Thew
Cc: Exim List
Subject: Re: [exim] Timeouts with Spamassassin 3.1.0 on particular mail
items

Only just upgraded, sorry for the delay...

Alan Thew <Alan.Thew@???> said
        (on Wed, Sep 28, 2005 at 02:36:31PM +0100):

> After upgrading to SA 3.1.0 we've seen a very few mails timeout every time


> they are offered to spamd.


We have exim-4.52 too (exim ports on FreeBSD 4 and 5). We're now
getting timeouts since upgrading to spamassassin 3.1.0. Didn't
notice these timeouts with 3.0.x (checked several months of logs,
too). It seems restricted to large e-mails here (we don't get so
many of these) - the following example is a 5.7MB spam mail.

Summary - we seem to be seeing two problems:

1) SA is taking over 2mins (or over 5mins, depending on load!)
    to process this mail, which seems excessive


2) exim seems to timeout waiting for spamd after 2mins (i.e. while
    in the first "warn ... spam = spamu:true" statement) but
    both exim and SA carry on(!), exim appearing to fall
    through to the next "spam = spamu:true" line (because of
    the "true"?) and starts *another* spamd on the message, so
    these concurrent spamd's (on the same message!) take even
    longer and after 5mins each they themselves "return" a
    timeout (but carry on to give a result to the log file!).


Bizarre. Potential DoS, too.

Here's an example:

# exigrep spamd /var/log/exim/mainlog
2005-10-10 00:27:19 1EOkWX-0007MO-EY spam acl condition: error reading from
spamd socket: Operation timed out
2005-10-10 00:27:19 1EOkWX-0007MO-EY H=in-mta [1.2.3.4] Warning: ACL "warn"
statement skipped: condition test deferred
2005-10-10 00:29:19 1EOkWX-0007MO-EY spam acl condition: error reading from
spamd socket: Operation timed out
2005-10-10 00:29:19 1EOkWX-0007MO-EY H=in-mta [1.2.3.4] Warning: ACL "warn"
statement skipped: condition test deferred
2005-10-10 00:31:19 1EOkWX-0007MO-EY spam acl condition: error reading from
spamd socket: Operation timed out
2005-10-10 00:31:19 1EOkWX-0007MO-EY H=in-mta [1.2.3.4] Warning: ACL "warn"
statement skipped: condition test deferred
2005-10-10 00:33:19 1EOkWX-0007MO-EY spam acl condition: error reading from
spamd socket: Operation timed out
2005-10-10 00:33:20 1EOkWX-0007MO-EY H=in-mta [1.2.3.4] F=<> temporarily
rejected after DATA

I get three set of errors from exim (from the 3 header-adding
"warn"s, I guess) - but each separated by 2mins...?

spamd's log (/var/log/maillog) - sorted by spamd session/PID:

Oct 10 00:25:19 me spamd[5049]: spamd: connection from localhost.mydom
[127.0.0.1] at port 63253
Oct 10 00:25:19 me spamd[5049]: spamd: using default config for spamu:
/home/spamu/user_prefs
Oct 10 00:25:22 me spamd[5049]: spamd: checking message
<20051008233052.12B6BEBE8E@in-mta> for spamu:2000
Oct 10 00:29:28 me spamd[5049]: spamd: identified spam (10.2/5.0) for
spamu:2000 in 249.0 seconds, 5741992 bytes.
Oct 10 00:29:28 me spamd[5049]: spamd: result: Y 10 -
ADVANCE_FEE_1,AWL,BAYES_00,DISGUISE_PORN_MUNDANE,DRUGS_PAIN,FUZZY_AMBIEN,FUZ
ZY_CPILL,FUZZY_MONEY,FUZZY_ROLEX,FUZZY_VLIUM,FUZZY_VPILL,FUZZY_XPILL,ML_MARK
ETING,NO_REAL_NAME,UNIQUE_WORDS,UPPERCASE_25_50
scantime=249.0,size=5741992,user=spamu,uid=2000,required_score=5.0,rhost=loc
alhost.mydom,raddr=127.0.0.1,rport=63253,mid=<20051008233052.12B6BEBE8E@in-m
ta>,bayes=0,autolearn=no

Oct 10 00:27:19 me spamd[5050]: spamd: connection from localhost.mydom
[127.0.0.1] at port 61575
Oct 10 00:27:19 me spamd[5050]: spamd: using default config for spamu:
/home/spamu/user_prefs
Oct 10 00:27:26 me spamd[5050]: spamd: checking message
<20051008233052.12B6BEBE8E@in-mta> for spamu:2000
Oct 10 00:32:20 me spamd[5050]: child processing timeout at
/usr/local/bin/spamd line 1085, <GEN48> line 74619.
Oct 10 00:32:21 me spamd[5050]: child processing timeout at
/usr/local/bin/spamd line 1085, <GEN48> line 74619.
Oct 10 00:36:16 me spamd[5050]: spamd: identified spam (10.2/5.0) for
spamu:2000 in 536.7 seconds, 5741992 bytes.
Oct 10 00:36:16 me spamd[5050]: spamd: result: Y 10 -
ADVANCE_FEE_1,AWL,BAYES_00,DISGUISE_PORN_MUNDANE,DRUGS_PAIN,FUZZY_AMBIEN,FUZ
ZY_CPILL,FUZZY_MONEY,FUZZY_ROLEX,FUZZY_VLIUM,FUZZY_VPILL,FUZZY_XPILL,ML_MARK
ETING,NO_REAL_NAME,UNIQUE_WORDS,UPPERCASE_25_50
scantime=536.7,size=5741992,user=spamu,uid=2000,required_score=5.0,rhost=loc
alhost.mydom,raddr=127.0.0.1,rport=61575,mid=<20051008233052.12B6BEBE8E@in-m
ta>,bayes=0,autolearn=no

Oct 10 00:29:30 me spamd[5049]: spamd: connection from localhost.mydom
[127.0.0.1] at port 58905
Oct 10 00:29:30 me spamd[5049]: spamd: using default config for spamu:
/home/spamu/user_prefs
Oct 10 00:29:33 me spamd[5049]: spamd: checking message
<20051008233052.12B6BEBE8E@in-mta> for spamu:2000
Oct 10 00:34:30 me spamd[5049]: child processing timeout at
/usr/local/bin/spamd line 1085, <GEN98> line 74619.
Oct 10 00:34:30 me spamd[5049]: child processing timeout at
/usr/local/bin/spamd line 1085, <GEN98> line 74619.
Oct 10 00:37:34 me spamd[5049]: spamd: identified spam (10.3/5.0) for
spamu:2000 in 484.7 seconds, 5741992 bytes.
Oct 10 00:37:34 me spamd[5049]: spamd: result: Y 10 -
ADVANCE_FEE_1,AWL,BAYES_00,DISGUISE_PORN_MUNDANE,DRUGS_PAIN,FUZZY_AMBIEN,FUZ
ZY_CPILL,FUZZY_MONEY,FUZZY_ROLEX,FUZZY_VLIUM,FUZZY_VPILL,FUZZY_XPILL,ML_MARK
ETING,NO_REAL_NAME,UNIQUE_WORDS,UPPERCASE_25_50
scantime=484.7,size=5741992,user=spamu,uid=2000,required_score=5.0,rhost=loc
alhost.mydom,raddr=127.0.0.1,rport=58905,mid=<20051008233052.12B6BEBE8E@in-m
ta>,bayes=0,autolearn=no


> We have perl 5.6.1 and had no problems with previous versions.


perl 5.8.7 here.

I suspect increasing SA's 5min timeout will not resolve exim's
apparent 2min timeout, so that might have to be increased too.
How one does this, I do not know - a quick look at the exim docs
didn't help (seems to default to 5mins, not 2mins!).

I'm currently focusing all my attention on configuring my exim to
accept the offending spam/e-mail so that I can debug this or be
able to pass it to someone else that will (an SA person, I hope!).

Hope this helps,

--
Geraint A. Edwards (aka "Gedge")
gedge@???

--
## List details at http://www.exim.org/mailman/listinfo/exim-users
## Exim details at http://www.exim.org/
## Please use the Wiki with this list - http://www.exim.org/eximwiki/


**********************************************************************

This email and any files transmitted with it are confidential and
intended solely for the use of the individual or entity to whom they
are addressed. If you have received this email in error please notify
the system manager.

This footnote confirms that this email message has been swept
for the presence of computer viruses and is believed to be clean.    


**********************************************************************