SA times out

[Kai Schaetzl]

Julian Field wrote on Wed, 02 Apr 2008 15:24:33 +0100:

> MailScanner --debug --debug-sa

Ok. 2 Findings. The output from spamassassin -D and the one from 
MailScanner is not exactly identical. There are portions where they almost 
completely match and there are other portions that appear in different 
order or are completely different. Is this to be expected?
I'm sure I'm using the same local config in /etc/mail/spamassassin for SA 
with and without MS.
[15949] dbg: config: using "/etc/mail/spamassassin" for site rules pre 
files

For instance one big difference is that MS does:

[15949] dbg: config: using "/usr/share/spamassassin" for sys rules pre 
files
[15949] dbg: config: using "/usr/share/spamassassin" for default rules dir
[15949] dbg: config: read file /usr/share/spamassassin/10_default_prefs.cf

while SA uses the new locations:

[16547] dbg: config: using "/var/lib/spamassassin/3.002004" for sys rules 
pre files
[16547] dbg: config: using "/var/lib/spamassassin/3.002004" for default 
rules dir
[16547] dbg: config: read file 
/var/lib/spamassassin/3.002004/70_sare_adult_cf_sare_sa-
update_dostech_net.cf

There are other things where it differs, this is the most troubling one, 
for me.

Then, later MS stops at this stage:

[15949] dbg: auto-whitelist: tie-ing to DB file of type DB_File R/W in 
/home/spamd/awl/auto-whitelist
[15949] dbg: auto-whitelist: db-based 
ignore at compiling.spamassassin.taint.org|ip=none scores 0/0
[15949] dbg: auto-whitelist: AWL active, pre-score: 3.053, autolearn 
score: 3.053, mean: undef, IP: undef
[15949] dbg: auto-whitelist: DB addr list: untie-ing and unlocking
[15949] dbg: auto-whitelist: DB addr list: file locked, breaking lock
[15949] dbg: locker: safe_unlock: unlocked /home/spamd/awl/auto-
whitelist.mutex
[15949] dbg: auto-whitelist: post auto-whitelist score: 3.053
[15949] dbg: rules: running body tests; score so far=3.053
[15949] dbg: rules: compiled body tests
[15949] dbg: rules: running uri tests; score so far=3.053
[15949] dbg: rules: compiled uri tests
[15949] dbg: rules: running rawbody tests; score so far=3.053
[15949] dbg: rules: compiled rawbody tests
[15949] dbg: rules: running full tests; score so far=3.053
[15949] dbg: rules: compiled full tests
[15949] dbg: rules: running meta tests; score so far=3.053
[15949] dbg: rules: compiled meta tests
[15949] dbg: check: is spam? score=3.053 required=5
[15949] dbg: check: 
tests=MISSING_DATE,MISSING_HEADERS,MISSING_SUBJECT,NO_RECEIVED,NO_RELAYS
[15949] dbg: check: 
subtests=__BOTNET_NOTRUST,__HAS_MSGID,__MISSING_REF,__MSGID_OK_DIGITS,__MS
GID_OK_HOST,__MSOE_MID_WRONG_CASE,__NONEMPTY_BODY,__SANE_MSGID,__UNUSABLE_
MSGID
[15949] dbg: bayes: untie-ing

here all activity drops (checked in top) to zero and eventually it goes on 
(without printing anything about a timeout, but I assume it hits the 
timeout at this stage) with this which is usually the last line:

commit ineffective with AutoCommit enabled at 
/usr/lib/MailScanner/MailScanner/CustomFunctions/MailWatch.pm line 93.
Commmit ineffective while AutoCommit is on at 
/usr/lib/MailScanner/MailScanner/CustomFunctions/MailWatch.pm line 93.

(Steve, can one do something about this? It doesn't seem to hurt, I 
remember it's always been this way on this machine)

On my first debug another message slipped in and I saw MailScanner 
printing that it stops now and exits because it is in debug mode. I assume 
this should happen each time? It didn't do this with this message but kept 
hanging after the above line, maybe it was still waiting for SA. I killed 
it.

Now, the output from SA -D looks like this:

[16547] dbg: rules: running uri tests; score so far=0
[16547] dbg: rules: compiled uri tests
[16547] dbg: plugin: Mail::SpamAssassin::Plugin::WLBLEval=HASH(0x92183b8) 
implements 'check_wb_list', priority 0
[16547] dbg: bayes: DB journal sync: last sync: 1207137283
[16547] dbg: bayes: corpus size: nspam = 62507, nham = 42292
[16547] dbg: bayes: score = 1
[16547] dbg: bayes: DB journal sync: last sync: 1207137283
[16547] dbg: bayes: untie-ing
[16547] dbg: rules: ran eval rule BAYES_99 ======> got hit (1)

There is no noticable pause after "untie-ing".
Also notice that there's no auto-whitelist check happening directly before 
this (that's why I quoted a bit more in the MS portion). In the SA output 
the auto-whitelist check happens much later.
The MS output stops at about line 375. The same line in SA output is at 
about line 460 and the auto-whitelist check happens at line 650. It's 
actually the last thing what it does before auto-learning and creating 
mail output. The message itself is about 800 lines in KOI-8 Russian.

I have a machine with a newer MS and a slightly older SA. I'll check later 
what output I get there.

Kai

-- 
Kai Schätzl, Berlin, Germany
Get your web at Conactive Internet Services: http://www.conactive.com