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 <[email protected]> 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 > > >
