Hi all,
Version:
3.1.4
OS - Unslung 6.8 on a Linksys
NSLU2 (Slug)
Running spamd with fetchmail
and postfix
A couple of days ago the Slug
hung with masses of disk activity; when I looked at what was going on, it seemd
that spamd and/or spamc were chewing up resources.
Looking at the spamd log file
(relevant part included below) indicates that I hadn't got my max-child setting
high enough to cope with a flurry of emails coming in. Is this my problem,
or is this a red herring, and is it the warning logged by child process
17429 ' copy_config timeout, respawning child process..'? After this, it sems
that 17429 no longer talks to the parent process.
I'd be surprised if too low a
max-children setting would be causing the problem, so can someone shed light on
what the problem was with this child process? I had to restart spamd to
get things going again.
Thanks,
James
Log file
extract:
Mon Oct 23 06:02:58 2006
[17427] info: prefork: child states: II
Mon Oct 23 06:38:55 2006 [17428] info: spamd: connection from localhost [127.0.0.1] at port 2676
Mon Oct 23 06:38:56 2006 [17428] info: spamd: setuid to spamd succeeded
Mon Oct 23 06:38:57 2006 [17428] info: spamd: processing message <[EMAIL PROTECTED]> for spamd:40
Mon Oct 23 06:39:18 2006 [17428] info: spamd: identified spam (16.6/5.0) for spamd:40 in 22.9 seconds, 2512 bytes.
Mon Oct 23 06:39:18 2006 [17428] info: spamd: result: Y 16 - INVALID_TZ_EST,URIBL_AB_SURBL,URIBL_BLACK,URIBL_JP_SURBL,URIBL_OB_SURBL,URIBL_SC_SURBL scantime=22.9,size=2512,user=spamd,uid=40,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=2676,mid=<[EMAIL PROTECTED]>,autolearn=no
Mon Oct 23 06:39:24 2006 [17427] info: prefork: child states: II
Mon Oct 23 06:59:51 2006 [17428] info: spamd: connection from localhost [127.0.0.1] at port 2698
Mon Oct 23 06:59:52 2006 [17428] info: spamd: setuid to spamd succeeded
Mon Oct 23 06:59:55 2006 [17429] info: spamd: connection from localhost [127.0.0.1] at port 2699
Mon Oct 23 06:59:58 2006 [17429] info: spamd: setuid to spamd succeeded
Mon Oct 23 07:00:00 2006 [17428] info: spamd: processing message <[EMAIL PROTECTED]> for spamd:40
Mon Oct 23 07:00:09 2006 [17429] info: spamd: processing message <[EMAIL PROTECTED]> for spamd:40
Mon Oct 23 07:00:57 2006 [17428] info: spamd: clean message (1.6/5.0) for spamd:40 in 65.6 seconds, 1881 bytes.
Mon Oct 23 07:00:58 2006 [17428] info: spamd: result: . 1 - INVALID_TZ_EST,UNDISC_RECIPS scantime=65.6,size=1881,user=spamd,uid=40,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=2698,mid=<[EMAIL PROTECTED]>,autolearn=no
Mon Oct 23 07:01:02 2006 [17429] info: spamd: clean message (1.6/5.0) for spamd:40 in 67.9 seconds, 1893 bytes.
Mon Oct 23 07:01:02 2006 [17429] info: spamd: result: . 1 - INVALID_TZ_EST,UNDISC_RECIPS scantime=67.9,size=1893,user=spamd,uid=40,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=2699,mid=<[EMAIL PROTECTED]>,autolearn=no
Mon Oct 23 07:01:58 2006 [17428] warn: spamd: copy_config timeout, respawning child process after 3 messages at /opt/bin/spamd line 967.
Mon Oct 23 07:02:09 2006 [17427] info: prefork: child states: BI
Mon Oct 23 07:02:10 2006 [17427] info: prefork: child states: BI
Mon Oct 23 07:02:13 2006 [17427] warn: prefork: cannot ping 17428, file handle not defined, child likely to still be processing SIGCHLD handler after killing itself
Mon Oct 23 07:02:13 2006 [17427] warn: Use of uninitialized value in concatenation (.) or string at /opt/lib/perl5/site_perl/5.8.8/Mail/SpamAssassin/SpamdForkScaling.pm line 127.
Mon Oct 23 07:02:13 2006 [17427] warn: prefork: killing failed child 17428 fd= at /opt/lib/perl5/site_perl/5.8.8/Mail/SpamAssassin/SpamdForkScaling.pm line 127.
Mon Oct 23 07:02:13 2006 [17427] warn: prefork: killed child 17428 at /opt/lib/perl5/site_perl/5.8.8/Mail/SpamAssassin/SpamdForkScaling.pm line 141.
Mon Oct 23 07:02:14 2006 [17427] info: spamd: handled cleanup of child pid 17428 due to SIGCHLD
Mon Oct 23 07:02:16 2006 [17427] info: spamd: server successfully spawned child process, pid 17528
Mon Oct 23 07:02:17 2006 [17427] info: prefork: child states: II
Mon Oct 23 07:05:51 2006 [17429] info: spamd: connection from localhost [127.0.0.1] at port 2706
Mon Oct 23 07:05:52 2006 [17429] info: spamd: setuid to spamd succeeded
Mon Oct 23 07:05:56 2006 [17429] info: spamd: processing message <[EMAIL PROTECTED]> for spamd:40
Mon Oct 23 07:06:14 2006 [17429] info: spamd: clean message (1.6/5.0) for spamd:40 in 23.2 seconds, 1885 bytes.
Mon Oct 23 07:06:14 2006 [17429] info: spamd: result: . 1 - INVALID_TZ_EST,UNDISC_RECIPS scantime=23.2,size=1885,user=spamd,uid=40,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=2706,mid=<[EMAIL PROTECTED]>,autolearn=no
Mon Oct 23 07:06:20 2006 [17427] info: prefork: child states: II
Mon Oct 23 07:06:57 2006 [17429] info: spamd: connection from localhost [127.0.0.1] at port 2709
Mon Oct 23 07:06:57 2006 [17429] info: spamd: setuid to spamd succeeded
Mon Oct 23 07:07:02 2006 [17528] info: spamd: connection from localhost [127.0.0.1] at port 2710
Mon Oct 23 07:07:03 2006 [17429] info: spamd: processing message <[EMAIL PROTECTED]> for spamd:40
Mon Oct 23 07:07:07 2006 [17528] info: spamd: setuid to spamd succeeded
Mon Oct 23 07:07:19 2006 [17528] info: spamd: processing message <[EMAIL PROTECTED]> for spamd:40
Mon Oct 23 07:08:14 2006 [17429] info: spamd: clean message (1.6/5.0) for spamd:40 in 76.8 seconds, 1887 bytes.
Mon Oct 23 07:08:14 2006 [17429] info: spamd: result: . 1 - INVALID_TZ_EST,UNDISC_RECIPS scantime=76.8,size=1887,user=spamd,uid=40,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=2709,mid=<[EMAIL PROTECTED]>,autolearn=no
Mon Oct 23 07:08:27 2006 [17528] info: spamd: clean message (1.6/5.0) for spamd:40 in 85.3 seconds, 2215 bytes.
Mon Oct 23 07:08:27 2006 [17528] info: spamd: result: . 1 - INVALID_TZ_EST,UNDISC_RECIPS scantime=85.3,size=2215,user=spamd,uid=40,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=2710,mid=<[EMAIL PROTECTED]>,autolearn=no
Mon Oct 23 07:08:48 2006 [17429] warn: spamd: copy_config timeout, respawning child process after 3 messages at /opt/bin/spamd line 967.
Mon Oct 23 07:08:56 2006 [17427] info: prefork: child states: BB
Mon Oct 23 07:08:58 2006 [17427] info: spamd: server successfully spawned child process, pid 17566
Mon Oct 23 07:09:02 2006 [17427] info: prefork: child states: BBS
Mon Oct 23 07:09:04 2006 [17427] info: spamd: server successfully spawned child process, pid 17567
Mon Oct 23 07:09:07 2006 [17528] info: spamd: connection from localhost [127.0.0.1] at port 2713
Mon Oct 23 07:09:07 2006 [17427] info: prefork: child states: BBSB
Mon Oct 23 07:09:08 2006 [17427] info: spamd: server successfully spawned child process, pid 17568
Mon Oct 23 07:09:10 2006 [17427] info: prefork: child states: BBBBS
Mon Oct 23 07:09:10 2006 [17427] info: prefork: server reached --max-children setting, consider raising it
Mon Oct 23 07:09:11 2006 [17528] info: spamd: setuid to spamd succeeded
Mon Oct 23 07:09:11 2006 [17427] info: prefork: child states: BBBBB
Mon Oct 23 07:09:11 2006 [17427] info: prefork: server reached --max-children setting, consider raising it
Mon Oct 23 07:09:12 2006 [17568] info: spamd: connection from localhost [127.0.0.1] at port 2716
Mon Oct 23 07:09:12 2006 [17567] info: spamd: connection from localhost [127.0.0.1] at port 2714
Mon Oct 23 07:09:13 2006 [17566] info: spamd: connection from localhost [127.0.0.1] at port 2715
Mon Oct 23 07:09:18 2006 [17567] info: spamd: setuid to spamd succeeded
Mon Oct 23 07:09:18 2006 [17566] info: spamd: setuid to spamd succeeded
Mon Oct 23 07:09:18 2006 [17568] info: spamd: setuid to spamd succeeded
Mon Oct 23 07:09:50 2006 [17427] warn: prefork: cannot ping 17429, file handle not defined, child likely to still be processing SIGCHLD handler after killing itself
Mon Oct 23 07:09:52 2006 [17427] warn: Use of uninitialized value in concatenation (.) or string at /opt/lib/perl5/site_perl/5.8.8/Mail/SpamAssassin/SpamdForkScaling.pm line 127.
Mon Oct 23 07:09:52 2006 [17427] warn: prefork: killing failed child 17429 fd= at /opt/lib/perl5/site_perl/5.8.8/Mail/SpamAssassin/SpamdForkScaling.pm line 127.
Mon Oct 23 07:09:56 2006 [17567] info: spamd: processing message <[EMAIL PROTECTED]> for spamd:40
Mon Oct 23 07:09:56 2006 [17566] info: spamd: processing message <[EMAIL PROTECTED]> for spamd:40
Mon Oct 23 07:09:56 2006 [17568] info: spamd: processing message <[EMAIL PROTECTED]> for spamd:40
Mon Oct 23 07:09:57 2006 [17427] info: spamd: handled cleanup of child pid 17429 due to SIGCHLD
Mon Oct 23 07:09:57 2006 [17427] warn: prefork: killed child 17429 at /opt/lib/perl5/site_perl/5.8.8/Mail/SpamAssassin/SpamdForkScaling.pm line 141.
Mon Oct 23 07:10:03 2006 [17528] info: spamd: processing message <[EMAIL PROTECTED]> for spamd:40
Mon Oct 23 07:14:09 2006 [17528] error: child processing timeout at /opt/bin/spamd line 1084, <GEN13> line 44.
Mon Oct 23 07:14:09 2006 [17528] error: child processing timeout at /opt/bin/spamd line 1084, <GEN13> line 44.
Mon Oct 23 07:14:09 2006 [17528] warn: rules: failed to run __UNUSABLE_MSGID test, skipping:
Mon Oct 23 07:14:09 2006 [17528] warn: (child processing timeout at /opt/bin/spamd line 1084, <GEN13> line 44.
Mon Oct 23 07:14:09 2006 [17528] warn: )
Mon Oct 23 07:14:17 2006 [17566] error: child processing timeout at /opt/bin/spamd line 1084, <GEN14> line 43.
Mon Oct 23 07:14:17 2006 [17566] error: child processing timeout at /opt/bin/spamd line 1084, <GEN14> line 43.
Mon Oct 23 07:14:17 2006 [17566] warn: auto-whitelist: open of auto-whitelist file failed: child processing timeout at /opt/bin/spamd line 1084, <GEN14> line 43.
Mon Oct 23 07:14:17 2006 [17567] error: child processing timeout at /opt/bin/spamd line 1084, <GEN17> line 43.
Mon Oct 23 07:14:18 2006 [17567] error: child processing timeout at /opt/bin/spamd line 1084, <GEN17> line 43.
Mon Oct 23 07:14:18 2006 [17568] error: child processing timeout at /opt/bin/spamd line 1084, <GEN20> line 43.
Mon Oct 23 07:14:18 2006 [17568] error: child processing timeout at /opt/bin/spamd line 1084, <GEN20> line 43.
Mon Oct 23 07:14:19 2006 [17567] warn: auto-whitelist: open of auto-whitelist file failed: child processing timeout at /opt/bin/spamd line 1084, <GEN17> line 43.
Mon Oct 23 07:14:19 2006 [17568] warn: auto-whitelist: open of auto-whitelist file failed: child processing timeout at /opt/bin/spamd line 1084, <GEN20> line 43.
Mon Oct 23 07:14:49 2006 [17566] info: spamd: clean message (1.6/5.0) for spamd:40 in 338.1 seconds, 1970 bytes.
Mon Oct 23 07:14:49 2006 [17566] info: spamd: result: . 1 - AWL,INVALID_TZ_EST,UNDISC_RECIPS scantime=338.1,size=1970,user=spamd,uid=40,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=2715,mid=<[EMAIL PROTECTED]>,autolearn=no
Mon Oct 23 07:14:54 2006 [17567] info: spamd: clean message (1.6/5.0) for spamd:40 in 344.5 seconds, 1920 bytes.
Mon Oct 23 07:14:54 2006 [17567] info: spamd: result: . 1 - INVALID_TZ_EST,UNDISC_RECIPS scantime=344.5,size=1920,user=spamd,uid=40,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=2714,mid=<[EMAIL PROTECTED]>,autolearn=no
Mon Oct 23 07:15:00 2006 [17568] info: spamd: clean message (1.6/5.0) for spamd:40 in 345.7 seconds, 1935 bytes.
Mon Oct 23 07:15:01 2006 [17568] info: spamd: result: . 1 - INVALID_TZ_EST,UNDISC_RECIPS scantime=345.7,size=1935,user=spamd,uid=40,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=2716,mid=<[EMAIL PROTECTED]>,autolearn=no
Mon Oct 23 07:16:02 2006 [17567] warn: spamd: copy_config timeout, respawning child process after 1 messages at /opt/bin/spamd line 967.
Mon Oct 23 07:16:02 2006 [17566] warn: spamd: copy_config timeout, respawning child process after 1 messages at /opt/bin/spamd line 967.
Mon Oct 23 07:16:05 2006 [17568] warn: spamd: copy_config timeout, respawning child process after 1 messages at /opt/bin/spamd line 967.
Mon Oct 23 07:16:52 2006 [17427] info: prefork: child states: BBBB
Mon Oct 23 07:17:44 2006 [17427] info: spamd: server successfully spawned child process, pid 17603
Mon Oct 23 07:24:39 2006 [17427] info: prefork: child states: BBBBB
Mon Oct 23 07:25:04 2006 [17603] info: spamd: connection from localhost [127.0.0.1] at port 2717
Mon Oct 23 07:25:53 2006 [17427] info: prefork: server reached --max-children setting, consider raising it
Mon Oct 23 07:33:31 2006 [17603] error: tcp timeout at /opt/bin/spamd line 1041.
Mon Oct 23 07:33:30 2006 [17427] warn: prefork: cannot ping 17568, file handle not defined, child likely to still be processing SIGCHLD handler after killing itself
Mon Oct 23 07:34:09 2006 [17603] error: tcp timeout at /opt/bin/spamd line 1041.
Mon Oct 23 07:34:11 2006 [17427] warn: Use of uninitialized value in concatenation (.) or string at /opt/lib/perl5/site_perl/5.8.8/Mail/SpamAssassin/SpamdForkScaling.pm line 127.
Mon Oct 23 07:34:32 2006 [17528] info: spamd: clean message (1.6/5.0) for spamd:40 in 1510.2 seconds, 2040 bytes.
Mon Oct 23 07:34:39 2006 [17427] warn: prefork: killing failed child 17568 fd= at /opt/lib/perl5/site_perl/5.8.8/Mail/SpamAssassin/SpamdForkScaling.pm line 127.
Mon Oct 23 07:34:41 2006 [17603] warn: spamd: timeout: (30 second socket timeout reading input from client) at /opt/bin/spamd line 1685.
Mon Oct 23 07:35:01 2006 [17528] info: spamd: result: . 1 - INVALID_TZ_EST,UNDISC_RECIPS scantime=1510.2,size=2040,user=spamd,uid=40,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=2713,mid=<[EMAIL PROTECTED]>,autolearn=no
Mon Oct 23 07:35:09 2006 [17427] info: spamd: server killed by SIGTERM, shutting down
Mon Oct 23 06:38:55 2006 [17428] info: spamd: connection from localhost [127.0.0.1] at port 2676
Mon Oct 23 06:38:56 2006 [17428] info: spamd: setuid to spamd succeeded
Mon Oct 23 06:38:57 2006 [17428] info: spamd: processing message <[EMAIL PROTECTED]> for spamd:40
Mon Oct 23 06:39:18 2006 [17428] info: spamd: identified spam (16.6/5.0) for spamd:40 in 22.9 seconds, 2512 bytes.
Mon Oct 23 06:39:18 2006 [17428] info: spamd: result: Y 16 - INVALID_TZ_EST,URIBL_AB_SURBL,URIBL_BLACK,URIBL_JP_SURBL,URIBL_OB_SURBL,URIBL_SC_SURBL scantime=22.9,size=2512,user=spamd,uid=40,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=2676,mid=<[EMAIL PROTECTED]>,autolearn=no
Mon Oct 23 06:39:24 2006 [17427] info: prefork: child states: II
Mon Oct 23 06:59:51 2006 [17428] info: spamd: connection from localhost [127.0.0.1] at port 2698
Mon Oct 23 06:59:52 2006 [17428] info: spamd: setuid to spamd succeeded
Mon Oct 23 06:59:55 2006 [17429] info: spamd: connection from localhost [127.0.0.1] at port 2699
Mon Oct 23 06:59:58 2006 [17429] info: spamd: setuid to spamd succeeded
Mon Oct 23 07:00:00 2006 [17428] info: spamd: processing message <[EMAIL PROTECTED]> for spamd:40
Mon Oct 23 07:00:09 2006 [17429] info: spamd: processing message <[EMAIL PROTECTED]> for spamd:40
Mon Oct 23 07:00:57 2006 [17428] info: spamd: clean message (1.6/5.0) for spamd:40 in 65.6 seconds, 1881 bytes.
Mon Oct 23 07:00:58 2006 [17428] info: spamd: result: . 1 - INVALID_TZ_EST,UNDISC_RECIPS scantime=65.6,size=1881,user=spamd,uid=40,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=2698,mid=<[EMAIL PROTECTED]>,autolearn=no
Mon Oct 23 07:01:02 2006 [17429] info: spamd: clean message (1.6/5.0) for spamd:40 in 67.9 seconds, 1893 bytes.
Mon Oct 23 07:01:02 2006 [17429] info: spamd: result: . 1 - INVALID_TZ_EST,UNDISC_RECIPS scantime=67.9,size=1893,user=spamd,uid=40,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=2699,mid=<[EMAIL PROTECTED]>,autolearn=no
Mon Oct 23 07:01:58 2006 [17428] warn: spamd: copy_config timeout, respawning child process after 3 messages at /opt/bin/spamd line 967.
Mon Oct 23 07:02:09 2006 [17427] info: prefork: child states: BI
Mon Oct 23 07:02:10 2006 [17427] info: prefork: child states: BI
Mon Oct 23 07:02:13 2006 [17427] warn: prefork: cannot ping 17428, file handle not defined, child likely to still be processing SIGCHLD handler after killing itself
Mon Oct 23 07:02:13 2006 [17427] warn: Use of uninitialized value in concatenation (.) or string at /opt/lib/perl5/site_perl/5.8.8/Mail/SpamAssassin/SpamdForkScaling.pm line 127.
Mon Oct 23 07:02:13 2006 [17427] warn: prefork: killing failed child 17428 fd= at /opt/lib/perl5/site_perl/5.8.8/Mail/SpamAssassin/SpamdForkScaling.pm line 127.
Mon Oct 23 07:02:13 2006 [17427] warn: prefork: killed child 17428 at /opt/lib/perl5/site_perl/5.8.8/Mail/SpamAssassin/SpamdForkScaling.pm line 141.
Mon Oct 23 07:02:14 2006 [17427] info: spamd: handled cleanup of child pid 17428 due to SIGCHLD
Mon Oct 23 07:02:16 2006 [17427] info: spamd: server successfully spawned child process, pid 17528
Mon Oct 23 07:02:17 2006 [17427] info: prefork: child states: II
Mon Oct 23 07:05:51 2006 [17429] info: spamd: connection from localhost [127.0.0.1] at port 2706
Mon Oct 23 07:05:52 2006 [17429] info: spamd: setuid to spamd succeeded
Mon Oct 23 07:05:56 2006 [17429] info: spamd: processing message <[EMAIL PROTECTED]> for spamd:40
Mon Oct 23 07:06:14 2006 [17429] info: spamd: clean message (1.6/5.0) for spamd:40 in 23.2 seconds, 1885 bytes.
Mon Oct 23 07:06:14 2006 [17429] info: spamd: result: . 1 - INVALID_TZ_EST,UNDISC_RECIPS scantime=23.2,size=1885,user=spamd,uid=40,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=2706,mid=<[EMAIL PROTECTED]>,autolearn=no
Mon Oct 23 07:06:20 2006 [17427] info: prefork: child states: II
Mon Oct 23 07:06:57 2006 [17429] info: spamd: connection from localhost [127.0.0.1] at port 2709
Mon Oct 23 07:06:57 2006 [17429] info: spamd: setuid to spamd succeeded
Mon Oct 23 07:07:02 2006 [17528] info: spamd: connection from localhost [127.0.0.1] at port 2710
Mon Oct 23 07:07:03 2006 [17429] info: spamd: processing message <[EMAIL PROTECTED]> for spamd:40
Mon Oct 23 07:07:07 2006 [17528] info: spamd: setuid to spamd succeeded
Mon Oct 23 07:07:19 2006 [17528] info: spamd: processing message <[EMAIL PROTECTED]> for spamd:40
Mon Oct 23 07:08:14 2006 [17429] info: spamd: clean message (1.6/5.0) for spamd:40 in 76.8 seconds, 1887 bytes.
Mon Oct 23 07:08:14 2006 [17429] info: spamd: result: . 1 - INVALID_TZ_EST,UNDISC_RECIPS scantime=76.8,size=1887,user=spamd,uid=40,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=2709,mid=<[EMAIL PROTECTED]>,autolearn=no
Mon Oct 23 07:08:27 2006 [17528] info: spamd: clean message (1.6/5.0) for spamd:40 in 85.3 seconds, 2215 bytes.
Mon Oct 23 07:08:27 2006 [17528] info: spamd: result: . 1 - INVALID_TZ_EST,UNDISC_RECIPS scantime=85.3,size=2215,user=spamd,uid=40,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=2710,mid=<[EMAIL PROTECTED]>,autolearn=no
Mon Oct 23 07:08:48 2006 [17429] warn: spamd: copy_config timeout, respawning child process after 3 messages at /opt/bin/spamd line 967.
Mon Oct 23 07:08:56 2006 [17427] info: prefork: child states: BB
Mon Oct 23 07:08:58 2006 [17427] info: spamd: server successfully spawned child process, pid 17566
Mon Oct 23 07:09:02 2006 [17427] info: prefork: child states: BBS
Mon Oct 23 07:09:04 2006 [17427] info: spamd: server successfully spawned child process, pid 17567
Mon Oct 23 07:09:07 2006 [17528] info: spamd: connection from localhost [127.0.0.1] at port 2713
Mon Oct 23 07:09:07 2006 [17427] info: prefork: child states: BBSB
Mon Oct 23 07:09:08 2006 [17427] info: spamd: server successfully spawned child process, pid 17568
Mon Oct 23 07:09:10 2006 [17427] info: prefork: child states: BBBBS
Mon Oct 23 07:09:10 2006 [17427] info: prefork: server reached --max-children setting, consider raising it
Mon Oct 23 07:09:11 2006 [17528] info: spamd: setuid to spamd succeeded
Mon Oct 23 07:09:11 2006 [17427] info: prefork: child states: BBBBB
Mon Oct 23 07:09:11 2006 [17427] info: prefork: server reached --max-children setting, consider raising it
Mon Oct 23 07:09:12 2006 [17568] info: spamd: connection from localhost [127.0.0.1] at port 2716
Mon Oct 23 07:09:12 2006 [17567] info: spamd: connection from localhost [127.0.0.1] at port 2714
Mon Oct 23 07:09:13 2006 [17566] info: spamd: connection from localhost [127.0.0.1] at port 2715
Mon Oct 23 07:09:18 2006 [17567] info: spamd: setuid to spamd succeeded
Mon Oct 23 07:09:18 2006 [17566] info: spamd: setuid to spamd succeeded
Mon Oct 23 07:09:18 2006 [17568] info: spamd: setuid to spamd succeeded
Mon Oct 23 07:09:50 2006 [17427] warn: prefork: cannot ping 17429, file handle not defined, child likely to still be processing SIGCHLD handler after killing itself
Mon Oct 23 07:09:52 2006 [17427] warn: Use of uninitialized value in concatenation (.) or string at /opt/lib/perl5/site_perl/5.8.8/Mail/SpamAssassin/SpamdForkScaling.pm line 127.
Mon Oct 23 07:09:52 2006 [17427] warn: prefork: killing failed child 17429 fd= at /opt/lib/perl5/site_perl/5.8.8/Mail/SpamAssassin/SpamdForkScaling.pm line 127.
Mon Oct 23 07:09:56 2006 [17567] info: spamd: processing message <[EMAIL PROTECTED]> for spamd:40
Mon Oct 23 07:09:56 2006 [17566] info: spamd: processing message <[EMAIL PROTECTED]> for spamd:40
Mon Oct 23 07:09:56 2006 [17568] info: spamd: processing message <[EMAIL PROTECTED]> for spamd:40
Mon Oct 23 07:09:57 2006 [17427] info: spamd: handled cleanup of child pid 17429 due to SIGCHLD
Mon Oct 23 07:09:57 2006 [17427] warn: prefork: killed child 17429 at /opt/lib/perl5/site_perl/5.8.8/Mail/SpamAssassin/SpamdForkScaling.pm line 141.
Mon Oct 23 07:10:03 2006 [17528] info: spamd: processing message <[EMAIL PROTECTED]> for spamd:40
Mon Oct 23 07:14:09 2006 [17528] error: child processing timeout at /opt/bin/spamd line 1084, <GEN13> line 44.
Mon Oct 23 07:14:09 2006 [17528] error: child processing timeout at /opt/bin/spamd line 1084, <GEN13> line 44.
Mon Oct 23 07:14:09 2006 [17528] warn: rules: failed to run __UNUSABLE_MSGID test, skipping:
Mon Oct 23 07:14:09 2006 [17528] warn: (child processing timeout at /opt/bin/spamd line 1084, <GEN13> line 44.
Mon Oct 23 07:14:09 2006 [17528] warn: )
Mon Oct 23 07:14:17 2006 [17566] error: child processing timeout at /opt/bin/spamd line 1084, <GEN14> line 43.
Mon Oct 23 07:14:17 2006 [17566] error: child processing timeout at /opt/bin/spamd line 1084, <GEN14> line 43.
Mon Oct 23 07:14:17 2006 [17566] warn: auto-whitelist: open of auto-whitelist file failed: child processing timeout at /opt/bin/spamd line 1084, <GEN14> line 43.
Mon Oct 23 07:14:17 2006 [17567] error: child processing timeout at /opt/bin/spamd line 1084, <GEN17> line 43.
Mon Oct 23 07:14:18 2006 [17567] error: child processing timeout at /opt/bin/spamd line 1084, <GEN17> line 43.
Mon Oct 23 07:14:18 2006 [17568] error: child processing timeout at /opt/bin/spamd line 1084, <GEN20> line 43.
Mon Oct 23 07:14:18 2006 [17568] error: child processing timeout at /opt/bin/spamd line 1084, <GEN20> line 43.
Mon Oct 23 07:14:19 2006 [17567] warn: auto-whitelist: open of auto-whitelist file failed: child processing timeout at /opt/bin/spamd line 1084, <GEN17> line 43.
Mon Oct 23 07:14:19 2006 [17568] warn: auto-whitelist: open of auto-whitelist file failed: child processing timeout at /opt/bin/spamd line 1084, <GEN20> line 43.
Mon Oct 23 07:14:49 2006 [17566] info: spamd: clean message (1.6/5.0) for spamd:40 in 338.1 seconds, 1970 bytes.
Mon Oct 23 07:14:49 2006 [17566] info: spamd: result: . 1 - AWL,INVALID_TZ_EST,UNDISC_RECIPS scantime=338.1,size=1970,user=spamd,uid=40,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=2715,mid=<[EMAIL PROTECTED]>,autolearn=no
Mon Oct 23 07:14:54 2006 [17567] info: spamd: clean message (1.6/5.0) for spamd:40 in 344.5 seconds, 1920 bytes.
Mon Oct 23 07:14:54 2006 [17567] info: spamd: result: . 1 - INVALID_TZ_EST,UNDISC_RECIPS scantime=344.5,size=1920,user=spamd,uid=40,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=2714,mid=<[EMAIL PROTECTED]>,autolearn=no
Mon Oct 23 07:15:00 2006 [17568] info: spamd: clean message (1.6/5.0) for spamd:40 in 345.7 seconds, 1935 bytes.
Mon Oct 23 07:15:01 2006 [17568] info: spamd: result: . 1 - INVALID_TZ_EST,UNDISC_RECIPS scantime=345.7,size=1935,user=spamd,uid=40,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=2716,mid=<[EMAIL PROTECTED]>,autolearn=no
Mon Oct 23 07:16:02 2006 [17567] warn: spamd: copy_config timeout, respawning child process after 1 messages at /opt/bin/spamd line 967.
Mon Oct 23 07:16:02 2006 [17566] warn: spamd: copy_config timeout, respawning child process after 1 messages at /opt/bin/spamd line 967.
Mon Oct 23 07:16:05 2006 [17568] warn: spamd: copy_config timeout, respawning child process after 1 messages at /opt/bin/spamd line 967.
Mon Oct 23 07:16:52 2006 [17427] info: prefork: child states: BBBB
Mon Oct 23 07:17:44 2006 [17427] info: spamd: server successfully spawned child process, pid 17603
Mon Oct 23 07:24:39 2006 [17427] info: prefork: child states: BBBBB
Mon Oct 23 07:25:04 2006 [17603] info: spamd: connection from localhost [127.0.0.1] at port 2717
Mon Oct 23 07:25:53 2006 [17427] info: prefork: server reached --max-children setting, consider raising it
Mon Oct 23 07:33:31 2006 [17603] error: tcp timeout at /opt/bin/spamd line 1041.
Mon Oct 23 07:33:30 2006 [17427] warn: prefork: cannot ping 17568, file handle not defined, child likely to still be processing SIGCHLD handler after killing itself
Mon Oct 23 07:34:09 2006 [17603] error: tcp timeout at /opt/bin/spamd line 1041.
Mon Oct 23 07:34:11 2006 [17427] warn: Use of uninitialized value in concatenation (.) or string at /opt/lib/perl5/site_perl/5.8.8/Mail/SpamAssassin/SpamdForkScaling.pm line 127.
Mon Oct 23 07:34:32 2006 [17528] info: spamd: clean message (1.6/5.0) for spamd:40 in 1510.2 seconds, 2040 bytes.
Mon Oct 23 07:34:39 2006 [17427] warn: prefork: killing failed child 17568 fd= at /opt/lib/perl5/site_perl/5.8.8/Mail/SpamAssassin/SpamdForkScaling.pm line 127.
Mon Oct 23 07:34:41 2006 [17603] warn: spamd: timeout: (30 second socket timeout reading input from client) at /opt/bin/spamd line 1685.
Mon Oct 23 07:35:01 2006 [17528] info: spamd: result: . 1 - INVALID_TZ_EST,UNDISC_RECIPS scantime=1510.2,size=2040,user=spamd,uid=40,required_score=5.0,rhost=localhost,raddr=127.0.0.1,rport=2713,mid=<[EMAIL PROTECTED]>,autolearn=no
Mon Oct 23 07:35:09 2006 [17427] info: spamd: server killed by SIGTERM, shutting down
