Almost every night between 1 and 4am I get a few messages like this:
2008-04-29 01:39:23 1JqlKN-0007RA-TD spam acl condition: error reading
from spamd socket: Connection timed out
2008-04-29 01:42:35 1JqlMT-0007RQ-L8 spam acl condition: error reading
from spamd socket: Connection timed out
2008-04-29 01:42:32 1JqlL9-0007RJ-UQ spam acl condition: error reading
from spamd socket: Connection timed out
2008-04-29 04:42:22 1JqoBZ-0000Vx-J1 spam acl condition: error reading
from spamd socket: Connection timed out
in exim's paniclog. I'm running Debian (testing) exim 4.69 and SA
3.2.4. Both are on the same machine and communicate via Unix Domain
sockets. There doesn't seem to be much in the logs before this, beyond
the fact that fetchmail ran. There are some interesting entries shortly
thereafter about auto-whitelisting, which I've noticed has sometimes
been mentioned as a culprit for these problems in earlier messages on
the list. I've put an excerpt from syslog at the bottom of this
message.
Less frequently I get messages suggesting I raise the max number of
children. I'm currently using the Debian defaults, which include a
warning:
# SpamAssassin uses a preforking model, so be careful! You need to
# make sure --max-children is not set to anything higher than 5,
# unless you know what you're doing.
OPTIONS="--create-prefs --max-children 5 --helper-home-dir \
--username=mail --socketpath=/var/run/spamd/socket"
I'm running on a Pentium 4 with hyperthreading, which appears as 2 CPU's
to the OSs. There's really only 1 CPU. I wonder if that could have
something to do with the trouble.
I'd appreciate any help tracking down and fixing this problem.
Thanks.
Ross Boylan
syslog excerpts:
Apr 29 01:37:23 corn spamd[2343]: spamd: got connection
over /var/run/spamd/socket
Apr 29 01:37:24 corn spamd[2343]: spamd: checking message
<[EMAIL PROTECTED]> for mail:8
Apr 29 01:38:48 corn fetchmail[6943]: reading message
[EMAIL PROTECTED]:1 of 1 (10701 octets) flushed
Apr 29 01:38:49 corn fetchmail[6943]: sleeping at Tue 29 Apr 2008
01:38:49 AM PDT for 240 seconds
Apr 29 01:38:51 corn cyrus/master[28613]: about to
exec /usr/lib/cyrus/bin/lmtpd
Apr 29 01:38:51 corn cyrus/lmtpunix[28613]: executed
Apr 29 01:38:52 corn cyrus/lmtpunix[28613]: accepted connection
Apr 29 01:38:52 corn cyrus/lmtpunix[28613]: lmtp connection preauth'd as
postman
Apr 29 01:38:52 corn cyrus/lmtpunix[28613]: WARNING: sieve
script /var/spool/sieve/r/ross/defaultbc doesn't exist: No such file or
directory
Apr 29 01:38:52 corn cyrus/lmtpunix[28613]: duplicate_check:
<[EMAIL PROTECTED]> user.ross 0
Apr 29 01:39:50 corn spamd[2343]: spamd: identified spam (11.6/5.0) for
mail:8 in 147.0 seconds, 4106 bytes.
Apr 29 01:39:51 corn spamd[2343]: spamd: result: Y 11 -
BAYES_80,HTML_MESSAGE,MIME_HTML_ONLY,RAZOR2_CF_RANGE_51_100,RAZOR2_CF_RANGE_E4_51_100,RAZOR2_CF_RANGE_E8_51_100,RAZOR2_CHECK,SPF_FAIL,URIBL_BLACK,URIBL_OB_SURBL
scantime=147.0,size=4106,user=mail,uid=8,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=/var/run/spamd/socket,mid=<[EMAIL
PROTECTED]>,bayes=0.878963,autolearn=no
Apr 29 01:39:51 corn spamd[17697]: prefork: child states: II
Apr 29 01:40:32 corn spamd[2343]: spamd: got connection
over /var/run/spamd/socket
Apr 29 01:40:35 corn spamd[22249]: spamd: got connection
over /var/run/spamd/socket
Apr 29 01:40:36 corn cyrus/lmtpunix[28580]: Delivered:
<[EMAIL PROTECTED]> to
mailbox: user.ross.comp.lyx
Apr 29 01:40:36 corn spamd[22249]: spamd: checking message
<[EMAIL PROTECTED]> for mail:8
Apr 29 01:40:36 corn spamd[2343]: spamd: checking message
<[EMAIL PROTECTED]> for mail:8
Apr 29 01:42:49 corn fetchmail[6943]: awakened at Tue 29 Apr 2008
01:42:49 AM PDT
Apr 29 01:47:30 corn cyrus/master[24864]: process 28580 exited, status 0
Apr 29 01:47:30 corn fetchmail[6943]: Server certificate verification
error: self signed certificate
Apr 29 01:48:18 corn fetchmail[6943]: 3 messages for ross at
pop.rawbw.com (22064 octets).
Apr 29 01:48:18 corn cyrus/imap[26829]: open: user ross opened INBOX
Apr 29 01:48:18 corn cyrus/lmtpunix[28613]: duplicate_check:
<[EMAIL PROTECTED]> user.ross 0
Apr 29 01:48:18 corn cyrus/lmtpunix[28613]: mystore: starting txn
2147484306
Apr 29 01:48:18 corn cyrus/lmtpunix[28613]: mystore: committing txn
2147484306
Apr 29 01:48:18 corn cyrus/lmtpunix[28613]: duplicate_mark:
<[EMAIL PROTECTED]> user.ross
1209458332 134539179
Apr 29 01:48:39 corn /USR/SBIN/CRON[28655]: (root) CMD
([ -x /usr/lib/sysstat/sa1 ] && { [ -r "$DEFAULT" ] && . "$DEFAULT" ;
[ "$ENABLED" = "true" ] && exec /usr/lib/sysstat/sa1 $SA1_OPTIONS 1
1 ; })
Apr 29 01:48:56 corn spamd[2343]: auto-whitelist: open of auto-whitelist
file failed: child processing timeout at /usr/sbin/spamd line 1262.
Apr 29 01:48:56 corn spamd[22249]: auto-whitelist: open of
auto-whitelist file failed: child processing timeout at /usr/sbin/spamd
line 1262.
Apr 29 01:48:56 corn spamd[2343]: print() on closed filehandle LTMP
at /usr/share/perl5/Mail/SpamAssassin/Locker/UnixNFSSafe.pm line 147.
Apr 29 01:48:56 corn spamd[2343]: stat() on closed filehandle LTMP
at /usr/share/perl5/Mail/SpamAssassin/Locker/UnixNFSSafe.pm line 149.
Apr 29 01:48:56 corn spamd[2343]: locker: safe_unlock: failed to create
lock
tmpfile /var/mail/.spamassassin/auto-whitelist.lock.corn.betterworld.us.2343 at
/usr/share/perl5/Mail/SpamAssassin/Locker/UnixNFSSafe.pm line 150.
Apr 29 01:48:56 corn spamd[2343]: spamd: clean message (1.9/5.0) for
mail:8 in 468.5 seconds, 6250 bytes.
Apr 29 01:48:56 corn spamd[2343]: spamd: result: . 1 -
BAYES_00,DNS_FROM_RFC_BOGUSMX,FORGED_HOTMAIL_RCVD2,UNPARSEABLE_RELAY,WHOIS_MYPRIVREG
scantime=468.5,size=6250,user=mail,uid=8,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=/var/run/spamd/socket,mid=<[EMAIL
PROTECTED]>,bayes=0.000000,autolearn=no
Apr 29 01:48:56 corn spamd[17697]: prefork: child states: BB
Apr 29 01:48:56 corn spamd[2343]: spamd: got connection
over /var/run/spamd/socket
Apr 29 01:48:56 corn spamd[17697]: spamd: server successfully spawned
child process, pid 28666
Apr 29 01:48:56 corn spamd[2343]: spamd: checking message
<[EMAIL PROTECTED]> for
mail:8
Apr 29 01:48:56 corn cyrus/imap[26829]: open: user ross opened INBOX
Apr 29 01:48:56 corn spamd[22249]: spamd: clean message (-2.6/5.0) for
mail:8 in 481.2 seconds, 7619 bytes.
Apr 29 01:48:56 corn fetchmail[6943]: reading message
[EMAIL PROTECTED]:1 of 3 (4886 octets) not flushed
Apr 29 01:48:56 corn spamd[28666]: spamd: got connection
over /var/run/spamd/socket
Apr 29 01:48:56 corn spamd[17697]: prefork: child states: BBB
Apr 29 01:48:57 corn spamd[22249]: spamd: result: . -2 -
BAYES_00,HTML_MESSAGE,UNPARSEABLE_RELAY
scantime=481.2,size=7619,user=mail,uid=8,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=/var/run/spamd/socket,mid=<[EMAIL
PROTECTED]>,bayes=0.000000,autolearn=ham
Apr 29 01:48:57 corn spamd[17697]: spamd: server successfully spawned
child process, pid 28680
Apr 29 01:48:57 corn spamd[22249]: spamd: got connection
over /var/run/spamd/socket
Apr 29 01:48:57 corn spamd[17697]: prefork: child states: BBBI
Apr 29 01:48:57 corn spamd[28680]: spamd: got connection
over /var/run/spamd/socket
