You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@spamassassin.apache.org by Guy Waugh <gw...@scu.edu.au> on 2006/06/08 02:23:37 UTC
SA 3.1.1 sometimes takes a long time...
Hi folks,
I'm pretty new to SpamAssassin. I have two MXes running sendmail 8.13.6,
smtp-vilter 1.2.4, SA 3.1.1 and clamav 0.88. Sendmail uses smtp-vilter
as a milter, and smtp-vilter calls clamd and spamd to scan incoming
messages at the point of delivery.
For most messages, it works fine - clamd does the virus scanning in a
flash, and SA takes between 0.1 seconds and 3 seconds to do its job.
However, for some emails, the SA scan goes over the 20 second timeout
that we currently have defined (in /etc/smtp-vilter/spamd.conf). When
this happens, sendmail tells the sender "451 4.3.2 - Please try again
later".
I turned on SA debugging for a while, and when the "451 4.3.2" error
happens, I see this in the logs:
Jun 7 15:36:56 server sendmail[573]: k575alO4000573:
from=<si...@lpnet.com.br>, size=10049, class=0, nrcpts=1,
msgid=<33...@lpnet.com.br>, proto=SMTP, daemon=MTA,
relay=[213.85.143.136]
Jun 7 15:36:56 server sendmail[573]: k575alO4000573: Milter add:
header: X-SMTP-Vilter-Version: 1.2.4
Jun 7 05:36:56 server smtp-vilter[527]: message contains no virus
Jun 7 15:36:56 server sendmail[573]: k575alO4000573: Milter add:
header: X-SMTP-Vilter-Virus-Backend: clamd
Jun 7 15:36:56 server sendmail[573]: k575alO4000573: Milter add:
header: X-SMTP-Vilter-Status: clean
Jun 7 15:36:56 server sendmail[573]: k575alO4000573: Milter add:
header: X-SMTP-Vilter-clamd-Virus-Status: clean
Jun 7 15:36:56 server spamd[484]: spamd: connection from
localhost.localdomain [127.0.0.1] at port 53693
Jun 7 15:36:56 server spamd[484]: spamd: checking message
<33...@lpnet.com.br> for (unknown):508
Jun 7 15:36:56 server spamd[484]: bayes: tie-ing to DB file R/O
/var/vscan/.spamassassin/bayes_toks
Jun 7 15:36:56 server spamd[484]: bayes: tie-ing to DB file R/O
/var/vscan/.spamassassin/bayes_seen
Jun 7 15:36:56 server spamd[484]: bayes: found bayes db version 3
Jun 7 15:36:56 server spamd[484]: bayes: DB journal sync: last sync:
1149658532
Jun 7 15:36:57 server spamd[484]: bayes: DB journal sync: last sync:
1149658532
Jun 7 15:36:57 server spamd[484]: bayes: corpus size: nspam = 88503,
nham = 231793
Jun 7 15:36:57 server spamd[484]: bayes: header tokens for *F =
"U*silviooleg D*lpnet.com.br D*com.br D*br"
Jun 7 15:36:57 server spamd[484]: bayes: header tokens for *R =
"U*silviooleg D*lpnet.com.br D*com.br D*br"
Jun 7 15:36:57 server spamd[484]: bayes: header tokens for *M = "
333694818070 166676502833 lpnet com br "
(then 20-30 more bayes token lines, then...)
Jun 7 15:36:57 server spamd[484]: bayes: score = 0.99938356891068
Jun 7 15:36:57 server spamd[484]: bayes: DB journal sync: last sync:
1149658532
Jun 7 15:36:57 server spamd[484]: bayes: untie-ing
Jun 7 15:36:57 server spamd[484]: bayes: untie-ing db_toks
Jun 7 15:36:57 server spamd[484]: bayes: untie-ing db_seen
(then this:)
Jun 7 05:37:16 server smtp-vilter[527]: spamd: lost header - no
response to CHECK cmd
Jun 7 05:37:16 server smtp-vilter[527]: error during spam scan of file
tmp/vilter.XXXXzJ7UnO
Jun 7 05:37:16 server smtp-vilter[527]: temporarily failing message
Jun 7 15:37:16 server sendmail[573]: k575alO4000573: Milter: data,
reject=451 4.3.2 Please try again later
Jun 7 15:37:16 server sendmail[573]: k575alO4000573:
to=<au...@chec.scu.edu.au>, delay=00:00:21, pri=40049, stat=Please
try again later
(which happens when the 20 second timeout is reached. Then this:)
Jun 7 15:37:21 server spamd[484]: learn: auto-learn: currently using
scoreset 3, recomputing score based on scoreset 1
Jun 7 15:37:21 server spamd[484]: learn: auto-learn: message score:
35.038, computed score for autolearn: 23.6
Jun 7 15:37:21 server spamd[484]: learn: auto-learn? ham=0.1, spam=12,
body-points=22.51, head-points=7.541, learned-points=3.5
Jun 7 15:37:21 server spamd[484]: learn: auto-learn? yes, spam (23.6 > 12)
Jun 7 15:37:21 server spamd[484]: learn: initializing learner
Jun 7 15:37:21 server spamd[484]: learn: learning spam
Jun 7 15:37:22 server spamd[484]: bayes: tie-ing to DB file R/W
/var/vscan/.spamassassin/bayes_toks
Jun 7 15:37:22 server spamd[484]: bayes: tie-ing to DB file R/W
/var/vscan/.spamassassin/bayes_seen
Jun 7 15:37:22 server spamd[484]: bayes: found bayes db version 3
Jun 7 15:37:22 server spamd[484]: bayes: header tokens for *F =
"U*silviooleg D*lpnet.com.br D*com.br D*br"
Jun 7 15:37:22 server spamd[484]: bayes: header tokens for *R =
"U*silviooleg D*lpnet.com.br D*com.br D*br"
Jun 7 15:37:22 server spamd[484]: bayes: header tokens for *M = "
333694818070 166676502833 lpnet com br "
Jun 7 15:37:22 server spamd[484]: bayes: header tokens for To =
"U*auniac10 D*chec.scu.edu.au D*scu.edu.au D*edu.au D*au"
Jun 7 15:37:22 server spamd[484]: bayes: header tokens for MIME-Version
= " "
Jun 7 15:37:22 server spamd[484]: bayes: header tokens for *c = "
Multipart/related; type="multipart/alternative"; ------------ HHHHHHHH
. HHHHHHHH"
Jun 7 15:37:22 server spamd[484]: bayes: header tokens for *RT = " "
Jun 7 15:37:22 server spamd[484]: bayes: header tokens for *RU = " [
ip=213.85.143.136 rdns= helo= by=server ident= envfrom= intl=0 id= auth=
] [ ip=196.93.229.61 rdns=linx helo=linx by=bbs.lpnet.com.br ident=
envfrom= intl=0 id= auth= ]"
Jun 7 15:37:22 server spamd[484]: bayes: header tokens for *r = "
linx (196.93.229 ip*196.93.229.61 ) by bbs.lpnet.com.br
<au...@chec.scu.edu.au>; "
Jun 7 15:37:22 server spamd[484]: bayes: header tokens for *r = "
linx (196.93.229 ip*196.93.229.61 ) by bbs.lpnet.com.br
<au...@chec.scu.edu.au>; bbs.lpnet.com.br by 213.85.143
ip*213.85.143.136 (8.9.3/8.9.3) <au...@chec.scu.edu.au>; "
Jun 7 15:37:22 server spamd[484]: bayes: learned
'22a7b772407e21c63185408ad9034a9cf7c9e98f@sa_generated', atime: 1149658639
Jun 7 15:37:22 server spamd[484]: bayes: untie-ing
Jun 7 15:37:22 server spamd[484]: bayes: untie-ing db_toks
Jun 7 15:37:22 server spamd[484]: bayes: untie-ing db_seen
Jun 7 15:37:22 server spamd[484]: bayes: files locked, now unlocking lock
Jun 7 15:37:22 server spamd[484]: learn: initializing learner
Jun 7 15:37:22 server spamd[484]: spamd: identified spam (35.0/8.0) for
(unknown):508 in 25.1 seconds, 10287 bytes.
Jun 7 15:37:22 server spamd[484]: spamd: result: Y 35 -
BAYES_99,EXTRA_MPART_TYPE,HTML_40_50,HTML_IMAGE_ONLY_04,HTML_MESSAGE,HTML_SHORT_LINK_IMG_1,MIME_HTML_MOSTLY,RCVD_IN_DSBL,RCVD_IN_WHOIS_BOGONS,RCVD_IN_XBL,UNPARSEABLE_RELAY,URIBL_JP_SURBL,URIBL_OB_SURBL,URIBL_SBL,URIBL_SC_SURBL,URIBL_WS_SURBL
scantime=25.1,size=10287,user=(unknown),uid=508,required_score=8.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=53693,mid=<33...@lpnet.com.br>,bayes=0.99938356891068,autolearn=spam
So, I have a few questions:
* Anyone know why there would be such a gap between SA scanning for spam
(up to 15:36:57 in the example above) and learning spam/ham (from 15:37:21)?
* The Bayes database is in Berkeley DB format... would having it in an
RDBMS help, perhaps?
* I only turned on SA debugging for bayes and learn to get the above log
entries. Are bayes, learn and dns the only debugging flags available?
Maybe next time I should turn on dns debugging as well?
* One thing I may want to do is configure the email server to only scan
for spam for messages coming from the Internet. smtp-vilter does not
seem to have this functionality, but it appears a few other milter
packages do (amavisd-new, MIMEDefang?). Any thoughts on changing from
smtp-vilter to one of these other milter packages? Difficulties, traps
etc.? Seems like it should be pretty straightforward...
* Any other comments or thoughts?
Thanks in advance,
Guy.
Re: SA 3.1.1 sometimes takes a long time...
Posted by Theo Van Dinter <fe...@apache.org>.
On Thu, Jun 08, 2006 at 01:51:22PM +1000, Guy Waugh wrote:
> Jun 8 13:21:07 server spamd[22945]: locker: safe_lock: trying to get
> lock on /var/vscan/spamassassin/auto-whitelist with 11 retries
If /var/vscan/spamassassin is on a local filesystem, try switching the lock
method to flock. It tends to suck less. ;)
> * Will there be locking issues if I put all the Berkeley DB stuff into,
> say, MySQL?
I don't believe so.
--
Randomly Generated Tagline:
See you in hell, candy boys!!
-- Homer Simpson
Homer Badman
Re: SA 3.1.1 sometimes takes a long time...
Posted by Guy Waugh <gw...@scu.edu.au>.
Daryl C. W. O'Shea wrote:
> On 6/7/2006 9:58 PM, Matt Kettler wrote:
>
>> Guy Waugh wrote:
>
>
>>> * I only turned on SA debugging for bayes and learn to get the above
>>> log entries. Are bayes, learn and dns the only debugging flags
>>> available? Maybe next time I should turn on dns debugging as well?
>>
>>
>> I know of at least one other... "all"
>>
>> message, config, check, plugin and rules also appear to be other working
>> options, but I've not tested them. There's probably more.. grep the code
>> for "dbg".. the text preceding the colon is the debug category needed to
>> log it (unless all is enabled)
>
>
>
> http://wiki.apache.org/spamassassin/DebugChannels
Thanks guys... should have seen that.
OK, I've turned on multitudinous debugging, and it seems to be
struggling with file locking on the 'auto-whitelist' file. When the "451
4.3.2" error happens, there are lots of these messages around it in the
logfile:
Jun 8 13:21:05 server spamd[22947]: locker: safe_lock: trying to get
lock on /var/vscan/spamassassin/auto-whitelist with 6 retries
Jun 8 13:21:05 server spamd[22941]: locker: safe_lock: trying to get
lock on /var/vscan/spamassassin/auto-whitelist with 15 retries
Jun 8 13:21:06 server spamd[22943]: locker: safe_lock: trying to get
lock on /var/vscan/spamassassin/auto-whitelist with 13 retries
Jun 8 13:21:06 server spamd[22942]: locker: safe_lock: trying to get
lock on /var/vscan/spamassassin/auto-whitelist with 13 retries
Jun 8 13:21:06 server spamd[22945]: locker: safe_lock: trying to get
lock on /var/vscan/spamassassin/auto-whitelist with 10 retries
Jun 8 13:21:06 server spamd[22947]: locker: safe_lock: trying to get
lock on /var/vscan/spamassassin/auto-whitelist with 7 retries
Jun 8 13:21:06 server spamd[22944]: locker: safe_lock: trying to get
lock on /var/vscan/spamassassin/auto-whitelist with 10 retries
Jun 8 13:21:06 server spamd[22946]: locker: safe_lock: trying to get
lock on /var/vscan/spamassassin/auto-whitelist with 6 retries
Jun 8 13:21:06 server spamd[22941]: locker: safe_lock: trying to get
lock on /var/vscan/spamassassin/auto-whitelist with 16 retries
Jun 8 13:21:06 server spamd[22943]: locker: safe_lock: trying to get
lock on /var/vscan/spamassassin/auto-whitelist with 14 retries
Jun 8 13:21:07 server spamd[22940]: locker: safe_lock: trying to get
lock on /var/vscan/spamassassin/auto-whitelist with 17 retries
Jun 8 13:21:07 server spamd[22947]: locker: safe_lock: trying to get
lock on /var/vscan/spamassassin/auto-whitelist with 8 retries
Jun 8 13:21:07 server spamd[22941]: locker: safe_lock: trying to get
lock on /var/vscan/spamassassin/auto-whitelist with 17 retries
Jun 8 13:21:07 server spamd[22940]: locker: safe_lock: trying to get
lock on /var/vscan/spamassassin/auto-whitelist with 18 retries
Jun 8 13:21:07 server spamd[22945]: locker: safe_lock: trying to get
lock on /var/vscan/spamassassin/auto-whitelist with 11 retries
OK, so... the auto-whitelist file is currently a Berkeley DB file. Does
anyone know:
* Will there be locking issues if I put all the Berkeley DB stuff into,
say, MySQL?
* Is there something else I can do to try to fix this, without going SQL?
Thanks again,
Guy.
Re: SA 3.1.1 sometimes takes a long time...
Posted by "Daryl C. W. O'Shea" <sp...@dostech.ca>.
On 6/7/2006 9:58 PM, Matt Kettler wrote:
> Guy Waugh wrote:
>>* I only turned on SA debugging for bayes and learn to get the above
>>log entries. Are bayes, learn and dns the only debugging flags
>>available? Maybe next time I should turn on dns debugging as well?
>
> I know of at least one other... "all"
>
> message, config, check, plugin and rules also appear to be other working
> options, but I've not tested them. There's probably more.. grep the code
> for "dbg".. the text preceding the colon is the debug category needed to
> log it (unless all is enabled)
http://wiki.apache.org/spamassassin/DebugChannels
Re: SA 3.1.1 sometimes takes a long time...
Posted by Matt Kettler <mk...@comcast.net>.
Guy Waugh wrote:
> Hi folks,
>
> I'm pretty new to SpamAssassin. I have two MXes running sendmail
> 8.13.6, smtp-vilter 1.2.4, SA 3.1.1 and clamav 0.88. Sendmail uses
> smtp-vilter as a milter, and smtp-vilter calls clamd and spamd to scan
> incoming messages at the point of delivery.
>
> For most messages, it works fine - clamd does the virus scanning in a
> flash, and SA takes between 0.1 seconds and 3 seconds to do its job.
>
> However, for some emails, the SA scan goes over the 20 second timeout
> that we currently have defined (in /etc/smtp-vilter/spamd.conf). When
> this happens, sendmail tells the sender "451 4.3.2 - Please try again
> later".
>
20 seconds is *WAY* to short.. By default, SA will attempt to
oportunistically perform bayes database maintenance (expiring old
tokens, merging journals, etc).. this can take several minutes at a
time, but doesn't happen often (every 12 hrs at most, I think...)
> So, I have a few questions:
>
> * Anyone know why there would be such a gap between SA scanning for
> spam (up to 15:36:57 in the example above) and learning spam/ham (from
> 15:37:21)?
Waiting for a write lock.. turning on bayes_learn_to_journal helps this
much, but does make the maintenance runs slightly longer. It also
causes "lag" in that your learning is not made live until a journal sync
occurs.
>
> * The Bayes database is in Berkeley DB format... would having it in an
> RDBMS help, perhaps?
Using SQL is the perfered method, and generally speaking much faster.
SDBM is another option, but it's not 100% bug free when I last tested
the conversion tools.
>
> * I only turned on SA debugging for bayes and learn to get the above
> log entries. Are bayes, learn and dns the only debugging flags
> available? Maybe next time I should turn on dns debugging as well?
I know of at least one other... "all"
message, config, check, plugin and rules also appear to be other working
options, but I've not tested them. There's probably more.. grep the code
for "dbg".. the text preceding the colon is the debug category needed to
log it (unless all is enabled)
i.e:
dbg("plugin: loading $package from $path");
requires all or plugin.
>
> * One thing I may want to do is configure the email server to only
> scan for spam for messages coming from the Internet. smtp-vilter does
> not seem to have this functionality, but it appears a few other milter
> packages do (amavisd-new, MIMEDefang?). Any thoughts on changing from
> smtp-vilter to one of these other milter packages? Difficulties, traps
> etc.? Seems like it should be pretty straightforward...
I'm not a milter user, can't comment (I use mailscanner)
>
> * Any other comments or thoughts?
>
> Thanks in advance,
> Guy.
>
>