SA TIMED OUT

[Daniel Bentley <da...@hermod.qsicorp.com>]

I've looked around for information about this, and have found mostly posts 
kind of like my problem, but not quite the same...

Here's the scenario: original setup, SA 2.64 upgraded via CPAN from SA 
2.63 (from original Mandrake install).  Attempted to upgrade to 3.0.1 via 
CPAN (backed up previous SA configs).  Due to errors and time, decided to 
back down to 2.64.  Blew away 3.0.1, reinstalled 2.64 from source .tar.gz 
from the SA site.

Mandrake 9.2, site-wide SA (spamd), Postfix and amavisd-new

Now I get the following (transaction taken from syslog):

Nov  4 15:45:46 <server> postfix/smtpd[11719]: connect from 
client.domain.tld[IP]
Nov  4 15:45:46 <server> postfix/smtpd[11719]: BD1E319D918: 
client=client.domain.tld[IP]
Nov  4 15:45:46 <server> postfix/cleanup[11963]: BD1E319D918: 
message-id=<41...@domain.tld>
Nov  4 15:45:46 <server> postfix/qmgr[2509]: BD1E319D918: 
from=<in...@domain.tld>, size=18301, nrcpt=1 (queue active)
Nov  4 15:45:46 <server> amavis[11932]: (11932-08) ESMTP::10024 
/var/amavis/amavis-20041104T154206-11932: <in...@domain.tld> -> 
<in...@qsicorp.com> Received: SIZE=18301 from server.domain.tld 
([127.0.0.1]) by localhost (server.domain.tld [127.0.0.1]) (amavisd-new, 
port 10024) with ESMTP id 11932-08 for <in...@domain.tld>; Thu,  
4 Nov 2004 15:45:46 -0700 (MST)
Nov  4 15:45:46 <server> postfix/smtpd[11719]: disconnect from 
client.domain.tld[IP]
Nov  4 15:45:46 <server> amavis[11932]: (11932-08) Checking: 
<in...@domain.tld> -> <in...@domain.tld>

<- snip ->

Nov  4 15:46:08 <server> amavis[11932]: (11932-08) SA TIMED OUT, 
backtrace: at 
/usr/lib/perl5/site_perl/5.8.1/Mail/SpamAssassin/BayesStore.pm line 
376\n\teval {...} called at 
/usr/lib/perl5/site_perl/5.8.1/Mail/SpamAssassin/BayesStore.pm line 
376\n\tMail::SpamAssassin::BayesStore::upgrade_db('Mail::SpamAssassin::BayesStore=HASH(0x954c290)
') called at 
/usr/lib/perl5/site_perl/5.8.1/Mail/SpamAssassin/BayesStore.pm line 
253\n\tMail::SpamAssassin::BayesStore::tie_db_writable('Mail::SpamAssassin::BayesStore=H
ASH(0x954c290)') called at 
/usr/lib/perl5/site_perl/5.8.1/Mail/SpamAssassin/Bayes.pm line 662\n\teval 
{...} called at /usr/lib/perl5/site_perl/5.8.1/Mail/SpamAssassin/Bayes.pm 
line 
655\n\tMail::SpamAssassin::Bayes::learn('Mail::SpamAssassin::Bayes=HASH(0x94ff868)',0,'Mail::SpamAssassin::NoMailAudit=HASH(0x9d9de3c)','undef') 
called at 
/usr/lib/perl5/site_perl/5.8.1/Mail/SpamAssassin/PerMsgLearner.pm line 
110\n\tMail::SpamAssassin::PerMsgLearner::le...

<- snip ->

Nov  4 15:47:08 <server> amavis[11932]: (11932-08) spam_scan: hits=0 
tests=
Nov  4 15:47:08 <server> amavis[11932]: (11932-08) FWD via SMTP: 
[127.0.0.1:10025] <in...@domain.tld> -> 
<in...@domain.tld>
Nov  4 15:47:08 <server> amavis[11932]: (11932-08) Passed, 
<in...@domain.tld> -> <in...@domain.tld>, Message-ID: 
<41...@qsicorp.com>, Hits: 0
Nov  4 15:47:08 <server> amavis[11932]: (11932-08) TIMING [total 81390 ms] 
- SMTP EHLO: 3 (0%), SMTP pre-MAIL: 1 (0%), SMTP pre-DATA-flush: 5 (0%), 
SMTP DATA: 81 (0%), body hash: 1 (0%), mime_decode: 53 (0%), 
get-file-type: 31 (0%), get-file-type: 16 (0%), decompose_part: 3 (0%), 
decompose_part: 0 (0%), parts: 0 (0%), AV-scan-1: 1133 (1%), SA msg read: 
8 (0%), SA parse: 3 (0%), SA check: 79943 (98%), fwd-connect: 14 (0%), 
fwd-mail-from: 2 (0%), fwd-rcpt-to: 7 (0%), write-header: 7 (0%), 
fwd-data: 6 (0%), fwd-data-end: 59 (0%), fwd-rundown: 3 (0%), 
unlink-2-files: 9 (0%), rundown: 1 (0%)
Nov  4 15:47:08 <server> postfix/smtp[11753]: BD1E319D918: 
to=<in...@domain.tld>, relay=127.0.0.1[127.0.0.1], delay=82, 
status=sent (250 2.6.0 Ok, id=11932-08, from MTA: 250 Ok: queued as 
2AE6B19D91A)
Nov  4 15:47:08 <server> postfix/qmgr[2509]: BD1E319D918: removed
Nov  4 15:47:08 <server> postfix/local[12116]: 2AE6B19D91A: 
to=<in...@domain.tld>, relay=local, delay=0, status=sent 
(delivered to command: /usr/bin/procmail -Y -a $DOMAIN)
Nov  4 15:47:08 <server> postfix/qmgr[2509]: 2AE6B19D91A: removed

So basically, while the e-mail still passes, it gets this delivery delay.  
This has shown up with e-mails internal -> internal, internal -> external, 
and external -> internal, and I haven't been able to track a similiar 
trait between which e-mails trigger this ('bout 17% of total e-mails 
today), and which don't.  bayes_seen and bayes_toks in 
/var/amavis/.spamassassin/ are being updated, the configs from 
'pre-install attempt' are in place and with proper permissions, I'm just 
out of ideas as to where else to look...  Things are ultimately working, 
it's just... annoying.  -.-

-- 
Daniel Bentley - Network Technician, QSI Corporation (www.qsicorp.com)
"Exploits care not whence the clicks come..."