http://bugzilla.spamassassin.org/show_bug.cgi?id=3828
------- Additional Comments From [EMAIL PROTECTED] 2004-11-15 11:43 -------
okay, the problem child was 2351. here is its life history.
12:28:54 - pid 2351 spawned.
12:28:58 - first message
12:31:31 - last log entry by pid 2351
12:45:01 - last log entry by spamd parent for pid 2351 cleanup
Here are the respective log entries for the 4 lines above.
2004-11-15 12:28:54.966903500 logmsg: [17464] server successfully spawned child
process, pid 2351
2004-11-15 12:31:31.173103500 logmsg: [2351] identified spam (10.3/7.0) for
$GLOBAL:0 in 1.1 seconds, 1332 bytes.
2004-11-15 12:31:31.173105500 logmsg: [2351] result: Y 10 -
DCC_CHECK,HELO_DYNAMIC_DHCP,HELO_DYNAMIC_IPADDR,HTML_50_60,HTML_IMAGE_ONLY_08,HTML_MESSAGE,HTML_MIME_NO_HTML_TAG,INFO_TLD,LONGWORDS,MIME_HTML_ONLY,MISSING_DATE
scantime=1.1,size=1332,mid=<[EMAIL PROTECTED]>,autolearn=disabled
2004-11-15 12:45:01.061316500 logmsg: [17464] server hit by SIGCHLD
2004-11-15 12:45:01.061320500 logmsg: [17464] handled cleanup of child pid 2351
12:45:01 coincides with when my script sent a kill -9 to it, as it runs on a 5
minute cron. also corresponds with the email received header (in GMT)..
Received: (qmail 9714 invoked by uid 0); 15 Nov 2004 18:45:01 -0000
so, to sum up...
2351 processed 23 messsages, start to finish... 8 spam, 15 ham in almost a 3
minute span.. 12:28:58 to 12:31:31. spamd is running with
--max-conn-per-child=25 so i dont think it has anything to do with that.
BEGINS
[EMAIL PROTECTED] spamd]# cat spamd.log2 | grep "\[2351\] config" | grep
retrieving
|wc -l
23
ENDS
[EMAIL PROTECTED] spamd]# cat spamd.log2 | grep "\[2351\] result" | wc -l
23
so the log doesnt indicate any of them never finishing, unless it hung right
after message 23 was fully processed? I guess i dont know what all goes on
after it sends the 'result' logmsg, it should just go back to read() for input
of #24 right? The total life of pid 2351 was 6 minutes and 7 seconds, but ps
showed 7 minutes and 57 seconds of CPU usage... during normal operation, the 25
max-conn-per-child will prevent a spamd child cpu utilization to under 30
seconds... so 7 minutes is very high.
here is the message i received from cron...
child pid 2351 running for 7 min, 57 sec
-> ALERT: spamd pid 2351 ran for 7 min, 57 sec and was killed!
child pid 9321 running for 0 min, 02 sec
child pid 9490 running for 0 min, 02 sec
child pid 9708 running for 0 min, 00 sec
child pid 9711 running for 0 min, 00 sec
here are the stops and starts on the child processes seen above.
spamd.log:2004-11-15 12:28:54.966903500 logmsg: [17464] server successfully
spawned child process, pid 2351
spamd.log:2004-11-15 12:45:01.061320500 logmsg: [17464] handled cleanup of child
pid 2351
spamd.log:2004-11-15 12:44:20.793041500 logmsg: [17464] server successfully
spawned child process, pid 9321
spamd.log:2004-11-15 12:46:47.325710500 logmsg: [17464] handled cleanup of child
pid 9321
spamd.log:2004-11-15 12:44:39.292863500 logmsg: [17464] server successfully
spawned child process, pid 9490
spamd.log:2004-11-15 12:47:20.977168500 logmsg: [17464] handled cleanup of child
pid 9490
a
pid 9708 is no where to be found? not sure what the deal is here?? maybe this
is part of the problem, but i dont know how. its the only thing i can find
that is strange here because if ps says its a spamd child, there should be
something in the logs about it.
[EMAIL PROTECTED] spamd]# grep "pid 9708" *
[EMAIL PROTECTED] spamd]#
spamdlog:2004-11-15 04:00:39.199207500 logmsg: [17464] server successfully
spawned child process, pid 9711
spamdlog:2004-11-15 04:06:08.322575500 logmsg: [17464] handled cleanup of child
pid 9711
so now i dont know what to do!! i guess i could add some debugging after the
result logmsg and see what its doing.. but now i have to wait for it to happen
again. fun fun.
------- You are receiving this mail because: -------
You are the assignee for the bug, or are watching the assignee.
