Help! SA timing out, mail undelivered

[mikea]

The subject pretty much says it all. It appears to have started
about 0600 this morning, and I'm having trouble figuring out just
what is causing the timeout. 

To get mail to flow, I have to disable SA, which means I have to do
without the rules I need for catching some particularly nasty things. 

Here is debug output with debug turned on for MS and SA both: 

: isdmon2# sh rc.M*er start
:  sendmail incoming outgoing MailScanner Starting MailScanner...
: In Debugging mode, not forking...
: debug: Score set 0 chosen.
: debug: ignore: test message to precompile patterns and load modules
: debug: using "/usr/local/share/spamassassin" for default rules dir
: debug: using "/etc/mail/spamassassin" for site rules dir
: debug: using "/opt/MailScanner/etc/spam.assassin.prefs.conf" for user prefs file
: debug: bayes: tie-ing to DB file R/O /root/.spamassassin/bayes_toks
: debug: bayes: tie-ing to DB file R/O /root/.spamassassin/bayes_seen
: debug: Score set 3 chosen.
: debug: Initialising learner
: debug: is Net::DNS::Resolver available? no
: debug: is DNS available? 0
: debug: running header regexp tests; score so far=0
: debug: running body-text per-line regexp tests; score so far=1.3
: debug: bayes corpus size: nspam = 4448, nham = 9521
: debug: tokenize: header tokens for *F = "ignore at compiling.spamassassin.taint.org"
: debug: tokenize: header tokens for *m = " 1060115123 spamassassin_spamd_init "
: debug: cannot use bayes on this message; db not initialised yet
: debug: bayes: not scoring message, returning 0.5
: debug: entering helper-app run mode
: debug: running in taint mode? no
: razor2 check skipped: No such file or directory Can't locate Razor2/Client/Agent.pm in @INC (@INC contains: /opt/MailScanner/bin /opt/MailScanner/bin/MailScanner /opt/MailScanner/lib /usr/local/lib/perl5/5.6.1/i386-freebsd /usr/local/lib/perl5/5.6.1 /usr/local/lib/perl5/site_perl/5.6.1/i386-freebsd /usr/local/lib/perl5/site_perl/5.6.1 /usr/local/lib/perl5/site_perl/5.005/i386-freebsd /usr/local/lib/perl5/site_perl/5.005 /usr/local/lib/perl5/site_perl . /opt/MailScanner/lib) at /usr/local/lib/perl5/site_perl/5.6.1/Mail/SpamAssassin/Dns.pm line 377.
: debug: leaving helper-app run mode
: debug: Razor2 results: spam? 0  highest cf score: 0
: debug: running raw-body-text per-line regexp tests; score so far=1.3
: debug: running uri tests; score so far=1.3
: debug: uri tests: Done uriRE
: debug: running full-text regexp tests; score so far=1.3
: debug: Razor2 is not available
: debug: DCC is not available: dccproc not found
: debug: Current PATH is: /sbin:/bin:/usr/sbin:/usr/bin
: debug: Pyzor is not available: pyzor not found
: debug: all '*To' addrs: 
: debug: all '*From' addrs: ignore at compiling.spamassassin.taint.org
: debug: running meta tests; score so far=1.3
: debug: is spam? score=1.3 required=5 tests=DATE_MISSING,NO_REAL_NAME
: debug: running header regexp tests; score so far=0
: debug: running body-text per-line regexp tests; score so far=0.7
: debug: bayes corpus size: nspam = 4448, nham = 9521
: debug: tokenize: header tokens for *p = "<g>"
: debug: tokenize: header tokens for *M = " tb2hg v2h2a 7 8e 4046  2e 624 ovl2dynrl "
: debug: tokenize: header tokens for *F = ""Amber Mcfadden" <zpo1mhu34 at yahoo.ca>"
: debug: tokenize: header tokens for To = "cbleeker at odot.okladot.state.ok.us"
: debug: tokenize: header tokens for *x = "Microsoft Outlook IMO, Build 9.0.2416 (9.0.2910.0)"
: debug: tokenize: header tokens for MIME-Version = ""
: debug: tokenize: header tokens for *c = "multipart/alternative;  HH _ HHHHH . HHHH _ HHHHHHHH"
: debug: tokenize: header tokens for X-Priority = "3"
: debug: tokenize: header tokens for X-MSMail-Priority = "Normal"
: debug: tokenize: header tokens for *r = "  kmj.ya3lx.org (HELO ry1) ([34.131.233]) by 200-206-162-110.dsl.telesp.net.br    ; "
: debug: tokenize: header tokens for *r = "  kmj.ya3lx.org (HELO ry1) ([34.131.233]) by 200-206-162-110.dsl.telesp.net.br    ;    200-206-162-110.dsl.telesp.net.br (200-206-162-110.dsl.telesp.net.br [200.206.162]) by odot.okladot.state.ok.us (AIX4.3/8.9.3/8.9.2)         <cbleeker at odot.org>; "
: debug: bayes token 'optout.php' => 0.991061452513966
: debug: bayes token 'sk:t_bone_' => 0.0444444444444444
: debug: bayes token 'HTo:sk:cbleeke' => 0.950272483866148
: debug: bayes token 'H*r:sk:cbleeke' => 0.950272483866148
: debug: bayes: score = 0.627485986917155
: debug: expiration is due: expiring old tokens now...
: debug: lock: 34757 created /root/.spamassassin/bayes.lock.isdmon2.okladot.state.ok.us.34757
: debug: lock: 34757 trying to get lock on /root/.spamassassin/bayes with 0 retries
: debug: lock: 34757 link to /root/.spamassassin/bayes.lock: link ok
: debug: bayes: tie-ing to DB file R/W /root/.spamassassin/bayes_toks
: debug: bayes: tie-ing to DB file R/W /root/.spamassassin/bayes_seen
: debug: bayes: untie-ing
: debug: bayes: untie-ing db_toks
: debug: bayes: untie-ing db_seen
: debug: bayes: files locked, now unlocking lock
: debug: unlock: 34757 unlink /root/.spamassassin/bayes.lock
: debug: synced Bayes databases from journal in 0 seconds: 4 entries
: debug: lock: 34757 created /root/.spamassassin/bayes.lock.isdmon2.okladot.state.ok.us.34757
: debug: lock: 34757 trying to get lock on /root/.spamassassin/bayes with 0 retries
: debug: lock: 34757 link to /root/.spamassassin/bayes.lock: link ok
: debug: bayes: tie-ing to DB file R/W /root/.spamassassin/bayes_toks
: debug: bayes: tie-ing to DB file R/W /root/.spamassassin/bayes_seen

I've done tcpdumps and tried to see what rbl queries were hanging, in
case one or more of the usual suspects might be under DDOS, but it all
seemed to be working OK. 

Meanwhile, SA is timing out: 

Aug  5 15:23:23 isdmon2 MailScanner[34303]: SpamAssassin timed out and was killed, consecutive failure 1 of 20 
Aug  5 15:23:37 isdmon2 MailScanner[34312]: SpamAssassin timed out and was killed, consecutive failure 1 of 20 
Aug  5 15:23:52 isdmon2 MailScanner[34353]: SpamAssassin timed out and was killed, consecutive failure 1 of 20 
Aug  5 15:24:09 isdmon2 MailScanner[34391]: SpamAssassin timed out and was killed, consecutive failure 1 of 20 
Aug  5 15:24:21 isdmon2 MailScanner[34397]: SpamAssassin timed out and was killed, consecutive failure 1 of 20 
Aug  5 15:26:09 isdmon2 MailScanner[34740]: SpamAssassin timed out and was killed, consecutive failure 1 of 20

Suggestions? 

-- 
Mike Andrews
mikea at mikea.ath.cx
Tired old sysadmin since 1964