You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@spamassassin.apache.org by Justin Mason <jm...@jmason.org> on 2009/03/21 23:38:21 UTC
Re: spamd children waiting 10 seconds before they start processing a
message
bizarre. the one thing that leaps to mind would be a DNS lookup
happening "behind the scenes"
to a broken/missing DNS server...
--j.
On Sat, Mar 21, 2009 at 22:31, Daryl C. W. O'Shea
<sp...@dostech.ca> wrote:
> Anybody know why a spamd child would consistently sleep 10 seconds
> before even starting to process a message after being ordered to do so
> by the spamd parent?
>
> /usr/local/scripts/spamd -p 5559 -x -u mail -m 2 -d -A 10.0.0.0/8 -i
> 10.10.10.85 -r /var/run/spamd2.pid -L -D
> --siteconfigpath=/home/techsupport/spamassassin --configpath=/dev/null
>
> The only plugin being loaded is the Check plugin. Everything else is
> disabled. The spamd children have the same 10 second delay when running
> in either prefork or round-robin mode.
>
> load average: 0.15, 0.20, 0.18
>
> Cpu(s): 4.8% us, 0.6% sy, 0.0% ni, 94.2% id, 0.0% wa, 0.0% hi, 0.3% si
>
> Thanks!
>
> Daryl
>
>
>> Mar 21 17:06:34 sa85 spamd[26187]: prefork: ordered 26188 to accept
>> Mar 21 17:06:34 sa85 spamd[26187]: prefork: sysread(6) not ready, wait max 300 secs
>> Mar 21 17:06:34 sa85 spamd[26187]: prefork: child 26188: entering state 2
>> Mar 21 17:06:34 sa85 spamd[26187]: prefork: new lowest idle kid: 26189
>> Mar 21 17:06:44 sa85 spamd[26188]: spamd: connection from 10.10.10.85 [10.10.10.85] at port 33494
>> Mar 21 17:06:44 sa85 spamd[26188]: info: user has changed
>> Mar 21 17:06:44 sa85 spamd[26188]: bayes: no dbs present, cannot tie DB R/O: /var/spool/mail/.spamassassin/bayes_toks
>> Mar 21 17:06:44 sa85 spamd[26188]: config: score set 0 chosen.
>> Mar 21 17:06:44 sa85 spamd[26188]: spamd: running as uid 8
>> Mar 21 17:06:44 sa85 spamd[26188]: message: main message type: multipart/mixed
>> Mar 21 17:06:44 sa85 spamd[26188]: spamd: processing message <munged> for root:8
>> Mar 21 17:06:44 sa85 spamd[26188]: bayes: no dbs present, cannot tie DB R/O: /var/spool/mail/.spamassassin/bayes_toks
>> Mar 21 17:06:44 sa85 spamd[26188]: conf: trusted_networks are not configured; it is recommended that you configure trusted_networks manually
> (snip receive header parsing debug output)
>> Mar 21 17:06:44 sa85 spamd[26188]: message: ---- MIME PARSER START ----
>> Mar 21 17:06:44 sa85 spamd[26188]: message: parsing multipart, got boundary: =_mixed 00493DD98625742D_=
>> Mar 21 17:06:44 sa85 spamd[26188]: message: found part of type multipart/alternative, boundary: =_alternative 00493DD98625742D_=
>> Mar 21 17:06:44 sa85 spamd[26188]: message: added part, type: multipart/alternative
>> Mar 21 17:06:44 sa85 spamd[26188]: message: found part of type application/octet-stream, boundary: =_mixed 00493DD98625742D_=
>> Mar 21 17:06:44 sa85 spamd[26188]: message: added part, type: application/octet-stream
>> Mar 21 17:06:44 sa85 spamd[26188]: message: parsing multipart, got boundary: =_alternative 00493DD98625742D_=
>> Mar 21 17:06:44 sa85 spamd[26188]: message: found part of type text/plain, boundary: =_alternative 00493DD98625742D_=
>> Mar 21 17:06:44 sa85 spamd[26188]: message: added part, type: text/plain
>> Mar 21 17:06:44 sa85 spamd[26188]: message: found part of type text/html, boundary: =_alternative 00493DD98625742D_=
>> Mar 21 17:06:44 sa85 spamd[26188]: message: added part, type: text/html
>> Mar 21 17:06:44 sa85 spamd[26188]: message: parsing normal part
>> Mar 21 17:06:44 sa85 last message repeated 2 times
>> Mar 21 17:06:44 sa85 spamd[26188]: message: ---- MIME PARSER END ----
>> Mar 21 17:06:44 sa85 spamd[26188]: message: no encoding detected
>> Mar 21 17:06:44 sa85 spamd[26188]: message: no encoding detected
>> Mar 21 17:06:44 sa85 spamd[26188]: rules: local tests only, ignoring RBL eval
>> Mar 21 17:06:44 sa85 spamd[26188]: check: running tests for priority: 0
>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running head tests; score so far=0
>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running body tests; score so far=0
>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running uri tests; score so far=0
>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running rawbody tests; score so far=0
>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running full tests; score so far=0
>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running meta tests; score so far=0
>> Mar 21 17:06:44 sa85 spamd[26188]: check: running tests for priority: 500
>> Mar 21 17:06:44 sa85 spamd[26188]: dns: harvest_dnsbl_queries
>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running head tests; score so far=0
>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running body tests; score so far=0
>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running uri tests; score so far=0
>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running rawbody tests; score so far=0
>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running full tests; score so far=0
>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running meta tests; score so far=0
>> Mar 21 17:06:44 sa85 spamd[26188]: check: is spam? score=0 required=5
>> Mar 21 17:06:44 sa85 spamd[26188]: check: tests=
>> Mar 21 17:06:44 sa85 spamd[26188]: check: subtests=
>> Mar 21 17:06:44 sa85 spamd[26188]: spamd: clean message (0.0/5.0) for root:8 in 10.0 seconds, 81532 bytes.
>> Mar 21 17:06:44 sa85 spamd[26188]: spamd: result: . 0 - scantime=10.0,size=81532,user=root,uid=8,required_score=5.0,rhost=10.10.10.85,raddr=10.10.10.85,rport=33494,mid=<munged>,autolearn=no
>> Mar 21 17:06:44 sa85 spamd[26188]: config: copying current conf from backup
>> Mar 21 17:06:44 sa85 spamd[26188]: prefork: sysread(7) not ready, wait max 300 secs
>> Mar 21 17:06:44 sa85 spamd[26187]: prefork: child 26188: entering state 1
>> Mar 21 17:06:44 sa85 spamd[26187]: prefork: new lowest idle kid: 26188
>> Mar 21 17:06:44 sa85 spamd[26187]: prefork: child reports idle
>> Mar 21 17:06:44 sa85 spamd[26187]: prefork: child states: II
>
>
>
Re: spamd children waiting 10 seconds before they start processing
a message
Posted by "Daryl C. W. O'Shea" <sp...@dostech.ca>.
Arg, I got sidetracked with a rule based DNS problem, thought to check
"other DNS problems", thought I did but apparently didn't.
Problem: rdns check on connecting host (for syslogging purposes) was
timing out after 10 seconds
...which is why the problem only affected spamd and not spamassassin.
Thanks!
Daryl
On 21/03/2009 6:38 PM, Justin Mason wrote:
> bizarre. the one thing that leaps to mind would be a DNS lookup
> happening "behind the scenes"
> to a broken/missing DNS server...
>
> --j.
>
> On Sat, Mar 21, 2009 at 22:31, Daryl C. W. O'Shea
> <sp...@dostech.ca> wrote:
>> Anybody know why a spamd child would consistently sleep 10 seconds
>> before even starting to process a message after being ordered to do so
>> by the spamd parent?
>>
>> /usr/local/scripts/spamd -p 5559 -x -u mail -m 2 -d -A 10.0.0.0/8 -i
>> 10.10.10.85 -r /var/run/spamd2.pid -L -D
>> --siteconfigpath=/home/techsupport/spamassassin --configpath=/dev/null
>>
>> The only plugin being loaded is the Check plugin. Everything else is
>> disabled. The spamd children have the same 10 second delay when running
>> in either prefork or round-robin mode.
>>
>> load average: 0.15, 0.20, 0.18
>>
>> Cpu(s): 4.8% us, 0.6% sy, 0.0% ni, 94.2% id, 0.0% wa, 0.0% hi, 0.3% si
>>
>> Thanks!
>>
>> Daryl
>>
>>
>>> Mar 21 17:06:34 sa85 spamd[26187]: prefork: ordered 26188 to accept
>>> Mar 21 17:06:34 sa85 spamd[26187]: prefork: sysread(6) not ready, wait max 300 secs
>>> Mar 21 17:06:34 sa85 spamd[26187]: prefork: child 26188: entering state 2
>>> Mar 21 17:06:34 sa85 spamd[26187]: prefork: new lowest idle kid: 26189
>>> Mar 21 17:06:44 sa85 spamd[26188]: spamd: connection from 10.10.10.85 [10.10.10.85] at port 33494
>>> Mar 21 17:06:44 sa85 spamd[26188]: info: user has changed
>>> Mar 21 17:06:44 sa85 spamd[26188]: bayes: no dbs present, cannot tie DB R/O: /var/spool/mail/.spamassassin/bayes_toks
>>> Mar 21 17:06:44 sa85 spamd[26188]: config: score set 0 chosen.
>>> Mar 21 17:06:44 sa85 spamd[26188]: spamd: running as uid 8
>>> Mar 21 17:06:44 sa85 spamd[26188]: message: main message type: multipart/mixed
>>> Mar 21 17:06:44 sa85 spamd[26188]: spamd: processing message <munged> for root:8
>>> Mar 21 17:06:44 sa85 spamd[26188]: bayes: no dbs present, cannot tie DB R/O: /var/spool/mail/.spamassassin/bayes_toks
>>> Mar 21 17:06:44 sa85 spamd[26188]: conf: trusted_networks are not configured; it is recommended that you configure trusted_networks manually
>> (snip receive header parsing debug output)
>>> Mar 21 17:06:44 sa85 spamd[26188]: message: ---- MIME PARSER START ----
>>> Mar 21 17:06:44 sa85 spamd[26188]: message: parsing multipart, got boundary: =_mixed 00493DD98625742D_=
>>> Mar 21 17:06:44 sa85 spamd[26188]: message: found part of type multipart/alternative, boundary: =_alternative 00493DD98625742D_=
>>> Mar 21 17:06:44 sa85 spamd[26188]: message: added part, type: multipart/alternative
>>> Mar 21 17:06:44 sa85 spamd[26188]: message: found part of type application/octet-stream, boundary: =_mixed 00493DD98625742D_=
>>> Mar 21 17:06:44 sa85 spamd[26188]: message: added part, type: application/octet-stream
>>> Mar 21 17:06:44 sa85 spamd[26188]: message: parsing multipart, got boundary: =_alternative 00493DD98625742D_=
>>> Mar 21 17:06:44 sa85 spamd[26188]: message: found part of type text/plain, boundary: =_alternative 00493DD98625742D_=
>>> Mar 21 17:06:44 sa85 spamd[26188]: message: added part, type: text/plain
>>> Mar 21 17:06:44 sa85 spamd[26188]: message: found part of type text/html, boundary: =_alternative 00493DD98625742D_=
>>> Mar 21 17:06:44 sa85 spamd[26188]: message: added part, type: text/html
>>> Mar 21 17:06:44 sa85 spamd[26188]: message: parsing normal part
>>> Mar 21 17:06:44 sa85 last message repeated 2 times
>>> Mar 21 17:06:44 sa85 spamd[26188]: message: ---- MIME PARSER END ----
>>> Mar 21 17:06:44 sa85 spamd[26188]: message: no encoding detected
>>> Mar 21 17:06:44 sa85 spamd[26188]: message: no encoding detected
>>> Mar 21 17:06:44 sa85 spamd[26188]: rules: local tests only, ignoring RBL eval
>>> Mar 21 17:06:44 sa85 spamd[26188]: check: running tests for priority: 0
>>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running head tests; score so far=0
>>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running body tests; score so far=0
>>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running uri tests; score so far=0
>>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running rawbody tests; score so far=0
>>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running full tests; score so far=0
>>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running meta tests; score so far=0
>>> Mar 21 17:06:44 sa85 spamd[26188]: check: running tests for priority: 500
>>> Mar 21 17:06:44 sa85 spamd[26188]: dns: harvest_dnsbl_queries
>>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running head tests; score so far=0
>>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running body tests; score so far=0
>>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running uri tests; score so far=0
>>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running rawbody tests; score so far=0
>>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running full tests; score so far=0
>>> Mar 21 17:06:44 sa85 spamd[26188]: rules: running meta tests; score so far=0
>>> Mar 21 17:06:44 sa85 spamd[26188]: check: is spam? score=0 required=5
>>> Mar 21 17:06:44 sa85 spamd[26188]: check: tests=
>>> Mar 21 17:06:44 sa85 spamd[26188]: check: subtests=
>>> Mar 21 17:06:44 sa85 spamd[26188]: spamd: clean message (0.0/5.0) for root:8 in 10.0 seconds, 81532 bytes.
>>> Mar 21 17:06:44 sa85 spamd[26188]: spamd: result: . 0 - scantime=10.0,size=81532,user=root,uid=8,required_score=5.0,rhost=10.10.10.85,raddr=10.10.10.85,rport=33494,mid=<munged>,autolearn=no
>>> Mar 21 17:06:44 sa85 spamd[26188]: config: copying current conf from backup
>>> Mar 21 17:06:44 sa85 spamd[26188]: prefork: sysread(7) not ready, wait max 300 secs
>>> Mar 21 17:06:44 sa85 spamd[26187]: prefork: child 26188: entering state 1
>>> Mar 21 17:06:44 sa85 spamd[26187]: prefork: new lowest idle kid: 26188
>>> Mar 21 17:06:44 sa85 spamd[26187]: prefork: child reports idle
>>> Mar 21 17:06:44 sa85 spamd[26187]: prefork: child states: II
>>
>>
>