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,FUZZY_CPILL,FUZZY_MONEY,FUZZY_ROLEX,FUZZY_VLIUM,FUZZY_VPILL,FUZZY_XPILL,ML_MARKETING,NO_REAL_NAME,UNIQUE_WORDS,UPPERCASE_25_50 scantime=249.0,size=5741992,user=spamu,uid=2000,required_score=5.0,rhost=localhost.mydom,raddr=127.0.0.1,rport=63253,mid=<20051008233052.12B6BEBE8E@in-mta>,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,FUZZY_CPILL,FUZZY_MONEY,FUZZY_ROLEX,FUZZY_VLIUM,FUZZY_VPILL,FUZZY_XPILL,ML_MARKETING,NO_REAL_NAME,UNIQUE_WORDS,UPPERCASE_25_50 scantime=536.7,size=5741992,user=spamu,uid=2000,required_score=5.0,rhost=localhost.mydom,raddr=127.0.0.1,rport=61575,mid=<20051008233052.12B6BEBE8E@in-mta>,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,FUZZY_CPILL,FUZZY_MONEY,FUZZY_ROLEX,FUZZY_VLIUM,FUZZY_VPILL,FUZZY_XPILL,ML_MARKETING,NO_REAL_NAME,UNIQUE_WORDS,UPPERCASE_25_50 scantime=484.7,size=5741992,user=spamu,uid=2000,required_score=5.0,rhost=localhost.mydom,raddr=127.0.0.1,rport=58905,mid=<20051008233052.12B6BEBE8E@in-mta>,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@???
