You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@spamassassin.apache.org by Scott Russell <ln...@us.ibm.com> on 2006/03/07 21:33:20 UTC
spamd children disobeying orders
Greets.
Running SA 3.1.0 with spamc/spamd on RHEL4 i386. I have the following
options for my spamd: -d --allow-tell --max-children=30
--min-children=10 --min-spare=3 --max-spare=6 -q -x -u spamd
Today I saw the following error in /var/log/maillog:
spamd[23150]: prefork: ordered child to accept, but child reported state
'1'
at /usr/lib/perl5/site_perl/5.8.5/Mail/SpamAssassin/SpamdForkScaling.pm
line 390.
After the error no additional 'prefork' messages were logged. I find
this odd as the server continued to accept mail. I did see several
additional spamd messages logged. These appeared to be spamd finishing
out the spamassassin checks of messages it had already accepted. No
further 'spamd connection from ...' messages were logged however.
Shortly there after spamd was down. Has anyone else seen similar? Here's
a more detailed section of the spamd log entries that surround the error
above.
Mar 7 13:39:25 imap spamd[14918]: spamd: connection from
localhost.localdomain [127.0.0.1] at port 35293
Mar 7 13:39:25 imap spamd[14914]: spamd: processing message
<20...@deneb.dwf.com> for ricklind:101
Mar 7 13:39:25 imap spamd[23150]: prefork: child states:
BBBBBBBBBBBBBBBBBBBB
Mar 7 13:39:25 imap spamd[23150]: spamd: server successfully spawned
child process, pid 14924
Mar 7 13:39:25 imap spamd[23150]: prefork: child states:
BBBBBBBBBBBBBBBBBBBBI
Mar 7 13:39:25 imap spamd[23150]: spamd: server successfully spawned
child process, pid 14925
Mar 7 13:39:25 imap spamd[23150]: prefork: child states:
BBBBBBBBBBBBBBBBBBBBII
Mar 7 13:39:25 imap spamd[14920]: spamd: connection from
localhost.localdomain [127.0.0.1] at port 35294
Mar 7 13:39:25 imap spamd[14920]: spamd: processing message
<OF...@LocalDomain>
for lnxgeek:101
Mar 7 13:39:25 imap spamd[14906]: spamd: processing message
<20...@deneb.dwf.com> for haren:101
Mar 7 13:39:25 imap spamd[14918]: spamd: processing message
<OF...@LocalDomain>
for lnxgeek:101
Mar 7 13:39:25 imap spamd[14916]: spamd: processing message
<OF...@LocalDomain>
for lnxgeek:101
Mar 7 13:39:25 imap spamd[23150]: spamd: server successfully spawned
child process, pid 14930
Mar 7 13:39:25 imap spamd[23150]: prefork: child states:
BBBBBBBBBBBBBBBBBBBBIII
Mar 7 13:39:25 imap spamd[14909]: spamd: processing message
<20...@deneb.dwf.com> for santil:101
Mar 7 13:39:26 imap spamd[14918]: spamd: clean message (2.2/4.4) for
lnxgeek:101 in 1.1 seconds, 4434 bytes.
Mar 7 13:39:26 imap spamd[14918]: spamd: result: . 2 -
BAYES_50,DATE_IN_PAST_96_XX,DNS_FROM_RFC_ABUSE,HTML_MESSAGE,MSGID_FROM_MTA_HEADER,UNPARSEABLE_RELAY
scantime=1.1,size=4434,user=lnxgeek,uid=101,required_score=4.4,rhost=localhost.localdomain,raddr=127.0.0.1,rport=35293,mid=<OFEB021CE1.48
48D148-ON85257088.006EA7CE-85257088.006EDBDF@LocalDomain>,bayes=0.495966299857951,autolearn=disabled
Mar 7 13:39:26 imap spamd[14920]: spamd: clean message (2.8/4.4) for
lnxgeek:101 in 1.3 seconds, 13466 bytes.
Mar 7 13:39:26 imap spamd[14920]: spamd: result: . 2 -
BAYES_40,DATE_IN_PAST_96_XX,DNS_FROM_RFC_ABUSE,HTML_MESSAGE,MSGID_FROM_MTA_HEADER,SARE_LWSHORTT,UNPARSEABLE_RELAY
scantime=1.3,size=13466,user=lnxgeek,uid=101,required_score=4.4,rhost=localhost.localdomain,raddr=127.0.0.1,rport=35294,mid
=<OF...@LocalDomain>,bayes=0.24968482791093,autolearn=disabled
Mar 7 13:39:27 imap spamd[14452]: spamd: clean message (0.0/5.0) for
colpatch:101 in 3.5 seconds, 3725 bytes.
Mar 7 13:39:27 imap spamd[14452]: spamd: result: . 0 -
scantime=3.5,size=3725,user=colpatch,uid=101,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=35282,mid=<20...@deneb.dwf.com>,autolearn=disabled
Mar 7 13:39:27 imap spamd[7180]: spamd: clean message (0.0/5.0) for
aball:101 in 3.6 seconds, 3725 bytes.
Mar 7 13:39:27 imap spamd[10327]: spamd: clean message (0.0/5.0) for
apw:101 in 3.5 seconds, 3725 bytes.
Mar 7 13:39:27 imap spamd[7180]: spamd: result: . 0 -
scantime=3.6,size=3725,user=aball,uid=101,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=35275,mid=<20...@deneb.dwf.com>,autolearn=disabled
Mar 7 13:39:27 imap spamd[10327]: spamd: result: . 0 -
scantime=3.5,size=3725,user=apw,uid=101,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=35277,mid=<20...@deneb.dwf.com>,autolearn=disabled
Mar 7 13:39:27 imap spamd[13173]: spamd: clean message (0.0/5.0) for
idr:101 in 3.5 seconds, 3725 bytes.
Mar 7 13:39:27 imap spamd[13173]: spamd: result: . 0 -
scantime=3.5,size=3725,user=idr,uid=101,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=35280,mid=<20...@deneb.dwf.com>,autolearn=disabled
Mar 7 13:39:27 imap spamd[14703]: spamd: clean message (0.0/5.0) for
linuxram:101 in 3.6 seconds, 3725 bytes.
Mar 7 13:39:27 imap spamd[14703]: spamd: result: . 0 -
scantime=3.6,size=3725,user=linuxram,uid=101,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=35283,mid=<20...@deneb.dwf.com>,autolearn=disabled
Mar 7 13:39:27 imap spamd[10335]: spamd: clean message (0.0/5.0) for
gh:101 in 3.6 seconds, 3725 bytes.
Mar 7 13:39:27 imap spamd[10335]: spamd: result: . 0 -
scantime=3.6,size=3725,user=gh,uid=101,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=35278,mid=<20...@deneb.dwf.com>,autolearn=disabled
Mar 7 13:39:27 imap spamd[14197]: spamd: clean message (0.0/5.0) for
janak:101 in 3.6 seconds, 3725 bytes.
Mar 7 13:39:27 imap spamd[14197]: spamd: result: . 0 -
scantime=3.6,size=3725,user=janak,uid=101,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=35281,mid=<20...@deneb.dwf.com>,autolearn=disabled
Mar 7 13:39:27 imap spamd[13151]: spamd: clean message (0.0/5.0) for
hien:101 in 3.7 seconds, 3725 bytes.
Mar 7 13:39:27 imap spamd[13151]: spamd: result: . 0 -
scantime=3.7,size=3725,user=hien,uid=101,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=35279,mid=<20...@deneb.dwf.com>,autolearn=disabled
Mar 7 13:39:27 imap spamd[23150]: prefork: ordered child to accept, but
child reported state '1' at
/usr/lib/perl5/site_perl/5.8.5/Mail/SpamAssassin/SpamdForkScaling.pm
line 390.
Mar 7 13:39:27 imap spamd[8871]: spamd: clean message (0.0/5.0) for
agl:101 in 3.7 seconds, 3725 bytes.
Mar 7 13:39:27 imap spamd[8871]: spamd: result: . 0 -
scantime=3.7,size=3725,user=agl,uid=101,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=35276,mid=<20...@deneb.dwf.com>,autolearn=disabled
Mar 7 13:39:27 imap spamd[14703]: spamd: connection from
localhost.localdomain [127.0.0.1] at port 35295
Mar 7 13:39:27 imap spamd[14703]: spamd: processing message
<OF...@LocalDomain>
for lnxgeek:101
Mar 7 13:39:27 imap spamd[14916]: spamd: clean message (3.0/4.4) for
lnxgeek:101 in 2.0 seconds, 20689 bytes.
Mar 7 13:39:27 imap spamd[14916]: spamd: result: . 2 -
BAYES_05,DATE_IN_PAST_96_XX,DNS_FROM_RFC_ABUSE,HTML_MESSAGE,MSGID_FROM_MTA_HEADER,UNPARSEABLE_RELAY,URI_SCHEME_MIXED_CASE
scantime=2.0,size=20689,user=lnxgeek,uid=101,required_score=4.4,rhost=localhost.localdomain,raddr=127.0.0.1,rport=3
5292,mid=<OF...@LocalDomain>,bayes=0.0155620345084976,autolearn=disabled
Mar 7 13:39:28 imap spamd[14912]: spamd: clean message (0.0/5.0) for
kravetz:101 in 2.7 seconds, 3725 bytes.
Mar 7 13:39:28 imap spamd[14912]: spamd: result: . 0 -
scantime=2.7,size=3725,user=kravetz,uid=101,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=35290,mid=<20...@deneb.dwf.com>,autolearn=disabled
Mar 7 13:39:28 imap spamd[14903]: spamd: clean message (0.0/5.0) for
jdmason:101 in 2.8 seconds, 3725 bytes.
Mar 7 13:39:28 imap spamd[14903]: spamd: result: . 0 -
scantime=2.8,size=3725,user=jdmason,uid=101,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=35285,mid=<20...@deneb.dwf.com>,autolearn=disabled
Mar 7 13:39:28 imap spamd[14906]: spamd: clean message (0.0/5.0) for
haren:101 in 2.7 seconds, 3725 bytes.
Mar 7 13:39:28 imap spamd[14906]: spamd: result: . 0 -
scantime=2.7,size=3725,user=haren,uid=101,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=35287,mid=<20...@deneb.dwf.com>,autolearn=disabled
Mar 7 13:39:28 imap spamd[7269]: spamd: clean message (0.0/5.0) for
lxiep:101 in 2.8 seconds, 3725 bytes.
Mar 7 13:39:28 imap spamd[7269]: spamd: result: . 0 -
scantime=2.8,size=3725,user=lxiep,uid=101,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=35284,mid=<20...@deneb.dwf.com>,autolearn=disabled
Mar 7 13:39:28 imap spamd[14914]: spamd: clean message (0.0/5.0) for
ricklind:101 in 2.7 seconds, 3725 bytes.
Mar 7 13:39:28 imap spamd[14914]: spamd: result: . 0 -
scantime=2.7,size=3725,user=ricklind,uid=101,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=35291,mid=<20...@deneb.dwf.com>,autolearn=disabled
Mar 7 13:39:28 imap spamd[14904]: spamd: clean message (0.0/5.0) for
wendyx:101 in 2.9 seconds, 3725 bytes.
Mar 7 13:39:28 imap spamd[14904]: spamd: result: . 0 -
scantime=2.9,size=3725,user=wendyx,uid=101,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=35286,mid=<20...@deneb.dwf.com>,autolearn=disabled
Mar 7 13:39:28 imap spamd[14908]: spamd: clean message (0.0/5.0) for
tbrian:101 in 2.9 seconds, 3725 bytes.
Mar 7 13:39:28 imap spamd[14908]: spamd: result: . 0 -
scantime=2.9,size=3725,user=tbrian,uid=101,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=35288,mid=<20...@deneb.dwf.com>,autolearn=disabled
Mar 7 13:39:28 imap spamd[14909]: spamd: clean message (0.0/5.0) for
santil:101 in 2.9 seconds, 3725 bytes.
Mar 7 13:39:28 imap spamd[14909]: spamd: result: . 0 -
scantime=2.9,size=3725,user=santil,uid=101,required_score=5.0,rhost=localhost.localdomain,raddr=127.0.0.1,rport=35289,mid=<20...@deneb.dwf.com>,autolearn=disabled
Mar 7 13:39:28 imap spamd[14703]: spamd: identified spam (4.7/4.4) for
lnxgeek:101 in 1.5 seconds, 17534 bytes.
Mar 7 13:39:28 imap spamd[14703]: spamd: result: Y 4 -
BAYES_40,DATE_IN_PAST_96_XX,DNS_FROM_RFC_ABUSE,HTML_MESSAGE,MSGID_FROM_MTA_HEADER,SARE_LWSHORTT,UNPARSEABLE_RELAY,URI_SCHEME_MIXED_CASE
scantime=1.5,size=17534,user=lnxgeek,uid=101,required_score=4.4,rhost=localhost.localdomain,raddr=127
.0.0.1,rport=35295,mid=<OF...@LocalDomain>,bayes=0.218591148107912,autolearn=disabled
Mar 7 13:39:29 imap spamc[15019]: connect(AF_INET) to spamd at
127.0.0.1 failed, retrying (#1 of 3): Connection refused
--
Scott Russell <ln...@us.ibm.com>
IBM Linux Technology Center
Re: spamd children disobeying orders
Posted by Scott Russell <ln...@us.ibm.com>.
Craig Green wrote:
>
> Scott Russell wrote:
>> Greets.
>>
>> Running SA 3.1.0 with spamc/spamd on RHEL4 i386. I have the following
>> options for my spamd: -d --allow-tell --max-children=30
>> --min-children=10 --min-spare=3 --max-spare=6 -q -x -u spamd
>>
>> Today I saw the following error in /var/log/maillog:
>>
>> spamd[23150]: prefork: ordered child to accept, but child reported
>> state '1'
>> at /usr/lib/perl5/site_perl/5.8.5/Mail/SpamAssassin/SpamdForkScaling.pm
>> line 390.
>
> I'd guess you're being bitten by:
> http://issues.apache.org/SpamAssassin/show_bug.cgi?id=4594
> Short answer: try --round-robin.
Thanks for pointing this out. FWIW, --round-robin had issues too. I ran
with "-d --max-children=30 --allow-tell --round-robin -q -x -u spamd"
and the problem was every time rules_du_jour updated and ran
"/etc/init.d/spamd restart" the restart failed. It looks like spamd
reports back immediately it has exited but in reality takes it's time
exiting until all children are done processing. The result is that when
spamd tries to start up again the socket is in use. I would come in
every morning after rules_du_jour ran to find spamd not running :)
--
Scott Russell <ln...@us.ibm.com>
IBM Linux Technology Center